Bug to report with I2S DAC

Geogaddi · August 13, 2020, 1:04pm

Hi there,

In relation to [SOLVED] Volumio 2.246 failed open Alsa where Darmur was kind enough to assist me I have to report a bug that is affecting my HiFiBerry Digi+ Pro Pi Hat in relation to a full, complete shutdown of the Pi4 and I’m pretty sure it’s Volumio software related.

Please see above, it is telling me “Error ALSA…”
This happens each and EVERY time that I fully shut down the Pi4 (I’m using an AUKRU Power Supply) and I switch the device down fully.

Every time I either unplug the device or fully shut the system down I get the error message, which I understand to be the system telling me that I’ve chosen the wrong I2S DAC. But as you can clearly see from attached image I am not!

Basically every time I either power off just the Pi4 or turn every thing off at the mains (which I do every night as we’re prone to powercuts all of the time where I live) I have to perform this painful ritual of pressing random buttons until it finally decides to work.

No rhyme or reason here…
Sometimes turning off I2S dac, restarting, turning it back on again, restarting will work. Sometimes it wont.
Sometimes changing the DAC to a random other, restarting, picking the Digi+ Pro, restarting will work. Sometimes it wont.
Sometimes going to /dev and slapping the Enable SSH a few times then restarting works, sometimes it doesn’t.

I’m using CoAxial and my new cable just landed this morning which is top quality! After dancing the dance a few times it has been working totally fine today with no issues; but as soon as I power off / back on again, please see attached image.

It’s kinda driving me a little insane and sadly I have to point this to being a Volumio issue. As I have a stack of SD Cards I quickly flashed HiFiBerryOS to a little 64gb card I had knocking around and it works with this DAC every time. Sadly HiFiBerryOS is painfully basic and can’t handle locally stored files on the SD-Card as well as Volumio (using a 256GB Card to store my 200gb FLAC collection).

I’m in a situation where leaving it on all the time isn’t a viable option, any help much appreciated. Thanks!

Darmur · August 14, 2020, 8:08pm

it looks like your DAC is not initialized properly when you get this error message.

Not being initialized properly, it’s not mapped properly by ALSA and Volumio does not find it where it is supposed to be (card2 = HW:2,0)

could you please try to post the log of the following command when you get this error message"

dmesg

Geogaddi · August 15, 2020, 11:21am

Hello again Darmur,

Thanks for replying you’re a very helpful guy.
Hope the following log is what you’re after.

Starting Live Log…
info: ------------------------------ 26ms
info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
info: CoreCommandRouter::volumioPlay
UNSET VOLATILE
info: CoreStateMachine::play index undefined
info: CoreStateMachine::setConsumeUpdateService undefined
info: CorePlayQueue::getTrack 0
info: CoreStateMachine::startPlaybackTimer
info: CorePlayQueue::getTrack 0

info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update

error: updateQueue error: null
info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info: ------------------------------ 5ms

error: ControllerMpd::pushError: TypeError: Cannot read property ‘split’ of undefined
info: ------------------------------ 10ms
info: ------------------------------ 7ms
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0

info: CoreStateMachine::syncState stateService pause
info: CoreStateMachine::syncState currentStatus stop
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 20ms

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 0

info: CoreStateMachine::syncState stateService pause
info: CoreStateMachine::syncState currentStatus stop
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioPushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: ------------------------------ 25ms

Darmur · August 15, 2020, 2:58pm

Hi @Geogaddi,

I think this is the log of Volumio itself, could you please post the log of dmesg ? This is required for getting error message from the DAC driver

Geogaddi · August 15, 2020, 5:07pm

Sorry I’m a little new to Volumio, how would I generate this report?

Darmur · August 15, 2020, 5:24pm

No problem, it’s quite simple. Just enable SSH and type the command dmesg after you get the error message, then copy/paste the log here

Geogaddi · August 15, 2020, 5:47pm

Thanka @Darmur, I’ve actually got it working at the mo, but I’ll post that log as soon as it goes again.

Geogaddi · August 17, 2020, 10:21am

volumio@volumio:~$ dmesg

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.118-v7l+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1311 SMP Mon Apr 27 14:26:42 BST 2020
[    0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.2
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 64 MiB at 0x000000003a000000
[    0.000000] On node 0 totalpages: 1024000
[    0.000000]   DMA zone: 1728 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 196608 pages, LIFO batch:63
[    0.000000]   HighMem zone: 827392 pages, LIFO batch:63
[    0.000000] random: get_random_bytes called from start_kernel+0xc0/0x4e8 with crng_init=0
[    0.000000] percpu: Embedded 17 pages/cpu s36928 r8192 d24512 u69632
[    0.000000] pcpu-alloc: s36928 r8192 d24512 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 1022272
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 cma=64M bcm2708_fb.fbwidth=1824 bcm2708_fb.fbheight=984 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:77:BB:4C vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  splash quiet plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 console=ttyS0,115200 kgdboc=ttyS0,115200 console=tty1 imgpart=/dev/mmcblk0p2 imgfile=/volumio_current.sqsh elevator=noop rootwait bootdelay=5 logo.nologo vt.global_cursor_default=0 loglevel=0 snd-bcm2835.enable_compat_alsa=1 snd_bcm2835.enable_headphones=1
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 3957848K/4096000K available (8192K kernel code, 690K rwdata, 2420K rodata, 2048K init, 860K bss, 72616K reserved, 65536K cma-reserved, 3244032K highmem)
[    0.000000] Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xf0800000 - 0xff800000   ( 240 MB)
    lowmem  : 0xc0000000 - 0xf0000000   ( 768 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
    modules : 0xbf000000 - 0xbfe00000   (  14 MB)
      .text : 0x(ptrval) - 0x(ptrval)   (10208 kB)
      .init : 0x(ptrval) - 0x(ptrval)   (2048 kB)
      .data : 0x(ptrval) - 0x(ptrval)   ( 691 kB)
       .bss : 0x(ptrval) - 0x(ptrval)   ( 861 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 28928 entries in 85 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] GIC: Using split EOI/Deactivate mode
[    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.000005] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000017] Switching to timer-based delay loop, resolution 18ns
[    0.000247] Console: colour dummy device 80x30
[    0.000269] console [tty1] enabled
[    0.000312] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
[    0.000329] pid_max: default: 32768 minimum: 301
[    0.000597] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000615] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001428] CPU: Testing write buffer coherency: ok
[    0.001834] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.002478] Setting up static identity map for 0x200000 - 0x20003c
[    0.002634] rcu: Hierarchical SRCU implementation.
[    0.003490] smp: Bringing up secondary CPUs ...
[    0.004289] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.005211] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.006080] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.006198] smp: Brought up 1 node, 4 CPUs
[    0.006212] SMP: Total of 4 processors activated (432.00 BogoMIPS).
[    0.006221] CPU: All CPU(s) started in HYP mode.
[    0.006230] CPU: Virtualization extensions available.
[    0.006934] devtmpfs: initialized
[    0.017776] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
[    0.017992] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.018012] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.020163] pinctrl core: initialized pinctrl subsystem
[    0.020961] NET: Registered protocol family 16
[    0.024248] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.025906] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.025916] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.026109] Serial: AMBA PL011 UART driver
[    0.029077] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[    0.050025] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-04-27 14:33, variant start
[    0.060040] raspberrypi-firmware soc:firmware: Firmware hash is 3a8f1793b758d6fb7f375edaa260e069ecd34c88
[    0.102610] bcm2835-dma fe007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.105616] vgaarb: loaded
[    0.105967] SCSI subsystem initialized
[    0.106161] usbcore: registered new interface driver usbfs
[    0.106211] usbcore: registered new interface driver hub
[    0.106307] usbcore: registered new device driver usb
[    0.107805] clocksource: Switched to clocksource arch_sys_counter
[    0.185644] VFS: Disk quotas dquot_6.6.0
[    0.185722] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.185863] FS-Cache: Loaded
[    0.186042] CacheFiles: Loaded
[    0.195377] NET: Registered protocol family 2
[    0.196012] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
[    0.196037] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.196103] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.196173] TCP: Hash tables configured (established 8192 bind 8192)
[    0.196296] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.196324] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.196528] NET: Registered protocol family 1
[    0.197065] RPC: Registered named UNIX socket transport module.
[    0.197075] RPC: Registered udp transport module.
[    0.197084] RPC: Registered tcp transport module.
[    0.197093] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.197107] PCI: CLS 0 bytes, default 64
[    0.197306] Trying to unpack rootfs image as initramfs...
[    1.731204] Freeing initrd memory: 19480K
[    1.739383] hw perfevents: enabled with armv7_cortex_a15 PMU driver, 7 counters available
[    1.741512] Initialise system trusted keyrings
[    1.741713] workingset: timestamp_bits=14 max_order=20 bucket_order=6
[    1.751842] FS-Cache: Netfs 'nfs' registered for caching
[    1.752332] NFS: Registering the id_resolver key type
[    1.752361] Key type id_resolver registered
[    1.752371] Key type id_legacy registered
[    1.752390] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.756878] Key type asymmetric registered
[    1.756889] Asymmetric key parser 'x509' registered
[    1.756999] bounce: pool size: 64 pages
[    1.757042] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    1.757200] io scheduler noop registered (default)
[    1.757211] io scheduler deadline registered
[    1.757370] io scheduler cfq registered
[    1.757381] io scheduler mq-deadline registered
[    1.757390] io scheduler kyber registered
[    1.808033] brcm-pcie fd500000.pcie: dmabounce: initialised - 32768 kB, threshold 0x00000000c0000000
[    1.808054] brcm-pcie fd500000.pcie: could not get clock
[    1.808116] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[    1.808153] brcm-pcie fd500000.pcie:   MEM 0x600000000..0x603ffffff -> 0xf8000000
[    1.867842] brcm-pcie fd500000.pcie: link up, 5.0 Gbps x1 (!SSC)
[    1.868114] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[    1.868130] pci_bus 0000:00: root bus resource [bus 00-01]
[    1.868147] pci_bus 0000:00: root bus resource [mem 0x600000000-0x603ffffff] (bus address [0xf8000000-0xfbffffff])
[    1.868198] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[    1.868337] pci 0000:00:00.0: PME# supported from D0 D3hot
[    1.871107] PCI: bus0: Fast back to back transfers disabled
[    1.871124] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[    1.871338] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[    1.871462] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[    1.871779] pci 0000:01:00.0: PME# supported from D0 D3cold
[    1.874531] PCI: bus1: Fast back to back transfers disabled
[    1.874547] pci_bus 0000:01: busn_res: [bus 01] end is updated to 01
[    1.874594] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[    1.874613] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[    1.874683] pci 0000:00:00.0: PCI bridge to [bus 01]
[    1.874701] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
[    1.874904] pcieport 0000:00:00.0: enabling device (0140 -> 0142)
[    1.875074] pcieport 0000:00:00.0: Signaling PME with IRQ 52
[    1.875239] pcieport 0000:00:00.0: AER enabled with IRQ 52
[    1.875406] pci 0000:01:00.0: enabling device (0140 -> 0142)
[    1.875939] bcm2708_fb soc:fb: FB found 1 display(s)
[    1.913184] Console: switching to colour frame buffer device 228x61
[    1.922373] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 1824x984
[    1.926105] iproc-rng200 fe104000.rng: hwrng registered
[    1.926324] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    1.926846] vc-sm: Videocore shared memory driver
[    1.927249] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[    1.937687] brd: module loaded
[    1.947611] loop: module loaded
[    1.948458] Loading iSCSI transport class v2.0-870.
[    1.950186] libphy: Fixed MDIO Bus: probed
[    1.950609] bcmgenet fd580000.genet: failed to get enet clock
[    1.950624] bcmgenet fd580000.genet: GENET 5.0 EPHY: 0x0000
[    1.950641] bcmgenet fd580000.genet: failed to get enet-wol clock
[    1.950658] bcmgenet fd580000.genet: failed to get enet-eee clock
[    1.950681] bcmgenet: Skipping UMAC reset
[    1.950926] unimac-mdio unimac-mdio.-19: DMA mask not set
[    1.967835] libphy: bcmgenet MII bus: probed
[    2.013587] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus at 0x(ptrval)
[    2.014548] usbcore: registered new interface driver r8152
[    2.014614] usbcore: registered new interface driver lan78xx
[    2.014667] usbcore: registered new interface driver smsc95xx
[    2.014989] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    2.015028] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    2.017721] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000001000000890
[    2.018127] genirq: irq_chip Brcm_MSI did not update eff. affinity mask of irq 53
[    2.018952] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    2.018966] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.018978] usb usb1: Product: xHCI Host Controller
[    2.018990] usb usb1: Manufacturer: Linux 4.19.118-v7l+ xhci-hcd
[    2.019001] usb usb1: SerialNumber: 0000:01:00.0
[    2.019540] hub 1-0:1.0: USB hub found
[    2.019622] hub 1-0:1.0: 1 port detected
[    2.020089] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    2.020111] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    2.020131] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    2.020487] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.19
[    2.020501] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.020512] usb usb2: Product: xHCI Host Controller
[    2.020523] usb usb2: Manufacturer: Linux 4.19.118-v7l+ xhci-hcd
[    2.020535] usb usb2: SerialNumber: 0000:01:00.0
[    2.021017] hub 2-0:1.0: USB hub found
[    2.021097] hub 2-0:1.0: 4 ports detected
[    2.022283] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.022467] dwc_otg: FIQ enabled
[    2.022476] dwc_otg: NAK holdoff enabled
[    2.022486] dwc_otg: FIQ split-transaction FSM enabled
[    2.022498] Module dwc_common_port init
[    2.022704] usbcore: registered new interface driver uas
[    2.022800] usbcore: registered new interface driver usb-storage
[    2.022994] mousedev: PS/2 mouse device common for all mice
[    2.024165] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    2.025801] sdhci: Secure Digital Host Controller Interface driver
[    2.025810] sdhci: Copyright(c) Pierre Ossman
[    2.026219] mmc-bcm2835 fe300000.mmcnr: could not get clk, deferring probe
[    2.026630] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.029741] ledtrig-cpu: registered to indicate activity on CPUs
[    2.029893] hidraw: raw HID events driver (C) Jiri Kosina
[    2.030022] usbcore: registered new interface driver usbhid
[    2.030030] usbhid: USB HID core driver
[    2.031019] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    2.032894] [vc_sm_connected_init]: start
[    2.042676] [vc_sm_connected_init]: end - returning 0
[    2.043806] Initializing XFRM netlink socket
[    2.043836] NET: Registered protocol family 17
[    2.043930] Key type dns_resolver registered
[    2.044487] Registering SWP/SWPB emulation handler
[    2.045088] registered taskstats version 1
[    2.045105] Loading compiled-in X.509 certificates
[    2.052237] uart-pl011 fe201000.serial: cts_event_workaround enabled
[    2.052311] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 34, base_baud = 0) is a PL011 rev2
[    2.057441] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    2.057992] brcmstb_thermal fd5d2200.thermal: registered AVS TMON of-sensor driver
[    2.058647] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    2.058659] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[    2.084693] sdhci-iproc fe340000.emmc2: Linked as a consumer to regulator.3
[    2.084772] sdhci-iproc fe340000.emmc2: Linked as a consumer to regulator.4
[    2.106020] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    2.107627] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.109250] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.112152] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    2.113769] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.116212] mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA
[    2.118564] of_cfs_init
[    2.118650] of_cfs_init: OK
[    2.126418] Freeing unused kernel memory: 2048K
[    2.126833] Run /init as init process
[    2.174337] random: fast init done
[    2.225787] mmc0: new ultra high speed DDR50 SDXC card at address 59b4
[    2.227248] mmcblk0: mmc0:59b4 6aLHR 239 GiB
[    2.229430]  mmcblk0: p1 p2 p3
[    2.232575] mmc1: new high speed SDIO card at address 0001
[    2.282224] initramfs: Booting Volumio for BCM2835
[    2.282378] initramfs: This script mounts rootfs RO with an overlay RW layer.
[    2.305583] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    2.325482] fuse init (API version 7.27)
[    2.326978] initramfs: IMGPART=/dev/mmcblk0p2
[    2.327112] initramfs: IMGFILE=/volumio_current.sqsh
[    2.327319] initramfs: Boot delay (except first time) will be 5 seconds
[    2.327575] initramfs: /dev/mmcblk0p2 not detected,retrying mdev in 5 seconds
[    2.387851] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    2.570472] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[    2.570486] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    2.570498] usb 1-1: Product: USB2.0 Hub
[    2.572396] hub 1-1:1.0: USB hub found
[    2.572718] hub 1-1:1.0: 4 ports detected
[    2.897863] usb 1-1.4: new full-speed USB device number 3 using xhci_hcd
[    2.976808] initramfs: /dev/mmcblk0p2:
[    3.043380] usb 1-1.4: New USB device found, idVendor=1997, idProduct=2433, bcdDevice= 1.03
[    3.043396] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    3.043408] usb 1-1.4: Product: mini keyboard
[    3.043420] usb 1-1.4: Manufacturer:
[    3.053747] input:   mini keyboard as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.0/0003:1997:2433.0001/input/input0
[    3.084496] EXT4-fs (mmcblk0p2): recovery complete
[    3.111772] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    3.113748] initramfs: Doing a 5 second delay here to give kernel load a headstart
[    3.118537] hid-generic 0003:1997:2433.0001: input,hidraw0: USB HID v1.01 Keyboard [  mini keyboard] on usb-0000:01:00.0-1.4/input0
[    3.123953] input:   mini keyboard as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.1/0003:1997:2433.0002/input/input1
[    3.124246] hid-generic 0003:1997:2433.0002: input,hidraw1: USB HID v1.01 Mouse [  mini keyboard] on usb-0000:01:00.0-1.4/input1
[    3.130076] input:   mini keyboard System Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.2/0003:1997:2433.0003/input/input2
[    3.198048] input:   mini keyboard Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.2/0003:1997:2433.0003/input/input3
[    3.198206] hid-generic 0003:1997:2433.0003: input,hidraw2: USB HID v1.01 Device [  mini keyboard] on usb-0000:01:00.0-1.4/input2
[    8.118359] initramfs: Checking for USB updates
[    8.221933] initramfs: No USB device detected (when incorrect, try adding 'bootdelay=5' to your boot cmdline)
[   10.083184] EXT4-fs (mmcblk0p3): recovery complete
[   10.110365] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null)
[   10.116678] initramfs: With Option:
[   10.271130] initramfs: VOLUMIO_VERSION="2.806"
[   10.271273] initramfs: Finish initramfs, continue booting Volumio
[   10.689555] random: systemd: uninitialized urandom read (16 bytes read)
[   10.695919] systemd[1]: systemd 215 running in system mode. (+PAM +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -SECCOMP -APPARMOR)
[   10.696244] systemd[1]: Detected architecture 'arm'.
[   10.819644] NET: Registered protocol family 10
[   10.820874] Segment Routing with IPv6
[   10.821080] systemd[1]: Inserted module 'ipv6'
[   10.830324] systemd[1]: Set hostname to <volumio>.
[   10.932267] random: systemd-sysv-ge: uninitialized urandom read (16 bytes read)
[   11.011499] random: systemd: uninitialized urandom read (16 bytes read)
[   11.088553] systemd[1]: [/lib/systemd/system/mpd.service:18] Unknown lvalue 'ProtectKernelTunables' in section 'Service'
[   11.088604] systemd[1]: [/lib/systemd/system/mpd.service:19] Unknown lvalue 'ProtectControlGroups' in section 'Service'
[   11.088649] systemd[1]: [/lib/systemd/system/mpd.service:20] Unknown lvalue 'ProtectKernelModules' in section 'Service'
[   11.088706] systemd[1]: [/lib/systemd/system/mpd.service:23] Unknown lvalue 'RestrictNamespaces' in section 'Service'
[   11.151891] systemd[1]: Cannot add dependency job for unit display-manager.service, ignoring: Unit display-manager.service failed to load: No such file or directory.
[   11.154411] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
[   11.398699] i2c /dev entries driver
[   11.618515] systemd-udevd[207]: starting version 215
[   11.962029] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[   11.964167] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[   11.964185] [vc_sm_connected_init]: start
[   11.970556] [vc_sm_connected_init]: installed successfully
[   11.971962] rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x0000ffff
[   11.974099] rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00000fff
[   11.979076] rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x0000ffff
[   11.981628] rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x0000ffff
[   11.990147] media: Linux media interface: v0.10
[   12.067905] videodev: Linux video capture interface: v2.00
[   12.152853] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[   12.221560] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[   12.223037] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[   12.262016] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[   12.266919] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[   12.266964] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[   12.271376] snd_bcm2835: unknown parameter 'index' ignored
[   12.275819] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[   12.275852] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[   12.290655] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[   12.290695] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[   12.322798] bcm2835_audio soc:audio: card created with 5 channels
[   12.332014] bcm2835_audio soc:audio: card created with 3 channels
[   12.407327] snd-rpi-wm8804 soc:sound: ASoC: CODEC DAI wm8804-spdif not registered - will retry
[   12.529025] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   12.552186] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   12.555787] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[   12.555806] cfg80211: failed to load regulatory.db
[   12.681076] snd-rpi-wm8804 soc:sound: ASoC: CODEC DAI wm8804-spdif not registered - will retry
[   12.682561] brcmfmac: F1 signature read @0x18000000=0x15264345
[   12.696169] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[   12.702737] usbcore: registered new interface driver brcmfmac
[   12.703913] snd-rpi-wm8804 soc:sound: ASoC: CODEC DAI wm8804-spdif not registered - will retry
[   12.909459] wm8804 1-003b: Linked as a consumer to regulator.1
[   12.910147] wm8804 1-003b: Failed to read device ID: -121
[   12.910430] wm8804: probe of 1-003b failed with error -121
[   13.049363] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[   13.084572] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Mar  2 2020 23:30:41 version 7.45.202 (r724630 CY) FWID 01-72f6ece2
[   13.407602] systemd-journald[186]: Received request to flush runtime journal from PID 1
[   14.954970] bcmgenet: Skipping UMAC reset
[   15.048434] bcmgenet fd580000.genet: configuring instance for external RGMII (no delay)
[   15.089189] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
[   15.923113] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[   16.098055] bcmgenet fd580000.genet eth0: Link is Down
[   16.320078] uart-pl011 fe201000.serial: no DMA platform data
[   16.860229] Bluetooth: Core ver 2.22
[   16.860309] NET: Registered protocol family 31
[   16.860319] Bluetooth: HCI device and connection manager initialized
[   16.860343] Bluetooth: HCI socket layer initialized
[   16.860367] Bluetooth: L2CAP socket layer initialized
[   16.860423] Bluetooth: SCO socket layer initialized
[   16.940392] Bluetooth: HCI UART driver ver 2.3
[   16.940409] Bluetooth: HCI UART protocol H4 registered
[   16.940542] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   16.941860] Bluetooth: HCI UART protocol Broadcom registered
[   18.345876] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   18.345884] Bluetooth: BNEP filters: protocol multicast
[   18.345896] Bluetooth: BNEP socket layer initialized
[   18.397914] random: crng init done
[   18.397922] random: 7 urandom warning(s) missed due to ratelimiting
[   20.247968] bcmgenet fd580000.genet eth0: Link is Up - 1Gbps/Full - flow control rx/tx
[   20.915950] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled

Darmur · August 18, 2020, 8:37am

[   12.407327] snd-rpi-wm8804 soc:sound: ASoC: CODEC DAI wm8804-spdif not registered - will retry

[   12.681076] snd-rpi-wm8804 soc:sound: ASoC: CODEC DAI wm8804-spdif not registered - will retry

[   12.909459] wm8804 1-003b: Linked as a consumer to regulator.1
[   12.910147] wm8804 1-003b: Failed to read device ID: -121
[   12.910430] wm8804: probe of 1-003b failed with error -121

As suspected, there are some problems with initialization of the IC of your DAC (wm8804). it looks like the RPi can’t read/write properly on it from I2C bus. When this happens, ALSA does not map your device as card2, so you get the error message.

Unfortunately I don’t have any HiFiBerry Digi+ Pro Pi Hat for debugging this problem, but I’ll think about some additional test to verify if it’s a hardware fault or a software one and come back to you, if you’re willing to spend some time with testing.

Geogaddi · August 18, 2020, 10:58am

Hi Darmur,
Thanks for all your help, I’ve worked out a workaround right now. It’s really weird but if I both have an optical cable attached as well as the CoAx & turn everything off at the wall and on again it appears to work every time. It’s only if the Pi is turned off/on separately & the optical cable isn’t attached where the issue occurs.

If there are any reports or logs that you need from me to assist please let me know, but as I’ve got a good workaround for now I’m happy for this to be closed off.

Geogaddi · August 18, 2020, 1:44pm

But yeah to clarify, more than happy to assist.

Darmur · August 19, 2020, 9:11am

As a first test, could you please try to use your DAC with latest official RaspiOs?

Please do so without updating the system (it will run with kernel 4.19.118) and after updating the system with sudo apt upgrade (it will move to kernel 5.4.51)

Geogaddi · August 20, 2020, 12:21pm

Hello!

Just installed RaspiOS. It insisted on updating as it installed as I had a network cable plugged in.
uname -a says it’s updated to 5.4.51 unfortunately, do I need to reflash and stop if from updating?

Darmur · August 20, 2020, 1:10pm

It would be nice to do so, because Volumio is using kernel 4.19.118.

If it’s a driver problem, most probably you will have it in RaspiOs too, but if some fixes were applied on newer kernel you will not spot that.

Geogaddi · August 20, 2020, 1:20pm

No problem @Darmur, I’ll get it re-flashed tomorrow and skip the network cable

Geogaddi · August 22, 2020, 12:23pm

Ok all done. Currently on 4.19

Marcin_Kowalczyk · November 26, 2020, 10:11pm

Hello.

I do have exactly the same problem with Rasberry Pi 3 (2015) and brand new HIFIberry DAC2 Pro (2020). Is there any follow up of this case?

I’m familar with Linux as an administrator, so maybe it would be helpful to find a solution. I’ve seen that many users have very similar problems with their HIFIBerry DACs.

m83 · November 27, 2020, 8:28am

Hi all,
I also confirm that there is a problem with RPI3 and HIFIberry DAC2 Pro.
Can you please provide solution?
Actually I use HIFIberry DAC+ Pro version in Volumio settings since it has the same overlay but it generates error like
aplay -l doesn’t list HIFIberry device altough its there.

gary_john_walker · November 28, 2020, 10:17pm

See this thread also: -