`Software caused connection abort` [НА 2022.8+, интеграция 4.1.1]

[driftertest]

Общая информация

• версия Home Assistant:
• способ установки Home Assistant:
  [ ] venv
  [x] Docker
  [ ] Home Assistant OS
• версия компонента: Home Assistant 2022.9.5
• модель бризера: Lite and 4S
• версия python-модуля:

[x] в момент проявления проблемы к бризеру никто не подключен
[x] bluetooth в системе работает корректно, действий из WiKi не требуется
[x] проблема не похожа ни на одну из FAQ

Краткое описание

Бризеры подключаются, каждые 120 секунд происходит опрос состояния, все функции работают. Но через какое-то время останавливается опрос и нельзя управлять бризерами через НА. После перезагрузки НА соединение восстанавливается и все работает какое-то время. Бризеры отваливаются не одновременно, а рандомно.

Debug-log

2022-09-25 12:10:13.001 INFO (MainThread) [custom_components.ha_tion_btle] Tion instance update started
2022-09-25 12:10:13.001 DEBUG (MainThread) [tion_btle.tion] Connecting. self.connection_status='disc'.
2022-09-25 12:10:13.001 DEBUG (MainThread) [tion_btle.tion] Trying 0/1: _try_connect(args=(<tion_btle.s4.TionS4 object at 0x147cd05d8310>,),kwargs={})
2022-09-25 12:10:13.001 DEBUG (MainThread) [tion_btle.tion] Updating _btle instance from HaBleakClientWrapper, E1:C1:DC:B1:93:12 to E1:C1:DC:B1:93:12: Breezer 4S
2022-09-25 12:10:19.699 DEBUG (MainThread) [tion_btle.tion] Enabling notification. self.connection_status='connected'
2022-09-25 12:10:19.922 DEBUG (MainThread) [tion_btle.tion] _enable_notifications done
2022-09-25 12:10:19.922 DEBUG (MainThread) [tion_btle.tion] _connect done. self.connection_status='connected'.
2022-09-25 12:10:19.922 DEBUG (MainThread) [tion_btle.tion] Trying 0/3: _try_write(args=(<tion_btle.s4.TionS4 object at 0x147cd05d8310>,),kwargs={'request': bytearray(b'\x80\x10\x00:\xa122\x9c{\xecE\xbcZ\x82h\xbb\xaa')})
2022-09-25 12:10:19.922 DEBUG (MainThread) [tion_btle.tion] Writing 8010003aa132329c7bec45bc5a8268bbaa to 98f00002-3788-83ea-453e-f52244709ddb, self.connection_status='connected'
2022-09-25 12:10:20.057 DEBUG (MainThread) [tion_btle.tion] Collecting data
2022-09-25 12:10:20.057 DEBUG (MainThread) [tion_btle.tion] Got data in 17 response 002f003a8431329c7bec45991b5a9e3f81001001
2022-09-25 12:10:20.057 DEBUG (MainThread) [tion_btle.tion] self._data=[bytearray(b'\x00/\x00:\x8412\x9c{\xecE\x99\x1bZ\x9e?\x81\x00\x10\x01')]
2022-09-25 12:10:20.058 DEBUG (MainThread) [tion_btle.tion] Got data in 17 response 40090b131fab420100513d0100b310ec00c5f803
2022-09-25 12:10:20.058 DEBUG (MainThread) [tion_btle.tion] self._data=[bytearray(b'\x00/\x00:\x8412\x9c{\xecE\x99\x1bZ\x9e?\x81\x00\x10\x01'), bytearray(b'@\t\x0b\x13\x1f\xabB\x01\x00Q=\x01\x00\xb3\x10\xec\x00\xc5\xf8\x03')]
2022-09-25 12:10:20.059 DEBUG (MainThread) [tion_btle.tion] Got data in 17 response c000000000000600ae38
2022-09-25 12:10:20.059 DEBUG (MainThread) [tion_btle.tion] self._data=[bytearray(b'\x00/\x00:\x8412\x9c{\xecE\x99\x1bZ\x9e?\x81\x00\x10\x01'), bytearray(b'@\t\x0b\x13\x1f\xabB\x01\x00Q=\x01\x00\xb3\x10\xec\x00\xc5\xf8\x03'), bytearray(b'\xc0\x00\x00\x00\x00\x00\x06\x00\xae8')]
2022-09-25 12:10:21.058 DEBUG (MainThread) [tion_btle.tion] Disconnecting. self.connection_status='connected'.
2022-09-25 12:10:23.838 DEBUG (MainThread) [tion_btle.tion] Updating _btle instance from HaBleakClientWrapper, E1:C1:DC:B1:93:12 to E1:C1:DC:B1:93:12: Breezer 4S
2022-09-25 12:10:23.838 DEBUG (MainThread) [tion_btle.tion] _disconnect done. self.connection_status='disc'
2022-09-25 12:10:23.838 DEBUG (MainThread) [custom_components.ha_tion_btle] Result is {'state': 'on', 'heater': False, 'heating': 'off', 'sound': 'on', 'mode': 'outside', 'out_temp': 11, 'in_temp': 9, 'heater_temp': 16, 'fan_speed': 1, 'filter_remain': 180, 'time': '12:10', 'request_error_code': 0, 'model': 'S4', 'light': 'on', 'is_on': True, 'is_heating': False, 'rssi': -83}
2022-09-25 12:10:23.838 DEBUG (MainThread) [custom_components.ha_tion_btle] Finished fetching Tion Breezer data in 10.838 seconds (success: True)
2022-09-25 12:11:40.001 INFO (MainThread) [custom_components.ha_tion_btle] Tion instance update started
2022-09-25 12:11:40.001 DEBUG (MainThread) [tion_btle.tion] Connecting. self.connection_status='disc'.
2022-09-25 12:11:40.001 DEBUG (MainThread) [tion_btle.tion] Trying 0/1: _try_connect(args=(<tion_btle.lite.TionLite object at 0x147cd9211d20>,),kwargs={})
2022-09-25 12:11:40.001 DEBUG (MainThread) [tion_btle.tion] Updating _btle instance from HaBleakClientWrapper, FB:3C:73:09:D8:3C to FB:3C:73:09:D8:3C: Br Lite
2022-09-25 12:11:47.173 DEBUG (MainThread) [tion_btle.tion] Enabling notification. self.connection_status='connected'
2022-09-25 12:11:47.396 DEBUG (MainThread) [tion_btle.tion] _enable_notifications done
2022-09-25 12:11:47.396 DEBUG (MainThread) [tion_btle.tion] _connect done. self.connection_status='connected'.
2022-09-25 12:11:47.396 DEBUG (MainThread) [tion_btle.tion] Trying 0/3: _try_write(args=(<tion_btle.lite.TionLite object at 0x147cd9211d20>,),kwargs={'request': bytearray(b'\x80\x10\x00:\x022\x12\r\xd7\x1f\x8fH\xd3\xc3\x1a\xbb\xaa')})
2022-09-25 12:11:47.396 DEBUG (MainThread) [tion_btle.tion] Writing 8010003a0232120dd71f8f48d3c31abbaa to 98f00002-3788-83ea-453e-f52244709ddb, self.connection_status='connected'
2022-09-25 12:11:47.531 DEBUG (MainThread) [tion_btle.tion] Collecting data
2022-09-25 12:11:47.531 DEBUG (MainThread) [tion_btle.tion] Got data in 17 response 0049003aef31120dd71f8f1e90a124c7d8021402
2022-09-25 12:11:47.531 DEBUG (MainThread) [tion_btle.tion] self._data=[bytearray(b'\x00I\x00:\xef1\x12\r\xd7\x1f\x8f\x1e\x90\xa1$\xc7\xd8\x02\x14\x02')]
2022-09-25 12:11:47.532 DEBUG (MainThread) [tion_btle.tion] Got data in 17 response 4014142186fedf0573c0370245e1e00047ae2400
2022-09-25 12:11:47.532 DEBUG (MainThread) [tion_btle.tion] self._data=[bytearray(b'\x00I\x00:\xef1\x12\r\xd7\x1f\x8f\x1e\x90\xa1$\xc7\xd8\x02\x14\x02'), bytearray(b'@\x14\x14!\x86\xfe\xdf\x05s\xc07\x02E\xe1\xe0\x00G\xae$\x00')]
2022-09-25 12:11:47.533 DEBUG (MainThread) [tion_btle.tion] Got data in 17 response 4000000000000000000000000000000100000000
2022-09-25 12:11:47.533 DEBUG (MainThread) [tion_btle.tion] self._data=[bytearray(b'\x00I\x00:\xef1\x12\r\xd7\x1f\x8f\x1e\x90\xa1$\xc7\xd8\x02\x14\x02'), bytearray(b'@\x14\x14!\x86\xfe\xdf\x05s\xc07\x02E\xe1\xe0\x00G\xae$\x00'), bytearray(b'@\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00')]
2022-09-25 12:11:47.533 DEBUG (MainThread) [tion_btle.tion] Got data in 17 response c000000000000a14190204060615009c5f
2022-09-25 12:11:47.534 DEBUG (MainThread) [tion_btle.tion] self._data=[bytearray(b'\x00I\x00:\xef1\x12\r\xd7\x1f\x8f\x1e\x90\xa1$\xc7\xd8\x02\x14\x02'), bytearray(b'@\x14\x14!\x86\xfe\xdf\x05s\xc07\x02E\xe1\xe0\x00G\xae$\x00'), bytearray(b'@\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00'), bytearray(b'\xc0\x00\x00\x00\x00\x00\n\x14\x19\x02\x04\x06\x06\x15\x00\x9c_')]
2022-09-25 12:11:48.531 DEBUG (MainThread) [tion_btle.tion] Disconnecting. self.connection_status='connected'.
2022-09-25 12:11:50.952 DEBUG (MainThread) [tion_btle.tion] Updating _btle instance from HaBleakClientWrapper, FB:3C:73:09:D8:3C to FB:3C:73:09:D8:3C: Br Lite
2022-09-25 12:11:50.952 DEBUG (MainThread) [tion_btle.tion] _disconnect done. self.connection_status='disc'
2022-09-25 12:11:50.952 DEBUG (MainThread) [tion_btle.lite] Data is c7d802140214142186fedf0573c0370245e1e00047ae24000000000000000000000000000000010000000000000000000a1419020406061500
2022-09-25 12:11:50.952 DEBUG (MainThread) [custom_components.ha_tion_btle] Result is {'state': 'on', 'heater': True, 'heating': 'off', 'sound': 'on', 'mode': 'outside', 'out_temp': 20, 'in_temp': 20, 'heater_temp': 20, 'fan_speed': 2, 'filter_remain': 171, 'time': '12:11', 'request_error_code': 0, 'model': 'Lite', 'code': 200, 'device_work_time': 27.823043981481483, 'electronic_work_time': 169.90377314814816, 'electronic_temp': 33, 'co2_auto_control': '0', 'filter_change_required': '0', 'light': 'on', 'is_on': True, 'is_heating': False, 'rssi': -87}
2022-09-25 12:11:50.952 DEBUG (MainThread) [custom_components.ha_tion_btle] Finished fetching Tion Lite data in 10.951 seconds (success: True)
2022-09-25 12:12:23.000 INFO (MainThread) [custom_components.ha_tion_btle] Tion instance update started
2022-09-25 12:12:23.000 DEBUG (MainThread) [tion_btle.tion] Connecting. self.connection_status='disc'.
2022-09-25 12:12:23.000 DEBUG (MainThread) [tion_btle.tion] Trying 0/1: _try_connect(args=(<tion_btle.s4.TionS4 object at 0x147cd05d8310>,),kwargs={})
2022-09-25 12:12:23.000 DEBUG (MainThread) [tion_btle.tion] Updating _btle instance from HaBleakClientWrapper, E1:C1:DC:B1:93:12 to E1:C1:DC:B1:93:12: Breezer 4S
2022-09-25 12:12:28.876 WARNING (MainThread) [tion_btle.tion] Got exception: [org.bluez.Error.Failed] Software caused connection abort. Will try again
2022-09-25 12:12:30.878 DEBUG (MainThread) [tion_btle.tion] Trying 1/1: _try_connect(args=(<tion_btle.s4.TionS4 object at 0x147cd05d8310>,),kwargs={})
2022-09-25 12:12:30.878 DEBUG (MainThread) [tion_btle.tion] Updating _btle instance from HaBleakClientWrapper, E1:C1:DC:B1:93:12 to E1:C1:DC:B1:93:12: Breezer 4S
2022-09-25 12:12:34.219 WARNING (MainThread) [tion_btle.tion] Got exception: [org.bluez.Error.Failed] Software caused connection abort. Will not try again
2022-09-25 12:12:36.220 CRITICAL (MainThread) [tion_btle.tion] Retry limit (1) exceeded for _try_connect((<tion_btle.s4.TionS4 object at 0x147cd05d8310>,), {})
2022-09-25 12:12:36.221 DEBUG (MainThread) [tion_btle.tion] Disconnecting. self.connection_status='disc'.
2022-09-25 12:12:36.221 DEBUG (MainThread) [tion_btle.tion] _disconnect done. self.connection_status='disc'
2022-09-25 12:12:36.221 CRITICAL (MainThread) [custom_components.ha_tion_btle] Got exception 
2022-09-25 12:12:36.222 CRITICAL (MainThread) [custom_components.ha_tion_btle] Will delay next check
2022-09-25 12:12:36.222 ERROR (MainThread) [custom_components.ha_tion_btle] Error fetching Tion Breezer data: MaxTriesExceededError
2022-09-25 12:12:36.222 DEBUG (MainThread) [custom_components.ha_tion_btle] Finished fetching Tion Breezer data in 13.222 seconds (success: False)

[IATkachenko]

Software caused connection abort
Нужно выяснять что в этот момент произошло.
Если сходить в dmesg в этот момент будет сообщение об отключении BT.

Примерно через какое время поле рестарта это происходит? В HA видел правки на тему проблем с BT из-за того что они принудительно scan гоняют...

Без перезагрузки есть два варианта:

1. спокойно подождать 10 минут. В случае таких проблем интеграция берет таймаут 10 минут чтобы бризеры/bluetooth пришли в себя.
2. вызвать вот такую службу, если очень не терпится:

service: homeassistant.update_entity
data: {}
target:
  entity_id: climate.tion_breezer

это запустит процесс обновления.

[IATkachenko]

У меня это выглядит так:

2022-09-25 14:27:15.058 DEBUG (MainThread) [custom_components.ha_tion_btle] Finished fetching Tion Breezer data in 5.056 seconds (success: True)
2022-09-25 14:28:15.003 INFO (MainThread) [custom_components.ha_tion_btle] Tion instance update started
...
2022-09-25 14:28:17.854 WARNING (MainThread) [tion_btle.tion] Got exception: [org.bluez.Error.Failed] Software caused connection abort. Will not try again
2022-09-25 14:28:19.861 CRITICAL (MainThread) [tion_btle.tion] Retry limit (1) exceeded for _try_connect((<tion_btle.s3.TionS3 object at 0x7f6688e3e0>,), {})
2022-09-25 14:28:19.863 DEBUG (MainThread) [tion_btle.tion] Disconnecting. self.connection_status='disc'.
2022-09-25 14:28:19.863 DEBUG (MainThread) [tion_btle.tion] _disconnect done. self.connection_status='disc'
2022-09-25 14:28:19.864 CRITICAL (MainThread) [custom_components.ha_tion_btle] Got exception
2022-09-25 14:28:19.865 CRITICAL (MainThread) [custom_components.ha_tion_btle] Will delay next check
2022-09-25 14:28:19.868 ERROR (MainThread) [custom_components.ha_tion_btle] Error fetching Tion Breezer data: MaxTriesExceededError
...

А дальше самое неприятное: подвисает bleak.connect()

2022-09-25 14:38:19.002 INFO (MainThread) [custom_components.ha_tion_btle] Tion instance update started
2022-09-25 14:38:19.003 DEBUG (MainThread) [tion_btle.tion] Connecting. self.connection_status='disc'.
2022-09-25 14:38:19.003 DEBUG (MainThread) [tion_btle.tion] Trying 0/1: _try_connect(args=(<tion_btle.s3.TionS3 object at 0x7f6688e3e0>,),kwargs={})
2022-09-25 14:38:19.004 DEBUG (MainThread) [tion_btle.tion] Updating _btle instance from HaBleakClientWrapper, FF:FF:FF:FF:FF:FF to FF:FF:FF:FF:FF:FF: Tion Breezer 3S

dmesg, кстати, оказался чистым.

Рестарт bluetooth не помогает.
Вчера более-менее стабильно весь день отработал...

[driftertest]

dmesg у меня тоже чистый, бризер отваливается совсем, хоть несколько часов жди. Причем сейчас 4S отвалился по логу в 12-12, а Lite работает корректно до сих пор и прошло 3 часа уже.

[IATkachenko]

Скорее всего висит в том же состоянии, на bleak.connect().
Я сейчас у себя попробую это поймать с debug'ом bleak, но не думаю что это как-то поможет...

[IATkachenko]

Вот так это выглядит с точки зрения bleak

2022-09-25 15:21:01.002 DEBUG (MainThread) [tion_btle.tion] Updating _btle instance from HaBleakClientWrapper, FF:FF:FF:FF:FF:FF to FF:FF:FF:FF:FF:FF: Tion Breezer 3S
2022-09-25 15:21:01.002 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to device @ FF:FF:FF:FF:FF:FF
2022-09-25 15:21:01.097 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_FF_FF_FF_FF_FF_FF): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -81)>}, []]
2022-09-25 15:21:01.127 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_FF_FF_FF_FF_FF_FF): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', True)>},[]]
2022-09-25 15:21:01.136 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_7D_D0_9C_41_01_06): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -82)>}, []]
2022-09-25 15:21:01.157 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_8C_5A_F8_EC_C4_18): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -82)>}, []]
2022-09-25 15:21:01.415 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_E0_CD_B7_0D_5F_E1): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -79)>}, []]
2022-09-25 15:21:01.601 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_54_48_E6_D3_8E_CB): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -83)>}, []]
2022-09-25 15:21:01.714 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_54_48_E6_D3_8E_CB): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -83)>}, []]
2022-09-25 15:21:01.715 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_7D_D0_9C_41_01_06): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -79)>}, []]
2022-09-25 15:21:02.262 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_7D_D0_9C_41_01_06): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -79)>}, []]
2022-09-25 15:21:02.815 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_7D_D0_9C_41_01_06): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -83)>}, []]
2022-09-25 15:21:02.833 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_FF_FF_FF_FF_FF_FF): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
2022-09-25 15:21:02.834 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Device disconnected (/org/bluez/hci0/dev_FF_FF_FF_FF_FF_FF)
2022-09-25 15:21:02.835 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_FF_FF_FF_FF_FF_FF)

и вот тут bleak.connect() должен вернуть что-то, но нет.

[IATkachenko]

При этом параллельный запрос из скрипта

import asyncio

from tion_btle.s3 import TionS3 as Breezer # don't forget change model

async def main():
    t = Breezer("put_mac_here")
    print(await t.get())

asyncio.run(main())

проходит корректно и приводит к "отвисанию".

[IATkachenko]

В 2022.10 в очредной раз обновили BT.
Теперь есть поддержка активного режима через bluetooth.
В ближайшее время посмотрю как это может помочь нам.

[IATkachenko]

Руки пока не дошли... Но все еще собираюсь :)

[AlexandrErohin]

@IATkachenko Есть новости? :)
Отваливается и не может восстановить соединение. Пробовал напрямую вызвать bluetoothctl connect MAC - не помогает

[IATkachenko]

Ух...
Если последняя версия интеграции работает также плохо, то могу порекомендовать только на https://github.com/dentra/esphome-tion перейти.

[AlexandrErohin]

Пока неделя и полет нормальный)