Z-Wave error

nothingman · September 5, 2015, 3:18pm

Hi,
every night a 2:00 a see this error in the openhab.log:

2015-09-05 02:00:04.261 [ERROR] [NodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
2015-09-05 02:00:04.303 [ERROR] [NodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
2015-09-05 02:00:04.344 [ERROR] [NodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
2015-09-05 02:00:04.385 [ERROR] [NodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED

Node 1 is a fibaro motion/temperature sensor which is battery powered and it does not repeat the signal. Is this log normal since node 1 does not repeat the signal ?

Regards

chris · September 5, 2015, 3:22pm

These sorts of errors aren’t uncommon since some of these services seem to time out. It’s very strange for it to time out quite so quickly though…

Are you sure? Node 1 is normally the controller. This is not always true - if you have a different controller, that might be node 1 instead, but it’s not common for node 1 to not be a controller. How is your network configured?

nothingman · September 5, 2015, 3:33pm

You are right… Node 1 is my aeotech z-stick usb controller…

I see this errors every night at 2 am

chris · September 5, 2015, 3:35pm

If you can provide a short debug log around the time of the problem (maybe 10 seconds before and a few seconds afterwards) I’ll take a look. I doubt there’s much I can glean from the log as all this happens very quickly, but I’d happily take a look.

What version of the z-stick is it?

nothingman · September 5, 2015, 3:48pm

Ok I will put in debug mode this night.
It’s the aeotech gen 5 z-stick

chris · September 5, 2015, 3:49pm

Hmmm - ok, thanks. It might act slightly differently to the old one… I have one here, but haven’t looked to see what happens at 2am

nothingman · September 6, 2015, 6:05am

These are the logs captured in debug mode:

2015-09-06 02:00:01.214 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 2: Starting heal
2015-09-06 02:00:01.219 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: Starting heal
2015-09-06 02:00:01.240 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - STARTING
2015-09-06 02:00:01.251 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - PING
2015-09-06 02:00:01.252 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - SETSUCROUTE
2015-09-06 02:00:01.257 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - UPDATENEIGHBORS
2015-09-06 02:00:01.280 [DEBUG] [NodeNeighborUpdateMessageClass] - NODE 1: Request neighbor update
2015-09-06 02:00:01.285 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = RequestNodeNeighborUpdate (0x48), type = Request (0x00)
2015-09-06 02:00:01.288 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-09-06 02:00:01.290 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 00 48 01 B2 
2015-09-06 02:00:01.301 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 04 00 48 01 B2 
2015-09-06 02:00:01.308 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 0
2015-09-06 02:00:01.347 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.377 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-09-06 02:00:01.385 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.392 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=0
2015-09-06 02:00:01.394 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.400 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = RequestNodeNeighborUpdate (0x48), type = Request (0x00), payload = 02 23 
2015-09-06 02:00:01.415 [DEBUG] [NodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
2015-09-06 02:00:01.416 [ERROR] [NodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
2015-09-06 02:00:01.423 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
2015-09-06 02:00:01.423 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:01.425 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: Network heal received FAILURE event
2015-09-06 02:00:01.432 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - UPDATENEIGHBORS
2015-09-06 02:00:01.432 [DEBUG] [NodeNeighborUpdateMessageClass] - NODE 1: Request neighbor update
2015-09-06 02:00:01.439 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = RequestNodeNeighborUpdate (0x48), type = Request (0x00)
2015-09-06 02:00:01.448 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-09-06 02:00:01.454 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-06 02:00:01.455 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:01.462 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Response processed after 140ms/2617ms.
2015-09-06 02:00:01.467 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-09-06 02:00:01.473 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 00 48 01 B2 
2015-09-06 02:00:01.483 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 04 00 48 01 B2 
2015-09-06 02:00:01.510 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.518 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-09-06 02:00:01.520 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.522 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.523 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = RequestNodeNeighborUpdate (0x48), type = Request (0x00), payload = 02 23 
2015-09-06 02:00:01.524 [DEBUG] [NodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
2015-09-06 02:00:01.525 [ERROR] [NodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
2015-09-06 02:00:01.526 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
2015-09-06 02:00:01.548 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=0
2015-09-06 02:00:01.550 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:01.553 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: Network heal received FAILURE event
2015-09-06 02:00:01.555 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - UPDATENEIGHBORS
2015-09-06 02:00:01.558 [DEBUG] [NodeNeighborUpdateMessageClass] - NODE 1: Request neighbor update
2015-09-06 02:00:01.570 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = RequestNodeNeighborUpdate (0x48), type = Request (0x00)
2015-09-06 02:00:01.575 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-09-06 02:00:01.578 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-06 02:00:01.579 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:01.584 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Response processed after 99ms/2617ms.
2015-09-06 02:00:01.598 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-09-06 02:00:01.606 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 00 48 01 B2 
2015-09-06 02:00:01.612 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 04 00 48 01 B2 
2015-09-06 02:00:01.639 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.646 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-09-06 02:00:01.648 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.662 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=0
2015-09-06 02:00:01.669 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.679 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = RequestNodeNeighborUpdate (0x48), type = Request (0x00), payload = 02 23 
2015-09-06 02:00:01.680 [DEBUG] [NodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
2015-09-06 02:00:01.681 [ERROR] [NodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
2015-09-06 02:00:01.687 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
2015-09-06 02:00:01.704 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:01.705 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: Network heal received FAILURE event
2015-09-06 02:00:01.706 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - UPDATENEIGHBORS
2015-09-06 02:00:01.709 [DEBUG] [NodeNeighborUpdateMessageClass] - NODE 1: Request neighbor update
2015-09-06 02:00:01.717 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = RequestNodeNeighborUpdate (0x48), type = Request (0x00)
2015-09-06 02:00:01.719 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-09-06 02:00:01.760 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-06 02:00:01.767 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:01.769 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Response processed after 156ms/2617ms.
2015-09-06 02:00:01.776 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-09-06 02:00:01.789 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 04 00 48 01 B2 
2015-09-06 02:00:01.795 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 04 00 48 01 B2 
2015-09-06 02:00:01.823 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.831 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-09-06 02:00:01.833 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.834 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 05 00 48 02 23 93 
2015-09-06 02:00:01.836 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = RequestNodeNeighborUpdate (0x48), type = Request (0x00), payload = 02 23 
2015-09-06 02:00:01.837 [DEBUG] [NodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
2015-09-06 02:00:01.838 [ERROR] [NodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
2015-09-06 02:00:01.860 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=0
2015-09-06 02:00:01.866 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
2015-09-06 02:00:01.867 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:01.871 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: Network heal received FAILURE event
2015-09-06 02:00:01.879 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: Maximum retries in state UPDATENEIGHBORS
2015-09-06 02:00:01.888 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: Heal - continuing to state GETASSOCIATIONS
2015-09-06 02:00:01.896 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - GETASSOCIATIONS
2015-09-06 02:00:01.897 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - GETASSOCIATIONS
2015-09-06 02:00:01.905 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 1: Update return routes
2015-09-06 02:00:01.916 [DEBUG] [.z.internal.protocol.ZWaveNode] - NODE 1: Node is not a routing node. No routes can be set.
2015-09-06 02:00:01.917 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - GETASSOCIATIONS
2015-09-06 02:00:01.919 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - GETASSOCIATIONS
2015-09-06 02:00:01.920 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: Heal is requesting node neighbor info.
2015-09-06 02:00:01.925 [DEBUG] [p.s.GetRoutingInfoMessageClass] - NODE 1: Request routing info
2015-09-06 02:00:01.934 [DEBUG] [o.b.z.i.protocol.SerialMessage] - NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00)
2015-09-06 02:00:01.936 [DEBUG] [b.z.i.protocol.ZWaveController] - Enqueueing message. Queue length = 1
2015-09-06 02:00:01.937 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-06 02:00:01.952 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:01.953 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Response processed after 155ms/2617ms.
2015-09-06 02:00:01.959 [DEBUG] [WaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2015-09-06 02:00:01.966 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 01 00 00 03 7A 
2015-09-06 02:00:01.979 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Sending REQUEST Message = 01 07 00 80 01 00 00 03 7A 
2015-09-06 02:00:02.006 [DEBUG] [eController$ZWaveReceiveThread] - Receive Message = 01 20 01 80 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5C 
2015-09-06 02:00:02.049 [DEBUG] [b.z.i.protocol.ZWaveController] - Receive queue TAKE: Length=0
2015-09-06 02:00:02.053 [DEBUG] [o.b.z.i.protocol.SerialMessage] - Assembled message buffer = 01 20 01 80 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5C 
2015-09-06 02:00:02.077 [DEBUG] [eController$ZWaveReceiveThread] - Receive queue ADD: Length=0
2015-09-06 02:00:02.079 [DEBUG] [b.z.i.protocol.ZWaveController] - Process Message = 01 20 01 80 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5C 
2015-09-06 02:00:02.099 [DEBUG] [b.z.i.protocol.ZWaveController] - Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2015-09-06 02:00:02.109 [DEBUG] [p.s.GetRoutingInfoMessageClass] - NODE 1: Got NodeRoutingInfo request.
2015-09-06 02:00:02.111 [DEBUG] [p.s.GetRoutingInfoMessageClass] - NODE 1: Neighbor nodes: 2
2015-09-06 02:00:02.118 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
2015-09-06 02:00:02.119 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:02.132 [DEBUG] [z.internal.ZWaveNetworkMonitor] - NODE 1: NETWORK HEAL - SAVE
2015-09-06 02:00:02.702 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer] - NODE 1: Serializing to file /var/lib/openhab/zwave/node1.xml
2015-09-06 02:00:02.843 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Sent message Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 01 00 00 03 
2015-09-06 02:00:02.862 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Recv message Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2015-09-06 02:00:02.867 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] - Checking transaction complete: class=GetRoutingInfo, expected=GetRoutingInfo, cancelled=false
2015-09-06 02:00:02.885 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor] -          transaction complete!
2015-09-06 02:00:02.896 [DEBUG] [b.z.i.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-06 02:00:02.901 [DEBUG] [.z.internal.ZWaveActiveBinding] - ZwaveIncomingEvent
2015-09-06 02:00:02.903 [DEBUG] [WaveController$ZWaveSendThread] - NODE 255: Response processed after 923ms/2617ms.
2015-09-06 02:01:56.325 [DEBUG] [z.internal.ZWaveNetworkMonitor] - Network Monitor: No nodes to ping!
2015-09-06 02:03:26.336 [DEBUG] [z.internal.ZWaveNetworkMonitor] - Network Monitor: No nodes to ping!
2015-09-06 02:04:56.352 [DEBUG] [z.internal.ZWaveNetworkMonitor] - Network Monitor: No nodes to ping!
2015-09-06 02:06:26.474 [DEBUG] [z.internal.ZWaveNetworkMonitor] - Network Monitor: No nodes to ping!
2015-09-06 02:07:56.487 [DEBUG] [z.internal.ZWaveNetworkMonitor] - Network Monitor: No nodes to ping!

The problem seems related to the Network Heal Process, but I cannot understand the cause…

chris · September 6, 2015, 9:21am

Yes - this is definately the case, but it’s unclear why the zstick is failing to perform this function. It may be that this is no longer supported in the zwave+ sticks, or maybe it’s changed - I’m not sure. Unfortunately with the closed nature of zwave, there’s no documentation on this so we need to guess (or spend a lot of time trying to reverse engineer the protocol, which is the same as guessing ).

I don’t think it’s causing any problem, so you have 2 options - disable the heal, or ignore the error (or I could simply downgrade the error to a debug message which might also be a good idea)…

nothingman · September 6, 2015, 6:05pm

Ok no problem, I will ignore this error…

egnesund · September 8, 2015, 2:52pm

In my default.cfg have following rows… It explains why it tries to heal att 2am, but not your problem with it.

################################ Z-Wave Binding ###################################### #Z-Wave nightly heal time. This is the hour (eg 2AM) at which the automatic nightly #network heal will be performed. zwave:healtime=2

lostcontrol · May 19, 2016, 6:24am

Sorry to reply to this old topic but I bought 2 Qubino Z-Wave+ relay (ZMNHND1) to extend my ZWave network (1x Aeotech Gen 5 Z-stick, 2x ZMNHND1, 1x Nodon Soft Remote) and get the same error message during healing. However, in my case it seems that routing is simply not working I can’t get my second Qubino to communicate with the network via the first Qubino!? I would expect a network healing to fix that. The second Qubino is something like 4 meters away from the first one with no wall in between. If I put both Qubino next to the Aeotech Gen 5 Z-stick I see both nodes in Habmin but then both are communicating directly with the controller. This is using version 1.8.1 of the binding.

So is network healing supposed to work with Aeotech Gen 5 Z-stick? If not, what should I do? Thanks