Inovelli LZW36 - Light turning off reliably after ~2 hr 10 min

[kreene1987]

Checklist:

• [X ] I am not using HomeAssistant. Or: a developer has told me to come here.
• [X ] I am not using ZWaveJS2MQTT. Or: a developer has told me to come here.
• [X ] I have checked the troubleshooting section and my problem is not described there.
• [X ] I have read the changelog and my problem was not mentioned there.

Describe the bug

After a reliable amount of time (near 2hr 10min), Inovelli and Home Assistant users on ZJS are experiencing the "Fan" endpoint of the device turning off. This is only when controlled "ON" by Home Assistant, not when the light is physically toggled.

Device information

Inovelli LZW36 Node ID: 16

Did you change anything?

• [ ] Yes: (please describe)
• [X ] No

Did this use to work before?

• [X ] Don't know, this is a new device
• [ ] No, it never worked anywhere
• [ ] Yes, in: (specify application with versions)

How are you using node-zwave-js

• [ ] zwavejs2mqtt (latest) docker image
• [ ] zwavejs2mqtt (dev) docker image
• [ ] zwavejs2mqtt Manual Docker build
  • node-zwave-js branch:
  • zwavejs2mqtt branch:
• [ ] ioBroker.zwave2 adapter
• [X ] HomeAssistant version 2021.3.4
• [ ] Pkg
• [ ] Manual Docker build
  • node-zwave-js branch:
  • zwavejs2mqtt branch:
• [ ] node-red-contrib-zwave-js
  • Module version (double click node):
• [ ] Manually built (as described in the docs)
• [ ] Other:

To Reproduce

Steps to reproduce the behavior: 1) Turn on light endpoint via HA 2) Light automatically turns off after period of time.

Additional context

Did not seem to be the case on earlier versions of ZJS integration into HA.

Logfile: Incoming, will replace once available.

[AlCalzone]

Let me know when you have a log. This seems oddly specific and I would assume this is some really weird interaction.

[kreene1987]

Cross-reference: https://community.inovelli.com/t/lzw36-light-randomly-turning-off/7531

[raman325]

Can you turn on debug logging for zwave-js-server and the HA integration and include those as well? The combination of the three logs (zwave-js, zwave-js-server, and the integration) will help narrow this down more quickly. You can add the following to your configuration.yaml to enable debug logs:

logger:
  default: info
  logs:
    zwave_js_server: debug
    homeassistant.components.zwave_js: debug

You can also call the logger.set_level service with the following payload to turn on the debug logs temporarily and without requiring a restart (it will reset after the next restart):

zwave_js_server: debug
homeassistant.components.zwave_js: debug

[firstof9]

Here's my log of the switch rebooting itself, it doesn't look like anything happens from zwave-js prior to the reboot. This log is long, the switch reboots itself near the end Node 043.

zwavejs_1.log

[blhoward2]

@firstof9 So is this where the reboot happens?

2021-03-26T00:02:01.117Z CNTRLR   [Node 043] [~] [Multilevel Switch] currentValue: 0 => 0           [Endpoint 2]
2021-03-26T00:02:01.122Z SERIAL » [ACK]                                                                   (0x06)
2021-03-26T00:02:01.136Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      2
                                    │ destination: 0
                                    └─[MultilevelSwitchCCReport]
                                        current value: 0
2021-03-26T00:02:03.533Z SERIAL « 0x01100004001e0a320221740000000000009a                              (18 bytes)
2021-03-26T00:02:03.535Z CNTRLR   [Node 030] [~] [Meter] value[66049]: 0 => 0                       [Endpoint 0]
2021-03-26T00:02:03.538Z SERIAL » [ACK]                                                                   (0x06)
2021-03-26T00:02:05.297Z SERIAL « 0x010d0004002b07600d010026034bd8                                    (15 bytes)
2021-03-26T00:02:05.299Z CNTRLR   [Node 043] [~] [Multilevel Switch] currentValue: 75 => 75         [Endpoint 1]
2021-03-26T00:02:05.302Z SERIAL » [ACK]                                                                   (0x06)
2021-03-26T00:02:05.306Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      1
                                    │ destination: 0
                                    └─[MultilevelSwitchCCReport]
                                        current value: 75
2021-03-26T00:02:09.807Z SERIAL » 0x0109001302022602258763                                            (11 bytes)
2021-03-26T00:02:09.814Z SERIAL « [ACK]                                                                   (0x06)
2021-03-26T00:02:09.818Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2021-03-26T00:02:09.819Z SERIAL » [ACK]                                                                   (0x06)
2021-03-26T00:02:09.821Z DRIVER « [RES] [SendData]
                                    was sent: true
2021-03-26T00:02:09.839Z SERIAL « 0x01070013870000026e                                                 (9 bytes)
2021-03-26T00:02:09.840Z SERIAL » [ACK]                                                                   (0x06)
2021-03-26T00:02:09.842Z DRIVER « [REQ] [SendData]
                                    callback id:     135
                                    transmit status: OK

Which would make this the change in HA that triggered the state ~2 hours before?

2021-03-25T21:51:47.203Z SERIAL » 0x011200132b0b600d00016c0184032601ff256fca                          (20 bytes)
2021-03-25T21:51:47.205Z DRIVER » [Node 043] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      111
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      0
                                    │ destination: 1
                                    └─[SupervisionCCGet]
                                      │ session id:      4
                                      │ request updates: true
                                      └─[MultilevelSwitchCCSet]
                                          target value: 255
2021-03-25T21:51:47.210Z SERIAL « [ACK]                                                                   (0x06)
2021-03-25T21:51:47.216Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2021-03-25T21:51:47.217Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:47.218Z DRIVER « [RES] [SendData]
                                    was sent: true
2021-03-25T21:51:47.230Z SERIAL « 0x010700136f00000286                                                 (9 bytes)
2021-03-25T21:51:47.231Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:47.232Z DRIVER « [REQ] [SendData]
                                    callback id:     111
                                    transmit status: OK
2021-03-25T21:51:47.252Z SERIAL « 0x010f0004002b09600d01006c0203ff0028                                (17 bytes)
2021-03-25T21:51:47.253Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:47.256Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      1
                                    │ destination: 0
                                    └─[SupervisionCCReport]
                                        session id:          3
                                        more updates follow: false
                                        status:              Success
                                        duration:            [Duration: 0seconds]
2021-03-25T21:51:47.259Z CNTRLR « [Node 043] Received update for a Supervision session
2021-03-25T21:51:47.267Z SERIAL « 0x010f0004002b09600d01006c028401feaf                                (17 bytes)
2021-03-25T21:51:47.268Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:47.270Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      1
                                    │ destination: 0
                                    └─[SupervisionCCReport]
                                        session id:          4
                                        more updates follow: true
                                        status:              Working
                                        duration:            [Duration: unknown]
2021-03-25T21:51:47.281Z SERIAL » 0x010d00132b06600d000126022570d1                                    (15 bytes)
2021-03-25T21:51:47.282Z DRIVER » [Node 043] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      112
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      0
                                    │ destination: 1
                                    └─[MultilevelSwitchCCGet]
2021-03-25T21:51:47.286Z SERIAL « [ACK]                                                                   (0x06)
2021-03-25T21:51:47.291Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2021-03-25T21:51:47.292Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:47.293Z DRIVER « [RES] [SendData]
                                    was sent: true
2021-03-25T21:51:47.305Z SERIAL « 0x010700137000000299                                                 (9 bytes)
2021-03-25T21:51:47.306Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:47.308Z DRIVER « [REQ] [SendData]
                                    callback id:     112
                                    transmit status: OK
2021-03-25T21:51:47.325Z SERIAL « 0x010f0004002b09600d01002603014b03d6                                (17 bytes)
2021-03-25T21:51:47.327Z CNTRLR   [Node 043] [~] [Multilevel Switch] targetValue: 255 => 75         [Endpoint 1]
2021-03-25T21:51:47.335Z CNTRLR   [Node 043] [~] [Multilevel Switch] duration: {"value":3,"unit":"s [Endpoint 1]
                                  econds"} => {"value":3,"unit":"seconds"}
2021-03-25T21:51:47.338Z CNTRLR   [Node 043] [~] [Multilevel Switch] currentValue: 0 => 1           [Endpoint 1]
2021-03-25T21:51:47.340Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:47.344Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      1
                                    │ destination: 0
                                    └─[MultilevelSwitchCCReport]
                                        current value: 1
                                        target value:  75
                                        duration:      [Duration: 3seconds]
2021-03-25T21:51:51.434Z SERIAL « 0x010d0004002b07600d010026034bd8                                    (15 bytes)
2021-03-25T21:51:51.436Z CNTRLR   [Node 043] [~] [Multilevel Switch] currentValue: 1 => 75          [Endpoint 1]
2021-03-25T21:51:51.439Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:51.442Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      1
                                    │ destination: 0
                                    └─[MultilevelSwitchCCReport]
                                        current value: 75
2021-03-25T21:51:56.693Z SERIAL » 0x0109001302022602257195                                            (11 bytes)
2021-03-25T21:51:56.697Z SERIAL « [ACK]                                                                   (0x06)
2021-03-25T21:51:56.703Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2021-03-25T21:51:56.704Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:56.706Z DRIVER « [RES] [SendData]
                                    was sent: true
2021-03-25T21:51:56.757Z SERIAL « 0x01070013710000069c                                                 (9 bytes)
2021-03-25T21:51:56.758Z SERIAL » [ACK]                                                                   (0x06)
2021-03-25T21:51:56.760Z DRIVER « [REQ] [SendData]
                                    callback id:     113
                                    transmit status: OK

@AlCalzone OZW doesn't support supervision, right? Could this be a fw bug resulting from a supervision command? We could try disabling that CC and see if it fixes the device, which would pinpoint the bug to that section of the fw? Or rule out that one difference between us and OZW where this isn't happening? It would explain why this only happens upon switching to zwave-js.

Edit: @firstof9 is going to test my crazy theory in the morning by adding the compat flag manually to disable Supervision.

[firstof9]

I'm gonna say yes, that's the only thing that shows up in the logs when the thing RGBed me.

[AlCalzone]

@blhoward2 You could be right - there's at least something the device does incorrectly in regards to Supervision.

When the device is first controlled with supervision, it immediately reports success for a supervision session we never used (0):

2021-03-25T21:51:37.543Z DRIVER » [Node 043] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      109
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      0
                                    │ destination: 1
                                    └─[SupervisionCCGet]
                                      │ session id:      3      <-- HERE!
                                      │ request updates: true
                                      └─[MultilevelSwitchCCSet]
                                          target value: 0

...

2021-03-25T21:51:37.596Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[SupervisionCCReport]
                                      session id:          0       <-- HERE!
                                      more updates follow: false
                                      status:              Success
                                      duration:            [Duration: 0seconds]

It then reports that the command we sent is in progress:

2021-03-25T21:51:37.614Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      1
                                    │ destination: 0
                                    └─[SupervisionCCReport]
                                        session id:          3
                                        more updates follow: true
                                        status:              Working
                                        duration:            [Duration: unknown]

10 seconds later when the device is turned back on with

2021-03-25T21:51:47.205Z DRIVER » [Node 043] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      111
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      0
                                    │ destination: 1
                                    └─[SupervisionCCGet]
                                      │ session id:      4
                                      │ request updates: true
                                      └─[MultilevelSwitchCCSet]
                                          target value: 255

we receive the final message for the previous session and the response that our current command is in progress:

2021-03-25T21:51:47.256Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      1
                                    │ destination: 0
                                    └─[SupervisionCCReport]
                                        session id:          3
                                        more updates follow: false
                                        status:              Success
                                        duration:            [Duration: 0seconds]
...
2021-03-25T21:51:47.270Z DRIVER « [Node 043] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      1
                                    │ destination: 0
                                    └─[SupervisionCCReport]
                                        session id:          4
                                        more updates follow: true
                                        status:              Working
                                        duration:            [Duration: unknown]

The final update for this never comes.

[firstof9]

After the modifications to disable the supervision CC the switch seems to no longer "reboot" itself.

Attached is the log from the whole 2+hrs of debug.

zwavejs2mqtt-store (1).zip

[blhoward2]

@AlCalzone Ive informed Inovelli. Should I push a PR to add the compat flag for now until it's fixed?

[AlCalzone]

Yup sounds like a good idea

[kreene1987]

I am now experiencing this with my LZW36. Turning on and off fan in Home Assistant turns on and off the light entity along with the fan.

Debug Logs: 2021-04-28T16:24:09.937Z CNTRLR [Node 075] Mapping unsolicited report from root device to first supporting end point #1 2021-04-28T16:24:10.597Z CNTRLR [Node 075] Mapping unsolicited report from root device to first supporting end point #1

Also might be related to #2154

Running v 0.1.20

[firstof9]

Please create a new issue for this.