Sometimes I have some delay in my zwave devices reacting to rules or UI interactions. Analyzing the logs I saw quite a number of entries inidcating timeouts for node 255 (in total moren than 200 today). My maximum node number in the Z-Wave Network is 122, so what is node 255? The controller? What can I do?
Node 255 is the controller - normally if there are timeouts it’s a bad sign of low level problems (eg serial port issues, VM issues, that sort of thing), but hard to say without seeing what’s happening.
I have a Aeon Z Stick Gen5, Windows 7, no VM, OH 2.0 Release version. Should I prepare a debug log?
Sure - if you provide one I’ll take a look.
Hi Chris,
here is a debug log with the details of a node 255 timeout starting at 21:11:26.829
2017-03-17 21:11:21.827 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 1F 84
2017-03-17 21:11:21.827 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 1F 84
2017-03-17 21:11:21.839 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B
2017-03-17 21:11:21.840 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:21.840 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 60 01 9B
2017-03-17 21:11:21.840 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 60 01 9B
2017-03-17 21:11:21.840 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=RequestNodeInfo[0x60], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-17 21:11:21.840 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2017-03-17 21:11:21.840 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=RequestNodeInfo[0x60], type=Request[0x00], priority=High, dest=255, callback=0, payload=1F
2017-03-17 21:11:21.840 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=RequestNodeInfo[0x60], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-17 21:11:21.840 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=RequestNodeInfo, callback id=0, expected=ApplicationUpdate, cancelled=false MISMATCH
2017-03-17 21:11:26.829 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-03-17 21:11:26.829 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-03-17 21:11:26.829 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-03-17 21:11:26.829 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 1F 84
2017-03-17 21:11:26.829 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 1F 84
2017-03-17 21:11:30.708 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B
2017-03-17 21:11:30.709 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:30.709 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 60 01 9B
2017-03-17 21:11:30.709 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 60 01 9B
2017-03-17 21:11:30.709 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=RequestNodeInfo[0x60], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-17 21:11:30.709 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2017-03-17 21:11:30.709 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=RequestNodeInfo[0x60], type=Request[0x00], priority=High, dest=255, callback=0, payload=1F
2017-03-17 21:11:30.709 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=RequestNodeInfo[0x60], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-03-17 21:11:30.709 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=RequestNodeInfo, callback id=0, expected=ApplicationUpdate, cancelled=false MISMATCH
2017-03-17 21:11:30.714 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.715 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:30.715 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.715 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.715 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 69 03 20 03 FF
2017-03-17 21:11:30.715 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 105: Application Command Request (ALIVE:DONE)
2017-03-17 21:11:30.715 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 105: Starting initialisation from DONE
2017-03-17 21:11:30.715 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@516b00d0 already registered
2017-03-17 21:11:30.715 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 105: Incoming command class BASIC
2017-03-17 21:11:30.715 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 105: Received Basic Request
2017-03-17 21:11:30.715 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 105: Basic report, value = 0xFF
2017-03-17 21:11:30.715 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-03-17 21:11:30.715 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 105: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-03-17 21:11:30.715 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 105: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
2017-03-17 21:11:30.715 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent. lastSent=255, incoming=255
2017-03-17 21:11:30.786 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.787 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:30.787 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.787 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.787 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 69 03 20 03 FF
2017-03-17 21:11:30.787 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 105: Application Command Request (ALIVE:DONE)
2017-03-17 21:11:30.787 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 105: Starting initialisation from DONE
2017-03-17 21:11:30.787 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@516b00d0 already registered
2017-03-17 21:11:30.787 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 105: Incoming command class BASIC
2017-03-17 21:11:30.787 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 105: Received Basic Request
2017-03-17 21:11:30.787 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 105: Basic report, value = 0xFF
2017-03-17 21:11:30.787 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-03-17 21:11:30.787 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 105: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-03-17 21:11:30.787 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 105: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
2017-03-17 21:11:30.787 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent. lastSent=255, incoming=255
2017-03-17 21:11:30.921 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.922 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:30.922 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.922 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:30.922 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 69 03 20 03 FF
2017-03-17 21:11:30.922 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 105: Application Command Request (ALIVE:DONE)
2017-03-17 21:11:30.922 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 105: Starting initialisation from DONE
2017-03-17 21:11:30.922 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@516b00d0 already registered
2017-03-17 21:11:30.922 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 105: Incoming command class BASIC
2017-03-17 21:11:30.922 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 105: Received Basic Request
2017-03-17 21:11:30.922 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 105: Basic report, value = 0xFF
2017-03-17 21:11:30.922 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-03-17 21:11:30.922 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 105: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-03-17 21:11:30.922 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 105: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
2017-03-17 21:11:30.922 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent. lastSent=255, incoming=255
2017-03-17 21:11:31.094 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.095 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.095 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.095 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.095 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.095 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.208 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.209 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.209 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.209 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.209 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.209 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.219 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.220 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.220 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.220 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.220 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.220 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.252 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 55 55 55 5D
2017-03-17 21:11:31.253 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.253 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 55 55 55 5D
2017-03-17 21:11:31.253 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 55 55 55 5D
2017-03-17 21:11:31.253 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 55 55 55
2017-03-17 21:11:31.253 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.286 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.287 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.287 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.287 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.287 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.287 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.295 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.296 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.296 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.296 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.296 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.296 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.318 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.319 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.319 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.319 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.319 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.319 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.331 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.332 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.332 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.332 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.332 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.332 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.369 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:31.370 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.370 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:31.370 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 69 03 20 03 FF 54
2017-03-17 21:11:31.371 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 69 03 20 03 FF
2017-03-17 21:11:31.371 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 105: Application Command Request (ALIVE:DONE)
2017-03-17 21:11:31.371 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 105: Starting initialisation from DONE
2017-03-17 21:11:31.371 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@516b00d0 already registered
2017-03-17 21:11:31.371 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 105: Incoming command class BASIC
2017-03-17 21:11:31.371 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 105: Received Basic Request
2017-03-17 21:11:31.371 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 105: Basic report, value = 0xFF
2017-03-17 21:11:31.371 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-03-17 21:11:31.371 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 105: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-03-17 21:11:31.371 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 105: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
2017-03-17 21:11:31.371 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent. lastSent=255, incoming=255
2017-03-17 21:11:31.439 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.440 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.440 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.440 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.440 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.440 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.450 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.451 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.451 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.451 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.451 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.451 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.470 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.471 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.471 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.471 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.471 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.471 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.481 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.482 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.482 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.482 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.482 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.482 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.523 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.524 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:31.524 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.524 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:31.524 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:31.524 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:31.830 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2017-03-17 21:11:31.830 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-03-17 21:11:31.830 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-03-17 21:11:31.830 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 1F 84
2017-03-17 21:11:31.830 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 1F 84
2017-03-17 21:11:36.831 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2017-03-17 21:11:36.831 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-03-17 21:11:36.831 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-03-17 21:11:36.831 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 1F 84
2017-03-17 21:11:36.831 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 1F 84
2017-03-17 21:11:40.883 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 00 9A
2017-03-17 21:11:40.884 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:40.884 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 60 00 9A
2017-03-17 21:11:40.884 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 60 00 9A
2017-03-17 21:11:40.884 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=RequestNodeInfo[0x60], type=Response[0x01], priority=High, dest=255, callback=0, payload=00
2017-03-17 21:11:40.884 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2017-03-17 21:11:40.884 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=RequestNodeInfo[0x60], type=Request[0x00], priority=High, dest=255, callback=0, payload=1F
2017-03-17 21:11:40.884 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=RequestNodeInfo[0x60], type=Response[0x01], priority=High, dest=255, callback=0, payload=00
2017-03-17 21:11:40.884 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=RequestNodeInfo, callback id=0, expected=ApplicationUpdate, cancelled=false MISMATCH
2017-03-17 21:11:40.885 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2017-03-17 21:11:40.886 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:40.887 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:40.887 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:40.887 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 E9 03 20 03 FF D4
2017-03-17 21:11:40.887 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 E9 03 20 03 FF
2017-03-17 21:11:40.887 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 233: Not initialized yet, ignoring message.
2017-03-17 21:11:40.954 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 47 03 20 03 FF 7A
2017-03-17 21:11:40.955 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-03-17 21:11:40.955 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 10 47 03 20 03 FF 7A
2017-03-17 21:11:40.955 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 10 47 03 20 03 FF 7A
2017-03-17 21:11:40.955 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=10 47 03 20 03 FF
2017-03-17 21:11:40.955 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 71: Application Command Request (ALIVE:DONE)
2017-03-17 21:11:40.955 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 71: Starting initialisation from DONE
2017-03-17 21:11:40.955 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@248311d1 already registered
2017-03-17 21:11:40.955 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 71: Incoming command class BASIC
2017-03-17 21:11:40.955 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 71: Received Basic Request
2017-03-17 21:11:40.955 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 71: Basic report, value = 0xFF
I analysed the logs in Excel and filtered on node 255 timeouts. The result is a regulary timeout pattern which shows that every 30 minutes the timeouts are repeating within the same minutes:
During the complete time timeouts occur again and again at 17:11, 18:11, 19:11 ans as well at 17:41, 18:41, 19:41 and so on. It seems that there is some regulary mechanism causing this (polling?).
Thanks for your help!
There’s something pretty strange with your system. It’s returning nodes that aren’t even possible - eg node 233 -:
The timeout itself seems to be related to a NIF request on node 31 - it seems to be returning immediately which is pretty strange -:
I would be tempted to try a complete reset of the stick to see if that helps.
I hesitated beacause I have about 100 active nodes and the thought of having to exclude und reinclude them all one by one was not very attractive…
For this reason I followed your other hint first that it might be a COM Port issue. So I changed my current OH2 Server (HP 260 G2 with WINDOWS 7) with my previous one (HP 260 G1 with WINDOWS 7) and it seems that the new server has some kind of undefinable issues with the USB ports. After now nearly 24 hours with the old server (but the same stick and same installation of OH2) I have NO timeouts for node 255 at all…
This is really strange and I did not expect this to be a potential cause, I will observe further…