custom-components / ble_monitor

BLE monitor for passive BLE sensors
https://community.home-assistant.io/t/passive-ble-monitor-integration/
MIT License
1.88k stars 243 forks source link

Event loop stopped before Future completed #295

Closed Toukite closed 2 years ago

Toukite commented 3 years ago

Hello,

I think this is linked to https://github.com/custom-components/ble_monitor/issues/167, but since I upgraded to Home Assistant OS 5.12 yesterday, I have trouble with my bluetooth temperature sensors. I don't see any other event that could have cause an issue, before that it was working perfectly well for months.

Now I can see this error multiple times in the logs: **ERROR (Thread-3) [custom_components.ble_monitor] HCIdump thread: Runtime error while stop scan request on hci0: Event loop stopped before Future completed.**

By reading the previous issue, I didn't really get what was the solution.

Additional info: I am running "pure" HassOS on RPI 4B, so I don't have access to root or to the linux behind or to commands like hcitool, the only command that seems to work is bluetoothctl, with which I already tried to re-enable everything and repair all devices without success. Another info, I use an external dongle (I identified its mac address by plugging it/unplugging it and by seing the output of bluetoothctl list command, and I set the external one as default controller with bluetoothctl)

Config:

ble_monitor:
  decimals: 1
  period: 60
  log_spikes: False
  use_median: False
  active_scan: False
  hci_interface:
    - 1
    - 0
  batt_entities: True
  discovery: False
  restore_state: False 
  report_unknown: False
  devices:
    - mac: 'xxx'
      name: 'xxx'
      temperature_unit: C

Thanks for the help !

Ernst79 commented 3 years ago

There were some issues after a supervisor update recently, which need a full restart of the system. So, not only a restart of HA, but of the entire system.

Could you give this a try first? For most users, this solves the issue.

Toukite commented 3 years ago

Unfortunately, I tried many things before actually submitting this issue, including several hard reboots (core, supervisor, host). No luck yet :(

Ernst79 commented 3 years ago

Ok, it was worth to try. I see you have two hci devices configured. Can you change this to the external one only?

and which dongle do you have?

Ernst79 commented 3 years ago

With the ssh addon you can get some access to the Linux system, although limited. You might try the following command, not sure it will work

sudo setcap 'cap_net_raw,cap_net_admin+eip' `readlink -f \`which python3.8\`` 
Toukite commented 3 years ago

I have this dongle: https://www.domadoo.fr/fr/interface-domotique/4947-jeedom-dongle-usb-bluetooth.html

As for the hci device, well the problem is that I have no idea which one is correct since I only have access to bluetoothctl command ... I need to be sure that the external one is taken into account and not the RPI one since I have range issues.

Toukite commented 3 years ago

image

Toukite commented 3 years ago

I will try to downgrade to HassOS 5.11 tonight in order to confirm that the issue is coming from there. I'll let you know

Ernst79 commented 3 years ago

Run the command without sudo. HassOs is already running as root

Toukite commented 3 years ago

I downgraded to 5.11 and everything works fine again

Ernst79 commented 3 years ago

Ok, that’s strange. Let m.e have a look at the changes

Ernst79 commented 3 years ago

the only thing I suspect is a firmware update for a raspberry (I assume you have a Pi?). I will try installing Home assistant OS myself on a second raspberry pi 3b

Toukite commented 3 years ago

Yes I'm on raspberry pi 4b

Ernst79 commented 3 years ago

But I doubt that a firmware update is reverted if you return to 5.11. But I will try. I have just downloaded 5.11

Toukite commented 3 years ago

Issue is on 5.12 not 5.11

Ernst79 commented 3 years ago

yes, I know, I want to check myself if it works on 5.11 first, and than do the upgrade

Ernst79 commented 3 years ago

Installed 5.11, all running fine.

But it won't let me update. No new update available in the supervisor. ha os update doesn't work (Unexpected server response. Status code: 500). How did you upgrade?

Toukite commented 3 years ago

Screenshot_20210226-205745 Directly through supervisor's tab Release note link: https://github.com/home-assistant/operating-system/releases/tag/5.12

Ernst79 commented 3 years ago

after a full host reboot, it is finally showing the update. I'll continue......

Ernst79 commented 3 years ago

image

Sorry, couldn't reproduce your issue. It's working fine on my end after the update.

Next possible steps.

  1. Could you try if it does work with only hci0 (on 5.12)? So, disable hci1.
  2. Another thing we can try is this topic, explaining how to access the underlying Home Assistant OS. https://developers.home-assistant.io/docs/operating-system/debugging/

See this topic as well, where it seems that they are able to use hcitool on Home Assistant OS.

Toukite commented 3 years ago

Could it be due to the rpi difference (me using a 4b and you a 3 ?) Also, I did have some values in 5.12, but others that did not come at all, and again others that came but with very sporadic update time (not every 60s as in 5.11) All of this with same xiaomi round temp device (i have a lot of them) And i had the error in the logs too

Maybe try adding more devices on your side and display the last update secondary info to see if you can reproduce over some time ?

I'll check the other post

Ernst79 commented 3 years ago

In the other topic, it is solved by a command that fixes the reference to the correct python version. Often people update e.g. the venv or docker installation with a certain python version, which is different than the version on the host system If this isn't the same, you get your the errors you showed. But in your case, you are running Home Assistant OS, which should always run the same version of python for HA as the one on the host system. Unless the changed something in 5.12.

But getting some data is strange, yes. I'll keep an eye on the sensors. I have 3 of them, all report fine so far, no errors.

The reason I would like to get access to the system, is that we can run some commands to check things. But I use a supervised installation, which allows you to run these commands. Have to find out if the method with USB stick works to get better access. I'll try it myself first, will let you know

Ernst79 commented 3 years ago

image

I managed to login and run some hci commands. I used this method.

https://developers.home-assistant.io/docs/operating-system/debugging/

You will have to generate ssh rsa keys, put the public key on an usb named CONFIG and upload it to HA (with a reboot, it will be added automatically). The full instructions are given in the link above. Next you can login via putty as root, with the private key that you generated. After that, you have to give the command login and you will get access to the system. When logged in this way, you can run the commands you can't run via the UI ssh add-on.

Not sure yet it's worth to do this. the setcap command from the other topic won't work. I'll look into it further tomorrow.

You might want to try to just update again to 5.12. Sometimes, it magically starts to work.

Ernst79 commented 3 years ago

I would like to ask you to check the following

  1. update to 5.12. Check if the error comes back or not
  2. Use only hci0. Check if the error disappears
  3. Use only hci1. Check if the error disappears
Toukite commented 3 years ago

Hi, So I did the upgrade again + root access to use the hcitool command (so now I know that the one I want to use is indeed hci0), and then I changed ble config to use only hci0 I just did it but for now I don't see any issue, all devices seem to update fine

Ernst79 commented 3 years ago

Ok, thanks for reporting back. I'll close the issue, if it isn't working in the future or the errors return, just reopen this issue again and we will look further.

Toukite commented 3 years ago

Spoke too soon .. system is up since 23 hours and was running fine until 4 hours ago where all my bluetooth sensors stopped updating and I see the error in the logs again... Before that upgrade of yesterday, everything ran for a week without issues on 5.11 Should I rollback again ?

Ernst79 commented 3 years ago

Going back is not a solution for the long term. Do you have other components that use Bluetooth? You might also create an issue on the home assistant OS github, perhaps they have an idea what is going on?

Toukite commented 3 years ago

No I only have a bunch of xiaomi mija temp sensors (round one) that use bluetooth, everything else is zigbee/zwave/wifi Pb is that my heating system decides what to do based upon those temp sensors ... So it's more than just a confort issue, I can't leave it like that

Ernst79 commented 3 years ago

I meant other components in HA, like the Bluetooth tracker component.

What you could try is checking if it works with build in Bluetooth for a couple of days (unplug the dongle). If that works, it might be a malfunctioning dongle. Also check if there are firmware updates for the dongle.

Toukite commented 3 years ago

I don't know how to test that bt tracker component :( I don't think it's the dongle as it has been perfectly working for months (and it is still working if I downgrade the OS) If nothing can be found here then I think the best course would be to downgrade again and as you said open an issue on os github !

Ernst79 commented 3 years ago

Yes, I guess so. I’m running out of ideas, sorry.

Toukite commented 3 years ago

I created https://github.com/home-assistant/operating-system/issues/1264 in case you want to add details or follow the issue !

pvojnisek commented 3 years ago

I have the same issue. Supervised HA is running on a Samsung NP300 notebook, debian buster. Everything is working like a charm after a reboot. Some hours later I got the same error message. A no data will come ever from the sensors.

Ernst79 commented 3 years ago

@pvojnisek Did you recently update python? Did you check the possible solution in https://github.com/custom-components/ble_monitor/issues/167#issuecomment-739541674

This wasn't a solution for @Toukite, but it worked for others.

Ernst79 commented 3 years ago

@Toukite To explain a bit more how ble monitor works. We use a slightly modified version of aioblescan (Python 3/asyncio library to listen for BLE advertized packets) to listen to the Bluetooth packets. The error Event loop stopped before Future completed. is generated somewhere in the library. Perhaps the developer @frawau of this library can help us.

I know @Magalex2x14 made small changes to the original aioblescan, which was, if I remember correctly, done for ble messages in the so called "extended" format. The modification is using parts of this none-merged PR. But I don't think this modification is causing your issues.

Unfortunately, I didn't create this part of the code, so it's a bit hard for me to help. I'm not a real programmer :-), and this part of our code has always been a bit of magic to me.

pvojnisek commented 3 years ago

When the bluetooth is not reachable, you type from terminal:

$ bluetoothctl
Agent Registered
# scan on
Failed to start discovery: org.bluez.Error.NotReady
Ernst79 commented 3 years ago

On my working system, is see the two bluetooth radio (internal + dongle).

# bluetoothctl
Agent registered
[CHG] Controller B8:27:EB:77:75:50 Pairable: yes
[CHG] Controller 00:1A:7D:DA:71:15 Pairable: yes

So, if it fails, it doesn't show your bluetooth dongle at all?

Could you run systemctl status bluetooth

frawau commented 3 years ago

Hi, I am not using HassOS, so I am not sure what your problem is. If I am not mistaken, you are using the atcmi plugin. If so could you try the library itself, something like

    python3 -m aioblescan -A

Again, I am not familiar with HassOS, so you may need to create a venv and install aioblescan in that environment to avoid conflicts with Hass.

Then again, if your bluetooth radio disappears from the system, this could point to a lower level problem.

pvojnisek commented 3 years ago

Hi @Ernst79,

systemctl status bluetooth

systemctrl is not available in Home Assistant command line.

bash-5.0# bluetoothctl 
Agent registered
[bluetooth]# scan on 
Discovery started
[CHG] Controller 50:B7:C3:4C:AF:B5 Discovering: yes
[CHG] Device xx:35:C1:67:31:EF RSSI: -65
[CHG] Device xx:EC:0A:0D:06:81 RSSI: -89
[CHG] Device xx:C6:81:16:47:65 RSSI: -59
[CHG] Device xx:C6:81:16:47:65 TxPower: 12

It looks running.

Ernst79 commented 3 years ago

For the earlier error,

# scan on
Failed to start discovery: org.bluez.Error.NotReady

I googled a bit and found the follow things you could try

bluetoothctl power on

and

rfkill unblock all

You could give these commands a try.

pvojnisek commented 3 years ago

It is getting strange. It was already unblocked.

ash-5.0# rfkill list
1: hci1: bluetooth
        Soft blocked: no
        Hard blocked: no
2: phy0: wlan
        Soft blocked: no
        Hard blocked: no

After that I start a scan:

ash-5.0# hcitool lescan
LE Scan ...
A4:C1:38:64:22:99 (unknown)
A4:C1:38:64:22:99 ATC_642299
4C:65:A8:DB:4E:02 (unknown)
4C:65:A8:DB:4E:02 MJ_HT_V1

And:

ash-5.0# bluetoothctl 
Agent registered
[bluetooth]# scan on
Discovery started
[CHG] Controller 50:B7:C3:4C:AF:B5 Discovering: yes
[NEW] Device F4:F5:DB:F7:97:DA xxxxx

Looks working from terminal. But in Home Assistant the log looks like this:

2021-03-22 13:44:35 ERROR (Thread-3) [custom_components.ble_monitor] HCIdump thread: OS error (hci0): [Errno 19] error while attempting to bind on interface 0: No such device

HA wants to connect to hci0!

Ernst79 commented 3 years ago

You can set BLE monitor to connect to hci1 in the options of the BLE monitor integration. Default is hci0, but in your case, you will need to change it to hci1.

image

pvojnisek commented 3 years ago

Thanks @Ernst79, That's right. Currently it is running. Let's wait for some hours or days. It was strange that is was stopped working after running ok for a while.

pvojnisek commented 3 years ago

The problem still exists.

Logger: custom_components.ble_monitor
Source: custom_components/ble_monitor/__init__.py:657
Integration: Passive BLE monitor (documentation)
First occurred: 21:11:55 (13 occurrences)
Last logged: 21:47:59
HCIdump thread: Runtime error while stop scan request on hci1: Event loop stopped before Future completed.

And no data is coming anymore. After this this is the situation:

bash-5.0# hcitool lescan
Could not open device: No such device
bash-5.0# rfkill list
1: hci1: bluetooth
        Soft blocked: no
        Hard blocked: no
2: phy0: wlan
        Soft blocked: no
        Hard blocked: no
bash-5.0# bluetoothctl 
Agent registered
[bluetooth]# scan on
Failed to start discovery: org.bluez.Error.NotReady
bash-5.0# rfkill block all
bash-5.0# rfkill unblock all
bash-5.0# bluetoothctl 
Agent registered
[bluetooth]# scan on
Discovery started
[CHG] Controller 50:B7:C3:4C:AF:B5 Discovering: yes
[NEW] Device 8C:C6:81:16:47:65 xxxxx
[NEW] Device 00:EC:0A:0D:06:81 xxxxx
bash-5.0# rfkill list
1: hci1: bluetooth
        Soft blocked: no
        Hard blocked: no
2: phy0: wlan
        Soft blocked: no
        Hard blocked: no

And the Passive BLE monitor in HA started to work again.

Now I will wait for the next outage and I will test this process again.

But this is strange:

bash-5.0# hcitool lescan
Set scan parameters failed: I/O error
Ernst79 commented 3 years ago

It looks like both hcitool and bluetoothctl do not recognize hci1 anymore at a certain moment. I have no idea why, though.

pvojnisek commented 3 years ago

Now it stopped again after less than 24 hours of operation. Here is the log:

Logger: custom_components.ble_monitor
Source: custom_components/ble_monitor/__init__.py:657
Integration: Passive BLE monitor (documentation)
First occurred: 23 March 2021, 08:22:54 (229 occurrences)
Last logged: 12:21:49

HCIdump thread: Runtime error while stop scan request on hci1: Event loop stopped before Future completed.
$ hcitool lescan
Set scan parameters failed: Operation not permitted
$ systemctl status bluetooth
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset
   Active: active (running) since Mon 2021-03-15 08:10:06 CET; 1 weeks 2 days ag
     Docs: man:bluetoothd(8)
 Main PID: 449 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 4213)
   Memory: 2.4M
   CGroup: /system.slice/bluetooth.service
           └─449 /usr/lib/bluetooth/bluetoothd
$ bluetoothctl 
Agent registered
[bluetooth]# scan on
Failed to start discovery: org.bluez.Error.InProgress
$ rfkill list
rfkill: /dev/rfkill: Operation not permitted

I have no clue what to do. I got some esp32 boards and send sensor data via ESPHome instead.

Ernst79 commented 3 years ago

I'll close the issue, as you have found a workaround.

Note that BLE monitor 1.5.0-beta is release, which is now using the MAC address in stead of hci. It might help, although in the background, the mac is still converted to a hci port.

Toukite commented 3 years ago

I'll close the issue, as you have found a workaround.

Can you please tell me what the workaround is ?

Ernst79 commented 3 years ago

The workaround @pvojnisek is using is using ESPHome. I understand it isn't a solution for BLE monitor, but we couldn't figure out what was wrong.

I'm under the impression that it has something to do with the Bluetooth installation and/or firmware of the Bluetooth radio.

I recently had the same error when I tried it on a supervised installation on Debian. I had a lot of troubles getting Bluetooth working on Debian, on a raspberry pi 3b+ (so not getting BLE monitor to work, but getting Bluetooth to work in the first place). And after I got it to work, it was still buggy, with the Event loop stopped error. I then tried Home Assistant OS on the same Raspberry, and I had no problem at all. Next I tried in on a supervised installation with Raspberry OS, again no problem at all.

You have home assistant OS, so it's strange that you have this issue. Unfortunately, I don't have a clue what is wrong, other than that I have often read that Bluetooth can be buggy on a raspberry.

klim123123 commented 3 years ago

Exactly the same problem with HASS and different usb dongles. I tried 5x different dongles including Asus USB-BT400. Randomly i get [custom_components.ble_monitor] HCIdump thread: Runtime error while stop scan request on hci0: Event loop stopped before Future completed. Operating System Home Assistant OS 6.1