autocreate: Fhem blockiert bei angeschlossenen Device ohne define-Eintrag

[klaus.schauer]

Für Elsner Wetterstationen mit RS485-Schnittstelle ist nun ein neues Modul ElsnerWS fertig. Der Sensor sendet unidirektional Datentelegramme im Sekundentakt. Falls der Sensor über den RS485-USB-Transceiver betriebsbereit ist und permanent sendet, das device aber noch nicht definiert ist, blockiert Fhem beim Start in der autocreate-Routine sobald die entsprechende Schnittstelle getestet wird.

Also war die erste Idee einen Zusatzeintrag in der autocreate usbtable mit den hoffentlich passenden Einträgen anzuhängen:

Code Auswählen Erweitern


    { NAME      => "ElsnerWS",
      matchList => ["cu.usbserial(.*)", "cu.usbmodem(.*)",
                    "ttyUSB(.*)", "ttyACM(.*)", "ttyAMA(.*)"],
      DeviceName=> "DEVICE\@19200",
      flush     => "\n",
      timeout   => 2.0,
      request   => "\x00",   # SOH NUL STX NUL ENQ ETX EOT
      response  => "^(W\+|W\-|G\+|G\-)(.*)",
      define    => "WS_PARAM ElsnerWS comtype=rs485 devicename=DEVICE\@19200", },


Der request-Eintrag wäre ja grundsätzlich nicht notwendig, da das Gerät ja ohnehin permanent periodisch sendet.

Code Auswählen Erweitern


...
2019.04.28 20:31:46 2: TCM TCM310_0 initialized
2019.04.28 20:31:46 1: usb create starting
2019.04.28 20:31:47 3: Probing ZWDongle device /dev/serial0
2019.04.28 20:31:47 3: Probing CUL device /dev/ttyAMA0
2019.04.28 20:31:47 3: Probing TCM_ESP3 device /dev/ttyAMA0
2019.04.28 20:31:47 3: Probing ZWDongle device /dev/ttyAMA0
2019.04.28 20:31:48 3: Probing SIGNALDuino device /dev/ttyAMA0
2019.04.28 20:31:48 3: Probing MYSENSORS device /dev/ttyAMA0
2019.04.28 20:31:48 3: Probing ArduCounter device /dev/ttyAMA0
2019.04.28 20:31:48 3: Probing FRM device /dev/ttyAMA0
2019.04.28 20:31:53 3: Probing ElsnerWS device /dev/ttyAMA0
2019.04.28 20:31:54 3: Probing TCM_ESP3 device /dev/ttyUSB1
2019.04.28 20:31:54 3: Probing TCM_ESP2 device /dev/ttyUSB1
2019.04.28 20:31:54 3: Probing FHZ device /dev/ttyUSB1
2019.04.28 20:31:55 3: Probing TRX device /dev/ttyUSB1
2019.04.28 20:31:56 3: Probing ZWDongle device /dev/ttyUSB1
2019.04.28 20:31:56 3: Probing SIGNALDuino device /dev/ttyUSB1
2019.04.28 20:31:56 3: Probing MYSENSORS device /dev/ttyUSB1
2019.04.28 20:31:56 3: Probing ArduCounter device /dev/ttyUSB1
2019.04.28 20:31:57 3: Probing FRM device /dev/ttyUSB1
2019.04.28 20:39:24 3: Probing ElsnerWS device /dev/ttyUSB1


Dennoch blockiert Fhem weiterhin. Steckt man das Gerät ab, startet Fhem. Dann kann man das Gerät einstecken und das Modul mit define problemlos manuell starten. Gibt es da einen Trick?

[rudolfkoenig]

Kannst Du bitte ein "attr global verbose 5 log" hier zeigen? Die letzten Zeilen vor dem Haengen reichen.

[klaus.schauer]

autocreate scheint nur in dem FRM-Profil ein Problem mit den Sensortelegrammen zu haben:

Code Auswählen Erweitern


2019.04.29 20:18:03 1: usb create starting
2019.04.29 20:18:03 3: Probing ZWDongle device /dev/serial0
2019.04.29 20:18:03 5: SW: 01030020dc06
2019.04.29 20:18:03 5:   answer:
2019.04.29 20:18:03 4:   wrong answer
2019.04.29 20:18:04 3: Probing CUL device /dev/ttyAMA0
2019.04.29 20:18:04 5: SW: 0a
2019.04.29 20:18:04 5: SW: 560a
2019.04.29 20:18:04 5:   answer:
2019.04.29 20:18:04 4:   wrong answer
2019.04.29 20:18:04 3: Probing TCM_ESP3 device /dev/ttyAMA0
2019.04.29 20:18:04 5: SW: 5500010005700838
2019.04.29 20:18:04 5:   answer:
2019.04.29 20:18:04 4:   wrong answer
2019.04.29 20:18:04 3: Probing ZWDongle device /dev/ttyAMA0
2019.04.29 20:18:04 5: SW: 01030020dc06
2019.04.29 20:18:04 5:   answer:
2019.04.29 20:18:04 4:   wrong answer
2019.04.29 20:18:04 3: Probing SIGNALDuino device /dev/ttyAMA0
2019.04.29 20:18:04 5: SW: 0a
2019.04.29 20:18:04 5: SW: 560a
2019.04.29 20:18:04 5:   answer:
2019.04.29 20:18:05 4:   wrong answer
2019.04.29 20:18:05 3: Probing MYSENSORS device /dev/ttyAMA0
2019.04.29 20:18:05 5: SW: 0a
2019.04.29 20:18:05 5: SW: 303b3235353b333b303b31380a
2019.04.29 20:18:05 5:   answer:
2019.04.29 20:18:05 4:   wrong answer
2019.04.29 20:18:05 3: Probing ArduCounter device /dev/ttyAMA0
2019.04.29 20:18:05 5: SW: 0a
2019.04.29 20:18:05 5: SW: 680a
2019.04.29 20:18:05 5:   answer:
2019.04.29 20:18:05 4:   wrong answer
2019.04.29 20:18:05 3: Probing FRM device /dev/ttyAMA0
2019.04.29 20:18:05 5: SW: f9
2019.04.29 20:18:10 5: SW: f079f7
2019.04.29 20:18:10 5:   answer:
2019.04.29 20:18:10 4:   wrong answer
2019.04.29 20:18:10 3: Probing ElsnerWS device /dev/ttyAMA0
2019.04.29 20:18:10 5: SW: 0a
2019.04.29 20:18:10 5: SW: 00
2019.04.29 20:18:10 5:   answer:
2019.04.29 20:18:10 4:   wrong answer
2019.04.29 20:18:10 4: ttyUSB0 is already used by the fhem device TCM310_0
2019.04.29 20:18:10 3: Probing TCM_ESP3 device /dev/ttyUSB1
2019.04.29 20:18:11 5: SW: 5500010005700838
2019.04.29 20:18:11 5:   answer:
2019.04.29 20:18:11 4:   wrong answer
2019.04.29 20:18:11 3: Probing TCM_ESP2 device /dev/ttyUSB1
2019.04.29 20:18:11 5: SW: a55aab5800000000000000000003
2019.04.29 20:18:11 5:   answer:
2019.04.29 20:18:11 4:   wrong answer
2019.04.29 20:18:11 3: Probing FHZ device /dev/ttyUSB1
2019.04.29 20:18:11 5: SW: 8105044fc90185
2019.04.29 20:18:11 5:   answer:
2019.04.29 20:18:11 4:   wrong answer
2019.04.29 20:18:11 3: Probing TRX device /dev/ttyUSB1
2019.04.29 20:18:11 5: SW: 0d00000000000000000000000000
2019.04.29 20:18:12 5: SW: 0d00000102000000000000000000
2019.04.29 20:18:12 5:   answer:
2019.04.29 20:18:12 4:   wrong answer
2019.04.29 20:18:12 3: Probing ZWDongle device /dev/ttyUSB1
2019.04.29 20:18:12 5: SW: 01030020dc06
2019.04.29 20:18:12 5:   answer:
2019.04.29 20:18:12 4:   wrong answer
2019.04.29 20:18:12 3: Probing SIGNALDuino device /dev/ttyUSB1
2019.04.29 20:18:12 5: SW: 0a
2019.04.29 20:18:13 5: SW: 560a
2019.04.29 20:18:13 5:   answer:
2019.04.29 20:18:13 4:   wrong answer
2019.04.29 20:18:13 3: Probing MYSENSORS device /dev/ttyUSB1
2019.04.29 20:18:13 5: SW: 0a
2019.04.29 20:18:13 5: SW: 303b3235353b333b303b31380a
2019.04.29 20:18:13 5:   answer:
2019.04.29 20:18:13 4:   wrong answer
2019.04.29 20:18:13 3: Probing ArduCounter device /dev/ttyUSB1
2019.04.29 20:18:13 5: SW: 0a
2019.04.29 20:18:13 5: SW: 680a
2019.04.29 20:18:13 5:   answer:
2019.04.29 20:18:13 4:   wrong answer
2019.04.29 20:18:13 3: Probing FRM device /dev/ttyUSB1
2019.04.29 20:18:13 5: SW: f9
##### Fhem blockiert ohne device Defintion
##### und weiter nach ausstecken des Sensors
2019.04.29 20:24:59 5: SW: f079f7
2019.04.29 20:24:59 5:   answer:
2019.04.29 20:24:59 4:   wrong answer
2019.04.29 20:24:59 3: Probing ElsnerWS device /dev/ttyUSB1
2019.04.29 20:24:59 5: SW: 0a
2019.04.29 20:24:59 5: SW: 00
2019.04.29 20:24:59 5:   answer:
2019.04.29 20:24:59 4:   wrong answer
2019.04.29 20:24:59 1: usb create end


Ich habe deshalb die Definitioen für das ElsnserWS-Modul

Code Auswählen Erweitern


    { NAME      => "ElsnerWS",
      matchList => ["cu.usbserial(.*)", "cu.usbmodem(.*)",
                    "ttyUSB(.*)", "ttyACM(.*)", "ttyAMA(.*)"],
      DeviceName=> "DEVICE\@19200",
      flush     => "\x03", # ETX end of telegram
      timeout   => 2.0,
      request   => "\x00",   # no request needed
      response  => "^(W\+|W\-|G\+|G\-)(.*)",
      define    => "WS_PARAM ElsnerWS comtype=rs485 devicename=DEVICE\@19200", },


vor die FRM-Definition gestellt. Damit ist es mir einmal gelungen, ein Devise automatisch anzulegen. Wahrscheinlich müsste autocreate zuerst auf das Ende eines periodisch gesendeten Telegramms warten und dann den Beginn des nächsten Telegramms auswerten.

Die Diagramme beginnen mit G+, G-, W+ oder W- und enden mit ETX (0x03). regex für die response-Auswertung passet wohl grundsätzlich. ETX (0x03) in flush dagegen scheint ein Leeren des Eingangspuffers nach dessen Empfang und das warten auf das nächste Telegramm nicht zu bewirken. Gibt es einen andere Lösung dafür?

[rudolfkoenig]

Ich habe FRM erstmal aus der autocreate/usbtable entfernt, da es auch in anderen Faellen zu einem lockup gefuehrt hat.
Erklaeren kann ich es nicht, da es spaetestens nach 5s weitergehen sollte.
Koenntest du bitte (mit aktivierten FRM in autocreate) ein strace Log des Haengens hier anhaengen?

[klaus.schauer]

Ich habe autocreate modifiziert, sodass der Sensor jetzt bei Fhem-Start bisher ohne Probleme zuverlässig erkannt und eingerichtet wird. Die geänderte Datei sende ich mit. Die beiden geänderten Bereiche sind mit ##### abgegrenzt.

Falls request in der Profildefinition nicht gesetzt ist, wird DevIo_TimeoutRead mit einem timeout = x unmittelbar aufgerufen und auf das komplette Empfangspaket (W\+|W\-|G\+|G\-)(.*)\x03 geprüft.

Da die Pakete im Sekundentakt gesendet werden und damit sichergestellt ist, dass ein komplettes Paket in dieser Zeit empfangen wird, wollte ich ein timeout von 1.1 s bis 1.2 s vorgeben. Dabei blockierte Fhem wie bei dem FRM-Profil. Dies aber erst, nachdem ich für den Test das an letzter Stelle im hash stehende FRM-Profil herauskommentiert hatte. Nachdem ich den timeout auf 0.9 s gesetzt habe, war der Fehler weg. Ergebnis: timeout muss beim letzten Profil im hash < 1 sein.

Ich hoffe das hilft etwas bei der Fehlersuche. Falls ein strace log noch benötigt wird, bitte nochmals melden.

Ich würde mich freuen, falls die Änderungen übernommen würden. Nach Beseitigung des Fehlers würde ich dann gerne noch den timeout mit 1.1 s bis 1.2 s testen. Das neue Modul ElsnerWS sende ich zur Info mit.

[rudolfkoenig]

Ich uebernehme gerne die Aenderungen, ich wuerde aber gerne das Problem fixen.Kennst Du einen Weg, das Problem auch ohne dein Hardware nachzustellen?

[jensb]

Ich habe FRM erstmal aus der autocreate/usbtable entfernt, da es auch in anderen Faellen zu einem lockup gefuehrt hat.

Der autocreate-Ablauf für FRM verwendet ein Firmata-Reset für init. Wenn tatsächlich ein Firmata-Device an der USB-Schnittstelle hängt, kann das in (eher seltenen) Einzelfällen ein Hängen der USB-Schnittstelle verursachen, so dass man z.B. das Firmata-Device abziehen muss oder sogar ein Boot erforderlich wird. Selbst wenn der Firmata-Reset erfolgreich ist, kann es aber je nach Firmata-Device auch mal länger als 5 Sekunden dauern, bis das Device wieder über USB ready ist.

Im Normalfall dürfte der request bei einem Firmata-Device auch ohne vorherigen Reset erfolgreich sein. Andererseits ist schwer vorherzusagen, in welchem Zustand sich das Firmata-Device nach den vorherigen autocreate Telegrammen für anderen Devices befindet, so dass der Firmata-Reset an sich eine gute Idee ist. Es ist  wahrscheinlich auch möglich, ein Firmata-Telegramm zu definieren, dass jedes vorherige Telegramm abschließt ohne einen Reset auszulösen.

Der 5-Sekunden-Timeout müsste aber all diese kleinen Abgründe überbrücken. Vor allem hat das nichts mit dem FRM-Modul zu tun, wenn eigentlich ein anderes Device angeschlossen ist, denn wenn ich autocreate richtig verstehe, wird ein Device erst mit define angelegt, wenn der Test erfolgreich war. Wenn der Test aber hängen bleibt, ist die Blockade wahrscheinlich in Richtung OS-USB-Treiber zu suchen.

Wenn gewünscht könnte ich prüfen, ob es ein alternatives init-Telegramm für FRM gibt.

[klaus.schauer]

Ich uebernehme gerne die Aenderungen, ich wuerde aber gerne das Problem fixen.Kennst Du einen Weg, das Problem auch ohne dein Hardware nachzustellen?

Mir fällt da leider keine Alternative ein. Ich mache aber natürlich traces, wenn es hilft.

[rudolfkoenig]

Ich mache aber natürlich traces, wenn es hilft.

Gerne. Am besten mit zusaetzlichen Angaben wie Zeitstempel und Pid

[klaus.schauer]

Bei strace bin ich nicht wirklich fit. Eine Standardabfrage wie

Code Auswählen Erweitern


strace -p PIDvonFHEM -ttT -o strace.log


bringt hier wegen dess notwendigen Fhem restart nichts, da sich die PID dabei ändert. Wie kann ich einen trace über den Fhem restart hinaus laufen lassen?

[rudolfkoenig]

Ich meine -f (fuer follow-fork) sollte helfen.
Alternativ fhem unter strace starten: "strace -f -t -o /tmp/xy perl fhem.pl fhem.cfg"

[klaus.schauer]

Hier die Ergebnisse mit der -f Option:
LOG autocreate_frm_error mit PID 12304 bis Blockade
LOG autocreate_frm_continue.log mit PID 12446 zum Weiterlauf nach Abstecken des RS485-Gerätes

Das verwendete autocreate-Modul hänge ich auch an.

[rudolfkoenig]

Danke.
Ich brauche scheinbar solche Logs, damit ich das Offensichtliche sehe: DevIo_TimeoutRead zu verwenden, um maximal 5 Sekunden zu warten ist Nonsens.
Ich habe jetzt diese Zeile gegen:

Code Auswählen Erweitern

DevIo_SimpleReadWithTimeout($hash, $thash->{timeout} ? $thash->{timeout}:0.5);ausgetauscht, was evtl. immer noch nicht perfekt ist, aber hoffentlich weniger Nonsens als bisher.

[klaus.schauer]

Gut damit ist jetzt das Problem bei "init" gelöst.

Leider bleibt aber noch ein Fehler, da für ein Abfrageinterval >= 1 bei der ElsnerWS Prüfung im "request/reponse" Block Fhem weiterhin blockiert. Warum auch immer 1 s scheinbar die Grenze ist.

Versuchsweise habe ich daher "DevIo_SimpleReadWithTimeout" auch dafür einsetzen wollen. Die Funktion liefert aber immer "undef" zurück, obwohl im Abfrageinterval mindestens ein Datenpaket angekommen sein muss. Die Änderungen habe ich im Quelltext mit ## markiert, siehe Anlage.

Vielleicht gibt es auch dafür eine Lösung. Falls augenblicklich eine zündende Idee fehlt, könnte man für die ElsnerWS Prüfung auch mit einem timeout von 0.9 an den Start gehen. Die Wahrscheinlichkeit, dass in dieser Zeit keine Daten angekommen sind ist eher gering. Sauberer wäre natürlich ein Zeitraum von > 1 s.

[rudolfkoenig]

Leider bleibt aber noch ein Fehler, da für ein Abfrageinterval >= 1 bei der ElsnerWS Prüfung im "request/reponse" Block Fhem weiterhin blockiert.

Kannst du mir bitte dafuer auch ein strace Log liefern?