mvdwetering/huesyncbox

Cannot connect to Hue Sync Box from HA

smithey253 opened this issue · 12 comments

Describe the bug
I am unable to connect to the Hue Sync Box using the integration in Home Assistant. I get the 'Connection Failed' error. This happens when connecting automatically when suggested through HA and also manually by selecting the integration and entering the details. I have power cycled the sync box, the router, restarted HA numerous times.

To Reproduce
Steps to reproduce the behavior:
I choose the Hue Sync Box Integration
Enter the IP address and Device ID from the Hue app
Click next
The error appears

Expected behavior
Home Assistant should connect to the Hue Sync Box

Diagnostics
No diagnostics as the integration has not yet connected.

Logging
Nothing in HA logs about the integration

Environment
Core
2023.12.0
Supervisor
2023.12.0
Operating System
11.2
Frontend
20231206.0

  • Huesyncbox integration version:
  • v2.0.1
  • Last working version (if known):
  • n/a

Additional info
Initially I thought that it was due to me not using the Hue integration as I bring Hue bulbs in through Smartthings but after adding the Hue Integration, the issue persists.

Since the integration is not loading at all enabling debug logging is a bit more complicated than usual.

Can you add the following section to your configuration.yaml, restart Home Assistant and try again?
I hope there is something in the logs then.

logger:
  default: info
  logs:
    custom_components.huesyncbox: debug
    aiohuesyncbox: debug

Brings back this on the logs:

2023-12-19 20:32:32.228 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_zeroconf, ZeroconfServiceInfo(ip_address=IPv4Address('192.168.86.71'), ip_addresses=[IPv4Address('192.168.86.71')], port=443, hostname='C42996038704.local.', type='_huesync._tcp.local.', name='HueSyncBox-C42996038704._huesync._tcp.local.', properties={'name': 'Sync Box', 'devicetype': 'HSB1', 'uniqueid': 'C42996038704', 'path': '/api'})
2023-12-19 20:32:32.231 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_zeroconf_confirm, None
2023-12-19 20:32:54.399 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_zeroconf_confirm, None
2023-12-19 20:32:55.753 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_zeroconf_confirm, {}
2023-12-19 20:32:55.754 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-19 20:32:55.756 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, ConnectionInfo(host='192.168.86.71', unique_id='C42996038704', access_token=None, registration_id=None, port=443, path='/api')
2023-12-19 20:32:55.763 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] post, https://_192.168.86.71:443/api/v1/registrations, {'appName': 'Home Assistant', 'instanceName': 'Home'}
2023-12-19 20:32:55.788 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-19 20:32:55.799 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, asyncio.CancelledError
2023-12-19 20:32:55.800 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, finally, True
2023-12-19 20:32:55.809 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_abort, None
2023-12-19 20:32:55.809 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_remove, True
2023-12-19 20:33:02.420 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_user, None
2023-12-19 20:33:04.368 INFO (MainThread) [hass_nabucasa.google_report_state] Connected
2023-12-19 20:34:33.304 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_user, {'host': '192.168.86.71', 'unique_id': 'C42996038704'}
2023-12-19 20:34:33.308 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_192.168.86.71:443/api/v1/registrations, None
2023-12-19 20:34:34.975 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] 401, {"code": 2, "message": "Invalid Token"}
2023-12-19 20:34:34.978 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-19 20:34:34.981 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, ConnectionInfo(host='192.168.86.71', unique_id='C42996038704', access_token=None, registration_id=None, port=443, path='/api')
2023-12-19 20:34:34.985 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] post, https://_192.168.86.71:443/api/v1/registrations, {'appName': 'Home Assistant', 'instanceName': 'Home'}
2023-12-19 20:34:35.164 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-19 20:34:35.172 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, asyncio.CancelledError
2023-12-19 20:34:35.173 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, finally, True
2023-12-19 20:34:35.179 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_abort, None
2023-12-19 20:34:35.180 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_remove, True

This is a tough one, for some reason the linking process gets cancelled, but I can't see from the logging.

I added a bit of additional logging to the dev branch, maybe that gives an idea of what could be the cause.
Could you install the "dev" version and try again?

If you are using HACS, choose redownload and make sure the "beta" switch is enabled and then select "dev" from the version list.

I've installed the DEV version, restarted HA and then ran the connection helper again. Here is the log:

2023-12-20 21:48:32.425 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_user, None
2023-12-20 21:49:13.925 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_user, {'host': '192.168.86.71', 'unique_id': 'C42996038704'}
2023-12-20 21:49:13.929 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_192.168.86.71:443/api/v1/registrations, None
2023-12-20 21:49:15.152 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] 401, {"code": 2, "message": "Invalid Token"}
2023-12-20 21:49:15.155 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-20 21:49:15.158 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, ConnectionInfo(host='192.168.86.71', unique_id='C42996038704', access_token=None, registration_id=None, port=443, path='/api')
2023-12-20 21:49:15.162 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] post, https://_192.168.86.71:443/api/v1/registrations, {'appName': 'Home Assistant', 'instanceName': 'Home'}
2023-12-20 21:49:15.191 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-20 21:49:15.200 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, asyncio.CancelledError
2023-12-20 21:49:15.200 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, finally, True
2023-12-20 21:49:15.208 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_abort, None
2023-12-20 21:49:15.209 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_remove, True
2023-12-20 21:51:37.151 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_user, None
2023-12-20 21:52:10.098 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_user, {'host': '192.168.86.71', 'unique_id': 'C42996038704'}
2023-12-20 21:52:10.101 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_192.168.86.71:443/api/v1/registrations, None
2023-12-20 21:52:11.403 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] 401, {"code": 2, "message": "Invalid Token"}
2023-12-20 21:52:11.406 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-20 21:52:11.410 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, ConnectionInfo(host='192.168.86.71', unique_id='C42996038704', access_token=None, registration_id=None, port=443, path='/api')
2023-12-20 21:52:11.413 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] post, https://_192.168.86.71:443/api/v1/registrations, {'appName': 'Home Assistant', 'instanceName': 'Home'}
2023-12-20 21:52:11.425 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-20 21:52:11.433 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, asyncio.CancelledError
2023-12-20 21:52:11.433 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, finally, True
2023-12-20 21:52:11.442 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_abort, None
2023-12-20 21:52:11.442 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_remove, True

Weird... the additional info I expected to be there is not showing.
Can you please double check if you are running dev?

In HACS it should show the text "986a1c7" instead of a normal version like 2.0.1 at the top left.
image

I've redownloaded and it is definitely on the dev version now

Here is the log info after running the connection helper again:

2023-12-23 16:39:12.104 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_user, None
2023-12-23 16:40:06.729 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_user, {'host': '192.168.86.71', 'unique_id': 'C42996038704'}
2023-12-23 16:40:06.733 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] get, https://_192.168.86.71:443/api/v1/registrations, None
2023-12-23 16:40:07.976 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] 401, {"code": 2, "message": "Invalid Token"}
2023-12-23 16:40:07.979 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-23 16:40:07.982 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, ConnectionInfo(host='192.168.86.71', unique_id='C42996038704', access_token=None, registration_id=None, port=443, path='/api')
2023-12-23 16:40:07.989 DEBUG (MainThread) [aiohuesyncbox.huesyncbox] post, https://_192.168.86.71:443/api/v1/registrations, {'appName': 'Home Assistant', 'instanceName': 'Home'}
2023-12-23 16:40:08.010 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_link, None
2023-12-23 16:40:08.020 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, asyncio.CancelledError
Traceback (most recent call last):
File "/config/custom_components/huesyncbox/config_flow.py", line 195, in _async_register
registration_info = await huesyncbox.register(
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/aiohuesyncbox/huesyncbox.py", line 139, in register
response = await self.request(
^^^^^^^^^^^^^^^^^^^
File "/usr/local/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 574, in _request
conn = await self._connector.connect(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/aiohttp/connector.py", line 544, in connect
proto = await self._create_connection(req, traces, timeout)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/aiohttp/connector.py", line 911, in _create_connection
_, proto = await self._create_direct_connection(req, traces, timeout)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/aiohttp/connector.py", line 1204, in _create_direct_connection
transp, proto = await self._wrap_create_connection(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/aiohttp/connector.py", line 992, in _wrap_create_connection
return await self._loop.create_connection(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/asyncio/base_events.py", line 1112, in create_connection
transport, protocol = await self._create_connection_transport(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/asyncio/base_events.py", line 1145, in _create_connection_transport
await waiter
asyncio.exceptions.CancelledError
2023-12-23 16:40:08.036 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] _async_register, finally, True
2023-12-23 16:40:08.040 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_step_abort, None
2023-12-23 16:40:08.040 DEBUG (MainThread) [custom_components.huesyncbox.config_flow] async_remove, True

I have been looking into this, but unfortunately I am running out of ideas.

With the latest logging I can see that it gets Cancelled somewhere deep in standard Python code, but I can't see why it is cancelled or by whom. Searching on the internet did not result in any good leads.

So not sure what to try next :(

No worries, thank you so much for trying to get it working! Much appreciated.

Hey

Coming back to this, the issue has now been resolved and I have connected to HueSync through HA.

Thanks for all of your help!

Great to hear it works now.

Do you happen to know what solved it?
It might help out someone in the future that has the same issue

Hey

Unfortunately I do not, HueSyncBox was still on the dev version when it started working. It could have been a HA update that had fixed it. Updated to the most recent version of HueSyncBox and still working.

Ok, I will close the issue then