Tipps fürs debuggen gesucht - fhem hängt sich auf

[Elektrolurch]

Hallo Rudi,
werde ich versuchen.
Mir ist aber noch etwas aufgefallen:
Bei manchen "Hängenbleibern" gibt es zusätzlich ein fhem-logfile mit Datum 1.1.1970, leerem Inhalt, kein Änderungs- oder Erstellungsdatum.
1.1.1970 ist ja das Unix-Urdatum. Aus irgendeinem Beitrag habe ich noch in Erinnerung, dass fhem auf einer FB nicht startet, wenn das Datum nicht gesetzt ist.
Könnte es vielleicht sein, das der ntp - Dienst auf der FB gelegentlich Mist zurückliefert und daher fhem dann  hängenbleibt?
Wenn fhem ja läuft, so sagt strace, dass es meistens zwischen select und time() "herumkurvt".

Wie gesagt: Die fhem-1970-1-1.log - Datei ist nicht bei jedem Hängenbleiber vorhanden.
So drei oder vier Mal war sie da.

Gruß


Elektrolurch

[rudolfkoenig]

Klingt merkwuerdig.
NTP setzt nicht die Zeit ohne weiteres, und schon gar nicht aut 1970.
Bist Du sicher, dass das FB nicht ein reboot durchgefuehrt hat (siehe uptime)?

[P.A.Trick]

Das mit der 1970er Zeit habe ich auf meiner 7390 auch nachdem die Fritte neustartet und fhem
vor der DSL Synchronisation startet. Sieht so aus, als ob die Fritte einfach im Betrieb abraucht. Vielleicht ein Memory Problem?

[Elektrolurch]

Hallo,
leider nicht. Die FB läuft ohne Neustart durch. Habe gerade mal die ganzen Ereignisanzeigen durchgesehen.  Der letzte Eintrag, welche was mit Zeit zu tun hat, ist vom 25.6., da stteht, dass die Zeit erfolgreich synchronisiert wurde.
Heute ist fhem um 11:42 Uhr(wurde dann durch meinen watchdog neu gestartet) und dann wieder gegen 14:00 Uhr hängengeblieben. Im Ereignisprotokoll der FB gibt es um die besagten Zeiten keinerlei Ereignisse, rein gar nichts.
Jetzt läuft fhem mit "attr global verbose 5". Habe den Standardlogfilenamen auf "tagesweise" log umgestellt, damit ich dann die unnötigen Infos nach 24 h löschen kann. Mal sehen, wie lange fhem jetzt durch läuft.
Können auch 3 Tage werden, ist nicht vorhersehbar.
Bin für jeden Tipp dankbar.

Gruß

Elektrolurch

[Elektrolurch]

Hallo,

da das Hängenbleiben von fhem nur sporadisch passiert, war das Einkreisen einr möglichen Ursache schwierig.
Seit dem ich attr global verbose 5 gesetzt hatte, blieb fhem nur einmal Hängen. So wie das aussieht, (s.u.) liegt es u.U. an dem 10_FBDECT - Modul.
Ich habe eine dect200 im Einsatz, die ist aber zwei Geschoßdecken entfernt und gelegentlich hatte ich so Eintragungen im log wie: ..out of sync.. reseting buffer...
Ich habe die dect200 jetzt mal deaktiviert, mal sehen, ob nun fhem wie gewohnt stabil durchläuft.

Hier das log, vor dem Hängenbleiber. Ich verstehe zwar das Modul nicht so ganz, aber an einer Stelle wird ein String zerlegt, ohne vorher abzufragen, ob der überhaupt vorhanden ist, bzw. die erwartete Länge hat.

2014.07.03 17:44:24 5: FBAHA/RAW: /070300200000001200100000000000100000002300080000000000010000ffff
2014.07.03 17:44:24 5: DECT200 dispatch 070300200000001200100000000000100000002300080000000000010000ffff
2014.07.03 17:44:24 5: FBAHA/RAW: /0703001c00000012001000000000000c0000000f0004000000000000
2014.07.03 17:44:24 5: DECT200 dispatch 0703001c00000012001000000000000c0000000f0004000000000000
2014.07.03 17:44:24 5: FBAHA/RAW: /0703001c00000012001000000000000c000000140004000000000000
2014.07.03 17:44:24 5: DECT200 dispatch 0703001c00000012001000000000000c000000140004000000000000
2014.07.03 17:44:24 5: FBAHA/RAW: /0703001c00000012001000000000000c000000130004000000038844
2014.07.03 17:44:24 5: DECT200 dispatch 0703001c00000012001000000000000c000000130004000000038844
2014.07.03 17:44:24 5: FBAHA/RAW: /0703001c00000012001000000000000c000000120004000000000000
2014.07.03 17:44:24 5: DECT200 dispatch 0703001c00000012001000000000000c000000120004000000000000
2014.07.03 17:44:24 5: FBAHA/RAW: /0703001c00000012001000000000000c000000150004000000003a54
2014.07.03 17:44:24 5: DECT200 dispatch 0703001c00000012001000000000000c000000150004000000003a54
2014.07.03 17:44:24 5: FBAHA/RAW: /0703001c00000012001000000000000c000000160004000000000000
2014.07.03 17:44:24 5: DECT200 dispatch 0703001c00000012001000000000000c000000160004000000000000
2014.07.03 17:44:24 5: FBAHA/RAW: /070300200000001200100000000000100000002300080000000000010000ffff
2014.07.03 17:44:24 5: DECT200 dispatch 070300200000001200100000000000100000002300080000000000010000ffff
2014.07.03 17:44:25 5: FBAHA/RAW: /040301240000001200100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f00000000000000120004000000000000000000130004000000038844
2014.07.03 17:44:25 5: FBAHA/RAW: 040301240000001200100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f00000000000000120004000000000000000000130004000000038844/0703002000000012001000000000001000000023000800000000ffff00000000
2014.07.03 17:44:26 5: FBAHA/RAW: 040301240000001200100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f000000000000001200040000000000000000001300040000000388440703002000000012001000000000001000000023000800000000ffff00000000/0703003c00000012001000000000002c00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f00000000
2014.07.03 17:44:26 5: DECT200 dispatch 040301240000001200100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f000000000000001200040000000000000000001300040000000388440703002000000012001000000000001000000023000800000000ffff000000000703003c


Gruß

Elektrolurch
 

[Elektrolurch]

Hallo,

nun war es heute nacht um 01:26 Uhr mal wieder so weit. fhem blieb hängen bis mein watchdog es nach 10 Minuten neu startete. Wieder waren Die letzten Eintragungen kommen von der dect200 (s.u.). Dort scheint der Fehler beim "dispatch" der Daten zu liegen.

Was kann man dagegen tun (außer als die dect200 aus fhem herauszunehmen )?
Jetzt sind die Experten gefragt....

Gruß


Elektrolurch


2014.07.06 01:21:55 5: FBAHA/RAW: /070300200000000700100000000000100000002300080000000000010000ffff
2014.07.06 01:21:55 5: DECT200 dispatch 070300200000000700100000000000100000002300080000000000010000ffff
2014.07.06 01:21:55 5: FBAHA/RAW: /0703001c00000007001000000000000c0000000f0004000000000000
2014.07.06 01:21:55 5: DECT200 dispatch 0703001c00000007001000000000000c0000000f0004000000000000
2014.07.06 01:21:55 5: FBAHA/RAW: /0703001c00000007001000000000000c000000140004000000000000
2014.07.06 01:21:55 5: DECT200 dispatch 0703001c00000007001000000000000c000000140004000000000000
2014.07.06 01:21:55 5: Triggering ts (1 changes)
2014.07.06 01:21:55 5: Notify loop for ts power: 0.00 W
2014.07.06 01:21:55 5: Alle_Geraete_im_Haus: not on any display, ignoring notify
2014.07.06 01:21:55 5: ts2: not on any display, ignoring notify
2014.07.06 01:21:55 5: Triggering ts_notify
2014.07.06 01:21:55 4: ts_notify exec {ts_not($NAME,$EVENT);;}
2014.07.06 01:21:55 5: Cmd: >{ts_not($NAME,$EVENT);}<
2014.07.06 01:21:55 5: FBAHA/RAW: /0703001c00000007001000000000000c00000013000400000003829c
2014.07.06 01:21:55 5: DECT200 dispatch 0703001c00000007001000000000000c00000013000400000003829c
2014.07.06 01:21:55 5: FBAHA/RAW: /0703001c00000007001000000000000c000000120004000000000000
2014.07.06 01:21:55 5: DECT200 dispatch 0703001c00000007001000000000000c000000120004000000000000
2014.07.06 01:21:55 5: FBAHA/RAW: /0703001c00000007001000000000000c000000150004000000003a61
2014.07.06 01:21:55 5: DECT200 dispatch 0703001c00000007001000000000000c000000150004000000003a61
2014.07.06 01:21:55 5: FBAHA/RAW: /0703001c00000007001000000000000c000000160004000000000000
2014.07.06 01:21:55 5: DECT200 dispatch 0703001c00000007001000000000000c000000160004000000000000
2014.07.06 01:21:55 5: FBAHA/RAW: /070300200000000700100000000000100000002300080000000000010000ffff
2014.07.06 01:21:55 5: DECT200 dispatch 070300200000000700100000000000100000002300080000000000010000ffff
2014.07.06 01:21:56 5: FBAHA/RAW: /040301240000000700100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f0000000000000012000400000000000000000013000400000003829c
2014.07.06 01:21:56 5: FBAHA/RAW: 040301240000000700100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f0000000000000012000400000000000000000013000400000003829c/0703002000000007001000000000001000000023000800000000ffff00000000
2014.07.06 01:21:56 5: FBAHA/RAW: 040301240000000700100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f0000000000000012000400000000000000000013000400000003829c0703002000000007001000000000001000000023000800000000ffff00000000/0703003c00000007001000000000002c00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f00000000
2014.07.06 01:21:56 5: DECT200 dispatch 040301240000000700100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f0000000000000012000400000000000000000013000400000003829c0703002000000007001000000000001000000023000800000000ffff000000000703003c

... und jetzt kommt 10 Minuten später der Neustart

2014.07.06 01:26:20 5: Initializing Type Library:
2014.07.06 01:26:20 1: Including fhem.cfg

[rudolfkoenig]

Ich habe versucht die letzte Meldung zu analysieren, das kann man auch "trocken" ohne FBAHA mit

Code Auswählen Erweitern

{ Dispatch($defs{fbaha}, "040301240000000700100200000000090000128054657374737465636b646f73650000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000b74303837363120303032383432390000000000000030332e3230000000000000000000000000000000000000000000000200100000000000840000000f00040000000000000000002300080000000000010000ffff00000025002400000000001000000001000000010000001400000005000001f40000003c0000000f0000000000000012000400000000000000000013000400000003829c0703002000000007001000000000001000000023000800000000ffff000000000703003c", undef) }

wobei fbaha vorher angelegt werden muss (Typ FBAHA).

Dabei kam raus, dass FHEM ein haufen Perl warnings (Use of uninitialized value) auspuckt, da die Nachricht irgendwie nicht vollstaendig ist, aber ueberlebt. Ich habe FBDECT/FBAHA modifiziert, damit die Probleme bei verbose 4 im Logfile landen.

Weiterhin unklar fuer mich ist wieso die Nachricht zu kurz ist (evtl copy&paste Fehler?), und wieso FHEM sich aufhaengt.

Ich wuerde mich freuen, wenn du diese aktuelle Version verwendest, sie enthaelt zusaetzlich eine relevante Debug-Meldung beim Verlassen der FBDECT_Parse Funktion. Ich habe sie diesmal direkt fuer upload zur Verfuegung gestellt.

Gruss,
  Rudi

[Elektrolurch]

Hallo Rudi,

update läuft schon. Kopiert habe ich alles, denn die zwei Zeilen vom Neustart waren ja auch dabei.
Danke für die Unterstützung. Ich denke, dass das Problem an dem Funksignal liegt, was sporadisch "kaputt" ankommt.
Da sind ja für type = 4 und 7 in dem dispatch - Teil zwei while - Schleifen, vielleicht bleibt ja fhem da hängen, wenn die Daten nicht stimmen....
Es reicht ja dann, für das dect-Teil  verbose auf 4 zu setzen.
Mal sehen... und Danke.

Gruß


Elektrolurch

[Elektrolurch]

Hallo,

sowie das aussieht, war es wohl das 10_FBDECT - Modul. Dank der Änderungen von Rudi kommt zwar nun ein log-Eintrag (sowas wie unknown Message 0), aber fhem bleibt nicht mehr hängen.
Wie schon oben gesagt, die Distanz zur FB geht über drei Geschoßdecken und da gehen wohl ab und zu mal dect-Gignale verstümmelt über den Äther.
Danke an Rudi für die Unterstützung.

Gruß


Elektrolurch

[rudolfkoenig]

10_FBDECT.pm konnte vor den aktuellen Aenderungen in eine Endlosschleife kommen, wenn die Nutzdatenlaenge eines Teilpaketes mit 0 angegeben wurde.

Ich verstehe zwar nicht, wieso solche Pakete zustande kommen koennen (vermutlich ist der AHA-Server auf dem FB auch noch nicht fehlerfrei), aber im aktuellen 10_FBDECT.pm sollte so eine Endlosschleife nicht mehr vorkommen.

[Elektrolurch]

Schön, wenn sich wieder mal ein Problem gelöst hat. Vielen Dank.

[bgewehr]

Ich habe zwar keine Dect200, aber ebenfalls sporadische Abstürze von FHEM. Der Perl Task läuft dann nicht mehr und ein Neustart auf der Telnet Konsole startet FHEM wieder normal an. Das Log gibt mir leider auch keine ordentliche Antwort. Soll ich jetzt auch mal global verbose 5 probieren? Neuer Thread oder hier? Danke!


Sent from my iPhone using Tapatalk

[rudolfkoenig]

Ja, Ja.