Nest Binding - API Return Code

@wborn

Is there a way for a Rule to inspect the latest Nest API return code (e.g., a channel on the structure or device)? I know that I can check the openHAB log to see when warnings or errors have occurred, but I want to check in the Rule whether a requested action (e.g., setpoint change) completed successfully. I want to implement some sort of retry mechanism.

Thanks.

Mike

If there isn’t (and I suspect there is not or else there would be a Channel for that) you could use the LogReader Binding to watch for those warnings in the logs and update an Item when they occur.

Thanks Rich.

I’m confused by the search pattern documentation. I’d want to look for “WARN” and “NestBridgeHandler” and I’d want a separate Thing for outright Nest errors (“ERROR” and “NestBridgeHandler”). Is the asterisk the wildcard (I don’t get the greedy/reluctant/possessive distinction)? In other words, something like this: "WARN*NestBridgeHandler"

Is that the correct syntax?

Mike

I don’t use this binding myself but I know it is using Regular Expressions.

In Regular Expressions * means "the previous pattern 0 or more times. So to define what you appear to be after you would use .*. The . means any character and the * will make it match any character 0 or more times. The greedy/reluctant/possessive will control how the .* expands across the String.

Google for regular expression tutorial for details on how to construct regular expressions. It is essentially a language unto itself.

There is no such way since it’s currently only logged.

Maybe you can check if the channel state has the expected value with a timer?

Wouter,

I guess the real issue is that the openHAB Item value is left at the “updated” value even though the Nest API did not complete the action successfully.

|2019-02-17 21:32:38.604|current Min = 72.0, current Max = 75.0
|2019-02-17 21:32:38.658|new Min = 71.0, new Max = 74.0
|2019-02-17 21:32:38.684|Item 'TargetTemperatureMin' received command 71.0
|2019-02-17 21:32:38.705|TargetTemperatureMin predicted to become 71.0
|2019-02-17 21:32:39.141|Nest API error: blocked
|2019-02-17 21:32:40.486|Item 'TargetTemperatureMax' received command 74.0
|2019-02-17 21:32:40.499|TargetTemperatureMax predicted to become 74.0
|2019-02-17 21:32:40.780|Nest API error: Cannot set target temperature closer than 3.0 degrees F
|2019-02-17 21:47:20.085|current Min = 71.0, current Max = 74.0
|2019-02-17 21:47:20.135|new Min = 72.0, new Max = 75.0

Rule invocation at 21:32

  • Sends request to change the Min to 71 (via item.sendCommand(value))
  • This request fails because it was blocked due to exceeded API data rate (too many changes in an hour - surprisingly low threshold). I am addressing this.
  • The Rule requests to change the Max to 74 (via item.sendCommand(value))
  • Expecting the Min to already be lowered to 71, this change fails too because Nest still sees the Min at 72. Thus 72-74 does not have the required 3 degrees separation.
  • Neither setpoint is changed.

Next Rule invocation at 21:47

  • State for both Items show the values which were not actually set (71/74).
  • Requested new changes complete without API errors and openHAB Items reflect the thermostat settings.

Items
These are Items linked to the Nest thermostat setpoint channels (see links below)

Number:Temperature TargetTemperatureMax "Target Temperature Max [%.1f %unit%]"
Number:Temperature TargetTemperatureMin "Target Temperature Min [%.1f %unit%]"

Relevant Links
I snipped the other channels/links from the REST output for brevity

  {
    "statusInfo": {
      "status": "ONLINE",
      "statusDetail": "NONE"
    },
    "editable": true,
    "label": "Hallway Thermostat (Home Thermostat)",
    "bridgeUID": "nest:account:<account>",
    "configuration": {
      "deviceId": "<deviceID>"
    },
    "properties": {
      "firmwareVersion": "5.9.3-6",
      "vendor": "Nest"
    },
    "UID": "nest:thermostat:<account>:<deviceID>",
    "thingTypeUID": "nest:thermostat",
    "channels": [
      {
        "linkedItems": [
          "TargetTemperatureMax"
        ],
        "uid": "nest:thermostat:<account>:<deviceID>:max_set_point",
        "id": "max_set_point",
        "channelTypeUID": "nest:MaxSetPoint",
        "itemType": "Number:Temperature",
        "kind": "STATE",
        "label": "Max Set Point",
        "description": "The max set point temperature",
        "defaultTags": [],
        "properties": {},
        "configuration": {}
      },
      {
        "linkedItems": [
          "TargetTemperatureMin"
        ],
        "uid": "nest:thermostat:<account>:<deviceID>:min_set_point",
        "id": "min_set_point",
        "channelTypeUID": "nest:MinSetPoint",
        "itemType": "Number:Temperature",
        "kind": "STATE",
        "label": "Min Set Point",
        "description": "The min set point temperature",
        "defaultTags": [],
        "properties": {},
        "configuration": {}
      },
    ],
    "location": "Hallway"
  }

Mike

Configuring the Item with autoupdate=false might work in this case. That causes OH to not change the state of the Item in response to a command and instead wait for the device/binding to report back that the command was realized.

What I don’t know is whether the Nest binding gets a response back when the target temp changes or whether you need to wait for the next polling period.

If I change autoupdate to false, the question is whether the binding updates the item when the operation is completed and only after it has confirmed a successful operation return code from the API. Let’s see what @wborn responds with wrt how the Nest binding treats this scenario.

As for how to set the autoupdate setting for an Item… since I am performing the links for the Nest binding via PaperUI, must I also make the autoupdate settings in the same manner or can I do this in the .items file (since I am not specifying the binding/channel in the .items file)? I assume that “Veto” in PaperUI corresponds to autoupdate=false (just to be certain).

Mike

I think you will have to remove the links and Items from PaperUI, then define the Item in .items file with the link and autoupdate=false defined there. I don’t know if there is a way to configure autoupdate=false through PaperUI.

Never mind, it’s there on the Item in PaperUI. However, I don’t know how it works with the link defined in PaperUI and the Item defined in a .items file. You will have to experiment.

I did some brief testing and it seems to work as expected. If you use an item with autoupdate=false it will only update when commands are accepted by the Nest API which results in an immediate update (because the binding uses the streaming REST API).

In Paper UI it seems to be called “Veto an auto update” when editing an item:

Thanks Wouter. Then, for ALL Nest “write” channels, it seems that auto update ought to be set to false (i.e., veto auto updates) so that the Item only reflects the value after the API successfully completes and the binding can update the value accordingly; yes?

Mike

Yes you’ll need that if you only want the values to be updated when they have been properly handled by the Nest API.

I changed the Nest Min & Max setpoint Items to not autoupdate (using Veto in PaperUI). It resolved some of the issues… but there are times when it seems to go ahead and update the Item even though there has been an API error. The instances where the Item is “predicted to become” is when the Items end up being changed even though the API blocked the change.

  • “current” - the value of the Items output to the log via logInfo in my Rule
  • “new” - the value that is going to be requested (via 'setpointItem'.setCommand(value)) output to the log via logInfo in my Rule
  • received command”, “predicted to become”, “Nest API error” - log messages resulting from openHAB actions (i.e., not output by my Rule code)

In the log output below, I added the single quotes around “predicted to become” to highlight those lines.

|2019-02-22 07:22:32.780|Running Rule
|2019-02-22 07:22:32.874|current Min = 71.0, current Max = 75.0
|2019-02-22 07:22:32.921|new Min = 72.0, new Max = 76.0
|2019-02-22 07:22:32.945|Item 'TargetTemperatureMax' received command 76.0
|2019-02-22 07:22:33.506|Nest API error: blocked
|2019-02-22 07:22:34.720|Item 'TargetTemperatureMin' received command 72.0
|2019-02-22 07:22:34.729|TargetTemperatureMin 'predicted to become' 72.0
|2019-02-22 07:22:35.013|Nest API error: blocked

|2019-02-22 07:24:02.489|Running Rule
|2019-02-22 07:24:02.627|current Min = 72.0, current Max = 75.0
|2019-02-22 07:24:02.672|new Min = 73.0, new Max = 76.0
|2019-02-22 07:24:02.695|Item 'TargetTemperatureMax' received command 76.0
|2019-02-22 07:24:02.970|Nest API error: blocked
|2019-02-22 07:24:04.483|Item 'TargetTemperatureMin' received command 73.0
|2019-02-22 07:24:04.495|TargetTemperatureMin 'predicted to become' 73.0
|2019-02-22 07:24:04.740|Nest API error: Cannot set target temperature closer than 3.0 degrees F

|2019-02-22 07:27:32.911|Running Rule
|2019-02-22 07:27:33.004|current Min = 73.0, current Max = 75.0
...

I could implement a kludge using logReader to trigger a Rule for me to handle the situation… but the “not always updated” issue is not consistent. Plus, it would be a kludge that likely has an explanation or a solution.

Please advise as to what may be occuring with the “predicted to become” instances that is causing the values to be updated improperly.

Thank you!

Mike

P.S. Yes, I am still working on handling the API data rate limit… but it’s actually not impacting the automation in that it later “catches up”. Having the values not reflect the actual setting on the thermostat is causing the logic to make incorrect decisions on modifying the setpoints. This is an issue with how this automation is operating.

For me it never updates commands that are blocked by Nest with autoupdate=false. Maybe you have a rule that updates an item instead of sending a command to it? Those will still succeed with autoupdate=false.

The code performs all updates in one rule and within one Lambda. A sendCommand or postUpdate is not performed in any other Rule neither in this rules file nor any other. Below is the code. I have removed most of my logging code and simplified the Rule itself (handling only one scenario) so you can see the calling mechanisms. The reason I broke it out into Lambdas was because there was similar code that did the checks to know to set Max before Min or vice versa as well as checking for 3 degrees of separation. With the rule “expanded” to handle different ambient vs. sensor readings, this “Lambda” code consolidates similar logic.

Let me turn on debugging to see if that provides any clues.

val Procedures.Procedure2<String,Number>
        setTemperatureSetpoint = [  String sSetpoint,
                                    Number nSetpointValue |
    try
    {
        APIRateThrottled.postUpdate(ON)
        setpointAdjusted.postUpdate(ON)
        if (sSetpoint.toUpperCase.contains("MIN"))
            TargetTemperatureMin.sendCommand((nSetpointValue).doubleValue)
        else
            TargetTemperatureMax.sendCommand((nSetpointValue).doubleValue)

        TargetSetTemperature.postUpdate((nSetpointValue).doubleValue)
        TargetSet.postUpdate(sSetpoint)
    }
    catch(Exception e)
    {
        logError("myLog", "Failure in setTemperatureSetpoint: {}", e.toString)
    }
]

val Procedures.Procedure3<Number,Number,Procedures.Procedure2<String,Number>>
        setTemperatureSetpoints = [ Number nSetpointMin,
                                    Number nSetpointMax,
                                    Procedures.Procedure2<String,Number> pSetTemperatureSetpoint |
    try
    {
        var setpointMin = (nSetpointMin).doubleValue
        var setpointMax = (nSetpointMax).doubleValue

        val thermMin = (TargetTemperatureMin.state as QuantityType<Number>).doubleValue
        val thermMax = (TargetTemperatureMax.state as QuantityType<Number>).doubleValue

        if (setpointMin < thermMin)  // Heating setpoint is being lowered, change it first to ensure that delta remains above required thermostat minimum
        {
            if ((setpointMax - setpointMin) < 3) setpointMax = setpointMin + 3
            pSetTemperatureSetpoint.apply("Min", setpointMin)
            if (setpointMax != thermMax) // If the Cooling setpoint is also changing
                createTimer(now.plusMillis(1750)) [ |
                    if (TargetSetTemperature.state == TargetTemperatureMin.state)
                        pSetTemperatureSetpoint.apply("Max", setpointMax)
                    else
                        logWarn("myLog", "setTemperatureSetpoint - Not changing Max.")
                ]
        }
        else
        {
            if ((setpointMax - setpointMin) < 3) setpointMin = setpointMax - 3

            if (setpointMax != thermMax) // Cooling setpoint is changing
            {
                pSetTemperatureSetpoint.apply("Max", setpointMax)
                if (setpointMin > thermMin) // If the Heating setpoint is also changing
                    createTimer(now.plusMillis(1750)) [ |
                        if (TargetSetTemperature.state == TargetTemperatureMax.state)
                            pSetTemperatureSetpoint.apply("Min", setpointMin)
                        else
                            logWarn("myLog", "setTemperatureSetpoint - Not changing Min.")
                    ]
            }
            else
                if (setpointMin > thermMin)  // If the Heating setpoint is changing
                    pSetTemperatureSetpoint.apply("Min", setpointMin)
        }
    }
    catch(Exception e)
    {
        logError("myLog", "Failure in setTemperatureSetpoints: {}", e.toString)
    }
]

rule "Temperature Sensor Adjust"
    when
        Member of gTemperature received update  // When a sensor has been triggered to send a reading
    then
        val String itemName = triggeringItem.name.toString
        val sensorTemperature = Math::round(((gTemperature.members.filter [sensorItem | sensorItem.name == itemName].head.state) as Number).doubleValue)
        val thermMin = (TargetTemperatureMin.state as QuantityType<Number>).doubleValue
        val thermMax = (TargetTemperatureMax.state as QuantityType<Number>).doubleValue
        val thermTemperature  = (AmbientTemperature.state as QuantityType<Number>).doubleValue
        val temperatureDelta = thermTemperature - sensorTemperature

        setTemperatureSetpoints.apply   (
                    thermMin + temperatureDelta,
                    thermMax + temperatureDelta,
                    setTemperatureSetpoint
                                                )
end

Mike

Maybe you can enable debug logging on the binding to see if/when those values are received by Nest?

Wouter,

I turned DEBUG on yesterday after my previous message…

Updates in succeeding post.

Mike

02/23/2019 Update: I fire off a 1750ms timer after the sendCommand for the first setpoint change. When the timer expires, I issue the second sendCommand for the other setpoint. Apparently, occasionally 1750ms is not long enough for the operation to complete. In the case below, it took 2.448 seconds to complete.

2019-02-23 20:49:21.030 [ItemCommandEvent]	Item 'TargetTemperatureMax' received command 76.0
2019-02-23 20:49:21.041 [NestBridgeHandler]	PUT content: {"target_temperature_high_f":76}
2019-02-23 20:49:21.046 [NestBridgeHandler]	Re-using access token from configuration: c.'access token'
2019-02-23 20:49:23.478 [NestBridgeHandler]	PUT response: {"target_temperature_high_f":76}

I have made my “delay” smarter by waiting in 250ms increments up to a maximum of 3 seconds (for now). If it hasn’t successfully made the change after 3 seconds, then I raise a warning and abort any subsequent corresponding setpoint change. This is better, but it didn’t catch every problem (see log in update below).

val Functions.Function2<String,Number,Boolean>
        setTemperatureSetpoint = [  String sSetpoint,
                                    Number nSetpointValue |
    try
    {
        APIRateThrottled.postUpdate(ON)
        setpointAdjusted.postUpdate(ON)

        var itemName = "TargetTemperatureMax"
        if (sSetpoint.toUpperCase.contains("MIN"))
            itemName = "TargetTemperatureMin"

        val setpointItem = gTempSetpoints.members.filter [ i | (i.name == itemName) ].head
        setpointItem.sendCommand((nSetpointValue).doubleValue)

        // Loop counter waiting for the setpoint change to complete
        // 12 loops of 250ms is 3 seconds
        var iSetpointWaitLoop = 12
        while((iSetpointWaitLoop=iSetpointWaitLoop-1) >= 0)
        {
            Thread::sleep(250)
            if ((nSetpointValue).doubleValue == (setpointItem.state as QuantityType<Number>).doubleValue)
            {
                logInfo    ("myLog", "setTemperatureSetpoint - Delay loop counter down to {}.", iSetpointWaitLoop)
                APIRateThrottled.postUpdate(ON)
                setpointAdjusted.postUpdate(ON)
                TargetSetTemperature.postUpdate((nSetpointValue).doubleValue)
                TargetSet.postUpdate(sSetpoint)
                return true
            }
        }

        logWarn("myLog", "setTemperatureSetpoint - {} set unsuccessful.", sSetpoint)
        return false
    }
    catch(Exception e)
    {
        logError("myLog", "Failure in setTemperatureSetpoint: {}", e.toString)
        return null
    }
]

This looping delay waiting for the Item value to correspond to the requested change isn’t catching all API error instances. The looping counter does vary. I’ve seen the “counter down to” values range between 5 and 11. I don’t have but a couple of instances, but I think this “wait for the requested value to match the Item value” fails when and API error occurs and the Item is “predicted to become”. The predicted events don’t always occur when a setCommand is performed. For those instances where an API occurs and there is not “predicted” instance, the “wait for match” works fine. I have no idea how to detect the difference in how sendCommand processes (when it’s predicted and when the Item just receives it in one step).

In the instance below, the API error did not actually come back until about a tenth after the matching detector thought it matched. Since I was not able to detect the first setpoint not being set, the second one failed due to failing the 3 degree gap.

02/24/2019 Update:

2019-02-24 15:12:31.947	[ItemCommandEvent]	Item 'TargetTemperatureMin' received command 71.0
2019-02-24 15:12:31.952	[ItemStatePredictedEvent]	TargetTemperatureMin predicted to become 71.0
2019-02-24 15:12:31.952	[NestBridgeHandler]	Putting data to: https://firebase-apiserver35-tah01-iad01.dapi.production.nest.com:9553/devices/thermostats/,deviceID>
2019-02-24 15:12:31.957	[NestBridgeHandler]	PUT content: {"target_temperature_low_f":71}
2019-02-24 15:12:31.960	[NestBridgeHandler]	Re-using access token from configuration: c.<accessToken>
2019-02-24 15:12:32.198		setTemperatureSetpoint	Delay loop counter down to 11.
2019-02-24 15:12:32.244	[ItemCommandEvent]	Item 'TargetTemperatureMax' received command 74.0
2019-02-24 15:12:32.333	[NestBridgeHandler]	PUT response: {"error":"blocked","type":"https://developer.nest.com/documentation/cloud/error-messages#blocked","message":"blocked","instance":"f9000f9b-d12e-4198-af12-5d6cc2297ec1"}
2019-02-24 15:12:32.335	[NestBridgeHandler]	Nest API error: ErrorData [error=blocked, type=https://developer.nest.com/documentation/cloud/error-messages#blocked, message=blocked, instance=f9000f9b-d12e-4198-af12-5d6cc2297ec1]
2019-02-24 15:12:32.337	[NestBridgeHandler]	Nest API error: blocked
2019-02-24 15:12:32.339	[NestBridgeHandler]	Putting data to: https://firebase-apiserver35-tah01-iad01.dapi.production.nest.com:9553/devices/thermostats/<deviceID>
2019-02-24 15:12:32.341	[NestBridgeHandler]	PUT content: {"target_temperature_high_f":74}
2019-02-24 15:12:32.343	[NestBridgeHandler]	Re-using access token from configuration: c.<accessToken>
2019-02-24 15:12:32.599	[NestBridgeHandler]	PUT response: {"error":"Cannot set target temperature closer than 3.0 degrees F","type":"https://developer.nest.com/documentation/cloud/error-messages#range-error","message":"Cannot set target temperature closer than 3.0 degrees F","instance":"fe3f1651-5550-4e7d-93e3-34fcd7068682","details":{"min":"3.0","scale":"F"}}
2019-02-24 15:12:32.602	[NestBridgeHandler]	Nest API error: ErrorData [error=Cannot set target temperature closer than 3.0 degrees F, type=https://developer.nest.com/documentation/cloud/error-messages#range-error, message=Cannot set target temperature closer than 3.0 degrees F, instance=fe3f1651-5550-4e7d-93e3-34fcd7068682]
2019-02-24 15:12:32.605	[NestBridgeHandler]	Nest API error: Cannot set target temperature closer than 3.0 degrees F

Mike

Do you also have logging where we can see the channel updates and JSON updates received by the NestStreamingRestClient? That logging would show when what updates are received from Nest by the binding and how these are handled.

Wouter,

Is that logger defined? I looked at org.ops4j.pax.logging.cfg and only saw NestBridgeHandler. Can you send me the full name of the NestStreamingRestClient facility. I can then add that definition to the logging configuration and turn on DEBUG level messages.

Mike