Abode randomly becomes "unavailable", restored by restart.

[gregorymartin]

The problem

About once a month my Abode integration and all entities will randomly become "unavailable". I have to restart the system for it to come back.

Environment

• Home Assistant Core release with the issue:

0.112.4

• Operating environment (OS/Container/Supervised/Core):

Home Assistant on Rasperry Pi 3B+

• Integration causing this issue:

Abode

Traceback/Error logs

Log Details (WARNING)
Logger: abodepy.socketio
Source: util/thread.py:20 
First occurred: 5:56:47 AM (1 occurrences) 
Last logged: 5:56:47 AM

Captured exception during SocketIO event callback: Request failed

Additional information

I've check Abode's system status as well as my network status and there haven't appeared to be any outages at the time this occurs.

[probot-home-assistant]

Hey there @shred86, mind taking a look at this issue as its been labeled with an integration (abode) you are listed as a codeowner for? Thanks!
_{^{(message by CodeOwnersMention)}}

[barndawgie]

I see this problem as well, and get the same log message:
2020-07-24 03:38:16 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Request failed

All Abode devices then went unavailable until I restarted Home Assistant.

[gregorymartin]

Abode just had an official outage and the same behavior happened. I wonder if this generally occurs when there is a communication issue with the API and the integration isn't able to recover gracefully without a restart?

[shred86]

I'm seeing the same thing with these Abode server issues:

2020-07-25 08:30:30 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Expecting value: line 1 column 1 (char 0)
2020-07-25 08:30:30 WARNING (SocketIOThread) [lomond] disconnecting websocket
2020-07-25 08:30:30 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Error: "Not Authorized"
2020-07-25 08:30:35 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Expecting value: line 1 column 1 (char 0)
2020-07-25 08:30:36 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Expecting value: line 1 column 1 (char 0)
2020-07-25 08:30:36 WARNING (SocketIOThread) [lomond] disconnecting websocket
2020-07-25 08:30:36 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Error: "Not Authorized"
2020-07-25 08:31:41 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Expecting value: line 1 column 1 (char 0)
2020-07-25 08:31:42 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Expecting value: line 1 column 1 (char 0)
2020-07-25 08:31:42 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Server Ping Timeout
2020-07-25 08:31:42 WARNING (SocketIOThread) [lomond] disconnecting websocket
2020-07-25 08:31:42 WARNING (SocketIOThread) [abodepy.socketio] SocketIO Error: "Not Authorized"
2020-07-25 08:32:48 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Expecting value: line 1 column 1 (char 0)
2020-07-25 08:33:48 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Expecting value: line 1 column 1 (char 0)

@MisterWil It looks like lomond is disconnecting the websocket but it never seems to reconnect now? I know in the past we would see the SocketIO Error: "Not Authorized" every once in a while but it would just reconnect. I don't remember seeing lomond actually disconnect the websocket though.

[MisterWil]

Well that's new. I also noticed this morning that nothing related to Abode was working, but I also knew there had been a service outage. I wonder if they changed something with one of the responses related to reconnecting. Fan-tastic.

[gregorymartin]

Yeah, interestingly, since I posted this bug there have been a couple of official outages that have replicated this issue.

[shred86]

Been working with @MisterWil on this issue and I think this might be the cause. Abodepy is definitely reconnecting the web socket in the background. When the web socket is connected, _on_socket_connected is called in the event controller which also calls self._abode.refresh(). That method then calls send_request which is where it's failing based on these logs:

2020-07-25 11:09:53 INFO (SocketIOThread) [abodepy.socketio] Websocket Connected
2020-07-25 11:09:53 INFO (SocketIOThread) [abodepy] Updating all devices...
2020-07-25 11:10:53 WARNING (SocketIOThread) [abodepy.socketio] Captured exception during SocketIO event callback: Expecting value: line 1 column 1 (char 0)

Normally, you would see a response with all the device states after "Updating all devices...". What I think is happening is the web socket gets connected but Abode's servers are still initializing so the device refresh actually fails and throws the exception in the log above (which isn't apparent looking at the send_request method, it's just several layers deep in callbacks). At that point, the callbacks inside the _on_socket_connected never get executed are what actually change the entity state in HA back to available.

So, I think a solution here is to use a try/catch/finally block in the abodepy event controller. The logic here is if _on_socket_connected is being called, then the web socket connection is established and the devices are "available" in terms of they should be getting device updates.

        try:
            self._abode.refresh()
        except Exception as exc:
            _LOGGER.warning("Captured exception during Abode refresh: %s", exc)
        finally:
            for callbacks in self._connection_status_callbacks.items():
                for callback in callbacks[1]:
                    _execute_callback(callback)

The issue is I don't have an easy way to test this specific issue other than waiting for Abode's servers to have this issue again, which might actually might happen given how unstable it's been these past ~12 hours.

Edit: Bad news is Abode servers are still having issues. Good news is I was able to test the changes I made above and it fixes this issue.

[shred86]

Fixed with #35164.

[gregorymartin]

This appears to have been resolved as part of the updates included in #35164.