Zwave Controller goes offline and can't recovery after night

Zwave.log almost only contains debug messages… did you download it ?

Using the log viewer I found something suspicious I couldn’t explain. Is node 255 a broadcast message?
Just about that time before everything stops working (04:03:50)

|04:03:50.799||TX REQ SendDataAbort

01 03 00 16 EA

The snippet you posted was only INFO messages. I looked quickly at zwave.log. Why is there a big time gap at 4:06-4:16 am? Seems to me that’s when stuff happened.

2021-03-18 04:06:37.053 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-18 04:06:37.053 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-18 04:06:54.862 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling...
2021-03-18 04:16:42.561 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling...
2021-03-18 04:16:43.291 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveNodeStatusEvent

The snipped were openhab and events log, only zwave was set to debug. Wasn’t there an optional for debugging serial too?
I can add whatever log somebody thinks is of interest. Usually it takes only one day to reoccur.

I don’t have an explanation for the time gap in the zwave.log though…

Small Update - so far 4 days and the items are still online.
It’s weird that now that finally debugging is fully active the system doesn’t stop working …

Bad News … this night it went offline again. I wasn’t home for those days. The only thing i know which might be different is that because i wasn’t home the Fibraro Motion Sensor wasn’t triggered.
I’ve set it to update quite frequently - could this be flooding my zwave network?

I’ve update the latest logs to download from my NAS:
http://gofile.me/6wJZy/AwmhoQX98

openhab.log has only one line which i deem suspicious in regards to the discussion:
2021-03-23 04:04:02.372 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@12919479' takes more than 5000ms.

following events.logs the issue seem to have happend between 4:06 (last successful update) and 4:17 (first node reporting offline)

2021-03-23 04:06:23.286 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ArbeitszimmerThermostat_Sensortemperature' changed from 19.38 °C to 19.42 °C
2021-03-23 04:10:36.486 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'openweathermap:weather-and-forecast:8fa826c227:local' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Total timeout 10000 ms elapsed
2021-03-23 04:10:36.925 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'openweathermap:weather-api:8fa826c227' changed from ONLINE to OFFLINE
2021-03-23 04:17:05.367 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:57dc600655:node2' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2021-03-23 04:20:39.753 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:57dc600655:node8' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2021-03-23 04:20:39.942 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:57dc600655:node10' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2021-03-23 04:20:46.414 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:57dc600655:node4' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2021-03-23 04:30:04.983 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:57dc600655:node7' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2021-03-23 04:33:27.594 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:57dc600655:node6' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2021-03-23 04:48:55.471 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:57dc600655:node5' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

and finally zwave.log (parts of it)

2021-03-23 04:10:27.241 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 04 46 08 00 7F 
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2021-03-23 04:10:27.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2021-03-23 04:10:27.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE, endpoint 0
2021-03-23 04:10:27.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY not supported
2021-03-23 04:10:27.242 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE V1 SCHEDULE_OVERRIDE_REPORT
2021-03-23 04:10:27.242 [DEBUG] [veClimateControlScheduleCommandClass] - NODE 5: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@515cf4e4.
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 04 46 08 00 7F 
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-23 04:10:27.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2021-03-23 04:10:27.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2021-03-23 04:10:27.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE, endpoint 0
2021-03-23 04:10:27.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY not supported
2021-03-23 04:10:27.242 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE V1 SCHEDULE_OVERRIDE_REPORT
2021-03-23 04:10:27.243 [DEBUG] [veClimateControlScheduleCommandClass] - NODE 5: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2021-03-23 04:10:27.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
2021-03-23 04:10:27.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@bcffd65.
2021-03-23 04:10:27.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-23 04:10:27.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-23 04:10:27.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-23 04:10:27.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-23 04:17:01.170 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
2021-03-23 04:17:01.371 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:17:01.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Setting OFFLINE
2021-03-23 04:17:05.367 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is DEAD
2021-03-23 04:17:05.402 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Node is DEAD.
2021-03-23 04:17:05.402 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:17:05.402 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Setting OFFLINE
2021-03-23 04:17:05.402 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is DEAD
2021-03-23 04:18:55.236 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling...
2021-03-23 04:19:37.183 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
2021-03-23 04:20:39.475 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling...
2021-03-23 04:20:39.480 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling...
2021-03-23 04:20:39.586 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:20:39.586 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:20:39.587 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Setting OFFLINE
2021-03-23 04:20:39.587 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Setting OFFLINE
2021-03-23 04:20:39.752 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 10: Node Status event - Node is DEAD
2021-03-23 04:20:39.752 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 8: Node Status event - Node is DEAD
2021-03-23 04:20:39.753 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Node is DEAD.
2021-03-23 04:20:39.753 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Node is DEAD.
2021-03-23 04:20:39.753 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:20:39.753 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:20:39.753 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Setting OFFLINE
2021-03-23 04:20:39.753 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Setting OFFLINE
2021-03-23 04:20:39.753 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 8: Node Status event - Node is DEAD
2021-03-23 04:20:39.942 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 10: Node Status event - Node is DEAD
2021-03-23 04:20:46.412 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling...
2021-03-23 04:20:46.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:20:46.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Setting OFFLINE
2021-03-23 04:20:46.413 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 4: Node Status event - Node is DEAD
2021-03-23 04:20:46.413 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Node is DEAD.
2021-03-23 04:20:46.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:20:46.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Setting OFFLINE
2021-03-23 04:20:46.413 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 4: Node Status event - Node is DEAD
2021-03-23 04:23:34.697 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling...
2021-03-23 04:30:04.231 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling...
2021-03-23 04:30:04.492 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:30:04.492 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Setting OFFLINE
2021-03-23 04:30:04.931 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 7: Node Status event - Node is DEAD
2021-03-23 04:30:04.931 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: Node is DEAD.
2021-03-23 04:30:04.931 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:30:04.931 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Setting OFFLINE
2021-03-23 04:30:04.931 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 7: Node Status event - Node is DEAD
2021-03-23 04:33:27.045 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling...
2021-03-23 04:33:27.378 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:33:27.593 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Setting OFFLINE
2021-03-23 04:33:27.593 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 6: Node Status event - Node is DEAD
2021-03-23 04:33:27.593 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Node is DEAD.
2021-03-23 04:33:27.593 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:33:27.594 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Setting OFFLINE
2021-03-23 04:33:27.594 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 6: Node Status event - Node is DEAD
2021-03-23 04:47:01.170 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
2021-03-23 04:48:55.236 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling...
2021-03-23 04:48:55.298 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:48:55.298 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Setting OFFLINE
2021-03-23 04:48:55.444 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 5: Node Status event - Node is DEAD
2021-03-23 04:48:55.444 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Node is DEAD.
2021-03-23 04:48:55.444 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2021-03-23 04:48:55.444 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Setting OFFLINE
2021-03-23 04:48:55.444 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 5: Node Status event - Node is DEAD

respective zwave.log part as screenshot from Z-Wave Log Viewer

How often is ‘quite frequently’?

@Andrew_Rowe it’s node 9 in the log files i linked …
in the thing configuration the following settings are appied to the fibaro motion sensor:

  • Blind time (1,5 sec)
  • Polling Period 86400
  • Command Poll Period 1500

looking at zwave.log files it doesn’t seem to appear as often as i thought… at least following the node stats. Is this because it’s the messages sent as opposed to received which lists as “undefined” ?

zwave.log → 1 message sent
zwave.log5 → 0 occurances
zwave.log6 → 5 occurances
zwave.log7 → 4 occurances

most thermostats have around 125 sent occurances per logfile

Today i found 3 more things

  1. The system crashed during the day (not at 4AM)
    last messages seem to be related to security setting issues with node 7 … should i try to turn off security?
2021-03-24 19:36:08.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:57dc600655:node7:thermostat_setpoint_heating --> 16 °C [QuantityType]
2021-03-24 19:36:08.604 [DEBUG] [ter.ZWaveThermostatSetpointConverter] - NODE 7: Thermostat command received for 16 °C
2021-03-24 19:36:08.604 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 7: Creating new message for command THERMOSTAT_SETPOINT_SET
2021-03-24 19:36:08.604 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: SECURITY not supported
2021-03-24 19:36:08.604 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: Command Class COMMAND_CLASS_THERMOSTAT_SETPOINT is NOT required to be secured
2021-03-24 19:36:08.604 [DEBUG] [ter.ZWaveThermostatSetpointConverter] - NODE 7: Sending Message: org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@70c2748c
2021-03-24 19:36:08.604 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 7: Creating new message for application command THERMOSTAT_SETPOINT_GET (Heating)
2021-03-24 19:36:08.604 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: SECURITY not supported
2021-03-24 19:36:08.604 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: Command Class COMMAND_CLASS_THERMOSTAT_SETPOINT is NOT required to be secured
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Bump transaction 15009 priority from Set to Immediate
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Adding to device queue
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Transaction already in queue - removed original
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Added 15009 to queue - size 12
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Bump transaction 15010 priority from Get to Immediate
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Adding to device queue
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Transaction already in queue - removed original
2021-03-24 19:36:08.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Added 15010 to queue - size 12
2021-03-24 19:36:08.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-24 19:36:08.605 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling initialised at 1800 seconds - start in 1500 milliseconds.
2021-03-24 19:36:10.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling...
  1. docker log showed something suspicious which kinda made the whole UI not accessible … should i worry?
2021-03-23 06:56:39,stdout,"Security framework of XStream not explicitly initialized, using predefined black list on your own risk.
"
2021-03-23 06:56:25,stdout,	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:778)

2021-03-23 06:56:25,stdout,java.lang.NullPointerException

2021-03-23 06:56:25,stdout,

2021-03-23 06:56:25,stdout,Exception in thread "ZWaveReceiveProcessorThread" 

what type of device is this? Unless it is a lock or something which requires security, it creates a lot of extra traffic. I have seen security enable zwave device swamp a system and lock it up. That an having nodes reporting in very short intervals also can be problematic in larger systems

node 1 is my controller,
node 3 is a main powered powermete /switch
node 9 a fibaro motion sensor
node 2 a comet-zwave thermostat
all other nodes 4,5,6,7,8,10 are develo thermostats

in more detail - node 7 is a “Danfoss MT02650” equivalent added as GENERIC_TYPE_THERMOSTAT

I finally decided to give up on that issue.
I got myself a Rasberry 3 and migrated my userdata files to an openhabian installation. So far everything works flawlessly … I’ll let you know in a new post in case other issues appear.

1 Like