Requested products are not installed

[realflash]

Dear all,

Having tested a single server OPSI instance successfully, I have built a second instance with two servers; one config server and one depot server. I have joined my first client (d002) to the config server (10.200.2.7) and set the requested status of three packages that are not installed to 'setup'. When I send on_demand to d002, opsiclientd responds as expected, and launches opsi-winst. But opsi-winst makes no attempt to install the packages:

Code: Alles auswählen

[1] [Jan 21 15:19:26:673] opsi-winst 4.11.4.12 started at >>
[1] [Jan 21 15:19:26:673] startmessage opsi-winst created at CentralForm.FormCreate: 21/01/2015 15:19:25
[1] [Jan 21 15:19:26:673] Loading skin from: C:\Program Files\opsi.org\opsi-client-agent\opsi-winst\winstskin
[1] [Jan 21 15:19:26:673] startmessage StartProgramModes and create log: 21/01/2015 15:19:25
[1] [Jan 21 15:19:26:673] startmessage start opsi service connection: 21/01/2015 15:19:25
[1] [Jan 21 15:19:26:673] JSON Bench for backend_info "params":[],"id":1} Start: 15:19:25:533 Time: 00:00:01:137
[1] [Jan 21 15:19:26:673] startmessage create log: 21/01/2015 15:19:26
[6] [Jan 21 15:19:26:674] JSON service request https://10.200.2.7:4447/rpc getDepotId
[6] [Jan 21 15:19:26:837] JSON Bench for getDepotId "params":["d002.c1.prod.amiab.int"],"id":1} Start: 15:19:26:674 Time: 00:00:00:163
[6] [Jan 21 15:19:26:841] JSON service request https://10.200.2.7:4447/rpc backend_setOptions
[6] [Jan 21 15:19:26:959] JSON Bench for backend_setOptions "params":[{"processProductOnClientSequence":true}] Start: 15:19:26:841 Time: 00:00:00:118
[6] [Jan 21 15:19:26:963] JSON service request https://10.200.2.7:4447/rpc productOnClient_getObjects
[6] [Jan 21 15:19:27:188] JSON Bench for productOnClient_getObjects "params":["",{"clientId":"d002.c1.prod.amiab.int", Start: 15:19:26:963 Time: 00:00:00:225
[6] [Jan 21 15:19:27:192] JSON service request https://10.200.2.7:4447/rpc backend_setOptions
[6] [Jan 21 15:19:27:308] JSON Bench for backend_setOptions "params":[{"processProductOnClientSequence":false} Start: 15:19:27:192 Time: 00:00:00:116
[5] [Jan 21 15:19:27:312] Computername:d002.c1.prod.amiab.int
[5] [Jan 21 15:19:27:312] Computername according to Environment Variable :D002
[5] [Jan 21 15:19:27:312] opsi service URL https://10.200.2.7:4447
[5] [Jan 21 15:19:27:312] Depot path:  p:\
[5] [Jan 21 15:19:27:312] 
[5] [Jan 21 15:19:27:312] bootmode BKSTD
???SHOULD BE SOMETHING HAPPENING IN HERE???
[6] [Jan 21 15:19:27:312] Registry key [HKLM\SOFTWARE\opsi.org\winst]  opened
[6] [Jan 21 15:19:27:312]                 Variable "RebootRequested"  set to "0"
[6] [Jan 21 15:19:27:313]                 Variable "LastLogFilename"  had value  "c:\tmp\opsi-client-agent.log"
[6] [Jan 21 15:19:27:313]                 Info:    "LastLogFilename"  changed to "c:\opsi.org\log\opsi-script.log"
[6] [Jan 21 15:19:27:313]                 Variable "ContinueLogFile"  had value  "1"
[6] [Jan 21 15:19:27:313]                 Info:    "ContinueLogFile"  changed to "0"
[6] [Jan 21 15:19:27:313]                 Variable "NumberOfErrors"  not found. Code: 2
[6] [Jan 21 15:19:27:322]                 Key flushed
[6] [Jan 21 15:19:27:322]                 Key closed
[5] [Jan 21 15:19:27:322] -------- submitted part of log file ends here, see the rest of log file on client ----------
[5] [Jan 21 15:19:27:323] read file created
[5] [Jan 21 15:19:27:323] read file opend
[5] [Jan 21 15:19:27:323] start reading read file ...
[5] [Jan 21 15:19:27:324] write line: >", "d002.c1.prod.amiab.int", "false"], "id": 1}<  to service...
[5] [Jan 21 15:19:27:324] start sending read file ...
[6] [Jan 21 15:19:27:516] JSON service request https://10.200.2.7:4447/rpc backend_exit
[6] [Jan 21 15:19:27:645] JSON Bench for backend_exit "params":[],"id":1} Start: 15:19:27:516 Time: 00:00:00:129

I know the product are requested because if I call "getProductStates_hash", I get this:

Code: Alles auswählen

{"id": 1,

"result": {"d002.c1.prod.amiab.int": [{"lastStateChange": "20150121080506",

"actionRequest": "setup",

"productVersion": "",

"productActionProgress": "",

"packageVersion": "",

"installationStatus": "not_installed",

"productId": "adobeflashplayer"},

{"lastStateChange": "20150121075327",

"actionRequest": "none",

"productVersion": "4.0.5.2",

"productActionProgress": "",

"packageVersion": "2",

"installationStatus": "installed",

"productId": "opsi-client-agent"},

{"lastStateChange": "20150121110159",

"actionRequest": "setup",

"productVersion": "",

"productActionProgress": "",

"packageVersion": "",

"installationStatus": "not_installed",

"productId": "jre"},

{"lastStateChange": "20150121110159",

"actionRequest": "setup",

"productVersion": "",

"productActionProgress": "",

"packageVersion": "",

"installationStatus": "not_installed",

"productId": "adobereader"}]},

"error": null}

Please can anyone tell me why opsi-winst is not attempting to install the products?

opsiconfd-4.0.5.2-1.2
opsi-client-agent-4.0.5.2-2

[realflash]

Update - version of opsi-winst is 4.11.4.12, I believe.

[n.wenselowski]

Hello,

this is very strange. Did you try to restart your Client and then try it again?


~Niko

[realflash]

I have tried that, yes. Looking into the code for opsi-winst, it looks like Produkt.Count is probably 0. Is there way I can change the logging level on opsiconfd to log the contents of inbound and outbound messages, so that I can see that it is telling the client?

[n.wenselowski]

Hallo,

setting the loglevel in the opsiclientd.conf should do the trick. More information in the manual. (There is a part configuration that should be it's own heading in the future - for now you have to manually search it.)


With kind regards

Niko

[realflash]

I have looked in the opsiclientd.log on the desktop, and here's the relevant part from when I sent the on_demand event:

I can see at 13:23:35 that there are products to process as expected.

Code: Alles auswählen

[5] [Jan 23 13:23:25] [ event processing on_demand{user_logged_in}]    [ 1] product adobeflashplayer:    setup   (EventProcessing.pyo|632)
[5] [Jan 23 13:23:25] [ event processing on_demand{user_logged_in}]    [ 2] product jre:                 setup   (EventProcessing.pyo|632)
[5] [Jan 23 13:23:25] [ event processing on_demand{user_logged_in}]    [ 3] product adobereader:         setup   (EventProcessing.pyo|632)

The action processor seems to mount the depot OK

Code: Alles auswählen

[6] [Jan 23 13:23:32] [ action_processor_starter.exe  ] <OPSI.Backend.JSONRPC.JSONRPCBackend instance at 0x0198EAF8>: Connected to service   (JSONRPC.pyo|442)
[6] [Jan 23 13:23:32] [ action_processor_starter.exe  ] Impersonating network account 'pcpatch'   (action_processor_starter.py|98)
[5] [Jan 23 13:23:32] [ action_processor_starter.exe  ] Mounting depot share smb://depot1.pshared.prod.amiab.int/opsi_depot   (action_processor_starter.py|103)
[6] [Jan 23 13:23:33] [ control server                ] Worker <ocdlib.ControlServer.WorkerOpsiclientdJsonRpc instance at 0x039566C0> started processing   (Worker.pyo|249)

And it launches opsi-winst OK and it returns with a 0:

Code: Alles auswählen

[5] [Jan 23 13:23:34] [ action_processor_starter.exe  ] Running command '"C:\Program Files\opsi.org\opsi-client-agent\\opsi-winst\\winst32.exe" /opsiservice "https://10.200.2.7:4447/rpc" /clientid d002.c1.prod.amiab.int /username d002.c1.prod.amiab.int /password *** confidential *** ' as user 'pcpatch' on desktop 'default'   (Windows.pyo|1880)
[6] [Jan 23 13:23:34] [ action_processor_starter.exe  ] Process startet, pid: 3816   (Windows.pyo|1884)
[6] [Jan 23 13:23:34] [ action_processor_starter.exe  ] Waiting for process ending: 3816 (timeout: 10800 seconds)   (Windows.pyo|1887)
[5] [Jan 23 13:23:37] [ action_processor_starter.exe  ] Process 3816 ended with exit code 0   (Windows.pyo|1897)

Where should I look next?

Full log: http://pastebin.com/n0SFB45E

[realflash]

I've now confirmed that when opsi-winst requests a list of products (productOnClient_getObjects), opsiconfd returns the correct thing. I turned the log level up to 8:

Code: Alles auswählen

[7] [Jan 23 10:15:48] Got productOnClients (Backend.py|2987)
[6] [Jan 23 10:15:48] Got result (JsonRpc.py|133)
[8] [Jan 23 10:15:48] RPC ID 15: [u'adobeflashplayer;LocalbootProduct;d002.c1.prod.amiab.int', u'jre;LocalbootProduct;d002.c1.prod.amiab.int', u'adobereader;LocalbootProduct;d002.c1.prod.amiab.int'] (JsonRpc.py|134)
[7] [Jan 23 10:15:48] Sending compressed (level: 1) data (Worker.py|593)

So the focus is on why opsi-winst is not actioning that list.

[d.oertel]

Hi,

I see that the opsiclientd sees the action requests and starts the opsi-script (opsi-winst).
Could you send the complete log of the opsi-winst (opsi-configed tab /log/ instlog) to me
d.oertel(at)uib.de so I may have look what is going wrong.

regards

d.oertel

[realflash]

My first post does contain the whole opsi-winst log. Subject to a bit more testing, I have now resolved this, I think, although I'm not sure how it happened.

I definitely did have the packages I was trying to install appearing on configed - you can see that in the clientd log. It seemed to be that winst was getting different instructions from confd than clientd was. Once I had built winst successfully, I noted in the additional debugging I added that opsi-client-agent was listed and not the others; this caused me to go back to configed, where I found the packages were no longer listed. I re-installed all the packages and everything started working. I don't have enough OPSI knowledge yet to understand what went wrong the first time.

Thank you for trying to help.

[d.oertel]

Hi,

sorry that I not seen the complete log in your first posting.

Yes - indeed the opsi-winst did not got the information that there was an action request and therefore terminated.
And I also have no idea why (and with out reproduction of the error it will be hard to find).

regards

d,oertel