[PATCH bpf-next] libbpf: Add libbpf_set_log_level() function to adjust logging

[PATCH bpf-next] libbpf: Add libbpf_set_log_level() function to adjust logging

[Toke Høiland-Jørgensen]

Currently, the only way to change the logging output of libbpf is to
override the print function with libbpf_set_print(). This is somewhat
cumbersome if one just wants to change the logging level (e.g., to enable
debugging), so add another function that just adjusts the default output
printing by adjusting the filtering of messages.

Signed-off-by: Toke Høiland-Jørgensen <toke@redhat.com>
---
 tools/lib/bpf/libbpf.c   | 12 +++++++++++-
 tools/lib/bpf/libbpf.h   |  2 ++
 tools/lib/bpf/libbpf.map |  1 +
 3 files changed, 14 insertions(+), 1 deletion(-)

diff --git a/tools/lib/bpf/libbpf.c b/tools/lib/bpf/libbpf.c
index d1c4440a678e..93909d9a423d 100644
--- a/tools/lib/bpf/libbpf.c
+++ b/tools/lib/bpf/libbpf.c
@@ -67,10 +67,12 @@
 
 #define __printf(a, b)	__attribute__((format(printf, a, b)))
 
+static enum libbpf_print_level __libbpf_log_level = LIBBPF_INFO;
+
 static int __base_pr(enum libbpf_print_level level, const char *format,
 		     va_list args)
 {
-	if (level == LIBBPF_DEBUG)
+	if (level > __libbpf_log_level)
 		return 0;
 
 	return vfprintf(stderr, format, args);
@@ -86,6 +88,14 @@ libbpf_print_fn_t libbpf_set_print(libbpf_print_fn_t fn)
 	return old_print_fn;
 }
 
+enum libbpf_print_level libbpf_set_log_level(enum libbpf_print_level level)
+{
+	enum libbpf_print_level old_level = __libbpf_log_level;
+
+	__libbpf_log_level = level;
+	return old_level;
+}
+
 __printf(2, 3)
 void libbpf_print(enum libbpf_print_level level, const char *format, ...)
 {
diff --git a/tools/lib/bpf/libbpf.h b/tools/lib/bpf/libbpf.h
index c63e2ff84abc..0bba6c2259f1 100644
--- a/tools/lib/bpf/libbpf.h
+++ b/tools/lib/bpf/libbpf.h
@@ -58,6 +58,8 @@ typedef int (*libbpf_print_fn_t)(enum libbpf_print_level level,
 				 const char *, va_list ap);
 
 LIBBPF_API libbpf_print_fn_t libbpf_set_print(libbpf_print_fn_t fn);
+LIBBPF_API enum libbpf_print_level
+libbpf_set_log_level(enum libbpf_print_level level);
 
 /* Hide internal to user */
 struct bpf_object;
diff --git a/tools/lib/bpf/libbpf.map b/tools/lib/bpf/libbpf.map
index d1473ea4d7a5..c3f79418c2be 100644
--- a/tools/lib/bpf/libbpf.map
+++ b/tools/lib/bpf/libbpf.map
@@ -197,4 +197,5 @@ LIBBPF_0.0.6 {
 		bpf_object__open_mem;
 		bpf_program__get_expected_attach_type;
 		bpf_program__get_type;
+		libbpf_set_log_level;
 } LIBBPF_0.0.5;
-- 
2.23.0

Re: [PATCH bpf-next] libbpf: Add libbpf_set_log_level() function to adjust logging

[Andrii Nakryiko]

On Fri, Oct 25, 2019 at 4:50 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>
> Currently, the only way to change the logging output of libbpf is to
> override the print function with libbpf_set_print(). This is somewhat
> cumbersome if one just wants to change the logging level (e.g., to enable

No, it's not. Having one way of doing things is good, proliferation of
APIs is not a good thing. Either way you require application to write
some additional code. Doing simple vprintf-based (or whatever
application is using to print logs, which libbpf shouldn't care
about!) function with single if is not hard and is not cumbersome. If
you care about helping users to be less confused on how to do that, I
think it would be a good idea to have some sort of libbpf-specific FAQ
with code samples on how to achieve typical and common stuff, like
this one. So please instead consider doing that.


> debugging), so add another function that just adjusts the default output
> printing by adjusting the filtering of messages.
>
> Signed-off-by: Toke Høiland-Jørgensen <toke@redhat.com>
> ---
>  tools/lib/bpf/libbpf.c   | 12 +++++++++++-
>  tools/lib/bpf/libbpf.h   |  2 ++
>  tools/lib/bpf/libbpf.map |  1 +
>  3 files changed, 14 insertions(+), 1 deletion(-)
>

[...]

Re: [PATCH bpf-next] libbpf: Add libbpf_set_log_level() function to adjust logging

[Toke Høiland-Jørgensen]

Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:

> On Fri, Oct 25, 2019 at 4:50 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>>
>> Currently, the only way to change the logging output of libbpf is to
>> override the print function with libbpf_set_print(). This is somewhat
>> cumbersome if one just wants to change the logging level (e.g., to enable
>
> No, it's not.

Yes, it is :)

> Having one way of doing things is good, proliferation of APIs is not a
> good thing. Either way you require application to write some
> additional code. Doing simple vprintf-based (or whatever application
> is using to print logs, which libbpf shouldn't care about!) function
> with single if is not hard and is not cumbersome.

The print function registration is fine for applications that want to
control its own logging in detail.

This patch is about lowering barriers to entry for people who are
starting out with libbpf, and just want to find out why their program
isn't doing what it's supposed to. Which is not the point to go figure
out an arcane function pointer-based debugging setup API just to get
some help. Helping users in this situation is the friendly thing to do,
and worth the (quite limited) cost of adding this mechanism.

If you're objecting to the new API function, an alternative could be to
react to an environment variable? I.e., turn on debugging of
LIBBPF_DEBUG=1 is in the environment? That way, users wouldn't even have
to add the extra function call, they could just re-run their application
with the env var set on the command line...

> If you care about helping users to be less confused on how to do that,
> I think it would be a good idea to have some sort of libbpf-specific
> FAQ with code samples on how to achieve typical and common stuff, like
> this one. So please instead consider doing that.

The fact that you're suggesting putting in a FAQ entry on *how to enable
debug logging* should be proof enough that the current API is
confusing...

-Toke

Re: [PATCH bpf-next] libbpf: Add libbpf_set_log_level() function to adjust logging

[Andrii Nakryiko]

On Sun, Oct 27, 2019 at 4:08 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>
> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>
> > On Fri, Oct 25, 2019 at 4:50 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >>
> >> Currently, the only way to change the logging output of libbpf is to
> >> override the print function with libbpf_set_print(). This is somewhat
> >> cumbersome if one just wants to change the logging level (e.g., to enable
> >
> > No, it's not.
>
> Yes, it is :)

As much fun as it is to keep exchanging subjective statements, I won't
do that. I'll just say that having written a bunch of applications
utilizing libbpf and speaking with people (not libbpf contributors)
who have write their own apps w/ libbpf, setting up custom logging
hook was never mentioned as a problem, not even a single time.

I'll go even further and will say that the fact that libbpf (a
library) can print out something to application's stderr is already
pretty bad behavior and for big production applications is a big
no-no. Library shouldn't pollute program's stdout/stderr with extra
unsolicited output. We might actually consider changing that
eventually.

>
> > Having one way of doing things is good, proliferation of APIs is not a
> > good thing. Either way you require application to write some
> > additional code. Doing simple vprintf-based (or whatever application
> > is using to print logs, which libbpf shouldn't care about!) function
> > with single if is not hard and is not cumbersome.
>
> The print function registration is fine for applications that want to
> control its own logging in detail.
>
> This patch is about lowering barriers to entry for people who are
> starting out with libbpf, and just want to find out why their program
> isn't doing what it's supposed to. Which is not the point to go figure
> out an arcane function pointer-based debugging setup API just to get

Which aspect you find arcane? that's it's a callback? that's it as
function pointer? that it's using va_list? what exactly is confusing
here?

> some help. Helping users in this situation is the friendly thing to do,
> and worth the (quite limited) cost of adding this mechanism.

It is not a small cost. It's a new mechanism and a new set of
conventions, which are not orthogonal to existing logging mechanism
and can easily break. If application sets its own debugging callback
(and your specific user might not even know about this, because he's
working on an application, which has a separate libbpf initialization
part done by someone else), this new API will do absolutely nothing,
confusing people as much or even more.

Further, this is introducing a new global state that we need to
maintain. We've been ignoring multi-threading concerns so far, but
this will have to stop and we'll need to deal with the need to
synchronize things, at least for global state. So adding more global
stuff is bad and has its costs.

>
> If you're objecting to the new API function, an alternative could be to
> react to an environment variable? I.e., turn on debugging of
> LIBBPF_DEBUG=1 is in the environment? That way, users wouldn't even have
> to add the extra function call, they could just re-run their application
> with the env var set on the command line...

Should this envvar be re-read every time libbpf might log something?
Or just once before libbpf is initialized? If the latter, when
precisely this envvar should be read? before first bpf_object is open?
or we should re-read every time new bpf_object is open? And so on...

Or, why not, say, a special agreed-upon (or maybe it should be
overridable through extra options) file somewhere, that will control
logging verbosity? Or maybe we should support a custom (and, of
course, optional) signal handler to be installed so that we can
trigger more verbose libbpf output without having to restart a
long-running application?

All this would be very helpful for some specific subset of situations,
but that doesn't mean that libbpf has to support all these custom
cases. It already provides a generic and easy to use mechanism to let
application decide for itself what it wants to do. And we should keep
it that way.

>
> > If you care about helping users to be less confused on how to do that,
> > I think it would be a good idea to have some sort of libbpf-specific
> > FAQ with code samples on how to achieve typical and common stuff, like
> > this one. So please instead consider doing that.
>
> The fact that you're suggesting putting in a FAQ entry on *how to enable
> debug logging* should be proof enough that the current API is
> confusing...

No, I'm suggesting, if you really think libbpf's logging is confusing,
to rather spend your efforts on writing a tiny piece of documentation
explaining how libbpf logging is done and, as a simple example, show
how to do verbose logging to stderr. That way you'll eliminate any
confusion explicitly, instead of adding another API call that: 1)
confused user will still have to find and 2) will now have to figure
out why the hell libbpf has two different ways to do logging, one of
them working only under a specific set of circumstances.

>
> -Toke
>

Re: [PATCH bpf-next] libbpf: Add libbpf_set_log_level() function to adjust logging

[Toke Høiland-Jørgensen]

Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:

> On Sun, Oct 27, 2019 at 4:08 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>>
>> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>>
>> > On Fri, Oct 25, 2019 at 4:50 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>> >>
>> >> Currently, the only way to change the logging output of libbpf is to
>> >> override the print function with libbpf_set_print(). This is somewhat
>> >> cumbersome if one just wants to change the logging level (e.g., to enable
>> >
>> > No, it's not.
>>
>> Yes, it is :)
>
> As much fun as it is to keep exchanging subjective statements, I won't
> do that.

Heh, yeah. Even though I think the current behaviour is incredibly
annoying, it's also somewhat of a bikeshedding issue, so let's just
agree to disagree on this, drop this patch and move on :)

-Toke