Nest integration failing due to aiohttp Network unreachable #44719
Comments
|
nest documentation |
|
Hey there @awarecan, @allenporter, mind taking a look at this issue as its been labeled with an integration ( |
|
@bdraco i was chatting with @SlickUnderTheGun on reddit about this one and was hoping you might have some insights here. This "network unreachable" thing seemed like it was related to aiohttp aio-libs/aiohttp#5112 however my impression was that you last upgraded aiohttp to include that fix. I was curious if you happeend to have seen anything like this before for other integrations. It seemed like odd symptoms where it mostly works then stops, and didn't seem like a typically "network connectivity" issue but something getting wedged. Any thoughts about how we can help or gather more data to diagnose this? |
|
Kind of similar to aio-libs/aiohttp#2522 and I believe I hit this same issue when creating the nest sdm command line tool where it was ok to hack it up to get it working, but fix doesn't seem appropriate more generally |
allenporter
changed the title
|
@SlickUnderTheGun are you running under docker? |
It doesn't look like a case of 5112 as that was much more predictable. It might be related to aio-libs/aiohttp#5156 which is fixed in 3.7.2 (not possible to update to because of sendfile bugs that still need to be fixed) but that seems unlikely since there isn't an exception similar to the one shown in that issue. Is ipv6 unreliable/broken on the system in question? |
|
@bdraco thanks for looking. It's true, when I saw this network unreachable problem it failed 100% of the time. I was able to upgrade to 3.7.3 and that let me remove the workarounds to force AF_INET: @SlickUnderTheGun in addition to the ipv6 question above, can you also confirm you have the latest version of aiohttp installed? with a command like: |
|
aio-libs/aiohttp#5157 regressed aio-libs/aiohttp#5125. My test wasn't good enough to catch it. That is what is blocking updating aiohttp (#42514) at the moment. I haven't had a moment to unravel what needs to change to fix zero byte files again. |
I am.
Not to my knowledge. I just never got around to enabling it. I can do that today if you'd like.
I can update packages within the container manually but when I pull a new docker image it'll revert to whatever version they're using so it wouldn't be an ideal solution. |
|
@SlickUnderTheGun yeah, that is not a solution, just to help diagnose whats going on. Was curious if you had an even older version, or if its the same issue that was already fixed or something else. You're also welcome to wait for the latest aiohttp to be integrated fully though it may take awhile, or continue to diagnose the network issues. |
|
I'm happy to continue to help troubleshoot until an acceptable solution has been found or you decide it isn't worth pursuing any further. I went ahead and enabled/configured IPv6 today and also updated my Home Assistant image to 2020.12.2. I'll send an update if the integration crashes or if it hasn't after a couple days. Let me know if you need any other information. |
|
The integration ran from 2021-01-02 17:41:55 until 2021-01-03 22:26:23 EST and then failed again with these messages. 2021-01-03 22:26:13 INFO (Thread-829) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-recoverable stream error 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2021-01-03 22:26:13 INFO (Thread-829) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] RPC termination has signaled streaming pull manager shutdown.
2021-01-03 22:26:13 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping consumer.
2021-01-03 22:26:13 INFO (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-terminating stream error 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2021-01-03 22:26:13 INFO (Thread-ConsumeBidirectionalStream) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Observed non-recoverable stream error 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2021-01-03 22:26:13 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping scheduler.
2021-01-03 22:26:13 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping leaser.
2021-01-03 22:26:13 INFO (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Thread-LeaseMaintainer exiting.
2021-01-03 22:26:13 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping dispatcher.
2021-01-03 22:26:13 DEBUG (Thread-CallbackRequestDispatcher) [google.cloud.pubsub_v1.subscriber._protocol.helper_threads] Exiting the QueueCallbackWorker.
2021-01-03 22:26:13 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Stopping heartbeater.
2021-01-03 22:26:13 INFO (Thread-Heartbeater) [google.cloud.pubsub_v1.subscriber._protocol.heartbeater] Thread-Heartbeater exiting.
2021-01-03 22:26:13 DEBUG (Thread-OnRpcTerminated) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Finished stopping manager.
2021-01-03 22:26:13 WARNING (Thread-OnRpcTerminated) [google_nest_sdm.google_nest_subscriber] Subscriber disconnected, will restart: <class 'google.api_core.exceptions.Unauthenticated'>: 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.
2021-01-03 22:26:23 DEBUG (MainThread) [google_nest_sdm.google_nest_subscriber] Watchdog: subscriber shut down; restartingI'll try to include some follow up information I think may be relevant. I'm now getting this message in my logs. It occurs about every hour but sometimes I don't see it for 2-5 hours. The entire message will also sometimes repeat up to three times with the same timestamp. The integration continues to function normally so it does seem to be non-fatal as the message indicates. I'm including it because there's now a reference to IPv6 on line 12. 2021-01-03 21:23:14 DEBUG (Thread-CallbackRequestDispatcher) [google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager] Exception while sending unary RPC. This is typically non-fatal as stream requests are best-effort.
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/google/api_core/grpc_helpers.py", line 57, in error_remapped_callable
return callable_(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/grpc/_channel.py", line 826, in __call__
return _end_unary_response_blocking(state, call, False, None)
File "/usr/local/lib/python3.8/site-packages/grpc/_channel.py", line 729, in _end_unary_response_blocking
raise _InactiveRpcError(state)
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
status = StatusCode.UNAUTHENTICATED
details = "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project."
debug_error_string = "{"created":"@1609726994.206401409","description":"Error received from peer ipv6:[2607:f8b0:4009:801::200a]:443","file":"src/core/lib/surface/call.cc","file_line":1061,"grpc_message":"Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.","grpc_status":16}"
>
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 417, in send
self._send_unary_request(request)
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 388, in _send_unary_request
self._client.acknowledge(
File "/usr/local/lib/python3.8/site-packages/google/cloud/pubsub_v1/_gapic.py", line 40, in <lambda>
fx = lambda self, *a, **kw: wrapped_fx(self.api, *a, **kw) # noqa
File "/usr/local/lib/python3.8/site-packages/google/pubsub_v1/services/subscriber/client.py", line 909, in acknowledge
rpc(
File "/usr/local/lib/python3.8/site-packages/google/api_core/gapic_v1/method.py", line 145, in __call__
return wrapped_func(*args, **kwargs)
File "/usr/local/lib/python3.8/site-packages/google/api_core/retry.py", line 281, in retry_wrapped_func
return retry_target(
File "/usr/local/lib/python3.8/site-packages/google/api_core/retry.py", line 184, in retry_target
return target()
File "/usr/local/lib/python3.8/site-packages/google/api_core/grpc_helpers.py", line 59, in error_remapped_callable
six.raise_from(exceptions.from_grpc_error(exc), exc)
File "<string>", line 3, in raise_from
google.api_core.exceptions.Unauthenticated: 401 Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.I also still get this message when trying to adjust the temperature with the Home Assistant climate card after the integration stops updating. 2021-01-03 23:24:24 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [2716375168] Access token failure: 400, message='Bad Request', url=URL('https://www.googleapis.com/oauth2/v4/token')
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/google_nest_sdm/auth.py", line 43, in request
access_token = await self.async_get_access_token()
File "/usr/src/homeassistant/homeassistant/components/nest/api.py", line 28, in async_get_access_token
await self._oauth_session.async_ensure_token_valid()
File "/usr/src/homeassistant/homeassistant/helpers/config_entry_oauth2_flow.py", line 465, in async_ensure_token_valid
new_token = await self.implementation.async_refresh_token(self.token)
File "/usr/src/homeassistant/homeassistant/helpers/config_entry_oauth2_flow.py", line 84, in async_refresh_token
new_token = await self._async_refresh_token(token)
File "/usr/src/homeassistant/homeassistant/helpers/config_entry_oauth2_flow.py", line 175, in _async_refresh_token
new_token = await self._token_request(
File "/usr/src/homeassistant/homeassistant/helpers/config_entry_oauth2_flow.py", line 194, in _token_request
resp.raise_for_status()
File "/usr/local/lib/python3.8/site-packages/aiohttp/client_reqrep.py", line 1002, in raise_for_status
raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 400, message='Bad Request', url=URL('https://www.googleapis.com/oauth2/v4/token')
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 135, in handle_call_service
await hass.services.async_call(
File "/usr/src/homeassistant/homeassistant/core.py", line 1445, in async_call
task.result()
File "/usr/src/homeassistant/homeassistant/core.py", line 1480, in _execute_service
await handler.job.target(service_call)
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
await self.hass.helpers.service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 593, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 664, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 630, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 544, in async_service_temperature_set
await entity.async_set_temperature(**kwargs)
File "/usr/src/homeassistant/homeassistant/components/nest/climate_sdm.py", line 316, in async_set_temperature
await trait.set_heat(temp)
File "/usr/local/lib/python3.8/site-packages/google_nest_sdm/thermostat_traits.py", line 124, in set_heat
return await self._cmd.execute(data)
File "/usr/local/lib/python3.8/site-packages/google_nest_sdm/traits.py", line 19, in execute
resp = await self._auth.request(
File "/usr/local/lib/python3.8/site-packages/google_nest_sdm/auth.py", line 45, in request
raise AuthException(f"Access token failure: {err}") from err
google_nest_sdm.exceptions.AuthException: Access token failure: 400, message='Bad Request', url=URL('https://www.googleapis.com/oauth2/v4/token')It may be completely unrelated but I have the Node-RED package node-red-contrib-home-assistant-websocket version 0.24.1 integrated with Home Assistant to handle all of my automations. I noticed that the integration failed about 10 minutes after a 'call service' node was used to change the temperature before we went to bed. I had this node disabled before the last time I updated Home Assistant (2021-01-02 17:41:55) but reenabled it yesterday. Is it possible that the Node-RED websocket call is somehow causing a problem with the Nest integration? I've updated node-red-contrib-home-assistant-websocket to version 0.29.1, updated Node-RED from version 1.1.3 to 1.2.6, and restarted Home Assistant. I'll continue to test. |
This is all separate from the network unreachable of course. |
|
@SlickUnderTheGun has your ipv6 work resolved your network unreachable errors? |
|
@allenporter I'm not sure if it was enabling IPv6 or improvements you've made to your code but I believe it may be resolved. I pulled a new docker image which updated my Home Assistant version to 2021.2.0.dev20210101 at 2021-01-04 20:44:00 EST and the integration has updated continuously since, about 84 hours. Between then and now I have 189 instances of the It shouldn't cause too much trouble on my network to disable IPv6 again if you'd like to see if we can get the issue to repeat itself more reliably. Otherwise I'm going to leave my installation/container/configuration/etc. as is and continue to monitor the integration for a few days and then close the issue if there aren't any further problems. |
|
@allenporter It looks like aiohttp was updated to 3.7.3 in release 2021.1.3 under a different MR to the one mentioned above. |
|
@SlickUnderTheGun I didn't change anything, so lets assume it was your ipv6 adjustments and that aiohttp upgrade should fix it for anyone else running into this. Thanks everyone! |
The problem
The Nest integration works properly for several hours (generally 2 to 3, longest was 21) and then fails to update changes to sensors and climate card. After the updates are no longer reported I am usually still able to use the climate card to make changes to target temperature, operation, and preset successfully (confirmed with Nest Android app). Occasionally making a change with the climate card after updates have failed results in a "Network unreachable" error. I am not sure if this is related or a separate issue.
Environment
Problem-relevant
configuration.yamlTraceback/Error logs
After the final log item there are no further messages from the integration until it is reloaded.
This is the error/traceback that is logged when the "Network unreachable" error occurs:
Additional information
Using the reload option on the integrations page is always successful and the integration functions properly for several hours before failing again.
The text was updated successfully, but these errors were encountered: