[PATCH bpf-next] libbpf: add debug message for each created program

[PATCH bpf-next] libbpf: add debug message for each created program

[Andrii Nakryiko]

Similar message for map creation is extremely useful, so add similar for BPF
programs.

Signed-off-by: Andrii Nakryiko <andriin@fb.com>
---
 tools/lib/bpf/libbpf.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/tools/lib/bpf/libbpf.c b/tools/lib/bpf/libbpf.c
index 18461deb1b19..f24a90c86c58 100644
--- a/tools/lib/bpf/libbpf.c
+++ b/tools/lib/bpf/libbpf.c
@@ -5379,8 +5379,9 @@ load_program(struct bpf_program *prog, struct bpf_insn *insns, int insns_cnt,
 	}
 
 	ret = bpf_load_program_xattr(&load_attr, log_buf, log_buf_size);
-
 	if (ret >= 0) {
+		pr_debug("prog '%s' ('%s'): created successfully, fd=%d\n",
+			 prog->name, prog->section_name, ret);
 		if (log_buf && load_attr.log_level)
 			pr_debug("verifier log:\n%s", log_buf);
 		*pfd = ret;
-- 
2.24.1

Re: [PATCH bpf-next] libbpf: add debug message for each created program

[Alexei Starovoitov]

On Tue, Jun 23, 2020 at 5:34 PM Andrii Nakryiko <andriin@fb.com> wrote:
>
> Similar message for map creation is extremely useful, so add similar for BPF
> programs.

'extremely useful' is quite subjective.
If we land this patch then everyone will be allowed to add pr_debug()
everywhere in libbpf with the same reasoning: "it's extremely useful pr_debug".

> Signed-off-by: Andrii Nakryiko <andriin@fb.com>
> ---
>  tools/lib/bpf/libbpf.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
>
> diff --git a/tools/lib/bpf/libbpf.c b/tools/lib/bpf/libbpf.c
> index 18461deb1b19..f24a90c86c58 100644
> --- a/tools/lib/bpf/libbpf.c
> +++ b/tools/lib/bpf/libbpf.c
> @@ -5379,8 +5379,9 @@ load_program(struct bpf_program *prog, struct bpf_insn *insns, int insns_cnt,
>         }
>
>         ret = bpf_load_program_xattr(&load_attr, log_buf, log_buf_size);
> -
>         if (ret >= 0) {
> +               pr_debug("prog '%s' ('%s'): created successfully, fd=%d\n",
> +                        prog->name, prog->section_name, ret);
>                 if (log_buf && load_attr.log_level)
>                         pr_debug("verifier log:\n%s", log_buf);
>                 *pfd = ret;
> --
> 2.24.1
>

Re: [PATCH bpf-next] libbpf: add debug message for each created program

[Andrii Nakryiko]

On Tue, Jun 23, 2020 at 11:47 PM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Tue, Jun 23, 2020 at 5:34 PM Andrii Nakryiko <andriin@fb.com> wrote:
> >
> > Similar message for map creation is extremely useful, so add similar for BPF
> > programs.
>
> 'extremely useful' is quite subjective.
> If we land this patch then everyone will be allowed to add pr_debug()
> everywhere in libbpf with the same reasoning: "it's extremely useful pr_debug".

We print this for maps, making it clear which maps and with which FD
were created. Having this for programs is just as useful. It doesn't
overwhelm output (and it's debug one either way). "everyone will be
allowed to add pr_debug()" is a big stretch, you can't just sneak in
or force random pr_debug, we do review patches and if something
doesn't make sense we can and we do reject it, regardless of claimed
usefulness by the patch author.

So far, libbpf debug logs were extremely helpful (subjective, of
course, but what isn't?) to debug "remotely" various issues that BPF
users had. They don't feel overwhelmingly verbose and don't have a lot
of unnecessary info. Adding a few lines (how many BPF programs are
there per each BPF object?) for listing BPF programs is totally ok.

But I'm not going to fight it, up to you, of course.

>
> > Signed-off-by: Andrii Nakryiko <andriin@fb.com>
> > ---
> >  tools/lib/bpf/libbpf.c | 3 ++-
> >  1 file changed, 2 insertions(+), 1 deletion(-)
> >
> > diff --git a/tools/lib/bpf/libbpf.c b/tools/lib/bpf/libbpf.c
> > index 18461deb1b19..f24a90c86c58 100644
> > --- a/tools/lib/bpf/libbpf.c
> > +++ b/tools/lib/bpf/libbpf.c
> > @@ -5379,8 +5379,9 @@ load_program(struct bpf_program *prog, struct bpf_insn *insns, int insns_cnt,
> >         }
> >
> >         ret = bpf_load_program_xattr(&load_attr, log_buf, log_buf_size);
> > -
> >         if (ret >= 0) {
> > +               pr_debug("prog '%s' ('%s'): created successfully, fd=%d\n",
> > +                        prog->name, prog->section_name, ret);
> >                 if (log_buf && load_attr.log_level)
> >                         pr_debug("verifier log:\n%s", log_buf);
> >                 *pfd = ret;
> > --
> > 2.24.1
> >

Re: [PATCH bpf-next] libbpf: add debug message for each created program

[Alexei Starovoitov]

On Tue, Jun 23, 2020 at 11:59:40PM -0700, Andrii Nakryiko wrote:
> On Tue, Jun 23, 2020 at 11:47 PM Alexei Starovoitov
> <alexei.starovoitov@gmail.com> wrote:
> >
> > On Tue, Jun 23, 2020 at 5:34 PM Andrii Nakryiko <andriin@fb.com> wrote:
> > >
> > > Similar message for map creation is extremely useful, so add similar for BPF
> > > programs.
> >
> > 'extremely useful' is quite subjective.
> > If we land this patch then everyone will be allowed to add pr_debug()
> > everywhere in libbpf with the same reasoning: "it's extremely useful pr_debug".
> 
> We print this for maps, making it clear which maps and with which FD
> were created. Having this for programs is just as useful. It doesn't
> overwhelm output (and it's debug one either way). "everyone will be
> allowed to add pr_debug()" is a big stretch, you can't just sneak in
> or force random pr_debug, we do review patches and if something
> doesn't make sense we can and we do reject it, regardless of claimed
> usefulness by the patch author.
> 
> So far, libbpf debug logs were extremely helpful (subjective, of
> course, but what isn't?) to debug "remotely" various issues that BPF
> users had. They don't feel overwhelmingly verbose and don't have a lot
> of unnecessary info. Adding a few lines (how many BPF programs are
> there per each BPF object?) for listing BPF programs is totally ok.

None of the above were mentioned in the commit log.
And no examples were given where this extra line would actually help.

I think libbpf pr_debug is extremely verbose instead of extremely useful.
Just typical output:
./test_progs -vv -t lsm
libbpf: loading object 'lsm' from buffer
libbpf: section(1) .strtab, size 306, link 0, flags 0, type=3
libbpf: skip section(1) .strtab
libbpf: section(2) .text, size 0, link 0, flags 6, type=1
libbpf: skip section(2) .text
libbpf: section(3) lsm/file_mprotect, size 192, link 0, flags 6, type=1
libbpf: found program lsm/file_mprotect
libbpf: section(4) .rellsm/file_mprotect, size 32, link 25, flags 0, type=9
libbpf: section(5) lsm/bprm_committed_creds, size 104, link 0, flags 6, type=1
libbpf: found program lsm/bprm_committed_creds
libbpf: section(6) .rellsm/bprm_committed_creds, size 32, link 25, flags 0, type=9

How's above useful for anyone?
libbpf says that there are '.strtab' and '.text' sections in the elf file.
That's wet water. Any elf file has that.
Then it says it's skipping '.text' ?
That reads surprising. Why library would skip the code?
And so on and so forth.
That output is useful to only few core libbpf developers.

I don't mind more thought through debug prints, but
saying that existing pr_debugs are 'extremely useful' is a stretch.

Re: [PATCH bpf-next] libbpf: add debug message for each created program

[Toke Høiland-Jørgensen]

Alexei Starovoitov <alexei.starovoitov@gmail.com> writes:

> On Tue, Jun 23, 2020 at 11:59:40PM -0700, Andrii Nakryiko wrote:
>> On Tue, Jun 23, 2020 at 11:47 PM Alexei Starovoitov
>> <alexei.starovoitov@gmail.com> wrote:
>> >
>> > On Tue, Jun 23, 2020 at 5:34 PM Andrii Nakryiko <andriin@fb.com> wrote:
>> > >
>> > > Similar message for map creation is extremely useful, so add similar for BPF
>> > > programs.
>> >
>> > 'extremely useful' is quite subjective.
>> > If we land this patch then everyone will be allowed to add pr_debug()
>> > everywhere in libbpf with the same reasoning: "it's extremely useful pr_debug".
>> 
>> We print this for maps, making it clear which maps and with which FD
>> were created. Having this for programs is just as useful. It doesn't
>> overwhelm output (and it's debug one either way). "everyone will be
>> allowed to add pr_debug()" is a big stretch, you can't just sneak in
>> or force random pr_debug, we do review patches and if something
>> doesn't make sense we can and we do reject it, regardless of claimed
>> usefulness by the patch author.
>> 
>> So far, libbpf debug logs were extremely helpful (subjective, of
>> course, but what isn't?) to debug "remotely" various issues that BPF
>> users had. They don't feel overwhelmingly verbose and don't have a lot
>> of unnecessary info. Adding a few lines (how many BPF programs are
>> there per each BPF object?) for listing BPF programs is totally ok.
>
> None of the above were mentioned in the commit log.
> And no examples were given where this extra line would actually help.
>
> I think libbpf pr_debug is extremely verbose instead of extremely useful.
> Just typical output:
> ./test_progs -vv -t lsm
> libbpf: loading object 'lsm' from buffer
> libbpf: section(1) .strtab, size 306, link 0, flags 0, type=3
> libbpf: skip section(1) .strtab
> libbpf: section(2) .text, size 0, link 0, flags 6, type=1
> libbpf: skip section(2) .text
> libbpf: section(3) lsm/file_mprotect, size 192, link 0, flags 6, type=1
> libbpf: found program lsm/file_mprotect
> libbpf: section(4) .rellsm/file_mprotect, size 32, link 25, flags 0, type=9
> libbpf: section(5) lsm/bprm_committed_creds, size 104, link 0, flags 6, type=1
> libbpf: found program lsm/bprm_committed_creds
> libbpf: section(6) .rellsm/bprm_committed_creds, size 32, link 25, flags 0, type=9
>
> How's above useful for anyone?
> libbpf says that there are '.strtab' and '.text' sections in the elf file.
> That's wet water. Any elf file has that.
> Then it says it's skipping '.text' ?
> That reads surprising. Why library would skip the code?
> And so on and so forth.
> That output is useful to only few core libbpf developers.
>
> I don't mind more thought through debug prints, but
> saying that existing pr_debugs are 'extremely useful' is a stretch.

Agreed. I had to demote libbpf debug output to an (additional) 'verbose'
level in xdp-tools because there was just too much output.

Personally I think the additional 'program loading succeeded' message
would be useful *if* some of the more verbose stuff (like what you
posted above) was cleared out.

-Toke

Re: [PATCH bpf-next] libbpf: add debug message for each created program

[Andrii Nakryiko]

On Wed, Jun 24, 2020 at 7:52 AM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Tue, Jun 23, 2020 at 11:59:40PM -0700, Andrii Nakryiko wrote:
> > On Tue, Jun 23, 2020 at 11:47 PM Alexei Starovoitov
> > <alexei.starovoitov@gmail.com> wrote:
> > >
> > > On Tue, Jun 23, 2020 at 5:34 PM Andrii Nakryiko <andriin@fb.com> wrote:
> > > >
> > > > Similar message for map creation is extremely useful, so add similar for BPF
> > > > programs.
> > >
> > > 'extremely useful' is quite subjective.
> > > If we land this patch then everyone will be allowed to add pr_debug()
> > > everywhere in libbpf with the same reasoning: "it's extremely useful pr_debug".
> >
> > We print this for maps, making it clear which maps and with which FD
> > were created. Having this for programs is just as useful. It doesn't
> > overwhelm output (and it's debug one either way). "everyone will be
> > allowed to add pr_debug()" is a big stretch, you can't just sneak in
> > or force random pr_debug, we do review patches and if something
> > doesn't make sense we can and we do reject it, regardless of claimed
> > usefulness by the patch author.
> >
> > So far, libbpf debug logs were extremely helpful (subjective, of
> > course, but what isn't?) to debug "remotely" various issues that BPF
> > users had. They don't feel overwhelmingly verbose and don't have a lot
> > of unnecessary info. Adding a few lines (how many BPF programs are
> > there per each BPF object?) for listing BPF programs is totally ok.
>
> None of the above were mentioned in the commit log.
> And no examples were given where this extra line would actually help.

I used it just 2 days ago trying to understand why bpftool doesn't
show its own bpf_iter program, but shows maps. I discovered with
surprise that we actually don't log FDs of loaded programs.

>
> I think libbpf pr_debug is extremely verbose instead of extremely useful.
> Just typical output:
> ./test_progs -vv -t lsm
> libbpf: loading object 'lsm' from buffer
> libbpf: section(1) .strtab, size 306, link 0, flags 0, type=3
> libbpf: skip section(1) .strtab
> libbpf: section(2) .text, size 0, link 0, flags 6, type=1
> libbpf: skip section(2) .text
> libbpf: section(3) lsm/file_mprotect, size 192, link 0, flags 6, type=1
> libbpf: found program lsm/file_mprotect
> libbpf: section(4) .rellsm/file_mprotect, size 32, link 25, flags 0, type=9
> libbpf: section(5) lsm/bprm_committed_creds, size 104, link 0, flags 6, type=1
> libbpf: found program lsm/bprm_committed_creds
> libbpf: section(6) .rellsm/bprm_committed_creds, size 32, link 25, flags 0, type=9
>
> How's above useful for anyone?
> libbpf says that there are '.strtab' and '.text' sections in the elf file.
> That's wet water. Any elf file has that.
> Then it says it's skipping '.text' ?
> That reads surprising. Why library would skip the code?
> And so on and so forth.

I can pick a few more not-so-useful (usually) pr_debug-level log lines
as well, I don't think it disproves that debug logs are useful.

> That output is useful to only few core libbpf developers.

Yes, and I don't expect typical BPF developers to have them turned on
by default. They are *DEBUG*-level output, after all, users shouldn't
care about them, only INFO and WARN/ERR ones, I'd hope. But it's #1
thing that I ask users to provide when they come with any questions
about BPF or libbpf.

So yeah, as a core libbpf developer and a person helping people with
various (often non-libbpf-specific) BPF problems both online and
within my company, I stand by my claim that libbpf debug logs are
extremely useful and helped debug and understand numerous issues.

Just yesterday (or two days ago, maybe), having those CO-RE relocation
logs, which I fought to keep when I added CO-RE relocs initially,
immediately shown that a person doesn't have bpf_iter compiled in its
running kernel, despite the claims otherwise.

>
> I don't mind more thought through debug prints, but
> saying that existing pr_debugs are 'extremely useful' is a stretch.

Some lines are extremely useful, yes, some less so. But then again,
depending on the situation. Not all parts of the log are relevant 100%
of the time, but sometimes even these ELF parsing logs are important.
How many people add and debug libbpf functionality that deals with
interpreting ELF sections/relocations/etc to be able to claim about
their usefulness anyway?

Regardless, we've spent way too much time on this, I don't care about
this particular pr_debug() enough to argue further.

Re: [PATCH bpf-next] libbpf: add debug message for each created program

[Alexei Starovoitov]

On Wed, Jun 24, 2020 at 09:34:52AM -0700, Andrii Nakryiko wrote:
> 
> Just yesterday (or two days ago, maybe), having those CO-RE relocation
> logs, which I fought to keep when I added CO-RE relocs initially,
> immediately shown that a person doesn't have bpf_iter compiled in its
> running kernel, despite the claims otherwise.
...
> of the time, but sometimes even these ELF parsing logs are important.

Prints for reloc make sense to me because that's libbpf's job.
Whereas info about elf sections could have been received by asking
that remote person to do objdump or llvm-objdump on the .o
Printing elf data from libbpf is an indication that libbpf itself
is not sure whether it has bugs in elf parsing. If that's the case
still after those years in production it just sad state of libbpf.
There could be an elf parsing bug there, of course, but keeping
all of that verbosity for likely rare bug is just not right.