Updates to thermostat revert to previous value within milliseconds

zwave
Tags: #<Tag:0x00007f0e97b3ca20>

(Matjordan) #1

Hello,

I noticed some updates to the cool set point of my CT 100, were applied and then reverted back to the original value. This was especially the case for updates triggered through rules. I just updated to the latest snapshot (openHAB 2.4.0 Build #1364, followed instructions here:ZWave binding updates) in an attempt to remedy this, but now all updates are being immediately reverted to their previous values.

Any ideas would be greatly appreciated.

2018-09-16 13:21:53.206 [ome.event.ItemCommandEvent] - Item 'HVAC_CoolSetPoint' received command 78

2018-09-16 13:21:53.222 [nt.ItemStatePredictedEvent] - HVAC_CoolSetPoint predicted to become 78

2018-09-16 13:21:53.238 [vent.ItemStateChangedEvent] - HVAC_CoolSetPoint changed from 77 to 78

==> /var/log/openhab2/openhab.log <==

2018-09-16 13:21:53.250 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Command received zwave:device:39a25486:node6:thermostat_setpoint_cooling --> 78 °C

2018-09-16 13:21:53.259 [DEBUG] [ter.ZWaveThermostatSetpointConverter] - NODE 6: Thermostat command received for 78 °C

2018-09-16 13:21:53.278 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 6: Creating new message for command THERMOSTAT_SETPOINT_SET

2018-09-16 13:21:53.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported

2018-09-16 13:21:53.291 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_THERMOSTAT_SETPOINT is NOT required to be secured

2018-09-16 13:21:53.304 [DEBUG] [ter.ZWaveThermostatSetpointConverter] - NODE 6: Sending Message: org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@ed3a47

2018-09-16 13:21:53.309 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 6: Creating new message for application command THERMOSTAT_SETPOINT_GET (Cooling)

2018-09-16 13:21:53.314 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported

2018-09-16 13:21:53.318 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_THERMOSTAT_SETPOINT is NOT required to be secured

2018-09-16 13:21:53.322 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue

2018-09-16 13:21:53.326 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2018-09-16 13:21:53.334 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 13 06 05 43 01 02 01 4E 25 DB 12 

2018-09-16 13:21:53.340 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message = 01 0C 00 13 06 05 43 01 02 01 4E 25 DB 12 

2018-09-16 13:21:53.345 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2018-09-16 13:21:53.348 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2018-09-16 13:21:53.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 475: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 219

2018-09-16 13:21:53.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2018-09-16 13:21:53.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue

2018-09-16 13:21:53.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2018-09-16 13:21:53.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2018-09-16 13:21:53.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 475: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 219

2018-09-16 13:21:53.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2018-09-16 13:21:53.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2018-09-16 13:21:53.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2018-09-16 13:21:53.370 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling intialised at 1800 seconds - start in 1500 milliseconds.

2018-09-16 13:21:53.383 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2018-09-16 13:21:53.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2018-09-16 13:21:53.392 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2018-09-16 13:21:53.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 475: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 219

2018-09-16 13:21:53.401 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 DB 00 00 05 35 

2018-09-16 13:21:53.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2018-09-16 13:21:53.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 475: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 219

2018-09-16 13:21:53.407 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=219, payload=DB 00 00 05 

2018-09-16 13:21:53.418 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2018-09-16 13:21:53.423 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: sentData successfully placed on stack.

2018-09-16 13:21:53.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 475: Advanced to WAIT_REQUEST

2018-09-16 13:21:53.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 475: Transaction not completed

2018-09-16 13:21:53.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=219, payload=DB 00 00 05 

2018-09-16 13:21:53.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 475: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 219

2018-09-16 13:21:53.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2018-09-16 13:21:53.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 475: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 219

2018-09-16 13:21:53.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 475: (Callback 219)

2018-09-16 13:21:53.446 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2018-09-16 13:21:53.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 475: callback 219

2018-09-16 13:21:53.453 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=219, payload=DB 00 00 05 

2018-09-16 13:21:53.456 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 219, Status = Transmission complete and ACK received(0)

2018-09-16 13:21:53.461 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: resetResendCount initComplete=true isDead=false

2018-09-16 13:21:53.463 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 475: Transaction COMPLETED

2018-09-16 13:21:53.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Response processed after 117ms

2018-09-16 13:21:53.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 475: Transaction completed

2018-09-16 13:21:53.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: notifyTransactionResponse TID:475 DONE

2018-09-16 13:21:53.473 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-09-16 13:21:53.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2018-09-16 13:21:53.478 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2018-09-16 13:21:53.482 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 06 03 43 02 02 25 DC 59 

2018-09-16 13:21:53.487 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message = 01 0A 00 13 06 03 43 02 02 25 DC 59 

2018-09-16 13:21:53.490 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2018-09-16 13:21:53.493 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2018-09-16 13:21:53.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 476: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 220

2018-09-16 13:21:53.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2018-09-16 13:21:53.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2018-09-16 13:21:53.501 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2018-09-16 13:21:53.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 476: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 220

2018-09-16 13:21:53.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2018-09-16 13:21:53.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2018-09-16 13:21:53.511 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2018-09-16 13:21:53.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 476: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 220

2018-09-16 13:21:53.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2018-09-16 13:21:53.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 476: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 220

2018-09-16 13:21:53.527 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2018-09-16 13:21:53.531 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: sentData successfully placed on stack.

2018-09-16 13:21:53.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 476: Advanced to WAIT_REQUEST

2018-09-16 13:21:53.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 476: Transaction not completed

2018-09-16 13:21:53.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2018-09-16 13:21:53.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2018-09-16 13:21:53.545 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 DC 00 00 05 32 

2018-09-16 13:21:53.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=220, payload=DC 00 00 05 

2018-09-16 13:21:53.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=220, payload=DC 00 00 05 

2018-09-16 13:21:53.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 476: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 220

2018-09-16 13:21:53.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2018-09-16 13:21:53.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 476: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 220

2018-09-16 13:21:53.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 476: (Callback 220)

2018-09-16 13:21:53.569 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2018-09-16 13:21:53.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 476: callback 220

2018-09-16 13:21:53.576 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=220, payload=DC 00 00 05 

2018-09-16 13:21:53.578 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 220, Status = Transmission complete and ACK received(0)

2018-09-16 13:21:53.581 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: resetResendCount initComplete=true isDead=false

2018-09-16 13:21:53.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 476: Advanced to WAIT_DATA

2018-09-16 13:21:53.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 476: Transaction not completed

2018-09-16 13:21:53.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2018-09-16 13:21:53.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2018-09-16 13:21:53.795 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 06 05 43 03 02 09 4D F5 

2018-09-16 13:21:53.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=6, callback=0, payload=00 06 05 43 03 02 09 4D 

2018-09-16 13:21:53.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=6, callback=0, payload=00 06 05 43 03 02 09 4D 

2018-09-16 13:21:53.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2018-09-16 13:21:53.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Application Command Request (ALIVE:DONE)

2018-09-16 13:21:53.824 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: resetResendCount initComplete=true isDead=false

2018-09-16 13:21:53.829 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Incoming command class COMMAND_CLASS_THERMOSTAT_SETPOINT, endpoint 0

2018-09-16 13:21:53.832 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported

2018-09-16 13:21:53.837 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 6: Received COMMAND_CLASS_THERMOSTAT_SETPOINT V1 THERMOSTAT_SETPOINT_REPORT

2018-09-16 13:21:53.841 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 6: Thermostat Setpoint report Scale = 1

2018-09-16 13:21:53.847 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 6: Thermostat Setpoint Value = 77

2018-09-16 13:21:53.850 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 6: Thermostat Setpoint Report, Type Cooling (2), value = 77

2018-09-16 13:21:53.856 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent

2018-09-16 13:21:53.859 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_THERMOSTAT_SETPOINT, value = 77

2018-09-16 13:21:53.865 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating channel state zwave:device:39a25486:node6:thermostat_setpoint_cooling to 77 °F [QuantityType]

2018-09-16 13:21:53.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Commands processed 1.

==> /var/log/openhab2/events.log <==

2018-09-16 13:21:53.883 [vent.ItemStateChangedEvent] - HVAC_CoolSetPoint changed from 78 to 77s

(Chris Jackson) #2

Probably you missed the part about setting the locale? Either that, or you like your heating REALLY hot as you’re setting it to 78 deg C.


(Matjordan) #3

Thanks for the quick reply! I managed to get it to work by adding the unit in the Item file.


(Chris Jackson) #4

You can set set the default in the system settings -:

The binding will now send through the units to the device, so this needs to be set correctly…


(Matjordan) #5

Seems I was celebrating to early. There were at least two different problems. Setting the locale fixed issue one: changing the value manually through habpanel etc. However issue two changing the value from rules still persists.

logfile


(Chris Jackson) #6

There’s nothing wrong with what the binding is sending -:

Does the thermostat actually change temperature?


(Matjordan) #7

When I trigger the update this way (through a rule) my dummy in habpanel blinks the new value, then goes back, the thermostat lcd doesn’t change at all. When changed out off habpanel, the update goes through and is reflected on the thermostat. When changed on the thermostat the new value is correctly updated in openhab.


(Chris Jackson) #8

In that case you need to work out what the difference is - check the logs for both and there must be a difference.


(Matjordan) #9

The difference seems to be that the rule sends a command to change the opmode to cool and sets a cool setpoint at basically the same time. While changing the value through habpanel only updates the set point. I commented the part with the opmode change out off the rule and now the setpoint is being updated as expected.
No idea why it doesn’t like both changes at once (especially as it has worked intermittent in the past), but I should be able to find a way around that now.

Thanks for pointing me in the right direction again!