[SOLVED] Z-Wave devices remain unknown after update

Tags: #<Tag:0x00007f74648b1548>

You are getting huge timeouts from node 7:

grafik

Try removing it from the controller, set it as failed, then click remove (advanced thing menu in HABmin).

I’m having similar problems with a Leviton dimmer plug in switch. If I move it real close to the unit it seems to sync up. Enough to get the channels in OpenHAB. Then when I move it to it’s destination and heal it’s there, but eventually gives a communication error. Funny thing it is slow but still responds to commands. So not sure if it’s a distance thing or what. Just sharing other device types are having this issue as well. On the same OH version and using the latest snapshot as of yesterday.

As a side note, if I try and change the Command Poll Period from 1500 to like 3000 which some say helps the communication error, it won’t stay. Looks like I can only “select” 1500 or Disabled.

JR

I ran into this issue now…
I dumped my old setup and installed a fresh openhab 2.5M1 the other day. I didnt exclude my devices from the dongle, ofcuse.
I used the 2.5M1 zwave binding from PaperUI, but on scanning, it finds my devices, but they´re all unknown…
A few minutes ago, I just updated the zwave binding to the latest snapshot… But again, my devices returns unknown on scanning…
Anyone have any idea why? I can seem to figure this one, though zwave has been running awesome for quite some time.

This is the binding I´m using now:

openhab> bundle:list -s |grep -i zwave
193 x Active   x  80 x 2.5.0.201906131958     x org.openhab.binding.zwave
openhab>

bundle:restart 193

Nope, doesnt fix it… I just clear the cahce/tmp and rebooted after upgrading the binding. Didnt help either

Check your logs if you have a problem with the serial driver (Controller should also be offline in this case) or if you have a problem with this issue:

Controller is ONLINE - Otherweise it wouldnt be able to scan for the devices :slight_smile:

I dont…

openhab> bundle:list -s |grep -i xstream
192 x Active   x  80 x 1.4.7.1                x org.apache.servicemix.bundles.xstream
openhab>

Actually, I notice that @5iver latest script install this jar as well.

Hmm… I think I found the reason…

ARRRGH!! :rage:

That comment is for the zigbee binding, although it is in a zwave thread.

Then I need some more advices… I simply cant get the stick to “read” the devices correctly…
@chris do you have any suggestions here?

No really - what is in the log?

Not really much I think. This is a debug log, few minutes old when I tried to scan the devices again:

2019-06-16 21:49:51.497 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:1239387c
2019-06-16 21:49:51.502 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeDone
2019-06-16 21:49:51.507 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2019-06-16 21:49:51.511 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2019-06-16 21:49:51.516 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:1239387c
2019-06-16 21:49:51.519 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2019-06-16 21:49:51.525 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-06-16 21:49:51.529 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2019-06-16 21:49:51.534 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2019-06-16 21:49:51.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 465 to queue - size 1
2019-06-16 21:49:51.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-06-16 21:49:51.545 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 90 E1 
2019-06-16 21:49:51.548 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 90 E1 
2019-06-16 21:49:51.550 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-06-16 21:49:51.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 465: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 144

2019-06-16 21:49:53.556 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2019-06-16 21:49:53.599 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.

2019-06-16 21:49:53.607 [home.event.InboxAddedEvent] - Discovery Result with UID 'zwave:device:1239387c:node3' has been added.

2019-06-16 21:49:53.606 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1239387c:node3' to inbox.
2019-06-16 21:49:53.614 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery completed
2019-06-16 21:49:53.645 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery could not resolve to a thingType! Manufacturer data not known.
2019-06-16 21:49:53.650 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1239387c:node5' to inbox.
2019-06-16 21:49:53.653 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 8: Device discovery completed
2019-06-16 21:49:53.663 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 8: Device discovery could not resolve to a thingType! Manufacturer data not known.
2019-06-16 21:49:53.683 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1239387c:node8' to inbox.
2019-06-16 21:49:53.685 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery completed
2019-06-16 21:49:53.695 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery could not resolve to a thingType! Manufacturer data not known.
2019-06-16 21:49:53.701 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1239387c:node10' to inbox.
2019-06-16 21:49:53.704 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovery completed
2019-06-16 21:49:53.713 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovery could not resolve to a thingType! Manufacturer data not known.
2019-06-16 21:49:53.719 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1239387c:node11' to inbox.
2019-06-16 21:49:53.722 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery completed
2019-06-16 21:49:53.724 [home.event.InboxAddedEvent] - Discovery Result with UID 'zwave:device:1239387c:node5' has been added.
2019-06-16 21:49:53.733 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery could not resolve to a thingType! Manufacturer data not known.
2019-06-16 21:49:53.743 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1239387c:node12' to inbox.
2019-06-16 21:49:53.746 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery completed
2019-06-16 21:49:53.758 [home.event.InboxAddedEvent] - Discovery Result with UID 'zwave:device:1239387c:node8' has been added.
2019-06-16 21:49:53.757 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery could not resolve to a thingType! Manufacturer data not known.
2019-06-16 21:49:53.760 [home.event.InboxAddedEvent] - Discovery Result with UID 'zwave:device:1239387c:node10' has been added.
2019-06-16 21:49:53.764 [home.event.InboxAddedEvent] - Discovery Result with UID 'zwave:device:1239387c:node11' has been added.
2019-06-16 21:49:53.768 [home.event.InboxAddedEvent] - Discovery Result with UID 'zwave:device:1239387c:node12' has been added.
2019-06-16 21:49:53.773 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1239387c:node13' to inbox.
2019-06-16 21:49:53.778 [home.event.InboxAddedEvent] - Discovery Result with UID 'zwave:device:1239387c:node13' has been added.

2019-06-16 21:49:56.556 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 465: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-06-16 21:49:56.562 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 465: Transaction is current transaction, so clearing!!!!!
2019-06-16 21:49:56.565 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 465: Transaction CANCELLED
2019-06-16 21:49:56.570 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:465 CANCELLED
2019-06-16 21:49:56.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-06-16 21:50:21.520 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:1239387c
2019-06-16 21:50:21.522 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeSent
2019-06-16 21:50:21.524 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-06-16 21:50:21.526 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 466 to queue - size 1
2019-06-16 21:50:21.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-06-16 21:50:21.530 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 91 24 
2019-06-16 21:50:21.532 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 91 24 
2019-06-16 21:50:21.533 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-06-16 21:50:21.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 466: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 145

2019-06-16 21:50:26.536 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 466: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-06-16 21:50:26.538 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 466: Transaction is current transaction, so clearing!!!!!
2019-06-16 21:50:26.540 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 466: Transaction CANCELLED
2019-06-16 21:50:26.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:466 CANCELLED
2019-06-16 21:50:26.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-06-16 21:50:36.551 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion timer at IncludeDone

==> /var/log/openhab2/openhab.log <==

2019-06-16 21:51:59.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@166e4d9
2019-06-16 21:51:59.414 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
2019-06-16 21:51:59.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Added 467 to queue - size 6
2019-06-16 21:51:59.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-06-16 21:51:59.426 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 05 9E 
2019-06-16 21:51:59.430 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 05 9E 
2019-06-16 21:51:59.433 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-06-16 21:51:59.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 467: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0

2019-06-16 21:52:01.438 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 5: TID 467: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-06-16 21:52:01.441 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 467: Transaction is current transaction, so clearing!!!!!
2019-06-16 21:52:01.444 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 467: Transaction CANCELLED
2019-06-16 21:52:01.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:467 CANCELLED
2019-06-16 21:52:01.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-06-16 21:52:01.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 467: Transaction event listener: DONE: CANCELLED -> 
2019-06-16 21:52:01.456 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@187cf8d

==> /var/log/openhab2/openhab.log <==

2019-06-16 21:53:30.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1d77b28
2019-06-16 21:53:30.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
2019-06-16 21:53:30.340 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Added 468 to queue - size 6
2019-06-16 21:53:30.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-06-16 21:53:30.344 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 92 21 
2019-06-16 21:53:30.346 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 92 21 
2019-06-16 21:53:30.347 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-06-16 21:53:30.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 468: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 146

2019-06-16 21:53:35.350 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 1: TID 468: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-06-16 21:53:35.352 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 468: Transaction is current transaction, so clearing!!!!!
2019-06-16 21:53:35.353 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 468: Transaction CANCELLED
2019-06-16 21:53:35.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:468 CANCELLED
2019-06-16 21:53:35.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-06-16 21:53:35.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 468: Transaction event listener: DONE: CANCELLED -> 
2019-06-16 21:53:35.373 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1743132

==> /var/log/openhab2/openhab.log <==

2019-06-16 21:54:21.925 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised

It´s pretty strange in my opinion… I have done this before without any issue… But since I installed a fresh openhab 2.5M1 the other day, I simply havn´t been able to get zwave to work… It has always worked rock steady…

Still no suggestion, anyone?? I´m getting rather frustrated here.

this thread is 44 posts long and marked as solved so for anyone to help they would need to read which post to help with your issue?. Maybe start new thread?

I am having the same problem. I have 2.5M1.

Zwave devices wont discover - Many do - Some sit for days unresolved.

Thermostats can receive commands but I cant get any data from them.

I can send commands to switches but Openhab doesnt see their status at all.

The whole thing just works poorly.

I get a number of Request node info not placed on stack due to error. errors from time to time.

Have Rasperry PI, Openhabian. and lots of devices and will be adding more. It feels like I need to burn the whole thing down and start over. Saw answer about serial stuff, but I don’t know what to do.

The controller seems to know something about these devices. Example:
GENERIC_TYPE_THERMOSTAT

If it knows this much, why can’t it get the rest of the information. The whole thing seems very shaky.

Hey @chris,

My zWave (OH 2.4 with zWave binding snapshot 2.5 as of May 2019) has been working excellent all year but all of sudden (last week or so); I’m getting a ton of these entries now. I blew away all the zWave devices in Paper and re-discovered all of them and they are all back and online.

What am I missing?

2019-07-31 10:47:54.565 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-07-31 10:48:36.881 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-07-31 10:48:37.137 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-07-31 10:48:37.389 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-07-31 10:50:52.050 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-07-31 10:50:52.303 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-07-31 10:50:52.556 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-07-31 10:50:53.694 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.

Best, Jay

Without more debug logging it’s hard to say for sure (and even debug logging is unlikely to confirm what I’m about to say). However, when I’ve seen these sort of errors in the past it’s caused by the stick running out of memory. Recently we had someone report this sort of error (not with the NIF, but other frames being rejected) and when I looked at some debug logs I found a lot of messages being received from a sensor device. Once this device was reset, and it stopped sending loads of spam messages, the errors stopped. I believe that by sending all these messages, the device was taking all the memory on the stick, and the binding could not send messages.

So, given that you haven’t changed the binding, I would look for this sort of thing. Check to see if debug logging shows anything strange such as multiple messages being received from the same node in quick succession for example.

Thanks Chris!

This is happening because my zWave rules are firing in sets of 3 - 4’s also. It’s not just 1 node it’s many from these types of nodes --> ZW100 Multisensor 6

2019-07-31 11:07:49.902 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Kitchen Sensor Status - 2 hour interval.
2019-07-31 11:07:52.997 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Kitchen Sensor Status - 2 hour interval.
2019-07-31 11:07:56.965 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Kitchen Sensor Status - 2 hour interval.
2019-07-31 11:08:39.315 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Attic Sensor Status - 2 hour interval.
2019-07-31 11:08:44.324 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Attic Sensor Status - 2 hour interval.
2019-07-31 11:12:18.227 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Loft Sensor Status - 2 hour interval.
2019-07-31 11:12:23.234 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Loft Sensor Status - 2 hour interval.
2019-07-31 11:25:01.045 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Loft Sensor Status - 2 hour interval.
2019-07-31 11:25:05.106 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Loft Sensor Status - 2 hour interval.
2019-07-31 11:25:10.023 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Loft Sensor Status - 2 hour interval.
2019-07-31 11:25:12.335 [INFO ] [eclipse.smarthome.model.script.zWave] - Checking Loft Sensor Status - 2 hour interval.

Based on this any other direction I can follow?

I do have these USB nodes set to fire at 300 ms. Should I offset them maybe as an idea?

Best, Jay

Thanks @chris

I looked up and found that my Aeotec zWave stick was only blinking yellow and not rotating through the rainbow of colors that this stick does.

I swapped it out with a backup copy of the stick that I keep in sync monthly and everything started to work again.

I can’t empathizes enough to keep a backup of your zWave bridge in case something happens. My USB stick was only 13 months old. This could of been a disaster re-including everything back onto a new stick and then modifying all the items with new nodes.

Keep up the great work!

Best, Jay