[PATCH v2 0/4] soundwire: bus: suppress probe deferral errors

[PATCH v2 0/4] soundwire: bus: suppress probe deferral errors

[Johan Hovold]

The soundwire bus code is incorrectly logging probe deferrals as errors.

This series addresses that, cleans up the soundwire bus logging and
drops the unused soudwire driver name field.

Johan


Changes in v2
 - drop probe error message completely
 - drop soundwire driver name field
 - cleanup probe warning messages
 - drop probe debug message


Johan Hovold (4):
  soundwire: bus: suppress probe deferral errors
  soundwire: bus: drop unused driver name field
  soundwire: bus: clean up probe warnings
  soundwire: bus: drop redundant probe debug message

 drivers/soundwire/bus_type.c  | 21 ++++-----------------
 include/linux/soundwire/sdw.h |  2 --
 2 files changed, 4 insertions(+), 19 deletions(-)

-- 
2.44.1

[PATCH v2 1/4] soundwire: bus: suppress probe deferral errors

[Johan Hovold]

Soundwire driver probe errors are currently being logged both by the bus
code and driver core:

	wsa884x-codec sdw:4:0:0217:0204:00:0: Probe of wsa884x-codec failed: -12
	wsa884x-codec sdw:4:0:0217:0204:00:0: probe with driver wsa884x-codec failed with error -12

Drop the redundant bus error message, which is also incorrectly being
logged on probe deferral:

	wsa884x-codec sdw:4:0:0217:0204:00:0: Probe of wsa884x-codec failed: -517

Note that no soundwire driver uses the driver struct name field, which
will be removed by a follow-on change.

Signed-off-by: Johan Hovold <johan+linaro@kernel.org>
---
 drivers/soundwire/bus_type.c | 6 ------
 1 file changed, 6 deletions(-)

diff --git a/drivers/soundwire/bus_type.c b/drivers/soundwire/bus_type.c
index c32faace618f..85fa5970d98a 100644
--- a/drivers/soundwire/bus_type.c
+++ b/drivers/soundwire/bus_type.c
@@ -83,7 +83,6 @@ static int sdw_drv_probe(struct device *dev)
 	struct sdw_slave *slave = dev_to_sdw_dev(dev);
 	struct sdw_driver *drv = drv_to_sdw_driver(dev->driver);
 	const struct sdw_device_id *id;
-	const char *name;
 	int ret;
 
 	/*
@@ -108,11 +107,6 @@ static int sdw_drv_probe(struct device *dev)
 
 	ret = drv->probe(slave, id);
 	if (ret) {
-		name = drv->name;
-		if (!name)
-			name = drv->driver.name;
-
-		dev_err(dev, "Probe of %s failed: %d\n", name, ret);
 		dev_pm_domain_detach(dev, false);
 		return ret;
 	}
-- 
2.44.1

Re: [PATCH v2 1/4] soundwire: bus: suppress probe deferral errors

[Pierre-Louis Bossart]

On 6/4/24 02:52, Johan Hovold wrote:
> Soundwire driver probe errors are currently being logged both by the bus
> code and driver core:
> 
> 	wsa884x-codec sdw:4:0:0217:0204:00:0: Probe of wsa884x-codec failed: -12
> 	wsa884x-codec sdw:4:0:0217:0204:00:0: probe with driver wsa884x-codec failed with error -12
> 
> Drop the redundant bus error message, which is also incorrectly being
> logged on probe deferral:

It's only redundant in the QCOM case... This would remove all error logs
for other codecs, e.g. see

rt711_sdca_sdw_probe
cs35l56_sdw_probe
wcd9390_probe

Looks like the wsa884x-codec is the chatty driver, others are just fine
with the existing code.

Re: [PATCH v2 1/4] soundwire: bus: suppress probe deferral errors

[Johan Hovold]

On Tue, Jun 04, 2024 at 10:30:21AM +0200, Pierre-Louis Bossart wrote:
> On 6/4/24 02:52, Johan Hovold wrote:
> > Soundwire driver probe errors are currently being logged both by the bus
> > code and driver core:
> > 
> > 	wsa884x-codec sdw:4:0:0217:0204:00:0: Probe of wsa884x-codec failed: -12
> > 	wsa884x-codec sdw:4:0:0217:0204:00:0: probe with driver wsa884x-codec failed with error -12
> > 
> > Drop the redundant bus error message, which is also incorrectly being
> > logged on probe deferral:
> 
> It's only redundant in the QCOM case... This would remove all error logs
> for other codecs, e.g. see
> 
> rt711_sdca_sdw_probe
> cs35l56_sdw_probe
> wcd9390_probe
> 
> Looks like the wsa884x-codec is the chatty driver, others are just fine
> with the existing code.

I believe you misunderstood this patch. The error messages above are not
printed by the wsa884x-codec driver, but by the soundwire bus code and
driver core, so the redundant error message will be printed for all
codecs on probe failures.

And specifically, driver core will still log probe failures after this
change.

Johan

Re: [PATCH v2 1/4] soundwire: bus: suppress probe deferral errors

[Pierre-Louis Bossart]

On 6/4/24 11:09, Johan Hovold wrote:
> On Tue, Jun 04, 2024 at 10:30:21AM +0200, Pierre-Louis Bossart wrote:
>> On 6/4/24 02:52, Johan Hovold wrote:
>>> Soundwire driver probe errors are currently being logged both by the bus
>>> code and driver core:
>>>
>>> 	wsa884x-codec sdw:4:0:0217:0204:00:0: Probe of wsa884x-codec failed: -12
>>> 	wsa884x-codec sdw:4:0:0217:0204:00:0: probe with driver wsa884x-codec failed with error -12
>>>
>>> Drop the redundant bus error message, which is also incorrectly being
>>> logged on probe deferral:
>>
>> It's only redundant in the QCOM case... This would remove all error logs
>> for other codecs, e.g. see
>>
>> rt711_sdca_sdw_probe
>> cs35l56_sdw_probe
>> wcd9390_probe
>>
>> Looks like the wsa884x-codec is the chatty driver, others are just fine
>> with the existing code.
> 
> I believe you misunderstood this patch. The error messages above are not
> printed by the wsa884x-codec driver, but by the soundwire bus code and
> driver core, so the redundant error message will be printed for all
> codecs on probe failures.
> 
> And specifically, driver core will still log probe failures after this
> change.

Ah yes, you're right I read 'driver core' sideways, my bad. That's fine
then.

[PATCH v2 2/4] soundwire: bus: drop unused driver name field

[Johan Hovold]

The soundwire driver name field is not currently used by any driver (and
even appears to never have been used) so drop it.

Signed-off-by: Johan Hovold <johan+linaro@kernel.org>
---
 drivers/soundwire/bus_type.c  | 9 ++-------
 include/linux/soundwire/sdw.h | 2 --
 2 files changed, 2 insertions(+), 9 deletions(-)

diff --git a/drivers/soundwire/bus_type.c b/drivers/soundwire/bus_type.c
index 85fa5970d98a..3979be0f8b65 100644
--- a/drivers/soundwire/bus_type.c
+++ b/drivers/soundwire/bus_type.c
@@ -198,16 +198,11 @@ static void sdw_drv_shutdown(struct device *dev)
  */
 int __sdw_register_driver(struct sdw_driver *drv, struct module *owner)
 {
-	const char *name;
-
 	drv->driver.bus = &sdw_bus_type;
 
 	if (!drv->probe) {
-		name = drv->name;
-		if (!name)
-			name = drv->driver.name;
-
-		pr_err("driver %s didn't provide SDW probe routine\n", name);
+		pr_err("driver %s didn't provide SDW probe routine\n",
+				drv->driver.name);
 		return -EINVAL;
 	}
 
diff --git a/include/linux/soundwire/sdw.h b/include/linux/soundwire/sdw.h
index 13e96d8b7423..5e133dfec8f2 100644
--- a/include/linux/soundwire/sdw.h
+++ b/include/linux/soundwire/sdw.h
@@ -704,8 +704,6 @@ struct sdw_master_device {
 	container_of(d, struct sdw_master_device, dev)
 
 struct sdw_driver {
-	const char *name;
-
 	int (*probe)(struct sdw_slave *sdw,
 			const struct sdw_device_id *id);
 	int (*remove)(struct sdw_slave *sdw);
-- 
2.44.1

[PATCH v2 3/4] soundwire: bus: clean up probe warnings

[Johan Hovold]

Clean up the probe warning messages by using a common succinct format
(e.g. without __func__ and with a space after ':').

Signed-off-by: Johan Hovold <johan+linaro@kernel.org>
---
 drivers/soundwire/bus_type.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/drivers/soundwire/bus_type.c b/drivers/soundwire/bus_type.c
index 3979be0f8b65..43e732ca73c0 100644
--- a/drivers/soundwire/bus_type.c
+++ b/drivers/soundwire/bus_type.c
@@ -123,7 +123,7 @@ static int sdw_drv_probe(struct device *dev)
 	/* init the dynamic sysfs attributes we need */
 	ret = sdw_slave_sysfs_dpn_init(slave);
 	if (ret < 0)
-		dev_warn(dev, "Slave sysfs init failed:%d\n", ret);
+		dev_warn(dev, "failed to initialise sysfs: %d\n", ret);
 
 	/*
 	 * Check for valid clk_stop_timeout, use DisCo worst case value of
@@ -147,7 +147,7 @@ static int sdw_drv_probe(struct device *dev)
 	if (drv->ops && drv->ops->update_status) {
 		ret = drv->ops->update_status(slave, slave->status);
 		if (ret < 0)
-			dev_warn(dev, "%s: update_status failed with status %d\n", __func__, ret);
+			dev_warn(dev, "failed to update status: %d\n", ret);
 	}
 
 	mutex_unlock(&slave->sdw_dev_lock);
-- 
2.44.1

Re: [PATCH v2 3/4] soundwire: bus: clean up probe warnings

[Pierre-Louis Bossart]

On 6/4/24 02:52, Johan Hovold wrote:
> Clean up the probe warning messages by using a common succinct format
> (e.g. without __func__ and with a space after ':').
> 
> Signed-off-by: Johan Hovold <johan+linaro@kernel.org>
> ---
>  drivers/soundwire/bus_type.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/soundwire/bus_type.c b/drivers/soundwire/bus_type.c
> index 3979be0f8b65..43e732ca73c0 100644
> --- a/drivers/soundwire/bus_type.c
> +++ b/drivers/soundwire/bus_type.c
> @@ -123,7 +123,7 @@ static int sdw_drv_probe(struct device *dev)
>  	/* init the dynamic sysfs attributes we need */
>  	ret = sdw_slave_sysfs_dpn_init(slave);
>  	if (ret < 0)
> -		dev_warn(dev, "Slave sysfs init failed:%d\n", ret);
> +		dev_warn(dev, "failed to initialise sysfs: %d\n", ret);
>  
>  	/*
>  	 * Check for valid clk_stop_timeout, use DisCo worst case value of
> @@ -147,7 +147,7 @@ static int sdw_drv_probe(struct device *dev)
>  	if (drv->ops && drv->ops->update_status) {
>  		ret = drv->ops->update_status(slave, slave->status);
>  		if (ret < 0)
> -			dev_warn(dev, "%s: update_status failed with status %d\n", __func__, ret);
> +			dev_warn(dev, "failed to update status: %d\n", ret);

the __func__ does help IMHO, 'failed to update status' is way too general...
Replacing 'with status' by ":" is fine, but do we really care about 10
chars in a log?

Re: [PATCH v2 3/4] soundwire: bus: clean up probe warnings

[Johan Hovold]

On Tue, Jun 04, 2024 at 10:33:02AM +0200, Pierre-Louis Bossart wrote:
> On 6/4/24 02:52, Johan Hovold wrote:
> > Clean up the probe warning messages by using a common succinct format
> > (e.g. without __func__ and with a space after ':').

> > @@ -123,7 +123,7 @@ static int sdw_drv_probe(struct device *dev)
> >  	/* init the dynamic sysfs attributes we need */
> >  	ret = sdw_slave_sysfs_dpn_init(slave);
> >  	if (ret < 0)
> > -		dev_warn(dev, "Slave sysfs init failed:%d\n", ret);
> > +		dev_warn(dev, "failed to initialise sysfs: %d\n", ret);
> >  
> >  	/*
> >  	 * Check for valid clk_stop_timeout, use DisCo worst case value of
> > @@ -147,7 +147,7 @@ static int sdw_drv_probe(struct device *dev)
> >  	if (drv->ops && drv->ops->update_status) {
> >  		ret = drv->ops->update_status(slave, slave->status);
> >  		if (ret < 0)
> > -			dev_warn(dev, "%s: update_status failed with status %d\n", __func__, ret);
> > +			dev_warn(dev, "failed to update status: %d\n", ret);
> 
> the __func__ does help IMHO, 'failed to update status' is way too general...

Error messages printed with dev_warn will include the device and driver
names so this message will be quite specific still.

> Replacing 'with status' by ":" is fine, but do we really care about 10
> chars in a log?

It's not primarily about the numbers of characters but about consistency.

Johan

Re: [PATCH v2 3/4] soundwire: bus: clean up probe warnings

[Pierre-Louis Bossart]

On 6/4/24 11:17, Johan Hovold wrote:
> On Tue, Jun 04, 2024 at 10:33:02AM +0200, Pierre-Louis Bossart wrote:
>> On 6/4/24 02:52, Johan Hovold wrote:
>>> Clean up the probe warning messages by using a common succinct format
>>> (e.g. without __func__ and with a space after ':').
> 
>>> @@ -123,7 +123,7 @@ static int sdw_drv_probe(struct device *dev)
>>>  	/* init the dynamic sysfs attributes we need */
>>>  	ret = sdw_slave_sysfs_dpn_init(slave);
>>>  	if (ret < 0)
>>> -		dev_warn(dev, "Slave sysfs init failed:%d\n", ret);
>>> +		dev_warn(dev, "failed to initialise sysfs: %d\n", ret);
>>>  
>>>  	/*
>>>  	 * Check for valid clk_stop_timeout, use DisCo worst case value of
>>> @@ -147,7 +147,7 @@ static int sdw_drv_probe(struct device *dev)
>>>  	if (drv->ops && drv->ops->update_status) {
>>>  		ret = drv->ops->update_status(slave, slave->status);
>>>  		if (ret < 0)
>>> -			dev_warn(dev, "%s: update_status failed with status %d\n", __func__, ret);
>>> +			dev_warn(dev, "failed to update status: %d\n", ret);
>>
>> the __func__ does help IMHO, 'failed to update status' is way too general...
> 
> Error messages printed with dev_warn will include the device and driver
> names so this message will be quite specific still.

The goal isn't to be 'quite specific' but rather 'completely
straightforward'. Everyone can lookup a function name in a xref tool and
 quickly find out what happened. Doing 'git grep' on message logs isn't
great really, and over time logs tend to be copy-pasted. Just look at
the number of patches where we had to revisit the dev_err logs to make
then really unique/useful.

>> Replacing 'with status' by ":" is fine, but do we really care about 10
>> chars in a log?
> 
> It's not primarily about the numbers of characters but about consistency.

I am advocating for inclusion of __func__ everywhere...It's simpler for
remote support and bug chasing.

The exception to the rule would be dev_dbg where you can get the
function name with module options.

Re: [PATCH v2 3/4] soundwire: bus: clean up probe warnings

[Johan Hovold]

On Tue, Jun 04, 2024 at 03:43:46PM +0200, Pierre-Louis Bossart wrote:
> On 6/4/24 11:17, Johan Hovold wrote:
> > On Tue, Jun 04, 2024 at 10:33:02AM +0200, Pierre-Louis Bossart wrote:
> >> On 6/4/24 02:52, Johan Hovold wrote:
> >>> Clean up the probe warning messages by using a common succinct format
> >>> (e.g. without __func__ and with a space after ':').
> > 
> >>> @@ -123,7 +123,7 @@ static int sdw_drv_probe(struct device *dev)
> >>>  	/* init the dynamic sysfs attributes we need */
> >>>  	ret = sdw_slave_sysfs_dpn_init(slave);
> >>>  	if (ret < 0)
> >>> -		dev_warn(dev, "Slave sysfs init failed:%d\n", ret);
> >>> +		dev_warn(dev, "failed to initialise sysfs: %d\n", ret);
> >>>  
> >>>  	/*
> >>>  	 * Check for valid clk_stop_timeout, use DisCo worst case value of
> >>> @@ -147,7 +147,7 @@ static int sdw_drv_probe(struct device *dev)
> >>>  	if (drv->ops && drv->ops->update_status) {
> >>>  		ret = drv->ops->update_status(slave, slave->status);
> >>>  		if (ret < 0)
> >>> -			dev_warn(dev, "%s: update_status failed with status %d\n", __func__, ret);
> >>> +			dev_warn(dev, "failed to update status: %d\n", ret);
> >>
> >> the __func__ does help IMHO, 'failed to update status' is way too general...
> > 
> > Error messages printed with dev_warn will include the device and driver
> > names so this message will be quite specific still.
> 
> The goal isn't to be 'quite specific' but rather 'completely
> straightforward'. Everyone can lookup a function name in a xref tool and
>  quickly find out what happened. Doing 'git grep' on message logs isn't
> great really, and over time logs tend to be copy-pasted. Just look at
> the number of patches where we had to revisit the dev_err logs to make
> then really unique/useful.

Error message should be self-contained and give user's some idea of what
went wrong and not leak implementation details like function names (and
be greppable, which "%s:" is not).

> >> Replacing 'with status' by ":" is fine, but do we really care about 10
> >> chars in a log?
> > 
> > It's not primarily about the numbers of characters but about consistency.
> 
> I am advocating for inclusion of __func__ everywhere...It's simpler for
> remote support and bug chasing.

A quick grep seems to suggest you're in a small minority here with some
5k of 65k dev_err() including __func__.

[ And there's only 55 out of 750 dev_err() like that in
drivers/soundwire, which is inconsistent at best. ]

Johan

Re: [PATCH v2 3/4] soundwire: bus: clean up probe warnings

[Pierre-Louis Bossart]

\
>>>>> @@ -123,7 +123,7 @@ static int sdw_drv_probe(struct device *dev)
>>>>>  	/* init the dynamic sysfs attributes we need */
>>>>>  	ret = sdw_slave_sysfs_dpn_init(slave);
>>>>>  	if (ret < 0)
>>>>> -		dev_warn(dev, "Slave sysfs init failed:%d\n", ret);
>>>>> +		dev_warn(dev, "failed to initialise sysfs: %d\n", ret);
>>>>>  
>>>>>  	/*
>>>>>  	 * Check for valid clk_stop_timeout, use DisCo worst case value of
>>>>> @@ -147,7 +147,7 @@ static int sdw_drv_probe(struct device *dev)
>>>>>  	if (drv->ops && drv->ops->update_status) {
>>>>>  		ret = drv->ops->update_status(slave, slave->status);
>>>>>  		if (ret < 0)
>>>>> -			dev_warn(dev, "%s: update_status failed with status %d\n", __func__, ret);
>>>>> +			dev_warn(dev, "failed to update status: %d\n", ret);
>>>>
>>>> the __func__ does help IMHO, 'failed to update status' is way too general...
>>>
>>> Error messages printed with dev_warn will include the device and driver
>>> names so this message will be quite specific still.
>>
>> The goal isn't to be 'quite specific' but rather 'completely
>> straightforward'. Everyone can lookup a function name in a xref tool and
>>  quickly find out what happened. Doing 'git grep' on message logs isn't
>> great really, and over time logs tend to be copy-pasted. Just look at
>> the number of patches where we had to revisit the dev_err logs to make
>> then really unique/useful.
> 
> Error message should be self-contained and give user's some idea of what
> went wrong and not leak implementation details like function names (and
> be greppable, which "%s:" is not).

"Failed to update status" doesn't sound terribly self-contained to me.

It's actually a great example of making the logs less clear with good
intentions. How many people know that the SoundWire bus exposes an
'update_status' callback, and that callback can be invoked from two
completely different places (probe or on device attachment)?

/* Ensure driver knows that peripheral unattached */
ret = sdw_update_slave_status(slave, status[i]);
if (ret < 0)
	dev_warn(&slave->dev, "Update Slave status failed:%d\n", ret);

You absolutely want to know which of these two cases failed, but with
your changes they now look rather identical except for the order of
words. one would be 'failed to update status' and the other 'update
status failed'.

What is much better is to know WHEN this failure happens, then folks
looking at logs to fix a problem don't need to worry about precise
wording or word order.

It's a constant battle to get meaningful messages that are useful for
validation/integration folks, and my take is that it's a
windmill-fighting endeavor. The function name is actually more useful,
it's not an implementation detail, it's what you're looking for when
reverse-engineering problematic sequences from a series of CI logs.

>>>> Replacing 'with status' by ":" is fine, but do we really care about 10
>>>> chars in a log?
>>>
>>> It's not primarily about the numbers of characters but about consistency.
>>
>> I am advocating for inclusion of __func__ everywhere...It's simpler for
>> remote support and bug chasing.

I meant everywhere in SoundWire. Other subsystems may have different
views and different observability tools, that's fine.

> A quick grep seems to suggest you're in a small minority here with some
> 5k of 65k dev_err() including __func__.
> 
> [ And there's only 55 out of 750 dev_err() like that in
> drivers/soundwire, which is inconsistent at best. ]

As you mentioned yourself, the asynchronous nature of the SoundWire
probe/attachment/interrupts makes it difficult to reverse-engineer, and
we want to err on the side of MORE information.

Also not all dev_err() are equal, most are part of paranoid checks and
never used. An example above is the sysfs log, we've never seen it happen.

That's different to changes that impact probe and interrupts which will
fail at some point on new platforms. It's not an academic statement,
I've spent most of my day chasing two such issues.

Re: [PATCH v2 3/4] soundwire: bus: clean up probe warnings

[Johan Hovold]

On Tue, Jun 04, 2024 at 05:07:39PM +0200, Pierre-Louis Bossart wrote:
> \
> >>>>> @@ -123,7 +123,7 @@ static int sdw_drv_probe(struct device *dev)
> >>>>>  	/* init the dynamic sysfs attributes we need */
> >>>>>  	ret = sdw_slave_sysfs_dpn_init(slave);
> >>>>>  	if (ret < 0)
> >>>>> -		dev_warn(dev, "Slave sysfs init failed:%d\n", ret);
> >>>>> +		dev_warn(dev, "failed to initialise sysfs: %d\n", ret);
> >>>>>  
> >>>>>  	/*
> >>>>>  	 * Check for valid clk_stop_timeout, use DisCo worst case value of
> >>>>> @@ -147,7 +147,7 @@ static int sdw_drv_probe(struct device *dev)
> >>>>>  	if (drv->ops && drv->ops->update_status) {
> >>>>>  		ret = drv->ops->update_status(slave, slave->status);
> >>>>>  		if (ret < 0)
> >>>>> -			dev_warn(dev, "%s: update_status failed with status %d\n", __func__, ret);
> >>>>> +			dev_warn(dev, "failed to update status: %d\n", ret);
> >>>>
> >>>> the __func__ does help IMHO, 'failed to update status' is way too general...
> >>>
> >>> Error messages printed with dev_warn will include the device and driver
> >>> names so this message will be quite specific still.
> >>
> >> The goal isn't to be 'quite specific' but rather 'completely
> >> straightforward'. Everyone can lookup a function name in a xref tool and
> >>  quickly find out what happened. Doing 'git grep' on message logs isn't
> >> great really, and over time logs tend to be copy-pasted. Just look at
> >> the number of patches where we had to revisit the dev_err logs to make
> >> then really unique/useful.
> > 
> > Error message should be self-contained and give user's some idea of what
> > went wrong and not leak implementation details like function names (and
> > be greppable, which "%s:" is not).
> 
> "Failed to update status" doesn't sound terribly self-contained to me.
> 
> It's actually a great example of making the logs less clear with good
> intentions. How many people know that the SoundWire bus exposes an
> 'update_status' callback, and that callback can be invoked from two
> completely different places (probe or on device attachment)?
> 
> /* Ensure driver knows that peripheral unattached */
> ret = sdw_update_slave_status(slave, status[i]);
> if (ret < 0)
> 	dev_warn(&slave->dev, "Update Slave status failed:%d\n", ret);
> 
> You absolutely want to know which of these two cases failed, but with
> your changes they now look rather identical except for the order of
> words. one would be 'failed to update status' and the other 'update
> status failed'.
> 
> What is much better is to know WHEN this failure happens, then folks
> looking at logs to fix a problem don't need to worry about precise
> wording or word order.
> 
> It's a constant battle to get meaningful messages that are useful for
> validation/integration folks, and my take is that it's a
> windmill-fighting endeavor. The function name is actually more useful,
> it's not an implementation detail, it's what you're looking for when
> reverse-engineering problematic sequences from a series of CI logs.

Just add "at probe" to differentiate the two cases if you really think
this is an issue:

	dev_warn(dev, "failed to update status at probe: %d\n", ret);

Johan

Re: [PATCH v2 3/4] soundwire: bus: clean up probe warnings

[Pierre-Louis Bossart]

On 6/5/24 14:11, Johan Hovold wrote:
> On Tue, Jun 04, 2024 at 05:07:39PM +0200, Pierre-Louis Bossart wrote:
>> \
>>>>>>> @@ -123,7 +123,7 @@ static int sdw_drv_probe(struct device *dev)
>>>>>>>  	/* init the dynamic sysfs attributes we need */
>>>>>>>  	ret = sdw_slave_sysfs_dpn_init(slave);
>>>>>>>  	if (ret < 0)
>>>>>>> -		dev_warn(dev, "Slave sysfs init failed:%d\n", ret);
>>>>>>> +		dev_warn(dev, "failed to initialise sysfs: %d\n", ret);
>>>>>>>  
>>>>>>>  	/*
>>>>>>>  	 * Check for valid clk_stop_timeout, use DisCo worst case value of
>>>>>>> @@ -147,7 +147,7 @@ static int sdw_drv_probe(struct device *dev)
>>>>>>>  	if (drv->ops && drv->ops->update_status) {
>>>>>>>  		ret = drv->ops->update_status(slave, slave->status);
>>>>>>>  		if (ret < 0)
>>>>>>> -			dev_warn(dev, "%s: update_status failed with status %d\n", __func__, ret);
>>>>>>> +			dev_warn(dev, "failed to update status: %d\n", ret);
>>>>>>
>>>>>> the __func__ does help IMHO, 'failed to update status' is way too general...
>>>>>
>>>>> Error messages printed with dev_warn will include the device and driver
>>>>> names so this message will be quite specific still.
>>>>
>>>> The goal isn't to be 'quite specific' but rather 'completely
>>>> straightforward'. Everyone can lookup a function name in a xref tool and
>>>>  quickly find out what happened. Doing 'git grep' on message logs isn't
>>>> great really, and over time logs tend to be copy-pasted. Just look at
>>>> the number of patches where we had to revisit the dev_err logs to make
>>>> then really unique/useful.
>>>
>>> Error message should be self-contained and give user's some idea of what
>>> went wrong and not leak implementation details like function names (and
>>> be greppable, which "%s:" is not).
>>
>> "Failed to update status" doesn't sound terribly self-contained to me.
>>
>> It's actually a great example of making the logs less clear with good
>> intentions. How many people know that the SoundWire bus exposes an
>> 'update_status' callback, and that callback can be invoked from two
>> completely different places (probe or on device attachment)?
>>
>> /* Ensure driver knows that peripheral unattached */
>> ret = sdw_update_slave_status(slave, status[i]);
>> if (ret < 0)
>> 	dev_warn(&slave->dev, "Update Slave status failed:%d\n", ret);
>>
>> You absolutely want to know which of these two cases failed, but with
>> your changes they now look rather identical except for the order of
>> words. one would be 'failed to update status' and the other 'update
>> status failed'.
>>
>> What is much better is to know WHEN this failure happens, then folks
>> looking at logs to fix a problem don't need to worry about precise
>> wording or word order.
>>
>> It's a constant battle to get meaningful messages that are useful for
>> validation/integration folks, and my take is that it's a
>> windmill-fighting endeavor. The function name is actually more useful,
>> it's not an implementation detail, it's what you're looking for when
>> reverse-engineering problematic sequences from a series of CI logs.
> 
> Just add "at probe" to differentiate the two cases if you really think
> this is an issue:
> 
> 	dev_warn(dev, "failed to update status at probe: %d\n", ret);

__func__ would provide equivalent functionality, only more precise...
I guess it's time for Vinod and Bard to chime in.

[PATCH v2 4/4] soundwire: bus: drop redundant probe debug message

[Johan Hovold]

Drop the redundant probe debug message which is already provided by
driver core. Whether probe succeeded can also be determined through
sysfs.

Signed-off-by: Johan Hovold <johan+linaro@kernel.org>
---
 drivers/soundwire/bus_type.c | 2 --
 1 file changed, 2 deletions(-)

diff --git a/drivers/soundwire/bus_type.c b/drivers/soundwire/bus_type.c
index 43e732ca73c0..5b9b129badff 100644
--- a/drivers/soundwire/bus_type.c
+++ b/drivers/soundwire/bus_type.c
@@ -152,8 +152,6 @@ static int sdw_drv_probe(struct device *dev)
 
 	mutex_unlock(&slave->sdw_dev_lock);
 
-	dev_dbg(dev, "probe complete\n");
-
 	return 0;
 }
 
-- 
2.44.1

Re: [PATCH v2 4/4] soundwire: bus: drop redundant probe debug message

[Pierre-Louis Bossart]

On 6/4/24 02:52, Johan Hovold wrote:
> Drop the redundant probe debug message which is already provided by
> driver core. Whether probe succeeded can also be determined through
> sysfs.
> 
> Signed-off-by: Johan Hovold <johan+linaro@kernel.org>
> ---
>  drivers/soundwire/bus_type.c | 2 --
>  1 file changed, 2 deletions(-)
> 
> diff --git a/drivers/soundwire/bus_type.c b/drivers/soundwire/bus_type.c
> index 43e732ca73c0..5b9b129badff 100644
> --- a/drivers/soundwire/bus_type.c
> +++ b/drivers/soundwire/bus_type.c
> @@ -152,8 +152,6 @@ static int sdw_drv_probe(struct device *dev)
>  
>  	mutex_unlock(&slave->sdw_dev_lock);
>  
> -	dev_dbg(dev, "probe complete\n");
> -
>  	return 0;
>  }

I don't see the point of removing this, we've used it for the last 5
years to figure out when the probe complete vs. when the device becomes
attached. It's a simple log that helped us immensely with race
conditions, etc.

And no, sysfs is not a viable alternative to look at CI logs, and
enabling dynamic debug on the driver core would be way to verbose.

Re: [PATCH v2 4/4] soundwire: bus: drop redundant probe debug message

[Johan Hovold]

On Tue, Jun 04, 2024 at 10:37:17AM +0200, Pierre-Louis Bossart wrote:
> On 6/4/24 02:52, Johan Hovold wrote:
> > Drop the redundant probe debug message which is already provided by
> > driver core. Whether probe succeeded can also be determined through
> > sysfs.

> > @@ -152,8 +152,6 @@ static int sdw_drv_probe(struct device *dev)
> >  
> >  	mutex_unlock(&slave->sdw_dev_lock);
> >  
> > -	dev_dbg(dev, "probe complete\n");
> > -
> >  	return 0;
> >  }
> 
> I don't see the point of removing this, we've used it for the last 5
> years to figure out when the probe complete vs. when the device becomes
> attached. It's a simple log that helped us immensely with race
> conditions, etc.

Fair enough. Soundwire probing is indeed a bit of a mess.

Johan