Inferior exception reporting in v2 client

[watchforstock]

I've continued to keep up to date with the more recent commits and all seems to be good here. (Although I see many of them look to be unit test updates that won't be affecting me anyway)

Apart from some 500 Server errors for a period yesterday (presumably due to actual server overloading) I haven't seen any request failures on either API so the session_id/access_token save and restore process seems solid.

On the V1 API polling every 5 minutes it managed to keep the same session id in use for more than a day, it only finally ended up having to get a new one after the 500 Server error outage where it wasn't able to get through for over 15 minutes, causing the session id to time out. And it seamlessly obtained a new session id once the 500 error period was over and maintained that session id until the next >15 minute 500 Server error outage.

The V2 API likewise has been working well, polling every 5 minutes and only having to authenticate once every 30 minutes, and when there is only one authentication per 30 minutes I'm not hitting any rate limiting.

The only thing I've noticed really is the inconsistent exception error reporting between the V1 and V2 API's, where the V1 API recently got new error reporting while the V2 API did not. For example here is rate limiting as reported by both API's:

Traceback (most recent call last):
  File "./evohome_V1", line 9, in <module>
    for device in client.temperatures():
  File "build/bdist.linux-armv6l/egg/evohomeclient/__init__.py", line 117, in temperatures
  File "build/bdist.linux-armv6l/egg/evohomeclient/__init__.py", line 78, in _populate_full_data
  File "build/bdist.linux-armv6l/egg/evohomeclient/__init__.py", line 109, in _populate_user_info
  File "build/bdist.linux-armv6l/egg/evohomeclient/__init__.py", line 197, in _do_request
requests.exceptions.HTTPError: HTTP Status = 429, Response = [
  {
    "code": "TooManyRequests",
    "message": "Request count limitation exceeded, please try again later."
  }
]

pi@pi1monitor:~ $ ./evohome_V2
Traceback (most recent call last):
  File "./evohome_V2", line 6, in <module>
    client = EvohomeClient('**************', '***********')
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 69, in __init__
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 72, in _login
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 193, in user_account
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 79, in _headers
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 116, in _basic_login
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 147, in _obtain_access_token
  File "/usr/local/lib/python2.7/dist-packages/requests/models.py", line 840, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 429 Client Error: Too Many Requests for url: https://tccna.honeywell.com/Auth/OAuth/Token

And here is invalid username/password as reported by both API's:

pi@pi1monitor:~ $ ./evohome_V1
Traceback (most recent call last):
  File "./evohome_V1", line 9, in <module>
    for device in client.temperatures():
  File "build/bdist.linux-armv6l/egg/evohomeclient/__init__.py", line 117, in temperatures
  File "build/bdist.linux-armv6l/egg/evohomeclient/__init__.py", line 78, in _populate_full_data
  File "build/bdist.linux-armv6l/egg/evohomeclient/__init__.py", line 109, in _populate_user_info
  File "build/bdist.linux-armv6l/egg/evohomeclient/__init__.py", line 197, in _do_request
requests.exceptions.HTTPError: HTTP Status = 401, Response = [
  {
    "code": "EmailOrPasswordIncorrect",
    "message": "The email or password provided is incorrect."
  }
]

pi@pi1monitor:~ $ ./evohome_V2
Traceback (most recent call last):
  File "./evohome_V2", line 6, in <module>
    client = EvohomeClient('************', '*********')
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 69, in __init__
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 72, in _login
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 193, in user_account
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 79, in _headers
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 117, in _basic_login
ValueError: Bad Username/Password, unable to continue.

I wonder if it was an oversight for the error reporting on the V2 API not to be updated to the same style the V1 API now uses ?

I'm only using the V1 API in evohome-munin now and I'm just printing the error report pretty much as is from the exception without trying to interpret the fields - the indented json appearance is perfectly readable in a log file:

            try:
                client = EvohomeClient(self.username, self.password, user_data=user_data)
                for device in client.temperatures():
                    data.append(device)
            except Exception as error:
                sys.stderr.write('Connection failed: ' + str(error) + '\n')
                sys.exit(1)

It means I can leave debugging off but if there is an error a proper error report with the cause of the error (instead of my previous generic server connection error) will appear in the log which is nice and is what allowed me to see that the failures I got yesterday were 500 Server errors, not 429 rate limiting or 401 authentication errors.

Originally posted by @DBMandrake in https://github.com/watchforstock/evohome-client/pull/80#issuecomment-470451300

[watchforstock]

I've separated out this issue as the previous thread was about a different topic. I want to draw a line under the other work and we can track fixing this separately.

[DBMandrake]

Fair enough. I saw another different failure mode this morning - both V1 and V2 API's timed out over about a 10 minute period. (across two polling periods)

On the evohome-munin script using the V1 API the script itself didn't return any errors, in fact munin-node terminated the script forcibly after 1 minute of no output from the script. The V2 API reported the following errors which I haven't seen before:

Traceback (most recent call last):
  File "/home/pi/evohome-new/evohome_V2_token", line 33, in <module>
    client = EvohomeClient('**************', '*********', refresh_token=refresh_token, access_token=access_token, access_token_expires=access_token_expires)
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 69, in __init__
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 72, in _login
  File "build/bdist.linux-armv6l/egg/evohomeclient2/__init__.py", line 193, in user_account
  File "/usr/local/lib/python2.7/dist-packages/requests/api.py", line 67, in get
    return request('get', url, params=params, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/requests/api.py", line 53, in request
    return session.request(method=method, url=url, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 468, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 576, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/requests/adapters.py", line 437, in send
    raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='tccna.honeywell.com', port=443): Max retries exceeded with url: /WebAPI/emea/api/v1/userAccount (Caused by NewConnectionError('<requests.packages.urllib3.connection.VerifiedHTTPSConnection object at 0xb64b1a10>: Failed to establish a new connection: [Errno 110] Connection timed out',))
Current time: 2019-03-10 06:01:05.143794

I suspect that the cause of this error may have been my internet connection being down, but I don't have any way to be sure. So is that the library reporting "max retries exceeded" due to it itself making multiple attempts before giving up ?

[zxdavb]

I suspect that the cause of this error may have been my internet connection being down,

Close. There is simply a network failure (urllib is reporting the error) for one end to connect with the other end (tccna.honeywell.com:443).

However, the problem could be at your end, or with your router, with ISPs transparent proxy, with DNS, or with Honeywell's reverse proxy/router/do-hicky/whatever... Experience tells me it is usually at Honeywell's end.

Anyway, not caused by the evohome-client library, I'm sure.

There is a good chance (but no guarantee that) the tokens/session ID would still be valid when network connectivity is restored (although the normal rules would still apply, e.g. expiry/timeouts).

[DBMandrake]

Close. There is simply a network failure (urllib is reporting the error) for one end to connect with the other end (tccna.honeywell.com:443).

However, the problem could be at your end, or with your router, with ISPs transparent proxy, with DNS, or with Honeywell's reverse proxy/router/do-hicky/whatever... Experience tells me it is usually at Honeywell's end.

Anyway, not caused by the evohome-client library, I'm sure.

To be clear, I wasn't suggesting it was a fault of the evohome-client library.

I was just posting it in relation to the inconsistent exception error reporting that is being discussed in this thread, as it seems to be another inconsistency with the exceptions that a client script has to be able to catch depending on what the cause of the failure is.

[zxdavb]

Sorry, I got excited & misunderstood.

[zxdavb]

OK, scrap the below, it's not that simple...

OK, looking at the code, I can see how _obtain_access_token() could be returning True when it shouldn't:

if response.status_code == requests.codes.bad_request:                   # pylint: disable=no-member
    if 'error' in response.text:  # don't use response.json() here!
        return response.json()['error'] != 'invalid_grant'
    raise requests.HTTPError(
        "Unable to obtain an Access Token: ", response.text)

Should be:

if response.status_code == requests.codes.bad_request:                   # pylint: disable=no-member
    if response.text:  # don't use response.json() here!
        raise requests.HTTPError("Unable to obtain an Access Token: ", response.text)
    else:
        raise requests.HTTPError("Unable to obtain an Access Token")

Will have another think about it...

[zxdavb]

Propose solution in #91 - anyone keen to test?

[watchforstock]

@zxdavb Thanks - I've tested with some tests I was adding anyway and it looks good (albeit the tests aren't really complete yet). I've merged into master which should make it easier for others to test - if it continues to look good I can do another release.

[zxdavb]

Oh god - I have implemented 0.3.2 in my HA components (both the official, and the custom_component version), and I am having second thoughts about how exceptions are handled.

I think evhomeclient2.AuthenticationError shouldn't be used when there is a requests.RequestsException - the requests exception should be passed up instead.

This is what I have in my app:

except (evohomeclient2.AuthenticationError, requests.exceptions.RequestException) as err:
    if not _handle_exception(err)
        return False  # unable to continue

This means (inter alia), we will never get a HTTP_BAD_REQUEST as it will always be caught by AuthenticationError - hence the need for the 'hint', below:

def _handle_exception(err) -> bool:
    _LOGGER.debug("_handle_exception(): Error message is: %s", err)
    try:
        raise err

    except EvohomeClient2.AuthenticationError as err:
        _LOGGER.error("Failed to authenticate with the vendor's server, hint: %s",
                      err, exc_info=True)
        return False

    except requests.exceptions.ConnectionError:
        _LOGGER.error("Unable to connect with the vendor's server. "
                      "Check your network, and the vendor's service status page.")
        return True

    except requests.exceptions.HTTPError:
        if err.response.status_code == HTTP_SERVICE_UNAVAILABLE:
            _LOGGER.error("The vendor says its servers are currently unavailable.")
        elif err.response.status_code == HTTP_TOO_MANY_REQUESTS:
            _LOGGER.error("The vendor says its API rate limit has been exceeded.")
        elif err.response.status_code == HTTP_BAD_REQUEST:
            _LOGGER.error("The vendor asks you check your username (%s) and password.", username)
        else:
            raise  # we don't expect/handle any other HTTPErrors
        return True

Also, how can we alert the consumer that a new set of tokens are available (so that they can be safely stored somewhere in case there is no graceful shutdown)?

Does anyone have any thoughts on this?