search

fsaris / home-assistant-awox

AwoX mesh light integration for Home Assistant
MIT License
83 stars 23 forks source link

Devices not available "Timed out connecting to ... after 15 seconds." #62

Closed immortaly007 closed 1 year ago

immortaly007 commented 1 year ago

Hi,

I have some Eglo Connect E27 bulbs (ESML-c9i, version 2.2.6 (HW 4.0)) that I'd love to connect to Home Assistant. I installed the latest beta of this integration to do that (1.3b3). The reason I'm using this beta version is the conflict with the latest HA (https://github.com/fsaris/home-assistant-awox/issues/59). Installation and login to my Awox account went well after switching to the beta. But I can't get the Awox lights to connect. I'm not sure if the issue is related to the bluetooth dongle (TP-Link UB500 Nano), an issue in the integration, or something else.

Environment: Home Assistant 2022.8.7. Running in "container" mode on Debian 10. The bluetooth controller seems to be available:

> docker-compose exec homeassistant bluetoothctl list
Controller E8:48:B8:C8:20:00 WHEATLEY [default]

The lights are quite close to the bluetooth dongle (the "corner lamp" is ~2.5m away).

Below, the logs from Home Assistant:

2022-09-16 01:07:19.884 DEBUG (SyncWorker_5) [custom_components.awox.awox_mesh] startup
2022-09-16 01:07:20.465 INFO (MainThread) [custom_components.awox.awox_mesh] Search for AwoX devices to find closest (best RSSI value) device
2022-09-16 01:07:21.566 INFO (MainThread) [custom_components.awox.scanner] Scanning 20 seconds for AwoX bluetooth mesh devices!
2022-09-16 01:07:41.744 INFO (SyncWorker_1) [custom_components.awox.bluetoothctl] found: {}
2022-09-16 01:07:41.744 DEBUG (MainThread) [custom_components.awox.scanner] Found devices: {}
2022-09-16 01:07:42.012 DEBUG (MainThread) [custom_components.awox.awox_mesh] Scan result: {}
2022-09-16 01:07:42.012 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:82:66:42][EGLO PLUG PLUS] Device NOT found during Bluetooth scan
2022-09-16 01:07:42.012 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:e7:07:58][Corner Lamp ] Device NOT found during Bluetooth scan
2022-09-16 01:07:42.012 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:90:69:da][Little Lampv2] Device NOT found during Bluetooth scan
2022-09-16 01:07:42.012 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:e6:29:5b][Lamp 1v2] Device NOT found during Bluetooth scan
2022-09-16 01:07:42.013 INFO (MainThread) [custom_components.awox.awox_mesh] async_update: Request status
2022-09-16 01:07:42.013 INFO (MainThread) [custom_components.awox.awox_mesh] Queue command requestStatus {'dest': 65535, 'withResponse': True}
2022-09-16 01:07:42.013 DEBUG (AwoxMeshCommands-Mze8RdZa) [custom_components.awox.awox_mesh] process 0/0 - {'command': 'requestStatus', 'params': {'dest': 65535, 'withResponse': True}, 'callback': <function AwoxMesh._async_add_command_to_queue.<locals>.command_executed at 0x7fba53485630>, 'allow_to_fail': False}
2022-09-16 01:07:42.015 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:82:66:42][EGLO PLUG PLUS] Trying to connect
2022-09-16 01:07:42.393 INFO (SyncWorker_1) [custom_components.awox.awoxmeshlight] Connecting to a4:c1:38:82:66:42 with timeout=15
2022-09-16 01:07:57.494 ERROR (SyncWorker_1) [custom_components.awox.awoxmeshlight] Timed out connecting to a4:c1:38:82:66:42 after 15 seconds.
2022-09-16 01:07:57.496 ERROR (MainThread) [custom_components.awox.awox_mesh] exception Timed out connecting to a4:c1:38:82:66:42 after 15 seconds.
Traceback (most recent call last):
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 101, in connect
with self._receiver.event("connect", timeout):
File "/usr/local/lib/python3.10/contextlib.py", line 142, in __exit__
next(self.gen)
File "/usr/local/lib/python3.10/site-packages/pygatt/backends/gatttool/gatttool.py", line 191, in event
self.wait(event, timeout)
File "/usr/local/lib/python3.10/site-packages/pygatt/backends/gatttool/gatttool.py", line 157, in wait
raise NotificationTimeout()
pygatt.exceptions.NotificationTimeout: None
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/config/custom_components/awox/awox_mesh.py", line 324, in _async_connect_device
if await self.hass.async_add_executor_job(device.connect):
File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 196, in connect
self.btdevice = self.adapter.connect(self.mac, timeout=15)
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 108, in connect
raise NotConnectedError(message)
pygatt.exceptions.NotConnectedError: Timed out connecting to a4:c1:38:82:66:42 after 15 seconds.
2022-09-16 01:07:57.498 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:82:66:42][EGLO PLUG PLUS] Failed to connect, trying next device [Timed out connecting to a4:c1:38:82:66:42 after 15 seconds.]
2022-09-16 01:07:57.498 DEBUG (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:82:66:42][EGLO PLUG PLUS] Setting up Bluetooth connection failed, making sure Bluetooth device stops trying
2022-09-16 01:07:57.499 DEBUG (SyncWorker_4) [custom_components.awox.awoxmeshlight] force stopping ble adapter
2022-09-16 01:07:57.800 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:e7:07:58][Corner Lamp ] Trying to connect
2022-09-16 01:07:58.151 INFO (SyncWorker_0) [custom_components.awox.awoxmeshlight] Connecting to a4:c1:38:e7:07:58 with timeout=15
2022-09-16 01:08:02.014 ERROR (MainThread) [custom_components.awox.awox_mesh] Timeout fetching awox data
2022-09-16 01:08:02.016 DEBUG (MainThread) [custom_components.awox.awox_mesh] Finished fetching awox data in 41.551 seconds (success: False)
2022-09-16 01:08:13.252 ERROR (SyncWorker_0) [custom_components.awox.awoxmeshlight] Timed out connecting to a4:c1:38:e7:07:58 after 15 seconds.
2022-09-16 01:08:13.253 ERROR (MainThread) [custom_components.awox.awox_mesh] exception Timed out connecting to a4:c1:38:e7:07:58 after 15 seconds.
Traceback (most recent call last):
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 101, in connect
with self._receiver.event("connect", timeout):
File "/usr/local/lib/python3.10/contextlib.py", line 142, in __exit__
next(self.gen)
File "/usr/local/lib/python3.10/site-packages/pygatt/backends/gatttool/gatttool.py", line 191, in event
self.wait(event, timeout)
File "/usr/local/lib/python3.10/site-packages/pygatt/backends/gatttool/gatttool.py", line 157, in wait
raise NotificationTimeout()
pygatt.exceptions.NotificationTimeout: None
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/config/custom_components/awox/awox_mesh.py", line 324, in _async_connect_device
if await self.hass.async_add_executor_job(device.connect):
File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 196, in connect
self.btdevice = self.adapter.connect(self.mac, timeout=15)
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 108, in connect
raise NotConnectedError(message)
pygatt.exceptions.NotConnectedError: Timed out connecting to a4:c1:38:e7:07:58 after 15 seconds.
2022-09-16 01:08:13.254 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:e7:07:58][Corner Lamp ] Failed to connect, trying next device [Timed out connecting to a4:c1:38:e7:07:58 after 15 seconds.]
2022-09-16 01:08:13.254 DEBUG (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:e7:07:58][Corner Lamp ] Setting up Bluetooth connection failed, making sure Bluetooth device stops trying
2022-09-16 01:08:13.254 DEBUG (SyncWorker_5) [custom_components.awox.awoxmeshlight] force stopping ble adapter
fsaris commented 1 year ago

Your Bluetooth device isn't able to find the lights. Is your Bluetooth controller in reach of one of your lights?

Maybe you could test this also directly in the container by using the command hcitool lescan

immortaly007 commented 1 year ago

Hi fsaris, thanks for the quick response! Although (at least one of) the lamps are quite close to the bluetooth adapter ( < 3 m), hcitool lescan gives no other output then LE Scan .... I also tried bluetoothctl scan on, which has the same result. So either my bluetooth adapter is not (quite) working yet. Or the devices are too far away.

immortaly007 commented 1 year ago

Should the lamps be in a specific state? I.e. on or off? Or should they be reset or somehow set to "pairing" mode?

fsaris commented 1 year ago

Should the lamps be in a specific state? I.e. on or off? Or should they be reset or somehow set to "pairing" mode?

Just make sure they have power. They should be initial paired with your awox account that's what the integration uses to get the needed credentials

ZTHawk commented 1 year ago

I have the same issue. Smartphone can connect without any issue (it is further away than my HA device). Before upgrade to 2022.7 my HA device could always connect via bluetooth. Position (distance) has not changed since then.

fsaris commented 1 year ago

@ZTHawk can you provide some debug logs?

ZTHawk commented 1 year ago

Here is an extract. Two of my four devices. It is the same for the other two and then repeats.

2022-09-17 22:55:38.130 DEBUG (SyncWorker_4) [custom_components.awox.awox_mesh] startup
2022-09-17 22:55:38.163 INFO (MainThread) [custom_components.awox.awox_mesh] Search for AwoX devices to find closest (best RSSI value) device
2022-09-17 22:55:38.865 INFO (MainThread) [custom_components.awox.scanner] Scanning 20 seconds for AwoX bluetooth mesh devices!
2022-09-17 22:55:59.052 INFO (SyncWorker_7) [custom_components.awox.bluetoothctl] found: {}
2022-09-17 22:55:59.053 DEBUG (MainThread) [custom_components.awox.scanner] Found devices: {}
2022-09-17 22:55:59.227 WARNING (MainThread) [homeassistant.util.async_] Detected blocking call to sleep inside the event loop. This is causing stability issues. Please report issue to the custom integration author for awox doing blocking calls at custom_components/awox/awox_mesh.py, line 346: devices = await DeviceScanner.async_find_devices(hass=self.hass, scan_timeout=20)
2022-09-17 22:55:59.335 DEBUG (MainThread) [custom_components.awox.awox_mesh] Scan result: {}
2022-09-17 22:55:59.336 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:b8:11:29][Lampe über Treppe] Device NOT found during Bluetooth scan
2022-09-17 22:55:59.336 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:2b:d6:b6][Lampe vor K2] Device NOT found during Bluetooth scan
2022-09-17 22:55:59.337 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:ce:52:6a][Lampe vor Bad] Device NOT found during Bluetooth scan
2022-09-17 22:55:59.337 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:64:7a:3e][Lampe vor E] Device NOT found during Bluetooth scan
2022-09-17 22:55:59.338 INFO (MainThread) [custom_components.awox.awox_mesh] async_update: Request status
2022-09-17 22:55:59.338 INFO (MainThread) [custom_components.awox.awox_mesh] Queue command requestStatus {'dest': 65535, 'withResponse': True}
2022-09-17 22:55:59.341 DEBUG (AwoxMeshCommands-ntOc9VHB) [custom_components.awox.awox_mesh] process 0/0 - {'command': 'requestStatus', 'params': {'dest': 65535, 'withResponse': True}, 'callback': <function AwoxMesh._async_add_command_to_queue.<locals>.command_executed at 0x7f6a27fd8430>, 'allow_to_fail': False}
2022-09-17 22:55:59.343 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:b8:11:29][Lampe über Treppe] Trying to connect
2022-09-17 22:55:59.761 INFO (SyncWorker_1) [custom_components.awox.awoxmeshlight] Connecting to a4:c1:38:b8:11:29 with timeout=15
2022-09-17 22:56:14.863 ERROR (SyncWorker_1) [custom_components.awox.awoxmeshlight] Timed out connecting to a4:c1:38:b8:11:29 after 15 seconds.
2022-09-17 22:56:14.869 ERROR (MainThread) [custom_components.awox.awox_mesh] exception Timed out connecting to a4:c1:38:b8:11:29 after 15 seconds.
Traceback (most recent call last):
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 101, in connect
with self._receiver.event("connect", timeout):
File "/usr/local/lib/python3.10/contextlib.py", line 142, in __exit__
next(self.gen)
File "/usr/local/lib/python3.10/site-packages/pygatt/backends/gatttool/gatttool.py", line 191, in event
self.wait(event, timeout)
File "/usr/local/lib/python3.10/site-packages/pygatt/backends/gatttool/gatttool.py", line 157, in wait
raise NotificationTimeout()
pygatt.exceptions.NotificationTimeout: None
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/config/custom_components/awox/awox_mesh.py", line 324, in _async_connect_device
if await self.hass.async_add_executor_job(device.connect):
File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 196, in connect
self.btdevice = self.adapter.connect(self.mac, timeout=15)
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 108, in connect
raise NotConnectedError(message)
pygatt.exceptions.NotConnectedError: Timed out connecting to a4:c1:38:b8:11:29 after 15 seconds.
2022-09-17 22:56:14.873 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:b8:11:29][Lampe über Treppe] Failed to connect, trying next device [Timed out connecting to a4:c1:38:b8:11:29 after 15 seconds.]
2022-09-17 22:56:14.873 DEBUG (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:b8:11:29][Lampe über Treppe] Setting up Bluetooth connection failed, making sure Bluetooth device stops trying
2022-09-17 22:56:14.873 DEBUG (SyncWorker_7) [custom_components.awox.awoxmeshlight] force stopping ble adapter
2022-09-17 22:56:15.178 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:2b:d6:b6][Lampe vor K2] Trying to connect
2022-09-17 22:56:15.537 INFO (SyncWorker_0) [custom_components.awox.awoxmeshlight] Connecting to a4:c1:38:2b:d6:b6 with timeout=15
2022-09-17 22:56:19.338 ERROR (MainThread) [custom_components.awox.awox_mesh] Timeout fetching awox data
2022-09-17 22:56:19.344 DEBUG (MainThread) [custom_components.awox.awox_mesh] Finished fetching awox data in 41.181 seconds (success: False)
2022-09-17 22:56:30.648 ERROR (SyncWorker_0) [custom_components.awox.awoxmeshlight] Timed out connecting to a4:c1:38:2b:d6:b6 after 15 seconds.
2022-09-17 22:56:30.651 ERROR (MainThread) [custom_components.awox.awox_mesh] exception Timed out connecting to a4:c1:38:2b:d6:b6 after 15 seconds.
Traceback (most recent call last):
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 101, in connect
with self._receiver.event("connect", timeout):
File "/usr/local/lib/python3.10/contextlib.py", line 142, in __exit__
next(self.gen)
File "/usr/local/lib/python3.10/site-packages/pygatt/backends/gatttool/gatttool.py", line 191, in event
self.wait(event, timeout)
File "/usr/local/lib/python3.10/site-packages/pygatt/backends/gatttool/gatttool.py", line 157, in wait
raise NotificationTimeout()
pygatt.exceptions.NotificationTimeout: None
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/config/custom_components/awox/awox_mesh.py", line 324, in _async_connect_device
if await self.hass.async_add_executor_job(device.connect):
File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 196, in connect
self.btdevice = self.adapter.connect(self.mac, timeout=15)
File "/config/custom_components/awox/awoxmeshlight/__init__.py", line 108, in connect
raise NotConnectedError(message)
pygatt.exceptions.NotConnectedError: Timed out connecting to a4:c1:38:2b:d6:b6 after 15 seconds.
2022-09-17 22:56:30.654 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:2b:d6:b6][Lampe vor K2] Failed to connect, trying next device [Timed out connecting to a4:c1:38:2b:d6:b6 after 15 seconds.]
2022-09-17 22:56:30.655 DEBUG (MainThread) [custom_components.awox.awox_mesh] [a4:c1:38:2b:d6:b6][Lampe vor K2] Setting up Bluetooth connection failed, making sure Bluetooth device stops trying
2022-09-17 22:56:30.655 DEBUG (SyncWorker_6) [custom_components.awox.awoxmeshlight] force stopping ble adapter
fsaris commented 1 year ago

@ZTHawk strange the Bluetooth scan doesn't find any device to connect. Do you have the HA Bluetooth integration enabled? Maybe that is claiming the Bluetooth controller

fsaris commented 1 year ago

End try to do a BLE scan directly on your host to check if it can find some Bluetooth devices just to be sure nothing else broke after upgrade of HA.

Run hcitool lescan or bluetoothctl and then scan on

immortaly007 commented 1 year ago

IMG20220918141333 For testing purposes, i put one of the lamps right next to the bluetooth adapter (as shown in the picture). But still the adapter can't seem to find it (this time directly from the host, not inside the container):

> /opt/pihole# hcitool lescan
Enable scan failed: Input/output error
 > /opt/pihole# bluetoothctl
Agent registered
[CHG] Controller E8:48:B8:C8:20:00 Pairable: yes
[bluetooth]# scan on
Discovery started
[CHG] Controller E8:48:B8:C8:20:00 Discovering: yes
[bluetooth]#

But nothing is found. I even put my soundbar in "pairing mode" to see if it would show up but it didn't. So I'm thinking something is up with the bluetooth adapter itself, or the awox plugin is claiming it so my direct commands don't work.

ZTHawk commented 1 year ago

It seems that my bluetooth adapter is not working.

Bluetooth: hci0: command 0xfc01 tx timeout
Bluetooth: hci0: FW download error recovery failed (-110)

HA is running in a virtual machine (virtualbox). But the bluetooth adapter was running before HA changed the bluetooth driver. Host system does recognize the bluetooth adapter and scanning is working fine.

I created an issue on HA board: https://github.com/home-assistant/operating-system/issues/2142

fsaris commented 1 year ago

Sorry can't help with that. I have it running in docker supervised