FHEM Absturz ohne (zuzuordnende) Fehlermeldung im Log nach ca. 43 Tagen Laufzeit

[r00t2]

Hallo zusammen,

gestern Abend hat sich unerwartet mein FHEM verabschiedet.

Meine letzte Änderung am System war (laut Tagebuch) vor ca. 2 Wochen.

Aufgefallen ist es mir nur, weil das Ganglicht nicht mehr auf den Bewegungssensor reagiert hat - ich aber gesehen habe, dass dieser ausgelöst hat.

Also Blick auf den RasPi mit SSH: Betriebssystem läuft noch - FHEM Service nicht.
Nach einem Neustart des RasPi (nur den Service neu zu starten habe ich nicht probiert) scheint alles wieder zu laufen.

Das Log beinhaltet ein paar Fehler, die ich so noch nicht hatte - aber direkt vor dem Absturz ist kein Fehler notiert.

Ich habe des öfteren Probleme mit dem Mail Modul - auch außerhalb des Reconnects meiner Fritzbox. Die Reconnects "umschiffe" ich, in dem ich das Mail Modul großzügig um den Zeitraum des Reconnects disable. Das funktioniert auch wunderbar. Dennoch bekomme ich oft solche Fehler im Log (beim Senden von 222 SELECT INBOX oder 223 IDLE), für die ich noch keine passable Lösung gefunden habe:

Code Auswählen Erweitern

2017.04.06 00:47:50 1: PERL WARNING: Trying command when NOT connected!
LastError was: Error sending '222 SELECT INBOX': NO not connected at
/usr/local/share/perl/5.20.2/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x4c21808), "Error
sending '222 SELECT INBOX': NO not connected") called at
/usr/local/share/perl/5.20.2/Mail/IMAPClient.pm line 1275
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x4c21808),
"SELECT INBOX") called at
/usr/local/share/perl/5.20.2/Mail/IMAPClient.pm line 846
Mail::IMAPClient::select(Mail::IMAPClient=HASH(0x4c21808), "INBOX")
called at ./FHEM/32_mailcheck.pm line 275
main::mailcheck_poll(undef) called at fhem.pl line 2899
main::HandleTimeout() called at fhem.pl line 605

2017.04.06 00:47:50 1: PERL WARNING: Trying command when NOT connected!
LastError was: Error sending '223 IDLE': NO not connected at
/usr/local/share/perl/5.20.2/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x4c21808), "Error
sending '223 IDLE': NO not connected") called at
/usr/local/share/perl/5.20.2/Mail/IMAPClient.pm line 1275
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x4c21808),
"IDLE", "+") called at /usr/local/share/perl/5.20.2/Mail/IMAPClient.pm
line 1119
Mail::IMAPClient::idle(Mail::IMAPClient=HASH(0x4c21808)) called at
./FHEM/32_mailcheck.pm line 276
main::mailcheck_poll(undef) called at fhem.pl line 2899
main::HandleTimeout() called at fhem.pl line 605


Dieses Mal kam jedoch direkt nach dem obigen Fehler ein weiterer Fehler dazu, den ich sonst noch nicht so hatte:

Code Auswählen Erweitern

2017.04.06 00:47:50 1: ERROR: Select error -1 (9), error count= 0
2017.04.06 00:47:50 1: Found and deleted bad fileno for sys_ReceiveMail
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at
character offset 0 (before "Can't connect to map...") at
./FHEM/98_TRAFFIC.pm line 384.

"sys_ReceiveMail" ist die Mail Instanz - aber was hat die mit "98_TRAFFIC.pm" zu tun? Ich habe zwar zwei Instanzen von Google Maps (Traffic) am laufen - diese sind aber nicht mit der Mail Instanz verknüpft.


Der Absturz war dann im Log ziemlich unspektakulär:

Code Auswählen Erweitern

2017.04.06 21:15:00 1: DOIF: Bewegung im Gang erkannt - Ganglicht an für 08:00 min
2017.04.06 21:15:00 3: ZWave set sw_Ganglicht on
2017.04.06 21:18:17 1: DOIF: Bewegungserkennung im Gang rückgesetzt bzw kein relevantes Event
2017.04.06 21:23:00 3: ZWave set sw_Ganglicht off

Danach kam nichts mehr im Log. Die Kombination DOIF + ZWave läuft so schon seit über 1 Monat ohne Probleme.

RAM und System Auslastung sahen am Morgen des Absturztages ganz normal aus:

Code Auswählen Erweitern

System Uptime: 53 days, 17 hours, 17 minutes (FHEM: 42 days, 08 hours, 58 minutes)

Load average: 0.01 0.02 0.00

CPU Temperature: 42.24 °C (average: 42.4 °C)
CPU Frequency Statistic: 600.00 900.00 600.02

Memory (RAM): Total: 925.53 MB, Used: 124.75 MB, 13.48 %, Free: 800.78 MB

File System (boot): Total: 63 MB, Used: 21 MB, 34 %, Available: 43 MB at /boot
File System (root): Total: 7385 MB, Used: 1696 MB, 25 %, Available: 5360 MB at /

Infos über das FHEM System:

Code Auswählen Erweitern

2017.04.06 22:52:29 0: Featurelevel: 5.7
2017.04.06 22:52:29 0: Server started with 87 defined entities
(fhem.pl:12966/2017-01-05 perl:5.020002 os:linux user:fhem pid:489)

Momentan kann ich mir keinen Reim drauf machen, warum der Absturz aufgetreten ist oder was Mail mit Traffic zu tun haben soll.
Hat von euch jemand eine Idee?

Update: Hier sind die Defines der scheinbar "Beteiligten".

sys_ReceiveMail:

Code Auswählen Erweitern

defmod sys_ReceiveMail mailcheck imap.googlemail.com adresse@googlemail.com Passwort
attr sys_ReceiveMail group FHEM Services
attr sys_ReceiveMail room System

DOIF time_ReceiveMail_Disable_by_Timespan (disabled Mail über die Zeit des Disconnects):

Code Auswählen Erweitern

defmod time_ReceiveMail_Disable_by_Timespan DOIF ([03:50 - 05:10]) (set sys_ReceiveMail inactive) DOELSE (set sys_ReceiveMail active)
attr time_ReceiveMail_Disable_by_Timespan room Zeitsteuerung

setstate time_ReceiveMail_Disable_by_Timespan cmd_2
setstate time_ReceiveMail_Disable_by_Timespan 2017-04-07 05:10:01 cmd 2
setstate time_ReceiveMail_Disable_by_Timespan 2017-04-07 05:10:01 cmd_event timer_2
setstate time_ReceiveMail_Disable_by_Timespan 2017-04-07 05:10:01 cmd_nr 2
setstate time_ReceiveMail_Disable_by_Timespan 2017-04-07 05:10:01 state cmd_2
setstate time_ReceiveMail_Disable_by_Timespan 2017-04-07 05:10:01 timer_01_c01 08.04.2017 03:50:00
setstate time_ReceiveMail_Disable_by_Timespan 2017-04-07 05:10:01 timer_02_c01 08.04.2017 05:10:00

Traffic Instanz 1 und 2 sehen jeweils so aus (nur mit unterschiedlichen Adressen):

Code Auswählen Erweitern

defmod tra_1 TRAFFIC API_KEY 900
attr tra_1 userattr end_address icon outputReadings start_address verbose
attr tra_1 end_address Adresse
attr tra_1 group Verkehr
attr tra_1 icon hue_room_driveway
attr tra_1 outputReadings text
attr tra_1 room Verkehr
attr tra_1 start_address Adresse
attr tra_1 verbose 1

setstate tra_1 OK
setstate tra_1 2017-04-07 12:22:48 delay 0 min
setstate tra_1 2017-04-07 12:22:48 distance 49.6 km
setstate tra_1 2017-04-07 12:22:48 duration 36 mins
setstate tra_1 2017-04-07 12:22:48 duration_in_traffic 35 mins
setstate tra_1 2017-04-07 12:22:48 eta 12:57:59
setstate tra_1 2017-04-07 12:22:48 state OK
setstate tra_1 2017-04-07 12:22:48 status OK

[viegener]

Aus den Informationen kann ich auch nicht herauslesen, was Deinen Server zum Absturz gebracht hat.

Ich würde annehmen, dass die Fehlermeldungen nicht mit dem Absturz zusammenhängen. Es sind zwar Fehler aber warum sollte dann unvermittelt 20 Stunden später der Server abstürzen. Auch das inaktivieren eines devices (das Modul wird ja nicht disabled) ist doch normale Funktion und sollte keinen Absturz erzeugen.
Insofern vermute ich keinen Zusammenhang

Die Fehlermeldungen zu Traffic und Mail stehen auch nur untereinander im log es gibt keinen direkten Zusammenhang.

Bist Du wirklich sicher, dass FHEM nicht hing sondern wirklich weg war?

Meine Empfehlung:
- Filesystem prüfen
- Die Fehlermeldungen angehen, denn schön sind die nicht und das sollte auch nicht so sein
- Abwarten und Tee trinken (vielleicht das loglevel global etwas erhöhen)

[r00t2]

Danke für Deine Antwort!

Ich würde annehmen, dass die Fehlermeldungen nicht mit dem Absturz zusammenhängen. Es sind zwar Fehler aber warum sollte dann unvermittelt 20 Stunden später der Server abstürzen. Auch das inaktivieren eines devices (das Modul wird ja nicht disabled) ist doch normale Funktion und sollte keinen Absturz erzeugen....

War auch das erste Mal, dass ich so etwas erlebt habe.

...Die Fehlermeldungen zu Traffic und Mail stehen auch nur untereinander im log es gibt keinen direkten Zusammenhang...

Bist Du Dir da sicher? Diese Meldung hier beinhaltet doch beide Module in einem Zeitstempel:

Code Auswählen Erweitern

2017.04.06 00:47:50 1: Found and deleted bad fileno for sys_ReceiveMail
malformed JSON string, neither array, object, number, string or atom, at character offset 0 (before "Can't connect to map...") at ./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at character offset 0 (before "Can't connect to map...") at ./FHEM/98_TRAFFIC.pm line 384.
malformed JSON string, neither array, object, number, string or atom, at character offset 0 (before "Can't connect to map...") at ./FHEM/98_TRAFFIC.pm line 384.
...

Normalerweise bekommt doch jede Meldung einen extra Zeitstempel, auch wenn sie "zeitgleich" mit noch anderen Meldungen auf dem Meldestack liegen sollte.
Oder wurden da einfach - aus welchem Grund auch immer - keine Zeitstempel mehr davor geschrieben?

...Bist Du wirklich sicher, dass FHEM nicht hing sondern wirklich weg war?...

Der Prozess (weder Perl noch FHEM) war in der Liste von top nicht mehr ersichtlich. Kann aber wirklich sein, dass er so weit unten gestanden hätte, dass ich ihn nur mit einem ps -A hätte sehen können (was ich nicht probiert habe).

...Meine Empfehlung:
- Filesystem prüfen
- Die Fehlermeldungen angehen, denn schön sind die nicht und das sollte auch nicht so sein
- Abwarten und Tee trinken (vielleicht das loglevel global etwas erhöhen)

- FS ist clean
- Die Mail Meldungen treten wieder auf und ich habe noch immer keinen Ansatzpunkt, wie ich sie abstellen kann, da sie scheinbar sporadisch zu nicht vorhersagbaren Zeiten auftreten. Manchmal läuft es auch 2 Tage lang ohne eine Meldung durch.
- Gute Idee In knapp 1.5 Monaten wissen wir mehr

[Thorsten Pferdekaemper]

Normalerweise bekommt doch jede Meldung einen extra Zeitstempel, auch wenn sie "zeitgleich" mit noch anderen Meldungen auf dem Meldestack liegen sollte.
Oder wurden da einfach - aus welchem Grund auch immer - keine Zeitstempel mehr davor geschrieben?

Zeitstempel gibt es nur, wenn die Meldung "sauber" über die FHEM-Mechanismen geschrieben wird. Wenn aber ein Modul das einfach per print oder so raushaut, dann wird es einfach so in's Log geschrieben. Dasselbe passiert normalerweise, wenn eine verwendete Bibliothek eine Meldung rausschreibt.
Ich würde mal behaupten, dass 98_TRAFFIC.pm an der Stelle zumindest etwas unsauber ist, da es den Fehler wohl nicht vorher abfängt.
Gruß,
   Thorsten

[r00t2]

Danke für die Info, Thorsten!

Habe mal in meinem Google API Dashboard nachgesehen: Im besagten Zeitraum wurden keine Fehler gemeldet, was die API angeht. Aber man sieht, dass die Requests zum fraglichen Zeitpunkt ausbleiben.

Werde mal schauen, ob zu diesem Zeitpunkt ggf. meine Internetverbindung bzw. die Verbindung zum Router gestört war und das vielleicht die Ursache der Meldungen gewesen sein könnte.

Werde wohl für die Zukunft mal ein zusätzliches Presence Modul mit Ping auf einen externen Server anlegen, um zu sehen, ob die Internetverbindung stabil ist. Oder kann Presence wirklich nur LAN IPs pingen und keine externen (wie z. B. 8.8.8.8 )?

[Wuppi68]

könnte auch die SD Karte sein ...

lese am besten einmal die komplette SD aus ( dd if=/dev/<Dein SD Device> of=/dev/null bs=1M -conf=noerror ) und schaue ob es Fehlermeldungen oder Timingaussetzer gibt

[r00t2]

Heute waren schon wieder Aussetzer

FHEM Service ist gelaufen aber diesmal hat ZWave nicht mehr funktioniert (weder Senden noch Empfangen) und die WebGUI nicht mehr reagiert, wenn man sich z. B. die preprocessed Data eines Plots ansehen wollte.

Event Monitor lief aber durch und hat aktualisiert...

Kann es sein, dass das FHEMWeb standardmäßig nur 6 parallele Verbindungen von der gleichen IP zur WebGUI zulässt? Also sprich: Ich kann mit dem Browser 6 FHEM Tabs parallel öffnen und ab dem 7. tut sich nichts mehr - der Rest läuft aber normal weiter.

@Wuppi68:
Kann/soll ich das dd nach /dev/null verwenden, wenn das System produktiv läuft oder nur, wenn die SD Karte in einer anderen Linux Box gemounted ist?

[Wuppi68]

@Wuppi68:
Kann/soll ich das dd nach /dev/null verwenden, wenn das System produktiv läuft oder nur, wenn die SD Karte in einer anderen Linux Box gemounted ist?

Sollte kein Problem sein - es wird ja nur von der SD gelesen .... geschrieben ins Nirwana .... und es wird ein wenig auf die Bremse getreten ...

nimm am besten das RAW Device von der SD - /dev/mmcblk0

vielleicht noch parallel dazu die System Logiles beobachten

[dev0]

Kann es sein, dass das FHEMWeb standardmäßig nur 6 parallele Verbindungen von der gleichen IP zur WebGUI zulässt?

Das ist eine Einschränkung des/der Browser, FHEM kann daran nichts ändern. Läßt sich bspw. durch unterschiedliche DNS Namen umgehen.

[frank]

Kann es sein, dass das FHEMWeb standardmäßig nur 6 parallele Verbindungen von der gleichen IP zur WebGUI zulässt? Also sprich: Ich kann mit dem Browser 6 FHEM Tabs parallel öffnen und ab dem 7. tut sich nichts mehr - der Rest läuft aber normal weiter.

bei firefox lässt sich das auch irgendwo konfigurieren.

[r00t2]

Sollte kein Problem sein - es wird ja nur von der SD gelesen .... geschrieben ins Nirwana .... und es wird ein wenig auf die Bremse getreten ...

nimm am besten das RAW Device von der SD - /dev/mmcblk0

vielleicht noch parallel dazu die System Logiles beobachten

Werde ich über die Ostertage mal angehen und dann berichten. Danke Dir!
Hatte eh vor, mal ein komplettes Backup der SD Karte zu erstellen.

@dev0 & frank: Danke für den Input. Ist mir so nur noch nie aufgefallen bei anderen Seiten (ich kann z. B. viel mehr als nur 6 Wikipedia Seiten in Tabs offen haben und es "läuft" dennoch alles weiter wie gewohnt).

Habe den Mailempfang jetzt erst mal komplett deaktiviert und die global verbosity auf 4 erhöht.

[frank]

@dev0 & frank: Danke für den Input. Ist mir so nur noch nie aufgefallen bei anderen Seiten (ich kann z. B. viel mehr als nur 6 Wikipedia Seiten in Tabs offen haben und es "läuft" dennoch alles weiter wie gewohnt).

bei fhem bleiben die verbindungen/connections für jeden tab offen, also x parallele verbindungen zur selben domain.
bei wikipedia werden sie wahrscheinlich nach der datenübertragung wieder geschlossen.