All z-wave nodes go from online to offline (not communicating with controller)

torsteinsunde · December 11, 2016, 9:12pm

I am in the process of migrating to OpenHab 2, but have some issues with my z-wave network. OH2 (build 477) is running on a VM server with Ubuntu and an Aeotec Gen 5 z-stick. After a successful boot, all the z-wave nodes come online and are operable. Soon after the nodes start changing status from online to offline in a rapid manner until the network is completely offline - except the controller which is still online.

2016-12-11 22:09:00.004 [ItemCommandEvent          ] - Item 'zwave_device_c40b37fc_node9_switch_binary' received command ON
2016-12-11 22:09:00.005 [ItemStateChangedEvent     ] - zwave_device_c40b37fc_node9_switch_binary changed from OFF to ON
2016-12-11 22:09:07.693 [ItemCommandEvent          ] - Item 'zwave_device_c40b37fc_node19_switch_binary' received command ON
2016-12-11 22:09:07.694 [ItemStateChangedEvent     ] - zwave_device_c40b37fc_node19_switch_binary changed from OFF to ON
2016-12-11 22:09:13.478 [ItemCommandEvent          ] - Item 'zwave_device_c40b37fc_node8_switch_binary' received command ON
2016-12-11 22:09:13.480 [ItemStateChangedEvent     ] - zwave_device_c40b37fc_node8_switch_binary changed from OFF to ON
2016-12-11 22:09:15.057 [hingStatusInfoChangedEvent] - 'zwave:device:c40b37fc:node9' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2016-12-11 22:09:30.109 [hingStatusInfoChangedEvent] - 'zwave:device:c40b37fc:node19' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with control           ler
2016-12-11 22:09:45.142 [hingStatusInfoChangedEvent] - 'zwave:device:c40b37fc:node8' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2016-12-11 22:11:17.839 [hingStatusInfoChangedEvent] - 'zwave:device:c40b37fc:node14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

Any ideas on how to proceed in finding a fix to this?

chris · December 11, 2016, 10:12pm

The first thing I’d suggest is to look at the debug logfile - otherwise, there’s no real way to know what this actually is…

torsteinsunde · December 12, 2016, 11:19pm

So I did a fresh install of both Ubunut 16.04 and OH2 (online snapshot) and installed only the zwave binding. Below is some of the log i get from one of the nodes. A full log from a restart until the nodes start to go offline is here:

openhab.log
events.log

All help is greatly appreciated!

2016-12-12 23:29:44.496 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: MANUFACTURER not set
2016-12-12 23:29:47.850 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 14: Node found
2016-12-12 23:29:47.923 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 14: Init node thread start
2016-12-12 23:29:48.446 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 14: Serializing from file /var/lib/openhab2/zwave/node14.xml
2016-12-12 23:29:48.449 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 14: Error serializing from file: file does not exist.
2016-12-12 23:29:48.598 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Starting initialisation from EMPTYNODE
2016-12-12 23:29:48.598 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2016-12-12 23:29:48.599 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2016-12-12 23:29:48.599 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: Initialisation starting
2016-12-12 23:29:48.599 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - advancing to PROTOINFO
2016-12-12 23:29:48.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2016-12-12 23:29:48.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: PROTOINFO - send IdentifyNode
2016-12-12 23:29:48.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:29:48.601 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 14: Init node thread finished
2016-12-12 23:29:48.740 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller status changed to ONLINE.
2016-12-12 23:29:48.741 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller is ONLINE. Starting device initialisation.
2016-12-12 23:29:48.741 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Updating node properties.
2016-12-12 23:29:48.750 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Updating node properties. MAN=2147483647
2016-12-12 23:29:48.751 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Properties synchronised
2016-12-12 23:29:48.753 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Initialising Thing Node...
2016-12-12 23:29:48.758 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
2016-12-12 23:29:49.413 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: ProtocolInfo
2016-12-12 23:29:49.413 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Listening = true
2016-12-12 23:29:49.413 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Routing = true
2016-12-12 23:29:49.413 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Beaming = true
2016-12-12 23:29:49.413 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Version = 4
2016-12-12 23:29:49.414 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: FLIRS = false
2016-12-12 23:29:49.414 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Security = false
2016-12-12 23:29:49.414 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Max Baud = 40000
2016-12-12 23:29:49.414 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Basic = Routing Slave
2016-12-12 23:29:49.414 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Generic = Multi-Level Switch
2016-12-12 23:29:49.415 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 14: Specific = Multilevel Power Switch
2016-12-12 23:29:49.415 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class NO_OPERATION
2016-12-12 23:29:49.415 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class NO_OPERATION, endpoint null created
2016-12-12 23:29:49.416 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Version = 1, version set. Enabling extra functionality.
2016-12-12 23:29:49.416 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class NO_OPERATION to the list of supported command classes.
2016-12-12 23:29:49.416 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class BASIC
2016-12-12 23:29:49.416 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class BASIC, endpoint null created
2016-12-12 23:29:49.416 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class BASIC to the list of supported command classes.
2016-12-12 23:29:49.417 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class SWITCH_MULTILEVEL
2016-12-12 23:29:49.417 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class SWITCH_MULTILEVEL, endpoint null created
2016-12-12 23:29:49.417 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class SWITCH_MULTILEVEL to the list of supported command classes.
2016-12-12 23:29:49.423 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2016-12-12 23:29:49.423 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - checking initialisation queue. Queue size 1.
2016-12-12 23:29:49.423 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - message removed from queue. Queue size 0.
2016-12-12 23:29:49.423 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - PROTOINFO: queue length(0), free to send(true)
2016-12-12 23:29:49.424 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 5000
2016-12-12 23:29:49.424 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2016-12-12 23:29:49.424 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - advancing to INIT_NEIGHBORS
2016-12-12 23:29:49.425 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-12-12 23:29:49.425 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - INIT_NEIGHBORS try 0: stageAdvanced(true)
2016-12-12 23:29:49.425 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: INIT_NEIGHBORS - send RoutingInfo
2016-12-12 23:29:49.425 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 14: Request routing info
2016-12-12 23:29:49.426 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:29:50.061 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 14: Got NodeRoutingInfo request.
2016-12-12 23:29:50.061 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 14: Neighbor nodes: 1 2 3 4 5 7 8 9 10 12 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 31 32 33
2016-12-12 23:29:50.062 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveNetworkEvent
2016-12-12 23:29:50.063 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - INIT_NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2016-12-12 23:29:50.063 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - checking initialisation queue. Queue size 1.
2016-12-12 23:29:50.063 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - message removed from queue. Queue size 0.
2016-12-12 23:29:50.064 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - INIT_NEIGHBORS: queue length(0), free to send(true)
2016-12-12 23:29:50.064 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 5000
2016-12-12 23:29:50.064 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - INIT_NEIGHBORS try 1: stageAdvanced(false)
2016-12-12 23:29:50.064 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - advancing to FAILED_CHECK
2016-12-12 23:29:50.065 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-12-12 23:29:50.065 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2016-12-12 23:29:50.070 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 14: Requesting IsFailedNode status from controller.
2016-12-12 23:29:50.071 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:29:50.587 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 14: Is currently marked as healthy by the controller
2016-12-12 23:29:50.588 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2016-12-12 23:29:50.589 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - checking initialisation queue. Queue size 1.
2016-12-12 23:29:50.589 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - message removed from queue. Queue size 0.
2016-12-12 23:29:50.589 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2016-12-12 23:29:50.589 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 5000
2016-12-12 23:29:50.590 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2016-12-12 23:29:50.590 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - advancing to WAIT
2016-12-12 23:29:50.590 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-12-12 23:29:50.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2016-12-12 23:29:50.594 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: WAIT - Listening=true, FrequentlyListening=false
2016-12-12 23:29:50.594 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: WAIT - Advancing
2016-12-12 23:29:50.595 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - advancing to PING
2016-12-12 23:29:50.595 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2016-12-12 23:29:50.595 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - PING try 0: stageAdvanced(true)
2016-12-12 23:29:50.596 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: PING - send NoOperation
2016-12-12 23:29:50.596 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 14: Creating new message for command No Operation
2016-12-12 23:29:50.596 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:29:55.589 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Stage PING. Initialisation retry timer triggered. Increased to 10000
2016-12-12 23:29:55.589 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - PING: queue length(0), free to send(false)
2016-12-12 23:29:55.590 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 10000
2016-12-12 23:29:55.590 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - PING try 1: stageAdvanced(false)
2016-12-12 23:29:55.590 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: PING - send NoOperation
2016-12-12 23:29:55.591 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 14: Creating new message for command No Operation
2016-12-12 23:29:55.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:30:05.590 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Stage PING. Initialisation retry timer triggered. Increased to 20000
2016-12-12 23:30:05.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - PING: queue length(0), free to send(false)
2016-12-12 23:30:05.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 20000
2016-12-12 23:30:05.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - PING try 2: stageAdvanced(false)
2016-12-12 23:30:05.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: PING - send NoOperation
2016-12-12 23:30:05.591 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 14: Creating new message for command No Operation
2016-12-12 23:30:05.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:30:25.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Stage PING. Initialisation retry timer triggered. Increased to 40000
2016-12-12 23:30:25.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - PING: queue length(0), free to send(false)
2016-12-12 23:30:25.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 40000
2016-12-12 23:30:25.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - PING try 3: stageAdvanced(false)
2016-12-12 23:30:25.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: PING - send NoOperation
2016-12-12 23:30:25.592 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 14: Creating new message for command No Operation
2016-12-12 23:30:25.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:30:48.313 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 14: Serialise aborted as static stages not complete
2016-12-12 23:30:48.332 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: MANUFACTURER not set
2016-12-12 23:30:48.333 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller status changed to ONLINE.
2016-12-12 23:30:48.333 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller is ONLINE. Starting device initialisation.
2016-12-12 23:30:48.336 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Updating node properties.
2016-12-12 23:30:48.338 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Updating node properties. MAN=2147483647
2016-12-12 23:30:48.339 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Initialising Thing Node...
2016-12-12 23:30:48.361 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Polling intialised at 1800 seconds - start in 1800000 milliseconds.
2016-12-12 23:31:05.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Stage PING. Initialisation retry timer triggered. Increased to 80000
2016-12-12 23:31:05.591 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - PING: queue length(0), free to send(false)
2016-12-12 23:31:05.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 80000
2016-12-12 23:31:05.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - PING try 4: stageAdvanced(false)
2016-12-12 23:31:05.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: PING - send NoOperation
2016-12-12 23:31:05.592 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 14: Creating new message for command No Operation
2016-12-12 23:31:05.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:32:10.857 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 14: Sending REQUEST Message = 01 08 00 13 0E 01 00 25 10 DE
2016-12-12 23:32:15.859 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Sending ABORT Message = 01 03 00 16 EA
2016-12-12 23:32:15.861 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Timeout while sending message. Requeueing - 0 attempts left!
2016-12-12 23:32:15.861 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 14: Got an error while sending data. Resending message.
2016-12-12 23:32:15.863 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 14: Sending REQUEST Message = 01 08 00 13 0E 01 00 25 6F A1
2016-12-12 23:32:20.865 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Sending ABORT Message = 01 03 00 16 EA
2016-12-12 23:32:20.866 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=14, callback=111, payload=0E 01 00
2016-12-12 23:32:25.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Stage PING. Initialisation retry timer triggered. Increased to 160000
2016-12-12 23:32:25.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - PING: queue length(0), free to send(false)
2016-12-12 23:32:25.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 160000
2016-12-12 23:32:25.593 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: loop - PING try 5: stageAdvanced(false)
2016-12-12 23:32:25.593 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: PING - send NoOperation
2016-12-12 23:32:25.593 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 14: Creating new message for command No Operation
2016-12-12 23:32:25.595 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - queued packet. Queue length is 1
2016-12-12 23:35:05.592 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Stage PING. Initialisation retry timer triggered. Increased to 320000
2016-12-12 23:35:05.593 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer - PING: queue length(0), free to send(false)
2016-12-12 23:35:05.593 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Initialisation retry timer started 320000
2016-12-12 23:35:05.593 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node advancer: Retries exceeded at PING
2016-12-12 23:35:05.593 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Retry timout: Can't advance
2016-12-12 23:35:06.065 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 14: Sending REQUEST Message = 01 08 00 13 0E 01 00 25 23 ED
2016-12-12 23:35:11.067 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Sending ABORT Message = 01 03 00 16 EA
2016-12-12 23:35:11.068 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Timeout while sending message. Requeueing - 0 attempts left!
2016-12-12 23:35:11.068 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 14: Got an error while sending data. Resending message.
2016-12-12 23:35:11.069 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 14: Sending REQUEST Message = 01 08 00 13 0E 01 00 25 93 5D
2016-12-12 23:35:16.071 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Sending ABORT Message = 01 03 00 16 EA
2016-12-12 23:35:16.073 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=14, callback=147, payload=0E 01 00
2016-12-12 23:37:11.326 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 14: Sending REQUEST Message = 01 08 00 13 0E 01 00 25 37 F9
2016-12-12 23:37:16.328 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Sending ABORT Message = 01 03 00 16 EA
2016-12-12 23:37:16.329 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Timeout while sending message. Requeueing - 0 attempts left!
2016-12-12 23:37:16.329 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Node is DEAD.
2016-12-12 23:37:16.330 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node Status event during initialisation - Node is DEAD
2016-12-12 23:37:16.330 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2016-12-12 23:37:16.331 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Setting OFFLINE
2016-12-12 23:37:16.336 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 14: Node Status event - Node is DEAD
2016-12-12 23:37:16.336 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 14: Node is DEAD. Dropping message.
2016-12-12 23:38:46.480 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 14: Sending REQUEST Message = 01 08 00 13 0E 01 00 25 4C 82
2016-12-12 23:38:51.481 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Sending ABORT Message = 01 03 00 16 EA
2016-12-12 23:38:51.482 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 14: Timeout while sending message. Requeueing - 0 attempts left!
2016-12-12 23:38:51.482 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 14: Node is DEAD. Dropping message.

torsteinsunde · December 18, 2016, 7:22pm

Just a follow up on this one. The problem was linked to ESXi 6.5 not handling certain USB devices very well. More specifically, I saw the same errors as described in this thread.

WARNING: usb_non_isoc_callback:1019: transfer error [20]: endpt = 0x82, nframes = 1, timeout = 5000, interval = 0, max_packet_size = 64, max_frame_size = 64: Failure

The solution was to downgrade ESXi 6.5 to ESXi 5.5 and reinstall OH2. No problems since.

MrBoggi · January 1, 2017, 5:18pm

I’m setting up a new OH2 installation running on esxi 6.5 and see the same problems as mentioned above. All my nodes go offline. I have a zwave.me uzb stick. I tried setting up OH2 on a windows-computer and found everything working fine there…

//Morten

MrBoggi · January 2, 2017, 6:47am

After a quick Google-session this morning I found that in 6.5 there are new drivers handling USB in ESXi. The old drivers are still present but not loaded as default. I will try this afternoon to change to the old drivers and see how that works. This link provide info regarding change of USB drivers:
http://www.devtty.uk/homelab/USB-Ethernet-driver-for-ESXi-6.5/
And this is a link to how to change what drivers to load:
https://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=2147650

//Morten

MrBoggi · January 3, 2017, 7:06am

Ok. So I tested yesterday changing to the old drivers and that worked really well. So the solution is to set up ESX to use the old USB drivers as i mentioned in the above post.

Cheers!!
Morten

torsteinsunde · January 8, 2017, 10:54pm

Great stuff! I used so much time on trying to find a viable solution to this. Thank you!

MrBoggi · January 9, 2017, 4:32am

Glad my research could help other. Have been running for a week now without problems… Well… without driver-problems anyway

jpg · February 24, 2017, 7:50pm

@MrBoggi thanks for your research/solution, I was about to tear my hair out as I really didn’t want to downgrade! I like simple fixes