WAN-Erweiterung seit OPSI 4.2 instabil

[magicalUnicorn]

Hallo Zusammen,

nach dem Upgrade auf OPSI 4.2 sind mir einige weitere Probleme aufgefallen. Diesmal in Verbindung mit der WAN-Erweiterung:

1. Das installieren von großen Paketen übers VPN verbraucht beim caching jetzt nicht mehr den gesamten RAM des Servers und bringt ihn so zum Absturz, was soweit sehr gut ist. Allerdings scheint der OPSI-Client auf den Rechnern das ganze bei großen Paketen (~20GB) dann nicht mehr richtig zu registrieren, wenn die Übertragung abgeschlossen ist. Er setzt dadurch keinen Neustart an und markiert das Paket auch nicht als vollständig gecached, obwohl alles komplett übertragen ist. Das ist in ca 90% der Tests der Fall gewesen, sehr selten gab es dann auch mal eine erfolgreiche Installation.

2. Die Notification, die in der unteren rechten Ecke angezeigt wird und um einen Neustart bittet, verschwindet bereits nach wenigen Sekunden wieder. Ich bin mir recht sicher, dass das bei OPSI 4.1 noch dauerhaft angezeigt wurde, bis der Rechner entweder neugestartet oder die Aktion aufgeschob wurde. Klar ich könnte den entsprechenden Hostparameter ändern, damit die Meldung öfter angezeigt wird, aber dann beschweren sich die User, die den Neustart aus guten Gründen aufschieben.

3. Der OPSI-Client scheint die entsprechenden Pakete beim Start nur zu installieren, wenn vorher über die Notification der Neustart ausgelöst wurde. Schiebe ich die Aktion auf und starte den Rechner anschließend manuell neu, findet keine Installation der Pakete im Zwischenspeicher statt.

Das sind die Probleme, die mir bisher aufgefallen sind. Eventuell gibt es ja für manche der Probleme (vor allem 2. und 3.) auch einfach neue Hostparameter, die ich bisher einfach übersehen habe.

Viele Grüße

[ThomasA]

Hallo,

bezüglich der Instabilität würde ich mich mal generell anschliessen, obwohl ich den Punkt 2 so nicht nachvollziehen kann. Aber da haben wir die Parameter für die Anzeigedauer auch selber angepasst.

Wir haben aber mit den neuesten client-Agent Versionen das Problem, dass er beim Neustart nach dem Cachen nur kurz das Opsi Fenster anzeigt, aber dann wieder schließt und keine Aufforderung zur Installation erscheint. Das führt dann ggf. zu Neustart-Schleifen durch das cachen, welches direkt danach wieder beginnt.
Ggf. hängt es auch mit dem hier berichteten Problem zusammen, dass der gui_startup event ausgeführt wird, obwohl der entsprechende Hostparameter auf "false" gesetzt ist. Zumindest sehe ich diesen event auch kurz aufblitzen.

Zusätzlich fällt mir derzeit auch eine deutlich höhere Rate an "failed: cached" Reports auf. Das legt sich dann mit der Zeit, aber gefühlt waren das bei älteren Versionen des Client Agents (oder mit der Version 4.1) deutlich weniger.

Gruß
Thomas

[magicalUnicorn]

Hi THomas,

schonmal gut zu wissen, dass das nicht alles EInbildung ist Welchen Parameter nutzt ihr zur Konfiguration der Anzeigedauer? opsiclientd.event_sync_completed{cache_ready_user_logged_in}.shutdown_warning_time oder gibts da noch einen anderen?

Das im von dir verlinkten Post beschriebene Problem kann ich genau so bestätigen. Ich konnte zuerst nicht den Finger auf die Ursache legen, warum das Timer Event scheinbar nicht mehr ordentlich ausgeführt ist, aber ich kann es genau wie im Thread beschrieben replizieren.

[j.schneider]

Hallo!

Um der Sache nachgehen zu können bräuchten wir mal eine opsiclientd.log von dem Zeitraum, in dem der notifier nur kurz erschienen ist.

Grüße

[magicalUnicorn]

Hi,

danke schonmal für die schnelle Antwort. Kann ich euch das Log einfach an info@uib zukommen lassen mit verweis auf den Thread?

Viele Grüße

Edit: Als Nachtrag eventuell noch folgende Info: Die Notification wird für <60 Sekunden angezeigt, verschwindet dann und wird (wenn nicht "aufschieben" ausgewählt wird) dann nach einiger Zeit wieder angezeigt. Das Timer-Event ist bei mir mit 60 Sekunden (zum testen) recht kurz konfiguriert. Eventuell spielt das da mit rein?

[j.schneider]

Ja, gerne per Mail.
Timer mit 60 Sekunden ist selbst zum Testen definitiv zu kurz!

[ThomasA]

Welchen Parameter nutzt ihr zur Konfiguration der Anzeigedauer? opsiclientd.event_sync_completed{cache_ready_user_logged_in}.shutdown_warning_time oder gibts da noch einen anderen?

Wir haben folgende Parameter gesetzt, die da ggf. Einfluss haben könnten:

Code: Alles auswählen

opsiclientd.event_sync_completed{cache_ready_user_logged_in}.shutdown_warning_repetition_time 21600
opsiclientd.event_sync_completed{cache_ready_user_logged_in}.shutdown_warning_time 21600
opsiclientd.event_software_on_demand.shutdown_warning_time 3600

Unser Timer Event wird übrigens ausgeführt, da haben wir scheinbar aktuell kein Problem.

Um der Sache nachgehen zu können bräuchten wir mal eine opsiclientd.log von dem Zeitraum, in dem der notifier nur kurz erschienen ist.

Und wenn ich mir das über die client daemon info page nochmal anschaue, ist der gui_startup event vielleicht dann doch garnicht so falsch denn dort steht:

Code: Alles auswählen

Processing event gui_startup
EventProcessingThread for occurrcence of event 'gui_startup{cache_ready}' (Thread-18) started
Wed, 02 Feb 2022 15:12:13 GMT
Wed, 02 Feb 2022 15:12:23 GMT

Processing of event gui_startup canceled
Processing of event (Thread-18) canceled
Wed, 02 Feb 2022 15:12:19 GMT

Edit: man sollte schon am gleichen Tag schauen
Im Log ist um diese Zeit folgendes:

Code: Alles auswählen

[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'gui_startup' added to event generator 'gui_startup'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'gui_startup{cache_ready}' added to event generator 'gui_startup'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'gui_startup{installation_pending}' added to event generator 'gui_startup'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'gui_startup{user_logged_in}' added to event generator 'gui_startup'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'on_demand' added to event generator 'on_demand'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'on_demand{user_logged_in}' added to event generator 'on_demand'   (Generators.py:146)
[6] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Cannot reconfigure event generator for event 'on_shutdown': not found   (Generators.py:137)
[6] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Cannot reconfigure event generator for event 'on_shutdown{installation_pending}': not found   (Generators.py:137)
[6] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Cannot reconfigure event generator for event 'opsiclientd_start': not found   (Generators.py:137)
[6] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Cannot reconfigure event generator for event 'opsiclientd_start{cache_ready}': not found   (Generators.py:137)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'silent_install' added to event generator 'silent_install'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'software_on_demand' added to event generator 'software_on_demand'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'sync_completed' added to event generator 'sync_completed'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'sync_completed{cache_ready_user_logged_in}' added to event generator 'sync_completed'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'sync_completed{cache_ready}' added to event generator 'sync_completed'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'timer' added to event generator 'timer'   (Generators.py:146)
[6] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Cannot reconfigure event generator for event 'timer_silentinstall': not found   (Generators.py:137)
[6] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Cannot reconfigure event generator for event 'user_login': not found   (Generators.py:137)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'vpn_connection' added to event generator 'vpn_connection'   (Generators.py:146)
[5] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Event config 'net_connection' added to event generator 'net_connection'   (Generators.py:146)
[6] [2022-02-02 15:12:19.852] [event processing gui_startup{cache_ready}] Updating config file: 'C:\Program Files (x86)\opsi.org\opsi-client-agent\opsiclientd\opsiclientd.conf'   (Config.py:505)
[6] [2022-02-02 15:12:19.868] [event processing gui_startup{cache_ready}] No need to write config file 'C:\Program Files (x86)\opsi.org\opsi-client-agent\opsiclientd\opsiclientd.conf', config file is up to date   (Config.py:571)
[5] [2022-02-02 15:12:19.868] [event processing gui_startup{cache_ready}] Writing log to service   (EventProcessing.py:289)
[6] [2022-02-02 15:12:19.882] [event processing gui_startup{cache_ready}] JSONRPC request to https://127.0.0.1:4441/rpc: ip_version=4, id=6, method=backend_exit, Content-Type=application/json, Content-Encoding=, timeout=60   (jsonrpc.py:399)
[6] [2022-02-02 15:12:19.882] [control server                          ] Worker <opsiclientd.ControlServer.WorkerCacheServiceJsonRpc object at 0x073EC130> started processing   (Worker.py:227)
[6] [2022-02-02 15:12:19.882] [control server                          ] Reusing session for client '127.0.0.1', application 'opsiclientd/4.2.0.99'   (Worker.py:360)
[5] [2022-02-02 15:12:19.882] [                                        ] -----> Executing: backend_exit()   (JsonRpc.py:106)
[6] [2022-02-02 15:12:19.882] [                                        ] Got result for backend_exit   (JsonRpc.py:114)
[6] [2022-02-02 15:12:19.882] [event processing gui_startup{cache_ready}] Got response status=200, Content-Type=application/json; charset=utf-8, Content-Encoding=gzip, duration=0.000s   (jsonrpc.py:411)
[5] [2022-02-02 15:12:19.882] [event processing gui_startup{cache_ready}] Processing of event <opsiclientd.Events.GUIStartup.GUIStartupEvent object at 0x055C6150> canceled   (EventProcessing.py:1719)
[6] [2022-02-02 15:12:19.882] [                                        ] Stopping notification server   (EventProcessing.py:261)
[6] [2022-02-02 15:12:20.923] [control server                          ] Client connection lost: <NotificationServerProtocol #1 on 44000> ([Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion.
]), 1 client(s) connected   (Message.py:493)
[6] [2022-02-02 15:12:20.924] [control server                          ] Client connection lost: <NotificationServerProtocol #0 on 44000> ([Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion.
]), 0 client(s) connected   (Message.py:493)
[5] [2022-02-02 15:12:20.967] [control pipe                            ] Client connected to \\.\pipe\opsiclientd   (ControlPipe.py:466)
[6] [2022-02-02 15:12:20.967] [control pipe                            ] Received request '{"id": 1, "method": "registerClient", "params": ["opsi-login-blocker","4.2.0.0"]}' from <NTPipeClientConnection #2>   (ControlPipe.py:72)
[6] [2022-02-02 15:12:20.967] [control pipe                            ] Client <NTPipeClientConnection #2> info set to: ['opsi-login-blocker', '4.2.0.0']   (ControlPipe.py:109)
[6] [2022-02-02 15:12:20.967] [control pipe                            ] Sending response '{"id": 1, "result": "client opsi-login-blocker/4.2.0.0/#2 registered", "error": null}' to <NTPipeClientConnection #2>   (ControlPipe.py:74)
[6] [2022-02-02 15:12:21.501] [control pipe                            ] Sending request '{"id": 1, "method": "blockLogin", "params": [true]}' to client <NTPipeClientConnection #2>   (ControlPipe.py:150)
[6] [2022-02-02 15:12:22.018] [control pipe                            ] Received response '{"id": 1, "result": "blocking login", "error": null}' from client <NTPipeClientConnection #2>   (ControlPipe.py:156)
[6] [2022-02-02 15:12:22.883] [control server                          ] Notification server stopped   (Message.py:694)
[5] [2022-02-02 15:12:22.906] [event processing gui_startup{cache_ready}] Block login now set to 'False'   (Opsiclientd.py:192)

Gruß
Thomas

[wolfbardo]

Code: Alles auswählen

Processing event gui_startup
EventProcessingThread for occurrcence of event 'gui_startup{cache_ready}' (Thread-18) started
Wed, 02 Feb 2022 15:12:13 GMT
Wed, 02 Feb 2022 15:12:23 GMT

Processing of event gui_startup canceled
Processing of event (Thread-18) canceled
Wed, 02 Feb 2022 15:12:19 GMT

sieht nach einem Bug aus, der in

opsi-client-agent 4.2.0.20-1

opsi-client-agent 4.2.0.20-1, opsi-linux-client-agent 4.2.0.14-1 und opsi-mac-client-agent 4.2.0.9-1 beheben einen Bug im Event-Handling, welches bei zeitgleichem Ausführen meherer Events (z.B. gui_startup und net_connection) zu Problem führen kann.

behoben ist.

Gruss
Bardo Wolf

[magicalUnicorn]

Ja, gerne per Mail.
Timer mit 60 Sekunden ist selbst zum Testen definitiv zu kurz!

Gut dann stell ich erstmal das Timer-Event hoch, und gucke ob sich das Problem dadurch erledigt, bevor ich euch Logs zuschicken. Ricky in diesem viewtopic.php?t=12777 hat den Timer ja auch auf 60 Sekunden gestellt

[magicalUnicorn]

Ich hab den Timer jetzt mal auf 30 MInuten umgestellt. Das hat dann zur Folge, dass die Notification länger angezeigt wird (ziemlich genau 30 Minuten +/-) und dann durch eine neue Notification ersetzt wird, bei der der Timer aber wieder von vorne beginnt.

Ich hab euch das entsprechende Log grade mal per Mail zukommen lassen.