core: Honeywell TCC error when adjusting settings

@mrsnyds : Please create a new issue for this one - it’s not related to this issue at all.

Im not able to test it until the weekend. I’ll let u know how it goes on Saturday.

I made a slight change - added the following so we get the also log when content_type is 'text/html; charset=utf-8' and only on calls to change the temp - make sense?

if resp.status == 200 and req == "/portal/Device/SubmitControlScreenChanges":
   _LOG.debug(f"request json response {resp} with payload {await resp.text()}")

Will send output in a bit.

Sounds good. I’m out for the rest of the day, so I’ll work on it and we can touch base when u get back.

@rdfurman Since I’ve been back its been behaving much better. Only 2 failures. Here’s the details.

Firstly, _resp_json in the version of client.py I’m running is a bit different than what you sent. Not sure why my version is different but it might be a clue to potentially other differences. Here’s the unaltered _resp_json from my client.py - there is no raise error at the end.

    @staticmethod                                                                  
    def _resp_json(resp, req):                                                       
        try:                                                                         
            return resp.json()                                                          
        except:                                                                      
            # Any error doing this is probably because we didn't                          
            # get JSON back (the API is terrible about this).
            _LOG.exception("Failed to de-JSON %s %s" % req, resp)

I modified it to:

    @staticmethod                                            
    def _resp_json(resp, req):                                         
        try:                                                                         
            return resp.json()                                    
        except:                                                  
            # Any error doing this is probably because we didn't     
            # get JSON back (the API is terrible about this).
            _LOG.exception('Response was %s' % resp)                       # Moved before de-JSON msg to get resp before next cmd fails
            _LOG.exception("Failed to de-JSON %s %s" % req, resp)          # This fails, so changed to _LOG.exception("Failed to de-JSON %s %s" % (req, resp))
            raise APIError('Failed to process %s response', req)

Here is an error from the log. You can see the response was <Response [200]>:

2022-12-01 11:30:00.066 ERROR (SyncWorker_6) [somecomfort] AndyLog: data: {'SystemSwitch': None, 'HeatSetpoint': None, 'CoolSetpoint': None, 'HeatNextPeriod': None, 'CoolNextPeriod': 72, 'StatusHeat': None, 'DeviceID': 7039159, 'StatusCool': 1}
2022-12-01 11:30:11.317 ERROR (SyncWorker_6) [somecomfort] Response was <Response [200]>
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/requests/models.py", line 971, in json
    return complexjson.loads(self.text, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/simplejson/__init__.py", line 525, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.10/site-packages/simplejson/decoder.py", line 372, in decode
    obj, end = self.raw_decode(s)
  File "/usr/local/lib/python3.10/site-packages/simplejson/decoder.py", line 402, in raw_decode
    return self.scan_once(s, idx=_w(s, idx).end())
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/somecomfort/client.py", line 429, in _resp_json
    return resp.json()
  File "/usr/local/lib/python3.10/site-packages/requests/models.py", line 975, in json
    raise RequestsJSONDecodeError(e.msg, e.doc, e.pos)
requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2022-12-01 11:30:11.327 ERROR (SyncWorker_6) [somecomfort] Failed to de-JSON /Device/SubmitControlScreenChanges <Response [200]>
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/requests/models.py", line 971, in json
    return complexjson.loads(self.text, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/simplejson/__init__.py", line 525, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.10/site-packages/simplejson/decoder.py", line 372, in decode
    obj, end = self.raw_decode(s)
  File "/usr/local/lib/python3.10/site-packages/simplejson/decoder.py", line 402, in raw_decode
    return self.scan_once(s, idx=_w(s, idx).end())
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/somecomfort/client.py", line 429, in _resp_json
    return resp.json()
  File "/usr/local/lib/python3.10/site-packages/requests/models.py", line 975, in json
    raise RequestsJSONDecodeError(e.msg, e.doc, e.pos)
requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2022-12-01 11:30:11.331 ERROR (SyncWorker_6) [homeassistant.components.honeywell.const] Temperature 69.0 out of range

Interestingly, the call that failed was setting CoolNextPeriod, not CoolSetpoint. Occasionally it does this before setting the CoolSetpoint. I’d like to understand the logic to setting CoolNextPeriod first, it seems random.

Calling CoolNextPeriod does not appear to be (part of) the problem because all other calls were successful. Here are a couple successful runs from the log:

2022-12-01 12:30:00.039 ERROR (SyncWorker_8) [somecomfort] AndyLog: url: https://www.mytotalconnectcomfort.com/portal/Device/SubmitControlScreenChanges
2022-12-01 12:30:00.042 ERROR (SyncWorker_8) [somecomfort] AndyLog: data: {'SystemSwitch': None, 'HeatSetpoint': None, 'CoolSetpoint': None, 'HeatNextPeriod': None, 'CoolNextPeriod': 72, 'StatusHeat': None, 'DeviceID': 7061292, 'StatusCool': 1}
2022-12-01 12:30:00.901 ERROR (SyncWorker_8) [somecomfort] AndyLog: Thermostat Temperature Change Successful
2022-12-01 12:30:00.904 ERROR (SyncWorker_8) [somecomfort] AndyLog: url: https://www.mytotalconnectcomfort.com/portal/Device/SubmitControlScreenChanges
2022-12-01 12:30:00.906 ERROR (SyncWorker_8) [somecomfort] AndyLog: data: {'SystemSwitch': None, 'HeatSetpoint': None, 'CoolSetpoint': 69.0, 'HeatNextPeriod': None, 'CoolNextPeriod': None, 'StatusHeat': None, 'DeviceID': 7061292}
2022-12-01 12:30:01.916 ERROR (SyncWorker_8) [somecomfort] AndyLog: Thermostat Temperature Change Successful
2022-12-01 12:30:01.928 ERROR (SyncWorker_2) [somecomfort] AndyLog: url: https://www.mytotalconnectcomfort.com/portal/Device/SubmitControlScreenChanges
2022-12-01 12:30:01.940 ERROR (SyncWorker_2) [somecomfort] AndyLog: data: {'SystemSwitch': None, 'HeatSetpoint': None, 'CoolSetpoint': 68.0, 'HeatNextPeriod': None, 'CoolNextPeriod': None, 'StatusHeat': None, 'DeviceID': 7039159}
2022-12-01 12:30:02.529 ERROR (SyncWorker_2) [somecomfort] AndyLog: Thermostat Temperature Change Successful

2022-12-01 13:00:00.032 ERROR (SyncWorker_8) [somecomfort] AndyLog: url: https://www.mytotalconnectcomfort.com/portal/Device/SubmitControlScreenChanges
2022-12-01 13:00:00.045 ERROR (SyncWorker_8) [somecomfort] AndyLog: data: {'SystemSwitch': None, 'HeatSetpoint': None, 'CoolSetpoint': 68.0, 'HeatNextPeriod': None, 'CoolNextPeriod': None, 'StatusHeat': None, 'DeviceID': 7061292}
2022-12-01 13:00:00.728 ERROR (SyncWorker_8) [somecomfort] AndyLog: Thermostat Temperature Change Successful
2022-12-01 13:00:00.731 ERROR (SyncWorker_2) [somecomfort] AndyLog: url: https://www.mytotalconnectcomfort.com/portal/Device/SubmitControlScreenChanges
2022-12-01 13:00:00.733 ERROR (SyncWorker_2) [somecomfort] AndyLog: data: {'SystemSwitch': None, 'HeatSetpoint': None, 'CoolSetpoint': 67.0, 'HeatNextPeriod': None, 'CoolNextPeriod': None, 'StatusHeat': None, 'DeviceID': 7039159}
2022-12-01 13:00:01.464 ERROR (SyncWorker_2) [somecomfort] AndyLog: Thermostat Temperature Change Successful

2022-12-01 13:30:00.028 ERROR (SyncWorker_7) [somecomfort] AndyLog: url: https://www.mytotalconnectcomfort.com/portal/Device/SubmitControlScreenChanges
2022-12-01 13:30:00.035 ERROR (SyncWorker_7) [somecomfort] AndyLog: data: {'SystemSwitch': None, 'HeatSetpoint': None, 'CoolSetpoint': 66.0, 'HeatNextPeriod': None, 'CoolNextPeriod': None, 'StatusHeat': None, 'DeviceID': 7061292}
2022-12-01 13:30:00.790 ERROR (SyncWorker_7) [somecomfort] AndyLog: Thermostat Temperature Change Successful

I appreciate your help with this. Let me know your thoughts.

Got it. I’ll test it next week on Dec.1 and post the results. Sorry I can’t test it sooner.

I’m having the exact same problem. I have 2 Honeywell thermostats that I’ve been integrating them into Home assistant. They were both working fine, then one started getting the error below when I try to change the target temp. I suspect as I’ve been testing I’ve exceeded the api rate limit. The thermostat that stopped working is the one I’ve been testing with. In my research I saw one that said the limit resets at midnight guess I’ll know tomorrow. Is anyone familiar w the api rate limit? Do u know how it works?

Here is the error from the logs:

  Logger: somecomfort
  Source: components/honeywell/__init__.py:105 
  First occurred: 8:06:02 PM (1 occurrences) 
  Last logged: 8:06:02 PM
  
  API Rate Limited.

---

UPDATE:

The next day I am able to set the temp on both thermostats, so looks like the api rate limit resets at midnight. Additional Information on the API can be found here: https://developer.honeywellhome.com/

---

UPDATE #2:

Each day the automation updates successfully a few times, then starts getting following error each time it updates. The automation runs every 1/2 hour, and today (3 days after previous update) there is no API Rate Limit error. I am going to dig into the code & will update this post when I have more info. Could be there are actually 2 errors here, API Rate Limit and whatever this one is.

Here is the error in the logs (w/o the trace):

  Logger: homeassistant.components.automation.variable_test
  Source: components/honeywell/climate.py:251
  Integration: Automation ([documentation](https://www.home-assistant.io/integrations/automation), [issues](https://github.com/home-assistant/home-assistant/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+automation%22))
  First occurred: 9:30:00 AM (3 occurrences)
  Last logged: 9:30:00 AM

HVAC 24A Set Temp: Choose at step 1: choice 1: Error executing script. Unexpected error for call_service at pos 2: not enough arguments for format string HVAC 24A Set Temp: Error executing script. Unexpected error for choose at pos 1: not enough arguments for format string While executing automation automation.variable_test

---

UPDATE #3:

client.py calls the Honeywell api to set the temperature, it gets a 200 back and is expecting a json payload, but apparently the payload is not json. Next step, get the values of req & resp. I’m not sure exactly how to do that, so if anyone knows, please let me know.

Here is the offending code:

def _resp_json(resp, req):
    try:
        return resp.json()
    except:
        # Any error doing this is probably because we didn't
        # get JSON back (the API is terrible about this).
        _LOG.exception("Failed to de-JSON %s %s" % req, resp)

---

UPDATE #4

I fixed the error in previous update by changing last line to _LOG.exception("Failed to de-JSON %s %s" % (req, resp)) Now it fails on the result.get(‘success’) line n the following code with the error ‘NoneType’ object has no attribute ‘get’

 def _set_thermostat_settings(self, thermostat_id, settings):
    data = {'SystemSwitch': None,
            'HeatSetpoint': None,
            'CoolSetpoint': None,
            'HeatNextPeriod': None,
            'CoolNextPeriod': None,
            'StatusHeat': None,
            'DeviceID': thermostat_id,
        }
    data.update(settings)
    url = "%s/Device/SubmitControlScreenChanges" % self._baseurl
    with self._retries_login():
        result = self._post_json(url, data=data)
        if result.get('success') != 1:
            raise APIError('API rejected thermostat settings')

So it would seem the post.json command returned nothing.

Also, I bumped Home Assistant stored_traces to 96 last night so this morning I have traces for the last 24 executions. Turns out 5 failed with the above error, 15 successfully changed the target temperature and 4 did not attempt to change the temp setting. I am no longer getting the API Rate Limit error, so I think I can rule out making too many calls to the API. I want to modify the code to print the url and data variables in the log, but haven’t yet figured out how to do this. I will be interesting to see if the calls that fail have different data than those that succeed.

Its also important to note that there is nothing special about the ones that failed. There were other changes that were exactly the same and worked, so I can rule out something specific about the changes that failed.

---

UPDATE #5

Updated the code above to not fail and to print the url and data in the log.

Here is the updated code:

 def _set_thermostat_settings(self, thermostat_id, settings):
    data = {'SystemSwitch': None,
            'HeatSetpoint': None,
            'CoolSetpoint': None,
            'HeatNextPeriod': None,
            'CoolNextPeriod': None,
            'StatusHeat': None,
            'DeviceID': thermostat_id,
        }
    data.update(settings)
    url = "%s/Device/SubmitControlScreenChanges" % self._baseurl             
    _LOG.info ("DEBUG.url: %s" % url)                                           
    _LOG.info ("DEBUG..data: %s" % data)                                         
    with self._retries_login():
        result = self._post_json(url, data=data)
        if result is None:
            raise APIError('API rejected thermostat settings')
        elif result.get('success') != 1:
            raise APIError('API rejected thermostat settings')

It fails gracefully now with the following. So we finally find the real error.

2022-11-16 08:18:11.970 ERROR (SyncWorker_10) [somecomfort] Failed to de-JSON /Device/SubmitControlScreenChanges <Response [200]>
Traceback (most recent call last):
		File "/usr/local/lib/python3.10/site-packages/requests/models.py", line 971, in json
	return complexjson.loads(self.text, **kwargs)
		File "/usr/local/lib/python3.10/site-packages/simplejson/__init__.py", line 525, in loads
	return _default_decoder.decode(s)
		File "/usr/local/lib/python3.10/site-packages/simplejson/decoder.py", line 370, in decode
	obj, end = self.raw_decode(s)
		File "/usr/local/lib/python3.10/site-packages/simplejson/decoder.py", line 400, in raw_decode
	return self.scan_once(s, idx=_w(s, idx).end())
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
		File "/usr/local/lib/python3.10/site-packages/somecomfort/client.py", line 429, in _resp_json
	return resp.json()
		File "/usr/local/lib/python3.10/site-packages/requests/models.py", line 975, in json
	raise RequestsJSONDecodeError(e.msg, e.doc, e.pos)
requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2022-11-16 08:18:11.981 ERROR (SyncWorker_10) [homeassistant.components.honeywell.const] Temperature 68.0 out of range

However its not consistent. There were a number of attempts to change the thermostat’s temperature to 68 that failed, but also 1 that succeeded. The limits on the thermostat were set to 65/80. I updated them to 60/80 just to be sure.