HA stops responding, bluepy-helper 100% CPU

[islepnev]

Не уверен, что дело именно в tion api, но других bluetooth устройств нет в HA.

ps -axfw:

  473 ?        Ssl  617:24 /home/hass/bin/python3.7 /home/hass/bin/hass -c /home/hass/.homeassistant
29021 ?        R    121:32  \_ /home/hass/lib/python3.7/site-packages/bluepy/bluepy-helper

top:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                               
29021 hass      20   0    3880    780    696 R  98.7   0.1 123:26.61 bluepy-helper                                                                                                                         
  473 hass      20   0  985492 191708  10132 S   0.7  19.4 617:25.36 hass                                                                                                                                  

HA web UI не отвечает.

[IATkachenko]

@islepnev, проблема стабильно воспроизводится/появляется (чтобы можно было поднять уровнь логов и посмотерть что происходит?)

[islepnev]

Hi,

@islepnev <https://github.com/islepnev>, проблема стабильно воспроизводится/появляется (чтобы можно было поднять уровнь логов и посмотерть что происходит?)

Насчет стабильности сложно оценить, но логи поанализировать надо. Где подкрутить?

…

-- Илья Слепнёв islepnev@gmail.com

[IATkachenko]

Полный вариант для configuration.yaml вот такой:

logger:
  default: warning
  logs:
    custom_components.tion.climate: debug
    s3: debug
    tion: debug
    tion.s3: debug

Дебага будет много, но будет видно чем занимается компонент и на какой стадии подвисает.

[IATkachenko]

@islepnev, удалось что-нибудь добыть?

[fishenebelny]

Нечто подобное проявляется. Только не Bluepy-helper грузит систему, а все подвисает. История не грузится. Кнопки не нажимаются, хотя по пунктам меню HA еще можно перемещаться.

[fishenebelny]

Я даже логи не могу вытащить. Кружочек крутится и крутится.

[fishenebelny]

Логи после рестарта все.

Логи

2020-08-25 12:28:52 INFO (MainThread) [homeassistant.bootstrap] Config directory: /home/homeassistant/.homeassistant
2020-08-25 12:28:52 WARNING (SyncWorker_0) [homeassistant.util.yaml.loader] YAML file /home/homeassistant/.homeassistant/configuration.yaml contains duplicate key "logger". Check lines 64 and 72
2020-08-25 12:28:52 INFO (SyncWorker_1) [homeassistant.loader] Loaded gismeteo from custom_components.gismeteo
2020-08-25 12:28:52 INFO (SyncWorker_3) [homeassistant.loader] Loaded sonoff from custom_components.sonoff
2020-08-25 12:28:52 INFO (SyncWorker_2) [homeassistant.loader] Loaded hacs from custom_components.hacs
2020-08-25 12:28:52 INFO (SyncWorker_1) [homeassistant.loader] Loaded tion from custom_components.tion
2020-08-25 12:28:52 INFO (SyncWorker_4) [homeassistant.loader] Loaded mosenergosbyt from custom_components.mosenergosbyt
2020-08-25 12:28:52 INFO (SyncWorker_4) [homeassistant.loader] Loaded homeassistant from homeassistant.components.homeassistant
2020-08-25 12:28:52 INFO (SyncWorker_0) [homeassistant.loader] Loaded persistent_notification from homeassistant.components.persistent_notification
2020-08-25 12:28:52 INFO (MainThread) [homeassistant.setup] Setting up homeassistant
2020-08-25 12:28:52 INFO (MainThread) [homeassistant.setup] Setup of domain homeassistant took 0.0 seconds
2020-08-25 12:28:52 INFO (MainThread) [homeassistant.setup] Setting up persistent_notification
2020-08-25 12:28:52 INFO (MainThread) [homeassistant.setup] Setup of domain persistent_notification took 0.0 seconds
2020-08-25 12:28:52 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for sonoff which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-08-25 12:28:52 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-08-25 12:28:52 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for tion which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-08-25 12:28:52 INFO (SyncWorker_26) [homeassistant.loader] Loaded script from homeassistant.components.script
2020-08-25 12:28:52 INFO (SyncWorker_1) [homeassistant.loader] Loaded logger from homeassistant.components.logger
2020-08-25 12:28:52 INFO (SyncWorker_24) [homeassistant.loader] Loaded tts from homeassistant.components.tts
2020-08-25 12:28:52 INFO (SyncWorker_27) [homeassistant.loader] Loaded utility_meter from homeassistant.components.utility_meter
2020-08-25 12:28:52 INFO (SyncWorker_5) [homeassistant.loader] Loaded scene from homeassistant.components.scene
2020-08-25 12:28:52 INFO (SyncWorker_13) [homeassistant.loader] Loaded group from homeassistant.components.group
2020-08-25 12:28:52 INFO (SyncWorker_9) [homeassistant.loader] Loaded cast from homeassistant.components.cast
2020-08-25 12:28:52 INFO (SyncWorker_11) [homeassistant.loader] Loaded tuya from homeassistant.components.tuya
2020-08-25 12:28:52 INFO (SyncWorker_3) [homeassistant.loader] Loaded counter from homeassistant.components.counter
2020-08-25 12:28:52 INFO (SyncWorker_16) [homeassistant.loader] Loaded mobile_app from homeassistant.components.mobile_app
2020-08-25 12:28:52 INFO (SyncWorker_0) [homeassistant.loader] Loaded automation from homeassistant.components.automation
2020-08-25 12:28:52 INFO (SyncWorker_4) [homeassistant.loader] Loaded cloud from homeassistant.components.cloud
2020-08-25 12:28:52 INFO (SyncWorker_12) [homeassistant.loader] Loaded shopping_list from homeassistant.components.shopping_list
2020-08-25 12:28:52 INFO (SyncWorker_14) [homeassistant.loader] Loaded recorder from homeassistant.components.recorder
2020-08-25 12:28:52 INFO (SyncWorker_17) [homeassistant.loader] Loaded weather from homeassistant.components.weather
2020-08-25 12:28:52 INFO (SyncWorker_23) [homeassistant.loader] Loaded sensor from homeassistant.components.sensor
2020-08-25 12:28:52 INFO (SyncWorker_18) [homeassistant.loader] Loaded met from homeassistant.components.met
2020-08-25 12:28:52 INFO (SyncWorker_6) [homeassistant.loader] Loaded binary_sensor from homeassistant.components.binary_sensor
2020-08-25 12:28:52 INFO (SyncWorker_25) [homeassistant.loader] Loaded zha from homeassistant.components.zha
2020-08-25 12:28:52 INFO (SyncWorker_7) [homeassistant.loader] Loaded esphome from homeassistant.components.esphome
2020-08-25 12:28:52 INFO (SyncWorker_2) [homeassistant.loader] Loaded speedtestdotnet from homeassistant.components.speedtestdotnet
2020-08-25 12:28:52 INFO (SyncWorker_33) [homeassistant.loader] Loaded default_config from homeassistant.components.default_config
2020-08-25 12:28:52 INFO (SyncWorker_15) [homeassistant.loader] Loaded smartthings from homeassistant.components.smartthings
2020-08-25 12:28:52 INFO (SyncWorker_35) [homeassistant.loader] Loaded http from homeassistant.components.http
2020-08-25 12:28:52 INFO (SyncWorker_29) [homeassistant.loader] Loaded zeroconf from homeassistant.components.zeroconf
2020-08-25 12:28:52 INFO (SyncWorker_31) [homeassistant.loader] Loaded websocket_api from homeassistant.components.websocket_api
2020-08-25 12:28:52 INFO (SyncWorker_30) [homeassistant.loader] Loaded webhook from homeassistant.components.webhook
2020-08-25 12:28:52 INFO (SyncWorker_38) [homeassistant.loader] Loaded fan from homeassistant.components.fan
2020-08-25 12:28:52 INFO (SyncWorker_40) [homeassistant.loader] Loaded api from homeassistant.components.api
2020-08-25 12:28:52 INFO (SyncWorker_41) [homeassistant.loader] Loaded frontend from homeassistant.components.frontend
2020-08-25 12:28:52 INFO (SyncWorker_43) [homeassistant.loader] Loaded alexa from homeassistant.components.alexa
2020-08-25 12:28:52 INFO (SyncWorker_42) [homeassistant.loader] Loaded person from homeassistant.components.person
2020-08-25 12:28:52 INFO (SyncWorker_34) [homeassistant.loader] Loaded auth from homeassistant.components.auth
2020-08-25 12:28:52 INFO (SyncWorker_24) [homeassistant.loader] Loaded config from homeassistant.components.config
2020-08-25 12:28:52 INFO (SyncWorker_27) [homeassistant.loader] Loaded device_automation from homeassistant.components.device_automation
2020-08-25 12:28:52 INFO (SyncWorker_13) [homeassistant.loader] Loaded lovelace from homeassistant.components.lovelace
2020-08-25 12:28:52 INFO (SyncWorker_11) [homeassistant.loader] Loaded onboarding from homeassistant.components.onboarding
2020-08-25 12:28:52 INFO (SyncWorker_16) [homeassistant.loader] Loaded search from homeassistant.components.search
2020-08-25 12:28:52 INFO (SyncWorker_4) [homeassistant.loader] Loaded system_log from homeassistant.components.system_log
2020-08-25 12:28:52 INFO (SyncWorker_14) [homeassistant.loader] Loaded history from homeassistant.components.history
2020-08-25 12:28:52 INFO (SyncWorker_6) [homeassistant.loader] Loaded logbook from homeassistant.components.logbook
2020-08-25 12:28:52 INFO (SyncWorker_25) [homeassistant.loader] Loaded map from homeassistant.components.map
2020-08-25 12:28:52 INFO (SyncWorker_54) [homeassistant.loader] Loaded ssdp from homeassistant.components.ssdp
2020-08-25 12:28:52 INFO (SyncWorker_7) [homeassistant.loader] Loaded sun from homeassistant.components.sun
2020-08-25 12:28:52 INFO (SyncWorker_15) [homeassistant.loader] Loaded system_health from homeassistant.components.system_health
2020-08-25 12:28:52 INFO (SyncWorker_22) [homeassistant.loader] Loaded updater from homeassistant.components.updater
2020-08-25 12:28:52 INFO (SyncWorker_37) [homeassistant.loader] Loaded zone from homeassistant.components.zone
2020-08-25 12:28:52 INFO (SyncWorker_35) [homeassistant.loader] Loaded input_boolean from homeassistant.components.input_boolean
2020-08-25 12:28:52 INFO (SyncWorker_32) [homeassistant.loader] Loaded input_datetime from homeassistant.components.input_datetime
2020-08-25 12:28:52 INFO (SyncWorker_29) [homeassistant.loader] Loaded input_text from homeassistant.components.input_text
2020-08-25 12:28:52 INFO (SyncWorker_19) [homeassistant.loader] Loaded input_number from homeassistant.components.input_number
2020-08-25 12:28:52 INFO (SyncWorker_30) [homeassistant.loader] Loaded input_select from homeassistant.components.input_select
2020-08-25 12:28:52 INFO (MainThread) [homeassistant.bootstrap] Domains to be set up: {'counter', 'auth', 'zone', 'scene', 'search', 'ssdp', 'recorder', 'cast', 'mobile_app', 'input_number', 'weather', 'automation', 'api', 'system_log', 'device_automation', 'webhook', 'tuya', 'speedtestdotnet', 'sonoff', 'config', 'input_select', 'frontend', 'group', 'websocket_api', 'binary_sensor', 'sensor', 'input_boolean', 'tts', 'cloud', 'updater', 'met', 'shopping_list', 'logger', 'http', 'smartthings', 'esphome', 'fan', 'system_health', 'zha', 'lovelace', 'script', 'hacs', 'map', 'tion', 'onboarding', 'default_config', 'history', 'input_text', 'zeroconf', 'person', 'alexa', 'sun', 'input_datetime', 'logbook', 'utility_meter', 'persistent_notification'}
2020-08-25 12:28:52 INFO (MainThread) [homeassistant.bootstrap] Setting up logging: {'recorder', 'system_log', 'logger'}
2020-08-25 12:28:53 INFO (MainThread) [homeassistant.setup] Setting up recorder
2020-08-25 12:28:53 INFO (MainThread) [homeassistant.setup] Setting up logger
2020-08-25 12:28:57 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for gismeteo which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-08-25 12:29:00 INFO (MainThread) [custom_components.tion] Setting up None 
2020-08-25 12:29:00 INFO (MainThread) [custom_components.tion] Setting up None 
2020-08-25 12:29:13 WARNING (MainThread) [custom_components.tion] Tion instance updated at None
2020-08-25 12:29:13 DEBUG (MainThread) [custom_components.tion] Update fired force = True. Keep connection is False
2020-08-25 12:29:13 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 1/3
2020-08-25 12:29:14 DEBUG (MainThread) [tion_btle.tion] Enabling notification
2020-08-25 12:29:14 DEBUG (MainThread) [tion_btle.tion] Notify handler is 11
2020-08-25 12:29:14 DEBUG (MainThread) [tion_btle.tion] Will write b'\x01\x00' to 12 handle
2020-08-25 12:29:14 DEBUG (MainThread) [tion_btle.tion] Result is {'rsp': ['wr']}
2020-08-25 12:29:15 DEBUG (MainThread) [tion_btle.tion] Doing _try_write. Attempt 1/3
2020-08-25 12:29:15 DEBUG (MainThread) [tion_btle.tion] Writing 3d0100000000000000000000000000000000005a to 6e400002-b5a3-f393-e0a9-e50e24dcca9e
2020-08-25 12:29:15 DEBUG (MainThread) [tion_btle.tion] Got data in 11 response b310260a03001717164b010e00008c1d0033005a
2020-08-25 12:29:15 WARNING (MainThread) [custom_components.tion] Tion instance updated at None
2020-08-25 12:29:15 DEBUG (MainThread) [custom_components.tion] Update fired force = True. Keep connection is False
2020-08-25 12:29:15 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 1/3
2020-08-25 12:29:25 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:29:27 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:29:27 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 2/3
2020-08-25 12:30:07 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:30:09 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:30:09 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 3/3
2020-08-25 12:30:47 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:30:49 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:30:49 ERROR (MainThread) [tion_btle.s3] ('_connect', 'Could not connect to c4:64:95:c3:5e:79')
2020-08-25 12:30:49 CRITICAL (MainThread) [custom_components.tion] Response is {'code': 400, 'error': "Got exception ('_connect', 'Could not connect to c4:64:95:c3:5e:79')"}
2020-08-25 12:30:49 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of binary_sensor platform ping is taking over 10 seconds.
2020-08-25 12:30:49 WARNING (MainThread) [homeassistant.components.weather] Setup of weather platform met is taking over 10 seconds.
2020-08-25 12:30:49 WARNING (MainThread) [homeassistant.components.climate] Setup of climate platform tion is taking over 10 seconds.
2020-08-25 12:30:49 WARNING (MainThread) [homeassistant.components.climate] Setup of climate platform tion is taking over 10 seconds.
2020-08-25 12:30:49 WARNING (MainThread) [homeassistant.components.device_tracker] Setup of device_tracker platform mobile_app is taking over 10 seconds.
2020-08-25 12:30:49 WARNING (MainThread) [homeassistant.components.device_tracker] Setup of device_tracker platform mobile_app is taking over 10 seconds.
2020-08-25 12:30:49 ERROR (MainThread) [homeassistant.components.device_tracker] Setup of platform mobile_app is taking longer than 60 seconds. Startup will proceed without waiting any longer.
2020-08-25 12:30:49 ERROR (MainThread) [homeassistant.components.device_tracker] Setup of platform mobile_app is taking longer than 60 seconds. Startup will proceed without waiting any longer.
2020-08-25 12:30:49 INFO (MainThread) [backoff] Backing off call_api(...) for 1.0s (concurrent.futures._base.TimeoutError)
2020-08-25 12:30:49 ERROR (MainThread) [metno] https://aa015h6buqvih86i1.api.met.no/weatherapi/locationforecast/2.0/classic returned 
2020-08-25 12:30:49 ERROR (MainThread) [homeassistant.components.met.weather] Retrying in 20 minutes
2020-08-25 12:30:49 ERROR (MainThread) [homeassistant.components.updater] Timeout fetching Home Assistant update data
2020-08-25 12:30:49 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: tuya, sonoff, smartthings, zha, hacs
2020-08-25 12:30:49 WARNING (MainThread) [custom_components.tion] Tion instance updated at 2020-08-25 11:30:13.368974+00:00
2020-08-25 12:30:49 DEBUG (MainThread) [custom_components.tion] Update fired force = False. Keep connection is False
2020-08-25 12:30:49 DEBUG (MainThread) [custom_components.tion] Now is 2020-08-25 11:30:13.368974+00:00
2020-08-25 12:30:49 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 1/3
2020-08-25 12:30:50 DEBUG (MainThread) [tion_btle.tion] Enabling notification
2020-08-25 12:30:50 DEBUG (MainThread) [tion_btle.tion] Notify handler is 11
2020-08-25 12:30:50 DEBUG (MainThread) [tion_btle.tion] Will write b'\x01\x00' to 12 handle
2020-08-25 12:30:50 DEBUG (MainThread) [tion_btle.tion] Result is {'rsp': ['wr']}
2020-08-25 12:30:51 DEBUG (MainThread) [tion_btle.tion] Doing _try_write. Attempt 1/3
2020-08-25 12:30:51 DEBUG (MainThread) [tion_btle.tion] Writing 3d0100000000000000000000000000000000005a to 6e400002-b5a3-f393-e0a9-e50e24dcca9e
2020-08-25 12:30:51 DEBUG (MainThread) [tion_btle.tion] Got data in 11 response b310260a03001717164b010e02008c1d0033005a
2020-08-25 12:30:51 WARNING (MainThread) [custom_components.tion] Tion instance updated at 2020-08-25 11:30:15.425209+00:00
2020-08-25 12:30:51 DEBUG (MainThread) [custom_components.tion] Update fired force = False. Keep connection is False
2020-08-25 12:30:51 DEBUG (MainThread) [custom_components.tion] Now is 2020-08-25 11:30:15.425209+00:00
2020-08-25 12:30:51 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 1/3
2020-08-25 12:30:56 DEBUG (MainThread) [tion_btle.tion] Enabling notification
2020-08-25 12:30:56 DEBUG (MainThread) [tion_btle.tion] Notify handler is 11
2020-08-25 12:30:56 DEBUG (MainThread) [tion_btle.tion] Will write b'\x01\x00' to 12 handle
2020-08-25 12:30:57 DEBUG (MainThread) [tion_btle.tion] Result is {'rsp': ['wr']}
2020-08-25 12:30:58 DEBUG (MainThread) [tion_btle.tion] Doing _try_write. Attempt 1/3
2020-08-25 12:30:58 DEBUG (MainThread) [tion_btle.tion] Writing 3d0100000000000000000000000000000000005a to 6e400002-b5a3-f393-e0a9-e50e24dcca9e
2020-08-25 12:30:58 DEBUG (MainThread) [tion_btle.tion] Got data in 11 response b310210a0100171716ab000e090000bd0033005a
2020-08-25 12:30:58 ERROR (MainThread) [homeassistant.components.climate] Error while setting up tion platform for climate
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity_platform.py", line 192, in _async_setup_platform
    await asyncio.gather(*pending)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity_platform.py", line 301, in async_add_entities
    await asyncio.gather(*tasks)
  File "/srv/homeassistant/lib/python3.7/site-packages/homeassistant/helpers/entity_platform.py", line 472, in _async_add_entity
    await entity.async_added_to_hass()
  File "/home/homeassistant/.homeassistant/custom_components/tion/climate.py", line 333, in async_added_to_hass
    await self._async_update_state(force=True)
  File "/home/homeassistant/.homeassistant/custom_components/tion/climate.py", line 410, in _async_update_state
    await self._tion_entry.async_update_state(time, force, keep_connection)
  File "/home/homeassistant/.homeassistant/custom_components/tion/__init__.py", line 107, in async_update_state
    raise e
  File "/home/homeassistant/.homeassistant/custom_components/tion/__init__.py", line 91, in async_update_state
    self.__out_temp = response["out_temp"]
KeyError: 'out_temp'
2020-08-25 12:30:58 WARNING (MainThread) [custom_components.tion.sensor] Init of sensor input temperature for 66d6f182c5e144baa7fd2de9be7788e5 
2020-08-25 12:30:58 WARNING (MainThread) [custom_components.tion.sensor] Init of sensor filters remain for 66d6f182c5e144baa7fd2de9be7788e5 
2020-08-25 12:30:58 WARNING (MainThread) [custom_components.tion.sensor] Init of sensor input temperature for 41120e979e634e49bcfa391287469890 
2020-08-25 12:30:58 WARNING (MainThread) [custom_components.tion.sensor] Init of sensor filters remain for 41120e979e634e49bcfa391287469890 
2020-08-25 12:30:58 ERROR (MainThread) [homeassistant.components.sensor] Platform tion does not generate unique IDs. ID Tion Breezer input temperature input temperature already exists - ignoring sensor.tion_breezer_input_temperature
2020-08-25 12:30:58 ERROR (MainThread) [homeassistant.components.sensor] Platform tion does not generate unique IDs. ID Tion Breezer filters remain filters remain already exists - ignoring sensor.tion_breezer_filters_remain
2020-08-25 12:30:58 ERROR (MainThread) [snitun.client.client_peer] Challenge/Response error with SniTun server
2020-08-25 12:30:58 ERROR (MainThread) [hass_nabucasa.remote] Connection problem to snitun server
2020-08-25 12:30:58 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for mosenergosbyt which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-08-25 12:30:59 WARNING (MainThread) [homeassistant.setup] Setup of sonoff is taking over 10 seconds.

[fishenebelny]

Попробовал нажать кнопку выключения проветривателя. Ничего не произошло. Попробовал через выпадающее меню его выключить. Ничего не произошло. Он также и продолжает работать. А еще не может подгрузить историю по температуре.
До этого такого не было. Практически моментальная обратная связь была.

Нажимал кнопку где-то в 14:38.

Details

Логи

2020-08-25 12:36:57 WARNING (MainThread) [custom_components.tion] Tion instance updated at 2020-08-25 11:36:04.393127+00:00
2020-08-25 12:36:57 DEBUG (MainThread) [custom_components.tion] Update fired force = False. Keep connection is False
2020-08-25 12:36:57 DEBUG (MainThread) [custom_components.tion] Now is 2020-08-25 11:36:04.393127+00:00
2020-08-25 12:36:57 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 1/3
2020-08-25 12:36:58 DEBUG (MainThread) [tion_btle.tion] Enabling notification
2020-08-25 12:36:58 DEBUG (MainThread) [tion_btle.tion] Notify handler is 11
2020-08-25 12:36:58 DEBUG (MainThread) [tion_btle.tion] Will write b'\x01\x00' to 12 handle
2020-08-25 12:36:59 DEBUG (MainThread) [tion_btle.tion] Result is {'rsp': ['wr']}
2020-08-25 12:36:59 DEBUG (MainThread) [tion_btle.tion] Doing _try_write. Attempt 1/3
2020-08-25 12:36:59 DEBUG (MainThread) [tion_btle.tion] Writing 3d0100000000000000000000000000000000005a to 6e400002-b5a3-f393-e0a9-e50e24dcca9e
2020-08-25 12:36:59 DEBUG (MainThread) [tion_btle.tion] Got data in 11 response b310260a03001717164b010e08008c1d0033005a
2020-08-25 12:36:59 WARNING (MainThread) [custom_components.tion] Tion instance updated at 2020-08-25 11:36:04.393403+00:00
2020-08-25 12:36:59 DEBUG (MainThread) [custom_components.tion] Update fired force = False. Keep connection is False
2020-08-25 12:36:59 DEBUG (MainThread) [custom_components.tion] Now is 2020-08-25 11:36:04.393403+00:00
2020-08-25 12:36:59 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 1/3
2020-08-25 12:37:30 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:37:32 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:37:32 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 2/3
2020-08-25 12:37:50 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:37:52 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:37:52 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 3/3
2020-08-25 12:38:32 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:38:34 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:38:34 ERROR (MainThread) [tion_btle.s3] ('_connect', 'Could not connect to c4:64:95:c3:5e:79')
2020-08-25 12:38:34 CRITICAL (MainThread) [custom_components.tion] Response is {'code': 400, 'error': "Got exception ('_connect', 'Could not connect to c4:64:95:c3:5e:79')"}
2020-08-25 12:38:34 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/home/homeassistant/.homeassistant/custom_components/tion/climate.py", line 410, in _async_update_state
    await self._tion_entry.async_update_state(time, force, keep_connection)
  File "/home/homeassistant/.homeassistant/custom_components/tion/__init__.py", line 107, in async_update_state
    raise e
  File "/home/homeassistant/.homeassistant/custom_components/tion/__init__.py", line 91, in async_update_state
    self.__out_temp = response["out_temp"]
KeyError: 'out_temp'
2020-08-25 12:38:34 WARNING (MainThread) [homeassistant.components.zone] Updating zone zone took longer than the scheduled update interval 0:00:15
2020-08-25 12:38:34 WARNING (MainThread) [homeassistant.components.sensor] Updating hacs sensor took longer than the scheduled update interval 0:00:30
2020-08-25 12:38:34 WARNING (MainThread) [aiohttp.websocket] websocket connection is closing.
2020-08-25 12:38:34 WARNING (MainThread) [custom_components.tion] Tion instance updated at 2020-08-25 11:37:57.818885+00:00
2020-08-25 12:38:34 DEBUG (MainThread) [custom_components.tion] Update fired force = False. Keep connection is False
2020-08-25 12:38:34 DEBUG (MainThread) [custom_components.tion] Now is 2020-08-25 11:37:57.818885+00:00
2020-08-25 12:38:34 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 1/3
2020-08-25 12:38:35 DEBUG (MainThread) [tion_btle.tion] Enabling notification
2020-08-25 12:38:35 DEBUG (MainThread) [tion_btle.tion] Notify handler is 11
2020-08-25 12:38:35 DEBUG (MainThread) [tion_btle.tion] Will write b'\x01\x00' to 12 handle
2020-08-25 12:38:35 DEBUG (MainThread) [tion_btle.tion] Result is {'rsp': ['wr']}
2020-08-25 12:38:36 DEBUG (MainThread) [tion_btle.tion] Doing _try_write. Attempt 1/3
2020-08-25 12:38:36 DEBUG (MainThread) [tion_btle.tion] Writing 3d0100000000000000000000000000000000005a to 6e400002-b5a3-f393-e0a9-e50e24dcca9e
2020-08-25 12:38:36 DEBUG (MainThread) [tion_btle.tion] Got data in 11 response b310260a03001717164b010e0a008c1d0033005a
2020-08-25 12:38:36 WARNING (MainThread) [custom_components.tion] Tion instance updated at 2020-08-25 11:37:57.819203+00:00
2020-08-25 12:38:36 DEBUG (MainThread) [custom_components.tion] Update fired force = False. Keep connection is False
2020-08-25 12:38:36 DEBUG (MainThread) [custom_components.tion] Now is 2020-08-25 11:37:57.819203+00:00
2020-08-25 12:38:36 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 1/3
2020-08-25 12:38:37 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:38:39 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:38:39 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 2/3
2020-08-25 12:39:02 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:39:04 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:39:04 DEBUG (MainThread) [tion_btle.tion] Doing _connect. Attempt 3/3
2020-08-25 12:39:23 WARNING (MainThread) [tion_btle.tion] Got Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random exception
2020-08-25 12:39:25 WARNING (MainThread) [tion_btle.tion] Got exception while _connect: Failed to connect to peripheral c4:64:95:c3:5e:79, addr type: random
2020-08-25 12:39:25 ERROR (MainThread) [tion_btle.s3] ('_connect', 'Could not connect to c4:64:95:c3:5e:79')
2020-08-25 12:39:25 CRITICAL (MainThread) [custom_components.tion] Response is {'code': 400, 'error': "Got exception ('_connect', 'Could not connect to c4:64:95:c3:5e:79')"}
2020-08-25 12:39:25 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/home/homeassistant/.homeassistant/custom_components/tion/climate.py", line 410, in _async_update_state
    await self._tion_entry.async_update_state(time, force, keep_connection)
  File "/home/homeassistant/.homeassistant/custom_components/tion/__init__.py", line 107, in async_update_state
    raise e
  File "/home/homeassistant/.homeassistant/custom_components/tion/__init__.py", line 91, in async_update_state
    self.__out_temp = response["out_temp"]
KeyError: 'out_temp'

[fishenebelny]

Удалил второй Тион и все стало замечательно. Выключатели стали работать, история стала подгружаться, Тион управляется прям как с пульта.

[islepnev]

поставил v1.3.1 тестироваться с HA 0.114.3. Pairing прошел с первого раза.

[IATkachenko]

@islepnev, спасибо.

Но проблема этого issue еще не решена (если мы не запутались и в оригинале проблема была тоже из-за нескольких устройств).
Да даже если и нет, нужно всеравно сделать модуль более асинхронным.

[IATkachenko]

@fishenebelny, похоже у вас и у @islepnev разные источники подвисания системы: у вас из-за нескольких бризеров, а у @islepnev из-за того что не проходил pairing.

@islepnev, у вас же с одним бризером была проблема (разрешившаяся после v1.3.1)? Если так, то это issue я прикрою (чтобы не путаться) и заведу новое на проблемы с одновременным опросом двух устройств.

@fishenebelny, касательно проблемы двух устройств: попробуйте v1.4.0-b1 -- это, возможно, частично, решит вашу проблему (в части получения данных. Изменение настроек буду делать если пойму что на верном пути).

[fishenebelny]

Пока на версии 1.4 не спаривается. И зависает при обновлении информации. Установка hassos с нуля.

[Flaxing]

При первой установке столкнулся с такой же проблемой. Помогло это:
killall bluepy-helper
По мотивам: IanHarvey/bluepy#239 (comment)

После не устанавливалась интеграция, ошибка парирования, помогло это:
bluetoothctl
[bluetooth]# help
[bluetooth]# power off
[bluetooth]# power on
[bluetooth]# pairable on
[bluetooth]# scan on
[bluetooth]# paired-devices
Device E9:XX:XX:XX:XX:22 Tion Breezer 3S
[bluetooth]# remove E9:XX:XX:XX:XX:22
[bluetooth]# trust E9:XX:XX:XX:XX:22
Интеграция установилась сходу.

[bluetooth]# pairable off

[fishenebelny]

На версии 1.4 не спаривается и со вторым Тионом. Хотя раньше вроде все в порядке было. Сейчас попробую назад к версии 1.3.1 перейти и посмотреть как будет.

[IATkachenko]

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

1. минимально возможное расстояние и отсутствие преград;
2. отсутствие подключений к бризеру другими устройствами;
3. отсутствие подключений устройства (в данном случае малины) к другим BT девайсам.

[vekser]

минимально возможное расстояние и отсутствие преград;

Возможно ли узнать RSSI от тиона до старта общения ? Т.е перед общением проверять уровень сигнала .

[vekser]

минимально возможное расстояние и отсутствие преград;

Есть способ это решить. Можно уменьшать расстояние, а можно уменьшить скорость передачи или поднять мошность передатчика. Это взаимозаменяемые параметры.
Т.е можно сделать одно или несколько из

• Увеличить мощность передатчика
• Увеличить чувствительность приемника (читаем, уменьшить скорость)
• Изменить вид модуляции, который более помехозащишенный

Подробнее тут (Table 2. Sensitivity Levels for Various Devices and Data Rates)
Я , пока, не вижу, как можно поменять конфигурацию BLE модуля RPI.

[vekser]

Про увеличение мощности передатчика. Похоже , нужен внешний BLE адаптер класса 1
https://www.raspberrypi.org/forums/viewtopic.php?t=155960

Как вариант https://shop.espruino.com/usb-bluetooth с внешней антенной.

Кроме того, у RPI BLE чипсет совмешен с Wifi. У них одна антенна и они не могут работать одновременно. Возможно может помочь отключение Wifi.

[fishenebelny]

Вполне может быть что проблема с бт адаптером малины. С того места, где ога у меня стоит телефон стабильно подкдючается к двум бризерам.
А вот сама малина иногда отваливается и не может получить информацию с бризера. Более того, с телефона уверенно цепляется к брищерам из соседней комнаты. Когда самамалина оттуда ничего сдедать через компонент не могла.
Надо действительно попробовать внешний бт модуль с какой нить внешней антенной.

[vekser]

• Я отключил wifi малины, буду наблюдать.
• Скоро получу такой адаптер , попробую с ним https://www.silabs.com/wireless/bluetooth/bluegiga-low-energy-legacy-modules/device.bled112.
• Есть еще вариант. Почему нельзя написать небольшое внешнее приложение, которое будет смотреть за загрузкой процессора и перезапускать весь HA , если там 100% от bluepy ? Пример, внешний питон скрипт делает что-то вроде

wget http://localhost:8123
HTTP request sent, awaiting response... 200 OK

Если возвращает 200 OK, значит работает.

Если

wget http://localhost:8123
Connecting to localhost (localhost)|::1|:8123... failed: Connection refused.
Connecting to localhost (localhost)|127.0.0.1|:8123... failed: Connection refused.

Идем на перезагрузку всей малины.

[vekser]

Похоже, действительно один из факторов данной проблемы - это коллизии работы с wifi на одну встроенную антенну
Посмотрите, пожалуйста, https://www.raspberrypi.org/forums/viewtopic.php?t=145423

[fishenebelny]

Ну та малина 3. У меня малина 4. Но вполне может быть. Надо будет внешний адаптер докупить и посмотреть как будет работать. Если стабильнее, то супер. Но я уже подустал спаривать тион и малину потоянно. Думаю, что у себя не ранее, чем через 3 недели что-то смогу узнать.

[vekser]

Отключение wifi не сильно помогло. Опять 100% от bluepy-helper. Думаю, нужно мониторить доступность HA и перезагружать малину.
Пример

[vekser]

Настроил монитор monit для контроля загрузки процессора.
Конфиг файл следующего вида

set daemon 120  with start delay 5 

check process bluepy-helper
        matching "bluepy-helper"
        stop program = "/usr/bin/killall bluepy-helper"
        if cpu usage > 80% for 2 cycles then stop

Проблема не заставила долго себя ждать

[EST Dec 24 08:26:00] error    : 'bluepy-helper' cpu usage of 100.0% matches resource limit [cpu usage>80.0%]
[EST Dec 24 08:28:00] error    : 'bluepy-helper' cpu usage of 99.8% matches resource limit [cpu usage>80.0%]
[EST Dec 24 08:28:00] info     : 'bluepy-helper' trying to restart
[EST Dec 24 08:28:00] info     : 'bluepy-helper' stop: '/usr/bin/killall bluepy-helper'
[EST Dec 24 08:30:00] info     : 'bluepy-helper' cpu usage check succeeded [current cpu usage=0.0%]

monit убил bluepy-helper, при этом HA продолжает работать и управлять устройством.

Единственно что, если за 4 мин перед циклами проверки произойдет какое-то событие, которое прописано в триггерах скрипта автоматизации HA, то оно будет пропушено. Но это меньшее из зол с такой проблемой.

P.S.
Следующий конфиг monit работает более стабильно

set daemon 120  with start delay 5 

check process bluepy-helper matching "bluepy-helper"
        if cpu usage > 80% for 2 cycles then exec "/bin/systemctl restart hassio-apparmor.service"

[fishenebelny]

Ну та малина 3. У меня малина 4. Но вполне может быть. Надо будет внешний адаптер докупить и посмотреть как будет работать. Если стабильнее, то супер. Но я уже подустал спаривать тион и малину потоянно. Думаю, что у себя не ранее, чем через 3 недели что-то смогу узнать.

Проверил с внешним безантенным бт4.0 адаптером CSR. На том же самом месте Тион через стенку вообще не видит. Видимо зависимость на БТ адаптер очень большая. Заказал еще другой адвптер бт5.0, который тоже должен в распберри поддерживаться. Попозже может быть еще и с антенной закажу.

[fishenebelny]

Установил другой адвптер. С антенной. Работает пока "как часы" оттуда где раньше не видел ни один Тион.
Прогресс видится. Мне кажется это уже не совсем относится к теме зависания.

[vekser]

@fishenebelny какую модель адаптера используете ?
"Мне кажется это уже не совсем относится к теме зависания." Думаю, относится. Не должно виснуть, если связь плохая.

[fishenebelny]

Адаптер - https://a.aliexpress.com/_9I5e4l
Но чтобы спарить черещ него Тион пришлось какие то танцы с бубном плясать. Не тооько по настройке ОС, но и в процессе добавления.
В файлах ОС мак Тиона есть, ключи там есть, но спаривание не проходит. В paired-devices не вилится. Пришлось удалять, добавлять, делать pair через bluetoothctl.
Потом добавлять без спаривания. В общем как-то добавился Тион. После полутора часа чтения вики и мнодественных попыток спарить.

[fishenebelny]

Подключил второй Тион. Посмотрим как будет работать.
Появилась идея, что у моих Тионов разные бт модули от разных производителей, разной мощности, что влияет на работу.

Посмотрим как будет работать с новым адаптером в новой расстановке.