home-assistant / operating-system

:beginner: Home Assistant Operating System
Apache License 2.0
4.83k stars 965 forks source link

Bluetooth integration fails on Raspberry Pi 3 HAOS greater 11.0 #3211

Open npasslick opened 7 months ago

npasslick commented 7 months ago

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](https://github.com/home-assistant/operating-system/files/14441310/home-assistant_2024-02-29T00-33-26.162Z.log)
sairon commented 7 months ago

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?

npasslick commented 7 months ago

This is the dmesg output

dmesg

bdraco commented 7 months ago

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 commented 7 months ago

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

bdraco commented 7 months ago

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

bdraco commented 7 months ago

Its timing out on the dbus call

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

npasslick commented 7 months ago

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

I will try that

npasslick commented 7 months ago

@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.

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

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

npasslick commented 7 months ago

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?

bdraco commented 7 months ago

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

npasslick commented 7 months ago

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

No worries, i will try that ^^

npasslick commented 7 months ago

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](https://github.com/home-assistant/operating-system/assets/10518890/dbe7538a-68f5-4f34-b17d-a51829abd436)
Full bluetooth debug log [home-assistant_bluetooth_2024-02-29T22-09-21.741Z.log](https://github.com/home-assistant/operating-system/files/14454082/home-assistant_bluetooth_2024-02-29T22-09-21.741Z.log)
bdraco commented 7 months ago

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

npasslick commented 7 months ago

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 commented 7 months ago

@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)

CasperNaudts commented 6 months ago

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.

JesusSanchezLopez commented 6 months ago

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 commented 6 months ago

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

npasslick commented 6 months ago

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

npasslick commented 6 months ago

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 :(

apetryk2 commented 5 months ago

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

CasperNaudts commented 5 months ago

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.

apetryk2 commented 5 months ago

I just tried 12.2 and the problem may be fixed.

CasperNaudts commented 5 months ago

Problem also is fixed here with the new 12.2 update.

frli4797 commented 5 months ago

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 commented 5 months ago

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

bdraco commented 5 months ago

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.

auditdata commented 5 months ago

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 commented 5 months ago
Screenshot 2024-04-30 at 09 12 13

Sad life now :-) :-) :-) :-(

StahlTim commented 4 months ago

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.

Same for me on a rpi3. Only power cycling (manually taking away the power for some time) fixes the issue for a couple of hours/days.

agners commented 4 months ago

@auditdata @StahlTim did you try HAOS 12.3? It comes with and updated Linux kernel which might change things. Also do you use active or passive mode?

npasslick commented 4 months ago

Seems like HAOS 12.3 has finally fixed this problem at least for me. The Bluetooth integration has been working in active mode since this morning without crashing. We'll see how it works in the long run and what other affected users running HAOS report, but I have a good feeling.

auditdata commented 4 months ago

@auditdata @StahlTim did you try HAOS 12.3? It comes with and updated Linux kernel which might change things. Also do you use active or passive mode?

Not sue as I cut my losses and bought an external Bluetooth adapter and all worked again. I guess I could unplug it and have a look but might wait for others to confirm now working again.

StahlTim commented 4 months ago

@auditdata @StahlTim did you try HAOS 12.3? It comes with and updated Linux kernel which might change things. Also do you use active or passive mode?

I am on 12.3 since its release and bluetooth is still not working in active mode (only for a couple of hours/days after power toggle).

Should I switch to passive mode?

npasslick commented 4 months ago

@auditdata @StahlTim did you try HAOS 12.3? It comes with and updated Linux kernel which might change things. Also do you use active or passive mode?

I am on 12.3 since its release and bluetooth is still not working in active mode (only for a couple of hours/days after power toggle).

Should I switch to passive mode?

Passive mode should generally work even with the bug (at least that was my workaround until the recent HAOS update), but keep in mind that you will lose functionalities that require active Bluetooth scanning if you have devices that provide those

StahlTim commented 4 months ago

@agners @npasslick My sensors require me to stick with active mode. However, did another power-unplug 2d ago (I think the first time after upgrading to 12.3).

Maybe upgrading and rebooting to 12.3 alone did not fix the issue, but an additional power cycle (actual removing power physically) helped to complete the process.

Will monitor further and report if failing/dropping again.

StahlTim commented 4 months ago

Update: Was on vacation - Bluetooth devices did disconnect again during my absence. Issue still present.

apetryk2 commented 4 months ago

Huh. I have two servers in two locations both running on Raspberry Pi. In one location the issue is fixed. In the other location it is not. Both on the same versions of HA OS and HA.

StahlTim commented 3 months ago

Just reviewed the logs once more, with the latest HAOS, the Bluetooth device is not listed as faulty within the homeassistant GUI, but in the logs, there are several:

hci0 (XX:XX:XX:XX:XX:XX): Successful fall-back to passive scanning mode after active scanning failed (4/4)

These warnings seem to be published every second minute.

github-actions[bot] commented 4 weeks ago

There hasn't been any activity on this issue recently. To keep our backlog manageable we have to clean old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant OS version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

JiDoan commented 4 weeks ago

Unfortunately, my Raspberry Pi 4 has very unstable Bluetooth even on the latest version of Home Assistant OS. Anything we can do to help debug the issue?

image

FlareFlo commented 4 weeks ago

For me, this issue only went away after upgrading to a Pi 5 4gb from a Pi3 B 1gb

Xavantex commented 1 week ago

Had similiar issues, but I upgraded from 11.5. I finally got mad enough to do a full backup and rebuild the SD card with a new image, the bluetooth reappeared without issue. EMQX on the other hand took a beating, but that was quickly solved :). So might be something inherent of the upgrading process?