[BUG] FW reported error: 104 - Other failure of module instance initialization request

Describe the bug
During check-suspend-resume-with-playback-5.sh test, FW reported error: 104 is occurred.

[ 4410.777465] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x60000068|0x10036: MOD_INIT_INSTANCE
[ 4410.777468] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 104 - Other failure of module instance initialization request
[ 4410.777519] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x40010004|0x10036
[ 4410.777548] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to create module alh-copier.SDW0-Playback.0

Intel internal daily test link:

planresultdetail/30296?model=MTLP_RVP_SDW&testcase=check-suspend-resume-with-playback-5
planresultdetail/30296?model=MTLP_SDW_AIOC&testcase=check-suspend-resume-with-playback-5

To Reproduce
TPLG=/lib/firmware/intel/sof-ace-tplg/sof-mtl-rt711-4ch.tplg MODEL=MTLP_RVP_SDW SOF_TEST_INTERVAL=5 ~/sof-test/test-case/check-suspend-resume-with-audio.sh -l 5 -m playback

Reproduction Rate
Starting from today. It happened in MTLP_RVP_SDW and MTLP_SDW_AIOC.

Environment

Kernel Branch: topic/sof-dev
Kernel Commit: b49e881b4db3
SOF Branch: main
SOF Commit: eac5a0a12ef4

Screenshots or console output

Found in ADLP_SKU0B00_SDCA also from today's daily test.

Intel internal daily test link:
planresultdetail/30853?model=ADLP_SKU0B00_SDCA-cavs2_5-ipc4&testcase=check-suspend-resume-with-playback-5

Not reproduced for 3 days

This issue happened again:
planresultdetail/31237?model=MTLP_SDW_AIOC-ace1_0-ipc4&testcase=check-suspend-resume-with-playback-5
planresultdetail/31270?model=MTLP_RVP_SDW-ace1_0-ipc4&testcase=check-signal-stop-start-playback-50

happen again

[ 1445.894941] kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create widget alh-copier.SDW0-Playback.0 instance 1 - pipe 1 - core 0
[ 1445.894944] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x40010004|0x10036: MOD_INIT_INSTANCE [data size: 216]
[ 1445.896264] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x60000068|0x10036: MOD_INIT_INSTANCE
[ 1445.896267] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 104 - Other failure of module instance initialization request
[ 1445.896280] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x40010004|0x10036
[ 1445.896287] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to create module alh-copier.SDW0-Playback.0
[ 1445.896293] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget gain.1.1 freed
[ 1445.896297] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12010000|0x0: GLB_DELETE_PIPELINE
[ 1445.896673] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[ 1445.896683] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x12010000|0x0: GLB_DELETE_PIPELINE
[ 1445.896686] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.1 freed
[ 1445.896688] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget mixout.1.1 freed
[ 1445.896691] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget mixin.15.1 freed
[ 1445.896693] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget gain.15.1 freed
[ 1445.896696] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12000000|0x0: GLB_DELETE_PIPELINE
[ 1445.897189] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[ 1445.897198] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x12000000|0x0: GLB_DELETE_PIPELINE
[ 1445.897201] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.15 freed
[ 1445.897203] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget host-copier.31.playback freed
[ 1445.897205] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to set up connected widgets
[ 1445.897210] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed widget list set up for pcm 31 dir 0
[ 1445.897214] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -22

planresultdetail/31496?model=MTLP_RVP_SDW-ace1_0-ipc4&testcase=check-signal-stop-start-playback-50

We haven't observed this issue in v2.7 stress test.

Tried a few days test but can't reproduce it

@fredoh9

@fredoh9 any recent sightings at your end ?

I haven't seen the same issue for a week+.

I haven't seen the same issue for a week+.

ok, pls close if not seen again by end of week.

Found today again with MTLP_SDW_AIOC

Intel Internal result: planresultdetail/32587?model=MTLP_SDW_AIOC-ace1_0-ipc4&testcase=check-suspend-resume-with-playback-5

Sure, it is also a hack to me. What I think is to set it by topology or rework our SOF but I have other high priority tasks to do.

@RanderWang

@RanderWang Can you provide more traces and specifically log transitions of the variable "be->dpcm[stream].users" and which stages this variable is updated (startup, hw_params, prepare, hw_free, shutdown).

In theory this refcount is used precisely to prevent transitions on shared BEs, e.g.
/* do not free hw if this BE is used by other FE */
		if (be->dpcm[stream].users > 1)
			continue;
My take is that there is probably something not quite right in soc-pcm.c, if there is a race condition we should fix the root cause. Changing how the node_id is cleared seems a bit like a hack to me.

@plbossart the problem is not be free. The node_id is set by BE component( SDW dai). When the first stream A is free, the FE dai widget is free by SOF, so the node_id is cleared, at this time the BE state is SND_SOC_DPCM_STATE_STOP. And the be_hw_params for second stream B want to call sdw_hw_params to set node_id, but it found the state is SND_SOC_DPCM_STATE_STOP, it will skip this BE hw_params, so the node_id will not be set.

int dpcm_be_dai_hw_params(struct snd_soc_pcm_runtime *fe, int stream)
{
               ......
	for_each_dpcm_be(fe, stream, dpcm) {
                .....

		if ((be->dpcm[stream].state != SND_SOC_DPCM_STATE_OPEN) &&
		    (be->dpcm[stream].state != SND_SOC_DPCM_STATE_HW_PARAMS) &&
		    (be->dpcm[stream].state != SND_SOC_DPCM_STATE_HW_FREE))
			continue;
        }
}

The bug is very random and I don't reproduce it today.

My plan was to keep FE dai widget alive in SOF since it was used by two steams, but we need to do much work to do it

I must admit I don't recall why we only added locking for the trigger cases. I don't know how we can protect the state of a BE which can be modified by separate FEs. Using the user counts and states is by construction racy, I can't think of a simple fix, unless I am gravely mistaken it looks like all the soc-pcm.c code needs to be revisited.

The path of least resistance for a quick fix would be to avoid clearing stuff and keeping the node_id constant for shared BEs.

@tiwai

@tiwai shares my analysis that the Linux BE locking isn't really up-to-snuff, we would need to come-up with a better mechanism to make sure FE transitions don't end-up corrupting the state of a shared BE.

This sort of change is tricky and will likely require multiple weeks and lots of testing before we get it right.

It looks like this a kernel issue, not firmware. Should be transferred to https://github.com/thesofproject/linux ?

@marc-hb

It looks like this a kernel issue, not firmware. Should be transferred to https://github.com/thesofproject/linux ?

@marc-hb yes this is a kernel issue and I have a good feeling that the linux PR #4829 would also fix this issue

Transferring this issue since Github does nice, automagic redirections that don't break URLs.

Transferring this issue since Github does nice, automagic redirections that don't break URLs.

There was a permission cleanup recently and I lost write access to https://github.com/thesofproject/linux/issues which is probably why I can't do this transfer.

EDIT: fixed.

@marc-hb

I've really lost the plot on this issue @marc-hb @fredoh9, do we still see this in any CI/daily tests now?

I haven't seen this in recent times. I guess some unrelated change just made the race described by Rander above less likely.

I haven't seen this problem lately.
I lost my test result database to confirm.

closing, let's reopen if that occurs again

Navigation Menu

Repository navigation

[BUG] FW reported error: 104 - Other failure of module instance initialization request #4832

27 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG] FW reported error: 104 - Other failure of module instance initialization request #4832

Description

Activity

fredoh9 commented on Aug 29, 2023

fredoh9 commented on Sep 1, 2023

keqiaozhang commented on Sep 5, 2023

fredoh9 commented on Sep 8, 2023

mengdonglin commented on Sep 14, 2023

RanderWang commented on Sep 25, 2023

lgirdwood commented on Sep 29, 2023

fredoh9 commented on Sep 29, 2023

lgirdwood commented on Oct 2, 2023

fredoh9 commented on Oct 2, 2023

27 remaining items

RanderWang commented on Jan 30, 2024

RanderWang commented on Jan 30, 2024

RanderWang commented on Jan 30, 2024

plbossart commented on Jan 30, 2024

plbossart commented on Jan 31, 2024

marc-hb commented on Jan 31, 2024

ranj063 commented on Feb 21, 2024

marc-hb commented on Feb 21, 2024

marc-hb commented on Feb 21, 2024

plbossart commented on Apr 24, 2024

marc-hb commented on Apr 24, 2024

fredoh9 commented on Apr 25, 2024

plbossart commented on May 3, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions