Updates to thermostat revert to previous value within milliseconds

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

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

Does the thermostat actually change temperature?

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.

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

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!

I am having this problem with my CT30 - It was working with no issues. I upgraded my ubuntu server from 14.04 to 16.04 and that broke all of my zwave devices. I have since got them all working again except now my setpoints are changing the value and they immediately change back (to 78F in my case). I have looked at the latest binding documentation and believe I am using the correct syntax.

Number HVAC_CoolSetPoint "Cool Set [%.1f F]" <thermostat> (HVAC) {zwave="5:command=thermostat_setpoint,setpoint_type=2,setpoint_scale=1" }


I am also seeing in the event log

2018-09-25 11:25:15.853 [ome.event.ItemCommandEvent] - Item 'HVAC_CoolSetPoint' received command 80
2018-09-25 11:25:15.859 [nt.ItemStatePredictedEvent] - HVAC_CoolSetPoint predicted to become 80
2018-09-25 11:25:15.864 [vent.ItemStateChangedEvent] - HVAC_CoolSetPoint changed from 78 to 80
2018-09-25 11:25:26.785 [vent.ItemStateChangedEvent] - HVAC_CoolSetPoint changed from 80 to 78

I can change the fan mode and the heating mode but I can’t change any setpoints. I am not sure what the difference is. I have checked through habmin to make sure that all the items are associated correctly. I don’t see any errors showing in habmin for the device.

I have set my default units in PaperUI to Imperial. I am not sure what else I can try, @chris any guidance on what else to check would be greatly appreciated.

I just wanted to add, I have installed the latest binding and removed the thing and added it again. The symptoms are the same.

This is my XML for the node

<node>
  <homeId>0x1852b21</homeId>
  <nodeId>5</nodeId>
  <version>3</version>
  <manufacturer>0x98</manufacturer>
  <deviceId>0x0</deviceId>
  <deviceType>0x0</deviceType>
  <listening>true</listening>
  <frequentlyListening>false</frequentlyListening>
  <routing>true</routing>
  <security>false</security>
  <beaming>true</beaming>
  <maxBaudRate>40000</maxBaudRate>
  <sleepDelay>1000</sleepDelay>
  <nodeInformationFrame>
    <commandClass>COMMAND_CLASS_BASIC</commandClass>
    <commandClass>COMMAND_CLASS_CLOCK</commandClass>
    <commandClass>COMMAND_CLASS_INDICATOR</commandClass>
    <commandClass>COMMAND_CLASS_MANUFACTURER_SPECIFIC</commandClass>
    <commandClass>COMMAND_CLASS_SENSOR_MULTILEVEL</commandClass>
    <commandClass>COMMAND_CLASS_THERMOSTAT_MODE</commandClass>
    <commandClass>COMMAND_CLASS_THERMOSTAT_OPERATING_STATE</commandClass>
    <commandClass>COMMAND_CLASS_THERMOSTAT_FAN_MODE</commandClass>
    <commandClass>COMMAND_CLASS_THERMOSTAT_FAN_STATE</commandClass>
    <commandClass>COMMAND_CLASS_THERMOSTAT_SETPOINT</commandClass>
    <commandClass>COMMAND_CLASS_VERSION</commandClass>
    <commandClass>COMMAND_CLASS_CONFIGURATION</commandClass>
    <commandClass>COMMAND_CLASS_BATTERY</commandClass>
    <commandClass>COMMAND_CLASS_ASSOCIATION</commandClass>
  </nodeInformationFrame>
  <associationGroups class="concurrent-hash-map">
    <entry>
      <int>1</int>
      <associationGroup>
        <index>1</index>
        <maxNodes>0</maxNodes>
        <associations>
          <associationMember>
            <node>1</node>
          </associationMember>
        </associations>
      </associationGroup>
    </entry>
  </associationGroups>
  <endpoints class="concurrent-hash-map">
    <entry>
      <int>0</int>
      <endPoint>
        <deviceClass>
          <basicDeviceClass>BASIC_TYPE_ROUTING_SLAVE</basicDeviceClass>
          <genericDeviceClass>GENERIC_TYPE_THERMOSTAT</genericDeviceClass>
          <specificDeviceClass>SPECIFIC_TYPE_THERMOSTAT_GENERAL_V2</specificDeviceClass>
        </deviceClass>
        <endpointId>0</endpointId>
        <secureCommandClasses/>
        <supportedCommandClasses class="concurrent-hash-map">
          <entry>
            <commandClass>COMMAND_CLASS_MANUFACTURER_SPECIFIC</commandClass>
            <COMMAND__CLASS__MANUFACTURER__SPECIFIC>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <initSerialNumber>false</initSerialNumber>
              <deviceManufacturer>152</deviceManufacturer>
              <deviceType>0</deviceType>
              <deviceId>0</deviceId>
            </COMMAND__CLASS__MANUFACTURER__SPECIFIC>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_BASIC</commandClass>
            <COMMAND__CLASS__BASIC>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__BASIC>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_NO_OPERATION</commandClass>
            <COMMAND__CLASS__NO__OPERATION>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
            </COMMAND__CLASS__NO__OPERATION>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_CONFIGURATION</commandClass>
            <COMMAND__CLASS__CONFIGURATION>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <configParameters/>
            </COMMAND__CLASS__CONFIGURATION>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_THERMOSTAT_OPERATING_STATE</commandClass>
            <COMMAND__CLASS__THERMOSTAT__OPERATING__STATE>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>2</versionSupported>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__THERMOSTAT__OPERATING__STATE>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_ASSOCIATION</commandClass>
            <COMMAND__CLASS__ASSOCIATION>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <maxGroups>1</maxGroups>
            </COMMAND__CLASS__ASSOCIATION>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_THERMOSTAT_FAN_MODE</commandClass>
            <COMMAND__CLASS__THERMOSTAT__FAN__MODE>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <fanModeTypes>
                <fanModeType>ON_LOW</fanModeType>
                <fanModeType>AUTO_LOW</fanModeType>
              </fanModeTypes>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__THERMOSTAT__FAN__MODE>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_THERMOSTAT_FAN_STATE</commandClass>
            <COMMAND__CLASS__THERMOSTAT__FAN__STATE>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <fanStateTypes/>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__THERMOSTAT__FAN__STATE>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_SENSOR_MULTILEVEL</commandClass>
            <COMMAND__CLASS__SENSOR__MULTILEVEL>
              <version>2</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>2</versionSupported>
              <sensors>
                <entry>
                  <multilevelSensorType>TEMPERATURE</multilevelSensorType>
                  <multilevelSensor>
                    <sensorType>TEMPERATURE</sensorType>
                    <initialised>true</initialised>
                  </multilevelSensor>
                </entry>
              </sensors>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__SENSOR__MULTILEVEL>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_BATTERY</commandClass>
            <COMMAND__CLASS__BATTERY>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <batteryLevel>100</batteryLevel>
              <batteryLow>false</batteryLow>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__BATTERY>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_CLOCK</commandClass>
            <COMMAND__CLASS__CLOCK>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
            </COMMAND__CLASS__CLOCK>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_INDICATOR</commandClass>
            <COMMAND__CLASS__INDICATOR>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <isGetSupported>true</isGetSupported>
              <supportedIndicatorsInitialised>true</supportedIndicatorsInitialised>
              <supportedIndicators/>
            </COMMAND__CLASS__INDICATOR>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_VERSION</commandClass>
            <COMMAND__CLASS__VERSION>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>1</versionSupported>
              <libraryType>LIB_SLAVE_ENHANCED</libraryType>
              <protocolVersion>3.28</protocolVersion>
              <applicationVersion>8.7</applicationVersion>
            </COMMAND__CLASS__VERSION>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_THERMOSTAT_MODE</commandClass>
            <COMMAND__CLASS__THERMOSTAT__MODE>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>2</versionSupported>
              <modeTypes>
                <modeType>HEAT</modeType>
                <modeType>COOL</modeType>
                <modeType>OFF</modeType>
              </modeTypes>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__THERMOSTAT__MODE>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_THERMOSTAT_SETPOINT</commandClass>
            <COMMAND__CLASS__THERMOSTAT__SETPOINT>
              <version>1</version>
              <instances>1</instances>
              <control>false</control>
              <versionSupported>2</versionSupported>
              <setpoints>
                <entry>
                  <setpointType>COOLING</setpointType>
                  <setpoint>
                    <setpointType>COOLING</setpointType>
                    <initialised>true</initialised>
                    <initCount>0</initCount>
                    <outer-class reference="../../../.."/>
                  </setpoint>
                </entry>
                <entry>
                  <setpointType>HEATING</setpointType>
                  <setpoint>
                    <setpointType>HEATING</setpointType>
                    <initialised>true</initialised>
                    <initCount>0</initCount>
                    <outer-class reference="../../../.."/>
                  </setpoint>
                </entry>
              </setpoints>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__THERMOSTAT__SETPOINT>
          </entry>
        </supportedCommandClasses>
      </endPoint>
    </entry>
  </endpoints>
  <nodeNeighbors>
    <int>4</int>
    <int>6</int>
    <int>7</int>
  </nodeNeighbors>
  <lastReceived>2018-09-25 17:44:36.144 UTC</lastReceived>
</node>

I also put the Zwave binding in debug mode and captured the log, I viewed in the log viewer but not really sure what I am looking at.

17:20:53.911	5	
TX REQ SendData 2 Zero length frame in command class  ACK AUTO_ROUTE
17:20:53.933	5	
RX RES SendData 2 ACCEPTED BY CONTROLLER 0 /128
17:20:54.268	5	
RX REQ ApplicationCommandHandler SENSOR_MULTI_LEVEL_REPORT TEMPERATURE=42 0 /128
17:20:54.314	5	
STATE UPDATE zwave:device:0001:node5 8-09-25 17:20:54.314 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:0001:node5:
17:20:54.351	5	
TX REQ SendData 2 Zero length frame in command class  ACK AUTO_ROUTE
17:20:54.399	5	
RX RES SendData 2 ACCEPTED BY CONTROLLER 0 /128
17:20:59.502	5	
TX REQ SendData 3 Zero length frame in command class  ACK AUTO_ROUTE
17:20:59.509	5	
RX RES SendData 3 ACCEPTED BY CONTROLLER 0 /128
17:20:59.941	5	
RX REQ ApplicationCommandHandler THERMOSTAT_SETPOINT_REPORT TYPE=2 SCALE=1 0 /128
17:20:59.972	5	
STATE UPDATE zwave:device:0001:node5 8-09-25 17:20:59.972 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:0001:node5:
17:21:00.004	5	
TX REQ SendData 3 Zero length frame in command class  ACK AUTO_ROUTE
17:21:00.016	5	
RX RES SendData 3 ACCEPTED BY CONTROLLER 1 /128
17:21:00.299	5	
RX REQ ApplicationCommandHandler THERMOSTAT_SETPOINT_REPORT TYPE=1 SCALE=1 0 /128
17:21:00.323	5	
STATE UPDATE zwave:device:0001:node5 8-09-25 17:21:00.323 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:0001:node5:
17:21:00.344	5	
TX REQ SendData 2 Zero length frame in command class  ACK AUTO_ROUTE
17:21:00.351	5	
RX RES SendData 2 ACCEPTED BY CONTROLLER 0 /128
17:21:00.688	5	
RX REQ ApplicationCommandHandler THERMOSTAT_FAN_MODE_REPORT 0 /128
17:21:00.700	5	
STATE UPDATE zwave:device:0001:node5 8-09-25 17:21:00.700 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:0001:node5:
17:21:00.715	5	
TX REQ SendData 2 Zero length frame in command class  ACK AUTO_ROUTE
17:21:00.721	5	
RX RES SendData 2 ACCEPTED BY CONTROLLER 0 /128

I don’t know if the zero length frame in command class messages are a problem or not.

The pretty version:

I have exhausted all the documentation I have found, nothing seems to point me to a solution for this. It used to work perfectly and now I only have control of the fan and the modes. Obviously the set points are the critical aspect with a thermostat.

Please can you provide the raw log - the log above is, well, I don’t really know what it is other than it’s been heavily filtered and modified :wink: . The pretty version is useful, but I need the real log so I can process it myself and find out what is happening.

etedEvent
2018-09-28 13:32:02.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-09-28 13:32:02.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-09-28 13:32:02.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:02.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-09-28 13:32:02.319 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 44 02 25 13 92
2018-09-28 13:32:02.319 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 44 02 25 13 92
2018-09-28 13:32:02.320 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-09-28 13:32:02.321 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 568: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 19
2018-09-28 13:32:02.322 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-09-28 13:32:02.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-09-28 13:32:02.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-09-28 13:32:02.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 568: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 19
2018-09-28 13:32:02.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-09-28 13:32:02.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:02.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-09-28 13:32:02.325 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-09-28 13:32:02.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:02.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:02.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 568: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 19
2018-09-28 13:32:02.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-09-28 13:32:02.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 568: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 19
2018-09-28 13:32:02.329 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:02.329 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: sentData successfully placed on stack.
2018-09-28 13:32:02.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 568: Advanced to WAIT_REQUEST
2018-09-28 13:32:02.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 568: Transaction not completed
2018-09-28 13:32:02.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:02.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-09-28 13:32:02.417 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 13 00 FA
2018-09-28 13:32:02.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=19, payload=13 00
2018-09-28 13:32:02.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=19, payload=13 00
2018-09-28 13:32:02.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 568: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 19
2018-09-28 13:32:02.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-09-28 13:32:02.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 568: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 19
2018-09-28 13:32:02.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 568: (Callback 19)
2018-09-28 13:32:02.420 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-09-28 13:32:02.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 568: callback 19
2018-09-28 13:32:02.421 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=19, payload=13 00
2018-09-28 13:32:02.421 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 19, Status = Transmission complete and ACK received(0)
2018-09-28 13:32:02.422 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2018-09-28 13:32:02.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 568: Advanced to WAIT_DATA
2018-09-28 13:32:02.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 568: Transaction not completed
2018-09-28 13:32:02.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:02.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-09-28 13:32:02.726 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 44 03 00 B3
2018-09-28 13:32:02.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 03 44 03 00
2018-09-28 13:32:02.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 03 44 03 00
2018-09-28 13:32:02.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-09-28 13:32:02.729 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2018-09-28 13:32:02.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2018-09-28 13:32:02.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_THERMOSTAT_FAN_MODE, endpoint 0
2018-09-28 13:32:02.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY not supported
2018-09-28 13:32:02.730 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_THERMOSTAT_FAN_MODE V1 THERMOSTAT_FAN_MODE_REPORT
2018-09-28 13:32:02.730 [DEBUG] [s.ZWaveThermostatFanModeCommandClass] - NODE 5: Thermostat Fan Mode report value = 0
2018-09-28 13:32:02.730 [DEBUG] [s.ZWaveThermostatFanModeCommandClass] - NODE 5: Thermostat Fan Mode Report value = Auto Low
2018-09-28 13:32:02.731 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-09-28 13:32:02.731 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_THERMOSTAT_FAN_MODE, value = 0
2018-09-28 13:32:02.732 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:0001:node5:thermostat_fanmode to 0 [DecimalType]
2018-09-28 13:32:02.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
2018-09-28 13:32:02.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@39a6d725.
2018-09-28 13:32:02.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@39a6d725.
2018-09-28 13:32:02.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:568 DONE
2018-09-28 13:32:02.736 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-09-28 13:32:02.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-09-28 13:32:02.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-09-28 13:32:02.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:02.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-09-28 13:32:02.737 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 80 02 25 14 51
2018-09-28 13:32:02.738 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 80 02 25 14 51
2018-09-28 13:32:02.744 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-09-28 13:32:02.746 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-09-28 13:32:02.746 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-09-28 13:32:02.747 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-09-28 13:32:02.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 569: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 20
2018-09-28 13:32:02.749 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-09-28 13:32:02.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 569: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 20
2018-09-28 13:32:02.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-09-28 13:32:02.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:02.756 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-09-28 13:32:02.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:02.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:02.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 569: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 20
2018-09-28 13:32:02.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-09-28 13:32:02.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 569: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 20
2018-09-28 13:32:02.758 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:02.759 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: sentData successfully placed on stack.
2018-09-28 13:32:02.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 569: Advanced to WAIT_REQUEST
2018-09-28 13:32:02.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 569: Transaction not completed
2018-09-28 13:32:02.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:02.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-09-28 13:32:02.836 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 14 00 FD
2018-09-28 13:32:02.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=20, payload=14 00
2018-09-28 13:32:02.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=20, payload=14 00
2018-09-28 13:32:02.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 569: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 20
2018-09-28 13:32:02.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-09-28 13:32:02.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 569: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 20
2018-09-28 13:32:02.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 569: (Callback 20)
2018-09-28 13:32:02.839 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-09-28 13:32:02.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 569: callback 20
2018-09-28 13:32:02.840 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=20, payload=14 00
2018-09-28 13:32:02.840 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 20, Status = Transmission complete and ACK received(0)
2018-09-28 13:32:02.841 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2018-09-28 13:32:02.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 569: Advanced to WAIT_DATA
2018-09-28 13:32:02.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 569: Transaction not completed
2018-09-28 13:32:02.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:02.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-09-28 13:32:03.132 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 80 03 64 13
2018-09-28 13:32:03.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 03 80 03 64
2018-09-28 13:32:03.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 03 80 03 64
2018-09-28 13:32:03.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-09-28 13:32:03.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2018-09-28 13:32:03.137 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2018-09-28 13:32:03.138 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0
2018-09-28 13:32:03.139 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY not supported
2018-09-28 13:32:03.140 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT
2018-09-28 13:32:03.140 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 5: Battery report value = 100
2018-09-28 13:32:03.141 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-09-28 13:32:03.142 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BATTERY, value = 100
2018-09-28 13:32:03.143 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:0001:node5:battery-level to 100 [DecimalType]
2018-09-28 13:32:03.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
2018-09-28 13:32:03.147 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@156d34b6.
2018-09-28 13:32:03.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@156d34b6.
2018-09-28 13:32:03.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:569 DONE
2018-09-28 13:32:03.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-09-28 13:32:03.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-09-28 13:32:03.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-09-28 13:32:03.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:03.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-09-28 13:32:03.151 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 13 05 05 43 01 01 01 45 25 15 D7
2018-09-28 13:32:03.151 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0C 00 13 05 05 43 01 01 01 45 25 15 D7
2018-09-28 13:32:03.154 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-09-28 13:32:03.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-09-28 13:32:03.157 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-09-28 13:32:03.158 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-09-28 13:32:03.158 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 540: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 21
2018-09-28 13:32:03.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:03.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-09-28 13:32:03.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 540: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 21
2018-09-28 13:32:03.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-09-28 13:32:03.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:03.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 540: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 21
2018-09-28 13:32:03.170 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-09-28 13:32:03.170 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 540: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 21
2018-09-28 13:32:03.171 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-09-28 13:32:03.172 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: sentData successfully placed on stack.
2018-09-28 13:32:03.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 540: Advanced to WAIT_REQUEST
2018-09-28 13:32:03.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 540: Transaction not completed
2018-09-28 13:32:03.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:03.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-09-28 13:32:03.244 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 15 00 FC
2018-09-28 13:32:03.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=21, payload=15 00
2018-09-28 13:32:03.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=21, payload=15 00
2018-09-28 13:32:03.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 540: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 21
2018-09-28 13:32:03.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-09-28 13:32:03.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 540: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 21
2018-09-28 13:32:03.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 540: (Callback 21)
2018-09-28 13:32:03.248 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-09-28 13:32:03.249 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 540: callback 21
2018-09-28 13:32:03.249 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=21, payload=15 00
2018-09-28 13:32:03.249 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 21, Status = Transmission complete and ACK received(0)
2018-09-28 13:32:03.250 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2018-09-28 13:32:03.250 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 540: Transaction COMPLETED
2018-09-28 13:32:03.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Response processed after 92ms
2018-09-28 13:32:03.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 540: Transaction completed
2018-09-28 13:32:03.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:540 DONE
2018-09-28 13:32:03.255 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-09-28 13:32:03.255 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-09-28 13:32:03.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Is this enough of it to work with? - I just changed the cool setpoint and the heat setpoint.

Did you get the right part of the log? I don’t see any setpoint commands in this log…

I was interested in the log you posted above which has all sorts of strange stuff in it - 0 length frames, and other strange corruption. Is this real, or is it an artefact of some processing you did to the log before viewing it?

The one above was before I turned on the debug mode. It is a real log of what was happening. Is there somewhere I can upload the whole file, I can give you the entire log rather than pasting it in. - I have it in debug mode for the zwave binding at the moment.

It’s very strange - it clearly has debug enabled, or there would be nothing showing, but it looks corrupted as there are lines extending into places that should never happen.

Anyway, if this is real, then I’d like to see this as something is very wrong :confused:.

There are many places on the net - you just need to find one (eg dropbox, github, icloud…).

– Link removed –

My guess is that problem is the commands are not formatted correctly…

Normally, there is a degree symbol in the command - like you see in the state update below -:

However, in your commands, it’s different -:

The binding is not getting the unit from this, so it is using degC, and this is likely then being rejected by the thermostat.

1 Like

Maybe the first one looked strange because I had copy pasted into a file on my Mac, not sure but I can tell you that I certainly didn’t make it up. - That’s what I see in my logs. I don’t think it was in DEBUG mode or each line would have had [DEBUG] in front like the current one does. I didn’t remove the tags. - The file I have linked to is just the openhab.log as it appears at this time in my /var/log/openhab/ directory.

OK, let me see if I can put a degree symbol in there. I do have my default units set to imperial.

You sir are a freakin’ genius!!! - That’ has completely solved the problem.
In case anyone is reading this to solve their own issue to get the degree symbol on a Mac you type option+shift+8

1 Like

Well, if it wasn’t debug, then your “pretty printed” version would have nothing in it at all. I’m not suggesting that you “made it up” just that somehow it got corrupted. eg -:


This is clearly a messed up log - there is probably a return missing, so the second line is printed on the end of the first. Clearly this is not correct though.

I don’t know what these are -:


Again, I suspect that they are corrupted logs rather than a major problem with the binding, but I don’t know.

Obviously this is a debug log or these lines would simply not be here as the transmit and receive data is only logged at debug level.

Honestly, I don’t think it was in debug level as I only turned it on once and since I did everything has [DEBUG] on the line however, it may have got messed up when I copy and pasted it into TextEdit on my Mac. I did that because where I was at the time, I did not have SFTP access to the server. Like you, I don’t think there is anything wrong with the binding as I am able to use all my other devices and the Fan and Thermostat mode from here. You were bang on when you said that it was the degree symbol, who knew that would make such a big difference but it certainly did. I really appreciate your excellent assistance @chris without you I think the zwave stuff is a non-starter. I know you are super busy but you always seem to make time to help us lesser mortals out. :smiley:

2 Likes

IanJ - I think I have a similar problem. Where are you putting the degree symbol?