Übertragen der Protokolldatei dauert sehr lange

[Nils]

Hallo zusammen,

seit einiger Zeit habe ich das "Phänomen", dass das Übertragen der Protokolldatei nach Installation einer beliebigen Anwendung sehr lange dauert. Sehr lange bedeutet, dass es teilweise bis zu 10 Minuten dauert.
Die Störung tritt auch unabhängig vom Client auf. Es spielt außerdem keine Rolle, ob der Client schon länger existiert oder gerade frisch installiert wurde.
Kann es evtl. daran liegen, dass der OPSI-Server erst in die Domäne aufgenommen wurde, nachdem er schon in Produktion war?

Leider habe ich bisher keinen Anhaltspunkt, woran es liegen kann, dass das Übertragen so extrem lange dauert. Auch weiß ich leider nicht, wie ich diesem "Fehler" am besten auf die Spur kommen kann.
Ich hoffe sehr, dass ihr mir weiterhelfen könnt!

Viele Grüße, noch einen schönen Tag und vor allem schon mal herzlichen Dank im Voraus
Nils

[d.oertel]

Hi,

Tritt das Problem bei allen Clients auf ?
Tritt das Problem immer auf ?

liefer doch mal:
ein paar Daten zu Deiner Installation (Welche Linux Version, Installierte Server Pakete, Installierter opsi-client-agen, opsi-winst)
Logs für einen Client bei dem das Problem auftritt: opsiconfd, instlog, opsiclientd
und zwar im Umfeld der 'writelog' aufrufe.

gruss
d.oertel

[Nils]

Hallo Herr Dr. Oertel,

vielen Dank für die schnelle Antwort und sorry, dass ich erst heute dazu komme, weitere Infos zu liefern.
Leider kann ich ihre beiden Fragen noch nicht mit Sicherheit beantworten, da die Störung (anscheinend) nur sporadisch und nicht auf allen Clients auftritt.
Ich gebe hier die Logs eines frisch installierten Clients wieder. Der Client wurde per PXE mit den Produkten winxppro sowie hw- und swaudit installiert. Merkwürdigerweise trat hier das o. g. Phänomen bereits nach der "Grundinstallation" auf.

Im opsiclientd.log fand ich Folgendes, was mich stutzig macht, mir jedoch nicht weiter hilft:

[5] [Feb 15 15:15:43] [ event processing gui_startup ] Event config 'on_demand{user_logged_in}' added to event generator 'on_demand' (Events.pyo|1107)
[5] [Feb 15 15:15:43] [ event processing gui_startup ] Updating config file: 'C:\Programme\opsi.org\opsi-client-agent\opsiclientd\opsiclientd.conf' (Config.pyo|322)
[5] [Feb 15 15:15:43] [ event processing gui_startup ] No need to write config file 'C:\Programme\opsi.org\opsi-client-agent\opsiclientd\opsiclientd.conf', config file is up to date (Config.pyo|353)
[5] [Feb 15 15:15:43] [ event processing gui_startup ] Writing log to service (EventProcessing.pyo|256)
[3] [Feb 15 15:25:36] [ event processing gui_startup ] Failed to write log to service: (EventProcessing.pyo|276)
[2] [Feb 15 15:25:36] [ event processing gui_startup ] Traceback: (Logger.pyo|742)
[2] [Feb 15 15:25:36] [ event processing gui_startup ] line 1177 in 'run' in file 'ocdlib\EventProcessing.pyo' (Logger.pyo|742)
[2] [Feb 15 15:25:36] [ event processing gui_startup ] line 272 in 'writeLogToService' in file 'ocdlib\EventProcessing.pyo' (Logger.pyo|742)
[2] [Feb 15 15:25:36] [ event processing gui_startup ] line 1 in 'log_write' in file '<string>' (Logger.pyo|742)
[2] [Feb 15 15:25:36] [ event processing gui_startup ] line 612 in '_jsonRPC' in file 'OPSI\Backend\JSONRPC.pyo' (Logger.pyo|742)
[2] [Feb 15 15:25:36] [ event processing gui_startup ] line 123 in 'execute' in file 'OPSI\Backend\JSONRPC.pyo' (Logger.pyo|742)
[2] [Feb 15 15:25:36] [ event processing gui_startup ] line 135 in 'waitForResult' in file 'OPSI\Backend\Backend.pyo' (Logger.pyo|742)
[2] [Feb 15 15:25:36] [ event processing gui_startup ] ==>>> (EventProcessing.pyo|1179)
[6] [Feb 15 15:25:36] [ opsiclientd ] shutdownRequested: 0 (Windows.pyo|340)
[6] [Feb 15 15:25:36] [ opsiclientd ] rebootRequested: 0 (Windows.pyo|326)
[5] [Feb 15 15:25:36] [ opsiclientd ] Block login now set to 'False' (Opsiclientd.pyo|111)
[6] [Feb 15 15:25:36] [ opsiclientd ] Terminating block login notifier app (pid 1600) (Opsiclientd.pyo|148)
[6] [Feb 15 15:25:36] [ event processing gui_startup ] Stopping notification server (EventProcessing.pyo|234)
[6] [Feb 15 15:25:37] [ control pipe ] Creating pipe \\.\pipe\opsiclientd (ControlPipe.pyo|253)
[5] [Feb 15 15:25:37] [ control pipe ] -----> Executing: getBlockLogin() (JsonRpc.pyo|123)
[5] [Feb 15 15:25:37] [ opsiclientd ] rpc getBlockLogin: blockLogin is 'False' (ControlPipe.pyo|428)
[6] [Feb 15 15:25:37] [ control pipe ] Got result (JsonRpc.pyo|131)
[6] [Feb 15 15:25:38] [ opsiclientd ] client connection lost (Message.pyo|464)
[6] [Feb 15 15:25:39] [ event generator wait_for_gui ] Notification server stopped (Message.pyo|652)
[5] [Feb 15 15:25:42] [ event processing gui_startup ] ============= EventProcessingThread for event 'gui_startup' ended ============= (EventProcessing.pyo|1228)
[5] [Feb 15 15:25:42] [ opsiclientd ] Done processing event '<ocdlib.Events.GUIStartupEvent object at 0x01B57F10>' (Opsiclientd.pyo|418)
[5] [Feb 15 15:25:42] [ opsiclientd ] Deleting local user 'pcpatch' (Opsiclientd.pyo|215)
[6] [Feb 15 15:25:42] [ opsiclientd ] Failed to delete user profile 'pcpatch' (sid S-1-5-21-1343024091-796845957-1644491937-1005): (2, 'DeleteProfile', 'Das System kann die angegebene Datei nicht finden.') (Windows.pyo|1424)
[6] [Feb 15 15:40:13] [ control pipe ] Creating pipe \\.\pipe\opsiclientd (ControlPipe.pyo|253)
[5] [Feb 15 15:40:13] [ event processing gui_startup ] -----> Executing: getBlockLogin() (JsonRpc.pyo|123)
[5] [Feb 15 15:40:13] [ opsiclientd ] rpc getBlockLogin: blockLogin is 'False' (ControlPipe.pyo|428)
[6] [Feb 15 15:40:13] [ event processing gui_startup ] Got result (JsonRpc.pyo|131)

Im opsiconfd erscheinen folgende Einträge (Domain- und IP-Angaben habe ich verfremdet):

[5] [Feb 15 15:15:40] New session created (session.py|74)
[5] [Feb 15 15:15:40] Application 'opsiclientd version 4.0.67' on client 'XXX.XXX.XXX.XXX' supplied non existing session id: 4aghbE2pbM0B1UF9Lwn8jLzcDptx4heh (Worker.py|393)
[5] [Feb 15 15:15:40] Authorization request from host mt20059.yyy-yyy@XXX.XXX.XXX.XXX (application: opsiclientd version 4.0.67) (workers.py|186)
[4] [Feb 15 15:15:40] Failed to read opsi modules file '/etc/opsi/modules': [Errno 2] No such file or directory: u'/etc/opsi/modules' (Backend.py|371)
[5] [Feb 15 15:15:40] -----> Executing: backend_setOptions({u'addConfigStateDefaults': True}) (JsonRpc.py|123)
[4] [Feb 15 15:15:40] Failed to read opsi modules file '/etc/opsi/modules': [Errno 2] No such file or directory: u'/etc/opsi/modules' (Backend.py|371)
[5] [Feb 15 15:15:40] -----> Executing: configState_getObjects([], {'objectId': u'mt20059.yyy-yyy'}) (JsonRpc.py|123)
[4] [Feb 15 15:15:41] Failed to read opsi modules file '/etc/opsi/modules': [Errno 2] No such file or directory: u'/etc/opsi/modules' (Backend.py|371)
[4] [Feb 15 15:19:59] Failed to read opsi modules file '/etc/opsi/modules': [Errno 2] No such file or directory: u'/etc/opsi/modules' (Backend.py|371)
[5] [Feb 15 15:19:59] New session created (session.py|74)
[5] [Feb 15 15:19:59] Application 'opsiclientd version 4.0.67' on client 'XXX.XXX.XXX.XXX' supplied non existing session id: Vux7zM2gSkEryKC0YWQa1Jhj7XRKijYy (Worker.py|393)
[5] [Feb 15 15:19:59] Authorization request from host mt20059.yyy-yyy@XXX.XXX.XXX.XXX (application: opsiclientd version 4.0.67) (workers.py|186)
[4] [Feb 15 15:25:33] Failed to read opsi modules file '/etc/opsi/modules': [Errno 2] No such file or directory: u'/etc/opsi/modules' (Backend.py|371)
[5] [Feb 15 15:25:33] New session created (session.py|74)
[5] [Feb 15 15:25:33] Application 'opsiclientd version 4.0.67' on client 'XXX.XXX.XXX.XXX' supplied non existing session id: Vux7zM2gSkEryKC0YWQa1Jhj7XRKijYy (Worker.py|393)
[5] [Feb 15 15:25:33] Authorization request from host mt20059.yyy-yyy@XXX.XXX.XXX.XXX (application: opsiclientd version 4.0.67) (workers.py|186)
[4] [Feb 15 15:25:33] Failed to read opsi modules file '/etc/opsi/modules': [Errno 2] No such file or directory: u'/etc/opsi/modules' (Backend.py|371)
[5] [Feb 15 15:25:34] User 'mt20059.yyy-yyy' asked to close the session (workers.py|428)
[5] [Feb 15 15:25:34] Session 'GejuFW6brULMuRv8WrsTFuKdSgdelRnl' from ip 'XXX.XXX.XXX.XXX', application 'opsiclientd version 4.0.67' deleted (Session.py|211)

Auf der Registerkarte "clientconnect" im opsi-Configed-DE_de steht für diesen Client gar nichts. Trotz mehrfachem Neuladen des Datenbestandes.

Auf der Registerkarte "instlog" im opsi-Configed-DE_de steht zuletzt:

[1] [15.2.2012 15:14:02] ___________________
[1] [15.2.2012 15:14:02] script finished
[1] [15.2.2012 15:14:02] 0 errors
[1] [15.2.2012 15:14:02] 0 warnings
[1] [15.2.2012 15:14:02]
[1] [15.2.2012 15:14:02] installed Produkt: swaudit Version: 4.0-11
[1] [15.2.2012 15:14:02]
[1] [15.2.2012 15:14:02] product "swaudit set to update
[1] [15.2.2012 15:14:02] Update script name:
[5] [15.2.2012 15:14:02] no script file name given
[1] [15.2.2012 15:14:02] we have no update script

Zum Einsatz kommt bei uns: "Linux opsisrv01 2.6.32-21-generic #32-Ubuntu SMP Fri Apr 16 08:10:02 UTC 2010 i686 GNU/Linux"
opsi-client-agent: Version 4.0.1-25
winst: Version 4.11.2.3-1

Ich hoffe, damit weiterhelfen zu können. Sollten sie weitere Daten benötigen, so lassen sie es mich bitte wissen.

Vielen Dank im Voraus für ihre Hilfe und noch einen schönen Tag.
Viele Grüße
Nils

[Nils]

Hallo nochmals,

soweit ich bisher feststellen konnte, wird im lokalen opsiclientd.log auf dem jeweiligen Client immer folgendes protokolliert, wenn die Störung auftritt:

[5] [Feb 22 07:04:12] [ event processing on_demand ] Writing log to service (EventProcessing.pyo|256)
[3] [Feb 22 07:15:22] [ event processing on_demand ] Failed to write log to service: (EventProcessing.pyo|276)
[2] [Feb 22 07:15:22] [ event processing on_demand ] Traceback: (Logger.pyo|742)
[2] [Feb 22 07:15:22] [ event processing on_demand ] line 1177 in 'run' in file 'ocdlib\EventProcessing.pyo' (Logger.pyo|742)
[2] [Feb 22 07:15:22] [ event processing on_demand ] line 272 in 'writeLogToService' in file 'ocdlib\EventProcessing.pyo' (Logger.pyo|742)
[2] [Feb 22 07:15:22] [ event processing on_demand ] line 1 in 'log_write' in file '<string>' (Logger.pyo|742)
[2] [Feb 22 07:15:22] [ event processing on_demand ] line 612 in '_jsonRPC' in file 'OPSI\Backend\JSONRPC.pyo' (Logger.pyo|742)
[2] [Feb 22 07:15:22] [ event processing on_demand ] line 123 in 'execute' in file 'OPSI\Backend\JSONRPC.pyo' (Logger.pyo|742)
[2] [Feb 22 07:15:22] [ event processing on_demand ] line 135 in 'waitForResult' in file 'OPSI\Backend\Backend.pyo' (Logger.pyo|742)
[2] [Feb 22 07:15:22] [ event processing on_demand ] ==>>> (EventProcessing.pyo|1179)
[6] [Feb 22 07:15:22] [ opsiclientd ] shutdownRequested: 0 (Windows.pyo|340)

Leider helfen mir diese Informationen absolut nicht weiter.
Warum schlug das Schreiben des Logs fehl?
Ich komm da einfach nicht weiter.

Die Störung tritt unabhängig der verwendeten Pakete auf. Auch bei Paketen, die (bisher) ohne Fehler funktionierten und die nicht geändert wurden(!), kommt es zur o. g. Störung.

Vielen Dank im Voraus für eure Tipps, Ratschläge und Hinweise.
Ich wünsche euch noch einen schönen und erfolgreichen Tag.
Viele Grüße
Nils

[ueluekmen]

Hi,

so kommt man dem Problem nicht auf die Spur.

Bitte in der opsiconfd.conf den Loglevel kurz auf 7 setzen, opsiconfd neu starten, dann nochmal dieses Problem reproduzieren und Clientconnect und opsiconfd.log vom Client posten, bitte am besten nur die interessanten Teile.

Klingt zwar jetzt blöd, aber bitte vorher mit

Code: Alles auswählen

df -h

checken, ob Platzprobleme auf der Platte auf dem Server Probleme machen.

Grüße
e. ueluekmen

[Nils]

Moin,

vielen Dank für die schnelle Antwort.

Ich habe nun das LogLevel auf 7 gesetzt, den Dienst neu gestartet und den Fehler reproduziert.

Hier der entsprechende Eintrag aus dem opsiclientd.log des Clients:

[5] [Feb 22 10:36:11] [ event processing on_demand ] Writing log to service (EventProcessing.pyo|256)
[3] [Feb 22 10:47:25] [ event processing on_demand ] Failed to write log to service: [Errno 10053] Eine bestehende Verbindung wurde softwaregesteuert

durch den Hostcomputer abgebrochen (EventProcessing.pyo|276)
[2] [Feb 22 10:47:25] [ event processing on_demand ] Traceback: (Logger.pyo|742)
[2] [Feb 22 10:47:25] [ event processing on_demand ] line 1177 in 'run' in file 'ocdlib\EventProcessing.pyo' (Logger.pyo|742)
[2] [Feb 22 10:47:25] [ event processing on_demand ] line 272 in 'writeLogToService' in file 'ocdlib\EventProcessing.pyo' (Logger.pyo|742)
[2] [Feb 22 10:47:25] [ event processing on_demand ] line 1 in 'log_write' in file '<string>' (Logger.pyo|742)
[2] [Feb 22 10:47:25] [ event processing on_demand ] line 612 in '_jsonRPC' in file 'OPSI\Backend\JSONRPC.pyo' (Logger.pyo|742)
[2] [Feb 22 10:47:25] [ event processing on_demand ] line 123 in 'execute' in file 'OPSI\Backend\JSONRPC.pyo' (Logger.pyo|742)
[2] [Feb 22 10:47:25] [ event processing on_demand ] line 135 in 'waitForResult' in file 'OPSI\Backend\Backend.pyo' (Logger.pyo|742)
[2] [Feb 22 10:47:25] [ event processing on_demand ] ==>>> [Errno 10053] Eine bestehende Verbindung wurde softwaregesteuert

durch den Hostcomputer abgebrochen (EventProcessing.pyo|1179)
[6] [Feb 22 10:47:25] [ opsiclientd ] shutdownRequested: 0 (Windows.pyo|340)

Etwas weiter unten im selben Log finde ich noch:

[5] [Feb 22 10:47:31] [ opsiclientd ] Deleting local user 'pcpatch' (Opsiclientd.pyo|215)
[6] [Feb 22 10:47:31] [ opsiclientd ] Failed to delete user profile 'pcpatch' (sid S-1-5-21-842925246-448539723-1644491937-1031): (2, 'DeleteProfile', 'Das System kann die angegebene Datei nicht finden.') (Windows.pyo|1424)

Leider finde ich unter c:\tmp keinen Hinweis auf "clientconnect". Mag aber sein, dass dies korrekt ist.
Im OPSI Config Editor steht unter "clientconnect" als Letzes:

[5] [Feb 22 09:11:30] [ event processing on_demand ] Writing log to service (EventProcessing.pyo|256)
-------------------- submitted part of log file ends here, see the rest of log file on client --------------------

Leider kein aktuellerer Eintrag.

df -h ergibt Folgendes:

Dateisystem Größe Benut Verf Ben% Eingehängt auf
/dev/sda2 58G 12G 44G 21% /
none 1,5G 176K 1,5G 1% /dev
none 1,5G 0 1,5G 0% /dev/shm
none 1,5G 3,2M 1,5G 1% /var/run
none 1,5G 0 1,5G 0% /var/lock
none 1,5G 0 1,5G 0% /lib/init/rw
/dev/sdb1 148G 42G 99G 30% /opt

Ich hoffe, diese Infos helfen weiter. Mir bedauerlicherweise nicht.

Vielen Dank im Voraus für weitere Tipps, Ratschläge und Hinweise.
Allseits wünsche ich noch einen erfolgreichen Tag.
Viele Grüße
Nils

[ueluekmen]

Hi,

ich würde das Problem systemtisch angehen. Wurde neue Software eingeführt?

Insbesondere im Bereich Antivirus?

Wurden Änderungen in der Infrastruktur vorgenommen, besonders im Netzwerkbereich?

Auch dem Client unter C:\tmp nach besonders großen Logdateien suchen, besonders die opsiclientd.log anschauen.

Das die Übertragung etwas länger dauern kann, kann schon mal vorkommen, aber 11 Minuten ist etwas zuviel des guten. Sind auf diesen Clients andere Netzseitigen Störungen, bzw Auffälligkeiten zu beobachten?

[Nils]

Guten Morgen!

Und vielen Dank für ihre Nachricht.
Zu ihren Fragen:

1.) Es wurde keine neue Software eingeführt. Auch nicht im Bereich Antivirus.
2.) Es wurden keine Änderungen an der Struktur vorgenommen. Weder im Bereich Netzwerk, noch in anderen Bereichen.
3.) Auf dem Client unter c:\tmp fällt lediglich das Logfile "opsi_loginblocker.txt" durch eine Größe von > 6 MB auf. In diesem Log sind Ereignisse vom 20.02.2012 (mittags) bis heute morgen (etwa 6:50 Uhr) protokolliert. Allerdings kann ich hier keine Einträge entdecken, die auf irgendeinen Fehler schließen ließen.
Alle anderen Logfiles in dem genannten Ordner sind max. 600 KB groß.
4.) Auf den Clients sind anderweitig keine Auffälligkeiten zu beobachten.

Heute Morgen habe ich noch einmal die Installation des selben Paketes vorgenommen, welches ich für Testzwecke gestern verwendet habe. Auf dem selben Client.
Merkwürdig dabei ist, dass das Übertragen heute Morgen keine Schwierigkeiten machte und innerhalb etwa einer Minute abgeschlossen war.
Zuvor hatte ich den lokalen Virenscanner auf dem Client deaktiviert. Doch auch bei einem weiteren Test mit aktiviertem Virenscanner war die Störung nicht mehr zu reproduzieren.
Sicherheitshalber habe ich die Installation auch auf einem weiteren Client, auf welchem die Störung gestern reproduzierbar war, wiederholt. Ohne vorher den Virenscanner zu deaktivieren. Ergebnis: Auch hier war die Störung nicht mehr feststellbar.
Ich werde später noch einmal das Testpaket installieren, um festzustellen, ob die Störung zu einem späteren Zeitpunkt wieder auftritt. Das Ergebnis werde ich hier "melden".

Ich werde immer ratloser. Und habe das Gefühl, immer weniger zu verstehen.

Hat jemand noch eine Idee, 1.) woran es liegen könnte und 2.) wie ich dem Verursacher auf die Spur kommen kann?
Was bedeutet der Hinweis im Log

Failed to write log to service: [Errno 10053] Eine bestehende Verbindung wurde softwaregesteuert durch den Hostcomputer abgebrochen (EventProcessing.pyo|276)

?
Ist mit Hostcomputer der Client gemeint? Welche Software (außer Virenscanner) könnte hierfür verantwortlich sein?

Für jeden Tipp, Rat und Hinweis herzlichen Dank im Voraus.
Viele Grüße und einen schönen Tag.
Nils

[ueluekmen]

Hi,

ich würde zusätzlich die Info-Page vom Server genauer unter die Lupe nehmen, vielleicht war der Webservices auch genau zu diesen Zeiten ausgelastet.

Die Meldung weiter unten besagt, dass eine Software auf dem System den Socket gekillt hat (wenn ich es richtig verstehe), warum, weshalb, wieso lässt sich nur raten. Man müsste schon tracen und genau diesen Fall reproduzieren und hoffen, dass man im Wust des trace noch erkennt welches Prozess sich am socket zu schaffen macht. Vielleicht sogar der opsiclientd selbst, obwohl mir kein Timeout bekannt ist, der sowas auslöst.

Da man nicht bei jedem Problem schweres geschütz auffährt (wie oben beschrieben), fängt man erst mal logisch an, nach einem möglichen Störenfried zu suchen. Und die Virensoftware ist immer ein guter Anlaufpunkt für eine solche These, auch andere Programme wie AntiSpam, AntiSpy-Ware, Firewall-App. Ich würde ehrlich gesagt auch Schadsoftware aus der Überlegung nicht ausschliessen!

[Nils]

Hallo!

Vielen Dank für die Tipps.
Inzwischen habe ich noch einmal Testinstallationen mit den beiden "Test"-Clients durchgeführt. Ohne, dass die Störung erneut auftrat.
Ich werde nun weitere Diagnose im Hinblick auf ihre Anregungen vornehmen und mich dann hier wieder melden.

Sollte jemand noch weitere Ratschläge / Hinweise haben, so bin ich natürlich sehr dankbar.

Einen schönen Tag aus dem hohen Norden wünscht
Nils