[PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Hans de Goede]

If SNDRV_PCM_IOCTL_PREPARE is called when  the mixer settings linking
frontend and backend have not been setup yet this results in
e.g. the following errors getting logged:

[   43.244549]  Baytrail Audio Port: ASoC: no backend DAIs enabled for Baytrail Audio Port
[   43.244744]  Baytrail Audio Port: ASoC: error at dpcm_fe_dai_prepare on Baytrail Audio Port: -22

pipewire triggers this leading to 96 repeats of this in the log
after the user has logged into a GNOME session.

IMHO userspace should not be able to get the kernel to spam dmesg like
this. Lower the severity of the "no backend DAIs enabled" log message
for dai-s with the dynamic flag set to avoid this.

And also changes _soc_pcm_ret() to not log for -EINVAL errors, to fix
the other error. Userspace passing wrong parameters should not lead
to dmesg messages.

Link: https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/3407
Signed-off-by: Hans de Goede <hdegoede@redhat.com>
---
 sound/soc/soc-pcm.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/sound/soc/soc-pcm.c b/sound/soc/soc-pcm.c
index 8896227e4fb7..fdc1a1c654d6 100644
--- a/sound/soc/soc-pcm.c
+++ b/sound/soc/soc-pcm.c
@@ -38,6 +38,7 @@ static inline int _soc_pcm_ret(struct snd_soc_pcm_runtime *rtd,
 	switch (ret) {
 	case -EPROBE_DEFER:
 	case -ENOTSUPP:
+	case -EINVAL:
 		break;
 	default:
 		dev_err(rtd->dev,
@@ -2466,7 +2467,11 @@ static int dpcm_fe_dai_prepare(struct snd_pcm_substream *substream)
 
 	/* there is no point preparing this FE if there are no BEs */
 	if (list_empty(&fe->dpcm[stream].be_clients)) {
-		dev_err(fe->dev, "ASoC: no backend DAIs enabled for %s\n",
+		if (fe->dai_link->dynamic)
+			dev_dbg(fe->dev, "ASoC: no backend DAIs enabled for %s\n",
+				fe->dai_link->name);
+		else
+			dev_err(fe->dev, "ASoC: no backend DAIs enabled for %s\n",
 				fe->dai_link->name);
 		ret = -EINVAL;
 		goto out;
-- 
2.41.0

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Pierre-Louis Bossart]

On 8/4/23 08:26, Hans de Goede wrote:
> If SNDRV_PCM_IOCTL_PREPARE is called when  the mixer settings linking
> frontend and backend have not been setup yet this results in
> e.g. the following errors getting logged:
> 
> [   43.244549]  Baytrail Audio Port: ASoC: no backend DAIs enabled for Baytrail Audio Port
> [   43.244744]  Baytrail Audio Port: ASoC: error at dpcm_fe_dai_prepare on Baytrail Audio Port: -22
> 
> pipewire triggers this leading to 96 repeats of this in the log
> after the user has logged into a GNOME session.
> 
> IMHO userspace should not be able to get the kernel to spam dmesg like
> this. Lower the severity of the "no backend DAIs enabled" log message
> for dai-s with the dynamic flag set to avoid this.
> 
> And also changes _soc_pcm_ret() to not log for -EINVAL errors, to fix
> the other error. Userspace passing wrong parameters should not lead
> to dmesg messages.

Maybe, but it's a questionable flow if pipewire tries to open stuff
without the mixer values set-up. Is there something done about this?

The reason why I am pushing back is that we had a similar issue with
HDaudio where HDMI/DP PCM devices were opened without checking if the
jack was connected.

It really makes no sense for userspace to try and open devices that are
known to be problematic. We can push kernel error logs below the rug, it
doesn't make the programming flows better.

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Takashi Iwai]

On Fri, 04 Aug 2023 16:06:45 +0200,
Pierre-Louis Bossart wrote:
> 
> 
> 
> On 8/4/23 08:26, Hans de Goede wrote:
> > If SNDRV_PCM_IOCTL_PREPARE is called when  the mixer settings linking
> > frontend and backend have not been setup yet this results in
> > e.g. the following errors getting logged:
> > 
> > [   43.244549]  Baytrail Audio Port: ASoC: no backend DAIs enabled for Baytrail Audio Port
> > [   43.244744]  Baytrail Audio Port: ASoC: error at dpcm_fe_dai_prepare on Baytrail Audio Port: -22
> > 
> > pipewire triggers this leading to 96 repeats of this in the log
> > after the user has logged into a GNOME session.
> > 
> > IMHO userspace should not be able to get the kernel to spam dmesg like
> > this. Lower the severity of the "no backend DAIs enabled" log message
> > for dai-s with the dynamic flag set to avoid this.
> > 
> > And also changes _soc_pcm_ret() to not log for -EINVAL errors, to fix
> > the other error. Userspace passing wrong parameters should not lead
> > to dmesg messages.
> 
> Maybe, but it's a questionable flow if pipewire tries to open stuff
> without the mixer values set-up. Is there something done about this?

I think it's an oft-seen problem when user runs the system without
installing a proper UCM profile.

> The reason why I am pushing back is that we had a similar issue with
> HDaudio where HDMI/DP PCM devices were opened without checking if the
> jack was connected.
> 
> It really makes no sense for userspace to try and open devices that are
> known to be problematic. We can push kernel error logs below the rug, it
> doesn't make the programming flows better.

Downgrading the message also hides to show what's wrong there.
Although the message doesn't indicate how to fix the problem, no
message would make debug harder.

So in general I agree that it's annoying and it should be fixed, but
hiding all as default can be bad, too.  Maybe we can introduce a
counter and shut out after three strikes?


Takashi

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Hans de Goede]

Hi,

On 8/4/23 16:42, Takashi Iwai wrote:
> On Fri, 04 Aug 2023 16:06:45 +0200,
> Pierre-Louis Bossart wrote:
>>
>>
>>
>> On 8/4/23 08:26, Hans de Goede wrote:
>>> If SNDRV_PCM_IOCTL_PREPARE is called when  the mixer settings linking
>>> frontend and backend have not been setup yet this results in
>>> e.g. the following errors getting logged:
>>>
>>> [   43.244549]  Baytrail Audio Port: ASoC: no backend DAIs enabled for Baytrail Audio Port
>>> [   43.244744]  Baytrail Audio Port: ASoC: error at dpcm_fe_dai_prepare on Baytrail Audio Port: -22
>>>
>>> pipewire triggers this leading to 96 repeats of this in the log
>>> after the user has logged into a GNOME session.
>>>
>>> IMHO userspace should not be able to get the kernel to spam dmesg like
>>> this. Lower the severity of the "no backend DAIs enabled" log message
>>> for dai-s with the dynamic flag set to avoid this.
>>>
>>> And also changes _soc_pcm_ret() to not log for -EINVAL errors, to fix
>>> the other error. Userspace passing wrong parameters should not lead
>>> to dmesg messages.
>>
>> Maybe, but it's a questionable flow if pipewire tries to open stuff
>> without the mixer values set-up. Is there something done about this?

I'm working with the pipewire folks to see if we can fix this on
pipewire's side too:

Link: https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/3407

> I think it's an oft-seen problem when user runs the system without
> installing a proper UCM profile.
> 
>> The reason why I am pushing back is that we had a similar issue with
>> HDaudio where HDMI/DP PCM devices were opened without checking if the
>> jack was connected.
>>
>> It really makes no sense for userspace to try and open devices that are
>> known to be problematic. We can push kernel error logs below the rug, it
>> doesn't make the programming flows better.
> 
> Downgrading the message also hides to show what's wrong there.
> Although the message doesn't indicate how to fix the problem, no
> message would make debug harder.
> 
> So in general I agree that it's annoying and it should be fixed, but
> hiding all as default can be bad, too.  Maybe we can introduce a
> counter and shut out after three strikes?

Right, this also happens with unsupported codecs (either unsupported in the kernel or no UCM profile available yet). So making this less "chatty" would be good.

I would prefer to just go for only log this once rather then
three strikes though, then we can simply use 'dev_err_once()'
for this.

Regards,

Hans

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Pierre-Louis Bossart]

>>> Maybe, but it's a questionable flow if pipewire tries to open stuff
>>> without the mixer values set-up. Is there something done about this?
> 
> I'm working with the pipewire folks to see if we can fix this on
> pipewire's side too:
> 
> Link: https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/3407
> 
>> I think it's an oft-seen problem when user runs the system without
>> installing a proper UCM profile.
>>
>>> The reason why I am pushing back is that we had a similar issue with
>>> HDaudio where HDMI/DP PCM devices were opened without checking if the
>>> jack was connected.
>>>
>>> It really makes no sense for userspace to try and open devices that are
>>> known to be problematic. We can push kernel error logs below the rug, it
>>> doesn't make the programming flows better.
>>
>> Downgrading the message also hides to show what's wrong there.
>> Although the message doesn't indicate how to fix the problem, no
>> message would make debug harder.
>>
>> So in general I agree that it's annoying and it should be fixed, but
>> hiding all as default can be bad, too.  Maybe we can introduce a
>> counter and shut out after three strikes?
> 
> Right, this also happens with unsupported codecs (either unsupported in the kernel or no UCM profile available yet). So making this less "chatty" would be good.
> 
> I would prefer to just go for only log this once rather then
> three strikes though, then we can simply use 'dev_err_once()'
> for this.

I'd be fine with dev_err_once(). In general when you have this error 
it's a telltale sign that a configuration is missing. Repeating the 
message does not makes things better.

Maybe also add some information for the user, e.g. "ASoC: no backend 
DAIs enabled for Baytrail Audio Port, possibly missing ALSA mixer-based 
routing or UCM profile"

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Mark Brown]

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

On Fri, Aug 04, 2023 at 04:42:34PM +0200, Takashi Iwai wrote:
> Pierre-Louis Bossart wrote:

> > > And also changes _soc_pcm_ret() to not log for -EINVAL errors, to fix
> > > the other error. Userspace passing wrong parameters should not lead
> > > to dmesg messages.

> > Maybe, but it's a questionable flow if pipewire tries to open stuff
> > without the mixer values set-up. Is there something done about this?

> I think it's an oft-seen problem when user runs the system without
> installing a proper UCM profile.

Yeah, it's really easy to do.

> > It really makes no sense for userspace to try and open devices that are
> > known to be problematic. We can push kernel error logs below the rug, it
> > doesn't make the programming flows better.

> Downgrading the message also hides to show what's wrong there.
> Although the message doesn't indicate how to fix the problem, no
> message would make debug harder.

> So in general I agree that it's annoying and it should be fixed, but
> hiding all as default can be bad, too.  Maybe we can introduce a
> counter and shut out after three strikes?

Hrm, do systems typically filter out debug logs?  Most of the systems I
work on do still log debug logs, they just only include them in dmesg by
default.  There are ratelimited printk APIs which we could use, though
they're not quite ratelimited enough for this I think.

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

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Takashi Iwai]

On Fri, 04 Aug 2023 17:15:14 +0200,
Mark Brown wrote:
> 
> On Fri, Aug 04, 2023 at 04:42:34PM +0200, Takashi Iwai wrote:
> > Pierre-Louis Bossart wrote:
> 
> > > > And also changes _soc_pcm_ret() to not log for -EINVAL errors, to fix
> > > > the other error. Userspace passing wrong parameters should not lead
> > > > to dmesg messages.
> 
> > > Maybe, but it's a questionable flow if pipewire tries to open stuff
> > > without the mixer values set-up. Is there something done about this?
> 
> > I think it's an oft-seen problem when user runs the system without
> > installing a proper UCM profile.
> 
> Yeah, it's really easy to do.
> 
> > > It really makes no sense for userspace to try and open devices that are
> > > known to be problematic. We can push kernel error logs below the rug, it
> > > doesn't make the programming flows better.
> 
> > Downgrading the message also hides to show what's wrong there.
> > Although the message doesn't indicate how to fix the problem, no
> > message would make debug harder.
> 
> > So in general I agree that it's annoying and it should be fixed, but
> > hiding all as default can be bad, too.  Maybe we can introduce a
> > counter and shut out after three strikes?
> 
> Hrm, do systems typically filter out debug logs?  Most of the systems I
> work on do still log debug logs, they just only include them in dmesg by
> default.

I thought flipping the dynamic debug flag needed for showing them up
with dev_dbg() and co.

> There are ratelimited printk APIs which we could use, though
> they're not quite ratelimited enough for this I think.

Yes, this is printed not too frequently but just repeatedly.

IMHO, dev_err_once() would be a good compromise.


thanks,

Takashi

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Mark Brown]

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

On Fri, Aug 04, 2023 at 05:40:20PM +0200, Takashi Iwai wrote:
> Mark Brown wrote:

> > Hrm, do systems typically filter out debug logs?  Most of the systems I
> > work on do still log debug logs, they just only include them in dmesg by
> > default.

> I thought flipping the dynamic debug flag needed for showing them up
> with dev_dbg() and co.

That's an optional feature, I guess perhaps distro kernels will tend to
turn it on but not the defconfigs I'm generally using so I've not been
seeing it.

> > There are ratelimited printk APIs which we could use, though
> > they're not quite ratelimited enough for this I think.

> Yes, this is printed not too frequently but just repeatedly.

> IMHO, dev_err_once() would be a good compromise.

I can imagine that being *super* frustrating when trying to actually
develop configurations since you only get told once per boot that
there's something missing.  dev_dbg() did seem like a sensible choice
here, even with dynamic debug you can at least turn it on.  Perhaps both
a dev_err_once() and a dev_dbg() so you get a hint that there's
something wrong in the logs and can still get ongoing information when
developing your configuration.

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

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Takashi Iwai]

On Fri, 04 Aug 2023 17:50:02 +0200,
Mark Brown wrote:
> 
> On Fri, Aug 04, 2023 at 05:40:20PM +0200, Takashi Iwai wrote:
> > Mark Brown wrote:
> 
> > > Hrm, do systems typically filter out debug logs?  Most of the systems I
> > > work on do still log debug logs, they just only include them in dmesg by
> > > default.
> 
> > I thought flipping the dynamic debug flag needed for showing them up
> > with dev_dbg() and co.
> 
> That's an optional feature, I guess perhaps distro kernels will tend to
> turn it on but not the defconfigs I'm generally using so I've not been
> seeing it.

Ah yes, most distros set CONFIG_DYNAMIC_DEBUG, but defconfig is a
different set.

> > > There are ratelimited printk APIs which we could use, though
> > > they're not quite ratelimited enough for this I think.
> 
> > Yes, this is printed not too frequently but just repeatedly.
> 
> > IMHO, dev_err_once() would be a good compromise.
> 
> I can imagine that being *super* frustrating when trying to actually
> develop configurations since you only get told once per boot that
> there's something missing.  dev_dbg() did seem like a sensible choice
> here, even with dynamic debug you can at least turn it on.  Perhaps both
> a dev_err_once() and a dev_dbg() so you get a hint that there's
> something wrong in the logs and can still get ongoing information when
> developing your configuration.

+1, this sounds like a solution.


thanks,

Takashi

Re: [PATCH] ASoC: lower "no backend DAIs enabled for ... Port" log severity

[Mark Brown]

On Fri, 04 Aug 2023 15:26:28 +0200, Hans de Goede wrote:
> If SNDRV_PCM_IOCTL_PREPARE is called when  the mixer settings linking
> frontend and backend have not been setup yet this results in
> e.g. the following errors getting logged:
> 
> [   43.244549]  Baytrail Audio Port: ASoC: no backend DAIs enabled for Baytrail Audio Port
> [   43.244744]  Baytrail Audio Port: ASoC: error at dpcm_fe_dai_prepare on Baytrail Audio Port: -22
> 
> [...]

Applied to

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

Thanks!

[1/1] ASoC: lower "no backend DAIs enabled for ... Port" log severity
      commit: 1f566435141047ca7db26aa4b0b6647a25badaee

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