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

[Johan Hovold <johan@kernel.org>]

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