Closed zianx closed 7 months ago
Hi! Is the new ESPHome proxy the same model with the same settings? Have you tried putting the mug back into paring mode after switching to the new proxy?
Hi!
The ESPHome proxy is the same model with the same settings. I even copied over from the older one, encase there was some slight differences in the yaml.
I had tried placing it in paring mode, with no luck.
But I tried it again, with the diag logs running and the new proxy was able to authenticate! (it must have known someone was watching)
I was able to get the mug to swap between the two proxies, by powering them on individually. There is a period of time in which the entities become unavailable, before the mug jumps over to the other proxy.
Is the implication of this, that the each Ember mug will need to pair with each proxy?
I have attached logs below, encase they will assist anyone and will mark as closed soon.
Thank you @sopelj for he hard work you put in to these components and assisting in troubleshooting.
ESPHome Device Log:
[14:38:45][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[14:38:45][I][esp32_ble_client:067]: [0] [C6:5B:55:02:F3:AC] 0x01 Attempting BLE connection
[14:38:46][D][esp32_ble_client:172]: [0] [C6:5B:55:02:F3:AC] ESP_GATTC_DISCONNECT_EVT, reason 62
[14:38:46][D][esp32_ble_tracker:266]: Starting scan...
[14:38:48][I][bluetooth_proxy:278]: [0] [C6:5B:55:02:F3:AC] Connecting v3 with cache
[14:38:48][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[14:38:48][I][esp32_ble_client:067]: [0] [C6:5B:55:02:F3:AC] 0x01 Attempting BLE connection
[14:38:48][D][esp32_ble_client:172]: [0] [C6:5B:55:02:F3:AC] ESP_GATTC_DISCONNECT_EVT, reason 62
[14:38:48][D][esp32_ble_tracker:266]: Starting scan...
[14:39:04][I][bluetooth_proxy:278]: [0] [C6:5B:55:02:F3:AC] Connecting v3 with cache
[14:39:04][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[14:39:04][I][esp32_ble_client:067]: [0] [C6:5B:55:02:F3:AC] 0x01 Attempting BLE connection
[14:39:04][D][esp32_ble_client:110]: [0] [C6:5B:55:02:F3:AC] ESP_GATTC_CONNECT_EVT
[14:39:04][D][esp32_ble_client:110]: [0] [C6:5B:55:02:F3:AC] ESP_GATTC_OPEN_EVT
[14:39:04][I][esp32_ble_client:154]: [0] [C6:5B:55:02:F3:AC] Connected
[14:39:04][D][esp32_ble_tracker:266]: Starting scan...
[14:39:04][I][esp32_ble_client:333]: [0] [C6:5B:55:02:F3:AC] auth complete. remote BD_ADDR: c65b5502f3ac
[14:39:04][D][esp32_ble_client:341]: [0] [C6:5B:55:02:F3:AC] auth success. address type = 1 auth mode = 1
[14:39:04][D][esp32_ble_client:110]: [0] [C6:5B:55:02:F3:AC] ESP_GATTC_REG_FOR_NOTIFY_EVT
[14:39:06][D][esp32_ble_client:306]: [0] [C6:5B:55:02:F3:AC] Event 46
[14:39:06][D][esp32_ble_client:188]: [0] [C6:5B:55:02:F3:AC] cfg_mtu status 0, mtu 23
[14:39:06][D][esp32_ble_client:110]: [0] [C6:5B:55:02:F3:AC] ESP_GATTC_WRITE_DESCR_EVT
[14:39:06][D][esp32_ble_client:110]: [0] [C6:5B:55:02:F3:AC] ESP_GATTC_READ_CHAR_EVT
[14:39:07][D][esp32_ble_client:110]: [0] [C6:5B:55:02:F3:AC] ESP_GATTC_READ_CHAR_EVT
Home Assistant Debug Log:
2024-03-13 14:36:58.011 DEBUG (MainThread) [custom_components.ember_mug.coordinator] [Full Update] Changed: None
2024-03-13 14:37:12.981 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Updating
2024-03-13 14:37:12.981 DEBUG (MainThread) [ember_mug.mug] Updating the following attributes: {'battery', 'led_colour', 'liquid_level', 'target_temp', 'temperature_unit', 'name', 'liquid_state', 'current_temp'}
2024-03-13 14:37:42.983 DEBUG (MainThread) [custom_components.ember_mug.coordinator] [Full Update] Changed: None
2024-03-13 14:37:42.983 DEBUG (MainThread) [custom_components.ember_mug] Finished fetching ember-mug-c65b5502f3ac data in 30.002 seconds (success: True)
2024-03-13 14:37:57.982 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Updating
2024-03-13 14:37:57.982 DEBUG (MainThread) [ember_mug.mug] Updating the following attributes: {'battery', 'led_colour', 'liquid_level', 'target_temp', 'temperature_unit', 'name', 'liquid_state', 'current_temp'}
2024-03-13 14:38:18.417 WARNING (MainThread) [aioesphomeapi.connection] bluetoothproxy-2 @ 192.168.1.165: Connection error occurred: [Errno 104] Connection reset by peer
2024-03-13 14:38:21.067 WARNING (MainThread) [aioesphomeapi.connection] bluetooth-proxy-study @ 192.168.1.81: Connection error occurred: Ping response not received after 90.0 seconds
2024-03-13 14:38:21.068 DEBUG (MainThread) [custom_components.ember_mug.coordinator] An error occurred trying to update the mug: Ping response not received after 90.0 seconds
2024-03-13 14:38:21.068 DEBUG (MainThread) [custom_components.ember_mug.coordinator] [Full Update] Changed: None
2024-03-13 14:38:21.068 DEBUG (MainThread) [custom_components.ember_mug] Finished fetching ember-mug-c65b5502f3ac data in 23.086 seconds (success: True)
2024-03-13 14:38:21.069 DEBUG (MainThread) [ember_mug.mug] Unexpectedly disconnected
2024-03-13 14:38:21.652 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for bluetooth-proxy-study @ 192.168.1.81: Error connecting to [AddrInfo(family=<AddressFamily.AF_INET: 2>, type=<SocketKind.SOCK_STREAM: 1>, proto=6, sockaddr=IPv4Sockaddr(address='192.168.1.81', port=6053))]: [Errno 113] Connect call failed ('192.168.1.81', 6053) (SocketAPIError)
2024-03-13 14:38:35.981 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Updating
2024-03-13 14:38:35.981 DEBUG (MainThread) [ember_mug.mug] Updating the following attributes: {'battery', 'led_colour', 'liquid_level', 'target_temp', 'temperature_unit', 'name', 'liquid_state', 'current_temp'}
2024-03-13 14:38:35.981 DEBUG (MainThread) [ember_mug.mug] Establishing a new connection from mug (ID: 140381408503440) to C6:5B:55:02:F3:AC: Ember Ceramic Mug
2024-03-13 14:38:35.981 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 1
2024-03-13 14:38:36.607 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 1, last rssi: None)
2024-03-13 14:38:37.108 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 2
2024-03-13 14:38:37.836 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 2, last rssi: None)
2024-03-13 14:38:38.338 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 3
2024-03-13 14:38:38.858 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 3, last rssi: None)
2024-03-13 14:38:39.359 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 4
2024-03-13 14:38:39.987 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 4, last rssi: None)
2024-03-13 14:38:40.488 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 5
2024-03-13 14:38:41.526 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 5, last rssi: None)
2024-03-13 14:38:42.027 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 6
2024-03-13 14:38:42.851 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 6, last rssi: None)
2024-03-13 14:38:43.352 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 7
2024-03-13 14:38:43.876 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 7, last rssi: None)
2024-03-13 14:38:44.376 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 8
2024-03-13 14:38:46.127 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 8, last rssi: None)
2024-03-13 14:38:46.629 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 9
2024-03-13 14:38:48.786 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect: Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish, device_missing: False, backing off: 0.5 (attempt: 9, last rssi: None)
2024-03-13 14:38:49.287 DEBUG (MainThread) [ember_mug.mug] C6:5B:55:02:F3:AC: Ember Ceramic Mug: Failed to connect to the mug: EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect after 9 attempt(s): Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish: Interference/range; External Bluetooth adapter w/extension may help; Extension cables reduce USB 3 port interference
2024-03-13 14:38:49.287 DEBUG (MainThread) [custom_components.ember_mug.coordinator] An error occurred trying to update the mug: EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Failed to connect after 9 attempt(s): Error ESP_GATT_CONN_FAIL_ESTABLISH while connecting: Connection failed to establish: Interference/range; External Bluetooth adapter w/extension may help; Extension cables reduce USB 3 port interference
2024-03-13 14:38:49.288 DEBUG (MainThread) [custom_components.ember_mug.coordinator] [Full Update] Changed: None
2024-03-13 14:38:49.288 DEBUG (MainThread) [custom_components.ember_mug] Finished fetching ember-mug-c65b5502f3ac data in 13.307 seconds (success: True)
2024-03-13 14:38:51.036 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Bluetooth event. Service Info: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7fac7fffea40>, change: BluetoothChange.ADVERTISEMENT
2024-03-13 14:38:51.037 DEBUG (MainThread) [ember_mug.mug] Set new device from C6:5B:55:02:F3:AC: Ember Ceramic Mug to C6:5B:55:02:F3:AC: Ember Ceramic Mug
2024-03-13 14:38:51.037 DEBUG (MainThread) [ember_mug.mug] Callback <bound method MugDataUpdateCoordinator._async_handle_callback of <custom_components.ember_mug.coordinator.MugDataUpdateCoordinator object at 0x7fad39746810>> already registered
2024-03-13 14:38:51.038 DEBUG (MainThread) [custom_components.ember_mug] Discovered bluetooth device: <habluetooth.models.BluetoothServiceInfoBleak object at 0x7fac7fffea40>
2024-03-13 14:39:03.981 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Updating
2024-03-13 14:39:03.981 DEBUG (MainThread) [ember_mug.mug] Updating the following attributes: {'battery', 'led_colour', 'liquid_level', 'target_temp', 'temperature_unit', 'name', 'liquid_state', 'current_temp'}
2024-03-13 14:39:03.981 DEBUG (MainThread) [ember_mug.mug] Establishing a new connection from mug (ID: 140381408503440) to C6:5B:55:02:F3:AC: Ember Ceramic Mug
2024-03-13 14:39:03.981 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connection attempt: 1
2024-03-13 14:39:04.401 DEBUG (MainThread) [bleak_retry_connector] EMBER (C6:5B:55:02:F3:AC) - C6:5B:55:02:F3:AC: Connected after 1 attempts
2024-03-13 14:39:04.956 INFO (MainThread) [ember_mug.mug] Subscribe to Push Events
2024-03-13 14:39:06.900 DEBUG (MainThread) [ember_mug.mug] Read attribute 'fc540007-236c-4c94-8fa9-944a3e5353fa' with value 'bytearray(b'9\x00\xf8\x11\x00')'
2024-03-13 14:39:07.001 DEBUG (MainThread) [ember_mug.mug] Read attribute 'fc540014-236c-4c94-8fa9-944a3e5353fa' with value 'bytearray(b'\xde\x00\xff\x07')'
2024-03-13 14:39:07.105 DEBUG (MainThread) [ember_mug.mug] Read attribute 'fc540005-236c-4c94-8fa9-944a3e5353fa' with value 'bytearray(b'\x1e')'
2024-03-13 14:39:07.254 DEBUG (MainThread) [ember_mug.mug] Read attribute 'fc540003-236c-4c94-8fa9-944a3e5353fa' with value 'bytearray(b'\x05\x18')'
2024-03-13 14:39:07.349 DEBUG (MainThread) [ember_mug.mug] Read attribute 'fc540004-236c-4c94-8fa9-944a3e5353fa' with value 'bytearray(b'\x00')'
2024-03-13 14:39:07.514 DEBUG (MainThread) [ember_mug.mug] Read attribute 'fc540001-236c-4c94-8fa9-944a3e5353fa' with value 'bytearray(b'EMBER')'
2024-03-13 14:39:07.614 DEBUG (MainThread) [ember_mug.mug] Read attribute 'fc540008-236c-4c94-8fa9-944a3e5353fa' with value 'bytearray(b'\x06')'
2024-03-13 14:39:07.723 DEBUG (MainThread) [ember_mug.mug] Read attribute 'fc540002-236c-4c94-8fa9-944a3e5353fa' with value 'bytearray(b'\x06\x18')'
2024-03-13 14:39:07.723 DEBUG (MainThread) [ember_mug.mug] Firing callbacks: {<bound method MugDataUpdateCoordinator._async_handle_callback of <custom_components.ember_mug.coordinator.MugDataUpdateCoordinator object at 0x7fad39746810>>: <function EmberMug.register_callback.<locals>.unregister_callback at 0x7fad0b934360>}
2024-03-13 14:39:07.723 DEBUG (MainThread) [custom_components.ember_mug.coordinator] Callback called in Home Assistant
2024-03-13 14:39:07.723 DEBUG (MainThread) [custom_components.ember_mug] Manually updated ember-mug-c65b5502f3ac data
2024-03-13 14:39:07.723 DEBUG (MainThread) [ember_mug.mug] Attributes updated: [Change(attr='battery', old_value=BatteryInfo(percent=58.0, on_charging_base=True), new_value=BatteryInfo(percent=57.0, on_charging_base=False))]
2024-03-13 14:39:07.723 DEBUG (MainThread) [custom_components.ember_mug.coordinator] [Full Update] Changed: [Change(attr='battery', old_value=BatteryInfo(percent=58.0, on_charging_base=True), new_value=BatteryInfo(percent=57.0, on_charging_base=False))]
2024-03-13 14:39:07.723 DEBUG (MainThread) [custom_components.ember_mug] Finished fetching ember-mug-c65b5502f3ac data in 3.742 seconds (success: True
```)
Haha, yes, sometimes just watching is all it takes.
So, with both running it switches between them automatically now, but there is some delay between the switch? If they are both running and they are close it might be a good idea to lower the signal strength a bit so there is less overlap.
Yes, I think that is the implication. If you change proxies or have multiple proxies it may be required to re-pair the mug to the proxy. This is probably because it's an active connection and thus pairing it required, but as soon as the mug pairs with a device it will leave pairing mode so it won't have the chance to pair with multiple. I'll update the documentation accordingly.
Thanks! I'm glad I can be of assistance and this can be of use. :)
Description
Mug becomes unavailable and is unable to connect unless using specific ESPHome Proxy.
What I Did
Attempted to add a second / replace a ESPHome Proxy, the second ESPHome Proxy attempts to connect to the Ember Mug using cache, but is unable to (ESP_GATTC_DISCONNECT_EVT, reason 62).
Powering the in the original ESPHome Proxy and removing the new proxy, the Ember Mug connects immediately.
Logs / Errors
Home Assistant Debug Log:
New/Second ESPHome Device Log: (unable to connect)
Original Device Log: (reconnecting)