'no ACK' bei ZWAVE - Schaltbefehlen

[PNinBB]

Die Vorgeschichte zu dem hier geschilderten Problem ist unter "Keine Event-Meldungen von ZWAVE-Sensoren" zu finden.
Im Fehlerlog erscheint nach dem "Umbau" meines FHEM-Systems nur noch eine Fehlermeldung, die auf ein Problem mit dem Funkfeld hinzuweisen scheint.

Code Auswählen Erweitern


2019.01.03 19:54:30.558 1: FlurBeleuchtung mit 1 started
2019.01.03 19:54:30.567 3: ZWave set FL_SK_D1 on
2019.01.03 19:54:30.817 3: ZWave set FL_SK_D2 on
2019.01.03 19:54:31.057 1: FlurBeleuchtung finished
2019.01.03 19:54:31.244 2: ZWDongle_ProcessSendStack: no ACK, resending message 010e00130b07600d00012501FF25bfc3

Der Hintergrund ist folgender. Ein Fibaro Sensor (FIBARO System FGMS001 Motion Sensor) löst bei erkannter Bewegung Ereignisse aus. Diese werden in einem notify gefiltert und starten eine Perl-Routine.
Nachfolgend die notify-Definition:

Code Auswählen Erweitern


Internals:
   .COMMAND   {myElektroUtils_FlurBeleuchtung($EVENT)}
   DEF        FL_DS_SM:[1] {myElektroUtils_FlurBeleuchtung($EVENT)}
   NAME       no_FL_Beleuchtung
   NOTIFYDEV  FL_DS_SM
   NR         148
   NTFY_ORDER 50-no_FL_Beleuchtung
   REGEXP     FL_DS_SM:[1]
   STATE      2019-01-03 20:12:54
   TRIGGERTIME 1546542774.68843
   TYPE       notify
   .attraggr:
   .attrminint:
   READINGS:
     2019-01-02 08:58:04   state           active
Attributes:
   DbLogExclude .*
   group      notify
   icon       light_on-for-timer.svg
   room       Timer

Die Perlroutine schaltet in Abhängigkeit von diversen Zeitbedingungen eine oder zwei Lampen (FL_SK_D1, FL_SK_D2; Knotennummer: 11, 0BH). Diese verlöschen nach einer definierten Zeit. Die jeweilgen Zeitparameter sind in Dummies abgelegt und können auch entsprechend geändert werden.
Die entscheidende Zeile in der Perlroutine ist:

Code Auswählen Erweitern


fhem("set FL_SK_D1 on-for-timer $DauerGrossSek; set FL_SK_D2 on-for-timer $DauerGrossSek");

Das funktioniert eigentlich so wie programmiert
Unerklärlich für mich ist die Meldung wegen des fehlenden ACK. Die beteiligten Aktoren und der Sensor sind nahe am Controller (ca. 3 m ohne Behinderungen).
Dabei spielt es keine Rolle, ob beide Lampen oder nur eine eingeschaltet werden; auch ist die Reihenfolge bedeutungslos.
Löse ich eine Bewegung entsprechend aus, dann zeigt Eventlog folgende Ereignisse:

Code Auswählen Erweitern


2019-01-03 09:13:05.544 MQTT MosquittoHA publish /SmartHome/FL/GrossesLicht/state ein
2019-01-03 09:13:05.554 ZWave FL_SK_D1 ein
2019-01-03 09:13:05.771 MQTT MosquittoHA publish /SmartHome/FL/KleinesLicht/state ein
2019-01-03 09:13:05.781 ZWave FL_SK_D2 ein
2019-01-03 09:13:05.819 ZWave FL_DS_SM 1
2019-01-03 09:13:05.819 ZWave FL_DS_SM reportedState: 1
2019-01-03 09:13:05.979 ZWave FL_DS_BS basicSet: 255
2019-01-03 09:13:08.305 ZWave FL_AB_RM ein
2019-01-03 09:13:08.305 ZWave FL_AB_RM reportedState: ein
2019-01-03 09:13:19.663 ZWave FL_DS_SM 0
2019-01-03 09:13:19.663 ZWave FL_DS_SM reportedState: 0
2019-01-03 09:13:19.820 ZWave FL_DS_BS basicSet: 0

Logfile mit verbose=5 sieht wie folgt aus:

Code Auswählen Erweitern


2019.01.03 09:13:05.146 4: ZWDongle_Read ZWAVE: rcvd 00040025033003ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2019.01.03 09:13:05.147 5: SW: 06
2019.01.03 09:13:05.149 5: ZWAVE: dispatch 00040025033003ff
2019.01.03 09:13:05.150 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:033003ff CB:00
2019.01.03 09:13:05.331 1: FlurBeleuchtung mit 1 started
2019.01.03 09:13:05.338 3: ZWave set FL_SK_D1 on
2019.01.03 09:13:05.339 5: ZWDongle_Write 00130b07600d00012501FF2542 (ed70b42b)
2019.01.03 09:13:05.341 5: SW: 010e00130b07600d00012501FF25423e
2019.01.03 09:13:05.571 3: ZWave set FL_SK_D2 on
2019.01.03 09:13:05.795 1: FlurBeleuchtung finished
2019.01.03 09:13:05.858 5: ZWDongle_Write 00132f0284082544 (ed70b42b)
2019.01.03 09:13:05.861 4: ZWDongle_Read ZWAVE: rcvd 00040025032001ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2019.01.03 09:13:05.862 5: SW: 06
2019.01.03 09:13:05.864 5: ZWAVE: dispatch 00040025032001ff
2019.01.03 09:13:05.865 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:032001ff CB:00
2019.01.03 09:13:05.869 4: ZWDongle_Read ZWAVE: CAN received
2019.01.03 09:13:05.873 4: ZWDongle_Read ZWAVE: rcvd 0004002507600d01012001ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2019.01.03 09:13:05.874 5: SW: 06
2019.01.03 09:13:05.876 5: ZWAVE: dispatch 0004002507600d01012001ff
2019.01.03 09:13:05.877 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:07600d01012001ff CB:00
2019.01.03 09:13:05.981 2: ZWDongle_ProcessSendStack: no ACK, resending message 010e00130b07600d00012501FF25423e
2019.01.03 09:13:05.982 5: SW: 010e00130b07600d00012501FF25423e
2019.01.03 09:13:05.985 5: ACK received, WaitForAck=>2 for 010e00130b07600d00012501FF25423e
2019.01.03 09:13:05.989 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2019.01.03 09:13:05.990 5: SW: 06
2019.01.03 09:13:05.992 5: ZWAVE: dispatch 011301
2019.01.03 09:13:06.004 4: ZWDongle_Read ZWAVE: rcvd 001342000002 (request ZW_SEND_DATA), sending ACK
2019.01.03 09:13:06.005 5: SW: 06
2019.01.03 09:13:06.006 5: device ack reveived, removing 010e00130b07600d00012501FF25423e from dongle sendstack
2019.01.03 09:13:06.007 5: ZWAVE: dispatch 001342000002
2019.01.03 09:13:06.008 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:42
2019.01.03 09:13:06.008 4: ZWAVE transmit OK for CB 42, target FL_AB_RM
2019.01.03 09:13:06.011 5: ZWDongle_Write 00130b07600d00022501FF2543 (ed70b42b)
2019.01.03 09:13:06.013 5: SW: 010900132f028408254425
2019.01.03 09:13:06.018 5: ACK received, WaitForAck=>2 for 010900132f028408254425
2019.01.03 09:13:06.022 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2019.01.03 09:13:06.022 5: SW: 06
2019.01.03 09:13:06.024 5: ZWAVE: dispatch 011301
2019.01.03 09:13:06.035 4: ZWDongle_Read ZWAVE: rcvd 001344000002 (request ZW_SEND_DATA), sending ACK
2019.01.03 09:13:06.036 5: SW: 06
2019.01.03 09:13:06.037 5: device ack reveived, removing 010900132f028408254425 from dongle sendstack
2019.01.03 09:13:06.038 5: ZWAVE: dispatch 001344000002
2019.01.03 09:13:06.039 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:44
2019.01.03 09:13:06.039 4: ZWAVE transmit OK for CB 44, target AZ_HZ_T1
2019.01.03 09:13:06.042 5: SW: 010e00130b07600d00022501FF25433c
2019.01.03 09:13:06.046 5: ACK received, WaitForAck=>2 for 010e00130b07600d00022501FF25433c
2019.01.03 09:13:06.050 4: ZWDongle_Read ZWAVE: rcvd 011301 (answer ZW_SEND_DATA), sending ACK
2019.01.03 09:13:06.050 5: SW: 06
2019.01.03 09:13:06.052 5: ZWAVE: dispatch 011301
2019.01.03 09:13:06.065 4: ZWDongle_Read ZWAVE: rcvd 001343000002 (request ZW_SEND_DATA), sending ACK
2019.01.03 09:13:06.065 5: SW: 06
2019.01.03 09:13:06.067 5: device ack reveived, removing 010e00130b07600d00022501FF25433c from dongle sendstack
2019.01.03 09:13:06.068 5: ZWAVE: dispatch 001343000002
2019.01.03 09:13:06.069 4: CMD:ZW_SEND_DATA ID:00 ARG:0002 CB:43
2019.01.03 09:13:06.069 4: ZWAVE transmit OK for CB 43, target FL_AB_RM
2019.01.03 09:13:08.076 4: ZWDongle_Read ZWAVE: rcvd 0004000b032503ff (request APPLICATION_COMMAND_HANDLER), sending ACK
2019.01.03 09:13:08.076 5: SW: 06
2019.01.03 09:13:08.079 5: ZWAVE: dispatch 0004000b032503ff
2019.01.03 09:13:08.080 4: CMD:APPLICATION_COMMAND_HANDLER ID:0b ARG:032503ff CB:00
2019.01.03 09:13:19.454 4: ZWDongle_Read ZWAVE: rcvd 0004002503300300 (request APPLICATION_COMMAND_HANDLER), sending ACK
2019.01.03 09:13:19.455 5: SW: 06
2019.01.03 09:13:19.457 5: ZWAVE: dispatch 0004002503300300
2019.01.03 09:13:19.458 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:03300300 CB:00
2019.01.03 09:13:19.703 4: ZWDongle_Read ZWAVE: rcvd 0004002503200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2019.01.03 09:13:19.703 5: SW: 06
2019.01.03 09:13:19.705 5: ZWAVE: dispatch 0004002503200100
2019.01.03 09:13:19.706 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:03200100 CB:00
2019.01.03 09:13:19.714 4: ZWDongle_Read ZWAVE: rcvd 0004002507600d0101200100 (request APPLICATION_COMMAND_HANDLER), sending ACK
2019.01.03 09:13:19.715 5: SW: 06
2019.01.03 09:13:19.717 5: ZWAVE: dispatch 0004002507600d0101200100
2019.01.03 09:13:19.718 4: CMD:APPLICATION_COMMAND_HANDLER ID:25 ARG:07600d0101200100 CB:00

Was mich am stärksten irritiert, sind die Zeitstempel und damit die Reihenfolge.
Im Eventlog steht:

Code Auswählen Erweitern


2019-01-03 09:13:05.544 MQTT MosquittoHA publish /SmartHome/FL/GrossesLicht/state ein
2019-01-03 09:13:05.554 ZWave FL_SK_D1 ein
2019-01-03 09:13:05.771 MQTT MosquittoHA publish /SmartHome/FL/KleinesLicht/state ein
2019-01-03 09:13:05.781 ZWave FL_SK_D2 ein
2019-01-03 09:13:05.819 ZWave FL_DS_SM 1
2019-01-03 09:13:05.819 ZWave FL_DS_SM reportedState: 1
2019-01-03 09:13:05.979 ZWave FL_DS_BS basicSet: 255

Die Schalter (ZWave FL_SK_D1 ein, ZWave FL_SK_D2 ein) werden betätigt, bevor der Sensor das Ereignis (ZWave FL_DS_SM 1) meldet ? ? ?
Um jeden Zweifel auszuräumen, habe ich die MQTT-Meldungen abgestellt; es bleibt bei der gleichen 'no ACK'-Meldung und der "falschen" Reihenfolge !
Aus dem Logfile ist es aber klar zu erkennen, dass die Schalter von der Perl-Routine geschaltet werden; 'FlurBeleuchtung... ' kommt von dieser.

Code Auswählen Erweitern


2019.01.03 09:13:05.331 1: FlurBeleuchtung mit 1 started
2019.01.03 09:13:05.338 3: ZWave set FL_SK_D1 on
2019.01.03 09:13:05.339 5: ZWDongle_Write 00130b07600d00012501FF2542 (ed70b42b)
2019.01.03 09:13:05.341 5: SW: 010e00130b07600d00012501FF25423e
2019.01.03 09:13:05.571 3: ZWave set FL_SK_D2 on
2019.01.03 09:13:05.795 1: FlurBeleuchtung finished

Ich habe bisher noch nicht die richtigen Dokumente gefunden, um die interne Darstellung der Befehlsstrings u. a. zu entschlüsseln; für einen Tipp wäre ich sehr dankbar.
Und noch ein Kuriosum: ich habe einmal den FHEM-Befehl in der Perl-Routine aufgeteilt in zwei separate Befehle und dazwischen ein 5 Sekunden-'sleep(5)' eingefügt. Trotzdem werden beide Lampen gleichzeitig geschaltet !!?? Strukturen mit diesen Aktoren gibt es nicht !
Da ich noch einen zweiten, gleichartigen Sensor in einem anderen Zimmer habe, habe ich das 'notify' auf den anderen Sensor umgelegt und die selben und auch andere elektrischen Lampen in Abhängigkeit von den dortigen Bewegungen geschaltet: kein Unterschied; insbesondere auch die gleiche Fehlermeldung (natürlich ist bei der Fehlermeldung dann die Knotennummer eine andere, wenn ein anderer Schalter verwendet wurde). Zu diesem Schalter wären allerdings die Ausbreitungsverhältnisse schwieriger (größere Entfernung und eine Zimmerecke dazwischen). In anderen Zusammenhängen reagiert dieser Schalter ohne Fehler !
Wie gesagt: es funktioniert immer wie gewollt, nur die Fehlermeldung irritiert mich.
Schönen Abend und Danke im Voraus für Hinweise.
Peter
P.S.: Bei Bedarf kann ich die 'list'-Ausgaben der Geräte nachliefern.

[rudolfkoenig]

Die Schalter (ZWave FL_SK_D1 ein, ZWave FL_SK_D2 ein) werden betätigt, bevor der Sensor das Ereignis (ZWave FL_DS_SM 1) meldet ? ? ?

Ist ein unerwuenschter Seiteneffekt der notify-Logik in FHEM: damit der Event-Monitor "bereicherte" Events meldet (wie z.Bsp. dewpoint/average/etc das tun), setzt er NTFY_ORDER auf einem moeglichst grossen Wert, damit er als Letztes benachrichtigt wird. Da alles rekursiv laeuft, werden die vom "urspruenglichen" Event ausgeloesten "Sekundaer"-Events im Event-Monitor vorher gemeldet. Oder im Ablauf:

Code Auswählen Erweitern


Event 1
  Notify wird fuer Event 1 benachrichtigt, sie generiert Event 2
    Notify wird fuer Event 2 benachrichtigt
    ...
    FHEMWEB wird fuer Event 2 benachrichtigt
  FHEMWEB wird fuer Event 1 benachrichtigt

Ich habe bisher noch nicht die richtigen Dokumente gefunden, um die interne Darstellung der Befehlsstrings u. a. zu entschlüsseln; für einen Tipp wäre ich sehr dankbar.

Ich meine fuer die USB-Kommunikation gibt es keins, das haben wir "abgeschaut".
Fuer die Command-Classes (CC) gibt es veroeffentlichte Dokumente, zBsp. SDS13781


Ein Befehl aus deinem Log (bzw. das was FHEM an dem Controller schickt) erklaert,:

Code Auswählen Erweitern

010e00130b07600d00012501FF25423e

01: Richtung FHEM => Controller
0e: Laenge der Daten
00: ??
13: Per Funk Senden (ZW_SEND_DATA)
0b: Adressat (NodeId)

07: Laenge der CC Befehls+Argumente
60 : CC MultiChannel (Dokument s.o.)
0d00: MultiChannel_Send
01: Adressat in MultiChannel: Kanal 1
25: CC SWITCH_BINARY (Dokument s.o.)
01: SET
FF: ON

25: Senden mit Explorer Frames
42: USB-Paket-Id, damit die Antwort des Controllers zugeordnet werden kann
3e: 8 Bit Checksum


[PNinBB]

@rudolfkoenig:
Herzlichen Dank für die Hinweise und Erläuterungen.
Da habe ich ja nun genügend Lektüre !!
Peter