bluetooth.service issue with SAP on bullseye

[seamusdemora]

Describe the bug

bluetoothctl fails to work properly in pairing to another raspberry pi

Steps to reproduce the behaviour

Raspberry Pi bullseye Lite:
Set up two RPi - both bullseye Lite (I used RPi4B & RPi3A)
start bluetoothctl & attempt to pair them.

This fails repeatedly

Device (s)

Raspberry Pi 4 Mod. B, Other

System

FOR THE RPI4B:

System Information

Raspberry Pi 4 Model B Rev 1.1
PRETTY_NAME="Raspbian GNU/Linux 11 (bullseye)"
NAME="Raspbian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"

Raspberry Pi reference 2023-02-21
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, f2d385517c9631f2ded876deb1115725d0c75995, stage2

Linux rpi4b 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr 3 17:24:16 BST 2023 aarch64 GNU/Linux
Revision : b03111
Serial : 100000006cce8fc1
Model : Raspberry Pi 4 Model B Rev 1.1
Throttled flag : throttled=0x50000
Camera : supported=0 detected=0, libcamera interfaces=0

Videocore information

Mar 17 2023 10:50:39
Copyright (c) 2012 Broadcom
version 82f3750a65fadae9a38077e3c2e217ad158c8d54 (clean) (release) (start)

alloc failures: 0
compactions: 0
legacy block fails: 0

Filesystem information

Filesystem 1K-blocks Used Available Use% Mounted on
/dev/root 61086684 5721244 52837096 10% /
devtmpfs 682572 0 682572 0% /dev
tmpfs 946796 0 946796 0% /dev/shm
tmpfs 378720 2072 376648 1% /run
tmpfs 5120 4 5116 1% /run/lock
/dev/mmcblk0p1 261106 53088 208018 21% /boot
//SynologyNAS-1/rpi_share 28107205512 2755285764 25351919748 10% /mnt/SynologyNAS/rpi_share
tmpfs 189356 0 189356 0% /run/user/1000

Filename Type Size Used Priority
/var/swap file 102396 0 -2

Package version information

raspberrypi-ui-mods:
Installed: (none)
raspberrypi-sys-mods:
Installed: 20230510~bullseye
openbox:
Installed: (none)
lxpanel:
Installed: (none)
pcmanfm:
Installed: (none)
rpd-plym-splash:
Installed: (none)

Networking Information

eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet x.x.x.x netmask x.x.x.x broadcast x.x.x.x
inet6 y::y.y.y.y prefixlen 64 scopeid 0x20
ether m.m.m.m txqueuelen 1000 (Ethernet)
RX packets 2936 bytes 378921 (370.0 KiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 342 bytes 48519 (47.3 KiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536
inet x.x.x.x netmask x.x.x.x
inet6 ::1 prefixlen 128 scopeid 0x10
loop txqueuelen 1000 (Local Loopback)
RX packets 21 bytes 3266 (3.1 KiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 21 bytes 3266 (3.1 KiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500
inet x.x.x.x netmask x.x.x.x broadcast x.x.x.x
inet6 y::y.y.y.y prefixlen 64 scopeid 0x20
ether m.m.m.m txqueuelen 1000 (Ethernet)
RX packets 2180 bytes 267843 (261.5 KiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 133 bytes 17931 (17.5 KiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

USB Information

/: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/4p, 5000M
/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
|__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M

Display Information

Running (F)KMS, console

/sys/class/drm/card1-HDMI-A-1

/sys/class/drm/card1-HDMI-A-2

/sys/class/drm/card1-Writeback-1

Connector 0 (32) HDMI-A-1 (disconnected)
Encoder 0 (31) TMDS
Connector 1 (42) HDMI-A-2 (disconnected)
Encoder 1 (41) TMDS

HDMI0: HDMI_HOTPLUG = 0x00000000
HDMI1: HDMI_HOTPLUG = 0x00000000

/sys/kernel/debug/dri/1/state:
plane[47]: plane-0
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=0
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[64]: plane-1
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=0
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[75]: plane-2
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=0
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[86]: plane-3
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=0
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[97]: plane-4
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=0
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[108]: plane-5
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=0
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[119]: plane-6
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=1
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[129]: plane-7
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=2
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[139]: plane-8
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=3
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[149]: plane-9
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=4
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[159]: plane-10
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=5
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[169]: plane-11
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=6
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[179]: plane-12
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=7
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[189]: plane-13
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=8
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[199]: plane-14
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=9
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[209]: plane-15
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=a
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[219]: plane-16
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=b
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[229]: plane-17
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=c
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[239]: plane-18
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=d
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[249]: plane-19
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=e
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[259]: plane-20
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=f
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[269]: plane-21
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=10
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[279]: plane-22
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=11
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[289]: plane-23
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=11
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[299]: plane-24
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=11
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[309]: plane-25
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=11
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[319]: plane-26
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=11
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
plane[329]: plane-27
crtc=(null)
fb=0
crtc-pos=0x0+0+0
src-pos=0.000000x0.000000+0.000000+0.000000
rotation=1
normalized-zpos=11
color-encoding=ITU-R BT.709 YCbCr
color-range=YCbCr limited range
crtc[57]: txp
enable=0
active=0
self_refresh_active=0
planes_changed=0
mode_changed=0
active_changed=0
connectors_changed=0
color_mgmt_changed=0
plane_mask=0
connector_mask=0
encoder_mask=0
mode: "": 0 0 0 0 0 0 0 0 0 0 0x0 0x0
crtc[74]: pixelvalve-0
enable=0
active=0
self_refresh_active=0
planes_changed=0
mode_changed=0
active_changed=0
connectors_changed=0
color_mgmt_changed=0
plane_mask=0
connector_mask=0
encoder_mask=0
mode: "": 0 0 0 0 0 0 0 0 0 0 0x0 0x0
crtc[85]: pixelvalve-1
enable=0
active=0
self_refresh_active=0
planes_changed=0
mode_changed=0
active_changed=0
connectors_changed=0
color_mgmt_changed=0
plane_mask=0
connector_mask=0
encoder_mask=0
mode: "": 0 0 0 0 0 0 0 0 0 0 0x0 0x0
crtc[96]: pixelvalve-2
enable=0
active=0
self_refresh_active=0
planes_changed=0
mode_changed=0
active_changed=0
connectors_changed=0
color_mgmt_changed=0
plane_mask=0
connector_mask=0
encoder_mask=0
mode: "": 0 0 0 0 0 0 0 0 0 0 0x0 0x0
crtc[107]: pixelvalve-4
enable=0
active=0
self_refresh_active=0
planes_changed=0
mode_changed=0
active_changed=0
connectors_changed=0
color_mgmt_changed=0
plane_mask=0
connector_mask=0
encoder_mask=0
mode: "": 0 0 0 0 0 0 0 0 0 0 0x0 0x0
crtc[118]: pixelvalve-3
enable=0
active=0
self_refresh_active=0
planes_changed=0
mode_changed=0
active_changed=0
connectors_changed=0
color_mgmt_changed=0
plane_mask=0
connector_mask=0
encoder_mask=0
mode: "": 0 0 0 0 0 0 0 0 0 0 0x0 0x0
connector[32]: HDMI-A-1
crtc=(null)
self_refresh_aware=0
max_requested_bpc=8
connector[42]: HDMI-A-2
crtc=(null)
self_refresh_aware=0
max_requested_bpc=8
connector[63]: Writeback-1
crtc=(null)
self_refresh_aware=0
max_requested_bpc=0

config.txt

arm_64bit=1
arm_boost=1
arm_freq=1500
audio_pwm_mode=514
camera_auto_detect=1
config_hdmi_boost=5
core_freq=500
core_freq_min=200
disable_commandline_tags=2
disable_l2cache=1
disable_overscan=1
display_auto_detect=1
display_hdmi_rotate=-1
display_lcd_rotate=-1
dvfs=3
enable_gic=1
force_eeprom_read=1
force_pwm_open=1
framebuffer_ignore_alpha=1
framebuffer_swap=1
gpu_freq=500
gpu_freq_min=250
init_uart_clock=0x2dc6c00
lcd_framerate=60
mask_gpu_interrupt0=3072
mask_gpu_interrupt1=25635
max_framebuffers=2
over_voltage_avs=-17500
pause_burst_frames=1
program_serial_random=1
total_mem=2048
hdmi_force_cec_address:0=65535
hdmi_force_cec_address:1=65535
hdmi_pixel_freq_limit:0=0x11e1a300
hdmi_pixel_freq_limit:1=0x11e1a300
device_tree=-
overlay_prefix=overlays/
hdmi_cvt:0=
hdmi_cvt:1=
hdmi_edid_filename:0=
hdmi_edid_filename:1=
hdmi_timings:0=
hdmi_timings:1=

cmdline.txt

coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_hdmi=0 smsc95xx.macaddr=DC:A6:32:02:F0:95 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 console=ttyS0,115200 console=tty1 root=PARTUUID=0ae4a626-02 rootfstype=ext4 fsck.repair=yes rootwait

raspi-gpio settings

BANK0 (GPIO 0 to 27):
GPIO 0: level=1 fsel=4 alt=0 func=SDA0 pull=UP
GPIO 1: level=1 fsel=4 alt=0 func=SCL0 pull=UP
GPIO 2: level=1 fsel=0 func=INPUT pull=UP
GPIO 3: level=1 fsel=0 func=INPUT pull=UP
GPIO 4: level=1 fsel=0 func=INPUT pull=UP
GPIO 5: level=1 fsel=0 func=INPUT pull=UP
GPIO 6: level=1 fsel=0 func=INPUT pull=UP
GPIO 7: level=1 fsel=0 func=INPUT pull=UP
GPIO 8: level=1 fsel=0 func=INPUT pull=UP
GPIO 9: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 10: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 11: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 12: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 13: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 14: level=1 fsel=0 func=INPUT pull=NONE
GPIO 15: level=1 fsel=0 func=INPUT pull=UP
GPIO 16: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 17: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 18: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 19: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 20: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 21: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 22: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 23: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 24: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 25: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 26: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 27: level=0 fsel=0 func=INPUT pull=DOWN
BANK1 (GPIO 28 to 45):
GPIO 28: level=1 fsel=2 alt=5 func=RGMII_MDIO pull=UP
GPIO 29: level=0 fsel=2 alt=5 func=RGMII_MDC pull=DOWN
GPIO 30: level=0 fsel=7 alt=3 func=CTS0 pull=UP
GPIO 31: level=0 fsel=7 alt=3 func=RTS0 pull=NONE
GPIO 32: level=1 fsel=7 alt=3 func=TXD0 pull=NONE
GPIO 33: level=1 fsel=7 alt=3 func=RXD0 pull=UP
GPIO 34: level=1 fsel=7 alt=3 func=SD1_CLK pull=NONE
GPIO 35: level=1 fsel=7 alt=3 func=SD1_CMD pull=UP
GPIO 36: level=1 fsel=7 alt=3 func=SD1_DAT0 pull=UP
GPIO 37: level=1 fsel=7 alt=3 func=SD1_DAT1 pull=UP
GPIO 38: level=1 fsel=7 alt=3 func=SD1_DAT2 pull=UP
GPIO 39: level=1 fsel=7 alt=3 func=SD1_DAT3 pull=UP
GPIO 40: level=0 fsel=4 alt=0 func=PWM1_0 pull=NONE
GPIO 41: level=0 fsel=4 alt=0 func=PWM1_1 pull=NONE
GPIO 42: level=0 fsel=1 func=OUTPUT pull=UP
GPIO 43: level=1 fsel=0 func=INPUT pull=UP
GPIO 44: level=1 fsel=0 func=INPUT pull=UP
GPIO 45: level=1 fsel=0 func=INPUT pull=UP
BANK2 (GPIO 46 to 53):
GPIO 46: level=0 fsel=0 func=INPUT pull=UP
GPIO 47: level=0 fsel=0 func=INPUT pull=UP
GPIO 48: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 49: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 50: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 51: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 52: level=0 fsel=0 func=INPUT pull=DOWN
GPIO 53: level=0 fsel=0 func=INPUT pull=DOWN

vcdbg log messages

004296.525: arasan: arasan_emmc_open
004296.696: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 400000 max: 400000 delay: 5
004401.463: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 400000 max: 400000 delay: 5
004401.552: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 390000 max: 400000 delay: 5
004430.428: arasan: arasan_emmc_set_clock C0: 0x00800f06 C1: 0x000e0207 emmc: 200000000 actual: 50000000 div: 0x00000002 target: 50000000 min: 0 max: 50000000 delay: 1
004436.796: brfs: File read: /mfs/sd/config.txt
004437.886: brfs: File read: 2385 bytes
004459.534: HDMI0:EDID error reading EDID block 0 attempt 0
004460.551: HDMI0:EDID giving up on reading EDID block 0
004472.367: HDMI1:EDID error reading EDID block 0 attempt 0
004473.382: HDMI1:EDID giving up on reading EDID block 0
004475.430: brfs: File read: /mfs/sd/config.txt
005269.577: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
005272.096: *** Restart logging
005272.116: brfs: File read: 2385 bytes
005277.646: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
005278.662: hdmi: HDMI0:EDID giving up on reading EDID block 0
005283.706: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
005284.723: hdmi: HDMI0:EDID giving up on reading EDID block 0
005284.739: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
005289.780: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
005290.796: hdmi: HDMI1:EDID giving up on reading EDID block 0
005295.836: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
005296.850: hdmi: HDMI1:EDID giving up on reading EDID block 0
005296.868: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
005296.884: HDMI0: hdmi_pixel_encoding: 300000000
005296.896: HDMI1: hdmi_pixel_encoding: 300000000
005297.233: kernel=
005304.177: dtb_file 'bcm2711-rpi-4-b.dtb'
005311.802: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb
005311.820: Loaded 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xcd71
005325.064: brfs: File read: 52593 bytes
005343.038: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
005418.561: brfs: File read: 2347 bytes
005421.948: brfs: File read: /mfs/sd/config.txt
005422.444: dtparam: audio=on
005427.027: brfs: File read: 2385 bytes
005447.606: brfs: File read: /mfs/sd/overlays/vc4-kms-v3d-pi4.dtbo
005508.909: Loaded overlay 'vc4-kms-v3d'
005508.993: dtparam: i2c_vc=on
005674.260: brfs: File read: 3913 bytes
005683.579: brfs: File read: /mfs/sd/overlays/i2c-rtc.dtbo
005718.339: Loaded overlay 'i2c-rtc'
005718.351: dtparam: ds3231=true
005719.137: dtparam: i2c0=true
005721.621: dtparam: wakeup-source=true
005725.082: dtparam: act_led_trigger=mmc0
005737.189: dtparam: act_led_activelow=off
005749.059: dtparam: pwr_led_trigger=default-on
005761.179: dtparam: pwr_led_activelow=off
005798.805: brfs: File read: 8092 bytes
005801.472: brfs: File read: /mfs/sd/cmdline.txt
005801.509: Read command line from file 'cmdline.txt':
005801.520: 'console=serial0,115200 console=tty1 root=PARTUUID=0ae4a626-02 rootfstype=ext4 fsck.repair=yes rootwait'
005912.384: brfs: File read: 102 bytes
006646.017: brfs: File read: /mfs/sd/kernel8.img
006646.036: Loaded 'kernel8.img' to 0x80000 size 0x7d6bd0
007819.462: Kernel relocated to 0x200000
007819.477: Device tree loaded to 0x2eff2c00 (size 0xd398)
007824.566: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
009738.610: vchiq_core: vchiq_init_state: slot_zero = 0xcf000000, is_master = 1

dmesg log

[ 0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[ 0.000000] Linux version 6.1.21-v8+ (dom@buildbot) (aarch64-linux-gnu-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1642 SMP PREEMPT Mon Apr 3 17:24:16 BST 2023
[ 0.000000] random: crng init done
[ 0.000000] Machine model: Raspberry Pi 4 Model B Rev 1.1
[ 0.000000] efi: UEFI not found.
[ 0.000000] Reserved memory: created CMA memory pool at 0x000000000ec00000, size 512 MiB
[ 0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[ 0.000000] Zone ranges:
[ 0.000000] DMA [mem 0x0000000000000000-0x000000003fffffff]
[ 0.000000] DMA32 [mem 0x0000000040000000-0x000000007fffffff]
[ 0.000000] Normal empty
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000000000-0x000000003b3fffff]
[ 0.000000] node 0: [mem 0x0000000040000000-0x000000007fffffff]
[ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000007fffffff]
[ 0.000000] On node 0, zone DMA32: 19456 pages in unavailable ranges
[ 0.000000] percpu: Embedded 29 pages/cpu s78504 r8192 d32088 u118784
[ 0.000000] pcpu-alloc: s78504 r8192 d32088 u118784 alloc=29*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Detected PIPT I-cache on CPU0
[ 0.000000] CPU features: detected: Spectre-v2
[ 0.000000] CPU features: detected: Spectre-v3a
[ 0.000000] CPU features: detected: Spectre-v4
[ 0.000000] CPU features: detected: Spectre-BHB
[ 0.000000] CPU features: kernel page table isolation forced ON by KASLR
[ 0.000000] CPU features: detected: Kernel page table isolation (KPTI)
[ 0.000000] CPU features: detected: ARM erratum 1742098
[ 0.000000] CPU features: detected: ARM errata 1165522, 1319367, or 1530923
[ 0.000000] alternatives: applying boot alternatives
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 496944
[ 0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_hdmi=0 smsc95xx.macaddr=m.m.m.m vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 console=ttyS0,115200 console=tty1 root=PARTUUID=0ae4a626-02 rootfstype=ext4 fsck.repair=yes rootwait
[ 0.000000] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[ 0.000000] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[ 0.000000] software IO TLB: area num 4.
[ 0.000000] software IO TLB: mapped [mem 0x0000000037400000-0x000000003b400000] (64MB)
[ 0.000000] Memory: 1365148K/2019328K available (11776K kernel code, 2106K rwdata, 3688K rodata, 4160K init, 1077K bss, 129892K reserved, 524288K cma-reserved)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] ftrace: allocating 39744 entries in 156 pages
[ 0.000000] ftrace: allocated 156 pages with 4 groups
[ 0.000000] trace event string verifier disabled
[ 0.000000] rcu: Preemptible hierarchical RCU implementation.
[ 0.000000] rcu: RCU event tracing is enabled.
[ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[ 0.000000] Trampoline variant of Tasks RCU enabled.
[ 0.000000] Rude variant of Tasks RCU enabled.
[ 0.000000] Tracing variant of Tasks RCU enabled.
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[ 0.000000] Root IRQ handler: gic_handle_irq
[ 0.000000] GIC: Using split EOI/Deactivate mode
[ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[ 0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[ 0.000001] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[ 0.000307] Console: colour dummy device 80x25
[ 0.000894] printk: console [tty1] enabled
[ 0.000960] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=216000)
[ 0.001001] pid_max: default: 32768 minimum: 301
[ 0.001143] LSM: Security Framework initializing
[ 0.001340] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
[ 0.001395] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
[ 0.002673] cgroup: Disabling memory control group subsystem
[ 0.004918] cblist_init_generic: Setting adjustable number of callback queues.
[ 0.004953] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 0.005143] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 0.005334] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 0.005780] rcu: Hierarchical SRCU implementation.
[ 0.005805] rcu: Max phase no-delay instances is 1000.
[ 0.007124] EFI services will not be available.
[ 0.007658] smp: Bringing up secondary CPUs ...
[ 0.008810] Detected PIPT I-cache on CPU1
[ 0.008964] CPU1: Booted secondary processor 0x0000000001 [0x410fd083]
[ 0.010097] Detected PIPT I-cache on CPU2
[ 0.010219] CPU2: Booted secondary processor 0x0000000002 [0x410fd083]
[ 0.011319] Detected PIPT I-cache on CPU3
[ 0.011441] CPU3: Booted secondary processor 0x0000000003 [0x410fd083]
[ 0.011587] smp: Brought up 1 node, 4 CPUs
[ 0.011677] SMP: Total of 4 processors activated.
[ 0.011698] CPU features: detected: 32-bit EL0 Support
[ 0.011717] CPU features: detected: 32-bit EL1 Support
[ 0.011739] CPU features: detected: CRC32 instructions
[ 0.011881] CPU: All CPU(s) started at EL2
[ 0.011959] alternatives: applying system-wide alternatives
[ 0.013707] devtmpfs: initialized
[ 0.025617] Enabled cp15_barrier support
[ 0.025684] Enabled setend support
[ 0.025917] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[ 0.025970] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[ 0.039062] pinctrl core: initialized pinctrl subsystem
[ 0.039974] DMI not present or invalid.
[ 0.040728] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[ 0.044264] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations
[ 0.044582] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[ 0.045539] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[ 0.045648] audit: initializing netlink subsys (disabled)
[ 0.045926] audit: type=2000 audit(0.044:1): state=initialized audit_enabled=0 res=1
[ 0.046537] thermal_sys: Registered thermal governor 'step_wise'
[ 0.046628] cpuidle: using governor menu
[ 0.047024] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[ 0.047237] ASID allocator initialised with 32768 entries
[ 0.047412] Serial: AMBA PL011 UART driver
[ 0.061258] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[ 0.084321] raspberrypi-firmware soc:firmware: Attached to firmware from 2023-03-17T10:50:39, variant start
[ 0.088334] raspberrypi-firmware soc:firmware: Firmware hash is 82f3750a65fadae9a38077e3c2e217ad158c8d54
[ 0.104266] KASLR enabled
[ 0.142272] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1
[ 0.148067] SCSI subsystem initialized
[ 0.148340] usbcore: registered new interface driver usbfs
[ 0.148413] usbcore: registered new interface driver hub
[ 0.148491] usbcore: registered new device driver usb
[ 0.148892] usb_phy_generic phy: supply vcc not found, using dummy regulator
[ 0.149134] usb_phy_generic phy: dummy supplies not allowed for exclusive requests
[ 0.149508] pps_core: LinuxPPS API ver. 1 registered
[ 0.149533] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti giometti@linux.it
[ 0.149574] PTP clock support registered
[ 0.150710] vgaarb: loaded
[ 0.151427] clocksource: Switched to clocksource arch_sys_counter
[ 1.310363] VFS: Disk quotas dquot_6.6.0
[ 1.310484] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 1.310688] FS-Cache: Loaded
[ 1.310975] CacheFiles: Loaded
[ 1.322089] NET: Registered PF_INET protocol family
[ 1.322512] IP idents hash table entries: 32768 (order: 6, 262144 bytes, linear)
[ 1.325573] tcp_listen_portaddr_hash hash table entries: 1024 (order: 2, 16384 bytes, linear)
[ 1.325638] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
[ 1.325678] TCP established hash table entries: 16384 (order: 5, 131072 bytes, linear)
[ 1.325817] TCP bind hash table entries: 16384 (order: 7, 524288 bytes, linear)
[ 1.326377] TCP: Hash tables configured (established 16384 bind 16384)
[ 1.326593] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear)
[ 1.326655] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear)
[ 1.326900] NET: Registered PF_UNIX/PF_LOCAL protocol family
[ 1.327700] RPC: Registered named UNIX socket transport module.
[ 1.327733] RPC: Registered udp transport module.
[ 1.327753] RPC: Registered tcp transport module.
[ 1.327772] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 1.327806] PCI: CLS 0 bytes, default 64
[ 1.330383] hw perfevents: enabled with armv8_cortex_a72 PMU driver, 7 counters available
[ 1.330789] kvm [1]: IPA Size Limit: 44 bits
[ 1.332167] kvm [1]: vgic interrupt IRQ9
[ 1.332416] kvm [1]: Hyp mode initialized successfully
[ 1.334625] Initialise system trusted keyrings
[ 1.335020] workingset: timestamp_bits=46 max_order=19 bucket_order=0
[ 1.342572] zbud: loaded
[ 1.345478] NFS: Registering the id_resolver key type
[ 1.345544] Key type id_resolver registered
[ 1.345565] Key type id_legacy registered
[ 1.345691] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[ 1.345720] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[ 1.347155] Key type asymmetric registered
[ 1.347187] Asymmetric key parser 'x509' registered
[ 1.347285] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[ 1.347638] io scheduler mq-deadline registered
[ 1.347667] io scheduler kyber registered
[ 1.349803] irq_brcmstb_l2: registered L2 intc (/soc/interrupt-controller@7ef00100, parent irq: 27)
[ 1.358581] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[ 1.358650] brcm-pcie fd500000.pcie: No bus range found for /scb/pcie@7d500000, using [bus 00-ff]
[ 1.358755] brcm-pcie fd500000.pcie: MEM 0x0600000000..0x063fffffff -> 0x00c0000000
[ 1.358855] brcm-pcie fd500000.pcie: IB MEM 0x0000000000..0x007fffffff -> 0x0400000000
[ 1.359910] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[ 1.359943] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 1.359972] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff])
[ 1.360062] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[ 1.360328] pci 0000:00:00.0: PME# supported from D0 D3hot
[ 1.364153] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[ 1.364443] pci_bus 0000:01: supply vpcie3v3 not found, using dummy regulator
[ 1.364642] pci_bus 0000:01: supply vpcie3v3aux not found, using dummy regulator
[ 1.364766] pci_bus 0000:01: supply vpcie12v not found, using dummy regulator
[ 1.413524] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC)
[ 1.413704] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[ 1.413841] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[ 1.414331] pci 0000:01:00.0: PME# supported from D0 D3cold
[ 1.415030] pci_bus 0000:01: busn_res: [bus 01-ff] end is updated to 01
[ 1.415088] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[ 1.415122] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[ 1.415178] pci 0000:00:00.0: PCI bridge to [bus 01]
[ 1.415210] pci 0000:00:00.0: bridge window [mem 0x600000000-0x6000fffff]
[ 1.428611] iproc-rng200 fe104000.rng: hwrng registered
[ 1.429219] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[ 1.430797] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[ 1.444017] brd: module loaded
[ 1.452799] loop: module loaded
[ 1.453669] Loading iSCSI transport class v2.0-870.
[ 1.458972] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000
[ 1.519588] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus
[ 1.520774] usbcore: registered new interface driver r8152
[ 1.520864] usbcore: registered new interface driver lan78xx
[ 1.520936] usbcore: registered new interface driver smsc95xx
[ 1.522546] pci 0000:00:00.0: enabling device (0000 -> 0002)
[ 1.522599] xhci_hcd 0000:01:00.0: enabling device (0000 -> 0002)
[ 1.522734] xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 1.522777] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[ 1.523589] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000e40000000890
[ 1.524293] xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 1.524327] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[ 1.524363] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[ 1.524745] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.01
[ 1.524781] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.524809] usb usb1: Product: xHCI Host Controller
[ 1.524831] usb usb1: Manufacturer: Linux 6.1.21-v8+ xhci-hcd
[ 1.524853] usb usb1: SerialNumber: 0000:01:00.0
[ 1.525611] hub 1-0:1.0: USB hub found
[ 1.525730] hub 1-0:1.0: 1 port detected
[ 1.526704] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.01
[ 1.526741] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.526767] usb usb2: Product: xHCI Host Controller
[ 1.526790] usb usb2: Manufacturer: Linux 6.1.21-v8+ xhci-hcd
[ 1.526812] usb usb2: SerialNumber: 0000:01:00.0
[ 1.527539] hub 2-0:1.0: USB hub found
[ 1.527647] hub 2-0:1.0: 4 ports detected
[ 1.529362] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 1.529715] dwc_otg: FIQ enabled
[ 1.529726] dwc_otg: NAK holdoff enabled
[ 1.529736] dwc_otg: FIQ split-transaction FSM enabled
[ 1.529755] Module dwc_common_port init
[ 1.530318] usbcore: registered new interface driver uas
[ 1.530464] usbcore: registered new interface driver usb-storage
[ 1.530710] mousedev: PS/2 mouse device common for all mice
[ 1.536872] sdhci: Secure Digital Host Controller Interface driver
[ 1.536910] sdhci: Copyright(c) Pierre Ossman
[ 1.537606] sdhci-pltfm: SDHCI platform and OF driver helper
[ 1.541253] ledtrig-cpu: registered to indicate activity on CPUs
[ 1.541628] hid: raw HID events driver (C) Jiri Kosina
[ 1.541843] usbcore: registered new interface driver usbhid
[ 1.541868] usbhid: USB HID core driver
[ 1.550724] NET: Registered PF_PACKET protocol family
[ 1.550882] Key type dns_resolver registered
[ 1.552225] registered taskstats version 1
[ 1.552317] Loading compiled-in X.509 certificates
[ 1.553219] Key type .fscrypt registered
[ 1.553246] Key type fscrypt-provisioning registered
[ 1.569027] uart-pl011 fe201000.serial: there is not valid maps for state default
[ 1.569784] uart-pl011 fe201000.serial: cts_event_workaround enabled
[ 1.569973] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 36, base_baud = 0) is a PL011 rev2
[ 1.579133] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[ 1.579707] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[ 1.581043] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[ 1.581077] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[ 1.609424] of_cfs_init
[ 1.609582] of_cfs_init: OK
[ 1.643008] mmc0: SDHCI controller on fe340000.mmc [fe340000.mmc] using ADMA
[ 1.643362] Waiting for root device PARTUUID=0ae4a626-02...
[ 1.695088] mmc1: new high speed SDIO card at address 0001
[ 1.746475] mmc0: new ultra high speed DDR50 SDXC card at address aaaa
[ 1.747526] mmcblk0: mmc0:aaaa SH64G 59.5 GiB
[ 1.750889] mmcblk0: p1 p2
[ 1.751578] mmcblk0: mmc0:aaaa SH64G 59.5 GiB (quirks 0x00004000)
[ 1.770607] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Quota mode: none.
[ 1.770748] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 1.777080] devtmpfs: mounted
[ 1.779563] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[ 1.785360] Freeing unused kernel memory: 4160K
[ 1.785576] Run /sbin/init as init process
[ 1.785597] with arguments:
[ 1.785606] /sbin/init
[ 1.785616] with environment:
[ 1.785625] HOME=/
[ 1.785634] TERM=linux
[ 1.938125] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[ 1.938187] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 1.938215] usb 1-1: Product: USB2.0 Hub
[ 1.940089] hub 1-1:1.0: USB hub found
[ 1.940589] hub 1-1:1.0: 4 ports detected
[ 2.120182] systemd[1]: System time before build time, advancing clock.
[ 2.321118] NET: Registered PF_INET6 protocol family
[ 2.323067] Segment Routing with IPv6
[ 2.323129] In-situ OAM (IOAM) with IPv6
[ 2.387831] systemd[1]: systemd 247.3-7+rpi1+deb11u2 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)
[ 2.388943] systemd[1]: Detected architecture arm64.
[ 2.402681] systemd[1]: Set hostname to .
[ 3.328130] systemd[1]: Queued start job for default target Multi-User System.
[ 3.347009] systemd[1]: Created slice system-getty.slice.
[ 3.349079] systemd[1]: Created slice system-modprobe.slice.
[ 3.350551] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[ 3.351949] systemd[1]: Created slice User and Session Slice.
[ 3.352889] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[ 3.353726] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 3.355272] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 3.356095] systemd[1]: Reached target Local Encrypted Volumes.
[ 3.356828] systemd[1]: Reached target Paths.
[ 3.357385] systemd[1]: Reached target Slices.
[ 3.357911] systemd[1]: Reached target Swap.
[ 3.360346] systemd[1]: Listening on Syslog Socket.
[ 3.361572] systemd[1]: Listening on fsck to fsckd communication Socket.
[ 3.362431] systemd[1]: Listening on initctl Compatibility Named Pipe.
[ 3.364197] systemd[1]: Listening on Journal Audit Socket.
[ 3.365453] systemd[1]: Listening on Journal Socket (/dev/log).
[ 3.366918] systemd[1]: Listening on Journal Socket.
[ 3.372137] systemd[1]: Listening on udev Control Socket.
[ 3.373510] systemd[1]: Listening on udev Kernel Socket.
[ 3.375010] systemd[1]: Condition check resulted in Huge Pages File System being skipped.
[ 3.399970] systemd[1]: Mounting POSIX Message Queue File System...
[ 3.405305] systemd[1]: Mounting RPC Pipe File System...
[ 3.411499] systemd[1]: Mounting Kernel Debug File System...
[ 3.417414] systemd[1]: Mounting Kernel Trace File System...
[ 3.418481] systemd[1]: Condition check resulted in Kernel Module supporting RPCSEC_GSS being skipped.
[ 3.426717] systemd[1]: Starting Restore / save the current clock...
[ 3.432787] systemd[1]: Starting Set the console keyboard layout...
[ 3.439404] systemd[1]: Starting Create list of static device nodes for the current kernel...
[ 3.445850] systemd[1]: Starting Load Kernel Module configfs...
[ 3.452703] systemd[1]: Starting Load Kernel Module drm...
[ 3.459330] systemd[1]: Starting Load Kernel Module fuse...
[ 3.473152] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[ 3.478375] systemd[1]: Starting File System Check on Root Device...
[ 3.488918] systemd[1]: Starting Journal Service...
[ 3.500395] systemd[1]: Starting Load Kernel Modules...
[ 3.506482] systemd[1]: Starting Coldplug All udev Devices...
[ 3.531260] systemd[1]: Mounted POSIX Message Queue File System.
[ 3.544395] systemd[1]: Mounted RPC Pipe File System.
[ 3.560111] systemd[1]: Mounted Kernel Debug File System.
[ 3.561477] systemd[1]: Mounted Kernel Trace File System.
[ 3.568070] systemd[1]: Finished Restore / save the current clock.
[ 3.575822] systemd[1]: Finished Create list of static device nodes for the current kernel.
[ 3.582703] fuse: init (API version 7.37)
[ 3.585391] systemd[1]: modprobe@configfs.service: Succeeded.
[ 3.587396] systemd[1]: Finished Load Kernel Module configfs.
[ 3.637119] i2c_dev: i2c /dev entries driver
[ 3.644300] systemd[1]: Mounting Kernel Configuration File System...
[ 3.661018] systemd[1]: Started File System Check Daemon to report status.
[ 3.679082] systemd[1]: modprobe@drm.service: Succeeded.
[ 3.691756] systemd[1]: Finished Load Kernel Module drm.
[ 3.694475] systemd[1]: modprobe@fuse.service: Succeeded.
[ 3.696166] systemd[1]: Finished Load Kernel Module fuse.
[ 3.699915] systemd[1]: Finished Load Kernel Modules.
[ 3.701354] systemd[1]: Mounted Kernel Configuration File System.
[ 3.728173] systemd[1]: Mounting FUSE Control File System...
[ 3.736539] systemd[1]: Starting Apply Kernel Variables...
[ 3.753324] systemd[1]: Mounted FUSE Control File System.
[ 3.794251] systemd[1]: Finished Apply Kernel Variables.
[ 3.813188] systemd[1]: Finished File System Check on Root Device.
[ 3.843029] systemd[1]: Starting Remount Root and Kernel File Systems...
[ 3.862142] systemd[1]: Started Journal Service.
[ 3.998283] EXT4-fs (mmcblk0p2): re-mounted. Quota mode: none.
[ 4.081112] systemd-journald[144]: Received client request to flush runtime journal.
[ 4.113443] systemd-journald[144]: File /var/log/journal/8b0b373987db4d96b6cd943078278af3/system.journal corrupted or uncleanly shut down, renaming and replacing.
[ 5.183299] mc: Linux media interface: v0.10
[ 5.312444] videodev: Linux video capture interface: v2.00
[ 5.426047] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.431398] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[ 5.431478] [vc_sm_connected_init]: start
[ 5.466019] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.475170] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.515802] [vc_sm_connected_init]: installed successfully
[ 5.525644] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.529967] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.551077] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.573969] rpivid_hevc: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.574207] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.610240] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.616270] rpivid feb10000.codec: Device registered as /dev/video19
[ 5.620075] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.623885] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[ 5.630866] bcm2835_audio bcm2835_audio: card created with 8 channels
[ 5.694572] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[ 5.694632] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[ 5.696826] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[ 5.697398] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[ 5.702129] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[ 5.702609] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[ 5.702645] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[ 5.702668] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[ 5.702687] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[ 5.702704] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[ 5.703178] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[ 5.703238] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[ 5.709802] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20
[ 5.710191] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[ 5.710236] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[ 5.710356] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21
[ 5.710902] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22
[ 5.711492] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23
[ 5.711530] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[ 5.711552] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[ 5.711570] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[ 5.711587] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[ 5.711859] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[ 5.725890] bcm2835-codec bcm2835-codec: Device registered as /dev/video18
[ 5.725973] bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx
[ 5.734900] bcm2835-codec bcm2835-codec: Device registered as /dev/video31
[ 5.734982] bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image
[ 5.763718] brcmstb-i2c fef04500.i2c: @97500hz registered in polling mode
[ 5.764639] brcmstb-i2c fef09500.i2c: @97500hz registered in polling mode
[ 5.888314] i2c i2c-22: Added multiplexed i2c bus 0
[ 5.892170] i2c i2c-22: Added multiplexed i2c bus 10
[ 5.952692] [drm] Initialized v3d 1.0.0 20180419 for fec00000.v3d on minor 0
[ 6.642908] vc4-drm gpu: bound fe400000.hvs (ops vc4_hvs_ops [vc4])
[ 6.721645] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[ 6.730527] Registered IR keymap rc-cec
[ 6.733557] rc rc0: vc4-hdmi-0 as /devices/platform/soc/fef00700.hdmi/rc/rc0
[ 6.733816] input: vc4-hdmi-0 as /devices/platform/soc/fef00700.hdmi/rc/rc0/input0
[ 6.785860] vc4-drm gpu: bound fef00700.hdmi (ops vc4_hdmi_ops [vc4])
[ 6.791315] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[ 6.812495] cfg80211: loaded regulatory.db is malformed or signature is missing/invalid
[ 6.832486] Registered IR keymap rc-cec
[ 6.832780] rc rc1: vc4-hdmi-1 as /devices/platform/soc/fef05700.hdmi/rc/rc1
[ 6.833257] input: vc4-hdmi-1 as /devices/platform/soc/fef05700.hdmi/rc/rc1/input1
[ 6.843739] vc4-drm gpu: bound fef05700.hdmi (ops vc4_hdmi_ops [vc4])
[ 6.844502] vc4-drm gpu: bound fe004000.txp (ops vc4_txp_ops [vc4])
[ 6.845000] vc4-drm gpu: bound fe206000.pixelvalve (ops vc4_crtc_ops [vc4])
[ 6.845494] vc4-drm gpu: bound fe207000.pixelvalve (ops vc4_crtc_ops [vc4])
[ 6.845954] vc4-drm gpu: bound fe20a000.pixelvalve (ops vc4_crtc_ops [vc4])
[ 6.846256] vc4-drm gpu: bound fe216000.pixelvalve (ops vc4_crtc_ops [vc4])
[ 6.846673] vc4-drm gpu: bound fec12000.pixelvalve (ops vc4_crtc_ops [vc4])
[ 6.932542] [drm] Initialized vc4 0.0.0 20140616 for gpu on minor 1
[ 6.936902] vc4-drm gpu: [drm] Cannot find any crtc or sizes
[ 7.164001] 8021q: 802.1Q VLAN Support v1.8
[ 7.190402] uart-pl011 fe201000.serial: no DMA platform data
[ 7.374479] Adding 102396k swap on /var/swap. Priority:-2 extents:1 across:102396k SSFS
[ 7.375175] bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay)
[ 7.380729] bcmgenet fd580000.ethernet eth0: Link is Down
[ 7.540392] brcmfmac: F1 signature read @0x18000000=0x15264345
[ 7.576063] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[ 7.585738] usbcore: registered new interface driver brcmfmac
[ 7.878132] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Nov 1 2021 00:37:25 version 7.45.241 (1a2f2fa CY) FWID 01-703fd60
[ 8.055594] rtc-ds1307 0-0068: 'wakeup-source' is set, request for an IRQ is disabled!
[ 8.066538] rtc-ds1307 0-0068: registered as rtc0
[ 8.069080] rtc-ds1307 0-0068: setting system clock to 2024-04-03T09:14:36 UTC (1712135676)
[ 8.309809] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 11.455594] bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx
[ 11.455636] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 11.903608] hwmon hwmon1: Undervoltage detected!
[ 14.169837] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 14.855495] Bluetooth: Core ver 2.22
[ 14.855602] NET: Registered PF_BLUETOOTH protocol family
[ 14.855608] Bluetooth: HCI device and connection manager initialized
[ 14.855628] Bluetooth: HCI socket layer initialized
[ 14.855637] Bluetooth: L2CAP socket layer initialized
[ 14.855651] Bluetooth: SCO socket layer initialized
[ 14.865583] Bluetooth: HCI UART driver ver 2.3
[ 14.865606] Bluetooth: HCI UART protocol H4 registered
[ 14.865674] Bluetooth: HCI UART protocol Three-wire (H5) registered
[ 14.865865] Bluetooth: HCI UART protocol Broadcom registered
[ 15.188244] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[ 15.188263] Bluetooth: BNEP filters: protocol multicast
[ 15.188279] Bluetooth: BNEP socket layer initialized
[ 15.194133] Bluetooth: MGMT ver 1.22
[ 15.203582] NET: Registered PF_ALG protocol family
[ 17.633209] Key type cifs.spnego registered
[ 17.633235] Key type cifs.idmap registered
[ 17.634988] CIFS: Attempting to mount \SynologyNAS-1\rpi_share
[ 17.951480] hwmon hwmon1: Voltage normalised

EEPROM

BOOTLOADER: up to date
CURRENT: Wed 11 Jan 17:40:52 UTC 2023 (1673458852)
LATEST: Wed 11 Jan 17:40:52 UTC 2023 (1673458852)
RELEASE: default (/lib/firmware/raspberrypi/bootloader/default)
Use raspi-config to change the release.

VL805_FW: Dedicated VL805 EEPROM
VL805: up to date
CURRENT: 000138c0
LATEST: 000138c0

Logs

SEE "Additional context"

Additional context

$ systemctl status bluetooth.service
● bluetooth.service - Bluetooth service
Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
Active: active (running) since Wed 2024-04-03 09:14:43 UTC; 2min 6s ago
Docs: man:bluetoothd(8)
Main PID: 590 (bluetoothd)
Status: "Running"
Tasks: 1 (limit: 1599)
CPU: 70ms
CGroup: /system.slice/bluetooth.service
└─590 /usr/libexec/bluetooth/bluetoothd

Apr 03 09:14:43 rpi4b systemd[1]: Starting Bluetooth service...
Apr 03 09:14:43 rpi4b bluetoothd[590]: Bluetooth daemon 5.55
Apr 03 09:14:43 rpi4b systemd[1]: Started Bluetooth service.
Apr 03 09:14:43 rpi4b bluetoothd[590]: Starting SDP server
Apr 03 09:14:43 rpi4b bluetoothd[590]: Bluetooth management interface 1.22 initialized
Apr 03 09:14:43 rpi4b bluetoothd[590]: profiles/sap/server.c:sap_server_register() Sap driver initialization failed.
Apr 03 09:14:43 rpi4b bluetoothd[590]: sap-server: Operation not permitted (1)
Apr 03 09:14:43 rpi4b bluetoothd[590]: Failed to set privacy: Rejected (0x0b)

[seamusdemora]

I add this to the "For What It's Worth" column:

It's from my RPi5 (bookworm Lite) Pi. Seems that there are also issues with BT configuration in bookworm also:

$ systemctl status bluetooth.service
● bluetooth.service - Bluetooth service
     Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; preset: enabled)
     Active: active (running) since Tue 2024-04-02 04:39:19 UTC; 1 day 17h ago
       Docs: man:bluetoothd(8)
   Main PID: 1305 (bluetoothd)
     Status: "Running"
      Tasks: 1 (limit: 4451)
        CPU: 46ms
     CGroup: /system.slice/bluetooth.service
             └─1305 /usr/libexec/bluetooth/bluetoothd

Apr 02 04:39:19 raspberrypi5 bluetoothd[1305]: profiles/audio/mcp.c:mcp_init() D-Bus experimental not enabled
Apr 02 04:39:19 raspberrypi5 bluetoothd[1305]: src/plugin.c:plugin_init() Failed to init mcp plugin
Apr 02 04:39:19 raspberrypi5 bluetoothd[1305]: profiles/audio/bap.c:bap_init() D-Bus experimental not enabled
Apr 02 04:39:19 raspberrypi5 bluetoothd[1305]: src/plugin.c:plugin_init() Failed to init bap plugin
Apr 02 04:39:19 raspberrypi5 bluetoothd[1305]: Bluetooth management interface 1.22 initialized
Apr 02 04:39:19 raspberrypi5 bluetoothd[1305]: profiles/sap/server.c:sap_server_register() Sap driver initialization failed.
Apr 02 04:39:19 raspberrypi5 bluetoothd[1305]: sap-server: Operation not permitted (1)
Apr 02 04:39:19 raspberrypi5 bluetoothd[1305]: Failed to set privacy: Rejected (0x0b)
Apr 02 04:39:24 raspberrypi5 bluetoothd[1305]: src/adv_monitor.c:btd_adv_monitor_power_down() Unexpected NULL btd_adv_monitor_manager object upon power down
Apr 02 04:58:38 raspberrypi5 bluetoothd[1305]: src/service.c:btd_service_connect() a2dp-sink profile connect failed for B8:F6:53:AE:13:F1: Protocol not available