Z-wave commands seem buffered

Setup, Configuration and Use Runtime
, ,
1

I am using:

  • openhab2
  • Z-wave mostly
  • Aeon Labs Aeotec Gen 5 usb stick for the z-wave connection
  • on Windows 10

I have connected about 8 switches, written some rules and everything is working sort of fine. The problem I am having is that it seems like openhab is queuing or buffering the commands I want to send to my devices. Let me give you some examples of what is happening:

Example 1:

  • In which ever gui (I use paper-ui, habmin, the android app), when I change a switch from off to on it takes between 0 and 5 seconds before that switch turns on. Sometimes it is almost instant, sometimes it takes 5 seconds.

Example 2:
I have a rule connected to 3 switches. If I activate the rule it it will turn on one of the switches. If I activate it again it will turn on a second switch. Activate it a third time and it turns on the 3rd switch. On the 4th activation it turns all switches off. I have bound this rule to a button in the gui.

I can activate the rule and it takes between 0 and 5 seconds to turn the switch on. If I press the button 1 time, wait a second and press it again I still have to wait for 0-4 seconds but after that the 2 actions will happen simultaneously.

The same happens when I activate the rule, wait 2-3 seconds and activate it again 1 or 2 times. In the end all the actions I seem to have queued up will happen at the same time.

To me it seems like what ever I do, openhab (or something else) will queue / buffer all the commands I send for 5 seconds. After that it empties the queue / flushes the buffer and all the actions will happen simultaneously.

2

One thought… You might be experiencing timeouts in your z-wave network. The timeout value in the z-wave binding is 5 seconds, which happens to align with the 5 second delay you’re seeing.

Have you looked in the openhab.log file for evidence of timeouts?

3

I am currently experiencing even longer delays. What I noticed is that the Aeon Labs Aeotec stick’s light gets stalled, i.e., the “disco-light” stops blinking and shows only one color. During that time ti receives information like wattage from the smart meter, but any command I send like turn light on are not executed immediately. After some time the lamp starts blinking again and the commands are sent.

Perhaps you face a similar thing? Did you look at the light of the stick blinking?

4

Looking at my log I see a lot of timeouts. All from my aeotec multisensor 6. I have it on usb power and it is configured to send an update every 30 seconds. It is doing that bit fine, but at the same time it is logging a lot of these errors:

2017-05-19 15:37:36.187 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2017-05-19 15:37:36.187 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 11: Node is DEAD. Dropping message.

I enabled debugging but it’s not helping me understand this problem. Neither did googling the problem. Most suggestions are about it being battery powered or downgrading certain linux libraries. I’m running Windows and it’s usb powered.

2017-05-19 15:46:16.306 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2017-05-19 15:46:16.306 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message.
2017-05-19 15:46:16.306 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 324. Queue={}
2017-05-19 15:46:16.306 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 323
2017-05-19 15:46:16.306 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 13 0B 05 71 04 00 07 00 25 85 3C 
2017-05-19 15:46:16.306 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 0C 00 13 0B 05 71 04 00 07 00 25 85 3C 
2017-05-19 15:46:16.314 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-05-19 15:46:16.315 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-05-19 15:46:16.315 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-05-19 15:46:16.316 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-05-19 15:46:16.316 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-05-19 15:46:16.316 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
2017-05-19 15:46:16.366 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2017-05-19 15:46:16.367 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Sending ABORT Message = 01 03 00 16 EA 
2017-05-19 15:46:16.367 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2017-05-19 15:46:16.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 03 00 16 EA 
2017-05-19 15:46:16.367 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2017-05-19 15:46:16.367 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 11: Node is DEAD. Dropping message.
2017-05-19 15:46:16.367 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 112004
2017-05-19 15:46:16.367 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 47 06 01 BA 
2017-05-19 15:46:16.367 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 05 00 47 06 01 BA 
2017-05-19 15:46:16.459 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 85 00 00 0F 61 
2017-05-19 15:46:16.459 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-05-19 15:46:16.459 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 85 00 00 0F 00 00 6F 
2017-05-19 15:46:16.459 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 85 00 00 0F 00 00 6F 
2017-05-19 15:46:16.459 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=85 00 00 0F 
2017-05-19 15:46:16.459 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 133, Status = Transmission complete and ACK received(0)
2017-05-19 15:46:16.460 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Starting initialisation from DONE
2017-05-19 15:46:16.460 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@756dd8ac already registered
2017-05-19 15:46:16.460 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=11, callback=133, payload=0B 05 71 04 00 07 00 
2017-05-19 15:46:16.460 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=85 00 00 0F 
2017-05-19 15:46:16.460 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=133, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-05-19 15:46:19.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling...
2017-05-19 15:46:19.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling zwave:device:326f5f4b:node11:sensor_binary
2017-05-19 15:46:19.313 [DEBUG] [converter.ZWaveBinarySensorConverter] - NODE 11: Generating poll message for SENSOR_BINARY, endpoint 0
2017-05-19 15:46:19.313 [DEBUG] [dclass.ZWaveBinarySensorCommandClass] - NODE 11: Creating new message for application command SENSOR_BINARY_GET
2017-05-19 15:46:19.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling zwave:device:326f5f4b:node11:sensor_relhumidity
2017-05-19 15:46:19.313 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 11: Generating poll message for SENSOR_MULTILEVEL, endpoint 0
2017-05-19 15:46:19.313 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Creating new message for command SENSOR_MULTI_LEVEL_GET
2017-05-19 15:46:19.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling zwave:device:326f5f4b:node11:sensor_temperature
2017-05-19 15:46:19.313 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 11: Generating poll message for SENSOR_MULTILEVEL, endpoint 0
2017-05-19 15:46:19.313 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Creating new message for command SENSOR_MULTI_LEVEL_GET
2017-05-19 15:46:19.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling zwave:device:326f5f4b:node11:sensor_luminance
2017-05-19 15:46:19.313 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 11: Generating poll message for SENSOR_MULTILEVEL, endpoint 0
2017-05-19 15:46:19.313 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Creating new message for command SENSOR_MULTI_LEVEL_GET
2017-05-19 15:46:19.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling zwave:device:326f5f4b:node11:sensor_ultraviolet
2017-05-19 15:46:19.314 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 11: Generating poll message for SENSOR_MULTILEVEL, endpoint 0
2017-05-19 15:46:19.314 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 11: Creating new message for command SENSOR_MULTI_LEVEL_GET
2017-05-19 15:46:19.314 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling zwave:device:326f5f4b:node11:alarm_burglar
2017-05-19 15:46:19.314 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 11: Generating poll message for ALARM, endpoint 0, alarm BURGLAR, event null
2017-05-19 15:46:19.314 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 11: Creating new message for application command NOTIFICATION_GET V3
2017-05-19 15:46:19.314 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling zwave:device:326f5f4b:node11:battery-level
2017-05-19 15:46:19.314 [DEBUG] [rnal.converter.ZWaveBatteryConverter] - NODE 11: Generating poll message for BATTERY endpoint 0
2017-05-19 15:46:19.314 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 11: Creating new message for application command BATTERY_GET
2017-05-19 15:46:19.314 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 324. Queue={}
2017-05-19 15:46:19.314 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 325. Queue={}
2017-05-19 15:46:19.314 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 326. Queue={}
2017-05-19 15:46:19.314 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 327. Queue={}
2017-05-19 15:46:19.314 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 328. Queue={}
2017-05-19 15:46:19.314 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 329. Queue={}
2017-05-19 15:46:19.314 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 330. Queue={}
2017-05-19 15:46:21.307 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 1 attempts left!
2017-05-19 15:46:21.307 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message.
2017-05-19 15:46:21.307 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 331. Queue={}
2017-05-19 15:46:21.307 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 330
2017-05-19 15:46:21.307 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 13 0B 05 71 04 00 07 00 25 8D 34 
2017-05-19 15:46:21.308 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 0C 00 13 0B 05 71 04 00 07 00 25 8D 34 
2017-05-19 15:46:21.316 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-05-19 15:46:21.317 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-05-19 15:46:21.317 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-05-19 15:46:21.317 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-05-19 15:46:21.317 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-05-19 15:46:21.317 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
2017-05-19 15:46:21.369 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-05-19 15:46:21.369 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 112005. Queue={}
2017-05-19 15:46:21.369 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 112004
2017-05-19 15:46:21.369 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 47 06 01 BA 
2017-05-19 15:46:21.369 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 05 00 47 06 01 BA 
2017-05-19 15:46:21.461 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 8D 00 00 0F 69 
2017-05-19 15:46:21.461 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-05-19 15:46:21.462 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 8D 00 00 0F 00 00 67 
2017-05-19 15:46:21.462 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 8D 00 00 0F 00 00 67 
2017-05-19 15:46:21.462 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=8D 00 00 0F 
2017-05-19 15:46:21.462 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 141, Status = Transmission complete and ACK received(0)
2017-05-19 15:46:21.462 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Starting initialisation from DONE
2017-05-19 15:46:21.462 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@756dd8ac already registered
2017-05-19 15:46:21.462 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=11, callback=141, payload=0B 05 71 04 00 07 00 
2017-05-19 15:46:21.462 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=8D 00 00 0F 
2017-05-19 15:46:21.462 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=141, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-05-19 15:46:26.311 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 0 attempts left!
2017-05-19 15:46:26.311 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message.
2017-05-19 15:46:26.311 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 331. Queue={}
2017-05-19 15:46:26.311 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 330
2017-05-19 15:46:26.311 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 13 0B 05 71 04 00 07 00 25 8E 37 
2017-05-19 15:46:26.311 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 0C 00 13 0B 05 71 04 00 07 00 25 8E 37 
2017-05-19 15:46:26.319 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-05-19 15:46:26.320 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-05-19 15:46:26.320 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-05-19 15:46:26.320 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-05-19 15:46:26.320 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-05-19 15:46:26.321 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
2017-05-19 15:46:26.371 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2017-05-19 15:46:26.371 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 112005. Queue={}
2017-05-19 15:46:26.371 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 112004
2017-05-19 15:46:26.371 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 47 06 01 BA 
2017-05-19 15:46:26.371 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 05 00 47 06 01 BA 
2017-05-19 15:46:26.464 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 8E 00 00 0F 6A 
2017-05-19 15:46:26.465 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-05-19 15:46:26.465 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 8E 00 00 0F 00 00 64 
2017-05-19 15:46:26.465 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 8E 00 00 0F 00 00 64 
2017-05-19 15:46:26.465 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=8E 00 00 0F

Edit:
I removed the device for now and that has resolved my problem, I don’t have any delay any more between sending a command and it actually happening.

5

Good to know that it’s the timeouts that were causing the problem. I have a couple of the Multisensor 6 devices, but mine are battery-powered, so I can’t be of much help with the issue you’re seeing.