Hurra! Mein erster WF Absturz!
Spaß beiseite … gestern hing das WF bei mir das erste Mal überhaupt und zwar komplett. Gezeigt hat es sich wie schon von BestEx beschrieben:
Interessant war, dass ich den Absturz wahrscheinlich ursächlich selbst ausgelöst habe. Bei Arbeiten im Verteilerkasten hatte ich einen Stromkreis abgeschaltet (ja, man kann durchaus den Strom dafür abschalten :o) der ein Device versorgt welches ich per SNMP alle 5 min. abfrage.
IPS hat also für einen längeren Zeitraum ins Leere gegriffen aber das auch schön im Log protokolliert und die entsprechenden Warn-Mails über den Logger versendet (ca. 200).
Angefangen hat es so:
23.09.2012 15:17:07.058 | 0 | CUSTOM | PHP | Error: Warning: snmpget(): No response from 192.168.xxx.xxx
Error in Script D:\IP-Symcon\scripts\27505.ips.php on Line 7
133 in IPSLibrary\app\core\IPSLogger\IPSLogger.inc.php (call IPSLogger_Out)
36 in IPSLibrary\app\core\IPSLogger\IPSLogger_PhpErrorHandler.inc.php (call IPSLogger_Err)
in IPSLogger_PhpErrorHandler
7 in 27505.ips.php (call snmpget)
Seltsam wurde es dann hier (die Access Violation zur „ntdll.dll“ macht mir Kopfschmerzen …):
Warning: snmpget(): No response from 192.168.xxx.xxx in D:\IP-Symcon\scripts\16533.ips.php on line 7
Warning: Cannot auto-convert to Float from Variant. Error: Could not convert variant of type (String) into type (Double) in D:\IP-Symcon\scripts\16533.ips.php on line 10
23.09.2012 15:30:07.582 | 16533 | DEBUG | ExecuteThreadID #9 | Ausgeführt, Resultat: 1, Erfolgreich: True, Zeit: 4085 ms
23.09.2012 15:30:08.016 | 14588 | MESSAGE | VariableManager | [Program\IPSLibrary\data\core\IPSLogger\IPSLogger\SingleOut_Msg] = <div style="color:#000000;background:#FF0000;">Error: Warning: snmpget(): No response from 192.168.xxx.xxx
Error in Script ...
23.09.2012 15:30:08.017 | 49192 | WARNING | ExecuteThreadID #10 | Fehler beim Ausführen des Skripts (49192.ips.php): Access violation at address 77C8E3BE in module 'ntdll.dll'. Read of address 18DACE35
23.09.2012 15:30:08.017 | 49192 | DEBUG | ExecuteThreadID #10 | Ausgeführt, Resultat: -1, Erfolgreich: False, Zeit: 4015 ms
Das bittere Ende sah dann so aus:
23.09.2012 17:34:27.001 | 22861 | DEBUG | ExecuteThreadID #3 | Skriptausführung: IPSLogger_SendMail.ips.php ~ Absender: Ereignis #37518, Zeit Ereignis
23.09.2012 17:34:27.001 | 22861 | WARNING | ExecuteThreadID #3 | Fehler beim Ausführen des Skripts (IPSLogger_SendMail.ips.php): Access violation at address 72CD151D in module 'php5ts.dll'. Read of address 00000001
23.09.2012 17:34:27.001 | 22861 | DEBUG | ExecuteThreadID #3 | Ausgeführt, Resultat: -1, Erfolgreich: False, Zeit: 0 ms
23.09.2012 17:34:28.503 | 0 | WARNING | Kernel | Service Shutdown requested!
23.09.2012 17:34:28.503 | 0 | MESSAGE | Kernel | *** IPS HERUNTERFAHREN
23.09.2012 17:34:28.506 | 0 | MESSAGE | Kernel | Deinitialisiere...
23.09.2012 17:34:28.506 | 0 | MESSAGE | EventManager | Warte auf Terminierung des Ereignisthread...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.606 | 0 | MESSAGE | TimerPool | Warte auf Terminierung des Timerthreads...
23.09.2012 17:34:28.706 | 0 | MESSAGE | ScriptEngine | Warte auf Terminierung des Threads 1... Sender: Ereignis #23224, Zeit Ereignis
23.09.2012 17:35:38.162 | 27914 | MESSAGE | HomeMatic Socket | Socket (Data Radio) - Disconnected
23.09.2012 17:35:38.366 | 27914 | MESSAGE | HomeMatic Socket | Socket (Data Wired) - Disconnected
Der Shutdown war unsauber. Sprich: ich musste den Dienst aus dem Status "Wird beendet… "per Taskmanager erlösen. Nach Neustart, Wiederherstellung der Konnektivität und nachdem sich die Settings wieder berappelt hatte lief alles wieder wunderbar. Bisher konnte ich keinen Datenverlust feststellen.
Ich konnte wg. des rapide sinkenden WAF-Wertes während des Hängers leider dann nicht mehr tiefgreifender analysieren :mad: Ich tendiere fast dazu, dem Logger die Schuld in die Schuhe zu schieben, die „ntdll.dll“ passt nur nicht wirklich ins Bild. Das deutet fast auf ein wie auch immer geartetes Problem mit dem Speicher/der Speicherverwaltung hin. Wenn gewünscht stelle ich den Wissenden aber natürlich gerne das/die/weitere Logfiles zur Verfügung.
Cheers
/Jens