Unexpected error fetching Schlage data: string indices must be integers

[mprobber]

Hi! Thanks for your work on the Schlage encode Wi-Fi lock. After years of waiting, I appreciate it, and I know others do too!

I was unsure of whether to put this issue here, or in pyschlage, but I think a fox in both may be in order. A fix in pyschlage to handle whatever Schlage’s API is throwing at me here, and a fix in ha-Schlage not to raise an unhandled exception when it fails to set up a lock.

I had some offline locks added to my account, and in order to get the integration working for me, I had to remove them from my account, because the integration would fail to initialize those devices, and would raise an exception because of a TypeError. Since updating, however, even though all my locks are all online, I’m still getting that TypeError. I don’t have visibility into what the API response actually is, but it would be great if you could help me troubleshoot.

If one lock having some unexpected exception on initialization could not crash the entire application, but instead just not initialize that lock (and log the error), that would greatly help troubleshooting.

Here are the error details

Logger: custom_components.schlage
Source: custom_components/schlage/__init__.py:40 
Integration: Schlage Locks ([documentation](https://github.com/dknowles2/ha-schlage), [issues](https://github.com/dknowles2/ha-schlage/issues)) 
First occurred: 6:03:20 AM (7 occurrences) 
Last logged: 6:06:08 AM

Unexpected error fetching schlage data: string indices must be integers

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 239, in _async_refresh
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 195, in _async_update_data
    return await self.update_method()
  File "/config/custom_components/schlage/__init__.py", line 40, in async_update_data
    for ac in await hass.async_add_executor_job(lock.access_codes)
  File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.10/site-packages/pyschlage/lock.py", line 160, in access_codes
    return [
  File "/usr/local/lib/python3.10/site-packages/pyschlage/lock.py", line 161, in <listcomp>
    AccessCode.from_json(self._auth, ac, self.device_id) for ac in resp.json()
  File "/usr/local/lib/python3.10/site-packages/pyschlage/code.py", line 184, in from_json
    if json["activationSecs"] == _MIN_TIME and json["expirationSecs"] == _MAX_TIME:
TypeError: string indices must be integers

[dknowles2]

That's an interesting error. That means the API is returning some sort of raw string for access codes instead of the expected JSON object.

I'll merge #46 and push a new release which should at least suppress the error for you.

I am interested in what the API is returning for you, though. Are you able to run the script in this gist and give me the output? (Feel free to redact any personal data if it outputs any): https://gist.github.com/dknowles2/3eebe440eeee490770cbfc0365272500

[dknowles2]

I pushed a new release, 2023.3.2, that should at least stop initialization from erroring out. Hopefully that fixes it for you!

[mprobber]

Wow - you are on it with the debug script + initialization fix! Installing the update now so I can see which of the locks is actually giving me the error on initialization. I'll run the script when I get to something with a usable terminal :)

[mprobber]

So, I used pprint so I could parse through the output to remove any sensitive information - here is the output with pprint. I wound up omitting "friendlyName", "accessCode" and "accesscodeId". They all seemed like sane values in the output, except for one of the "accessCode" responses which was only a three digit code as opposed to a four digit code. Not sure how that happened.

With the latest version of ha-schlage installed on my HA instance, initialization is working, and all devices that previously existed still now exist, but two fail to lock (the same two that fail to initialize, looking at the logs).

Here's the output from the debug script (modified slightly to use pprint)

[   {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'xxxxx',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'xxxxxxx',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'xxxx',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'xxxxx',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'Xxxxxxx',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}}]
[   {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'Xxxxx',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'XX',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'Xxxxx',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'xxxxxx',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxxx,
        'accesscodeId': 'UUID omitted',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'XXXXXX',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}}]
[   {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'XXXXXXX',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}},
    {   'accessCode': xxxx,
        'accesscodeId': 'UUID OMITTED',
        'activationSecs': 0,
        'disabled': 0,
        'expirationSecs': 4294967295,
        'friendlyName': 'XXXXXXXX',
        'notification': 0,
        'schedule1': {   'daysOfWeek': '7F',
                         'endHour': 23,
                         'endMinute': 59,
                         'startHour': 0,
                         'startMinute': 0}}]

[dknowles2]

That's really strange. Passing those values into the AccessCode.from_json() method works without error. Based on the traceback, I expected one of the access codes to be an error string or something.

Did each lock return its access codes? Was one of the replies an empty string?

[dknowles2]

Okay, I'm actually seeing this in my own logs as well. I'll try and take a look later tonight. I see two different but similar stacktraces:

Traceback (most recent call last):
  File "/config/custom_components/schlage/__init__.py", line 39, in async_update_data
    access_codes = await hass.async_add_executor_job(lock.access_codes)
  File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.10/site-packages/pyschlage/lock.py", line 165, in access_codes
    return [
  File "/usr/local/lib/python3.10/site-packages/pyschlage/lock.py", line 166, in <listcomp>
    AccessCode.from_json(self._auth, ac, self.device_id) for ac in resp.json()
  File "/usr/local/lib/python3.10/site-packages/pyschlage/code.py", line 184, in from_json
    if json["activationSecs"] == _MIN_TIME and json["expirationSecs"] == _MAX_TIME:
TypeError: string indices must be integers

and

Traceback (most recent call last):
  File "/config/custom_components/schlage/__init__.py", line 49, in async_update_data
    logs = await hass.async_add_executor_job(lock.logs)
  File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.10/site-packages/pyschlage/lock.py", line 154, in logs
    return [LockLog.from_json(l) for l in resp.json()]
  File "/usr/local/lib/python3.10/site-packages/pyschlage/lock.py", line 154, in <listcomp>
    return [LockLog.from_json(l) for l in resp.json()]
  File "/usr/local/lib/python3.10/site-packages/pyschlage/log.py", line 98, in from_json
    created_at_str = json["createdAt"].rstrip("Z") + "+00:00"
TypeError: string indices must be integers

I suspect this is transient, since my locks seem to still be working. But I'll try and make the code a bit more defensive against this.

[dknowles2]

I ran a test overnight and it failed in yet another spot where I wasn't able to grab the output.

I suspect what's happening is that the API is returning an unexpected error which doesn't return a JSON dict as expected. (In normal circumstances, it seems that HTTP errors from the API are supposed to return a JSON dict like {"error":"Not Found","message":"Not Found","statusCode":404})

Whatever is returned must still be valid JSON though because the requests library would raise a RequestsJSONDecodeError if it weren't. Instead we're getting a plain string. So the response must be a string that's got quotes around it, which is even stranger.

I'm running a different test now to see if I can catch it.

[dknowles2]

Ah, got it!

I ran into a 401 Unauthorized error. In this case, it returns a JSON dict like I said before (except in this case, it doesn't have an "error" key for some reason). For each of these cases we're seeing, the code is expecting a JSON list returned. Iterating over JSON value is totally valid with a dict, but it's returning an iterable of strings instead of an iterable of dicts. Hence the TypeError on access.

I think the fix here is actually to explicitly look for HTTP errors in the response and raise an error (and possibly retry the request as well). That can be caught properly in the HA code since HTTP errors are always a possibility when calling a cloud API.

I'll work on a fix tonight after work.

[mprobber]

Super impressed with the follow-up here! Sorry for the silence. Thank you again!