ZWave binding updates

[Andrew_Rowe]

@vespaman

OK, after doing a lot of tests…I now know what is the issue in my system

Micael absolutely great job diagnosing your issue!!!
davorf has now confirmed this was also his issue

[Chura (CR)]

Thank you and @chris it was my issue as well, after upgrading to 2.5GA last night, Zwave and Powermax flapping. I went into addon.config and found action.pushbullet and misc.restdocs. probably old addons that was removed, however still appeared in my config (installed from paper, not manually)

EDIT: so, my fault, its registered under “Things to do before upgrade”

openhab/openhab-distro

[Bruce_Osborne]

@Chura

misc.restdocs

If you want restdocs it got moved to user interfaces.

[feens (Trevor)]

@chris Updated to 2.5 yesterday, and now I seem to be having intermittent issues where things seem to be come unresponsive for a period of time. It seems to happen to various devices. Things will work fine for a bit, and then I’ll go to control an item and it just does nothing until a number of minutes later.

I pulled some logs from when it was a happening…look for Node 33 in this case.

2019-12-17 20:37:14.812 [nt.ItemStatePredictedEvent] - zwave_device_node33_switch_dimmer predicted to become OFF
2019-12-17 20:37:14.835 [vent.ItemStateChangedEvent] - zwave_device_node33_switch_dimmer changed from 100 to 0
2019-12-17 20:37:14.838 [GroupItemStateChangedEvent] - Dimmers changed from 75.00000000 to 62.50000000 through zwave_device_node33_switch_dimmer
==> /var/log/openhab2/openhab.log <==
2019-12-17 20:37:14.839 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Command received zwave:device:168118d907c:node33:switch_dimmer --> OFF [OnOffType]
2019-12-17 20:37:14.844 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 33: Creating new message for command SWITCH_MULTILEVEL_SET
2019-12-17 20:37:14.847 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: SECURITY not supported
2019-12-17 20:37:14.851 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-12-17 20:37:14.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Adding to device queue
2019-12-17 20:37:14.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Added 1945 to queue - size 14
2019-12-17 20:37:14.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:37:14.865 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling initialised at 86400 seconds - start in 3000 milliseconds.
2019-12-17 20:37:17.865 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling...
2019-12-17 20:37:17.867 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling zwave:device:168118d907c:node33:switch_dimmer
2019-12-17 20:37:17.869 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 33: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-12-17 20:37:17.870 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 33: Creating new message for command SWITCH_MULTILEVEL_GET
2019-12-17 20:37:17.873 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: SECURITY not supported
2019-12-17 20:37:17.874 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-12-17 20:37:17.876 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Polling skipped for zwave:device:168118d907c:node33:switch_dimmer on COMMAND_CLASS_BASIC
2019-12-17 20:37:17.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Adding to device queue
2019-12-17 20:37:17.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Added 1946 to queue - size 15
2019-12-17 20:37:17.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:37:24.156 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 45: TID 1932: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:37:24.157 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1932: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:37:24.159 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1932: Transaction CANCELLED
2019-12-17 20:37:24.161 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:37:24.162 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 45: notifyTransactionResponse TID:1932 CANCELLED
2019-12-17 20:37:24.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:37:24.169 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0C 03 25 01 00 25 95 7D 
2019-12-17 20:37:24.172 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 25 01 00 25 95 7D 
2019-12-17 20:37:24.174 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:37:24.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1933: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 149
2019-12-17 20:37:26.178 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 12: TID 1933: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:37:26.179 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:37:26.181 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1933: Transaction ABORTED
2019-12-17 20:37:26.183 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:37:26.186 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-12-17 20:37:26.188 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:37:26.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:37:38.182 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 12: TID 1933: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:37:38.184 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1933: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:37:38.185 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1933: Transaction CANCELLED
2019-12-17 20:37:38.187 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:37:38.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:1933 CANCELLED
2019-12-17 20:37:38.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:37:38.194 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0D 03 25 01 00 25 96 7F 
2019-12-17 20:37:38.197 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 0A 00 13 0D 03 25 01 00 25 96 7F 
2019-12-17 20:38:31.989 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:31.991 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-12-17 20:38:31.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:31.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-12-17 20:38:32.001 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-12-17 20:38:32.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-12-17 20:38:32.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-12-17 20:38:32.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-12-17 20:38:32.008 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-12-17 20:38:32.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-12-17 20:38:32.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-12-17 20:38:32.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-12-17 20:38:32.017 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-12-17 20:38:32.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.023 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-12-17 20:38:32.030 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.037 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-12-17 20:38:32.038 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 3<>125 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.040 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: sentData successfully placed on stack.
2019-12-17 20:38:32.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1934: Advanced to WAIT_REQUEST
2019-12-17 20:38:32.045 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 1934: Transaction not completed
2019-12-17 20:38:32.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 4<>124 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (3): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.051 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-12-17 20:38:32.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1934: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:32.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 4<>124 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2019-12-17 20:38:32.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1934: Resetting transaction
2019-12-17 20:38:32.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: notifyTransactionResponse TID:1934 WAIT_REQUEST
2019-12-17 20:38:32.064 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Adding to device queue
2019-12-17 20:38:32.067 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Added 1934 to queue - size 14
2019-12-17 20:38:32.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-12-17 20:38:32.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (4): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.077 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (3): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.082 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.087 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-12-17 20:38:32.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-12-17 20:38:32.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-12-17 20:38:32.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-12-17 20:38:32.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:38:32.310 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0D 03 25 01 00 25 96 7F 
2019-12-17 20:38:32.312 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 0A 00 13 0D 03 25 01 00 25 96 7F 
2019-12-17 20:38:32.314 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:32.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1934: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 150
2019-12-17 20:38:34.318 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 13: TID 1934: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:38:34.320 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:38:34.321 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1934: Transaction ABORTED
2019-12-17 20:38:34.322 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:38:34.325 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-12-17 20:38:34.330 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:34.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:38:46.322 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 13: TID 1934: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:38:46.325 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1934: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:38:46.326 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1934: Transaction CANCELLED
2019-12-17 20:38:46.328 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:38:46.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: notifyTransactionResponse TID:1934 CANCELLED
2019-12-17 20:38:46.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:38:46.335 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 2C 03 25 01 00 25 97 5F 
2019-12-17 20:38:46.338 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 44: Sending REQUEST Message = 01 0A 00 13 2C 03 25 01 00 25 97 5F 
2019-12-17 20:38:46.340 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:46.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1935: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 151
2019-12-17 20:38:48.344 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 44: TID 1935: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:38:48.345 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:38:48.347 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1935: Transaction ABORTED
2019-12-17 20:38:48.349 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:38:48.351 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-12-17 20:38:48.353 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:38:48.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:39:00.349 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 44: TID 1935: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:39:00.350 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1935: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:39:00.352 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1935: Transaction CANCELLED
2019-12-17 20:39:00.354 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 44: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:39:00.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 44: notifyTransactionResponse TID:1935 CANCELLED
2019-12-17 20:39:00.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:39:00.370 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 2D 03 25 01 FF 25 98 AE 
2019-12-17 20:39:00.373 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 45: Sending REQUEST Message = 01 0A 00 13 2D 03 25 01 FF 25 98 AE 
2019-12-17 20:39:00.375 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:39:00.377 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1942: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 152
2019-12-17 20:39:02.380 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 45: TID 1942: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:39:02.381 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:39:02.383 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1942: Transaction ABORTED
2019-12-17 20:39:02.386 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:39:02.389 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-12-17 20:39:02.391 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:39:02.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-12-17 20:39:14.385 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 45: TID 1942: Timeout at state ABORTED. 3 retries remaining.
2019-12-17 20:39:14.387 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1942: Transaction is current transaction, so clearing!!!!!
2019-12-17 20:39:14.389 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1942: Transaction CANCELLED
2019-12-17 20:39:14.391 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-12-17 20:39:14.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 45: notifyTransactionResponse TID:1942 CANCELLED
2019-12-17 20:39:14.395 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-12-17 20:39:14.399 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 21 03 26 01 00 25 99 5F 
2019-12-17 20:39:14.402 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 33: Sending REQUEST Message = 01 0A 00 13 21 03 26 01 00 25 99 5F 
2019-12-17 20:39:14.404 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-12-17 20:39:14.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1945: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 153
2019-12-17 20:39:16.409 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 33: TID 1945: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-12-17 20:39:16.410 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-12-17 20:39:16.412 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1945: Transaction ABORTED
2019-12-17 20:39:16.415 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-12-17 20:39:16.417 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA ```

[Andrew_Rowe]

@feens

Updated to 2.5 yesterday, and now I seem to be having intermittent issues where things seem to be come unresponsive for a period of time. It seems to happen to various devices

Hi Trevor
I think this is probably less of a symptom of a problem with the binding and more of a issue with a device flooding the network because it is low on battery power or something similar. The zwave binding is rock solid and you’ve already taken the first most important step in figuring it out, set the logs to debug and see what is going on.

[LukeRock]

I am having the same experience. Multiple instances of delays in responsiveness, post 2.5 upgrade. I haven’t done much troubleshooting yet, but something has dramatically changed with the upgrade.

[chris (Chris Jackson)]

@feens

Updated to 2.5 yesterday

What were you running before? There have been very few changes to the ZWave binding since 2.4, and even less since the last few milestones so I’m just trying to understand what changes have happened between versions. My guess is that it’s not related to the binding, but it’s hard to tell.

Looking at your log -:

To me, the issue appears to be network related. I see a lot of CAN messages - this means that the controller is busy and unable to accept commands. When I’ve seen this in the past, it’s often been caused by a node that has started spamming the network. Here we see lots of CAN messages coming in, and toward the end of the log, there are no responses from the controller. I don’t think this is a binding issue - it could be delays in the PC if there were serial port/USB issues maybe, otherwise I think it could be on the network side.

[chris (Chris Jackson)]

@LukeRock

I am having the same experience.

Sorry, but one of my biggest bug bears is when people say things like “I have the same problem” and don’t actually provide any information. More often than not when people say this, it is not the same problem.

To be fair, you say you have the same “experience” - so as a user you observe the same thing - maybe. However, in order to find what the problem is, you must report what issue you have and provide logs or other supporting information.

We had a “big issue” just before 2.5 was released which was people saying there was a major problem in the binding because multiple people had issues with the serial port. These issues turned out to be a number of different issues that were not related to the binding at all, so I really urge people to report the problem they see .

[feens (Trevor)]

@Andrew_Rowe I only have 2 battery devices in my network, so I’m fairly sure it’s not them (I don’t see any significant activity for them in my logs).

@chris Something flooding the network would make sense given the behaviour, but I can’t find any correlation to that in the logs. I did have a plug that was reporting power that I felt was sending too much traffic so I disabled that. I was running 2.4 previously (with no issues for quite some time).

I would think it’s something other than the binding, except my non-zwave items seem to be working fine. It’s still suspect to me that everything was working quite well right up until I upgraded to 2.5.

[Bruce_Osborne]

@feens

I did have a plug that was reporting power that I felt was sending too much traffic so I disabled that.

How did you disable that? If it is off the network but still appears as a (zombie) node then devices may still try and route through the non-existent device.

[LukeRock]

That’s fair. I am having the same experience.

I will get more time over the next few days, to dig through logs, and see what is going on. For what it is worth, after rebooting my RaspberryPi and allowing a Z-Wave network heal to occur, things appear to be back to my 2.4 performance levels.

What I did experience for the first 24 hours after the upgrade to 2.5, was a delay of up to 15 minutes for my Z-Wave devices to respond to a command, if at all.

Here is a snapshot of some of the logs, which do indicate some network issues. Why the update would have triggered that, is really the question, if that is the case.

2019-12-18 02:53:36.124 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node20’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.145 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node21’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.166 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node22’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.185 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node23’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.208 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node24’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.270 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node50’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.292 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node49’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.313 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node48’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.339 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node47’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller

2019-12-18 02:53:36.422 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node2’ has been updated.

2019-12-18 02:53:37.661 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node2’ has been updated.

2019-12-18 02:54:30.679 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node10’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

==> /var/log/openhab2/openhab.log <==

2019-12-18 03:01:10.190 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.

==> /var/log/openhab2/events.log <==

2019-12-18 03:08:14.476 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node42’ has been updated.

2019-12-18 03:08:14.531 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node32’ has been updated.

2019-12-18 03:17:02.401 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node42’ has been updated.

2019-12-18 03:17:02.472 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node42’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:17:03.056 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node34’ has been updated.

2019-12-18 03:25:48.229 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node43’ has been updated.

==> /var/log/openhab2/openhab.log <==

2019-12-18 03:25:48.242 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.

==> /var/log/openhab2/events.log <==

2019-12-18 03:35:01.565 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node32’ has been updated.

2019-12-18 03:35:01.609 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node32’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

==> /var/log/openhab2/openhab.log <==

2019-12-18 03:36:08.091 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 7: Device discovery could not resolve to a thingType! Manufacturer data not known.

2019-12-18 03:36:08.100 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:d7db299b:node7’ to inbox.

==> /var/log/openhab2/events.log <==

2019-12-18 03:36:08.101 [home.event.InboxAddedEvent] - Discovery Result with UID ‘zwave:device:d7db299b:node7’ has been added.

2019-12-18 03:44:51.956 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node30’ has been updated.

2019-12-18 03:44:53.508 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node43’ has been updated.

2019-12-18 03:44:53.583 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node43’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:53:53.169 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node5’ has been updated.

==> /var/log/openhab2/openhab.log <==

2019-12-18 03:53:53.186 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.

==> /var/log/openhab2/events.log <==

2019-12-18 03:53:55.909 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node5’ has been updated.

2019-12-18 03:53:55.964 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node5’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:53:56.579 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node34’ has been updated.

2019-12-18 03:53:56.594 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node15’ has been updated.

2019-12-18 03:53:56.615 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node34’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:53:56.697 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node21’ has been updated.

2019-12-18 03:53:57.815 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node15’ has been updated.

2019-12-18 03:53:57.872 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node15’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:53:58.670 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node21’ has been updated.

2019-12-18 03:53:58.697 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node35’ has been updated.

2019-12-18 03:53:58.715 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node21’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:53:58.796 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node36’ has been updated.

2019-12-18 03:54:06.352 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node35’ has been updated.

2019-12-18 03:54:06.382 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node35’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:54:07.896 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node36’ has been updated.

2019-12-18 03:54:07.917 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node45’ has been updated.

2019-12-18 03:54:07.938 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node36’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:54:07.952 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node6’ has been updated.

2019-12-18 03:54:11.861 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node6’ has been updated.

2019-12-18 03:54:11.895 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node6’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:54:12.669 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node37’ has been updated.

2019-12-18 03:54:14.844 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node45’ has been updated.

2019-12-18 03:54:14.882 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node45’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:54:15.796 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node31’ has been updated.

2019-12-18 03:54:23.166 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node37’ has been updated.

2019-12-18 03:54:23.194 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node37’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:54:24.091 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node38’ has been updated.

2019-12-18 03:54:26.026 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node31’ has been updated.

2019-12-18 03:54:26.051 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node31’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:54:26.152 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node50’ has been updated.

2019-12-18 03:54:33.031 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node38’ has been updated.

2019-12-18 03:54:33.057 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node38’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:54:33.807 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node48’ has been updated.

2019-12-18 03:54:35.978 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node50’ has been updated.

2019-12-18 03:54:36.003 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node50’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 03:54:36.111 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node28’ has been updated.

2019-12-18 04:11:52.320 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node20’ has been updated.

2019-12-18 04:11:58.763 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node48’ has been updated.

2019-12-18 04:11:58.842 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node48’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:11:59.498 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node20’ has been updated.

2019-12-18 04:11:59.510 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node20’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:11:59.637 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node40’ has been updated.

2019-12-18 04:12:01.939 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node40’ has been updated.

2019-12-18 04:12:01.964 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node40’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:12:02.074 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node19’ has been updated.

2019-12-18 04:12:04.862 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node19’ has been updated.

2019-12-18 04:12:04.887 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node19’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:12:04.913 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node46’ has been updated.

2019-12-18 04:12:05.976 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node22’ has been updated.

2019-12-18 04:12:06.001 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node22’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:12:08.051 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node10’ has been updated.

2019-12-18 04:12:11.496 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node46’ has been updated.

2019-12-18 04:12:11.543 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node46’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:12:12.768 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node16’ has been updated.

2019-12-18 04:12:15.332 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node16’ has been updated.

2019-12-18 04:12:15.342 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node16’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:12:15.768 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node17’ has been updated.

2019-12-18 04:12:15.771 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node10’ has been updated.

2019-12-18 04:12:15.791 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node23’ has been updated.

2019-12-18 04:12:17.028 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node17’ has been updated.

2019-12-18 04:12:17.041 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node17’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:12:18.022 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node23’ has been updated.

2019-12-18 04:12:18.038 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node44’ has been updated.

2019-12-18 04:12:18.051 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node23’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:12:18.115 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node8’ has been updated.

2019-12-18 04:12:22.544 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node8’ has been updated.

2019-12-18 04:12:22.576 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node8’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:12:25.703 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node44’ has been updated.

2019-12-18 04:12:25.725 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node44’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:43:30.585 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node47’ has been updated.

2019-12-18 04:43:30.624 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node4’ has been updated.

2019-12-18 04:43:30.792 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node4’ has been updated.

2019-12-18 04:43:30.833 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node4’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 04:50:21.934 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node47’ has been updated.

2019-12-18 04:50:22.014 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node47’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 05:00:01.896 [vent.ItemStateChangedEvent] - GE_Plugin_3 changed from OFF to ON

2019-12-18 05:00:18.976 [vent.ItemStateChangedEvent] - Basement_Office_Dimmer changed from NULL to 0

2019-12-18 05:03:12.724 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node28’ has been updated.

2019-12-18 05:03:12.789 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node28’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 05:04:58.473 [vent.ItemStateChangedEvent] - Upstairs_Bathroom_Dimmer changed from NULL to 0

2019-12-18 05:04:58.522 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node41’ changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE

2019-12-18 05:07:51.002 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node14’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

2019-12-18 05:10:07.872 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node24’ has been updated.

2019-12-18 05:10:08.991 [me.event.ThingUpdatedEvent] - Thing ‘zwave:device:d7db299b:node24’ has been updated.

2019-12-18 05:10:09.011 [hingStatusInfoChangedEvent] - ‘zwave:device:d7db299b:node24’ changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

==> /var/log/openhab2/openhab.log <==

2019-12-18 05:23:59.695 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovery could not resolve to a thingType! Manufacturer data not known.

2019-12-18 05:23:59.703 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:d7db299b:node11’ to inbox.

[feens (Trevor)]

@Bruce_Osborne

How did you disable that? If it is off the network but still appears as a (zombie) node then devices may still try and route through the non-existent device.

Sorry, I disabled the energy reporting, not the device…the device itself works fine.

[Andrew_Pawelski]

@feens

@chris Something flooding the network would make sense given the behaviour, but I can’t find any correlation to that in the logs. I did have a plug that was reporting power that I felt was sending too much traffic so I disabled that. I was running 2.4 previously (with no issues for quite some time).

I “had the same thing” a while back where I had a good experience for a while after a reboot, then slowly got worse where I thought my zwave network must have been getting tired because it happened mostly late at night (but this is probs when more devices re being used eg lights) and it was to the point I could toggle an OH switch and count to 5 sometimes longer before the light would respond.

I had the same logs, things in the queue etc, I went through and excluded every zwave device, factory reset the z-stick then included- same problem - tried it on a different NUC, different OH instance - think even different version - same problem.

So, in an act if insanity, I did the same thing again (excluded, factory reset, included) and ran it from the SAME OH instance, version, binding and like magic it worked and performance was excellent.

What I didnt realize was that I forgot to include one device, (not sure if important but a battery powered ZXT-120 IR A/C emitter which was not run on batteries but permanent USB), I included this device, and the delays reappeared, exclude the device - performance back up.

I have since factory reset the ZXT-120 and reincluded it and things are still good.

So, that was a long story but thought it might help someone else join the dots on what they are experiencing. I was lucky enough to have accidentally found the offending device, and it could well be that the FLiRS mode of the battery device went awry, but now discovered with permanent power on at the time after a reset I am good again.

I am on 2.5M2 (cant upgrade till the broadlink binding is compatible with the GM version).

[Bruce_Osborne]

@Andrew_Pawelski

it could well be that the FLiRS mode of the battery device went awry, but now discovered with permanent power on at the time after a reset I am good again.

I have one sensor that can be either USB or battery powered. According to the vendor if you are using USB mode it must be use powered when included in the network.

[feens (Trevor)]

The thing is…mine was working perfectly fine on 2.4. I’ve checked my battery devices and they all seem to work without issue (and have good battery levels).

One theory I have is that something in the binding has changed that has exposed/reacted differently to a bad device. I did look through some of the changes to the binding since 2.4 and nothing sticks out, but obviously I don’t know the codebase.

[Andrew_Rowe]

@Andrew_Pawelski

So, that was a long story but thought it might help someone else join the dots on what they are experiencing. I was lucky enough to have accidentally found the offending device

yes… excellent example… we see a lot of very similar type things here in the forum. One bad node can spoil the party and it does seem to crop up on upgrades and stuff and it is easy to point the finger at the upgrade when the problem was probably there before the upgrade

[phinnay]

I’ve been pulling my hair out on this one since upgrading; the zwave plugin would work briefly when I first restarted openhab, then restart itself over and over

Fixing an unrelated error seems to have solved it - I was getting an error referencing a ‘restdocs’ plugin. Removing the line misc="restdocs"from addons.config stopped the plugin restarts and allowed zwave to stabilize.

on my system it is located at openHAB2-userdata/config/org/openhab/addons.config

[feens (Trevor)]

I’m curious if the logs (debug or trace) would reveal a bad device. I.e. would I see activity for the device or is it just a trial and error thing? @chris you maybe be able to answer that. I’d prefer to not have to rebuild my whole setup.

[Andrew_Rowe]

@phinnay

Fixing an unrelated error seems to have solved it - I was getting an error referencing a ‘restdocs’ plugin. Removing the line misc="restdocs" from addons.config stopped the plugin restarts and allowed zwave to stabilize.

this is actually at this point a well know issue, glad you got it sorted, and yes, it had nothing to do with the zwave binding

[Andrew_Rowe]

@feens

I’m curious if the logs (debug or trace) would reveal a bad device.

yes, I believe the logs start showing a ton of ‘CAN’ entries or some such

@chris

I see a lot of CAN messages - this means that the controller is busy and unable to accept commands. When I’ve seen this in the past, it’s often been caused by a node that has started spamming the network.

, which is the controller choking

but edit to add… you only see the network bogging down, you don’t see the specific node, takes a little detective work