core icon indicating copy to clipboard operation
core copied to clipboard

Bluetooth Error

Open kksligh opened this issue 2 years ago • 4 comments

The problem

My bluetooth has been quite unstable since moving to the core integration (I used to use the HACS BLE integration for a long time using the same device). Today, i keep seeing my entities for BT go in and out - and decided to file a ticket.

Note, I am on a Intel NUC using the internal BT module. While its never had the best range, its worked consistently for over a year. This instability started after I moved over to the new core integration this month and it seems to be getting worse with each build.

The Bluetooth main integration will show the error in the picture below - if I reload the integration, it goes into an "initialization" mode that seems to last forever.

image

image

I captured the logs below for this error:

' Logger: homeassistant.components.bluetooth.scanner Source: components/bluetooth/scanner.py:277 Integration: Bluetooth (documentation, issues) First occurred: 6:32:29 PM (49 occurrences) Last logged: 6:58:25 PM

hci0 (94:E2:3C:8B:3F:E3): Failed to restart Bluetooth scanner: hci0 (94:E2:3C:8B:3F:E3): Timed out starting Bluetooth after 15 seconds Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 232, in _async_start await self.scanner.start() # type: ignore[no-untyped-call] File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/scanner.py", line 150, in start self._stop = await manager.active_scan( File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 358, in active_scan reply = await self._bus.call( File "/usr/local/lib/python3.10/site-packages/dbus_fast/aio/message_bus.py", line 337, in call await future asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Logger: homeassistant.components.bluetooth.scanner Source: components/bluetooth/scanner.py:277 Integration: Bluetooth (documentation, issues) First occurred: 6:32:29 PM (49 occurrences) Last logged: 6:58:25 PM

hci0 (94:E2:3C:8B:3F:E3): Failed to restart Bluetooth scanner: hci0 (94:E2:3C:8B:3F:E3): Timed out starting Bluetooth after 15 seconds Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 232, in _async_start await self.scanner.start() # type: ignore[no-untyped-call] File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/scanner.py", line 150, in start self._stop = await manager.active_scan( File "/usr/local/lib/python3.10/site-packages/bleak/backends/bluezdbus/manager.py", line 358, in active_scan reply = await self._bus.call( File "/usr/local/lib/python3.10/site-packages/dbus_fast/aio/message_bus.py", line 337, in call await future asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 231, in _async_start async with async_timeout.timeout(START_TIMEOUT): File "/usr/local/lib/python3.10/site-packages/async_timeout/init.py", line 129, in aexit self._do_exit(exc_type) File "/usr/local/lib/python3.10/site-packages/async_timeout/init.py", line 212, in _do_exit raise asyncio.TimeoutError asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 362, in _async_scanner_watchdog await self._async_start() File "/usr/src/homeassistant/homeassistant/components/bluetooth/scanner.py", line 277, in _async_start raise ScannerStartError( homeassistant.components.bluetooth.scanner.ScannerStartError: hci0 (94:E2:3C:8B:3F:E3): Timed out starting Bluetooth after 15 seconds

Logger: homeassistant.components.bluetooth.scanner Source: components/bluetooth/scanner.py:352 Integration: Bluetooth (documentation, issues) First occurred: 6:29:56 PM (2 occurrences) Last logged: 6:31:56 PM

hci0 (94:E2:3C:8B:3F:E3): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress `

What version of Home Assistant Core has the issue?

2022.9.5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Supervised

Integration causing the issue

bluetooth

Link to integration documentation on our website

https://www.home-assistant.io/integrations/bluetooth

Diagnostics information

config_entry-bluetooth-0e44c326dae00b2b6eb90fc14d919bdb.json.txt

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

kksligh avatar Sep 21 '22 00:09 kksligh

Hey there @bdraco, mind taking a look at this issue as it has been labeled with an integration (bluetooth) you are listed as a code owner for? Thanks! (message by CodeOwnersMention)

Looks like a problem with BlueZ on your host. What version are you running?

Jc2k avatar Sep 21 '22 13:09 Jc2k

No idea - how do I check that?

kksligh avatar Sep 21 '22 13:09 kksligh

Supervised means you are using your own OS doesn't it?

Jc2k avatar Sep 21 '22 13:09 Jc2k

I'm not sure what you mean. I've installed the HA OS on a Intel NUC. I can either get to the bios of the NUC or look in the home assistant application for verifying what you're asking for. This was working previously so I'm not sure what has changed.

kksligh avatar Sep 21 '22 13:09 kksligh

image

kksligh avatar Sep 21 '22 14:09 kksligh

Ok, in your initial report you said "Home Assistant Supervised":

Screenshot 2022-09-21 at 15 04 52

Thats an advanced manual installation, when you provide your own operating system (like Ubuntu or Debian or something). That means that providing me the information i need to help you would have been much harder for you.

But Home Assistant OS makes this much easier - thanks to that screenshot i know you have a recent kernel, recent firmware, the "good" dbus broker and recent bluez.

I don't suppose you know what kind of Bluetooth module the NUC has?

Jc2k avatar Sep 21 '22 14:09 Jc2k

And can I also check what you mean by:

This was working previously so I'm not sure what has changed.

Do you mean the passive BLE monitor integration (https://github.com/custom-components/ble_monitor) was working previously, OR do you mean 2022.8.0 was working.

Jc2k avatar Sep 21 '22 14:09 Jc2k

And can I also check what you mean by:

This was working previously so I'm not sure what has changed.

Do you mean the passive BLE monitor integration (https://github.com/custom-components/ble_monitor) was working previously, OR do you mean 2022.8.0 was working.

Both - the HACS and the core integration were both working great prior to this month's software updates.

kksligh avatar Sep 21 '22 15:09 kksligh

Do you know how to get SSH access to your Home Assistant machine? (To the underyling linux system, not the HA shell).

Jc2k avatar Sep 21 '22 15:09 Jc2k

so not this?

image

I could get into the NUC Bios but its a pain. What are the steps I need to do and I'll work on it.

kksligh avatar Sep 21 '22 15:09 kksligh

Ok, in your initial report you said "Home Assistant Supervised":

Screenshot 2022-09-21 at 15 04 52

Thats an advanced manual installation, when you provide your own operating system (like Ubuntu or Debian or something). That means that providing me the information i need to help you would have been much harder for you.

But Home Assistant OS makes this much easier - thanks to that screenshot i know you have a recent kernel, recent firmware, the "good" dbus broker and recent bluez.

I don't suppose you know what kind of Bluetooth module the NUC has?

here's the hardware specs.

GENERAL INFORMATION Brand: Intel Model: NUC11PAHI7 Form Factor: Mini PC Operating System: Windows 10 Pro

PROCESSOR Processor Brand: Intel Processor Type: Core i7-1165G7 Number of Cores: 4 Base Frequency: 2.8GHz Turbo Frequency: 4.7GHz SmartCache: 12MB

MEMORY Memory Capacity: 16GB Memory Type: DDR4 Memory Form Factor: SO-DIMM Memory Speed: 2400 Max Supported Memory: 32 GB

STORAGE Drive Capacity: 512GB Drive Type: NVMe SSD (PCIe)

VIDEO Integrated Graphics: Intel Iris Xe Graphics

AUDIO Audio Tech: HD Audio

PORTS & FEATURES Video Ports: 1x HDMI, 1x Mini DisplayPort, 2x Thunderbolt 4 Audio Ports: 1 x Headphone/Microphone Combo Jack USB Ports: Front: 1x USB 3.2 Gen 2, 1x Thunderbolt 3. Rear: 2x USB 3.2 Gen 2, 1x Thunderbolt 4 Card Reader: 3-in-1 Security Slot: Yes

COMMUNICATIONS LAN: Gigabit Ethernet Wi-Fi: Wi-Fi 6 Bluetooth: Bluetooth 5.0

kksligh avatar Sep 21 '22 15:09 kksligh

I don't use HA OS so i'll struggle to help you with that tbh. Maybe its this? https://developers.home-assistant.io/docs/operating-system/debugging/

Jc2k avatar Sep 21 '22 15:09 Jc2k

When you are able to get SSH access to the right bit, you should be able to run bluetoothctl and it will drop you into the bluetooth shell. On a healthy system where HA is working it will immediately start streaming logs that look like this:

[CHG] Device 76:FC:AD:5D:A8:DB RSSI: -67
[CHG] Device 34:9F:7B:E9:09:96 RSSI: -65
[CHG] Device 6C:3C:4A:62:22:DB RSSI: -84
[CHG] Device 01:D3:E6:42:B1:CD RSSI: -86
[CHG] Device 6F:70:76:A9:C2:AC RSSI: -80
[CHG] Device 4A:A1:56:70:AB:28 RSSI: -59
[CHG] Device 74:04:BD:70:1C:C0 RSSI: -92
[CHG] Device 9C:8C:6E:E2:C6:D3 RSSI: -89
[CHG] Device 56:88:10:F3:32:17 RSSI: -64
[CHG] Device 7A:16:3C:85:26:49 RSSI: -77
[CHG] Device C4:7C:8D:6A:3E:7A RSSI: -75
[CHG] Device C4:7C:8D:6A:3E:7A ServiceData Key: 0000fe95-0000-1000-8000-00805f9b34fb
[CHG] Device C4:7C:8D:6A:3E:7A ServiceData Value:
  71 20 98 00 a4 7a 3e 6a 8d 7c c4 0d 04 10 02 ed  q ...z>j.|......
  00                                               .               
[CHG] Device 7A:16:3C:85:26:49 RSSI: -75

If you are instead met with silence, you can try running scan on. If that doesn't work, try power off, power on and then scan on again.

If you see error messages from these commands or you are still met with no output then its a HA OS, not a HA Core problem.

Jc2k avatar Sep 21 '22 15:09 Jc2k

what is the code to "Run" bluetoothct1

kksligh avatar Sep 21 '22 15:09 kksligh

I'm trying 2 SSH add ons...

image

image

kksligh avatar Sep 21 '22 16:09 kksligh

It's l not 1 (lower case L)

Jc2k avatar Sep 21 '22 16:09 Jc2k

image

kksligh avatar Sep 21 '22 16:09 kksligh

Try scan on now

Jc2k avatar Sep 21 '22 16:09 Jc2k

image

kksligh avatar Sep 21 '22 16:09 kksligh

Ok, try: power off, power on, scan on (3 commands, 3 lines)

Jc2k avatar Sep 21 '22 16:09 Jc2k

image

kksligh avatar Sep 21 '22 16:09 kksligh

So yeah, it looks like its a problem with BlueZ rather than HA Core. It would be good if you could test with the previous release of HA OS. (Ideally we would test a downgrade fixed it, and an upgrade fixed it).

Jc2k avatar Sep 21 '22 16:09 Jc2k

so is BlueZ something I can update? Or you think downgrading and then upgrading may resolve it?

kksligh avatar Sep 21 '22 16:09 kksligh

HA OS isn't a general purpose operating system - the only way to change the version of bluez is to downgrade or upgrade the entire OS.

Based on the behaviour you have described I think it's either the OS or it's a hardware problem that is being triggered by new features that didn't used to exist. But neither of these theories are confirmed. We need to be sure if I am right before looping in anyone else.

It could be a transient error (rebooting the entire box might fix it, or a full power off and cold boot might). So start there.

If that doesn't help a downgrade of the whole OS might fix it. What we need to do is prove is that HA OS 8.x and HA core 2022.9.5 work together.

Then upgrade to HA OS 2022.9.

If it breaks again, it probably is a regression in one of the OS components. If it carries on working then it was a transient error - your Bluetooth adapter inside the NUC probably crashed. If that keeps happening you might need to switch to an external one.

Jc2k avatar Sep 21 '22 16:09 Jc2k

got it - I'll work on this and get back

kksligh avatar Sep 21 '22 16:09 kksligh

OK...so after I power cycled the NUC and reinstalled a saved build to see if there was any corruption in the install - it's been stable for a few hours. If it continues I'll close this tonight.

Thanks for everything you do on this platform!

kksligh avatar Sep 21 '22 22:09 kksligh