zwave-js / node-zwave-js

Z-Wave driver written entirely in JavaScript/TypeScript
https://zwave-js.github.io/node-zwave-js/
MIT License
741 stars 596 forks source link

[question] Migrated from OpenZwave - Difficulties with almost all devices #1689

Closed zeddski closed 3 years ago

zeddski commented 3 years ago

Last week migrated from OpenZwave to Zwave-JS. Network key seems to be correct, since the right amount of devices are listed. But, information about the devices is gone. Sometimes one of the non-battery-devices returns for a little while, then disappears again. I'm using Home Assistant too (both in a container).

I've enabled logging, which isn't helping much yet. I'm concentrating on two devices. Node 5, which is a Zwave power plug and Node 18 which is a battery powered PIR (motion sensor). The PIR shows up in logs, but no information is shown in the device listing. Removing and re-associating gives me a new device with (again) no information.

So, let's concentrate on Node 5, because that node logs every few minutes. As can be seen below, it logs "has returned", just to immediatly be declared dead again. After a few seconds, the node's information rolls down the screen. Every five minutes something lkie this happens again: it gets declared dead, with some updated values directly following the RIP report (limited to 3 log rules, not as extensive as this example).

Does anyone have a clue to what might be going on and how to debug further?

2021-02-09 21:15:08.589 INFO ZWAVE: Node 5: has returned from the dead 2021-02-09 21:15:12.740 INFO ZWAVE: Node 5 is now dead 2021-02-09 21:15:16.888 ERROR ZWAVE: Interview of node 5 has failed: The node is dead 2021-02-09 21:18:24.518 INFO ZWAVE: Node 15: value updated: 50-0-value-65537 199.72 => 199.72 2021-02-09 21:18:24.521 INFO ZWAVE: Node 15: value updated: 50-0-previousValue-65537 199.72 => 199.72 2021-02-09 21:18:24.524 INFO ZWAVE: Node 15: value updated: 50-0-deltaTime-65537 301 => 301 2021-02-09 21:18:24.535 INFO ZWAVE: Node 15: has returned from the dead 2021-02-09 21:18:24.592 INFO ZWAVE: Node 15: value added 15-37-0-currentValue => true 2021-02-09 21:18:24.594 INFO ZWAVE: Node 15: value added 15-37-0-targetValue => undefined 2021-02-09 21:18:24.596 INFO ZWAVE: Node 15: value added 15-50-0-value-65537 => 199.72 2021-02-09 21:18:24.598 INFO ZWAVE: Node 15: value added 15-50-0-deltaTime-65537 => 301 2021-02-09 21:18:24.600 INFO ZWAVE: Node 15: value added 15-50-0-previousValue-65537 => 199.72 2021-02-09 21:18:24.601 INFO ZWAVE: Node 15: value added 15-50-0-value-66049 => 0 2021-02-09 21:18:24.603 INFO ZWAVE: Node 15: value added 15-50-0-previousValue-66049 => 0 2021-02-09 21:18:24.605 INFO ZWAVE: Node 15: value added 15-50-0-deltaTime-66049 => 12 2021-02-09 21:18:24.606 INFO ZWAVE: Node 15: value added 15-50-0-value-66561 => 228.16 2021-02-09 21:18:24.608 INFO ZWAVE: Node 15: value added 15-50-0-previousValue-66561 => 228.24 2021-02-09 21:18:24.610 INFO ZWAVE: Node 15: value added 15-50-0-deltaTime-66561 => 15 2021-02-09 21:18:24.613 INFO ZWAVE: Node 15: value added 15-50-0-value-66817 => 0 2021-02-09 21:18:24.614 INFO ZWAVE: Node 15: value added 15-50-0-previousValue-66817 => 0 2021-02-09 21:18:24.616 INFO ZWAVE: Node 15: value added 15-50-0-deltaTime-66817 => 37 2021-02-09 21:18:24.618 INFO ZWAVE: Node 15: value added 15-50-0-reset => undefined 2021-02-09 21:18:24.619 INFO ZWAVE: Node 15: value added 15-112-0-1 => 1 2021-02-09 21:18:24.621 INFO ZWAVE: Node 15: value added 15-112-0-2 => 300 2021-02-09 21:18:24.643 INFO ZWAVE: Node 15: value added 15-112-0-3 => 13 2021-02-09 21:18:24.652 INFO ZWAVE: Node 15: value added 15-112-0-4 => 12 2021-02-09 21:18:24.655 INFO ZWAVE: Node 15: value added 15-112-0-5 => 1 2021-02-09 21:18:24.656 INFO ZWAVE: Node 15: value added 15-112-0-6 => 5 2021-02-09 21:18:24.657 INFO ZWAVE: Node 15: value added 15-112-0-7 => 1 2021-02-09 21:18:24.659 INFO ZWAVE: Node 15: value added 15-112-0-8 => 0 2021-02-09 21:18:24.660 INFO ZWAVE: Node 15: value added 15-112-0-9 => 150 2021-02-09 21:18:24.663 INFO ZWAVE: Node 15: value added 15-112-0-10 => 1 2021-02-09 21:18:24.664 INFO ZWAVE: Node 15: value added 15-113-0-alarmType => undefined 2021-02-09 21:18:24.666 INFO ZWAVE: Node 15: value added 15-113-0-alarmLevel => undefined 2021-02-09 21:18:24.667 INFO ZWAVE: Node 15: value added 15-114-0-manufacturerId => 600 2021-02-09 21:18:24.668 INFO ZWAVE: Node 15: value added 15-114-0-productType => 3 2021-02-09 21:18:24.669 INFO ZWAVE: Node 15: value added 15-114-0-productId => 4231 2021-02-09 21:18:24.670 INFO ZWAVE: Node 15: value added 15-134-0-libraryType => 3 2021-02-09 21:18:24.671 INFO ZWAVE: Node 15: value added 15-134-0-protocolVersion => 4.5 2021-02-09 21:18:24.672 INFO ZWAVE: Node 15: value added 15-134-0-firmwareVersions => 3.94 2021-02-09 21:18:24.673 INFO ZWAVE: Node 15: value added 15-134-0-hardwareVersion => undefined 2021-02-09 21:18:24.678 INFO ZWAVE: Node 15 ready: Shenzhen Neo Electronics Co., Ltd. - NAS-WR01ZE (Wall Plug Switch) 2021-02-09 21:18:28.842 INFO ZWAVE: Node 15 is now dead 2021-02-09 21:18:33.070 ERROR ZWAVE: Interview of node 15 has failed: The node is dead

robertsLando commented 3 years ago

@zeddski Please attach logs. Follow: https://zwave-js.github.io/zwavejs2mqtt/#/troubleshooting/bug_report

zeddski commented 3 years ago

Thanks Robert, relevant logs attached. zwavejs2mqtt.log

robertsLando commented 3 years ago

@zeddski I also need zwavejs logs please :)

robertsLando commented 3 years ago

From zwavejs2mqtt logs i can only see the interviews fails, I don't know why

zeddski commented 3 years ago

zwavejs_1.log zwavejs2mqtt.log

I made two new ones, so the timestamps match. Curious to what you can figure out of these...

robertsLando commented 3 years ago

@AlCalzone Could you give the logs a check? Seems that the Interview process fails on the RequestNodeInfo

AlCalzone commented 3 years ago

From what I'm seeing in the logs, I'm getting the feeling that Node 5 has really bad connectivity. It does respond from time to time, but most commands result in

09:45:45.215 DRIVER « [REQ] [SendData]
                        callback id:     12
                        transmit status: NoAck

which means the protocol-level acknowledgement that tells us a message was received didn't come back. My first thought went to "this thing sleeps and didn't tell the controller", but power plugs usually don't do that, since they are permanently powered.

Do you have a chance to move the device closer to the controller to test if that improves the situation? If so, a network heal could solve your issue.

zeddski commented 3 years ago

OK, what I did:

I do appreciate all the attention :)

zwavejs_1.log zwavejs2mqtt.log

AlCalzone commented 3 years ago

I don't see the node going dead in the new log. So looks to me like it was a connectivity issue. I'd put the node back where it belongs and perform a network heal, so the routes can be regenerated.

ivdimitro commented 3 years ago

Hi, I have similar issue with a device which goes through a plug to the controller.

[Node 005] did not respond after 1/3 attempts. Scheduling next try in 500 ms.

I also see this message and the device is declared dead only to be revived in less than a second with subsequent messages. @AlCalzone do you think increasing the 500ms waiting period can help with remote devices or the ones that go over multiple hops?

AlCalzone commented 3 years ago

That message is a result of the controller callback, which we have no control over. The 500ms is the wait time before we try sending again. Increasing that won't help if the ACK does not come back.

zeddski commented 3 years ago

I don't see the node going dead in the new log. So looks to me like it was a connectivity issue. I'd put the node back where it belongs and perform a network heal, so the routes can be regenerated.

So it seems. It even helped "finding" other devices that were gone. I'll put a node between this Node 15 and the zwave-server, to increase network coverage.

Leaves me with node 18, the PIR. It is sitting very close to the server but still, it doesn't show up in the device listing. Walking through the logs, it does show up now and then in the Zwave-logs, but very sporadic, even though I've triggered the PIR a lot. Several other devices (like a door sensor) don't show up either, although they are fairly close to the server. And remember: a week ago, when I was still using Open Zwave, all these devices worked fine. I'll do a network heal anyway, but hints and new insights remain very welcome!

zwavejs2mqtt.log zwavejs_1.log

AlCalzone commented 3 years ago

Node 18 does not respond to any node info query, so we don't know what it supports. OZW likely already did, which is why it used to work. It also sends all its reports as broadcast, so it seems like it is set up strangely.

Node 14 for example is registered as a listening (always on) device, but does not acknowledge any messages.

Network heal is probably a good idea.

zeddski commented 3 years ago

I've been able to get Node018 to provide information through a "re-interview" command and forcably waking up the device. I needed to re-awake it several times, but FINALLY it shows up in the WebUI, correctly. For anyone who's interested: waking up the device meant putting it in association mode by pressing the button three times. I did this no more than four times with 20 second intervals, which led to my final success. For future reference, I've included the relevant logs.

Thanks for all the help! I'll move the ZWave-part to a different RPI and place that one on a more central location in my house. Under the stairs, probably...

zwavejs_1.log zwavejs2mqtt.log

AlCalzone commented 3 years ago

For anyone who's interested: waking up the device meant putting it in association mode by pressing the button three times.

Yep, it is a common misconception that if a device does something it must mean that it is awake. Short - it is not and you have to physically wake it up with a button push or something.