search

skodaconnect / homeassistant-myskoda

Homeassistant integration for MySkoda.
96 stars 15 forks source link

myskoda.mqtt.ConcurrentSubscribeError causes HA Core to get unresponsive #140

Closed ChristianForstner closed 1 month ago

ChristianForstner commented 1 month ago

After updating from version 1.5.0 to 1.6.2, this error occurs:

2024-10-26 14:19:50.434 ERROR (MainThread) [myskoda.mqtt] Failed to connect to MQTT.
2024-10-26 14:19:55.537 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 150, in connect
    await self._subscribe_to_topic(f"{user_id}/{vin}/operation-request/{topic}")
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 260, in _subscribe_to_topic
    raise ConcurrentSubscribeError
myskoda.mqtt.ConcurrentSubscribeError

This myskoda.mqtt.ConcurrentSubscribeError causes HA core to get unresponsive.

2024-10-26 14:29:18.641 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /core/info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-26 14:29:18.648 ERROR (MainThread) [homeassistant.components.hassio.coordinator] Error fetching hassio data: Error on Supervisor API: 
2024-10-26 15:14:20.250 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /os/info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-26 15:14:20.252 WARNING (MainThread) [homeassistant.components.hassio] Can't read Supervisor data: 
2024-10-26 15:19:18.639 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-26 15:19:18.647 ERROR (MainThread) [homeassistant.components.hassio.coordinator] Error fetching hassio data: Error on Supervisor API: 
2024-10-26 15:20:28.354 ERROR (MainThread) [homeassistant.components.homeassistant_alerts.coordinator] Timeout fetching homeassistant_alerts data

At some point, also a DNSError occurs:

2024-10-26 15:21:05.132 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/resolver.py", line 105, in resolve
    resp = await self._resolver.getaddrinfo(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
aiodns.error.DNSError: (12, 'Timeout while contacting DNS servers')

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1287, in _create_direct_connection
    hosts = await self._resolve_host(host, port, traces=traces)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 938, in _resolve_host
    return await asyncio.shield(resolved_host_task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 975, in _resolve_host_with_throttle
    addrs = await self._resolver.resolve(host, port, family=self._family)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/resolver.py", line 114, in resolve
    raise OSError(msg) from exc
OSError: Timeout while contacting DNS servers

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 143, in connect
    while not await self._perform_connect():  # noqa: ASYNC110
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 128, in _perform_connect
    await self.authorization.get_access_token(),
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 293, in get_access_token
    await self.refresh_token()
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 262, in refresh_token
    if await self._perform_refresh_token():
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 241, in _perform_refresh_token
    async with self.session.post(
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 1355, in __aenter__
    self._resp: _RetType = await self._coro
                           ^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 659, in _request
    conn = await self._connector.connect(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 557, in connect
    proto = await self._create_connection(req, traces, timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1002, in _create_connection
    _, proto = await self._create_direct_connection(req, traces, timeout)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1293, in _create_direct_connection
    raise ClientConnectorError(req.connection_key, exc) from exc
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host mysmob.api.connect.skoda-auto.cz:443 ssl:default [None]
2024-10-26 15:59:18.643 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /supervisor/info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]

In the end, Supervisor restarts HA Core and this loop starts again and again.

Core: 2024.10.4 Supervisor: 2024.10.3 Operating System: 13.2 Frontend: 20241002.4 homeassistant-myskoda: 1.6.2

Car is a Skoda Enyaq (2024)

WebSpider commented 1 month ago

We have multiple report of this occurring, thanks for providing this detailed report 👍

WebSpider commented 1 month ago

This should be improved a lot in 1.6.3, please report your experiences!

ChristianForstner commented 1 month ago

Thanks for the fast response. I removed the integration and installed version 1.6.3, just to be on the safe side that there were no residuals from 1.6.2 left. Unfortunately, the situation hasn't changed:

2024-10-28 14:41:15.810 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 14:41:35.016 ERROR (MainThread) [metno] Access to https://aa015h6buqvih86i1.api.met.no/weatherapi/locationforecast/2.0/complete returned error 'TimeoutError'
2024-10-28 14:41:35.017 ERROR (MainThread) [homeassistant.components.met.coordinator] Error fetching met data: Update failed: 
2024-10-28 14:41:53.120 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/resolver.py", line 105, in resolve
    resp = await self._resolver.getaddrinfo(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
aiodns.error.DNSError: (12, 'Timeout while contacting DNS servers')

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1287, in _create_direct_connection
    hosts = await self._resolve_host(host, port, traces=traces)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 938, in _resolve_host
    return await asyncio.shield(resolved_host_task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 975, in _resolve_host_with_throttle
    addrs = await self._resolver.resolve(host, port, family=self._family)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/resolver.py", line 114, in resolve
    raise OSError(msg) from exc
OSError: Timeout while contacting DNS servers

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 144, in connect
    while not await self._perform_connect():  # noqa: ASYNC110
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 129, in _perform_connect
    await self.authorization.get_access_token(),
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 293, in get_access_token
    await self.refresh_token()
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 262, in refresh_token
    if await self._perform_refresh_token():
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 241, in _perform_refresh_token
    async with self.session.post(
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 1355, in __aenter__
    self._resp: _RetType = await self._coro
                           ^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 659, in _request
    conn = await self._connector.connect(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 557, in connect
    proto = await self._create_connection(req, traces, timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1002, in _create_connection
    _, proto = await self._create_direct_connection(req, traces, timeout)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1293, in _create_direct_connection
    raise ClientConnectorError(req.connection_key, exc) from exc
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host mysmob.api.connect.skoda-auto.cz:443 ssl:default [None]
2024-10-28 14:41:55.900 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 14:43:09.205 ERROR (MainThread) [custom_components.myskoda.coordinator] Error fetching myskoda data: ('Error getting update from MySkoda API: %s', ClientConnectorError(ConnectionKey(host='mysmob.api.connect.skoda-auto.cz', port=443, is_ssl=True, ssl=True, proxy=None, proxy_auth=None, proxy_headers_hash=-XXXXXXXXXXXXXXXXXXX), OSError('Timeout while contacting DNS servers')))
2024-10-28 14:43:09.775 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 151, in connect
    await self._subscribe_to_topic(f"{user_id}/{vin}/operation-request/{topic}")
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 260, in _subscribe_to_topic
    raise ConcurrentSubscribeError
myskoda.mqtt.ConcurrentSubscribeError
2024-10-28 14:43:09.777 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 151, in connect
    await self._subscribe_to_topic(f"{user_id}/{vin}/operation-request/{topic}")
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 260, in _subscribe_to_topic
    raise ConcurrentSubscribeError
myskoda.mqtt.ConcurrentSubscribeError
2024-10-28 14:43:09.779 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 151, in connect
    await self._subscribe_to_topic(f"{user_id}/{vin}/operation-request/{topic}")
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 260, in _subscribe_to_topic
    raise ConcurrentSubscribeError
myskoda.mqtt.ConcurrentSubscribeError
2024-10-28 14:43:09.781 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 151, in connect
    await self._subscribe_to_topic(f"{user_id}/{vin}/operation-request/{topic}")
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 260, in _subscribe_to_topic
    raise ConcurrentSubscribeError
myskoda.mqtt.ConcurrentSubscribeError
2024-10-28 14:43:09.783 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 151, in connect
    await self._subscribe_to_topic(f"{user_id}/{vin}/operation-request/{topic}")
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 260, in _subscribe_to_topic
    raise ConcurrentSubscribeError
myskoda.mqtt.ConcurrentSubscribeError
2024-10-28 14:44:50.801 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-28 14:44:50.809 ERROR (MainThread) [homeassistant.components.hassio.coordinator] Error fetching hassio data: Error on Supervisor API: 
2024-10-28 14:45:31.268 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 14:47:48.378 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 14:54:51.873 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /network/info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-28 14:54:51.874 WARNING (MainThread) [homeassistant.components.hassio] Can't read Supervisor data: 
2024-10-28 15:02:48.871 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 15:05:41.496 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 15:07:58.605 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 15:09:50.802 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-28 15:09:50.811 ERROR (MainThread) [homeassistant.components.hassio.coordinator] Error fetching hassio data: Error on Supervisor API: 
2024-10-28 15:14:50.802 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-28 15:19:50.803 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /core/info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
WebSpider commented 1 month ago

Thanks for your report!

Do you have mqtt enabled inside homeassistant as well, for instance for zigbee2mqtt?

ChristianForstner commented 1 month ago

As far as I know, the only integration I have installed along this one using mqtt is wattpilot-HA with its dependency wattpilot. I'm running HA on a Yellow with only Thread being enabled. I can try to disable wattpilot-HA and see if myskoda.mqtt.ConcurrentSubscribeError is raised again.

Edit: It looks like wattpilot-HA is actually trying to parse something:

2024-10-28 18:42:03.467 ERROR (MainThread) [custom_components.wattpilot.utils] PROBABLY_SOME_SECTRET_ID - PropertyUpdateHandler: Could not 'self' execute async: 'PROBABLY_SOME_SECTRET_ID' (builtins.KeyError)

Edit 2: After disabling wattpilot-HA, I'm still getting the same errors as above, e.g.

2024-10-28 19:48:53.132 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/resolver.py", line 105, in resolve
    resp = await self._resolver.getaddrinfo(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
aiodns.error.DNSError: (12, 'Timeout while contacting DNS servers')

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1287, in _create_direct_connection
    hosts = await self._resolve_host(host, port, traces=traces)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 938, in _resolve_host
    return await asyncio.shield(resolved_host_task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 975, in _resolve_host_with_throttle
    addrs = await self._resolver.resolve(host, port, family=self._family)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/resolver.py", line 114, in resolve
    raise OSError(msg) from exc
OSError: Timeout while contacting DNS servers

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 144, in connect
    while not await self._perform_connect():  # noqa: ASYNC110
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/mqtt.py", line 129, in _perform_connect
    await self.authorization.get_access_token(),
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 293, in get_access_token
    await self.refresh_token()
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 262, in refresh_token
    if await self._perform_refresh_token():
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/myskoda/auth/authorization.py", line 241, in _perform_refresh_token
    async with self.session.post(
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 1355, in __aenter__
    self._resp: _RetType = await self._coro
                           ^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 659, in _request
    conn = await self._connector.connect(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 557, in connect
    proto = await self._create_connection(req, traces, timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1002, in _create_connection
    _, proto = await self._create_direct_connection(req, traces, timeout)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1293, in _create_direct_connection
    raise ClientConnectorError(req.connection_key, exc) from exc
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host mysmob.api.connect.skoda-auto.cz:443 ssl:default [None]
2024-10-28 20:22:21.426 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /supervisor/info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-28 20:22:21.431 ERROR (MainThread) [homeassistant.components.hassio.coordinator] Error fetching hassio data: Error on Supervisor API: 
2024-10-28 20:26:38.416 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 21:03:43.115 ERROR (MainThread) [homeassistant.components.hassio.handler] Client error on /host/info request Cannot connect to host 172.30.32.2:80 ssl:default [No such file or directory]
2024-10-28 21:03:43.116 ERROR (MainThread) [homeassistant.components.hassio] Failed to to call /host/info -

Edit 3: Failed to connect to MQTT has not appeared before.

2024-10-28 22:30:53.352 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 22:30:54.219 ERROR (MainThread) [paho.mqtt.client] Caught exception in on_socket_register_write: [Errno 2] No such file or directory
2024-10-28 22:30:54.219 ERROR (MainThread) [myskoda.mqtt] Failed to connect to MQTT.
WebSpider commented 1 month ago

We have an attempt at solving this more permanently at https://github.com/skodaconnect/myskoda/pull/140 I've been running this with an operating car for 2h now, and it seems to be stable.

If anyone else feels like giving this branch of the library a chance, make sure you run it with the following lines in your configuration.yaml to produce relevant logging:

logger:
  default: info
  logs:
    custom_components.myskoda: debug
    myskoda: debug
    paho: debug

If we feel this is stable, we will release an update

WebSpider commented 1 month ago

Version 1.6.4 has just been released that should fix this. Please update at your earliest convenience and let us know if you are still seeing this.

ChristianForstner commented 1 month ago

Have been running 1.6.4 for a couple of hours and everything seems to be stable now. The error has not occurred and HA core doesn't randomly restart anymore. Great job 👍