Hangouts Stops Working With Session Closed

dshokouhi commented 5 years ago

Home Assistant release with the issue:

0.80.3

Last working Home Assistant release (if known): All

Operating environment (Hass.io/Docker/Windows/etc.):

virtual environment

Component/platform:

hangouts: https://www.home-assistant.io/components/hangouts/ Description of problem:

As reported in #16593 the hangouts component stops working randomly with a session is closed error and requires a Home Assistant restart to resolve. There was an attempted fix #17518 that was released in 0.80.3 but it seems like the fix is still not working.

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

configured via config entry

Traceback (if applicable):

2018-10-19 09:13:20 ERROR (MainThread) [homeassistant.core] Error executing service <ServiceCall hangouts.send_message (c:284e26ee0dd74401a6af87e78fe9f767): target=[OrderedDict([('id', 'SECRET')])], message=[OrderedDict([('text', "Welcome home! Do you need help? Type 'help' or 'yes' if yes.")])]>
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/core.py", line 1177, in _event_to_service_call
    await service_handler.func(service_call)
  File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/components/hangouts/hangouts_bot.py", line 310, in async_handle_send_message
    service.data.get(ATTR_DATA, {}))
  File "/srv/homeassistant/lib/python3.6/site-packages/homeassistant/components/hangouts/hangouts_bot.py", line 284, in _async_send_message
    await conv.send_message(messages, image_file)
  File "/srv/homeassistant/lib/python3.6/site-packages/hangups/conversation.py", line 439, in send_message
    await self._client.send_chat_message(request)
  File "/srv/homeassistant/lib/python3.6/site-packages/hangups/client.py", line 591, in send_chat_message
    send_chat_message_request, response)
  File "/srv/homeassistant/lib/python3.6/site-packages/hangups/client.py", line 417, in _pb_request
    request_pb.SerializeToString()
  File "/srv/homeassistant/lib/python3.6/site-packages/hangups/client.py", line 470, in _base_request
    'post', url, headers=headers, params=params, data=data,
  File "/srv/homeassistant/lib/python3.6/site-packages/hangups/http_utils.py", line 64, in fetch
    headers=headers, data=data) as res:
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/client.py", line 855, in __aenter__
    self._resp = await self._coro
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/client.py", line 254, in _request
    raise RuntimeError('Session is closed')
RuntimeError: Session is closed

Additional information: cc: @hobbypunk90

If we decide to reopen #16593 we can close this if not we should keep this open

amagnolo commented 5 years ago

The same happens to me. I confirm that #16593 is not solved.

I can add that in my case, the RPi3 running Hassio is connected via ethernet cable to a 4G wireless router for internet access; sometimes the router disconnects and reconnects to the mobile network (once or twice a day). I don't know if this is related to this bug. Anyway, once the hangouts integration stops working, even while the internet connection is working all right, the only solution is to restart home assistant.

brillb commented 5 years ago

Happening to me as well, exactly the same. It works for a little while, but I'm assuming if the connection is even briefly interrupted it is not properly reconnecting. Rebooting the RPi will bring it back.

hobbypunk90 commented 5 years ago

🤔 any ideas how we can solve this problem? I run out of any ideas... I'll think about this problem 😒

dshokouhi commented 5 years ago

@hobbypunk90 this error only shows up when we use hangouts.send_message I personally have not seen anything that indicates in the logs when exactly the session was closed. Maybe we should try to catch the error first and attempt to reconnect during the send_message service call?

brillb commented 5 years ago

Not entirely true, the error only shows up, but incoming messages (and thus the ability to have a "bot") are also broken. So you only see the error when you send a message, but the session is definitely closed - incoming messages are not delivered because effectively, you're "disconnected" from hangouts - so it doesn't even know the incoming message happened. So the fix needs to be in the daemon or whatever's meant to keep the session alive.

dshokouhi commented 5 years ago

@brillb thats what @hobbypunk90 just tried I thought so maybe the disconnection is not really happening on the HA end?

https://github.com/hobbypunk90/home-assistant/blob/778a772e10b25587c48fc13eee7e2c1efeb011f8/homeassistant/components/hangouts/hangouts_bot.py#L194

brillb commented 5 years ago

There's several other on_xxxx events, and two different kinds of errors which it looks like aren't handled, perhaps one of these is being encountered? https://hangups.readthedocs.io/en/latest/developer_guide/low_level.html#exceptions

dshokouhi commented 5 years ago

found this but the issue was closed? https://github.com/tdryer/hangups/issues/288

amagnolo commented 5 years ago

Maybe as a (ugly) patch, while investiganting a proper solution, you could expose a method in the API that checks the connection and reopens it if it's closed. Then we could schedule an automation to run it periodically, so at least the bot would be down for a short time and we don't have to restart the whole HA. (I am using this method for an autossh tunnel from the ssh add-on)

brillb commented 5 years ago

Where are the logs from Hangups? Or, if nowhere, how do we turn that on inside of HA? (FYI my connection is dead again this morning)

brillb commented 5 years ago

Any thoughts on this? I'm happy to help debug but I'm not clear on how to get more debugging out of Hangups.

hobbypunk90 commented 5 years ago

i have an idea for an workaround but i don't like it 😁 as i see, hangups don't give us more logs in a simple way and it also didn't realize the reconnect (or an disconnect...) my workaround looks like this: i add a reconnect service tomorrow morning and create an example for a scrape sensor against a website which provides your external ip. with this information, we can add an automation to reconnect the bot if your ip address changed.

as i said, i don't really like this workaround, but i don't see any other options at this moment...

hobbypunk90 commented 5 years ago

it's in 😁 i added a description for the workaround to the doc 😉 i hope this fixes our problem with the reconnect

mrlime commented 5 years ago

I experience this Hangouts disconnect issue and have a static IP address, so I doubt it has to do with the IP address changing.

However, I do automatically reboot my router every night, which may trigger a temporary disconnect akin to a changing IP address. Is there a way I can help?

hobbypunk90 commented 5 years ago

@mrlime it should be the same problem 😉 I know, it has nothing directly to do with the ip change, I think if the router reconnects, it's not nessesary, if the ip changes oder not 😉 the websocket from the hangouts library "disconnects", not a normal disconnect, then the lib reacts on it and disconnects the client, so we automatically reconnect 😉 I'm not deep enough in the websocket communication, but I think when the router reconnects, the socket is still open, but disfunctional so the hangouts lib "thinks" it is online and has a working connection to the Google server

amagnolo commented 5 years ago

Maybe there is a way to check the connection when hangouts lib "thinks" it is online? Like trying to send an empty message every few minutes and check if it throws an exception?

Or what about periodically calling the service hangouts.update (updates the list of conversations) and if it doesn't work automatically perform hangouts.reconnect ?

This would be more efficient than checking the IP; especially since I think that the disconnection can occur even while the IP stays the same.

Ton1965 commented 5 years ago

I have the same problem. Version 0.81.6 still does have it. Yesterday night my router rebooted and hangouts session got closed. Had to reboot HA to make it work again. The worst thing is you do not know when it happens. If you do not expect many notifications the problem stays unnoticed and you may miss something important. Hope it can be fixed.

brillb commented 5 years ago

The problem is that a workaround won't work... as was mentioned above, any interruption in internet connection, even when the external IP stays the same, is causing hangups to think that the hangouts session is still up, when it isn't. So we need to get to the root of this and fix the problem. I think it's over in the hangups code, though.

hobbypunk90 commented 5 years ago

@brillb you are right, but the workaround should help, if your up stay the same, you have to check your up more often than every 10s. At least with with a frequency of 1s you should get the disconnection, because your router don't reconnect instantly 😉 As I said in the beginning, I don't like this workaround, it's as far away from a good solution as it could, but as you mentioned, the problem is in the hangups code or deeper 😉

amagnolo commented 5 years ago

How can I try the "reconnect" service? I have just updated hassio to 0.82.1 but still when I try to call the service I get: Unable to find service hangouts/reconnect

jshank commented 5 years ago

Still happening in 0.85.0. I also have a static IP so it isn't IP related.

therimmer96 commented 5 years ago

Is this still an issue you are experiencing? Can you please try upgrading to the latest version of Home Assistant (0.90) and report back if this is still a problem? Thanks!

dshokouhi commented 5 years ago

Yup this is definitely still an issue I just got hit by it yesterday. Had to call the hangouts.reconnect service

e2m32 commented 5 years ago

Yup this is definitely still an issue I just got hit by it yesterday. Had to call the hangouts.reconnect service

Thanks for the hangouts.reconnect service trick. Could there be a way to automate this? Say check the service somehow every hour and call the service?

Mine doesn't seem to disconnect very often, is there any harm in setting up an automation to call the service every x time? Say once a day or something?

DrRob commented 5 years ago

This happened to me today with Home Assistant version 0.92.2, and hangups manually updated to 0.4.9 to sort out an authorisation problem.

DrRob commented 5 years ago

I see https://github.com/home-assistant/home-assistant/pull/18142

Rather than detect disconnections and reconnect automatically, could the message sending function detect a failure to send and reconnect then retry?

DrRob commented 5 years ago

I don't know if this is at relevant, but there's a lot of "Opening new long-polling request" from hangups in the Home Assistant logs. In the past four days, the time in seconds between these log entries has looked like this:

Note the one outlier, which is a 10.5-hour gap when it was disconnected from Hangouts. This happened ~220 minutes after the long-poll period became erratic, and began with an error in the logs:

hangups.log

(I've hidden a few ids with "<blah>" as I'm not sure if I should keep them private.) . You can see where I forced hangups to reconnect at the end of the logs there.

DrRob commented 5 years ago

I've been testing a tweak to the hangups code, with some improvement, but not perfect:

root@serf:/usr/src/app# cd /usr/src/app/homeassistant/components/hangouts/
root@serf:/usr/src/app/homeassistant/components/hangouts# diff -C5 hangouts_bot.py.orig hangouts_bot.py
*** hangouts_bot.py.orig    2019-05-31 05:39:15.792421437 +0000
--- hangouts_bot.py 2019-05-31 05:39:19.672430655 +0000
***************
*** 281,291 ****
                      _LOGGER.error('Path "%s" not allowed', uri)

          if not messages:
              return False
          for conv in conversations:
!             await conv.send_message(messages, image_file)

      async def _async_list_conversations(self):
          import hangups
          self._user_list, self._conversation_list = \
              (await hangups.build_user_conversation_list(self._client))
--- 281,298 ----
                      _LOGGER.error('Path "%s" not allowed', uri)

          if not messages:
              return False
          for conv in conversations:
!             try:
!                 await conv.send_message(messages, image_file)
!             except:
!                 _LOGGER.error('send_message failed, reconnecting...')
!                 await self.async_handle_reconnect()
!                 _LOGGER.error('...reconnected, trying again...')
!                 await conv.send_message(messages, image_file)
!

      async def _async_list_conversations(self):
          import hangups
          self._user_list, self._conversation_list = \
              (await hangups.build_user_conversation_list(self._client))

When it fails I see this in the logs:

2019-06-03 09:43:40 INFO (MainThread) [homeassistant.components.automation] Executing Front door
2019-06-03 09:43:40 INFO (MainThread) [homeassistant.helpers.script] Script Front door: Running script
2019-06-03 09:43:40 INFO (MainThread) [homeassistant.helpers.script] Script Front door: Executing step call service
2019-06-03 09:43:40 INFO (MainThread) [hangups.http_utils] Request returned unexpected status: 502 Bad Gateway
2019-06-03 09:43:40 WARNING (MainThread) [hangups.conversation] Failed to send message: Request return unexpected status: 502: Bad Gateway
2019-06-03 09:43:40 ERROR (MainThread) [homeassistant.components.hangouts.hangouts_bot] send_message failed, reconnecting...
2019-06-03 09:43:40 INFO (MainThread) [hangups.client] Graceful disconnect requested
2019-06-03 09:43:40 INFO (SyncWorker_5) [hangups.auth] Authenticating with refresh token
2019-06-03 09:43:40 INFO (MainThread) [hangups.client] Client.connect returning because Channel.listen returned
2019-06-03 09:43:41 INFO (SyncWorker_5) [hangups.auth] Authentication successful
2019-06-03 09:43:41 ERROR (MainThread) [homeassistant.components.hangouts.hangouts_bot] ...reconnected, trying again...
2019-06-03 09:43:41 ERROR (MainThread) [homeassistant.core] Error executing service <ServiceCall hangouts.send_message (c:<blah>): target=[OrderedDict([('id', '<blah>')])], message=[{'text': 'Front door on', 'parse_str': True}]>
Traceback (most recent call last):
  File "/usr/src/app/homeassistant/components/hangouts/hangouts_bot.py", line 287, in _async_send_message
    await conv.send_message(messages, image_file)
  File "/config/deps/lib/python3.7/site-packages/hangups/conversation.py", line 471, in send_message
    await self._client.send_chat_message(request)
  File "/config/deps/lib/python3.7/site-packages/hangups/client.py", line 591, in send_chat_message
    send_chat_message_request, response)
  File "/config/deps/lib/python3.7/site-packages/hangups/client.py", line 417, in _pb_request
    request_pb.SerializeToString()
  File "/config/deps/lib/python3.7/site-packages/hangups/client.py", line 470, in _base_request
    'post', url, headers=headers, params=params, data=data,
  File "/config/deps/lib/python3.7/site-packages/hangups/http_utils.py", line 88, in fetch
    .format(res.status, res.reason)
hangups.exceptions.NetworkError: Request return unexpected status: 502: Bad Gateway

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/app/homeassistant/core.py", line 1150, in _safe_execute
    await self._execute_service(handler, service_call)
  File "/usr/src/app/homeassistant/core.py", line 1163, in _execute_service
    await handler.func(service_call)
  File "/usr/src/app/homeassistant/components/hangouts/hangouts_bot.py", line 319, in async_handle_send_message
    service.data.get(ATTR_DATA, {}))
  File "/usr/src/app/homeassistant/components/hangouts/hangouts_bot.py", line 292, in _async_send_message
    await conv.send_message(messages, image_file)
  File "/config/deps/lib/python3.7/site-packages/hangups/conversation.py", line 471, in send_message
    await self._client.send_chat_message(request)
  File "/config/deps/lib/python3.7/site-packages/hangups/client.py", line 591, in send_chat_message
    send_chat_message_request, response)
  File "/config/deps/lib/python3.7/site-packages/hangups/client.py", line 417, in _pb_request
    request_pb.SerializeToString()
  File "/config/deps/lib/python3.7/site-packages/hangups/client.py", line 470, in _base_request
    'post', url, headers=headers, params=params, data=data,
  File "/config/deps/lib/python3.7/site-packages/hangups/http_utils.py", line 65, in fetch
    headers=headers, data=data) as res:
  File "/usr/local/lib/python3.7/site-packages/aiohttp/client.py", line 1005, in __aenter__
    self._resp = await self._coro
  File "/usr/local/lib/python3.7/site-packages/aiohttp/client.py", line 348, in _request
    raise RuntimeError('Session is closed')
RuntimeError: Session is closed

So this notification failed, but a subsequent one 2.5 minutes later succeeded:

2019-06-03 09:43:41 INFO (MainThread) [hangups.channel] Requesting new gsessionid and SID...
2019-06-03 09:43:41 INFO (MainThread) [hangups.channel] New SID: <blah>
2019-06-03 09:43:41 INFO (MainThread) [hangups.channel] New gsessionid: <blah>
2019-06-03 09:43:41 INFO (MainThread) [hangups.channel] Opening new long-polling request
2019-06-03 09:43:42 INFO (MainThread) [hangups.client] Received new client_id: 'lcsw_hangouts_<blah>'
2019-06-03 09:43:42 INFO (MainThread) [hangups.client] Adding channel services...
2019-06-03 09:43:42 INFO (MainThread) [hangups.conversation] Requesting conversations page 0
2019-06-03 09:43:42 INFO (MainThread) [hangups.client] Channel services added
2019-06-03 09:43:42 INFO (MainThread) [hangups.conversation] Reached final conversations page
2019-06-03 09:43:42 INFO (MainThread) [hangups.conversation] Synced 1 total conversations
2019-06-03 09:43:43 INFO (MainThread) [hangups.user] UserList initialized with 2 user(s)
2019-06-03 09:43:44 INFO (MainThread) [homeassistant.components.automation] Executing Front door
2019-06-03 09:43:44 INFO (MainThread) [homeassistant.helpers.script] Script Front door: Running script
2019-06-03 09:43:44 INFO (MainThread) [homeassistant.helpers.script] Script Front door: Executing step call service
2019-06-03 09:43:44 INFO (MainThread) [hangups.conversation] latest_read_timestamp for <blah> updated to 2019-06-03 09:43:44.352909+00:00
2019-06-03 09:43:44 INFO (MainThread) [hangups.conversation] latest_read_timestamp for conv <blah> participant <blah> updated to 2019-06-03 09:43:44.352909+00:00

I'm wondering if await self.async_handle_reconnect() doesn't complete the reconnection before returning?

F13 commented 5 years ago

Potentially related to this is an issue where over the course of a few days, the hangouts bot will start responding a whole bunch of times.

Calling the send_message service manually does not result in duplicate messages.

pedrolamas commented 4 years ago

@DrRob I think you are on a very good path!

Looking at the code for async_handle_reconnect method, what it does is calling async_disconnect and then async_connect, and it's this second call that seems to actually not be properly awaited - or better, it doesn't actually await to confirm that the connection has been properly established.

We need to ensure that the connection was complete before re-trying to send the message.

pedrolamas commented 4 years ago

I'm following up on this here as it seems to me that all the manual reconnection code should not exist... my understanding of the hangups code is that it should automatically reconnect without the need for the manual reconnection code in HA.

dshokouhi commented 4 years ago

@PedroLamas it does not automatically reconnect so the service hangouts.reconnect was created to help with the session being closed. This still happens today as well. There are multiple reasons for it to happen, I notice it happens most often when internet goes down but sometimes it just looses the session for no reason and the service has to be called to reconnect since the internal logic does not do it.

pedrolamas commented 4 years ago

@dshokouhi I agree with your comments and my findings do match the behavior you described. But as it appears that there is some internal logic on hangups component, I wonder if there's anything we can do at that level that would mitigate or at least improve this situation.

stale[bot] commented 4 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

jshank commented 4 years ago

Still happening. Has anyone done an automation to react to the Session is closed and call reconnect until this is addressed?

hgop67 commented 4 years ago

Noticed that the success of Hangouts seems to depend on the status of AdGuard when starting Home Assistant.

xumxum commented 3 years ago

Still happens in 0.117.5 :/ , and indeed not related to the IP change. The example code to detect IP change from the integration page using rest API for some reason it triggers very often even though the IP value is the same, thus hangouts is restarted very often. I put a notification to detect an IP change and saw it was triggering every half hour even though IP change was not happening, thus restarting the hangouts, thus increasing the chance of working but this is not the solution.

home-assistant / core

Hangouts Stops Working With Session Closed #17622