mvdwetering/huesyncbox

Integration work only until container recreation/restart

Oliviakrkk opened this issue · 7 comments

Describe the bug
Integration stops working after container with home assistant is restarted or is recreated:
image

If it enters that state I have to remove the sync boxes from the integration and readd them pushing the button on them.

To Reproduce
Configure sync box. Restart container.

Expected behavior
Integration should work normally after restart

Diagnostics

2023-12-13 20:35:27.798 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_10.0.2.36:443/api/v1, None
2023-12-13 20:35:27.799 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_10.0.2.35:443/api/v1, None
2023-12-13 20:35:39.256 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Katarzyna's Sync Box for huesyncbox: Timeout requesting data from 10.0.2.36
Traceback (most recent call last):
  File "/config/deps/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 216, in request
    async with self._clientsession.request(
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 1187, in __aenter__
    self._resp = await self._coro
                 ^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 601, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_reqrep.py", line 960, in start
    with self._timer:
  File "/usr/local/lib/python3.11/site-packages/aiohttp/helpers.py", line 735, in __exit__
    raise asyncio.TimeoutError from None
TimeoutError

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

Traceback (most recent call last):
  File "/config/custom_components/huesyncbox/__init__.py", line 45, in async_setup_entry
    await api.initialize()
  File "/config/deps/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 163, in initialize
    await self.update()
  File "/config/deps/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 174, in update
    response = await self.request("get", "")
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/deps/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 237, in request
    raise RequestError(
aiohuesyncbox.errors.RequestError: Timeout requesting data from 10.0.2.36

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 402, in async_setup
    result = await component.async_setup_entry(hass, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/huesyncbox/__init__.py", line 50, in async_setup_entry
    raise ConfigEntryError(err) from err
homeassistant.exceptions.ConfigEntryError: Timeout requesting data from 10.0.2.36
2023-12-13 20:35:39.260 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry TV Sync Box for huesyncbox: Timeout requesting data from 10.0.2.35
Traceback (most recent call last):
  File "/config/deps/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 216, in request
    async with self._clientsession.request(
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 1187, in __aenter__
    self._resp = await self._coro
                 ^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 601, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_reqrep.py", line 960, in start
    with self._timer:
  File "/usr/local/lib/python3.11/site-packages/aiohttp/helpers.py", line 735, in __exit__
    raise asyncio.TimeoutError from None
TimeoutError

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

Traceback (most recent call last):
  File "/config/custom_components/huesyncbox/__init__.py", line 45, in async_setup_entry
    await api.initialize()
  File "/config/deps/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 163, in initialize
    await self.update()
  File "/config/deps/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 174, in update
    response = await self.request("get", "")
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/deps/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 237, in request
    raise RequestError(
aiohuesyncbox.errors.RequestError: Timeout requesting data from 10.0.2.35

Logging
If there are errors in the Home Assistant logs please add them here.

Environment
Provide details about the versions you are using, which helps to reproduce and find the issue quicker.

  • Home Assistant Core version: 2023.12.2
  • Home Assistant operating environment (OS/Container/Supervised/Core): Container
  • Huesyncbox integration version: v2.0.0.0
  • Last working version (if known): Unknown

Additional info
Add any other info about the problem here.

I tested overall conectivity and it looks good:

>>> requests.get("https://10.0.2.36:443/api/v1", verify=False)
/usr/lib/python3/dist-packages/urllib3/connectionpool.py:1020: InsecureRequestWarning: Unverified HTTPS request is being made to host '10.0.2.36'. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings
  warnings.warn(
<Response [401]>

The only idea I have is that there is "_" in the address? Or it is just the log...?

2023-12-13 20:35:27.798 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_10.0.2.36:443/api/v1, None
2023-12-13 20:35:27.799 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_10.0.2.35:443/api/v1, None

Because of https://github.com/mvdwetering/aiohuesyncbox/blob/8b0cb370bb44e53a39a9063d4ea1cf03e44da0ab/aiohuesyncbox/huesyncbox.py#L184 ?

The _ is only in the log. I add the _ to force a name lookup as the name resolver seemed the only place I could hook into the certificate validation. I should probably improve that log because it confused me also when I was just looking at it. If the _ somehow did not get resolved it should result in a host not found like error, not a timeout.

I am wondering what could be causing this.
At first glance it seems a network issue, but not sure how that would be triggered.

Does this only occur when restarting the whole container or also when you just reload the integration or disable and enable it again?

My normal HA is Home Assistant OS and my dev environment is a manual install on Python, so I will need to setup a container and see if I can reproduce it.

How are you running your container? Docker or something else? Which OS?

Thinking about this a bit more I think there are 2 problems.

  1. it is running into a timeout when starting the container. The timeout is 10 seconds. that should be plenty of time to setup the connection. Could it be that the system is just really busy when starting the container and it does not have enough CPU power to handle the connection in time?

  2. After a setup failure HA should retry setting up the integration again. It looks like I am using the wrong error in the integration, so that explains why it does not retry. I will at least get that fixed soon.

  1. No. My nas is doing almost nothing.. load average: 0.94, 1.41, 0.84 and I have 4 cores..(i3-8100T).
  2. Thanks.

I also did one more test - I disconnected second Hue Sync Box, to make sure this is not a problem with having 2.
Component reload does not break anything.
Container restart with one sync box configured and connected to the network is also braking it.
Disabling and enabling the integration does not break it.

So maybe the fix will work.

I just released 2.0.1 which lets Home Assistant retry the setup if it fails.
Could you give it a try when you have time?

I just updated. I did try to restart the home assistant container and also recreate it. It works with two Sync Boxes configured.

Thank you!

Hmm, with the 2.0.1 update now my Hue integration fails to start ("Failed setup, will retry") after restarting HA. No issues with 2.0.0.

Update: Ignore that, it was the sync box being finicky. Works fine. :-)