Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

HCI is powering off after few seconds of BLE scanning #887

Open
LukaszBrzyszkiewicz opened this issue Jul 14, 2022 · 5 comments
Open

HCI is powering off after few seconds of BLE scanning #887

LukaszBrzyszkiewicz opened this issue Jul 14, 2022 · 5 comments
Labels
3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself Backend: BlueZ Issues and PRs relating to the BlueZ backend

Comments

@LukaszBrzyszkiewicz
Copy link

  • 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)>}, []]
@dlech
Copy link
Collaborator

dlech commented Jul 14, 2022

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 dlech added the Backend: BlueZ Issues and PRs relating to the BlueZ backend label Jul 14, 2022
@LukaszBrzyszkiewicz
Copy link
Author

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.

@dlech
Copy link
Collaborator

dlech commented Jul 18, 2022

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 dlech added the 3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself label Oct 3, 2022
@kishangondaliya
Copy link

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

@hlima
Copy link

hlima commented Oct 4, 2024

using version 5.66 and seeing same issue ....

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself Backend: BlueZ Issues and PRs relating to the BlueZ backend
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@hlima @dlech @kishangondaliya @LukaszBrzyszkiewicz