[Gelöst] "No ACK from" bei Multichannel-Devices im Log trotz korrekter Antwort

rudolfkoenig · 14 Juni 2016, 22:08:09

- "Das Ausgangsproblem ist weiterhin vorhanden"... "NO ACK diesmal nicht vorhanden!" Was nu: gibts das Anfangsproblem mit No ACK oder nicht. Ich sehe es jedenfalls nicht.
- "Antworten kommen einfach so mehrfach" Was nu: einfach oder mehrfach

Ich tippe darauf, dass der Controller das 06 nicht bekommt, und deswegen die Daten immer wieder schickt. 10-mal. Ziemlich geduldig, der Bursche. Stellt sich aber die Frage, wieso der Controller den Get sauber kriegt, und auch die ACKs auf 011301 bzw. 00131d00, aber nicht fuer die Antwort. Und wieso die Antwort vor dem 0013 kommt.

Hmmm. Totally lost

krikan · 14 Juni 2016, 22:21:51

Zitat von: rudolfkoenig am 14 Juni 2016, 22:08:09
- "Das Ausgangsproblem ist weiterhin vorhanden"... "NO ACK diesmal nicht vorhanden!" Was nu: gibts das Anfangsproblem mit No ACK oder nicht. Ich sehe es jedenfalls nicht.

Anfangsproblem noch vorhanden; nur einmalig (im geposteten Log) nicht.

Zitat
"Antworten kommen einfach so mehrfach" Was nu: einfach oder mehrfach

Mehrfache Antwort auf ein durch FHEM verschicktes Telegramm

ZitatIch tippe darauf, dass der Controller das 06 nicht bekommt, und deswegen die Daten immer wieder schickt. 10-mal. Ziemlich geduldig, der Bursche. Stellt sich aber die Frage, wieso der Controller den Get sauber kriegt, und auch die ACKs auf 011301 bzw. 00131d00, aber nicht fuer die Antwort. Und wieso die Antwort vor dem 0013 kommt.

Ich schrieb ja: Chaos. Kann Dir auch andere Varianten mit unerklärlichen Wiederholungen von 0113 und 0013 liefern. In grauer Vorzeit hattest Du dem Controller schon mal Merkwürdigkeiten attestiert. Meine 0013 fehlte eine Zeit lang.
Und Du solltest Dir keine Kopfschmerzen wegen meines Sonderproblems machen und es vergessen.

Mich würde aber doch mal interessieren, ob das Thread-Ausgangsproblem bei anderen weg ist.

A.Harrenberg · 14 Juni 2016, 22:59:16

Hi,

Zitat von: krikan am 14 Juni 2016, 22:21:51
Mich würde aber doch mal interessieren, ob das Thread-Ausgangsproblem bei anderen weg ist.

ich habe leider kein Multichannel Device, kann daher auch nicht testen.

Ich kann mich jetzt leider nicht mehr so genau an die Details erinnern, aber ich hatte auch mal SEHR merkwürdige Effekte als ich einige CAN durch das ConfigAll bekommen hatte (im Zuge der Einführung der Sendestacks). Da waren mit einem Mal auch etliche Nachrichten verschwunden, dafür tauchten andere unerklärlich oft auf, und das obwohl die ACKs eigentlich alle "passend" waren. Ich habe das dann allerdings nicht mehr reproduzieren können um es weiter zu untersuchen. Ist von alleine gekommen und ist auch wieder von alleine verschwunden...

Mit was für einem Dongle arbeitest Du eigentlich auf dem Testsystem?

Gruß,
Andreas.

krikan · 14 Juni 2016, 23:14:33

Ist ein Vision Z-Wave USB Stick ZU 1401 EU mit SDK 6.02 und 4er Chipsatz. Wesentlichen Funktionen von ZWave-Plus (100k, EF, usw) sind schon drin. War mein 1. Controller als ZWave-Plus noch kein Thema war.

Das Merkwürdige ist: Im Normalbetrieb ist alles unauffällig. Wenn ich "Stresstests" mache, funktioniert es meistens. Ab und an und ohne für mich erkennbare Logik passt irgendetwas nicht und das auch teilweise nach Neustarts. Im Fazit nichts, was uns wirklich weiterbringt

.

gamauf · 15 Juni 2016, 18:23:28

Hab grad "update" laufen lassen und nach einem FHEM Neustart ein "get ZWave_SWITCH_BINARY_27.01 swbStatus" ausgeführt:

Code Auswählen

2016.06.15 18:19:21 2: ZWave get ZWave_SWITCH_BINARY_27.01 swbStatus
2016.06.15 18:19:21 2: ZWave get ZWave_SWITCH_BINARY_27.01 swbStatus
2016.06.15 18:19:26 2: ZWave: No ACK from ZWave_SWITCH_BINARY_27 after 5s for sentackget:131b06600d010125022505

...

LG
Rainer

PS.: Controller ist ZME_UZB1

krikan · 17 Juni 2016, 20:27:07

Die NO_ACK bei Multichannel-Devices kommt bei meinen Tests mit meinen beiden anderen Controllern und auf anderem System immer noch und regelmäßig. Wenn ich Dir irgendwie bei der Analyse mit Logs helfen kann, lass es mich wissen. Habe selbst schon erfolglos gesucht.

Bezüglich der Schmerzmedikamente-fördernden Logs:
Habe den Vision 4er auf meinen Vision Zwave+-Controller repliziert und anschließend auch auf einen UZB1.
Dann habe ich versucht jeweils die gleichen Stresstests mit Win und Debian bei jedem Controller durchzuführen: Beim 4er Vision kommen immer wieder in unregelmäßigen Abständen merkwürdige Logs. Bei den ZWavePlus Controllern gibt es auch schon einmal Auffälligkeiten, aber nicht so häufig. Darum mein Vermutung, dass es evtl. doch mit dem Controller zusammenhängt, auch wenn Deine für mich nachvollziehbare Vermutung in eine andere Richtung geht. Werde zukünftig für Tests nur noch die Plus-Controller einsetzen, da der 4er Chipsatz sowieso eine Seltenheit darstellt.

throbin · 18 Juni 2016, 17:34:15

Hi,

ich habe den UZB1 mit Firmware 5.6 am Pi3 im Einsatz. Als Device dient ein FIBARO FGS-222. Am Endpoint 1 habe ich einen EG_Terrasse_LampeWS (reales Device) konfiguriert, am Endpoint 2 einen EG_Terrasse_SteckdoseWS (Endpoint Device). Wenn ich "get EG_Terrasse_SteckdoseWS swbStatus" (über WEB UI) ausführe, bekomme ich folgendes Log:

Code Auswählen


2016.06.18 17:23:21.229 2: ZWave get EG_Terrasse_SteckdoseWS swbStatus 
2016.06.18 17:23:21.283 2: ZWave set EG_Terrasse_Steckdose off 
2016.06.18 17:23:26.234 2: ZWave: No ACK from EG_Terrasse_LampeWS after 5s for sentackget:130f06600d01022502250b

Listing vom Device:

Code Auswählen


Internals: 
   DEF        dad62400 15 
   IODev      ZWDongle_0 
   LASTInputDev ZWDongle_0 
   MSGCNT     24 
   NAME       EG_Terrasse_LampeWS 
   NR         57 
   STATE      aus 
   TYPE       ZWave 
   ZWDongle_0_MSGCNT 24 
   ZWDongle_0_RAWMSG 0004000f057006100101 
   ZWDongle_0_TIME 2016-06-18 17:32:54 
   homeId     dad62400 
   isWakeUp 
   lastMsgSent 1466263989.26927 
   nodeIdHex  0f 
   timeToAck  0.028 
   Readings: 
     2016-06-18 17:32:44   assocGroup_1    Max 5 Nodes ZWDongle_0 
     2016-06-18 17:32:44   assocGroup_2    Max 5 Nodes 
     2016-06-18 17:32:44   assocGroup_3    Max 1 Nodes ZWDongle_0 
     2016-06-18 17:32:44   assocGroups     3 
     2016-06-18 17:32:54   configALARMFLASHINGAlarmTime 600 
     2016-06-18 17:32:54   configAutoOffForRelay1 0 
     2016-06-18 17:32:54   configAutoOffForRelay2 0 
     2016-06-18 17:32:54   configAutoOffRelayAfterSpecifiedTime ManualOverrideDisabled 
     2016-06-18 17:32:54   configDimmerRollerShutterControl DisableDimmerRollerShutter0 
     2016-06-18 17:32:54   configEnableDisableALLONOFF ALLONActiveALLOFFActive 
     2016-06-18 17:32:54   configInputsBehaviour Toggle 
     2016-06-18 17:32:54   configInputsButtonSwitchConfiguration MonoStableInputButton 
     2016-06-18 17:32:54   configManagingTheTransmissionOfControl6 TheControlCommandsAreSentWhenThe0 
     2016-06-18 17:32:54   configManagingTheTransmissionOfControl7 TheControlCommandsAreSentWhenThe0 
     2016-06-18 17:32:54   configRelay1ResponseToGeneralAlarm ALARMFLASHINGRelayWillTurnONAndO3 
     2016-06-18 17:32:54   configRelay1ResponseToSmokeCOCO2Alarm ALARMFLASHINGRelayWillTurnONAndO3 
     2016-06-18 17:32:54   configRelay1ResponseToTemperatureAlarm ALARMRELAYONRelayWillTurnONUpon1 
     2016-06-18 17:32:54   configRelay1ResponseToWaterFloodAlarm ALARMRELAYOFFRelayWillTurnOFF2 
     2016-06-18 17:32:54   configRelay2ResponseToGeneralAlarm ALARMFLASHINGRelayWillTurnONAndO3 
     2016-06-18 17:32:54   configRelay2ResponseToSmokeCOCO2Alarm ALARMFLASHINGRelayWillTurnONAndO3 
     2016-06-18 17:32:54   configRelay2ResponseToTemperatureAlarm ALARMRELAYONRelayWillTurnONUpon1 
     2016-06-18 17:32:54   configRelay2ResponseToWaterFloodAlarm ALARMRELAYOFFRelayWillTurnOFF2 
     2016-06-18 17:32:54   configSavingStateBeforePowerFailure StateSavedAtPowerFailureAll1 
     2016-05-25 08:02:49   mcCapability_01 SWITCH_BINARY 
     2016-05-25 08:02:49   mcCapability_02 SWITCH_BINARY 
     2016-05-25 08:02:49   mcEndpoints     total 2, identical 
     2016-05-25 08:02:49   model           FIBARO System FGS222 Double Relay Switch 2x1.5kW 
     2016-05-25 08:02:49   modelConfig     fibaro/fgs222.xml 
     2016-05-25 08:02:49   modelId         010f-0202-1002 
     2016-06-18 17:21:28   reportedState   off 
     2016-06-18 17:21:28   state           off 
     2016-06-18 17:33:09   transmit        OK 
Attributes: 
   IODev      ZWDongle_0 
   classes    MANUFACTURER_SPECIFIC VERSION CONFIGURATION ASSOCIATION MULTI_CHANNEL_ASSOCIATION MULTI_CHANNEL SWITCH_BINARY SWITCH_ALL FIRMWARE_UPDATE_MD POWERLEVEL MARK SWITCH_BINARY MULTI_CHANNEL 
   eventMap   on:an off:aus 
   group      Wandsender 
   room       Terrasse,ZWave 
   vclasses   ASSOCIATION:2 CONFIGURATION:1 FIRMWARE_UPDATE_MD:1 MANUFACTURER_SPECIFIC:1 MULTI_CHANNEL:2 MULTI_CHANNEL_ASSOCIATION:1 POWERLEVEL:1 SWITCH_ALL:1 SWITCH_BINARY:1 VERSION:1

Komischerweise wird ein "set EG_Terrasse_Steckdose off" gemeldet, ich verstehe nicht, warum? Ist es mein Fehler?

Danke schon mal im Voraus!

rudolfkoenig · 18 Juni 2016, 22:08:01

Habe es auf meinem verbauten fgs221 nachgestellt und das Problem gefixt. Duerfte seit ca 3 Monaten vorhanden sein. Es geht darum, dass beim get die gesendete Klasse mit der Empfangenen verglichen wird, leider einmal mit Multi-Channel Encapsulation, einmal ohne.

throbin · 19 Juni 2016, 12:52:56

Hallo Rudolf,

sieht gut aus, der Fehler kommt nicht mehr:

Code Auswählen


2016.06.19 12:50:29.378 2: ZWave get EG_Terrasse_SteckdoseWS swbStatus 
2016.06.19 12:50:29.378 5: ZWDongle_Write 00130f06600d010225022505 (dad62400)
2016.06.19 12:50:29.379 5: SW: 010d00130f06600d01022502250581
2016.06.19 12:50:29.381 5: ACK received, WaitForAck=>2 for 010d00130f06600d01022502250581
2016.06.19 12:50:29.387 4: ZWDongle_Read ZWDongle_0: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2016.06.19 12:50:29.387 5: SW: 06
2016.06.19 12:50:29.388 5: ZWDongle_0 dispatch 011301
2016.06.19 12:50:29.405 4: ZWDongle_Read ZWDongle_0: rcvd 001305000002 (request ZW_SEND_DATA), sending ACK
2016.06.19 12:50:29.405 5: SW: 06
2016.06.19 12:50:29.406 5: device ack reveived, removing 010d00130f06600d01022502250581 from dongle sendstack
2016.06.19 12:50:29.406 5: ZWDongle_0 dispatch 001305000002
2016.06.19 12:50:29.406 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:05
2016.06.19 12:50:29.407 4: ZWDongle_0 transmit OK for CB 05, target EG_Terrasse_LampeWS
2016.06.19 12:50:29.416 4: ZWDongle_Read ZWDongle_0: rcvd 0004000f07600d0201250300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2016.06.19 12:50:29.416 5: SW: 06
2016.06.19 12:50:29.418 5: ZWDongle_0 dispatch 0004000f07600d0201250300
2016.06.19 12:50:29.418 4: CMD:APPLICATION_COMMAND_HANDLER ID:0f ARG:07600d0201250300 CB:00
2016.06.19 12:50:29.424 2: ZWave set EG_Terrasse_Steckdose off 
2016.06.19 12:50:29.425 5: ZWDongle_Write 00130e07600d01022501002506 (dad62400)
2016.06.19 12:50:29.425 5: SW: 010e00130e07600d0102250100250682
2016.06.19 12:50:29.433 5: ACK received, WaitForAck=>2 for 010e00130e07600d0102250100250682
2016.06.19 12:50:29.434 4: ZWDongle_Read ZWDongle_0: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2016.06.19 12:50:29.434 5: SW: 06
2016.06.19 12:50:29.435 5: ZWDongle_0 dispatch 011301
2016.06.19 12:50:29.452 4: ZWDongle_Read ZWDongle_0: rcvd 001306000003 (request ZW_SEND_DATA), sending ACK
2016.06.19 12:50:29.452 5: SW: 06
2016.06.19 12:50:29.453 5: device ack reveived, removing 010e00130e07600d0102250100250682 from dongle sendstack
2016.06.19 12:50:29.453 5: ZWDongle_0 dispatch 001306000003
2016.06.19 12:50:29.454 4: CMD:ZW_SEND_DATA ID:00 ARG:0003 CB:06
2016.06.19 12:50:29.454 4: ZWDongle_0 transmit OK for CB 06, target EG_Terrasse_Lampe

Danke!

gamauf · 22 Juni 2016, 17:32:38

Zitatsieht gut aus, der Fehler kommt nicht mehr:

kann ich bestätigen!

Danke!

Rainer

gamauf · 24 Juni 2016, 15:02:32

Hallo!

Bein Switch ist's behoben, aber beim Dimmer (FIBARO System FGD212 Dimmer 2) scheint es noch zu bestehen:

Code Auswählen

2016.06.24 14:53:55.879 2: ZWave get ZWave_ZWAVEPLUS_INFO_20.01 swmStatus
2016.06.24 14:53:55.879 5: ZWDongle_Write 00131406600d0101260225c3 (cb838b79)
2016.06.24 14:53:55.880 5: SW: 010d00131406600d0101260225c35c
2016.06.24 14:53:55.883 5: ACK received, WaitForAck=>2 for 010d00131406600d0101260225c35c
2016.06.24 14:53:55.889 4: ZWDongle_Read ZWDongle_0: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2016.06.24 14:53:55.889 5: SW: 06
2016.06.24 14:53:55.891 5: ZWDongle_0 dispatch 011301
2016.06.24 14:53:55.905 4: ZWDongle_Read ZWDongle_0: rcvd 0013c3000002 (request ZW_SEND_DATA), sending ACK
2016.06.24 14:53:55.905 5: SW: 06
2016.06.24 14:53:55.907 5: device ack reveived, removing 010d00131406600d0101260225c35c from dongle sendstack
2016.06.24 14:53:55.907 5: ZWDongle_0 dispatch 0013c3000002
2016.06.24 14:53:55.907 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:c3
2016.06.24 14:53:55.908 4: ZWDongle_0 transmit OK for CB c3, target ZWave_SWITCH_MULTILEVEL_20
2016.06.24 14:53:55.918 4: ZWDongle_Read ZWDongle_0: rcvd 0004001407600d010126034d (request APPLICATION_COMMAND_HANDLER), sending ACK
2016.06.24 14:53:55.918 5: SW: 06
2016.06.24 14:53:55.920 5: ZWDongle_0 dispatch 0004001407600d010126034d
2016.06.24 14:53:55.920 4: CMD:APPLICATION_COMMAND_HANDLER ID:14 ARG:07600d010126034d CB:00
2016.06.24 14:54:00.881 2: ZWave: No ACK from ZWave_SWITCH_MULTILEVEL_20 after 5s for sentackget:131406600d0101260225c3

...nur zur Info, hat keine Priorität...

(die Sub-Devices mit den "komischen" Namen hat FHEM automatisch angelegt:
ZWave_SWITCH_MULTILEVEL_20, ZWave_ZWAVEPLUS_INFO_20.01 und ZWave_ZWAVEPLUS_INFO_20.02)

rudolfkoenig · 25 Juni 2016, 18:27:52

Da ich so'n Geraet nicht habe: kannst du bitte:
- in FHEM/10_ZWave.pm, Funktion ZWave_processSendStack die Log Zeile mit pSS aktivieren (# entfernen)
- in der Funktion ZWave_addToSendStack die Log Zeile mit aTSS aktivieren
- FHEM neu starten
- Problem reproduzieren
- Ausgabe hier anhaengen

gamauf · 05 Juli 2016, 12:39:45

Hallo Rudolf!
Danke für Deine Antwort!
Hab' leider erst jetzt Zeit gefunden, Deiner Anleitung zu folgen.
Hier ist der Log-Auszug:

Code Auswählen

2016.07.05 12:36:28.522 3: ZWave get ZWave_ZWAVEPLUS_INFO_20.01 swmStatus
2016.07.05 12:36:28.523 1: aTSS: ZWave_SWITCH_MULTILEVEL_20, get, 131406600d010126022501 / L:1
2016.07.05 12:36:28.523 1: pSS: ZWave_SWITCH_MULTILEVEL_20, next get:131406600d010126022501
2016.07.05 12:36:28.565 1: pSS: ZWave_SWITCH_MULTILEVEL_20, ack sentget:131406600d010126022501
2016.07.05 12:36:28.569 1: pSS: ZWave_SWITCH_MULTILEVEL_20, msg sentackget:131406600d010126022501
2016.07.05 12:36:33.525 2: ZWave: No ACK from ZWave_SWITCH_MULTILEVEL_20 after 5s for sentackget:131406600d010126022501
2016.07.05 12:36:33.525 1: pSS: ZWave_SWITCH_MULTILEVEL_20, next sentackget:131406600d010126022501

LG
Rainer

rudolfkoenig · 05 Juli 2016, 20:19:10

Sorry, reicht leider nicht. Bitte die pSS Zeile durch die Folgende ersetzen, und nochmal probieren:

Code Auswählen

  Log 1, "pSS: $hash->{NAME}, $ackType $ss->[0]".($omsg ? "  omsg:$omsg" : "");

gamauf · 06 Juli 2016, 10:55:50

kein Problem!
Hier das neue Log:

Code Auswählen


2016.07.06 10:47:59.767 3: ZWave get ZWave_ZWAVEPLUS_INFO_20.01 swmStatus
2016.07.06 10:47:59.768 1: aTSS: ZWave_SWITCH_MULTILEVEL_20, get, 131406600d010126022501 / L:1
2016.07.06 10:47:59.768 1: pSS: ZWave_SWITCH_MULTILEVEL_20, next get:131406600d010126022501
2016.07.06 10:47:59.768 5: ZWDongle_Write 00131406600d010126022501 (cb838b79)
2016.07.06 10:47:59.769 5: SW: 010d00131406600d0101260225019e
2016.07.06 10:47:59.772 5: ACK received, WaitForAck=>2 for 010d00131406600d0101260225019e
2016.07.06 10:47:59.778 4: ZWDongle_Read ZWDongle_0: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2016.07.06 10:47:59.779 5: SW: 06
2016.07.06 10:47:59.780 5: ZWDongle_0 dispatch 011301
2016.07.06 10:47:59.808 4: ZWDongle_Read ZWDongle_0: rcvd 001301000002 (request ZW_SEND_DATA), sending ACK
2016.07.06 10:47:59.808 5: SW: 06
2016.07.06 10:47:59.810 5: device ack reveived, removing 010d00131406600d0101260225019e from dongle sendstack
2016.07.06 10:47:59.811 5: ZWDongle_0 dispatch 001301000002
2016.07.06 10:47:59.812 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:01
2016.07.06 10:47:59.812 4: ZWDongle_0 transmit OK for CB 01, target ZWave_SWITCH_MULTILEVEL_20
2016.07.06 10:47:59.813 1: pSS: ZWave_SWITCH_MULTILEVEL_20, ack sentget:131406600d010126022501  omsg:01
2016.07.06 10:47:59.814 4: ZWDongle_Read ZWDongle_0: rcvd 0004001407600d010126034d (request APPLICATION_COMMAND_HANDLER), sending ACK
2016.07.06 10:47:59.815 5: SW: 06
2016.07.06 10:47:59.816 5: ZWDongle_0 dispatch 0004001407600d010126034d
2016.07.06 10:47:59.817 4: CMD:APPLICATION_COMMAND_HANDLER ID:14 ARG:07600d010126034d CB:00
2016.07.06 10:47:59.819 1: pSS: ZWave_SWITCH_MULTILEVEL_20, msg sentackget:131406600d010126022501  omsg:0326034d
2016.07.06 10:48:04.770 2: ZWave: No ACK from ZWave_SWITCH_MULTILEVEL_20 after 5s for sentackget:131406600d010126022501
2016.07.06 10:48:04.770 1: pSS: ZWave_SWITCH_MULTILEVEL_20, next sentackget:131406600d010126022501
2016.07.06 10:48:22.460 4: ZWDongle_Read ZWDongle_0: rcvd 0004001306310504220000 (request APPLICATION_COMMAND_HANDLER), sending ACK
2016.07.06 10:48:22.460 5: SW: 06
2016.07.06 10:48:22.462 5: ZWDongle_0 dispatch 0004001306310504220000
2016.07.06 10:48:22.462 4: CMD:APPLICATION_COMMAND_HANDLER ID:13 ARG:06310504220000 CB:00