Hi
I woul like to know if there´’s a way to set a diffrent timeout for Zwave nodes in my case i beleive just that 6000 or 7000 ms is the best time before it ends. I’m having a bit ao delay in my routings.
No - this can’t be changed. I’d be really surprised if 6 seconds was required - it seems very long and it probably suggests that there’s a problem somewhere with the network…
Thanks for a quick reply, Today I had som time leftover and testet Homegenie and there it works good. But it seems to me that the big thing for Openhab is to updtae classic UI with powerconsumtion and sometimes even states. I was thinking wit Z wave that there would be an easy way to se if command is received by switch.
And unfortunatley I got a new version of fibaro wallplugg i think that doesn’t hav any support yet in database or atleast in my 1.83 binding.
So you are getting 6 second timeouts and this is working ok on the other software? I think I would look to find the problem if you really have such long delays getting responses since this really doesn’t feel right to me - maybe it is ok, but it’s going to make a very unresponsive system if every command takes this time as commands will start to back up (i.e. if you send two commands at the same time, the second one will take 12 seconds, and the third 18 seconds).
We could change the timeout in OH to increase this, but as above, I think your system will not be nice to operate with these sort of response times.
From that opinion I will agree with you but could tehre be som problem witm my Fiabor wallplugg fgwpf-102?
I get this in my error logg
2017-01-08 19:31:36.337 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-08 19:31:36.337 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2017-01-08 19:31:41.339 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-08 19:31:41.339 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2017-01-08 19:31:46.343 [ERROR] [WaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-08 19:31:46.343 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2017-01-08 19:31:51.345 [WARN ] [WaveController$ZWaveSendThread] - NODE 2: Too many retries. Discarding message: Message: class = SendData (0x13), type = Request (0x00), payload = 02 02 27 02
2017-01-08 19:46:06.835 [WARN ] [c.u.store.FileDataStoreFactory] - unable to change permissions for everybody: C:\Openhab\etc\gcal
2017-01-08 19:46:06.836 [WARN ] [c.u.store.FileDataStoreFactory] - unable to change permissions for owner: C:\Openhab\etc\gcal
2017-01-08 19:59:28.049 [ERROR] [WaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-08 19:59:28.049 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message.
2017-01-08 19:59:33.051 [ERROR] [WaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-08 19:59:33.051 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message.
2017-01-08 19:59:38.054 [ERROR] [WaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-08 19:59:38.054 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message.
2017-01-08 19:59:43.058 [WARN ] [WaveController$ZWaveSendThread] - NODE 4: Too many retries. Discarding message: Message: class = SendData (0xIt’s hard to say what is causing this without a debug log. This just shows timeouts - that’s not too uncommon, but to work out what might be the cause we’d need to see the full debug level log.
Hello Here comes some more logging thought of a new problem today, Switch item lider could sometimes be blue like its on even item is off and even lightbulb icon could light yellow as on even item is off.
17:48:35.735 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38 ] - NODE 4: Sent Data successfully placed on stack.
17:48:35.745 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 07 00 13 44 00 00 02 AD
17:48:35.746 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
17:48:35.746 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
17:48:35.747 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 09 00 13 44 00 00 02 00 00 A3
17:48:35.747 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 09 00 13 44 00 00 02 00 00 A3
17:48:35.748 [DEBUG] [b.z.i.protocol.ZWaveController:192 ] - Message: class = SendData (0x13), type = Request (0x00), payload = 44 00 00 02
17:48:35.748 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74 ] - NODE 4: SendData Request. CallBack ID = 68, Status = Transmission complete and ACK received(0)
17:48:35.749 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 04 02 27 02
17:48:35.749 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 44 00 00 02
17:48:35.750 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ] - Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
17:48:40.722 [ERROR] [WaveController$ZWaveSendThread:1309 ] - NODE 4: Timeout while sending message. Requeueing - 1 attempts left!
17:48:40.722 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ] - NODE 4: Got an error while sending data. Resending message.
17:48:40.722 [DEBUG] [b.z.i.protocol.ZWaveController:938 ] - Callback ID = 69
17:48:40.723 [DEBUG] [b.z.i.protocol.ZWaveController:620 ] - Enqueueing message. Queue length = 1
17:48:40.723 [DEBUG] [WaveController$ZWaveSendThread:1211 ] - Took message from queue for sending. Queue length = 0
17:48:40.723 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 09 00 13 04 02 27 02 25 45 A6
17:48:40.724 [DEBUG] [WaveController$ZWaveSendThread:1268 ] - NODE 4: Sending REQUEST Message = 01 09 00 13 04 02 27 02 25 45 A6
17:48:40.734 [DEBUG] [eController$ZWaveReceiveThread:1481 ] - Receive Message = 01 04 01 13 01 E8
17:48:40.735 [DEBUG] [eController$ZWaveReceiveThread:1405 ] - Receive queue ADD: Length=1
17:48:40.735 [DEBUG] [b.z.i.protocol.ZWaveController:1163 ] - Receive queue TAKE: Length=0
17:48:40.736 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ] - Assembled message buffer = 01 04 01 13 01 E8
17:48:40.736 [DEBUG] [b.z.i.protocol.ZWaveController:1164 ] - Process Message = 01 04 01 13 01 E8
17:48:40.736 [DEBUG] [b.z.i.protocol.ZWaveController:192 ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01
17:48:40.737 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38 ] - NODE 4: Sent Data successfully placed on stack.
Hi,
It looks like I have an issue that looks very much like this.
Recently I upgraded to the latest snapshot of openhab and I also resetted all my Z-wave devices (3).
I don’t know exactly what is causing this issue. I turned on the debug logging on the Z-wave binding but it doesn’t clear things out for me.
Here is my debug output (which appears every half hour in the log files):
2017-01-13 13:37:42.655 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
2017-01-13 13:37:42.655 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:cca69429:node2:switch_binary
2017-01-13 13:37:42.655 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 2: Generating poll message for SWITCH_BINARY, endpoint 0
2017-01-13 13:37:42.655 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_GET
2017-01-13 13:37:42.655 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:cca69429:node2:switch_dimmer
2017-01-13 13:37:42.655 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 2: Generating poll message for SWITCH_MULTILEVEL, endpoint 0
2017-01-13 13:37:42.655 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET
2017-01-13 13:37:42.655 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:cca69429:node2:switch_dimmer
2017-01-13 13:37:42.655 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 2: Generating poll message for SWITCH_MULTILEVEL, endpoint 0
2017-01-13 13:37:42.655 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET
2017-01-13 13:37:42.656 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-01-13 13:37:42.656 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-01-13 13:37:42.656 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-01-13 13:37:42.656 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-01-13 13:37:42.656 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 25 02 25 7B 9C
2017-01-13 13:37:42.656 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 25 02 25 7B 9C
2017-01-13 13:37:42.663 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-01-13 13:37:42.663 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:37:42.663 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-01-13 13:37:42.663 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-01-13 13:37:42.663 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-01-13 13:37:42.664 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2017-01-13 13:37:42.679 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7B 00 00 02 92
2017-01-13 13:37:42.680 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:37:42.680 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 7B 00 00 02 00 00 9C
2017-01-13 13:37:42.680 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 7B 00 00 02 00 00 9C
2017-01-13 13:37:42.680 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=7B 00 00 02
2017-01-13 13:37:42.680 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 123, Status = Transmission complete and ACK received(0)
2017-01-13 13:37:42.680 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-01-13 13:37:42.680 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@ba10f8d already registered
2017-01-13 13:37:42.680 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=123, payload=02 02 25 02
2017-01-13 13:37:42.680 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=7B 00 00 02
2017-01-13 13:37:42.680 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=123, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2017-01-13 13:37:42.690 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 25 03 00 D5
2017-01-13 13:37:42.691 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:37:42.691 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 02 03 25 03 00 D5
2017-01-13 13:37:42.691 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 02 03 25 03 00 D5
2017-01-13 13:37:42.691 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 03 25 03 00
2017-01-13 13:37:42.691 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)
2017-01-13 13:37:42.691 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-01-13 13:37:42.691 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@ba10f8d already registered
2017-01-13 13:37:42.691 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class SWITCH_BINARY
2017-01-13 13:37:42.692 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 2
2017-01-13 13:37:42.692 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Switch Binary report, value = 0
2017-01-13 13:37:42.692 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-01-13 13:37:42.692 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-01-13 13:37:42.692 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0
2017-01-13 13:37:42.692 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:cca69429:node2:switch_binary to OFF [OnOffType]
2017-01-13 13:37:42.692 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=123, payload=02 02 25 02
2017-01-13 13:37:42.693 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 03 25 03 00
2017-01-13 13:37:42.693 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=123, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2017-01-13 13:37:42.693 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-01-13 13:37:42.693 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-01-13 13:37:42.693 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Response processed after 37ms/946ms.
2017-01-13 13:37:42.693 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-01-13 13:37:42.693 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 26 02 25 7C 98
2017-01-13 13:37:42.693 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 7C 98
2017-01-13 13:37:42.701 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-01-13 13:37:42.702 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:37:42.702 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-01-13 13:37:42.702 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-01-13 13:37:42.702 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-01-13 13:37:42.702 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2017-01-13 13:37:42.717 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7C 00 00 03 94
2017-01-13 13:37:42.717 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:37:42.717 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 7C 00 00 03 00 00 9A
2017-01-13 13:37:42.717 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 7C 00 00 03 00 00 9A
2017-01-13 13:37:42.717 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=7C 00 00 03
2017-01-13 13:37:42.718 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 124, Status = Transmission complete and ACK received(0)
2017-01-13 13:37:42.718 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-01-13 13:37:42.718 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@ba10f8d already registered
2017-01-13 13:37:42.718 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=124, payload=02 02 26 02
2017-01-13 13:37:42.718 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=7C 00 00 03
2017-01-13 13:37:42.718 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=124, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2017-01-13 13:37:47.695 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2017-01-13 13:37:47.695 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2017-01-13 13:37:47.695 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-01-13 13:37:47.695 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-01-13 13:37:47.695 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 26 02 25 7E 9A
2017-01-13 13:37:47.695 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 7E 9A
2017-01-13 13:37:47.703 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-01-13 13:37:47.703 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:37:47.704 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-01-13 13:37:47.704 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-01-13 13:37:47.704 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-01-13 13:37:47.704 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2017-01-13 13:37:47.719 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7E 00 00 02 97
2017-01-13 13:37:47.720 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:37:47.720 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 7E 00 00 02 00 00 99
2017-01-13 13:37:47.720 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 7E 00 00 02 00 00 99
2017-01-13 13:37:47.720 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=7E 00 00 02
2017-01-13 13:37:47.720 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 126, Status = Transmission complete and ACK received(0)
2017-01-13 13:37:47.720 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
<removed a piece to fit in one post - looks similar to rest of log>
2017-01-13 13:38:07.727 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@ba10f8d already registered
2017-01-13 13:38:07.727 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=129, payload=02 02 26 02
2017-01-13 13:38:07.727 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=81 00 00 03
2017-01-13 13:38:07.727 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=129, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2017-01-13 13:38:12.705 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-13 13:38:12.705 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2017-01-13 13:38:12.705 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-01-13 13:38:12.705 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-01-13 13:38:12.705 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 26 02 25 82 66
2017-01-13 13:38:12.705 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 82 66
2017-01-13 13:38:12.713 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-01-13 13:38:12.714 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:38:12.714 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-01-13 13:38:12.714 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-01-13 13:38:12.714 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-01-13 13:38:12.714 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2017-01-13 13:38:12.729 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 82 00 00 02 6B
2017-01-13 13:38:12.730 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:38:12.730 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 82 00 00 02 00 00 65
2017-01-13 13:38:12.731 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 82 00 00 02 00 00 65
2017-01-13 13:38:12.731 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=82 00 00 02
2017-01-13 13:38:12.731 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 130, Status = Transmission complete and ACK received(0)
2017-01-13 13:38:12.731 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-01-13 13:38:12.731 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@ba10f8d already registered
2017-01-13 13:38:12.731 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=130, payload=02 02 26 02
2017-01-13 13:38:12.732 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=82 00 00 02
2017-01-13 13:38:12.732 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=130, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2017-01-13 13:38:17.707 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
2017-01-13 13:38:17.707 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2017-01-13 13:38:17.707 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-01-13 13:38:17.707 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-01-13 13:38:17.707 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 26 02 25 83 67
2017-01-13 13:38:17.707 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 83 67
2017-01-13 13:38:17.715 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-01-13 13:38:17.715 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:38:17.716 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-01-13 13:38:17.716 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-01-13 13:38:17.716 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-01-13 13:38:17.716 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2017-01-13 13:38:17.732 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 83 00 00 02 6A
2017-01-13 13:38:17.732 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-13 13:38:17.732 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 83 00 00 02 00 00 64
2017-01-13 13:38:17.733 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 83 00 00 02 00 00 64
2017-01-13 13:38:17.733 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=83 00 00 02
2017-01-13 13:38:17.733 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 131, Status = Transmission complete and ACK received(0)
2017-01-13 13:38:17.733 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-01-13 13:38:17.733 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@ba10f8d already registered
2017-01-13 13:38:17.733 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=131, payload=02 02 26 02
2017-01-13 13:38:17.733 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=83 00 00 02
2017-01-13 13:38:17.734 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=131, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2017-01-13 13:38:22.709 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=2, callback=131, payload=02 02 26 02
Thanks.
Greetings,
Frederic
@chris: do you have any suggestions or is there anything else I can do to get more details on this issue?
Thanks!
Sorry - I have very limited access to internet at the moment - I can currently only read email (sometimes!), but the email the forum sends doesn’t really provide much information (it’s one line). I’ll probably look at this more next week when I’m home.
No problem at all! Thanks!
Hi Chris,
Did you already found some time to check this issue?
Thanks!
Greetings,
Frederic
What is the device that’s causing these issues? Maybe it’s misconfigured…
Sorry for the late reply, I missed you reply.
In my case the device that is causing this behavior is a valve.
This is the device: http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/438
Here you have a screenshot of the device configuration:
NOTE: it was working without any problems in my first installation of OpenHAB. This issue came up when I reinstalled OpenHAB completely (I’ve also resetted the flood sensor). Now I’m using build 715 of OpenHAB.
Any info?
Sorry - I missed your messages (it’s best to reply to me or mention me - otherwise there’s no notification!).
I will take a look at the log tonight.
No problem! I know you’re busy with reworking the Z-wave binding so I can imagine you have more important stuff to do.
Except for the error messages my setup is working fine but it just makes a mess of the log files 
Thanks!
The problem is caused by a database error - someone has added a non-existant channel connected to the switch_multilevel command class which the device doesn’t seem to support (according to the docs). The device doesn’t respond to this, and there’s a timeout.
I’ll update the database and this issue should go away.
Thanks a lot for looking at it!
I’ll check and confirm if it is fixed.