[bug][JSL]" error at snd_soc_dai_startup on intel-hdmi-hifi1: -16" occured if boot up system with DP connected.

[sinahuang]

Describe the bug
" error at snd_soc_dai_startup on intel-hdmi-hifi1: -16" occured if boot up system with DP connected. And then terminal will be stuck all the time when input any command in terminal. All pipeline can't start to work.

Note: Error not seen if boot up only with HDMI connected. Log as below:
dmesg-hdmi.log

To Reproduce
1.Boot up system with DP connected.
2.Check dmesg.

Reproduce rate
5/5

Expected result
System should work normally and no error info in dmesg.

Actual result
" error at snd_soc_dai_startup on intel-hdmi-hifi1: -16" occured if boot up system with DP connected.
Dmesg:

[    8.471326] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790908
[    8.471354] snd_hda_codec_hdmi ehdaudio0D2: HDMI: hinfo 000000002fa213bb not registered
[    8.471640] snd_hda_codec_hdmi ehdaudio0D2: hda_codec_setup_stream: NID=0x5, stream=0x2, channel=0, format=0x31
[    8.472152] snd_hda_codec_hdmi ehdaudio0D2: ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi1: -16
[    8.472159] snd_hda_codec_hdmi ehdaudio0D2: ASoC: can't open DAI intel-hdmi-hifi1: -16
[    8.955581] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[    8.955605] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[    9.046317] r8169 0000:01:00.0 enp1s0: Link is Up - 100Mbps/Full - flow control off
[    9.046335] IPv6: ADDRCONF(NETDEV_CHANGE): enp1s0: link becomes ready
[    9.455539] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[    9.455567] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   13.107963] rfkill: input handler disabled

Test recipe
Kernel:https://github.com/thesofproject/linux/commits/topic/sof-dev commit: b0c0ab3
FW: https://github.com/thesofproject/sof/commits/master commit: 145d9aa
Tplg: sof-hda-generic-4ch.tplg
Platform:JSL-RVP with ALC700 in HDA mode
dmesg.log
sof_trace.log

[sinahuang]

Might be related with #2084

[sinahuang]

Issue can't be reproduced if boot up system with DP connected after pulseauido disabled and all pipeline can work well.

[kv2019i]

This seems similar to #2084 indeed. Let's check the additional logs with that bug and it might reveal the rootcause for this as well. Suspicious logs here:

[ 8.468405] snd_hda_codec_hdmi ehdaudio0D2: choose cvt 1 for pin nid 4
[...]
[ 8.469664] snd_hda_codec_hdmi ehdaudio0D2: hda_codec_setup_stream: NID=0x3, stream=0x1, channel=0, format=0x31

[kv2019i]

@sinahuang To confirm this either same or different with #2084, could you take the same logs from this JSL case:

• output of "alsa-info" when both monitors are connected
• i915 log
  modprobe conf.d:
  options drm debug=0x1e
  or with kernel cmdline:
  drm.debug=0x1e

[sinahuang]

Attached the I915 log:
drm_log.log

Tried to get the alsa-info , but error shows as below, can't output some alsa info. Attached amixer contents.
amixer.txt

ubuntu@sh-Jasper-Lake-HDA:~$ alsa-info
ALSA Information Script v 0.4.65
--------------------------------

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.

lspci: Unable to load libkmod resources: error -12
cat: '/sys/module/snd_soc_skl_hda_dsp/parameters/*': No such file or directory

[kv2019i]

@sinahuang wrote:

ubuntu@sh-Jasper-Lake-HDA:~$ alsa-info
lspci: Unable to load libkmod resources: error -12
cat: '/sys/module/snd_soc_skl_hda_dsp/parameters/*': No such file or directory

... try running alsa-info as root, that should fix the above.

[kv2019i]

@sinahuang wrote:

Attached the I915 log:
drm_log.log

Thank you! One question: this log does not seem to have the "snd_hda_codec_hdmi ehdaudio0D2: ASoC: can't open DAI intel-hdmi-hifi1: -16" error. Did the error happen when you took the log?

One alternative, maybe instead of "dmesg", you can capture the log with following command:

journalctl -b-0 >system_log.txt

This will capture all kernel and system logs for the current boot. This works even when dmesg buffer overflow and is now available on all our test machines.

[sinahuang]

Attached the system log.
system_log.txt
kern.log
Tried run alsa-info as root , error still can be seen as below:

ubuntu@sh-Jasper-Lake-HDA:~$ sudo alsa-info
ALSA Information Script v 0.4.65
--------------------------------

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.

lspci: Unable to load libkmod resources: error -12
cat: '/sys/module/snd_soc_skl_hda_dsp/parameters/*': No such file or directory

ubuntu@sh-Jasper-Lake-HDA:~$ sudo su
root@sh-Jasper-Lake-HDA:/home/ubuntu# alsa-info
ALSA Information Script v 0.4.65
--------------------------------

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.

lspci: Unable to load libkmod resources: error -12
cat: '/sys/module/snd_soc_skl_hda_dsp/parameters/*': No such file or directory

[plbossart]

lspci: Unable to load libkmod resources: error -12
cat: '/sys/module/snd_soc_skl_hda_dsp/parameters/*': No such file or directory

does this prevent alsa-info from generating a report? if not that's not an error really for SOF.

[kv2019i]

I got a lead on the problem now:
[ 4.633635] snd_hda_codec_hdmi ehdaudio0D2: hdmi: pcm_num set to 5

... that value should not happen and I now suspect a timing raise in the probe sequence. I'll continue to run some tests with a local kernel and will update here again tomorrow.