Abarbeitung des WakeUp-Sendstacks wird in Einzelfällen unterbrochen

[krikan]

Da ich heute nicht mehr so viel Zeit habe werde ich mich wahrscheinlich frühestens morgen mal melden. Da wäre ich bei Bedarf dann auch ohne Dein Angebot auf Dich

Ok, also einfach melden. Hinweis: Morgen bin ich nur stark eingeschränkt erreichbar.

[9zehn75]

Bin ein wenig vorsichtig, das hier festgestellte Problem auf alle Problemfälle zu übertragen und damit zu generalisieren. Man müsste sich die Logs von Deinem Problem genau anschauen. Die Unterbrechnung der Abarbeitung des Sendstacks tritt nicht immer auf. Bei mir ist der weitaus häufigere Fall eine korrekte und komplette Abarbeitung des Sendstacks. Das Problem tritt im Wesentlichen auch nur bei sehr vollem Sendstack oder Störungen durch andere Geräte auf. Insbesondere wenn Du noch die Repeater einsetzt oder das Netz nach einer Entfernung nicht komplett neu aufgebaut wurde, zweifele ich sehr stark an einer Parallele.
Behaupte: Nein

Das Netz mit meinen Repeatern gibt es nicht mehr. Ich habe alle Geräte entfernt, FHEM gelöscht, neu installiert, alle Geräte neu inkludiert (ohne Repeater) und alles neu eingerichtet. Seitdem habe ich nur noch die o.g. Probleme. Die auch nicht immer. Besonders voller Sendstack könnte passen. Habe aber im Moment keine Zeit, dem intensiver nachzugehen.

[rudolfkoenig]

Diese Geschichte ist auf meinem Stack irgendwie nach unten gerutscht. Ihr seid ja ganz fleissig gewesen, ich habe aber trotzdem den Eindruck, dass es noch nicht erledigt ist.

Zum Log aus Beitrag #1:
- der Dongle meint, die gleiche Antwort auf "get version XX" oefters presentieren zu muessen. Ich vermute, dass der PST02 den Ack der Dongle nicht gehoert hat, und deswegen die Nachricht wiederholt hat.
- Theorie: da der Dongle gerade was empfaengt, will nichts zum Schicken entgegennehmen, deswegen ein CAN.
- Mit der wiederholten Nachricht kommt erstens der Sendstack aus dem Tritt, weil FHEM glaubt eine Antwort auf die naechste Frage (der wg. CAN abgeblockt wurde) bekommen zu haben. Deswegen wurden einige "get version" Anfragen nicht verschickt.
- warum Befehle auf dem Stack bleiben, kann ich nicht wirklich erklaeren, evtl. schlaeft der PST02 wg. dem CAN-Resend-Timout selbst ein.
- Um das Problem zu fixen muesste ich:
  1. DeviceUnabhaengige CallbackIds einfuehren (ich hoer schon das "endlich" ), und die Antwort mit dem Letzten vergleichen zu koennen.
  2. Falls ein CAN von einer Nachricht gefolgt wird, dann Senden sofort wiederholen / nicht warten.

Zum Log aus Beitrag #5:
- hier ist alles perfekt bis zur vorletzten Zeile.
- danach haette eine Antwort auf "get basicStatus" eintreffen muessen, da es nicht eintraf, ist die Verarbeitung stehengeblieben.
- bei nicht batteriebetriebenen Geraeten gibts nach 5 Sek. en NO_ACK, und es geht weiter. Da das default WNMI 2 Sekunden ist, wird dieser Mechanismus bei Batteriebetriebenen nicht aktiviert.
- ich wuesste nicht, wie/was ich hier fixen soll.

@Andreas / Beitrag #6:
- Christian hat "get associationAll" ausgeloest. Der packt ein "get associationGroups" auf dem stack, und setzt den Hook. Wenn eine Antwort kommt, dann wird ein "get association 1" auf dem Stack gelegt, usw.

@Andreas / Beitrag #7:
- Keyfob sendet in der Tat ein Application-Update, wenn man alle 4 Knoepfe und dann #2 drueckt. Das verwende ich zum Simulieren eines Batteriebetriebenen Geraetes. Ich weiss nicht, wieso das hier stoeren sollte, und wage zu wetten, dass bei Christian nichts aendern wird.

@Christian / Beitrag #8:

Laut Sendstack habe ich die 2x abgerufen. Ob dadurch Probleme mit dem Hook entstehen, kann ich nicht nachvollziehen.

Habs geschaut, ich behaupte das sollte kein Problem sein.

Log aus Beitrag #10:
Hier sind viele (11) CANs, ist also eine verschaerfte Variante des ersten Logs: dein PST02 hoert schlecht

Wenn ich nichts von euch hoere, dann versuche ich morgen meinen Vorschlag umzusetzen. Ist leider nicht ganz trivial.

[krikan]

Zum Log aus Beitrag #1:
- warum Befehle auf dem Stack bleiben, kann ich nicht wirklich erklaeren, evtl. schlaeft der PST02 wg. dem CAN-Resend-Timout selbst ein.

Glaube ich nicht, laut Specs schläft der erst 10 Sekunden nach der letzten Nachricht ein, wenn kein WNMI geschickt wird. Nach meiner Erinnerung habe ich das damals bei den SECURITY-Tests für Andreas auch mal so praktisch festgestellt.

Log aus Beitrag #10:
Hier sind viele (11) CANs, ist also eine verschaerfte Variante des ersten Logs: dein PST02 hoert schlecht

Zweifel  . Vielleicht löst sich das nach Deinen Änderungen von alleine, ansonsten habe ich noch eine Idee, die auch Problem aus #5 lösen könnte. Jedoch den Komplexitätsgrad enorm steigert. Stichwort: Telegrammlaufzeitverhersage -> habe ich mir bei ozw und zway wie im anderen Thread angekündigt mal angesehen.

Wenn ich nichts von euch hoere, dann versuche ich morgen meinen Vorschlag umzusetzen. Ist leider nicht ganz trivial.

Ich bin jetzt ruhig. 

[A.Harrenberg]

Hi Rudi,

Callbacks wären schön...

@Andreas / Beitrag #7:
- Keyfob sendet in der Tat ein Application-Update, wenn man alle 4 Knoepfe und dann #2 drueckt. Das verwende ich zum Simulieren eines Batteriebetriebenen Geraetes. Ich weiss nicht, wieso das hier stoeren sollte, und wage zu wetten, dass bei Christian nichts aendern wird.

Was hier bei meinem Multisensor "stört" ist die Tatsache das FHEM schon bei dem APPLICATION_UPDATE anfängt zu senden, der Sensor aber erst mal seine Meldungen loswerden will und DANACH dann die WUN schickt. Durch das gleichzeitige Senden kommt es zu CAN Msg. Irgendwann bleibt dann der SendStack hängen, das ist aber ein anderes Problem, das ja anscheinend auch ohne CAN Msg ausgelöst werden kann.

Wenn jetzt Wunschkonzert wäre würde ich mir wünschen das standardmäßig der WU-Stack NICHT bei APPLIKATION_UPDATE geöffnet wird, sondern wirklich erst mit der WUN und das bei besonderen Geräte das für APPLIKATION_UPDATE per Attribut freigeschaltet werden kann falls nötig. Aber das ist hier eher untergeordnet. Das Grundproblem das der Stack hängenbleibt müssen wir erst noch richtig verstehen...

Ich bin mir nicht ganz sicher, ich hatte damals nur ganz kurz mit den Callback-IDs gespielt aber irgendwie abgespeichert das die eben NICHT immer (oder gar nicht?) zurückgesendet wurden. Bevor Du hier viel Aufwand in einen Umbau steckst sollte erst mal klar sein das die Antworten von den Nodes auch wirklich die übergebene Callback-ID nutzen.

Ein anderer Ansatzpunkt wäre aus meiner Sicht für jeden Befehl eine etwas spezifischere Regexp für die Antwort zu definieren. Momentan wird ja alles was von der Node kommt als Antwort auf das get akzeptiert/interpretiert. Eigentlich weiß man man bei jedem Befehl ja welche CC und welchen Report-Code man als Antwort erwartet. Damit könnte man besser entscheiden ob das die erwartete Antwort oder eine "unsolicited" Msg ist.

Ich bin mir bei einigen von den CAN Msg auch nicht sicher auf was die sich eigentlich beziehen und ob dann die richtige Nachricht erneut verschickt wird. Im Log von Christian war so ein Fall bei dem ich eigentlich davon ausgegangen wäre das die Nachricht schon vom Stack verschwunden sein sollte...

Ich hab' mein Log noch nicht bis zu der interessanten Stelle durchgeschaut, ich mach' morgen früh damit weiter und melde mich sobald ich da was neue rausgefunden habe.

Und wie immer bist Du deutlich schneller als wir ,-)

Gruß,
Andreas.

[krikan]

Ich bin mir nicht ganz sicher, ich hatte damals nur ganz kurz mit den Callback-IDs gespielt aber irgendwie abgespeichert das die eben NICHT immer (oder gar nicht?) zurückgesendet wurden. Bevor Du hier viel Aufwand in einen Umbau steckst sollte erst mal klar sein das die Antworten von den Nodes auch wirklich die übergebene Callback-ID nutzen.

Wollte ja ruhig sein, aber: jetzt rede ihm die CallbackIds bloß nicht wieder aus   
Zur Sache:
Mir ist unbekannt, dass die CalbackIDs bei ZW_SEND_DATA nicht immer kommen. Die CallbackIDs sind doch laut zwapi Pflicht und in allen Beschreibungen und selbst in Musterabläufen enthalten. Bei ozw und z-way Logs ist mir letzte Woche dazu auch nichts untergekommen, worüber ich gestolpert bin. Es wird in den Logs alles über die CallbackIDs verfolgt. Eigentlich bin ich mir relativ sicher, dass wir auf CallbakIDs setzen können. Hast Du denn noch Anhaltspunkte, wo das Problem damals lag?

[A.Harrenberg]

Hi,

ich will das Rudi ja nicht ausreden...

Ich wollte nur sagen das man da erst mal die IDs einfügt und schaut ob die zurückkommen bevor man den ganzen Ablauf damit steuert und die dann doch nicht bei jedem Gerät oder Befehl kommen...

Ich kann wirklich nicht mehr sagen was ich das damals alles so mit den IDs gemacht habe. Kann auch gut sein das ich das ich das jetzt aus dem Gedächtnis mit irgendeinem anderen Problem vermische. Ich bin nämlich auch ziemlich sicher das OZW beim Ablauf die Callbackids verwendet und diese "exepected answer" Meldungen damit erzeugt.

Spannend wird dann wieder die Frage wieweit sich das ganze dann mit SECURITY verträgt...

Wobei CRC16 Nachrichten oder Multi-CMD Nachrichten könnten auch noch interessant werden, da hier eine Kapselung stattfindet bzw. mehrere Befehle zusammengefasst werden. Wobei ich bei Multi-Cmd aber der Meinung bin das die nicht als Antwort auf ein Get kommen, sondern nur als "unsolicited" Statusmeldung.

Gruß,
Andreas.

[A.Harrenberg]

Hi,

hier jetzt wie angedroht meine Analyse... WIe immer recht länglich ,-)

Ich bin mir jetzt nicht mehr ganz so sicher ob das Problem von Christian (ohne die CAN) und das was ich hier bei mir vorfinde letztendlich das gleiche Grundproblem hat.
Aber ich bin mir jetzt ziemlich sicher das Senden nach APPLICATION_UPDATE eine schlechte Idee ist...

Testbedingungen: AEOTEC Multisensor, Batteriebetrieb -> WakeUpModus, "get configAll" im WU-Stack, dann manuell auf den "Knopf" gedrückt

- >  APPLICATION_UPDATE wird gesendet, später wird aber auch eine WUN gesendet, die dann das ganze "Chaos" auslöst, da beim Empfang der WUN der SendStack erneut im Modus "next" geöffnet wird und eine neue Nachricht freigeben wird, obwohl ja bereits eine Kommunikation läuft.

Code Auswählen Erweitern


        2016.03.05 09:11:02.202 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 004984ab120421015e86725985737184803031707aef5a
        2016.03.05 09:11:02.203 5: SW: 06
        2016.03.05 09:11:02.204 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:02.204 5: ZWDongle_0 dispatch 004984ab120421015e86725985737184803031707aef5a
        2016.03.05 09:11:02.204 4: CMD:ZW_APPLICATION_UPDATE ID:ab ARG:120421015e86725985737184803031707aef5a
# Application_Update received       
       
        2016.03.05 09:11:02.204 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <next> from ZWave_Parse (WU / APPLICATION_UPDATE)
  # Trigger by Application Update

ZWave_processSendStack wird also über APPLICATION_UPDATE getriggert, danach werden etliche GET-Befehle aus der configAll Anfrage sauber abgearbeitet.

In dem Logabschnitt unten kann man dann sehen das mitten in die Kommunikation die WUN kommt und den ZWave_processSendStack mit "next" startet. Zu dem Zeitpunkt ist die Antwort auf ein "get 70052a" noch offen und es wird ein "get 700527" zusätzlich abgesetzt.
Ab da ist der Ablauf "asynchron" und es kommt zu den CAN Messages:

In Kurzform:
get 70052a
WUN
get 700527 released and send
70062a received
70052e released
CAN
1s timeout
700527 resend
70052e send
700627 received
CAN
1s timeout
70052e resend
7005cb released and send
70062e received
CAN
1s timeout
7005cb resend
7006cb received

Stack arbeitet danach nicht weiter da anscheinend $hash->{wakeupAlive} nicht mehr gesetzt ist. Hier ist dann die nächste Auffälligkeit, ich habe noch weitere Logs gemacht in denen ich den Status abgefragt habe, und der ist bereits nach dem ersten CAN nicht mehr aktiv! Nach meinem Verständnis müsste dann doch eigentlich der WU-Stack wieder aktiv werden, oder?

Bei den beiden anderen CAN waren zu dem Zeitpunkt zwei Nachrichten offen, sodass hier die Abfrage auf das wakeupAlive nicht greift...

WNMI ist auf 0.3 sekunden gesetzt...

Eine weitere Auffälligkeit ist das der Sensor auch nach dem Timout von 1 sekunde weiter antwortet und NICHT eingeschlafen ist. Das ist ja gerade die Besonderheit von dem Ding das da sonst nach weniger als 0.3 sekunden schon ein NO_ACK kommt.

Das werde ich mir noch mal genauer anschauen, ich denke das ich da damals einen voreiligen Schluss gezogen habe und das der Sensor nach dem Applikation_UPDATE bereits so schnell einschläft, nach der WUN aber dann doch vielleicht länger wach bleibt. Zumindest würde das so einiges erklären...

Code Auswählen Erweitern


        2016.03.05 09:11:03.041 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <msg> from ZWave_Parse (no WU)
  # ZW
        2016.03.05 09:11:03.042 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called with ackType: msg
        2016.03.05 09:11:03.042 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
        2016.03.05 09:11:03.042 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
        2016.03.05 09:11:03.042 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack going to remove Timer
        2016.03.05 09:11:03.042 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack Timer removed
        2016.03.05 09:11:03.042 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack type: get msg: 13ab0370052a25ab
        2016.03.05 09:11:03.042 5: ZWDongle_Write 0013ab0370052a25ab (e015dfed)
        2016.03.05 09:11:03.042 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Write
    # ZWD
        2016.03.05 09:11:03.042 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.042 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.042 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:03.042 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:03.042 1: ZWDongle_0: Dongle_processSendStack, send msg 010a0013ab0370052a25ab9f
        2016.03.05 09:11:03.042 5: SW: 010a0013ab0370052a25ab9f
# get 70052a
        2016.03.05 09:11:03.043 1: ZWDongle_0: Dongle_processSendStack, start timer for ZWDongle_ProcessSendStack +1s
    # exit ZWD
        2016.03.05 09:11:03.043 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack marking as sent in sendstack
        2016.03.05 09:11:03.043 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack leaving processSendStack
  #exit ZW
        2016.03.05 09:11:03.044 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:03.044 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.044 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.044 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:03.044 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:03.044 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:03.047 1: ZWDongle_0: ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:03.047 5: ACK received, WaitForAck=>2 for 010a0013ab0370052a25ab9f
        2016.03.05 09:11:03.047 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:03.047 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.047 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.047 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:03.047 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:03.047 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:03.065 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
        2016.03.05 09:11:03.065 5: SW: 06
        2016.03.05 09:11:03.066 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:03.066 5: ZWDongle_0 dispatch 011301
        2016.03.05 09:11:03.066 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:03.066 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.066 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.066 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:03.066 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:03.067 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:03.107 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab028407
# WUN
        2016.03.05 09:11:03.107 5: SW: 06
        2016.03.05 09:11:03.108 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:03.108 5: ZWDongle_0 dispatch 000400ab028407
        2016.03.05 09:11:03.108 4: CMD:APPLICATION_COMMAND_HANDLER ID:ab ARG:028407
       
        2016.03.05 09:11:03.108 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <next> from ZWave_Parse (WU)
# start of ZW due to WUN -> new command to be released!
        2016.03.05 09:11:03.108 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called with ackType: next
        2016.03.05 09:11:03.108 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
        2016.03.05 09:11:03.108 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
        2016.03.05 09:11:03.108 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack going to remove Timer
        2016.03.05 09:11:03.108 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack Timer removed
        2016.03.05 09:11:03.108 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack type: get msg: 13ab0370052725ab
        2016.03.05 09:11:03.109 5: ZWDongle_Write 0013ab0370052725ab (e015dfed)
        2016.03.05 09:11:03.109 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Write
    # ZWD
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
# not typicall -> waitForAck is typically not set at this stage for a new command but it is still set from the ongoing communication
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:03.109 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack marking as sent in sendstack
# marking WHICH command as sent?
        2016.03.05 09:11:03.109 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack leaving processSendStack
  # exit ZW
        2016.03.05 09:11:03.109 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:03.109 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:03.135 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0013ab000008
        2016.03.05 09:11:03.135 5: SW: 06
        2016.03.05 09:11:03.136 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:03.136 5: device ack reveived, removing 010a0013ab0370052a25ab9f from dongle sendstack
        2016.03.05 09:11:03.136 5: ZWDongle_0 dispatch 0013ab000008
        2016.03.05 09:11:03.136 4: CMD:ZW_SEND_DATA ID:00 ARG:0008
        2016.03.05 09:11:03.136 4: ZWDongle_0 transmit OK for ab
        2016.03.05 09:11:03.136 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <ack> from ZWave_Parse
  # ZW
        2016.03.05 09:11:03.136 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called with ackType: ack
        2016.03.05 09:11:03.136 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
        2016.03.05 09:11:03.136 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
        2016.03.05 09:11:03.136 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack get / ack detected, set sentackget, leaving processSendStack
  # exit ZW
        2016.03.05 09:11:03.136 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:03.136 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.136 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.136 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:03.136 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:03.136 1: ZWDongle_0: Dongle_processSendStack, send msg 010a0013ab0370052725ab92
        2016.03.05 09:11:03.136 5: SW: 010a0013ab0370052725ab92
# get 700527 -> two commands are "open"
        2016.03.05 09:11:03.138 1: ZWDongle_0: Dongle_processSendStack, start timer for ZWDongle_ProcessSendStack +1s
    # exit ZWD
        2016.03.05 09:11:03.161 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab0570062a010a
        2016.03.05 09:11:03.161 5: SW: 06
        2016.03.05 09:11:03.162 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:03.162 5: ZWDongle_0 dispatch 000400ab0570062a010a
        2016.03.05 09:11:03.162 4: CMD:APPLICATION_COMMAND_HANDLER ID:ab ARG:0570062a010a
#answer 70062a -> answer for first command received w/o CAN, only this command is open now...
        2016.03.05 09:11:03.162 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <msg> from ZWave_Parse (no WU)
  # ZW
        2016.03.05 09:11:03.162 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called with ackType: msg
        2016.03.05 09:11:03.162 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
        2016.03.05 09:11:03.162 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
        2016.03.05 09:11:03.162 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack going to remove Timer
        2016.03.05 09:11:03.162 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack Timer removed
        2016.03.05 09:11:03.162 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack type: get msg: 13ab0370052e25ab
        2016.03.05 09:11:03.162 5: ZWDongle_Write 0013ab0370052e25ab (e015dfed)
        2016.03.05 09:11:03.163 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Write
    # ZWD
        2016.03.05 09:11:03.163 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.163 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.163 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:03.163 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:03.163 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:03.163 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack marking as sent in sendstack
        2016.03.05 09:11:03.163 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack leaving processSendStack
  # exit ZW
        2016.03.05 09:11:03.164 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:03.164 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.164 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.164 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:03.164 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:03.164 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:03.165 4: ZWDongle_Read ZWDongle_0: CAN received
# CAN received -> 70062a??
        2016.03.05 09:11:03.165 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:03.166 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:03.166 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:03.166 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:03.166 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:03.166 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
   
    # no communication "open" as CAN was received, no resend so far...
    # ZWD called by timer!
        2016.03.05 09:11:04.167 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:04.167 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:04.167 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:04.167 1: ZWDongle_0: Dongle_processSendStack, WaitForAck==1 and dt > 1 sec.
        2016.03.05 09:11:04.167 2: ZWDongle_ProcessSendStack: no ACK, resending message 010a0013ab0370052725ab92
        2016.03.05 09:11:04.167 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:04.167 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:04.167 1: ZWDongle_0: Dongle_processSendStack, send msg 010a0013ab0370052725ab92
        2016.03.05 09:11:04.167 5: SW: 010a0013ab0370052725ab92
# resend 700527 -> answer was already received -> 70052a should have been sent instead...
        2016.03.05 09:11:04.168 1: ZWDongle_0: Dongle_processSendStack, start timer for ZWDongle_ProcessSendStack +1s
    # exit ZWD
        2016.03.05 09:11:04.169 1: ZWDongle_0: ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:04.169 5: ACK received, WaitForAck=>2 for 010a0013ab0370052725ab92
        2016.03.05 09:11:04.169 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:04.169 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:04.169 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:04.169 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:04.169 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:04.169 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:04.183 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
        2016.03.05 09:11:04.183 5: SW: 06
        2016.03.05 09:11:04.184 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:04.184 5: ZWDongle_0 dispatch 011301
        2016.03.05 09:11:04.184 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:04.184 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:04.184 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:04.184 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:04.184 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:04.184 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:04.211 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0013ab000002
        2016.03.05 09:11:04.211 5: SW: 06
        2016.03.05 09:11:04.212 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:04.212 5: device ack reveived, removing 010a0013ab0370052725ab92 from dongle sendstack
        2016.03.05 09:11:04.212 5: ZWDongle_0 dispatch 0013ab000002
        2016.03.05 09:11:04.212 4: CMD:ZW_SEND_DATA ID:00 ARG:0002
        2016.03.05 09:11:04.212 4: ZWDongle_0 transmit OK for ab
        2016.03.05 09:11:04.212 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <ack> from ZWave_Parse
  # ZW
        2016.03.05 09:11:04.212 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called with ackType: ack
        2016.03.05 09:11:04.212 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
        2016.03.05 09:11:04.212 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
        2016.03.05 09:11:04.212 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack get / ack detected, set sentackget, leaving processSendStack
  # exit ZW
        2016.03.05 09:11:04.212 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:04.212 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:04.212 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:04.212 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:04.212 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:04.212 1: ZWDongle_0: Dongle_processSendStack, send msg 010a0013ab0370052e25ab9b
        2016.03.05 09:11:04.212 5: SW: 010a0013ab0370052e25ab9b
# get 70052e -> two commands open, answer for resend of 700527 is still open (has just arrived...)
        2016.03.05 09:11:04.213 1: ZWDongle_0: Dongle_processSendStack, start timer for ZWDongle_ProcessSendStack +1s
    # eixt ZWD
        2016.03.05 09:11:04.245 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab057006270114
        2016.03.05 09:11:04.245 5: SW: 06
        2016.03.05 09:11:04.246 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:04.246 5: ZWDongle_0 dispatch 000400ab057006270114
        2016.03.05 09:11:04.247 4: CMD:APPLICATION_COMMAND_HANDLER ID:ab ARG:057006270114
# answer 700627 (from resend)

        2016.03.05 09:11:04.247 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <msg> from ZWave_Parse (no WU)
  # ZW
        2016.03.05 09:11:04.248 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:04.248 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:04.248 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:04.248 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:04.248 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:04.248 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:04.250 4: ZWDongle_Read ZWDongle_0: CAN received
# CAN received 70052e??
        2016.03.05 09:11:04.250 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:04.250 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:04.250 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:04.250 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:04.250 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:04.250 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
   
        2016.03.05 09:11:05.250 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
    # ZWD called by timer!
        2016.03.05 09:11:05.250 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:05.250 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:05.250 1: ZWDongle_0: Dongle_processSendStack, WaitForAck==1 and dt > 1 sec.
        2016.03.05 09:11:05.250 2: ZWDongle_ProcessSendStack: no ACK, resending message 010a0013ab0370052e25ab9b
        2016.03.05 09:11:05.250 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:05.250 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:05.250 1: ZWDongle_0: Dongle_processSendStack, send msg 010a0013ab0370052e25ab9b
        2016.03.05 09:11:05.250 5: SW: 010a0013ab0370052e25ab9b
# get 70052e (resend)
        2016.03.05 09:11:05.251 1: ZWDongle_0: Dongle_processSendStack, start timer for ZWDongle_ProcessSendStack +1s
    # exit ZWD
        2016.03.05 09:11:05.251 1: ZWDongle_0: ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:05.251 5: ACK received, WaitForAck=>2 for 010a0013ab0370052e25ab9b
        2016.03.05 09:11:05.252 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:05.252 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:05.252 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:05.252 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:05.252 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:05.252 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:05.266 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
        2016.03.05 09:11:05.267 5: SW: 06
        2016.03.05 09:11:05.268 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:05.268 5: ZWDongle_0 dispatch 011301
        2016.03.05 09:11:05.268 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:05.268 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:05.268 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:05.268 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:05.268 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:05.268 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:05.285 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0013ab000002
        2016.03.05 09:11:05.285 5: SW: 06
        2016.03.05 09:11:05.286 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:05.286 5: device ack reveived, removing 010a0013ab0370052e25ab9b from dongle sendstack
        2016.03.05 09:11:05.286 5: ZWDongle_0 dispatch 0013ab000002
        2016.03.05 09:11:05.286 4: CMD:ZW_SEND_DATA ID:00 ARG:0002
        2016.03.05 09:11:05.286 4: ZWDongle_0 transmit OK for ab
        2016.03.05 09:11:05.286 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <ack> from ZWave_Parse
  # ZW
        2016.03.05 09:11:05.286 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called with ackType: ack
        2016.03.05 09:11:05.286 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
        2016.03.05 09:11:05.287 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
        2016.03.05 09:11:05.287 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack going to remove Timer
        2016.03.05 09:11:05.287 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack Timer removed
        2016.03.05 09:11:05.287 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack type: get msg: 13ab037005cb25ab
        2016.03.05 09:11:05.287 5: ZWDongle_Write 0013ab037005cb25ab (e015dfed)
        2016.03.05 09:11:05.287 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Write
    # ZWD
        2016.03.05 09:11:05.287 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:05.287 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:05.287 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:05.287 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:05.287 1: ZWDongle_0: Dongle_processSendStack, send msg 010a0013ab037005cb25ab7e
        2016.03.05 09:11:05.287 5: SW: 010a0013ab037005cb25ab7e
# get 7005cb
        2016.03.05 09:11:05.288 1: ZWDongle_0: Dongle_processSendStack, start timer for ZWDongle_ProcessSendStack +1s
    # exit ZWD
        2016.03.05 09:11:05.288 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack marking as sent in sendstack
        2016.03.05 09:11:05.288 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack leaving processSendStack
  # exit ZW
        2016.03.05 09:11:05.288 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:05.288 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:05.288 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:05.288 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:05.288 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:05.288 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:05.323 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab0570062e0100
        2016.03.05 09:11:05.323 5: SW: 06
        2016.03.05 09:11:05.324 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:05.324 5: ZWDongle_0 dispatch 000400ab0570062e0100
        2016.03.05 09:11:05.324 4: CMD:APPLICATION_COMMAND_HANDLER ID:ab ARG:0570062e0100
# answer 70062e (from resend)

        2016.03.05 09:11:05.325 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <msg> from ZWave_Parse (no WU)
  # ZW
        2016.03.05 09:11:05.326 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:05.326 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:05.326 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:05.326 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:05.326 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:05.326 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:05.335 4: ZWDongle_Read ZWDongle_0: CAN received
# CAN
        2016.03.05 09:11:05.335 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:05.335 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:05.335 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:05.335 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:05.335 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:05.335 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:06.335 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
    # ZWD called by timer!   
        2016.03.05 09:11:06.335 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:06.335 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:06.335 1: ZWDongle_0: Dongle_processSendStack, WaitForAck==1 and dt > 1 sec.
        2016.03.05 09:11:06.335 2: ZWDongle_ProcessSendStack: no ACK, resending message 010a0013ab037005cb25ab7e
        2016.03.05 09:11:06.335 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:06.335 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:06.335 1: ZWDongle_0: Dongle_processSendStack, send msg 010a0013ab037005cb25ab7e
        2016.03.05 09:11:06.335 5: SW: 010a0013ab037005cb25ab7e
# get 7005cb (resend)
        2016.03.05 09:11:06.337 1: ZWDongle_0: Dongle_processSendStack, start timer for ZWDongle_ProcessSendStack +1s
    # exit ZWD
        2016.03.05 09:11:06.338 1: ZWDongle_0: ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:06.338 5: ACK received, WaitForAck=>2 for 010a0013ab037005cb25ab7e
        2016.03.05 09:11:06.338 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:06.338 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:06.338 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:06.338 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:06.338 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:06.338 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:06.351 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
        2016.03.05 09:11:06.351 5: SW: 06
        2016.03.05 09:11:06.352 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:06.352 5: ZWDongle_0 dispatch 011301
        2016.03.05 09:11:06.352 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:06.352 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:06.352 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:06.352 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist gesetzt
        2016.03.05 09:11:06.352 1: ZWDongle_0: Dongle_processSendStack, no_resend and no no_response, going to start timer
        2016.03.05 09:11:06.352 1: ZWDongle_0: Dongle_processSendStack, timer started +1s
    # exit ZWD
        2016.03.05 09:11:06.386 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0013ab000002
        2016.03.05 09:11:06.386 5: SW: 06
        2016.03.05 09:11:06.388 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:06.388 5: device ack reveived, removing 010a0013ab037005cb25ab7e from dongle sendstack
        2016.03.05 09:11:06.388 5: ZWDongle_0 dispatch 0013ab000002
        2016.03.05 09:11:06.388 4: CMD:ZW_SEND_DATA ID:00 ARG:0002
        2016.03.05 09:11:06.388 4: ZWDongle_0 transmit OK for ab
        2016.03.05 09:11:06.388 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <ack> from ZWave_Parse
  # ZW
        2016.03.05 09:11:06.388 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called with ackType: ack
        2016.03.05 09:11:06.388 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
        2016.03.05 09:11:06.388 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
        2016.03.05 09:11:06.388 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack get / ack detected, set sentackget, leaving processSendStack
  # exit ZW
        2016.03.05 09:11:06.388 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
    # ZWD
        2016.03.05 09:11:06.388 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:06.388 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:06.388 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:06.388 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:06.388 1: ZWDongle_0: Dongle_processSendStack, <return>
    # exit ZWD   
        2016.03.05 09:11:06.429 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab067006cb020000
        2016.03.05 09:11:06.429 5: SW: 06
        2016.03.05 09:11:06.430 1: ZWDongle_0: device ACK received, calling ZWDongle_shiftSendStack
        2016.03.05 09:11:06.430 5: ZWDongle_0 dispatch 000400ab067006cb020000
        2016.03.05 09:11:06.430 4: CMD:APPLICATION_COMMAND_HANDLER ID:ab ARG:067006cb020000
# answer 7006cb (from resend)
        2016.03.05 09:11:06.431 1: ZWave_SENSOR_MULTILEVEL_171: calling ZWave_processSendStack with <msg> from ZWave_Parse (no WU)
  # ZW
  # ???
  # ZWave_processSendStack($hash, "msg")       if(!ZWave_isWakeUp($hash) || $hash->{wakeupAlive});
  # -> wakeupAlive no longer active?
        2016.03.05 09:11:06.431 1: ZWDongle_0: calling ZWDongle_ProcessSendStack from ZWDongle_Read
        2016.03.05 09:11:06.431 1: ZWDongle_0: Dongle_processSendStack called, going to remove timer
        2016.03.05 09:11:06.431 1: ZWDongle_0: Dongle_processSendStack timer removed
        2016.03.05 09:11:06.431 1: ZWDongle_0: Dongle_processSendStack, WaitForAck ist nicht gesetzt
        2016.03.05 09:11:06.431 1: ZWDongle_0: Dongle_processSendStack, check for <return>
        2016.03.05 09:11:06.431 1: ZWDongle_0: Dongle_processSendStack, <return>



Ich sehe für dieses Problem (ich zweifle mittlerweile das Christians Problem die gleiche Ursache hat...) folgende Ansatzpunkte:

a.) Senden nach APPLICATION_UPDATE nicht standardmäßig, sondern nur für besondere Geräte (z.B . die KFOBs)
b.) Falls doch nach APPLICATION_UPDATE gesendet wird, Abfrage bei Eintreffen der WUN um "doppeltes" Öffnen des SendStacks zu verhindern

Mich macht in dem Log aber stutzig das da noch etliche Befehle hin-und-her gehen, obwohl doch wakeupAlive gar nicht mehr gesetzt ist...
Außerdem wird gar kein WUNMI abgesetzt...

Gruß,
Andreas.

[rudolfkoenig]

- der KFOB sendet direct nach Application-Update eine WN, ich habe den wake-up code beim Application-Update auskommentiert. Kann man zum kuenstlichen Erzeugen der CAN Probleme aktivieren.
- ein globales/fortlaufendes callbackId kommt doch nicht (ich hoere gerade: buuuuh). Der Dongle sendet nur fuer den 0013-er ACK diese ID zurueck, und da ich nicht vorhabe, an einem Geraet mehr als eine Nachricht ohne 0013-er Ack zu senden, ist die bisher verwendete NodeId als callbackId genausogut.
- bei allen Nachrichten, die direkt vom Geraet kommen, ist callbackId 0, und auch nach Durchsicht der uebrigen Bits bekomme ich nichts vom Dongle, was mir beim Identifizieren einer Wiederholung helfen koennte: Der Code im ZWave_processSendStack bleibt erstmal gleich.
Im Log / CMD: Zeile wird ab sofort callbackId mit CB: ausgegeben, vielleicht entdeckt ihr was anderes.
- Ab sofort sendet FHEM Befehle erneut an den Dongle, wenn der Dongle eine "richtige" Nachricht (kein Ack) meldet. Das behebt hoffentlich das Unterbrechen der Abarbeitung.

[A.Harrenberg]

Hi Rudi,

- der KFOB sendet direct nach Application-Update eine WN, ich habe den wake-up code beim Application-Update auskommentiert. Kann man zum kuenstlichen Erzeugen der CAN Probleme aktivieren.

Ok, das hilft schon mal. Aus irgendeinem Grund habt Ihr beide aber darauf bestanden das so zu lassen weil es für irgendeinen Sonderfall benötigt wurde... Ich krieg' das aber aus dem Gedächtnis nicht mehr hin. Na ja, wenn es wirklich so war wird es ja jetzt auffallen.

- ein globales/fortlaufendes callbackId kommt doch nicht (ich hoere gerade: buuuuh). Der Dongle sendet nur fuer den 0013-er ACK diese ID zurueck, und da ich nicht vorhabe, an einem Geraet mehr als eine Nachricht ohne 0013-er Ack zu senden, ist die bisher verwendete NodeId als callbackId genausogut.

War mir doch so als ob das damals bei mir auch nicht das gewünschte Ergebnis gezeigt hat. Schade, wäre (relativ) einfach zu nutzen gewesen...
Und "buuuh" kriegst Du von mir dafür nicht, habe das ja befürchtet.

- bei allen Nachrichten, die direkt vom Geraet kommen, ist callbackId 0, und auch nach Durchsicht der uebrigen Bits bekomme ich nichts vom Dongle, was mir beim Identifizieren einer Wiederholung helfen koennte: Der Code im ZWave_processSendStack bleibt erstmal gleich.
Im Log / CMD: Zeile wird ab sofort callbackId mit CB: ausgegeben, vielleicht entdeckt ihr was anderes.

Bei der Lektüre der Application Guideline bekomme ich auch den Eindruck das die Callback-IDs für allem für die Dongle-, bzw. Node-interne Programmierung gedacht sind und nicht für die globale Kommunikation da sind.
Ich werde das mit CB: mal beobachten, denke aber nicht das dabei was neues rauskommt.

Was ist denn mit meinem Ansatz die Regexp für get spezifischer zu generieren? Würde bedeuten das man beim Senden schon z.B. mit ":" angehängt die Regexp mitgibt die auf die erwartete Antwort passt. Damit müsste es möglich sein unsolicited Nachrichten von den erwarteten Antworten unterscheiden zu können.

- Ab sofort sendet FHEM Befehle erneut an den Dongle, wenn der Dongle eine "richtige" Nachricht (kein Ack) meldet. Das behebt hoffentlich das Unterbrechen der Abarbeitung.

Hmm, hier bin ich nicht sicher ob das für alle Möglichkeiten, wann eine Nachricht eintreffen kann, die richtige Lösung ist... Das kann ich mir in meinem kleinen Kopf nicht alles vorstellen...
Müsste nicht eigentlich verhindert werden das "unsolicited Messages" den (ZWave|ZWDongle)_(p|P)rocessSendStack aufrufen? Die CAN-Nachricht die bei so einem Fall auftreten kann lässt sich ja nicht vermeiden und wird ja vom SendStack auch problemlos verkraftet.

Gruß,
Andreas.

[rudolfkoenig]

Was ist denn mit meinem Ansatz die Regexp für get spezifischer zu generieren?

Ich habe eine einfache Variante davon eingebaut: bei einem get wird die Klasse der gesendeten Anfrage mit der Klasse der empfangenen Nachricht verglichen. Das hilft leider nicht beim Fehler waehrend "get configAll". Ein genaueres Regexp ist mAn nur sehr aufwendig zu erstellen.

[A.Harrenberg]

Hi Rudi,

Ich habe eine einfache Variante davon eingebaut: bei einem get wird die Klasse der gesendeten Anfrage mit der Klasse der empfangenen Nachricht verglichen. Das hilft leider nicht beim Fehler waehrend "get configAll". Ein genaueres Regexp ist mAn nur sehr aufwendig zu erstellen.

werde ich mir im Laufe der Woche mal ansehen.

Ob genauere Regexp wirklich so aufwändig sind glaube ich erst mal nicht ,-)
Ich könnte mir vorstellen das man einfach an alle GET-Befehle per Trennzeichen (":") die Regexp mit zum Senden übergibt. Der SendStack müsste das dann für das eigentlich Senden abschneiden und für den Aufruf der ReadAnswerFn wieder abfragen.
Aber während eines configAll wird wohl kaum eine unsolicited Nachricht mit der config-classe kommen. Die werden mMn nicht unsolicited versendet, von daher müsste das auch so ausreichen.

Gruß,
Andreas.

[krikan]

.
- ein globales/fortlaufendes callbackId kommt doch nicht (ich hoere gerade: buuuuh). Der Dongle sendet nur fuer den 0013-er ACK diese ID zurueck, und da ich nicht vorhabe, an einem Geraet mehr als eine Nachricht ohne 0013-er Ack zu senden, ist die bisher verwendete NodeId als callbackId genausogut.

Habe die geänderten Module zuerst einmal mit einem netzbetriebenen Gerät getestet.

Dazu habe ich den Befehl "get <device> versionClassAll" abgesetzt. Nach meinem Verständnis wird hier im unten gezeigten Logausschnitt nach einer Nachricht ohne 0013-er Ack eine neue Nachricht verschickt. Das komplette Log habe ich angehängt, da der ganze Ablauf mMn wichtig ist. Der Ärger geht schon spätestens bei 2x 0013-er ACK um 11:32:04.175 los. Dort scheint es eine automatisches Resend durch den Controller gegeben zu haben. Wegen fehlender fortlaufender Callback-ID  kann ich aber nicht definitiv feststellen, was vom Gerät mehrfach empfangen, d.h. welche genaue Nachricht mit 0013er-ACK bestätigt wurde. AUswertung von versionClass 73 wird bspw. 4x empfangen.

Eventuell habe ich einen Verständnisproblem, aber bevor ich das am WakeUp-Geräten probiere, wäre es schön, wenn ihr mal einen Blick darauf werfen würdet und mich belehrt. Danke, Christian

Code Auswählen Erweitern

2016.03.07 11:32:08.540 2: ZWave get ZWave_SWITCH_MULTILEVEL_4 versionClass METER
2016.03.07 11:32:08.544 5: ZWDongle_Write 001304038613322504 (e345c452)
2016.03.07 11:32:08.547 5: SW: 010a00130403861332250467
2016.03.07 11:32:08.557 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400040486147301
2016.03.07 11:32:08.558 5: SW: 06
2016.03.07 11:32:08.563 5: ZWDongle_0 dispatch 000400040486147301
2016.03.07 11:32:08.566 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:0486147301 CB:00
2016.03.07 11:32:08.586 2: ZWave get ZWave_SWITCH_MULTILEVEL_4 versionClass SENSOR_MULTILEVEL
2016.03.07 11:32:08.590 5: ZWDongle_Write 001304038613312504 (e345c452)
2016.03.07 11:32:08.593 2: ZWDongle_ProcessSendStack: no ACK, resending message 010a00130403861332250467
2016.03.07 11:32:08.595 5: SW: 010a00130403861332250467
2016.03.07 11:32:08.604 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400040486147301
2016.03.07 11:32:08.606 5: SW: 06
2016.03.07 11:32:08.611 5: ZWDongle_0 dispatch 000400040486147301
2016.03.07 11:32:08.614 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:0486147301 CB:00

[krikan]

Das list zum obigen Log. Das Attribut vclasses zeigt die Merkwürdigkeit im Sendeverlauf mMn:

Code Auswählen Erweitern

Internals:
   CHANGED
   DEF        e345c452 4
   IODev      ZWDongle_0
   LASTInputDev ZWDongle_0
   MSGCNT     5
   NAME       ZWave_SWITCH_MULTILEVEL_4
   NR         240
   STATE      Blind 0 Slat 0
   TYPE       ZWave
   ZWDongle_0_MSGCNT 5
   ZWDongle_0_RAWMSG 0004000406310504220000
   ZWDongle_0_TIME 2016-03-07 12:52:02
   homeId     e345c452
   isWakeUp
   lastMsgSent 1457347101.15657
   nodeIdHex  04
   Readings:
     2016-03-06 20:26:04   SEND_DATA       failed:00
     2016-01-03 20:49:48   UNPARSED        MANUFACTURER_SPECIFIC 0a7205010e000800020000
     2016-02-10 19:12:33   assocGroup_1    Max 16 Nodes
     2016-02-10 19:12:22   assocGroup_2    Max 16 Nodes
     2016-02-10 19:12:28   assocGroup_3    Max 1 Nodes ZWDongle_0
     2016-02-10 19:12:27   assocGroups     3
     2016-03-06 21:47:37   configEnergyReports 10
     2016-03-06 21:47:37   configForcedRollerShutterCalibration Default
     2016-03-06 21:47:37   configInRollerBlindModeOrVenetianBlind17 10
     2016-03-06 21:47:37   configInVenetianBlindModeTheParameter12 150
     2016-03-06 21:47:43   configManagingLamellasInResponseTo35 SetLamellasToTheirExtreme1
     2016-03-06 21:47:43   configMotorOperationDetection 10
     2016-03-06 21:47:43   configMotorOperationTime 240
     2016-03-06 21:47:46   configPeriodicPowerOrEnergyReports 3600
     2016-03-06 21:47:46   configPowerReports 10
     2016-03-06 21:47:52   configReportsType BlindPositionReportsSentToThe1
     2016-03-06 21:47:52   configResponseToFloodingAlarm NoReaction
     2016-03-06 21:47:52   configResponseToGeneralAlarm CloseBlind
     2016-03-06 21:47:52   configResponseToSmokeCOOrCO2Alarm NoReaction
     2016-03-06 21:47:52   configResponseToTemperatureAlarm OpenBlind
     2016-03-06 21:47:53   configRollerShutterOperatingModes VenetianBlindModeWithPositioning
     2016-03-06 21:47:53   configScenesAssociationsActivation AssociationsActivation
     2016-03-06 21:47:53   configSelfMeasurement SelfMeasurementInactive
     2016-03-06 21:47:53   configSetLamellasBackToPrevious13 LamellasReturnToPreviouslySet1
     2016-03-06 21:47:54   configSwitchType MomentarySwitches
     2016-03-07 12:51:03   energy           0.1 kWh
     2016-03-07 11:38:21   meterSupported   type: energy scales: 0:kWh, 2:W resetable: yes
     2016-02-18 09:04:41   model           FIBARO System FGRM222 Roller Shutter Controller 2
     2016-02-18 09:04:41   modelConfig     fibaro/fgrm222.xml
     2016-02-18 09:04:41   modelId         010f-0301-1001
     2016-02-28 12:30:30   neighborList    ZWave_SWITCH_BINARY_6 ZWave_SENSOR_BINARY_18 ZWave_SWITCH_MULTILEVEL_26 ZWave_SWITCH_MULTILEVEL_27 ZWave_GARAGE_DOOR_31 ZWave_SENSOR_MULTILEVEL_43 ZWave_WALL_CONTROLLER_44
     2016-02-28 18:52:20   position        Blind 0 Slat 0
     2016-03-07 12:52:02   power           0.0 W
     2016-03-06 21:56:09   reportedState   off
     2016-03-07 11:32:12   state           TRANSMIT_NO_ACK
     2016-03-07 11:38:21   transmit        OK
     2016-02-18 19:04:22   version         Lib 3 Prot 3.52 App 22.22
     2015-12-23 19:56:12   versionClass_47 00
     2015-12-23 19:59:52   versionClass_70 01
     2016-02-07 10:53:01   versionClass_85 02
Attributes:
   IODev      ZWDongle_0
   classes    MANUFACTURER_SPECIFIC VERSION CONFIGURATION ASSOCIATION SWITCH_BINARY POWERLEVEL METER SENSOR_MULTILEVEL FIRMWARE_UPDATE_MD SWITCH_BINARY MANUFACTURER_PROPRIETARY PROTECTION MARK METER SENSOR_MULTILEVEL MANUFACTURER_PROPRIETARY SCENE_ACTIVATION SWITCH_MULTILEVEL SWITCH_BINARY
   event-on-change-reading .*
   room       ZWave
   stateFormat position
   vclasses   MANUFACTURER_SPECIFIC:1 VERSION:1 CONFIGURATION:1 ASSOCIATION:2 SWITCH_BINARY:1 POWERLEVEL:1 POWERLEVEL:1 POWERLEVEL:1 POWERLEVEL:1 SWITCH_BINARY:1 MANUFACTURER_PROPRIETARY:1 PROTECTION:2


[krikan]

Habe jetzt noch ein wenig mit netzbetriebenen Geräten experimentiert und ZWave-Infos gelesen. Ich komme zu folgenden theoretischen Überlegungen:

Werden viele Nachrichten für einen Node abgesetzt, dann kann es aufgrund von "Netzstörungen" mMn nicht sichergestellt werden, dass 0013er-ACK ohne fortlaufende CallbackID zur korrekten Verarbeitung des Stacks führen.

Es ist mMn derzeit bei NodeID=CallbackID nicht sicher feststellbar, ob eine eintreffende 0013er-ACK zur letzten verschickten oder einer vorherigen Nachricht des Nodes gehört. Die Telegrammlaufzeiten sind unterschiedlich, so dass ACK zeitversetzt eintreffen können und es gibt auch automatiche Wiederholungen durch den Controller, die FHEM nicht mitbekommt. Mir ist nicht bekannt, dass der Controller bei erfolgreichen Wiederholungen automatische Filterung vornimmt.

Ordnet man ein 0013er-ACK immer der letzten Nachricht zu, dann werden evtl. Nachrichten als ordnungsgemäß verschickt deklariert, die nie beim Node angekommen sind (könnte auf obiges Log für "get versionClass Meter zutreffen). Das 0013er-ACK könnte nämlich für einen vorherigen Befehl durch Wiederhoungsversuche oder unterschiedliche Telegrammlaufzeiten sein. Diese Verluste sind -vermutlich auch gerade bei SECURITY- unschön.

Der andere Fall sind mehrfach eintreffenden Antwort-Nachrichten auf einen Befehl an eine Node. Wenn man über die eindeutige CallbackID feststellen könnte, wie oft ein Befehl beim Node eingetroffen ist, könnte man die herausfiltern. Momentan halte ich das aber für unnötig.

Hoffe meine Gedankengänge sind nachvollziehbar. Gegenargumente sind willkommen, aber momentan ist das für mich die plausibelste Begründung für meine Beobachtungen.

Gruß, Christian

PS: Der Aktor im letzten Log reagiert auf die versionClass MARK - Abfrage nie; ist bei allen meinen FGRM-222 so.