ZwaveJS2Mqtt does not query initial state on interfaces during startup - incorrect values for switch states, thermostats

PeteRage · March 27, 2022, 3:29pm

I have multiple switches that exhibit the same behavior. At startup zwave-js does not query the switch state and hence Home Assistant shows whatever its last known switch state was. So, for example, if the switch was off when zwave-js was shutdown; and then the switch get’s turned on, on restart of zwave-js it still reports off. Going into the zwave-js control panel, show the switch as off; and if I hit the refresh it then updates. Once it’s up it seems to track on/off properly whether invoked from the device or lovelace. Likewise Thermostats are showing the last state (heating instead of idle and the wrong setpoints)

The specific switch I have are:

GE/Jasco 46202 / ZW4009
AEON Labs ZW096
Leviton DZPA1

The specific themostat I have is:

Honeywell TH6320ZW

And they all behave the same - so this is not an issue with one vendors code.

When I look at the logs (OZW_Log.txt) for one of the AEON Labs ZW096 (Node 009) at zwave network startup I see the following lines:


    Line 155066: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x30, 0xdc
	Line 155067: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) SwitchMultilevelCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x26, 0x02, 0x25, 0x31, 0xde
	Line 155068: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) MeterCmd_Get (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x32, 0x01, 0x00, 0x25, 0x32, 0xc8
	Line 155069: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) MeterCmd_Get (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x32, 0x01, 0x10, 0x25, 0x33, 0xd9
	Line 155070: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) MeterCmd_Get (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x32, 0x01, 0x20, 0x25, 0x34, 0xee
	Line 155071: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) MeterCmd_Get (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x32, 0x01, 0x28, 0x25, 0x35, 0xe7
	Line 155072: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) ColorCmd_Get (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x33, 0x03, 0x02, 0x25, 0x36, 0xcd
	Line 155073: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) ColorCmd_Get (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x33, 0x03, 0x03, 0x25, 0x37, 0xcd
	Line 155074: 2022-03-27 10:46:25.526 Detail, Node009, Queuing (Send) ColorCmd_Get (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x33, 0x03, 0x04, 0x25, 0x38, 0xc5
	Line 155075: 2022-03-27 10:46:25.527 Detail, Node009, Queuing (Send) ClockCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x81, 0x05, 0x25, 0x39, 0x76
	Line 155076: 2022-03-27 10:46:25.527 Detail, Node009, Queuing (Query) Query Stage Complete (Dynamic)
	Line 155078: 2022-03-27 10:46:25.527 Info, Node009, Sending (Send) message (Callback ID=0x30, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x30, 0xdc
	Line 155079: 2022-03-27 10:46:25.534 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
	Line 155080: 2022-03-27 10:46:25.534 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
	Line 155081: 2022-03-27 10:46:25.551 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x30, 0x00, 0x00, 0x02, 0xd9
	Line 155082: 2022-03-27 10:46:25.551 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x30 received (expected 0x30)
	Line 155083: 2022-03-27 10:46:25.551 Info, Node009, Request RTT 23 Average Request RTT 23
	Line 155085: 2022-03-27 10:46:25.562 Detail, Node009,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x09, 0x03, 0x25, 0x03, 0xff, 0x21
	Line 155087: 2022-03-27 10:46:25.562 Info, Node009, Response RTT 34 Average Response RTT 34
	Line 155088: 2022-03-27 10:46:25.562 Info, Node009, Received SwitchBinary report from node 9: level=On

In other words, it looks like at startup the Zwave (deprecated) driver automatically queries the discovered topics for the device and hence get’s the current values.

When I look in the zwavejs2mqtt log I see the following:

	Line 201: 2022-03-27T14:04:54.711Z CNTRLR   [Node 009] Embedded device config loaded
	Line 250: 2022-03-27T14:04:55.512Z CNTRLR » [Node 009] pinging the node...
	Line 287: 2022-03-27T14:04:56.035Z DRIVER » [Node 009] [REQ] [SendData]
	Line 301: 2022-03-27T14:04:56.072Z CNTRLR   [Node 009] The node is alive.
	Line 302: 2022-03-27T14:04:56.275Z CNTRLR   [Node 009] The node is ready to be used
	Line 303: 2022-03-27T14:04:56.285Z CNTRLR « [Node 009] ping successful
	Line 583: 2022-03-27T14:08:22.699Z CNTRLR   [Node 009] [~] [Meter] value[66561]: 126.524 => 125.663           [Endpoint 0]
	Line 585: 2022-03-27T14:08:22.707Z DRIVER « [Node 009] [REQ] [ApplicationCommand]
	Line 593: 2022-03-27T14:08:22.797Z CNTRLR   [Node 009] [~] [Meter] value[66817]: 0 => 0.182                   [Endpoint 0]
	Line 595: 2022-03-27T14:08:22.805Z DRIVER « [Node 009] [REQ] [ApplicationCommand]
	Line 603: 2022-03-27T14:08:22.897Z CNTRLR   [Node 009] [~] [Meter] value[65537]: 19.318 => 19.392             [Endpoint 0]
	Line 605: 2022-03-27T14:08:22.901Z DRIVER « [Node 009] [REQ] [ApplicationCommand]
	Line 614: 2022-03-27T14:08:22.996Z CNTRLR   [Node 009] [~] [Meter] value[66049]: 0 => 12.081                  [Endpoint 0]
	Line 616: 2022-03-27T14:08:23.000Z DRIVER « [Node 009] [REQ] [ApplicationCommand]
	Line 850: 2022-03-27T14:13:22.695Z CNTRLR   [Node 009] [~] [Meter] value[66561]: 125.663 => 126.169           [Endpoint 0]
	Line 852: 2022-03-27T14:13:22.701Z DRIVER « [Node 009] [REQ] [ApplicationCommand]
	Line 860: 2022-03-27T14:13:22.795Z CNTRLR   [Node 009] [~] [Meter] value[66817]: 0.182 => 0.183               [Endpoint 0]
	Line 862: 2022-03-27T14:13:22.799Z DRIVER « [Node 009] [REQ] [ApplicationCommand]
	Line 870: 2022-03-27T14:13:22.896Z CNTRLR   [Node 009] [~] [Meter] value[65537]: 19.392 => 19.393             [Endpoint 0]
	Line 872: 2022-03-27T14:13:22.900Z DRIVER « [Node 009] [REQ] [ApplicationCommand]
	Line 881: 2022-03-27T14:13:22.995Z CNTRLR   [Node 009] [~] [Meter] value[66049]: 12.081 => 12.207             [Endpoint 0]
	Line 883: 2022-03-27T14:13:22.999Z DRIVER « [Node 009] [REQ] [ApplicationCommand]

Note: it has not queried the topics. Then you can see Node 09 delivering the Meter data every 5 minutes as it’s configured. Later on when I refresh the Binary Switch in the control panel I get this data.

	Line 1363: 2022-03-27T14:21:58.361Z CNTRLR » [Node 009] querying Binary Switch state...
	Line 1365: 2022-03-27T14:21:58.401Z DRIVER » [Node 009] [REQ] [SendData]
	Line 1380: 2022-03-27T14:21:58.439Z CNTRLR   [Node 009] [~] [Binary Switch] currentValue: false => true        [Endpoint 0]
	Line 1381: 2022-03-27T14:21:58.443Z CNTRLR   [Node 009] [+] [Binary Switch] targetValue: undefined             [Endpoint 0]
	Line 1383: 2022-03-27T14:21:58.449Z DRIVER « [Node 009] [REQ] [ApplicationCommand]
	Line 1386: 2022-03-27T14:21:58.464Z CNTRLR « [Node 009] received Binary Switch state:

In HA I do not have any polling configured for this device. So it seems that ZwaveJs2Mqtt is not querying the devices at network startup as it should (or the default config does not do this).

The thermostats have the same issue. As an example, the climate entity had the wrong state “Heating” and the wrong setpoint. Which is definitely misleading and problematic.

I suspect the same with other sensors.

Meaning Zwave-JS does not query any interfaces at startup; whereas Zwave (deprecated) does.

freshcoast · March 27, 2022, 4:25pm

This is by design. Z-Wave JS does not query values on startup for devices that have been interviewed completely.

PeteRage · March 27, 2022, 4:30pm

That seems like a design flaw then.

Incorrect data in an automation system is a critical issue - as you are writing automations and making decisions from this data.

freshcoast · March 27, 2022, 4:40pm

I guess it being a design flaw is just an opinion. Z-Wave JS originally implemented it that way, but it was changed after heavy discussion. https://github.com/zwave-js/node-zwave-js/discussions/1432

PeteRage · March 27, 2022, 6:11pm

Sure every one has an opinion😊

There is this command in the zwave-js

https://zwave-js.github.io/node-zwave-js/#/api/node?id=refreshccvalues

That seems to do what needs to be done to get the current values which is I think what most users would expect.

The simplest thing to do is add this method to the integration, such that an automation could call this on all the nodes when it wants to.

A better solution would be to add this to the integration - so that whenever it re-establishes - a connection (which likely signifies the zwavejs was down) - it calls this for each node. We could make it optional (for those who want unreliable data) - but probably default to true,

Thanks for the link. I think Al had the right user perspective, just got talked out of it.

ceh · March 27, 2022, 10:40pm

You could have an automation update the values triggered by home assistant starting.

PeteRage · March 28, 2022, 1:25am

Good idea. The issue though is not related to HA starting, rather the zwavejs2mqtt container being restarted. Is it possible to trigger an automation based on the zwavejs integration establishing a connection the the container?

freshcoast · March 28, 2022, 1:55am

You could try the zwave_js.event trigger platform. Trigger off something like the driver event source and one of the driver events like "all nodes ready".

Alternatively, just pick the set of entities that are crucial. Trigger based on their state going from “unavailable” to anything else, and refresh the entity as the action.

PeteRage · March 28, 2022, 12:28pm

That looks good - I like it - should work. I counted up the entities - it’s only a handful as it’s limited. Al did explain to me the issues with querying everything on a large network - which was helpful as i understand the design tradeoffs now.

Most data like temperature, power, humidity get sent at a periodic interval, for me that’s 10 minutes to 1 hour depending on whether it’s a plugged in or on battery. So this stuff comes in on its own. If a value gets missed it’s not a big deal as it’s relatively linear. For example, temperature goes from 62, 62.3, 62.4. So it’ll auto correct anyways.

So it’s really switch states. Some of my switches are managing mechanical systems like well pumps (via 30 amp relays). So knowing the state and that the device is alive is super important as not many points are gained having no water in the middle of a shower because the well is disabled. Nor Is not having the not well turn off when a leak is detected.

Anyways, more I think about this, for these “critical” switches - I’ll do the automation approach you recommend, setup polling, and alert if updates are not received. Same on the climate controls.