search

sopelj / hass-ember-mug-component

Ember Mug Integration for Home Assistant
MIT License
116 stars 4 forks source link

Ember integration not working in Home Assistant OS #32

Closed rybackisback closed 9 months ago

rybackisback commented 1 year ago

Home Assistant Version (eg. 2023.6.2): Ember Mug Component Version (eg. 0.7.1): Which device(s) are you using for Bluetooth (e.g. Bluetooth Dongle / ESPHome Proxy): Intel NUC built in bluetooth

Description

Describe what you were trying to get done. Trying to install ember mug integration after moving from Ubuntu 22.04 LTS to Home Assistant OS version 10.3

What I Did

I tried re-installing the inetgration I tried running running command bluetoth ctl from terminal Paste the command(s) you ran and the output.

Logs / Errors

Logger: ember_mug.mug Source: custom_components/ember_mug/coordinator.py:62 Integration: Ember Mug (documentation, issues) First occurred: June 22, 2023 at 7:40:09 PM (855 occurrences) Last logged: 9:24:11 AM

xxxxxx: Ember Ceramic Mug: Failed to connect to the mug: xxxxx - xxxxxx: Failed to connect: xxxxxx: Ember Ceramic Mug: Failed to connect to the mug: xxxxxx - xxxxxx: Failed to connect: [org.bluez.Error.Failed] Operation already in progress

seanre453 commented 1 year ago

I'm able to replicate the exact same behavior on a Raspberry Pi 4 with the following system details:

Also followed all troubleshooting in readme to no avail, as well as uninstall/reinstall component and ran bluetoothctl.

The device appears to be initially detected when instantiating the integration, as the configuration page with the MAC address and Celsius/Fahrenheit selector does appear. However, hitting submit results in a 'this integration has been successfully configured' message, after which it keeps getting stuck in this 'Failed to Connect / Operation already in progress' loop without generating any entities.

This error originated from a custom integration.

Logger: custom_components.ember_mug.coordinator
Source: custom_components/ember_mug/coordinator.py:72
Integration: Ember Mug (documentation, issues)
First occurred: 11:33:19 PM (21 occurrences)
Last logged: 11:45:34 PM

An error occurred whilst updating the Ember Ceramic Mug: (xx:xx:xx:xx:xx:xx) - xx:xx:xx:xx:xx:xx: Failed to connect: [org.bluez.Error.Failed] Operation already in progress
An error occurred whilst updating the Ember Ceramic Mug: (xx:xx:xx:xx:xx:xx) - xx:xx:xx:xx:xx:xx: Failed to connect:
sopelj commented 1 year ago

Oh ok, thank you very much for your testing and confirming the issue. Would it be possible to perhaps try with debugging enabled for the integration and associated Bluetooth libraries, perhaps to see if anything sticks out?

logger:
    default: error  # or whatever you want
    logs:
      custom_components.ember_mug: debug
      ember_mug: debug
      bleak.backends.bluezdbus.client: debug
      bleak_retry_connector: debug
seanre453 commented 1 year ago

Hey @sopelj ;

Deleted previous comment, sorry; it was a long day at work and the mug was inactive, so deleted errors were legit because it couldn't be detected. The following output is between 'failed to connect' errors after I actively re-paired the mug before it turned off:

2023-06-27 23:21:02.380 ERROR (MainThread) [ember_mug.mug] F6:77:49:00:E2:23: Ember Ceramic Mug: Failed to connect to the mug: (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect:
2023-06-27 23:21:02.511 ERROR (MainThread) [custom_components.ember_mug.coordinator] An error occurred whilst updating the Ember Ceramic Mug: (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect:
2023-06-27 23:21:02.515 DEBUG (MainThread) [custom_components.ember_mug] Finished fetching ember-mug-f6774900e223 data in 61.467 seconds (success: False)
2023-06-27 23:21:02.515 DEBUG (MainThread) [ember_mug.mug] Unregistered callback: <function async_setup_entry.<locals>.<lambda> at 0x7f5f6d5260>
2023-06-27 23:21:07.568 DEBUG (MainThread) [ember_mug.mug] New mug connection initialized.
2023-06-27 23:21:07.569 DEBUG (MainThread) [ember_mug.mug] Registered callback: <bound method MugDataUpdateCoordinator._async_handle_callback of <custom_components.ember_mug.coordinator.MugDataUpdateCoordinator object at 0x7f59c83490>>
2023-06-27 23:21:07.569 INFO (MainThread) [custom_components.ember_mug.coordinator] Ember Ceramic Mug ember-mug-f6774900e223 Setup
2023-06-27 23:21:07.569 DEBUG (MainThread) [ember_mug.mug] Registered callback: <function async_setup_entry.<locals>.<lambda> at 0x7f65920180>
2023-06-27 23:21:07.569 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Bluetooth event. Service Info: <home_assistant_bluetooth.models.BluetoothServiceInfoBleak object at 0x7f6591ca40>, change: BluetoothChange.ADVERTISEMENT
2023-06-27 23:21:07.570 DEBUG (MainThread) [ember_mug.mug] Set new device from F6:77:49:00:E2:23: Ember Ceramic Mug to F6:77:49:00:E2:23: Ember Ceramic Mug
2023-06-27 23:21:07.570 DEBUG (MainThread) [ember_mug.mug] Callback <bound method MugDataUpdateCoordinator._async_handle_callback of <custom_components.ember_mug.coordinator.MugDataUpdateCoordinator object at 0x7f59c83490>> already registered
2023-06-27 23:21:07.570 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Updating
2023-06-27 23:21:07.571 DEBUG (MainThread) [ember_mug.mug] Updating the following attributes: {'date_time_zone', 'firmware', 'meta', 'udsk', 'dsk'}
2023-06-27 23:21:07.571 DEBUG (MainThread) [ember_mug.mug] Establishing a new connection from mug (ID: 546989639760) to F6:77:49:00:E2:23: Ember Ceramic Mug
2023-06-27 23:21:07.571 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 1
2023-06-27 23:21:07.572 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:07.588 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:21.951 DEBUG (MainThread) [ember_mug.mug] New mug connection initialized.
2023-06-27 23:21:21.951 DEBUG (MainThread) [ember_mug.mug] Registered callback: <bound method MugDataUpdateCoordinator._async_handle_callback of <custom_components.ember_mug.coordinator.MugDataUpdateCoordinator object at 0x7f59c5de10>>
2023-06-27 23:21:21.951 INFO (MainThread) [custom_components.ember_mug.coordinator] Ember Ceramic Mug ember-mug-f6774900e223 Setup
2023-06-27 23:21:21.951 DEBUG (MainThread) [ember_mug.mug] Registered callback: <function async_setup_entry.<locals>.<lambda> at 0x7f5a49e340>
2023-06-27 23:21:21.951 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Bluetooth event. Service Info: <home_assistant_bluetooth.models.BluetoothServiceInfoBleak object at 0x7f6591ca40>, change: BluetoothChange.ADVERTISEMENT
2023-06-27 23:21:21.951 DEBUG (MainThread) [ember_mug.mug] Set new device from F6:77:49:00:E2:23: Ember Ceramic Mug to F6:77:49:00:E2:23: Ember Ceramic Mug
2023-06-27 23:21:21.951 DEBUG (MainThread) [ember_mug.mug] Callback <bound method MugDataUpdateCoordinator._async_handle_callback of <custom_components.ember_mug.coordinator.MugDataUpdateCoordinator object at 0x7f59c5de10>> already registered
2023-06-27 23:21:21.952 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Updating
2023-06-27 23:21:21.952 DEBUG (MainThread) [ember_mug.mug] Updating the following attributes: {'date_time_zone', 'firmware', 'meta', 'udsk', 'dsk'}
2023-06-27 23:21:21.952 DEBUG (MainThread) [ember_mug.mug] Establishing a new connection from mug (ID: 547309763984) to F6:77:49:00:E2:23: Ember Ceramic Mug
2023-06-27 23:21:21.952 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 1
2023-06-27 23:21:21.952 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:21.963 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:21.967 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:21.967 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] Operation already in progress, backing off: 0.25 (attempt: 1, last rssi: None)
2023-06-27 23:21:21.968 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00012018403504043818 seconds to disconnect
2023-06-27 23:21:21.969 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:21.970 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] br-connection-canceled, backing off: 0.25 (attempt: 1, last rssi: None)
2023-06-27 23:21:21.970 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00011925795115530491 seconds to disconnect
2023-06-27 23:21:22.220 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 2
2023-06-27 23:21:22.221 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:22.225 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 2
2023-06-27 23:21:22.225 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:22.237 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:22.240 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:22.244 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:22.246 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] Operation already in progress, backing off: 0.25 (attempt: 2, last rssi: None)
2023-06-27 23:21:22.246 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00012075796257704496 seconds to disconnect
2023-06-27 23:21:22.249 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:22.251 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] br-connection-canceled, backing off: 0.25 (attempt: 2, last rssi: None)
2023-06-27 23:21:22.251 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00010633294004946947 seconds to disconnect
2023-06-27 23:21:22.498 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 3
2023-06-27 23:21:22.499 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:22.506 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 3
2023-06-27 23:21:22.506 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:22.513 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:22.516 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:22.520 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:22.520 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] Operation already in progress, backing off: 0.25 (attempt: 3, last rssi: None)
2023-06-27 23:21:22.521 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00011586898472160101 seconds to disconnect
2023-06-27 23:21:22.522 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:22.524 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] br-connection-canceled, backing off: 0.25 (attempt: 3, last rssi: None)
2023-06-27 23:21:22.524 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.0001247950131073594 seconds to disconnect
2023-06-27 23:21:22.771 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 4
2023-06-27 23:21:22.772 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:22.779 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:22.782 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 4
2023-06-27 23:21:22.782 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:22.787 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:22.792 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:22.793 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] Operation already in progress, backing off: 0.25 (attempt: 4, last rssi: None)
2023-06-27 23:21:22.793 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00012349896132946014 seconds to disconnect
2023-06-27 23:21:22.795 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:22.797 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] br-connection-canceled, backing off: 0.25 (attempt: 4, last rssi: None)
2023-06-27 23:21:22.797 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00010670197661966085 seconds to disconnect
2023-06-27 23:21:23.045 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 5
2023-06-27 23:21:23.045 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:23.052 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 5
2023-06-27 23:21:23.052 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:23.059 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:23.064 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:23.068 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:23.070 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] Operation already in progress, backing off: 0.25 (attempt: 5, last rssi: None)
2023-06-27 23:21:23.070 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00011349900159984827 seconds to disconnect
2023-06-27 23:21:23.073 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:23.073 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] br-connection-canceled, backing off: 0.25 (attempt: 5, last rssi: None)
2023-06-27 23:21:23.074 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.0001223880099132657 seconds to disconnect
2023-06-27 23:21:23.322 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 6
2023-06-27 23:21:23.322 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:23.329 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Connection attempt: 6
2023-06-27 23:21:23.329 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ F6:77:49:00:E2:23
2023-06-27 23:21:23.336 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:23.339 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_F6_77_49_00_E2_23
2023-06-27 23:21:23.344 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:23.345 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] Operation already in progress, backing off: 0.25 (attempt: 6, last rssi: None)
2023-06-27 23:21:23.346 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00012670306023210287 seconds to disconnect
2023-06-27 23:21:23.348 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_F6_77_49_00_E2_23)
2023-06-27 23:21:23.348 DEBUG (MainThread) [bleak_retry_connector] (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] br-connection-canceled, backing off: 0.25 (attempt: 6, last rssi: None)
2023-06-27 23:21:23.348 DEBUG (MainThread) [bleak_retry_connector.bluez] Ember Ceramic Mug - F6:77:49:00:E2:23: Waited 0.00012048101052641869 seconds to disconnect
2023-06-27 23:21:23.597 ERROR (MainThread) [ember_mug.mug] F6:77:49:00:E2:23: Ember Ceramic Mug: Failed to connect to the mug: (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] Operation already in progress
2023-06-27 23:21:23.601 ERROR (MainThread) [custom_components.ember_mug.coordinator] An error occurred whilst updating the Ember Ceramic Mug: (F6:77:49:00:E2:23) - F6:77:49:00:E2:23: Failed to connect: [org.bluez.Error.Failed] Operation already in progress

fwiw, I am aware the device addresses aren't obfuscated this round; this is my second comment attempt, I'm lazy, and it's a coffee mug not a server lol

bjornarfjelldal commented 1 year ago

Can also confirm same issue - HAOS Intel NUC latest 2023.6. I have tried with stock bluetooth, dongle and espproxies on and off.

sopelj commented 1 year ago

Oh very interesting. Thanks for testing. Yeah, not much to worry with not masking the MAC address.

That's very interesting. There is specifically a fix for a Bluetooth on both Intel NUC and Raspberry Pis in Home Assistant OS 10.3. Perhaps it introduced a regression? There are a couple issues open with Bluetooth on their github so it may be an OS error.

Have you tried with a Bluetooth Proxy and without the Bluetooth adapter enabled?

Do you have any related errors in the "Host" or "Supervisor" logs?

seanre453 commented 1 year ago

Hi @sopelj I don't currently have any existing bluetooth proxy infrastructure set up, but I can try digging out an esp32 for testing. Will report back on that if I make it anywhere with that. Will also check host and supervisor logs. Should have an update for you after work today.

sopelj commented 1 year ago

Hi @sopelj I don't currently have any existing bluetooth proxy infrastructure set up, but I can try digging out an esp32 for testing. Will report back on that if I make it anywhere with that. Will also check host and supervisor logs. Should have an update for you after work today.

Oh ok, thank you very much! If you don't have the setup that's fine too, it was mostly because @bjornarfjelldal mentioned having tried ESP Proxies without luck, which is very strange. I'm just curious if it's related to the integration or not. I'm thinking it might be a hass OS issue. If a proxy or a different dongle work, it would point to an issue with Hass os and the NUC built-in Bluetooth.

bjornarfjelldal commented 1 year ago

Hi @sopelj I don't currently have any existing bluetooth proxy infrastructure set up, but I can try digging out an esp32 for testing. Will report back on that if I make it anywhere with that. Will also check host and supervisor logs. Should have an update for you after work today.

Oh ok, thank you very much! If you don't have the setup that's fine too, it was mostly because @bjornarfjelldal mentioned having tried ESP Proxies without luck, which is very strange. I'm just curious if it's related to the integration or not. I'm thinking it might be a hass OS issue. If a proxy or a different dongle work, it would point to an issue with Hass os and the NUC built-in Bluetooth.

Hi again!

It seems I misinformed you in my previous post, ESP proxies where/are not active on my installation, I just thought that they were. But they will for some reason not show up, allthough I have re-flashed them using serial as per documentation. But that is a separate issue/topic.

So; only with Intel NUC bluetooth + StarTech Bluetooth dongle then. And it is still not working.. :)

My bet is also on an Hass OS issue.

noxhirsch commented 1 year ago

Some time ago I tested this integration with my NUC and could not connect to the Mug either. But the BT module from the NUC is not good anyway and constantly found / invented random devices. Therefore, I have then given up at that time. Recently I switched completely to a BT proxy (WT32-ETH01 so that BT and WiFi do not have to share an antenna). Today I tried it again. And lo and behold: The connection to the Ember Mug works wonderfully 👍

sopelj commented 1 year ago

Some time ago I tested this integration with my NUC and could not connect to the Mug either. But the BT module from the NUC is not good anyway and constantly found / invented random devices. Therefore, I have then given up at that time. Recently I switched completely to a BT proxy (WT32-ETH01 so that BT and WiFi do not have to share an antenna). Today I tried it again. And lo and behold: The connection to the Ember Mug works wonderfully +1

Awesome! Thanks for testing and the update! Home Assistant OS 10.4 was released a couple weeks ago, perhaps that's what fixed it. Is that what you are running now?

noxhirsch commented 1 year ago

I actually had version 10.4 running. But to test it again, I just downgraded to 10.3 and was able to add the Ember Mug without any problems. So the Bluetooth proxies seem to have been the solution here.

sopelj commented 1 year ago

I actually had version 10.4 running. But to test it again, I just downgraded to 10.3 and was able to add the Ember Mug without any problems. So the Bluetooth proxies seem to have been the solution here.

Oh, awesome! Thanks for your thorough testing! Perhaps it cleared something up just by upgrading?

Is anyone still having troubles since upgrading to 10.4?

bjornarfjelldal commented 1 year ago

Hi! Yes, still having problems. This is what I have done and tested;

Deactivated Intel NUC's BT module inside BIOS. Running HASS OS in Proxmox. Using the StarTech USBBT1EDR4 (CSR8510A10) as BT dongle with USB passthrough.

With this setup, no ember mugs are even discoverable. Both in 10.3 and 10.4.

Now, when adding some ESP BT Proxies, they immediately become discoverable by HA. However, when trying to add them, they time out on either initializing, or never even get that far.

Skjermbilde 2023-08-07 kl 12 40 53

I can try to provide logs on a new adding session (it takes some time from removing them before they become discoverable again also..). Which ones do you preferable need? From ESP BT module, or HASS?

sopelj commented 1 year ago

Hi! Yes, still having problems. This is what I have done and tested;

Deactivated Intel NUC's BT module inside BIOS. Running HASS OS in Proxmox. Using the StarTech USBBT1EDR4 (CSR8510A10) as BT dongle with USB passthrough.

With this setup, no ember mugs are even discoverable. Both in 10.3 and 10.4.

Now, when adding some ESP BT Proxies, they immediately become discoverable by HA. However, when trying to add them, they time out on either initializing, or never even get that far.

Skjermbilde 2023-08-07 kl 12 40 53

I can try to provide logs on a new adding session (it takes some time from removing them before they become discoverable again also..). Which ones do you preferable need? From ESP BT module, or HASS?

Hi! Sorry, I did not see your message. Ok, upon adding your Bluetooth dongle did you add the dongle in Home Assistant via the Bluetooth Integration?

With either the Bluetooth Dongle or the Proxies does it detect your mug in pairing mode? Using both of the same time can cause frequent disconnects, but should function.

That's very strange. I have never seen that error before. Yes, if you could perhaps try removing the entities related to the integration and trying again with more verbose logging enable that would be much appreciated. Which log depends on where the problem is. If there is a problem with the proxies you may find some information that could be helpful, but the logs related to this integration will be in Home Assistant's log.

Also, worth noting that Home Assistant OS 10.5 is in beta right now. I don't see any specific fixes for the NUC though. But sometimes just kernel upgrades is enough.

bjornarfjelldal commented 1 year ago

10.5 did not fix it. I will try to add verbose logging on full reset of mugs. Just a question in the mean time - it should work fine with two mugs, no?

Also, answering your questions; Bluetooth dongle is now my only device in the Bluetooth integration. Once in this limbo above, it does not recognize them anymore. What seem to work (allthough not 100% reproducable) is to delete all Ember mug integration devices, factory reset mugs, and hardware restart home assistant.

bjornarfjelldal commented 1 year ago

Doing the reset procedue above, I get this:

Skjermbilde 2023-09-18 kl 11 19 53 Skjermbilde 2023-09-18 kl 11 20 56 
Logger: homeassistant.config_entries
Source: components/bluetooth/wrappers.py:292
First occurred: 11:19:38 (1 occurrences)
Last logged: 11:19:38

Error setting up entry Ember Ceramic Mug for ember_mug
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 387, in async_setup
    result = await component.async_setup_entry(hass, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/ember_mug/__init__.py", line 83, in async_setup_entry
    await mug_coordinator.async_config_entry_first_refresh()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 257, in async_config_entry_first_refresh
    await self._async_refresh(
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 293, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/ember_mug/coordinator.py", line 62, in _async_update_data
    changed = await self.mug.update_initial()
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/ember_mug/mug.py", line 350, in update_initial
    return await self._update_multiple(self.data.model.initial_attributes)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/ember_mug/mug.py", line 359, in _update_multiple
    await self._ensure_connection()
  File "/usr/local/lib/python3.11/site-packages/ember_mug/mug.py", line 103, in _ensure_connection
    client = await establish_connection(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bleak_retry_connector/__init__.py", line 350, in establish_connection
    await client.connect(
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/wrappers.py", line 292, in connect
    connected = await super().connect(**kwargs)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bleak/__init__.py", line 605, in connect
    return await self._backend.connect(**kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bleak/backends/bluezdbus/client.py", line 209, in connect
    reply = await self._bus.call(
            ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/dbus_fast/aio/message_bus.py", line 390, in call
    await future
asyncio.exceptions.CancelledError: aiohttp connection lost

No logs in either ESP proxies, so I am guessing it tries through the main dongle (on board chip disabled in BIOS).

bjornarfjelldal commented 1 year ago

@sopelj

And in the odd case that it goes past the first add screen, I make them enter pairing mode (blue blinking) but only get these errors:

Logger: homeassistant.config_entries
Source: config_entries.py:951
First occurred: 11:31:38 (1 occurrences)
Last logged: 11:31:38

Config entry 'Ember Ceramic Mug' for ember_mug integration not ready yet: An error occurred updating Ember Ceramic Mug: e=BleakDBusError('org.bluez.Error.Failed', 'Operation failed with ATT error: 0x0e'); Retrying in background
Logger: ember_mug.mug
Source: runner.py:186
First occurred: 11:30:35 (9 occurrences)
Last logged: 11:32:16

Unexpectedly disconnected

Denne feilen stammer fra en tilpasset integrasjon.
Logger: ember_mug.mug
Source: custom_components/ember_mug/coordinator.py:62
Integration: Ember Mug (documentation, issues)
First occurred: 11:30:34 (9 occurrences)
Last logged: 11:32:16

Failed to subscribe to state attr: [org.bluez.Error.NotConnected] Not Connected
Failed to subscribe to state attr: [org.bluez.Error.Failed] Operation failed with ATT error: 0x0e (Unlikely Error)

Denne feilen stammer fra en tilpasset integrasjon.
Logger: custom_components.ember_mug.coordinator
Source: custom_components/ember_mug/coordinator.py:72
Integration: Ember Mug (documentation, issues)
First occurred: 11:30:35 (9 occurrences)
Last logged: 11:32:16

An error occurred whilst updating the Ember Ceramic Mug: [org.bluez.Error.Failed] Operation failed with ATT error: 0x0e (Unlikely Error)
An error occurred whilst updating the Ember Ceramic Mug: Not connected

bilde bilde

bjornarfjelldal commented 1 year ago

Now one of them suddenly connected, and after triggering "bluetoothctl" in terminal the other one got connected as well (this could be a concidence). Given that I have been able to connect them for a few days before they become unavailable again, I assume this will be a temporarily condition.

By the way, my bluetoothctl prints like 50 lines a second repeating, is this normal behavior? I recall it being rather static before.

sopelj commented 1 year ago

Now one of them suddenly connected, and after triggering "bluetoothctl" in terminal the other one got connected as well (this could be a concidence). Given that I have been able to connect them for a few days before they become unavailable again, I assume this will be a temporarily condition.

By the way, my bluetoothctl prints like 50 lines a second repeating, is this normal behavior? I recall it being rather static before.

Hi! Sorry, I've been away for a little bit. Depending on your setup and device sometimes, when using Bluetooth dongles instead of the ESPHome proxies, opening bluetoothctl is, unfortunately, required. It should be listed in the troubleshooting/setup steps.

Do they remain unavailable and do you have any errors? Sometimes they will be unavailable when the battery gets very low, but unless the battery dies completely they should automatically reconnect when charged.

I cannot be sure, not knowing what the output is, but given you had no devices before, it's normal that it is more dynamic now. 50 lines a second does seem like a lot. It does many queries to the mug to fetch the different attributes. I think that's like 10 or so every 30 seconds. Given you have two mugs, it may be triggering more often as the second may disconnect the first and vise versa.

sopelj commented 9 months ago

Have any of you had any luck with the above suggestions?

bjornarfjelldal commented 9 months ago

Hi! I have had no issues since a few months back - unsure what made it work, probably a combination of ESPhome BT proxies being improved (I am solely using these), frequent reboots of said ESPs as they would drop connections after a while, as well as improvements on other BT integrations that may or may not have caused troubles with BT in general (particularly AirThings BLE) :)

sopelj commented 9 months ago

That's great! They have made great improvements with proxies, they wen't from barely working to being the recommended method in a few iterations. Thanks for the update. I'll close this issue, but feel free to create one if future if there are other prtoblems