bleak icon indicating copy to clipboard operation
bleak copied to clipboard
verified publisher icon hbldh

HCI is powering off after few seconds of BLE scanning

Open LukaszBrzyszkiewicz opened this issue 3 years ago • 5 comments

  • bleak version: 0.14.3
  • Python version: 3.9.2
  • Operating System: Debian GNU/Linux 11 (bullseye) 5.10.0-16-amd64
  • BlueZ version (bluetoothctl -v) in case of Linux: 5.64

Description

I'm trying to run Theengs gateway on my NAS but it hangs randomly after few seconds. After restarting Theengs it's working again but after few seconds - hangs again...

What I Did

Those my attempts:

  1. modify Theengs loop to not start/stop scanning constantly but same result. I was trying to do this, because I saw that scanner.stop() function is hanging.
  2. upgraded BlueZ version from native 5.55 to 5.64 - no changes in hangs, but it's wors because when it hangs I need to do hci0 down/up cycle (doesn't up automatically).
  3. enabled debug logs from bleak and it looks like after some time, hci0 is turning down. It's weird, because when I'm using hcitool lescan it scans constantly and issue is not reproducing (passive mode scanning). I was trying to power up hci0 again, but it doesn't change anything (probably it needs to also bleak reset).

It looks like someting is powering down hci0 when break is using it and after that it hangs. Do you have any ideas how I could investigate it further?

INFO:BLEGateway:Starting BLE scan
INFO:BLEGateway:Connected to MQTT Broker!
INFO:BLEGateway:Subscribed to home/TheengsGateway/+
2022-07-14 11:17:25,876 bleak.backends.bluezdbus.scanner DEBUG: cached devices: {}
DEBUG:bleak.backends.bluezdbus.scanner:cached devices: {}
2022-07-14 11:17:26,027 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_next.signature.Variant ('b', True)>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_next.signature.Variant ('b', True)>}, []]
2022-07-14 11:17:27,960 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_A4_C1_38_05_69_48', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_next.signature.Variant ('s', A4:C1:38:05:69:48)>, 'AddressType': <dbus_next.signature.Variant ('s', public)>, 'Name': <dbus_next.signature.Variant ('s', ATC_biuro)>, 'Alias': <dbus_next.signature.Variant ('s', ATC_biuro)>, 'Paired': <dbus_next.signature.Variant ('b', False)>, 'Trusted': <dbus_next.signature.Variant ('b', False)>, 'Blocked': <dbus_next.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_next.signature.Variant ('b', False)>, 'RSSI': <dbus_next.signature.Variant ('n', -77)>, 'Connected': <dbus_next.signature.Variant ('b', False)>, 'UUIDs': <dbus_next.signature.Variant ('as', [])>, 'Adapter': <dbus_next.signature.Variant ('o', /org/bluez/hci0)>, 'ServiceData': <dbus_next.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_next.signature.Variant ('ay', b'\xa4\xc18\x05iH\x00\xfa2I\x0b.\xa3')>})>, 'ServicesResolved': <dbus_next.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_A4_C1_38_05_69_48', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_next.signature.Variant ('s', A4:C1:38:05:69:48)>, 'AddressType': <dbus_next.signature.Variant ('s', public)>, 'Name': <dbus_next.signature.Variant ('s', ATC_biuro)>, 'Alias': <dbus_next.signature.Variant ('s', ATC_biuro)>, 'Paired': <dbus_next.signature.Variant ('b', False)>, 'Trusted': <dbus_next.signature.Variant ('b', False)>, 'Blocked': <dbus_next.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_next.signature.Variant ('b', False)>, 'RSSI': <dbus_next.signature.Variant ('n', -77)>, 'Connected': <dbus_next.signature.Variant ('b', False)>, 'UUIDs': <dbus_next.signature.Variant ('as', [])>, 'Adapter': <dbus_next.signature.Variant ('o', /org/bluez/hci0)>, 'ServiceData': <dbus_next.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_next.signature.Variant ('ay', b'\xa4\xc18\x05iH\x00\xfa2I\x0b.\xa3')>})>, 'ServicesResolved': <dbus_next.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
DEBUG:BLEGateway:A4:C1:38:05:69:48 RSSI:-77 AdvertisementData(local_name='ATC_biuro', service_data={'0000181a-0000-1000-8000-00805f9b34fb': b'\xa4\xc18\x05iH\x00\xfa2I\x0b.\xa3'})
INFO:BLEGateway:publishing device `{'name': 'ATC_biuro', 'id': 'A4:C1:38:05:69:48', 'rssi': -77, 'brand': 'Xiaomi', 'model': 'LYWSD03MMC', 'model_id': 'LYWSD03MMC_ATC', 'tempc': 25, 'tempf': 77, 'hum': 50, 'batt': 73, 'volt': 2.862}`
INFO:BLEGateway:Sent `{"stat_t": "+/+/BTtoMQTT/A4C138056948", "dev_cla": "battery", "unit_of_meas": "%", "name": "LYWSD03MMC_ATC-batt", "uniq_id": "A4C138056948-batt", "val_tpl": "{{ value_json.batt | is_defined }}", "state_class": "measurement", "device": {"identifiers": ["A4C138056948"], "connections": [["mac", "A4C138056948"]], "manufacturer": "Xiaomi", "model": "LYWSD03MMC_ATC", "name": "ATC_biuro", "via_device": "TheengsGateway"}}` to topic `homeassistant/sensor/A4C138056948-batt/config`
INFO:BLEGateway:Sent `{"stat_t": "+/+/BTtoMQTT/A4C138056948", "dev_cla": "voltage", "unit_of_meas": "V", "name": "LYWSD03MMC_ATC-volt", "uniq_id": "A4C138056948-volt", "val_tpl": "{{ value_json.volt | is_defined }}", "state_class": "measurement", "device": {"identifiers": ["A4C138056948"], "connections": [["mac", "A4C138056948"]], "manufacturer": "Xiaomi", "model": "LYWSD03MMC_ATC", "name": "ATC_biuro", "via_device": "TheengsGateway"}}` to topic `homeassistant/sensor/A4C138056948-volt/config`
INFO:BLEGateway:Sent `{"stat_t": "+/+/BTtoMQTT/A4C138056948", "dev_cla": "temperature", "unit_of_meas": "\u00b0C", "name": "LYWSD03MMC_ATC-tempc", "uniq_id": "A4C138056948-tempc", "val_tpl": "{{ value_json.tempc | is_defined }}", "state_class": "measurement", "device": {"identifiers": ["A4C138056948"], "connections": [["mac", "A4C138056948"]], "manufacturer": "Xiaomi", "model": "LYWSD03MMC_ATC", "name": "ATC_biuro", "via_device": "TheengsGateway"}}` to topic `homeassistant/sensor/A4C138056948-tempc/config`
INFO:BLEGateway:Sent `{"stat_t": "+/+/BTtoMQTT/A4C138056948", "dev_cla": "humidity", "unit_of_meas": "%", "name": "LYWSD03MMC_ATC-hum", "uniq_id": "A4C138056948-hum", "val_tpl": "{{ value_json.hum | is_defined }}", "state_class": "measurement", "device": {"identifiers": ["A4C138056948"], "connections": [["mac", "A4C138056948"]], "manufacturer": "Xiaomi", "model": "LYWSD03MMC_ATC", "name": "ATC_biuro", "via_device": "TheengsGateway"}}` to topic `homeassistant/sensor/A4C138056948-hum/config`
INFO:BLEGateway:Sent `{"name": "ATC_biuro", "id": "A4:C1:38:05:69:48", "rssi": -77, "brand": "Xiaomi", "model": "LYWSD03MMC", "model_id": "LYWSD03MMC_ATC", "tempc": 25, "tempf": 77, "hum": 50, "batt": 73, "volt": 2.862}` to topic `home/TheengsGateway/BTtoMQTT/A4C138056948`
2022-07-14 11:17:35,583 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -78)>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -78)>}, []]
2022-07-14 11:17:43,119 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -77)>, 'ServiceData': <dbus_next.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_next.signature.Variant ('ay', b'\xa4\xc18\x05iH\x00\xf92I\x0b,\xa4')>})>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -77)>, 'ServiceData': <dbus_next.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_next.signature.Variant ('ay', b'\xa4\xc18\x05iH\x00\xf92I\x0b,\xa4')>})>}, []]
DEBUG:BLEGateway:A4:C1:38:05:69:48 RSSI:-77 AdvertisementData(local_name='ATC_biuro', service_data={'0000181a-0000-1000-8000-00805f9b34fb': b'\xa4\xc18\x05iH\x00\xf92I\x0b,\xa4'})
DEBUG:BLEGateway:Already discovered or filtered: A4C138056948
INFO:BLEGateway:Sent `{"name": "ATC_biuro", "id": "A4:C1:38:05:69:48", "rssi": -77, "brand": "Xiaomi", "model": "LYWSD03MMC", "model_id": "LYWSD03MMC_ATC", "tempc": 24.9, "tempf": 76.82, "hum": 50, "batt": 73, "volt": 2.86}` to topic `home/TheengsGateway/BTtoMQTT/A4C138056948`
2022-07-14 11:17:48,063 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -77)>, 'ServiceData': <dbus_next.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_next.signature.Variant ('ay', b'\xa4\xc18\x05iH\x00\xfa2I\x0b0\xa5')>})>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -77)>, 'ServiceData': <dbus_next.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_next.signature.Variant ('ay', b'\xa4\xc18\x05iH\x00\xfa2I\x0b0\xa5')>})>}, []]
DEBUG:BLEGateway:A4:C1:38:05:69:48 RSSI:-77 AdvertisementData(local_name='ATC_biuro', service_data={'0000181a-0000-1000-8000-00805f9b34fb': b'\xa4\xc18\x05iH\x00\xfa2I\x0b0\xa5'})
DEBUG:BLEGateway:Already discovered or filtered: A4C138056948
INFO:BLEGateway:Sent `{"name": "ATC_biuro", "id": "A4:C1:38:05:69:48", "rssi": -77, "brand": "Xiaomi", "model": "LYWSD03MMC", "model_id": "LYWSD03MMC_ATC", "tempc": 25, "tempf": 77, "hum": 50, "batt": 73, "volt": 2.864}` to topic `home/TheengsGateway/BTtoMQTT/A4C138056948`
2022-07-14 11:17:53,170 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -77)>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -77)>}, []]
2022-07-14 11:17:55,686 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -77)>, 'ServiceData': <dbus_next.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_next.signature.Variant ('ay', b'\xa4\xc18\x05iH\x00\xfa2I\x0b.\xa6')>})>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -77)>, 'ServiceData': <dbus_next.signature.Variant ('a{sv}', {'0000181a-0000-1000-8000-00805f9b34fb': <dbus_next.signature.Variant ('ay', b'\xa4\xc18\x05iH\x00\xfa2I\x0b.\xa6')>})>}, []]
DEBUG:BLEGateway:A4:C1:38:05:69:48 RSSI:-77 AdvertisementData(local_name='ATC_biuro', service_data={'0000181a-0000-1000-8000-00805f9b34fb': b'\xa4\xc18\x05iH\x00\xfa2I\x0b.\xa6'})
DEBUG:BLEGateway:Already discovered or filtered: A4C138056948
INFO:BLEGateway:Sent `{"name": "ATC_biuro", "id": "A4:C1:38:05:69:48", "rssi": -77, "brand": "Xiaomi", "model": "LYWSD03MMC", "model_id": "LYWSD03MMC_ATC", "tempc": 25, "tempf": 77, "hum": 50, "batt": 73, "volt": 2.862}` to topic `home/TheengsGateway/BTtoMQTT/A4C138056948`
2022-07-14 11:18:00,729 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -79)>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {'RSSI': <dbus_next.signature.Variant ('n', -79)>}, []]
2022-07-14 11:18:00,960 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {}, ['RSSI']]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_A4_C1_38_05_69_48): ['org.bluez.Device1', {}, ['RSSI']]
2022-07-14 11:18:00,961 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_A4_C1_38_05_69_48', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_A4_C1_38_05_69_48', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
2022-07-14 11:18:00,961 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Class': <dbus_next.signature.Variant ('u', 0)>, 'Powered': <dbus_next.signature.Variant ('b', False)>, 'Discovering': <dbus_next.signature.Variant ('b', False)>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Class': <dbus_next.signature.Variant ('u', 0)>, 'Powered': <dbus_next.signature.Variant ('b', False)>, 'Discovering': <dbus_next.signature.Variant ('b', False)>}, []]
2022-07-14 11:19:58,085 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Class': <dbus_next.signature.Variant ('u', 260)>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Class': <dbus_next.signature.Variant ('u', 260)>}, []]
2022-07-14 11:19:58,086 bleak.backends.bluezdbus.scanner DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Powered': <dbus_next.signature.Variant ('b', True)>}, []]
DEBUG:bleak.backends.bluezdbus.scanner:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Powered': <dbus_next.signature.Variant ('b', True)>}, []]

LukaszBrzyszkiewicz avatar Jul 14 '22 09:07 LukaszBrzyszkiewicz

Bleak doesn't control the power on the Bluetooth adapter, so something else must be doing this. You could try monitoring d-bus to see if another app might be doing this (sudo dbus-monitor --system). Or maybe something is wrong with the hardware or the drivers?

dlech avatar Jul 14 '22 15:07 dlech

OK, so I've not found any important entry in dbus-monitor so still I don't known what is causing powering off hci interface when I'm using bleak (this problem doesn't occur when using for example hcidump).

But after all - should bleak hang when hci is turned off? I don't think so, because there is no possibility to restart interface, because for example stop scanning isn't working. I think that bleak should react (and probably inform by some callback) when used interface is powered down and/or up.

LukaszBrzyszkiewicz avatar Jul 18 '22 07:07 LukaszBrzyszkiewicz

I think that bleak should react (and probably inform by some callback) when used interface is powered down and/or up.

This sounds like a good suggestion to add to #652

dlech avatar Jul 18 '22 15:07 dlech

Facing the same issue. Has anyone found a solution or workaround for this?

kishangondaliya avatar Apr 12 '24 07:04 kishangondaliya