search

OpenZWave / open-zwave

a C++ library to control Z-Wave Networks via a USB Z-Wave Controller.
http://www.openzwave.net/
GNU Lesser General Public License v3.0
1.05k stars 917 forks source link

DZS15-1LZ switches block Z-Wave messages for 10 seconds #2235

Open sjakub opened 4 years ago

sjakub commented 4 years ago

I have a bunch of Leviton DZS15-1LZ switches. They are older (not ZWave "plus") and they don't offer instant updates when they are physically triggered (due to some Lutron patent). However, I recently discovered that they cause the Z-Wave controller to stop sending ANY messages for 10 seconds after triggering them.

In the log below, I triggered DZS15-1LZ switch (Node008), and it reported something to the controller, which then sent SwitchBinaryCmd_Get command to it, which it never gets a response to. Eventually - after 10 seconds - it timed out. But before the timeout, another switch was triggered - Node031, which is a newer one and supports instantaneous updates. However, the SwitchBinaryCmd_Get command was not sent to that switch until after the previous message to Node008 timed-out...

Ideally, maybe there is a way to update the DZS15-1LZ switch to work properly (Lutron patent supposedly expired). If not, maybe there is a way to prevent OpenZWave from sending SwitchBinaryCmd_Get message after UPDATE_STATE_NODE_INFO_RECEIVED?

EDIT: I lowered the RetryTimeout to 3s and that improved the behaviour of the network. I am not sure, however, if this could cause any other issues... I also tried adding getsupported="false" to COMMAND_CLASS_SWITCH_BINARY section in zwcfg.xml file. It fixed the network "freezes", but prevented the switch from being updated at all - ever, even when triggered over Z-Wave. Is there a better way? Would it be possible to add an option to skip (or, ideally, delay) that first 'get' after UPDATE_STATE_NODE_INFO_RECEIVED?

I have quite a few of those older switches (so replacing all of them would be costly) and I am ok with them not updating right away. But they are messing up everything else that otherwise would work perfectly...

2020-05-30 23:14:08.269 Detail, Node008,   Received: 0x01, 0x12, 0x00, 0x49, 0x84, 0x08, 0x0c, 0x04, 0x10, 0x03, 0x25, 0x27, 0x2b, 0x2c, 0x72, 0x86, 0x91, 0x77, 0x73, 0x57
2020-05-30 23:14:08.269 Detail,
2020-05-30 23:14:08.269 Info, Node008, UPDATE_STATE_NODE_INFO_RECEIVED from node 8
2020-05-30 23:14:08.269 Detail, Node008, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2020-05-30 23:14:08.270 Detail, Node008, QueryStage_Dynamic
2020-05-30 23:14:08.270 Detail, Node008, Queuing (Send) SwitchBinaryCmd_Get (Node=8): 0x01, 0x09, 0x00, 0x13, 0x08, 0x02, 0x25, 0x02, 0x25, 0x5f, 0xb2
2020-05-30 23:14:08.270 Detail, Node008, Queuing (Query) Query Stage Complete (Dynamic)
2020-05-30 23:14:08.270 Detail,
2020-05-30 23:14:08.270 Info, Node008, Sending (Send) message (Callback ID=0x5f, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=8): 0x01, 0x09, 0x00, 0x13, 0x08, 0x02, 0x25, 0x02, 0x25, 0x5f, 0xb2
2020-05-30 23:14:08.278 Detail, Node008,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-05-30 23:14:08.278 Detail, Node008,   ZW_SEND_DATA delivered to Z-Wave stack
2020-05-30 23:14:08.321 Detail, Node008,   Received: 0x01, 0x07, 0x00, 0x13, 0x5f, 0x00, 0x00, 0x05, 0xb1
2020-05-30 23:14:08.321 Detail, Node008,   ZW_SEND_DATA Request with callback ID 0x5f received (expected 0x5f)
2020-05-30 23:14:08.321 Info, Node008, Request RTT 50 Average Request RTT 37
2020-05-30 23:14:08.321 Detail,   Expected callbackId was received
2020-05-30 23:14:08.331 Detail, Node008,   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x08, 0x04, 0x22, 0x01, 0x00, 0x00, 0xde
2020-05-30 23:14:08.331 Detail,
2020-05-30 23:14:08.331 Info, Node008, Response RTT 60 Average Response RTT 47
2020-05-30 23:14:10.348 Detail, Node031,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x1f, 0x02, 0x82, 0x01, 0x6d
2020-05-30 23:14:10.348 Detail,
2020-05-30 23:14:10.348 Info, Node031, Received Hail command from node 31
2020-05-30 23:14:10.348 Detail, Node031, Queuing (Send) SwitchMultilevelCmd_Get (Node=31): 0x01, 0x09, 0x00, 0x13, 0x1f, 0x02, 0x26, 0x02, 0x25, 0x60, 0x99
2020-05-30 23:14:18.271 Error, Node008, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-05-30 23:14:18.272 Detail, Node008, Removing current message
2020-05-30 23:14:18.272 Detail, Node008, Notification: Notification - TimeOut
2020-05-30 23:14:18.280 Detail,
2020-05-30 23:14:18.280 Info, Node031, Sending (Send) message (Callback ID=0x60, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=31): 0x01, 0x09, 0x00, 0x13, 0x1f, 0x02, 0x26, 0x02, 0x25, 0x60, 0x99
2020-05-30 23:14:18.288 Detail, Node031,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-05-30 23:14:18.288 Detail, Node031,   ZW_SEND_DATA delivered to Z-Wave stack
2020-05-30 23:14:18.412 Detail, Node031,   Received: 0x01, 0x07, 0x00, 0x13, 0x60, 0x00, 0x00, 0x0d, 0x86
2020-05-30 23:14:18.412 Detail, Node031,   ZW_SEND_DATA Request with callback ID 0x60 received (expected 0x60)
2020-05-30 23:14:18.412 Info, Node031, Request RTT 131 Average Request RTT 106
Fishwaldo commented 4 years ago

2020-05-30 23:14:10.348 Info, Node031, Received Hail command from node 31 2020-05-30 23:14:10.348 Detail, Node031, Queuing (Send) SwitchMultilevelCmd_Get (Node=31): 0x01, 0x09, 0x00, 0x13, 0x1f, 0x02, 0x26, 0x02, 0x25, 0x60, 0x99 2020-05-30 23:14:18.271 Error, Node008, ERROR: Dropping command, expected response not received after 1 attempt(s)

Unfortunately this device is pretty old and buggy. Sending a NIF and Hail message were from ancient times (as you noted) and it failing to respond to a standard "SwitchMultilevelCmd_Get" indicates these devices are "underpowered" as well (or bad coding in the firmware).

There are improvements coming (around OZW 1.8 with the supervision CC) that improve reliability of messages, but such a old device wouldn't support that...

and Unless this affects a lot of people, sorry, I just dont have the time to implement a workaround for a single device.

sjakub commented 4 years ago

Would you accept a patch? And if so, what would be the right approach? Adding a parameter that could be configured in xml config file to skip that 'get' after the update state message?

SchroedingerHepcat commented 3 years ago

I also have a bunch of these Leviton switches and dimmers in my home and am running into the same problem when the switch is triggered manually. It times out listening for a response to the SwitchBinaryCmd_Get:

2020-10-12 00:34:40.302340981  [20201012 0:34:40.301 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x12, 0x00, 0x49, 0x84, 0x04, 0x0c, 0x04, 0x10, 0x03, 0x25, 0x27, 0x2b, 0x2c, 0x72, 0x86, 0x91, 0x77, 0x73, 0x5b
2020-10-12 00:34:40.302472201  [20201012 0:34:40.302 UTC] [ozw.library] [info]: Info - Node: 4 UPDATE_STATE_NODE_INFO_RECEIVED from node 4
2020-10-12 00:34:40.302688878  [20201012 0:34:40.302 UTC] [ozw.library] [debug]: Detail - Node: 4 AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2020-10-12 00:34:40.302852709  [20201012 0:34:40.302 UTC] [ozw.library] [debug]: Detail - Node: 4 QueryStage_Dynamic
2020-10-12 00:34:40.303057315  [20201012 0:34:40.302 UTC] [ozw.library] [debug]: Detail - Node: 4 Queuing (Send) SwitchBinaryCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x25, 0x02, 0x25, 0x46, 0xa7
2020-10-12 00:34:40.303248583  [20201012 0:34:40.303 UTC] [ozw.library] [debug]: Detail - Node: 4 Queuing (Query) Query Stage Complete (Dynamic)
2020-10-12 00:34:40.303447462  [20201012 0:34:40.303 UTC] [ozw.library] [info]: Info - Node: 4 Sending (Send) message (Callback ID=0x46, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x25, 0x02, 0x25, 0x46, 0xa7
2020-10-12 00:34:40.303604174  [20201012 0:34:40.303 UTC] [ozw.library] [info]: Info - Node: 4 Encrypted Flag is 0
2020-10-12 00:34:40.309950805  [20201012 0:34:40.309 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-12 00:34:40.310225407  [20201012 0:34:40.310 UTC] [ozw.library] [debug]: Detail - Node: 4   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-12 00:34:40.326003510  [20201012 0:34:40.325 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x05, 0x00, 0x13, 0x46, 0x00, 0xaf
2020-10-12 00:34:40.326119188  [20201012 0:34:40.326 UTC] [ozw.library] [debug]: Detail - Node: 4   ZW_SEND_DATA Request with callback ID 0x46 received (expected 0x46)
2020-10-12 00:34:40.326210939  [20201012 0:34:40.326 UTC] [ozw.library] [info]: Info - Node: 4 Request RTT 22 Average Request RTT 21
2020-10-12 00:34:40.326299748  [20201012 0:34:40.326 UTC] [ozw.library] [debug]: Detail - Node: 4   Expected callbackId was received
2020-10-12 00:34:40.335021269  [20201012 0:34:40.334 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x04, 0x04, 0x22, 0x01, 0x00, 0x00, 0xd2
2020-10-12 00:34:40.335131049  [20201012 0:34:40.335 UTC] [ozw.library] [info]: Info - Node: 4 Response RTT 31 Average Response RTT 31
2020-10-12 00:34:50.304616594  [20201012 0:34:50.304 UTC] [ozw.library] [critical]: Error - Node: 4 ERROR: Dropping command, expected response not received after 1 attempt(s). Command: "SwitchBinaryCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x25, 0x02, 0x25, 0x46, 0xa7"
2020-10-12 00:34:50.304717964  [20201012 0:34:50.304 UTC] [ozw.library] [debug]: Detail - Node: 4 Removing current message
2020-10-12 00:34:50.304886038  [20201012 0:34:50.304 UTC] [ozw.library] [debug]: Detail - Node: 4 Notification: Notification - TimeOut
2020-10-12 00:34:50.305050407  [20201012 0:34:50.304 UTC] [ozw.library] [debug]: Detail - Node: 4 Query Stage Complete (Dynamic)
2020-10-12 00:34:50.305349588  [20201012 0:34:50.305 UTC] [ozw.library] [debug]: Detail - Node: 4 AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2020-10-12 00:34:50.305617692  [20201012 0:34:50.305 UTC] [ozw.library] [debug]: Detail - Node: 4 QueryStage_Configuration
2020-10-12 00:34:50.305782618  [20201012 0:34:50.305 UTC] [ozw.library] [debug]: Detail - Node: 4 QueryStage_Complete
2020-10-12 00:34:50.305975478  [20201012 0:34:50.305 UTC] [ozw.library] [warning]: Warning - Node: 0 CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2020-10-12 00:34:50.306134175  [20201012 0:34:50.306 UTC] [ozw.library] [info]: Info - Node: 0 Saving Cache
2020-10-12 00:34:50.306543624  [20201012 0:34:50.306 UTC] [ozw.library] [info]: Info - Node: 1 Cache Save for Node 1 as its QueryStage_CacheLoad
2020-10-12 00:34:50.307314020  [20201012 0:34:50.307 UTC] [ozw.library] [info]: Info - Node: 4 Cache Save for Node 4 as its QueryStage_CacheLoad
2020-10-12 00:34:50.345579438  [20201012 0:34:50.345 UTC] [ozw.library] [debug]: Detail - Node: 4 Notification: NodeQueriesComplete

Interestingly, the switch appears to reply to the SwitchBinaryCmd_Get when it is issued after issuing a switch command from HomeAssistant using open-zwave:

2020-10-12 00:43:43.714307896  [20201012 0:43:43.714 UTC] [ozw.library] [info]: Info - Node: 4 Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2020-10-12 00:43:43.714440882  [20201012 0:43:43.714 UTC] [ozw.library] [info]: Info - Node: 4 SwitchBinary::Set - Setting to On
2020-10-12 00:43:43.714582946  [20201012 0:43:43.714 UTC] [ozw.library] [debug]: Detail - Node: 4 Queuing (Send) SwitchBinaryCmd_Set (Node=4): 0x01, 0x0a, 0x00, 0x13, 0x04, 0x03, 0x25, 0x01, 0xff, 0x25, 0x47, 0x58
2020-10-12 00:43:43.714767157  [20201012 0:43:43.714 UTC] [ozw.library] [debug]: Detail - Node: 4 Queuing (Send) SwitchBinaryCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x25, 0x02, 0x25, 0x48, 0xa9
2020-10-12 00:43:43.715040192  [20201012 0:43:43.714 UTC] [ozw.library] [info]: Info - Node: 4 Sending (Send) message (Callback ID=0x47, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=4): 0x01, 0x0a, 0x00, 0x13, 0x04, 0x03, 0x25, 0x01, 0xff, 0x25, 0x47, 0x58
2020-10-12 00:43:43.715362330  [20201012 0:43:43.715 UTC] [ozw.library] [info]: Info - Node: 4 Encrypted Flag is 0
2020-10-12 00:43:43.722348605  [20201012 0:43:43.722 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-12 00:43:43.722507083  [20201012 0:43:43.722 UTC] [ozw.library] [debug]: Detail - Node: 4   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-12 00:43:43.737470341  [20201012 0:43:43.737 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x05, 0x00, 0x13, 0x47, 0x00, 0xae
2020-10-12 00:43:43.737619399  [20201012 0:43:43.737 UTC] [ozw.library] [debug]: Detail - Node: 4   ZW_SEND_DATA Request with callback ID 0x47 received (expected 0x47)
2020-10-12 00:43:43.737753831  [20201012 0:43:43.737 UTC] [ozw.library] [info]: Info - Node: 4 Request RTT 22 Average Request RTT 21
2020-10-12 00:43:43.737929941  [20201012 0:43:43.737 UTC] [ozw.library] [debug]: Detail - Node: 4   Expected callbackId was received
2020-10-12 00:43:43.738133427  [20201012 0:43:43.737 UTC] [ozw.library] [debug]: Detail - Node: 4   Expected reply was received
2020-10-12 00:43:43.738294964  [20201012 0:43:43.738 UTC] [ozw.library] [debug]: Detail - Node: 4   Message transaction complete
2020-10-12 00:43:43.738452641  [20201012 0:43:43.738 UTC] [ozw.library] [debug]: Detail - Node: 4 Removing current message
2020-10-12 00:43:43.738690093  [20201012 0:43:43.738 UTC] [ozw.library] [info]: Info - Node: 4 Sending (Send) message (Callback ID=0x48, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x25, 0x02, 0x25, 0x48, 0xa9
2020-10-12 00:43:43.738836585  [20201012 0:43:43.738 UTC] [ozw.library] [info]: Info - Node: 4 Encrypted Flag is 0
2020-10-12 00:43:43.745449152  [20201012 0:43:43.745 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-12 00:43:43.745603820  [20201012 0:43:43.745 UTC] [ozw.library] [debug]: Detail - Node: 4   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-12 00:43:43.761465530  [20201012 0:43:43.761 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x05, 0x00, 0x13, 0x48, 0x00, 0xa1
2020-10-12 00:43:43.761640187  [20201012 0:43:43.761 UTC] [ozw.library] [debug]: Detail - Node: 4   ZW_SEND_DATA Request with callback ID 0x48 received (expected 0x48)
2020-10-12 00:43:43.761791303  [20201012 0:43:43.761 UTC] [ozw.library] [info]: Info - Node: 4 Request RTT 22 Average Request RTT 21
2020-10-12 00:43:43.761938561  [20201012 0:43:43.761 UTC] [ozw.library] [debug]: Detail - Node: 4   Expected callbackId was received
2020-10-12 00:43:43.770468895  [20201012 0:43:43.770 UTC] [ozw.library] [debug]: Detail - Node: 4   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x04, 0x03, 0x25, 0x03, 0xff, 0x2c
2020-10-12 00:43:43.770679523  [20201012 0:43:43.770 UTC] [ozw.library] [info]: Info - Node: 4 Response RTT 31 Average Response RTT 31
2020-10-12 00:43:43.770837150  [20201012 0:43:43.770 UTC] [ozw.library] [info]: Info - Node: 4 Received SwitchBinary report from node 4: level=On
2020-10-12 00:43:43.770997184  [20201012 0:43:43.770 UTC] [ozw.library] [debug]: Detail - Node: 4 Value Updated: old value=false, new value=true, type=bool
2020-10-12 00:43:43.771248796  [20201012 0:43:43.771 UTC] [ozw.library] [debug]: Detail - Node: 4 Changes to this value are not verified
2020-10-12 00:43:43.771346957  [20201012 0:43:43.771 UTC] [ozw.library] [debug]: Detail - Node: 4   Expected reply and command class was received
2020-10-12 00:43:43.771500844  [20201012 0:43:43.771 UTC] [ozw.library] [debug]: Detail - Node: 4   Message transaction complete
2020-10-12 00:43:43.771658401  [20201012 0:43:43.771 UTC] [ozw.library] [debug]: Detail - Node: 4 Removing current message
2020-10-12 00:43:43.771962751  [20201012 0:43:43.771 UTC] [ozw.library] [debug]: Detail - Node: 4 Notification: ValueChanged CC: COMMAND_CLASS_SWITCH_BINARY Instance: 1 Index: 0

The commands are slightly different. The successful get is this:

SwitchBinaryCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x25, 0x02, 0x25, 0x48, 0xa9

with a response of:

Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x04, 0x03, 0x25, 0x03, 0xff, 0x2c

While the unsuccessful get is:

SwitchBinaryCmd_Get (Node=
4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x25, 0x02, 0x25, 0x46, 0xa7

with a response of:

Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x04, 0x04, 0x22, 0x01, 0x00, 0x00, 0xd2

I'm new to the z-wave world, so I haven't yet decoded what these messages are actually saying, but I'll update if I figure it out. I've mostly worked with the zigbee stack before this. I'm happy to help debug or workaround this, but I'd love some pointers in the right direction.