[PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Hans de Goede]

At least on Canon Lake each time the SOF firmware is booted,
the following error is logged in dmesg:

[   36.711803] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0

Since the DSP is powered down when not in used this happens everytime
e.g. a notification plays, polluting dmesg with these false-positive
errors.

Add a check to snd_sof_ipc_reply() which makes it return success when
receiving an unexpected msg_id 0 during fw-boot, fixing these
false-positive errors being logged.

Signed-off-by: Hans de Goede <hdegoede@redhat.com>
---
 sound/soc/sof/ipc.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/sound/soc/sof/ipc.c b/sound/soc/sof/ipc.c
index 78aa1da7c7a9..7303b3d42f12 100644
--- a/sound/soc/sof/ipc.c
+++ b/sound/soc/sof/ipc.c
@@ -312,6 +312,11 @@ int snd_sof_ipc_reply(struct snd_sof_dev *sdev, u32 msg_id)
 {
 	struct snd_sof_ipc_msg *msg = &sdev->ipc->msg;
 
+	/* Ignore msg_id 0 being send during fw-boot */
+	if (msg->ipc_complete && sdev->fw_state == SOF_FW_BOOT_IN_PROGRESS &&
+	    msg_id == 0)
+		return 0;
+
 	if (msg->ipc_complete) {
 		dev_err(sdev->dev, "error: no reply expected, received 0x%x",
 			msg_id);
-- 
2.26.0

[PATCH 2/2] ASoC: SOF: Turn "firmware boot complete" message into a dbg message

[Hans de Goede]

Using a Canon Lake machine with the SOF driver causes dmesg to fill
up with a ton of these messages:

[  275.902194] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  351.529358] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  560.049047] sof-audio-pci 0000:00:1f.3: firmware boot complete
etc.

Since the DSP is powered down when not in used this happens everytime
e.g. a notification plays, polluting dmesg.

Turn this messages into a debug message, matching what the code already
does for the ""booting DSP firmware" message.

Signed-off-by: Hans de Goede <hdegoede@redhat.com>
---
 sound/soc/sof/loader.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/sound/soc/sof/loader.c b/sound/soc/sof/loader.c
index fc4ab51bacf4..4760a9734585 100644
--- a/sound/soc/sof/loader.c
+++ b/sound/soc/sof/loader.c
@@ -603,7 +603,7 @@ int snd_sof_run_firmware(struct snd_sof_dev *sdev)
 	}
 
 	if (sdev->fw_state == SOF_FW_BOOT_COMPLETE)
-		dev_info(sdev->dev, "firmware boot complete\n");
+		dev_dbg(sdev->dev, "firmware boot complete\n");
 	else
 		return -EIO; /* FW boots but fw_ready op failed */
 
-- 
2.26.0

Re: [PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Pierre-Louis Bossart]

On 4/2/20 1:49 PM, Hans de Goede wrote:
> At least on Canon Lake each time the SOF firmware is booted,
> the following error is logged in dmesg:
> 
> [   36.711803] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
> 
> Since the DSP is powered down when not in used this happens everytime
> e.g. a notification plays, polluting dmesg with these false-positive
> errors.

What kernel are you using Hans? I thought this was solved with

8354d9b44530b ("ASoC: SOF: Intel: hda-loader: clear the IPC ack bit 
after FW_PURGE done")

Set DONE bit after the FW_PURGE IPC is polled successfully, to clear the
interrupt and avoid the arrival of the confusing unexpected ipc.
> Add a check to snd_sof_ipc_reply() which makes it return success when
> receiving an unexpected msg_id 0 during fw-boot, fixing these
> false-positive errors being logged.
> 
> Signed-off-by: Hans de Goede <hdegoede@redhat.com>
> ---
>   sound/soc/sof/ipc.c | 5 +++++
>   1 file changed, 5 insertions(+)
> 
> diff --git a/sound/soc/sof/ipc.c b/sound/soc/sof/ipc.c
> index 78aa1da7c7a9..7303b3d42f12 100644
> --- a/sound/soc/sof/ipc.c
> +++ b/sound/soc/sof/ipc.c
> @@ -312,6 +312,11 @@ int snd_sof_ipc_reply(struct snd_sof_dev *sdev, u32 msg_id)
>   {
>   	struct snd_sof_ipc_msg *msg = &sdev->ipc->msg;
>   
> +	/* Ignore msg_id 0 being send during fw-boot */
> +	if (msg->ipc_complete && sdev->fw_state == SOF_FW_BOOT_IN_PROGRESS &&
> +	    msg_id == 0)
> +		return 0;
> +
>   	if (msg->ipc_complete) {
>   		dev_err(sdev->dev, "error: no reply expected, received 0x%x",
>   			msg_id);
> 

Re: [PATCH 2/2] ASoC: SOF: Turn "firmware boot complete" message into a dbg message

[Pierre-Louis Bossart]

On 4/2/20 1:49 PM, Hans de Goede wrote:
> Using a Canon Lake machine with the SOF driver causes dmesg to fill
> up with a ton of these messages:
> 
> [  275.902194] sof-audio-pci 0000:00:1f.3: firmware boot complete
> [  351.529358] sof-audio-pci 0000:00:1f.3: firmware boot complete
> [  560.049047] sof-audio-pci 0000:00:1f.3: firmware boot complete
> etc.
> 
> Since the DSP is powered down when not in used this happens everytime
> e.g. a notification plays, polluting dmesg.
> 
> Turn this messages into a debug message, matching what the code already
> does for the ""booting DSP firmware" message.
> 
> Signed-off-by: Hans de Goede <hdegoede@redhat.com>

Acked-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>

Thanks Hans.

> ---
>   sound/soc/sof/loader.c | 2 +-
>   1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/sound/soc/sof/loader.c b/sound/soc/sof/loader.c
> index fc4ab51bacf4..4760a9734585 100644
> --- a/sound/soc/sof/loader.c
> +++ b/sound/soc/sof/loader.c
> @@ -603,7 +603,7 @@ int snd_sof_run_firmware(struct snd_sof_dev *sdev)
>   	}
>   
>   	if (sdev->fw_state == SOF_FW_BOOT_COMPLETE)
> -		dev_info(sdev->dev, "firmware boot complete\n");
> +		dev_dbg(sdev->dev, "firmware boot complete\n");
>   	else
>   		return -EIO; /* FW boots but fw_ready op failed */
>   
> 

Re: [PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Hans de Goede]

Hi,

On 4/2/20 9:15 PM, Pierre-Louis Bossart wrote:
> 
> 
> On 4/2/20 1:49 PM, Hans de Goede wrote:
>> At least on Canon Lake each time the SOF firmware is booted,
>> the following error is logged in dmesg:
>>
>> [   36.711803] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
>>
>> Since the DSP is powered down when not in used this happens everytime
>> e.g. a notification plays, polluting dmesg with these false-positive
>> errors.
> 
> What kernel are you using Hans? I thought this was solved with

5.6.0

> 8354d9b44530b ("ASoC: SOF: Intel: hda-loader: clear the IPC ack bit after FW_PURGE done") >
> Set DONE bit after the FW_PURGE IPC is polled successfully, to clear the
> interrupt and avoid the arrival of the confusing unexpected ipc.

That commit is not in Torvald's tree yet, but it is in
broonie/sound.git, I've cherry picked it into my local tree
and reverted my own fix.

Unfortunately even with that patch cherry picked the errors my
patch silences still happen.

Regards,

Hans



>> Add a check to snd_sof_ipc_reply() which makes it return success when
>> receiving an unexpected msg_id 0 during fw-boot, fixing these
>> false-positive errors being logged.
>>
>> Signed-off-by: Hans de Goede <hdegoede@redhat.com>
>> ---
>>   sound/soc/sof/ipc.c | 5 +++++
>>   1 file changed, 5 insertions(+)
>>
>> diff --git a/sound/soc/sof/ipc.c b/sound/soc/sof/ipc.c
>> index 78aa1da7c7a9..7303b3d42f12 100644
>> --- a/sound/soc/sof/ipc.c
>> +++ b/sound/soc/sof/ipc.c
>> @@ -312,6 +312,11 @@ int snd_sof_ipc_reply(struct snd_sof_dev *sdev, u32 msg_id)
>>   {
>>       struct snd_sof_ipc_msg *msg = &sdev->ipc->msg;
>> +    /* Ignore msg_id 0 being send during fw-boot */
>> +    if (msg->ipc_complete && sdev->fw_state == SOF_FW_BOOT_IN_PROGRESS &&
>> +        msg_id == 0)
>> +        return 0;
>> +
>>       if (msg->ipc_complete) {
>>           dev_err(sdev->dev, "error: no reply expected, received 0x%x",
>>               msg_id);
>>
> 

Re: [PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Pierre-Louis Bossart]

On 4/3/20 3:01 AM, Hans de Goede wrote:
> Hi,
> 
> On 4/2/20 9:15 PM, Pierre-Louis Bossart wrote:
>>
>>
>> On 4/2/20 1:49 PM, Hans de Goede wrote:
>>> At least on Canon Lake each time the SOF firmware is booted,
>>> the following error is logged in dmesg:
>>>
>>> [   36.711803] sof-audio-pci 0000:00:1f.3: error: no reply expected, 
>>> received 0x0
>>>
>>> Since the DSP is powered down when not in used this happens everytime
>>> e.g. a notification plays, polluting dmesg with these false-positive
>>> errors.
>>
>> What kernel are you using Hans? I thought this was solved with
> 
> 5.6.0
> 
>> 8354d9b44530b ("ASoC: SOF: Intel: hda-loader: clear the IPC ack bit 
>> after FW_PURGE done") >
>> Set DONE bit after the FW_PURGE IPC is polled successfully, to clear the
>> interrupt and avoid the arrival of the confusing unexpected ipc.
> 
> That commit is not in Torvald's tree yet, but it is in
> broonie/sound.git, I've cherry picked it into my local tree
> and reverted my own fix.
> 
> Unfortunately even with that patch cherry picked the errors my
> patch silences still happen.

Ok, we'll look into it. Give us a couple of days on this one, thanks!

Applied "ASoC: SOF: Turn "firmware boot complete" message into a dbg message" to the asoc tree

[Mark Brown]

The patch

   ASoC: SOF: Turn "firmware boot complete" message into a dbg message

has been applied to the asoc tree at

   https://git.kernel.org/pub/scm/linux/kernel/git/broonie/sound.git 

All being well this means that it will be integrated into the linux-next
tree (usually sometime in the next 24 hours) and sent to Linus during
the next merge window (or sooner if it is a bug fix), however if
problems are discovered then the patch may be dropped or reverted.  

You may get further e-mails resulting from automated or manual testing
and review of the tree, please engage with people reporting problems and
send followup patches addressing any issues that are reported if needed.

If any updates are required or you are submitting further changes they
should be sent as incremental updates against current git, existing
patches will not be replaced.

Please add any relevant lists and maintainers to the CCs when replying
to this mail.

Thanks,
Mark

From 904f353d0e508fb4b3a3f902a02b0a028cda33a6 Mon Sep 17 00:00:00 2001
From: Hans de Goede <hdegoede@redhat.com>
Date: Thu, 2 Apr 2020 20:49:48 +0200
Subject: [PATCH] ASoC: SOF: Turn "firmware boot complete" message into a dbg
 message

Using a Canon Lake machine with the SOF driver causes dmesg to fill
up with a ton of these messages:

[  275.902194] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  351.529358] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  560.049047] sof-audio-pci 0000:00:1f.3: firmware boot complete
etc.

Since the DSP is powered down when not in used this happens everytime
e.g. a notification plays, polluting dmesg.

Turn this messages into a debug message, matching what the code already
does for the ""booting DSP firmware" message.

Signed-off-by: Hans de Goede <hdegoede@redhat.com>
Acked-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Link: https://lore.kernel.org/r/20200402184948.3014-2-hdegoede@redhat.com
Signed-off-by: Mark Brown <broonie@kernel.org>
---
 sound/soc/sof/loader.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/sound/soc/sof/loader.c b/sound/soc/sof/loader.c
index 1f2e0be812bd..64af08293daa 100644
--- a/sound/soc/sof/loader.c
+++ b/sound/soc/sof/loader.c
@@ -597,7 +597,7 @@ int snd_sof_run_firmware(struct snd_sof_dev *sdev)
 	}
 
 	if (sdev->fw_state == SOF_FW_BOOT_COMPLETE)
-		dev_info(sdev->dev, "firmware boot complete\n");
+		dev_dbg(sdev->dev, "firmware boot complete\n");
 	else
 		return -EIO; /* FW boots but fw_ready op failed */
 
-- 
2.20.1

Re: [PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 478 bytes --]

On Fri, Apr 03, 2020 at 08:17:32AM -0500, Pierre-Louis Bossart wrote:
> On 4/3/20 3:01 AM, Hans de Goede wrote:

> > That commit is not in Torvald's tree yet, but it is in
> > broonie/sound.git, I've cherry picked it into my local tree
> > and reverted my own fix.

> > Unfortunately even with that patch cherry picked the errors my
> > patch silences still happen.

> Ok, we'll look into it. Give us a couple of days on this one, thanks!

It's been more than a few days now...

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Pierre-Louis Bossart]

On 4/20/20 7:48 AM, Mark Brown wrote:
> On Fri, Apr 03, 2020 at 08:17:32AM -0500, Pierre-Louis Bossart wrote:
>> On 4/3/20 3:01 AM, Hans de Goede wrote:
> 
>>> That commit is not in Torvald's tree yet, but it is in
>>> broonie/sound.git, I've cherry picked it into my local tree
>>> and reverted my own fix.
> 
>>> Unfortunately even with that patch cherry picked the errors my
>>> patch silences still happen.
> 
>> Ok, we'll look into it. Give us a couple of days on this one, thanks!
> 
> It's been more than a few days now...

Sorry about the delay, on my side I don't see this anymore in my 
ApolloLake or CML tests. Kai, can you confirm for HDaudio platforms?

Re: [PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Kai Vehmanen]

Hey,

On Mon, 20 Apr 2020, Pierre-Louis Bossart wrote:

>>> On 4/3/20 3:01 AM, Hans de Goede wrote:
>>>> Unfortunately even with that patch cherry picked the errors my
>>>> patch silences still happen.
> 
> Sorry about the delay, on my side I don't see this anymore in my ApolloLake or
> CML tests. Kai, can you confirm for HDaudio platforms?

I tested on a set of HDA platforms and I could not trigger the "no reply 
expected" errors. Tested with sof-dev (Mark's latest tree but staged SOF 
patches) that has the "ASoC: SOF: Intel: hda-loader: clear the IPC ack bit 
after FW_PURGE" patch.

If I revert this patch, the error trace comes back immediately, so this 
definitely helps to the trace spam at least in these cases.

There could of course be some relation to FW version. So if someone can 
still get the error trace, the FW version and platform used would be 
interesting information.

Br, Kai

Re: [PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Hans de Goede]

Hi,

On 4/20/20 10:28 PM, Kai Vehmanen wrote:
> Hey,
> 
> On Mon, 20 Apr 2020, Pierre-Louis Bossart wrote:
> 
>>>> On 4/3/20 3:01 AM, Hans de Goede wrote:
>>>>> Unfortunately even with that patch cherry picked the errors my
>>>>> patch silences still happen.
>>
>> Sorry about the delay, on my side I don't see this anymore in my ApolloLake or
>> CML tests. Kai, can you confirm for HDaudio platforms?
> 
> I tested on a set of HDA platforms and I could not trigger the "no reply
> expected" errors. Tested with sof-dev (Mark's latest tree but staged SOF
> patches) that has the "ASoC: SOF: Intel: hda-loader: clear the IPC ack bit
> after FW_PURGE" patch.
> 
> If I revert this patch, the error trace comes back immediately, so this
> definitely helps to the trace spam at least in these cases.
> 
> There could of course be some relation to FW version. So if someone can
> still get the error trace, the FW version and platform used would be
> interesting information.

I've retested with 5.7-rc2 (previous testing was on 5.6-rc# + the
"ASoC: SOF: Intel: hda-loader: clear the IPC ack bit after FW_PURGE" patch)
and I'm no longer seeing this. So I guess fixing this also needed some other
patches which have now landed in 5.7.

So this is resolved now and my patch for this can be dropped.

Regards,

Hans

Re: [PATCH 1/2] ASoC: SOF: Fix "no reply expected" error during firmware-boot

[Pierre-Louis Bossart]

> I've retested with 5.7-rc2 (previous testing was on 5.6-rc# + the
> "ASoC: SOF: Intel: hda-loader: clear the IPC ack bit after FW_PURGE" patch)
> and I'm no longer seeing this. So I guess fixing this also needed some 
> other
> patches which have now landed in 5.7.
> 
> So this is resolved now and my patch for this can be dropped.

Thanks for confirming Hans. We followed-up on your suggestion and 
demoted additional error messages to avoid polluting the logs.