FW reported error: 113 - Invalid destination queue (pin) ID provided following nocodec topology change 6318

[greg-intel]

Describe the bug #6318 seems to have caused a major regression found in daily 15919?model=TGLU_RVP_NOCODEC_CAVSIPC4&testcase=check-playback-100sec, most tests are failing.

From /var/log/syslog (/var/log/journal/ has been entirely deleted on that system?!?)

Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.541660] snd_sof:sof_ipc4_route_setup: sof-audio-pci-intel-tgl 0000:00:1f.3: bind gain.7.1:0 -> copier.host.7.1:0
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.541663] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x45000006|0x10004: MOD_BIND
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.541906] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x65000000|0x10004: MOD_BIND
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.541944] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x45000006|0x10004: MOD_BIND
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.541951] snd_sof:sof_ipc4_route_setup: sof-audio-pci-intel-tgl 0000:00:1f.3: bind copier.SSP.8.1:0 -> gain.7.1:0
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.541955] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x45000004|0x6: MOD_BIND
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542162] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x65000071|0x6: MOD_BIND
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542165] sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 113 - Invalid destination queue (pin) ID provided
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542230] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x45000004|0x6
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542237] sof-audio-pci-intel-tgl 0000:00:1f.3: sof_ipc4_route_setup: failed to bind modules copier.SSP.8.1 -> gain.7.1
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542245] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12000000|0x0: GLB_DELETE_PIPELINE
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542652] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542677] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x12000000|0x0: GLB_DELETE_PIPELINE
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542681] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget pipeline.8 freed
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542683] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget copier.SSP.8.1 freed
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542685] snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules gain.7.1:0 -> copier.host.7.1:0
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542688] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x46000006|0x10004: MOD_UNBIND
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542907] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x66000000|0x10004: MOD_UNBIND
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542944] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x46000006|0x10004: MOD_UNBIND
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542948] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget gain.7.1 freed
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.542951] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12010000|0x0: GLB_DELETE_PIPELINE
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543393] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543454] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x12010000|0x0: GLB_DELETE_PIPELINE
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543461] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget pipeline.7 freed
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543463] snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget copier.host.7.1 freed
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543467] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed widget list set up for pcm 0 dir 1
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543472] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -22
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543488]  Port0: ASoC: error at __soc_pcm_hw_params on Port0: -22
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543495]  Port0: ASoC: error at dpcm_fe_dai_hw_params on Port0: -22
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543501] snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: free stream 0 dir 1
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543692] snd-soc-dummy snd-soc-dummy: Runtime PM usage count underflow!
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543695] snd_sof:sof_pcm_close: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: close stream 0 dir 1
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 kernel: [  149.543707] snd-soc-dummy snd-soc-dummy: Runtime PM usage count underflow!
Oct  3 21:34:24 sh-tglu-rvp-nocodec-ci-02 ubuntu: ktime=149 sof-test PID=2904: ending
Oct  3 21:34:27 sh-tglu-rvp-nocodec-ci-02 kernel: [  151.865854] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]

Also from the dmesg

[  149.542165] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 113 - Invalid destination queue (pin) ID provided
[  149.542230] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x45000004|0x6
[  149.542237] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: sof_ipc4_route_setup: failed to bind modules copier.SSP.8.1 -> gain.7.1
[  149.542245] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12000000|0x0: GLB_DELETE_PIPELINE
[  149.542652] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[  149.542677] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x12000000|0x0: GLB_DELETE_PIPELINE
[  149.542681] kernel: snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget pipeline.8 freed
[  149.542683] kernel: snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget copier.SSP.8.1 freed
[  149.542685] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules gain.7.1:0 -> copier.host.7.1:0
[  149.542688] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x46000006|0x10004: MOD_UNBIND
[  149.542907] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x66000000|0x10004: MOD_UNBIND
[  149.542944] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x46000006|0x10004: MOD_UNBIND
[  149.542948] kernel: snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget gain.7.1 freed
[  149.542951] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12010000|0x0: GLB_DELETE_PIPELINE
[  149.543393] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[  149.543454] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x12010000|0x0: GLB_DELETE_PIPELINE
[  149.543461] kernel: snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget pipeline.7 freed
[  149.543463] kernel: snd_sof:sof_widget_free: sof-audio-pci-intel-tgl 0000:00:1f.3: widget copier.host.7.1 freed
[  149.543467] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed widget list set up for pcm 0 dir 1
[  149.543472] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -22
[  149.543488] kernel:  Port0: ASoC: error at __soc_pcm_hw_params on Port0: -22
[  149.543495] kernel:  Port0: ASoC: error at dpcm_fe_dai_hw_params on Port0: -22

To Reproduce

1. Connect to the DUT.
2. Run TPLG=/lib/firmware/intel/avs-tplg/cavs-tgl-nocodec.tplg MODEL=TGLU_RVP_NOCODEC_CAVSIPC4 ~/sof-test/test-case/check-capture.sh -d 3 -l 1 -r 1 -F
3. Fails

Reproduction Rate Happens every time.

Expected behavior Expectation is that the test will run without failure.

Impact Causes some of the following tests to fail. Makes the test picture very clouded.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: ddc2987f8e32
   • SOF: e31c7abeeb59
2. Name of the topology file
   • Topology: cavs-tgl-nocodec.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: sh-tglu-rvp-nocodec-ci-02.sh.intel.com

Screenshots or console output In description Repro case:

[greg-intel]

Resolution verified.

1. git revert
2. ./scripts/docker-run.sh ./scripts/build-tools.sh -T (on build/local machine) from sof root.
3. Transferred cavs-tgl-nocodec.tplg to /lib/firmware/intel/avs-tplg on DUT.
4. In /home/ubuntu/sof-test/tools/kmod ran sof_remove.sh followed by sof_insert.sh
5. Ran the above reproduction case
6. Passed

[ranj063]

@greg-intel lets not close this issue because the revert is only a temporary solution. @RanderWang FYI. can you please look into this?

[RanderWang]

Sure. Some potential bugs would be detected with my PR as I expected

[RanderWang]

The problem is that for capture, gain module should be in the same pipeline of dai copier else FW can't find sink. The root reason is that gain module doesn't support get_sink() ops. (closed source FW, not cSOF)

[RanderWang]

@greg-intel can we close it since we find root reason

[marc-hb]

We reverted a regression. @ranj063 asked to file this as a reminder to resubmit the same but fixed "feature", without the regression. Will you resubmit a fixed version or are you giving up for some reason? (because it can't be done?)

[ranj063]

@marc-hb here's the resubmit (merged but with a revised version of the original) and a fix on top of it pending merge https://github.com/thesofproject/sof/pull/6417

[marc-hb]

Thanks @ranj063 ! So let's close this once #6417 is merged and the next daily run is passing.

[lgirdwood]

Thanks @ranj063 ! So let's close this once #6417 is merged and the next daily run is passing.

Now merged, can this be closed ?