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

Reset function makes integration unresponsive after a few days #549

Closed
Ernst79 opened this issue Nov 9, 2021 · 6 comments
Closed

Reset function makes integration unresponsive after a few days #549

Ernst79 opened this issue Nov 9, 2021 · 6 comments

Comments

@Ernst79
Copy link
Collaborator

Ernst79 commented Nov 9, 2021

Issue from #167 by @eValker

Unfortunately I had to revert back the integration to v5.5.2. I think restart happens too often and this leads to situation in which the Bluetooth device become completely unresponsive (or even undetectable like in example below).
After some time (like 1-2 days of uptime) I am getting errors like below each second:

2021-11-08 03:43:02 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:03 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:04 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:05 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:06 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:07 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:08 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:09 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:10 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:11 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:12 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:13 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:14 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device
2021-11-08 03:43:15 ERROR (Thread-2563) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device

Only way to fix it is to reset entire Pi.
I think it will be helpful to have 2 additional configurations:

  • option to disable restart mechanism
  • option to setup delay between restarts (like 30 seconds or so)
    My custom restart solution have 30 seconds delay between executions and I never had a problem with bluetooth device become unresponsive.
@Ernst79
Copy link
Collaborator Author

Ernst79 commented Nov 9, 2021 •
edited
Loading

@eValker
An option to disable the auto-restart mechanism seems ok to me to add.

Regarding the delay, I prefer to find a value that works for everybody, we already have a ton of options in BLE monitor. I will first build in a delay of the reset functionality with a hard coded 30 second delay time between resets and we will see if that works.

Regarding the error, it seems that it either cannot find the BT adapter on hci0 anymore. It would be interesting to find out if the OS has changed the BT adapter to hci1 or if it isn't available at all anymore. Could you check this?

@Ernst79
Copy link
Collaborator Author

Ernst79 commented Nov 12, 2021

Option to enable/disable the automatic reset of the BT adapter has been added in 6.0.0-beta

@eValker
Copy link

eValker commented Dec 8, 2021

Hello,
sorry for the long delay. I didn't have time to play with the HA :)
I am not sure if automatic reset option is working as expected. I have disabled automatic restarts, however integration is trying to reset BT anyway.

2021-12-08 14:32:17 DEBUG (MainThread) [custom_components.ble_monitor] async_setup_entry: {'bt_interface': ['XX:XX:XX:XX:XX:XX'], 'bt_auto_restart': False, 'active_scan': False, 'discovery': False, 'period': 0, 'use_median': False, 'decimals': 1, 'log_spikes': False, 'restore_state': True, 'report_unknown': 'Off', 'devices': [(...)], 'is_flow': True, 'hci_interface': [0]}
(...)
2021-12-08 14:32:20 ERROR (Thread-3) [custom_components.ble_monitor] HCIdump thread: Runtime error while sending scan request on hci0: Event loop stopped before Future completed.. Resetting Bluetooth adapter XX:XX:XX:XX:XX:XX and trying again.
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] resetting Bluetooth
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] bluetoothctl select XX:XX:XX:XX:XX:XX
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] bluetoothctl show.....
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] Power state of bluetooth adapter is off before resetting Bluetooth, trying to turn it back on.
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] rfkill list bluetooth.....
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] bluetooth adapter is not soft blocked before reset
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] bluetooth adapter is not hard blocked before reset
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] bluetoothctl power on.....
2021-12-08 14:32:20 DEBUG (Thread-3) [custom_components.ble_monitor.bt_helpers] rfkill unblock bluetooth.....

obraz

Also as I said before: after 2-3 days of automatic restarts BT is not responding at all even after software reset. I need to reset whole rasberry pi in order to make it work. I didn't notice this issue in my restart implementation where I have 30-60 seconds delay between restarts (I think 60 second option is more safe).

Here is additional info I have got before I performed hard (hardware) restart.

root@homeassistant:~# rfkill list
0: phy0: Wireless LAN
        Soft blocked: no
        Hard blocked: no
1: hci0: Bluetooth
        Soft blocked: no
        Hard blocked: no

root@homeassistant:/var/log# bluetoothctl list
Controller XX:XX:XX:XX:XX:XX homeassistant [default]
root@homeassistant:/var/log# bluetoothctl show XX:XX:XX:XX:XX:XX
Controller XX:XX:XX:XX:XX:XX (public)
        Name: homeassistant
        Alias: homeassistant
        Class: 0x000c0000
        Powered: yes
        Discoverable: no
        Pairable: yes
        UUID: Headset AG                (00001112-0000-1000-8000-00805f9b34fb)
        UUID: Generic Attribute Profile (00001801-0000-1000-8000-00805f9b34fb)
        UUID: A/V Remote Control        (0000110e-0000-1000-8000-00805f9b34fb)
        UUID: Generic Access Profile    (00001800-0000-1000-8000-00805f9b34fb)
        UUID: PnP Information           (00001200-0000-1000-8000-00805f9b34fb)
        UUID: A/V Remote Control Target (0000110c-0000-1000-8000-00805f9b34fb)
        UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
        UUID: Audio Source              (0000110a-0000-1000-8000-00805f9b34fb)
        UUID: Headset                   (00001108-0000-1000-8000-00805f9b34fb)
        Modalias: usb:v1D6Bp0246d0532
        Discovering: no
root@homeassistant:/var/log# bluetoothctl devices
(no results returned)

root@homeassistant:~# hciconfig -a
hci0:   Type: Primary  Bus: USB
        BD Address: XX:XX:XX:XX:XX:XX  ACL MTU: 1021:8  SCO MTU: 64:1
        UP RUNNING
        RX bytes:277094767 acl:0 sco:0 events:6999077 errors:0
        TX bytes:4966190 acl:0 sco:0 commands:955776 errors:0
        Features: 0xbf 0xfe 0xcf 0xfe 0xdb 0xff 0x7b 0x87
        Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
        Link policy: RSWITCH SNIFF
        Link mode: SLAVE ACCEPT
Can't read local name on hci0: Connection timed out (110)

root@homeassistant:~# service bluetooth status
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2021-12-06 05:05:57 CET; 2 days ago
     Docs: man:bluetoothd(8)
 Main PID: 473 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/bluetooth.service
           └─473 /usr/lib/bluetooth/bluetoothd

Dec 06 05:05:56 homeassistant systemd[1]: Starting Bluetooth service...
Dec 06 05:05:57 homeassistant bluetoothd[473]: Bluetooth daemon 5.50
Dec 06 05:05:57 homeassistant systemd[1]: Started Bluetooth service.
Dec 06 05:05:57 homeassistant bluetoothd[473]: Starting SDP server
Dec 06 05:05:58 homeassistant bluetoothd[473]: Bluetooth management interface 1.18 initialized
Dec 06 05:05:58 homeassistant bluetoothd[473]: Sap driver initialization failed.
Dec 06 05:05:58 homeassistant bluetoothd[473]: sap-server: Operation not permitted (1)
Dec 06 05:05:58 homeassistant bluetoothd[473]: Failed to set privacy: Rejected (0x0b)
Dec 06 05:06:28 homeassistant bluetoothd[473]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc
Dec 06 05:06:28 homeassistant bluetoothd[473]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc

Also a lot of errors in dmesg:

[207242.858487] Bluetooth: hci0: command 0x1002 tx timeout
[207255.898617] Bluetooth: hci0: command 0x1002 tx timeout
[207268.938758] Bluetooth: hci0: command 0x1002 tx timeout
[207281.978943] Bluetooth: hci0: command 0x1002 tx timeout
[207295.099064] Bluetooth: hci0: command 0x1002 tx timeout
[207308.139260] Bluetooth: hci0: command 0x1002 tx timeout
[207321.099379] Bluetooth: hci0: command 0x1002 tx timeout
[207334.139534] Bluetooth: hci0: command 0x1002 tx timeout
[207347.179687] Bluetooth: hci0: command 0x1002 tx timeout
[207360.219804] Bluetooth: hci0: command 0x1002 tx timeout
[207373.259916] Bluetooth: hci0: command 0x1002 tx timeout
[207386.380105] Bluetooth: hci0: command 0x1002 tx timeout
[207399.340270] Bluetooth: hci0: command 0x1002 tx timeout
[207412.380403] Bluetooth: hci0: command 0x1002 tx timeout
[207425.420532] Bluetooth: hci0: command 0x1002 tx timeout
[207435.500635] Bluetooth: hci0: command 0x0c14 tx timeout
[207438.460679] Bluetooth: hci0: command 0x1002 tx timeout
[207451.500823] Bluetooth: hci0: command 0x1002 tx timeout
[207464.541081] Bluetooth: hci0: command 0x1002 tx timeout
[207477.581118] Bluetooth: hci0: command 0x1002 tx timeout
[207490.621249] Bluetooth: hci0: command 0x1002 tx timeout
[207503.741370] Bluetooth: hci0: command 0x1002 tx timeout
[207516.791557] Bluetooth: hci0: command 0x1002 tx timeout
[207529.821707] Bluetooth: hci0: command 0x1002 tx timeout
[207542.871839] Bluetooth: hci0: command 0x1002 tx timeout
[207555.901977] Bluetooth: hci0: command 0x1002 tx timeout
[207568.942126] Bluetooth: hci0: command 0x1002 tx timeout
[207581.982289] Bluetooth: hci0: command 0x1002 tx timeout
[207585.502340] Bluetooth: hci0: command 0x0c14 tx timeout
[207595.022423] Bluetooth: hci0: command 0x1002 tx timeout
[207608.062599] Bluetooth: hci0: command 0x1002 tx timeout
[207621.102721] Bluetooth: hci0: command 0x1002 tx timeout
[207634.142854] Bluetooth: hci0: command 0x1002 tx timeout
[207647.183008] Bluetooth: hci0: command 0x1002 tx timeout
[207660.223162] Bluetooth: hci0: command 0x1002 tx timeout
[207673.263310] Bluetooth: hci0: command 0x1002 tx timeout
[207686.303446] Bluetooth: hci0: command 0x1002 tx timeout
[207699.343627] Bluetooth: hci0: command 0x1002 tx timeout
[207712.383761] Bluetooth: hci0: command 0x1002 tx timeout
[207725.423893] Bluetooth: hci0: command 0x1002 tx timeout
[207738.383997] Bluetooth: hci0: command 0x1002 tx timeout
[207751.424187] Bluetooth: hci0: command 0x1002 tx timeout
[207764.544303] Bluetooth: hci0: command 0x1002 tx timeout
[207777.584471] Bluetooth: hci0: command 0x1002 tx timeout
[207790.544622] Bluetooth: hci0: command 0x1002 tx timeout
[207803.744726] Bluetooth: hci0: command 0x1002 tx timeout
[207816.784893] Bluetooth: hci0: command 0x1002 tx timeout
[207829.825070] Bluetooth: hci0: command 0x1002 tx timeout
[207842.865194] Bluetooth: hci0: command 0x1002 tx timeout
[207855.825361] Bluetooth: hci0: command 0x1002 tx timeout

I wasn't sure if there is some other command I can execute in order to get more info.
If you would like an output of any other command please let me know, so I can get it for you next time the problem reappears.

@Ernst79
Copy link
Collaborator Author

Ernst79 commented Dec 30, 2021

I don't understand why it is doing this. In __init__.py, I have the following code on line 612.

                        if CONF_BT_AUTO_RESTART:

CONF_BT_AUTO_RESTART should be False in your case, so it should not do this. Could you try the following.

Change line 612 to

                        if CONF_BT_AUTO_RESTART is True:

I'll add a delay timer to the reset function anyway, to only reset once every 60 seconds max.

@Ernst79
Copy link
Collaborator Author

Ernst79 commented Dec 30, 2021 •
edited
Loading

I've released 6.4.3 which adds a 60 seconds minimum time between BT resets. I also have added the change in the above post. Please give it a try. I assume this should fix your issue, if not, please reopen the issue.

@Ernst79 Ernst79 closed this as completed Jan 1, 2022
@eValker
Copy link

eValker commented Jan 2, 2022

@Ernst79
The fix helped and it is not restarting anymore. Thanks :)

This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@eValker @Ernst79