Login

gforster · 04-20-2020, 01:18 PM

Hello world,

I am new to this forum and have read through the forum rules. I also saw that there are several entries related to "MPD error" and "Failed to open ALSA".
First, I wanted to thank Tim for this great audio player. A friend of mine and I first wanted to build our audio players based on Volumio, but then we found moode audio player which offers much more options.

We did build two versions of audio players. Both are based on a Raspberry Pi 3B+ and are running the latest moodeaudio 6.4.x version, but are using two different I2S audio HAT cards:
(1) Suptronics X400 V3.0
(2) IQaudIO Pi DigiAmp+

The problem I am describing is valid for both types of audio cards (1) and (2) above. It does, however, ONLY occur during a coldstart.
When I say coldstart, I mean switching-on the external AC/DC power supply (230VAC 50Hz, 12VDC@3A) and powering-up the hardware.
The problem is reproduceable and occurs every time I perform a coldstart.

The problem does not occur when performing a warmstart, ie moode audio player restart/reboot or when executing an SSH "sudo reboot" command.

Here are the "moodeutl -l" logs:

Coldstart (bad case):
20200419 193009 worker: -- Start
20200419 193009 worker: Successfully daemonized
20200419 193010 worker: Integrity check (passed)
20200419 193010 worker: Session loaded
20200419 193010 worker: Debug logging (off)
20200419 193010 worker: Device raw: (0:|1:empty|i2s:IQaudIO Pi-DigiAMP+)
20200419 193010 worker: Device cfg: (IQaudIO Pi-DigiAMP+|0|0|Digital|0)
20200419 193010 worker: ALSA volume set to (Invalid card number.) Angry

20200419 193010 worker: -- System
20200419 193012 worker: Host name     (moode)
20200419 193012 worker: moOde release (6.4.2 2020-02-12)
20200419 193012 worker: Raspbian OS   (10.2)
20200419 193012 worker: Linux kernel (4.19.97-v7+ #1293)
20200419 193012 worker: Platform      (Pi-3B+ 1GB v1.3)
20200419 193012 worker: Architecture (armv7l)
20200419 193012 worker: MPD version   (0.21.16)
20200419 193012 worker: CPU governor (ondemand)
20200419 193012 worker: USB boot enabled
20200419 193012 worker: File system expanded

Warmstart (good case):
20200420 140848 worker: -- Start
20200420 140848 worker: Successfully daemonized
20200420 140848 worker: Integrity check (passed)
20200420 140848 worker: Session loaded
20200420 140848 worker: Debug logging (off)
20200420 140848 worker: Device raw: (0:IQaudIODAC|1:empty|i2s:IQaudIO Pi-DigiAMP+)
20200420 140848 worker: Device cfg: (IQaudIO Pi-DigiAMP+|0|0|Digital|Invalid card $
20200420 140848 worker: ALSA volume set to (0%) Smile

20200420 140849 worker: -- System
20200420 140850 worker: Host name     (moode)
20200420 140850 worker: moOde release (6.4.2 2020-02-12)
20200420 140850 worker: Raspbian OS   (10.2)
20200420 140850 worker: Linux kernel (4.19.97-v7+ #1293)
20200420 140850 worker: Platform      (Pi-3B+ 1GB v1.3)
20200420 140850 worker: Architecture (armv7l)
20200420 140850 worker: MPD version   (0.21.16)
20200420 140850 worker: CPU governor (ondemand)
20200420 140850 worker: USB boot enabled
20200420 140851 worker: File system expanded

What I suspect is, that the audio card - independent whether it is the Suptronics or the IQaudIO - is not yet fully initialized when it is beeing accessed during the boot sequence. What makes me believe in my theorie is that the radio perfectly works after a warmstart. At a warmstart condition, the radio (Pi and the audio card) are continuously powered and the audio card is fully initialized.

[Image: huh.png]

So my question to the forum is the following:
Is there a way to slow-down / pause the boot sequence for a second or so before moode / ALSA tries to access the audio card?
This would probably give the audio card sufficient time to complete it's init phase and respond correctly to any command.

thx & brgds,
Gerhard

**Tim Curtis** · 04-20-2020, 01:40 PM

The symptom suggests something external to moOde software is causing the HAT to fail to initialize on power up.

HAT initialization happens during the Linux boot sequence which occurs before moOde starts. moOde startup is launched in the /etc/rc.local script which is not executed until Linux has fully completed its boot sequence.

Examine the boot log for HAT initialization errors.

Code:
dmesg

gforster · (This post was last modified: 04-20-2020, 04:31 PM by gforster.)

(04-20-2020, 01:40 PM)Tim Curtis Wrote: The symptom suggests something external to moOde software is causing the HAT to fail to initialize on power up.

HAT initialization happens during the Linux boot sequence which occurs before moOde starts. moOde startup is launched in the /etc/rc.local script which is not executed until Linux has fully completed its boot sequence.

Examine the boot log for HAT initialization errors.

Code:
dmesg

Hi Tim,

thx for the quick response. I did record the dmesg results in a file. Below the different sections related to snd-init.

dmesg_warm:

Code:
[ 5.578530] snd-rpi-iqaudio-dac soc:sound: ASoC: CODEC DAI pcm512x-hifi not registered - will retry

[ 5.585943] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'

[ 5.664330] snd-rpi-iqaudio-dac soc:sound: ASoC: CODEC DAI pcm512x-hifi not registered - will retry

[ 5.666240] brcmfmac: F1 signature read @0x18000000=0x15264345

[ 5.674900] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6

[ 5.675311] usbcore: registered new interface driver brcmfmac

[ 5.676108] snd-rpi-iqaudio-dac soc:sound: ASoC: CODEC DAI pcm512x-hifi not registered - will retry

[ 5.881458] random: crng init done

[ 5.881474] random: 7 urandom warning(s) missed due to ratelimiting

[ 5.904837] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6

[ 5.927828] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04

[ 6.326225] pcm512x 1-004c: Linked as a consumer to regulator.1

[ 6.337715] snd-rpi-iqaudio-dac soc:sound: pcm512x-hifi <-> 3f203000.i2s mapping ok

complete_dmesg_warm_log:

Code:
[    0.000000] Booting Linux on physical CPU 0x0

[    0.000000] Linux version 4.19.97-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1293 SMP Wed Jan 22 17:10:55 GMT 2020

[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d

[    0.000000] CPU: div instructions available: patching division code

[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache

[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3

[    0.000000] Memory policy: Data cache writealloc

[    0.000000] cma: Reserved 8 MiB at 0x3ac00000

[    0.000000] On node 0 totalpages: 242688

[    0.000000]   Normal zone: 2133 pages used for memmap

[    0.000000]   Normal zone: 0 pages reserved

[    0.000000]   Normal zone: 242688 pages, LIFO batch:63

[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0

[    0.000000] percpu: Embedded 16 pages/cpu s36864 r8192 d20480 u65536

[    0.000000] pcpu-alloc: s36864 r8192 d20480 u65536 alloc=16*4096

[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 

[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555

[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 bcm2708_fb.fbwidth=800 bcm2708_fb.fbheight=444 bcm2708_fb.fbswap=1 smsc95xx.macaddr=B8:27:EB:A8:66:CD vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  net.ifnames=0 console=ttyS0,115200 console=tty1 root=PARTUUID=6c586e13-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait

[    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: 939076K/970752K available (8192K kernel code, 653K rwdata, 2220K rodata, 1024K init, 822K bss, 23484K reserved, 8192K cma-reserved)

[    0.000000] Virtual kernel memory layout:

                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)

                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)

                   vmalloc : 0xbb800000 - 0xff800000   (1088 MB)

                   lowmem  : 0x80000000 - 0xbb400000   ( 948 MB)

                   modules : 0x7f000000 - 0x80000000   (  16 MB)

                     .text : 0x(ptrval) - 0x(ptrval)   (9184 kB)

                     .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)

                     .data : 0x(ptrval) - 0x(ptrval)   ( 654 kB)

                      .bss : 0x(ptrval) - 0x(ptrval)   ( 823 kB)

[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1

[    0.000000] ftrace: allocating 26858 entries in 79 pages

[    0.000000] rcu: Hierarchical RCU implementation.

[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16

[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).

[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns

[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns

[    0.000024] Switching to timer-based delay loop, resolution 52ns

[    0.000290] Console: colour dummy device 80x30

[    0.000914] console [tty1] enabled

[    0.000968] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)

[    0.001013] pid_max: default: 32768 minimum: 301

[    0.001372] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)

[    0.001408] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)

[    0.002379] CPU: Testing write buffer coherency: ok

[    0.002870] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000

[    0.003547] Setting up static identity map for 0x100000 - 0x10003c

[    0.003717] rcu: Hierarchical SRCU implementation.

[    0.004540] smp: Bringing up secondary CPUs ...

[    0.005456] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001

[    0.006453] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002

[    0.007373] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003

[    0.007498] smp: Brought up 1 node, 4 CPUs

[    0.007580] SMP: Total of 4 processors activated (153.60 BogoMIPS).

[    0.007604] CPU: All CPU(s) started in HYP mode.

[    0.007625] CPU: Virtualization extensions available.

[    0.008614] devtmpfs: initialized

[    0.022058] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4

[    0.022332] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns

[    0.022382] futex hash table entries: 1024 (order: 4, 65536 bytes)

[    0.022986] pinctrl core: initialized pinctrl subsystem

[    0.023868] NET: Registered protocol family 16

[    0.026900] DMA: preallocated 1024 KiB pool for atomic coherent allocations

[    0.032641] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.

[    0.032677] hw-breakpoint: maximum watchpoint size is 8 bytes.

[    0.032910] Serial: AMBA PL011 UART driver

[    0.035615] bcm2835-mbox 3f00b880.mailbox: mailbox enabled

[    0.050028] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-01-22 17:25, variant start

[    0.060041] raspberrypi-firmware soc:firmware: Firmware hash is 53a54c770c493957d99bf49762dfabc4eee00e45

[    0.103170] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1

[    0.104835] SCSI subsystem initialized

[    0.105079] usbcore: registered new interface driver usbfs

[    0.105154] usbcore: registered new interface driver hub

[    0.105265] usbcore: registered new device driver usb

[    0.106852] clocksource: Switched to clocksource arch_sys_counter

[    0.196807] VFS: Disk quotas dquot_6.6.0

[    0.196950] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)

[    0.197125] FS-Cache: Loaded

[    0.197353] CacheFiles: Loaded

[    0.207415] NET: Registered protocol family 2

[    0.208278] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)

[    0.208345] TCP established hash table entries: 8192 (order: 3, 32768 bytes)

[    0.208475] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)

[    0.208680] TCP: Hash tables configured (established 8192 bind 8192)

[    0.208835] UDP hash table entries: 512 (order: 2, 16384 bytes)

[    0.208905] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)

[    0.209173] NET: Registered protocol family 1

[    0.209769] RPC: Registered named UNIX socket transport module.

[    0.209797] RPC: Registered udp transport module.

[    0.209819] RPC: Registered tcp transport module.

[    0.209840] RPC: Registered tcp NFSv4.1 backchannel transport module.

[    0.211593] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available

[    0.214682] Initialise system trusted keyrings

[    0.214895] workingset: timestamp_bits=14 max_order=18 bucket_order=4

[    0.224720] FS-Cache: Netfs 'nfs' registered for caching

[    0.225315] NFS: Registering the id_resolver key type

[    0.225363] Key type id_resolver registered

[    0.225385] Key type id_legacy registered

[    0.225416] nfs4filelayout_init: NFSv4 File Layout Driver Registering...

[    0.227797] Key type asymmetric registered

[    0.227827] Asymmetric key parser 'x509' registered

[    0.227896] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)

[    0.228079] io scheduler noop registered

[    0.228103] io scheduler deadline registered (default)

[    0.228297] io scheduler cfq registered

[    0.228321] io scheduler mq-deadline registered (default)

[    0.228345] io scheduler kyber registered

[    0.230635] bcm2708_fb soc:fb: FB found 1 display(s)

[    0.242160] Console: switching to colour frame buffer device 100x27

[    0.250168] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 800x444

[    0.254947] bcm2835-rng 3f104000.rng: hwrng registered

[    0.257855] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)

[    0.261034] vc-sm: Videocore shared memory driver

[    0.263980] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000

[    0.277420] brd: module loaded

[    0.290223] loop: module loaded

[    0.293451] Loading iSCSI transport class v2.0-870.

[    0.296747] libphy: Fixed MDIO Bus: probed

[    0.299547] usbcore: registered new interface driver lan78xx

[    0.302266] usbcore: registered new interface driver smsc95xx

[    0.304836] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)

[    0.335301] dwc_otg 3f980000.usb: base=(ptrval)

[    0.538090] Core Release: 2.80a

[    0.540514] Setting default values for core params

[    0.542992] Finished setting default values for core params

[    0.745782] Using Buffer DMA mode

[    0.748295] Periodic Transfer Interrupt Enhancement - disabled

[    0.750889] Multiprocessor Interrupt Enhancement - disabled

[    0.753517] OTG VER PARAM: 0, OTG VER FLAG: 0

[    0.756140] Dedicated Tx FIFOs mode

[    0.759159] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = bad14000 dma = 0xfad14000 len=9024

[    0.764464] FIQ FSM acceleration enabled for :

               Non-periodic Split Transactions

               Periodic Split Transactions

               High-Speed Isochronous Endpoints

               Interrupt/Control Split Transaction hack enabled

[    0.776643] dwc_otg: Microframe scheduler enabled

[    0.776702] WARN::hcd_init_fiq:457: FIQ on core 1

[    0.779125] WARN::hcd_init_fiq:458: FIQ ASM at 8067fbe4 length 36

[    0.781544] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000

[    0.783937] dwc_otg 3f980000.usb: DWC OTG Controller

[    0.786412] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1

[    0.788958] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000

[    0.791456] Init: Port Power? op_state=1

[    0.793888] Init: Power Port (0)

[    0.796516] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19

[    0.799122] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1

[    0.801683] usb usb1: Product: DWC OTG Controller

[    0.804193] usb usb1: Manufacturer: Linux 4.19.97-v7+ dwc_otg_hcd

[    0.806720] usb usb1: SerialNumber: 3f980000.usb

[    0.809832] hub 1-0:1.0: USB hub found

[    0.812336] hub 1-0:1.0: 1 port detected

[    0.815254] dwc_otg: FIQ enabled

[    0.815260] dwc_otg: NAK holdoff enabled

[    0.815266] dwc_otg: FIQ split-transaction FSM enabled

[    0.815276] Module dwc_common_port init

[    0.815564] usbcore: registered new interface driver usb-storage

[    0.818071] mousedev: PS/2 mouse device common for all mice

[    0.821240] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer

[    0.823855] bcm2835-cpufreq: min=600000 max=1400000

[    0.826720] sdhci: Secure Digital Host Controller Interface driver

[    0.829217] sdhci: Copyright(c) Pierre Ossman

[    0.832042] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe

[    0.834982] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe

[    0.837730] sdhci-pltfm: SDHCI platform and OF driver helper

[    0.841893] ledtrig-cpu: registered to indicate activity on CPUs

[    0.844679] hidraw: raw HID events driver (C) Jiri Kosina

[    0.847540] usbcore: registered new interface driver usbhid

[    0.850183] usbhid: USB HID core driver

[    0.853573] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0

[    0.857923] [vc_sm_connected_init]: start

[    0.866700] [vc_sm_connected_init]: end - returning 0

[    0.870439] Initializing XFRM netlink socket

[    0.872996] NET: Registered protocol family 17

[    0.875619] Key type dns_resolver registered

[    0.878635] Registering SWP/SWPB emulation handler

[    0.881804] registered taskstats version 1

[    0.884358] Loading compiled-in X.509 certificates

[    0.893668] uart-pl011 3f201000.serial: cts_event_workaround enabled

[    0.896357] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2

[    0.900990] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0

[    0.903705] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated

[    0.930232] sdhost: log_buf @ (ptrval) (fad13000)

[    0.968922] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)

[    0.973115] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)

[    0.977180] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)

[    0.981290] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)

[    0.984929] of_cfs_init

[    0.987364] of_cfs_init: OK

[    0.990162] Waiting for root device PARTUUID=6c586e13-02...

[    1.004483] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)

[    1.036982] Indeed it is in host mode hprt0 = 00021501

[    1.105537] random: fast init done

[    1.123138] mmc0: host does not support reading read-only switch, assuming write-enable

[    1.129182] mmc0: new high speed SDHC card at address aaaa

[    1.132902] mmcblk0: mmc0:aaaa SC32G 29.7 GiB

[    1.141015]  mmcblk0: p1 p2

[    1.144912] mmc1: new high speed SDIO card at address 0001

[    1.181252] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)

[    1.183922] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.

[    1.194076] devtmpfs: mounted

[    1.201534] Freeing unused kernel memory: 1024K

[    1.217264] Run /sbin/init as init process

[    1.246896] usb 1-1: new high-speed USB device number 2 using dwc_otg

[    1.249498] Indeed it is in host mode hprt0 = 00001101

[    1.487200] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3

[    1.489913] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0

[    1.493409] hub 1-1:1.0: USB hub found

[    1.496229] hub 1-1:1.0: 4 ports detected

[    1.812920] systemd[1]: System time before build time, advancing clock.

[    1.816896] usb 1-1.1: new high-speed USB device number 3 using dwc_otg

[    1.947207] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3

[    1.950168] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0

[    1.953730] hub 1-1.1:1.0: USB hub found

[    1.956702] hub 1-1.1:1.0: 3 ports detected

[    1.975768] NET: Registered protocol family 10

[    1.979828] Segment Routing with IPv6

[    2.033296] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)

[    2.043131] systemd[1]: Detected architecture arm.

[    2.056903] usb 1-1.2: new low-speed USB device number 4 using dwc_otg

[    2.071320] systemd[1]: Set hostname to <moode>.

[    2.076324] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument

[    2.206693] usb 1-1.2: New USB device found, idVendor=046d, idProduct=c31d, bcdDevice=66.00

[    2.209910] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0

[    2.212980] usb 1-1.2: Product: USB Keyboard

[    2.216379] usb 1-1.2: Manufacturer: Logitech

[    2.250389] input: Logitech USB Keyboard as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.0/0003:046D:C31D.0001/input/input0

[    2.286918] usb 1-1.1.3: new low-speed USB device number 5 using dwc_otg

[    2.317752] hid-generic 0003:046D:C31D.0001: input,hidraw0: USB HID v1.10 Keyboard [Logitech USB Keyboard] on usb-3f980000.usb-1.2/input0

[    2.350138] input: Logitech USB Keyboard Consumer Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.1/0003:046D:C31D.0002/input/input1

[    2.427143] input: Logitech USB Keyboard System Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.1/0003:046D:C31D.0002/input/input2

[    2.434674] hid-generic 0003:046D:C31D.0002: input,hidraw1: USB HID v1.10 Device [Logitech USB Keyboard] on usb-3f980000.usb-1.2/input1

[    2.452775] usb 1-1.1.3: New USB device found, idVendor=046d, idProduct=c050, bcdDevice=27.20

[    2.456604] usb 1-1.1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0

[    2.460395] usb 1-1.1.3: Product: USB-PS/2 Optical Mouse

[    2.464053] usb 1-1.1.3: Manufacturer: Logitech

[    2.486595] input: Logitech USB-PS/2 Optical Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.3/1-1.1.3:1.0/0003:046D:C050.0003/input/input3

[    2.495096] hid-generic 0003:046D:C050.0003: input,hidraw2: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-3f980000.usb-1.1.3/input0

[    2.796909] usb 1-1.1.1: new high-speed USB device number 6 using dwc_otg

[    2.798419] systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly.

[    2.885624] systemd[1]: /lib/systemd/system/smbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/smbd.pid → /run/samba/smbd.pid; please update the unit file accordingly.

[    2.927371] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00

[    2.931617] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0

[    2.936578] systemd[1]: /lib/systemd/system/nmbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/nmbd.pid → /run/samba/nmbd.pid; please update the unit file accordingly.

[    3.055785] random: systemd: uninitialized urandom read (16 bytes read)

[    3.088711] random: systemd: uninitialized urandom read (16 bytes read)

[    3.093374] systemd[1]: Listening on udev Control Socket.

[    3.102289] random: systemd: uninitialized urandom read (16 bytes read)

[    3.112373] systemd[1]: Created slice User and Session Slice.

[    3.120959] systemd[1]: Reached target Slices.

[    3.200452] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed

[    3.208526] libphy: lan78xx-mdiobus: probed

[    3.236253] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64

[    4.006665] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)

[    4.158215] systemd-journald[119]: Received request to flush runtime journal from PID 1

[    4.720666] Registered IR keymap rc-rc6-mce

[    4.744330] rpi-ft5406 rpi_ft5406: Probing device

[    4.757596] input: FT5406 memory based driver as /devices/virtual/input/input5

[    4.760386] IR RC6 protocol handler initialized

[    4.797730] rc rc0: gpio_ir_recv as /devices/platform/ir-receiver@e/rc/rc0

[    4.798078] input: gpio_ir_recv as /devices/platform/ir-receiver@e/rc/rc0/input4

[    4.798376] rc rc0: lirc_dev: driver gpio_ir_recv registered at minor = 0, raw IR receiver, no transmitter

[    5.010062] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.

[    5.014100] bcm2835_vc_sm_cma_probe: Videocore shared memory driver

[    5.014115] [vc_sm_connected_init]: start

[    5.018523] media: Linux media interface: v0.10

[    5.019126] [vc_sm_connected_init]: installed successfully

[    5.056675] videodev: Linux video capture interface: v2.00

[    5.103711] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.

[    5.104916] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.

[    5.113539] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.

[    5.131667] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.

[    5.148777] bcm2835-codec bcm2835-codec: Device registered as /dev/video10

[    5.148824] bcm2835-codec bcm2835-codec: Loaded V4L2 decode

[    5.153710] bcm2835-codec bcm2835-codec: Device registered as /dev/video11

[    5.153760] bcm2835-codec bcm2835-codec: Loaded V4L2 encode

[    5.162686] bcm2835-codec bcm2835-codec: Device registered as /dev/video12

[    5.162726] bcm2835-codec bcm2835-codec: Loaded V4L2 isp

[    5.453358] cfg80211: Loading compiled-in X.509 certificates for regulatory database

[    5.578530] snd-rpi-iqaudio-dac soc:sound: ASoC: CODEC DAI pcm512x-hifi not registered - will retry

[    5.585943] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'

[    5.664330] snd-rpi-iqaudio-dac soc:sound: ASoC: CODEC DAI pcm512x-hifi not registered - will retry

[    5.666240] brcmfmac: F1 signature read @0x18000000=0x15264345

[    5.674900] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6

[    5.675311] usbcore: registered new interface driver brcmfmac

[    5.676108] snd-rpi-iqaudio-dac soc:sound: ASoC: CODEC DAI pcm512x-hifi not registered - will retry

[    5.881458] random: crng init done

[    5.881474] random: 7 urandom warning(s) missed due to ratelimiting

[    5.904837] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6

[    5.927828] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04

[    6.326225] pcm512x 1-004c: Linked as a consumer to regulator.1

[    6.337715] snd-rpi-iqaudio-dac soc:sound: pcm512x-hifi <-> 3f203000.i2s mapping ok

[    7.881869] 8021q: 802.1Q VLAN Support v1.8

[    8.253926] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready

[    8.253944] brcmfmac: power management disabled

[    8.589662] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready

[    8.589701] 8021q: adding VLAN 0 to HW filter on device eth0

[    8.595290] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

[   21.247118] pcm512x 1-004c: No SCLK, using BCLK: -2

[   24.344714] uart-pl011 3f201000.serial: no DMA platform data

[   24.415256] fuse init (API version 7.27)

[   31.128228] Bluetooth: Core ver 2.22

[   31.128325] NET: Registered protocol family 31

[   31.128332] Bluetooth: HCI device and connection manager initialized

[   31.128354] Bluetooth: HCI socket layer initialized

[   31.128367] Bluetooth: L2CAP socket layer initialized

[   31.128407] Bluetooth: SCO socket layer initialized

[   31.151282] Bluetooth: HCI UART driver ver 2.3

[   31.151296] Bluetooth: HCI UART protocol H4 registered

[   31.151384] Bluetooth: HCI UART protocol Three-wire (H5) registered

[   31.151606] Bluetooth: HCI UART protocol Broadcom registered

[   31.330307] Bluetooth: BNEP (Ethernet Emulation) ver 1.3

[   31.330317] Bluetooth: BNEP filters: protocol multicast

[   31.330338] Bluetooth: BNEP socket layer initialized

[   32.813590] pcm512x 1-004c: No SCLK, using BCLK: -2

[   32.831035] snd-rpi-iqaudio-dac soc:sound: snd_rpi_iqaudio_gpio_unmute: un-muting amp using GPIO22

[   49.766925] rc rc0: two consecutive events of type space

[   59.357251] snd-rpi-iqaudio-dac soc:sound: snd_rpi_iqaudio_gpio_mute: muting amp using GPIO22

dmesg_cold:

Code:
[ 5.791101] snd-rpi-iqaudio-dac soc:sound: ASoC: CODEC DAI pcm512x-hifi not registered - will retry

[ 5.960241] random: crng init done

[ 5.960258] random: 7 urandom warning(s) missed due to ratelimiting

[ 5.967956] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6

[ 6.020227] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04

[ 6.391691] pcm512x 1-004c: Linked as a consumer to regulator.1

[ 6.616342] pcm512x 1-004c: Failed to reset device: -121

[ 6.616768] pcm512x: probe of 1-004c failed with error -121

complete_dmesg_coldstart_log:

Code:
[    0.000000] Booting Linux on physical CPU 0x0

[    0.000000] Linux version 4.19.97-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1293 SMP Wed Jan 22 17:10:55 GMT 2020

[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d

[    0.000000] CPU: div instructions available: patching division code

[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache

[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3

[    0.000000] Memory policy: Data cache writealloc

[    0.000000] cma: Reserved 8 MiB at 0x3ac00000

[    0.000000] On node 0 totalpages: 242688

[    0.000000]   Normal zone: 2133 pages used for memmap

[    0.000000]   Normal zone: 0 pages reserved

[    0.000000]   Normal zone: 242688 pages, LIFO batch:63

[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0

[    0.000000] percpu: Embedded 16 pages/cpu s36864 r8192 d20480 u65536

[    0.000000] pcpu-alloc: s36864 r8192 d20480 u65536 alloc=16*4096

[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 

[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555

[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 bcm2708_fb.fbwidth=800 bcm2708_fb.fbheight=444 bcm2708_fb.fbswap=1 smsc95xx.macaddr=B8:27:EB:A8:66:CD vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  net.ifnames=0 console=ttyS0,115200 console=tty1 root=PARTUUID=6c586e13-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait

[    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: 939076K/970752K available (8192K kernel code, 653K rwdata, 2220K rodata, 1024K init, 822K bss, 23484K reserved, 8192K cma-reserved)

[    0.000000] Virtual kernel memory layout:

                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)

                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)

                   vmalloc : 0xbb800000 - 0xff800000   (1088 MB)

                   lowmem  : 0x80000000 - 0xbb400000   ( 948 MB)

                   modules : 0x7f000000 - 0x80000000   (  16 MB)

                     .text : 0x(ptrval) - 0x(ptrval)   (9184 kB)

                     .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)

                     .data : 0x(ptrval) - 0x(ptrval)   ( 654 kB)

                      .bss : 0x(ptrval) - 0x(ptrval)   ( 823 kB)

[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1

[    0.000000] ftrace: allocating 26858 entries in 79 pages

[    0.000000] rcu: Hierarchical RCU implementation.

[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16

[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).

[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns

[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns

[    0.000024] Switching to timer-based delay loop, resolution 52ns

[    0.000290] Console: colour dummy device 80x30

[    0.000914] console [tty1] enabled

[    0.000970] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)

[    0.001014] pid_max: default: 32768 minimum: 301

[    0.001375] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)

[    0.001412] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)

[    0.002380] CPU: Testing write buffer coherency: ok

[    0.002867] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000

[    0.003540] Setting up static identity map for 0x100000 - 0x10003c

[    0.003710] rcu: Hierarchical SRCU implementation.

[    0.004529] smp: Bringing up secondary CPUs ...

[    0.005448] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001

[    0.006443] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002

[    0.007362] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003

[    0.007486] smp: Brought up 1 node, 4 CPUs

[    0.007568] SMP: Total of 4 processors activated (153.60 BogoMIPS).

[    0.007593] CPU: All CPU(s) started in HYP mode.

[    0.007613] CPU: Virtualization extensions available.

[    0.008602] devtmpfs: initialized

[    0.022063] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4

[    0.022337] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns

[    0.022386] futex hash table entries: 1024 (order: 4, 65536 bytes)

[    0.022990] pinctrl core: initialized pinctrl subsystem

[    0.023869] NET: Registered protocol family 16

[    0.026878] DMA: preallocated 1024 KiB pool for atomic coherent allocations

[    0.032620] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.

[    0.032656] hw-breakpoint: maximum watchpoint size is 8 bytes.

[    0.032891] Serial: AMBA PL011 UART driver

[    0.035597] bcm2835-mbox 3f00b880.mailbox: mailbox enabled

[    0.050029] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-01-22 17:25, variant start

[    0.060041] raspberrypi-firmware soc:firmware: Firmware hash is 53a54c770c493957d99bf49762dfabc4eee00e45

[    0.103190] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1

[    0.104858] SCSI subsystem initialized

[    0.105102] usbcore: registered new interface driver usbfs

[    0.105177] usbcore: registered new interface driver hub

[    0.105288] usbcore: registered new device driver usb

[    0.106887] clocksource: Switched to clocksource arch_sys_counter

[    0.196860] VFS: Disk quotas dquot_6.6.0

[    0.197003] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)

[    0.197213] FS-Cache: Loaded

[    0.197441] CacheFiles: Loaded

[    0.207497] NET: Registered protocol family 2

[    0.208362] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)

[    0.208428] TCP established hash table entries: 8192 (order: 3, 32768 bytes)

[    0.208559] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)

[    0.208763] TCP: Hash tables configured (established 8192 bind 8192)

[    0.208919] UDP hash table entries: 512 (order: 2, 16384 bytes)

[    0.208990] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)

[    0.209258] NET: Registered protocol family 1

[    0.209855] RPC: Registered named UNIX socket transport module.

[    0.209882] RPC: Registered udp transport module.

[    0.209904] RPC: Registered tcp transport module.

[    0.209926] RPC: Registered tcp NFSv4.1 backchannel transport module.

[    0.211688] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available

[    0.214780] Initialise system trusted keyrings

[    0.214998] workingset: timestamp_bits=14 max_order=18 bucket_order=4

[    0.224828] FS-Cache: Netfs 'nfs' registered for caching

[    0.225420] NFS: Registering the id_resolver key type

[    0.225467] Key type id_resolver registered

[    0.225490] Key type id_legacy registered

[    0.225521] nfs4filelayout_init: NFSv4 File Layout Driver Registering...

[    0.227908] Key type asymmetric registered

[    0.227938] Asymmetric key parser 'x509' registered

[    0.228006] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)

[    0.228188] io scheduler noop registered

[    0.228212] io scheduler deadline registered (default)

[    0.228406] io scheduler cfq registered

[    0.228429] io scheduler mq-deadline registered (default)

[    0.228454] io scheduler kyber registered

[    0.230746] bcm2708_fb soc:fb: FB found 1 display(s)

[    0.242265] Console: switching to colour frame buffer device 100x27

[    0.250262] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 800x444

[    0.255041] bcm2835-rng 3f104000.rng: hwrng registered

[    0.257969] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)

[    0.261151] vc-sm: Videocore shared memory driver

[    0.264093] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000

[    0.277539] brd: module loaded

[    0.290331] loop: module loaded

[    0.293561] Loading iSCSI transport class v2.0-870.

[    0.296925] libphy: Fixed MDIO Bus: probed

[    0.299673] usbcore: registered new interface driver lan78xx

[    0.302397] usbcore: registered new interface driver smsc95xx

[    0.304972] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)

[    0.335445] dwc_otg 3f980000.usb: base=(ptrval)

[    0.538231] Core Release: 2.80a

[    0.540661] Setting default values for core params

[    0.543141] Finished setting default values for core params

[    0.745947] Using Buffer DMA mode

[    0.748467] Periodic Transfer Interrupt Enhancement - disabled

[    0.751065] Multiprocessor Interrupt Enhancement - disabled

[    0.753694] OTG VER PARAM: 0, OTG VER FLAG: 0

[    0.756316] Dedicated Tx FIFOs mode

[    0.759330] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = bad14000 dma = 0xfad14000 len=9024

[    0.764639] FIQ FSM acceleration enabled for :

               Non-periodic Split Transactions

               Periodic Split Transactions

               High-Speed Isochronous Endpoints

               Interrupt/Control Split Transaction hack enabled

[    0.776819] dwc_otg: Microframe scheduler enabled

[    0.776897] WARN::hcd_init_fiq:457: FIQ on core 1

[    0.779320] WARN::hcd_init_fiq:458: FIQ ASM at 8067fbe4 length 36

[    0.781742] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000

[    0.784131] dwc_otg 3f980000.usb: DWC OTG Controller

[    0.786602] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1

[    0.789144] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000

[    0.791636] Init: Port Power? op_state=1

[    0.794063] Init: Power Port (0)

[    0.796689] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19

[    0.799290] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1

[    0.801848] usb usb1: Product: DWC OTG Controller

[    0.804357] usb usb1: Manufacturer: Linux 4.19.97-v7+ dwc_otg_hcd

[    0.806907] usb usb1: SerialNumber: 3f980000.usb

[    0.809999] hub 1-0:1.0: USB hub found

[    0.812509] hub 1-0:1.0: 1 port detected

[    0.815414] dwc_otg: FIQ enabled

[    0.815420] dwc_otg: NAK holdoff enabled

[    0.815426] dwc_otg: FIQ split-transaction FSM enabled

[    0.815436] Module dwc_common_port init

[    0.815712] usbcore: registered new interface driver usb-storage

[    0.818218] mousedev: PS/2 mouse device common for all mice

[    0.821383] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer

[    0.823985] bcm2835-cpufreq: min=600000 max=1400000

[    0.826850] sdhci: Secure Digital Host Controller Interface driver

[    0.829345] sdhci: Copyright(c) Pierre Ossman

[    0.832166] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe

[    0.835104] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe

[    0.837847] sdhci-pltfm: SDHCI platform and OF driver helper

[    0.842029] ledtrig-cpu: registered to indicate activity on CPUs

[    0.844816] hidraw: raw HID events driver (C) Jiri Kosina

[    0.847674] usbcore: registered new interface driver usbhid

[    0.850316] usbhid: USB HID core driver

[    0.853702] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0

[    0.858037] [vc_sm_connected_init]: start

[    0.866829] [vc_sm_connected_init]: end - returning 0

[    0.870557] Initializing XFRM netlink socket

[    0.873119] NET: Registered protocol family 17

[    0.875756] Key type dns_resolver registered

[    0.878775] Registering SWP/SWPB emulation handler

[    0.881945] registered taskstats version 1

[    0.884502] Loading compiled-in X.509 certificates

[    0.893809] uart-pl011 3f201000.serial: cts_event_workaround enabled

[    0.896497] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2

[    0.901137] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0

[    0.903857] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated

[    0.930284] sdhost: log_buf @ (ptrval) (fad13000)

[    0.967962] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)

[    0.972162] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)

[    0.976223] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)

[    0.981433] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)

[    0.983732] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)

[    0.987305] of_cfs_init

[    0.989584] of_cfs_init: OK

[    0.992274] Waiting for root device PARTUUID=6c586e13-02...

[    1.037132] Indeed it is in host mode hprt0 = 00021501

[    1.105267] random: fast init done

[    1.122782] mmc0: host does not support reading read-only switch, assuming write-enable

[    1.128727] mmc0: new high speed SDHC card at address aaaa

[    1.133143] mmcblk0: mmc0:aaaa SC32G 29.7 GiB

[    1.141313] mmc1: new high speed SDIO card at address 0001

[    1.144168]  mmcblk0: p1 p2

[    1.181205] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)

[    1.183775] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.

[    1.193812] devtmpfs: mounted

[    1.201112] Freeing unused kernel memory: 1024K

[    1.246924] usb 1-1: new high-speed USB device number 2 using dwc_otg

[    1.249468] Indeed it is in host mode hprt0 = 00001101

[    1.312245] Run /sbin/init as init process

[    1.487228] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3

[    1.489888] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0

[    1.493258] hub 1-1:1.0: USB hub found

[    1.496100] hub 1-1:1.0: 4 ports detected

[    1.816934] usb 1-1.1: new high-speed USB device number 3 using dwc_otg

[    1.907226] systemd[1]: System time before build time, advancing clock.

[    1.947205] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3

[    1.950218] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0

[    1.953824] hub 1-1.1:1.0: USB hub found

[    1.956840] hub 1-1.1:1.0: 3 ports detected

[    2.056980] usb 1-1.2: new low-speed USB device number 4 using dwc_otg

[    2.069714] NET: Registered protocol family 10

[    2.073788] Segment Routing with IPv6

[    2.127278] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)

[    2.137102] systemd[1]: Detected architecture arm.

[    2.162150] systemd[1]: Set hostname to <moode>.

[    2.167109] systemd[1]: Failed to bump fs.file-max, ignoring: Invalid argument

[    2.210729] usb 1-1.2: New USB device found, idVendor=046d, idProduct=c31d, bcdDevice=66.00

[    2.214170] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0

[    2.217494] usb 1-1.2: Product: USB Keyboard

[    2.220567] usb 1-1.2: Manufacturer: Logitech

[    2.248306] input: Logitech USB Keyboard as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.0/0003:046D:C31D.0001/input/input0

[    2.287002] usb 1-1.1.3: new low-speed USB device number 5 using dwc_otg

[    2.318077] hid-generic 0003:046D:C31D.0001: input,hidraw0: USB HID v1.10 Keyboard [Logitech USB Keyboard] on usb-3f980000.usb-1.2/input0

[    2.353550] input: Logitech USB Keyboard Consumer Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.1/0003:046D:C31D.0002/input/input1

[    2.437203] input: Logitech USB Keyboard System Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.1/0003:046D:C31D.0002/input/input2

[    2.444402] usb 1-1.1.3: New USB device found, idVendor=046d, idProduct=c050, bcdDevice=27.20

[    2.448084] usb 1-1.1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0

[    2.451596] usb 1-1.1.3: Product: USB-PS/2 Optical Mouse

[    2.455071] usb 1-1.1.3: Manufacturer: Logitech

[    2.458988] hid-generic 0003:046D:C31D.0002: input,hidraw1: USB HID v1.10 Device [Logitech USB Keyboard] on usb-3f980000.usb-1.2/input1

[    2.483643] input: Logitech USB-PS/2 Optical Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.3/1-1.1.3:1.0/0003:046D:C050.0003/input/input3

[    2.491895] hid-generic 0003:046D:C050.0003: input,hidraw2: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-3f980000.usb-1.1.3/input0

[    2.816944] usb 1-1.1.1: new high-speed USB device number 6 using dwc_otg

[    2.863977] systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly.

[    2.945864] systemd[1]: /lib/systemd/system/smbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/smbd.pid → /run/samba/smbd.pid; please update the unit file accordingly.

[    2.947416] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00

[    2.962618] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0

[    2.997031] systemd[1]: /lib/systemd/system/nmbd.service:9: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/nmbd.pid → /run/samba/nmbd.pid; please update the unit file accordingly.

[    3.114896] random: systemd: uninitialized urandom read (16 bytes read)

[    3.147328] random: systemd: uninitialized urandom read (16 bytes read)

[    3.188822] systemd[1]: Listening on RPCbind Server Activation Socket.

[    3.198019] random: systemd: uninitialized urandom read (16 bytes read)

[    3.202699] systemd[1]: Listening on fsck to fsckd communication Socket.

[    3.212810] systemd[1]: Created slice system-getty.slice.

[    3.231935] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed

[    3.240614] libphy: lan78xx-mdiobus: probed

[    3.270891] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64

[    4.098323] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)

[    4.249205] systemd-journald[126]: Received request to flush runtime journal from PID 1

[    4.798108] Registered IR keymap rc-rc6-mce

[    4.806122] rpi-ft5406 rpi_ft5406: Probing device

[    4.816696] input: FT5406 memory based driver as /devices/virtual/input/input5

[    4.830118] IR RC6 protocol handler initialized

[    4.867409] rc rc0: gpio_ir_recv as /devices/platform/ir-receiver@e/rc/rc0

[    4.867675] input: gpio_ir_recv as /devices/platform/ir-receiver@e/rc/rc0/input4

[    4.867891] rc rc0: lirc_dev: driver gpio_ir_recv registered at minor = 0, raw IR receiver, no transmitter

[    5.146413] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.

[    5.151313] bcm2835_vc_sm_cma_probe: Videocore shared memory driver

[    5.151330] [vc_sm_connected_init]: start

[    5.154826] media: Linux media interface: v0.10

[    5.155723] [vc_sm_connected_init]: installed successfully

[    5.201370] videodev: Linux video capture interface: v2.00

[    5.281668] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.

[    5.284224] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.

[    5.312816] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.

[    5.318319] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.

[    5.337728] bcm2835-codec bcm2835-codec: Device registered as /dev/video10

[    5.337770] bcm2835-codec bcm2835-codec: Loaded V4L2 decode

[    5.344451] bcm2835-codec bcm2835-codec: Device registered as /dev/video11

[    5.344488] bcm2835-codec bcm2835-codec: Loaded V4L2 encode

[    5.368036] bcm2835-codec bcm2835-codec: Device registered as /dev/video12

[    5.368074] bcm2835-codec bcm2835-codec: Loaded V4L2 isp

[    5.471133] cfg80211: Loading compiled-in X.509 certificates for regulatory database

[    5.611660] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'

[    5.717267] brcmfmac: F1 signature read @0x18000000=0x15264345

[    5.729612] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6

[    5.730572] usbcore: registered new interface driver brcmfmac

[    5.791101] snd-rpi-iqaudio-dac soc:sound: ASoC: CODEC DAI pcm512x-hifi not registered - will retry

[    5.960241] random: crng init done

[    5.960258] random: 7 urandom warning(s) missed due to ratelimiting

[    5.967956] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6

[    6.020227] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04

[    6.391691] pcm512x 1-004c: Linked as a consumer to regulator.1

[    6.616342] pcm512x 1-004c: Failed to reset device: -121

[    6.616768] pcm512x: probe of 1-004c failed with error -121

[    7.750831] 8021q: 802.1Q VLAN Support v1.8

[    8.202202] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready

[    8.202240] brcmfmac: power management disabled

[    8.535786] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready

[    8.535800] 8021q: adding VLAN 0 to HW filter on device eth0

[    8.535885] lan78xx 1-1.1.1:1.0 eth0: kevent 4 may have been dropped

[    8.557302] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

[   23.837695] uart-pl011 3f201000.serial: no DMA platform data

[   23.838035] fuse init (API version 7.27)

[   30.552144] Bluetooth: Core ver 2.22

[   30.552247] NET: Registered protocol family 31

[   30.552253] Bluetooth: HCI device and connection manager initialized

[   30.552276] Bluetooth: HCI socket layer initialized

[   30.552289] Bluetooth: L2CAP socket layer initialized

[   30.552332] Bluetooth: SCO socket layer initialized

[   30.570333] Bluetooth: HCI UART driver ver 2.3

[   30.570349] Bluetooth: HCI UART protocol H4 registered

[   30.570442] Bluetooth: HCI UART protocol Three-wire (H5) registered

[   30.570680] Bluetooth: HCI UART protocol Broadcom registered

[   30.774464] Bluetooth: BNEP (Ethernet Emulation) ver 1.3

[   30.774474] Bluetooth: BNEP filters: protocol multicast

[   30.774495] Bluetooth: BNEP socket layer initialized

If necessary, I can also provide the entire dmesg log files if this provides any further relevant data.

Understand that the HAT init is part of Linux boot rather than moode boot. Do you know if there is a way to implement a delay to the "Linux boot sequence" ?

thx,
Gerhard

**Tim Curtis** · 04-20-2020, 03:22 PM

Please edit your post and place the log output in a code box. Its the 3rd or 5th button from the right on the toolbar when composing/editing a post.

gforster · 04-20-2020, 04:33 PM

(04-20-2020, 03:22 PM)Tim Curtis Wrote: Please edit your post and place the log output in a code box. Its the 3rd or 5th button from the right on the toolbar when composing/editing a post.

just updated the post. Sorry, didn't know about the code window.

**Tim Curtis** · 04-20-2020, 04:55 PM

No prob.

The DMESG logs confirm the drivers for both audio devices fail to initialize during Linux boot. I'd suspect the power supply.

The PSU I've used with IQaudIO Pi-DigiAmp+ is XP Power VEH60US15 (15V/$A) I don't know what the other amp HAT requires.

gforster · 04-22-2020, 02:19 PM

(04-20-2020, 04:55 PM)Tim Curtis Wrote: No prob.

The DMESG logs confirm the drivers for both audio devices fail to initialize during Linux boot. I'd suspect the power supply.

The PSU I've used with IQaudIO Pi-DigiAmp+ is XP Power VEH60US15 (15V/$A) I don't know what the other amp HAT requires.

The Suptronics X400 requires an input voltage in the range of 6-26V, the IQaudIO 12-24V.
I changed the power supply and tested with

12V, cabable of providing up to 5A
15V, capable of providing up to 10A

Neither one of these alternate power supplies did resolve the coldstart issue.
The max current drawn was 600mA, ie 9Watts.

As a second step,I did add a delay of 30 seconds to the boot process within /boot/config.txt in order to give the sound card more time to initialize:

Code:
bootcode_delay=30

The raspberry website describes at https://www.raspberrypi.org/documentatio...xt/boot.md
that the bootcode_delay command is particularly useful to insert a delay if the Pi and other devices are powered from the same power source, but the device takes longer to start up than the Pi. Try to set this value if the device detection is wrong on initial boot, but is correct if you soft-reboot the Pi without removing power from the other device.
Even this recommendation was specifically for a monitor, my hope was that this would also resolve the coldstart issue of the sound card.

Unfortunately, the delayed boot sequence did not resolve the coldstart. The boot time took 30 seconds longer (I also tried it with 60 seconds), but the "Failed to open ALSA" problem message was still there.

For me it is quite certain that the root cause of the problem is not moode, but something inside the OS boot trying to access the audio/sound card which is not responding correctly.

The workaround for me is to avoid a coldstart situation. Of course, this can't be prevented when the radio is powered-up for the first time. Instead of turning off the radio when it's not used, I just put it into sleep mode by a push-button managed through the GPIO handler of moode, which is then initiating the following command:

Code:
sudo shutdown now

Another push-button then restarts the radio by shorting GPIO#3 to GND. This is a warmstart and does not cause any ALSA failure. Wink

Still don't understand why it is working fine during warmstart but not during coldstart. Would be great if someone finds out the root cause of this behaviour and how to overcome this. Undecided

**Tim Curtis** · 04-22-2020, 02:48 PM

Just tested a Pi-2B w/DigiAmp+ and no issues. Granted I'm using the soon to be release 6.5.0 which is based on Raspbian 10.3 and kernel 4.19.115.

Maybe try reseating the HAT board after spraying on some contact cleaner or alternatively updating to latest kernel in case you are experiencing some sort of kernel bug.

Code:
Authenticated to rp2 ([192.168.1.248]:22).

Raspbian 10.3 | 4.19.115-v7+ #1305 | armv7l (32-bit)

                          ____     __

              __ _  ___  / __ \___/ /__

             /  ' \/ _ \/ /_/ / _  / -_)

            /_/_/_/\___/\____/\_,_/\__/

                 moOde audio player

              Release 6.5.0 2020-04-21

                (C) 2014 Tim Curtis

The programs included with Moode are free software; the

exact distribution terms for each program are described

in the individual files in /usr/share/doc/*/copyright.

Moode comes with absolutely no warranties expressed or

implied, or any other guarantees.

Last login: Wed Apr 22 10:35:52 2020 from 192.168.1.125

pi@rp2:~ $ moodeutl -l

20200422 103828 worker: -- Start

20200422 103828 worker: Successfully daemonized

20200422 103829 worker: Integrity check (passed)

20200422 103829 worker: Session loaded

20200422 103829 worker: Debug logging (off)

20200422 103829 worker: Device raw: (0:IQaudIODAC|1:empty|i2s:IQaudIO Pi-DigiAMP+)

20200422 103829 worker: Device cfg: (IQaudIO Pi-DigiAMP+|0|0|Digital|0)

20200422 103829 worker: ALSA volume set to (0%)

20200422 103829 worker: -- System

20200422 103832 worker: Host     (rp2)

20200422 103832 worker: moOde    (6.5.0 2020-04-21)

20200422 103832 worker: Raspbian (10.3)

20200422 103832 worker: Kernel   (4.19.115-v7+ #1305)

20200422 103832 worker: Platform (Pi-2B 1GB v1.1)

20200422 103832 worker: ARM arch (armv7l, 32-bit kernel)

20200422 103832 worker: MPD ver  (0.21.22)

20200422 103832 worker: CPU gov  (ondemand)

20200422 103832 worker: USB boot not available

20200422 103832 worker: File system expanded

20200422 103832 worker: HDMI port off

20200422 103835 worker: File check (OK)

20200422 103835 worker: -- Network

20200422 103835 worker: eth0 exists

20200422 103835 worker: eth0 address not assigned

20200422 103835 worker: wlan0 exists

20200422 103835 worker: wifi country (US)

20200422 103835 worker: wlan0 trying SSID (AirnetN2)

20200422 103835 worker: IP addr (192.168.1.248)

20200422 103836 worker: Netmask (255.255.255.0)

20200422 103836 worker: Gateway (192.168.1.1)

20200422 103836 worker: Pri DNS (192.168.1.1)

20200422 103836 worker: Domain  (home)

20200422 103836 worker: -- Audio

20200422 103836 worker: IQaudIO Pi-DigiAMP+ unmuted

20200422 103836 worker: ALSA card number (0)

20200422 103836 worker: Audio output (I2S audio device)

20200422 103836 worker: Audio device (IQaudIO Pi-DigiAMP+)

20200422 103837 worker: Audio formats (S16_LE, S24_LE, S32_LE)

20200422 103837 worker: ALSA mixer name (Digital)

20200422 103837 worker: MPD volume control (hardware)

20200422 103837 worker: Hdwr volume controller exists

20200422 103837 worker: Max ALSA volume (100%)

20200422 103837 worker: Reset renderer active flags

20200422 103837 worker: -- MPD

20200422 103838 worker: MPD conf updated

20200422 103838 worker: MPD started

20200422 103839 worker: MPD accepting connections

20200422 103839 worker: Configure MPD outputs

20200422 103839 worker: MPD output 1 ALSA default (on)

20200422 103839 worker: MPD output 2 ALSA crossfeed (off)

20200422 103839 worker: MPD output 3 ALSA parametric eq (off)

20200422 103839 worker: MPD output 4 ALSA graphic eq (off)

20200422 103839 worker: MPD output 5 ALSA polarity inversion (off)

20200422 103839 worker: MPD output 6 ALSA bluetooth (off)

20200422 103839 worker: MPD output 7 HTTP stream (off)

20200422 103839 worker: MPD crossfade (off)

20200422 103839 worker: -- Feature availability

20200422 103839 worker: Source select (available)

20200422 103839 worker: Source select (source: MPD)

20200422 103839 worker: Source select (output: I2S audio device)

20200422 103840 worker: Bluetooth (available)

20200422 103840 worker: Airplay renderer (available)

20200422 103840 worker: Airplay renderer (started)

20200422 103840 worker: Spotify renderer (available)

20200422 103840 worker: Squeezelite renderer (available)

20200422 103840 worker: UPnP renderer (available)

20200422 103840 worker: DLNA server (available)

20200422 103840 worker: UPnP browser (available)

20200422 103840 worker: Audio scrobbler (available)

20200422 103840 worker: GPIO button handler (available)

20200422 103840 worker: -- Music sources

20200422 103840 worker: USB sources (none attached)

20200422 103841 worker: NAS and UPnP sources (mountall initiated)

20200422 103841 worker: -- Miscellaneous

20200422 103842 worker: Rotary encoder on (100 2 3 23 24)

20200422 103842 worker: USB volume knob (Off)

20200422 103842 worker: USB auto-mounter (udisks-glue)

20200422 103842 worker: LED0 (On)

20200422 103842 worker: LED1 (On)

20200422 103842 worker: Saved MPD vol level (0)

20200422 103842 worker: Preamp volume level (0)

20200422 103842 worker: MPD volume level (15) restored

20200422 103843 worker: ALSA volume level (53%)

20200422 103843 worker: Auto-play (Off)

20200422 103843 worker: Auto-shuffle service (Off)

20200422 103843 worker: Maintenance interval (3 hrs)

20200422 103843 worker: Screen saver activation (Never)

20200422 103843 worker: Session permissions (OK)

20200422 103843 worker: Watchdog started

20200422 103843 worker: Ready

pi@rp2:~ $ dmesg |grep i2s

[    8.378186] snd-rpi-iqaudio-dac soc:sound: pcm512x-hifi <-> 3f203000.i2s mapping ok

pi@rp2:~ $

Login
Username:
Password:	Lost Password?
	Remember me