Stop roller shutter does not work, v3.2.2

[sek]

Hi,

I'm currently switching from v2.3.8 (Raspberry 2, Jessie) to v3.2.2 (Raspberry 4, Bullseye).
Both systems are up and running.

I did move two roller shutter devices from the old to the new platform.

On the new platform the up, down and percentage do work fine.
But the "stop" button does not work.

I did try to re-include the devices with "Secure" and "Unsecure".
The problem remains.

Below I added a part of the z-way-server.log.

It says
"Job is already marked as waiting for reply, Supervision overrides it - check encapsulated packet not to be a Get"
I am not sure what this means.

Somebody any idea ?

Regards, sek.


Z-way-server.log, v3.2.2

[2021-12-23 14:57:09.830] [core] --- ZWayVDev_zway_3-0-38 performCommand processing: {"0":"stop","1":{}}
[2021-12-23 14:57:09.831] [W] [zway] wrap 0xb0a2bd48
[2021-12-23 14:57:09.831] [W] [zway] success callback 0xb1cfd9fc
[2021-12-23 14:57:09.831] [W] [zway] failure callback 0xb1cfd9f8
[2021-12-23 14:57:09.831] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3 = Empty
[2021-12-23 14:57:09.831] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.status = Empty
[2021-12-23 14:57:09.831] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.duration = Empty
[2021-12-23 14:57:09.831] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.moreStatusUpdates = Empty
[2021-12-23 14:57:09.832] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.lastEvent = Empty
[2021-12-23 14:57:09.832] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.status = 255 (0x000000ff)
[2021-12-23 14:57:09.832] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.duration = 0 (0x00000000)
[2021-12-23 14:57:09.832] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.moreStatusUpdates = False
[2021-12-23 14:57:09.832] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.lastEvent = 211418 (0x000339da)
[2021-12-23 14:57:09.832] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3 = Empty
[2021-12-23 14:57:09.832] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.lastSession = 3 (0x00000003)
[2021-12-23 14:57:09.832] [zway] Using security scheme S2 Access
[2021-12-23 14:57:09.832] [zway] Adding job: SwitchMultilevel Stop Level Change to node 3
[2021-12-23 14:57:09.833] [C] [zway] Job is already marked as waiting for reply, Supervision overrides it - check encapsulated packet not to be a Get
[2021-12-23 14:57:09.834] [zway] Adding job: Security S2 Encapsulation (S2 Access), SwitchMultilevel Stop Level Change to node 3
[2021-12-23 14:57:09.844] [D] [zway] SENDING (cb 0x07): ( 01 19 00 13 03 12 9F 03 5F 00 4B EC BB 04 24 80 5F 79 9B 12 B2 B4 59 A8 25 07 E1 )
[2021-12-23 14:57:09.844] [D] [zway] Secure payload: ( 6C 01 83 02 26 05 )
[2021-12-23 14:57:09.847] [D] [zway] RECEIVED ACK
[2021-12-23 14:57:09.851] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-12-23 14:57:09.852] [D] [zway] SENT ACK
[2021-12-23 14:57:09.852] [zway] Job 0x13 (Security S2 Encapsulation (S2 Access), SwitchMultilevel Stop Level Change to node 3): Response received - transfered to encapsulated jobs
[2021-12-23 14:57:09.852] [D] [zway] Delivered to Z-Wave stack
[2021-12-23 14:57:09.852] [D] [zway] Delivered to Z-Wave stack
[2021-12-23 14:57:09.871] [D] [zway] RECEIVED: ( 01 18 00 13 07 00 00 02 00 D4 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 24 )
[2021-12-23 14:57:09.871] [D] [zway] SENT ACK
[2021-12-23 14:57:09.871] [zway] Job 0x13 (Security S2 Encapsulation (S2 Access), SwitchMultilevel Stop Level Change to node 3): Callback received - transfered to encapsulated jobs
[2021-12-23 14:57:09.871] [zway] Job 0x13 (SwitchMultilevel Stop Level Change to node 3): Delivered
[2021-12-23 14:57:09.871] [D] [zway] SendData Response with callback 0x07 received: received by recipient
[2021-12-23 14:57:09.871] [D] [zway] Job 0x13 (SwitchMultilevel Stop Level Change to node 3): success
[2021-12-23 14:57:09.872] [W] [zway] wrap success callback 0xb0a2bd48
[2021-12-23 14:57:09.872] [W] [zway] success callback (nil)
[2021-12-23 14:57:09.872] [zway] Waiting for job reply: SwitchMultilevel Stop Level Change from node 3
[2021-12-23 14:57:09.872] [zway] Job 0x13 (Security S2 Encapsulation (S2 Access), SwitchMultilevel Stop Level Change to node 3): Delivered
[2021-12-23 14:57:09.872] [D] [zway] SendData Response with callback 0x07 received: received by recipient
[2021-12-23 14:57:09.872] [D] [zway] SETDATA devices.3.data.lastSendInternal = **********
[2021-12-23 14:57:09.872] [D] [zway] SETDATA devices.3.data.lastSend = 211421 (0x000339dd)
[2021-12-23 14:57:09.872] [D] [zway] Job 0x13 (Security S2 Encapsulation (S2 Access), SwitchMultilevel Stop Level Change to node 3): success
[2021-12-23 14:57:09.872] [zway] Removing job: Security S2 Encapsulation (S2 Access), SwitchMultilevel Stop Level Change to node 3
[2021-12-23 14:57:09.900] [D] [zway] RECEIVED: ( 01 1A 00 04 00 03 11 9F 03 D7 00 47 78 90 82 AB 4D 01 C0 4A 0B 60 13 EF D4 00 00 BB )
[2021-12-23 14:57:09.900] [D] [zway] SENT ACK
[2021-12-23 14:57:09.900] [D] [zway] SETDATA devices.3.data.lastReceived = 0 (0x00000000)
[2021-12-23 14:57:09.900] [I] [zway] Node 3:0 CC SecurityS2: passing S2 Access decrypted packet to application level: [ 6c 02 03 ff 00 ]
[2021-12-23 14:57:09.900] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.status = 255 (0x000000ff)
[2021-12-23 14:57:09.901] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.duration = 0 (0x00000000)
[2021-12-23 14:57:09.901] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.moreStatusUpdates = False
[2021-12-23 14:57:09.901] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3.lastEvent = 211423 (0x000339df)
[2021-12-23 14:57:09.901] [D] [zway] SETDATA devices.3.instances.0.commandClasses.108.data.3 = Empty
[2021-12-23 14:57:09.901] [D] [zway] Received reply on job (SwitchMultilevel Stop Level Change to node 3)
[2021-12-23 14:57:09.901] [I] [zway] Node 3:0 CC Supervision: Setter packet was confirmed: SwitchMultilevel Stop Level Change
[2021-12-23 14:57:11.885] [D] [zway] Node 3:0 CC SwitchMultilevel: Unsolicited report not received, sending Get
[2021-12-23 14:57:11.885] [I] [zway] Using security scheme S2 Access
[2021-12-23 14:57:11.885] [I] [zway] Adding job: SwitchMultilevel Get to node 3
[2021-12-23 14:57:11.896] [I] [zway] Adding job: Security S2 Encapsulation (S2 Access), SwitchMultilevel Get to node 3
[2021-12-23 14:57:11.906] [D] [zway] SENDING (cb 0x08): ( 01 15 00 13 03 0E 9F 03 60 00 B0 6B 34 30 F2 FA FD A9 2F 2A 25 08 A3 )
[2021-12-23 14:57:11.906] [D] [zway] Secure payload: ( 26 02 )
[2021-12-23 14:57:11.909] [D] [zway] RECEIVED ACK
[2021-12-23 14:57:11.913] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-12-23 14:57:11.913] [D] [zway] SENT ACK
[2021-12-23 14:57:11.913] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Access), SwitchMultilevel Get to node 3): Response received - transfered to encapsulated jobs
[2021-12-23 14:57:11.913] [D] [zway] Delivered to Z-Wave stack
[2021-12-23 14:57:11.913] [D] [zway] Delivered to Z-Wave stack
[2021-12-23 14:57:11.933] [D] [zway] RECEIVED: ( 01 18 00 13 08 00 00 02 00 D5 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 2A )
[2021-12-23 14:57:11.933] [D] [zway] SENT ACK
[2021-12-23 14:57:11.933] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Access), SwitchMultilevel Get to node 3): Callback received - transfered to encapsulated jobs
[2021-12-23 14:57:11.933] [I] [zway] Job 0x13 (SwitchMultilevel Get to node 3): Delivered
[2021-12-23 14:57:11.933] [D] [zway] SendData Response with callback 0x08 received: received by recipient
[2021-12-23 14:57:11.933] [D] [zway] Job 0x13 (SwitchMultilevel Get to node 3): success
[2021-12-23 14:57:11.933] [I] [zway] Waiting for job reply: SwitchMultilevel Get from node 3
[2021-12-23 14:57:11.933] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Access), SwitchMultilevel Get to node 3): Delivered
[2021-12-23 14:57:11.933] [D] [zway] SendData Response with callback 0x08 received: received by recipient
[2021-12-23 14:57:11.934] [D] [zway] SETDATA devices.3.data.lastSendInternal = **********
[2021-12-23 14:57:11.934] [D] [zway] SETDATA devices.3.data.lastSend = 211622 (0x00033aa6)
[2021-12-23 14:57:11.934] [D] [zway] Job 0x13 (Security S2 Encapsulation (S2 Access), SwitchMultilevel Get to node 3): success
[2021-12-23 14:57:11.934] [I] [zway] Removing job: Security S2 Encapsulation (S2 Access), SwitchMultilevel Get to node 3
[2021-12-23 14:57:11.960] [D] [zway] RECEIVED: ( 01 1A 00 04 00 03 11 9F 03 D8 00 62 13 5C 41 50 4E 61 3C 94 91 E4 A9 AB D5 00 00 AE )
[2021-12-23 14:57:11.961] [D] [zway] SENT ACK
[2021-12-23 14:57:11.961] [D] [zway] SETDATA devices.3.data.lastReceived = 0 (0x00000000)
[2021-12-23 14:57:11.961] [I] [zway] Node 3:0 CC SecurityS2: passing S2 Access decrypted packet to application level: [ 26 03 5f 5f 00 ]
[2021-12-23 14:57:11.961] [D] [zway] Received reply on job (SwitchMultilevel Get to node 3)
[2021-12-23 14:57:11.961] [D] [zway] SETDATA devices.3.instances.0.commandClasses.38.data.level = 95 (0x0000005f)

------

Z-way-server.log, v2.3.8 (not secure)

[2021-12-23 15:19:02.864] [I] [zway] Adding job: SwitchMultilevel Stop Level Change
[2021-12-23 15:19:02.865] [I] [zway] Adding job: SwitchMultilevel Get
[2021-12-23 15:19:02.870] [D] [zway] SENDING (cb 0x22): ( 01 09 00 13 0D 02 26 05 25 22 CE )
[2021-12-23 15:19:02.872] [D] [zway] RECEIVED ACK
[2021-12-23 15:19:02.876] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-12-23 15:19:02.876] [D] [zway] SENT ACK
[2021-12-23 15:19:02.877] [D] [zway] Delivered to Z-Wave stack
[2021-12-23 15:19:02.921] [D] [zway] RECEIVED: ( 01 07 00 13 22 00 00 05 CC )
[2021-12-23 15:19:02.921] [D] [zway] SENT ACK
[2021-12-23 15:19:02.921] [I] [zway] Job 0x13 (SwitchMultilevel Stop Level Change): Delivered
[2021-12-23 15:19:02.922] [D] [zway] SendData Response with callback 0x22 received: received by recipient
[2021-12-23 15:19:02.922] [D] [zway] SETDATA devices.13.data.lastSendInternal = **********
[2021-12-23 15:19:02.922] [D] [zway] SETDATA devices.13.data.lastSend = 1368383762 (0x518fe112)
[2021-12-23 15:19:02.922] [D] [zway] Job 0x13 (SwitchMultilevel Stop Level Change): success
[2021-12-23 15:19:02.922] [I] [zway] Removing job: SwitchMultilevel Stop Level Change
[2021-12-23 15:19:02.962] [D] [zway] SENDING (cb 0x23): ( 01 09 00 13 0D 02 26 02 25 23 C8 )
[2021-12-23 15:19:02.964] [D] [zway] RECEIVED ACK
[2021-12-23 15:19:02.968] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-12-23 15:19:02.969] [D] [zway] SENT ACK
[2021-12-23 15:19:02.969] [D] [zway] Delivered to Z-Wave stack
[2021-12-23 15:19:02.993] [D] [zway] RECEIVED: ( 01 07 00 13 23 00 00 02 CA )
[2021-12-23 15:19:02.993] [D] [zway] SENT ACK
[2021-12-23 15:19:02.993] [I] [zway] Job 0x13 (SwitchMultilevel Get): Delivered
[2021-12-23 15:19:02.993] [D] [zway] SendData Response with callback 0x23 received: received by recipient
[2021-12-23 15:19:02.994] [D] [zway] SETDATA devices.13.data.lastSendInternal = **********
[2021-12-23 15:19:02.994] [D] [zway] SETDATA devices.13.data.lastSend = 1368383769 (0x518fe119)
[2021-12-23 15:19:02.994] [D] [zway] Job 0x13 (SwitchMultilevel Get): success
[2021-12-23 15:19:02.994] [I] [zway] Waiting for job reply: SwitchMultilevel Get
[2021-12-23 15:19:03.004] [D] [zway] RECEIVED: ( 01 0B 00 04 00 0D 05 26 03 00 00 00 DD )
[2021-12-23 15:19:03.005] [D] [zway] SENT ACK
[2021-12-23 15:19:03.005] [D] [zway] SETDATA devices.13.data.lastReceived = 0 (0x00000000)
[2021-12-23 15:19:03.005] [D] [zway] Received reply on job (SwitchMultilevel Get)
[2021-12-23 15:19:03.005] [D] [zway] SETDATA devices.13.instances.0.commandClasses.38.data.level = 0 (0x00000000)
[2021-12-23 15:19:05.166] [D] [zway] Job 0x13: deleted from queue

[seattleneil]

The log also shows the following:
[2021-12-23 14:57:09.831] [W] [zway] failure callback 0xb1cfd9f8
Your log does not show what function was associated with the callback, but the callback failure could be part of the problem.

As a suggestion, unless you absolutely need encryption, why don't you force an unsecure inclusion? That should provide similar log results to the v2.3.8 log file.

Also, you can use the Expert UI to better understand communication issues with the device by looking at Network->Timing Info and Analytics->Packets info. Ideally, packet communication should be fast (timing < 10) and efficient (100% delivered without rerouting).

[sek]

Thank you for your quick response.

I did an insecure including.
To have a more clean log I changed the noise check from every 30 sec to 5 min.

So I have a part of the log beneath.

1. Timings

I have looked into the timings. I do not see any problems. All within 3 ms.

2. Failure

The failure in the beginning is unclear to me.
As you can see beneath there is no activity in the minute before the "up" button has been pushed.

3. Channel 3 ?

I do not understand the noise check of the channels.
There are 3 to check but only 2 active ?
The logs shows: "Ch#3: not available"
(I use a razberry on top of my raspberry)
Is this a problem ?

4. "stop" delivered after "up" ?

Looking at the log the "stop" is delivered after the "up" has been completed.
The "Supervision" sets a delay of 23 sec.
I think this is the problem,
How to override ?

z-way-server.log:

[2021-12-24 14:36:30.902] [zway] Adding job: Get background noise level
[2021-12-24 14:36:30.912] [D] [zway] SENDING: ( 01 03 00 3B C7 )
[2021-12-24 14:36:30.914] [D] [zway] RECEIVED ACK
[2021-12-24 14:36:30.914] [D] [zway] RECEIVED: ( 01 05 01 3B AB AD C6 )
[2021-12-24 14:36:30.914] [D] [zway] SENT ACK
[2021-12-24 14:36:30.914] [D] [zway] SETDATA controller.data.statistics.backgroundRSSI.channel1 = 171 (0x000000ab)
[2021-12-24 14:36:30.914] [D] [zway] SETDATA controller.data.statistics.backgroundRSSI.channel2 = 173 (0x000000ad)
[2021-12-24 14:36:30.915] [D] [zway] SETDATA controller.data.statistics.backgroundRSSI.channel3 = 127 (0x0000007f)
# Channel 3 not available ?
[2021-12-24 14:36:30.915] [zway] Job 0x3b (Get background noise level): RSSI Ch#1: -83 dBm, Ch#2: -83 dBm, Ch#3: not available
[2021-12-24 14:36:30.915] [D] [zway] Job 0x3b (Get background noise level): success
[2021-12-24 14:36:30.915] [zway] Removing job: Get background noise level
[2021-12-24 14:36:51.057] [D] [zway] Job 0x3b: deleted from queue
# start, pushed button up
[2021-12-24 14:37:58.971] [core] --- ZWayVDev_zway_7-0-38 performCommand processing: {"0":"exact","1":{"level":"99"}}
[2021-12-24 14:37:58.972] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9 = Empty
[2021-12-24 14:37:58.972] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.status = Empty
[2021-12-24 14:37:58.972] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.duration = Empty
[2021-12-24 14:37:58.972] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.moreStatusUpdates = Empty
[2021-12-24 14:37:58.972] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.lastEvent = Empty
[2021-12-24 14:37:58.973] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.status = 255 (0x000000ff)
[2021-12-24 14:37:58.973] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.duration = 0 (0x00000000)
[2021-12-24 14:37:58.973] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.moreStatusUpdates = False
[2021-12-24 14:37:58.973] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.lastEvent = 453293 (0x0006eaad)
[2021-12-24 14:37:58.973] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9 = Empty
[2021-12-24 14:37:58.973] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.lastSession = 9 (0x00000009)
[2021-12-24 14:37:58.973] [zway] Adding job: SwitchMultilevel Set to node 7
[2021-12-24 14:37:58.973] [C] [zway] Job is already marked as waiting for reply, Supervision overrides it - check encapsulated packet not to be a Get
[2021-12-24 14:37:58.979] [D] [zway] SENDING (cb 0x13): ( 01 0F 00 13 07 08 6C 01 89 04 26 01 63 FF 25 13 81 )
[2021-12-24 14:37:58.981] [D] [zway] RECEIVED ACK
[2021-12-24 14:37:58.986] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-12-24 14:37:58.986] [D] [zway] SENT ACK
[2021-12-24 14:37:58.986] [D] [zway] Delivered to Z-Wave stack
[2021-12-24 14:37:59.004] [D] [zway] RECEIVED: ( 01 18 00 13 13 00 00 01 00 DA 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 3D )
[2021-12-24 14:37:59.004] [D] [zway] SENT ACK
[2021-12-24 14:37:59.005] [zway] Job 0x13 (SwitchMultilevel Set to node 7): Delivered
[2021-12-24 14:37:59.005] [D] [zway] SendData Response with callback 0x13 received: received by recipient
[2021-12-24 14:37:59.005] [D] [zway] SETDATA devices.7.data.lastSendInternal = **********
[2021-12-24 14:37:59.006] [D] [zway] SETDATA devices.7.data.lastSend = 453295 (0x0006eaaf)
[2021-12-24 14:37:59.006] [D] [zway] Job 0x13 (SwitchMultilevel Set to node 7): success
[2021-12-24 14:37:59.006] [zway] Waiting for job reply: SwitchMultilevel Set from node 7
[2021-12-24 14:37:59.021] [D] [zway] RECEIVED: ( 01 0E 00 04 00 07 05 6C 02 89 01 17 DA 00 00 DC )
[2021-12-24 14:37:59.021] [D] [zway] SENT ACK
[2021-12-24 14:37:59.022] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-12-24 14:37:59.022] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.status = 1 (0x00000001)
[2021-12-24 14:37:59.022] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.duration = 23 (0x00000017)
[2021-12-24 14:37:59.022] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.moreStatusUpdates = True
[2021-12-24 14:37:59.022] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.lastEvent = 453296 (0x0006eab0)
[2021-12-24 14:37:59.022] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9 = Empty
# A delay is set ?
[2021-12-24 14:37:59.022] [zway] Node 7:0 CC Supervision: Setter packet was accepted for execution, but will take 23 seconds: SwitchMultilevel Set
[2021-12-24 14:37:59.022] [D] [zway] Delaying request job (SwitchMultilevel Set to node 7) by 23 seconds
[2021-12-24 14:37:59.022] [D] [zway] SETDATA devices.7.data.lastSendInternal = **********
# pushed button stop
[2021-12-24 14:38:05.781] [core] --- ZWayVDev_zway_7-0-38 performCommand processing: {"0":"stop","1":{}}
[2021-12-24 14:38:05.782] [W] [zway] wrap 0xb0892158
[2021-12-24 14:38:05.782] [W] [zway] success callback 0xb1bfd9fc
[2021-12-24 14:38:05.782] [W] [zway] failure callback 0xb1bfd9f8
[2021-12-24 14:38:05.782] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10 = Empty
[2021-12-24 14:38:05.782] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.status = Empty
[2021-12-24 14:38:05.782] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.duration = Empty
[2021-12-24 14:38:05.782] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.moreStatusUpdates = Empty
[2021-12-24 14:38:05.782] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.lastEvent = Empty
[2021-12-24 14:38:05.782] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.status = 255 (0x000000ff)
[2021-12-24 14:38:05.783] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.duration = 0 (0x00000000)
[2021-12-24 14:38:05.783] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.moreStatusUpdates = False
[2021-12-24 14:38:05.783] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.lastEvent = 453963 (0x0006ed4b)
[2021-12-24 14:38:05.783] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10 = Empty
[2021-12-24 14:38:05.783] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.lastSession = 10 (0x0000000a)
[2021-12-24 14:38:05.783] [zway] Adding job: SwitchMultilevel Stop Level Change to node 7
[2021-12-24 14:38:05.783] [C] [zway] Job is already marked as waiting for reply, Supervision overrides it - check encapsulated packet not to be a Get
[2021-12-24 14:38:12.631] [D] [zway] RECEIVED: ( 01 18 00 04 00 07 0F 32 02 21 34 00 00 05 83 0E A6 00 00 00 00 00 D7 00 00 37 )
[2021-12-24 14:38:12.632] [D] [zway] SENT ACK
[2021-12-24 14:38:12.632] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-12-24 14:38:12.632] [D] [zway] SETDATA devices.7.instances.0.commandClasses.50.data.2.val = 141.100006
[2021-12-24 14:38:12.632] [D] [zway] SETDATA devices.7.instances.0.commandClasses.50.data.2.delta = 3750 (0x00000ea6)
[2021-12-24 14:38:12.632] [D] [zway] SETDATA devices.7.instances.0.commandClasses.50.data.2.ratetype = 1 (0x00000001)
[2021-12-24 14:38:12.632] [D] [zway] SETDATA devices.7.instances.0.commandClasses.50.data.2.previous = 0.000000
[2021-12-24 14:38:12.632] [D] [zway] SETDATA devices.7.instances.0.commandClasses.50.data.2 = Empty
[2021-12-24 14:38:12.688] [I] [core] [BaseModule-15] Set lastLevel to 141.1000064 for ZWayVDev_zway_7-0-50-2 (was 143.6999936)
[2021-12-24 14:38:22.020] [D] [zway] RECEIVED: ( 01 0E 00 04 00 07 05 6C 02 09 FF 00 D7 00 00 B8 )
[2021-12-24 14:38:22.020] [D] [zway] SENT ACK
[2021-12-24 14:38:22.020] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-12-24 14:38:22.020] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.status = 255 (0x000000ff)
[2021-12-24 14:38:22.020] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.duration = 0 (0x00000000)
[2021-12-24 14:38:22.020] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.moreStatusUpdates = False
[2021-12-24 14:38:22.021] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9.lastEvent = 455567 (0x0006f38f)
[2021-12-24 14:38:22.021] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.9 = Empty
[2021-12-24 14:38:22.021] [D] [zway] Received reply on job (SwitchMultilevel Set to node 7)
[2021-12-24 14:38:22.021] [I] [zway] Node 7:0 CC Supervision: Setter packet was confirmed: SwitchMultilevel Set
[2021-12-24 14:38:22.021] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 99 (0x00000063)
[2021-12-24 14:38:22.026] [I] [core] Notification: device-info (device-status): {"dev":"Werkkamer groot raam","l":"99%","location":1}
[2021-12-24 14:38:22.052] [I] [core] [BaseModule-15] Set lastLevel to 99 for ZWayVDev_zway_7-0-38 (was 0)
[2021-12-24 14:38:22.548] [D] [zway] RECEIVED: ( 01 0E 00 04 00 07 05 26 03 63 63 00 D7 00 00 05 )
[2021-12-24 14:38:22.548] [D] [zway] SENT ACK
[2021-12-24 14:38:22.549] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-12-24 14:38:22.549] [D] [zway] SETDATA devices.7.instances.0.commandClasses.38.data.level = 99 (0x00000063)
[2021-12-24 14:38:23.371] [D] [zway] SENDING (cb 0x14): ( 01 0D 00 13 07 06 6C 01 8A 02 26 05 25 14 17 )
[2021-12-24 14:38:23.373] [D] [zway] RECEIVED ACK
[2021-12-24 14:38:23.377] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2021-12-24 14:38:23.377] [D] [zway] SENT ACK
[2021-12-24 14:38:23.377] [D] [zway] Delivered to Z-Wave stack
[2021-12-24 14:38:23.396] [D] [zway] RECEIVED: ( 01 18 00 13 14 00 00 02 00 D7 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 34 )
[2021-12-24 14:38:23.396] [D] [zway] SENT ACK
# delivered stop after up completed ?
[2021-12-24 14:38:23.396] [I] [zway] Job 0x13 (SwitchMultilevel Stop Level Change to node 7): Delivered
[2021-12-24 14:38:23.397] [D] [zway] SendData Response with callback 0x14 received: received by recipient
[2021-12-24 14:38:23.397] [D] [zway] SETDATA devices.7.data.lastSendInternal = **********
[2021-12-24 14:38:23.397] [D] [zway] SETDATA devices.7.data.lastSend = 455701 (0x0006f415)
[2021-12-24 14:38:23.397] [D] [zway] Job 0x13 (SwitchMultilevel Stop Level Change to node 7): success
[2021-12-24 14:38:23.398] [W] [zway] wrap success callback 0xb0892158
[2021-12-24 14:38:23.398] [W] [zway] success callback (nil)
[2021-12-24 14:38:23.398] [I] [zway] Waiting for job reply: SwitchMultilevel Stop Level Change from node 7
[2021-12-24 14:38:23.413] [D] [zway] RECEIVED: ( 01 0E 00 04 00 07 05 6C 02 0A FF 00 D7 00 00 BB )
[2021-12-24 14:38:23.413] [D] [zway] SENT ACK
[2021-12-24 14:38:23.414] [D] [zway] SETDATA devices.7.data.lastReceived = 0 (0x00000000)
[2021-12-24 14:38:23.414] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.status = 255 (0x000000ff)
[2021-12-24 14:38:23.414] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.duration = 0 (0x00000000)
[2021-12-24 14:38:23.414] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.moreStatusUpdates = False
[2021-12-24 14:38:23.414] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10.lastEvent = 455702 (0x0006f416)
[2021-12-24 14:38:23.415] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.10 = Empty
[2021-12-24 14:38:23.415] [D] [zway] Received reply on job (SwitchMultilevel Stop Level Change to node 7)
[2021-12-24 14:38:23.415] [I] [zway] Node 7:0 CC Supervision: Setter packet was confirmed: SwitchMultilevel Stop Level Change
[2021-12-24 14:38:24.174] [D] [zway] Job 0x13: deleted from queue
[2021-12-24 14:38:25.420] [D] [zway] Node 7:0 CC SwitchMultilevel: Unsolicited report received, skipping Get
[2021-12-24 14:38:25.501] [D] [zway] Job 0x13: deleted from queue
# end
[2021-12-24 14:38:49.090] [D] [zway] RECEIVED: ( 01 24 00 04 00 05 1B 9F 03 E7 00 CE 14 F9 D1 B2 A1 3D 41 E5 F0 C5 F7 F5 4D EB 55 62 7B 28 C3 4D C9 8F BE 00 00 41 )
[2021-12-24 14:38:49.091] [D] [zway] SENT ACK
[2021-12-24 14:38:49.091] [D] [zway] SETDATA devices.5.data.lastReceived = 0 (0x00000000)
[2021-12-24 14:38:49.092] [I] [zway] Node 5:0 CC SecurityS2: passing S2 Access decrypted packet to application level: [ 32 02 21 44 00 00 00 01 0e 10 00 00 00 01 00 ]
[2021-12-24 14:38:49.092] [D] [zway] SETDATA devices.5.instances.0.commandClasses.50.data.0.val = 0.010000
[2021-12-24 14:38:49.093] [D] [zway] SETDATA devices.5.instances.0.commandClasses.50.data.0.delta = 3600 (0x00000e10)
[2021-12-24 14:38:49.093] [D] [zway] SETDATA devices.5.instances.0.commandClasses.50.data.0.ratetype = 1 (0x00000001)
[2021-12-24 14:38:49.094] [D] [zway] SETDATA devices.5.instances.0.commandClasses.50.data.0.previous = 0.010000
[2021-12-24 14:38:49.094] [D] [zway] SETDATA devices.5.instances.0.commandClasses.50.data.0 = Empty

[seattleneil]

It looks like the problem is with Z-Way's logic where it waits until the multilevel switch=99 command is completed before sending the stop command. From what I read in the Z-Wave specification (see: https://sdomembers.z-wavealliance.org/document/dl/652 - CC:006C.01.01.11.00A - A receiving node MUST abort an active operation in favor of a new command with a new Session ID if that new command affects the same resources as the active operation.), Z-Way should have sent the stop command immediately. I'm hoping @PoltoS will provide additional information. In the meantime, you might be able to disable the Supervision logic by marking the Supervision interview as false using the following command (substitute [Z-WAY ADMIN PASSWORD]):

curl -u admin:[Z-WAY ADMIN PASSWORD] --globoff 'http://127.0.0.1:8083/JS/Run/zway.devic ... Done=false'

Everything else looks normal (although it would be nice for Z-Way to not report a problem with channel 3 since it should know there are only 2 channels in the US).

[sek]

Thank you for the response.

I did run

curl -u admin:mysecretpasswd --globoff http: //myip:8083/JS/Run/zway.devices[7].instances[0].Supervision.data.interviewDone=false

in the log I get

[2021-12-25 09:56:36.490] [D] [zway] SETDATA devices.7.instances.0.commandClasses.108.data.interviewDone = False

The results is the same, the "stop" waits for the command to finish:

[2021-12-25 10:02:29.447] [ I ] [zway] Node 7:0 CC Supervision: Setter packet was accepted for execution, but will take 23 seconds: SwitchMultilevel Set
[2021-12-25 10:02:29.447] [D] [zway] Delaying request job (SwitchMultilevel Set to node 7) by 23 seconds

The Expert UI says the interview is not fully done.
See attachement.
The "Supervision" is (still ?) within the "Command Class".

And of course have a nice Christmas !

[seattleneil]

It looks like we're both Xmas geeks

As best as I can tell, Z-Way has a bug in its logic where it improperly waits for the supervised multilevel switch command to complete before issuing another multilevel switch command for the same device. I can understand this makes sense if the second multilevel switch command is another set, but in this case, the second multilevel switch command is a stop (and it doesn't make sense to wait for the stop to be sent). Until the Z-Way bug is fixed, you're probably stuck with needing to do some type of workaround. Hopefully, @PoltoS will add to this thread.

Unfortunately, the simple workaround of changing the interview status for the Supervision command class did not make a difference. I suggest "fixing" the interview status by running the same curl command, but change "false" to "true".

A different workaround involves directly issuing the multilevel switch command using the lower-level SendData function. First, with the shade in the down position, raise the shade up using this command:
curl -u admin:mysecretpasswd --globoff 'http://127.0.0.1:8083/JS/Run/zway.SendD ... ,99,255,37]);'

Note that this command isn't the complete workaround, it mostly verifies the SendData bytes are doing what you want them to do and it also bypasses the supervision logic.

While the shade is moving up, issue a command to stop the level change:
curl -u admin:mysecretpasswd --globoff 'http://127.0.0.1:8083/JS/Run/zway.SendD ... 8,05,37,20]);'

This command is the workaround for stopping the shade.

If the stop command works, then repeat the test by using the UI to lower the shade and then use the UI to start raising the shade. Unlike the first curl raise shade command, the UI-driven messages will include supervision. While the shade is raising, repeat the magic curl stop command. With luck, the stop command will work which means you can modify the JavaScript for the Shade device to emit the SendData bytes.

[PoltoS]

"failure callback 0xb1cfd9f8" is just a debug output (accidentally moved into a release, will be removed in the next one).

"Job is already marked as waiting for reply" is also normal (mystery log output, but don't mind).

In some regions there are 3 channels. This message reports that in yours the third is not available - this is okay.

As for the analysis by @seattleneil, correct, there is a Z-Way issue that we need to fix. We will check how to fix it as it breaks a bit the logic of delayed answers. And indeed, turning off the Supervision is an easy workaround. But the correct line is:

curl -u admin:mysecretpasswd --globoff http: //myip:8083/JS/Run/zway.devices[7].instances[0].Supervision.data.disabled=true

And turn back interviewDone to true.

[sek]

Hi,

Disabling the Supervision solves the problem!

Thank you both, Seattleneil and PoltoS, for your replies.

For everyone a happy new Year !