Abarbeitung des WakeUp-Sendstacks wird in Einzelfällen unterbrochen

[rudolfkoenig]

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.

Ja, ja, aber!
FHEM darf nur eine Nachricht rausschicken, was nicht per ACK bestaetigt wurde.
Fuer unaufgeforderte Nachrichten vom Geraet kriegt FHEM auch kein ACK.
Falls ich was nicht kapiert habe, bitte geduldig mit mir sein

[krikan]

Fuer unaufgeforderte Nachrichten vom Geraet kriegt FHEM auch kein ACK.

Das ist mir klar, die habe ich nicht betrachtet.

Ja, ja, aber!
FHEM darf nur eine Nachricht rausschicken, was nicht per ACK bestaetigt wurde.
Falls ich was nicht kapiert habe, bitte geduldig mit mir sein

Also habe ich schlecht erklärt, denn das "aber" passt nicht, da mir das auch klar ist.
Voraussetzung: "viele" anstehende/verschickte Nachrichten von FHEM hintereinander an einen Node
Es ist in FHEM kein Bezug zwischen versandter Nachricht und dem 0013er-ACK gegeben, außer der Annahme, das ein 0013er-ACK immer zur letzten versandten Nachricht des Nodes gehört und 0013er-ACK für eine von FHEM per ZWDongle_Write versandte Nachricht nur genau einmal eintrifft.
Diese Annahme ist aber mMn falsch:

• Nachrichten werden automatisch vom Controller mehrfach (direkt, Route, Explorer Frames bis zu 7(?)x) verschickt ohne dass FHEM diesen mehrfachen Versand feststellen kann. Es gibt dann evtl. mehrfache 0013er-ACK für eine Nachricht, die FHEM fälschlich einer anderen nachfolgenden Nachricht an den Node zuordnet.
  
• Nachrichten können verschiedene Routen nehmen und also auch Telegrammlaufzeiten unterschiedlich sein.
  In Kombination führen die beiden obigen Punkte bei vielen Nachrichten an eine Node zu einem Zuordnungsproblem und -fehlern, gerade wenn auch noch NO_ACK oder andere Probleme auftreten.
  
  Danke auch für Deine Geduld  . Hoffe, dass ich keine Gedankenfehler habe, aber irgendwie bin ich mir relativ sicher oder habe mich verrannt....
  

[rudolfkoenig]

Ok, ich glaube ich habs inzwischen auch verstanden.

- um 11:32:04.062 wird "get versionClass SWITCH_BINARY" rausgeschickt

- es kommen 2(!) ACKs (00130400) rein, in einer Sekunde Abstand. Theorie: die ACK wird vom Zielgeraet auf unterschiedlichen Routes geschickt, und es kommen mehrere Telegramme an. Der Stick reicht alle weiter, und meint, Duplikatserkennung ist Aufgabe der hoeheren Schichten. Wir koennten die Callbackids fortlaufend nummerieren, um ACK-Duplikatserkennung zu machen, leider wuerde das in diesem Fall (get) nichts aendern, da das naechste Befehl sowieso erst nach einem "richtigen" Message bzw. seit gestern eins mit der gleichen Klasse weitergeht. Falls man eine Menge von sets hat, dann wuerde die fortlaufende Nummerierung verhindern, dass mehr als ein Befehl weitergeschickt wird. Das macht die Sache vermutlich etwas besser, allerdings sollte das Problem im ZWDongle-Stack abgefangen sein, insofern erwarte ich nach einem Umbau keine wesentliche Besserung. Wenn ich falsch liegen sollte, bitte mich aufklaeren.

- auf die um 11:32:05.226 verschickte Frage nach "get versionClass POWERLEVEL" gibt es innerhalb von 150ms 4 Antworten. Theorie: die Antwort wurde auf mindestens 4 Routes erfolgreich zugestellt. Leider reicht der Dongle die vorhandene Seriennummer nicht weiter, so dass FHEM diese Nachrichten nicht als Duplikat erkennen kann.

- ZWave_versionClassAllGet fuegt beim Empfang einer Anwort ein Class:Version Token zu vclasses, und generiert die naechste get Frage.
Das geht in diesem Fall fuerchterlich schief. EIch habe jetzt die Funktion umgebaut: es werden alle gets am Anfang schon ins Stack gepackt, und beim Empfang wird der passende Token erneuert. Nebeneffekte: vclasses ist alphabetisch sortiert, "get versionClass XX" erzeugt kein Reading mehr, sondern modifiziert vclasses.

- Was mich wundert: dieses Problem sollte mit der aktuellen ZWave_processSendStack Aenderung eher ent- als verschaerft worden sein.

- ich filtere jetzt MARK in ZWave_versionClassAllGet raus.

- die Meldung

"my" variable $msg masks earlier declaration in same scope at ./FHEM/10_ZWave.pm line 3579, <$fh> line 24.

habe ich entfernt.

[rudolfkoenig]

Entweder ist die Duplikatserkennung Aufgabe von FHEM (dann fehlt aber die Seriennummer aus dem Funktelegramm, Bug im ZWDongle-Protokoll), oder ist das die Aufgabe von ZWDongle, dann ist dein Dongle (oder viele?) fehlerhaft. Alternativ muss man dem Dongle sagen, dass er Duplikate filtert, oder die Seriennummer weitergibt, ich weiss aber nicht, wo man das aktiviert.

Btw. bisher filtern wir im ZWCUL auch keine Duplikate, aber wir koennten!

[krikan]

Der Stick reicht alle weiter, und meint, Duplikatserkennung ist Aufgabe der hoeheren Schichten.

Habe ich gerade im INS (Softwarearchitektur) auch so gefunden.

leider wuerde das in diesem Fall (get) nichts aendern, da das naechste Befehl sowieso erst nach einem "richtigen" Message bzw. seit gestern eins mit der gleichen Klasse weitergeht.

OK, habe also bei get übersehen, dass zusätzlich zu 0013er-ACK auch auf eine Antwort nichtr blockierend gewartet wird. Also bei get demnach unproblematisch. Korrekt?

- auf die um 11:32:05.226 verschickte Frage nach "get versionClass POWERLEVEL" gibt es innerhalb von 150ms 4 Antworten. Theorie: die Antwort wurde auf mindestens 4 Routes erfolgreich zugestellt. Leider reicht der Dongle die vorhandene Seriennummer nicht weiter, so dass FHEM diese Nachrichten nicht als Duplikat erkennen kann.

Das könnte man mit fortlaufender CallbackID verhindern, ist aber unnötig. (Ja ja, verabschiede mich langsam wieder von der fortlaufenden ID  )

dieses Problem sollte mit der aktuellen ZWave_processSendStack Aenderung eher ent- als verschaerft worden sein.

Eventuell wegen härterer Testbedingungen/-methoden  : Größeres Netz; kenne den Weg, welchen Aktor ich hier ausschalten muss, um künstlich Explorer Frames zu erzeugen.

Entweder ist die Duplikatserkennung Aufgabe von FHEM (dann fehlt aber die Seriennummer aus dem Funktelegramm, Bug im ZWDongle-Protokoll), oder ist das die Aufgabe von ZWDongle, dann ist dein Dongle (oder viele?) fehlerhaft. Alternativ muss man dem Dongle sagen, dass er Duplikate filtert, oder die Seriennummer weitergibt, ich weiss aber nicht, wo man das aktiviert.

Genau das hat mich erst auch stutzig gemacht und stolpern lassen.
Aber, INS scheint vorzuschreiben, dass FHEM es machen muss.
Nur warum gibt es dann die Seriennummer bei ZWCul....

[krikan]

Letzter Strohhalm  :

2(!) ACKs (00130400) rein, in einer Sekunde Abstand. Theorie: die ACK wird vom Zielgeraet auf unterschiedlichen Routes geschickt, und es kommen mehrere Telegramme an. Der Stick reicht alle weiter, und meint, Duplikatserkennung ist Aufgabe der hoeheren Schichten. Wir koennten die Callbackids fortlaufend nummerieren, um ACK-Duplikatserkennung zu machen, leider wuerde das in diesem Fall (get) nichts aendern, da das naechste Befehl sowieso erst nach einem "richtigen" Message bzw. seit gestern eins mit der gleichen Klasse weitergeht.

Geringfügig andere Telegrammlaufzeiten: Wenn das 1. ACK hereinkommt gefolgt als nächstes von einer "richtigen" Message, dann würde doch die nächste Nachricht des Nodes verschickt. Wenn nun erst das 2. ACK von der vorherigen Nachricht ankommt, dann gilt die Nachricht als ordnungsgemäß, obwohl vom falschen ACK bestätigt. Ob die  Nachricht ankommt ist dann vollkommen unbekannt. Also Abarbeitung durcheinander.  -> Verhinderung nur durch fortlaufende CallbackID
Die Prüfung auf richtige Klasse ist hier und in den anderen "xyzAll"-Fällen dann auch zu wenig und wir sind bei Andreas stärker Prüfung. Die würde aber komplexer.

[rudolfkoenig]

Nur warum gibt es dann die Seriennummer bei ZWCul....

Weil ZWCUL auf dem fortlaufenden Zahl im Telegramm (1-15, wir geben das als SN: aus in ZWCUL) zugreifen kann. Das Wird aber vom ZWDongle verschwiegen, und "unser" CallbackId kommt nur fuer die ACKs zurueck, aber nie fuer die Antworten auf die gets. Die kommen immer mit CB:0

Dein "letzter Strohhalm" ist zwar esoterisch aber richtig. Ich sehe schon, ich werde erst Ruhe kriegen, wenn ich den fortlaufenden CallbackId eingebaut hab

[A.Harrenberg]

Hi,

ich wollte nur mal sagen das ich nichts dazu sage ,-)

Ihr seid ja ganz schön fleissig. Ich werde diese Woche wohl eher nicht mehr zum Testen kommen, und danach bin ich dann wie gesagt so bis Anfang Mai weg.

Gruß,
Andreas

[krikan]

zwar esoterisch aber richtig. Ich sehe schon, ich werde erst Ruhe kriegen, wenn ich den fortlaufenden CallbackId eingebaut hab

Habe länger über esoterisch grübeln müssen  , aber da Andreas nichts sagt, muss ich wohl alleine weitermachen.

Warum dieser Thread entstand:
Ich wollte endlich den KEYFOB per SECURITY einbinden. Im Produktiv-Netz funktionieren der KEYFOB und der PST01 mit SECURITY aber nicht zufriedenstellend. KEYFOB wahrscheinlich wegen der Ortsveränderungen deutlich schlechter als PST01. Es kommt immer wieder zu Stockungen in der Abarbeitung, die ich auf irgendein Chaos beim Ablauf der Kommunikation zurückführe. Hinweise zu Problemen in der Ablaufsteuerung der Telegramme bei SECURITY gibt es ja bereits mehrere und die betroffenen Geräte waren jeweils WakeUp-Geräte. Also habe ich mir den WakeUp-Sendstack ohne SECURITY vorgenommen und die hier angesprochenen Merkwürdigkeiten festgestellt. Die eingecheckten Änderungen zum Wakeup können aber mMn das SECURITY-Problem nicht gelöst haben. Darum habe ich heute eine Ebene tiefer mit den netzbetriebenen Geräten getestet und befürchte aus den Beobachtungen Probleme im Ablauf, die normalerweise (ohne SECURITY) nicht so schlimm sind, bei SECURITY aber vermutlich zum Abbruch führen.

Vermute eben, dass die fehlende Duplikatserkennung und ggfs. falsche ACK-Zuordnung mit zu den SECURITY Problemen führen. Definitives Wissen ist nicht vorhanden. Ich weiß ja noch nicht einmal, ob die obige 1. 0013er-ACK nicht tatsächlich die 2. 0013er ACK für den vorherigen get-Befehl ist  ; vermute, es ist nicht so.

Rudi, wenn meine Gedankengänge tatsächlich daneben liegen, dann bitte Klartext. Und eigentlich gehe ich davon aus, dass Du sowieso nichts einbaust nur um Deine Ruhe zu kriegen.  "Nein" ist immer OK und Du hast Deine Ruhe.

Gruß, Christian

[A.Harrenberg]

Hi,

eine kleine Bemerkung doch noch von mir. Ich habe gerade mal meine ganzen Debug-Zeilen wieder rausgenommen und ein paar Mal gespielt, bisher ohne Probleme. Als ich das Senden nach APPLICATION_UPDATE wieder aktiviert habe konnte ich einmal einen Hänger provozieren, dabei ist mir aber eingefallen das ich noch mal das WNMI bei dem Multisensor prüfen wollte.

Und was soll ich sagen, wenn man nicht nach dem APPLICATION_UPDATE sendet sondern nur nach WU, dann funktioniert sogar ein 5 sekunden WNMI-delay! D.h. die "Besonderheit" des Sensors mit dem schnellen Einschlafen gilt nur wenn er gar nicht wirklich wach ist ,-)

Ich lasse das bei mir jetzt mal auf 2 sekunden stehen und schaue ob das auch über längere Zeit funktioniert.

Gruß,
Andreas.

P.S.: Danke Rudi!

[krikan]

- ZWave_versionClassAllGet fuegt beim Empfang einer Anwort ein Class:Version Token zu vclasses, und generiert die naechste get Frage.
Das geht in diesem Fall fuerchterlich schief. Ich habe jetzt die Funktion umgebaut: es werden alle gets am Anfang schon ins Stack gepackt, und beim Empfang wird der passende Token erneuert. Nebeneffekte: vclasses ist alphabetisch sortiert, "get versionClass XX" erzeugt kein Reading mehr, sondern modifiziert vclasses.

Hallo Rudi,
Die versionClassAll-Abfrage wird für Classes die im Attribut classes 2 (vor und hinter MARK) oder mehrmals (defekter NIF-> FGRM222) vorkommen, mehrfach ausgeführt. Bin mir nicht sicher, ob das so sein muss. Habe mal per copy und paste Deine Duplikatslöschung von ein paar Zeilen tiefer kopiert, damit jede Class nur 1x abgefragt wird. Meine Tests damit waren erfolgreich. Der Patch hängt an. Bitte kontrolliere den Patch, da ich nicht behaupten kann, alles zu durchblicken. Wollte aber auch mal direkt Code liefern. 
Gruß, Christian

[rudolfkoenig]

Dein Patch ist einwandfrei, habs eingecheckt.

[krikan]

habs eingecheckt.

Danke, Rudi.

da das naechste Befehl sowieso erst nach einem "richtigen" Message bzw. seit gestern eins mit der gleichen Klasse weitergeht. Falls man eine Menge von sets hat, dann wuerde die fortlaufende Nummerierung verhindern, dass mehr als ein Befehl weitergeschickt wird. Das macht die Sache vermutlich etwas besser, allerdings sollte das Problem im ZWDongle-Stack abgefangen sein, insofern erwarte ich nach einem Umbau keine wesentliche Besserung. Wenn ich falsch liegen sollte, bitte mich aufklaeren.

Weg von CallbackId: Wenn ich Deine zitierte Aussage korrekt verstanden habe, dann dürften doch die Abläufe in nachfolgenden Logs nicht auftreten!? Es wird jeweils eine neue Nachricht per ZWDongle_Write/SW verschickt, obwohl überhaupt noch keine "richtige" Message als Antwort auf letzte ZWDongle_Write/SW eingetroffen ist. Denn 0013er-ACK ist doch keine "richtige" Nachricht.

Code Auswählen Erweitern

2016.03.08 12:31:27.085 5: ZWDongle_Write 001304038613702504 (e345c452)
2016.03.08 12:31:27.089 5: SW: 010a00130403861370250425
2016.03.08 12:31:27.115 5: ACK received, WaitForAck=>2 for 010a00130403861370250425
2016.03.08 12:31:27.118 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.08 12:31:27.120 5: SW: 06
2016.03.08 12:31:27.135 5: ZWDongle_0 dispatch 011301
2016.03.08 12:31:27.157 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130400
2016.03.08 12:31:27.159 5: SW: 06
2016.03.08 12:31:27.174 5: device ack reveived, removing 010a00130403861370250425 from dongle sendstack
2016.03.08 12:31:27.177 5: ZWDongle_0 dispatch 00130400
2016.03.08 12:31:27.180 4: CMD:ZW_SEND_DATA ID:00 ARG: CB:04
2016.03.08 12:31:27.183 4: ZWDongle_0 transmit OK for 04
2016.03.08 12:31:29.457 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00130400
2016.03.08 12:31:29.459 5: SW: 06
2016.03.08 12:31:29.465 5: ZWDongle_0 dispatch 00130400
2016.03.08 12:31:29.469 4: CMD:ZW_SEND_DATA ID:00 ARG: CB:04
2016.03.08 12:31:29.471 4: ZWDongle_0 transmit OK for 04
2016.03.08 12:31:29.489 5: ZWDongle_Write 0013040386137a2504 (e345c452)
2016.03.08 12:31:29.503 5: SW: 010a0013040386137a25042f

Code Auswählen Erweitern

2016.03.08 13:01:23.807 5: SW: 010a00131a03861391251ac4
2016.03.08 13:01:23.819 5: ACK received, WaitForAck=>2 for 010a00131a03861391251ac4
2016.03.08 13:01:23.822 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.08 13:01:23.824 5: SW: 06
2016.03.08 13:01:23.829 5: ZWDongle_0 dispatch 011301
2016.03.08 13:01:23.917 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 00131a00
2016.03.08 13:01:23.919 5: SW: 06
2016.03.08 13:01:23.923 5: device ack reveived, removing 010a00131a03861391251ac4 from dongle sendstack
2016.03.08 13:01:23.926 5: ZWDongle_0 dispatch 00131a00
2016.03.08 13:01:23.929 4: CMD:ZW_SEND_DATA ID:00 ARG: CB:1a
2016.03.08 13:01:23.931 4: ZWDongle_0 transmit OK for 1a
2016.03.08 13:01:23.940 5: ZWDongle_Write 00131a03861372251a (e345c452)
2016.03.08 13:01:23.944 5: SW: 010a00131a03861372251a27

Das sind jeweils Auszüge aus "versionClassAll"-Abfragen. Habe die im normalen Betrieb abgesetzt.

Beim 1. Log gibt es Wiederholungen bei 0013-ACK. Vorher sieht das Log sauber aus.
Beim 2. Log war vorher ZW_SEND_DATA mit "transmit queue overflow" (ZWDongle_0 dispatch 011300) gescheitert und ab da ist es mMn durcheinander.

Rest der Logs kann ich bei Bedarf auch liefern, mir geht es aber erst einmal nur darum, ob ich Deine Aussage richtig verstanden habe. Oder gibt es bei versionClassAll eine Sonderbehandlung, die ich nicht erkenne?

[rudolfkoenig]

Beim 1. Log gibt es Wiederholungen bei 0013-ACK. Vorher sieht das Log sauber aus.

Stimmt, duerfte nicht passieren. Die Nachrichten werden bei mir mit < 10ms weitergeschickt, ich frage mich, wie du die 2.5 Sekunden hingekriegt hast. Jaja, ich stll schon noch auf fortlaufende IDs um, bei so einem Chaos ist das sicher angebracht Kannst du bitte vorne in ZWave_processSendStack ein

Code Auswählen Erweitern

Log 4, "processSendStack ".$ss->[0];
einfuegen, und es nochmal probieren?

Beim 2. Log war vorher ZW_SEND_DATA mit "transmit queue overflow" (ZWDongle_0 dispatch 011300) gescheitert und ab da ist es mMn durcheinander.

Huch: woher weisst du das mit "transmit queue overflow" ?

[krikan]

woher weisst du das mit "transmit queue overflow" ?

INS/OZW

Code Auswählen Erweitern

01 13 00/01
Bei einem Response (01), auch bei ZW_SEND_DATA (13), ist der Rückgabewert von 01 der "Gut"-Fall und 00 der "Schlecht"-Fall (s. auch 00_ZWDongle.pm). Dokumentiert ist für ZW_SEND_DATA nur der Schlechtfall 00 mit "if transmit queue overflow".
Bei einem Request (00) ist das Schema bspw. "00 13 xx 00/01" der Rückgabewerte für Gut/Schlecht bzw. Wahr/Falsch genau umgedreht. Warum auch immer.

Die Nachrichten werden bei mir mit < 10ms weitergeschickt, ich frage mich, wie du die 2.5 Sekunden hingekriegt hast.

Das ist sicherlich der Normalfall mit wenigen Routern und Geräten an festen Positionen. Der Node vom 1. Log ist aber nur über min. 2 Router-Zwischenstationen erreichbar, schließe ich aus örtlicher Lage und den Ergebnissen von ZW_AreNodesNeighbours. Wenn dann noch mehrfache Sendeversuche und Explorer Frames dazukommen, sind 2.5 Sekunden zumindest laut ozw-Mailing List nicht ungewöhnlich. Habe es schon 3 oder 4x so durch Zwischen-Router stromlos machen hinbekommen und probiere es mit Deiner Log-Ergänzung auch noch mal. Habe auch schon probiert mit ZWCul mitzuloggen, um meine Theorie bestätigen zu können. Gelingt mir aber nicht sauber.