Kernel 6.6.y and DAC Allo Piano 2.1+Kali fails init

[foonerd]

Describe the bug

It seems that sound/soc/bcm/allo-piano-dac-plus.c is not parsing parameters for alsa use. What I can observe is that the dtoverlay partly fails register the card:

[   19.836848] snd-allo-piano-dac-plus soc:sound: snd_soc_register_card() failed: -517
[   19.882239] snd-allo-piano-dac-plus soc:sound: snd_soc_register_card() failed: -517

However module somewhat loads:
ls -la /sys/module/snd_soc_allo_piano_dac_plus/

drwxr-xr-x   6 root root    0 Dec 10 08:08 .
drwxr-xr-x 150 root root    0 Jan  1  1970 ..
-r--r--r--   1 root root 4096 Dec 10 08:08 coresize
drwxr-xr-x   2 root root    0 Dec 10 08:08 drivers
drwxr-xr-x   2 root root    0 Dec 10 08:08 holders
-r--r--r--   1 root root 4096 Dec 10 08:08 initsize
-r--r--r--   1 root root 4096 Dec 10 08:08 initstate
drwxr-xr-x   2 root root    0 Dec 10 08:08 notes
-r--r--r--   1 root root 4096 Dec 10 08:08 refcnt
drwxr-xr-x   2 root root    0 Dec 10 08:08 sections
-r--r--r--   1 root root 4096 Dec 10 08:08 srcversion
-r--r--r--   1 root root 4096 Dec 10 08:08 taint
--w-------   1 root root 4096 Dec 10 08:08 uevent

Simple test with alsa-info shows that the expected DAC's control parameters are missing:

ALSA Information Script v 0.5.1
--------------------------------

This script visits the following commands/files to collect diagnostic
information about your ALSA installation and sound related hardware.

  dmesg
  lspci
  aplay
  amixer
  alsactl
  rpm, dpkg
  /proc/asound/
  /sys/class/sound/
  ~/.asoundrc (etc.)

See '/usr/sbin/alsa-info --help' for command line options.

cat: /tmp/alsa-info.2lPuin51C4/acpidevicestatus.tmp: No such file or directory
pgrep: pattern that searches for process name longer than 15 characters will result in zero matches
Try `pgrep -f' option to match against the complete command line.
cat: '/sys/module/snd_soc_allo_piano_dac_plus/parameters/*': No such file or directory

In addition, there seems to be a deadlock after module load preventing init level change.

Steps to reproduce the behaviour

Load overlay with config.txt:

# Enable audio (loads snd_bcm2835)
dtparam=audio=off
[all]
dtoverlay=allo-piano-dac-plus-pcm512x-audio

Load manually:

sudo dtoveraly allo-piano-dac-plus-pcm512x-audio

Device (s)

Raspberry Pi 3 Mod. B+, Raspberry Pi 4 Mod. B, Raspberry Pi 400, Raspberry Pi 5, Raspberry Pi CM4, Raspberry Pi CM4 Lite, Other

System

cat /etc/rpi-issue

Raspberry Pi reference 2024-07-04
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 48efb5fc5485fafdc9de8ad481eb5c09e1182656, stage5

vcgencmd version

Nov 26 2024 12:54:19 
Copyright (c) 2012 Broadcom
version 2ae30f53898ae2f1ba77ff570a92991bedfb0398 (clean) (release) (start)

uname -a

Linux bookworm 6.6.62+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.62-1+rpt1 (2024-11-25) aarch64 GNU/Linux

Logs

dmesg shows continuously:

[  242.652712] INFO: task alsactl:514 blocked for more than 120 seconds.
[  242.652754]       Tainted: G         C         6.6.62+rpt-rpi-v8 #1 Debian 1:6.6.62-1+rpt1
[  242.652766] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  242.652773] task:alsactl         state:D stack:0     pid:514   ppid:1      flags:0x00000805
[  242.652800] Call trace:
[  242.652810]  __switch_to+0xe0/0x148
[  242.652841]  __schedule+0x37c/0xd60
[  242.652856]  schedule+0x64/0x108
[  242.652871]  schedule_preempt_disabled+0x2c/0x50
[  242.652893]  rwsem_down_read_slowpath+0x214/0x528
[  242.652915]  down_read+0xac/0xc0
[  242.652931]  snd_soc_card_get_kcontrol+0x34/0xc0 [snd_soc_core]
[  242.653171]  snd_soc_limit_volume+0x2c/0x80 [snd_soc_core]
[  242.653360]  pcm512x_set_reg_master+0x110/0x138 [snd_soc_allo_piano_dac_plus]
[  242.653401]  snd_ctl_elem_write+0xfc/0x208 [snd]
[  242.653508]  snd_ctl_ioctl+0x14c/0x920 [snd]
[  242.653598]  __arm64_sys_ioctl+0xb4/0x100
[  242.653619]  invoke_syscall+0x50/0x128
[  242.653642]  el0_svc_common.constprop.0+0xc8/0xf0
[  242.653662]  do_el0_svc+0x24/0x38
[  242.653681]  el0_svc+0x38/0xd0
[  242.653702]  el0t_64_sync_handler+0x100/0x130
[  242.653723]  el0t_64_sync+0x190/0x198
[  242.653745] INFO: task alsactl:532 blocked for more than 120 seconds.
[  242.653758]       Tainted: G         C         6.6.62+rpt-rpi-v8 #1 Debian 1:6.6.62-1+rpt1
[  242.653768] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  242.653775] task:alsactl         state:D stack:0     pid:532   ppid:1      flags:0x00000004
[  242.653796] Call trace:
[  242.653803]  __switch_to+0xe0/0x148
[  242.653820]  __schedule+0x37c/0xd60
[  242.653834]  schedule+0x64/0x108
[  242.653849]  schedule_preempt_disabled+0x2c/0x50
[  242.653865]  rwsem_down_write_slowpath+0x32c/0x6d8
[  242.653888]  down_write+0x98/0xa8
[  242.653906]  snd_ctl_release+0x74/0x130 [snd]
[  242.653996]  __fput+0xc4/0x290
[  242.654017]  __fput_sync+0x58/0x70
[  242.654037]  __arm64_sys_close+0x40/0x90
[  242.654056]  invoke_syscall+0x50/0x128
[  242.654076]  el0_svc_common.constprop.0+0x48/0xf0
[  242.654095]  do_el0_svc+0x24/0x38
[  242.654113]  el0_svc+0x38/0xd0
[  242.654133]  el0t_64_sync_handler+0x100/0x130
[  242.654154]  el0t_64_sync+0x190/0x198
[  242.654221] INFO: task wireplumber:989 blocked for more than 120 seconds.
[  242.654233]       Tainted: G         C         6.6.62+rpt-rpi-v8 #1 Debian 1:6.6.62-1+rpt1
[  242.654243] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  242.654251] task:wireplumber     state:D stack:0     pid:989   ppid:961    flags:0x00000804
[  242.654271] Call trace:
[  242.654277]  __switch_to+0xe0/0x148
[  242.654293]  __schedule+0x37c/0xd60
[  242.654308]  schedule+0x64/0x108
[  242.654322]  schedule_preempt_disabled+0x2c/0x50
[  242.654338]  rwsem_down_write_slowpath+0x32c/0x6d8
[  242.654356]  down_write+0x98/0xa8
[  242.654372]  snd_ctl_release+0x74/0x130 [snd]
[  242.654467]  __fput+0xc4/0x290
[  242.654488]  __fput_sync+0x58/0x70
[  242.654507]  __arm64_sys_close+0x40/0x90
[  242.654525]  invoke_syscall+0x50/0x128
[  242.654544]  el0_svc_common.constprop.0+0xc8/0xf0
[  242.654563]  do_el0_svc+0x24/0x38
[  242.654583]  el0_svc+0x38/0xd0
[  242.654603]  el0t_64_sync_handler+0x100/0x130
[  242.654623]  el0t_64_sync+0x190/0x198
[  363.484702] INFO: task alsactl:514 blocked for more than 241 seconds.
[  363.484745]       Tainted: G         C         6.6.62+rpt-rpi-v8 #1 Debian 1:6.6.62-1+rpt1
[  363.484758] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Additional context

No response

[foonerd]

The last working kernel version was 6.1.y.
Checked with a simple overlay allo-piano-dac-pcm512x-audio and a single chip channel loads with a simplified controls. It leads me to believe, that the switch part is not functioning as it is meant to be.

[pelwell]

517 is EPROBEDEFER, which means "not yet" - the kernel will try again later. It's nice if drivers suppress those error messages as they can be confusing, but otherwise I don['t see anything wrong there. The stall is probably caused by something failing to release a mutex.

Like most of the drivers we host in our kernel, we can't offer any support for them unless they reveal an underlying problem in the bits we do maintain. Our involvement consists of forward-porting the patches to new kernel versions, which is basically just a matter of getting them to compile again when the APIs change.

Allo seems to be long gone - your best hope would be that one of the users out there has some coding experience. Even a relative novice could learn quite a bit about the problem by scattering a few pr_info() calls around the driver.

[foonerd]

Thank you for looking into this. Appreciated. Being a "novice" as you mention I can dive into the module, however will need a bit of guidance: mutex. What troubleshooting steps or actions would you suggest?

[pelwell]

Here's a rough plan of action:

1. After booting your current kernel, run dmesg -l err,warn and look for any messages that might be relevant.
2. Once the error has occurred, run that dmesg again, and look for additions. Report your findings.
3. As you'll be building your own kernel you should use the fastest Pi you have, which looks to be a Pi 5. To avoid the need to set up a cross-compiler, I recommend you use a 64-bit image (to match the 64-bit kernel). Just in case something goes disastrously wrong, you might want to install a fresh image to a spare card - even a 64-bit Lite image would be enough.
4. Follow the kernel build instructions here: https://www.raspberrypi.com/documentation/computers/linux_kernel.html#building
   You need the "Natively build a kernel" instructions.
5. Once compilation has completed, follow the installation steps and verify that it boots.
6. Now we're going trace all the snd_soc_... calls. At the top of the file, after the last #include, add:

#define snd_soc_component_read(c, r) my_snd_soc_component_read(c, r, __LINE__)
#define snd_soc_component_write(c, r, v) my_snd_soc_component_write(c, r, v, __LINE__)
static unsigned int my_snd_soc_component_read(struct snd_soc_component *component,
				      unsigned int reg, int line);
static int my_snd_soc_component_write(struct snd_soc_component *component,
			    unsigned int reg, unsigned int val, int line);

7. At the end of the file (before MODULE_AUTHOR should be OK), put this:

#undef snd_soc_component_read
#undef snd_soc_component_write

static unsigned int my_snd_soc_component_read(struct snd_soc_component *component,
				      unsigned int reg, int line)
{
	unsigned int val;
	pr_info("< read %x (%d)\n", reg, line);
	val = snd_soc_component_read(component, reg);
	pr_info("> read %x -> %x (%d)\n", reg, val, line);
	return val;
}

static int my_snd_soc_component_write(struct snd_soc_component *component,
			    unsigned int reg, unsigned int val, int line)
{
	int ret;
	pr_info("< write %x = %x (%d)\n", reg, val, line);
	ret = snd_soc_component_write(component, reg, val);
	pr_info("> write %x = %x ret %d (%d)\n", reg, val, ret, line);
	return ret;
}

8. Rebuild and reinstall the kernel (it should be quick this time since you've only changed one file), and confirm that you are seeing messages (dmesg -l err).
9. Run it until you get a failure, then dmesg -l err,warn | pastebinit (you may need to sudo apt install pastebinit first).

[foonerd]

Thank you for the steps. This round, the module was built against "stock" Pi kernel - 6.6.62-v7+ #1816 using cross-compiler.

load dtoverlay -> http://paste.debian.net/1339146/
after reboot on alsa test -> http://paste.debian.net/1339151/

I would expect a bit more output at this time, however the test was on Pi 3B+, moving to Pi5 or CM5 to speed-up the native build work.

[foonerd]

Stock kernel:
uname -a
Linux foopi 6.6.62+rpt-rpi-2712 #1 SMP PREEMPT Debian 1:6.6.62-1+rpt1 (2024-11-25) aarch64 GNU/Linux

dmesg -l err,warn

No overlays	DAC overlay dynamic	DAC overlay reboot
https://paste.debian.net/hidden/6fb41fac/	https://paste.debian.net/hidden/e3bfc68c/	https://paste.debian.net/hidden/81078b39/

There are no new messages from test other than task alsactl:67778 blocked for more than xxx seconds.
On shutdown/reboot the alsa-restore.service stop job waits for over 5 min; hard reset.

[foonerd]

Kernel from repo:
uname -a
Linux foopi 6.6.63-v8-16k+ #1 SMP PREEMPT Tue Dec 10 13:25:12 GMT 2024 aarch64 GNU/Linux

dmesg -l err,warn

No overlays	DAC overlay dynamic	DAC overlay reboot
https://paste.debian.net/hidden/55089d41/	https://paste.debian.net/hidden/4e15b3e3/	https://paste.debian.net/hidden/f6ed63d9/

Same behaviour as before.

[pelwell]

Odd. Can you put another pr_err (any message you like) before the "return 0;" at the end of snd_allo_piano_dac_probe? That should confirm whether the driver initialisation is completing or not.

[foonerd]

Kernel with updated module:
uname -a
Linux foopi 6.6.63-v8-16k+ #1 SMP PREEMPT Tue Dec 10 13:25:12 GMT 2024 aarch64 GNU/Linux

dmesg -l err,warn

No overlays	DAC overlay dynamic	DAC overlay reboot
https://paste.debian.net/hidden/a4c4c1a0/	https://paste.debian.net/hidden/44f61fe7/	https://paste.debian.net/hidden/e8d35d5f/

Same behaviour as before.

[foonerd]

Odd. Can you put another pr_err (any message you like) before the "return 0;" at the end of snd_allo_piano_dac_probe? That should confirm whether the driver initialisation is completing or not.

                if ((mute_gpio[0]) && (mute_gpio[1]))
                        snd_allo_piano_gpio_mute(&snd_allo_piano_dac);
                pr_err("DAC issue #6527\n");

                return 0;

Result: https://paste.debian.net/hidden/0aaf8bb3/

Looks like it does.

[pelwell]

(I'll take your word that there is no change - you don't need to upload the logs each time)
Let's just double check that all the probe calls are failing - add another message at the start of snd_allo_piano_dac_probe, then if we only see it twice followed by two -517s then we know that the instantiation never succeeds.

[6by9]

sudo cat /sys/kernel/debug/devices_deferred should also tell you if there are still outstanding devices that are deferred. (The dependency will only be listed if the driver has used dev_err_probe though)

[foonerd]

sudo cat /sys/kernel/debug/devices_deferred should also tell you if there are still outstanding devices that are deferred. (The dependency will only be listed if the driver has used dev_err_probe though)

Nothing, just empty:

foonerd@foopi:~ $ sudo cat /sys/kernel/debug/devices_deferred
foonerd@foopi:~ $ sudo ls -la /sys/kernel/debug/devices_deferred
-r--r--r-- 1 root root 0 Jan  1  1970 /sys/kernel/debug/devices_deferred

[pelwell]

(The dependency will only be listed if the driver has used dev_err_probe though)

It doesn't.

[foonerd]

add another message at the start of snd_allo_piano_dac_probe, then if we only see it twice followed by two -517s then we know that the instantiation never succeeds.

This is getting interesting - https://paste.debian.net/hidden/168f11aa/

Purely boot only, nothing touched... yet.