Re: Missing actions/status report when sending multiple requests at once
Posted: 16 Apr 2021 00:20
can you show log just before the first "Could not be delivered"?
Code: Select all
[2021-04-15 21:49:29.572] [D] [zway] RECEIVED: ( 01 1B 00 04 00 15 12 60 0D 02 00 32 02 21 64 00 1F DA 2A 00 57 00 1F DA 08 AE 00 00 26 )
[2021-04-15 21:49:29.572] [D] [zway] SENT ACK
[2021-04-15 21:49:29.572] [D] [zway] SETDATA devices.21.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:29.572] [D] [zway] SETDATA devices.21.instances.2.commandClasses.50.data.0.val = 2087.466064
[2021-04-15 21:49:29.572] [D] [zway] SETDATA devices.21.instances.2.commandClasses.50.data.0.delta = 87 (0x00000057)
[2021-04-15 21:49:29.572] [D] [zway] SETDATA devices.21.instances.2.commandClasses.50.data.0.ratetype = 1 (0x00000001)
[2021-04-15 21:49:29.572] [D] [zway] SETDATA devices.21.instances.2.commandClasses.50.data.0.previous = 2087.431885
[2021-04-15 21:49:29.572] [D] [zway] SETDATA devices.21.instances.2.commandClasses.50.data.0 = Empty
[2021-04-15 21:49:29.575] [I] [core] HK: updated ZWayVDev_zway_21-2-50-0
[2021-04-15 21:49:31.899] [I] [core] --- Scenes_16 performCommand processing: {"0":"on","1":{}}
[2021-04-15 21:49:31.900] [I] [core] --- ZWayVDev_zway_2-0-38 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.901] [I] [zway] Adding job: SwitchMultilevel Set
[2021-04-15 21:49:31.901] [I] [zway] Adding job: SwitchMultilevel Get
[2021-04-15 21:49:31.901] [I] [core] --- ZWayVDev_zway_7-0-38 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.901] [I] [zway] Adding job: SwitchMultilevel Set
[2021-04-15 21:49:31.901] [I] [zway] Adding job: SwitchMultilevel Get
[2021-04-15 21:49:31.901] [I] [core] --- ZWayVDev_zway_14-0-37 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.901] [I] [zway] Adding job: SwitchBinary Set
[2021-04-15 21:49:31.902] [I] [zway] Adding job: SwitchBinary Get
[2021-04-15 21:49:31.902] [I] [core] --- ZWayVDev_zway_15-0-37 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.902] [I] [zway] Adding job: SwitchBinary Set
[2021-04-15 21:49:31.902] [I] [zway] Adding job: SwitchBinary Get
[2021-04-15 21:49:31.902] [I] [core] --- ZWayVDev_zway_18-0-38 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.902] [I] [zway] Adding job: SwitchMultilevel Set
[2021-04-15 21:49:31.902] [I] [zway] Adding job: SwitchMultilevel Get
[2021-04-15 21:49:31.902] [I] [core] --- ZWayVDev_zway_23-0-38 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.902] [I] [zway] Adding job: SwitchMultilevel Set
[2021-04-15 21:49:31.902] [I] [zway] Adding job: SwitchMultilevel Get
[2021-04-15 21:49:31.902] [I] [core] --- ZWayVDev_zway_33-0-38 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.903] [I] [zway] Adding job: SwitchMultilevel Set
[2021-04-15 21:49:31.903] [I] [zway] Adding job: SwitchMultilevel Get
[2021-04-15 21:49:31.903] [I] [core] --- ZWayVDev_zway_59-0-37 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.903] [I] [zway] Adding job: SwitchBinary Set
[2021-04-15 21:49:31.903] [I] [zway] Adding job: SwitchBinary Get
[2021-04-15 21:49:31.903] [I] [core] --- ZWayVDev_zway_39-0-37 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.903] [I] [zway] Adding job: SwitchBinary Set
[2021-04-15 21:49:31.903] [I] [zway] Adding job: SwitchBinary Get
[2021-04-15 21:49:31.903] [I] [core] --- ZWayVDev_zway_41-0-37 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.903] [I] [zway] Adding job: SwitchBinary Set
[2021-04-15 21:49:31.904] [I] [zway] Adding job: SwitchBinary Get
[2021-04-15 21:49:31.904] [I] [core] --- ZWayVDev_zway_42-0-37 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.904] [I] [zway] Adding job: SwitchBinary Set
[2021-04-15 21:49:31.904] [I] [zway] Adding job: SwitchBinary Get
[2021-04-15 21:49:31.904] [I] [core] --- ZWayVDev_zway_43-0-37 performCommand processing: {"0":"off"}
[2021-04-15 21:49:31.904] [I] [zway] Adding job: SwitchBinary Set
[2021-04-15 21:49:31.904] [I] [zway] Adding job: SwitchBinary Get
[2021-04-15 21:49:31.906] [I] [core] Notification: device-info (device-OnOff): {"dev":"All Lights OFF Test","l":"on","location":0,"customIcon":false}
[2021-04-15 21:49:31.907] [I] [core] HK: updated Scenes_16
[2021-04-15 21:49:31.909] [D] [zway] SENDING (cb 0xa0): ( 01 0B 00 13 02 04 26 01 00 FF 25 A0 BC )
[2021-04-15 21:49:31.911] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:31.920] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-04-15 21:49:31.920] [D] [zway] SENT ACK
[2021-04-15 21:49:31.920] [D] [zway] Delivered to Z-Wave stack
[2021-04-15 21:49:31.947] [D] [zway] RECEIVED: ( 01 18 00 13 A0 00 00 02 00 B5 7F 7F 7F 7F 01 01 03 00 00 00 00 02 01 00 00 E3 )
[2021-04-15 21:49:31.947] [D] [zway] SENT ACK
[2021-04-15 21:49:31.947] [I] [zway] Job 0x13 (SwitchMultilevel Set): Delivered
[2021-04-15 21:49:31.947] [D] [zway] SendData Response with callback 0xa0 received: received by recipient
[2021-04-15 21:49:31.947] [D] [zway] SETDATA devices.2.data.lastSendInternal = **********
[2021-04-15 21:49:31.947] [D] [zway] SETDATA devices.2.data.lastSend = 2652443 (0x0028791b)
[2021-04-15 21:49:31.947] [D] [zway] Job 0x13 (SwitchMultilevel Set): success
[2021-04-15 21:49:31.947] [I] [zway] Removing job: SwitchMultilevel Set
[2021-04-15 21:49:31.948] [D] [zway] SENDING (cb 0xa1): ( 01 0B 00 13 07 04 26 01 00 FF 25 A1 B8 )
[2021-04-15 21:49:31.949] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:31.958] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-04-15 21:49:31.958] [D] [zway] SENT ACK
[2021-04-15 21:49:31.958] [D] [zway] Delivered to Z-Wave stack
[2021-04-15 21:49:32.007] [D] [zway] RECEIVED: ( 01 18 00 13 A1 00 00 05 01 B6 7F 7F 7F 7F 01 01 03 35 00 00 00 02 01 00 00 D2 )
[2021-04-15 21:49:32.007] [D] [zway] SENT ACK
[2021-04-15 21:49:32.007] [I] [zway] Job 0x13 (SwitchMultilevel Set): Delivered
[2021-04-15 21:49:32.008] [D] [zway] SendData Response with callback 0xa1 received: received by recipient
[2021-04-15 21:49:32.008] [D] [zway] SETDATA devices.7.data.lastSendInternal = **********
[2021-04-15 21:49:32.008] [D] [zway] SETDATA devices.7.data.lastSend = 2652450 (0x00287922)
[2021-04-15 21:49:32.008] [D] [zway] Job 0x13 (SwitchMultilevel Set): success
[2021-04-15 21:49:32.008] [I] [zway] Removing job: SwitchMultilevel Set
[2021-04-15 21:49:32.008] [D] [zway] SENDING (cb 0xa2): ( 01 09 00 13 02 02 26 02 25 A2 46 )
[2021-04-15 21:49:32.015] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:32.018] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-04-15 21:49:32.018] [D] [zway] SENT ACK
[2021-04-15 21:49:32.018] [D] [zway] Delivered to Z-Wave stack
[2021-04-15 21:49:32.046] [D] [zway] RECEIVED: ( 01 18 00 13 A2 00 00 02 00 B5 7F 7F 7F 7F 01 01 03 00 00 00 00 02 01 00 00 E1 )
[2021-04-15 21:49:32.046] [D] [zway] SENT ACK
[2021-04-15 21:49:32.046] [I] [zway] Job 0x13 (SwitchMultilevel Get): Delivered
[2021-04-15 21:49:32.046] [D] [zway] SendData Response with callback 0xa2 received: received by recipient
[2021-04-15 21:49:32.047] [D] [zway] SETDATA devices.2.data.lastSendInternal = **********
[2021-04-15 21:49:32.047] [D] [zway] SETDATA devices.2.data.lastSend = 2652455 (0x00287927)
[2021-04-15 21:49:32.047] [D] [zway] Job 0x13 (SwitchMultilevel Get): success
[2021-04-15 21:49:32.047] [I] [zway] Waiting for job reply: SwitchMultilevel Get
[2021-04-15 21:49:32.047] [D] [zway] SENDING (cb 0xa3): ( 01 09 00 13 07 02 26 02 25 A3 42 )
[2021-04-15 21:49:32.051] [W] [zway] Received SOF, while awaiting ACK
[2021-04-15 21:49:32.058] [D] [zway] RECEIVED: ( 01 0C 00 04 00 02 03 26 03 30 B5 00 00 56 )
[2021-04-15 21:49:32.058] [D] [zway] SENT ACK
[2021-04-15 21:49:32.058] [D] [zway] SETDATA devices.2.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:32.058] [D] [zway] Received reply on job (SwitchMultilevel Get)
[2021-04-15 21:49:32.058] [D] [zway] SETDATA devices.2.instances.0.commandClasses.38.data.level = 48 (0x00000030)
[2021-04-15 21:49:32.061] [D] [zway] RECEIVED CAN
[2021-04-15 21:49:32.072] [D] [zway] SENDING (cb 0xa4): ( 01 09 00 13 07 02 26 02 25 A4 45 )
[2021-04-15 21:49:32.074] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:32.080] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-04-15 21:49:32.080] [D] [zway] SENT ACK
[2021-04-15 21:49:32.080] [D] [zway] Delivered to Z-Wave stack
[2021-04-15 21:49:32.081] [I] [core] Notification: device-info (device-status): {"dev":"Cooper Dimmer (#2)","l":"48%","location":0}
[2021-04-15 21:49:32.081] [I] [core] HK: updated ZWayVDev_zway_2-0-38
[2021-04-15 21:49:32.200] [D] [zway] RECEIVED: ( 01 18 00 13 A4 00 00 0C 01 B6 7F 7F 7F 7F 01 01 03 35 00 00 00 02 01 00 00 DE )
[2021-04-15 21:49:32.200] [D] [zway] SENT ACK
[2021-04-15 21:49:32.200] [I] [zway] Job 0x13 (SwitchMultilevel Get): Delivered
[2021-04-15 21:49:32.201] [D] [zway] SendData Response with callback 0xa4 received: received by recipient
[2021-04-15 21:49:32.201] [D] [zway] SETDATA devices.7.data.lastSendInternal = **********
[2021-04-15 21:49:32.201] [D] [zway] SETDATA devices.7.data.lastSend = 2652471 (0x00287937)
[2021-04-15 21:49:32.201] [D] [zway] Job 0x13 (SwitchMultilevel Get): success
[2021-04-15 21:49:32.201] [I] [zway] Waiting for job reply: SwitchMultilevel Get
[2021-04-15 21:49:32.201] [D] [zway] SENDING (cb 0xa5): ( 01 0A 00 13 0E 03 25 01 00 25 A5 4F )
[2021-04-15 21:49:32.206] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:32.209] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-04-15 21:49:32.209] [D] [zway] SENT ACK
[2021-04-15 21:49:32.209] [D] [zway] Delivered to Z-Wave stack
[2021-04-15 21:49:32.387] [D] [zway] RECEIVED: ( 01 0C 00 04 10 07 03 26 03 45 AA 00 00 29 )
[2021-04-15 21:49:32.387] [D] [zway] SENT ACK
[2021-04-15 21:49:32.388] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:32.388] [D] [zway] Received reply on job (SwitchMultilevel Get)
[2021-04-15 21:49:32.388] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 69 (0x00000045)
[2021-04-15 21:49:32.393] [I] [core] Notification: device-info (device-status): {"dev":"Cooper Dimmer (#7)","l":"69%","location":0}
[2021-04-15 21:49:32.393] [I] [core] HK: updated ZWayVDev_zway_7-0-38
[2021-04-15 21:49:32.449] [D] [zway] RECEIVED: ( 01 0C 00 04 10 07 03 26 03 45 AE 00 00 2D )
[2021-04-15 21:49:32.450] [D] [zway] SENT ACK
[2021-04-15 21:49:32.450] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:32.450] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 69 (0x00000045)
[2021-04-15 21:49:32.453] [I] [core] HK: updated ZWayVDev_zway_7-0-38
[2021-04-15 21:49:32.476] [D] [zway] RECEIVED: ( 01 0C 00 04 10 07 03 26 03 45 BC 00 00 3F )
[2021-04-15 21:49:32.476] [D] [zway] SENT ACK
[2021-04-15 21:49:32.476] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:32.476] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 69 (0x00000045)
[2021-04-15 21:49:32.483] [I] [core] HK: updated ZWayVDev_zway_7-0-38
[2021-04-15 21:49:32.557] [D] [zway] RECEIVED: ( 01 0C 00 04 10 07 03 26 03 45 AA 00 00 29 )
[2021-04-15 21:49:32.557] [D] [zway] SENT ACK
[2021-04-15 21:49:32.558] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:32.558] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 69 (0x00000045)
[2021-04-15 21:49:32.562] [I] [core] HK: updated ZWayVDev_zway_7-0-38
[2021-04-15 21:49:32.568] [D] [zway] RECEIVED: ( 01 0C 00 04 10 07 03 26 03 45 A8 00 00 2B )
[2021-04-15 21:49:32.568] [D] [zway] SENT ACK
[2021-04-15 21:49:32.568] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:32.568] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 69 (0x00000045)
[2021-04-15 21:49:32.592] [I] [core] HK: updated ZWayVDev_zway_7-0-38
[2021-04-15 21:49:32.759] [D] [zway] RECEIVED: ( 01 18 00 13 A5 00 00 37 01 AD 7F 7F 7F 7F 01 01 03 37 00 00 00 01 03 00 00 FC )
[2021-04-15 21:49:32.759] [D] [zway] SENT ACK
[2021-04-15 21:49:32.759] [I] [zway] Job 0x13 (SwitchBinary Set): Delivered
[2021-04-15 21:49:32.759] [D] [zway] SendData Response with callback 0xa5 received: received by recipient
[2021-04-15 21:49:32.759] [D] [zway] SETDATA devices.14.data.lastSendInternal = **********
[2021-04-15 21:49:32.759] [D] [zway] SETDATA devices.14.data.lastSend = 2652530 (0x00287972)
[2021-04-15 21:49:32.759] [D] [zway] Job 0x13 (SwitchBinary Set): success
[2021-04-15 21:49:32.760] [I] [zway] Removing job: SwitchBinary Set
[2021-04-15 21:49:32.760] [D] [zway] SENDING (cb 0xa6): ( 01 0A 00 13 0F 03 25 01 00 25 A6 4D )
[2021-04-15 21:49:32.768] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:32.770] [D] [zway] RECEIVED: ( 01 04 01 13 00 E9 )
[2021-04-15 21:49:32.771] [D] [zway] SENT ACK
[2021-04-15 21:49:32.771] [I] [zway] Job 0x13 (SwitchBinary Set): Could not be delivered to Z-Wave stack
[2021-04-15 21:49:32.771] [D] [zway] SENDING (cb 0xa7): ( 01 0A 00 13 0F 03 25 01 00 25 A7 4C )
[2021-04-15 21:49:32.779] [W] [zway] Received SOF, while awaiting ACK
[2021-04-15 21:49:32.779] [D] [zway] RECEIVED: ( 01 0C 00 04 10 07 03 26 03 45 C3 00 00 40 )
[2021-04-15 21:49:32.779] [D] [zway] SENT ACK
[2021-04-15 21:49:32.780] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:32.780] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 69 (0x00000045)
[2021-04-15 21:49:32.781] [D] [zway] RECEIVED CAN
[2021-04-15 21:49:32.787] [I] [core] HK: updated ZWayVDev_zway_7-0-38
[2021-04-15 21:49:32.792] [D] [zway] SENDING (cb 0xa8): ( 01 09 00 13 0E 02 25 02 25 A8 43 )
[2021-04-15 21:49:32.793] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:32.802] [D] [zway] RECEIVED: ( 01 04 01 13 00 E9 )
[2021-04-15 21:49:32.802] [D] [zway] SENT ACK
[2021-04-15 21:49:32.802] [I] [zway] Job 0x13 (SwitchBinary Get): Could not be delivered to Z-Wave stack
[2021-04-15 21:49:32.802] [D] [zway] SENDING (cb 0xa9): ( 01 09 00 13 0E 02 25 02 25 A9 42 )
[2021-04-15 21:49:32.805] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:32.805] [D] [zway] RECEIVED: ( 01 04 01 13 00 E9 )
[2021-04-15 21:49:32.805] [D] [zway] SENT ACK
[2021-04-15 21:49:32.805] [I] [zway] Job 0x13 (SwitchBinary Get): Could not be delivered to Z-Wave stack
[2021-04-15 21:49:32.805] [D] [zway] SENDING (cb 0xaa): ( 01 09 00 13 0E 02 25 02 25 AA 41 )
[2021-04-15 21:49:32.812] [D] [zway] RECEIVED ACK
[2021-04-15 21:49:32.812] [D] [zway] RECEIVED: ( 01 04 01 13 00 E9 )
[2021-04-15 21:49:32.812] [D] [zway] SENT ACK
[2021-04-15 21:49:32.812] [I] [zway] Job 0x13 (SwitchBinary Get): Could not be delivered to Z-Wave stack
[2021-04-15 21:49:32.812] [I] [zway] Job 0x13 (SwitchBinary Get): Removing job due to too much retransmitions
[2021-04-15 21:49:32.813] [D] [zway] Job 0x13 (SwitchBinary Get): fail
[2021-04-15 21:49:32.813] [I] [zway] Waiting for job reply: SwitchBinary Get
[2021-04-15 21:49:32.813] [D] [zway] SENDING (cb 0xab): ( 01 0A 00 13 0F 03 25 01 00 25 AB 40 )
[2021-04-15 21:49:32.816] [W] [zway] Received SOF, while awaiting ACK
[2021-04-15 21:49:32.823] [D] [zway] RECEIVED: ( 01 0C 00 04 10 07 03 26 03 45 BB 00 00 38 )
[2021-04-15 21:49:32.823] [D] [zway] SENT ACK
[2021-04-15 21:49:32.824] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-04-15 21:49:32.824] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 69 (0x00000045)
[2021-04-15 21:49:32.827] [D] [zway] RECEIVED CAN
I do have Zniffer somewhere ... I'll try to find it and share the results...PoltoS wrote: ↑18 Apr 2021 02:35I have such voice commands issuing about 15 on/off packets. In the past (older SDK) we experienced this bug, but not anymore. Do you have a Zniffer to see what the chip is actually sending when it can not accept the packet for delivery?
Another thing we can do is to pause the Z-Way queue on such "Could not be delivered" to let the Z-Wave SDK relax a bit. May be this will help. We will do that in next release and let you tests.
If I get a 700 series z-wave dongle from sigma can I use it with z-way ? I believe I tried this in the past but it did not work.PoltoS wrote: ↑19 Apr 2021 02:00Laughing on the last paragraph No, we will not let Z-Way become as buggy We have added this pausing and will try to reproduce the "Could not be delivered" to see how it works in real world. And of course we will not release it if it makes Z-Way worse!
Mix of different chips is certainly the reason. Thanks for sharing this founding! Note that 300 chips vs 500 and 700 chips uses 9.6 and 40 kbps, while modern devices do use additional 100 kbps channel. So the routing is also different (other routes via 500/700 devices only). This might affect the state machine somehow.
I now don't see those "Could not be delivered" since I'm on 7th gen RaZberry (pre-production sample, should be available late May). But soon will change back to the old 5th gen and check again.