Is this a consistent time? Could you have something interfering on the spectrum durring this time? Something like a RF noisy sump pump running or anything like that?
1 Like
I don’t know, I need to track it down. I can’t think of anything in the house that I am running that would cause this. It’s pretty quiet here!
Is your Zwave tranceiver anywhere near a AC motor, heating system? blower? high voltage transformer?
I guess it is near the air handler in the attic. I’m kind of constrained in where I can put my system. That said, the air handler hasn’t been running recently.
Any ideas, anyone? All I see in the event log is a sudden communication error, but no reason for it. And it happens to all the zwave devices. Surely there is a way to send the command to the controller? How does the user interface do it?
It sounds similar to this. In any case, you should set your log to debug and post your results so that we can determine why your network goes offline. Otherwise, you’re just slapping a bandage on it.
exactly, you need to figure out why the network is going offline, the root cause of the problem. Does this happen at a certain time? Set logs to debug and post them please
I’ve already added logs to the other issue - thanks for linking.
I’ll check if sync restores my System too, next time it goes offline and report back if this is a similarity.
PS I’m fairly flexible with my setup and have the USB dongle on a USB extension. I wouldn’t know of any interference except for the power brick of the synology (2m away)
I can confirm using sync network on my controller also restores the network. Can anyone advice on how I can permanently increase the log level to debug in order to get a more complete log ?
1 Like
Syncronize command is not really designed for this purpose. It is there to make the controllers in the network exchange network information so unless you have multiple controllers it is not going to do very much. I guess it might be helping here as it might reset the serial bus. This would cause the network to reinitialised. You could also try pause and un pause and see if that brings it back but doing a synchronize is unlikely to solve the problem other than kicking things off again.
Like described in my original post pause and resume is what I originally used…
@antamy are you OK with us discussing the root cause of the issue in this thread or should this one stick to the wish to be able to schedule disable enable events via rules engine. If so we could use my other thread to continue the technical discussion.
- out of interest- what’s your hardware setup , where do you run OH in which version with what kind of zwave hardware ?
It is good that a simple pause helps.
Why would you want to run synchronise from a rule/schedule?
It is something that you would only need to run if you have multiple controllers and you have changed you network you want to force through quickly.
For example a secondary controller used as an inclusion controller and you have added or removed a node using the secondary controller. Synchronize would make sure the primary was in sync with the changes.
Do you run multiple controllers or have any portable controllers?
The only other z-wave controller actions are:
- Hard reset which would be a very interesting thing to use from a rule and possibly not wise to make it too easy to do by mistake.
- Soft reset would be papering over the cracks as in normal use it should not be required.
- Heal which you can schedule if it is really your thing. Some love it some avoid it. I never use it as my network does not ever need it.
I think the only reason we considered running it from a schedule was because this would ensure the workaround to be executed…
1 Like
I set the logs to debug and the problem seems to occur as a result of a network heal. When the heal starts at 2am, lots of stuff seems to happen and then I get the results shown below for all the nodes. For now, I’ve set the heal time to Disabled and I’ll see if it happens again.
2021-03-11 02:07:24.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Retry count exceeded. Discarding message: TID 2910: [CANCELLED] priority=Controller, requiresResponse=true, callback: 220
2021-03-11 02:07:24.555 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Node Status event - Node is DEAD
2021-03-11 02:07:24.556 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Node is DEAD.
2021-03-11 02:07:24.557 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Node Status event - Node is DEAD
2021-03-11 02:07:24.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: TID 2910: Transaction completed
2021-03-11 02:07:24.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:2910 CANCELLED
2021-03-11 02:07:24.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-11 02:07:24.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2910: Transaction event listener: DONE: CANCELLED ->
2021-03-11 02:07:24.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-11 02:07:24.564 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 02 DB 6B
2021-03-11 02:07:24.564 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@9c6b16
2021-03-11 02:07:24.566 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 02 DB 6B
2021-03-11 02:07:24.569 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-03-11 02:07:24.570 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-11 02:07:24.572 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 DB 23 4A
2021-03-11 02:07:24.589 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-03-11 02:07:24.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2911: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 219
2021-03-11 02:07:24.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-11 02:07:24.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=219, payload=DB 23
2021-03-11 02:07:24.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2911: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 219
2021-03-11 02:07:24.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-03-11 02:07:24.596 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=219, payload=DB 23
2021-03-11 02:07:24.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2911: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 219
2021-03-11 02:07:24.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-03-11 02:07:24.599 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2911: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 219
2021-03-11 02:07:24.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 2911: (Callback 219)
2021-03-11 02:07:24.601 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2021-03-11 02:07:24.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 2911: callback 219
2021-03-11 02:07:24.604 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=219, payload=DB 23
2021-03-11 02:07:24.605 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 2: Got NodeNeighborUpdate request.
2021-03-11 02:07:24.606 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 2: NodeNeighborUpdate FAILED
2021-03-11 02:07:24.607 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNetworkEvent
2021-03-11 02:07:24.608 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2911: Transaction CANCELLED
2021-03-11 02:07:24.609 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2021-03-11 02:07:24.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: CANCEL while sending message. Requeueing - 1 attempts left!
2021-03-11 02:07:24.612 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2911: Transaction RESET with 1 retries remaining.
2021-03-11 02:07:24.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2021-03-11 02:07:24.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 2911 to queue - size 6
2021-03-11 02:07:24.615 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-11 02:07:24.616 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 02 DD 6D
I tried Synchronize Network and it cures the problem of the nodes being offline. So, whether it is the right command or not, whatever it does brings everything back online.
It’s not clear to me whether the online / offline status is something that openHAB generates or whether it is truly a status on the controller. Since I don’t have other controllers, my suspicion is that kicking off the synchronize causes openHAB to get the correct status of the devices and it corrects itself.
Here’s what I see when the nodes go down (after a heal):
2021-03-11 02:07:24.669 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:fc48139338:node2' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2021-03-11 02:07:24.847 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:fc48139338:node3' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
...
When I Synchronize Network, what I see in the debug log is a ton of messages that show that the Zwave network controller is shutting down. Then it starts up again, all the nodes are found and everything is fine.
So, if turning off heal doesn’t work, I’d like to find someway to synchronize the network, since I can’t monitor this manually everyday to make sure it’s working
Thanks
According to the logs, it does a ton of stuff. It shuts down the controller and then re-initializes it. It should be renamed “Restart Network” !
It sends one command to the controller. It does not shut down the controller - or at least it shouldn’t. The command may of course cause the controller to do a ton of stuff - but that’s what it’s meant to do - the controller is meant to synchronise with the SIS (if you have one in your network).
Not that it really matters, this is what I see:
2021-03-11 10:52:44.427 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2021-03-11 10:52:44.443 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_softreset to false
2021-03-11 10:52:44.445 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update security_networkkey to ED 43 EC D6 24 42 A2 C9 EA E5 BD CE 3B 05 97 33
2021-03-11 10:52:44.447 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update security_inclusionmode to 0
2021-03-11 10:52:44.449 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_sisnode to 1
....
2021-03-11 10:52:44.460 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_inclusiontimeout to 30
2021-03-11 10:52:44.461 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_hardreset to false
2021-03-11 10:52:44.470 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing receive thread
2021-03-11 10:52:44.656 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
2021-03-11 10:52:44.658 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Stopping ZWave network
2021-03-11 10:52:44.658 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller status changed to OFFLINE.
2021-03-11 10:52:44.660 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller status changed to OFFLINE.
...
2021-03-11 10:52:44.671 [DEBUG] [ve.internal.protocol.ZWaveController] - Shutting down ZWave controller
2021-03-11 10:52:44.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Shutting down transaction manager
2021-03-11 10:52:44.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Exiting ZWave Receive Thread
2021-03-11 10:52:44.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction manager shutdown
2021-03-11 10:52:44.694 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response TIMEOUT_WAITING_FOR_RESPONSE
2021-03-11 10:52:44.696 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DONE
2021-03-11 10:52:44.697 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /var/lib/openhab/zwave/network_0184da03__node_1.xml
2021-03-11 10:52:44.711 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init transaction completed with response TIMEOUT_WAITING_FOR_RESPONSE
...
2021-03-11 10:52:45.083 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller shutdown
2021-03-11 10:52:45.086 [DEBUG] [zwave.handler.ZWaveControllerHandler] - ZWave network stopped
Then it starts up again. Is there a way behind the scenes to just send that command to /dev/ttyUSB0 ?
Thanks
I don’t even see the command here to sync the network - it’s not being sent.
There are only a couple of commands that will cause the network to reinitialise - inclusion timer, security key, and serial port. From this it seems you have updated the security key and that the likely restart trigger.
I’m not really sure what command you want to send? In this log, it doesn’t seem that ANY commands are sent to the serial port since the config update triggers a reinitialisation.