Hey, thanks for this project! Since the pHAT DAC has been discontinu

Maybe related. <a class="issue-link js-issue-link" data-error-text="

Here is the full /var/log/dmesg. <div class="snippet-clipboard-content notranslate

Frame reassembly failed (Pirate Audio),about spietika/meta-rpi-bt-dac

Comments (13)

kspeakman commented on July 24, 2024

Maybe related.

raspberrypi/firmware#1150

from meta-rpi-bt-dac.

spietika commented on July 24, 2024

The comments in the linked issue do seem quite similar. Would you mind attaching the whole log (e.g. from dmesg) to give a bit more context in case there are other prints that might be related.

from meta-rpi-bt-dac.

kspeakman commented on July 24, 2024

Here is the full /var/log/dmesg.

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.88 (oe-user@oe-host) (gcc version 8.3.0 (GCC)) #1 Sun Apr 12 08:29:28 UTC 2020
[    0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi Zero W Rev 1.1
[    0.000000] Memory policy: Data cache writeback
[    0.000000] cma: Reserved 256 MiB at 0x0bc00000
[    0.000000] On node 0 totalpages: 114688
[    0.000000]   Normal zone: 1008 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 114688 pages, LIFO batch:31
[    0.000000] random: get_random_bytes called from start_kernel+0x94/0x498 with crng_init=0
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 113680
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 cma=256M video=HDMI-A-1:1280x1024M@60,margin_left=0,margin_right=0,margin_top=0,margin_bottom=0 smsc95xx.macaddr=B8:27:EB:40:72:07 vc_mem.mem_base=0x1ec00000 vc_mem.mem_size=0x20000000  dwc_otg.lpm_enable=0  root=/dev/mmcblk0p2 rootfstype=ext4 rootwait
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 179220K/458752K available (7424K kernel code, 658K rwdata, 2312K rodata, 468K init, 800K bss, 17388K reserved, 262144K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xdc800000 - 0xff800000   ( 560 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xdc000000   ( 448 MB)
[    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
[    0.000000]       .text : 0x(ptrval) - 0x(ptrval)   (7426 kB)
[    0.000000]       .init : 0x(ptrval) - 0x(ptrval)   ( 468 kB)
[    0.000000]       .data : 0x(ptrval) - 0x(ptrval)   ( 659 kB)
[    0.000000]        .bss : 0x(ptrval) - 0x(ptrval)   ( 801 kB)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] ftrace: allocating 26756 entries in 79 pages
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000034] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns
[    0.000101] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns
[    0.000232] bcm2835: system timer (irq = 27)
[    0.000663] Console: colour dummy device 80x30
[    0.001275] console [tty0] enabled
[    0.001366] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
[    0.060418] pid_max: default: 32768 minimum: 301
[    0.060977] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.061038] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.062512] CPU: Testing write buffer coherency: ok
[    0.063909] Setting up static identity map for 0x8200 - 0x8238
[    0.065385] devtmpfs: initialized
[    0.077030] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
[    0.077533] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.077611] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.113630] pinctrl core: initialized pinctrl subsystem
[    0.115342] NET: Registered protocol family 16
[    0.118638] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.126612] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
[    0.126688] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.126859] Serial: AMBA PL011 UART driver
[    0.131070] bcm2835-mbox 2000b880.mailbox: mailbox enabled
[    0.180048] bcm2835-dma 20007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.182930] SCSI subsystem initialized
[    0.183269] usbcore: registered new interface driver usbfs
[    0.183416] usbcore: registered new interface driver hub
[    0.183683] usbcore: registered new device driver usb
[    0.201334] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-10-21 16:50, variant start
[    0.211361] raspberrypi-firmware soc:firmware: Firmware hash is 509fb1bcb9511d963439429724a6f6dfb8251107
[    0.223860] clocksource: Switched to clocksource timer
[    0.336297] VFS: Disk quotas dquot_6.6.0
[    0.336489] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.336853] FS-Cache: Loaded
[    0.337257] CacheFiles: Loaded
[    0.338111] simple-framebuffer 1e97a000.framebuffer: framebuffer at 0x1e97a000, 0x280000 bytes, mapped to 0x(ptrval)
[    0.338192] simple-framebuffer 1e97a000.framebuffer: format=r5g6b5, mode=1280x1024x16, linelength=2560
[    0.351035] Console: switching to colour frame buffer device 160x64
[    0.362163] simple-framebuffer 1e97a000.framebuffer: fb0: simplefb registered!
[    0.382373] NET: Registered protocol family 2
[    0.383982] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes)
[    0.384243] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    0.384466] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
[    0.384693] TCP: Hash tables configured (established 4096 bind 4096)
[    0.385006] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.385170] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.385728] NET: Registered protocol family 1
[    0.386965] RPC: Registered named UNIX socket transport module.
[    0.387128] RPC: Registered udp transport module.
[    0.387235] RPC: Registered tcp transport module.
[    0.387339] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.388711] hw perfevents: no irqs for PMU, sampling events not supported
[    0.388945] hw perfevents: enabled with armv6_1176 PMU driver, 3 counters available
[    0.393418] Initialise system trusted keyrings
[    0.394238] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[    0.410428] FS-Cache: Netfs 'nfs' registered for caching
[    0.411949] NFS: Registering the id_resolver key type
[    0.412153] Key type id_resolver registered
[    0.412259] Key type id_legacy registered
[    0.412381] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.418449] Key type asymmetric registered
[    0.418601] Asymmetric key parser 'x509' registered
[    0.418826] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.419471] io scheduler noop registered
[    0.419603] io scheduler deadline registered
[    0.420313] io scheduler cfq registered (default)
[    0.420446] io scheduler mq-deadline registered
[    0.425580] io scheduler kyber registered
[    0.435394] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    0.443631] bcm2835-rng 20104000.rng: hwrng registered
[    0.449404] vc-mem: phys_addr:0x00000000 mem_base=0x1ec00000 mem_size:0x20000000(512 MiB)
[    0.455874] vc-sm: Videocore shared memory driver
[    0.461720] gpiomem-bcm2835 20200000.gpiomem: Initialised: Registers at 0x20200000
[    0.488203] brd: module loaded
[    0.507331] loop: module loaded
[    0.513410] Loading iSCSI transport class v2.0-870.
[    0.519655] usbcore: registered new interface driver smsc95xx
[    0.524788] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.557874] dwc_otg 20980000.usb: base=(ptrval)
[    0.763272] Core Release: 2.80a
[    0.768352] Setting default values for core params
[    0.773273] Finished setting default values for core params
[    0.978622] Using Buffer DMA mode
[    0.983610] Periodic Transfer Interrupt Enhancement - disabled
[    0.988542] Multiprocessor Interrupt Enhancement - disabled
[    0.993397] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.998328] Dedicated Tx FIFOs mode
[    1.004365] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = cbd04000 dma = 0x4bd04000 len=9024
[    1.009449] FIQ FSM acceleration enabled for :
[    1.009449] Non-periodic Split Transactions
[    1.009449] Periodic Split Transactions
[    1.009449] High-Speed Isochronous Endpoints
[    1.009449] Interrupt/Control Split Transaction hack enabled
[    1.033512] dwc_otg: Microframe scheduler enabled
[    1.033784] WARN::hcd_init_fiq:457: FIQ on core 0
[    1.038613] WARN::hcd_init_fiq:458: FIQ ASM at c056dd88 length 36
[    1.043356] WARN::hcd_init_fiq:497: MPHI regs_base at dc810000
[    1.048153] dwc_otg 20980000.usb: DWC OTG Controller
[    1.052911] dwc_otg 20980000.usb: new USB bus registered, assigned bus number 1
[    1.057728] dwc_otg 20980000.usb: irq 56, io mem 0x00000000
[    1.062440] Init: Port Power? op_state=1
[    1.067073] Init: Power Port (0)
[    1.072008] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    1.076760] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.081389] usb usb1: Product: DWC OTG Controller
[    1.086030] usb usb1: Manufacturer: Linux 4.19.88 dwc_otg_hcd
[    1.090593] usb usb1: SerialNumber: 20980000.usb
[    1.096417] hub 1-0:1.0: USB hub found
[    1.101218] hub 1-0:1.0: 1 port detected
[    1.107127] dwc_otg: FIQ enabled
[    1.107142] dwc_otg: NAK holdoff enabled
[    1.107149] dwc_otg: FIQ split-transaction FSM enabled
[    1.107170] Module dwc_common_port init
[    1.107736] usbcore: registered new interface driver usb-storage
[    1.113027] mousedev: PS/2 mouse device common for all mice
[    1.119842] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    1.125196] bcm2835-cpufreq: min=700000 max=1000000
[    1.130761] sdhci: Secure Digital Host Controller Interface driver
[    1.135546] sdhci: Copyright(c) Pierre Ossman
[    1.140872] mmc-bcm2835 20300000.mmcnr: could not get clk, deferring probe
[    1.146544] sdhost-bcm2835 20202000.mmc: could not get clk, deferring probe
[    1.151639] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.157201] ledtrig-cpu: registered to indicate activity on CPUs
[    1.162131] hidraw: raw HID events driver (C) Jiri Kosina
[    1.167155] usbcore: registered new interface driver usbhid
[    1.171833] usbhid: USB HID core driver
[    1.177883] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    1.184759] [vc_sm_connected_init]: start
[    1.194046] [vc_sm_connected_init]: end - returning 0
[    1.200799] Initializing XFRM netlink socket
[    1.205782] NET: Registered protocol family 17
[    1.210669] Key type dns_resolver registered
[    1.217496] registered taskstats version 1
[    1.222250] Loading compiled-in X.509 certificates
[    1.236618] uart-pl011 20201000.serial: cts_event_workaround enabled
[    1.241510] 20201000.serial: ttyAMA0 at MMIO 0x20201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    1.248822] 20215040.serial: ttyS0 at MMIO 0x0 (irq = 53, base_baud = 31250000) is a 16550
[    1.256690] mmc-bcm2835 20300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    1.261541] mmc-bcm2835 20300000.mmcnr: DMA channel allocated
[    1.295332] sdhost: log_buf @ (ptrval) (4bd03000)
[    1.324188] Indeed it is in host mode hprt0 = 00021501
[    1.396924] random: fast init done
[    1.402571] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    1.409719] of_cfs_init
[    1.435385] of_cfs_init: OK
[    1.442240] Waiting for root device /dev/mmcblk0p2...
[    1.447360] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    1.453999] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.460530] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    1.468624] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    1.534896] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.539891] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    1.544870] Indeed it is in host mode hprt0 = 00001101
[    1.610872] mmc0: new high speed SDHC card at address aaaa
[    1.618609] mmcblk0: mmc0:aaaa SL16G 14.8 GiB
[    1.631712]  mmcblk0: p1 p2 p3
[    1.675849] mmc1: new high speed SDIO card at address 0001
[    1.698488] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.703375] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.719835] devtmpfs: mounted
[    1.729263] Freeing unused kernel memory: 468K
[    1.734134] This architecture does not have kernel memory protection.
[    1.738812] Run /sbin/init as init process
[    1.784773] usb 1-1: New USB device found, idVendor=1a40, idProduct=0101, bcdDevice= 1.00
[    1.789727] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.794564] usb 1-1: Product: USB2.0 HUB
[    1.801654] hub 1-1:1.0: USB hub found
[    1.807641] hub 1-1:1.0: 4 ports detected
[    2.234007] usb 1-1.1: new low-speed USB device number 3 using dwc_otg
[    2.448751] EXT4-fs (mmcblk0p3): recovery complete
[    2.450199] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null)
[    2.486107] usb 1-1.1: New USB device found, idVendor=0566, idProduct=3055, bcdDevice= 1.20
[    2.486146] usb 1-1.1: New USB device strings: Mfr=0, Product=2, SerialNumber=0
[    2.486169] usb 1-1.1: Product: USB KeyBoard
[    2.500002] input: USB KeyBoard as /devices/platform/soc/20980000.usb/usb1/1-1/1-1.1/1-1.1:1.0/0003:0566:3055.0001/input/input0
[    2.565050] hid-generic 0003:0566:3055.0001: input,hidraw0: USB HID v1.11 Keyboard [USB KeyBoard] on usb-20980000.usb-1.1/input0
[    2.576633] input: USB KeyBoard Consumer Control as /devices/platform/soc/20980000.usb/usb1/1-1/1-1.1/1-1.1:1.1/0003:0566:3055.0002/input/input1
[    2.644377] input: USB KeyBoard System Control as /devices/platform/soc/20980000.usb/usb1/1-1/1-1.1/1-1.1:1.1/0003:0566:3055.0002/input/input2
[    2.645085] hid-generic 0003:0566:3055.0002: input,hidraw1: USB HID v1.11 Device [USB KeyBoard] on usb-20980000.usb-1.1/input1
[    2.685418] udevd[87]: starting version 3.2.7
[    2.719669] random: udevd: uninitialized urandom read (16 bytes read)
[    2.720929] random: udevd: uninitialized urandom read (16 bytes read)
[    2.722301] random: udevd: uninitialized urandom read (16 bytes read)
[    2.742825] udevd[87]: specified group 'kvm' unknown
[    2.793822] udevd[88]: starting eudev-3.2.7
[    2.844064] usb 1-1.2: new low-speed USB device number 4 using dwc_otg
[    3.081494] usb 1-1.2: New USB device found, idVendor=046d, idProduct=c05a, bcdDevice=63.00
[    3.081536] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    3.081559] usb 1-1.2: Product: USB Optical Mouse
[    3.081578] usb 1-1.2: Manufacturer: Logitech
[    3.090345] input: Logitech USB Optical Mouse as /devices/platform/soc/20980000.usb/usb1/1-1/1-1.2/1-1.2:1.0/0003:046D:C05A.0003/input/input3
[    3.092084] hid-generic 0003:046D:C05A.0003: input,hidraw2: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-20980000.usb-1.2/input0
[    3.283585] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    3.286957] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    3.286998] [vc_sm_connected_init]: start
[    3.309190] media: Linux media interface: v0.10
[    3.335687] [vc_sm_connected_init]: installed successfully
[    3.491396] videodev: Linux video capture interface: v2.00
[    3.661074] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    3.662536] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    3.680943] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    3.777668] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    3.838354] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    3.838439] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    3.861423] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    3.861503] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    3.896594] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    3.896677] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    4.359254] snd-rpi-simple soc:sound: pcm5102a-hifi <-> 20203000.i2s mapping ok
[    4.396973] vc4_hdmi 20902000.hdmi: ASoC: Failed to create component debugfs directory
[    4.417382] vc4_hdmi 20902000.hdmi: vc4-hdmi-hifi <-> 20902000.hdmi mapping ok
[    4.423946] vc4-drm soc:gpu: bound 20902000.hdmi (ops vc4_hdmi_ops [vc4])
[    4.424644] vc4-drm soc:gpu: bound 20806000.vec (ops vc4_vec_ops [vc4])
[    4.425101] vc4-drm soc:gpu: bound 20004000.txp (ops vc4_txp_ops [vc4])
[    4.425382] vc4-drm soc:gpu: bound 20400000.hvs (ops vc4_hvs_ops [vc4])
[    4.426492] vc4-drm soc:gpu: bound 20206000.pixelvalve (ops vc4_crtc_ops [vc4])
[    4.427540] vc4-drm soc:gpu: bound 20207000.pixelvalve (ops vc4_crtc_ops [vc4])
[    4.428641] vc4-drm soc:gpu: bound 20807000.pixelvalve (ops vc4_crtc_ops [vc4])
[    4.513698] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    4.607193] vc4-drm soc:gpu: bound 20c00000.v3d (ops vc4_v3d_ops [vc4])
[    4.614174] checking generic (1e97a000 280000) vs hw (0 ffffffff)
[    4.614235] fb: switching to vc4drmfb from simple
[    4.619033] Console: switching to colour dummy device 80x30
[    4.627992] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 0
[    4.628032] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    4.628051] [drm] Driver supports precise vblank timestamp query.
[    4.640306] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    4.644868] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[    4.644922] cfg80211: failed to load regulatory.db
[    4.694626] Console: switching to colour frame buffer device 160x64
[    4.694871] vc4-drm soc:gpu: fb0: DRM emulated frame buffer device
[    4.804010] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[    4.814761] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[    4.815236] usbcore: registered new interface driver brcmfmac
[    5.063778] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[    5.080863] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: May  2 2019 02:39:18 version 7.45.98.83 (r714225 CY) FWID 01-e539531f
[    5.937711] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)

from meta-rpi-bt-dac.

spietika commented on July 24, 2024

I dont't see any obvious problems in the logs. It seems you some USB peripherals connected (mouse / keyboard?). Does disconnecting all other peripherals have any effect on the issue? In the linked issue, there was a mention that the bluetooth serial communication does not have flow control, so at least in principle long irq delays from other devices could cause the BT communication to go out of sync. Though, this is probably a long-shot.

You could also try the previous release (https://github.com/spietika/meta-rpi-bt-dac/releases/tag/v0.3) which does not have HD audio and thus transfers less data.

from meta-rpi-bt-dac.

kspeakman commented on July 24, 2024

I tried with only power and line out connected with 0.4. Still same issue.

The 0.3 image gives the same errors but it keeps playing. Additionally it gives these two warnings on the console before the bluetooth errors start.

random: crng init done
random: 2 urandom warning(s) missed due to ratelimiting

Edit: I flashed back and forth between 0.3 and 0.4 multiple times, and tried different combinations of things plugged in. I actually cannot get USB to work at all in 0.3.

I wonder if the additional AAC step does not gracefully handle the bluetooth failures. Because the same errors look to be there in about the same quantity in both versions. Usually 0.4 stops immediately if it plays sound at all, but I have had it play as long as a few seconds. For now I will use 0.3.

Any further steps I can do to help troubleshoot?

from meta-rpi-bt-dac.

spietika commented on July 24, 2024

I upgraded the project to newer Yocto release (Dunfell) which also bumps the kernel, bluetooth stack etc. versions. It would be interesting to see if the newer versions show similar behavior.

https://github.com/spietika/meta-rpi-bt-dac/releases/tag/v0.5

from meta-rpi-bt-dac.

kspeakman commented on July 24, 2024

0.5 is quite problematic. It takes about 15 seconds before bluetooth tries to connect. Then bluetooth takes another 5+ seconds. And I cannot get it to reliably repeat the same behavior.

Usually I start a song on my phone and no sound comes out. The message below appears on the console.

/urs/bin/bluealsa: Activating RTP mark bit quirk workaround

Other times, it would play for 0 to 5 seconds and cut out, similar to the 0.4 behavior. It started giving the same bluetooth errors (frame reassembly failed). After them there was a continual spam of errors. These errors do not appear to be recorded in /var/log/messages. The last ones are below.

/usr/bin/bluealsa: AAC decode frame error: Parse error
...
/usr/bin/bluealsa: AAC buffer fill error: Unknown error

The buffer fill error will keep spamming as long as the phone keeps playing. The behavior does not trigger consistently, so I had to keep trying and immediately stop the music to even see the decode frame error before the buffer fill errors pushed it off the screen. If we ignore the new error spam, the observed behavior is still quite similar to 0.4 in this case. But the majority of the time 0.5 does not play for me at all.

from meta-rpi-bt-dac.

spietika commented on July 24, 2024

Okay, these logs provided a good hint, since they are all coming from bluealsa. I checked the bluez-alsa project (https://github.com/Arkq/bluez-alsa) that provides bluealsa, and it turns out the project has taken major steps forward from the version 1.4.0 that was in use here. Browsing through the commits between 1.4.0 and 3.0.0, there seems to be dozens of fixes done.

I made a new build with the latest bluez-alsa:
https://github.com/spietika/meta-rpi-bt-dac/releases/tag/v0.5.1

from meta-rpi-bt-dac.

kspeakman commented on July 24, 2024

0.5.1 experiences:

First boot. I connect and hit play. No sound comes out. Here are the errors:

  <2 frame reassembly errors>
/usr/bin/bluealsa: E: AAC decode Frame error: Invalid codebook
Bluetooth: hci0: last event is not cmd complete (0x00)
Bluetooth: hci0: invalid read key size response
Bluetooth: hci0: Frame reassembly failed (-84)
Bluetooth: hci0: ACL packet for unknown connection handle 926
  <12 frame reassembly errors>
Bluetooth: hci0: ACL packet for unknown connection handle 1182
  <17 frame reassembly errors>
Bluetooth: hci0: ACL packet for unknown connection handle 65280
  <22 frame reassembly errors>
/usr/bin/bluealsa: W: Missing RTP packet: 45 != 23

Second boot (I also switch my phone's bluetooth off and on), it reconnects to my phone. I hit play. No sound comes out. I stop, wait ten seconds, and hit play again. No sound. These are the messages:

<1st play>
/usr/bin/bluealsa: W: Activating RTP mark bit quirk workaround
<2nd play>
/usr/bin/bluealsa: W: Missing RTP packet: 1 != 573
/usr/bin/bluealsa: W: Activating RTP mark bit quirk workaround

Each attempt to play emits the mark bit quirk message. If I attempt to play again too soon there is no message. The Missing RTP message is rare. The same behavior happens on subsequent reboots and when I disconnect and reconnect bt from my phone.

This version still takes 15+ seconds to get booted. Whereas 0.3 takes 5.

None of the above errors are being sent to /var/log/messages. But for reference, I have made a gist of all the logs after trying to play a few times. Note that the gists show USB devices connected because it was necessary to get the logs. But prior tests were run with only power, line out and HDMI connected (so I could make observations).

from meta-rpi-bt-dac.

spietika commented on July 24, 2024

I looked in to the Bluetooth UART and it seems that while earlier Raspberry Pi version did not have the flow control connected, the RPi Zero does have them. So I modified the Bluetooth init to enable the flow control. This change is available in 0.5.2 version.

https://github.com/spietika/meta-rpi-bt-dac/releases/tag/v0.5.2

from meta-rpi-bt-dac.

kspeakman commented on July 24, 2024

It works!

It gives the mark bit quirk workaround message when I play, so that one must be informational and benign.

Boot and reconnect takes about 20 seconds total. 0.3 might still be preferable for that reason. Although 0.5.2 sounds really good!

from meta-rpi-bt-dac.

spietika commented on July 24, 2024

Great! I'll need to look into the increased boot time. Probably related to the Yocto update.

One final question. Did the prebuilt images work with Pirate Audio DAC as is or did you have to change anything? I could update the README to mention that as well.

Thanks!

from meta-rpi-bt-dac.

kspeakman commented on July 24, 2024

Yes, the prebuilt images worked with Pirate Audio as is. I just flashed the image and booted. Of course the display and buttons on the pirate audio are not utilized. But that was expected.

from meta-rpi-bt-dac.

Frame reassembly failed (Pirate Audio) about meta-rpi-bt-dac HOT 13 CLOSED

Comments (13)

Related Issues (6)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent