[bpf-next] libbpf: change log level of BTF loading error message

Commit Message

Ihor Solodrai Sept. 18, 2024, 7:33 p.m. UTC

Reduce log level of BTF loading error to INFO if BTF is not required.

Suggested-by: Andrii Nakryiko <[e-mail]>
Signed-off-by: Ihor Solodrai <[e-mail]>
---
 tools/lib/bpf/libbpf.c | 9 +++++----
 1 file changed, 5 insertions(+), 4 deletions(-)

Comments

Eduard Zingerman Sept. 18, 2024, 9:03 p.m. UTC | #1

On Wed, 2024-09-18 at 19:33 +0000, Ihor Solodrai wrote:
> Reduce log level of BTF loading error to INFO if BTF is not required.
> 
> Suggested-by: Andrii Nakryiko <[e-mail]>
> Signed-off-by: Ihor Solodrai <[e-mail]>
> ---

fwiw, I took verifier_bswap.bpf.o and replaced .BTF section with empty
one inside it:

    for s in .BTF .rel.BTF .BTF.ext .rel.BTF.ext; do objcopy --remove-section $s verifier_bswap.bpf.o; done
    touch empty
    objcopy --add-section .BTF=empty verifier_bswap.bpf.o

And modified veristat to show log level for libbpf messages:

--- a/tools/testing/selftests/bpf/veristat.c
+++ b/tools/testing/selftests/bpf/veristat.c
@@ -187,6 +187,7 @@ static int libbpf_print_fn(enum libbpf_print_level level, const char *format, va
                return 0;
        if (level == LIBBPF_DEBUG  && !env.debug)
                return 0;
+       fprintf(stderr, "%d: ", level);
        return vfprintf(stderr, format, args);
 }

And here is the output for veristat loading modified verifier_bswap.bpf.o:

    ./veristat -d /home/eddy/work/tmp/verifier_bswap.bpf.o  -f bswap_16
    PROCESSING /home/eddy/work/tmp/verifier_bswap.bpf.o/bswap_16, DURATION US: 26, VERDICT: success, VERIFIER LOG:
    verification time 26 usec
    stack depth 0
    processed 3 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
    2: libbpf: loading object from /home/eddy/work/tmp/verifier_bswap.bpf.o
    2: libbpf: elf: section(2) socket, size 80, link 0, flags 6, type=1
    2: libbpf: sec 'socket': found program 'bswap_16' at insn offset 0 (0 bytes), code size 3 insns (24 bytes)
    2: libbpf: sec 'socket': found program 'bswap_32' at insn offset 3 (24 bytes), code size 3 insns (24 bytes)
    2: libbpf: sec 'socket': found program 'bswap_64' at insn offset 6 (48 bytes), code size 4 insns (32 bytes)
    2: libbpf: elf: section(3) license, size 4, link 0, flags 3, type=1
    2: libbpf: license of /home/eddy/work/tmp/verifier_bswap.bpf.o is GPL
    2: libbpf: elf: section(18) .BTF, size 0, link 0, flags 0, type=1
    2: libbpf: elf: section(19) .symtab, size 336, link 20, flags 0, type=2
    2: libbpf: BTF header not found
    0: libbpf: Error loading ELF section .BTF: -22.
    ...

Note the log level is 0 which corresponds to LIBBPF_WARN.
So, if the goal is to move all optional invalid BTF messages to info
level there are probably a few more places to modify.

Ihor Solodrai Sept. 18, 2024, 9:45 p.m. UTC | #2

On Wednesday, September 18th, 2024 at 2:03 PM, Eduard Zingerman <[e-mail]> wrote:

> 
> fwiw, I took verifier_bswap.bpf.o and replaced .BTF section with empty
> one inside it:

[...]

> So, if the goal is to move all optional invalid BTF messages to info
> level there are probably a few more places to modify.

Eduard, thanks for checking. My understanding is that a user
complained about this particular message being too noisy.

I don't know how to quickly check all the places that might be
relevant to optional BTF, and going through all the warnings feels
like too much work.

  $ grep -r 'pr_warn' | wc -l
  630

Maybe Andrii or others have a comment on this.

Andrii Nakryiko Sept. 19, 2024, 4:25 a.m. UTC | #3

On Wed, Sep 18, 2024 at 11:04 PM Eduard Zingerman <[e-mail]> wrote:
>
> On Wed, 2024-09-18 at 19:33 +0000, Ihor Solodrai wrote:
> > Reduce log level of BTF loading error to INFO if BTF is not required.
> >
> > Suggested-by: Andrii Nakryiko <[e-mail]>
> > Signed-off-by: Ihor Solodrai <[e-mail]>
> > ---
>
> fwiw, I took verifier_bswap.bpf.o and replaced .BTF section with empty
> one inside it:
>
>     for s in .BTF .rel.BTF .BTF.ext .rel.BTF.ext; do objcopy --remove-section $s verifier_bswap.bpf.o; done
>     touch empty
>     objcopy --add-section .BTF=empty verifier_bswap.bpf.o
>
> And modified veristat to show log level for libbpf messages:
>
> --- a/tools/testing/selftests/bpf/veristat.c
> +++ b/tools/testing/selftests/bpf/veristat.c
> @@ -187,6 +187,7 @@ static int libbpf_print_fn(enum libbpf_print_level level, const char *format, va
>                 return 0;
>         if (level == LIBBPF_DEBUG  && !env.debug)
>                 return 0;
> +       fprintf(stderr, "%d: ", level);
>         return vfprintf(stderr, format, args);
>  }
>
> And here is the output for veristat loading modified verifier_bswap.bpf.o:
>
>     ./veristat -d /home/eddy/work/tmp/verifier_bswap.bpf.o  -f bswap_16
>     PROCESSING /home/eddy/work/tmp/verifier_bswap.bpf.o/bswap_16, DURATION US: 26, VERDICT: success, VERIFIER LOG:
>     verification time 26 usec
>     stack depth 0
>     processed 3 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
>     2: libbpf: loading object from /home/eddy/work/tmp/verifier_bswap.bpf.o
>     2: libbpf: elf: section(2) socket, size 80, link 0, flags 6, type=1
>     2: libbpf: sec 'socket': found program 'bswap_16' at insn offset 0 (0 bytes), code size 3 insns (24 bytes)
>     2: libbpf: sec 'socket': found program 'bswap_32' at insn offset 3 (24 bytes), code size 3 insns (24 bytes)
>     2: libbpf: sec 'socket': found program 'bswap_64' at insn offset 6 (48 bytes), code size 4 insns (32 bytes)
>     2: libbpf: elf: section(3) license, size 4, link 0, flags 3, type=1
>     2: libbpf: license of /home/eddy/work/tmp/verifier_bswap.bpf.o is GPL
>     2: libbpf: elf: section(18) .BTF, size 0, link 0, flags 0, type=1
>     2: libbpf: elf: section(19) .symtab, size 336, link 20, flags 0, type=2
>     2: libbpf: BTF header not found
>     0: libbpf: Error loading ELF section .BTF: -22.
>     ...
>
> Note the log level is 0 which corresponds to LIBBPF_WARN.
> So, if the goal is to move all optional invalid BTF messages to info
> level there are probably a few more places to modify.
>

Nowadays the expectation is that the BPF program will have a valid
.BTF section, so even though .BTF is "optional", I think it's fine to
emit a warning for that case (any reasonably recent Clang will produce
valid BTF).

Ihor's patch is fixing the situation with an outdated host kernel that
doesn't understand BTF. libbpf will try to "upload" the program's BTF,
but if that fails and the BPF object doesn't use any features that
require having BTF uploaded, then it's just an information message to
the user, but otherwise can be ignored.

tl;dr, I think Ihor's patch is fine and sufficient. bpf-next is
closed, will apply when it reopens.

Eduard Zingerman Sept. 19, 2024, 4:32 a.m. UTC | #4

On Thu, 2024-09-19 at 06:25 +0200, Andrii Nakryiko wrote:

[...]

> Nowadays the expectation is that the BPF program will have a valid
> .BTF section, so even though .BTF is "optional", I think it's fine to
> emit a warning for that case (any reasonably recent Clang will produce
> valid BTF).
> 
> Ihor's patch is fixing the situation with an outdated host kernel that
> doesn't understand BTF. libbpf will try to "upload" the program's BTF,
> but if that fails and the BPF object doesn't use any features that
> require having BTF uploaded, then it's just an information message to
> the user, but otherwise can be ignored.
> 
> tl;dr, I think Ihor's patch is fine and sufficient. bpf-next is
> closed, will apply when it reopens.

Understood, thank you for explaining.

[e-mail] Sept. 25, 2024, 10:20 a.m. UTC | #5

Hello:

This patch was applied to bpf/bpf-next.git (master)
by Daniel Borkmann <[e-mail]>:

On Wed, 18 Sep 2024 19:33:22 +0000 you wrote:
> Reduce log level of BTF loading error to INFO if BTF is not required.
> 
> Suggested-by: Andrii Nakryiko <[e-mail]>
> Signed-off-by: Ihor Solodrai <[e-mail]>
> ---
>  tools/lib/bpf/libbpf.c | 9 +++++----
>  1 file changed, 5 insertions(+), 4 deletions(-)

Here is the summary with links:
  - [bpf-next] libbpf: change log level of BTF loading error message
    https://git.kernel.org/bpf/bpf-next/c/cc475dea00c1

You are awesome, thank you!

Patch

diff --git a/tools/lib/bpf/libbpf.c b/tools/lib/bpf/libbpf.c
index 219facd0e66e..b8d72b5fbc79 100644
--- a/tools/lib/bpf/libbpf.c
+++ b/tools/lib/bpf/libbpf.c
@@ -3581,11 +3581,12 @@  static int bpf_object__sanitize_and_load_btf(struct bpf_object *obj)
 report:
 	if (err) {
 		btf_mandatory = kernel_needs_btf(obj);
-		pr_warn("Error loading .BTF into kernel: %d. %s\n", err,
-			btf_mandatory ? "BTF is mandatory, can't proceed."
-				      : "BTF is optional, ignoring.");
-		if (!btf_mandatory)
+		if (btf_mandatory) {
+			pr_warn("Error loading .BTF into kernel: %d. BTF is mandatory, can't proceed.\n", err);
+		} else {
+			pr_info("Error loading .BTF into kernel: %d. BTF is optional, ignoring.\n", err);
 			err = 0;
+		}
 	}
 	return err;
 }