Problem in 00_ZWDongle.pm

[gero]

Hallo,

ich beschäftige mich erst seit Kurzem mit ZWave. Aber einige Effekte, die ich beobachtet habe, haben mich dazu veranlaßt, doch mal genauer nachzuforschen.
- häufige Meldungen "ZWDongle: wrong checksum:"
- das spontane Ändern der homeId vom Dongle
- das Auftauchen von neuen Endpoints oder Geräten

Zumindest für das erste Problem habe ich die Ursache gefunden und ich bin mir ziemlich sicher, dass die anderen Probleme ebenfalls die gleich Ursache haben.

Problem:
- ZWDongle_Read hängt die gelesenen Daten an $hash->{PARTIAL}
- Falls ein komplettes Frame in den Daten vorhanden ist, wird ZWDongle_Parse aufgerufen, ohne vorher $hash->{PARTIAL} zu aktualisieren.
- ZWDongle_Parse kann Funktionen aufrufen, die ihrerseits ZWDongle_ReadAnswer aufrufen, das wiederum ZWDongle_Read aufruft (Rekursion).
Resultat sind ungültige Frames

Wenn man z.B. bei einem batteriebetriebenen Device über ein Notify auf das Wakeup-Telegramm ein get triggert, kann man den Fehler sehr einfach reproduzieren

Code Auswählen Erweitern

define ZWave_SENSOR_BINARY_6.Battery notify ZWave_SENSOR_BINARY_6:wakeup:.* get ZWave_SENSOR_BINARY_6 battery

Ich habe das Logging etwas erweitert. Die Ausgabe "ZWDongle_Read data remaining:..." erfolgt direkt vor dem ZWDongle_Parse Aufruf in der Funktion ZWDongle_Read und Die Ausgabe "ZWDongle_Read partial:... " erfolgt kurz vor Verlassen der ZWDongle_Read Funktion.

Hier das Log für den Gut-Fall:

Code Auswählen Erweitern


2015.05.22 09:24:26 5: ZWDongle/RAW: /01080004000602840774
2015.05.22 09:24:26 5: SW: 06
2015.05.22 09:24:26 5: ZWDongle_Read ZWDongle: 00040006028407
2015.05.22 09:24:26 5: ZWDongle_Read data remaining:
2015.05.22 09:24:26 5: ZWDongle dispatch 00040006028407
2015.05.22 09:24:26 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:028407
2015.05.22 09:24:26 2: ZWave get ZWave_SENSOR_BINARY_6 battery
2015.05.22 09:24:26 5: SW: 01080013060280020567
2015.05.22 09:24:26 5: ZWDongle_ReadAnswer: arg: battery regexp: ^00040006
2015.05.22 09:24:26 5: ZWDongle/RAW: /06
2015.05.22 09:24:26 5: ZWDongle_Read partial:
2015.05.22 09:24:26 5: ZWDongle_ReadAnswer: answ:
2015.05.22 09:24:26 5: ZWDongle/RAW: /0104011301e8
2015.05.22 09:24:26 5: SW: 06
2015.05.22 09:24:26 5: ZWDongle_Read ZWDongle: 011301
2015.05.22 09:24:26 5: ZWDongle_Read data remaining:
2015.05.22 09:24:26 5: ZWDongle dispatch 011301
2015.05.22 09:24:26 5: ZWDongle_Read partial:
2015.05.22 09:24:26 5: ZWDongle_ReadAnswer: answ:
2015.05.22 09:24:26 5: ZWDongle/RAW: /01
2015.05.22 09:24:26 5: ZWDongle_Read partial: 01
2015.05.22 09:24:26 5: ZWDongle_ReadAnswer: answ:
2015.05.22 09:24:26 5: ZWDongle/RAW: 01/07001354000003bc
2015.05.22 09:24:26 5: SW: 06
2015.05.22 09:24:26 5: ZWDongle_Read ZWDongle: 001354000003
2015.05.22 09:24:26 5: ZWDongle_Read data remaining:
2015.05.22 09:24:26 5: ZWDongle dispatch 001354000003
2015.05.22 09:24:26 4: ZWDongle CMD:ZW_SEND_DATA ID:00 ARG:0003
2015.05.22 09:24:26 4: ZWDongle transmit OK for 54
2015.05.22 09:24:26 5: ZWDongle_Read partial:
2015.05.22 09:24:26 5: ZWDongle_ReadAnswer: answ:
2015.05.22 09:24:26 5: ZWDongle/RAW: /0109000400060380036410
2015.05.22 09:24:26 5: SW: 06
2015.05.22 09:24:26 5: ZWDongle_Read ZWDongle: 0004000603800364
2015.05.22 09:24:26 5: ZWDongle_Read data remaining:
2015.05.22 09:24:26 5: ZWDongle_Read partial:
2015.05.22 09:24:26 5: ZWDongle_ReadAnswer: answ: 0004000603800364
2015.05.22 09:24:26 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:03800364
2015.05.22 09:24:26 3: ZWave_SENSOR_BINARY_6.Battery return value: battery:100 %
2015.05.22 09:24:26 5: ZWDongle_Read partial:


Und hier das Log für den Fehler:

Code Auswählen Erweitern


2015.05.22 09:54:24 5: ZWDongle/RAW: /010800040006
2015.05.22 09:54:24 5: ZWDongle_Read partial: 010800040006
2015.05.22 09:54:24 5: ZWDongle/RAW: 010800040006/02840774
2015.05.22 09:54:24 5: SW: 06
2015.05.22 09:54:24 5: ZWDongle_Read ZWDongle: 00040006028407
2015.05.22 09:54:24 5: ZWDongle_Read data remaining:
2015.05.22 09:54:24 5: ZWDongle dispatch 00040006028407
2015.05.22 09:54:24 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:028407
2015.05.22 09:54:24 2: ZWave get ZWave_SENSOR_BINARY_6 battery
2015.05.22 09:54:24 5: SW: 01080013060280020567
2015.05.22 09:54:24 5: ZWDongle_ReadAnswer: arg: battery regexp: ^00040006
2015.05.22 09:54:24 5: ZWDongle/RAW: 010800040006/06
2015.05.22 09:54:24 5: ZWDongle_Read partial: 01080004000606
2015.05.22 09:54:24 5: ZWDongle_ReadAnswer: answ: undef
2015.05.22 09:54:24 5: ZWDongle/RAW: 01080004000606/0104011301e8
2015.05.22 09:54:24 1: ZWDongle: wrong checksum: received 01, computed f6 for 0800040006060104
2015.05.22 09:54:24 5: SW: 15
2015.05.22 09:54:24 1: ZWDongle: SOF missing (got 13 instead of 01)
2015.05.22 09:54:24 5: ZWDongle_Read partial: 1301e8
2015.05.22 09:54:24 5: ZWDongle_ReadAnswer: answ: 00040006060104
2015.05.22 09:54:24 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:060104
2015.05.22 09:54:24 3: ZWave_SENSOR_BINARY_6.Battery return value: UNPARSED:UNKNOWN_01 060104
2015.05.22 09:54:24 5: ZWDongle_Read partial:
2015.05.22 09:54:24 5: ZWDongle/RAW: /0104011301e8
2015.05.22 09:54:24 5: SW: 06
2015.05.22 09:54:24 5: ZWDongle_Read ZWDongle: 011301
2015.05.22 09:54:24 5: ZWDongle_Read data remaining:
2015.05.22 09:54:24 5: ZWDongle dispatch 011301
2015.05.22 09:54:24 5: ZWDongle_Read partial:
2015.05.22 09:54:24 5: ZWDongle/RAW: /0109000400
2015.05.22 09:54:24 5: ZWDongle_Read partial: 0109000400
2015.05.22 09:54:24 5: ZWDongle/RAW: 0109000400/060380036410
2015.05.22 09:54:24 5: SW: 06
2015.05.22 09:54:24 5: ZWDongle_Read ZWDongle: 0004000603800364
2015.05.22 09:54:24 5: ZWDongle_Read data remaining:
2015.05.22 09:54:24 5: ZWDongle dispatch 0004000603800364
2015.05.22 09:54:24 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:03800364
2015.05.22 09:54:24 5: ZWDongle_Read partial:
2015.05.22 09:54:24 5: ZWDongle/RAW: /0107001354000008b7
2015.05.22 09:54:24 5: SW: 06
2015.05.22 09:54:24 5: ZWDongle_Read ZWDongle: 001354000008
2015.05.22 09:54:24 5: ZWDongle_Read data remaining:
2015.05.22 09:54:24 5: ZWDongle dispatch 001354000008
2015.05.22 09:54:24 4: ZWDongle CMD:ZW_SEND_DATA ID:00 ARG:0008
2015.05.22 09:54:24 4: ZWDongle transmit OK for 54
2015.05.22 09:54:24 5: ZWDongle_Read partial:
2015.05.22 09:54:24 5: ZWDongle/RAW: /0109000400060380036410
2015.05.22 09:54:24 5: SW: 06
2015.05.22 09:54:24 5: ZWDongle_Read ZWDongle: 0004000603800364
2015.05.22 09:54:24 5: ZWDongle_Read data remaining:
2015.05.22 09:54:24 5: ZWDongle dispatch 0004000603800364
2015.05.22 09:54:24 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:03800364
2015.05.22 09:54:24 5: ZWDongle_Read partial:
2015.05.22 09:54:41 5: ZWDongle/RAW: /010c00040005063105
2015.05.22 09:54:41 5: ZWDongle_Read partial: 010c00040005063105
2015.05.22 09:54:41 5: ZWDongle/RAW: 010c00040005063105/0422002ec8
2015.05.22 09:54:41 5: SW: 06
2015.05.22 09:54:41 5: ZWDongle_Read ZWDongle: 000400050631050422002e
2015.05.22 09:54:41 5: ZWDongle_Read data remaining:
2015.05.22 09:54:41 5: ZWDongle dispatch 000400050631050422002e
2015.05.22 09:54:41 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:05 ARG:0631050422002e
2015.05.22 09:54:41 5: ZWDongle_Read partial:



Hier noch ein Beispiel für das Auftauchen eines neuen Gerätes:

Code Auswählen Erweitern

2015.05.22 09:04:28 5: ZWDongle/RAW: /01080004
2015.05.22 09:04:28 5: ZWDongle_Read partial: 01080004
2015.05.22 09:04:28 5: ZWDongle/RAW: 01080004/000602840774
2015.05.22 09:04:28 5: SW: 06
2015.05.22 09:04:28 5: ZWDongle_Read ZWDongle: 00040006028407
2015.05.22 09:04:28 5: ZWDongle_Read data remaining:
2015.05.22 09:04:28 5: ZWDongle dispatch 00040006028407
2015.05.22 09:04:28 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:028407
2015.05.22 09:04:28 2: ZWave get ZWave_SENSOR_BINARY_6 battery
2015.05.22 09:04:28 5: SW: 01080013060280020567
2015.05.22 09:04:28 5: ZWDongle/RAW: 01080004/06
2015.05.22 09:04:28 5: ZWDongle_Read partial: 0108000406
2015.05.22 09:04:28 5: ZWDongle/RAW: 0108000406/0104011301e8
2015.05.22 09:04:28 1: ZWDongle: wrong checksum: received 01, computed e2 for 0800040601040113
2015.05.22 09:04:28 5: SW: 15
2015.05.22 09:04:28 1: ZWDongle: SOF missing (got e8 instead of 01)
2015.05.22 09:04:28 5: ZWDongle_Read partial: e8
2015.05.22 09:04:28 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:01 ARG:040113
2015.05.22 09:04:28 3: UNDEFINED ZWave_Node_1 ZWave c9cde420 1, please define it
2015.05.22 09:04:28 5: ZWDongle_Read partial:
2015.05.22 09:04:28 5: ZWDongle/RAW: /0104011301e8
2015.05.22 09:04:28 5: SW: 06
2015.05.22 09:04:28 5: ZWDongle_Read ZWDongle: 011301
2015.05.22 09:04:28 5: ZWDongle_Read data remaining:
2015.05.22 09:04:28 5: ZWDongle dispatch 011301
2015.05.22 09:04:28 5: ZWDongle_Read partial:
2015.05.22 09:04:28 5: ZWDongle/RAW: /0107001354000002bd
2015.05.22 09:04:28 5: SW: 06
2015.05.22 09:04:28 5: ZWDongle_Read ZWDongle: 001354000002
2015.05.22 09:04:28 5: ZWDongle_Read data remaining:
2015.05.22 09:04:28 5: ZWDongle dispatch 001354000002
2015.05.22 09:04:28 4: ZWDongle CMD:ZW_SEND_DATA ID:00 ARG:0002
2015.05.22 09:04:28 4: ZWDongle transmit OK for 54
2015.05.22 09:04:28 5: ZWDongle_Read partial:
2015.05.22 09:04:28 5: ZWDongle/RAW: /01090004000603
2015.05.22 09:04:28 5: ZWDongle_Read partial: 01090004000603
2015.05.22 09:04:28 5: ZWDongle/RAW: 01090004000603/80036410
2015.05.22 09:04:28 5: SW: 06
2015.05.22 09:04:28 5: ZWDongle_Read ZWDongle: 0004000603800364
2015.05.22 09:04:28 5: ZWDongle_Read data remaining:
2015.05.22 09:04:28 5: ZWDongle dispatch 0004000603800364
2015.05.22 09:04:28 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:03800364
2015.05.22 09:04:28 5: ZWDongle_Read partial:
Hier sieht man meiner Meinung nach noch andere Fehler:
Bei einem SOF-Fehler, wird die while-Schleife beendet und $msg als return value zurückgeliefert, obwohl die regexp nicht matched.
In diesem Fall sollte zumindest msg auf undef gesetzt werden.

    if($fb ne "01") {   # SOF
      Log3 $name, 1, "$name: SOF missing (got $fb instead of 01)";
      undef @{$hash->{SendStack}};
      $msg = undef;
      last;
    }

Aber evtl. sollte man auch alle empfangenen Daten verwerfen oder den Buffer nach einem gültigen Frame durchsuchen.

Eine mögliche Lösung wäre es  $hash->{PARTIAL}  vor der Rekursion, also vor dem Aufruf von ZWDongle_Parse zu aktualisieren.

    # upper layer function may call ZWDongle_Get -> ZWDongle_Read
    # so we have to update $hash->{PARTIAL} at this point
   $hash->{PARTIAL} = $data;   
    ZWDongle_Parse($hash, $name, $msg);

Aber ich halte die Rekursion von Read -> Parse -> ... -> ReadAnswer -> Read -> ... insgesamt für ein unglückliches und gefährliches Konstrukt. Vielleicht sollte man hier eher über ein SW-Redesign nachdenken.
Dafür spricht auch ein weiteres Problem:
Ein get läuft unweigerlich in ein Timeout, wenn sich ein anderes Kommando im sendstack befindet:

Code Auswählen Erweitern


2015.05.22 10:09:49 2: ZWave set ZWave_SENSOR_BINARY_6 wakeupInterval

2015.05.22 10:14:05 5: ZWDongle/RAW: /01
2015.05.22 10:14:05 5: ZWDongle_Read partial: 01
2015.05.22 10:14:05 5: ZWDongle/RAW: 01/0c0004000506310504220027c1
2015.05.22 10:14:05 5: SW: 06
2015.05.22 10:14:05 5: ZWDongle_Read ZWDongle: 0004000506310504220027
2015.05.22 10:14:05 5: ZWDongle_Read data remaining:
2015.05.22 10:14:05 5: ZWDongle dispatch 0004000506310504220027
2015.05.22 10:14:05 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:05 ARG:06310504220027
2015.05.22 10:14:05 5: ZWDongle_Read partial:
2015.05.22 10:14:22 5: ZWDongle/RAW: /01080004000602840774
2015.05.22 10:14:22 5: SW: 06
2015.05.22 10:14:22 5: ZWDongle_Read ZWDongle: 00040006028407
2015.05.22 10:14:22 5: ZWDongle_Read data remaining:
2015.05.22 10:14:22 5: ZWDongle dispatch 00040006028407
2015.05.22 10:14:22 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:028407
2015.05.22 10:14:22 5: SW: 010d00130606840400003c0105065f
2015.05.22 10:14:22 2: ZWave get ZWave_SENSOR_BINARY_6 battery
2015.05.22 10:14:22 5: ZWDongle_ReadAnswer: arg: battery regexp: ^00040006
2015.05.22 10:14:22 5: ZWDongle/RAW: /060104011301e8
2015.05.22 10:14:22 5: SW: 06
2015.05.22 10:14:22 5: ZWDongle_Read ZWDongle: 011301
2015.05.22 10:14:22 5: ZWDongle_Read data remaining:
2015.05.22 10:14:22 5: ZWDongle dispatch 011301
2015.05.22 10:14:22 5: ZWDongle_Read partial:
2015.05.22 10:14:22 5: ZWDongle_ReadAnswer: answ: undef
2015.05.22 10:14:22 5: ZWDongle/RAW: /01
2015.05.22 10:14:22 5: ZWDongle_Read partial: 01
2015.05.22 10:14:22 5: ZWDongle_ReadAnswer: answ: undef
2015.05.22 10:14:22 5: ZWDongle/RAW: 01/07001306000004e9
2015.05.22 10:14:22 5: SW: 06
2015.05.22 10:14:22 5: ZWDongle_Read ZWDongle: 001306000004
2015.05.22 10:14:22 5: ZWDongle_Read data remaining:
2015.05.22 10:14:22 5: ZWDongle dispatch 001306000004
2015.05.22 10:14:22 4: ZWDongle CMD:ZW_SEND_DATA ID:00 ARG:0004
2015.05.22 10:14:22 5: SW: 01080013060284080569
2015.05.22 10:14:22 4: ZWDongle transmit OK for 06
2015.05.22 10:14:22 5: ZWDongle_Read partial:
2015.05.22 10:14:22 5: ZWDongle_ReadAnswer: answ: undef
2015.05.22 10:14:22 5: ZWDongle/RAW: /06
2015.05.22 10:14:22 5: ZWDongle_Read partial:
2015.05.22 10:14:22 5: ZWDongle_ReadAnswer: answ: undef
2015.05.22 10:14:22 5: ZWDongle/RAW: /0104011301e8
2015.05.22 10:14:22 5: SW: 06
2015.05.22 10:14:22 5: ZWDongle_Read ZWDongle: 011301
2015.05.22 10:14:22 5: ZWDongle_Read data remaining:
2015.05.22 10:14:22 5: ZWDongle dispatch 011301
2015.05.22 10:14:22 5: ZWDongle_Read partial:
2015.05.22 10:14:22 5: ZWDongle_ReadAnswer: answ: undef
2015.05.22 10:14:25 3: ZWave_SENSOR_BINARY_6.Battery return value: Timeout reading answer for get battery
2015.05.22 10:14:25 5: ZWDongle_Read partial:
2015.05.22 10:14:25 5: SW: 01080013060280020567
2015.05.22 10:14:26 5: ZWDongle/RAW: /060104011301e8
2015.05.22 10:14:26 5: SW: 06
2015.05.22 10:14:26 5: ZWDongle_Read ZWDongle: 011301
2015.05.22 10:14:26 5: ZWDongle_Read data remaining:
2015.05.22 10:14:26 5: ZWDongle dispatch 011301
2015.05.22 10:14:26 5: ZWDongle_Read partial:

Die ZWDongle_Write Funktion setzt zwar einen InternalTimer mit einer Sekunde für das nächste Kommando. Aber solange in der Funktion ZWDongle_ReadAnswer auf eine passende Antwort gewartet wird, wird der Timer nicht ausgeführt.

Außerdem bin ich mir nicht sicher, ob die korrekte Zuordnung eines Frames durch die regexp 100% gesichert ist. Dazu überblicke ich die Implementierung (noch) zu wenig.

Meiner Meinung nach sollte die Funktion ZWDongle_ReadAnswer komplett rausdesigned und das get asynchron realisiert werden. Ich bin mir allerdings bewußt, dass das nicht ganz einfach wird.

Ich liefere absichtlich noch keinen Patch, weil ich mir noch nicht sicher bin, ob die von mir vorgeschlagenen minimalen Änderungen wirklich eine Lösung sind.

Gruß,
Gero

[micha80]

Und ich dachte, das ist nur bei mir so...
Wenn du Hilfe beim testen benötigst, bin ich gern dabei

[gero]

Danke für das Angebot. Mit den beiden oben genannten Änderungen, habe ich bisher keine "wrong checksum", SOF, "undefined device" oder homeId-Fehler.
Ich komme wahrscheinlich erst morgen dazu einen Patch zum Testen zu erzeugen.
Gruß,
Gero

[micha80]

soweit so richtig?

Code Auswählen Erweitern

raspi2:~/fhem-code/fhem/FHEM# svn diff
Index: 00_ZWDongle.pm
===================================================================
--- 00_ZWDongle.pm      (Revision 8620)
+++ 00_ZWDongle.pm      (Arbeitskopie)
@@ -522,6 +522,8 @@
     if($fb ne "01") {   # SOF
       Log3 $name, 1, "$name: SOF missing (got $fb instead of 01)";
       undef @{$hash->{SendStack}};
+      #changed_for: #37418
+      $msg = undef;
       last;
     }

@@ -546,6 +548,10 @@
     Log3 $name, 5, "ZWDongle_Read $name: $msg";

     last if(defined($local) && (!defined($regexp) || ($msg =~ m/$regexp/)));
+    #changed_for: #37418
+    # upper layer function may call ZWDongle_Get -> ZWDongle_Read
+    # so we have to update $hash->{PARTIAL} at this point
+    $hash->{PARTIAL} = $data;
     ZWDongle_Parse($hash, $name, $msg);
     $msg = undef;
   }


[gero]

Sieht gut aus.

[gero]

Anbei ein Patch mit minimalen Änderungen, der zumindest einige wichtige Probleme löst.

Ungelöst bleibt
- Das Nichtabarbeiten des sendstacks, wenn in der Funktion ReadAnswer gewartet wird.
- Das unzureichende Patternmatching, um Anworten eindeutig einer Anfrage zuzuordnen. (Warum wird als Pattern nur "^000400$id" genommen und nicht auch zusätzlich der Befehlscode?)

Vor allem letzteres muß noch dringend gelöst werden, um einen wirklich stabilen ZWave-Betrieb zu gewährleisten.
Hier noch ein Beispiel für eine falsche Zuordnung:

Code Auswählen Erweitern

2015.05.23 23:30:41 5: ZWDongle/RAW: /01080004000602840774
2015.05.23 23:30:41 5: SW: 06
2015.05.23 23:30:41 5: ZWDongle_Read ZWDongle: 00040006028407
2015.05.23 23:30:41 5: ZWDongle dispatch 00040006028407
2015.05.23 23:30:41 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:028407
2015.05.23 23:30:41 2: ZWave get ZWave_SENSOR_BINARY_6 battery
2015.05.23 23:30:41 5: SW: 01080013060280020567
2015.05.23 23:30:41 5: ZWDongle_ReadAnswer: arg: battery regexp: ^00040006
2015.05.23 23:30:42 5: ZWDongle/RAW: /01080004000602
2015.05.23 23:30:42 5: ZWDongle/RAW: 01080004000602/84077418
2015.05.23 23:30:42 5: SW: 06
2015.05.23 23:30:42 5: ZWDongle_Read ZWDongle: 00040006028407
2015.05.23 23:30:42 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:028407
2015.05.23 23:30:42 3: ZWave_SENSOR_BINARY_6.Battery return value: wakeup:notification
2015.05.23 23:30:42 4: ZWDongle: CANCEL received, retransmitting.
2015.05.23 23:30:42 5: SW: 01080013060280020567
2015.05.23 23:30:42 5: ZWDongle/RAW: /060104011301e8
2015.05.23 23:30:42 5: SW: 06
2015.05.23 23:30:42 5: ZWDongle_Read ZWDongle: 011301
2015.05.23 23:30:42 5: ZWDongle dispatch 011301
2015.05.23 23:30:42 5: ZWDongle/RAW: /01
2015.05.23 23:30:42 5: ZWDongle/RAW: 01/09000400060380036410
2015.05.23 23:30:42 5: SW: 06
2015.05.23 23:30:42 5: ZWDongle_Read ZWDongle: 0004000603800364
2015.05.23 23:30:42 5: ZWDongle dispatch 0004000603800364
2015.05.23 23:30:42 4: ZWDongle CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:03800364

Einen Patch für die 00_CUL.pm habe ich ebenfalls vorbereitet. Die Datei hat zwar nichts mit ZWave zu tun, ist aber ebenfalls von ähnlichen Problemen betroffen.
In welchen anderen Dateien sich ähnliche Probleme finden, kann ich leider nicht überblicken.

Gruß,
Gero

[rudolfkoenig]

Die teilweise verdauten Daten in PARTIAL zu merken, waehrend man Dispatch aufruft, ist jedenfalls richtig, hab dein Patch uebernommen. Die andere Aenderung bei SOF kommt nur bei CRC-Fehler zum Einsatz, das Problem sollte mAn nach auch da geloest werden: habe die Zeile dorthin geschoben.

"Das unzureichende Patternmatching" kann auch auftauchen, ich habe das Regexp jetzt mit der Klasse ergaenzt, sollte in den meisten Faellen reichen.

Das Problem der "Nichtabarbeiten des sendstacks" sehe ich noch nicht.

[gero]

Die teilweise verdauten Daten in PARTIAL zu merken, waehrend man Dispatch aufruft, ist jedenfalls richtig, hab dein Patch uebernommen. Die andere Aenderung bei SOF kommt nur bei CRC-Fehler zum Einsatz, das Problem sollte mAn nach auch da geloest werden: habe die Zeile dorthin geschoben.

"Das unzureichende Patternmatching" kann auch auftauchen, ich habe das Regexp jetzt mit der Klasse ergaenzt, sollte in den meisten Faellen reichen.

Danke für das Einpflegen der Änderungen und das Erweitern des Patternmatchings.

Das Problem der "Nichtabarbeiten des sendstacks" sehe ich noch nicht.

Das Problem gibt es scheinbar doch nicht. Ich hatte mich durch ein Log etwas in die Irre führen lassen.

Es gehört zwar nicht zu ZWave. Aber, da wir am Beispiel von 00_ZWDongle.pm die Problematik identifiziert haben, poste ich trotzdem hier einen Patch für die 00_CUL.pm.
Ich nehme an, dass auch viele andere Modulauthoren, deine Low-Level-Module als Vorlage genommen haben und dass daher auch andere Module von ähnlichen Problemen betroffen sein könnten. Wäre es nicht sinnvoll die entsprechenden Authoren darauf aufmerksam zu machen?

Gruß,
Gero

[rudolfkoenig]

Habs eingebaut.

Ich glaube das Problem tritt beim CUL deutlich seltener auf, da es nicht ueblich ist auf eine Nachricht hin eine Abfrage zu machen, wie das beim batteriebetriebenen ZWave Geraeten der Fall ist. Ich habe aber kein Problem damit, wenn du Modul-Autoren darauf aufmerksam machen willst.

[gero]

Du hast recht: In den meisten Modulen ist der Aufruf von Read -> Parse -> Get -> ReadAnswer wahrscheinlich eher selten. Aber falls doch, kommt es zu evtl. schwer analysierbaren Fehlern. Und eine saubere Basiskommunikation halte ich auch für zukünfigte Module für sehr wichtig.
Ich werde mal nachsehen, welche Module potentiell betroffen sind.

Gruß,
Gero

[krikan]

Hallo Gero, Hallo Rudi,

vermutlich durch die hier diskutierten Änderungen der 00_ZWDongle.pm werden bei mir nun anscheinend Befehle an die Geräte mehrfach  (bis zum Abbruch nach 3 Versuchen) verschickt und auch mehrfach verarbeitet.

In den nachfolgenden Logs kann man das mMn erkennen:

Code Auswählen Erweitern

2015.06.05 19:48:34 2: ZWave get ZWave_SWITCH_BINARY_6 powerlevelTest
2015.06.05 19:48:34 5: ZWDongle_Write msg 130602730505
2015.06.05 19:48:34 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 0
2015.06.05 19:48:34 5: ZWave_ProcessSendStack: sending msg 01080013060273050593
2015.06.05 19:48:34 5: SW: 01080013060273050593
2015.06.05 19:48:34 4: ZWDongle_ReadAnswer arg:powerlevelTest regexp:^00040006..73
2015.06.05 19:48:34 5: ZWDongle_ReadAnswer: read 7 bytes
2015.06.05 19:48:34 5: ZWDongle RAW buffer: 060104011301e8
2015.06.05 19:48:34 5: ZWDongle_0: ACK received
2015.06.05 19:48:34 5: ZWDongle_Read -> sending ACK
2015.06.05 19:48:34 5: SW: 06
2015.06.05 19:48:34 5: ZWDongle_Read ZWDongle_0: processing 011301
2015.06.05 19:48:34 5: ZWDongle_0 dispatch 011301
2015.06.05 19:48:34 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:34 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:48:34 5: ZWDongle_Read returning local msg undef hash PARTIAL:
2015.06.05 19:48:34 5: ZWDongle_ReadAnswer: read 14 bytes
2015.06.05 19:48:34 5: ZWDongle RAW buffer: 010c0004000606730604010046c1
2015.06.05 19:48:34 5: ZWDongle_Read -> sending ACK
2015.06.05 19:48:34 5: SW: 06
2015.06.05 19:48:34 5: ZWDongle_Read ZWDongle_0: processing 0004000606730604010046
2015.06.05 19:48:34 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:34 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:48:34 5: ZWDongle_Read returning local msg 0004000606730604010046 hash PARTIAL:
2015.06.05 19:48:35 5: ZWDongle_ReadAnswer: returning 0004000606730604010046
2015.06.05 19:48:35 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:06730604010046
2015.06.05 19:48:36 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:36 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.05 19:48:36 5: ZWave_ProcessSendStack: sending msg 01080013060273050593
2015.06.05 19:48:36 5: SW: 01080013060273050593
2015.06.05 19:48:36 5: ZWDongle RAW buffer: 060104011301e8
2015.06.05 19:48:36 5: ZWDongle_0: ACK received
2015.06.05 19:48:36 5: ZWDongle_Read -> sending ACK
2015.06.05 19:48:36 5: SW: 06
2015.06.05 19:48:36 5: ZWDongle_Read ZWDongle_0: processing 011301
2015.06.05 19:48:36 5: ZWDongle_0 dispatch 011301
2015.06.05 19:48:36 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:36 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:48:36 5: ZWDongle RAW buffer: 010c0004000606730604010046c1
2015.06.05 19:48:36 5: ZWDongle_Read -> sending ACK
2015.06.05 19:48:36 5: SW: 06
2015.06.05 19:48:36 5: ZWDongle_Read ZWDongle_0: processing 0004000606730604010046
2015.06.05 19:48:36 5: ZWDongle_0 dispatch 0004000606730604010046
2015.06.05 19:48:36 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:06730604010046
2015.06.05 19:48:37 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:37 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:48:38 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:38 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.05 19:48:38 5: ZWave_ProcessSendStack: sending msg 01080013060273050593
2015.06.05 19:48:38 5: SW: 01080013060273050593
2015.06.05 19:48:38 5: ZWDongle RAW buffer: 060104011301e8
2015.06.05 19:48:38 5: ZWDongle_0: ACK received
2015.06.05 19:48:38 5: ZWDongle_Read -> sending ACK
2015.06.05 19:48:38 5: SW: 06
2015.06.05 19:48:38 5: ZWDongle_Read ZWDongle_0: processing 011301
2015.06.05 19:48:38 5: ZWDongle_0 dispatch 011301
2015.06.05 19:48:38 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:38 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:48:38 5: ZWDongle RAW buffer: 010c0004000606730604010046c1
2015.06.05 19:48:38 5: ZWDongle_Read -> sending ACK
2015.06.05 19:48:38 5: SW: 06
2015.06.05 19:48:38 5: ZWDongle_Read ZWDongle_0: processing 0004000606730604010046
2015.06.05 19:48:38 5: ZWDongle_0 dispatch 0004000606730604010046
2015.06.05 19:48:38 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:06730604010046
2015.06.05 19:48:39 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:39 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:48:43 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:43 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.05 19:48:43 5: ZWave_ProcessSendStack: sending msg 01080013060273050593
2015.06.05 19:48:43 5: SW: 01080013060273050593
2015.06.05 19:48:44 5: ZWDongle RAW buffer: 060104011301e8
2015.06.05 19:48:44 5: ZWDongle_0: ACK received
2015.06.05 19:48:44 5: ZWDongle_Read -> sending ACK
2015.06.05 19:48:44 5: SW: 06
2015.06.05 19:48:44 5: ZWDongle_Read ZWDongle_0: processing 011301
2015.06.05 19:48:44 5: ZWDongle_0 dispatch 011301
2015.06.05 19:48:44 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:44 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:48:44 5: ZWDongle RAW buffer: 010c0004000606730604010046c1
2015.06.05 19:48:44 5: ZWDongle_Read -> sending ACK
2015.06.05 19:48:44 5: SW: 06
2015.06.05 19:48:44 5: ZWDongle_Read ZWDongle_0: processing 0004000606730604010046
2015.06.05 19:48:44 5: ZWDongle_0 dispatch 0004000606730604010046
2015.06.05 19:48:44 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:06730604010046
2015.06.05 19:48:45 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:48:45 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.05 19:48:45 1: ZWave_ProcessSendStack: max send retrys reached -> cancel sending
Obwohl die Antwort auf die Abfrage bereits gekommen ist, wird die Anfrage nochmals verschickt. Auch das wird wieder beantwortet und dann kommt der Abbruch.

Hier das gleiche für eine andere Abfrage. Ich kann das beliebig reproduzieren.

Code Auswählen Erweitern

015.06.05 19:51:56 2: ZWave get ZWave_SWITCH_BINARY_6 version
2015.06.05 19:51:56 5: ZWDongle_Write msg 130602861105
2015.06.05 19:51:56 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 0
2015.06.05 19:51:56 5: ZWave_ProcessSendStack: sending msg 01080013060286110572
2015.06.05 19:51:56 5: SW: 01080013060286110572
2015.06.05 19:51:56 4: ZWDongle_ReadAnswer arg:version regexp:^00040006..86
2015.06.05 19:51:56 5: ZWDongle_ReadAnswer: read 7 bytes
2015.06.05 19:51:56 5: ZWDongle RAW buffer: 060104011301e8
2015.06.05 19:51:56 5: ZWDongle_0: ACK received
2015.06.05 19:51:56 5: ZWDongle_Read -> sending ACK
2015.06.05 19:51:56 5: SW: 06
2015.06.05 19:51:56 5: ZWDongle_Read ZWDongle_0: processing 011301
2015.06.05 19:51:56 5: ZWDongle_0 dispatch 011301
2015.06.05 19:51:56 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:51:56 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:51:56 5: ZWDongle_Read returning local msg undef hash PARTIAL:
2015.06.05 19:51:56 5: ZWDongle_ReadAnswer: read 17 bytes
2015.06.05 19:51:56 5: ZWDongle RAW buffer: 010f0004000609861203035c0318500078
2015.06.05 19:51:56 5: ZWDongle_Read -> sending ACK
2015.06.05 19:51:56 5: SW: 06
2015.06.05 19:51:56 5: ZWDongle_Read ZWDongle_0: processing 0004000609861203035c03185000
2015.06.05 19:51:56 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:51:56 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:51:56 5: ZWDongle_Read returning local msg 0004000609861203035c03185000 hash PARTIAL:
2015.06.05 19:51:56 5: ZWDongle_ReadAnswer: returning 0004000609861203035c03185000
2015.06.05 19:51:56 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:09861203035c03185000
2015.06.05 19:51:57 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:51:57 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.05 19:51:57 5: ZWave_ProcessSendStack: sending msg 01080013060286110572
2015.06.05 19:51:57 5: SW: 01080013060286110572
2015.06.05 19:51:57 5: ZWDongle RAW buffer: 060104011301e8
2015.06.05 19:51:57 5: ZWDongle_0: ACK received
2015.06.05 19:51:57 5: ZWDongle_Read -> sending ACK
2015.06.05 19:51:57 5: SW: 06
2015.06.05 19:51:57 5: ZWDongle_Read ZWDongle_0: processing 011301
2015.06.05 19:51:57 5: ZWDongle_0 dispatch 011301
2015.06.05 19:51:57 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:51:57 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:51:57 5: ZWDongle RAW buffer: 010f0004000609861203035c0318500078
2015.06.05 19:51:57 5: ZWDongle_Read -> sending ACK
2015.06.05 19:51:57 5: SW: 06
2015.06.05 19:51:57 5: ZWDongle_Read ZWDongle_0: processing 0004000609861203035c03185000
2015.06.05 19:51:57 5: ZWDongle_0 dispatch 0004000609861203035c03185000
2015.06.05 19:51:57 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:09861203035c03185000
2015.06.05 19:51:57 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:51:57 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:51:58 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:51:58 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.05 19:51:58 5: ZWave_ProcessSendStack: sending msg 01080013060286110572
2015.06.05 19:51:58 5: SW: 01080013060286110572
2015.06.05 19:51:58 5: ZWDongle RAW buffer: 060104011301e8
2015.06.05 19:51:58 5: ZWDongle_0: ACK received
2015.06.05 19:51:58 5: ZWDongle_Read -> sending ACK
2015.06.05 19:51:58 5: SW: 06
2015.06.05 19:51:58 5: ZWDongle_Read ZWDongle_0: processing 011301
2015.06.05 19:51:58 5: ZWDongle_0 dispatch 011301
2015.06.05 19:51:58 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:51:58 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:51:58 5: ZWDongle RAW buffer: 010f0004000609861203035c0318500078
2015.06.05 19:51:58 5: ZWDongle_Read -> sending ACK
2015.06.05 19:51:58 5: SW: 06
2015.06.05 19:51:58 5: ZWDongle_Read ZWDongle_0: processing 0004000609861203035c03185000
2015.06.05 19:51:58 5: ZWDongle_0 dispatch 0004000609861203035c03185000
2015.06.05 19:51:58 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:09861203035c03185000
2015.06.05 19:51:59 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:51:59 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:52:00 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:52:00 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.05 19:52:00 5: ZWave_ProcessSendStack: sending msg 01080013060286110572
2015.06.05 19:52:00 5: SW: 01080013060286110572
2015.06.05 19:52:00 5: ZWDongle RAW buffer: 060104011301e8
2015.06.05 19:52:00 5: ZWDongle_0: ACK received
2015.06.05 19:52:00 5: ZWDongle_Read -> sending ACK
2015.06.05 19:52:00 5: SW: 06
2015.06.05 19:52:00 5: ZWDongle_Read ZWDongle_0: processing 011301
2015.06.05 19:52:00 5: ZWDongle_0 dispatch 011301
2015.06.05 19:52:00 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:52:00 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:52:00 5: ZWDongle RAW buffer: 010f0004000609861203035c0318500078
2015.06.05 19:52:00 5: ZWDongle_Read -> sending ACK
2015.06.05 19:52:00 5: SW: 06
2015.06.05 19:52:00 5: ZWDongle_Read ZWDongle_0: processing 0004000609861203035c03185000
2015.06.05 19:52:00 5: ZWDongle_0 dispatch 0004000609861203035c03185000
2015.06.05 19:52:00 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:06 ARG:09861203035c03185000
2015.06.05 19:52:00 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:52:00 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.05 19:52:01 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.05 19:52:01 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.05 19:52:01 1: ZWave_ProcessSendStack: max send retrys reached -> cancel sending

Nach meiner Meinung sollte das so nicht sein oder übersehe/mißinterpretiere ich etwas?

Wenn ich mir openzwave anschaue, wird dort nach meinem Verständnis bei fehlendem ACK auch nicht mehr mehrfach verschickt.
Aus https://github.com/OpenZWave/open-zwave/blob/f99b8b35307f7bcc5a8e140afe895cf7eaf28574/cpp/src/Defs.h:

#define MAX_TRIES   1   // set this to one, as I believe now that a ACK failure is indication that the device is offline, hence additional attempts will not work.

Mehrfach (bis zu 7x) wird nach meinem Nicht-Programmiererverständnis (also bitte Nachsicht) nur bei CAN verschickt.

Wäre schön, wenn Ihr Euch das einmal anschauen könntet.

Danke und Gruß, Christian

[gero]

Tut mit leid, ich kann mich erst in zwei Wochen wieder drum kümmern. Bin im Urlaub.
In den letzten openzwave Sourcen, die ich gesehen habe, stand MAX_TRIES mMn auf 3.
Ich werde es mir aber dann gerne nochmal ansehen.

Gruß,
Gero

[krikan]

@gero:
Am Meisten wundert mich halt, dass mehrfach verschickt wird, obwohl Antwort vom Gerät kommt. MAX_TRIES in ozw ist mir nur bei der Suche nach dem Problem untergekommen und nicht so wichtig.
Schönen Urlaub und keine Hektik, Christian

[rudolfkoenig]

00_ZWDongle fuehrt ein resend aus, falls Nachrichten an Geraete (01....13.*, also nicht an das Dongle selbst) nicht mit ZW_SEND_DATA:OK (0013..00) bestaetigt wurden. Falls ich z.Bsp version abfrage, dann kriege ich zunaechst ein 06 (ACK), dann ein 011301 (??), und dann ein 00130500 (ZW_SEND_DATA:OK). Nach dieser Nachricht entfernt 00_ZWDongle die Versions-Abfrage vom SendStack, damit wird es nicht nochmal gesendet. Anschliessend kommt die eigentliche Nachricht mit dem Antwort des Geraetes. In deinem Fall gab es nur 06 und 011301, aber kein 0013..00.

Der Patch von gero sollte an diesem Verhalten nichts aendern, das war mAn auch frueher schon so.
Gero hat den SendStack fuer Nachrichten, die direkt an das Dongle gehen, aktiviert.

Nach dem openzwave Kommentar klingt es so, dass im Falle eines Funkproblems die Resends vom Dongle ausgefuehrt werden, da bin ich aber noch unsicher und das sollten wir verifizieren.

Genauso interessant waere zu wissen, was genau 011301 zu bedeuten hat.

[krikan]

aber kein 0013..00

Das fehlt bei meinem Vison-Controller anscheinend seit kurzem immer. Habe es gerade auf einer "frischen" Fhem-Installation ausprobiert und dort das gleiche Problem. Mein Experimentiercontroller UZB1 hat das Problem definitv nicht, dort gibt es die "transmit ..OK" - Einträge im Log noch und es wird alles nur 1x  verschickt. Also eine Macke in meiner Installation, bei der ich keine Ahnung habe, wie ich den Vision-Controller wieder auf Spur bringe. Da das mein Controller für das Produktivsystem ist, ziehe ich mich mit dem Reset etwas. Sorry für die falsche "Verdächtigung".

Der Patch von gero sollte an diesem Verhalten nichts aendern, das war mAn auch frueher schon so.

Nach meiner Erinnerung wurde früher aber nur 1x verschickt, einen Resend gab es doch nicht?

Nach dem openzwave Kommentar klingt es so, dass im Falle eines Funkproblems die Resends vom Dongle ausgefuehrt werden, da bin ich aber noch unsicher und das sollten wir verifizieren.

Verstehe ich eben auch so; zumindest, wenn die zu verschickende Nachricht ordnungsgemäß im Controller landet. Ansonsten machen mMn die TRANSMIT_OPTIONS bei SEND_DATA keinen Sinn (-> Explorer Frames).
Hast Du ein Testsetup im Kopf, wie man das verifizieren könnte? Ansonsten suche ich mal die Stellen im INS*.

[krikan]

Genauso interessant waere zu wissen, was genau 011301 zu bedeuten hat.

01= Antwort auf
13= ZW_SEND_DATA
01= vermutlich OK, wenn 00=FALSE
Dokumentiert ist nur FALSE: "If transmit queue overflow"

Die bei meinem Vision fehlende Nachricht 0013..00 (00 13 [callbackID] [txStatus]) kommt erst, wenn Telegrammübermittlung komplett. callback soll immer überprüft werden, um festzustellen, wann das nächste Telegramm verschickt werden soll; ansonsten "will overflow the transmit queue and eventually fail". Ob das wirklich Ursache für mein Problem mit Vision Stick wage ich zu bezweifeln.

CAN/SOF/NCK müssten mMn noch eine Ebene tiefer liegen.

[rudolfkoenig]

Ich haette es gerne genauer. Dass 0113 Anwer/ZW_SEND_DATA ist, das habe ich schon geahnt, aber wer schickt es wann genau? Bei 0013..XX ist XX=00 OK, und XX=01 NO_ACK (siehe ZWave.pm) Wieso ist es bei 0113XX andersrum? Kann ich SendQueue auch bei einem 0113 abhaken oder erst bei dem 0013? In deinem Fall muesste 011301 den Eintrag entfernen, die Frage ist, ob das immer richtig ist, oder nur bei bestimmten Sticks. Oder haengt es mit deinem lokalen EF Modifikation zusammen?

[krikan]

Ich haette es gerne genauer.

Schwierig, da ich keine genaueren Infos als die INS* kenne. Habe das daraus (bruckstückhaft) zitiert. Vermutlich hast Du dort auch schon reingeschaut.
0113 Anwer/ZW_SEND_DATA ist Return-Wert der Funktion ZW_SEND_DATA, der sofort kommt. 0013 ist die Antwort aus callback, die irgendwann kommt.

Wieso ist es bei 0113XX andersrum?

Die Aussage zu 00/01 war nur eine Vermutung, da wir bisher immer 01 hatten. Hoffe das ist nicht alles FALSE gewesen.
In der alten ZENSYS ZW_transport_api.h http://svn.linuxmce.org/trac/browser/trunk/src/ZWave/ZW_transport_api.h?rev=7476 habe ich auch keine definitiven Anhaltspunkte erkannt.

Kann ich SendQueue auch bei einem 0113 abhaken oder erst bei dem 0013? In deinem Fall muesste 011301 den Eintrag entfernen, die Frage ist, ob das immer richtig ist, oder nur bei bestimmten Sticks. Oder haengt es mit deinem lokalen EF Modifikation zusammen?

So wie es in Fhem eingebaut ist, ist es nach meinem Verständnis korrekt. Nur über die Wiederholungen sollten wir noch nachdenken.

Das mein Stick 0013 seit einigen Tagen nicht mehr liefert ist der Fehler. Wie der entstanden ist, verstehe ich nicht. An EF sollte es nicht liegen, da ich das Problem mit unmodifiziertem Fhem habe und mit neu aufgesetztem Fhem noch mal gegengecheckt habe.

[rudolfkoenig]

Nur über die Wiederholungen sollten wir noch nachdenken.

Bin ganz offen, und unentschlossen:
- 1-mal wie frueher? Es wuerde aber eine Meldung auf Log 1 nach sich ziehen.
- oder per Attribut ganz abschaltbar?
- oder per Attribut 011301 mit 0013..00 gleichsetzen?

[krikan]

Bin ganz offen, und unentschlossen:
- 1-mal wie frueher? Es wuerde aber eine Meldung auf Log 1 nach sich ziehen.
- oder per Attribut ganz abschaltbar?
- oder per Attribut 011301 mit 0013..00 gleichsetzen?

Ich auch. Letztes würde ich aber erst mal ausschließen, da bei meinem Controller anscheinend etwas kaputt ist und das kann nicht Grundlage sein.
Irgendwie stört mich nur das mehrfache Senden. Dies verschleiert nur schlechte oder fehlerhafte Systeme/Kommunikation; so oder ähnlich hat das nach meiner Erinnerung hier auch mal ein Entwickler geschrieben  . Vielleicht sollten wir auf Gero warten und ich suche bei Gelegenheit noch mal Infos zur automatischen Wiederholung von Telegrammen durch Controller.

[krikan]

Code Auswählen Erweitern

00 13 [callbackID] [txStatus]
btw.: Gibt es eigentlich einen Grund dafür, dass die callbackID in Zeile 638 10_ZWave.pm nur bei set-Befehlen für Geräte auf die nodeId gesetzt wird und nicht auch bei get-Befehlen (->Reading "transmit") ?

[rudolfkoenig]

Da die CallBackId in FHEM nicht ausgewertet wird, habe ich es zunaechst nur da eingefuehrt, wo es mir unerlaesslich schien. Insb. wollte ich nicht alles nochmal durchtesten, falls die Antwort einen anderen Format haben sollte.

[krikan]

callbackId bei set wird doch als Kontrolle für korrekten Versand genutzt und setzt Reading "transmit" beim Geräte-Device bzw. "state" bei Problemen. Darum irritiert mich Deine Aussage, dass callbackId in FHEM nicht ausgewertet wird. Habe ich das falsch verstanden?

Bei get-Befehlen wird derzeit immer die TRANSMIT_OPTION 05 als callbackId genutzt. Setzt das nicht immer bei nodeId 05 das Reading "transmit" bei get-Befehlen, egal welche nodeId abgefragt wird (habe keine nodeId 5)? Habe gestern abend if-Abfrage in der besagten Zeile rausgenommen. Probleme sehe ich auf Anhieb nicht, nur den Vorteil, das "transmit" auch bei "get" gesetzt wird und die Zuordnung zum Gerät passt. Fände ich so auch sinnvoller. Beim funktionierenden Testcontroller habe ich aber nur 2 Nodes und meinen Produktivcontroller habe ich noch nicht wieder im Griff .

[krikan]

Bei get-Befehlen wird derzeit immer die TRANSMIT_OPTION 05 als callbackId genutzt.

DIe Aussage von mir ist nach nochmaligen Test falsch. Es ist nicht immer callbackId 05. Nach einem reboot ist es derzeit 06. Da ich die nodeid 06 habe, sieht man auch, dass get-Befehle von anderen nodeId das Reading "transmit" setzen. Bsp.: "get nodeid4 version" führt zur Aktualisierung Reading "transmit" nodeid6.
System erkenne ich derzeit nicht. Nur bringt mich das zur Schlußfolgerung, dass Setzen der callbackId bei get auch zwingend ist. Es wäre schön, wenn das jemand noch mal gegentesten könnte.

PS: Nach erneutem reboot ist callbackId bei get wieder immer 05.

[rudolfkoenig]

Nach etwas Code-Inspizieren:
- get und set sind gleich, da beide durch ZWave_Cmd realisiert wurden.
- falls das Geraet kein WAKE_UP hat, dann bekommen alle Befehle ein callbackId.
- das callbackId ist immer das nodeId des Geraetes, der angesprochen werden soll.
- callbackid wird nur bei den ZW_SEND_DATA Befehlen geprueft, um das transmit Reading zu setzen.

[krikan]

Das heißt: Bei meinem Setup stimmt etwas nicht? Ich müsste bei allen get-Befehlen auch in 00 13 xx 00 xx=nodeId haben?

[rudolfkoenig]

Ich war bei meinem vorigen Analyse geistig nicht bei der Sache:
- callbackid wird bei Geraeten ohne WAKE_UP nur bei set gesetzt.
- bei  Geraeten mit WAKE_UP nur dann, falls das Befehl nicht sofort gesendet wird (da Geraet schlaeft).

Ich meine diese Sonderfaelle gehoeren abgeschafft.

[krikan]

Beruhigt mich enorm.

Ja, die Sonderfälle müssten raus. Insbesondere, da das bei get zu falschen transmit-Readings führt und ich auch andere Nebenwirkungen bei fehlenden Callbacks befürchte. Ich hatte hierzu -wie geschrieben- Zeile 638 von 10_ZWave.pm so geändert, dass überall die nodeId=callbackId und keine Probleme festgestellt. Überlege nur noch, welche Nach-/Vorteile eine separate CallbackId-Liste (callbackId => nodeId) hätte.

WAKE_UP Geräte hatte ich mir in dem Zusammenhang noch nicht angeschaut, aber die sollten auch callbackIds nutzen.

[krikan]

Beim Anschauen der WAKE_UP-Geräte fällt mir nebenbei auf:
bei leerem Sendstack wird keine wakeUpNoMoreInformation-Nachricht an die Geräte verschickt -> Geräte bleiben mit geräteabhängige Maximalzeit wach und Batterie wird nicht geschont. Besser wäre es doch bei leerem Sendstack nach 1-2 Sekunden automatisch eine wakeUpNoMoreInformation-Nachricht an das Gerät zu schicken. Nur gibt es schon einen InternalTimer in 10_ZWave.pm und irgendwie scheinen sich bei meinen Versuchen 2 nicht zu vertragen!?

Zurück zu 00_ZWDongle und Wiederholungen:
Schickt man eine Nachricht an ein nicht-reagierendes Gerät, wird trotz erhaltener NO_ACK von ZW_SEND_DATA-callback gewartet und gewartet, dann 2x wiederholt gesendet mit den gleichen Wartezeiten bis dann endlich abgebrochen wird. Ergibt eine Laufzeit von 9 Sekunden. Das finde ich nicht optimal. Eigentlich müsste doch zumindest nach NO_ACK sofort wiederholt gesendet werden und nicht weiter auf ein (nie eintretendes) ACK von ZW_SEND_DATA-callback gewartet werden:

Code Auswählen Erweitern

2015.06.08 20:40:18 2: ZWave get ZWave_SWITCH_MULTILEVEL_4 swbStatus
2015.06.08 20:40:18 5: ZWDongle_Write msg 13040225020504
2015.06.08 20:40:18 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 0
2015.06.08 20:40:18 5: ZWave_ProcessSendStack: sending msg 01090013040225020504c5
2015.06.08 20:40:18 5: SW: 01090013040225020504c5
2015.06.08 20:40:18 4: ZWDongle_ReadAnswer arg:swbStatus regexp:^00040004..25
2015.06.08 20:40:18 5: ZWDongle_ReadAnswer: read 1 bytes
2015.06.08 20:40:18 5: ZWDongle RAW buffer: 06
2015.06.08 20:40:18 5: ZWDongle_0: ACK received
2015.06.08 20:40:18 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:18 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:18 5: ZWDongle_Read returning local msg undef hash PARTIAL:
2015.06.08 20:40:18 5: ZWDongle_ReadAnswer: read 6 bytes
2015.06.08 20:40:18 5: ZWDongle RAW buffer: 0104011301e8
2015.06.08 20:40:18 5: ZWDongle_Read ZWDongle_0: ACK, processing 011301
2015.06.08 20:40:18 5: SW: 06
2015.06.08 20:40:18 5: ZWDongle_0 dispatch 011301
2015.06.08 20:40:18 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:18 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:18 5: ZWDongle_Read returning local msg undef hash PARTIAL:
2015.06.08 20:40:19 5: ZWDongle_ReadAnswer: read 7 bytes
2015.06.08 20:40:19 5: ZWDongle RAW buffer: 010500130401ec
2015.06.08 20:40:19 5: ZWDongle_Read ZWDongle_0: ACK, processing 00130401
2015.06.08 20:40:19 5: SW: 06
2015.06.08 20:40:19 5: ZWDongle_0 dispatch 00130401
2015.06.08 20:40:19 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.08 20:40:19 2: ZWDongle_0 transmit NO_ACK for 04
2015.06.08 20:40:19 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:19 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.08 20:40:19 5: ZWave_ProcessSendStack: sending msg 01090013040225020504c5
2015.06.08 20:40:19 5: SW: 01090013040225020504c5
2015.06.08 20:40:19 5: ZWDongle_Read returning local msg undef hash PARTIAL:
2015.06.08 20:40:19 5: ZWDongle_ReadAnswer: read 1 bytes
2015.06.08 20:40:19 5: ZWDongle RAW buffer: 06
2015.06.08 20:40:19 5: ZWDongle_0: ACK received
2015.06.08 20:40:19 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:19 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:19 5: ZWDongle_Read returning local msg undef hash PARTIAL:
2015.06.08 20:40:19 5: ZWDongle_ReadAnswer: read 6 bytes
2015.06.08 20:40:19 5: ZWDongle RAW buffer: 0104011301e8
2015.06.08 20:40:19 5: ZWDongle_Read ZWDongle_0: ACK, processing 011301
2015.06.08 20:40:19 5: SW: 06
2015.06.08 20:40:19 5: ZWDongle_0 dispatch 011301
2015.06.08 20:40:19 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:19 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:19 5: ZWDongle_Read returning local msg undef hash PARTIAL:
2015.06.08 20:40:20 5: ZWDongle_ReadAnswer: read 7 bytes
2015.06.08 20:40:20 5: ZWDongle RAW buffer: 010500130401ec
2015.06.08 20:40:20 5: ZWDongle_Read ZWDongle_0: ACK, processing 00130401
2015.06.08 20:40:20 5: SW: 06
2015.06.08 20:40:20 5: ZWDongle_0 dispatch 00130401
2015.06.08 20:40:20 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.08 20:40:20 2: ZWDongle_0 transmit NO_ACK for 04
2015.06.08 20:40:20 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:20 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:20 5: ZWDongle_Read returning local msg undef hash PARTIAL:
2015.06.08 20:40:23 5: ZWDongle_ReadAnswer: select timeout
2015.06.08 20:40:23 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:23 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.08 20:40:23 5: ZWave_ProcessSendStack: sending msg 01090013040225020504c5
2015.06.08 20:40:23 5: SW: 01090013040225020504c5
2015.06.08 20:40:23 5: ZWDongle RAW buffer: 06
2015.06.08 20:40:23 5: ZWDongle_0: ACK received
2015.06.08 20:40:23 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:23 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:23 5: ZWDongle RAW buffer: 0104011301e8
2015.06.08 20:40:23 5: ZWDongle_Read ZWDongle_0: ACK, processing 011301
2015.06.08 20:40:23 5: SW: 06
2015.06.08 20:40:23 5: ZWDongle_0 dispatch 011301
2015.06.08 20:40:23 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:23 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:24 5: ZWDongle RAW buffer: 010500130401ec
2015.06.08 20:40:24 5: ZWDongle_Read ZWDongle_0: ACK, processing 00130401
2015.06.08 20:40:24 5: SW: 06
2015.06.08 20:40:24 5: ZWDongle_0 dispatch 00130401
2015.06.08 20:40:24 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.08 20:40:24 2: ZWDongle_0 transmit NO_ACK for 04
2015.06.08 20:40:24 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:24 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:25 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:25 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.08 20:40:25 5: ZWave_ProcessSendStack: sending msg 01090013040225020504c5
2015.06.08 20:40:25 5: SW: 01090013040225020504c5
2015.06.08 20:40:25 5: ZWDongle RAW buffer: 06
2015.06.08 20:40:25 5: ZWDongle_0: ACK received
2015.06.08 20:40:25 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:25 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:25 5: ZWDongle RAW buffer: 0104011301e8
2015.06.08 20:40:25 5: ZWDongle_Read ZWDongle_0: ACK, processing 011301
2015.06.08 20:40:25 5: SW: 06
2015.06.08 20:40:25 5: ZWDongle_0 dispatch 011301
2015.06.08 20:40:25 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:25 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:25 5: ZWDongle RAW buffer: 010500130401ec
2015.06.08 20:40:25 5: ZWDongle_Read ZWDongle_0: ACK, processing 00130401
2015.06.08 20:40:25 5: SW: 06
2015.06.08 20:40:25 5: ZWDongle_0 dispatch 00130401
2015.06.08 20:40:25 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.08 20:40:25 2: ZWDongle_0 transmit NO_ACK for 04
2015.06.08 20:40:26 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:26 5: ZWave_ProcessSendStack: waiting for ACK -> check again
2015.06.08 20:40:27 5: ZWave_ProcessSendStack: 1 items on stack, waitForAck 1
2015.06.08 20:40:27 2: ZWave_ProcessSendStack: timeout sending message -> trigger resend
2015.06.08 20:40:27 1: ZWave_ProcessSendStack: max send retrys reached -> cancel sending

Bei der Recherche habe ich noch folgende Infos gefunden:
Der mit "set ZW_Dongle timeouts" gesetzte Timeout soll beim Warten im Programm wegen Telegrammlaufzeiten etwas größer sein. Bsp.: Dongle: 1,5 / Programm: 2,0 Sek. In Fhem ist das jetzt jeweils 1 Sek.
Das Dongle verschickt korrekt im transmit queue eingestellte Telegramme bei Fehlern in der Route/Erreichbarkeit des Nodes automatisch mehrfach über mehrere Ausweichrouten (bei TRANSMIT_OPTION 05 bzw. bei Einschluß Explorer Frames) ohne Mitwirkung des Programms. NO_ACK über"transmit complete callback" von ZW_SEND_DATA kommt, wenn keine Antwort bei allen Versuchen kommt bzw. dass beim Dongle festgelegte timeout überschritten wird.

[krikan]

@gero und Rudi:
Meine Spekulationen/Aussagen haben keine Eile. Ich  halte das nur hier fest bevor ich es wieder vergesse , da ich gerade die geänderte Fassungen der ZWave-Module mit Unmengen Log-Aufrufen für mein Verständnis versehe...

[rudolfkoenig]

Wie lange ist eigentlich die "Maximalzeit wach"? Ich dachte 1-2 Sekunden.
FHEM muesste abwarten, ob nicht via notify requests abgeschickt werden, aber dafuer wuerde auch 0.1 Sec reichen. Ich frag mich, ob es einen Unterschied macht.

Die ACK-Logik bin ich auch schon am umbauen, da bei der SEC-Inlusion mit der aktuellen Version komische Wiederholungen gibt.

[krikan]

Wie lange ist eigentlich die "Maximalzeit wach"? Ich dachte 1-2 Sekunden.

Aus der Erinnerung hätte ich 5-10 Sekunden behauptet.
Aber Paetz schreibt in der alten Auflage seines Buches auf S. 81, dass das erst ca. eine Minute nach dem letzten empfangenen und verarbeiteten Befehl geschieht, wenn keine wakeUpNoMoreInformation versandt wird. Eigentlich sollte der es wissen und dann verstehe ich auch, warum mein Philio-Sensor immer so viele Batterien schluckt. Dachte, das liegt an meinen Experimenten.

Die ACK-Logik bin ich auch schon am umbauen, da bei der SEC-Inlusion mit der aktuellen Version komische Wiederholungen gibt.

Prima. Obwohl ich dann wieder Tage/Wochen brauche um es halbwegs zu verstehen .

Gegen die Wiederholungen von ZW_SEND_DATA bei callbacks mit Fehlermeldungen sprechen nach nochmaligen Überlegen auch die Explorer Frames. Explorer Frames sollen die Funklast deutlich erhöhen und werden selbst vom api beschränkt. Wenn Fhem dann Explorer Frames verschicken würde, sollten bei aktuellen Geräten ein NO_ACK aus callback ZW_SEND_DATA ausreichen, um hinreichend sicher zu sein, dass das Gerät nicht erreichbar ist. Wiederholungen würden die Funklast nur unnötig weiter hochtreiben. Also ich komme immer mehr zum Schluß, dass ich ZW_SEND_DATA-Wiederholungen bei Fehlern im callback nicht so gut finde und das lieber konfigurierbar hätte.

[krikan]

Aber Paetz schreibt in der alten Auflage seines Buches auf S. 81, dass das erst ca. eine Minute nach dem letzten empfangenen und verarbeiteten Befehl geschieht, wenn keine wakeUpNoMoreInformation versandt wird.

Habe mir die aktuelle Auflage gegönnt und dort heißt es nun bei Pos. 1614 (Seite kann ich im Ebook nicht erkennen): "nach einer im Gerät individuell programmierten Zeit"
Also: mal so, mal so... aber wakeUpNoMoreInformation wäre mMn trotzdem immer sinnvoll

[krikan]

FHEM muesste abwarten, ob nicht via notify requests abgeschickt werden, aber dafuer wuerde auch 0.1 Sec reichen. Ich frag mich, ob es einen Unterschied macht.

Könnte 0.1 nicht Probleme bereiten, wenn andere Geräte mit dem wakeup-Gerät direkt assoziert sind, d.h. Controller schickt zu früh in den Schlaf bevor direkte Assoziations-Kommunikation bspw. zwischen Bewegungsmelder und Schaltaktor verarbeitet ist.
Openhab hat derzeit eine Pause von 1 Sek., bis vor kurzem noch 2 Sek.
Bei openzwave finde ich dazu auf Anhieb nichts.

[rudolfkoenig]

Na FHEM wuerde nur sagen, dass jetzt nichts mehr zu sagen gibt (wakeUpNoMoreInformation).
Die Kommunikation zw. batteriebetriebenes Geraet und Anderen sollte davon nicht betroffen sein, und ob das Geraet sich danach schlafen laegt oder nicht, ist ihm ueberlassen.

[krikan]

Na dann, ausprobieren ...

[rudolfkoenig]

Ab sofort wird nach einem wakeup:notification nach 0.1 Sekunde ein wakeupNoMoreInformation gesendet, falls der WakeUp Stack leer ist.

Habs nicht getestet, da ich z.Zt. kein WAKE_UP Geraet mit sinnvollen timeout habe.
-> Waere wg. feedback dankbar.

[krikan]

Habe per notify auf wakeup:.notification "get ZWave_Node_7 version" abgesetzt und dann manuell aufgeweckt.
Durch das manuelle Aufwecken wird nach meinem Verständnis wakeup:.notification 2x ausgelöst und die letzte Abfrage von "get ZWave_Node_7 version" läuft in NO_ACK.

Code Auswählen Erweitern

2015.06.14 17:01:35 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400070d8f0101097105000000ff070300
2015.06.14 17:01:35 5: SW: 06
2015.06.14 17:01:35 5: ZWDongle_0 dispatch 000400070d8f0101097105000000ff070300
2015.06.14 17:01:35 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:07 ARG:0d8f0101097105000000ff070300
2015.06.14 17:01:37 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00040007028407
2015.06.14 17:01:37 5: SW: 06
2015.06.14 17:01:37 5: ZWDongle_0 dispatch 00040007028407
2015.06.14 17:01:37 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:07 ARG:028407
2015.06.14 17:01:37 2: ZWave get ZWave_Node_7 version
2015.06.14 17:01:37 5: ZWDongle_Write 00 130702861105
2015.06.14 17:01:37 5: SW: 01080013070286110573
2015.06.14 17:01:37 4: ZWDongle_ReadAnswer arg:version regexp:^00040007..86
2015.06.14 17:01:37 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00040407028407
2015.06.14 17:01:37 5: SW: 06
2015.06.14 17:01:37 5: ZWDongle_0 dispatch 00040407028407
2015.06.14 17:01:37 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:07 ARG:028407
2015.06.14 17:01:37 4: ZWDongle_Read ZWDongle_0: CAN received
2015.06.14 17:01:37 5: SW: 01080013070286110573
2015.06.14 17:01:37 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.14 17:01:37 5: SW: 06
2015.06.14 17:01:37 5: ZWDongle_0 dispatch 011301
2015.06.14 17:01:38 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130700
2015.06.14 17:01:38 5: SW: 06
2015.06.14 17:01:38 5: ZW_SEND_DATA:OK received, removing 01080013070286110573 from sendstack
2015.06.14 17:01:38 5: ZWDongle_0 dispatch 00130700
2015.06.14 17:01:38 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:00 ARG:
2015.06.14 17:01:38 4: ZWDongle_0 transmit OK for 07
2015.06.14 17:01:38 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400070b861203035f01110101010f
2015.06.14 17:01:38 5: SW: 06
2015.06.14 17:01:38 4: ZWDongle_ReadAnswer for version: 000400070b861203035f01110101010f
2015.06.14 17:01:38 4: ZWDongle_0 CMD:APPLICATION_COMMAND_HANDLER ID:07 ARG:0b861203035f01110101010f
2015.06.14 17:01:38 3: test return value: version:Lib 3 Prot 3.95 App 1.17 HW 1 FWCounter 1 FW 1.15
2015.06.14 17:01:38 5: ZWDongle_Write 00 130702840805
2015.06.14 17:01:38 5: SW: 01080013070284080568
2015.06.14 17:01:38 5: ZWDongle_Write 00 130702840805
2015.06.14 17:01:38 5: ZWDongle_Write reordered sendStack
2015.06.14 17:01:38 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.14 17:01:38 5: SW: 06
2015.06.14 17:01:38 5: ZWDongle_0 dispatch 011301
2015.06.14 17:01:38 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130700
2015.06.14 17:01:38 5: SW: 06
2015.06.14 17:01:38 5: ZW_SEND_DATA:OK received, removing 01080013070284080568 from sendstack
2015.06.14 17:01:38 5: ZWDongle_0 dispatch 00130700
2015.06.14 17:01:38 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:00 ARG:
2015.06.14 17:01:38 4: ZWDongle_0 transmit OK for 07
2015.06.14 17:01:38 5: SW: 01080013070284080568
2015.06.14 17:01:38 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.14 17:01:38 5: SW: 06
2015.06.14 17:01:38 5: ZWDongle_0 dispatch 011301
2015.06.14 17:01:39 2: ZWave_ProcessSendStack: no ACK, resending message
2015.06.14 17:01:39 5: SW: 01080013070284080568
2015.06.14 17:01:39 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.14 17:01:39 5: SW: 06
2015.06.14 17:01:39 5: ZWDongle_0 dispatch 011301
2015.06.14 17:01:39 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130701
2015.06.14 17:01:39 5: SW: 06
2015.06.14 17:01:39 5: ZWDongle_0 dispatch 00130701
2015.06.14 17:01:39 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.14 17:01:39 2: ZWDongle_0 transmit NO_ACK for 07
2015.06.14 17:01:40 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130701
2015.06.14 17:01:40 5: SW: 06
2015.06.14 17:01:40 5: ZWDongle_0 dispatch 00130701
2015.06.14 17:01:40 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.14 17:01:40 2: ZWDongle_0 transmit NO_ACK for 07
2015.06.14 17:01:40 2: ZWave_ProcessSendStack: no ACK, resending message
2015.06.14 17:01:40 5: SW: 01080013070284080568
2015.06.14 17:01:40 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.14 17:01:40 5: SW: 06
2015.06.14 17:01:40 5: ZWDongle_0 dispatch 011301
2015.06.14 17:01:41 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130701
2015.06.14 17:01:41 5: SW: 06
2015.06.14 17:01:41 5: ZWDongle_0 dispatch 00130701
2015.06.14 17:01:41 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.14 17:01:41 2: ZWDongle_0 transmit NO_ACK for 07
2015.06.14 17:01:42 2: ZWave_ProcessSendStack: no ACK, resending message
2015.06.14 17:01:42 5: SW: 01080013070284080568
2015.06.14 17:01:42 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.14 17:01:42 5: SW: 06
2015.06.14 17:01:42 5: ZWDongle_0 dispatch 011301
2015.06.14 17:01:43 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130701
2015.06.14 17:01:43 5: SW: 06
2015.06.14 17:01:43 5: ZWDongle_0 dispatch 00130701
2015.06.14 17:01:43 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.14 17:01:43 2: ZWDongle_0 transmit NO_ACK for 07
2015.06.14 17:01:43 2: ZWave_ProcessSendStack: no ACK, resending message
2015.06.14 17:01:43 1: ERROR: max send retries reached, removing 01080013070284080568 from sendstack

Was mir noch aufgefallen ist: Die Abarbeitung der wakeup-Sendeliste mit foreach führt häufiger zum Abbruch eines Befehls nach den max. Sendeversuchen mit CAN seit den Änderungen in 00_ZWDongle. Derzeit verliere ich bei 10 Befehlen im Schnitt 2 wegen max. CAN. Bei den Tests zur Einführung der Behandlungsänderung der WAKE_UP Geräte hatte ich (damals) keine solchen Verluste und dort hatte ich bis zu 80 Befehle in einem Rutsch. Unterschied in der Testhardware: damals Philio PSM02 und heute PST02; also 400er bzw. 500er Chipsatz.

[rudolfkoenig]

Habs wieder umgebaut , diesmal mit dem KFOB und ZW_APPLICATION_UPDATE getestet (der schickt bei mir entgegen Doku kein wakeup:notification).

Konnte 4 gets vom Stack + 1 via notify abarbeiten. Auch wenn nichts auf dem Stack ist, klappt das get vom notify.
wakeupNoMoreInformation wird zum Schluss gesendet.

[krikan]

Danke für Deine wakeupNoMoreInformation-Änderungen.

Bin ganz offen, und unentschlossen:
- 1-mal wie frueher? Es wuerde aber eine Meldung auf Log 1 nach sich ziehen.
- oder per Attribut ganz abschaltbar?

Schiebe das Thema der Wiederholungen ($hash->{MaxSendRetries}=3;) noch mal hoch, da mich das nach einer weiteren halben Stunde Dauertests nur noch stört: NO_ACK einmal reicht, Wiederholungen führen bei mir nur zu unnötigen Sendeversuchen, Verzögerungen und einem gut gefülltem Log.
Darum meine Bitte/Wunsch:
Kann das nicht bitte zumindest abschaltbar sein? Oder gibt es einen Grund, das so zu machen, den ich noch nicht erkannt habe?

[rudolfkoenig]

Den Grund kennt nur gero. Wir wiederholen jetzt bai CAN, NACK und ausbleiben von ACK.
Entweder bei CAN oder bei NACK sollte man nicht wiederholen, weiss nur nicht bei welchem.

Meinst du mit "NO_ACK einmal reicht", dass es im Fall von NACK kein resend passieren soll?

[krikan]

Hier ein Beispiel, wenn ich einen nicht errichbaren Aktor abfrage:

Code Auswählen Erweitern

2015.06.15 19:25:49 2: ZWave get ZWave_SWITCH_MULTILEVEL_4 version
2015.06.15 19:25:49 5: ZWDongle_Write 00 130402861105
2015.06.15 19:25:49 5: SW: 01080013040286110570
2015.06.15 19:25:49 4: ZWDongle_ReadAnswer arg:version regexp:^00040004..86
2015.06.15 19:25:49 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.15 19:25:49 5: SW: 06
2015.06.15 19:25:49 5: ZWDongle_0 dispatch 011301
2015.06.15 19:25:49 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130501
2015.06.15 19:25:49 5: SW: 06
2015.06.15 19:25:49 5: ZWDongle_0 dispatch 00130501
2015.06.15 19:25:49 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.15 19:25:49 2: ZWDongle_0 transmit NO_ACK for 05
2015.06.15 19:25:52 5: ZWDongle_ReadAnswer: select timeout
2015.06.15 19:25:52 2: ZWave_ProcessSendStack: no ACK, resending message
2015.06.15 19:25:52 5: SW: 01080013040286110570
2015.06.15 19:25:53 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.15 19:25:53 5: SW: 06
2015.06.15 19:25:53 5: ZWDongle_0 dispatch 011301
2015.06.15 19:25:53 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130501
2015.06.15 19:25:53 5: SW: 06
2015.06.15 19:25:53 5: ZWDongle_0 dispatch 00130501
2015.06.15 19:25:53 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.15 19:25:53 2: ZWDongle_0 transmit NO_ACK for 05
2015.06.15 19:25:54 2: ZWave_ProcessSendStack: no ACK, resending message
2015.06.15 19:25:54 5: SW: 01080013040286110570
2015.06.15 19:25:54 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.15 19:25:54 5: SW: 06
2015.06.15 19:25:54 5: ZWDongle_0 dispatch 011301
2015.06.15 19:25:54 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130501
2015.06.15 19:25:54 5: SW: 06
2015.06.15 19:25:54 5: ZWDongle_0 dispatch 00130501
2015.06.15 19:25:54 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.15 19:25:54 2: ZWDongle_0 transmit NO_ACK for 05
2015.06.15 19:25:55 2: ZWave_ProcessSendStack: no ACK, resending message
2015.06.15 19:25:55 5: SW: 01080013040286110570
2015.06.15 19:25:55 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2015.06.15 19:25:55 5: SW: 06
2015.06.15 19:25:55 5: ZWDongle_0 dispatch 011301
2015.06.15 19:25:56 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130501
2015.06.15 19:25:56 5: SW: 06
2015.06.15 19:25:56 5: ZWDongle_0 dispatch 00130501
2015.06.15 19:25:56 4: ZWDongle_0 CMD:ZW_SEND_DATA ID:01 ARG:
2015.06.15 19:25:56 2: ZWDongle_0 transmit NO_ACK for 05
2015.06.15 19:25:57 2: ZWave_ProcessSendStack: no ACK, resending message
2015.06.15 19:25:57 1: ERROR: max send retries reached, removing 01080013040286110570 from sendstack
Nach meinem Verständnis kann ab diesem "transmit NO_ACK" (00130501)

Code Auswählen Erweitern

2015.06.15 19:25:49 2: ZWDongle_0 transmit NO_ACK for 05
schon abgebrochen werden. Alles danach führt (bei mir) zum gleichen Ergebnis, da Aktor nicht antwortet bzw. ZW_SEND_DATA callback in Timeout läuft.

Kann auch gerne auf Gero warten, hatte verdrängt, dass er 2 Wochen weg ist .

[rudolfkoenig]

Hab dein Vorschlag eingebaut.

[krikan]

Danke für Deine Änderung.

Was mir noch aufgefallen ist: Die Abarbeitung der wakeup-Sendeliste mit foreach führt häufiger zum Abbruch eines Befehls nach den max. Sendeversuchen mit CAN seit den Änderungen in 00_ZWDongle. Derzeit verliere ich bei 10 Befehlen im Schnitt 2 wegen max. CAN. Bei den Tests zur Einführung der Behandlungsänderung der WAKE_UP Geräte hatte ich (damals) keine solchen Verluste und dort hatte ich bis zu 80 Befehle in einem Rutsch. Unterschied in der Testhardware: damals Philio PSM02 und heute PST02; also 400er bzw. 500er Chipsatz.

Das Problem habe ich interessanterweise nach dieser Ändernung nicht mehr. Ich bin jetzt bis auf 40 Befehle mit notify hochgegangen und habe keine Befehlsverluste wegen zu vieler CAN mehr. Das läuft nun sauber durch.

[gero]

Hallo,

ich bin wieder da. Allerdings türmt sich auf meinem Schreibtisch die Arbeit und daher ist die Zeit etwas knapp. Ich werde versuchen die letzten Post nöglichst bald in Ruhe durchzulesen und die Änderungen zu testen.

Gruß,
Gero

[krikan]

@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]

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]

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]

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]

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]

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

[krikan]

Und bei Problemen muesstest du ein resend sehen.

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

Code Auswählen Erweitern

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 Erweitern

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.

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]

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]

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]

Hast 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.

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

Zum Testen bin ich gerne bereit 

TRANSMIT_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

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]

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]

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.

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]

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 Erweitern


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]

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]

Beruhigt mich.

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.

[rudolfkoenig]

Habe callbackid fuer get aktiviert, und das resend vereinfacht: es gibt keine Ausnahmen mehr fuer ZW_SEND_DATA. Habs eine Weile bei mir getestet ohne Auffaelligkeiten.