Problem in 00_ZWDongle.pm

krikan · 26 Juni 2015, 19:45:49

@gero und @all:
Hier noch eine Info des openzwave Maintainers, warum in aktuellen ozw Versionen keine Retrys mehr stattfinden:
https://groups.google.com/d/msg/openzwave/MsWDzBQAgwU/bYTC4HcrxhEJ
Also sollte das derzeitige Verhalten in Fhem mMn korrekt sein. Nur der letzte Schritt der Exlorer Frames fehlt noch.

gero · 03 Juli 2015, 12:09:19

Ich habe es jetzt zumindest geschafft, alles nachzulesen, was ihr während meiner Abwesenheit geschrieben habt.
Zur Zeit klingt für mich alles logisch und nachvollziehbar.

Ein Hauptproblem für mich ist, dass ich die API Dokumentation vom Dongle nicht habe.
So Senden wir z.B. ein NACK, wenn die Checksum eines Telegramms (egal ob vom Dongle intern oder von einem Node) falsch ist, um es neu anzufordern.
Ich bin davon ausgegangen, dass dieses Verhalten symetrisch ist. Da lag ich wohl falsch.

Den genauen Diff vom Code werde ich mir die nächsten Tage nochmal ansehen.

Gruß,
Gero

krikan · 07 Juli 2015, 09:49:03

Zu den fehlenden Telegrammen 0013..00 bei meinem Vision ZWave-Controller aus Antworten 10-14 habe ich jetzt nach längerer Suche folgendes Schema festgestellt:

Werden mit Fhem längere Zeit ausschließlich "get"-Befehle abgesetzt, erhalte ich irgendwann keine 0013..00 Nachrichten mehr. Wird dann ein bzw. zwei "set"-Befehl(e) abgeschickt oder der Rechner neu gestartet, tauchen die 0013..00 Nachrichten wieder auf. Werden dann wieder nur "get"-Befehle verschickt, verschwinden die 0013..00 wieder und können mit "set"-Befehl oder Server-Neustart wieder "aktiviert" werden. Die Zeitspanne wie lange 0013..00 - Nachrichten nach ausschließlichen Versand von "get"-Befehlen kommen, ist nach meiner Beobachtung vermutlich von der Menge/zeitliche Abfolge der "get"-Befehle abhängig. Eine bestimmte Anzahl bis zum Auftreten des Problems ist aber nicht erkennbar
Habe versucht das Verhalten mit Openzwave nachzustellen. Das gelingt mir aber nicht. Mit Openzwave sind die 0013..00 Nachrichten immer vorhanden; egal wie lange ich ausschließlich "get"-Befehle abschicke. Maximale Testdauer 3 Tage.
Einiziger erkennbarer Unterschied zwischen Openzwave und Fhem ist mMn das Setzen von CallbackIds auch bei "get"-Befehlen. Habe daher bei Fhem mal bei "get"-Befehlen auch mal CallbackIds aktiviert ; und dann das Problem auch in Fhem nicht mehr reproduzieren können.

-> Wenn mein Controller eine Firmwaremacke hat, kann man die mit konsequenten Setzen der CallbackIds bei den versandten Telegrammen nach den Test beheben ; oder wenn die Firmware meines Controllers OK ist, ist es ist allgemein zwingend CallbackIds zu setzen.

PS: Das ganze habe ich nicht mit meinem Testcontroller UZB1 gegengecheckt, da es die Tests ziemlich zeitintensiv waren. Teilweise trat das Problem erst nach 1,5 Tagen ausschließlichen "get"-Befehlen auf.

rudolfkoenig · 07 Juli 2015, 10:10:54

Ich habe kein Problem mit sinnlosen Callbackids, schauen wir mal, und ob es Nebeneffekte hat. Das koennen wir nur durch einen breiteren Einsatz rausfinden. Kannst du mir ein Patch hinstellen, dann haette ich etwas weniger Testaufwand, und wuerde nicht was falsches einbauen.

krikan · 07 Juli 2015, 20:26:21

Mache ich bei Gelegenheit.

Aber ich bin nicht wirklich überzeugt, ob die Ursache letztlich nicht irgendwo anders liegt:
Vor den Änderungen an 00_ZWDongle hatte ich diese Probleme nicht. Oder mir sind Sie nicht aufgefallen, was mich aber wundern würde, da ich schon recht intensiv Tests durchgeführt hatte.
Meine eigentliche Vermutung war, dass der Internaltimer für "ZWave_ProzessSendStack" zu schnell zuschlägt und die Nachricht zu schnell wieder verschickt wird, so dass 0013..00 quasi überschrieben wird, weil es sich mit ZWDongle_Set($hash, $name, ("timeouts", 100, 15)) aus ZWDongle_DoInit "beißt"/überschneidet. Testweise hatte ich den Internaltimer höher gesetzt, aber nicht wirklichen Erfolg feststellen können. Ideen, wie ich das weiter überprüfen könnte, habe ich aber auch nicht.....

rudolfkoenig · 07 Juli 2015, 23:08:12

Die Wiederholung kommt erst nach eine Sekunde, das ist mir schon fast zu lang.
Und bei Problemen muesstest du ein resend sehen.

krikan · 08 Juli 2015, 08:19:51

Zitat von: rudolfkoenig am 07 Juli 2015, 23:08:12
Und bei Problemen muesstest du ein resend sehen.

Genau das passiert im "Falsch"-Fall bis zum Erreichen der maxretries:

Code Auswählen

2015.07.05 23:05:49 2: ZWave get ZWave_SWITCH_BINARY_6 zwavePlusInfo
2015.07.05 23:05:49 5: ZWDongle_Write 00 1306025e0105
2015.07.05 23:05:49 5: SW: 0108001306025e0105ba
2015.07.05 23:05:49 4: ZWDongle_ReadAnswer arg:zwavePlusInfo regexp:^00040006..5e
2015.07.05 23:05:49 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.07.05 23:05:49 5: SW: 06
2015.07.05 23:05:49 5: ZWDongle_0 dispatch 011301
2015.07.05 23:05:49 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00040006095e020105000f000f00
2015.07.05 23:05:49 5: SW: 06
2015.07.05 23:05:49 4: ZWDongle_ReadAnswer for zwavePlusInfo: 00040006095e020105000f000f00
2015.07.05 23:05:49 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:095e020105000f000f00
2015.07.05 23:05:50 2: ZWave_ProcessSendStack: no ACK, resending message
2015.07.05 23:05:50 5: SW: 0108001306025e0105ba
2015.07.05 23:05:50 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.07.05 23:05:50 5: SW: 06
2015.07.05 23:05:50 5: ZWDongle_0 dispatch 011301
2015.07.05 23:05:50 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00040006095e020105000f000f00
2015.07.05 23:05:50 5: SW: 06
2015.07.05 23:05:50 5: ZWDongle_0 dispatch 00040006095e020105000f000f00
2015.07.05 23:05:50 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:095e020105000f000f00
2015.07.05 23:05:51 2: ZWave_ProcessSendStack: no ACK, resending message
2015.07.05 23:05:51 5: SW: 0108001306025e0105ba
2015.07.05 23:05:51 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.07.05 23:05:51 5: SW: 06
2015.07.05 23:05:51 5: ZWDongle_0 dispatch 011301
2015.07.05 23:05:51 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00040006095e020105000f000f00
2015.07.05 23:05:51 5: SW: 06
2015.07.05 23:05:51 5: ZWDongle_0 dispatch 00040006095e020105000f000f00
2015.07.05 23:05:51 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:095e020105000f000f00
2015.07.05 23:05:52 2: ZWave_ProcessSendStack: no ACK, resending message
2015.07.05 23:05:52 5: SW: 0108001306025e0105ba
2015.07.05 23:05:52 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.07.05 23:05:52 5: SW: 06
2015.07.05 23:05:52 5: ZWDongle_0 dispatch 011301
2015.07.05 23:05:53 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00040006095e020105000f000f00
2015.07.05 23:05:53 5: SW: 06
2015.07.05 23:05:53 5: ZWDongle_0 dispatch 00040006095e020105000f000f00
2015.07.05 23:05:53 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:095e020105000f000f00
2015.07.05 23:05:54 2: ZWave_ProcessSendStack: no ACK, resending message
2015.07.05 23:05:54 1: ERROR: max send retries reached, removing 0108001306025e0105ba from sendstack

Im "Richtig"-Fall sieht es so aus:

Code Auswählen

2015.07.08 03:39:03 2: ZWave get ZWave_SWITCH_BINARY_6 version
2015.07.08 03:39:03 5: ZWDongle_Write 00 130602861105
2015.07.08 03:39:03 5: SW: 01080013060286110572
2015.07.08 03:39:03 4: ZWDongle_ReadAnswer arg:version regexp:^00040006..86
2015.07.08 03:39:03 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.07.08 03:39:03 5: SW: 06
2015.07.08 03:39:03 5: ZWDongle_0 dispatch 011301
2015.07.08 03:39:03 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130500
2015.07.08 03:39:03 5: SW: 06
2015.07.08 03:39:03 5: ZW_SEND_DATA:OK received, removing 01080013060286110572 from sendstack
2015.07.08 03:39:03 5: ZWDongle_0 dispatch 00130500
2015.07.08 03:39:03 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:00 ARG:
2015.07.08 03:39:03 4: ZWDongle_0 transmit OK for 05
2015.07.08 03:39:03 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0004000609861203035c03185000
2015.07.08 03:39:03 5: SW: 06
2015.07.08 03:39:03 4: ZWDongle_ReadAnswer for version: 0004000609861203035c03185000
2015.07.08 03:39:03 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:09861203035c03185000

Meine gewagte Interpretation im "Falsch"-Fall ist, dass zu kurz auf eine Antwort des Empfängers von ZW_SEND_DATA mit 0013..xx gewartet wird. Nach meinem Vertändnis sollte das Dongle immer 0013..xx liefern. Im Fall das der Empfänger nicht reagiert müsste das Dongle ein TRANSMIT_COMPLETE_NO_ACK (0013..01) liefern, wenn ich das ErrorHandling richtig verstehe. Genau dort vermute ich durch resend im 1 Sek-Takt, was Timeout entspricht, ein Problem; resend hatten wir vorher nicht. Warum das Problem der fehlenden 0013..xx bei mir aber mit genannten Schema auftritt und bei aktivem Setzen der CallbackId bisher nicht aufgetreten ist, verstehe ich nicht.

Zitat von: rudolfkoenig am 07 Juli 2015, 23:08:12
Die Wiederholung kommt erst nach eine Sekunde, das ist mir schon fast zu lang.

Ja und nein. Normalerweise müsste 1 Sekunde warten reichen. Bei ozw wird aber in bestimmten Fällen auch von deutlich längeren Laufzeiten berichtet. Und ich komme wieder zur Frage der Notwendigkeit von resends: Dürfen resends überhaupt bei nicht vorhandener Antwort 0013..xx ausgelöst werden oder lässt man die resend dann bzw. ganz bleiben, wenn 011301 existiert?

So, genug der Spekulation. Vielleicht hat jemand mehr Ahnung bzw. sieht etwas, was ich übersehen habe. Testen kann ich bei Ideen gerne. Ansonsten kommt der Patch für CallbackId.

btw: ZW_SEND_DATA hat als ReturnValue im Falle von "If transmit queue overflow" ein FALSE. Das wird mMn doch bisher nicht überwacht? Vielleicht wäre das noch ein Ansatzpunkt.

krikan · 08 Juli 2015, 09:11:28

Zitat von: krikan am 08 Juli 2015, 08:19:51
btw: ZW_SEND_DATA hat als ReturnValue im Falle von "If transmit queue overflow" ein FALSE. Das wird mMn doch bisher nicht überwacht? Vielleicht wäre das noch ein Ansatzpunkt.

Streicht das, ist ja 011300 bzw. 011301 und wird überwacht.

gero · 08 Juli 2015, 13:11:40

Hast du schon mal versucht den Timer für das resend bei ausbleibendem ACK wesentlich höher zu setzen?

Es könnte sein, dass du mit deiner Vermutung recht hast. Eigentlich sollte, wenn wir in den txOptions für ZW_SEND_DATA die Option ACK setzen, auf jeden Fall eine Rückmeldung vom Controller kommen.
Falls dies wirklich so ist, sollten wir das Handling umstellen. Ich habe folgende Definitionen gefunden:
TRANSMIT_COMPLETE_ACK - alles okay, Nachricht entfernen
TRANSMIT_COMPLETE_NO_ACK - device mybe asleep, retransmit error
TRANSMIT_COMPLETE_FAIL - ZWave network busy
TRANSMIT_COMPLETE_NOT_IDLE -

TRANSMIT_COMPLETE_NOROUTE - no route available

D.h. falls wir eine TRANSMIT_COMPLETE_* Nachricht erhalten, sollten wir meiner Meinung nach kein Retransmit ausführen. Wir sollten davon ausgehen, das der Controller schon alles Mögliche getan hat, den Knoten zu erreichen.

Gruß,
Gero

krikan · 08 Juli 2015, 14:05:54

ZitatHast du schon mal versucht den Timer für das resend bei ausbleibendem ACK wesentlich höher zu setzen?

Habe ganz am Anfang den Internaltimer mal auf 1,5 Sek erhöht, was aber keine Besserung brachte. Dann hab ich es leider nicht weiter verfolgt, da ich auf der CallbackId-Spur war.

Zitat
Falls dies wirklich so ist, sollten wir das Handling umstellen.

Zum Testen bin ich gerne bereit

ZitatTRANSMIT_COMPLETE_NOT_IDLE - ?

~~Schau mal im trunk von Linuxmce nach ZW_Serialapi.h, da steht etwas dazu drin. Ich verstehe es aber nicht.~~ https://github.com/OpenZWave/open-zwave/blob/master/cpp/src/Driver.cpp -> Network is busy

Zitat
falls wir eine TRANSMIT_COMPLETE_* Nachricht erhalten, sollten wir meiner Meinung nach kein Retransmit ausführen. Wir sollten davon ausgehen, das der Controller schon alles Mögliche getan hat, den Knoten zu erreichen.

Ja, aber genau die fehlt ja bei mir in bestimmten Situationen

rudolfkoenig · 08 Juli 2015, 15:28:28

Wenn ich das "Falsch" Log von krikan ansehe, dann sehe ich da ein 011301, im Erfolgfall kommt danach auch ein 00130500. Ich habe 00_ZWDongle angepasst, sodass beim Emfang von einer diesen Nachrichten der resend von FHEM ausbleibt.

Die Antwortmoeglichkeiten (TRANSMIT_COMPLETE_*) verstaerken meine urspruengliche Vermutung, dass der Dongle fuer die Network-Resends zustaendig ist, und nicht FHEM. In diesem Fall reicht eigentlich ein OK (06) vom Dongle, um mit den resends aufzuhoeren.

krikan · 08 Juli 2015, 22:16:52

ZitatDie Antwortmoeglichkeiten (TRANSMIT_COMPLETE_*) verstaerken meine urspruengliche Vermutung, dass der Dongle fuer die Network-Resends zustaendig ist, und nicht FHEM. In diesem Fall reicht eigentlich ein OK (06) vom Dongle, um mit den resends aufzuhoeren.

Dem schließe ich mich erst mal an und danke für die Änderung; werde es testen.

@Rudi: Könntest Du bitte, wenn Du -wie ich befürchte- den verschobenen Thread http://forum.fhem.de/index.php/topic,37793.0.html noch nicht gesehen hast, einen Blick darauf werfen und ggfs. eingreifen. Danke.

krikan · 09 Juli 2015, 18:43:38

Ich schon wieder

Ist das wieder nur bei mir so, dass auf jeden set/get-Befehl ein "ZW_SEND_DATA:NO_ACK received" folgt, obwohl mMn das laut Log doch vorhanden ist. Das bekomme ich auch durch Restart nicht abgestellt.

Beispiel:

Code Auswählen


2015.07.09 18:34:56 2: ZWave set ZWave_SWITCH_BINARY_6 powerlevel
2015.07.09 18:34:56 5: ZWDongle_Write 00 130604730101010506
2015.07.09 18:34:56 5: SW: 010b0013060473010101050694
2015.07.09 18:34:56 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.07.09 18:34:56 5: SW: 06
2015.07.09 18:34:56 5: ZW_SEND_DATA:NO_ACK received, removing 010b0013060473010101050694 from sendstack
2015.07.09 18:34:56 5: ZWDongle_0 dispatch 011301
2015.07.09 18:34:56 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130600
2015.07.09 18:34:56 5: SW: 06
2015.07.09 18:34:56 5: ZWDongle_0 dispatch 00130600
2015.07.09 18:34:56 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:00 ARG:
2015.07.09 18:34:56 4: ZWDongle_0 transmit OK for 06

rudolfkoenig · 10 Juli 2015, 08:18:40

Ich bekomme das Gleiche. Halten wir also fest: 011301 ist nicht eine abgewandelte Version von 0013xx01, die erste Variante bedeutet nicht NO_ACK.
Ich werde die Resend-Sonderbehandlung fuer ZW_SEND_DATA entfernen, Resends werden sich nur an ACK/NACK/CAN orientieren.

krikan · 10 Juli 2015, 08:41:09

Beruhigt mich.

Zitat von: rudolfkoenig am 10 Juli 2015, 08:18:40
Ich bekomme das Gleiche. Halten wir also fest: 011301 ist nicht eine abgewandelte Version von 0013xx01, die erste Variante bedeutet nicht NO_ACK.

011301 = ACK: Controller hat Telegramm verschickt
0013xx00= ACK: Empfänger hat Telegramm korrekt erhalten
Also haben 00 und 01 in den beiden Fällen genau umgekehrte Bedeutung. Zusätzliche Quelle bei ozw habe ich dazu bei Bedarf auch noch irgendwo.

Dann zurück zu meinem anderen Dauerthema: Habe gestern beim Fibaro FGRM222 noch festgestellt, dass die CallbackIds nicht "sinnlos" sind. Wenn die CallbackId bei "get" nicht angehängt wird, bleiben bei bestimmten Telegramm-Kombinationen die TRANSMIT:OK Events aus. Hänge ich die CallbackId an, funktioniert das. Habe dazu in Zeile 638 10_ZWave.pm die Beschränkung auf "set" aufgehoben.
Man könnte nun annehmen, dass sei ein Firmware-Bug. ZW_SEND_DATA verlangt aber eine CallbackId von daher behaupte ich, dass ist eine strikte Umsetzung der ZWave-Standards durch Fibaro.