"I2S SYNC error", then "rcu_sched detected stalls on CPUs/tasks" then crash

[HinTak]

Describe the bug

This is a post-mortem - the headless pi crashed, and the below is what's in syslog after reboot. Apparently the audio / pulseaudio locked up, causing a kernel panic, I think:

Apr 27 21:22:42 raspberrypi kernel: [436512.647215] bcm2835-i2s fe203000.i2s: I2S SYNC error!
Apr 27 21:23:13 raspberrypi kernel: [436533.695109] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
Apr 27 21:23:13 raspberrypi kernel: [436533.695120] rcu: 	1-...0: (0 ticks this GP) idle=f92/1/0x40000000 softirq=2474494/2474494 fqs=720 
Apr 27 21:23:13 raspberrypi kernel: [436533.695123] rcu: 	(detected by 2, t=2102 jiffies, g=8927073, q=31)
Apr 27 21:23:13 raspberrypi kernel: [436533.695131] Sending NMI from CPU 2 to CPUs 1:
Apr 27 21:23:13 raspberrypi kernel: [436543.695841] rcu: rcu_sched kthread starved for 608 jiffies! g8927073 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
Apr 27 21:23:13 raspberrypi kernel: [436543.695844] rcu: RCU grace-period kthread stack dump:
Apr 27 21:23:13 raspberrypi kernel: [436543.695847] rcu_sched       I    0    10      2 0x00000000
Apr 27 21:23:13 raspberrypi kernel: [436543.695869] [<c09c8f5c>] (__schedule) from [<c09c95cc>] (schedule+0x50/0xa8)
Apr 27 21:23:13 raspberrypi kernel: [436543.695877] [<c09c95cc>] (schedule) from [<c09cd584>] (schedule_timeout+0x1d0/0x428)
Apr 27 21:23:13 raspberrypi kernel: [436543.695885] [<c09cd584>] (schedule_timeout) from [<c0291318>] (rcu_gp_kthread+0x4ac/0xa30)
Apr 27 21:23:13 raspberrypi kernel: [436543.695894] [<c0291318>] (rcu_gp_kthread) from [<c02446a0>] (kthread+0x138/0x168)
Apr 27 21:23:13 raspberrypi kernel: [436543.695902] [<c02446a0>] (kthread) from [<c02010ac>] (ret_from_fork+0x14/0x28)
Apr 27 21:23:13 raspberrypi kernel: [436543.695905] Exception stack(0xef923fb0 to 0xef923ff8)
Apr 27 21:23:13 raspberrypi kernel: [436543.695910] 3fa0:                                     00000000 00000000 00000000 00000000
Apr 27 21:23:13 raspberrypi kernel: [436543.695915] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Apr 27 21:23:13 raspberrypi kernel: [436543.695919] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000
Apr 27 21:23:13 raspberrypi rtkit-daemon[8436]: The canary thread is apparently starving. Taking action.
Apr 27 21:23:13 raspberrypi rtkit-daemon[8436]: Demoting known real-time threads.
Apr 27 21:23:13 raspberrypi rtkit-daemon[8436]: Successfully demoted thread 7929 of process 7929 (n/a).
Apr 27 21:23:13 raspberrypi rtkit-daemon[8436]: Demoted 1 threads.
Apr 27 21:24:16 raspberrypi kernel: [436596.745463] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
Apr 27 21:24:16 raspberrypi kernel: [436596.745474] rcu: 	1-...0: (0 ticks this GP) idle=f92/1/0x40000000 softirq=2474494/2474494 fqs=2571 
Apr 27 21:24:16 raspberrypi kernel: [436596.745477] rcu: 	(detected by 2, t=8407 jiffies, g=8927073, q=94)
Apr 27 21:24:16 raspberrypi kernel: [436596.745485] Sending NMI from CPU 2 to CPUs 1:
Apr 27 21:24:16 raspberrypi rtkit-daemon[8436]: The canary thread is apparently starving. Taking action.
Apr 27 21:24:16 raspberrypi systemd[629]: pulseaudio.service: State 'stop-sigterm' timed out. Killing.
Apr 27 21:24:16 raspberrypi rtkit-daemon[8436]: Demoting known real-time threads.
Apr 27 21:24:16 raspberrypi systemd[629]: pulseaudio.service: Killing process 7929 (pulseaudio) with signal SIGKILL.
Apr 27 21:24:16 raspberrypi rtkit-daemon[8436]: Successfully demoted thread 7929 of process 7929 (n/a).
Apr 27 21:24:16 raspberrypi rtkit-daemon[8436]: Demoted 1 threads.
Apr 27 21:25:01 raspberrypi CRON[13171]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Apr 27 21:25:19 raspberrypi kernel: [436659.795835] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
Apr 27 21:25:19 raspberrypi kernel: [436659.795846] rcu: 	1-...0: (0 ticks this GP) idle=f92/1/0x40000000 softirq=2474494/2474494 fqs=4451 
Apr 27 21:25:19 raspberrypi kernel: [436659.795849] rcu: 	(detected by 2, t=14712 jiffies, g=8927073, q=535)
Apr 27 21:25:19 raspberrypi kernel: [436659.795857] Sending NMI from CPU 2 to CPUs 1:
Apr 27 21:25:19 raspberrypi rtkit-daemon[8436]: The canary thread is apparently starving. Taking action.
Apr 27 21:25:19 raspberrypi rtkit-daemon[8436]: Demoting known real-time threads.
Apr 27 21:25:19 raspberrypi rtkit-daemon[8436]: Successfully demoted thread 7929 of process 7929 (n/a).
Apr 27 21:25:19 raspberrypi rtkit-daemon[8436]: Demoted 1 threads.
Apr 27 21:25:19 raspberrypi systemd[1]: systemd-logind.service: Watchdog timeout (limit 3min)!
Apr 27 21:25:19 raspberrypi systemd[1]: systemd-logind.service: Killing process 356 (systemd-logind) with signal SIGABRT.
Apr 27 21:25:20 raspberrypi systemd[1]: systemd-udevd.service: Watchdog timeout (limit 3min)!
Apr 27 21:25:20 raspberrypi systemd[1]: systemd-udevd.service: Killing process 143 (systemd-udevd) with signal SIGABRT.
Apr 27 21:17:04 raspberrypi systemd-modules-load[102]: Inserted module 'snd_soc_seeed_voicecard'
Apr 27 21:17:04 raspberrypi systemd-modules-load[102]: Inserted module 'snd_soc_ac108'
Apr 27 21:17:04 raspberrypi systemd-modules-load[102]: Inserted module 'snd_soc_wm8960'
Apr 27 21:17:04 raspberrypi fake-hwclock[99]: Mon 27 Apr 20:17:01 UTC 2020
Apr 27 21:17:04 raspberrypi systemd-fsck[124]: e2fsck 1.44.5 (15-Dec-2018)
Apr 27 21:17:04 raspberrypi systemd-fsck[124]: rootfs: clean, 272697/939744 files, 2025093/3822976 blocks

To reproduce
Just before it, I was doing aplay -L / arecord -L - the I2S error seems to be a delay action to it - it appears occasionally, but never actually caused a crash in the past.

Expected behaviour
I2S error and pulseaudio/rtkit-daemon shouldn't cause this.

Actual behaviour
pi crashed.

System

raspinfo output - after reboot:

raspinfo.txt

Additional context

This is the audio board attached:
https://github.com/respeaker/seeed-voicecard

[HinTak]

BTW, in the log, the clock jumped backwards on reboot.

[6by9]

Your sound card is using out of tree drivers which means the support burden is really on you or the supplier of that card.

I2S SYNC error! just means that the I2S peripheral is not receiving the audio signal it was expecting to receive. I'm not aware of any reports of sync errors and stalls with other sound cards on 4.19.97-v7l, so I'd be more suspicious of that out of tree driver, or possibly a hardware issue.

If this has worked in the past, have you done a bisect to identify where things started to fail?

[HinTak]

Other than the aplay -L/arecord -L once in a while I left the pi idle and plug-in (for days and weeks); it is hard to see what caused the stall and crash.

Yes, I understand the issue about out of tree drivers.

[HinTak]

Btw, I am actually aware of an I2S error, with a different sound device, and a in-tree driver too.

I think I have seen something more recent, but here is an old one:
Audio-Injector/stereo-and-zero#15

[pelwell]

I2S SYNC error is just the generic symptom of an unhappy I2S sound card, the emphasis being on symptom. There can be many different causes, so in itself it doesn't tell us very much.

[JulyIghor]

Got the same on Ubuntu Core 20.04

[pelwell]

With which Pi? And which soundcard? Are you using PulseAudio? Try and anticipate some of the obvious questions.

[JulyIghor]

With which Pi? And which soundcard? Are you using PulseAudio? Try and anticipate some of the obvious questions.

Raspberry Pi 3B+
I just flash official 64 bit Ubuntu Core 20.04 to USB flash drive. USB devices only keyboard and boot flash drive.
Next installed apt install net-tools avahi-daemon apt-file bluez blueman bluetooth bluez-tools
Then I just tried to reboot from the terminal, and it failed to shutdown with exactly the same issue.

[JulyIghor]

And this issue https://askubuntu.com/questions/1156466/cannot-find-bluetooth-device-ubuntu-core-on-raspberry-pi-3-b is still there, I have to create symlink to make bluetooth work, so if anyone can affect it, please do it.

[pelwell]

You got an I2S SYNC error with no external sound card or overlay? That is hard to believe.

The other issue isn't present in Raspbian, so this isn't the right place to report it.

[HinTak]

Yes, the ubuntu packaging issue should be filed at ubuntu's launchpad.

[JulyIghor]

You got an I2S SYNC error with no external sound card or overlay? That is hard to believe.

The other issue isn't present in Raspbian, so this isn't the right place to report it.

no sound card, and I can't remember was there I2S SYNC or no, so next time I'll send more info
sorry if made any confusion

[lybtongji]

the same problem. RPi 3B+ with ubuntu server 20.04 64bit. just installed samba.

[JulyIghor]

the same problem. RPi 3B+ with ubuntu server 20.04 64bit. just installed samba.

I give up with Ubuntu, switched to https://www.reddit.com/r/raspberry_pi/comments/gs6omd/raspberry_pi_os_for_arm64_finally_released/

[HinTak]

I suspect that this problem with 4.19.97 is a more mundane version of respeaker/seeed-voicecard#251 . The problem has gotten more serious over time, as multi-tasking context switching for the pi improves (and the seeed voicecard driver wants to hold onto the CPU with spinlocks...).