Repository navigation
Closed
Labels
P1Blocker bugs or important featuresBlocker bugs or important features
Description
root@fedora ~]# SOF_LOGGING=none TPLG=/lib/firmware/intel/avs-tplg/sof-hda-generic.tplg /root/sof-test/test-case/check-kmod-load-unload.sh -l 1
2022-01-28 00:47:42 UTC [INFO] ===== Starting iteration 1 of 1 =====
2022-01-28 00:47:42 UTC [INFO] wait dsp power status to become suspended
2022-01-28 00:47:42 UTC [INFO] run kmod/sof-kmod-remove.sh
WARNING: running as root is not supported
RMMOD snd_usb_audio
SKIP snd_hda_intel not loaded
RMMOD snd_sof_pci_intel_tng
SKIP snd_sof_pci_intel_skl not loaded
RMMOD snd_sof_pci_intel_apl
RMMOD snd_sof_pci_intel_cnl
RMMOD snd_sof_pci_intel_icl
RMMOD snd_sof_pci_intel_tgl
RMMOD snd_sof_acpi_intel_byt
RMMOD snd_sof_acpi_intel_bdw
RMMOD snd_sof_intel_hda_common
RMMOD snd_sof_acpi
RMMOD snd_sof_pci
RMMOD snd_sof_intel_atom
SKIP snd_soc_catpt not loaded
SKIP snd_intel_sst_acpi not loaded
SKIP snd_intel_sst_core not loaded
SKIP snd_soc_sst_atom_hifi2_platform not loaded
SKIP snd_soc_skl not loaded
SKIP snd_sof_intel_byt not loaded
SKIP snd_sof_intel_bdw not loaded
SKIP snd_sof_intel_hda_common not loaded
RMMOD snd_sof_intel_hda
SKIP snd_sof_intel_ipc not loaded
RMMOD snd_sof_xtensa_dsp
RMMOD snd_soc_acpi_intel_match
SKIP snd_soc_sof_rt5682 not loaded
SKIP snd_soc_sof_da7219_max98373 not loaded
SKIP snd_soc_sst_bdw_rt5677_mach not loaded
SKIP snd_soc_sst_broadwell not loaded
SKIP snd_soc_sst_bxt_da7219_max98357a not loaded
SKIP snd_soc_sst_sof_pcm512x not loaded
SKIP snd_soc_sst_bxt_rt298 not loaded
SKIP snd_soc_sst_sof_wm8804 not loaded
SKIP snd_soc_sst_byt_cht_da7213 not loaded
SKIP snd_soc_sst_byt_cht_es8316 not loaded
SKIP snd_soc_sst_bytcr_rt5640 not loaded
SKIP snd_soc_sst_bytcr_rt5651 not loaded
SKIP snd_soc_sst_cht_bsw_max98090_ti not loaded
SKIP snd_soc_sst_cht_bsw_nau8824 not loaded
SKIP snd_soc_sst_cht_bsw_rt5645 not loaded
SKIP snd_soc_sst_cht_bsw_rt5672 not loaded
SKIP snd_soc_sst_glk_rt5682_max98357a not loaded
SKIP snd_soc_cml_rt1011_rt5682 not loaded
RMMOD snd_soc_skl_hda_dsp
SKIP snd_soc_sdw_rt700 not loaded
SKIP snd_soc_sdw_rt711_rt1308_rt715 not loaded
SKIP snd_soc_sof_sdw not loaded
SKIP snd_soc_ehl_rt5660 not loaded
RMMOD snd_soc_intel_hda_dsp_common
SKIP snd_soc_intel_sof_maxim_common not loaded
SKIP snd_sof_probes not loaded
SKIP snd_sof_ipc_test not loaded
RMMOD snd_sof_ipc_flood_test
RMMOD snd_sof_ipc_msg_injector
SKIP snd_sof_dma_trace not loaded
SKIP snd_sof_nocodec not loaded
RMMOD snd_sof
SKIP snd_sof_nocodec not loaded
RMMOD snd_sof_utils
RMMOD snd_soc_da7213
RMMOD snd_soc_da7219
RMMOD snd_soc_pcm512x_i2c
RMMOD snd_soc_pcm512x
SKIP snd_soc_rt274 not loaded
RMMOD snd_soc_rt286
RMMOD snd_soc_rt298
RMMOD snd_soc_rt700
RMMOD snd_soc_rt711
RMMOD snd_soc_rt1308
RMMOD snd_soc_rt1308_sdw
RMMOD snd_soc_rt715
RMMOD snd_soc_rt711_sdca
RMMOD snd_soc_rt1316_sdw
RMMOD snd_soc_rt715_sdca
RMMOD snd_soc_sdw_mockup
RMMOD snd_soc_rt1011
RMMOD snd_soc_rt5640
RMMOD snd_soc_rt5645
RMMOD snd_soc_rt5651
RMMOD snd_soc_rt5660
RMMOD snd_soc_rt5670
RMMOD snd_soc_rt5677
RMMOD snd_soc_rt5677_spi
RMMOD snd_soc_rt5682_sdw
RMMOD snd_soc_rt5682_i2c
RMMOD snd_soc_rt5682
SKIP snd_soc_rt5682s not loaded
RMMOD snd_soc_rl6231
RMMOD snd_soc_rl6347a
RMMOD snd_soc_wm8804_i2c
RMMOD snd_soc_wm8804
RMMOD snd_soc_max98090
RMMOD snd_soc_ts3a227e
RMMOD snd_soc_max98357a
RMMOD snd_soc_max98373_sdw
RMMOD snd_soc_max98373_i2c
RMMOD snd_soc_max98373
RMMOD snd_soc_max98390
RMMOD snd_soc_hdac_hda
RMMOD snd_soc_hdac_hdmi
RMMOD snd_hda_codec_hdmi
RMMOD snd_soc_dmic
RMMOD snd_hda_codec_realtek
RMMOD snd_hda_codec_generic
RMMOD snd_soc_acpi
RMMOD snd_hda_ext_core
RMMOD snd_intel_dspcfg
SKIP soundwire_intel_init not loaded
RMMOD soundwire_intel
RMMOD soundwire_cadence
RMMOD soundwire_generic_allocation
RMMOD regmap_sdw
RMMOD regmap_sdw_mbq
RMMOD soundwire_bus
RMMOD snd_intel_sdw_acpi
RMMOD snd_soc_core
RMMOD snd_hda_codec
RMMOD snd_hda_core
RMMOD snd_hwdep
RMMOD snd_compress
SKIP snd_pcm_dmaengine not loaded
RMMOD snd_pcm
2022-01-28 00:47:44 UTC [INFO] checking for general errors after kmod unload with sof-kernel-log-check tool
declare -- cmd="journalctl_cmd --since=@1643330854"
2022-01-28 00:47:44 UTC [INFO] run kmod/sof_insert.sh
MODPROBE snd_soc_da7213
MODPROBE snd_soc_da7219
MODPROBE snd_soc_pcm512x_i2c
MODPROBE snd_soc_wm8804_i2c
SKIP snd_soc_rt274 (not in tree)
MODPROBE snd_soc_rt286
MODPROBE snd_soc_rt298
MODPROBE snd_soc_rt700
MODPROBE snd_soc_rt711
MODPROBE snd_soc_rt1308
MODPROBE snd_soc_rt1308_sdw
MODPROBE snd_soc_rt715
MODPROBE snd_soc_rt711_sdca
MODPROBE snd_soc_rt1316_sdw
MODPROBE snd_soc_rt715_sdca
MODPROBE snd_soc_sdw_mockup
MODPROBE snd_soc_rt1011
MODPROBE snd_soc_rt5640
MODPROBE snd_soc_rt5645
MODPROBE snd_soc_rt5651
MODPROBE snd_soc_rt5660
MODPROBE snd_soc_rt5670
MODPROBE snd_soc_rt5677
MODPROBE snd_soc_rt5677_spi
MODPROBE snd_soc_rt5682_i2c
MODPROBE snd_soc_rt5682_sdw
MODPROBE snd_soc_max98090
MODPROBE snd_soc_ts3a227e
MODPROBE snd_soc_max98357a
MODPROBE snd_soc_max98373_sdw
MODPROBE snd_soc_max98373_i2c
MODPROBE snd_soc_max98390
MODPROBE snd_sof_acpi_intel_byt
MODPROBE snd_sof_acpi_intel_bdw
MODPROBE snd_sof_pci_intel_tng
MODPROBE snd_sof_pci_intel_apl
MODPROBE snd_sof_pci_intel_cnl
MODPROBE snd_sof_pci_intel_icl
MODPROBE snd_sof_pci_intel_tgl
MODPROBE snd_sof_acpi
MODPROBE snd_sof_pci
MODPROBE snd_usb_audio
2022-01-28 00:47:45 UTC [INFO] checking for general errors after kmod insert with sof-kernel-log-check tool
declare -- cmd="journalctl_cmd --since=@1643330856"
2022-01-28 00:47:45 UTC [INFO] checking if firmware is loaded successfully
2022-01-28 00:47:45 UTC Sub-Test: [INFO] Checking SOF Firmware load info in kernel log
[ 168.740358] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: tplg2: 1 hw_configs found, default id: 3!
[ 168.740360] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: tplg2: 1 hw_configs found, default id: 4!
[ 168.740364] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: tplg2: 1 hw_configs found, default id: 5!
[ 168.740369] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: Parent card not yet available, widget card binding deferred
[ 168.794065] kernel: snd_hda_codec_realtek ehdaudio0D0: autoconfig for ALC3204: line_outs=1 (0x14/0x0/0x0/0x0/0x0) type:speaker
[ 168.794069] kernel: snd_hda_codec_realtek ehdaudio0D0: speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
[ 168.794071] kernel: snd_hda_codec_realtek ehdaudio0D0: hp_outs=1 (0x21/0x0/0x0/0x0/0x0)
[ 168.794072] kernel: snd_hda_codec_realtek ehdaudio0D0: mono: mono_out=0x0
[ 168.794072] kernel: snd_hda_codec_realtek ehdaudio0D0: inputs:
[ 168.794074] kernel: snd_hda_codec_realtek ehdaudio0D0: Headset Mic=0x19
[ 168.794075] kernel: snd_hda_codec_realtek ehdaudio0D0: Headphone Mic=0x1a
[ 168.794076] kernel: snd_hda_codec_realtek ehdaudio0D0: Internal Mic=0x12
[ 168.838301] kernel: snd_hda_codec_realtek ehdaudio0D0: ASoC: sink widget AIF1TX overwritten
[ 168.838307] kernel: snd_hda_codec_realtek ehdaudio0D0: ASoC: source widget AIF1RX overwritten
[ 168.838393] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: creating new PCM HDMI1
[ 168.838395] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: spcm: allocate Gain Playback 3 playback DMA buffer size 0x10000 max 0x10000
[ 168.838417] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: creating new PCM HDMI2
[ 168.838418] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: spcm: allocate Gain Playback 4 playback DMA buffer size 0x10000 max 0x10000
[ 168.838438] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: creating new PCM HDMI3
[ 168.838439] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: spcm: allocate Gain Playback 5 playback DMA buffer size 0x10000 max 0x10000
[ 168.838464] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: creating new PCM HDA Analog
[ 168.838465] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: spcm: allocate Gain Playback 0 playback DMA buffer size 0x10000 max 0x10000
[ 168.838467] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: spcm: allocate Gain Capture 0 capture DMA buffer size 0x10000 max 0x10000
[ 168.838494] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: creating new PCM HDA Digital
[ 168.838495] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: spcm: allocate Gain Playback 1 playback DMA buffer size 0x10000 max 0x10000
[ 168.838497] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: spcm: allocate Gain Capture 1 capture DMA buffer size 0x10000 max 0x10000
[ 168.838546] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: sink widget hifi3 overwritten
[ 168.838549] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: sink widget hifi2 overwritten
[ 168.838552] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: sink widget hifi1 overwritten
[ 168.838555] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: source widget Codec Output Pin1 overwritten
[ 168.838558] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: sink widget Codec Input Pin1 overwritten
[ 168.838562] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: sink widget Analog Codec Playback overwritten
[ 168.838565] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: sink widget Digital Codec Playback overwritten
[ 168.838569] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: sink widget Alt Analog Codec Playback overwritten
[ 168.838573] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: source widget Analog Codec Capture overwritten
[ 168.838576] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: source widget Digital Codec Capture overwritten
[ 168.838581] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: source widget Alt Analog Codec Capture overwritten
[ 168.838587] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: hda_dsp_hdmi_build_controls: no PCM in topology for HDMI converter 3
[ 168.838588] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: hda_dsp_hdmi_build_controls: no PCM in topology for HDMI converter 4
[ 168.838590] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: hda_dsp_hdmi_build_controls: no PCM in topology for HDMI converter 5
[ 168.838591] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: hda_dsp_hdmi_build_controls: no PCM in topology for HDMI converter 6
[ 168.838592] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: hda_dsp_hdmi_build_controls: no PCM in topology for HDMI converter 7
[ 168.838593] kernel: skl_hda_dsp_generic skl_hda_dsp_generic: hda_dsp_hdmi_build_controls: no PCM in topology for HDMI converter 8
[ 168.858385] kernel: input: sof-hda-dsp Headphone Mic as /devices/pci0000:00/0000:00:1f.3/skl_hda_dsp_generic/sound/card0/input22
[ 168.858481] kernel: input: sof-hda-dsp HDMI/DP,pcm=3 as /devices/pci0000:00/0000:00:1f.3/skl_hda_dsp_generic/sound/card0/input23
[ 168.858572] kernel: input: sof-hda-dsp HDMI/DP,pcm=4 as /devices/pci0000:00/0000:00:1f.3/skl_hda_dsp_generic/sound/card0/input24
[ 168.858648] kernel: input: sof-hda-dsp HDMI/DP,pcm=5 as /devices/pci0000:00/0000:00:1f.3/skl_hda_dsp_generic/sound/card0/input25
[ 168.924460] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: open stream 5 dir 0
[ 168.924464] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: period min 192 max 16384 bytes
[ 168.924466] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: period count 2 max 16
------
Check journalctl status:
----
● systemd-journald-dev-log.socket - Journal Socket (/dev/log)
Loaded: loaded (/usr/lib/systemd/system/systemd-journald-dev-log.socket; static)
Active: active (running) since Thu 2022-01-27 08:44:57 PST; 8h ago
Triggers: ● systemd-journald.service
Docs: man:systemd-journald.service(8)
man:journald.conf(5)
Listen: /run/systemd/journal/dev-log (Datagram)
CGroup: /system.slice/systemd-journald-dev-log.socket
Notice: journal has been rotated since unit was started, output may be incomplete.
● systemd-journald.socket - Journal Socket
Loaded: loaded (/usr/lib/systemd/system/systemd-journald.socket; static)
Active: active (running) since Thu 2022-01-27 08:44:57 PST; 8h ago
Triggers: ● systemd-journald.service
Docs: man:systemd-journald.service(8)
man:journald.conf(5)
Listen: /run/systemd/journal/socket (Datagram)
/run/systemd/journal/stdout (Stream)
CGroup: /system.slice/systemd-journald.socket
Notice: journal has been rotated since unit was started, output may be incomplete.
● systemd-journald.service - Journal Service
Loaded: loaded (/usr/lib/systemd/system/systemd-journald.service; static)
Active: active (running) since Thu 2022-01-27 16:45:00 PST; 2min 45s ago
TriggeredBy: ● systemd-journald-audit.socket
● systemd-journald.socket
● systemd-journald-dev-log.socket
Docs: man:systemd-journald.service(8)
man:journald.conf(5)
Main PID: 469 (systemd-journal)
Status: "Processing requests..."
CPU: 683ms
CGroup: /system.slice/systemd-journald.service
└─469 /usr/lib/systemd/systemd-journald
Jan 27 16:45:00 fedora systemd-journald[469]: Journal started
Jan 27 16:45:00 fedora systemd-journald[469]: Runtime Journal (/run/log/journal/aeb6d152cc6b470ea11ccfb36c4d966c) is 8.0M, max 1.2G, 1.2G free.
Jan 27 16:45:00 fedora systemd[1]: systemd-journald.service: unit configures an IP firewall, but the local system does not support BPF/cgroup firewalling.
Jan 27 16:45:00 fedora systemd[1]: (This warning is only shown for the first unit using IP firewalling.)
Jan 27 16:45:00 fedora systemd[1]: systemd-journald.service: Deactivated successfully.
Jan 27 16:45:00 fedora systemd-journald[469]: Time spent on flushing to /var/log/journal/aeb6d152cc6b470ea11ccfb36c4d966c is 32.882ms for 1146 entries.
Jan 27 16:45:00 fedora systemd-journald[469]: System Journal (/var/log/journal/aeb6d152cc6b470ea11ccfb36c4d966c) is 1.0G, max 2.8G, 1.7G free.
● systemd-journald-audit.socket - Journal Audit Socket
Loaded: loaded (/usr/lib/systemd/system/systemd-journald-audit.socket; static)
Active: active (running) since Thu 2022-01-27 08:44:57 PST; 8h ago
Triggers: ● systemd-journald.service
Docs: man:systemd-journald.service(8)
man:journald.conf(5)
Listen: audit 1 (Netlink)
CGroup: /system.slice/systemd-journald-audit.socket
Notice: journal has been rotated since unit was started, output may be incomplete.
2022-01-28 00:47:45 UTC Sub-Test: [ERROR] Cannot find the sof audio version
2022-01-28 00:47:45 UTC Sub-Test: [ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-01-28 00:47:45 UTC Sub-Test: [ERROR] die() @ /root/sof-test/test-case/../case-lib/lib.sh
2022-01-28 00:47:45 UTC Sub-Test: [ERROR] main() @ /root/sof-test/test-case/verify-sof-firmware-load.sh:40
2022-01-28 00:47:45 UTC Sub-Test: [INFO] Test Result: FAIL!
2022-01-28 00:47:45 UTC [ERROR] Failed to load firmware after module insertion
2022-01-28 00:47:45 UTC [ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-01-28 00:47:45 UTC [ERROR] die() @ /root/sof-test/case-lib/lib.sh
2022-01-28 00:47:45 UTC [ERROR] main() @ /root/sof-test/test-case/check-kmod-load-unload.sh:95
2022-01-28 00:47:45 UTC [INFO] Test Result: FAIL!
Clearly a false alarm
Metadata
Metadata
Assignees
Labels
P1Blocker bugs or important featuresBlocker bugs or important features
Activity
marc-hb commentedon Jan 28, 2022
This does not look like a sof-logger dependency and nothing else in the log above shows any sof-logger dependency either. This is probably caused by IPC4 only.
In fact this test is surprisingly one of the rare tests that has no dependency on the sof-logger at all. I deleted sof-logger from my system which made all tests fail except this one.
So hopefully a duplicate of #842
[-][FEATURE] IPC4: check-kmod-load-unload.sh fails due to sof-logger dependencies[/-][+][FEATURE] IPC4: check-kmod-load-unload.sh fails due to SOF version check issues[/+]plbossart commentedon Jan 28, 2022
It's the check for the version that's hard-coded, it's different for IPC4. I don't know what the solution might be here.
plbossart commentedon Feb 7, 2022
@marc-hb so this is a miss in the IPC4 boot flow, we don't retrieve the firmware version and that's taken as an error by sof-test.
it's a kernel issue that we will fix at a TBD time, but for the time being I'd like an option to work-around it in sof-test. The manual tests with sof_remove.sh and sof_insert.sh work fine. I am not sure why there is a hard-coded call to verify-sof-firmware-load.sh?
marc-hb commentedon Feb 7, 2022
This is basic code re-use, we don't want the "loaded?" and the "unload/load/loaded?" tests to duplicate code.
Maybe looking for the firmware version in the kernel logs is not the best thing to check here, any alternative to suggest?
plbossart commentedon Feb 9, 2022
solved by #853
verify-sof-firmware-load: fix test to actually check the FW is loaded
kmod-load-unload: search logs for "firmware boot complete"
kmod-load-unload: search logs for "firmware boot complete"