ble_monitor: Multiple Bluetooth and hci errors

I recently updated Rasbian and am now seeing multiple errors and unstable hci interface. These errors only occur when the ble_monitor is running.

I was running the older (original passive) mitemp_ble (which was stable) when I updated and I saw the errors immediately on Raspbian update. I then updated to ble_monitor and I still see the errors.

I also suffer from the issue of the internal/external Bletooth device issue documented here. https://www.raspberrypi.org/forums/viewtopic.php?f=28&t=282948#p1713622

I am seeing lots of hci errors when trying to read Bluetooth data. the hci interfaces crash regularly.

Selection of syslog errors.

Feb 07 06:49:15 hassio kernel: Bluetooth: hci0: advertising data len corrected 18 -> 3
Feb 07 06:49:15 hassio kernel: Bluetooth: hci0: hardware error 0x00
Feb 07 06:49:15 hassio kernel: debugfs: File 'force_bredr_smp' in directory 'hci0' already present!
Feb 07 06:49:28 hassio kernel: Bluetooth: hci1: advertising data len corrected 17 -> 14
Feb 07 06:49:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000

Feb 07 06:51:33 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:51:33 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:51:33 hassio kernel: Bluetooth: hci1: hardware error 0x00
Feb 07 06:51:33 hassio kernel: debugfs: File 'force_bredr_smp' in directory 'hci1' already present!
Feb 07 06:51:48 hassio kernel: Bluetooth: hci0: advertising data len corrected 28 -> 4
Feb 07 06:51:48 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:48 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:48 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:48 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:49 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:49 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:49 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:49 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:49 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:49 hassio kernel: Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 07 06:51:50 hassio kernel: Bluetooth: hci0: hardware error 0x03
Feb 07 06:51:50 hassio kernel: debugfs: File 'force_bredr_smp' in directory 'hci0' already present!
Feb 07 06:52:07 hassio kernel: Bluetooth: hci0: hardware error 0x00
Feb 07 06:52:08 hassio kernel: debugfs: File 'force_bredr_smp' in directory 'hci0' already present!
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: advertising data len corrected 28 -> 4
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:19 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:52:28 hassio kernel: Bluetooth: hci1: hardware error 0x37
Feb 07 06:52:28 hassio kernel: debugfs: File 'force_bredr_smp' in directory 'hci1' already present!
Feb 07 06:53:02 hassio kernel: Bluetooth: hci1: advertising data len corrected 18 -> 3
Feb 07 06:53:02 hassio kernel: Bluetooth: hci1: hardware error 0x03
Feb 07 06:53:02 hassio kernel: debugfs: File 'force_bredr_smp' in directory 'hci1' already present!
Feb 07 06:54:18 hassio apcupsd[612]: Communications with UPS lost.
Feb 07 06:54:44 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:44 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:44 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:44 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:44 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:44 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:44 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:47 hassio kernel: Bluetooth: hci1: advertising data len corrected 28 -> 4
Feb 07 06:54:47 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:47 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:47 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:47 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:47 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000
Feb 07 06:54:47 hassio kernel: Bluetooth: hci1: Received unexpected HCI Event 00000000

Feb 07 07:00:01 hassio kernel: Bluetooth: hci1: command 0x040a tx timeout
Feb 07 07:00:15 hassio kernel: Bluetooth: hci0: hardware error 0x76
Feb 07 07:00:15 hassio kernel: debugfs: File 'force_bredr_smp' in directory 'hci0' already present!

HA Log

2021-02-07 06:49:49 DEBUG (MainThread) [custom_components.ble_monitor.binary_sensor] 0 MiBeacon BLE ADV messages processed for 0 binary sensor device(s) total. Priority queue = 0
2021-02-07 06:50:00 DEBUG (MainThread) [custom_components.ble_monitor.sensor] 50 MiBeacon BLE ADV messages processed for 5 measuring device(s).
2021-02-07 06:50:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: main event_loop stopped, finishing
2021-02-07 06:50:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Scanning will be restarted
2021-02-07 06:50:00 DEBUG (Thread-2881) [custom_components.ble_monitor] 883 HCI events processed for previous period.
2021-02-07 06:50:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Run
2021-02-07 06:50:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci0
2021-02-07 06:50:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci1
2021-02-07 06:50:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: start main event_loop
2021-02-07 06:50:02 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:50:32 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:50:49 DEBUG (MainThread) [custom_components.ble_monitor.binary_sensor] 0 MiBeacon BLE ADV messages processed for 0 binary sensor device(s) total. Priority queue = 0
2021-02-07 06:51:00 DEBUG (MainThread) [custom_components.ble_monitor.sensor] 80 MiBeacon BLE ADV messages processed for 5 measuring device(s).
2021-02-07 06:51:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: main event_loop stopped, finishing
2021-02-07 06:51:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Scanning will be restarted
2021-02-07 06:51:00 DEBUG (Thread-2881) [custom_components.ble_monitor] 1629 HCI events processed for previous period.
2021-02-07 06:51:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Run
2021-02-07 06:51:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci0
2021-02-07 06:51:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci1
2021-02-07 06:51:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: start main event_loop
2021-02-07 06:51:02 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:51:32 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:51:49 DEBUG (MainThread) [custom_components.ble_monitor.binary_sensor] 0 MiBeacon BLE ADV messages processed for 0 binary sensor device(s) total. Priority queue = 0
2021-02-07 06:52:00 DEBUG (MainThread) [custom_components.ble_monitor.sensor] 75 MiBeacon BLE ADV messages processed for 5 measuring device(s).
2021-02-07 06:52:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: main event_loop stopped, finishing
2021-02-07 06:52:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Scanning will be restarted
2021-02-07 06:52:00 DEBUG (Thread-2881) [custom_components.ble_monitor] 1645 HCI events processed for previous period.
2021-02-07 06:52:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Run
2021-02-07 06:52:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci0
2021-02-07 06:52:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci1
2021-02-07 06:52:00 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: start main event_loop
2021-02-07 06:52:02 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:52:32 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:52:49 DEBUG (MainThread) [custom_components.ble_monitor.binary_sensor] 0 MiBeacon BLE ADV messages processed for 0 binary sensor device(s) total. Priority queue = 0
2021-02-07 06:53:01 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: main event_loop stopped, finishing
2021-02-07 06:53:01 DEBUG (MainThread) [custom_components.ble_monitor.sensor] 44 MiBeacon BLE ADV messages processed for 5 measuring device(s).
2021-02-07 06:53:01 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Scanning will be restarted
2021-02-07 06:53:01 DEBUG (Thread-2881) [custom_components.ble_monitor] 787 HCI events processed for previous period.
2021-02-07 06:53:01 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Run
2021-02-07 06:53:01 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci0
2021-02-07 06:53:01 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci1
2021-02-07 06:53:01 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: start main event_loop
2021-02-07 06:53:02 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:53:32 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:53:49 DEBUG (MainThread) [custom_components.ble_monitor.binary_sensor] 0 MiBeacon BLE ADV messages processed for 0 binary sensor device(s) total. Priority queue = 0
2021-02-07 06:54:02 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:54:02 DEBUG (MainThread) [custom_components.ble_monitor.sensor] 39 MiBeacon BLE ADV messages processed for 5 measuring device(s).
2021-02-07 06:54:02 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: main event_loop stopped, finishing
2021-02-07 06:54:02 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Scanning will be restarted
2021-02-07 06:54:02 DEBUG (Thread-2881) [custom_components.ble_monitor] 1038 HCI events processed for previous period.
2021-02-07 06:54:02 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Run
2021-02-07 06:54:02 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci0
2021-02-07 06:54:02 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci1
2021-02-07 06:54:02 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: start main event_loop
2021-02-07 06:54:32 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:54:50 DEBUG (MainThread) [custom_components.ble_monitor.binary_sensor] 0 MiBeacon BLE ADV messages processed for 0 binary sensor device(s) total. Priority queue = 0
2021-02-07 06:55:02 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:55:03 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: main event_loop stopped, finishing
2021-02-07 06:55:03 DEBUG (MainThread) [custom_components.ble_monitor.sensor] 116 MiBeacon BLE ADV messages processed for 5 measuring device(s).
2021-02-07 06:55:03 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Scanning will be restarted
2021-02-07 06:55:03 DEBUG (Thread-2881) [custom_components.ble_monitor] 2201 HCI events processed for previous period.
2021-02-07 06:55:03 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: Run
2021-02-07 06:55:03 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci0
2021-02-07 06:55:03 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: connected to hci1
2021-02-07 06:55:03 DEBUG (Thread-2881) [custom_components.ble_monitor] HCIdump thread: start main event_loop
2021-02-07 06:55:32 DEBUG (Recorder) [homeassistant.components.recorder] Sending keepalive
2021-02-07 06:55:50 DEBUG (MainThread) [custom_components.ble_monitor.binary_sensor] 0 MiBeacon BLE ADV messages processed for 0 binary sensor device(s) total. Priority queue = 0

About this issue

Original URL
State: closed
Created 3 years ago
Reactions: 1
Comments: 28

Most upvoted comments

I had similar problem. Component worked normally, but after some time and after errors: Bluetooth: hci0: Received unexpected HCI Event 00000000 dongle go down until physical restart or command sudo hciconfig hci0 up After install packages: sudo apt install bluetooth pi-bluetooth bluez blueman bluez-hcidump

It works well. No errors. No problem.

vdemidov on Mar 14, 2021

Well that is the solution. How on earth the packages get deleted on upgrade!

It has been rock solid for 12 hours.

Thanks for your support and help @Ernst79 and keep up the good work 😄

borpin on Feb 12, 2021

I don’t have any hold back packages.

~ $ uname -a
Linux raspberrypi4 5.10.14-v7l+ #1401 SMP Mon Feb 8 14:27:07 GMT 2021 armv7l GNU/Linux

I did a dist upgrade yesterday to see if it would fix my issues, but that didn’t help.

Ernst79 on Feb 9, 2021

Ok, lets find out what commands are send to the HCI interface. (I didn’t write this part myself, so I need to figure it out as well). Below I will try to find out what is exactly does. The communication with the HCI interface is somewhere in aioblescan_ext.py, but it is started from __init__.py in this part.

Lets start with __init__.py. In the code, I think we should look in this part.

            for hci in self._interfaces:
                try:
                    mysocket[hci] = aiobs.create_bt_socket(hci)
                except OSError as error:
                    _LOGGER.error("HCIdump thread: OS error (hci%i): %s", hci, error)
                else:
                    fac[hci] = getattr(self._event_loop, "_create_connection_transport")(
                        mysocket[hci], aiobs.BLEScanRequester, None, None
                    )
                    conn[hci], btctrl[hci] = self._event_loop.run_until_complete(fac[hci])
                    _LOGGER.debug("HCIdump thread: connected to hci%i", hci)
                    btctrl[hci].process = self.process_hci_events
                    try:
                        self._event_loop.run_until_complete(btctrl[hci].send_scan_request(self._active))
                    except RuntimeError as error:
                        _LOGGER.error(
                            "HCIdump thread: Runtime error while sending scan request on hci%i: %s", hci, error
                        )

So, assuming you have hci0 an 1, we first have mysocket[0] = aiobs.create_bt_socket(0). This returns the following: <socket.socket fd=24, family=AddressFamily.AF_BLUETOOTH, type=SocketKind.SOCK_RAW, proto=1>

if no errors occur, we continue with fac[0] = getattr(self._event_loop, "_create_connection_transport")(mysocket[0], aiobs.BLEScanRequester, None, None). This returns the following coroutine object BaseEventLoop._create_connection_transport at 0xadb9e328

Next, we have conn[hci], btctrl[0] = self._event_loop.run_until_complete(fac[0]), which returns <_SelectorSocketTransport fd=24 read=polling write=<idle, bufsize=0>>

And then btctrl[0].process = self.process_hci_events, which returns <bound method HCIdump.process_hci_events of <HCIdump(Thread-4, started 2915037216)>>

This is followed by something similar for hci 1 (can’t test this myself)

So, based on the last output, it seems it is making an HCIdump. With two hci interfaces, I assume it is making two HCIdumps at the same time.

Edit: quick question in between, are you using other components that use bluetooth?

Ernst79 on Feb 7, 2021

The syslog errors must be being created by the calls made by ble_monitor, as they stop when I disable the integration.

But that doesn’t mean that ble_monitor is the cause of your problem. ble_monitor is “telling” the system to listen to the HCI interface. We use a slightly modified aioblescan for that. But the issue can still be in either ble_monitor, in aioblescan, in your OS/bluetooth software or even in Linux/kernel itself. Based on your logs, I don’t think there is an issue in ble_monitor. My guess (but I’m not an expert at all) you have an an issue in either the firmware of one of the bluetooth radio’s or in the bluetooth software.

Ernst79 on Feb 7, 2021