Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
12 tasks
kreene1987 opened this issue Mar 25, 2021 · 12 comments · Fixed by #2167
Closed
12 tasks

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

kreene1987 opened this issue Mar 25, 2021 · 12 comments · Fixed by #2167
Labels
investigate 🔎 Not sure what's going on here - need to investigate waiting for info ⏳
Projects
Triage

Comments

@kreene1987
Copy link
Contributor

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.
@kreene1987 kreene1987 added the bug Something isn't working label Mar 25, 2021
@zwave-js-bot zwave-js-bot added this to Needs triage in Triage Mar 25, 2021
@AlCalzone
Copy link
Member

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

@kreene1987
Copy link
Contributor Author

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

@raman325
Copy link
Contributor

raman325 commented Mar 25, 2021 •
edited
Loading

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

@AlCalzone AlCalzone added investigate 🔎 Not sure what's going on here - need to investigate waiting for info ⏳ and removed bug Something isn't working labels Mar 25, 2021
@firstof9
Copy link
Contributor

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
Copy link
Collaborator

blhoward2 commented Mar 26, 2021 •
edited
Loading

@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
Copy link
Contributor

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

@AlCalzone
Copy link
Member

@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
Copy link
Contributor

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
Copy link
Collaborator

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

@AlCalzone
Copy link
Member

Yup sounds like a good idea

@blhoward2 blhoward2 mentioned this issue Mar 27, 2021
Merged
Triage automation moved this from Needs triage to Closed Mar 27, 2021
@blhoward2 blhoward2 mentioned this issue Apr 7, 2021
Closed
@kreene1987
Copy link
Contributor Author

kreene1987 commented Apr 28, 2021 •
edited
Loading

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
Copy link
Contributor

Please create a new issue for this.

@kreene1987 kreene1987 mentioned this issue Apr 28, 2021
Closed
@itpeters itpeters mentioned this issue Oct 26, 2021
Closed
11 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
investigate 🔎 Not sure what's going on here - need to investigate waiting for info ⏳
Projects
No open projects
Triage
Closed
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix: remove Supervision CC from LZW36 due to firmware bug blhoward2/node-zwave-js
5 participants
@firstof9 @raman325 @AlCalzone @kreene1987 @blhoward2