Z-Wave binding_cmdrepollperiod cannot exceed 15 seconds

[shutterfreak (Olivier Biot)]

My Fakro ARZ roller shutters don’t ever report their position, unless polled.

I hoped I could set the command poll period to the time needed for my roller shutters to fully open / close (about 20 seconds). Unfortunately it appears that whenever I try to set binding_cmdrepollperiod to 20000 (20 seconds), it seems to successfully store this information in the Z-Wave log…

==> /var/log/openhab2/events.log <==
2019-04-16 16:44:10.644 [hingStatusInfoChangedEvent] - 'zwave:device:controller:node4' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

==> /var/log/openhab2/zwave.log <==
2019-04-16 16:44:10.648 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Event listener added.
2019-04-16 16:44:10.649 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising Thing Node...
2019-04-16 16:44:10.650 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising cmd channel zwave:device:controller:node4:switch_binary for OnOffType
2019-04-16 16:44:10.651 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising state channel zwave:device:controller:node4:switch_binary for OnOffType
2019-04-16 16:44:10.653 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising cmd channel zwave:device:controller:node4:blinds_control for StopMoveType
2019-04-16 16:44:10.654 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising cmd channel zwave:device:controller:node4:blinds_control for UpDownType
2019-04-16 16:44:10.656 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising cmd channel zwave:device:controller:node4:blinds_control for PercentType
2019-04-16 16:44:10.657 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising state channel zwave:device:controller:node4:blinds_control for PercentType
2019-04-16 16:44:10.659 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising state channel zwave:device:controller:node4:blinds_control for PercentType
2019-04-16 16:44:10.660 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling intialised at 86400 seconds - start in 77241600 milliseconds.
2019-04-16 16:44:10.661 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Device initialisation complete.

==> /var/log/openhab2/events.log <==
2019-04-16 16:44:10.666 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:controller:node4' has been updated.

==> /var/log/openhab2/zwave.log <==
2019-04-16 16:44:59.235 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Configuration update received

2019-04-16 16:44:59.244 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Configuration update set binding_cmdrepollperiod to 20000 (BigDecimal)

2019-04-16 16:44:59.245 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Configuration update set binding_pollperiod to 300 (BigDecimal)
2019-04-16 16:44:59.247 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling intialised at 300 seconds - start in 120900 milliseconds.

==> /var/log/openhab2/events.log <==
2019-04-16 16:44:59.266 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:controller:node4' has been updated.
2019-04-16 16:44:59.269 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]

However, when I then operate the roller shutters, I see that the Z-Wave binding won’t obey the 20 second polling interval and already polls the Z-Wave node after 15 seconds. Since the roller shutters take longer than 15 seconds to fully open or close, Z-Wave reports 254 as state, which translates to ‘undefined position’.

Here’s the command to operate the roller shutters:

==> /var/log/openhab2/events.log <==
2019-04-16 16:57:47.374 [ome.event.ItemCommandEvent] - Item 'AT_Shutter_SW' received command 100

==> /var/log/openhab2/zwave.log <==
2019-04-16 16:57:47.391 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:controller:node4:blinds_control --> 100 [PercentType]
2019-04-16 16:57:47.394 [DEBUG] [col.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Creating new message for command SWITCH_MULTILEVEL_SET
2019-04-16 16:57:47.396 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported
2019-04-16 16:57:47.398 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-04-16 16:57:47.400 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
2019-04-16 16:57:47.401 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Added 58 to queue - size 1
2019-04-16 16:57:47.403 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-16 16:57:47.407 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 04 03 26 01 00 25 32 D1 
2019-04-16 16:57:47.410 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 0A 00 13 04 03 26 01 00 25 32 D1 
2019-04-16 16:57:47.412 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-04-16 16:57:47.414 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 58: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 50
2019-04-16 16:57:47.414 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-04-16 16:57:47.416 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-04-16 16:57:47.417 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling intialised at 300 seconds - start in 15000 milliseconds.
2019-04-16 16:57:47.418 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-04-16 16:57:47.421 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 58: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 50
2019-04-16 16:57:47.421 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-04-16 16:57:47.422 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-04-16 16:57:47.423 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-16 16:57:47.423 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-16 16:57:47.425 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-16 16:57:47.427 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-16 16:57:47.427 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 58: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 50
2019-04-16 16:57:47.429 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-04-16 16:57:47.430 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 58: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 50
2019-04-16 16:57:47.431 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-16 16:57:47.432 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: sentData successfully placed on stack.
2019-04-16 16:57:47.434 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 58: Advanced to WAIT_REQUEST
2019-04-16 16:57:47.435 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: TID 58: Transaction not completed
2019-04-16 16:57:47.436 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-16 16:57:47.437 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-16 16:57:47.460 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 32 00 DB 
2019-04-16 16:57:47.463 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=50, payload=32 00 
2019-04-16 16:57:47.464 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=50, payload=32 00 
2019-04-16 16:57:47.465 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 58: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 50
2019-04-16 16:57:47.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-04-16 16:57:47.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 58: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 50
2019-04-16 16:57:47.467 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 58: (Callback 50)
2019-04-16 16:57:47.468 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-04-16 16:57:47.468 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 58: callback 50
2019-04-16 16:57:47.469 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=50, payload=32 00 
2019-04-16 16:57:47.470 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 50, Status = Transmission complete and ACK received(0)
2019-04-16 16:57:47.472 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: resetResendCount initComplete=true isDead=false
2019-04-16 16:57:47.472 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 58: Transaction COMPLETED
2019-04-16 16:57:47.473 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Response processed after 60ms
2019-04-16 16:57:47.474 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: TID 58: Transaction completed
2019-04-16 16:57:47.475 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:58 DONE
2019-04-16 16:57:47.477 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-04-16 16:57:47.478 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-16 16:57:47.479 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

And 15 seconds later, here’s the status polling:

2019-04-16 16:58:02.416 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling...
2019-04-16 16:58:02.419 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling zwave:device:controller:node4:blinds_control
2019-04-16 16:58:02.420 [DEBUG] [.internal.converter.ZWaveMultiLevelSwitchConverter] - NODE 4: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-04-16 16:58:02.422 [DEBUG] [col.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Creating new message for command SWITCH_MULTILEVEL_GET
2019-04-16 16:58:02.423 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported
2019-04-16 16:58:02.424 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-04-16 16:58:02.425 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling skipped for zwave:device:controller:node4:blinds_control on COMMAND_CLASS_BASIC
2019-04-16 16:58:02.427 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
2019-04-16 16:58:02.428 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Added 59 to queue - size 1
2019-04-16 16:58:02.429 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-04-16 16:58:02.432 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 04 02 26 02 25 33 D1 
2019-04-16 16:58:02.435 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 09 00 13 04 02 26 02 25 33 D1 
2019-04-16 16:58:02.437 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-04-16 16:58:02.439 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-04-16 16:58:02.438 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 59: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 51
2019-04-16 16:58:02.440 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-04-16 16:58:02.442 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-04-16 16:58:02.443 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 59: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 51
2019-04-16 16:58:02.444 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-04-16 16:58:02.446 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-16 16:58:02.446 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-04-16 16:58:02.447 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-16 16:58:02.450 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-16 16:58:02.452 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-16 16:58:02.453 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 59: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 51
2019-04-16 16:58:02.454 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-04-16 16:58:02.455 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 59: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 51
2019-04-16 16:58:02.457 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-04-16 16:58:02.458 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: sentData successfully placed on stack.
2019-04-16 16:58:02.459 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 59: Advanced to WAIT_REQUEST
2019-04-16 16:58:02.461 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: TID 59: Transaction not completed
2019-04-16 16:58:02.462 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-16 16:58:02.463 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-16 16:58:02.486 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 33 00 DA 
2019-04-16 16:58:02.489 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=51, payload=33 00 
2019-04-16 16:58:02.491 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=51, payload=33 00 
2019-04-16 16:58:02.493 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 59: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 51
2019-04-16 16:58:02.494 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-04-16 16:58:02.495 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 59: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 51
2019-04-16 16:58:02.496 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 59: (Callback 51)
2019-04-16 16:58:02.498 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-04-16 16:58:02.499 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 59: callback 51
2019-04-16 16:58:02.500 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=51, payload=33 00 
2019-04-16 16:58:02.502 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 51, Status = Transmission complete and ACK received(0)
2019-04-16 16:58:02.503 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: resetResendCount initComplete=true isDead=false
2019-04-16 16:58:02.504 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 59: Advanced to WAIT_DATA
2019-04-16 16:58:02.505 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: TID 59: Transaction not completed
2019-04-16 16:58:02.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-16 16:58:02.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-04-16 16:58:02.530 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 04 03 26 03 FE AD 00 81 
2019-04-16 16:58:02.538 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=4, callback=0, payload=00 04 03 26 03 FE AD 00 
2019-04-16 16:58:02.541 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=4, callback=0, payload=00 04 03 26 03 FE AD 00 
2019-04-16 16:58:02.543 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-04-16 16:58:02.544 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Application Command Request (ALIVE:DONE)
2019-04-16 16:58:02.545 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: resetResendCount initComplete=true isDead=false
2019-04-16 16:58:02.547 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-04-16 16:58:02.549 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported

2019-04-16 16:58:02.550 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 4: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2019-04-16 16:58:02.551 [DEBUG] [col.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Switch Multi Level report, value = 254

2019-04-16 16:58:02.553 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-04-16 16:58:02.554 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=254

2019-04-16 16:58:02.556 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Commands processed 1.
2019-04-16 16:58:02.557 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@13f0bb8.
2019-04-16 16:58:02.558 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@13f0bb8.
2019-04-16 16:58:02.560 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:59 DONE
2019-04-16 16:58:02.561 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-04-16 16:58:02.566 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-04-16 16:58:02.567 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-04-16 16:58:02.568 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-04-16 16:58:02.569 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

When looking at the 300 second polling, I see that the Z-Wave binding reverts to 15 second re-polling (instead of the 20 seconds requested):

2019-04-16 16:57:47.417 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling intialised at 300 seconds - start in 15000 milliseconds.

Could it be related to Long delay in item state changing

[chris (Chris Jackson)]

You can only set the poll period to a minimum of 15 seconds - that is limited by the binding. The repoll period can only be set to a maximum of 15 seconds - again, this is limited by the binding.

@shutterfreak

When looking at the 300 second polling, I see that the Z-Wave binding reverts to 15 second re-polling

Hmmm - these are two very different settings doing different things.

1. Polling is the routine poll. ie the device will be polled regularly at this rate
2. Repoll is the period after a command is sent for the binding to request the state update

[shutterfreak (Olivier Biot)]

@chris

You can only set the poll period to a minimum of 15 seconds - that is limited by the binding. The repoll period can only be set to a maximum of 15 seconds - again, this is limited by the binding.

shutterfreak:

So I’m out of luck in this case, unless I poll the roller shutters every 20-30 seconds?

[chris (Chris Jackson)]

There is nothing to stop you adding a rule to update the value a certain time after the command is sent is there?

We could probably update the binding to increase the repoll time if this is what you want (??) but I’m a little apprehensive to make this too long for an edge case.

[shutterfreak (Olivier Biot)]

@chris

There is nothing to stop you adding a rule to update the value a certain time after the command is sent is there?

Is there a way for me to trigger the Z-Wave binding to poll the state by means of a rule? All I need is a SWITCH_MULTILEVEL_GET.

Otherwise I will have to either:

1. Revert on using autoupdate for setting the roller shutter states
2. Use a rule to set the state independently of the actual state (as I can’t get it from the node within 15 seconds

@chris

We could probably update the binding to increase the repoll time if this is what you want (??) but I’m a little apprehensive to make this too long for an edge case.

Unless I can explicitly poll a node through the Z-Wave binding. Is the 15 second limit imposed by the Z-Wave standard, or is this limit set in the Z-Wave binding?

[chris (Chris Jackson)]

@shutterfreak

Is there a way for me to trigger the Z-Wave binding to poll the state by means of a rule?

Yes, you can use the REFRESH command.

@shutterfreak

Is the 15 second limit imposed by the Z-Wave standard

No - this sort of thing is not imposed by the standard - it doesn’t recommend or require any polling.

There needs to be a limit - I could make it 20 seconds - but then someone finds another device that wants 25 - where do we stop? I don’t want to make it too long as people setting this to long values will potentially cause problems with timer queues that then need to be resolved and it starts getting real messy.

[shutterfreak (Olivier Biot)]

@chris

Is there a way for me to trigger the Z-Wave binding to poll the state by means of a rule?

Yes, you can use the REFRESH command.

Sweet! Here’s the rule that seems to do the job:

rule "Refresh Fakro ARZ roof shutters after command"
when
	Item AT_Shutter_N received command
	or Item AT_Shutter_SE received command
	or Item AT_Shutter_SW received command
then
	if (receivedCommand.toString.toUpperCase != "REFRESH") {
		val String ruleTitle = "Refresh Z-Wave node after command"
		val int delay = 20
		logDebug(ruleTitle, triggeringItem.getName() + " received '" + receivedCommand.toString + "' - will refresh state in " + delay + ' seconds')
		createTimer(now.plusSeconds(delay), [ |
			logDebug(ruleTitle, triggeringItem.getName() + " received '" + receivedCommand.toString + "' - will refresh state NOW")
			sendCommand(triggeringItem, "REFRESH")
		])
	}
end

I suppose I could improve this by defining one timer per roller shutter item and reset the timer if it already runs, in case I am compulsively operating the controls
In that case the rule for one shutter looks like:

var Timer timer_AT_Shutter_N = null

rule "Refresh Fakro ARZ roof shutter AT_Shutter_N after command"
when
	Item AT_Shutter_N received command
then
	// Only process commands different from "REFRESH" (avoid dead-lock):
	if (receivedCommand.toString.toUpperCase != "REFRESH") {
		val String ruleTitle = "Refresh Z-Wave node after command"
		val int delay = 20
		logDebug(ruleTitle, triggeringItem.getName() + " received '" + receivedCommand.toString + "' - will refresh state in " + delay + ' seconds')
		if (timer_AT_Shutter_N === null) {
			timer_AT_Shutter_N = createTimer(now.plusSeconds(delay), [ |
				logDebug(ruleTitle, triggeringItem.getName() + " received '" + receivedCommand.toString + "' - will refresh state NOW")
				sendCommand(triggeringItem, "REFRESH")
				timer_AT_Shutter_N = null
			])
		} else {
			logInfo(ruleTitle, triggeringItem.getName() + " received '" + receivedCommand.toString + "' - timer already running (resetting) - will refresh state in " + delay + ' seconds')
			timer_AT_Shutter_N.reschedule(now.plusSeconds(delay))
		}
	}
end

So no need to change the binding.

[shutterfreak (Olivier Biot)]

Here’s how I ended up writing my rules. To avoid code duplication, I created a lambda: processRollerShutterCommandReceived. Being a lambda, it must explicitly receive all required elements of the context so it needs to access global variables holding the roller shutter timers and timer values per shutter.

import java.util.HashMap

// Roller shutter timers - must be initialized in a rule at system startup:
val HashMap<String, Timer> timers = newHashMap

// Timer values to fully open/close a roller shutter:
val HashMap<String, Integer> timer_values = newHashMap(
	'AT_Shutter_N' -> 14,
	'AT_Shutter_SE' -> 20,
	'AT_Shutter_SW' -> 20
)


// Lambda for handling a roller shutter command:
val processRollerShutterCommandReceived = [
	GenericItem shutter,
	String cmdReceived,
	HashMap<String, Timer> timers,
	HashMap<String, Integer> timer_values	
	|
	val String ruleTitle = "Refresh Z-Wave node after command"
	logDebug(ruleTitle, "Shutter '" + shutter.getName() + "' received '" + cmdReceived + "' - at START of lambda")
	logDebug(ruleTitle, "Timers = " + timers)
	// Only process commands different from "REFRESH" (avoid dead-lock)
	if (cmdReceived.toUpperCase != "REFRESH") {
		logDebug(ruleTitle, "Shutter '" + shutter.getName() + "' received '" + cmdReceived + "' - NOT 'REFRESH'")
		// val String shutterName = shutter.getName()
		if (cmdReceived.toUpperCase == 'STOP') {
			logDebug(ruleTitle, "Shutter '" + shutter.getName() + "' received '" + cmdReceived + "' - is 'STOP'")
			if (timers.get(shutter.getName()) !== null) {
				timers.get(shutter.getName()).cancel()
				logDebug(ruleTitle, shutter.getName() + " received '" + cmdReceived + "' - cancelling the refresh timer")
				timers.put(shutter.getName(), null)
			}
			logDebug(ruleTitle, shutter.getName() + " received '" + cmdReceived + "' - will refresh state NOW")
			sendCommand(shutter, "REFRESH")
		} else {
			logDebug(ruleTitle, shutter.getName() + " received '" + cmdReceived + "' - will refresh state in " + timer_values.get(shutter.getName()) + ' seconds')
			if (timers.get(shutter.getName()) === null) {
				logDebug(ruleTitle, "Shutter '" + shutter.getName() + "' received '" + cmdReceived + "' - no timer - will create a new timer")
				timers.put(shutter.getName(), createTimer(now.plusSeconds(timer_values.get(shutter.getName())), [ |
					logDebug(ruleTitle, shutter.getName() + " received '" + cmdReceived + "' - will refresh state NOW")
					sendCommand(shutter, "REFRESH")
					timers.put(shutter.getName(), null)
				]))
			} else {
				logDebug(ruleTitle, shutter.getName() + " received '" + cmdReceived + "' - timer already running (resetting) - will refresh state in " + timer_values.get(shutter.getName()) + ' seconds')
				timers.get(shutter.getName()).reschedule(now.plusSeconds(timer_values.get(shutter.getName())))
			}
		}
	}
	logDebug(ruleTitle, "Shutter '" + shutter.getName() + "' received '" + cmdReceived + "' - at END of lambda")
]


// Initialize the roller shutter timers at system startup
rule "System startup - shutters"
when
	System started
then
	logInfo("System startup - shutters", "Initializing timers")
	timers.put('AT_Shutter_N', null as Timer) // timer_AT_Shutter_N
	timers.put('AT_Shutter_SE', null as Timer) // timer_AT_Shutter_SE
	timers.put('AT_Shutter_SW', null as Timer) // timer_AT_Shutter_SW
end


// Manage the roller shutter commands and set the timers accordingly
rule "Refresh Fakro ARZ roof shutter after command"
when
	Item AT_Shutter_N received command
	or Item AT_Shutter_SE received command
	or Item AT_Shutter_SW received command
then
	logInfo("Refresh Fakro ARZ roof shutter after command", triggeringItem.getName() + " received command " + receivedCommand.toString)
	processRollerShutterCommandReceived.apply(
		triggeringItem as GenericItem,
		receivedCommand.toString,
		timers,
		timer_values
	)
end

Have fun!

[shutterfreak (Olivier Biot)]

Sadly the radio link between my Fakro roller shutters and the controller seems to be weak. As a result, I often get node disconnects, and the REFRESH command doesn’t always return state.

Should I add a cron schedule to poll the roller shutter states every few minutes?

[rossko57]

@shutterfreak

Sadly the radio link between my Fakro roller shutters and the controller seems to be weak. As a result, I often get node disconnects, and the REFRESH command doesn’t always return state.

I don’t know how zwave works, but do you not (eventually) get a failed state, manifesting as UNDEF?
I expected a failed REFRESH to get held in a queue for a zwave device, and kick in when radio comms restored.

As for cron job, it’d be better to let the refresh timer reschedule itself, so you don’t get new requests popping up in the middle of a work in progress.

[shutterfreak (Olivier Biot)]

@rossko57

Sadly the radio link between my Fakro roller shutters and the controller seems to be weak. As a result, I often get node disconnects, and the REFRESH command doesn’t always return state.

I don’t know how zwave works, but do you not (eventually) get a failed state, manifesting as UNDEF?
I expected a failed REFRESH to get held in a queue for a zwave device, and kick in when radio comms restored.

Unless the Z-Wave node answers the status request triggered by sending “REFRESH”, the binding is unable to set the state.

I also noticed that in case I partially lower or raise the shutters, they report a Z-Wave status value of 0xFE (254 in decimal). This is expected in this case since these roller shutters are not positional aware, only endpoint aware. However, the 0xFE state returned by the Z-Wave node is never translated into a state in OH2 (say, UNDEF). Not sure if this is by design.

In other words, it appears that in my case I will only receive state updates whenever the roller shutters reached a physical endpoint, which translates in Z-Wave status of 0x00 (fully closed) or 0xFF (fully open). And never in other cases.

The problem is that, in addition, the Z-Wave radio link seems to be very short-range (2 meters at most for 80% reliable operation). This is not only the case with the Z-Wave USB controller (ZME-E-UZB1) but also with the portable Fakro ZWP10 controllers.

@rossko57

As for cron job, it’d be better to let the refresh timer reschedule itself, so you don’t get new requests popping up in the middle of a work in progress.

I already have a rule that is triggered whenever a command is sent to any of the Z-Wave roller shutters. This rule in turn calls a lambda function which takes care of (re)setting the appropriate refresh timers when needed. So I could resort on scheduling a sendCommand("REFRESH") message to all Z-Wave roller shutters in a dedicated cron rule, as the command will properly be intercepted and processed by the existing rule (which sets timers via a lambda function).

In fact I did, but then I hit into the shortcomings I mentioned above.

[rossko57]

@shutterfreak

I already have a rule that is triggered whenever …

That was my point. Use this existing timer setup, by rescheduling, to also add your periodic refresh-poll requirement to the same mechanism…

If you set up an independent cron-based refresh you risk having the occasional clash of an independent poll arriving in the middle of one of your command-wait-poll sequences, or just before, or just after. Treading on its toes. I don’t know what issues that might cause, but why introduce further problems? It just has the look of a classic race condition waiting to bite you.

The method I would suggest - at the end of timer execution, have it reschedule itself to do the long period routine poll. When issuing a command, reschedule for the short period post-command poll. (When that finishes it will auto resume long polls.)
You’d probably want to start off all timers at system startup to establish the long polls.

None of which helps your radio issues of course!. You could get clever and make a decision within the timer based on last successful update time - if recent, just sleep for long time. If old and stale, issue refresh and check again soon. Variable poll rate, or retry mechanism.

@shutterfreak

they report a Z-Wave status value of 0xFE

It strikes me you could do with a transform on the roller status; 0 and 100 of course, and a personal choice of 50 or UNDEF to indicate neither open nor closed.

[shutterfreak (Olivier Biot)]

@rossko57

they report a Z-Wave status value of 0xFE

It strikes me you could do with a transform on the roller status; 0 and 100 of course, and a personal choice of 50 or UNDEF to indicate neither open nor closed.

The problem is that the Z-Wave binding does not report that 0xFE status so OH2 doesn’t know of this state. There’s no way to get that state reported to OH2 unless the binding reports it. So using a state transform won’t work in this case.

[shutterfreak (Olivier Biot)]

@rossko57

The method I would suggest - at the end of timer execution, have it reschedule itself to do the long period routine poll. When issuing a command, reschedule for the short period post-command poll. (When that finishes it will auto resume long polls.)
You’d probably want to start off all timers at system startup to establish the long polls.

I like the idea. I’ll do some reading to see how I can enrich my current simple timer setup to that end.

[rossko57]

@shutterfreak

the Z-Wave binding does not report that 0xFE status

Right, I misunderstood. Although COMMAND_CLASS_SWITCH_MULTILEVEL suggests it ought to, to me. I don’t know any zwave nuts and bolts to comment if that would be a sensible enhancement.

[chris (Chris Jackson)]

0xFE means that the state is unknown. I suspect when this was written, it was not possible to set a state to UNKNOWN (or UNDEF) as this didn’t exist in the past. It could be changed to report this.

[shutterfreak (Olivier Biot)]

@chris

0xFE means that the state is unknown. I suspect when this was written, it was not possible to set a state to UNKNOWN (or UNDEF) as this didn’t exist in the past. It could be changed to report this.

It would be great if Z-Wave state 0xFE were reported as UNDEF in OH2.

[rossko57]

UNDEF would be the closest match to “unknown”. That is distinct from NULL, which might be described as “not known to openHAB yet”. UNDEF never arises by accident or default, something has to have set it.

Background, many other bindings set UNDEF states in the case of say a comms or decoding failure - “I tried but failed”. (That’s not generally sensible for zwave, where healthy devices may just be sleeping.)
Just saying that’s a slightly different use case, indicating underlying failure rather than simply indeterminate; but UNDEF still seems entirely appropriate here. It’s undefined here because the device is positively telling you that it cannot define it.

It might be worth considering if this should be an option - to set UNDEF, or to ignore 0xFE and let the last value stand.
My gut says a device’s positive response “unknown” should by default result in a state update to UNDEF. That’s what its there for?
But I have no knowledge of how this might knock-on to other devices supporting 0xFE type behaviour.

Sounds like it’d be worth raising a Github enhancement request issue @shutterfreak so that such thoughts can be thrashed out and @chris can giver proper consideration.

[shutterfreak (Olivier Biot)]

@rossko57

My gut says a device’s positive response “unknown” should by default result in a state update to UNDEF. That’s what its there for?

To my knowledge Z-Wave has two interpretations of the Z-Wave 0xFE state:

1. The device hasn’t been properly initialised (e.g., due to a restart after a power cut)
2. The device is in an undeterminable state (e.g., in-between end positions if the device doesn’t support positional awareness)

It’s then a matter of determining which OH state best matches this “double interpretation” 0xFE Z-Wave state.

[rossko57]

Let’s put it this way … there aren’t any other OH choices
UNDEF is a good fit for -
Indeterminate because device cannot work it out (no sensor)
Indeterminate because device will not work it out (busy or crippled)
Either way a successful status report has come in, which we’d like to know about.