White LED lamp connection issues

[Toopala]

I managed to install the integration and sync my account and it fetched the correct light bulb. Integration added the light entity correctly but I cannot interact with it. For what I can gather from the logs, it clearly finds something but isn't quite happy:

2021-01-17 18:40:50 DEBUG (MainThread) [custom_components.awox.awox_mesh] Finished fetching awox data in 5.009 seconds
2021-01-17 18:40:50 INFO (MainThread) [custom_components.awox.awox_mesh] Shutdown mesh
2021-01-17 18:40:50 INFO (MainThread) [custom_components.awox] setup config flow entry {'mesh_name': 'xxxxxx', 'mesh_password': 'xxxxxx', 'mesh_key': 'xxxxx', 'devices': [{'mesh_id': xxxxx, 'name': 'EGLOBulb', 'mac': 'a4:c1:xx:xx:xx:xx', 'model': 'ESMLm-w9w', 'manufacturer': 'AwoxByEglo', 'firmware': '1.6.27', 'hardware': '4.0', 'type': '.ble.tlmesh.light.switch.white.dimming.', 'supported_features': 1}]}
2021-01-17 18:40:50 DEBUG (MainThread) [custom_components.awox.light] entry [{'mesh_id': xxxxx, 'name': 'EGLOBulb', 'mac': 'a4:c1:xx:xx:xx:xx', 'model': 'ESMLm-w9w', 'manufacturer': 'AwoxByEglo', 'firmware': '1.6.27', 'hardware': '4.0', 'type': '.ble.tlmesh.light.switch.white.dimming.', 'supported_features': 1}]
2021-01-17 18:40:50 INFO (MainThread) [custom_components.awox.awox_mesh] Registered [a4:c1:xx:xx:xx:xx] xxxxx
2021-01-17 18:40:50 INFO (MainThread) [custom_components.awox.light] setup entry [xxxxx] EGLOBulb
2021-01-17 18:40:50 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Trying to connect
2021-01-17 18:40:50 WARNING (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Failed to connect, trying next device [Failed to connect to peripheral a4:c1:xx:xx:xx:xx, addr type: public]
2021-01-17 18:40:50 ERROR (MainThread) [custom_components.awox.awox_mesh] Error fetching awox data: No device connected

[fsaris]

Sometimes it doesn't want to connect the first time. Not exactly sure yet why, but normally it will a second or third attempt.

It should try to connect again after 30seconds.

[Toopala]

Yeah it seems that it tries to reconnect but now it get following errors in regular basis:

2021-01-17 20:40:48 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Trying to connect
2021-01-17 20:40:49 WARNING (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Failed to connect, trying next device [Bluetooth command failed (code: 14, error: Request attribute has encountered an unlikely error)]
2021-01-17 20:40:49 DEBUG (MainThread) [custom_components.awox.awox_mesh] Finished fetching awox data in 1.612 seconds
2021-01-17 20:41:19 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Trying to connect
2021-01-17 20:41:19 WARNING (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Failed to connect, trying next device [Failed to connect to peripheral a4:c1:xx:xx:xx:xx, addr type: public]
2021-01-17 20:41:19 DEBUG (MainThread) [custom_components.awox.awox_mesh] Finished fetching awox data in 0.849 seconds
2021-01-17 20:41:49 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Trying to connect
2021-01-17 20:41:49 WARNING (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Failed to connect, trying next device [Failed to connect to peripheral a4:c1:xx:xx:xx:xx, addr type: public]
2021-01-17 20:41:49 DEBUG (MainThread) [custom_components.awox.awox_mesh] Finished fetching awox data in 0.550 seconds
2021-01-17 20:42:19 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Trying to connect
2021-01-17 20:42:19 WARNING (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Failed to connect, trying next device [Bluetooth command failed (code: 14, error: Request attribute has encountered an unlikely error)]
2021-01-17 20:42:19 DEBUG (MainThread) [custom_components.awox.awox_mesh] Finished fetching awox data in 0.827 seconds
2021-01-17 20:42:49 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Trying to connect
2021-01-17 20:42:49 WARNING (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Failed to connect, trying next device [Failed to connect to peripheral a4:c1:xx:xx:xx:xx, addr type: public]
2021-01-17 20:42:49 DEBUG (MainThread) [custom_components.awox.awox_mesh] Finished fetching awox data in 0.497 seconds

Other bluetooth devices work just fine

[fsaris]

Is it close enough to the HA system to connect?

With the 0.0.2 version you should get a rssi value in the logs. On startup is tries to detect which device from the mesh is closest

[Toopala]

Yeah I've been testing that the bulb is right next to the server.

When I scan for devices with bluetoothctl it finds the MAC address which matches the mesh name:

A4:C1:xx:xx:xx:xx Caylxxxxx

Here's more log after updating to 0.0.2:

2021-01-17 21:29:36 INFO (MainThread) [custom_components.awox] setup config flow entry {'mesh_name': 'Caylxxxxx', 'mesh_password': 'xxxxxxxx', 'mesh_key': 'xxxxxxxx', 'devices': [{'mesh_id': xxxxx, 'name': 'EGLOBulb', 'mac': 'a4:c1:xx:xx:xx:xx', 'model': 'ESMLm-w9w', 'manufacturer': 'AwoxByEglo', 'firmware': '1.6.27', 'hardware': '4.0', 'type': '.ble.tlmesh.light.switch.white.dimming.', 'supported_features': 1}]}
2021-01-17 21:29:36 DEBUG (AwoxMeshCommands-Caylxxxxx) [custom_components.awox.awox_mesh] get item from queue
2021-01-17 21:29:36 DEBUG (MainThread) [custom_components.awox.light] entry [{'mesh_id': xxxxx, 'name': 'EGLOBulb', 'mac': 'a4:c1:xx:xx:xx:xx', 'model': 'ESMLm-w9w', 'manufacturer': 'AwoxByEglo', 'firmware': '1.6.27', 'hardware': '4.0', 'type': '.ble.tlmesh.light.switch.white.dimming.', 'supported_features': 1}]
2021-01-17 21:29:36 INFO (MainThread) [custom_components.awox.awox_mesh] Registered [a4:c1:xx:xx:xx:xx] xxxxx
2021-01-17 21:29:36 INFO (MainThread) [custom_components.awox.light] setup entry [xxxxx] EGLOBulb
2021-01-17 21:30:06 INFO (MainThread) [custom_components.awox.awox_mesh] Search for AwoX devices to find closest (best rssi value) device
2021-01-17 21:30:06 INFO (MainThread) [custom_components.awox.scanner] Scanning 30 seconds for AwoX bluetooth mesh devices!
2021-01-17 21:30:36 DEBUG (MainThread) [custom_components.awox.awox_mesh] devices: {'a4:c1:xx:xx:xx:xx': {'mac': 'a4:c1:xx:xx:xx:xx', 'name': 'Caylxxxxx', 'rssi': None}}
2021-01-17 21:30:36 INFO (MainThread) [custom_components.awox.awox_mesh] async_update: Request status
2021-01-17 21:30:36 DEBUG (AwoxMeshCommands-Caylxxxxx) [custom_components.awox.awox_mesh] process 0/0 - {'command': 'requestStatus', 'params': {'dest': xxxxx, 'withResponse': True}, 'callback': <function AwoxMesh._async_add_command_to_queue.<locals>.command_executed at 0x7f1141cdbc10>, 'allow_to_fail': False}
2021-01-17 21:30:36 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Trying to connect
2021-01-17 21:30:36 DEBUG (SyncWorker_8) [custom_components.awox.awoxmeshlight] _waitResp - set timeout to 5
2021-01-17 21:30:36 DEBUG (SyncWorker_8) [custom_components.awox.awoxmeshlight] _waitResp - set timeout to 5
2021-01-17 21:30:36 DEBUG (SyncWorker_8) [custom_components.awox.awoxmeshlight] _waitResp - resp [{'rsp': ['stat'], 'state': ['tryconn'], 'dst': ['a4:c1:xx:xx:xx:xx'], 'mtu': [0], 'sec': ['low']}]
2021-01-17 21:30:36 DEBUG (SyncWorker_8) [custom_components.awox.awoxmeshlight] _waitResp - set timeout to 5
2021-01-17 21:30:37 DEBUG (SyncWorker_8) [custom_components.awox.awoxmeshlight] _waitResp - resp [{'rsp': ['stat'], 'state': ['conn'], 'dst': ['a4:c1:xx:xx:xx:xx'], 'mtu': [0], 'sec': ['low']}]
2021-01-17 21:30:37 INFO (MainThread) [custom_components.awox.awox_mesh] [a4:c1:xx:xx:xx:xx][EGLOBulb] Failed to connect, trying next device [Bluetooth command failed (code: 14, error: Request attribute has encountered an unlikely error)]

Also I'm running newest core and HassOS:

Version supervisor-2021.01.4 Version core-2021.1.4

[fsaris]

[custom_components.awox.awox_mesh] devices: {'a4:c1:xx:xx:xx:xx': {'mac': 'a4:c1:xx:xx:xx:xx', 'name': 'Caylxxxxx', 'rssi': None}}

Looks like your Homeassistent system doesn't find the light after a 30 seconds scan of bluetoothctl (code is using bluetoothctl under the hood).

How long does it take to find the light if you run it manually?

[Toopala]

Now it seems it found the signal:

2021-01-17 22:18:17 INFO (MainThread) [custom_components.awox.scanner] Scanning 30 seconds for AwoX bluetooth mesh devices!
2021-01-17 22:18:48 DEBUG (MainThread) [custom_components.awox.awox_mesh] devices: {'A4:C1:xx:xx:xx:xx': {'mac': 'A4:C1:xx:xx:xx:xx', 'name': 'Caylxxxx', 'rssi': -64}}
2021-01-17 22:18:48 INFO (MainThread) [custom_components.awox.awox_mesh] async_update: Request status
2021-01-17 22:18:48 DEBUG (AwoxMeshCommands-Caylxxxx) [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 0x7f113d786430>, 'allow_to_fail': False}
2021-01-17 22:18:48 INFO (MainThread) [custom_components.awox.awox_mesh] [A4:C1:xx:xx:xx:xx][EGLOBulb] Trying to connect
2021-01-17 22:18:48 DEBUG (SyncWorker_43) [custom_components.awox.awoxmeshlight] _waitResp - set timeout to 5
2021-01-17 22:18:48 DEBUG (SyncWorker_43) [custom_components.awox.awoxmeshlight] _waitResp - set timeout to 5
2021-01-17 22:18:48 DEBUG (SyncWorker_43) [custom_components.awox.awoxmeshlight] _waitResp - resp [{'rsp': ['stat'], 'state': ['tryconn'], 'dst': ['A4:C1:xx:xx:xx:xx'], 'mtu': [0], 'sec': ['low']}]
2021-01-17 22:18:48 DEBUG (SyncWorker_43) [custom_components.awox.awoxmeshlight] _waitResp - set timeout to 5
2021-01-17 22:18:48 DEBUG (SyncWorker_43) [custom_components.awox.awoxmeshlight] _waitResp - resp [{'rsp': ['stat'], 'state': ['conn'], 'dst': ['A4:C1:xx:xx:xx:xx'], 'mtu': [0], 'sec': ['low']}]

But the light is still inoperable.

Another thing I noticed, when I reloaded the integration from the ui the HassOS's virtual machine outputs loads of these rows to console: Bluetooth: hci0: advertising data len corrected and cpu usage jumps to 100%

[fsaris]

Bluetooth: hci0: advertising data len corrected

Had also a lot of these messages last week. They went away after a reboot of the host.

Not sure what the reason was looked like the bluetooth adapter didn't correctly release some processes for some reason

[fsaris]

Do you still have the high cpu load?

[Toopala]

Sorry for delayed answer but haven't had time to tinker lately. CPU load is not high anymore, but I still can't get the bulb to work.
I still get these messages in HassOS's virtual machine: Bluetooth: hci0: advertising data len corrected

When I install the integration, it discovers my bulb, but I cannot interact with it.

[fsaris]

There were some more connection improvements last month. But not directly related to the initial connect.

If you still have issues please provide some more logs.