Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Switchbot Tilt / Cover not working (Bluetooth Proxy) #109734

Closed
rkaramandi opened this issue Feb 5, 2024 · 5 comments
Closed

Switchbot Tilt / Cover not working (Bluetooth Proxy) #109734

rkaramandi opened this issue Feb 5, 2024 · 5 comments
Assignees
Milestone

Comments

@rkaramandi
Copy link

The problem

I have 3 Switchbot Tilt's connected via BLE Proxy and am encountering an issue where other stats synchronize (like battery % etc, but the actual cover component doesn't work). Seen this issue in pretty much every build of 2024.2, but these logs were taken from core-2024.2.0b6, with frontend version 20240202.0; but I've tested this on 2024.2.0b3 too with similar results.

The status of the cover entities show up as unknown and these are the results from the home assistant logs when adjusting the cover position from fresh reboot (the device in question ends in 93:7F)

2024-02-05 11:19:31.588 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 576, in update
    self._update_parsed_data(info)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 611, in _update_parsed_data
    self._set_parsed_data(self._sb_adv_data, merged_data)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/curtain.py", line 68, in _set_parsed_data
    new_position = data["position"]
                   ~~~~^^^^^^^^^^^^
KeyError: 'position'
2024-02-05 11:19:39.083 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 576, in update
    self._update_parsed_data(info)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 611, in _update_parsed_data
    self._set_parsed_data(self._sb_adv_data, merged_data)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/curtain.py", line 68, in _set_parsed_data
    new_position = data["position"]
                   ~~~~^^^^^^^^^^^^
KeyError: 'position'
2024-02-05 11:19:39.784 DEBUG (MainThread) [switchbot.devices.device] None (D0:59:2E:13:C8:F6): Executing timed disconnect after timeout of 8.5
2024-02-05 11:19:39.784 DEBUG (MainThread) [switchbot.devices.device] None (D0:59:2E:13:C8:F6): Executing disconnect
2024-02-05 11:19:39.785 DEBUG (MainThread) [switchbot.devices.device] None (D0:59:2E:13:C8:F6): Executing disconnect with lock
2024-02-05 11:19:39.785 DEBUG (MainThread) [switchbot.devices.device] None (D0:59:2E:13:C8:F6): Disconnecting
2024-02-05 11:19:39.985 DEBUG (MainThread) [switchbot.devices.device] None (D0:59:2E:13:C8:F6): Disconnected from device; RSSI: -84
2024-02-05 11:19:39.986 DEBUG (MainThread) [switchbot.devices.device] None (D0:59:2E:13:C8:F6): Disconnect completed successfully
2024-02-05 11:19:47.287 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Executing timed disconnect after timeout of 8.5
2024-02-05 11:19:47.287 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Executing disconnect
2024-02-05 11:19:47.287 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Executing disconnect with lock
2024-02-05 11:19:47.287 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Disconnecting
2024-02-05 11:19:47.462 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Disconnected from device; RSSI: -91
2024-02-05 11:19:47.462 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Disconnect completed successfully
2024-02-05 11:19:51.924 DEBUG (MainThread) [homeassistant.components.switchbot.cover] Switchbot to move at 47 D9:26:25:E6:93:7F
2024-02-05 11:19:51.924 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Scheduling command 570f450101012f
2024-02-05 11:19:51.924 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Connecting; RSSI: -91
2024-02-05 11:19:53.818 DEBUG (MainThread) [switchbot.devices.device] None (C2:B2:2D:15:6C:4F): Connected; RSSI: -90
2024-02-05 11:19:53.818 DEBUG (MainThread) [switchbot.devices.device] None (C2:B2:2D:15:6C:4F): Starting notify and disconnect timer; RSSI: -90
2024-02-05 11:19:53.818 DEBUG (MainThread) [switchbot.devices.device] None (C2:B2:2D:15:6C:4F): Subscribe to notifications; RSSI: -90
2024-02-05 11:19:53.912 DEBUG (MainThread) [switchbot.devices.device] None (C2:B2:2D:15:6C:4F): Sending command: 5702
2024-02-05 11:19:54.132 DEBUG (MainThread) [switchbot.devices.device] None (C2:B2:2D:15:6C:4F): Notification received: 01551501c00c2b00
2024-02-05 11:19:54.132 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 576, in update
    self._update_parsed_data(info)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 611, in _update_parsed_data
    self._set_parsed_data(self._sb_adv_data, merged_data)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/curtain.py", line 68, in _set_parsed_data
    new_position = data["position"]
                   ~~~~^^^^^^^^^^^^
KeyError: 'position'
2024-02-05 11:19:55.577 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Connected; RSSI: -91
2024-02-05 11:19:55.578 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Starting notify and disconnect timer; RSSI: -91
2024-02-05 11:19:55.578 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Subscribe to notifications; RSSI: -91
2024-02-05 11:19:55.707 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Sending command: 570f450101012F
2024-02-05 11:19:56.608 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Notification received: 013400
2024-02-05 11:19:56.608 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Scheduling command 570f450105ff2f
2024-02-05 11:19:56.608 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Already connected before obtaining lock, resetting timer; RSSI: -91
2024-02-05 11:19:56.609 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Sending command: 570f450105FF2F
2024-02-05 11:19:56.797 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Notification received: 012d00
2024-02-05 11:19:56.797 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Scheduling command 5702
2024-02-05 11:19:56.797 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Already connected before obtaining lock, resetting timer; RSSI: -91
2024-02-05 11:19:56.797 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Sending command: 5702
2024-02-05 11:19:56.988 DEBUG (MainThread) [switchbot.devices.device] None (D9:26:25:E6:93:7F): Notification received: 01511501c00d2d00
2024-02-05 11:19:56.988 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140190134669376] 'position'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 240, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2279, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2316, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 892, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 962, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/switchbot/cover.py", line 187, in async_set_cover_tilt_position
    self._last_run_success = bool(await self._device.set_position(position))
                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 96, in _async_update_after_operation_wrap
    await self.update()
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 576, in update
    self._update_parsed_data(info)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 611, in _update_parsed_data
    self._set_parsed_data(self._sb_adv_data, merged_data)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/curtain.py", line 68, in _set_parsed_data
    new_position = data["position"]
                   ~~~~^^^^^^^^^^^^
KeyError: 'position'

and I get the error Failed to call service cover/set_cover_tilt_position. 'position' on the UI when this happens.

The device does respond, however the UI still shows unknown.

The BLE Proxy shows as follows with Verbose logging turned on (again, the device in question ends in 93:7F):

[11:19:47][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 6] - 5
[11:19:47][V][esp32_ble_client:119]: [2] [D9:26:25:E6:93:7F] gattc_event_handler: event=5 gattc_if=6
[11:19:47][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[11:19:47][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=41 gattc_if=4
[11:19:47][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[11:19:47][V][esp32_ble_client:119]: [1] [] gattc_event_handler: event=41 gattc_if=5
[11:19:47][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 6] - 41
[11:19:47][V][esp32_ble_client:119]: [2] [D9:26:25:E6:93:7F] gattc_event_handler: event=41 gattc_if=6
[11:19:47][V][esp32_ble_client:173]: [2] [D9:26:25:E6:93:7F] ESP_GATTC_DISCONNECT_EVT, reason 22
[11:19:47][V][bluetooth_proxy:100]: [0] Used connection by [C2:B2:2D:15:6C:4F]
[11:19:47][V][bluetooth_proxy:097]: [1] Free connection
[11:19:47][V][bluetooth_proxy:097]: [2] Free connection
[11:19:47][W][component:214]: Component esp32_ble took a long time for an operation (0.10 s).
[11:19:47][W][component:215]: Components should block for at most 20-30ms.
[11:19:47][C][api:139]: API Server:
[11:19:47][C][api:140]:   Address: ************
[11:19:47][C][api:142]:   Using noise encryption: YES
[11:19:49][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[11:19:49][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=41 gattc_if=4
[11:19:49][V][esp32_ble_client:173]: [0] [C2:B2:2D:15:6C:4F] ESP_GATTC_DISCONNECT_EVT, reason 62
[11:19:49][V][bluetooth_proxy:097]: [0] Free connection
[11:19:49][V][bluetooth_proxy:097]: [1] Free connection
[11:19:49][V][bluetooth_proxy:097]: [2] Free connection
[11:19:49][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 2
[11:19:49][V][esp32_ble_client:119]: [0] [] gattc_event_handler: event=2 gattc_if=4
[11:19:49][V][esp32_ble_client:134]: [0] [] ESP_GATTC_OPEN_EVT
[11:19:49][W][esp32_ble_client:139]: [0] [] Connection failed, status=133
[11:19:49][V][bluetooth_proxy:097]: [0] Free connection
[11:19:49][V][bluetooth_proxy:097]: [1] Free connection
[11:19:49][V][bluetooth_proxy:097]: [2] Free connection
[11:19:49][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[11:19:49][V][esp32_ble_client:119]: [1] [] gattc_event_handler: event=41 gattc_if=5
[11:19:49][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 6] - 41
[11:19:49][V][esp32_ble_client:119]: [2] [] gattc_event_handler: event=41 gattc_if=6
[11:19:49][W][component:214]: Component esp32_ble took a long time for an operation (0.11 s).
[11:19:49][W][component:215]: Components should block for at most 20-30ms.
[11:19:49][D][esp32_ble_tracker:266]: Starting scan...
[11:19:49][V][esp32_ble:314]: (BLE) gap_event_handler - 2
[11:19:49][V][esp32_ble:314]: (BLE) gap_event_handler - 7
[11:19:49][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:19:49][V][bluetooth_proxy:058]: Proxying 1 packets
[11:19:49][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:19:49][V][bluetooth_proxy:058]: Proxying 1 packets
[11:19:49][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:19:49][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:19:49][V][bluetooth_proxy:058]: Proxying 2 packets
[11:19:49][I][bluetooth_proxy:282]: [0] [C2:B2:2D:15:6C:4F] Connecting v3 without cache
[11:19:49][V][bluetooth_proxy:100]: [0] Used connection by [C2:B2:2D:15:6C:4F]
[11:19:49][V][bluetooth_proxy:097]: [1] Free connection
[11:19:49][V][bluetooth_proxy:097]: [2] Free connection
[11:19:49][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[11:19:49][V][esp32_ble:314]: (BLE) gap_event_handler - 18
[11:19:49][I][esp32_ble_client:069]: [0] [C2:B2:2D:15:6C:4F] 0x01 Attempting BLE connection
[11:19:52][I][bluetooth_proxy:278]: [1] [D9:26:25:E6:93:7F] Connecting v3 with cache
[11:19:52][V][bluetooth_proxy:100]: [0] Used connection by [C2:B2:2D:15:6C:4F]
[11:19:52][V][bluetooth_proxy:100]: [1] Used connection by [D9:26:25:E6:93:7F]
[11:19:52][V][bluetooth_proxy:097]: [2] Free connection
[11:19:52][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 40
[11:19:52][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=40 gattc_if=4
[11:19:52][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 2
[11:19:52][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=2 gattc_if=4
[11:19:52][V][esp32_ble_client:134]: [0] [C2:B2:2D:15:6C:4F] ESP_GATTC_OPEN_EVT
[11:19:52][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 40
[11:19:52][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=40 gattc_if=5
[11:19:52][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 6] - 40
[11:19:52][V][esp32_ble_client:119]: [2] [] gattc_event_handler: event=40 gattc_if=6
[11:19:52][W][component:214]: Component esp32_ble took a long time for an operation (0.08 s).
[11:19:52][W][component:215]: Components should block for at most 20-30ms.
[11:19:53][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 46
[11:19:53][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=46 gattc_if=4
[11:19:53][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 7
[11:19:53][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=7 gattc_if=4
[11:19:53][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 7
[11:19:53][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=7 gattc_if=4
[11:19:53][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 7
[11:19:53][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=7 gattc_if=4
[11:19:53][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 6
[11:19:53][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=6 gattc_if=4
[11:19:53][V][esp32_ble_client:194]: [0] [C2:B2:2D:15:6C:4F] ESP_GATTC_SEARCH_CMPL_EVT
[11:19:53][I][esp32_ble_client:201]: [0] [C2:B2:2D:15:6C:4F] Connected
[11:19:53][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 18
[11:19:53][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=18 gattc_if=4
[11:19:53][V][esp32_ble_client:165]: [0] [C2:B2:2D:15:6C:4F] cfg_mtu status 0, mtu 247
[11:19:53][V][bluetooth_proxy:100]: [0] Used connection by [C2:B2:2D:15:6C:4F]
[11:19:53][V][bluetooth_proxy:100]: [1] Used connection by [D9:26:25:E6:93:7F]
[11:19:53][V][bluetooth_proxy:097]: [2] Free connection
[11:19:53][W][component:214]: Component esp32_ble took a long time for an operation (0.12 s).
[11:19:53][W][component:215]: Components should block for at most 20-30ms.
[11:19:53][I][esp32_ble_client:069]: [1] [D9:26:25:E6:93:7F] 0x01 Attempting BLE connection
[11:19:53][V][bluetooth_proxy.connection:258]: [0] [C2:B2:2D:15:6C:4F] Registering for GATT characteristic notifications handle 18
[11:19:53][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 38
[11:19:53][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=38 gattc_if=4
[11:19:53][V][bluetooth_proxy.connection:236]: [0] [C2:B2:2D:15:6C:4F] Writing GATT descriptor handle 19
[11:19:53][V][bluetooth_proxy.connection:198]: [0] [C2:B2:2D:15:6C:4F] Writing GATT characteristic handle 16
[11:19:54][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 9
[11:19:54][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=9 gattc_if=4
[11:19:54][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 4
[11:19:54][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=4 gattc_if=4
[11:19:54][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 10
[11:19:54][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=10 gattc_if=4
[11:19:54][V][bluetooth_proxy.connection:137]: [0] [C2:B2:2D:15:6C:4F] ESP_GATTC_NOTIFY_EVT: handle=0x12
[11:19:55][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 40
[11:19:55][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=40 gattc_if=4
[11:19:55][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 40
[11:19:55][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=40 gattc_if=5
[11:19:55][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 2
[11:19:55][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=2 gattc_if=5
[11:19:55][V][esp32_ble_client:134]: [1] [D9:26:25:E6:93:7F] ESP_GATTC_OPEN_EVT
[11:19:55][I][esp32_ble_client:149]: [1] [D9:26:25:E6:93:7F] Connected
[11:19:55][V][bluetooth_proxy:100]: [0] Used connection by [C2:B2:2D:15:6C:4F]
[11:19:55][V][bluetooth_proxy:100]: [1] Used connection by [D9:26:25:E6:93:7F]
[11:19:55][V][bluetooth_proxy:097]: [2] Free connection
[11:19:55][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 6] - 40
[11:19:55][V][esp32_ble_client:119]: [2] [] gattc_event_handler: event=40 gattc_if=6
[11:19:55][W][component:214]: Component esp32_ble took a long time for an operation (0.11 s).
[11:19:55][W][component:215]: Components should block for at most 20-30ms.
[11:19:55][D][esp32_ble_tracker:266]: Starting scan...
[11:19:55][V][bluetooth_proxy.connection:258]: [1] [D9:26:25:E6:93:7F] Registering for GATT characteristic notifications handle 18
[11:19:55][V][esp32_ble:314]: (BLE) gap_event_handler - 2
[11:19:55][V][esp32_ble:314]: (BLE) gap_event_handler - 7
[11:19:55][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 38
[11:19:55][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=38 gattc_if=5
[11:19:55][V][bluetooth_proxy.connection:236]: [1] [D9:26:25:E6:93:7F] Writing GATT descriptor handle 19
[11:19:55][V][bluetooth_proxy.connection:198]: [1] [D9:26:25:E6:93:7F] Writing GATT characteristic handle 16
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 46
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=46 gattc_if=5
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 18
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=18 gattc_if=5
[11:19:56][V][esp32_ble_client:165]: [1] [D9:26:25:E6:93:7F] cfg_mtu status 0, mtu 247
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 9
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=9 gattc_if=5
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 4
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=4 gattc_if=5
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 10
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=10 gattc_if=5
[11:19:56][V][bluetooth_proxy.connection:137]: [1] [D9:26:25:E6:93:7F] ESP_GATTC_NOTIFY_EVT: handle=0x12
[11:19:56][V][bluetooth_proxy.connection:198]: [1] [D9:26:25:E6:93:7F] Writing GATT characteristic handle 16
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 4
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=4 gattc_if=5
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 10
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=10 gattc_if=5
[11:19:56][V][bluetooth_proxy.connection:137]: [1] [D9:26:25:E6:93:7F] ESP_GATTC_NOTIFY_EVT: handle=0x12
[11:19:56][V][bluetooth_proxy.connection:198]: [1] [D9:26:25:E6:93:7F] Writing GATT characteristic handle 16
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 4
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=4 gattc_if=5
[11:19:56][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 10
[11:19:56][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=10 gattc_if=5
[11:19:56][V][bluetooth_proxy.connection:137]: [1] [D9:26:25:E6:93:7F] ESP_GATTC_NOTIFY_EVT: handle=0x12
[11:19:56][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:19:56][V][bluetooth_proxy:058]: Proxying 1 packets
[11:19:57][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:19:57][V][bluetooth_proxy:058]: Proxying 1 packets
[11:19:59][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:19:59][V][bluetooth_proxy:058]: Proxying 1 packets
[11:20:00][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:00][V][bluetooth_proxy:058]: Proxying 1 packets
[11:20:00][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:00][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:00][V][bluetooth_proxy:058]: Proxying 2 packets
[11:20:01][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:01][V][bluetooth_proxy:058]: Proxying 1 packets
[11:20:02][I][esp32_ble_client:086]: [0] [C2:B2:2D:15:6C:4F] Disconnecting.
[11:20:02][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 5
[11:20:02][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=5 gattc_if=4
[11:20:02][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[11:20:02][V][esp32_ble_client:119]: [0] [C2:B2:2D:15:6C:4F] gattc_event_handler: event=41 gattc_if=4
[11:20:02][V][esp32_ble_client:173]: [0] [C2:B2:2D:15:6C:4F] ESP_GATTC_DISCONNECT_EVT, reason 22
[11:20:02][V][bluetooth_proxy:097]: [0] Free connection
[11:20:02][V][bluetooth_proxy:100]: [1] Used connection by [D9:26:25:E6:93:7F]
[11:20:02][V][bluetooth_proxy:097]: [2] Free connection
[11:20:02][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[11:20:02][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=41 gattc_if=5
[11:20:02][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 6] - 41
[11:20:02][V][esp32_ble_client:119]: [2] [] gattc_event_handler: event=41 gattc_if=6
[11:20:02][W][component:214]: Component esp32_ble took a long time for an operation (0.09 s).
[11:20:02][W][component:215]: Components should block for at most 20-30ms.
[11:20:02][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:02][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:02][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:02][V][bluetooth_proxy:058]: Proxying 3 packets
[11:20:04][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:04][V][bluetooth_proxy:058]: Proxying 1 packets
[11:20:05][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:05][V][esp32_ble:314]: (BLE) gap_event_handler - 3
[11:20:05][V][bluetooth_proxy:058]: Proxying 2 packets
[11:20:05][I][esp32_ble_client:086]: [1] [D9:26:25:E6:93:7F] Disconnecting.
[11:20:05][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 5
[11:20:05][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=5 gattc_if=5
[11:20:05][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 4] - 41
[11:20:05][V][esp32_ble_client:119]: [0] [] gattc_event_handler: event=41 gattc_if=4
[11:20:05][V][esp32_ble:342]: (BLE) gattc_event [esp_gatt_if: 5] - 41
[11:20:05][V][esp32_ble_client:119]: [1] [D9:26:25:E6:93:7F] gattc_event_handler: event=41 gattc_if=5
[11:20:05][V][esp32_ble_client:173]: [1] [D9:26:25:E6:93:7F] ESP_GATTC_DISCONNECT_EVT, reason 22

I can recreate this pretty much every time.

Happy to recreate / provide more results as necessary

What version of Home Assistant Core has the issue?

core-2024.2.0b6

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Switchbot

Link to integration documentation on our website

https://www.home-assistant.io/integrations/switchbot/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

The recurring error seems to be:

2024-02-05 11:19:54.132 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 576, in update
    self._update_parsed_data(info)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/device.py", line 611, in _update_parsed_data
    self._set_parsed_data(self._sb_adv_data, merged_data)
  File "/usr/local/lib/python3.12/site-packages/switchbot/devices/curtain.py", line 68, in _set_parsed_data
    new_position = data["position"]
                   ~~~~^^^^^^^^^^^^
KeyError: 'position'


### Additional information

_No response_
@home-assistant
Copy link

home-assistant bot commented Feb 5, 2024

Hey there @Danielhiversen, @RenierM26, @murtas, @Eloston, @dsypniewski, mind taking a look at this issue as it has been labeled with an integration (switchbot) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of switchbot can trigger bot actions by commenting:

  • @home-assistant close Closes the issue.
  • @home-assistant rename Awesome new title Renames the issue.
  • @home-assistant reopen Reopen the issue.
  • @home-assistant unassign switchbot Removes the current integration label and assignees on the issue, add the integration domain after the command.
  • @home-assistant add-label needs-more-information Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue.
  • @home-assistant remove-label needs-more-information Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)


switchbot documentation
switchbot source
(message by IssueLinks)

@frenck frenck added this to the 2024.2.0 milestone Feb 5, 2024
@rkaramandi
Copy link
Author

Update: saw core-2024.2.0b7 was out and updated; issue still persists.

@derekcentrico
Copy link

@Danielhiversen this likely is related to #108087

@lviciedo
Copy link

lviciedo commented Feb 8, 2024

issue persists
image

@rkaramandi
Copy link
Author

Issue seems to be fixed in 2024.2, probably with #110275 by bumping PySwitchBot to 0.45.0

@github-actions github-actions bot locked and limited conversation to collaborators Mar 31, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants