Z-wave sensor stops reporting values ("Polling deferred until initialisation complete")

Add-ons Bindings
,
1
  • Platform information:
    • OS: Debian 9.4 64-bit
    • Java Runtime Environment: openjdk version “1.8.0_181” OpenJDK Runtime Environment (build 1.8.0_181-8u181-b13-1~deb9u1-b13)
    • openHAB version: 2.3.0
    • z-wave version: 2.4.0.201809081506
    • z-wave controller: aeotec gen5

Hi all!

I have a pretty small z-wave network with only 4 nodes and its great compared to the 433 Mhz. But the latest addition to the network (Node 6, MCO Home MH9-CO2 Sensor) started to mess things up (i think the sensor is the cause but I cant be certain). The network was working great but after some time the CO2-sensor gets stuck and doesn’t report any more values. But the sensor is not reported as dead.
This has happened a couple of times and the first time I had some missconfigs I thought was the cause for this problem (yes, I’m a z-wave/openhab noob :cowboy_hat_face:). But here we are some weeks later and the problem has occurred once again.

The first log is the last report from the sensor (no cuts):

12-Dec-2018 00:00:46.885 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:DONE)
12-Dec-2018 00:00:46.885 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: resetResendCount initComplete=true isDead=false
12-Dec-2018 00:00:46.885 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
12-Dec-2018 00:00:46.885 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported
12-Dec-2018 00:00:46.885 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 6: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
12-Dec-2018 00:00:46.885 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 6: Sensor Type = CO2(17), Scale = 0
12-Dec-2018 00:00:46.886 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 6: Sensor Value = 804
12-Dec-2018 00:00:46.886 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMultiLevelSensorValueEvent
12-Dec-2018 00:00:46.886 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
12-Dec-2018 00:00:46.886 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 804
12-Dec-2018 00:00:46.886 [DEBUG] [.internal.converter.ZWaveMultiLevelSensorConverter] - NODE 6: Sensor conversion not performed for CO2.
12-Dec-2018 00:00:46.886 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating channel state zwave:device:dd005807:node6:sensor_co2 to 804 [DecimalType]
12-Dec-2018 00:00:46.886 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Commands processed 1.
12-Dec-2018 00:00:46.888 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6e4d1bbf.
12-Dec-2018 00:00:46.888 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
12-Dec-2018 00:00:46.888 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
12-Dec-2018 00:00:46.889 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12-Dec-2018 00:00:46.889 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
12-Dec-2018 00:00:46.889 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
12-Dec-2018 00:00:46.889 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
12-Dec-2018 00:11:26.771 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling...
12-Dec-2018 00:11:26.772 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling zwave:device:dd005807:node6:sensor_temperature
12-Dec-2018 00:11:26.772 [DEBUG] [.internal.converter.ZWaveMultiLevelSensorConverter] - NODE 6: Generating poll message for COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
12-Dec-2018 00:11:26.772 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 6: Creating new message for command SENSOR_MULTILEVEL_GET
12-Dec-2018 00:11:26.772 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Encapsulating message, endpoint 0
12-Dec-2018 00:11:26.772 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported
12-Dec-2018 00:11:26.772 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_SENSOR_MULTILEVEL is NOT required to be secured
12-Dec-2018 00:11:26.772 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling zwave:device:dd005807:node6:sensor_relhumidity
12-Dec-2018 00:11:26.772 [DEBUG] [.internal.converter.ZWaveMultiLevelSensorConverter] - NODE 6: Generating poll message for COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
12-Dec-2018 00:11:26.772 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 6: Creating new message for command SENSOR_MULTILEVEL_GET
12-Dec-2018 00:11:26.773 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Encapsulating message, endpoint 0
12-Dec-2018 00:11:26.773 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported
12-Dec-2018 00:11:26.773 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_SENSOR_MULTILEVEL is NOT required to be secured
12-Dec-2018 00:11:26.773 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling zwave:device:dd005807:node6:sensor_co2
12-Dec-2018 00:11:26.773 [DEBUG] [.internal.converter.ZWaveMultiLevelSensorConverter] - NODE 6: Generating poll message for COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
12-Dec-2018 00:11:26.773 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 6: Creating new message for command SENSOR_MULTILEVEL_GET
12-Dec-2018 00:11:26.773 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Encapsulating message, endpoint 0
12-Dec-2018 00:11:26.773 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported
12-Dec-2018 00:11:26.773 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_SENSOR_MULTILEVEL is NOT required to be secured
12-Dec-2018 00:11:26.774 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue
12-Dec-2018 00:11:26.774 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Added to queue - size 1
12-Dec-2018 00:11:26.774 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
12-Dec-2018 00:11:26.774 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == true, frequentlyListening == false, awake == false
12-Dec-2018 00:11:26.774 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
12-Dec-2018 00:11:26.774 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
12-Dec-2018 00:11:26.774 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 6: Creating empty message of class = SendData (0x13), type = Request
12-Dec-2018 00:11:26.774 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 47
12-Dec-2018 00:11:26.774 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 13 06 04 31 04 01 00 25 DB 2F
12-Dec-2018 00:11:26.775 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message = 01 0B 00 13 06 04 31 04 01 00 25 DB 2F
12-Dec-2018 00:11:26.935 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
12-Dec-2018 00:11:26.935 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: Transaction Start type SendData
12-Dec-2018 00:11:26.935 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 8481: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 219
12-Dec-2018 00:11:26.935 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_SENSOR_MULTILEVEL
12-Dec-2018 00:11:26.936 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 5
12-Dec-2018 00:11:26.936 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
12-Dec-2018 00:11:26.936 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
12-Dec-2018 00:11:26.937 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
12-Dec-2018 00:11:26.937 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12-Dec-2018 00:11:26.937 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12-Dec-2018 00:11:26.937 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12-Dec-2018 00:11:26.937 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
12-Dec-2018 00:11:26.937 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
12-Dec-2018 00:11:26.937 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12-Dec-2018 00:11:26.938 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 12 00:11:28 CET 2018 - 2000ms
12-Dec-2018 00:11:26.938 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 8481: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 219
12-Dec-2018 00:11:26.938 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
12-Dec-2018 00:11:26.938 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12-Dec-2018 00:11:26.938 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
12-Dec-2018 00:11:26.939 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 12 00:11:28 CET 2018 - 1999ms
12-Dec-2018 00:11:26.939 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
12-Dec-2018 00:11:26.939 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 12 00:11:28 CET 2018 - 1999ms
12-Dec-2018 00:11:26.939 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue
12-Dec-2018 00:11:26.939 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Added to queue - size 1
12-Dec-2018 00:11:26.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
12-Dec-2018 00:11:26.940 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12-Dec-2018 00:11:26.940 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
12-Dec-2018 00:11:26.940 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 12 00:11:28 CET 2018 - 1998ms
12-Dec-2018 00:11:26.941 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue
12-Dec-2018 00:11:26.941 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: Added to queue - size 2
12-Dec-2018 00:11:26.941 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
12-Dec-2018 00:11:26.941 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
12-Dec-2018 00:11:26.942 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12-Dec-2018 00:11:26.942 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
12-Dec-2018 00:11:26.942 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 12 00:11:28 CET 2018 - 1996ms
12-Dec-2018 00:11:26.951 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
12-Dec-2018 00:11:26.951 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
12-Dec-2018 00:11:26.952 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = -24
12-Dec-2018 00:11:26.952 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
12-Dec-2018 00:11:26.952 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
12-Dec-2018 00:11:26.952 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
12-Dec-2018 00:11:26.953 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
12-Dec-2018 00:11:26.953 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
12-Dec-2018 00:11:26.953 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
12-Dec-2018 00:11:26.953 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
12-Dec-2018 00:11:26.953 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 8481: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 219
12-Dec-2018 00:11:26.954 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12-Dec-2018 00:11:26.954 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 8481: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 219
12-Dec-2018 00:11:26.954 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
12-Dec-2018 00:11:26.954 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
12-Dec-2018 00:11:26.954 [TRACE] [ternal.protocol.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
12-Dec-2018 00:11:26.954 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 6: sentData successfully placed on stack.
12-Dec-2018 00:11:26.954 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance ST: WAIT_RESPONSE
12-Dec-2018 00:11:26.954 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance WT: ApplicationCommandHandler {}
12-Dec-2018 00:11:26.954 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
12-Dec-2018 00:11:26.954 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance TO: WAIT_REQUEST
12-Dec-2018 00:11:26.955 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 8481: Advanced to WAIT_REQUEST
12-Dec-2018 00:11:26.955 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: TID 8481: Transaction not completed
12-Dec-2018 00:11:26.955 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12-Dec-2018 00:11:26.955 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
12-Dec-2018 00:11:26.955 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12-Dec-2018 00:11:26.955 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
12-Dec-2018 00:11:26.955 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 12 00:11:31 CET 2018 - 5000ms
12-Dec-2018 00:11:26.959 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
12-Dec-2018 00:11:26.971 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 DB 00 00 02 32
12-Dec-2018 00:11:26.971 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 DB 00 00 02 32
12-Dec-2018 00:11:26.971 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 50
12-Dec-2018 00:11:26.972 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
12-Dec-2018 00:11:26.972 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 0: Message payload = DB 00 00 02
12-Dec-2018 00:11:26.972 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
12-Dec-2018 00:11:26.974 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
12-Dec-2018 00:11:26.974 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=219, payload=DB 00 00 02
12-Dec-2018 00:11:26.975 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=219, payload=DB 00 00 02
12-Dec-2018 00:11:26.975 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=219, payload=DB 00 00 02
12-Dec-2018 00:11:26.975 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 8481: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 219
12-Dec-2018 00:11:26.976 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12-Dec-2018 00:11:26.976 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 8481: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 219
12-Dec-2018 00:11:26.976 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 8481: (Callback 219)
12-Dec-2018 00:11:26.976 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
12-Dec-2018 00:11:26.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 8481: callback 219
12-Dec-2018 00:11:26.977 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=219, payload=DB 00 00 02
12-Dec-2018 00:11:26.977 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
12-Dec-2018 00:11:26.977 [TRACE] [ternal.protocol.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
12-Dec-2018 00:11:26.978 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 219, Status = Transmission complete and ACK received(0)
12-Dec-2018 00:11:26.978 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: resetResendCount initComplete=true isDead=false
12-Dec-2018 00:11:26.978 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance ST: WAIT_REQUEST
12-Dec-2018 00:11:26.978 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
12-Dec-2018 00:11:26.978 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance WT: ApplicationCommandHandler {}
12-Dec-2018 00:11:26.979 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=219, payload=DB 00 00 02
12-Dec-2018 00:11:26.979 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler
12-Dec-2018 00:11:26.979 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 8481: TransactionAdvance TO: WAIT_DATA
12-Dec-2018 00:11:26.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 8481: Advanced to WAIT_DATA
12-Dec-2018 00:11:26.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 6: TID 8481: Transaction not completed
12-Dec-2018 00:11:26.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12-Dec-2018 00:11:26.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
12-Dec-2018 00:11:26.981 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
12-Dec-2018 00:11:26.981 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer

This is a couple of hours later and this is whats happens from now on. The unit and another node (Node 5, a Fibaro dimmer2 that seems to be working as it should) reports “Polling deferred until initialisation complete”

12-Dec-2018 07:07:54.411 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@2da94f10
12-Dec-2018 07:11:26.771 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling...
12-Dec-2018 07:11:26.771 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling deferred until initialisation complete
12-Dec-2018 07:13:21.846 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling...
12-Dec-2018 07:13:21.846 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling deferred until initialisation complete
12-Dec-2018 07:19:08.221 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@19896ca0
12-Dec-2018 07:19:08.221 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
12-Dec-2018 07:19:08.222 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Added to queue - size 1

Help is much appreciated! :dizzy:

2

The symptom had almost spread to all my nodes (Polling deferred until initialisation complete). And a usual, once I restart openhab everything works for some time.
But I just found that someone (wife) had put a wardrobe against the dimmer wall switch. Making it dimm up and down (there are currently no lights connected to the sockets).
Could this have been the culprit?

3

From the logs it doesn’t look like anything is wrong - the new device is just not fully initialised so the binding doesn’t try to poll. To complete the initialisation, it needs to be woken up - have a look at the manual for how to do this.

Once the initialisation completes, then it should perform the polling. This is just a debug message, so you should not worry too much about it.

I should add that polling is not the recommended way to get sensor data from ZWave devices. Also, unless the device wakes up, it can’t ever poll anyway.

4

Yes! I was hoping that you would help Chris :slight_smile:

NODE 6 (the MCO multi sensor) is mains connected and has no info in the manual about sleep/waking up. I see that all my nodes have had this “issue” when I search the log. I thought that only battery devices had “sleep mode”, and I have no battery nodes.
But you seem to be right that this has nothing to do with the problem. Because now the sensor stopped reporting again and another node (Node 4) has gone dead in the last couple of hours.
I’ve uploaded the log file, starting 15 minutes before the last sensor report (29-Dec-2018 15:18:01.074) and NODE 4 is reported dead at 29-Dec-2018 15:26:13.519
https://file.io/vCSNYv

Help is much appreciated! :christmas_tree:

5

Correct - I didn’t look at the devices in question, so this was an assumption as it’s the normal cause.

The bottom line is still the same - polling is not performed while a device is still initialising. The question is why it’s still initialising if the devices are mains powered.

I see in the first log, that initialisation is actually complete ALIVE:DONE (the DONE part means init is complete). I guess later you may have restarted the binding and this will mean there is a little bit of reinitialisation to complete (it’s normally very short). Given the second log above is only 8 lines, it’s hard to say what is happening.

image

6

Hmmm
https://file.io/7s814E
also

7

Still the same result - page not found.

8


Did you get it? I don’t know any good site for uploading files…

9

This link works - thanks.

10

The log shows that node 4 is not responding to requests. Other nodes seem to be ok - they are initialised, and there should be no problem with polling. I don’t see any errors in the log, and no issues with the reported “polling deferred”.

You should look at node 4 to see what is wrong - it might be out of range, or it might have some other problem.

11

Strange… But thanks for your time.
Node 4 is approx 3 m from the controller to one side and Node 6 to the other, through a brick wall and has not had any problems before…
It was cheap but I have antother thats working great aprox 5 m from the controller.
I will look in to replacing it maybe.

12

But how come that everything works when I restart OH?

13

I don’t know. All I can say is that in the log you provided, node 4 was not responding every time, so something is not right -:

image
image1014×658 127 KB

The first time above it does respond, the next 2 times it doesn’t. These NO ACK messages come from the controller, so it has decided that there was no low level ack at the protocol level.

I can’t really say much more than that I’m agraid.

14

Hmmm, here is the complete log from the last restart yesterday.

15

I will take a look, but it’s unlikely to provide a lot more information than the segment above. If the device is close to the controller, and sometimes it’s not responding, then I’m not sure what you can do.

16

1 in 4 messages to this node are not getting responses -:

image
image.png1308×380 16.3 KB

Other nodes seem to respond fine - there are no timeouts to any of the other devices with between 50 and 142 messages sent to them.

Node 6 that you reported issues with above looks fine to me - no errors, no timeouts, from a quick 5-10 minutes review of your log, I don’t see any problems. The following shows polling working, and also unsolicited reports -:

image
image.png1136×496 133 KB

I’m not really sure what else you want me to look for?

17

I will replace Node 4 and see if the problem is resolved. Node 4 and 6 are close neighbors.
Thank you for your time! :christmas_tree:

18

I just reconnected my fibaro dimmer2 and get the same problem when I try to dim.
“NODE 5: Polling deferred until initialization complete”
and the light doesn’t respond to commands i OH or is very delayed.
Is there something I can do to start fault searching my network?

26-Jan-2019 16:44:28.734 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:dd005807:node5:switch_dimmer --> 100
26-Jan-2019 16:44:28.735 [TRACE] [.internal.converter.ZWaveMultiLevelSwitchConverter] - NODE 5: Converted command '100' to value 99 for channel = zwave:device:dd005807:node5:switch_dimmer, endpoint = 0.
26-Jan-2019 16:44:28.735 [DEBUG] [col.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 5: Creating new message for command SWITCH_MULTILEVEL_SET
26-Jan-2019 16:44:28.735 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 5: Encapsulating message, endpoint 0
26-Jan-2019 16:44:28.735 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
26-Jan-2019 16:44:28.735 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 5: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
26-Jan-2019 16:44:28.735 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
26-Jan-2019 16:44:28.735 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Added to queue - size 1
26-Jan-2019 16:44:28.736 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
26-Jan-2019 16:44:28.736 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 5: listening == true, frequentlyListening == false, awake == false
26-Jan-2019 16:44:28.736 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
26-Jan-2019 16:44:28.736 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
26-Jan-2019 16:44:28.736 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 5: Creating empty message of class = SendData (0x13), type = Request
26-Jan-2019 16:44:28.736 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = -59
26-Jan-2019 16:44:28.736 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 26 01 63 25 44 C5 
26-Jan-2019 16:44:28.737 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 26 01 63 25 44 C5 
26-Jan-2019 16:44:28.922 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
26-Jan-2019 16:44:28.922 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 337: Transaction Start type SendData 
26-Jan-2019 16:44:28.923 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 337: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 68
26-Jan-2019 16:44:28.923 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
26-Jan-2019 16:44:28.924 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
26-Jan-2019 16:44:28.924 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
26-Jan-2019 16:44:28.925 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Jan 26 16:44:30 CET 2019 - 2000ms
26-Jan-2019 16:44:28.926 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 337: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 68
26-Jan-2019 16:44:28.926 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
26-Jan-2019 16:44:28.927 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Jan 26 16:44:30 CET 2019 - 1999ms
26-Jan-2019 16:44:28.927 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling intialised at 1800 seconds - start in 1500 milliseconds.
26-Jan-2019 16:44:30.427 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling...
26-Jan-2019 16:44:30.428 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling deferred until initialisation complete
26-Jan-2019 16:44:30.926 [TRACE] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Transaction Timeout.......... 1 outstanding transactions
26-Jan-2019 16:44:30.926 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 5: TID 337: Timeout at state WAIT_RESPONSE. 3 retries remaining.
26-Jan-2019 16:44:30.926 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Aborting Transaction!
26-Jan-2019 16:44:30.926 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 337: Transaction ABORTED
26-Jan-2019 16:44:30.926 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = SendDataAbort (0x16), type = Request
26-Jan-2019 16:44:30.926 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = -22
26-Jan-2019 16:44:30.927 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
26-Jan-2019 16:44:30.927 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
26-Jan-2019 16:44:30.931 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
26-Jan-2019 16:44:30.931 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
26-Jan-2019 16:44:30.932 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
26-Jan-2019 16:44:30.932 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
26-Jan-2019 16:44:30.933 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Jan 26 16:44:42 CET 2019 - 11993ms
26-Jan-2019 16:44:42.927 [TRACE] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Transaction Timeout.......... 1 outstanding transactions
26-Jan-2019 16:44:42.927 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 5: TID 337: Timeout at state ABORTED. 3 retries remaining.
26-Jan-2019 16:44:42.927 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 337: Transaction is current transaction, so clearing!!!!!
26-Jan-2019 16:44:42.927 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 337: Transaction CANCELLED
26-Jan-2019 16:44:42.927 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
26-Jan-2019 16:44:42.927 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
26-Jan-2019 16:44:42.927 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:337 CANCELLED
26-Jan-2019 16:44:42.928 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
26-Jan-2019 16:44:42.928 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
26-Jan-2019 16:44:42.928 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
26-Jan-2019 16:44:42.928 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
19

I have to add some new information and mabye refer back to me being a OH-noob. :man_farmer:
I have been running a snapshot of the z-wave binding (2.4.0.201809081506). Because I haven’t been able to get OH to update the binding i paperUI to 2.4.0. But i did some poking and got i updated to the official version.
Now when I look at the log I see:

28-Jan-2019 12:30:08.405 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling intialised at 1800 seconds - start in 324000 milliseconds.
28-Jan-2019 12:30:08.405 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Device initialisation complete.

Lets hope it works.

20

Just to report back. I replaced Node4 with a new one and everything has been working great since.
Thanks Chris (and all others) and keep up the good work :slight_smile:

1 Like