search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.16k stars 30.2k forks source link

identical messages sent to zwavejs are succeeding, then failing with ZW1405 #98851

Closed josh-m-sharpe closed 10 months ago

josh-m-sharpe commented 1 year ago

The problem

TL;DR Seemingly identical messages(?) sent from HomeAssistant "work" a few times, then fail with 

ERROR Z-WAVE-SERVER: The node failed to decode the message

The error can be seen on HA's side as well: 

ERROR (MainThread) [homeassistant.components.zwave_js] Unable to set value 59-38-0-targetValue: Z-Wave error 1405: The node failed to decode the message. (ZW1405)

My Setup:

Scenario: An event is triggered on a zwave device (Inovelli Red Dimmer) connected to a light That event gets run through a node-red flow and ultimately a HA Call Service node which is supposed to dim the light. This has worked well in the past. Now it's sporatic.

It appears that restarting HomeAssistant temporarily resolves it. To be more clear, if I restart HA, then trigger 1-2 events the likelyhood of them working is high. 3 or more events and they begin to fail.

Troubleshooting steps:

I think I found something that is decently relevant. I've been able to reproduce this issue consistently: 1) Restart HA 2) Trigger event at light switch (double tap) 3) check logs for event activity 4) verify lights dim 5) Trigger same event at light switch (double tap) 6) See debugging logs and stack traces.

Interestingly, it looks like HA is sending the exact same message. On the first event there is an actual success response. On the second, a stack trace. Hopefully this is helpful - actual logs of the problem showing the same input and two different results.

Successful Logs from first event trigger:

 2023-08-22 19:42:38.617 DEBUG (MainThread) [zwave_js_server] Publishing message:
 {'command': 'node.set_value',
  'messageId': '93bc8f55ef21448bb3651f8424ccfe70',
  'nodeId': 59,
  'options': {'transitionDuration': 'default'},
  'value': 20,
  'valueId': {'commandClass': 38, 'endpoint': 0, 'property': 'targetValue'}}

 2023-08-22 19:42:38.736 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"controller","event":"statistics updated","statistics":{"messagesTX":54,"messagesRX":134,"messagesDroppedRX":0,"NAK":0,"CAN":0,"timeoutACK":0,"timeoutResponse":0,"timeoutCallback":0,"messagesDroppedTX":0,"backgroundRSSI":{"channel0":{"current":-71,"average":-74},"channel1":{"current":-80,"average":-79},"timestamp":1692747745765}}}}', extra='')

 2023-08-22 19:42:38.739 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"statistics updated","nodeId":59,"statistics":{"commandsTX":2,"commandsRX":1,"commandsDroppedRX":1,"commandsDroppedTX":0,"timeoutResponse":0,"rtt":103.2,"lastSeen":"2023-08-22T23:42:38.586Z","rssi":-54,"lwr":{"protocolDataRate":2,"repeaters":[14],"rssi":-54,"repeaterRSSI":[-71]}}}}', extra='')

 2023-08-22 19:42:39.162 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"controller","event":"statistics updated","statistics":{"messagesTX":54,"messagesRX":135,"messagesDroppedRX":0,"NAK":0,"CAN":0,"timeoutACK":0,"timeoutResponse":0,"timeoutCallback":0,"messagesDroppedTX":0,"backgroundRSSI":{"channel0":{"current":-71,"average":-74},"channel1":{"current":-80,"average":-79},"timestamp":1692747745765}}}}', extra='')

 2023-08-22 19:42:39.169 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"statistics updated","nodeId":59,"statistics":{"commandsTX":3,"commandsRX":1,"commandsDroppedRX":1,"commandsDroppedTX":0,"timeoutResponse":0,"rtt":103.2,"lastSeen":"2023-08-22T23:42:38.586Z","rssi":-54,"lwr":{"protocolDataRate":2,"repeaters":[14],"rssi":-54,"repeaterRSSI":[-71]}}}}', extra='')

 2023-08-22 19:42:39.396 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"value updated","nodeId":59,"args":{"commandClassName":"Multilevel Switch","commandClass":38,"endpoint":0,"property":"targetValue","newValue":20,"prevValue":20,"propertyName":"targetValue"}}}', extra='')

 2023-08-22 19:42:39.398 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"value updated","nodeId":59,"args":{"commandClassName":"Multilevel Switch","commandClass":38,"property":"currentValue","endpoint":0,"newValue":20,"prevValue":20,"propertyName":"currentValue"}}}', extra='')

2023-08-22 19:42:39.398 DEBUG (MainThread) [homeassistant.components.zwave_js] [light.kitchen_island_lights] Value currentValue/None changed to: 20
2023-08-22 19:42:39.398 DEBUG (MainThread) [zwave_js_server] Received message:
WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"result","success":true,"messageId":"93bc8f55ef21448bb3651f8424ccfe70","result":{"success":true}}', extra='')

Successful ZwaveJS Logs from first event:

23:42:38.592 CNTRLR « [Node 059] received CentralScene notification {
                          "nodeId": 59,
                          "ccId": "Central Scene",
                          "ccCommand": "0x03",
                          "payload": "0x128301"
                      }

Failed Logs from Second event fired (few seconds later):

 2023-08-22 19:43:01.418 DEBUG (MainThread) [zwave_js_server] Publishing message:
 {'command': 'node.set_value',
  'messageId': '241ff4f07991499db1f62473c6906d11',
  'nodeId': 59,
  'options': {'transitionDuration': 'default'},
  'value': 20,
  'valueId': {'commandClass': 38, 'endpoint': 0, 'property': 'targetValue'}}

 2023-08-22 19:43:01.419 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"controller","event":"statistics updated","statistics":{"messagesTX":55,"messagesRX":137,"messagesDroppedRX":0,"NAK":0,"CAN":0,"timeoutACK":0,"timeoutResponse":0,"timeoutCallback":0,"messagesDroppedTX":0,"backgroundRSSI":{"channel0":{"current":-74,"average":-74},"channel1":{"current":-77,"average":-79},"timestamp":1692747775765}}}}', extra='')

 2023-08-22 19:43:01.646 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"statistics updated","nodeId":59,"statistics":{"commandsTX":4,"commandsRX":4,"commandsDroppedRX":1,"commandsDroppedTX":0,"timeoutResponse":0,"rtt":186.6,"lastSeen":"2023-08-22T23:43:01.551Z","rssi":-54,"lwr":{"protocolDataRate":2,"repeaters":[14],"rssi":-54,"repeaterRSSI":[-72]},"nlwr":{"protocolDataRate":2,"repeaters":[40],"rssi":-54,"repeaterRSSI":[-77],"routeFailedBetween":[40,59]}}}}', extra='')

 2023-08-22 19:43:01.669 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"controller","event":"statistics updated","statistics":{"messagesTX":55,"messagesRX":139,"messagesDroppedRX":0,"NAK":0,"CAN":0,"timeoutACK":0,"timeoutResponse":0,"timeoutCallback":0,"messagesDroppedTX":0,"backgroundRSSI":{"channel0":{"current":-74,"average":-74},"channel1":{"current":-77,"average":-79},"timestamp":1692747775765}}}}', extra='')

 2023-08-22 19:43:01.802 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"controller","event":"statistics updated","statistics":{"messagesTX":55,"messagesRX":140,"messagesDroppedRX":0,"NAK":0,"CAN":0,"timeoutACK":0,"timeoutResponse":0,"timeoutCallback":0,"messagesDroppedTX":0,"backgroundRSSI":{"channel0":{"current":-74,"average":-74},"channel1":{"current":-77,"average":-79},"timestamp":1692747775765}}}}', extra='')

 2023-08-22 19:43:01.806 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"statistics updated","nodeId":59,"statistics":{"commandsTX":4,"commandsRX":5,"commandsDroppedRX":1,"commandsDroppedTX":0,"timeoutResponse":0,"rtt":186.6,"lastSeen":"2023-08-22T23:43:01.743Z","rssi":-54,"lwr":{"protocolDataRate":2,"repeaters":[14],"rssi":-54,"repeaterRSSI":[-72]},"nlwr":{"protocolDataRate":2,"repeaters":[40],"rssi":-54,"repeaterRSSI":[-77],"routeFailedBetween":[40,59]}}}}', extra='')

 2023-08-22 19:43:01.998 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"statistics updated","nodeId":59,"statistics":{"commandsTX":4,"commandsRX":6,"commandsDroppedRX":1,"commandsDroppedTX":0,"timeoutResponse":0,"rtt":186.6,"lastSeen":"2023-08-22T23:43:01.825Z","rssi":-54,"lwr":{"protocolDataRate":2,"repeaters":[14],"rssi":-54,"repeaterRSSI":[-72]},"nlwr":{"protocolDataRate":2,"repeaters":[40],"rssi":-54,"repeaterRSSI":[-77],"routeFailedBetween":[40,59]}}}}', extra='')

 2023-08-22 19:43:02.052 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"controller","event":"statistics updated","statistics":{"messagesTX":55,"messagesRX":141,"messagesDroppedRX":0,"NAK":0,"CAN":0,"timeoutACK":0,"timeoutResponse":0,"timeoutCallback":0,"messagesDroppedTX":0,"backgroundRSSI":{"channel0":{"current":-74,"average":-74},"channel1":{"current":-77,"average":-79},"timestamp":1692747775765}}}}', extra='')

 2023-08-22 19:43:02.066 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"result","success":false,"messageId":"241ff4f07991499db1f62473c6906d11","errorCode":"zwave_error","zwaveErrorCode":1405,"zwaveErrorMessage":"The node failed to decode the message. (ZW1405)"}', extra='')

 2023-08-22 19:43:02.067 ERROR (MainThread) [homeassistant.components.zwave_js] Unable to set value 59-38-0-targetValue: Z-Wave error 1405: The node failed to decode the message. (ZW1405)
 2023-08-22 19:43:02.069 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140624612323088]
 Traceback (most recent call last):
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/components/zwave_js/entity.py", line 318, in _async_set_value
     return await self.info.node.async_set_value(
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/zwave_js_server/model/node/__init__.py", line 490, in async_set_value
     result = await self.async_send_command(
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/zwave_js_server/model/node/__init__.py", line 447, in async_send_command
     result = await self.client.async_send_command(message, **kwargs)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/zwave_js_server/client.py", line 116, in async_send_command
     return await future
            ^^^^^^^^^^^^
 zwave_js_server.exceptions.FailedZWaveCommand: Z-Wave error 1405: The node failed to decode the message. (ZW1405)

 The above exception was the direct cause of the following exception:

 Traceback (most recent call last):
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/components/websocket_api/commands.py", line 205, in handle_call_service
     await hass.services.async_call(
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/core.py", line 1965, in async_call
     response_data = await coro
                     ^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/core.py", line 2005, in _execute_service
     return await cast(
            ^^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/helpers/entity_component.py", line 235, in handle_service
     return await service.entity_service_call(
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/helpers/service.py", line 848, in entity_service_call
     response_data = task.result()  # pop exception if have
                     ^^^^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/helpers/entity.py", line 1192, in async_request_call
     return await coro
            ^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/helpers/service.py", line 892, in _handle_entity_call
     result = await task
              ^^^^^^^^^^
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/components/light/__init__.py", line 582, in async_handle_light_on_service
     await light.async_turn_on(**filter_turn_on_params(light, params))
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/components/zwave_js/light.py", line 293, in async_turn_on
     await self._async_set_brightness(kwargs.get(ATTR_BRIGHTNESS), transition)
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/components/zwave_js/light.py", line 351, in _async_set_brightness
     await self._async_set_value(
   File "/lsiopy/lib/python3.11/site-packages/homeassistant/components/zwave_js/entity.py", line 323, in _async_set_value
     raise HomeAssistantError from err
 homeassistant.exceptions.HomeAssistantError
 2023-08-22 19:43:02.080 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"statistics updated","nodeId":59,"statistics":{"commandsTX":5,"commandsRX":6,"commandsDroppedRX":1,"commandsDroppedTX":0,"timeoutResponse":0,"rtt":215.3,"lastSeen":"2023-08-22T23:43:02.055Z","rssi":-54,"lwr":{"protocolDataRate":2,"repeaters":[14],"rssi":-54,"repeaterRSSI":[-72]},"nlwr":{"protocolDataRate":2,"repeaters":[40],"rssi":-54,"repeaterRSSI":[-77],"routeFailedBetween":[40,59]}}}}', extra='')

 2023-08-22 19:43:02.309 DEBUG (MainThread) [zwave_js_server] Received message:
 WSMessage(type=<WSMsgType.TEXT: 1>, data='{"type":"event","event":{"source":"node","event":"statistics updated","nodeId":59,"statistics":{"commandsTX":5,"commandsRX":7,"commandsDroppedRX":1,"commandsDroppedTX":0,"timeoutResponse":0,"rtt":215.3,"lastSeen":"2023-08-22T23:43:02.140Z","rssi":-54,"lwr":{"protocolDataRate":2,"repeaters":[14],"rssi":-54,"repeaterRSSI":[-72]},"nlwr":{"protocolDataRate":2,"repeaters":[40],"rssi":-54,"repeaterRSSI":[-77],"routeFailedBetween":[40,59]}}}}', extra='')

Failed Zwave-JS logs for second event:

23:43:01.396 CNTRLR « [Node 059] received CentralScene notification {
                          "nodeId": 59,
                          "ccId": "Central Scene",
                          "ccCommand": "0x03",
                          "payload": "0x138301"
                      }
23:43:01.745 CNTRLR   [Node 059] failed to decode the message, retrying with SPAN extension...
23:43:02.055 CNTRLR   [Node 059] failed to decode the message after re-transmission with SPAN extens
                      ion, dropping the message.
2023-08-22 23:43:02.061 ERROR Z-WAVE-SERVER: The node failed to decode the message. (ZW1405)
ZWaveError: The node failed to decode the message. (ZW1405)
    at Driver.sendMessage (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:4768:23)
    at Driver.sendCommandInternal (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:4965:28)
    at Driver.sendSupervisedCommand (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:5010:27)
    at Driver.sendCommand (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:5058:30)
    at Proxy.set (/usr/src/app/node_modules/@zwave-js/cc/src/cc/MultilevelSwitchCC.ts:251:24)
    at Proxy.<anonymous> (/usr/src/app/node_modules/@zwave-js/cc/src/cc/MultilevelSwitchCC.ts:327:17)
    at ZWaveNode.setValue (/usr/src/app/node_modules/zwave-js/src/lib/node/Node.ts:1123:39)
    at NodeMessageHandler.handle (/usr/src/app/node_modules/@zwave-js/server/dist/lib/node/message_handler.js:20:43)
    at Object.node (/usr/src/app/node_modules/@zwave-js/server/dist/lib/server.js:42:96)
    at Client.receiveMessage (/usr/src/app/node_modules/@zwave-js/server/dist/lib/server.js:107:99)
23:43:02.142 CNTRLR « [Node 059] received S2 nonce without an active transaction, not sure what to d
                      o with it

What version of Home Assistant Core has the issue?

2023.7.3

What was the last working version of Home Assistant Core?

Maaaybe 2023.2.x - but I think I was seeing problems there that I didn't investigate

What type of installation are you running?

Home Assistant Container

Integration causing the issue

zwavejs

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zwave_js/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

home-assistant[bot] commented 1 year ago

Hey there @home-assistant/z-wave, mind taking a look at this issue as it has been labeled with an integration (zwave_js) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `zwave_js` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign zwave_js` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)

zwave_js documentation zwave_js source (message by IssueLinks)

issue-triage-workflows[bot] commented 10 months ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.