log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[Heiner Kallweit]

Since this commit my system log is spammed with firmware load errors. One example:

loading /lib/firmware/updates/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
loading /lib/firmware/updates/iwlwifi-3160-16.ucode failed with error -2
loading /lib/firmware/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
-> finally load attempt from /lib/firmware/iwlwifi-3160-16.ucode succeeds

Before this commit, when a load from one path in fw_path failed, silently the next path was tried.
Only if all attempts failed an error message was printed.
Now for each single failed attempt an error message is printed what doesn't make sense.

Re: log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[Luis R. Rodriguez]

On Sat, Feb 27, 2016 at 05:49:38PM +0100, Heiner Kallweit wrote:
> Since this commit my system log is spammed with firmware load errors. One example:
> 
> loading /lib/firmware/updates/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
> loading /lib/firmware/updates/iwlwifi-3160-16.ucode failed with error -2
> loading /lib/firmware/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
> -> finally load attempt from /lib/firmware/iwlwifi-3160-16.ucode succeeds
> 
> Before this commit, when a load from one path in fw_path failed, silently the next path was tried.
> Only if all attempts failed an error message was printed.
> Now for each single failed attempt an error message is printed what doesn't make sense.

To be clear, this is an issue on linux-next, due to the latest merge
of Mimi's common kernel file loader pulled recently by James.

Heiner, thanks for the report, this patch fixes that. I'll be submitting that
now.  James, should this go through your tree? Please note I've been meaning to
add myself to MAINTAINERS for FIRMWARE_CLASS as requested by Greg at kernel
summit as I've been helping with cleanup there but I hadn't done so as I had
some pending patches with a full new functionality added. With Mimi's changes
merged on linux-next though and the common kernel file loader now done I can
follow up with my series of changes after this.

  Luis

>From 92e2bd76bf1abb3ce381b8d54ba5486a295af1a9 Mon Sep 17 00:00:00 2001
From: "Luis R. Rodriguez" <mcgrof@kernel.org>
Date: Sat, 27 Feb 2016 14:58:08 -0800
Subject: [PATCH] firmware: change kernel read fail to dev_dbg()

When we now use the new kernel_read_file_from_path() we
are reporting a failure when we iterate over all the paths
possible for firmware. Before using kernel_read_file_from_path()
we only reported a failure once we confirmed a file existed
with filp_open() but failed with fw_read_file_contents().

With kernel_read_file_from_path() both are done for us and
we obviously are now reporting too much information given that
some optional paths will always fail and clutter the logs.

fw_get_filesystem_firmware() already has a check for failure
and uses an internal flag, FW_OPT_NO_WARN, to let users
warn or not warn. For instance request_firmware_direct()
does not warn as this can be used for optional firmware
as it has no usermode helper fallback. In the future we
may want to change this, given everyone is disabling the
usermode helper anyway now, but for now keep reporting
only as was designed. request_firmware_direct() will
continue to not report errors as it was designed not to.

Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
Cc: Heiner Kallweit <hkallweit1@gmail.com>
Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
Cc: Kees Cook <keescook@chromium.org>
Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>
---
 drivers/base/firmware_class.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
index 1cff832ab74e..b1cf4d61ffc9 100644
--- a/drivers/base/firmware_class.c
+++ b/drivers/base/firmware_class.c
@@ -328,7 +328,7 @@ static int fw_get_filesystem_firmware(struct device *device,
 		rc = kernel_read_file_from_path(path, &buf->data, &size,
 						INT_MAX, READING_FIRMWARE);
 		if (rc) {
-			dev_warn(device, "loading %s failed with error %d\n",
+			dev_dbg(device, "loading %s failed with error %d\n",
 				 path, rc);
 			continue;
 		}
-- 
2.7.0

Re: log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[Mimi Zohar]

On Sun, 2016-02-28 at 00:15 +0100, Luis R. Rodriguez wrote:
> On Sat, Feb 27, 2016 at 05:49:38PM +0100, Heiner Kallweit wrote:
> > Since this commit my system log is spammed with firmware load errors. One example:
> > 
> > loading /lib/firmware/updates/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
> > loading /lib/firmware/updates/iwlwifi-3160-16.ucode failed with error -2
> > loading /lib/firmware/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
> > -> finally load attempt from /lib/firmware/iwlwifi-3160-16.ucode succeeds
> > 
> > Before this commit, when a load from one path in fw_path failed, silently the next path was tried.
> > Only if all attempts failed an error message was printed.
> > Now for each single failed attempt an error message is printed what doesn't make sense.
> 
> To be clear, this is an issue on linux-next, due to the latest merge
> of Mimi's common kernel file loader pulled recently by James.

It looks like commit "3e358ac firmware: Be a bit more verbose about
direct firmware loading failure", made the change.  Then commit ed04630
"firmware: simplify dev_*() print messages for generic helper" modified
the message.

Mimi

> Heiner, thanks for the report, this patch fixes that. I'll be submitting that
> now.  James, should this go through your tree? Please note I've been meaning to
> add myself to MAINTAINERS for FIRMWARE_CLASS as requested by Greg at kernel
> summit as I've been helping with cleanup there but I hadn't done so as I had
> some pending patches with a full new functionality added. With Mimi's changes
> merged on linux-next though and the common kernel file loader now done I can
> follow up with my series of changes after this.
> 
>   Luis
> 
> From 92e2bd76bf1abb3ce381b8d54ba5486a295af1a9 Mon Sep 17 00:00:00 2001
> From: "Luis R. Rodriguez" <mcgrof@kernel.org>
> Date: Sat, 27 Feb 2016 14:58:08 -0800
> Subject: [PATCH] firmware: change kernel read fail to dev_dbg()
> 
> When we now use the new kernel_read_file_from_path() we
> are reporting a failure when we iterate over all the paths
> possible for firmware. Before using kernel_read_file_from_path()
> we only reported a failure once we confirmed a file existed
> with filp_open() but failed with fw_read_file_contents().
> 
> With kernel_read_file_from_path() both are done for us and
> we obviously are now reporting too much information given that
> some optional paths will always fail and clutter the logs.
> 
> fw_get_filesystem_firmware() already has a check for failure
> and uses an internal flag, FW_OPT_NO_WARN, to let users
> warn or not warn. For instance request_firmware_direct()
> does not warn as this can be used for optional firmware
> as it has no usermode helper fallback. In the future we
> may want to change this, given everyone is disabling the
> usermode helper anyway now, but for now keep reporting
> only as was designed. request_firmware_direct() will
> continue to not report errors as it was designed not to.
> 
> Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
> Cc: Heiner Kallweit <hkallweit1@gmail.com>
> Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
> Cc: Kees Cook <keescook@chromium.org>
> Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>
> ---
>  drivers/base/firmware_class.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
> index 1cff832ab74e..b1cf4d61ffc9 100644
> --- a/drivers/base/firmware_class.c
> +++ b/drivers/base/firmware_class.c
> @@ -328,7 +328,7 @@ static int fw_get_filesystem_firmware(struct device *device,
>  		rc = kernel_read_file_from_path(path, &buf->data, &size,
>  						INT_MAX, READING_FIRMWARE);
>  		if (rc) {
> -			dev_warn(device, "loading %s failed with error %d\n",
> +			dev_dbg(device, "loading %s failed with error %d\n",
>  				 path, rc);
>  			continue;
>  		}

Re: log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[Kees Cook]

On Sat, Feb 27, 2016 at 3:15 PM, Luis R. Rodriguez <mcgrof@kernel.org> wrote:
> On Sat, Feb 27, 2016 at 05:49:38PM +0100, Heiner Kallweit wrote:
>> Since this commit my system log is spammed with firmware load errors. One example:
>>
>> loading /lib/firmware/updates/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
>> loading /lib/firmware/updates/iwlwifi-3160-16.ucode failed with error -2
>> loading /lib/firmware/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
>> -> finally load attempt from /lib/firmware/iwlwifi-3160-16.ucode succeeds
>>
>> Before this commit, when a load from one path in fw_path failed, silently the next path was tried.
>> Only if all attempts failed an error message was printed.
>> Now for each single failed attempt an error message is printed what doesn't make sense.
>
> To be clear, this is an issue on linux-next, due to the latest merge
> of Mimi's common kernel file loader pulled recently by James.
>
> Heiner, thanks for the report, this patch fixes that. I'll be submitting that
> now.  James, should this go through your tree? Please note I've been meaning to
> add myself to MAINTAINERS for FIRMWARE_CLASS as requested by Greg at kernel
> summit as I've been helping with cleanup there but I hadn't done so as I had
> some pending patches with a full new functionality added. With Mimi's changes
> merged on linux-next though and the common kernel file loader now done I can
> follow up with my series of changes after this.
>
>   Luis
>
> From 92e2bd76bf1abb3ce381b8d54ba5486a295af1a9 Mon Sep 17 00:00:00 2001
> From: "Luis R. Rodriguez" <mcgrof@kernel.org>
> Date: Sat, 27 Feb 2016 14:58:08 -0800
> Subject: [PATCH] firmware: change kernel read fail to dev_dbg()
>
> When we now use the new kernel_read_file_from_path() we
> are reporting a failure when we iterate over all the paths
> possible for firmware. Before using kernel_read_file_from_path()
> we only reported a failure once we confirmed a file existed
> with filp_open() but failed with fw_read_file_contents().
>
> With kernel_read_file_from_path() both are done for us and
> we obviously are now reporting too much information given that
> some optional paths will always fail and clutter the logs.
>
> fw_get_filesystem_firmware() already has a check for failure
> and uses an internal flag, FW_OPT_NO_WARN, to let users
> warn or not warn. For instance request_firmware_direct()
> does not warn as this can be used for optional firmware
> as it has no usermode helper fallback. In the future we
> may want to change this, given everyone is disabling the
> usermode helper anyway now, but for now keep reporting
> only as was designed. request_firmware_direct() will
> continue to not report errors as it was designed not to.
>
> Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
> Cc: Heiner Kallweit <hkallweit1@gmail.com>
> Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
> Cc: Kees Cook <keescook@chromium.org>
> Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>
> ---
>  drivers/base/firmware_class.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
> index 1cff832ab74e..b1cf4d61ffc9 100644
> --- a/drivers/base/firmware_class.c
> +++ b/drivers/base/firmware_class.c
> @@ -328,7 +328,7 @@ static int fw_get_filesystem_firmware(struct device *device,
>                 rc = kernel_read_file_from_path(path, &buf->data, &size,
>                                                 INT_MAX, READING_FIRMWARE);
>                 if (rc) {
> -                       dev_warn(device, "loading %s failed with error %d\n",
> +                       dev_dbg(device, "loading %s failed with error %d\n",
>                                  path, rc);
>                         continue;
>                 }
> --
> 2.7.0
>

I think this should warn on non-ENOENT errors and dbg on ENOENT. What
do others think?

-Kees

-- 
Kees Cook
Chrome OS & Brillo Security

Re: log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[Ming Lei]

On Sun, Feb 28, 2016 at 10:27 AM, Kees Cook <keescook@chromium.org> wrote:
> On Sat, Feb 27, 2016 at 3:15 PM, Luis R. Rodriguez <mcgrof@kernel.org> wrote:
>> On Sat, Feb 27, 2016 at 05:49:38PM +0100, Heiner Kallweit wrote:
>>> Since this commit my system log is spammed with firmware load errors. One example:
>>>
>>> loading /lib/firmware/updates/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
>>> loading /lib/firmware/updates/iwlwifi-3160-16.ucode failed with error -2
>>> loading /lib/firmware/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
>>> -> finally load attempt from /lib/firmware/iwlwifi-3160-16.ucode succeeds
>>>
>>> Before this commit, when a load from one path in fw_path failed, silently the next path was tried.
>>> Only if all attempts failed an error message was printed.
>>> Now for each single failed attempt an error message is printed what doesn't make sense.
>>
>> To be clear, this is an issue on linux-next, due to the latest merge
>> of Mimi's common kernel file loader pulled recently by James.
>>
>> Heiner, thanks for the report, this patch fixes that. I'll be submitting that
>> now.  James, should this go through your tree? Please note I've been meaning to
>> add myself to MAINTAINERS for FIRMWARE_CLASS as requested by Greg at kernel
>> summit as I've been helping with cleanup there but I hadn't done so as I had
>> some pending patches with a full new functionality added. With Mimi's changes
>> merged on linux-next though and the common kernel file loader now done I can
>> follow up with my series of changes after this.
>>
>>   Luis
>>
>> From 92e2bd76bf1abb3ce381b8d54ba5486a295af1a9 Mon Sep 17 00:00:00 2001
>> From: "Luis R. Rodriguez" <mcgrof@kernel.org>
>> Date: Sat, 27 Feb 2016 14:58:08 -0800
>> Subject: [PATCH] firmware: change kernel read fail to dev_dbg()
>>
>> When we now use the new kernel_read_file_from_path() we
>> are reporting a failure when we iterate over all the paths
>> possible for firmware. Before using kernel_read_file_from_path()
>> we only reported a failure once we confirmed a file existed
>> with filp_open() but failed with fw_read_file_contents().
>>
>> With kernel_read_file_from_path() both are done for us and
>> we obviously are now reporting too much information given that
>> some optional paths will always fail and clutter the logs.
>>
>> fw_get_filesystem_firmware() already has a check for failure
>> and uses an internal flag, FW_OPT_NO_WARN, to let users
>> warn or not warn. For instance request_firmware_direct()
>> does not warn as this can be used for optional firmware
>> as it has no usermode helper fallback. In the future we
>> may want to change this, given everyone is disabling the
>> usermode helper anyway now, but for now keep reporting
>> only as was designed. request_firmware_direct() will
>> continue to not report errors as it was designed not to.
>>
>> Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
>> Cc: Heiner Kallweit <hkallweit1@gmail.com>
>> Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
>> Cc: Kees Cook <keescook@chromium.org>
>> Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>
>> ---
>>  drivers/base/firmware_class.c | 2 +-
>>  1 file changed, 1 insertion(+), 1 deletion(-)
>>
>> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
>> index 1cff832ab74e..b1cf4d61ffc9 100644
>> --- a/drivers/base/firmware_class.c
>> +++ b/drivers/base/firmware_class.c
>> @@ -328,7 +328,7 @@ static int fw_get_filesystem_firmware(struct device *device,
>>                 rc = kernel_read_file_from_path(path, &buf->data, &size,
>>                                                 INT_MAX, READING_FIRMWARE);
>>                 if (rc) {
>> -                       dev_warn(device, "loading %s failed with error %d\n",
>> +                       dev_dbg(device, "loading %s failed with error %d\n",
>>                                  path, rc);
>>                         continue;
>>                 }
>> --
>> 2.7.0
>>
>
> I think this should warn on non-ENOENT errors and dbg on ENOENT. What
> do others think?

Agree, that looks better.

Thanks,

Re: log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[Luis R. Rodriguez]

On Sun, Feb 28, 2016 at 10:10:57PM +0800, Ming Lei wrote:
> On Sun, Feb 28, 2016 at 10:27 AM, Kees Cook <keescook@chromium.org> wrote:
> > On Sat, Feb 27, 2016 at 3:15 PM, Luis R. Rodriguez <mcgrof@kernel.org> wrote:
> >> On Sat, Feb 27, 2016 at 05:49:38PM +0100, Heiner Kallweit wrote:
> >>> Since this commit my system log is spammed with firmware load errors. One example:
> >>>
> >>> loading /lib/firmware/updates/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
> >>> loading /lib/firmware/updates/iwlwifi-3160-16.ucode failed with error -2
> >>> loading /lib/firmware/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
> >>> -> finally load attempt from /lib/firmware/iwlwifi-3160-16.ucode succeeds
> >>>
> >>> Before this commit, when a load from one path in fw_path failed, silently the next path was tried.
> >>> Only if all attempts failed an error message was printed.
> >>> Now for each single failed attempt an error message is printed what doesn't make sense.
> >>
> >> To be clear, this is an issue on linux-next, due to the latest merge
> >> of Mimi's common kernel file loader pulled recently by James.
> >>
> >> Heiner, thanks for the report, this patch fixes that. I'll be submitting that
> >> now.  James, should this go through your tree? Please note I've been meaning to
> >> add myself to MAINTAINERS for FIRMWARE_CLASS as requested by Greg at kernel
> >> summit as I've been helping with cleanup there but I hadn't done so as I had
> >> some pending patches with a full new functionality added. With Mimi's changes
> >> merged on linux-next though and the common kernel file loader now done I can
> >> follow up with my series of changes after this.
> >>
> >>   Luis
> >>
> >> From 92e2bd76bf1abb3ce381b8d54ba5486a295af1a9 Mon Sep 17 00:00:00 2001
> >> From: "Luis R. Rodriguez" <mcgrof@kernel.org>
> >> Date: Sat, 27 Feb 2016 14:58:08 -0800
> >> Subject: [PATCH] firmware: change kernel read fail to dev_dbg()
> >>
> >> When we now use the new kernel_read_file_from_path() we
> >> are reporting a failure when we iterate over all the paths
> >> possible for firmware. Before using kernel_read_file_from_path()
> >> we only reported a failure once we confirmed a file existed
> >> with filp_open() but failed with fw_read_file_contents().
> >>
> >> With kernel_read_file_from_path() both are done for us and
> >> we obviously are now reporting too much information given that
> >> some optional paths will always fail and clutter the logs.
> >>
> >> fw_get_filesystem_firmware() already has a check for failure
> >> and uses an internal flag, FW_OPT_NO_WARN, to let users
> >> warn or not warn. For instance request_firmware_direct()
> >> does not warn as this can be used for optional firmware
> >> as it has no usermode helper fallback. In the future we
> >> may want to change this, given everyone is disabling the
> >> usermode helper anyway now, but for now keep reporting
> >> only as was designed. request_firmware_direct() will
> >> continue to not report errors as it was designed not to.
> >>
> >> Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
> >> Cc: Heiner Kallweit <hkallweit1@gmail.com>
> >> Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
> >> Cc: Kees Cook <keescook@chromium.org>
> >> Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>
> >> ---
> >>  drivers/base/firmware_class.c | 2 +-
> >>  1 file changed, 1 insertion(+), 1 deletion(-)
> >>
> >> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
> >> index 1cff832ab74e..b1cf4d61ffc9 100644
> >> --- a/drivers/base/firmware_class.c
> >> +++ b/drivers/base/firmware_class.c
> >> @@ -328,7 +328,7 @@ static int fw_get_filesystem_firmware(struct device *device,
> >>                 rc = kernel_read_file_from_path(path, &buf->data, &size,
> >>                                                 INT_MAX, READING_FIRMWARE);
> >>                 if (rc) {
> >> -                       dev_warn(device, "loading %s failed with error %d\n",
> >> +                       dev_dbg(device, "loading %s failed with error %d\n",
> >>                                  path, rc);
> >>                         continue;
> >>                 }
> >> --
> >> 2.7.0
> >>
> >
> > I think this should warn on non-ENOENT errors and dbg on ENOENT. What
> > do others think?
> 
> Agree, that looks better.

OK then this:

>From e63d19975787c0e237a47c17efd01e41b2a8e2fa Mon Sep 17 00:00:00 2001
From: "Luis R. Rodriguez" <mcgrof@kernel.org>
Date: Sat, 27 Feb 2016 14:58:08 -0800
Subject: [PATCH] firmware: change kernel read fail to dev_dbg()

When we now use the new kernel_read_file_from_path() we
are reporting a failure when we iterate over all the paths
possible for firmware. Before using kernel_read_file_from_path()
we only reported a failure once we confirmed a file existed
with filp_open() but failed with fw_read_file_contents().

With kernel_read_file_from_path() both are done for us and
we obviously are now reporting too much information given that
some optional paths will always fail and clutter the logs.

fw_get_filesystem_firmware() already has a check for failure
and uses an internal flag, FW_OPT_NO_WARN, but this does not
let us capture other unxpected errors. This enables that
as changed by Neil via commit:

"firmware: Be a bit more verbose about direct firmware loading failure"

Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
Cc: Neil Horman <nhorman@tuxdriver.com>
Cc: Heiner Kallweit <hkallweit1@gmail.com>
Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
Cc: Kees Cook <keescook@chromium.org>
Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>
---
 drivers/base/firmware_class.c | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
index 1cff832ab74e..9503a88b189b 100644
--- a/drivers/base/firmware_class.c
+++ b/drivers/base/firmware_class.c
@@ -328,8 +328,12 @@ static int fw_get_filesystem_firmware(struct device *device,
 		rc = kernel_read_file_from_path(path, &buf->data, &size,
 						INT_MAX, READING_FIRMWARE);
 		if (rc) {
-			dev_warn(device, "loading %s failed with error %d\n",
-				 path, rc);
+			if (rc == -ENOENT)
+				dev_dbg(device, "loading %s failed with error %d\n",
+					 path, rc);
+			else
+				dev_warn(device, "loading %s failed with error %d\n",
+					 path, rc);
 			continue;
 		}
 		dev_dbg(device, "direct-loading %s\n", buf->fw_id);
-- 
2.7.0

Re: log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[Kees Cook]

On Sun, Feb 28, 2016 at 12:57 PM, Luis R. Rodriguez <mcgrof@suse.com> wrote:
> On Sun, Feb 28, 2016 at 10:10:57PM +0800, Ming Lei wrote:
>> On Sun, Feb 28, 2016 at 10:27 AM, Kees Cook <keescook@chromium.org> wrote:
>> > On Sat, Feb 27, 2016 at 3:15 PM, Luis R. Rodriguez <mcgrof@kernel.org> wrote:
>> >> On Sat, Feb 27, 2016 at 05:49:38PM +0100, Heiner Kallweit wrote:
>> >>> Since this commit my system log is spammed with firmware load errors. One example:
>> >>>
>> >>> loading /lib/firmware/updates/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
>> >>> loading /lib/firmware/updates/iwlwifi-3160-16.ucode failed with error -2
>> >>> loading /lib/firmware/4.5.0-rc5-next-20160226/iwlwifi-3160-16.ucode failed with error -2
>> >>> -> finally load attempt from /lib/firmware/iwlwifi-3160-16.ucode succeeds
>> >>>
>> >>> Before this commit, when a load from one path in fw_path failed, silently the next path was tried.
>> >>> Only if all attempts failed an error message was printed.
>> >>> Now for each single failed attempt an error message is printed what doesn't make sense.
>> >>
>> >> To be clear, this is an issue on linux-next, due to the latest merge
>> >> of Mimi's common kernel file loader pulled recently by James.
>> >>
>> >> Heiner, thanks for the report, this patch fixes that. I'll be submitting that
>> >> now.  James, should this go through your tree? Please note I've been meaning to
>> >> add myself to MAINTAINERS for FIRMWARE_CLASS as requested by Greg at kernel
>> >> summit as I've been helping with cleanup there but I hadn't done so as I had
>> >> some pending patches with a full new functionality added. With Mimi's changes
>> >> merged on linux-next though and the common kernel file loader now done I can
>> >> follow up with my series of changes after this.
>> >>
>> >>   Luis
>> >>
>> >> From 92e2bd76bf1abb3ce381b8d54ba5486a295af1a9 Mon Sep 17 00:00:00 2001
>> >> From: "Luis R. Rodriguez" <mcgrof@kernel.org>
>> >> Date: Sat, 27 Feb 2016 14:58:08 -0800
>> >> Subject: [PATCH] firmware: change kernel read fail to dev_dbg()
>> >>
>> >> When we now use the new kernel_read_file_from_path() we
>> >> are reporting a failure when we iterate over all the paths
>> >> possible for firmware. Before using kernel_read_file_from_path()
>> >> we only reported a failure once we confirmed a file existed
>> >> with filp_open() but failed with fw_read_file_contents().
>> >>
>> >> With kernel_read_file_from_path() both are done for us and
>> >> we obviously are now reporting too much information given that
>> >> some optional paths will always fail and clutter the logs.
>> >>
>> >> fw_get_filesystem_firmware() already has a check for failure
>> >> and uses an internal flag, FW_OPT_NO_WARN, to let users
>> >> warn or not warn. For instance request_firmware_direct()
>> >> does not warn as this can be used for optional firmware
>> >> as it has no usermode helper fallback. In the future we
>> >> may want to change this, given everyone is disabling the
>> >> usermode helper anyway now, but for now keep reporting
>> >> only as was designed. request_firmware_direct() will
>> >> continue to not report errors as it was designed not to.
>> >>
>> >> Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
>> >> Cc: Heiner Kallweit <hkallweit1@gmail.com>
>> >> Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
>> >> Cc: Kees Cook <keescook@chromium.org>
>> >> Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>
>> >> ---
>> >>  drivers/base/firmware_class.c | 2 +-
>> >>  1 file changed, 1 insertion(+), 1 deletion(-)
>> >>
>> >> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
>> >> index 1cff832ab74e..b1cf4d61ffc9 100644
>> >> --- a/drivers/base/firmware_class.c
>> >> +++ b/drivers/base/firmware_class.c
>> >> @@ -328,7 +328,7 @@ static int fw_get_filesystem_firmware(struct device *device,
>> >>                 rc = kernel_read_file_from_path(path, &buf->data, &size,
>> >>                                                 INT_MAX, READING_FIRMWARE);
>> >>                 if (rc) {
>> >> -                       dev_warn(device, "loading %s failed with error %d\n",
>> >> +                       dev_dbg(device, "loading %s failed with error %d\n",
>> >>                                  path, rc);
>> >>                         continue;
>> >>                 }
>> >> --
>> >> 2.7.0
>> >>
>> >
>> > I think this should warn on non-ENOENT errors and dbg on ENOENT. What
>> > do others think?
>>
>> Agree, that looks better.
>
> OK then this:
>
> From e63d19975787c0e237a47c17efd01e41b2a8e2fa Mon Sep 17 00:00:00 2001
> From: "Luis R. Rodriguez" <mcgrof@kernel.org>
> Date: Sat, 27 Feb 2016 14:58:08 -0800
> Subject: [PATCH] firmware: change kernel read fail to dev_dbg()
>
> When we now use the new kernel_read_file_from_path() we
> are reporting a failure when we iterate over all the paths
> possible for firmware. Before using kernel_read_file_from_path()
> we only reported a failure once we confirmed a file existed
> with filp_open() but failed with fw_read_file_contents().
>
> With kernel_read_file_from_path() both are done for us and
> we obviously are now reporting too much information given that
> some optional paths will always fail and clutter the logs.
>
> fw_get_filesystem_firmware() already has a check for failure
> and uses an internal flag, FW_OPT_NO_WARN, but this does not
> let us capture other unxpected errors. This enables that
> as changed by Neil via commit:
>
> "firmware: Be a bit more verbose about direct firmware loading failure"
>
> Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
> Cc: Neil Horman <nhorman@tuxdriver.com>
> Cc: Heiner Kallweit <hkallweit1@gmail.com>
> Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
> Cc: Kees Cook <keescook@chromium.org>
> Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>

Perfect, thanks!

Acked-by: Kees Cook <keescook@chromium.org>

-Kees

> ---
>  drivers/base/firmware_class.c | 8 ++++++--
>  1 file changed, 6 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
> index 1cff832ab74e..9503a88b189b 100644
> --- a/drivers/base/firmware_class.c
> +++ b/drivers/base/firmware_class.c
> @@ -328,8 +328,12 @@ static int fw_get_filesystem_firmware(struct device *device,
>                 rc = kernel_read_file_from_path(path, &buf->data, &size,
>                                                 INT_MAX, READING_FIRMWARE);
>                 if (rc) {
> -                       dev_warn(device, "loading %s failed with error %d\n",
> -                                path, rc);
> +                       if (rc == -ENOENT)
> +                               dev_dbg(device, "loading %s failed with error %d\n",
> +                                        path, rc);
> +                       else
> +                               dev_warn(device, "loading %s failed with error %d\n",
> +                                        path, rc);
>                         continue;
>                 }
>                 dev_dbg(device, "direct-loading %s\n", buf->fw_id);
> --
> 2.7.0
>



-- 
Kees Cook
Chrome OS & Brillo Security

Re: log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[Ming Lei]

On Mon, Feb 29, 2016 at 4:57 AM, Luis R. Rodriguez <mcgrof@suse.com> wrote:
> On Sun, Feb 28, 2016 at 10:10:57PM +0800, Ming Lei wrote:


>
> OK then this:
>
> From e63d19975787c0e237a47c17efd01e41b2a8e2fa Mon Sep 17 00:00:00 2001
> From: "Luis R. Rodriguez" <mcgrof@kernel.org>
> Date: Sat, 27 Feb 2016 14:58:08 -0800
> Subject: [PATCH] firmware: change kernel read fail to dev_dbg()
>
> When we now use the new kernel_read_file_from_path() we
> are reporting a failure when we iterate over all the paths
> possible for firmware. Before using kernel_read_file_from_path()
> we only reported a failure once we confirmed a file existed
> with filp_open() but failed with fw_read_file_contents().
>
> With kernel_read_file_from_path() both are done for us and
> we obviously are now reporting too much information given that
> some optional paths will always fail and clutter the logs.
>
> fw_get_filesystem_firmware() already has a check for failure
> and uses an internal flag, FW_OPT_NO_WARN, but this does not
> let us capture other unxpected errors. This enables that
> as changed by Neil via commit:
>
> "firmware: Be a bit more verbose about direct firmware loading failure"
>
> Reported-by: Heiner Kallweit <hkallweit1@gmail.com>
> Cc: Neil Horman <nhorman@tuxdriver.com>
> Cc: Heiner Kallweit <hkallweit1@gmail.com>
> Cc: Mimi Zohar <zohar@linux.vnet.ibm.com>
> Cc: Kees Cook <keescook@chromium.org>
> Signed-off-by: Luis R. Rodriguez <mcgrof@kernel.org>
> ---
>  drivers/base/firmware_class.c | 8 ++++++--
>  1 file changed, 6 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
> index 1cff832ab74e..9503a88b189b 100644
> --- a/drivers/base/firmware_class.c
> +++ b/drivers/base/firmware_class.c
> @@ -328,8 +328,12 @@ static int fw_get_filesystem_firmware(struct device *device,
>                 rc = kernel_read_file_from_path(path, &buf->data, &size,
>                                                 INT_MAX, READING_FIRMWARE);
>                 if (rc) {
> -                       dev_warn(device, "loading %s failed with error %d\n",
> -                                path, rc);
> +                       if (rc == -ENOENT)
> +                               dev_dbg(device, "loading %s failed with error %d\n",
> +                                        path, rc);
> +                       else
> +                               dev_warn(device, "loading %s failed with error %d\n",
> +                                        path, rc);
>                         continue;
>                 }
>                 dev_dbg(device, "direct-loading %s\n", buf->fw_id);

Acked-by: Ming Lei <ming.lei@canonical.com>

Thanks,

Re: log spammed with "loading xx failed with error -2" since commit e40ba6d56b [replace call to fw_read_file_contents() with kernel version]

[James Morris]

On Sun, 28 Feb 2016, Luis R. Rodriguez wrote:

> >From e63d19975787c0e237a47c17efd01e41b2a8e2fa Mon Sep 17 00:00:00 2001
> From: "Luis R. Rodriguez" <mcgrof@kernel.org>
> Date: Sat, 27 Feb 2016 14:58:08 -0800
> Subject: [PATCH] firmware: change kernel read fail to dev_dbg()
> 

Applied to
git://git.kernel.org/pub/scm/linux/kernel/git/jmorris/linux-security.git next



-- 
James Morris
<jmorris@namei.org>