[PATCH v2] firmware loader: log path to loaded firmwares

[PATCH v2] firmware loader: log path to loaded firmwares

[Drew DeVault]

This is useful for users who are trying to identify the firmwares in use
on their system.

Signed-off-by: Drew DeVault <sir@cmpwn.com>
---
v2 uses dev_dbg instead of printk(KERN_INFO)

 drivers/base/firmware_loader/main.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/drivers/base/firmware_loader/main.c b/drivers/base/firmware_loader/main.c
index bf44c79beae9..2537da43a572 100644
--- a/drivers/base/firmware_loader/main.c
+++ b/drivers/base/firmware_loader/main.c
@@ -504,6 +504,7 @@ fw_get_filesystem_firmware(struct device *device, struct fw_priv *fw_priv,
 					 path);
 			continue;
 		}
+		dev_dbg(device, "Loading firmware from %s\n", path);
 		if (decompress) {
 			dev_dbg(device, "f/w decompressing %s\n",
 				fw_priv->fw_name);
-- 
2.23.0

Re: [PATCH v2] firmware loader: log path to loaded firmwares

[Luis Chamberlain]

On Sun, Nov 03, 2019 at 01:06:46PM -0500, Drew DeVault wrote:
> 
> This is useful for users who are trying to identify the firmwares in use
> on their system.
> 
> Signed-off-by: Drew DeVault <sir@cmpwn.com>
> ---
> v2 uses dev_dbg instead of printk(KERN_INFO)
> 
>  drivers/base/firmware_loader/main.c | 1 +
>  1 file changed, 1 insertion(+)
> 
> diff --git a/drivers/base/firmware_loader/main.c b/drivers/base/firmware_loader/main.c
> index bf44c79beae9..2537da43a572 100644
> --- a/drivers/base/firmware_loader/main.c
> +++ b/drivers/base/firmware_loader/main.c
> @@ -504,6 +504,7 @@ fw_get_filesystem_firmware(struct device *device, struct fw_priv *fw_priv,
>  					 path);
>  			continue;
>  		}
> +		dev_dbg(device, "Loading firmware from %s\n", path);

Because this is dev_dbg() I'm willing to consider it, so that its not
always enabled. However its not in the right place, the code path you
are addressing is only for direct filesystem lookups. If that fails
some systems do a fallback call out to userspace. To cover both cases,
you want it at the end of _request_firmware() on the success path. Can
you send a new patch?

  Luis

>  		if (decompress) {
>  			dev_dbg(device, "f/w decompressing %s\n",
>  				fw_priv->fw_name);
> -- 
> 2.23.0
> 

Re: [PATCH v2] firmware loader: log path to loaded firmwares

[Drew DeVault]

Sure, no problem. Thanks for clarifying.

Re: [PATCH v2] firmware loader: log path to loaded firmwares

[Robin H. Johnson]

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

On Wed, Nov 13, 2019 at 12:56:28AM +0000, Luis Chamberlain wrote:
> On Sun, Nov 03, 2019 at 01:06:46PM -0500, Drew DeVault wrote:
> > 
> > This is useful for users who are trying to identify the firmwares in use
> > on their system.
> > 
> > Signed-off-by: Drew DeVault <sir@cmpwn.com>
> > ---
> > v2 uses dev_dbg instead of printk(KERN_INFO)
> > 
> >  drivers/base/firmware_loader/main.c | 1 +
> >  1 file changed, 1 insertion(+)
> > 
> > diff --git a/drivers/base/firmware_loader/main.c b/drivers/base/firmware_loader/main.c
> > index bf44c79beae9..2537da43a572 100644
> > --- a/drivers/base/firmware_loader/main.c
> > +++ b/drivers/base/firmware_loader/main.c
> > @@ -504,6 +504,7 @@ fw_get_filesystem_firmware(struct device *device, struct fw_priv *fw_priv,
> >  					 path);
> >  			continue;
> >  		}
> > +		dev_dbg(device, "Loading firmware from %s\n", path);
> 
> Because this is dev_dbg() I'm willing to consider it, so that its not
> always enabled. However its not in the right place, the code path you
> are addressing is only for direct filesystem lookups. If that fails
> some systems do a fallback call out to userspace. To cover both cases,
> you want it at the end of _request_firmware() on the success path. Can
> you send a new patch?
As the author of a separate patch that predates Drew's patch (originally
in July, with a later version sent to the list last week):
https://pastebin.com/Tf09x3ed (v1)
https://lkml.org/lkml/2019/11/7/800 (v2)

This already uses the _request_firmware path to fire after the firmware
was successfully loaded. The commit message is also specific that it's
to cover early boot situations, before UEVENT can be logged.

dev_dbg means that the loglevel must have been set to debug BEFORE the
firmware load took place, but this means either setting system-wide
debug spam or requiring debugfs, which is annoying for boot stuff (not
impossible, just annoying).

I have two uses cases overall:
- log so you know exactly when it's loaded successfully (great if
  loading a firmware causes your system to lock up a few seconds later)
- at some point in the future, being able to query what firmware was
  loaded in the past, and esp. exactly what version/data was in that
  firmware file.

-- 
Robin Hugh Johnson
Gentoo Linux: Dev, Infra Lead, Foundation Treasurer
E-Mail   : robbat2@gentoo.org
GnuPG FP : 11ACBA4F 4778E3F6 E4EDF38E B27B944E 34884E85
GnuPG FP : 7D0B3CEB E9B85B1F 825BCECF EE05E6F6 A48F6136

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

Re: [PATCH v2] firmware loader: log path to loaded firmwares

[Luis Chamberlain]

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

On Wed, Nov 13, 2019 at 08:19:07PM +0000, Robin H. Johnson wrote:
> I have two uses cases overall:
> - log so you know exactly when it's loaded successfully (great if
>   loading a firmware causes your system to lock up a few seconds later)

Then you can change the driver to confirm this, not impose every driver
to do the same.

> - at some point in the future, being able to query what firmware was
>   loaded in the past, and esp. exactly what version/data was in that
>   firmware file.

Firmware data is opaque to the firmware loader, as such details to
extract generic information about firmware details can only be done
by the driver, which could decode the firmware information. Many
drivers print these details themselves already, if they want it.

A generic interface to let us query *all* devices and currently loaded
firmware through the firmware loader would only be possible today for
firmware which requests (the default) caching of firmware upon
suspend/resume given that we keep the device / firmware name pair
around prior to suspend. For those devices it could be possible to
extend the firmware loader with a driver callback which can extract
firmware details in a generic codified way. To support *all* drivers
though, in a more clean way for this, a separate but similar list
could be kept which enables one to do this. Such items would be
torn down upon driver removal. But that would then be an opt-in
new mechanism.

  Luis

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

Re: [PATCH v2] firmware loader: log path to loaded firmwares

[Drew DeVault]

I have a new patch prepared which moves my logging into
_request_firmware. Would you prefer I send this along or would you like
to take Robin's patch?

[PATCH v3] firmware: log name & outcome of loaded firmware

[Robin H. Johnson]

It's non-trivial to figure out names of firmware that was actually
loaded, add a debug statement at the end of _request_firmware that logs
the name & result of each firmware.

This is esp. valuable early in boot, before logging of UEVENT is
available.

v3:
- Log at dev_dbg level per maintainer.
- HOWTO: Enable at boot via kernel boot param
  dyndbg="func _request_firmware +p"
- Credit to Drew DeVault for parallel creation and help promoting the
  idea.

Alternate-Creation: Drew DeVault <sir@cmpwn.com>
Signed-off-by: Robin H. Johnson <robbat2@gentoo.org>
---
 drivers/base/firmware_loader/main.c | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/drivers/base/firmware_loader/main.c b/drivers/base/firmware_loader/main.c
index bf44c79beae9..84a879608ca4 100644
--- a/drivers/base/firmware_loader/main.c
+++ b/drivers/base/firmware_loader/main.c
@@ -791,6 +791,13 @@ _request_firmware(const struct firmware **firmware_p, const char *name,
 		fw = NULL;
 	}
 
+	/* Provide a consistent way to capture the result of trying to load any
+	 * firmware. As a potential future improvement, this might include
+	 * persistent state that firmware is loaded (or failed to load for some
+	 * reason). See Message-ID: <20191113205010.GY11244@42.do-not-panic.com>
+	 * for background */
+	dev_dbg(device, "%s %s ret=%d\n", __func__, name, ret);
+
 	*firmware_p = fw;
 	return ret;
 }
-- 
2.24.0

Re: [PATCH v3] firmware: log name & outcome of loaded firmware

[Greg KH]

On Sun, Nov 17, 2019 at 03:47:34PM -0800, Robin H. Johnson wrote:
> It's non-trivial to figure out names of firmware that was actually
> loaded, add a debug statement at the end of _request_firmware that logs
> the name & result of each firmware.
> 
> This is esp. valuable early in boot, before logging of UEVENT is
> available.
> 
> v3:
> - Log at dev_dbg level per maintainer.
> - HOWTO: Enable at boot via kernel boot param
>   dyndbg="func _request_firmware +p"
> - Credit to Drew DeVault for parallel creation and help promoting the
>   idea.

These "v3.." lines need to go below the --- line.

> 
> Alternate-Creation: Drew DeVault <sir@cmpwn.com>

Is that a valid tag?  You can have co-developed-by (or something like
that, read the documentation for the real name), but I have never seen
this one before.

> Signed-off-by: Robin H. Johnson <robbat2@gentoo.org>
> ---
>  drivers/base/firmware_loader/main.c | 7 +++++++
>  1 file changed, 7 insertions(+)
> 
> diff --git a/drivers/base/firmware_loader/main.c b/drivers/base/firmware_loader/main.c
> index bf44c79beae9..84a879608ca4 100644
> --- a/drivers/base/firmware_loader/main.c
> +++ b/drivers/base/firmware_loader/main.c
> @@ -791,6 +791,13 @@ _request_firmware(const struct firmware **firmware_p, const char *name,
>  		fw = NULL;
>  	}
>  
> +	/* Provide a consistent way to capture the result of trying to load any
> +	 * firmware. As a potential future improvement, this might include
> +	 * persistent state that firmware is loaded (or failed to load for some
> +	 * reason). See Message-ID: <20191113205010.GY11244@42.do-not-panic.com>

Just provide a lore link with the message id if you really want this.

But really, this type of thing belongs in the changelog text, not in a
comment, right?

> +	 * for background */
> +	dev_dbg(device, "%s %s ret=%d\n", __func__, name, ret);

That does not provide any real information as to what is going on, why
doesn't ftrace suffice for this?

thanks,

greg k-h