search

TionAPI / HA-tion

Home assistant integration for Tion breezers
Apache License 2.0
72 stars 6 forks source link

Отваливаются почему-то тионы и периодически не работает управление. #60

Closed kalend closed 2 years ago

kalend commented 3 years ago

Приветствую.

Стоит HA на Raspberry PI4B. HA установлен в docker, имеется HACS и установленный HA-Tion HA version: core-2021.9.6 HA-Tion version: v2.0.0

Описание проблемы:

Имеем несколько Tion lite, подключенных через Raspberry PI 4. Выглядит так, будто периодически Тионы отваливаются по Bluetooth. Интеграция работает через раз - периодически выдает ошибки. Куда копать пока не понял. В bluetoothctl видно как Тионы подключаются и отключаются. 

bluetoothctl 
Agent registered
[bluetooth]#  connect FC:2C:C1:7C:F9:DC
Attempting to connect to FC:2C:C1:7C:F9:DC
[Br Lite]# connect F9:EF:AC:46:D0:5C
Attempting to connect to F9:EF:AC:46:D0:5C
[CHG] Device F9:EF:AC:46:D0:5C Connected: yes
Connection successful
[CHG] Device F9:EF:AC:46:D0:5C ServicesResolved: yes
[CHG] Device F9:EF:AC:46:D0:5C Paired: yes
[CHG] Device F9:EF:AC:46:D0:5C ServicesResolved: no
[CHG] Device F9:EF:AC:46:D0:5C Connected: no
...

В логах HA:

Error doing job: Task exception was never retrieved
21:31:40 – (ОШИБКА) Tion breezer (кастомная интеграция)
Response is {}
21:31:40 – (КРИТИЧЕСКАЯ ОШИБКА) Tion breezer (кастомная интеграция)
Got Device disconnected while read in handleNotification. May continue working.
21:31:40 – (ПРЕДУПРЕЖДЕНИЕ) /usr/local/lib/python3.9/site-packages/tion_btle/tion.py - первое сообщение получено 19:04:10 и повторялось 2 раз
Error executing service: <ServiceCall climate.set_temperature (c:d9a8282f48fce414ccfd4f0f9146ca78): temperature=7.0, entity_id=['climate.gostevaya']>
21:30:57 – (ОШИБКА) Tion breezer (кастомная интеграция) - первое сообщение получено 21:18:29 и повторялось 2 раз
Got BTLEDisconnectError:Device disconnected
21:30:57 – (ПРЕДУПРЕЖДЕНИЕ) /usr/local/lib/python3.9/site-packages/tion_btle/tion.py - первое сообщение получено 19:03:07 и повторялось 76 раз
_enable_notifications: got 'Device disconnected' while first read! Could not continue!
21:30:37 – (КРИТИЧЕСКАЯ ОШИБКА) /usr/local/lib/python3.9/site-packages/tion_btle/tion.py - первое сообщение получено 19:15:11 и повторялось 3 раз
IATkachenko commented 3 years ago

В сторону BT копать. Если есть возможность -- попробуйте внешний стик и подключить через удлинитель (чтобы адаптер был на некотором расстоянии от малины).

kalend commented 3 years ago

Внешний стик это конечно аварийный вариант, но его пока нет. Вопрос - а должна ли интеграция держать BLE соединение с тионами или она только соединяется для управления? Сам bluetooth connect работает на ура с этими железками. Не ли рецепта для Bluetooth малины?

IATkachenko commented 3 years ago

Нет, интеграция соединение установленным не держит. По двум причинам:

  1. BTLE -- точка-точка, те если соединение не закрыть, то никто к бризеру подключиться не сможет
  2. если от бризера не отключиться, то хост ничего не сможет делать с BTLE. Соответственно, интеграция повторят тот трюк, который делает приложение, если поставить галочку "разрешить множественные подключения" (или как-то так, приложение давно не видел): подключается только для того чтобы считать состояние и передать новые параметры (есть неприятность что считанное не запоминается на уровне модуля, но я пока так и не определился: баг это или фича :) )

Но и постоянных ошибок _enable_notifications: got 'Device disconnected' while first read! Could not continue! и Got Device disconnected while read in handleNotification. May continue working. быть не должно.

На встроенном BT малины:

Собственно эволюция у меня была Pi-3 (нужен был апгрейд железа, в части USB-3) -> Pi-4 -> Pi-4 со стиком.

Но нормально -- это примерно десяток дисконнектов в день, без заметного влияния на работу.

IATkachenko commented 3 years ago

У меня (Pi-4 со стиком, Tion 3S) за 1.5 дня в логах примерно 50 сообщений Failed to connect, без дисконнектов.

IATkachenko commented 3 years ago

Еще в #58 обсуждали проблемы похожей инсталляции.

kalend commented 3 years ago

Интересная еще ругань в логах и сегодня самопроизвольно HA перезапустился (последнее было про Tion). 2021-10-28 19:13:52 CRITICAL (MainThread) [custom_components.tion] Response is {} 2021-10-28 19:13:52 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/config/custom_components/tion/climate.py", line 395, in _async_update_state await self._tion_entry.async_update_state(time, force, keep_connection) File "/config/custom_components/tion/init.py", line 122, in async_update_state raise e File "/config/custom_components/tion/init.py", line 99, in async_update_state response = self.__tion.get(keep_connection) File "/usr/local/lib/python3.9/site-packages/tion_btle/tion.py", line 235, in get response = self._get_data_from_breezer() File "/usr/local/lib/python3.9/site-packages/tion_btle/tion.py", line 601, in _get_data_from_breezer self._btle.waitForNotifications(1.0) File "/usr/local/lib/python3.9/site-packages/bluepy/btle.py", line 560, in waitForNotifications resp = self._getResp(['ntfy','ind'], timeout) File "/usr/local/lib/python3.9/site-packages/bluepy/btle.py", line 416, in _getResp self.delegate.handleNotification(hnd, data) File "/usr/local/lib/python3.9/site-packages/tion_btle/tion.py", line 41, in handleNotification self.__topic.read() File "/usr/local/lib/python3.9/site-packages/bluepy/btle.py", line 197, in read return self.peripheral.readCharacteristic(self.valHandle) File "/usr/local/lib/python3.9/site-packages/bluepy/btle.py", line 530, in readCharacteristic resp = self._getResp('rd') File "/usr/local/lib/python3.9/site-packages/bluepy/btle.py", line 407, in _getResp resp = self._waitResp(wantType + ['ntfy', 'ind'], timeout) File "/usr/local/lib/python3.9/site-packages/bluepy/btle.py", line 338, in _waitResp if self._helper.poll() is not None: AttributeError: 'NoneType' object has no attribute 'poll'

kalend commented 3 years ago

Еще в #58 обсуждали проблемы похожей инсталляции.

Спасибо, там все-таки иное - свисток есть и докеру не сказали с каким bluetooth общаться. Хотя возможно что-то здравое есть. Покопаю в сторону докера.

kalend commented 3 years ago

Валится все-таки достаточно часто. Вот в логах так выглядит еще: 2021-10-28 19:26:56 ERROR (stream_worker) [homeassistant.components.stream.worker] Error demuxing stream: 2021-10-28 19:28:42 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral F9:EF:AC:46:D5:5C, addr type: random 2021-10-28 19:28:45 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Device disconnected 2021-10-28 19:28:45 CRITICAL (MainThread) [custom_components.tion] Got exception Device disconnected 2021-10-28 19:28:45 CRITICAL (MainThread) [custom_components.tion] Will delay next check 2021-10-28 19:29:52 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral d0:9b:f3:17:55:0d, addr type: random 2021-10-28 19:29:52 ERROR (stream_worker) [homeassistant.components.stream.worker] Error demuxing stream: 2021-10-28 19:30:54 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral fc:2c:c1:7c:f1:dc, addr type: random 2021-10-28 19:30:57 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral fc:2c:c1:7c:f1:dc, addr type: random 2021-10-28 19:30:57 CRITICAL (MainThread) [custom_components.tion] Got exception Failed to connect to peripheral fc:2c:c1:7c:f1:dc, addr type: random 2021-10-28 19:30:57 CRITICAL (MainThread) [custom_components.tion] Will delay next check 2021-10-28 19:34:52 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral d0:9b:f3:17:55:0d, addr type: random 2021-10-28 19:38:55 ERROR (stream_worker) [homeassistant.components.stream.worker] Error demuxing stream: 2021-10-28 19:39:41 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral F9:EF:AC:46:D5:5C, addr type: random 2021-10-28 19:40:40 ERROR (stream_worker) [homeassistant.components.stream.worker] Error demuxing stream: 2021-10-28 19:40:54 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral fc:2c:c1:7c:f1:dc, addr type: random 2021-10-28 19:40:54 CRITICAL (MainThread) [custom_components.tion] Got exception Failed to connect to peripheral fc:2c:c1:7c:f1:dc, addr type: random 2021-10-28 19:40:54 CRITICAL (MainThread) [custom_components.tion] Will delay next check 2021-10-28 19:41:42 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Device disconnected 2021-10-28 19:41:44 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral F9:EF:AC:46:D5:5C, addr type: random 2021-10-28 19:41:44 CRITICAL (MainThread) [custom_components.tion] Got exception Failed to connect to peripheral F9:EF:AC:46:D5:5C, addr type: random 2021-10-28 19:41:44 CRITICAL (MainThread) [custom_components.tion] Will delay next check 2021-10-28 19:43:12 ERROR (stream_worker) [homeassistant.components.stream.worker] Error demuxing stream: 2021-10-28 19:47:52 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral d0:9b:f3:17:55:0d, addr type: random 2021-10-28 19:50:12 ERROR (stream_worker) [homeassistant.components.stream.worker] Error demuxing stream:

IATkachenko commented 3 years ago

@kalend, боюсь что копать в сторону bluetooth надо, а не докера.

IATkachenko commented 2 years ago

@kalend, в v2.1.2 @kizill это, похоже, поправил. После обновления лучше стало?

kalend commented 2 years ago

По ощущениям железки себе спокойно управляются и реагируют. Однако в логах HA жуть творится. Вот пример за сегодня. Может убрать логирование столь детальное в дебаг или таймауты и кол-во коннектов увеличить, чтобы ругань не сыпала так часто?

Logger: tion_btle.tion Source: /usr/local/lib/python3.9/site-packages/tion_btle/tion.py:361 First occurred: 11 января 2022 г., 20:17:23 (435 occurrences) Last logged: 12:11:28

Got BTLEDisconnectError:Failed to connect to peripheral d0:9b:f3:17:44:0d, addr type: random Got BTLEDisconnectError:Failed to connect to peripheral fc:2c:c1:7c:f9:dc, addr type: random Got BTLEDisconnectError:Failed to connect to peripheral F9:EF:AC:46:D0:5C, addr type: random Got BTLEDisconnectError:Device disconnected

IATkachenko commented 2 years ago

Логируется неудачная попытка сделать connect внутри python-модуля, что само по себе не нормально. Глянул свои логи -- у меня тоже самое, так что будет возможность поковырять.

kalend commented 2 years ago

Я думаю, что причина кроется в timeout. Полагаю, что эти железки работают так: делается connect, команда выполняется и они по bluetooth отключаются. При каждом запросе-изменении идет повторный connect. Это я проверял руками, когда делал connect по bluetooth к Tion. Полагаю, что при попытке сделать connect из интеграции есть задержка для первого запроса и нужно его повторить (кстати иногда замечал на предыдущей версии, что Тионы управляются со второго, а не с первого раза, что подтверждает сей факт) и видимо по таймауту идет логирование. Если таймауты увеличить или сделать повторные запросы без фиксации ошибки в логах, то возможно это полечит проблему.

IATkachenko commented 2 years ago

Да, общая схема действительно такая: connect - команда - disconnect. Если команд несколько, то они группируются в одну пачку. Сделано это чтобы к бризеру можно было подключиться пультом/приложением между опросами. На DEBUG уровне для tion_btle.tion хорошо видно как это происходит: Нормальный запрос, без ошибки

2022-01-12 14:15:07 DEBUG (MainThread) [tion_btle.tion] Connecting
2022-01-12 14:15:08 DEBUG (MainThread) [tion_btle.tion] Enabling notification

С ошибкой

2022-01-12 14:18:07 DEBUG (MainThread) [tion_btle.tion] Connecting
2022-01-12 14:18:08 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral RR:RR:RR:RR:RR:RR, addr type: random
2022-01-12 14:18:08 DEBUG (MainThread) [tion_btle.tion] Will try again.
2022-01-12 14:18:10 DEBUG (MainThread) [tion_btle.tion] Connecting
2022-01-12 14:18:11 DEBUG (MainThread) [tion_btle.tion] Enabling notification

Происходит все здесь: https://github.com/TionAPI/tion_python/blob/6f25f1dcb5e231a7b77ba98fa80c4ee43fc5559b/tion_btle/tion.py#L345

Мне там сейчас не очень нравится кусок с определением характеристик. И, думаю, виноват именно этот блок.

Я у себя еще поэкспериментирую на эту тему, но дело явно не в timeout, поскольку BTLEDisconnectError прилетает мгновенно.

Не фиксировать ошибку я тоже не буду: это только маскирует проблему. Если сильно мешает -- можно в настройках логирования указать в configuration.yaml:

logger:
  logs:
    tion_btle.tion: critical

Тогда эти варнинги от модуля сыпаться в лог не будут.

IATkachenko commented 2 years ago

Нет, этот блок работает корректно.

2022-01-12 14:44:32 DEBUG (MainThread) [tion_btle.tion] Connecting
2022-01-12 14:44:32 DEBUG (MainThread) [tion_btle.tion] Connection_status is disc
2022-01-12 14:44:32 WARNING (MainThread) [tion_btle.tion] Got BTLEDisconnectError:Failed to connect to peripheral ..., addr type: random
2022-01-12 14:44:32 DEBUG (MainThread) [tion_btle.tion] Will try again.

Куда копать я понял. В ближайшее время будет fix-релиз для этого и завел #65. Это issue, раз пробелма решена, закрываю.