ble_monitor icon indicating copy to clipboard operation
ble_monitor copied to clipboard

Published 20 hours ago • verified publisher icon custom-components

[Bug]: ble_monitor keeps trying to listen on bt-interfaces even if they are not available

Open Magalex2x14 opened this issue 2 years ago • 2 comments

What happened?

Log from issue #815 highlighted a bug - integration keeps trying to collect data from unavailable (or not LE) interfaces. Next will be a slightly cleaned up log (the original is here).

Sensor type

No response

Relevant log output

2022-04-07 17:11:07 DEBUG (MainThread) [custom_components.ble_monitor.bt_helpers] Response(header=<event_code=CommandCompleteEvent, controller_idx=0, param_len=283>, event_frame=<command_opcode=ReadControllerInformation, status=Success>, cmd_response_frame=<address=00:15:E9:7B:5F:83, bluetooth_version=2, manufacturer=15, supported_settings=69823, current_settings={Powered: True, Connectable: False, FastConnectable: False, Discoverable: False, Bondable: False, LinkLevelSecurity: False, SecureSimplePairing: False, BREDR: True, HighSpeed: False, LowEnergy: False, Advertising: False, SecureConnections: False, DebugKeys: False, Privacy: False, ControllerConfiguration: False, StaticAddress: False, PHYConfiguration: False, WidebandSpeech: False}, class_of_device=2097152, name=b'ha-mougins #1', short_name=0>)
2022-04-07 17:11:07 WARNING (MainThread) [custom_components.ble_monitor.bt_helpers] hci0 (00:15:E9:7B:5F:83) have no BT LE capabilities and will be ignored.
2022-04-07 17:11:07 DEBUG (MainThread) [custom_components.ble_monitor.bt_helpers] No Bluetooth LE adapter found. Make sure Bluetooth is installed on your system.
2022-04-07 17:11:07 DEBUG (MainThread) [custom_components.ble_monitor] Initializing BLE Monitor integration (YAML): {'hci_interface': [1, 0], 'bt_auto_restart': True, 'active_scan': False, 'discovery': False, 'period': 60, 'use_median': False, 'decimals': 1, 'log_spikes': False, 'restore_state': True, 'report_unknown': False, 'devices': [{'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température salon', 'encryption_key': '8b903cb68eb7dc12db481d2396467ccd', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}, {'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température entrée', 'encryption_key': '82cf0c1e3e539c7a3845da6127019d19', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}], 'batt_entities': True, 'bt_interface': 'disable', 'is_flow': False, 'ids_from_name': True}
2022-04-07 17:11:09 DEBUG (MainThread) [custom_components.ble_monitor.config_flow] async_step_import: {'hci_interface': [1, 0], 'bt_auto_restart': True, 'active_scan': False, 'discovery': False, 'period': 60, 'use_median': False, 'decimals': 1, 'log_spikes': False, 'restore_state': True, 'report_unknown': False, 'devices': [{'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température salon', 'encryption_key': '8b903cb68eb7dc12db481d2396467ccd', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}, {'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température entrée', 'encryption_key': '82cf0c1e3e539c7a3845da6127019d19', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}], 'batt_entities': True, 'bt_interface': 'disable', 'is_flow': False, 'ids_from_name': True}
2022-04-07 17:11:09 DEBUG (MainThread) [custom_components.ble_monitor.config_flow] async_step_user: {'hci_interface': [1, 0], 'bt_auto_restart': True, 'active_scan': False, 'discovery': False, 'period': 60, 'use_median': False, 'decimals': 1, 'log_spikes': False, 'restore_state': True, 'report_unknown': False, 'devices': '--Devices--', 'batt_entities': True, 'bt_interface': 'disable', 'is_flow': False, 'ids_from_name': True}
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] Initializing BLE Monitor entry (config entry): <homeassistant.config_entries.ConfigEntry object at 0x7fb08d1400>
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] async_setup_entry: domain {'hci_interface': [1, 0], 'bt_auto_restart': True, 'active_scan': False, 'discovery': False, 'period': 60, 'use_median': False, 'decimals': 1, 'log_spikes': False, 'restore_state': True, 'report_unknown': False, 'devices': [{'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température salon', 'encryption_key': '8b903cb68eb7dc12db481d2396467ccd', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}, {'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température entrée', 'encryption_key': '82cf0c1e3e539c7a3845da6127019d19', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}], 'batt_entities': True, 'bt_interface': 'disable', 'is_flow': False, 'ids_from_name': True}
2022-04-07 17:11:14 INFO (MainThread) [custom_components.ble_monitor] Available Bluetooth interfaces for BLE monitor: ["Don't use Bluetooth adapter"]
2022-04-07 17:11:14 ERROR (MainThread) [custom_components.ble_monitor] Bluetooth interface hci1 is not available
2022-04-07 17:11:14 ERROR (MainThread) [custom_components.ble_monitor] Bluetooth interface hci0 is not available
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] HCI interface is [1, 0]
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] async_setup_entry: {'hci_interface': [1, 0], 'bt_auto_restart': True, 'active_scan': False, 'discovery': False, 'period': 60, 'use_median': False, 'decimals': 1, 'log_spikes': False, 'restore_state': True, 'report_unknown': False, 'devices': [{'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température salon', 'encryption_key': '8b903cb68eb7dc12db481d2396467ccd', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}, {'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température entrée', 'encryption_key': '82cf0c1e3e539c7a3845da6127019d19', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}], 'batt_entities': True, 'bt_interface': [], 'is_flow': False, 'ids_from_name': True}
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] Spawning HCIdump thread
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] HCIdump thread: Init
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] 2 encryptors mac:key pairs loaded
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] sensor whitelist: [XX:XX:XX:XX:XX:XX, XX:XX:XX:XX:XX:XX]
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] 2 sensor whitelist item(s) loaded
2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] 0 device tracker(s) being monitored
2022-04-07 17:11:14 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: Run
2022-04-07 17:11:14 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: BLEScanRequester._initialized is False for hci0, waiting for connection...
2022-04-07 17:11:14 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: connected to hci0
2022-04-07 17:11:14 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: BLEScanRequester._initialized is True for hci0, connection established, send_scan_request succeeded.
2022-04-07 17:11:14 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: BLEScanRequester._initialized is False for hci1, waiting for connection...
2022-04-07 17:11:16 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: connected to hci1
2022-04-07 17:11:16 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: BLEScanRequester._initialized is True for hci1, connection established, send_scan_request succeeded.
2022-04-07 17:11:16 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: start main event_loop
2022-04-07 17:12:15 DEBUG (MainThread) [custom_components.ble_monitor.sensor] 0 BLE advertisements processed for 0 sensor device(s)
2022-04-07 17:12:15 DEBUG (MainThread) [custom_components.ble_monitor.binary_sensor] 0 BLE advertisements processed for 0 binary sensor device(s)
2022-04-07 17:12:15 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: main event_loop stopped, finishing.
2022-04-07 17:12:15 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: Scanning will be restarted
2022-04-07 17:12:15 DEBUG (Thread-3) [custom_components.ble_monitor] 6 HCI events processed for previous period
2022-04-07 17:12:16 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: Run
2022-04-07 17:12:16 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: BLEScanRequester._initialized is False for hci0, waiting for connection...
2022-04-07 17:12:16 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: connected to hci0
2022-04-07 17:12:16 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: BLEScanRequester._initialized is True for hci0, connection established, send_scan_request succeeded.
2022-04-07 17:12:16 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: BLEScanRequester._initialized is False for hci1, waiting for connection...
2022-04-07 17:12:17 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: connected to hci1
2022-04-07 17:12:17 ERROR (Thread-3) [root] Uncaught thread exception
Traceback (most recent call last):
File "/usr/local/lib/python3.9/threading.py", line 973, in _bootstrap_inner
self.run()
File "/config/custom_components/ble_monitor/__init__.py", line 742, in run
self._event_loop.run_until_complete(
File "/usr/local/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
return future.result()
File "/usr/local/lib/python3.9/site-packages/aioblescan/aioblescan.py", line 1806, in send_scan_request
if self._use_ext_scan():
File "/usr/local/lib/python3.9/site-packages/aioblescan/aioblescan.py", line 1791, in _use_ext_scan
return (self._supported_commands[37] & 0x60) == 0x60
TypeError: 'NoneType' object is not subscriptable
2022-04-07 17:12:23 DEBUG (MainThread) [custom_components.ble_monitor.device_tracker] 0 BLE ADV messages processed last 60 seconds for 0 device tracker device(s)
 
2022-04-07 17:13:16 DEBUG (MainThread) [custom_components.ble_monitor] Spawning HCIdump thread

Magalex2x14 avatar Apr 07 '22 17:04 Magalex2x14

The case described above refers to a YAML-configured integration

Magalex2x14 avatar Apr 07 '22 18:04 Magalex2x14

Just to understand. in first instance, both hci interfaces are not available

2022-04-07 17:11:14 ERROR (MainThread) [custom_components.ble_monitor] Bluetooth interface hci1 is not available
2022-04-07 17:11:14 ERROR (MainThread) [custom_components.ble_monitor] Bluetooth interface hci0 is not available

But, as it has been set up in YAML, it just ignores this fact, and configures hci0 and hci1 anyway

2022-04-07 17:11:14 DEBUG (MainThread) [custom_components.ble_monitor] async_setup_entry: {'hci_interface': [1, 0], 'bt_auto_restart': True, 'active_scan': False, 'discovery': False, 'period': 60, 'use_median': False, 'decimals': 1, 'log_spikes': False, 'restore_state': True, 'report_unknown': False, 'devices': [{'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température salon', 'encryption_key': '8b903cb68eb7dc12db481d2396467ccd', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}, {'mac': 'XX:XX:XX:XX:XX:XX', 'name': 'Température entrée', 'encryption_key': '82cf0c1e3e539c7a3845da6127019d19', 'temperature_unit': '°C', 'decimals': 2, 'use_median': False, 'restore_state': True, 'report_unknown': False, 'consider_home': 180, 'track_device': False, 'tracker_scan_interval': 20, 'reset_timer': 35}], 'batt_entities': True, 'bt_interface': [], 'is_flow': False, 'ids_from_name': True}

It than just starts to connect to the hci interfaces, and it even is able to connect.

2022-04-07 17:11:14 DEBUG (Thread-3) [custom_components.ble_monitor] HCIdump thread: connected to hci0

In the end it fails, as it doesn't support LE capabilities.

question What I don't understand yet is why it is saying in the begin that the hci interface is unavailable, while later on, it is able to connect to it.

possible solution Modify the code that it doesn't setup hci0 and hci1, if it is "unavailable" (like is done in UI mode).

Ernst79 avatar Apr 08 '22 06:04 Ernst79