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@xxxxxxxx> 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@xxxxxxxxxxxx> wrote:
>> > On Sat, Feb 27, 2016 at 3:15 PM, Luis R. Rodriguez <mcgrof@xxxxxxxxxx> 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@xxxxxxxxxx>
>> >> 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@xxxxxxxxx>
>> >> Cc: Heiner Kallweit <hkallweit1@xxxxxxxxx>
>> >> Cc: Mimi Zohar <zohar@xxxxxxxxxxxxxxxxxx>
>> >> Cc: Kees Cook <keescook@xxxxxxxxxxxx>
>> >> Signed-off-by: Luis R. Rodriguez <mcgrof@xxxxxxxxxx>
>> >> ---
>> >>  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@xxxxxxxxxx>
> 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@xxxxxxxxx>
> Cc: Neil Horman <nhorman@xxxxxxxxxxxxx>
> Cc: Heiner Kallweit <hkallweit1@xxxxxxxxx>
> Cc: Mimi Zohar <zohar@xxxxxxxxxxxxxxxxxx>
> Cc: Kees Cook <keescook@xxxxxxxxxxxx>
> Signed-off-by: Luis R. Rodriguez <mcgrof@xxxxxxxxxx>

Perfect, thanks!

Acked-by: Kees Cook <keescook@xxxxxxxxxxxx>

-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