operating-system icon indicating copy to clipboard operation
operating-system copied to clipboard

Published 20 hours ago • verified publisher icon home-assistant

Bluetooth integration fails on Raspberry Pi 3 HAOS greater 11.0

Open npasslick opened this issue 11 months ago • 46 comments

Describe the issue you are experiencing

On my Raspberry Pi 3B+ with Home Assistant OS 12.0 currently installed, I unfortunately experienced that the Bluetooth integration for HAOS regularly crashes/becomes unavailable with HAOS version greater 11.0. The Bluetooth integration is usually still available when HAOS is rebooted or started, but then becomes unavailable within a maximum of one hour (usually significantly faster). This is most noticeable for me in the fact that my BTHome sensors will no longer be available from this point on.

Currently I always have to downgrade to HAOS version 11.0 to have Bluetooth consistently available again and I had hoped that this problem would be solved with version 12.0 at the latest, but the problem persists.

I use onboard Bluetooth from my Raspberry Pi 3B+ board and no external adapter. Updates of Home Assistant Core / Supervisor have no influence, the problem only ever appears when upgrading HAOS to >11.0. Other components are up-to-date.

Similar issues: #3207 #3180 #3047 (solution approaches in these issues without effect)

What operating system image do you use?

rpi3-64 (Raspberry Pi 3 64-bit OS)

What version of Home Assistant Operating System is installed?

12.0

Did you upgrade the Operating System.

Yes

Steps to reproduce the issue

  1. Upgrade HAOS to version greater 11.0 (in this case: 12.0)
  2. Wait for bluetooth integration to become unavailable (noticeable for me in form of missing BTHome sensors) - max. 1 hour
  3. Integration becomes unavailable...
  4. Cry and downgrade to HAOS 11.0 - everything works fine now (Core and Supervisor up-to-date)

Anything in the Supervisor logs that might be useful for us?

24-02-28 23:50:50 INFO (MainThread) [supervisor.docker.monitor] Started docker events monitor
24-02-28 23:50:50 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
24-02-28 23:50:50 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/aarch64-hassio-cli with version 2023.11.0
24-02-28 23:50:50 INFO (MainThread) [supervisor.plugins.cli] Starting CLI plugin
24-02-28 23:50:53 INFO (MainThread) [supervisor.docker.cli] Starting CLI ghcr.io/home-assistant/aarch64-hassio-cli with version 2023.11.0 - 172.30.32.5
24-02-28 23:50:53 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/aarch64-hassio-dns with version 2023.06.2
24-02-28 23:50:53 INFO (MainThread) [supervisor.plugins.dns] Starting CoreDNS plugin
24-02-28 23:50:56 INFO (MainThread) [supervisor.docker.dns] Starting DNS ghcr.io/home-assistant/aarch64-hassio-dns with version 2023.06.2 - 172.30.32.3
24-02-28 23:50:56 INFO (MainThread) [supervisor.plugins.dns] Updated /etc/resolv.conf
24-02-28 23:50:56 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/aarch64-hassio-audio with version 2023.12.0
24-02-28 23:50:56 INFO (MainThread) [supervisor.plugins.audio] Starting Audio plugin
24-02-28 23:51:01 INFO (MainThread) [supervisor.docker.audio] Starting Audio ghcr.io/home-assistant/aarch64-hassio-audio with version 2023.12.0 - 172.30.32.4
24-02-28 23:51:01 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/aarch64-hassio-observer with version 2023.06.0
24-02-28 23:51:01 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/aarch64-hassio-multicast with version 2023.06.2
24-02-28 23:51:01 INFO (MainThread) [supervisor.plugins.multicast] Starting Multicast plugin
24-02-28 23:51:05 INFO (MainThread) [supervisor.docker.multicast] Starting Multicast ghcr.io/home-assistant/aarch64-hassio-multicast with version 2023.06.2 - Host
24-02-28 23:51:05 INFO (MainThread) [supervisor.homeassistant.secrets] Loaded 1 Home Assistant secrets
24-02-28 23:51:05 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/home-assistant/raspberrypi3-64-homeassistant with version 2024.2.5
24-02-28 23:51:05 INFO (MainThread) [supervisor.os.manager] Detect Home Assistant Operating System 12.0 / BootSlot B
24-02-28 23:51:08 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/5c53de3b repository
24-02-28 23:51:08 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/9074a9fa repository
24-02-28 23:51:08 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/git/a0d7b954 repository
24-02-28 23:51:08 INFO (MainThread) [supervisor.store.git] Loading add-on /data/addons/core repository
24-02-28 23:51:10 INFO (MainThread) [supervisor.store] Loading add-ons from store: 78 all - 78 new - 0 remove
24-02-28 23:51:10 INFO (MainThread) [supervisor.addons.manager] Found 3 installed add-ons
24-02-28 23:51:10 INFO (MainThread) [supervisor.docker.interface] Attaching to homeassistant/aarch64-addon-ssh with version 9.9.0
24-02-28 23:51:10 INFO (MainThread) [supervisor.docker.interface] Attaching to ghcr.io/brenner-tobias/cloudflared/aarch64 with version 5.1.4
24-02-28 23:51:10 INFO (MainThread) [supervisor.docker.interface] Attaching to homeassistant/aarch64-addon-configurator with version 5.8.0
24-02-28 23:51:10 INFO (MainThread) [supervisor.backups.manager] Found 40 backup files
24-02-28 23:51:11 INFO (MainThread) [supervisor.discovery] Loaded 0 messages
24-02-28 23:51:11 INFO (MainThread) [supervisor.ingress] Loaded 1 ingress sessions
24-02-28 23:51:11 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state setup
24-02-28 23:51:11 INFO (MainThread) [supervisor.resolution.check] System checks complete
24-02-28 23:51:11 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state setup
24-02-28 23:51:11 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
24-02-28 23:51:11 INFO (MainThread) [supervisor.jobs] 'ResolutionFixup.run_autofix' blocked from execution, system is not running - setup
24-02-28 23:51:11 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state setup
24-02-28 23:51:11 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
24-02-28 23:51:11 INFO (MainThread) [__main__] Running Supervisor
24-02-28 23:51:11 INFO (MainThread) [supervisor.os.manager] Rauc: B - marked slot kernel.1 as good
24-02-28 23:51:11 INFO (MainThread) [supervisor.addons.manager] Phase 'initialize' starting 0 add-ons
24-02-28 23:51:11 INFO (MainThread) [supervisor.addons.manager] Phase 'system' starting 0 add-ons
24-02-28 23:51:11 INFO (MainThread) [supervisor.addons.manager] Phase 'services' starting 1 add-ons
24-02-28 23:51:16 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-ssh with version 9.9.0
24-02-28 23:51:21 INFO (MainThread) [supervisor.core] Start Home Assistant Core
24-02-28 23:51:21 INFO (SyncWorker_6) [supervisor.docker.manager] Starting homeassistant
24-02-28 23:51:22 INFO (MainThread) [supervisor.homeassistant.core] Wait until Home Assistant is ready
24-02-28 23:51:44 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
24-02-28 23:51:46 INFO (MainThread) [supervisor.homeassistant.core] Home Assistant Core state changed to NOT_RUNNING
24-02-28 23:52:01 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state startup
24-02-28 23:52:01 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
24-02-28 23:52:47 INFO (MainThread) [supervisor.homeassistant.core] Home Assistant Core state changed to RUNNING
24-02-28 23:52:47 INFO (MainThread) [supervisor.homeassistant.core] Detect a running Home Assistant instance
24-02-28 23:52:47 INFO (MainThread) [supervisor.addons.manager] Phase 'application' starting 2 add-ons
24-02-28 23:52:58 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-configurator with version 5.8.0
24-02-28 23:53:04 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on ghcr.io/brenner-tobias/cloudflared/aarch64 with version 5.1.4
24-02-28 23:53:15 INFO (MainThread) [supervisor.api.middleware.security] /core/info access from 9074a9fa_cloudflared
24-02-28 23:53:29 INFO (MainThread) [supervisor.misc.tasks] All core tasks are scheduled
24-02-28 23:53:29 INFO (MainThread) [supervisor.core] Supervisor is up and running
24-02-28 23:53:29 INFO (MainThread) [supervisor.host.info] Updating local host information
24-02-28 23:53:29 INFO (MainThread) [supervisor.updater] Fetching update data from https://version.home-assistant.io/stable.json
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state running
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for trust/supervisor
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for free_space/system
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for multiple_data_disks/system
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for security/core
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_failed/dns_server
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for docker_config/system
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for no_current_backup/system
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.module] Create new suggestion create_full_backup - system / None
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.module] Create new issue no_current_backup - system / None
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for ipv4_connection_problem/system
24-02-28 23:53:29 INFO (MainThread) [supervisor.resolution.checks.base] Run check for pwned/addon
24-02-28 23:53:30 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_ipv6_error/dns_server
24-02-28 23:53:30 INFO (MainThread) [supervisor.resolution.check] System checks complete
24-02-28 23:53:30 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state running
24-02-28 23:53:31 INFO (MainThread) [supervisor.host.services] Updating service information
24-02-28 23:53:31 INFO (MainThread) [supervisor.host.network] Updating local network information
24-02-28 23:53:32 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
24-02-28 23:53:32 INFO (MainThread) [supervisor.resolution.fixup] Starting system autofix at state running
24-02-28 23:53:32 INFO (MainThread) [supervisor.resolution.fixup] System autofix complete
24-02-28 23:53:32 INFO (MainThread) [supervisor.host.sound] Updating PulseAudio information
24-02-28 23:53:33 INFO (MainThread) [supervisor.host.manager] Host information reload completed
24-02-29 00:21:48 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.check] Starting system checks with state running
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for trust/supervisor
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for free_space/system
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for multiple_data_disks/system
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for security/core
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_failed/dns_server
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for docker_config/system
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for ipv4_connection_problem/system
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for pwned/addon
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.checks.base] Run check for dns_server_ipv6_error/dns_server
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.check] System checks complete
24-02-29 00:51:11 INFO (MainThread) [supervisor.resolution.evaluate] Starting system evaluation with state running
24-02-29 00:51:13 INFO (MainThread) [supervisor.resolution.evaluate] System evaluation complete
24-02-29 00:51:13 INFO (MainThread) [supervisor.resolution.fixup] Starting system autofix at state running
24-02-29 00:51:13 INFO (MainThread) [supervisor.resolution.fixup] System autofix complete
24-02-29 00:52:11 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token

Anything in the Host logs that might be useful for us?

Feb 28 22:51:15 hass kernel: audit: type=1300 audit(1709160675.417:173): arch=c00000b7 syscall=211 success=yes exit=648 a0=3 a1=7fc72641a8 a2=0 a3=1 items=0 ppid=493 pid=2022 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-nft-multi" subj=unconfined key=(null)
Feb 28 22:51:15 hass kernel: audit: type=1327 audit(1709160675.417:173): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D740066696C746572002D4100444F434B45520000002D690068617373696F002D6F0068617373696F002D7000746370002D64003137322E33302E33332E30002D2D64706F7274003232002D6A00414343455054
Feb 28 22:51:15 hass kernel: audit: type=1325 audit(1709160675.433:174): table=nat:74 family=2 entries=1 op=nft_register_rule pid=2024 subj=unconfined comm="iptables"
Feb 28 22:51:16 hass systemd[1]: Started libcontainer container b973f9e375a607233ed2a4b0a33acdb4a13db609d00719df748e910597550506.
Feb 28 22:51:16 hass kernel: eth0: renamed from veth1aa935b
Feb 28 22:51:16 hass kernel: IPv6: ADDRCONF(NETDEV_CHANGE): veth7fcd086: link becomes ready
Feb 28 22:51:16 hass kernel: hassio: port 6(veth7fcd086) entered blocking state
Feb 28 22:51:16 hass kernel: hassio: port 6(veth7fcd086) entered forwarding state
Feb 28 22:51:16 hass NetworkManager[414]: <info>  [1709160676.3691] device (veth7fcd086): carrier: link connected
Feb 28 22:51:19 hass systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Feb 28 22:51:19 hass systemd[1]: systemd-timedated.service: Deactivated successfully.
Feb 28 22:51:22 hass systemd[1]: run-docker-runtime\x2drunc-moby-753c92d7b6e8e3547f5d78ecb511ca1b449956aaa3ac8722c524abe4afcbfa62-runc.3bGe5X.mount: Deactivated successfully.
Feb 28 22:51:22 hass systemd[1]: Started libcontainer container 753c92d7b6e8e3547f5d78ecb511ca1b449956aaa3ac8722c524abe4afcbfa62.
Feb 28 22:51:22 hass kernel: kauditd_printk_skb: 44 callbacks suppressed
Feb 28 22:51:22 hass kernel: audit: type=1334 audit(1709160682.341:195): prog-id=46 op=LOAD
Feb 28 22:51:22 hass kernel: audit: type=1300 audit(1709160682.341:195): arch=c00000b7 syscall=280 success=yes exit=15 a0=5 a1=40001318b0 a2=78 a3=0 items=0 ppid=2301 pid=2310 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
Feb 28 22:51:22 hass kernel: audit: type=1327 audit(1709160682.341:195): proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F72756E2F636F6E7461696E6572642F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F37353363393264376236653865333534376635643738656362
Feb 28 22:51:22 hass kernel: audit: type=1334 audit(1709160682.341:196): prog-id=47 op=LOAD
Feb 28 22:51:22 hass kernel: audit: type=1300 audit(1709160682.341:196): arch=c00000b7 syscall=280 success=yes exit=17 a0=5 a1=4000131640 a2=78 a3=0 items=0 ppid=2301 pid=2310 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
Feb 28 22:51:22 hass kernel: audit: type=1327 audit(1709160682.341:196): proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F72756E2F636F6E7461696E6572642F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F37353363393264376236653865333534376635643738656362
Feb 28 22:51:22 hass kernel: audit: type=1334 audit(1709160682.341:197): prog-id=47 op=UNLOAD
Feb 28 22:51:22 hass kernel: audit: type=1334 audit(1709160682.342:198): prog-id=46 op=UNLOAD
Feb 28 22:51:22 hass kernel: audit: type=1334 audit(1709160682.342:199): prog-id=48 op=LOAD
Feb 28 22:51:22 hass kernel: audit: type=1300 audit(1709160682.342:199): arch=c00000b7 syscall=280 success=yes exit=15 a0=5 a1=4000131b10 a2=78 a3=0 items=0 ppid=2301 pid=2310 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
Feb 28 22:52:51 hass systemd[1]: var-lib-docker-overlay2-ce4247b01557d357a80e67301a59c51663a3512cadd4e896ceeaf444ffcd7ee5\x2dinit-merged.mount: Deactivated successfully.
Feb 28 22:52:51 hass systemd[1]: mnt-data-docker-overlay2-ce4247b01557d357a80e67301a59c51663a3512cadd4e896ceeaf444ffcd7ee5\x2dinit-merged.mount: Deactivated successfully.
Feb 28 22:52:51 hass kernel: hassio: port 7(veth6b2b6f7) entered blocking state
Feb 28 22:52:51 hass kernel: hassio: port 7(veth6b2b6f7) entered disabled state
Feb 28 22:52:52 hass kernel: device veth6b2b6f7 entered promiscuous mode
Feb 28 22:52:52 hass kernel: kauditd_printk_skb: 1 callbacks suppressed
Feb 28 22:52:52 hass kernel: audit: type=1700 audit(1709160771.932:200): dev=veth6b2b6f7 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
Feb 28 22:52:52 hass kernel: audit: type=1300 audit(1709160771.932:200): arch=c00000b7 syscall=206 success=yes exit=40 a0=c a1=400081e000 a2=28 a3=0 items=0 ppid=1 pid=493 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dockerd" exe="/usr/bin/dockerd" subj=unconfined key=(null)
Feb 28 22:52:52 hass kernel: audit: type=1327 audit(1709160771.932:200): proctitle=2F7573722F62696E2F646F636B657264002D480066643A2F2F002D2D636F6E7461696E6572643D2F72756E2F636F6E7461696E6572642F636F6E7461696E6572642E736F636B
Feb 28 22:52:52 hass NetworkManager[414]: <info>  [1709160772.6291] manager: (vethd2df121): new Veth device (/org/freedesktop/NetworkManager/Devices/21)
Feb 28 22:52:52 hass NetworkManager[414]: <info>  [1709160772.6578] manager: (veth6b2b6f7): new Veth device (/org/freedesktop/NetworkManager/Devices/22)
Feb 28 22:52:55 hass systemd[1]: Started libcontainer container af5f10d60a77a229254c7bcaccb1eac5442446cd8cd63f2971a1c61ba37ceff3.
Feb 28 22:52:55 hass kernel: audit: type=1334 audit(1709160775.934:201): prog-id=49 op=LOAD
Feb 28 22:52:55 hass kernel: audit: type=1334 audit(1709160775.940:202): prog-id=50 op=LOAD
Feb 28 22:52:55 hass kernel: audit: type=1300 audit(1709160775.940:202): arch=c00000b7 syscall=280 success=yes exit=16 a0=5 a1=40001298b0 a2=78 a3=0 items=0 ppid=2480 pid=2491 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
Feb 28 22:52:55 hass kernel: audit: type=1327 audit(1709160775.940:202): proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F72756E2F636F6E7461696E6572642F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F61663566313064363061373761323239323534633762636163
Feb 28 22:52:55 hass kernel: audit: type=1334 audit(1709160775.941:203): prog-id=51 op=LOAD
Feb 28 22:52:55 hass kernel: audit: type=1300 audit(1709160775.941:203): arch=c00000b7 syscall=280 success=yes exit=18 a0=5 a1=4000129640 a2=78 a3=0 items=0 ppid=2480 pid=2491 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="runc" exe="/usr/bin/runc" subj=unconfined key=(null)
Feb 28 22:52:55 hass kernel: audit: type=1327 audit(1709160775.941:203): proctitle=72756E63002D2D726F6F74002F7661722F72756E2F646F636B65722F72756E74696D652D72756E632F6D6F6279002D2D6C6F67002F72756E2F636F6E7461696E6572642F696F2E636F6E7461696E6572642E72756E74696D652E76322E7461736B2F6D6F62792F61663566313064363061373761323239323534633762636163
Feb 28 22:52:57 hass kernel: kauditd_printk_skb: 5 callbacks suppressed
Feb 28 22:52:57 hass kernel: audit: type=1325 audit(1709160777.584:207): table=nat:2 family=2 entries=2 op=nft_register_chain pid=2518 subj=unconfined comm="iptables"
Feb 28 22:52:57 hass kernel: audit: type=1300 audit(1709160777.584:207): arch=c00000b7 syscall=211 success=yes exit=124 a0=3 a1=7ffa9db898 a2=0 a3=1 items=0 ppid=493 pid=2518 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-nft-multi" subj=unconfined key=(null)
Feb 28 22:52:57 hass kernel: audit: type=1327 audit(1709160777.584:207): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4E00444F434B45525F4F5554505554
Feb 28 22:52:57 hass kernel: audit: type=1325 audit(1709160777.596:208): table=nat:3 family=2 entries=2 op=nft_register_chain pid=2519 subj=unconfined comm="iptables"
Feb 28 22:52:57 hass kernel: audit: type=1300 audit(1709160777.596:208): arch=c00000b7 syscall=211 success=yes exit=396 a0=3 a1=7fc55ee938 a2=0 a3=1 items=0 ppid=493 pid=2519 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-nft-multi" subj=unconfined key=(null)
Feb 28 22:52:57 hass kernel: audit: type=1327 audit(1709160777.596:208): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D49004F5554505554002D64003132372E302E302E3131002D6A00444F434B45525F4F5554505554
Feb 28 22:52:57 hass kernel: audit: type=1325 audit(1709160777.620:209): table=nat:4 family=2 entries=1 op=nft_register_chain pid=2521 subj=unconfined comm="iptables"
Feb 28 22:52:57 hass kernel: audit: type=1300 audit(1709160777.620:209): arch=c00000b7 syscall=211 success=yes exit=100 a0=3 a1=7fda8b60a8 a2=0 a3=1 items=0 ppid=493 pid=2521 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-nft-multi" subj=unconfined key=(null)
Feb 28 22:52:57 hass kernel: audit: type=1327 audit(1709160777.620:209): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4E00444F434B45525F504F5354524F5554494E47
Feb 28 22:52:57 hass kernel: audit: type=1325 audit(1709160777.635:210): table=nat:5 family=2 entries=2 op=nft_register_chain pid=2522 subj=unconfined comm="iptables"
Feb 28 22:52:57 hass kernel: eth0: renamed from vethd2df121
Feb 28 22:52:57 hass kernel: IPv6: ADDRCONF(NETDEV_CHANGE): veth6b2b6f7: link becomes ready
Feb 28 22:52:57 hass kernel: hassio: port 7(veth6b2b6f7) entered blocking state
Feb 28 22:52:57 hass kernel: hassio: port 7(veth6b2b6f7) entered forwarding state
Feb 28 22:52:58 hass NetworkManager[414]: <info>  [1709160778.1642] device (veth6b2b6f7): carrier: link connected
Feb 28 22:52:58 hass systemd[1]: var-lib-docker-overlay2-5e0b3ce2af32f3b02bdcf1d86bf40f3f3e8ae63ebaa765d803d2fc57cb2ecefa\x2dinit-merged.mount: Deactivated successfully.
Feb 28 22:52:58 hass systemd[1]: mnt-data-docker-overlay2-5e0b3ce2af32f3b02bdcf1d86bf40f3f3e8ae63ebaa765d803d2fc57cb2ecefa\x2dinit-merged.mount: Deactivated successfully.
Feb 28 22:53:00 hass kernel: hassio: port 8(vethe00a2f0) entered blocking state
Feb 28 22:53:00 hass kernel: hassio: port 8(vethe00a2f0) entered disabled state
Feb 28 22:53:00 hass kernel: device vethe00a2f0 entered promiscuous mode
Feb 28 22:53:00 hass NetworkManager[414]: <info>  [1709160780.3687] manager: (vetha5a68f2): new Veth device (/org/freedesktop/NetworkManager/Devices/23)
Feb 28 22:53:00 hass NetworkManager[414]: <info>  [1709160780.3824] manager: (vethe00a2f0): new Veth device (/org/freedesktop/NetworkManager/Devices/24)
Feb 28 22:53:00 hass systemd[1]: Started libcontainer container e50e02cc2686159d6cb3f2d037e958f3ebfad7c4d9307d5c36e51d017a282103.
Feb 28 22:53:01 hass kernel: eth0: renamed from vetha5a68f2
Feb 28 22:53:01 hass kernel: IPv6: ADDRCONF(NETDEV_CHANGE): vethe00a2f0: link becomes ready
Feb 28 22:53:01 hass kernel: hassio: port 8(vethe00a2f0) entered blocking state
Feb 28 22:53:01 hass kernel: hassio: port 8(vethe00a2f0) entered forwarding state
Feb 28 22:53:01 hass NetworkManager[414]: <info>  [1709160781.4360] device (vethe00a2f0): carrier: link connected
Feb 28 22:53:29 hass kernel: kauditd_printk_skb: 53 callbacks suppressed
Feb 28 22:53:29 hass kernel: audit: type=1334 audit(1709160809.463:230): prog-id=57 op=LOAD
Feb 28 22:53:29 hass kernel: audit: type=1334 audit(1709160809.465:231): prog-id=58 op=LOAD
Feb 28 22:53:29 hass kernel: audit: type=1334 audit(1709160809.465:232): prog-id=59 op=LOAD
Feb 28 22:53:29 hass systemd[1]: Starting Hostname Service...
Feb 28 22:53:30 hass systemd[1]: Started Hostname Service.
Feb 28 22:53:30 hass kernel: audit: type=1334 audit(1709160810.806:233): prog-id=60 op=LOAD
Feb 28 22:53:30 hass kernel: audit: type=1334 audit(1709160810.806:234): prog-id=61 op=LOAD
Feb 28 22:53:30 hass kernel: audit: type=1334 audit(1709160810.806:235): prog-id=62 op=LOAD
Feb 28 22:53:30 hass systemd[1]: Starting Time & Date Service...
Feb 28 22:53:31 hass systemd[1]: Started Time & Date Service.
Feb 28 22:54:00 hass systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Feb 28 22:54:00 hass kernel: audit: type=1334 audit(1709160840.896:236): prog-id=59 op=UNLOAD
Feb 28 22:54:00 hass kernel: audit: type=1334 audit(1709160840.896:237): prog-id=58 op=UNLOAD
Feb 28 22:54:00 hass kernel: audit: type=1334 audit(1709160840.896:238): prog-id=57 op=UNLOAD
Feb 28 22:54:01 hass systemd[1]: systemd-timedated.service: Deactivated successfully.
Feb 28 22:54:01 hass kernel: audit: type=1334 audit(1709160841.776:239): prog-id=62 op=UNLOAD
Feb 28 22:54:01 hass kernel: audit: type=1334 audit(1709160841.776:240): prog-id=61 op=UNLOAD
Feb 28 22:54:01 hass kernel: audit: type=1334 audit(1709160841.776:241): prog-id=60 op=UNLOAD
Feb 28 23:05:12 hass systemd[1]: Starting Cleanup of Temporary Directories...
Feb 28 23:05:13 hass systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.
Feb 28 23:05:13 hass systemd[1]: Finished Cleanup of Temporary Directories.
Feb 28 23:05:13 hass systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully.
Feb 29 00:00:17 hass systemd[1]: run-docker-runtime\x2drunc-moby-af5f10d60a77a229254c7bcaccb1eac5442446cd8cd63f2971a1c61ba37ceff3-runc.jVirS5.mount: Deactivated successfully.
Feb 29 00:01:59 hass kernel: audit: type=1334 audit(1709164918.942:242): prog-id=63 op=LOAD
Feb 29 00:01:59 hass systemd[1]: Started Journal Gateway Service.
Feb 29 00:01:59 hass systemd-timesyncd[484]: Network configuration changed, trying to establish connection.
Feb 29 00:01:59 hass systemd-timesyncd[484]: Contacted time server 162.159.200.123:123 (time.cloudflare.com).
Feb 29 00:01:59 hass systemd-journal-gatewayd[5731]: microhttpd: MHD_OPTION_EXTERNAL_LOGGER is not the first option specified for the daemon. Some messages may be printed by the standard MHD logger.

System information

System Information

version core-2024.2.5
installation_type Home Assistant OS
dev false
hassio true
docker true
user root
virtualenv false
python_version 3.12.1
os_name Linux
os_version 6.1.73-haos-raspi
arch aarch64
timezone Europe/Berlin
config_dir /config
Home Assistant Community Store
GitHub API ok
GitHub Content ok
GitHub Web ok
GitHub API Calls Remaining 4996
Installed Version 1.33.0
Stage running
Available Repositories 1399
Downloaded Repositories 7
Home Assistant Cloud
logged_in false
can_reach_cert_server ok
can_reach_cloud_auth ok
can_reach_cloud ok
Home Assistant Supervisor
host_os Home Assistant OS 12.0
update_channel stable
supervisor_version supervisor-2024.02.0
agent_version 1.6.0
docker_version 24.0.7
disk_total 58.0 GB
disk_used 8.0 GB
healthy true
supported true
board rpi3-64
supervisor_api ok
version_api ok
installed_addons Terminal & SSH (9.9.0), File editor (5.8.0), Cloudflared (5.1.4)
Dashboards
dashboards 1
resources 0
views 4
mode storage
Recorder
oldest_recorder_run February 19, 2024 at 3:01 AM
current_recorder_run February 28, 2024 at 11:51 PM
estimated_db_size 705.62 MiB
database_engine sqlite
database_version 3.44.2

Additional information

Other relevant logs

Logger: habluetooth.scanner, source: /usr/local/lib/python3.12/asyncio/events.py:84

Logger: habluetooth.scanner Source: /usr/local/lib/python3.12/asyncio/events.py:84 First occurred: 12:05:51 AM (48 occurrences) Last logged: 12:52:51 AM

hci0 (B8:27:EB:3C:56:D2): Failed to restart Bluetooth scanner: hci0 (B8:27:EB:3C:56:D2): Timed out starting Bluetooth after 15 seconds; Try power cycling the Bluetooth hardware. Traceback (most recent call last): File "src/habluetooth/scanner.py", line 249, in habluetooth.scanner.HaScanner._async_start File "/usr/local/lib/python3.12/site-packages/bleak/init.py", line 198, in start await self._backend.start() File "/usr/local/lib/python3.12/site-packages/bleak/backends/bluezdbus/scanner.py", line 185, in start self._stop = await manager.active_scan( ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/bleak/backends/bluezdbus/manager.py", line 408, in active_scan reply = await self._bus.call( ^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/dbus_fast/aio/message_bus.py", line 384, in call await future asyncio.exceptions.CancelledError

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

Traceback (most recent call last): File "src/habluetooth/scanner.py", line 248, in habluetooth.scanner.HaScanner._async_start File "/usr/local/lib/python3.12/asyncio/timeouts.py", line 115, in aexit raise TimeoutError from exc_val TimeoutError

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

Traceback (most recent call last): File "src/habluetooth/scanner.py", line 380, in habluetooth.scanner.HaScanner._async_restart_scanner File "src/habluetooth/scanner.py", line 294, in _async_start habluetooth.scanner.ScannerStartError: hci0 (B8:27:EB:3C:56:D2): Timed out starting Bluetooth after 15 seconds; Try power cycling the Bluetooth hardware.

Logger: habluetooth.scanner, source: runner.py:188

Logger: habluetooth.scanner Source: runner.py:188 First occurred: 12:03:16 AM (2 occurrences) Last logged: 12:05:16 AM

hci0 (B8:27:EB:3C:56:D2): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress

Full Home Assistant Core log

home-assistant_2024-02-29T00-33-26.162Z.log

npasslick avatar Feb 29 '24 00:02 npasslick

Similarly to #3047 it seems to me that the adapter still works but habluetooth ends up stuck trying to restart it - IMHO it should be more resilient to that, please create a Core issue for debugging it on that side. I don't see any apparent issues with the adapter, can you also check dmesg | grep -i bluetooth?

sairon avatar Feb 29 '24 08:02 sairon

This is the dmesg output

dmesg

npasslick avatar Feb 29 '24 16:02 npasslick

Similarly to #3047 it seems to me that the adapter still works but habluetooth ends up stuck trying to restart it - IMHO it should be more resilient to that, please create a Core issue for debugging it on that side. I don't see any apparent issues with the adapter, can you also check dmesg | grep -i bluetooth?

Do you have a suggestion on what hablueooth should do in this case? Its going to try every time setup retry fires which is every few minutes.

bdraco avatar Feb 29 '24 19:02 bdraco

The scanner start code is here https://github.com/Bluetooth-Devices/habluetooth/blob/71bd22a4bea50fff5ff9b8661b4c19814a512331/src/habluetooth/scanner.py#L249

bdraco avatar Feb 29 '24 19:02 bdraco

@npasslick Does the problem go away if you turn on passive scanning

bdraco avatar Feb 29 '24 19:02 bdraco

Its timing out on the dbus call

https://github.com/hbldh/bleak/blob/054b092e19c7a45d5ea07d8948022f54117fe5e8/bleak/backends/bluezdbus/manager.py#L408

bdraco avatar Feb 29 '24 19:02 bdraco

@npasslick Does the problem go away if you turn on passive scanning

I will try that

npasslick avatar Feb 29 '24 19:02 npasslick

@npasslick Does the problem go away if you turn on passive scanning

I have upgraded my system back to HAOS 12.0 and activated passive scanning immediately.

The activation of passive scanning seems to have actually prevented the problem so far, as I already mentioned, the integration usually crashes within an hour of system startup, and this period has now elapsed. Seems to be a suitable workaround for now, but of course it won't solve the problem long-term.

I will have to wait and see if the Bluetooth integration does not crash over a longer period of time with passive scanning, but looks good so far.

npasslick avatar Feb 29 '24 20:02 npasslick 

[bluetooth]# scan off
Discovery stopped
[bluetooth]# scan on
Discovery started
[bluetooth]# scan on
Failed to start discovery: org.bluez.Error.InProgress
[bluetooth]#

bdraco avatar Feb 29 '24 20:02 bdraco

If it happens again in ~~advice~~active mode, can you try turning the scan off with bluetoothctl, pasting the output here, and seeing if it can recover?

bdraco avatar Feb 29 '24 20:02 bdraco

If it happens again in advice mode, can you try turning the scan off with bluetoothctl, pasting the output here, and seeing if it can recover?

Sure thing, I guess with advice mode you mean active / non-passive mode?

npasslick avatar Feb 29 '24 20:02 npasslick

Sorry, flipping between too many things this morning: should have wrote: active mode

bdraco avatar Feb 29 '24 20:02 bdraco

Sorry, flipping between too many things this morning: should have wrote: active mode

No worries, i will try that ^^

npasslick avatar Feb 29 '24 20:02 npasslick

If it happens again in ~advice~active mode, can you try turning the scan off with bluetoothctl, pasting the output here, and seeing if it can recover?

Unsurprisingly, the bluetooth integration failed again in active mode. It does not recover after scan off or scan on

scan off --> org.bluez.Error.Failed scan on ---> scan off --> org.bluez.Error.InProgress

bluetoothctl output

bluetoothctl

Full bluetooth debug log

home-assistant_bluetooth_2024-02-29T22-09-21.741Z.log

npasslick avatar Feb 29 '24 22:02 npasslick

It seems like there isn't much we can do in habluetooth if its failing in bluetoothctl which means its too far down the stack for any retries to work.

I expect passive is going to work fine because it doesn't hit the path where you get the bluez errors

bdraco avatar Feb 29 '24 22:02 bdraco

It seems like there isn't much we can do in habluetooth if its failing in bluetoothctl which means its too far down the stack for any retries to work.

I expect passive is going to work fine because it doesn't hit the path where you get the bluez errors

Hmm I see, then something underlying must have changed after HAOS 11.0, but thanks for the tip with the passive mode, for my purposes this should be sufficient, but others will certainly have to deal with this problem. Maybe someone else can identify the underlying problem.

npasslick avatar Feb 29 '24 22:02 npasslick

@bdraco Thank you much for your effort so far, at least I can use the current version of HAOS now ^^ Keep up the good work, I will make a small donation to your Food Bank as a gesture of my appreciation (y)

npasslick avatar Feb 29 '24 22:02 npasslick

Having the same issue on my Raspberry Pi 4. Passive mode fixes the initialisation issue for the bluetooth integration but breaks my switchbot bots. Switchbot curtains do work in passive mode. If there is some additional stuff, I can test for you guys feel free to let me know and I will give it a shot.

CasperNaudts avatar Mar 08 '24 23:03 CasperNaudts

I upgraded HA Core from 2023.12.3 to 2024.3.0 and experienced the similar issue. My Bluetooth sensors would periodically disconnect then reconnect sporadically. I downgraded to 2023.12.3 and Bluetooth devices work again:

co2

JesusSanchezLopez avatar Mar 12 '24 13:03 JesusSanchezLopez

I also upgraded to HA Core 2024.3.2 and within an hour I started getting sensor unavailable messages. Reverting back to 2024.1.5

JesusSanchezLopez avatar Mar 22 '24 18:03 JesusSanchezLopez

Likewise, no improvement for me with the latest version of HA Core in Bluetooth active mode

npasslick avatar Mar 22 '24 19:03 npasslick

Well, now I'm in a situation where I've got a new device and passive scanning is simply not enough to ensure reliable operation. I hope someone can take care of this soon, unfortunately my skills are currently not sufficient for hardware-oriented programming :(

npasslick avatar Mar 26 '24 13:03 npasslick

On my end the bluetooth issue with raspberry Pi popped up in 12.1. Downgrading to 12.0 fixes the problem. In case others are searching for how to downgrade the OS version issue the following command in an SSH session:

ha os update --version 12.0

apetryk2 avatar Apr 07 '24 17:04 apetryk2

I found a weird way to temporarily fix the issue. Bluetooth isn't willing to initialize in active mode after a software reboot. When I unplug the power and replug the power Bluetooth initialises with no issues in active mode until the next software reboot.

CasperNaudts avatar Apr 08 '24 13:04 CasperNaudts

I just tried 12.2 and the problem may be fixed.

apetryk2 avatar Apr 11 '24 19:04 apetryk2

Problem also is fixed here with the new 12.2 update.

CasperNaudts avatar Apr 12 '24 15:04 CasperNaudts

I'm on 12.2 with a Homeassistant Yellow (CM4). Problem still persists. Or actually, I did not have this problem before, but now I got it.

frli4797 avatar Apr 17 '24 13:04 frli4797

Seems like this problem has been pending for a bit. Any progress?

frli4797 avatar Apr 22 '24 09:04 frli4797

I found a weird way to temporarily fix the issue. Bluetooth isn't willing to initialize in active mode after a software reboot. When I unplug the power and replug the power Bluetooth initialises with no issues in active mode until the next software reboot.

Sadly its pretty common that these chips will stop responding and need to be powered down to get them to work again.

The upcoming HAOS 12.3 uses the 6.6.x linux kernels which, at least for me, seems to be a bit more stable with the RPi Bluetooth hardware.

bdraco avatar Apr 22 '24 10:04 bdraco

I have a rpi4-64. What gets me is 4 weeks ago and for at least a year before it all worked perfectly. Nothing in the hardware has changed. So it must be HAOS. What changed? Someone must know. I have tried the scan thing but makes no difference and tried the power off/power on thing and again no difference. The only thing that works is turning the mains power off and on again. This is not a solution in the long term.

[bluetooth]# scan off
Failed to stop discovery: org.bluez.Error.Failed
[bluetooth]# scan on
[bluetooth]#

The only thing that works is turning the mains power off and on again. This is not a solution in the long term.

auditdata avatar Apr 30 '24 07:04 auditdata