Z-wave Single Switch Reading LOG

oeo · February 14, 2019, 8:59pm

Hi,
I have a strange issue with my fibaro single switch. There is sometimes a large latency in receiving commands.
I acivated the Debug-Log, but I’m not sure if there is something unnormal.

2019-02-13 20:54:07.020 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Polling...
2019-02-13 20:54:07.024 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Polling zwave:device:5668fa7e:node36:meter_watts
2019-02-13 20:54:07.027 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 36: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-02-13 20:54:07.029 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 36: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-02-13 20:54:07.032 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 36: Creating new message for application command METER_GET
2019-02-13 20:54:07.035 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: SECURITY NOT required on COMMAND_CLASS_METER
2019-02-13 20:54:07.037 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: Command Class COMMAND_CLASS_METER is NOT required to be secured
2019-02-13 20:54:07.040 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Polling zwave:device:5668fa7e:node36:meter_kwh
2019-02-13 20:54:07.042 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 36: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-02-13 20:54:07.044 [DEBUG] [ternal.converter.ZWaveMeterConverter] - NODE 36: Generating poll message for COMMAND_CLASS_METER, endpoint 0
2019-02-13 20:54:07.047 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 36: Creating new message for application command METER_GET
2019-02-13 20:54:07.049 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: SECURITY NOT required on COMMAND_CLASS_METER
2019-02-13 20:54:07.052 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: Command Class COMMAND_CLASS_METER is NOT required to be secured
2019-02-13 20:54:07.054 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Polling zwave:device:5668fa7e:node36:switch_binary1
2019-02-13 20:54:07.056 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 36: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 1
2019-02-13 20:54:07.059 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 36: Creating new message for application command SWITCH_BINARY_GET
2019-02-13 20:54:07.061 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: Encapsulating message, instance / endpoint 1
2019-02-13 20:54:07.063 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 36: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2019-02-13 20:54:07.066 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2019-02-13 20:54:07.068 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2019-02-13 20:54:07.070 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Polling skipped for zwave:device:5668fa7e:node36:switch_binary1 on COMMAND_CLASS_BASIC
2019-02-13 20:54:07.073 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Adding to device queue
2019-02-13 20:54:07.075 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Added 450 to queue - size 36
2019-02-13 20:54:07.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-13 20:54:07.082 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 24 03 32 01 10 25 45 82 
2019-02-13 20:54:07.085 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 36: Sending REQUEST Message = 01 0A 00 13 24 03 32 01 10 25 45 82 
2019-02-13 20:54:07.090 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-02-13 20:54:07.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-02-13 20:54:07.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-02-13 20:54:07.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-13 20:54:07.099 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-02-13 20:54:07.100 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-02-13 20:54:07.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-13 20:54:07.111 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-02-13 20:54:07.113 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 450: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 69
2019-02-13 20:54:07.115 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-13 20:54:07.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Adding to device queue
2019-02-13 20:54:07.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Added 451 to queue - size 36
2019-02-13 20:54:07.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-13 20:54:07.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Adding to device queue
2019-02-13 20:54:07.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Added 452 to queue - size 37
2019-02-13 20:54:07.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-13 20:54:07.142 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-13 20:54:07.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-13 20:54:07.144 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 45 00 00 02 AC 
2019-02-13 20:54:07.145 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 450: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 69
2019-02-13 20:54:07.147 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-02-13 20:54:07.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 450: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 69
2019-02-13 20:54:07.151 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-13 20:54:07.153 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 36: sentData successfully placed on stack.
2019-02-13 20:54:07.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 450: Advanced to WAIT_REQUEST
2019-02-13 20:54:07.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: TID 450: Transaction not completed
2019-02-13 20:54:07.158 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-13 20:54:07.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-13 20:54:07.172 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=69, payload=45 00 00 02 
2019-02-13 20:54:07.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=69, payload=45 00 00 02 
2019-02-13 20:54:07.174 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 24 08 32 02 21 32 00 00 00 00 FA 
2019-02-13 20:54:07.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 450: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 69
2019-02-13 20:54:07.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-02-13 20:54:07.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 450: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 69
2019-02-13 20:54:07.182 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 450: (Callback 69)
2019-02-13 20:54:07.183 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-02-13 20:54:07.185 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 450: callback 69
2019-02-13 20:54:07.187 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=69, payload=45 00 00 02 
2019-02-13 20:54:07.189 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 36: SendData Request. CallBack ID = 69, Status = Transmission complete and ACK received(0)
2019-02-13 20:54:07.190 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: resetResendCount initComplete=true isDead=false
2019-02-13 20:54:07.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 450: Advanced to WAIT_DATA
2019-02-13 20:54:07.194 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: TID 450: Transaction not completed
2019-02-13 20:54:07.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-13 20:54:07.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-13 20:54:07.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=36, callback=0, payload=00 24 08 32 02 21 32 00 00 00 00 
2019-02-13 20:54:07.204 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=36, callback=0, payload=00 24 08 32 02 21 32 00 00 00 00 
2019-02-13 20:54:07.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-13 20:54:07.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Application Command Request (ALIVE:DONE)
2019-02-13 20:54:07.210 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: resetResendCount initComplete=true isDead=false
2019-02-13 20:54:07.212 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: Incoming command class COMMAND_CLASS_METER, endpoint 0
2019-02-13 20:54:07.214 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: SECURITY NOT required on COMMAND_CLASS_METER
2019-02-13 20:54:07.216 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 36: Received COMMAND_CLASS_METER V3 METER_REPORT
2019-02-13 20:54:07.218 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 36: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2019-02-13 20:54:07.219 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got an event from Z-Wave network: ZWaveMeterValueEvent
2019-02-13 20:54:07.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0E+1
2019-02-13 20:54:07.223 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Updating channel state zwave:device:5668fa7e:node36:meter_watts to 0 [DecimalType]
2019-02-13 20:54:07.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Commands processed 1.
2019-02-13 20:54:07.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1129881.
2019-02-13 20:54:07.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1129881.
2019-02-13 20:54:07.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: notifyTransactionResponse TID:450 DONE
2019-02-13 20:54:07.235 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-02-13 20:54:07.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-02-13 20:54:07.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-13 20:54:07.241 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-13 20:54:07.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-13 20:54:07.245 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 24 03 32 01 00 25 46 91 
2019-02-13 20:54:07.247 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 36: Sending REQUEST Message = 01 0A 00 13 24 03 32 01 00 25 46 91 
2019-02-13 20:54:07.251 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-02-13 20:54:07.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-02-13 20:54:07.256 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-02-13 20:54:07.271 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-02-13 20:54:07.273 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 451: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 70
2019-02-13 20:54:07.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-02-13 20:54:07.277 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 451: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 70
2019-02-13 20:54:07.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-02-13 20:54:07.281 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-13 20:54:07.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-13 20:54:07.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-13 20:54:07.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-13 20:54:07.304 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 46 00 00 02 AF 
2019-02-13 20:54:07.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 451: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 70
2019-02-13 20:54:07.307 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-02-13 20:54:07.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 451: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 70
2019-02-13 20:54:07.311 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-13 20:54:07.313 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 36: sentData successfully placed on stack.
2019-02-13 20:54:07.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 451: Advanced to WAIT_REQUEST
2019-02-13 20:54:07.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: TID 451: Transaction not completed
2019-02-13 20:54:07.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-13 20:54:07.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-13 20:54:07.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 02 
2019-02-13 20:54:07.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 02 
2019-02-13 20:54:07.335 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 24 0A 32 02 21 44 00 00 02 DA 00 00 48 
2019-02-13 20:54:07.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 451: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 70
2019-02-13 20:54:07.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-02-13 20:54:07.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 451: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 70
2019-02-13 20:54:07.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 451: (Callback 70)
2019-02-13 20:54:07.343 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-02-13 20:54:07.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 451: callback 70
2019-02-13 20:54:07.347 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=70, payload=46 00 00 02 
2019-02-13 20:54:07.348 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 36: SendData Request. CallBack ID = 70, Status = Transmission complete and ACK received(0)
2019-02-13 20:54:07.350 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: resetResendCount initComplete=true isDead=false
2019-02-13 20:54:07.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 451: Advanced to WAIT_DATA
2019-02-13 20:54:07.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: TID 451: Transaction not completed
2019-02-13 20:54:07.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-13 20:54:07.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-13 20:54:07.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=36, callback=0, payload=00 24 0A 32 02 21 44 00 00 02 DA 00 00 
2019-02-13 20:54:07.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=36, callback=0, payload=00 24 0A 32 02 21 44 00 00 02 DA 00 00 
2019-02-13 20:54:07.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-13 20:54:07.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Application Command Request (ALIVE:DONE)
2019-02-13 20:54:07.370 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: resetResendCount initComplete=true isDead=false
2019-02-13 20:54:07.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: Incoming command class COMMAND_CLASS_METER, endpoint 0
2019-02-13 20:54:07.377 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: SECURITY NOT required on COMMAND_CLASS_METER
2019-02-13 20:54:07.378 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 36: Received COMMAND_CLASS_METER V3 METER_REPORT
2019-02-13 20:54:07.380 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 36: Meter: Type=Electric(1), Scale=kWh(0), Value=7.3
2019-02-13 20:54:07.382 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got an event from Z-Wave network: ZWaveMeterValueEvent
2019-02-13 20:54:07.384 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 7.3
2019-02-13 20:54:07.386 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Updating channel state zwave:device:5668fa7e:node36:meter_kwh to 7.3 [DecimalType]
2019-02-13 20:54:07.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Commands processed 1.
2019-02-13 20:54:07.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@113a2aa.
2019-02-13 20:54:07.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@113a2aa.
2019-02-13 20:54:07.395 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: notifyTransactionResponse TID:451 DONE
2019-02-13 20:54:07.397 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-02-13 20:54:07.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-02-13 20:54:07.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-13 20:54:07.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-13 20:54:07.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-13 20:54:07.408 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 24 06 60 0D 01 01 25 02 25 47 EB 
2019-02-13 20:54:07.410 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 36: Sending REQUEST Message = 01 0D 00 13 24 06 60 0D 01 01 25 02 25 47 EB 
2019-02-13 20:54:07.415 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 10 0A 60 0D 01 01 31 05 04 22 00 00 8E 
2019-02-13 20:54:07.441 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-02-13 20:54:07.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 452: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 71

chris · February 15, 2019, 3:17pm

This log shows 2 transactions - they both respond very quickly (both under 100ms!). It’s certainly not showing any problem.

oeo · February 15, 2019, 5:23pm

All right I will upload a longer Log, just because its possible, that I just uploaded the wrong time sequence. There is so much going on in the zwave network, that I thought its a good thing cut it.

oeo · February 15, 2019, 8:47pm

My loger Logfile: Zwave-LogFile
I think I just found something.
I had again a massive latency with my bath light at 20:55. Node 40 has some possible strange entries with …:255(12) = #NUM!.
There is another thing at 20:44. Node 28 has obviously some real problems.

oeo · February 23, 2019, 8:18am

Again a long ZwaveLog with problems with high latency.
LOG
@chris: Could you have a look, especially at 7:49 or at 9:02 ?

oeo · February 24, 2019, 5:22pm

@chris: could you please have a look or is there just nothing strange in the log?

chris · February 24, 2019, 6:03pm

Sorry - I’ve been travelling all week and was out all day yesterday and this morning. I will try and take a look tonight.

oeo · February 25, 2019, 4:49pm

There seems to be an issue with the Spirit Thermostats: (Latencies over 7 seconds?? Node 28,29,74 are Thermostats)

|commandClass:COMMAND_CLASS_ALARM|Informs the controller about critical system events/errors|
|---|---|
|commandClass:COMMAND_CLASS_ASSOCIATION|Allows to associate with other Z-Wave devices.|
|commandClass:COMMAND_CLASS_ASSOCIATION_GRP_INFO|Allows to group associations|
|commandClass:COMMAND_CLASS_BASIC|Provides access to basic functionality|
|commandClass:COMMAND_CLASS_BATTERY|Returns the current battery level of the device.|
|commandClass:COMMAND_CLASS_CONFIGURATION|Allows to configure the device settings|
|commandClass:COMMAND_CLASS_DEVICE_RESET_LOCALLY|Informs the Z-Wave Controller that the device was factory reset|
|commandClass:COMMAND_CLASS_FIRMWARE_UPDATE_MD|Allows Over the Air Update of the device.|
|commandClass:COMMAND_CLASS_MANUFACTURER_SPECIFIC|Provides information about Manufacturer and Product|
|commandClass:COMMAND_CLASS_POWERLEVEL|Used to alter the rf-power(required by Z-Wave).|
|commandClass:COMMAND_CLASS_PROTECTION|Allows to lock the device (child protection).|
|commandClass:COMMAND_CLASS_SECURITY|Allows encrypted Z-Wave Communication|
|commandClass:COMMAND_CLASS_SENSOR_MULTILEVEL|Provides the measured room temperature|
|commandClass:COMMAND_CLASS_SWITCH_MULTILEVEL|Provides or sets the valve opening degree of the valve Controlling the valve opening degree requires manufacturer specific mode|
|commandClass:COMMAND_CLASS_THERMOSTAT_MODE|Configures the operation mode|
|commandClass:COMMAND_CLASS_THERMOSTAT_SETPOINT|Allows to configure the desired room temperature|
|commandClass:COMMAND_CLASS_VERSION|Returns information about the Firmware.|
|commandClass:COMMAND_CLASS_ZWAVEPLUS_INFO|Identifies the device as a Z-Wave Plus Device|
|dbReference|710|
|defaultAssociations|1|
|manufacturerId|0148|
|manufacturerRef|0003:0001,0003:0003|
|modelId|Spirit|
|vendor|Eurotronics|
|zwave_beaming|true|
|zwave_class_basic|BASIC_TYPE_ROUTING_SLAVE|
|zwave_class_generic|GENERIC_TYPE_THERMOSTAT|
|zwave_class_specific|SPECIFIC_TYPE_THERMOSTAT_GENERAL_V2|
|zwave_deviceid|1|
|zwave_devicetype|3|
|zwave_frequent|true|
|zwave_lastheal|2019-02-25T01:38:47Z|
|zwave_listening|false|
|zwave_manufacturer|328|
|zwave_neighbours|1,16,20,21,26,30,35,36,40,43,54,75|
|zwave_nodeid|28|
|zwave_plus_devicetype|NODE_TYPE_ZWAVEPLUS_NODE|
|zwave_plus_roletype|ROLE_TYPE_SLAVE_SLEEPING_LISTENING|
|zwave_routing|true|
|zwave_secure|false|
|zwave_version|0.15|

chris · February 25, 2019, 5:15pm

I don’t see that from the log - this shows an issue with communicating to the controller (see the big red error ). You can see that the latency is about 1.2 seconds which is about right for this type of device as it is a FLIRS device.

oeo · February 25, 2019, 5:30pm

All right so no problems with the thermostat, but what could cause the issue with the controller? The big red error appears quite regulary in the log and actually only with the thermostats.