Abarbeitung des WakeUp-Sendstacks wird in Einzelfällen unterbrochen

9zehn75 · 03 März 2016, 21:36:28

Kann eine Ausprägung dieses Problems sein, dass der Sendstack mehrere Aufwach-Vorgänge benötigt bis er abgearbeitet ist? So ist es bei mir - bisher dachte ich, dass muss so sein, weil die WakeUp-Geräte einfach nicht lange genug wach bleiben.

A.Harrenberg · 03 März 2016, 21:42:31

Hi,

hier mal ein erster "Befund":

Der "normaler" Ablauf ist so wie im ersten Block (bis zur Leerzeile) beim Versenden von 70052a, der Befehl wird aus dem SendStack versendet, und als "sent" markiert. Sobald das ACK da ist wird es als "sentAckGet" markiert. Nach dem Eintreffen der Anwort wird der Eintrag und der Timer entfernt.

Dann wird 700527 gesendet, aber dabei kommt bei mir die WakeUp-Notification "dazwischen" und der Sendstack macht anscheinend weiter als wäre das die Antwort auf das abgeschickte GET, (was es natürlich nicht ist). Dann wird im Sendstack der nächste GET 70052e freigegeben, ist aber noch nicht vom Dongle verschickt., dann kommt die CAN-Msg vom Dongle und die 700527 wird noch mal versendet, obwohl die nach meinem Verständnis zu dem Zeitpunkt bereits aus dem Stack entfernt sein sollte.

Ich werde mir dann als nächsten den Stack mal etwas genauer ansehen um festzustellen ob der "070527" wirklich schon aus dem Stack raus war oder doch noch oben drauf lag...

Mann kann auf jeden Fall schon mal erkennen das eine "unsolicited" Msg in einer solchen Abfragefolge das System irgendwie aus dem Tritt und zum Stolpern bringt. Ist auf jeden Fall ein interessantes Problem

Code Auswählen

2016.03.03 21:03:10.719 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack type: get msg: 13ab0370052a25ab
2016.03.03 21:03:10.720 5: ZWDongle_Write 0013ab0370052a25ab (e015dfed)
2016.03.03 21:03:10.720 5: SW: 010a0013ab0370052a25ab9f
2016.03.03 21:03:10.721 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack marking as sent in sendstack
2016.03.03 21:03:10.721 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack leaving processSendStack
2016.03.03 21:03:10.723 5: ACK received, WaitForAck=>2 for 010a0013ab0370052a25ab9f
2016.03.03 21:03:10.738 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 21:03:10.738 5: SW: 06
2016.03.03 21:03:10.740 5: ZWDongle_0 dispatch 011301
2016.03.03 21:03:10.774 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0013ab000002
2016.03.03 21:03:10.775 5: SW: 06
2016.03.03 21:03:10.776 5: device ack reveived, removing 010a0013ab0370052a25ab9f from dongle sendstack
2016.03.03 21:03:10.776 5: ZWDongle_0 dispatch 0013ab000002
2016.03.03 21:03:10.776 4: CMD:ZW_SEND_DATA ID:00 ARG:0002
2016.03.03 21:03:10.776 4: ZWDongle_0 transmit OK for ab
2016.03.03 21:03:10.776 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called
2016.03.03 21:03:10.776 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
2016.03.03 21:03:10.776 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
2016.03.03 21:03:10.776 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack get / ack detected, set sentackget, leaving processSendStack
2016.03.03 21:03:10.808 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab0570062a010a
2016.03.03 21:03:10.808 5: SW: 06
2016.03.03 21:03:10.809 5: ZWDongle_0 dispatch 000400ab0570062a010a
2016.03.03 21:03:10.809 4: CMD:APPLICATION_COMMAND_HANDLER ID:ab ARG:0570062a010a
2016.03.03 21:03:10.809 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called
2016.03.03 21:03:10.809 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
2016.03.03 21:03:10.809 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
2016.03.03 21:03:10.809 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack going to remove Timer
2016.03.03 21:03:10.809 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack Timer removed

2016.03.03 21:03:10.809 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack type: get msg: 13ab0370052725ab
2016.03.03 21:03:10.809 5: ZWDongle_Write 0013ab0370052725ab (e015dfed)
2016.03.03 21:03:10.809 5: SW: 010a0013ab0370052725ab92
2016.03.03 21:03:10.810 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack marking as sent in sendstack
2016.03.03 21:03:10.810 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack leaving processSendStack
2016.03.03 21:03:10.834 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab028407
2016.03.03 21:03:10.834 5: SW: 06
2016.03.03 21:03:10.836 5: ZWDongle_0 dispatch 000400ab028407
2016.03.03 21:03:10.836 4: CMD:APPLICATION_COMMAND_HANDLER ID:ab ARG:028407
2016.03.03 21:03:10.836 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called
2016.03.03 21:03:10.836 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
2016.03.03 21:03:10.836 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
2016.03.03 21:03:10.836 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack going to remove Timer
2016.03.03 21:03:10.836 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack Timer removed

2016.03.03 21:03:10.836 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack type: get msg: 13ab0370052e25ab
2016.03.03 21:03:10.836 5: ZWDongle_Write 0013ab0370052e25ab (e015dfed)
2016.03.03 21:03:10.836 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack marking as sent in sendstack
2016.03.03 21:03:10.836 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack leaving processSendStack

2016.03.03 21:03:10.838 4: ZWDongle_Read ZWDongle_0: CAN received
2016.03.03 21:03:11.839 2: ZWDongle_ProcessSendStack: no ACK, resending message 010a0013ab0370052725ab92
2016.03.03 21:03:11.839 5: SW: 010a0013ab0370052725ab92
2016.03.03 21:03:11.842 5: ACK received, WaitForAck=>2 for 010a0013ab0370052725ab92
2016.03.03 21:03:11.855 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 21:03:11.855 5: SW: 06
2016.03.03 21:03:11.856 5: ZWDongle_0 dispatch 011301
2016.03.03 21:03:11.879 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0013ab000002
2016.03.03 21:03:11.879 5: SW: 06
2016.03.03 21:03:11.880 5: device ack reveived, removing 010a0013ab0370052725ab92 from dongle sendstack
2016.03.03 21:03:11.880 5: ZWDongle_0 dispatch 0013ab000002
2016.03.03 21:03:11.880 4: CMD:ZW_SEND_DATA ID:00 ARG:0002
2016.03.03 21:03:11.880 4: ZWDongle_0 transmit OK for ab

2016.03.03 21:03:11.880 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called
2016.03.03 21:03:11.880 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
2016.03.03 21:03:11.880 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
2016.03.03 21:03:11.880 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack get / ack detected, set sentackget, leaving processSendStack
2016.03.03 21:03:11.880 5: SW: 010a0013ab0370052e25ab9b
2016.03.03 21:03:11.911 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab057006270114
2016.03.03 21:03:11.911 5: SW: 06

Das Log geht dann noch zwei mal mit CAN-Msg so weiter und dann bleibt das auch stehen:

Code Auswählen

2016.03.03 21:03:13.967 2: ZWDongle_ProcessSendStack: no ACK, resending message 010a0013ab037005cb25ab7e
2016.03.03 21:03:13.967 5: SW: 010a0013ab037005cb25ab7e
2016.03.03 21:03:13.971 5: ACK received, WaitForAck=>2 for 010a0013ab037005cb25ab7e
2016.03.03 21:03:13.988 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 21:03:13.988 5: SW: 06
2016.03.03 21:03:13.989 5: ZWDongle_0 dispatch 011301
2016.03.03 21:03:14.006 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0013ab000002
2016.03.03 21:03:14.006 5: SW: 06
2016.03.03 21:03:14.007 5: device ack reveived, removing 010a0013ab037005cb25ab7e from dongle sendstack
2016.03.03 21:03:14.007 5: ZWDongle_0 dispatch 0013ab000002
2016.03.03 21:03:14.007 4: CMD:ZW_SEND_DATA ID:00 ARG:0002
2016.03.03 21:03:14.007 4: ZWDongle_0 transmit OK for ab
2016.03.03 21:03:14.007 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack called
2016.03.03 21:03:14.007 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack sendstack not empty
2016.03.03 21:03:14.007 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack entry sent
2016.03.03 21:03:14.007 1: ZWave_SENSOR_MULTILEVEL_171: processSendStack get / ack detected, set sentackget, leaving processSendStack
2016.03.03 21:03:14.027 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400ab067006cb020000
2016.03.03 21:03:14.027 5: SW: 06
2016.03.03 21:03:14.028 5: ZWDongle_0 dispatch 000400ab067006cb020000
2016.03.03 21:03:14.028 4: CMD:APPLICATION_COMMAND_HANDLER ID:ab ARG:067006cb020000

Gruß,
Andreas.

A.Harrenberg · 03 März 2016, 21:52:36

Hi,

Zitat von: 9zehn75 am 03 März 2016, 21:36:28
Kann eine Ausprägung dieses Problems sein, dass der Sendstack mehrere Aufwach-Vorgänge benötigt bis er abgearbeitet ist? So ist es bei mir - bisher dachte ich, dass muss so sein, weil die WakeUp-Geräte einfach nicht lange genug wach bleiben.

das ist definitiv richtig beobachtet. Wenn der "hängenbleibt" liegen noch die restlichen Befehle auf dem Stack. Beim nächsten WakeUp macht er irgendwie weiter. Wie FHEM dabei mit dem eigentlich bereits versendeten Befehl (ohne Antwort) oben auf dem Stack umgeht habe ich mir noch nicht angeschaut.

Normalerweise arbeiten die WakeUp-Geräte den SendStack komplett ab bevor FHEM sie dann wieder schlafen schickt.

Die Theorie ist: Gerät wacht auf und schickt eine WakeUp-Notification zum Dongle. Der schaut nach ob Befehle für das Geräte vorhanden sind, wenn ja werden die alle verschickt. Wenn dann keine Befehle mehr da sind, oder es gar keine gebeben hat, dann schickt das Dongle eine WNMI-Nachricht (WakeUp No More Information) welche dem Gerät sagt das es wieder schlafen gehen kann/soll. Die Geräte sollen laut Spezifikation auch ohne diese Nachricht nach einer bestimmten Zeit wieder einschlafen um Batterie zu sparen, dummerweise gibt es keine festgelegte Zeit, und das macht dann anscheinend jeder wie er will.

Hierbei ist der AEOTEC MultiSensor anscheinend von Narkolepsie befallen, der schläft ultraschnell (~0.2 sek) wieder ein, während andere Geräte da in der Größenordnung von 2 Sekunden oder noch mehr liegen.

Gruß,
Andreas.

A.Harrenberg · 03 März 2016, 22:11:29

Hi Christian,

Zitat von: krikan am 03 März 2016, 20:31:45
Log hängt an.

auch in Deinem Log finden sich SEHR merkwürdige Sachen:

Code Auswählen

2016.03.03 20:03:43.180 5: ZWDongle_Write 0013040370050d2504 (c16c11c4)
2016.03.03 20:03:43.180 5: SW: 010a0013040370050d2504b8
2016.03.03 20:03:43.186 5: ACK received, WaitForAck=>2 for 010a0013040370050d2504b8
2016.03.03 20:03:43.286 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:43.287 5: SW: 06
2016.03.03 20:03:43.289 5: ZWDongle_0 dispatch 011301

2016.03.03 20:03:43.296 2: ZWave get ZWave_SENSOR_NOTIFICATION_4 zwavePlusInfo 
2016.03.03 20:03:43.297 4: ZWDongle_ReadAnswer arg:zwavePlusInfo regexp:^00040004..5e

2016.03.03 20:03:43.300 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 001304000003
2016.03.03 20:03:43.300 5: SW: 06
2016.03.03 20:03:43.302 5: device ack reveived, removing 010a0013040370050d2504b8 from dongle sendstack
2016.03.03 20:03:43.303 5: ZWDongle_0 dispatch 001304000003
2016.03.03 20:03:43.303 4: CMD:ZW_SEND_DATA ID:00 ARG:0003
2016.03.03 20:03:43.303 4: ZWDongle_0 transmit OK for 04
2016.03.03 20:03:43.304 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400040570060d010c
2016.03.03 20:03:43.304 5: SW: 06
2016.03.03 20:03:43.306 5: ZWDongle_0 dispatch 000400040570060d010c
2016.03.03 20:03:43.306 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:0570060d010c

Hier gibt es mitten in der Ausführung der ganzen config Befehle eine zwavePlusInfo Abfrage, die sogar eine ReadAnswerFn aufruft, allerdings erkenne ich nicht wo/wann die überhaupt abgesetzt wird...

Code Auswählen


2016.03.03 20:03:43.307 5: ZWDongle_Write 001304037005142504 (c16c11c4)
2016.03.03 20:03:43.307 5: SW: 010a001304037005142504a1
2016.03.03 20:03:43.313 5: ACK received, WaitForAck=>2 for 010a001304037005142504a1
2016.03.03 20:03:46.315 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:46.315 5: SW: 06
2016.03.03 20:03:46.317 5: ZWDongle_0 dispatch 011301
2016.03.03 20:03:46.317 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:46.317 5: SW: 06
2016.03.03 20:03:46.319 5: ZWDongle_0 dispatch 011301
2016.03.03 20:03:46.319 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:46.319 5: SW: 06
2016.03.03 20:03:46.321 5: ZWDongle_0 dispatch 011301
2016.03.03 20:03:46.321 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:46.321 5: SW: 06
2016.03.03 20:03:46.323 5: ZWDongle_0 dispatch 011301
2016.03.03 20:03:46.323 4: no response from device, removing 010a001304037005142504a1 from dongle sendstack
2016.03.03 20:03:46.324 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 001304000002
2016.03.03 20:03:46.324 5: SW: 06
2016.03.03 20:03:46.327 5: ZWDongle_0 dispatch 001304000002
2016.03.03 20:03:46.327 4: CMD:ZW_SEND_DATA ID:00 ARG:0002
2016.03.03 20:03:46.327 4: ZWDongle_0 transmit OK for 04
2016.03.03 20:03:46.328 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 0004000405700614011e
2016.03.03 20:03:46.328 5: SW: 06
2016.03.03 20:03:46.330 5: ZWDongle_0 dispatch 0004000405700614011e
2016.03.03 20:03:46.330 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:05700614011e

Hier geht es dann "richtig" durcheinander...
auf das SW: gibt es haufenweise ACK, dennoch kommt dann ein "no response from device, removing...." (Der Befehl dazu war ein 700514)
Danach kommt dann das ACK von der Node und auch dann "oh Wunder" kommt die Antwort auf die 700514 -> 700614

Das gleich wiederholt sich dann mit einer 700502 und der Antwort 700602

Code Auswählen

2016.03.03 20:03:46.331 5: ZWDongle_Write 001304037005022504 (c16c11c4)
2016.03.03 20:03:46.331 5: SW: 010a001304037005022504b7
2016.03.03 20:03:46.336 5: ACK received, WaitForAck=>2 for 010a001304037005022504b7
2016.03.03 20:03:49.338 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:49.338 5: SW: 06
2016.03.03 20:03:49.339 5: ZWDongle_0 dispatch 011301
2016.03.03 20:03:49.340 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:49.340 5: SW: 06
2016.03.03 20:03:49.343 5: ZWDongle_0 dispatch 011301
2016.03.03 20:03:49.343 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:49.344 5: SW: 06
2016.03.03 20:03:49.346 5: ZWDongle_0 dispatch 011301
2016.03.03 20:03:49.346 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 011301
2016.03.03 20:03:49.346 5: SW: 06
2016.03.03 20:03:49.349 5: ZWDongle_0 dispatch 011301
2016.03.03 20:03:49.349 4: no response from device, removing 010a001304037005022504b7 from dongle sendstack
2016.03.03 20:03:49.350 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 001304000002
2016.03.03 20:03:49.350 5: SW: 06
2016.03.03 20:03:49.352 5: ZWDongle_0 dispatch 001304000002
2016.03.03 20:03:49.352 4: CMD:ZW_SEND_DATA ID:00 ARG:0002
2016.03.03 20:03:49.353 4: ZWDongle_0 transmit OK for 04
2016.03.03 20:03:49.353 4: ZWDongle_Read ZWDongle_0: sending ACK, processing 000400040570060201ff
2016.03.03 20:03:49.353 5: SW: 06
2016.03.03 20:03:49.355 5: ZWDongle_0 dispatch 000400040570060201ff
2016.03.03 20:03:49.355 4: CMD:APPLICATION_COMMAND_HANDLER ID:04 ARG:0570060201ff

Danach wird es dann noch "bunter", obwohl keine Antwort kommt wird der nächste Befehl verabreitet und damit ist das ganze dann nicht mehr synchron, später tauchen dann auch wieder "no response" und CAN auf.

Ich verstehe es auch noch nicht, mich würde aber interessieren woher die mehrfachen ACK kommen...

Gruß,
Andreas.

krikan · 03 März 2016, 22:25:08

Zitat von: A.Harrenberg am 03 März 2016, 22:11:29
Hier gibt es mitten in der Ausführung der ganzen config Befehle eine zwavePlusInfo Abfrage, die sogar eine ReadAnswerFn aufruft, allerdings erkenne ich nicht wo/wann die überhaupt abgesetzt wird...

Mein Verdacht: Ich habe "get <device> zwavePlusInfo" als letzten Befehl im Menü ausgewählt und abgesetzt. WakeupNotification war schon gekommen und Befehl wird dazwischen geschoben. Bin zwar nicht ganz sicher, könnte aber vom zeitlichen Verlauf passen.

Irgendwie kommen mir wieder die CallbackIds in den Sinn...

A.Harrenberg · 03 März 2016, 22:35:27

Hi Christian,

CallBackIDs könnte man noch mal probieren abzusetzen und schauen was da von den Nodes zurückkommt. Ich hatte das damals mal ganz kurz gemacht und irgendwie abgespeichert das die dummerweise nicht immer mit zurückkommen...

Aber soetwas wie "expected Answer" wäre machbar, wenn man z.B. so einen Get-Befehl mit "700502" verschickt, weiss man ja das die Antwort eine "700602" sein muss...

Bevor wir das hier aber "weiterentwickeln" sollten wir erst einmal den Hintergrund der momentanen Probleme erkennen und fixen. Ich habe nur leider momentan nicht so viel Zeit wie ich gerne hätte und dann bin ich demnächst auch noch bis Ende April weg

Gruß,
Andreas.

krikan · 03 März 2016, 22:50:13

Denke nicht, dass das Problem so brennend ist und eine sofortige Lösung braucht. Also keine Hetze. Rudi wird sicherlich irgendwann wieder mehr Zeit haben und seinen Input brauchen wir auch.

A.Harrenberg · 03 März 2016, 23:06:34

Hi,

Zitat von: krikan am 03 März 2016, 22:50:13
Denke nicht, dass das Problem so brennend ist und eine sofortige Lösung braucht. Also keine Hetze. Rudi wird sicherlich irgendwann wieder mehr Zeit haben und seinen Input brauchen wir auch.

Irgendwie finde ich schon das dies ein schwerwiegendes Problem ist und möglichst schnell behoben werden sollte.
Ich vermute ein grundsätzliches Problem das auch im Normalbetrieb auftreten kann, durch die Massenabfertigung mit WU-Stack aber verstärkt auftritt.
Ob sich das dann einfach/schnell beheben lässt wissen wir natürlich erst wenn wir die eigentliche Ursache gefunden haben. Ich suche so lange und intensiv es meine freie Zeit zulässt, wenn es nicht bis zu meinem Urlaub gelöst ist dann eben später.
Mal sehen was das WE bringt.
Gruß,
Andreas.

Gesendet von meinem LIFETAB_S785X mit Tapatalk

reen · 04 März 2016, 09:20:32

Hi,
ich kann zwar nichts zur Lösung beitragen, aber bei mir passiert das gerade auch. (JFYI)

Code Auswählen


Save config 
Unsorted
ZWave
icoEverything Everything
Logfile
Commandref
Remote doc
Edit files
Select style
Event monitor

 Internals: 
   DEF        d344759d 27 
   IODev      ZWAVE1 
   LASTInputDev ZWAVE1 
   MSGCNT     871 
   NAME       Fib_Sensor 
   NR         24 
   STATE      closed 
   TYPE       ZWave 
   ZWAVE1_MSGCNT 871 
   ZWAVE1_RAWMSG 0004101b063105012200ca 
   ZWAVE1_TIME 2016-03-04 01:20:32 
   homeId     d344759d 
   isWakeUp   1 
   lastMsgSent 1457041250.999 
   nodeIdHex  1b 
   Readings: 
     2016-03-03 22:40:50   CMD             ZW_APPLICATION_UPDATE 
     2016-02-26 17:53:28   UNPARSED        SENSOR_MULTILEVEL 063101070a000b 
     2016-03-04 00:13:30   alarm_type_00   level ff node 1b seconds 0 
     2016-02-21 23:34:22   assocGroup_1    Max 5 Nodes ZWAVE1 
     2016-02-21 23:34:22   assocGroup_2    Max 5 Nodes 
     2016-02-21 23:34:22   assocGroup_3    Max 1 Nodes ZWAVE1 
     2016-02-21 23:34:17   assocGroups     3 
     2016-03-04 00:13:34   basicSet        00 
     2016-03-03 22:33:29   battery         100 % 
     2016-02-27 15:25:40   configAmbientIlluminationLevelAbove83 1000 
     2016-02-27 15:25:40   configAmbientIlluminationLevelBelow82 100 
     2016-02-27 15:25:40   configBASICOFFCommandFrameValue 0 
     2016-02-27 15:25:40   configBASICONCommandFrameValue 255 
     2016-02-27 15:25:41   configBasicCommandClassFrames12 BASICONAndBASICOFFCommandFrames0 
     2016-03-03 22:40:51   configIlluminationReportThreshold 25 
     2016-02-27 15:25:41   configIlluminationReportsInterval 0 
     2016-02-27 15:25:41   configIntervalOfTemperatureMeasuring 900 
     2016-03-03 22:34:45   configLEDBrightness 20 
     2016-03-03 22:33:55   configLEDIndicatingTamperAlarm LEDDoesNotIndicateTamperAlarm 
     2016-02-27 15:25:41   configLEDSignalingMode LongBlinkWhite 
     2016-02-27 15:25:41   configMaximumTemperatureResultingInRed87 28 
     2016-02-27 15:25:42   configMinimumTemperatureResultingIn86 18 
     2016-02-27 15:25:42   configMotionAlarmCancellationDelay 10 
     2016-02-27 15:25:42   configMotionSensorSBlindTime2 15 
     2016-02-27 15:25:42   configMotionSensorSSensitivity 10 
     2016-02-27 15:25:42   configNightDay  200 
     2016-02-27 15:25:42   configPIRSensorOperatingMode PIRSensorAlwaysActive 
     2016-02-27 15:25:42   configPIRSensorSPulseCounter 1 
     2016-02-27 15:25:43   configPIRSensorSWindowTime 2 
     2016-02-27 15:25:43   configTamperAlarmBroadcastMode TamperAlarmIsNotSentInBroadcast0 
     2016-02-27 15:25:43   configTamperAlarmCancellationDelay 30 
     2016-02-27 15:25:43   configTamperOperatingModes Tamper 
     2016-02-27 15:25:43   configTamperSensitivity 15 
     2016-02-27 15:25:43   configTemperatureOffset 0 
     2016-02-27 15:25:43   configTemperatureReportThreshold 10 
     2016-02-27 15:25:43   configTemperatureReportsInterval 0 
     2016-03-03 23:15:49   luminance       2 Lux 
     2016-02-21 20:02:36   model           FIBARO System FGMS001 Motion Sensor 
     2016-02-21 20:02:36   modelConfig     fibaro/fgms.xml 
     2016-02-21 20:02:36   modelId         010f-0800-1001 
     2016-03-04 00:13:34   reportedState   closed 
     2016-03-04 00:13:34   state           closed 
     2016-03-04 01:20:32   temperature     20.2 C 
     2016-03-03 22:40:53   transmit        OK 
     2016-03-03 05:44:52   wakeup          notification 
   SendStack: 
     get:131b028002251b 
     get:131b028002251b 
     get:131b028002251b 
     get:131b028505251b 
     get:131b028505251b 
     set:131b05700451010c251b 
     get:131b03700551251b 
     set:131b05700451010c251b 
     set:131b05700451010c251b 
     set:131b05700451010b251b 
     set:131b05700451010c251b 
     get:131b03700551251b 
     set:131b05700451010a251b 
     get:131b03700551251b 
     get:131b03700551251b 
Attributes: 
   IODev      ZWAVE1 
   classes    SENSOR_BINARY WAKE_UP ASSOCIATION BATTERY MULTI_CMD CRC_16_ENCAP MANUFACTURER_SPECIFIC VERSION CONFIGURATION MULTI_CHANNEL_ASSOCIATION SENSOR_MULTILEVEL SENSOR_ALARM MARK SENSOR_BINARY SENSOR_MULTILEVEL SENSOR_ALARM BASIC 
   room       ZWave

Habe gestern zwischen 23-00Uhr ein paar Einstellungen der config-Parameter ausprobiert (vor allem Blinkverhalten und Helligkeitsanpassung der LED).
Habe dann so 3-4 mal den Sensor manuell aufgeweckt um die Parameter zu setzen. Hat auch funktioniert. Aber nach ein paar mal, wurden plötzlich nichtsmehr gesetzt, und die Befehle landeten im sendstack.
Auch die Werte werden seitdem nicht mehr übermittelt.

krikan · 04 März 2016, 09:32:25

ZitatAuch die Werte werden seitdem nicht mehr übermittelt.

Wenn jetzt gar keine Werte mehr kommen, tippe ich auf einen andere Ursache. Dongle hängt o.ä.; würde Dongle mal stromlos machen und/oder Server-Computer stromlos und neu starten.
verbose 5-Logs hast Du vermutlich nicht, oder?
Bei meinem/unserem Problem der Unterbrechung der Sendstack-Abarbeitung funktioniert der Meldungsempfang vom Sensor weiterhin und der Sendstack wird später bei der nächsten WakeupNotification mEn weiter abgearbeitet.

9zehn75 · 04 März 2016, 10:25:57

Zitat von: A.Harrenberg am 03 März 2016, 21:52:36
Hi,das ist definitiv richtig beobachtet. Wenn der "hängenbleibt" liegen noch die restlichen Befehle auf dem Stack. Beim nächsten WakeUp macht er irgendwie weiter. Wie FHEM dabei mit dem eigentlich bereits versendeten Befehl (ohne Antwort) oben auf dem Stack umgeht habe ich mir noch nicht angeschaut.

Normalerweise arbeiten die WakeUp-Geräte den SendStack komplett ab bevor FHEM sie dann wieder schlafen schickt.

Die Theorie ist: Gerät wacht auf und schickt eine WakeUp-Notification zum Dongle. Der schaut nach ob Befehle für das Geräte vorhanden sind, wenn ja werden die alle verschickt. Wenn dann keine Befehle mehr da sind, oder es gar keine gebeben hat, dann schickt das Dongle eine WNMI-Nachricht (WakeUp No More Information) welche dem Gerät sagt das es wieder schlafen gehen kann/soll. Die Geräte sollen laut Spezifikation auch ohne diese Nachricht nach einer bestimmten Zeit wieder einschlafen um Batterie zu sparen, dummerweise gibt es keine festgelegte Zeit, und das macht dann anscheinend jeder wie er will.

Das erklärt einiges. Bei meinen WU-Geräten dauert es zum Teil Tage (Aufwachen alle 12 Stunden) bis alle gewünschten Readings befüllt sind. Dachte schon, es liegt an mir...

9zehn75 · 04 März 2016, 10:29:06

Zitat von: A.Harrenberg am 03 März 2016, 22:11:29
Danach wird es dann noch "bunter", obwohl keine Antwort kommt wird der nächste Befehl verabreitet und damit ist das ganze dann nicht mehr synchron, später tauchen dann auch wieder "no response" und CAN auf.

Ich habe schon mehrfach beobachtet, dass im "STATE" von WU-Geräte Stati stehen, die dort eigentlich nicht hindürfen (z.B. die Rückmeldung auf "get wakeupInterval"). Das könnte dann auch daran liegen, oder?

krikan · 04 März 2016, 10:38:48

ZitatDas erklärt einiges. Bei meinen WU-Geräten dauert es zum Teil Tage (Aufwachen alle 12 Stunden) bis alle gewünschten Readings befüllt sind. Dachte schon, es liegt an mir...

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.

ZitatIch habe schon mehrfach beobachtet, dass im "STATE" von WU-Geräte Stati stehen, die dort eigentlich nicht hindürfen (z.B. die Rückmeldung auf "get wakeupInterval"). Das könnte dann auch daran liegen, oder?

Behaupte: Nein

krikan · 05 März 2016, 09:27:07

Andreas, wenn ich hier bei Problemanalyse irgendwie helfen kann, gib bitte Bescheid. Mir fehlen momentan die Ideen/Ansatzpunkte.
Gruß, Christian

A.Harrenberg · 05 März 2016, 09:44:26

Hi Christian,

ich acker gerade ein mit Debug-messages gespicktes Logfile ab um erst einmal zu verstehen was Rudi da mit den beiden ProcessSendStack Funktionen in der 00_ZWDongle.pm und 10_ZWave.pm eigentlich so anstellt ,-)

Wenn ich das dann mal durchhabe und evtl. die eine oder andere Debug-message noch ergänzt habe könnte es sein das ich ein weiteres Log aus einem anderen Szenario brauche.

Es scheint ja mehrere Möglichkeiten zu geben in dieses "Anhalten" reinlaufen zu können und wir sollten sicherstellen das es im Code die gleiche Ursache hat und wir hier nicht mit zwei verschiedenen Problemen kämpfen.

Ohne das bisher im Detail nachvollzogen zu haben fürchte ich das hier die "unsolicited" Nachrichten von der Node die in eine solche Abfrage reingeraten (also zwischen get und dem report) den Sendstack aushebelt und der dann neue Nachrichten zu früh freigibt wodurch dann jede Menge CAN auftreten. An welcher Stelle dann allerdings die Ausführung stoppt habe ich noch nicht begriffen, da ja da auch immer ein Timer mit gestartet wird der dann zumindest einen Fehler ausgeben sollte.

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 zugekommen

Gruß,
Andreas.