Zwave, SRT321/HRT4-ZW Thermostat, Writing Setpoint by Zwave, reliability problem

Dears,

This thermostat set-point is a “bidirectional” Number,
correctly binded to OH2 ZWAVE HRT4-ZW Battery Powered Wall Thermostat.

I configured its WakeUp time to 300 seconds (… and testing becomes tiring !!!)

For testing, I have an Item (Number) binded to that set-point (chThermo_Temp_SetPoint).
I “trig on change” on that Item, only to update another (local unbinded) Item, only to display its value, what perfectly and immediately runs while the set-point is adjusted on the device.

For writing, I do

chThermo_Temp_SetPoint.sendCommand(Indoor_Temp_Nuit.state as Number)

The event log always confirms something like that:

- Item 'chThermo_Temp_SetPoint' received command 22
- chThermo_Temp_SetPoint updated to 22
- chThermo_Temp_SetPoint changed from 23 to 22
- chThermo_Temp_SetPoint updated to 22 

I observe the result on the display of the thermostat :

  • Sometimes, the value is correctly transferred, in the 5 minutes.
  • Sometimes, the value is transferred “with a blow of delay”
    (the preview value was not transferred, but seems to be transferred on the next sendCommand)
  • Sometimes, the value is never transferred, or pherhaps after a while, or after a next sendCommand

In every case, the events are correctly logged.
In “DEBUG” logging, I don’t analyzed the RX transactions, but I observe that the updated values seem always correctly queued on the TX WakeUpQueue, while the eventual previous pending output values seems also correctly removed, if any.

Remark
I found on the Internet a few (a lot) of articles describing this problem, but not clearly enough, and overall, I never found a comment saying if the problem is solved or not. It could be a problem of the SRT321. (it seems).

Question:
Does somebody already experimented this problem ?
In any case, does somebody knows a reliable solution to cope to this problem ?

Hoping having an answer,
Thanks in advance.
Charly.

I am having the exact same issue on all my 9 SRT321 thermostats. Manually changing the setpoint through the dial triggers an immediate update in the logs, but sendCommand(x) almost always comes with a delay. My wake up period is the minimum 256 seconds but I have just witnessed an update delay of 21 minutes on one of my thermostats. I don’t remember having this issue on my previous Vera Edge controller.

I know this is not ideal but I guess one solution is to give up on the thermostat display and work off of the setpoint variables you create in your rules. The current temperatures and manual setpoint updates will always be accurate and timely, so if you have rules that “turn on the boiler if setpoint > current temp” they should work fine (obviously what OH thinks the setpoint is will not match what is displayed on the thermostat).

Yetkin

I would suggest to check the logs to see what is happening. If there’s some sort of problem, then feel free to raise an issue.

Thanks Chris - did some testing and debugging this morning. I didn’t see any obvious warnings or errors in the log, only that the setpoint update is skipping 3-4 wake-ups every time and there seems to be 5-6 messages in the queue in every wake-up. This is for a HRT-4ZW thermostat which is in the same room as the OH server using a Aeotec Z-stick, so I do not think it is a range issue. Also the current temperature updates and manual setpoint changes through the dial of the thermostat get picked up instantaneously, so this must be an issue specific to setpoint commands over the air.

So as a tactical fix I will change my rules to use a “software” setpoint instead of pushing one to the thermostat and reading it back - this morning I had one setpoint update fail which caused the thermostat to stay in the “Heat On” position, keeping the boiler on longer than necessary.

Part of the debug file relevant to one of my thermostats below - you can see the update went through in 10 minutes, while the device woke up 3 times during that period (wake up period is 256 seconds):

06:12:00	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Command received zwave:device:4e4692bc:node10:thermostat_setpoint_heating --> 25						
06:12:00	[DEBUG]	[.ZWaveThermostatSetpointCommandClass]	NODE 10: Creating new message for application command THERMOSTAT_SETPOINT_GET (Heating)						
06:12:00	[DEBUG]	[.ZWaveThermostatSetpointCommandClass]	NODE 10: Creating new message for command THERMOSTAT_SETPOINT_SET						
06:12:00	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Message already on the wake-up queue. Removing original.						
06:12:00	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Putting message SendData in wakeup queue.						
06:12:00	[DEBUG]	[ter.ZWaveThermostatSetpointConverter]	NODE 10: Sending Message: Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=10, call	back=	0, pay	lo	ad=0	A 0	5 43 01 01 01 19
06:12:00	[DEBUG]	[ter.ZWaveThermostatSetpointConverter]	NODE 10: Thermostat command received for 25						
06:12:00	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Putting message SendData in wakeup queue.						
06:13:28	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:13:28	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class WAKE_UP						
06:13:28	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Received Wake Up Request						
06:13:28	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Received WAKE_UP_NOTIFICATION						
06:13:28	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:13:28	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveWakeUpEvent						
06:13:28	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Is awake with 6 messages in the wake-up queue.						
06:13:28	[DEBUG]	[ing.zwave.handler.ZWaveSerialHandler]	NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 25 02 25 F5 1A						
06:13:28	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: Sent Data successfully placed on stack.						
06:13:28	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: SendData Request. CallBack ID = 245, Status = Transmission complete and ACK received(0)						
06:13:28	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:13:28	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:13:28	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveWakeUpEvent						
06:13:28	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class WAKE_UP						
06:13:28	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Is awake with 5 messages in the wake-up queue.						
06:13:28	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Received Wake Up Request						
06:13:28	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Received WAKE_UP_NOTIFICATION						
06:13:28	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:13:33	[DEBUG]	[ocol.ZWaveController$ZWaveSendThread]	NODE 10: Timeout while sending message. Requeueing - 2 attempts left!						
06:13:33	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Is sleeping						
06:13:33	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Putting message SendData in wakeup queue.						
06:13:33	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Putting message SendData in wakeup queue.						
06:13:33	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:13:33	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class SENSOR_MULTILEVEL						
06:13:33	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V1						
06:13:33	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Multi Level REPORT received						
06:13:33	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Type = Temperature(1), Scale = 0						
06:13:33	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Value = 21.5						
06:13:33	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:13:33	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value =	21.5					
06:13:33	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent						
06:13:33	[DEBUG]	[erter.ZWaveMultiLevelSensorConverter]	NODE 10: Sensor is reporting scale 0, requiring conversion to 0. Value is now 21.5.						
06:13:33	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:sensor_temperature to 21.5 [DecimalType]						
06:13:33	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:13:33	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class SENSOR_MULTILEVEL						
06:13:33	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V1						
06:13:33	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Multi Level REPORT received						
06:13:33	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Type = Temperature(1), Scale = 0						
06:13:33	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Value = 21.5						
06:13:33	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:13:33	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value =	21.5					
06:13:33	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent						
06:13:33	[DEBUG]	[erter.ZWaveMultiLevelSensorConverter]	NODE 10: Sensor is reporting scale 0, requiring conversion to 0. Value is now 21.5.						
06:13:33	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:sensor_temperature to 21.5 [DecimalType]						
06:13:37	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Transaction not completed: node address inconsistent.  lastSent=10, incoming=255						
06:13:37	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Transaction not completed: node address inconsistent.  lastSent=10, incoming=255						
06:13:37	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Transaction not completed: node address inconsistent.  lastSent=10, incoming=255						
06:13:37	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Transaction not completed: node address inconsistent.  lastSent=10, incoming=255						
06:13:38	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:13:38	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class SENSOR_MULTILEVEL						
06:13:38	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V1						
06:13:38	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Multi Level REPORT received						
06:13:38	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Type = Temperature(1), Scale = 0						
06:13:38	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:13:38	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value =	21.6					
06:13:38	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent						
06:13:38	[DEBUG]	[erter.ZWaveMultiLevelSensorConverter]	NODE 10: Sensor is reporting scale 0, requiring conversion to 0. Value is now 21.6.						
06:13:38	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Value = 21.6						
06:13:38	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:sensor_temperature to 21.6 [DecimalType]						
06:13:38	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:13:38	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class SENSOR_MULTILEVEL						
06:13:38	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V1						
06:13:38	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Multi Level REPORT received						
06:13:38	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Type = Temperature(1), Scale = 0						
06:13:38	[DEBUG]	[ss.ZWaveMultiLevelSensorCommandClass]	NODE 10: Sensor Value = 21.6						
06:13:38	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:13:38	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value =	21.6					
06:13:38	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent						
06:13:38	[DEBUG]	[erter.ZWaveMultiLevelSensorConverter]	NODE 10: Sensor is reporting scale 0, requiring conversion to 0. Value is now 21.6.						
06:13:38	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:sensor_temperature to 21.6 [DecimalType]						
06:17:44	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:17:44	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class WAKE_UP						
06:17:44	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Is awake with 6 messages in the wake-up queue.						
06:17:44	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Received Wake Up Request						
06:17:44	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Received WAKE_UP_NOTIFICATION						
06:17:44	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:17:44	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveWakeUpEvent						
06:17:44	[DEBUG]	[ing.zwave.handler.ZWaveSerialHandler]	NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 80 02 25 19 53						
06:17:44	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: Sent Data successfully placed on stack.						
06:17:44	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: SendData Request. CallBack ID = 25, Status = Transmission complete and ACK received(0)						
06:17:44	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:17:44	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:17:44	[DEBUG]	[ommandclass.ZWaveBatteryCommandClass]	NODE 10: Battery report value = 30						
06:17:44	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = BATTERY, value = 30						
06:17:44	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:17:44	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class BATTERY						
06:17:44	[DEBUG]	[ommandclass.ZWaveBatteryCommandClass]	NODE 10: Received Battery Request						
06:17:44	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:17:44	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:battery-level to 30 [DecimalType]						
06:17:44	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent						
06:17:44	[DEBUG]	[ocol.ZWaveController$ZWaveSendThread]	NODE 10: Response processed after 44ms/4998ms.						
06:17:44	[DEBUG]	[ing.zwave.handler.ZWaveSerialHandler]	NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 40 02 25 1A 90						
06:17:44	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: Sent Data successfully placed on stack.						
06:17:44	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: SendData Request. CallBack ID = 26, Status = Transmission complete and ACK received(0)						
06:17:44	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:17:49	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Is sleeping						
06:17:49	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Putting message SendData in wakeup queue.						
06:17:49	[DEBUG]	[ocol.ZWaveController$ZWaveSendThread]	NODE 10: Timeout while sending message. Requeueing - 1 attempts left!						
06:17:57	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Transaction not completed: node address inconsistent.  lastSent=10, incoming=255						
06:21:50	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:21:50	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class THERMOSTAT_MODE						
06:21:50	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Received Thermostat Mode Request						
06:21:50	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:21:50	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Thermostat Mode report, value = 0						
06:21:50	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Thermostat Mode Report, value = Off						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = THERMOSTAT_MODE, value = 0						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:thermostat_mode to 0 [DecimalType]						
06:21:50	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:21:50	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class THERMOSTAT_MODE						
06:21:50	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = THERMOSTAT_MODE, value = 0						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:21:50	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Received Thermostat Mode Request						
06:21:50	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Thermostat Mode report, value = 0						
06:21:50	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Thermostat Mode Report, value = Off						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:thermostat_mode to 0 [DecimalType]						
06:21:50	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:21:50	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class SWITCH_BINARY						
06:21:50	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:21:50	[DEBUG]	[dclass.ZWaveBinarySwitchCommandClass]	NODE 10: Switch Binary report, value = 0						
06:21:50	[DEBUG]	[dclass.ZWaveBinarySwitchCommandClass]	NODE 10: Switch Binary SET						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:switch_binary to OFF [OnOffType]						
06:21:50	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:21:50	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class SWITCH_BINARY						
06:21:50	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:21:50	[DEBUG]	[dclass.ZWaveBinarySwitchCommandClass]	NODE 10: Switch Binary report, value = 0						
06:21:50	[DEBUG]	[dclass.ZWaveBinarySwitchCommandClass]	NODE 10: Switch Binary SET						
06:21:50	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:switch_binary to OFF [OnOffType]						
06:22:00	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:22:00	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class WAKE_UP						
06:22:00	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Received Wake Up Request						
06:22:00	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Received WAKE_UP_NOTIFICATION						
06:22:00	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:00	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveWakeUpEvent						
06:22:00	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Is awake with 5 messages in the wake-up queue.						
06:22:00	[DEBUG]	[ing.zwave.handler.ZWaveSerialHandler]	NODE 10: Sending REQUEST Message = 01 0C 00 13 0A 05 43 01 01 01 19 25 2F BE						
06:22:00	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: Sent Data successfully placed on stack.						
06:22:00	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent						
06:22:00	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: SendData Request. CallBack ID = 47, Status = Transmission complete and ACK received(0)						
06:22:00	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:00	[DEBUG]	[ocol.ZWaveController$ZWaveSendThread]	NODE 10: Response processed after 37ms/4998ms.						
06:22:00	[DEBUG]	[ing.zwave.handler.ZWaveSerialHandler]	NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 43 02 01 25 30 BA						
06:22:00	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: Sent Data successfully placed on stack.						
06:22:00	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: SendData Request. CallBack ID = 48, Status = Transmission complete and ACK received(0)						
06:22:00	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:00	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:22:00	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class THERMOSTAT_SETPOINT						
06:22:00	[DEBUG]	[.ZWaveThermostatSetpointCommandClass]	NODE 10: Received Thermostat Setpoint Request						
06:22:00	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:00	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = THERMOSTAT_SETPOINT, value	25					
06:22:00	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent						
06:22:00	[DEBUG]	[.ZWaveThermostatSetpointCommandClass]	NODE 10: Thermostat Setpoint report Scale = 0						
06:22:00	[DEBUG]	[.ZWaveThermostatSetpointCommandClass]	NODE 10: Thermostat Setpoint Report, Type Heating (1), value = 25						
06:22:00	[DEBUG]	[.ZWaveThermostatSetpointCommandClass]	NODE 10: Thermostat Setpoint Value = 25						
06:22:00	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:thermostat_setpoint_heating to 25 [DecimalT	ype]					
06:22:00	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent						
06:22:00	[DEBUG]	[ocol.ZWaveController$ZWaveSendThread]	NODE 10: Response processed after 39ms/4998ms.						
06:22:00	[DEBUG]	[ing.zwave.handler.ZWaveSerialHandler]	NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 25 02 25 31 DE						
06:22:00	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: Sent Data successfully placed on stack.						
06:22:00	[DEBUG]	[l.serialmessage.SendDataMessageClass]	NODE 10: SendData Request. CallBack ID = 49, Status = Transmission complete and ACK received(0)						
06:22:00	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:04	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Transaction not completed: node address inconsistent.  lastSent=10, incoming=255						
06:22:05	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Is sleeping						
06:22:05	[DEBUG]	[commandclass.ZWaveWakeUpCommandClass]	NODE 10: Putting message SendData in wakeup queue.						
06:22:05	[DEBUG]	[ocol.ZWaveController$ZWaveSendThread]	NODE 10: Timeout while sending message. Requeueing - 1 attempts left!						
06:22:05	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:22:05	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class THERMOSTAT_MODE						
06:22:05	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = THERMOSTAT_MODE, value = 1						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:22:05	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Received Thermostat Mode Request						
06:22:05	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Thermostat Mode report, value = 1						
06:22:05	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Thermostat Mode Report, value = Heat						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:thermostat_mode to 1 [DecimalType]						
06:22:05	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:22:05	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class THERMOSTAT_MODE						
06:22:05	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Received Thermostat Mode Request						
06:22:05	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = THERMOSTAT_MODE, value = 1						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:22:05	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Thermostat Mode report, value = 1						
06:22:05	[DEBUG]	[lass.ZWaveThermostatModeCommandClass]	NODE 10: Thermostat Mode Report, value = Heat						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:thermostat_mode to 1 [DecimalType]						
06:22:05	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:22:05	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class SWITCH_BINARY						
06:22:05	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:22:05	[DEBUG]	[dclass.ZWaveBinarySwitchCommandClass]	NODE 10: Switch Binary report, value = 255						
06:22:05	[DEBUG]	[dclass.ZWaveBinarySwitchCommandClass]	NODE 10: Switch Binary SET						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:switch_binary to ON [OnOffType]						
06:22:05	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Application Command Request (ALIVE:DONE)						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent						
06:22:05	[DEBUG]	[ssage.ApplicationCommandMessageClass]	NODE 10: Incoming command class SWITCH_BINARY						
06:22:05	[DEBUG]	[alization.ZWaveNodeInitStageAdvancer]	NODE 10: Starting initialisation from DONE						
06:22:05	[DEBUG]	[dclass.ZWaveBinarySwitchCommandClass]	NODE 10: Switch Binary report, value = 255						
06:22:05	[DEBUG]	[dclass.ZWaveBinarySwitchCommandClass]	NODE 10: Switch Binary SET						
06:22:05	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Updating channel state zwave:device:4e4692bc:node10:switch_binary to ON [OnOffType]

Please can you provide the logfile somewhere? By filtering the log like this it’s removed some of the information I need. Also, if you can use the standard log formats it would also be useful as I think the log viewer won’t work with your revised format :frowning: .

Sure, sorry about that - I tried to clean it up by displaying only line items relevant to Node 10. Here is the full log file.

Thanks,
Yetkin

Thanks for your interest for this problem.

I also confirm that the problems occur (only : I don’t have formal proof) after modifying the SetPoint locally (on the device).

The wrong behavior seems to be resulting of a disturbance of the “output queue”, which seems to be not correctly flushed when application writes a new value (or when it should be).

Remark : These observations / assumptions are done at “observer” level. I didn’t look into the code!

Still Thanks.
Charly.

It looks like the issue might be that the device doesn’t respond to the GET command for the switch status - at least it doesn’t any time in the log, and yet the command does get ack’d by the device, so it does receive it. This means the binding waits for the device to respond to this request, and in the meantime, it goes back to sleep.

I can configure the database to not send this request and hopefully it will help - and hopefully fix the problem.

Makes sense, and thanks for looking into it. Let me know when I can help with testing etc.

Yetkin

Chris, sorry to chase - but have you had any luck with this?

Yes, I updated the binding last week.

I still have some delays… I am using binding version 2.2.0.201711260007 - this should have the updates right?

here is a sample log file from this evening - at 9pm a bunch of my rules fired to set thermostat setpoints to 18. Take Node 11 for example - it missed the wake ups at 21:02:50 and 21:07:06 and only updated at 21:11:22 (if I am reading the logs correctly… I can also confirm the delay visually from the thermostat display).

Am I doing something wrong here?

Hello @chris and @yetkin ,
Thank’s for your work.

I didn’t make very extensive tests, but so far I tested, I observed that it works fine.

For testing, and probably I want always proceed so for “bidirectional” variables, even if it is not necessary, I map an Input variable and an Output variable to the same channel.

Number  chThermo_SetPoint_Inp "chThermo_SetPoint_Inp [%.1f °C]" {channel="zwave:device:a05f4566:node2:thermostat_setpoint_heating"}
Number  chThermo_SetPoint_Out "chThermo_SetPoint_Out [%.1f °C]" {channel="zwave:device:a05f4566:node2:thermostat_setpoint_heating"}

I always trig on SetPoint_Inp, and I always write to SetPoint_Out.

So I could handle value if it is modified by the thermostat itself or by application, I even could survey the good transmission of the value, which, now, seems to be always in the 5 minutes, as configured.

Then for me, so far I “tested”, it seems that the communication is now reliable.

Still Thanks.
Charly.

Hello, i own that device and switched to openhab2 last week.
I reproduce that issue with stable release. I have updated to last snapshot with no luck.
I set up two items bind to thermostat_setpoint_heating

Number	Thermostat_Consigne	"Consigne[%.1f°C]"	<temperature>	(gChauffage,gTempZwave,gGraphTemps)	{ channel="zwave:device:1bcdc2c1:node8:thermostat_setpoint_heating" }
Number	Consigne	"Programmation[%.1f°C]"	<temperature>	(gChauffage,gTempZwave)	{ channel="zwave:device:1bcdc2c1:node8:thermostat_setpoint_heating" }

Consigne is what I set up (caldav) and Thermostat_Consigne is the actual setpoint on the device (used by heating system). wakeup of device is set to 900.
What i notice is that
when I set up Consigne, the setpoint actually change on the device but Thermostat_Consigne is never updated on Openhab. That setup worked fine on openhab 1.x. Once I set a setpoint on the device, it is well updated on openHab.
As winter coming, I switch back to legacy zwave binding 1.x

Does pooling period may be the issue ? i changed it from 30 to 10

Edit ; I dig a little further in logs.
According to zwave logs, channels are updated but i don t see anything in events.log.
ie:

2017-12-07 20:04:56.796 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent
2017-12-07 20:04:56.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got a value event from Z-Wave network, endpoint = 0, command class = THERMOSTAT_SETPOINT, value = 2E+1
2017-12-07 20:04:56.797 [DEBUG] [converter.ZWaveCommandClassConverter] - Converted temperature from 2E+1C to 2E+1C
2017-12-07 20:04:56.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Updating channel state zwave:device:1bcdc2c1:node8:thermostat_setpoint_heating to 20 [DecimalType]

Nothing in events.log at that time

I also notice that some battery updates are not seen in events.log

2017-12-07 20:04:56.844 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-12-07 20:04:56.844 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got a value event from Z-Wave network, endpoint = 0, command class = BATTERY, value = 61
2017-12-07 20:04:56.845 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Updating channel state zwave:device:1bcdc2c1:node8:battery-level to 61 [DecimalType]

I start to think zwave binding is not the issue. where can i check in logs ?

I’m having the same problem with setting the target temperature on the thermostat, using openhab 2, so have reverted to openhab 1.

Did you manage to resolve this? I would very much like to know what worked for you. Thanks

It seems that after the @chris 's action on Nov 18, I never had a fatal problem.
I however observed in some circumstances very big delays between the set-point modification and its activation on SRT. But after a while (perhaps hours) the communication “falls back on his paws”.

It would be well if @chris could give a status about this issue.

I can only repeat the status from what I said in November - I’ve not done anything else as people were reporting that it was generally working (as I read the above anyway).

Maybe this is related?