Built in Z-Wave Shelly Wave Shutter driver perpetually opening/closing state on 2.4.1.154 (with and without JS)

bogus.wojcik · April 5, 2025, 3:47pm

Hello,

Environment: Hubitat C8 Pro, 2.4.1.154, Z-Wave JS, radio firmware updated
Device: Shelly Wave Shutter, S2 Authenticated, latest device firmware

The issue is that the driver does not properly show open and closed states, being perpetually stuck at "opening" and "closing" states.

Z-Wave JS logs:

2025-04-05 17:11:44.815DRIVER all queues idle
2025-04-05 17:11:44.812DRIVER « [RES] [GetBackgroundRSSI] - channel 0: -95 dBm - channel 1: -97 dBm - channel 2: -97 dBm - channel 3: N/A
2025-04-05 17:11:44.810SERIAL » [ACK] (0x06)
2025-04-05 17:11:44.809SERIAL « 0x0107013ba19f9f7f1c (9 bytes)
2025-04-05 17:11:44.807SERIAL « [ACK] (0x06)
2025-04-05 17:11:44.803SERIAL » 0x0103003bc7 (5 bytes)
2025-04-05 17:11:44.797DRIVER one or more queues busy
2025-04-05 17:11:35.984DRIVER « [Node 044] [REQ] [BridgeApplicationCommand] - │ RSSI: -87 dBm - └─[Security2CCMessageEncapsulation] - │ sequence number: 132 - │ security class: S2_Authenticated - └─[MultiChannelCCCommandEncapsulation] - │ source: 1 - │ destination: 0 - └─[MeterCCReport] - meter type: Electric - scale: W - rate type: Consumed - value: 0 - time delta: 0 seconds
2025-04-05 17:11:35.981CNTRLR [Node 044] [~] [Meter] value[66049]: 212.8 => 0 [Endpoint 1]
2025-04-05 17:11:35.979CNTRLR [Node 044] [Meter] value[66049]: metadata updated [Endpoint 1]
2025-04-05 17:11:35.976SERIAL » [ACK] (0x06)
2025-04-05 17:11:35.973SERIAL « 0x012800a800012c1f9f038400379754181e7758b3b1e1fca2a8e0a91114502d58e (42 bytes) - 71c62129a638700a9a8
2025-04-05 17:11:35.463DRIVER « [Node 044] [REQ] [BridgeApplicationCommand] - │ RSSI: -87 dBm - └─[Security2CCMessageEncapsulation] - │ sequence number: 131 - │ security class: S2_Authenticated - └─[MultiChannelCCCommandEncapsulation] - │ source: 1 - │ destination: 0 - └─[MultilevelSwitchCCReport] - current value: 99 - target value: 99 - duration: 0s
2025-04-05 17:11:35.460CNTRLR [Node 044] [~] [Multilevel Switch] currentValue: 0 => 99 [Endpoint 1]
2025-04-05 17:11:35.459CNTRLR [Node 044] [~] [Multilevel Switch] duration: {"value":0,"unit":"s [Endpoint 1] - econds"} => {"value":0,"unit":"seconds"}
2025-04-05 17:11:35.457CNTRLR [Node 044] [~] [Multilevel Switch] targetValue: 0 => 99 [Endpoint 1]
2025-04-05 17:11:35.454SERIAL » [ACK] (0x06)
2025-04-05 17:11:35.450SERIAL « 0x011e00a800012c159f03830027ec6177bd3011b0b7c9a338bbb892206c00a90e (32 bytes)
2025-04-05 17:11:23.170DRIVER all queues idle
2025-04-05 17:11:23.168CNTRLR [Node 044] [~] [Multilevel Switch] currentValue: 88 => 11 [Endpoint 0]
2025-04-05 17:11:23.166CNTRLR [Node 044] [~] [Multilevel Switch] duration: {"value":2,"unit":"s [Endpoint 0] - econds"} => {"value":2,"unit":"seconds"}
2025-04-05 17:11:23.164CNTRLR [Node 044] [~] [Multilevel Switch] targetValue: 255 => 99 [Endpoint 0]
2025-04-05 17:11:23.162SERIAL » [ACK] (0x06)
2025-04-05 17:11:23.160SERIAL « 0x011a00a800012c119f038200224439a7d0597c96865ca8fe8500a954 (28 bytes)
2025-04-05 17:11:23.154DRIVER « [REQ] [SendDataBridge] - callback id: 52 - transmit status: OK, took 10 ms - routing attempts: 1 - protocol & route speed: Z-Wave, 100 kbit/s - routing scheme: LWR - ACK RSSI: -87 dBm - ACK channel no.: 0 - TX channel no.: 0
2025-04-05 17:11:23.153SERIAL » [ACK] (0x06)
2025-04-05 17:11:23.151SERIAL « 0x011d00a93400000100a97f7f7f7f00000300000000030100007f7f7f7f7fa9 (31 bytes)
2025-04-05 17:11:23.136SERIAL » [ACK] (0x06)
2025-04-05 17:11:23.134SERIAL « 0x010401a90152 (6 bytes)
2025-04-05 17:11:23.131SERIAL « [ACK] (0x06)
2025-04-05 17:11:23.127DRIVER » [Node 044] [REQ] [SendDataBridge] - │ source node id: 1 - │ transmit options: 0x25 - │ callback id: 52 - └─[Security2CCMessageEncapsulation] - │ sequence number: 92 - │ security class: S2_Authenticated - └─[MultilevelSwitchCCGet]
2025-04-05 17:11:23.126SERIAL » 0x011a00a9012c0e9f035c009dcf0eb18247b2f665b125000000003406 (28 bytes)
2025-04-05 17:11:23.123DRIVER one or more queues busy
2025-04-05 17:11:18.119DRIVER all queues idle
2025-04-05 17:11:18.117CNTRLR [Node 044] Timed out while waiting for a response from the node (ZW0201)
2025-04-05 17:11:17.704DRIVER « [Node 044] [REQ] [BridgeApplicationCommand] - │ RSSI: -87 dBm - └─[Security2CCMessageEncapsulation] - │ sequence number: 129 - │ security class: S2_Authenticated - └─[MultiChannelCCCommandEncapsulation] - │ source: 1 - │ destination: 0 - └─[MeterCCReport] - meter type: Electric - scale: W - rate type: Consumed - value: 212.8 - time delta: 0 seconds
2025-04-05 17:11:17.702CNTRLR [Node 044] [~] [Meter] value[66049]: 0 => 212.8 [Endpoint 1]
2025-04-05 17:11:17.700CNTRLR [Node 044] [Meter] value[66049]: metadata updated [Endpoint 1]
2025-04-05 17:11:17.697SERIAL » [ACK] (0x06)
2025-04-05 17:11:17.694SERIAL « 0x012800a800012c1f9f0381005476c82f9357e78f42f03b6ae03ea255a5b5c87e6 (42 bytes) - 92c662bc7bb6700a9ef
2025-04-05 17:11:17.095DRIVER « [Node 044] [REQ] [BridgeApplicationCommand] - │ RSSI: -87 dBm - └─[Security2CCMessageEncapsulation] - │ sequence number: 128 - │ security class: S2_Authenticated - └─[MultiChannelCCCommandEncapsulation] - │ source: 1 - │ destination: 0 - └─[SupervisionCCReport] - session id: 29 - more updates follow: true - status: Working - duration: 2s
2025-04-05 17:11:17.092SERIAL » [ACK] (0x06)
2025-04-05 17:11:17.090SERIAL « 0x011e00a800012c159f0380007229367d6d26111b218ec25489c4a5391000a96d (32 bytes)
2025-04-05 17:11:17.082SERIAL » [ACK] (0x06)
2025-04-05 17:11:17.080SERIAL « 0x011d00a93300000100a97f7f7f7f00000300000000030100007f7f7f7f7fae (31 bytes)
2025-04-05 17:11:17.066DRIVER « [RES] [SendDataBridge] - was sent: true
2025-04-05 17:11:17.064SERIAL » [ACK] (0x06)
2025-04-05 17:11:17.063SERIAL « 0x010401a90152 (6 bytes)
2025-04-05 17:11:17.061SERIAL « [ACK] (0x06)
2025-04-05 17:11:17.056DRIVER » [Node 044] [REQ] [SendDataBridge] - │ source node id: 1 - │ transmit options: 0x25 - │ callback id: 51 - └─[Security2CCMessageEncapsulation] - │ sequence number: 91 - │ security class: S2_Authenticated - └─[SupervisionCCGet] - │ session id: 29 - │ request updates: true - └─[MultilevelSwitchCCSet] - target value: 255
2025-04-05 17:11:17.055SERIAL » 0x012000a9012c149f035b003dad9c209bf1d87baac5a100241721f425000000003 (34 bytes) - 353
2025-04-05 17:11:17.051DRIVER one or more queues busy
2025-04-05 17:11:17.026DRIVER all queues idle
2025-04-05 17:11:17.022CNTRLR [Node 044] Timed out while waiting for a response from the node (ZW0201)
2025-04-05 17:11:16.001DRIVER « [Node 044] [REQ] [BridgeApplicationCommand] - │ RSSI: -87 dBm - └─[Security2CCMessageEncapsulation] - │ sequence number: 127 - │ security class: S2_Authenticated - └─[MultiChannelCCCommandEncapsulation] - │ source: 1 - │ destination: 0 - └─[SupervisionCCReport] - session id: 28 - more updates follow: true - status: Working - duration: 2s
2025-04-05 17:11:15.998SERIAL » [ACK] (0x06)
2025-04-05 17:11:15.995SERIAL « 0x011e00a800012c159f037f00684c6f042a5e71f1b829b50ed51e36eba300a91f (32 bytes)
2025-04-05 17:11:15.987DRIVER « [REQ] [SendDataBridge] - callback id: 50 - transmit status: OK, took 10 ms - routing attempts: 1 - protocol & route speed: Z-Wave, 100 kbit/s - routing scheme: LWR - ACK RSSI: -87 dBm - ACK channel no.: 0 - TX channel no.: 0
2025-04-05 17:11:15.984SERIAL » [ACK] (0x06)
2025-04-05 17:11:15.983SERIAL « 0x011d00a93200000100a97f7f7f7f00000300000000030100007f7f7f7f7faf (31 bytes)
2025-04-05 17:11:15.975DRIVER « [RES] [SendDataBridge] - was sent: true
2025-04-05 17:11:15.973SERIAL » [ACK] (0x06)
2025-04-05 17:11:15.972SERIAL « 0x010401a90152 (6 bytes)
2025-04-05 17:11:15.969SERIAL « [ACK] (0x06)
2025-04-05 17:11:15.963DRIVER » [Node 044] [REQ] [SendDataBridge] - │ source node id: 1 - │ transmit options: 0x25 - │ callback id: 50 - └─[Security2CCMessageEncapsulation] - │ sequence number: 90 - │ security class: S2_Authenticated - └─[SupervisionCCGet] - │ session id: 28 - │ request updates: true - └─[MultilevelSwitchCCSet] - target value: 255
2025-04-05 17:11:15.959SERIAL » 0x012000a9012c149f035a001ae6bda720ad3b8d973e1dbe460d1e0c25000000003 (34 bytes) - 210
2025-04-05 17:11:15.948DRIVER one or more queues busy

Debug logs from driver:

dev:692025-04-05 17:11:35.992debugskip:hubitat.zwave.commands.multichannelv4.MultiChannelCmdEncap@899de3
dev:692025-04-05 17:11:35.989debugparse:{"cc":50,"cmd":2,"ep":1,"values":[{"ccSpecific":{"meterType":1,"rateType":1,"scale":2},"commandClass":50,"commandClassName":"Meter","endpoint":1,"newValue":0,"prevValue":212.8,"property":"value","propertyKey":66049,"propertyKeyName":"Electric_W_Consumed","propertyName":"value","ts":1743865895983}]}
dev:692025-04-05 17:11:35.469debugskip:hubitat.zwave.commands.multichannelv4.MultiChannelCmdEncap@142b254
dev:692025-04-05 17:11:35.465debugparse:{"cc":38,"cmd":3,"ep":1,"values":[{"commandClass":38,"commandClassName":"Multilevel Switch","endpoint":1,"newValue":99,"prevValue":0,"property":"currentValue","propertyName":"currentValue","ts":1743865895461},{"commandClass":38,"commandClassName":"Multilevel Switch","endpoint":1,"newValue":{"unit":"seconds","value":0},"prevValue":{"unit":"seconds","value":0},"property":"duration","propertyName":"duration","ts":1743865895459},{"commandClass":38,"commandClassName":"Multilevel Switch","endpoint":1,"newValue":99,"prevValue":0,"property":"targetValue","propertyName":"targetValue","ts":1743865895457}]}
dev:692025-04-05 17:11:17.711debugskip:hubitat.zwave.commands.multichannelv4.MultiChannelCmdEncap@a75efc
dev:692025-04-05 17:11:17.707debugparse:{"cc":50,"cmd":2,"ep":1,"values":[{"ccSpecific":{"meterType":1,"rateType":1,"scale":2},"commandClass":50,"commandClassName":"Meter","endpoint":1,"newValue":212.8,"prevValue":0,"property":"value","propertyKey":66049,"propertyKeyName":"Electric_W_Consumed","propertyName":"value","ts":1743865877702}]}
dev:692025-04-05 17:11:17.030debugsupervision report for session: 3
dev:692025-04-05 17:11:17.028debugparse:zw device: 2C, command: 6C02, payload: 03 FF 00, isMulticast: false
dev:692025-04-05 17:11:15.920infoRoleta gabinetu lewa is opening
dev:692025-04-05 17:11:15.903debugnew supervised packet for session: 3
dev:692025-04-05 17:11:15.901debugopen()

My interpretation is that there is some really bad implementation of the supervision. ZwaveJS logs clearly show that:

driver sends encapsulated open command
device responds with session confirmation with status "waiting", which is a correct behavior, because blinds take about 20 seconds to fully open.
however, several attempts are made to retry the command
finally the driver completely skips the final encapsulated report which provides information about the current state of the device

There are two things wrong here I believe:

Z-Wave wrongly retries on its own the command to the device several times. This has the downside that my morning and evening automation for 10 blinds now have about a 30% miss rate, because commands are lost.
The driver does not properly read the closed/open state.

For your info: @bertabcd1234 @gopher.ny

A question from me is, is this Zwave JS, Hubitat controller plane or the driver doing these retries?

bertabcd1234 · April 5, 2025, 3:50pm

This is probably one for @bcopeland. I don't know what Z-Wave JS does other than that it should handle Supervision on its own (possibly including retries if it doesn't hear back), but the platform itself doesn't do anything unless you have the new Command Retry feature enabled for the device, which it is not by default.

bogus.wojcik · April 5, 2025, 4:30pm

@bertabcd1234 Still, the driver ignores the encapsulated report sent on its own. Any idea why? (see log where it says "skip")

EDIT: I just switch back to zip gateway and the problem persists. So it looks like it is CAUSED by the platform not Z-Wave JS.

As for Z-Wave JS, I am pretty sure that the handling of supervision is incorrect here. If we look just at this:

2025-04-05 17:11:17.022CNTRLR [Node 044] Timed out while waiting for a response from the node (ZW0201)
2025-04-05 17:11:16.001DRIVER « [Node 044] [REQ] [BridgeApplicationCommand] - │ RSSI: -87 dBm - └─[Security2CCMessageEncapsulation] - │ sequence number: 127 - │ security class: S2_Authenticated - └─[MultiChannelCCCommandEncapsulation] - │ source: 1 - │ destination: 0 - └─[SupervisionCCReport] - session id: 28 - more updates follow: true - status: Working - duration: 2s

The status is working, more updates will follow, yet there is a retry...

In another instance for different device Z-Wave JS is also doing some shenanigans.