Hi @chris, my system (Openhabian on Pi) was running now since over 2 weeks, and since 7 days OpenHAB with new 2.3.0 release.
Today all my zwave devices switched to status “Node is not communicating with controller” and no further communication seems to be possible.
I had this situation already 2 times in the past 2 months and by that I was running all the time with Debug option for the Zwave binding. I kindly ask you to view my logfiles and try to find out what the source of the issue can be.
My controller is a Cyrus SmartHome USB Dongle, Z-Wave Plus.
I tried a soft reset of the controller and the “heal the network” by the controller, but I receive the following error
2018-06-12 23:54:13.976 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2018-06-12 23:54:13.990 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_sync to true
2018-06-12 23:54:13.995 [DEBUG] [age.RequestNetworkUpdateMessageClass] - Request network update.
2018-06-12 23:54:14.000 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2018-06-12 23:54:14.000 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2018-06-12 23:54:14.003 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller request network update
2018-06-12 23:54:14.004 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 53 01 A9
2018-06-12 23:54:14.007 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 53 01 A9
2018-06-12 23:54:14.010 [ERROR] [ing.zwave.handler.ZWaveSerialHandler] - Got I/O exception Input/output error in writeArray during sending. exiting thread.
I have logfiles from restart of the system on June 3rd (after upgrade to 2.3 stable) with Debug info for Zwave binding. Let me please know how I can provide these 2 large files (logfile is not an authorized extension for upload).
The USB stick is assigned to:
The system shows:
The events log part of first devices going offline:
2018-06-12 13:31:00.006 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered END
2018-06-12 13:35:37.921 [vent.ItemStateChangedEvent] - PIP_RasPi_CPU_Load changed from 2.5 to 2.4
2018-06-12 13:35:37.928 [vent.ItemStateChangedEvent] - RasPiOpenHAB_CpuLoad changed from 2.5 to 2.4
2018-06-12 13:41:31.847 [hingStatusInfoChangedEvent] - 'zwave:device:b1506bc3:node18' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2018-06-12 13:42:09.432 [hingStatusInfoChangedEvent] - 'zwave:device:b1506bc3:node21' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2018-06-12 13:44:06.979 [hingStatusInfoChangedEvent] - 'zwave:device:b1506bc3:node10' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2018-06-12 13:44:31.547 [hingStatusInfoChangedEvent] - 'zwave:device:b1506bc3:node7' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2018-06-12 13:45:06.804 [hingStatusInfoChangedEvent] - 'zwave:device:b1506bc3:node11' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2018-06-12 13:45:38.048 [vent.ItemStateChangedEvent] - PIP_RasPi_CPU_Load changed from 2.4 to 2.7
2018-06-12 13:45:38.075 [vent.ItemStateChangedEvent] - RasPiOpenHAB_CpuLoad changed from 2.4 to 2.7
2018-06-12 13:14:38.736 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 11: Application Command Request (ALIVE:DONE)
2018-06-12 13:14:38.739 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Starting initialisation from DONE
2018-06-12 13:14:38.741 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@80b4b0 already registered
2018-06-12 13:14:38.743 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 11: Incoming command class SWITCH_BINARY
2018-06-12 13:14:38.745 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 11
2018-06-12 13:14:38.747 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 11: Switch Binary report, value = 255
2018-06-12 13:14:38.750 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-06-12 13:14:38.752 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-06-12 13:14:38.754 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255
2018-06-12 13:14:38.756 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Updating channel state zwave:device:b1506bc3:node11:switch_binary to ON [OnOffType]
2018-06-12 13:14:38.769 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=11, callback=235, payload=0B 02 25 02
2018-06-12 13:14:38.771 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0B 03 25 03 FF
2018-06-12 13:14:38.773 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=235, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2018-06-12 13:14:38.775 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-06-12 13:14:38.776 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-06-12 13:14:38.778 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Response processed after 116ms/4813ms.
2018-06-12 13:17:32.762 [WARN ] [airquality.handler.AirQualityHandler] - Error in aqicn.org (Air Quality), retrying once
2018-06-12 13:41:16.481 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling...
2018-06-12 13:41:16.485 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling zwave:device:b1506bc3:node18:switch_binary
2018-06-12 13:41:16.489 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 18: Generating poll message for SWITCH_BINARY, endpoint 0
2018-06-12 13:41:16.493 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 18: Creating new message for application command SWITCH_BINARY_GET
2018-06-12 13:41:16.506 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling zwave:device:b1506bc3:node18:meter_current
2018-06-12 13:41:16.510 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 18: Generating poll message for METER, endpoint 0
2018-06-12 13:41:16.513 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 18: Generating poll message for METER, endpoint 0
2018-06-12 13:41:16.516 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 18: Creating new message for application command METER_GET
2018-06-12 13:41:16.521 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling zwave:device:b1506bc3:node18:meter_kwh
2018-06-12 13:41:16.526 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 18: Generating poll message for METER, endpoint 0
2018-06-12 13:41:16.529 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 18: Generating poll message for METER, endpoint 0
2018-06-12 13:41:16.532 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 18: Creating new message for application command METER_GET
2018-06-12 13:41:16.538 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling zwave:device:b1506bc3:node18:meter_watts
2018-06-12 13:41:16.541 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 18: Generating poll message for METER, endpoint 0
2018-06-12 13:41:16.545 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 18: Generating poll message for METER, endpoint 0
2018-06-12 13:41:16.548 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 18: Creating new message for application command METER_GET
2018-06-12 13:41:16.553 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling zwave:device:b1506bc3:node18:meter_voltage
2018-06-12 13:41:16.556 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 18: Generating poll message for METER, endpoint 0
2018-06-12 13:41:16.558 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 18: Generating poll message for METER, endpoint 0
2018-06-12 13:41:16.562 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 18: Creating new message for application command METER_GET
2018-06-12 13:41:16.566 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling zwave:device:b1506bc3:node18:alarm_power
2018-06-12 13:41:16.570 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2018-06-12 13:41:16.570 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2018-06-12 13:41:16.573 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2018-06-12 13:41:16.576 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 12 02 25 02 25 EC 1B
2018-06-12 13:41:16.576 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2018-06-12 13:41:16.581 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2018-06-12 13:41:16.585 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 09 00 13 12 02 25 02 25 EC 1B
2018-06-12 13:41:16.585 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2018-06-12 13:41:21.591 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2018-06-12 13:41:21.595 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 18: Sending ABORT Message = 01 03 00 16 EA
2018-06-12 13:41:21.600 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2018-06-12 13:41:21.604 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
2018-06-12 13:41:21.607 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 18: Timeout while sending message. Requeueing - 2 attempts left!
2018-06-12 13:41:21.610 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: Got an error while sending data. Resending message.
2018-06-12 13:41:21.613 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2018-06-12 13:41:21.616 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2018-06-12 13:41:21.622 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 12 02 25 02 25 F1 06
2018-06-12 13:41:21.627 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 09 00 13 12 02 25 02 25 F1 06
2018-06-12 13:41:26.632 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2018-06-12 13:41:26.637 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 18: Sending ABORT Message = 01 03 00 16 EA
2018-06-12 13:41:26.643 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2018-06-12 13:41:26.647 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
2018-06-12 13:41:26.651 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 18: Timeout while sending message. Requeueing - 1 attempts left!
2018-06-12 13:41:26.654 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: Got an error while sending data. Resending message.
2018-06-12 13:41:26.657 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2018-06-12 13:41:26.660 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2018-06-12 13:41:26.665 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 12 02 25 02 25 F2 05
2018-06-12 13:41:26.671 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 09 00 13 12 02 25 02 25 F2 05
2018-06-12 13:41:31.676 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2018-06-12 13:41:31.681 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 18: Sending ABORT Message = 01 03 00 16 EA
2018-06-12 13:41:31.685 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2018-06-12 13:41:31.689 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
2018-06-12 13:41:31.692 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 18: Timeout while sending message. Requeueing - 0 attempts left!
2018-06-12 13:41:31.695 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Node is DEAD.