[BUG][ADL-N] Kernel panic when echo reference stream is opend

[Vamshigopal]

Steps to reproduce:
start echo reference capture

Expected result:
Echo reference capture should take the feedback from speaker.

Actual result:
Seeing BUG: kernel NULL pointer dereference, address: 0000000000000000
with kernel panic.

logs:
ramoops.log

kernel:
https://chromium.googlesource.com/chromiumos/third_party/kernel/+/refs/heads/chromeos-5.15

Codec:
max98360

[Vamshigopal]

[ 94.483736] BUG: kernel NULL pointer dereference, address: 0000000000000000
[ 94.483753] #PF: supervisor read access in kernel mode
[ 94.483759] #PF: error_code(0x0000) - not-present page
[ 94.483765] PGD 0 P4D 0
[ 94.483773] Oops: 0000 [#1] PREEMPT SMP NOPTI
[ 94.483781] CPU: 0 PID: 4626 Comm: arecord Tainted: G U 5.15.81-15079-g6808275160f6-dirty #23 7f56a0459ce6561741b760165e2a1814d18b7858
[ 94.483790] Hardware name: Google Nivviks/Nivviks, BIOS Google_Nivviks.15224.0.0 10/31/2022
[ 94.483796] RIP: 0010:dpcm_process_paths+0x1c4/0x585
[ 94.483808] Code: 18 03 00 00 48 8b 84 10 d0 00 00 00 49 8b 8c 24 f8 05 00 00 48 89 55 b0 48 8b 9c 11 d0 00 00 00 48 8b 00 80 b8 31 07 00 00 00 <48> 8b 03 8a 80 31 07 00 00 74 27 84 c0 75 2b 49 8b 3c 24 48 c7 c6
[ 94.483815] RSP: 0018:ffffb9c705c6f9d0 EFLAGS: 00010202
[ 94.483820] RAX: ffffa2ac2fe5c800 RBX: 0000000000000000 RCX: ffffa2ac2fe58000
[ 94.483825] RDX: 0000000000000318 RSI: ffffffffc06c8248 RDI: ffffa2ac419d7028
[ 94.483830] RBP: ffffb9c705c6fa60 R08: 0000000000000060 R09: ffffa2ac4378b9c0
[ 94.483835] R10: ffffa2ac4186a800 R11: ffffffffbb6e5b7d R12: ffffa2ac3c936028
[ 94.483839] R13: 0000000000000003 R14: ffffa2ac11c42800 R15: 0000000000000001
[ 94.483844] FS: 00007cb4a52d4b80(0000) GS:ffffa2ac7ba00000(0000) knlGS:0000000000000000
[ 94.483850] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 94.483855] CR2: 0000000000000000 CR3: 0000000142318001 CR4: 0000000000770ef0
[ 94.483860] PKRU: 55555554
[ 94.483864] Call Trace:
[ 94.483871]
[ 94.483882] dpcm_fe_dai_open+0x8f/0x791
[ 94.483891] ? __get_free_pages+0x16/0x3a
[ 94.483901] snd_pcm_open_substream+0x554/0x7f2
[ 94.483911] snd_pcm_open+0xd2/0x1fa
[ 94.483917] ? sched_dynamic_update+0x23f/0x23f
[ 94.483925] snd_pcm_capture_open+0x43/0x68
[ 94.483933] chrdev_open+0xcb/0x1c7
[ 94.483943] do_dentry_open+0x270/0x362
[ 94.483950] path_openat+0xa8b/0xc42
[ 94.483958] ? avc_has_extended_perms+0x2f7/0x488
[ 94.483967] do_filp_open+0xa3/0x116
[ 94.483977] do_sys_openat2+0x8e/0x1bd
[ 94.483983] do_sys_open+0x5f/0x7d
[ 94.483988] do_syscall_64+0x55/0x9d
[ 94.483996] ? exit_to_user_mode_prepare+0x3c/0x8b
[ 94.484003] entry_SYSCALL_64_after_hwframe+0x61/0xcb
[ 94.484012] RIP: 0033:0x7cb4a546b55a
[ 94.484018] Code: 25 00 00 41 00 3d 00 00 41 00 74 44 64 8b 04 25 18 00 00 00 85 c0 75 58 44 89 e2 4c 89 ee bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 77 7e 48 8b 4d b8 64 48 2b 0c 25 28 00 00 00 0f
[ 94.484024] RSP: 002b:00007fffe0525e60 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 94.484030] RAX: ffffffffffffffda RBX: 0000000000080802 RCX: 00007cb4a546b55a
[ 94.484035] RDX: 0000000000080802 RSI: 00007fffe0526030 RDI: 00000000ffffff9c
[ 94.484039] RBP: 00007fffe0525ed0 R08: 0000000000000000 R09: 00007fffe0525c67
[ 94.484044] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000080802
[ 94.484048] R13: 00007fffe0526030 R14: 00007cb4a5580b8d R15: 0000000000000000
[ 94.484053]
[ 94.484057] Modules linked in: uinput veth snd_soc_sof_nau8825 snd_soc_intel_hda_dsp_common snd_soc_intel_sof_maxim_common snd_sof_probes snd_soc_dmic cros_ec_ishtp intel_ishtp_loader intel_ishtp_hid 8021q snd_hda_codec_hdmi xt_cgroup snd_sof_pci_intel_tgl snd_sof_intel_hda_common snd_sof_intel_hda soundwire_intel soundwire_generic_allocation soundwire_cadence snd_sof_pci snd_sof_xtensa_dsp snd_soc_hdac_hda snd_soc_acpi_intel_match snd_soc_acpi snd_hda_ext_core snd_sof snd_sof_utils soundwire_bus snd_intel_dspcfg snd_intel_sdw_acpi snd_hda_codec snd_hwdep snd_hda_core mei_hdcp uvcvideo xt_MASQUERADE videobuf2_vmalloc videobuf2_v4l2 videobuf2_memops videobuf2_common rfcomm snd_soc_nau8825 cros_ec_typec intel_pmc_mux snd_soc_max98357a roles typec iwlwifi intel_ish_ipc intel_ishtp fuse ip6table_nat cmac algif_hash algif_skcipher af_alg cfg80211 iio_trig_sysfs cros_ec_lid_angle cros_ec_sensors cros_ec_sensors_core industrialio_triggered_buffer kfifo_buf industrialio cros_ec_sensorhub
[ 94.484140] lzo_rle lzo_compress zram r8152 mii btusb btrtl btintel btmtk btbcm bluetooth ecdh_generic ecc joydev
[ 94.486986] gsmi: Log Shutdown Reason 0x03
[ 94.486991] CR2: 0000000000000000
[ 94.486995] ---[ end trace 32103bb6f6709909 ]---
[ 94.498330] RIP: 0010:dpcm_process_paths+0x1c4/0x585
[ 94.498336] Code: 18 03 00 00 48 8b 84 10 d0 00 00 00 49 8b 8c 24 f8 05 00 00 48 89 55 b0 48 8b 9c 11 d0 00 00 00 48 8b 00 80 b8 31 07 00 00 00 <48> 8b 03 8a 80 31 07 00 00 74 27 84 c0 75 2b 49 8b 3c 24 48 c7 c6
[ 94.498339] RSP: 0018:ffffb9c705c6f9d0 EFLAGS: 00010202
[ 94.498343] RAX: ffffa2ac2fe5c800 RBX: 0000000000000000 RCX: ffffa2ac2fe58000
[ 94.498346] RDX: 0000000000000318 RSI: ffffffffc06c8248 RDI: ffffa2ac419d7028
[ 94.498349] RBP: ffffb9c705c6fa60 R08: 0000000000000060 R09: ffffa2ac4378b9c0
[ 94.498351] R10: ffffa2ac4186a800 R11: ffffffffbb6e5b7d R12: ffffa2ac3c936028
[ 94.498354] R13: 0000000000000003 R14: ffffa2ac11c42800 R15: 0000000000000001
[ 94.498357] FS: 00007cb4a52d4b80(0000) GS:ffffa2ac7ba00000(0000) knlGS:0000000000000000
[ 94.498360] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 94.498363] CR2: 0000000000000000 CR3: 0000000142318001 CR4: 0000000000770ef0
[ 94.498366] PKRU: 55555554
[ 94.498369] Kernel panic - not syncing: Fatal exception
[ 94.498420] Kernel Offset: 0x39c00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[ 94.498811] gsmi: Log Shutdown Reason 0x02

[kv2019i]

@Vamshigopal Any occurence data? Can this be reproduced?

[Vamshigopal]

@kv2019i reproduces always, 1/1 tries

arecord -Dhw:0,6 -f s16_le -c 2 -r 48000 /tmp/rec.wav

localhost ~ # arecord -l
**** List of CAPTURE Hardware Devices ****
card 0: sofrt5682 [sof-rt5682], device 1: Headset () []
Subdevices: 1/1
Subdevice #0: subdevice #0
card 0: sofrt5682 [sof-rt5682], device 6: EchoRef () []
Subdevices: 1/1
Subdevice #0: subdevice #0
card 0: sofrt5682 [sof-rt5682], device 7: Bluetooth () []
Subdevices: 1/1
Subdevice #0: subdevice #0
card 0: sofrt5682 [sof-rt5682], device 99: DMIC () []
Subdevices: 1/1
Subdevice #0: subdevice #0
card 0: sofrt5682 [sof-rt5682], device 100: DMIC16kHz (*) []
Subdevices: 1/1
Subdevice #0: subdevice #0

[sathyap-chrome]

@kv2019i if we use RPL001 FW ( tried on ADL -P) with below kernel, then the panic comes on boot itself. Same signature.
note that there is no Echo ref device in UCM too.

https://github.com/dineshXadireddi/Backport-series/commits/working_branch_New_Nov26 is the kernel used for v5.10

[Vamshigopal]

it fails exactly when finding BE for corresponding FE
dpcm_fe_dai_open() -> dpcm_process_paths

[kv2019i]

I could reproduce the problem. It seems there are multiple issues in upstream kernel with this topology. The use-case does work if playback is started first on PCM0, but the mechanism to return -ENODATA on PCM6 if PCM0 is not running, is not working correctly. I'll send a PR to fix the kernel issue (so it doesn't crash), but it would seem additional fixes are needed on FW side.

CRAS should open the PCMs in correct order though (the oops needs to be fixed of course).

[sathyap-chrome]

@kv2019i the sequence in CRAS is to start this only after starting speaker playback. But there should be no panic on starting this out of sequence. Error out is the right way.

[kv2019i]

#4085 fixes the kernel oops. I'm still looking at why FW times out to TRIG_STOP after -ENODATA.

[kv2019i]

FW side fix to handle the IPC timeout -> thesofproject/sof#6753