FHEM Forum

FHEM - Hausautomations-Systeme => Homematic => Thema gestartet von: teddibaer am 14 Februar 2013, 12:44:19

Titel: HMLAN crash
Beitrag von: teddibaer am 14 Februar 2013, 12:44:19
Hi,

ich hab ein HMLAN mit einem Temperatur Sensor und einem Aktor. Hab mir dann in der fhem config 2 einfache scripte gebastelt die abhängig vom Temperatur Sensor den Aktor ein- oder aussschalten (mehr so ne spielerei zum warm werden mit fhem). Das Ganze ist auch noch abhängig davon ob mein Handy ping-bar ist.

Nun ist es so, dass das meistens ganz toll funktioniert, aber nach etwa 2-4 Tagen steigt mir das HMLAN aus (kein ping mehr möglich und die Lampen blinken hektisch). Im Log vom fhem sehe ich dann zuvor immer zB so etwas:

2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D6AF d2:0001
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D6BA d2:0001
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D6C5 d2:0001
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D6CF d2:0001
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D6DA d2:0001
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D6E5 d2:0001
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D6F0 d2:0001
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D6FB d2:0001
2013.02.14 12:03:51 5: HMLAN_Send:  K
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D706 d2:0001
2013.02.14 12:03:51 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0264D711 d2:0001

oder auch

2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:34 5: HMLAN_Send:  K
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:025158E0 d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:025158EB d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:025158F5 d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:02515900 d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0251590B d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:02515915 d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:02515920 d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:0251592B d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:02515935 d2:0001
2013.02.14 11:42:38 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:02515940 d2:0001


Nun hab ich irgendwo gelesen, dass zu viele messages schnell hintereinander das HMLAN killen können ...?

Das einzige was IMHO meine scripte machen (was evtl kritisch sein könnte) ist das hier:

    use POSIX ":sys_wait_h";\
    $SIG{CHLD} = "DEFAULT";\
\
    my $res = system("ping", "-c", "1", "192.168.178.24");\

Nun meine Fragen:
a) irgendeine Idee ob das was damit zu tun haben könnte oder was überhaupt das Problem ist?
b) gibt es andere (saubere) Möglichkeit einen "ping" zu machen (im aktuellen changelog hab ich was davon gelesen ohne das bisher genauer angeschaut zu haben)

Edit: meine fhem Version ist die 'offizielle' 5.3 und läuft unter Ubuntu.

Grüße,
  Ralf
Titel: Aw: HMLAN crash
Beitrag von: martinp876 am 15 Februar 2013, 09:04:52
das 'K' ist ein keep-alive. Da kommen deutlich zu viele. Die sollten nur alle 25 sec kommen. Wie startest du das Ganze? in FHEM sollte dies nocht vorkommen.

diese messages sind nicht die wirklichen 'killer' - aber man kann den HMLAN definitiv ueberfahren, zum reset bringen und schlimmeres.

Die Frage ist, was dein ping soll. Das Ping - wenn keine Antwort kommt - dauert 10sec. In der Zeit steht alles.
Du solltest dein ping auf ein paket beschraenken UND die max wartezeit beschraenken - nach 1 sec sollte eine Antwort da sein (es sei denn du pingst ueber das internet...)

Also erst einmal ping nachlesen, das ist komplexer als viele denken.

Dann kannst du "forken". Ist eigentlich ganz einfach - so lange du das Ergebnis in ein file schreibst und nicht den Elternprocess informieren musst. Dann erst wird es kompliziert.

zusammenfassung: die passenden Loesung haengt von der Anforderung ab
Gruss
Martin
Titel: Aw: HMLAN crash
Beitrag von: teddibaer am 15 Februar 2013, 10:30:46
Hi Martin,

danke für deine Erklärung - aber so ganz klar ist mir die Sache noch nicht.
Das mit dem ping weiss ich - was du mir aber sagen willst ist, dass wenn der fhem 'steht', dass trotzdem 'keep-alives' irgendwie gequeued werden und diese dann als block auf einmal verschickt werden?

Ich mach in meinem script genau 2 pings ins LAN die jede Minute (via fhem) getriggert werden. Diese kommen normalerweise innerhalb weniger Sekunden zurück (gerade eben getestet - da waren es ca. 4 Sekunden pro ping wenn der host nicht erreichbar ist).
So oder so verstehe ich also nicht wie sich dann keep-alives auf-queuen (tooles DEnglisch) können(?)

Ich werde mal den Timeout im ping dazu machen und sehen was passiert. Fork wäre ein overkill.
Das umbiegen des signal handlers hat keine Auswirkungen auf den fhem?

Grüße,
  Ralf
Titel: Aw: HMLAN crash
Beitrag von: martinp876 am 15 Februar 2013, 14:37:27
Zitatwenn der fhem 'steht', dass trotzdem 'keep-alives' irgendwie gequeued werden und diese dann als block auf einmal verschickt werden?

nein, das sollte nicht der Fall sein.

ich gehe davon aus, dass du ein neues 00_HMLAN hast. dort sollten Vorkehrungen sein, doppelte keep-alive timer zu vermeiden. Falls sie doch noch auftreten, lass es mich wissen

deine 4sek machen Sinn. Ein Ping wird per default 3mal wiederholt, das ganze 2 mal.
Sollte der Ping schief gehen bist du so bei 10*3*2sec.
Daher
ping -c 1 -w 1 <ip>

achtung - die Parameter von PING sind auf jedem Target unterschiedlich! Musst du einmal testen

Titel: Aw: HMLAN crash
Beitrag von: teddibaer am 15 Februar 2013, 16:29:32
Hi,

hmm - nochmal: wenn der host NICHT da ist dauert ein ping ins LAN bei mir mit "ping -c 1 <ip>" ca. 4 Sek. (so wie ich es bisher immer verwendet habe) auf der Kommandozeile.

Mit 2 hosts sollte das also locker in 10 Sek. abgehandelt sein.

Wenn ich das Logfile vom fhem richtig lese ist das das auch der Fall: Zu den Zeiten wo die pings in Leere laufen braucht das script lt. Logfile ca. 6-7 Sek. (die Zeit vom exec ... bis zum redefine ...).
Über 2 Tage hinweg im Logfile hab ich da auch keine Abweichungen fest stellen können (wenn jemand da war waren die pings natürlich schneller zurück).

Meines Erachtens erklärt das also noch nicht dieses queuen von keep-alives.

Ich hab mal das Log noch etwas genauer untersucht und nur die HMLAN messages gefiltert und mir die Stelle raus gesucht wo er zum ersten mal 2 keep-a-lives erzeugt:

2013.02.15 07:54:35 5: HMLAN_Send:  K
2013.02.15 07:54:35 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:06A723C8 d2:0001
2013.02.15 07:55:10 5: HMLAN_Send:  ABFE335
2013.02.15 07:55:10 5: HMLAN_Send:  C
2013.02.15 07:55:10 5: HMLAN_Send:  Y01,01,
2013.02.15 07:55:10 5: HMLAN_Send:  Y02,00,
2013.02.15 07:55:10 5: HMLAN_Send:  Y03,00,
2013.02.15 07:55:10 5: HMLAN_Send:  Y03,00,
2013.02.15 07:55:10 5: HMLAN_Send:  T18B08A3E,04,00,00000000
2013.02.15 07:55:10 5: HMLAN_Send:  K
2013.02.15 07:55:10 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:06A7ADD7 d2:0001
2013.02.15 07:55:14 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:06A7AE3B d2:0000
2013.02.15 07:55:35 5: HMLAN_Send:  K
2013.02.15 07:55:35 5: HMLAN_Send:  K
2013.02.15 07:55:35 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:06A80FF9 d2:0000
2013.02.15 07:55:35 5: HMLAN_Parse: hmlan V:03C1 sNo:JEQ0315600 d:1C6614 O:BFE335 m:06A81004 d2:0000
2013.02.15 07:56:00 5: HMLAN_Send:  K
2013.02.15 07:56:00 5: HMLAN_Send:  K

Im erweiterten Log sehe in an der Stelle:

2013.02.15 07:55:05 1: JEQ0315600:1000 disconnected, waiting to reappear
...
2013.02.15 07:55:10 1: JEQ0315600:1000 reappeared (hmlan)

Du siehst was ich vermute ..?

Grüße,
  Ralf
Titel: Aw: HMLAN crash
Beitrag von: martinp876 am 16 Februar 2013, 17:42:09
ZitatMit 2 hosts sollte das also locker in 10 Sek. abgehandelt sein.
ok, ist eben so bei deinem System

ZitatMeines Erachtens erklärt das also noch nicht dieses queuen von keep-alives.
Da stimme ich zu. Es kann zu HMLAN disconnects führen, das ist an der Grenze - aber zum Queuen sollte es nicht kommen. Bei jeden event werden alle anderen timer gelöscht.

Ich habe dir ein HMLAN angehängt. Das hat einen zusätzlichen trace, der den Timer benennt. Wenn du den einmal laufen lassen kannst und die logs sammeln kannst, wenn es wieder auftritt, waeren gut

Gruss
Martin
Titel: Aw: HMLAN crash
Beitrag von: teddibaer am 05 Mai 2013, 12:56:23
Hi,

tut mir leid dass es etwas gedauert hat aber ich war in letzter Zeit etwas eingespannt ...

Wie auch immer und um das Thema ab zu schliessen: mit dem Test-Code konnte ich das Problem nicht mehr re-produzieren (mit alten Code war das immer eindeutig innerhalb von 12h möglich). Das Problem wurde also irgendwann zwischendrin bereits gelöst.

Inzwischen bin auch auf 5.4 um gestiegen und auch da läuft alles glatt.

Ergo: Alles Gut.

Grüße und Danke für die Hilfe,
  Ralf