Message-ID: <87r1tegusj.fsf@toke.dk>
Date:   Tue, 14 Jul 2020 14:12:12 +0200
From:   Toke Høiland-Jørgensen <toke@...hat.com>
To:     Andrii Nakryiko <andrii.nakryiko@...il.com>,
        bpf <bpf@...r.kernel.org>, Alexei Starovoitov <ast@...nel.org>,
        Daniel Borkmann <daniel@...earbox.net>
Cc:     Martin KaFai Lau <kafai@...com>, Song Liu <songliubraving@...com>,
        Yonghong Song <yhs@...com>, Andrii Nakryiko <andriin@...com>,
        John Fastabend <john.fastabend@...il.com>,
        KP Singh <kpsingh@...omium.org>,
        Networking <netdev@...r.kernel.org>,
        Kernel Team <kernel-team@...com>
Subject: Re: BPF logging infrastructure. Was: [PATCH bpf-next 4/6] tools: add new members to bpf_attr.raw_tracepoint in bpf.h

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

> On Mon, Jul 13, 2020 at 1:13 PM Toke Høiland-Jørgensen <toke@...hat.com> wrote:
>>
>> From: Toke Høiland-Jørgensen <toke@...hat.com>
>>
>> Sync addition of new members from main kernel tree.
>>
>> Signed-off-by: Toke Høiland-Jørgensen <toke@...hat.com>
>> ---
>>  tools/include/uapi/linux/bpf.h |    9 +++++++--
>>  1 file changed, 7 insertions(+), 2 deletions(-)
>>
>> diff --git a/tools/include/uapi/linux/bpf.h b/tools/include/uapi/linux/bpf.h
>> index da9bf35a26f8..662a15e4a1a1 100644
>> --- a/tools/include/uapi/linux/bpf.h
>> +++ b/tools/include/uapi/linux/bpf.h
>> @@ -573,8 +573,13 @@ union bpf_attr {
>>         } query;
>>
>>         struct { /* anonymous struct used by BPF_RAW_TRACEPOINT_OPEN command */
>> -               __u64 name;
>> -               __u32 prog_fd;
>> +               __u64           name;
>> +               __u32           prog_fd;
>> +               __u32           log_level;      /* verbosity level of log */
>> +               __u32           log_size;       /* size of user buffer */
>> +               __aligned_u64   log_buf;        /* user supplied buffer */
>> +               __u32           tgt_prog_fd;
>> +               __u32           tgt_btf_id;
>>         } raw_tracepoint;
>>
>>         struct { /* anonymous struct for BPF_BTF_LOAD */
>>
>
> I think BPF syscall would benefit from common/generalized log support
> across all commands, given how powerful/complex it already is.
> Sometimes it's literally impossible to understand why one gets -EINVAL
> without adding printk()s in the kernel.

Yes, I agree! This is horrible UI!

> But it feels wrong to add log_level/log_size/log_buf fields to every
> section of bpf_attr and require the user to specify it differently for
> each command. So before we go and start adding per-command fields,
> let's discuss how we can do this more generically. I wonder if we can
> come up with a good way to do it in one common way and then gradually
> support that way throughout all BPF commands.
>
> Unfortunately it's too late to just add a few common fields to
> bpf_attr in front of all other per-command fields, but here's two more
> ideas just to start discussion. I hope someone can come up with
> something nicer.
>
> 1. Currently bpf syscall accepts 3 input arguments (cmd, uattr, size).
> We can extend it with two more optional arguments: one for pointer to
> log-defining attr (for log_buf pointer, log_size, log_level, maybe
> something more later) and another for the size of that log attr.
> Beyond that we'd need some way to specify that the user actually meant
> to provide those 2 optional args. The most straightforward way would
> be to use the highest bit of cmd argument. So instead of calling bpf()
> with BPF_MAP_CREATE command, you'd call it with BPF_MAP_CREATE |
> BPF_LOGGED, where BPF_LOGGED = 1<<31.

Well, if only we'd had a 'flags' argument to the syscall... I don't
suppose we want a bpf2()? :)

I like your idea of just using the top bits of the 'cmd' field as flag
bits, but in that case we should just define this explicitly, say
'#define BPF_CMD_FLAGS_MASK 0xFFFF0000'?

And instead of adding new arguments, why not just change the meaning of
the 'attr' argument? Say we define:

struct bpf_extended_attr {
       __u32 log_level;
       __u32 log_size;
       __aligned_u64 log_buf;
       __u8 reserved[48];
       union bpf_attr attr;
};

And then define a new flag BPF_USES_EXTENDED_ATTR which will cause the
kernel to interpret the second argument of the syscall as a pointer to
that struct instead of to the bpf_attr union?

> 2. A more "stateful" approach, would be to have an extra BPF command
> to set log buffer (and level) per thread. And if such a log is set, it
> would be overwritten with content on each bpf() syscall invocation
> (i.e., log position would be reset to 0 on each BPF syscall).

I don't think adding something stateful is a good idea; that's bound to
lead to weird issues when someone messes up the state management in
userspace.

> Of course, the existing BPF_LOAD_PROG command would keep working with
> existing log, but could fall back to the "common one", if
> BPF_LOAD_PROG-specific one is not set.
>
> It also doesn't seem to be all that critical to signal when the log
> buffer is overflown. It's pretty easy to detect from user-space:
> - either last byte would be non-zero, if we don't care about
> guaranteeing zero-termination for truncated log;
> - of second-to-last byte would be non-zero, if BPF syscall will always
> zero-terminate the log.

I think if we're doing this we should think about making the contents of
the log machine-readable, so applications can figure out what's going on
without having to parse the text strings. The simplest would be to make
this new log buffer use TLV-style messaging, say we define the log
buffer output to be a series of messages like these:

struct bpf_log_msg {
       __u16 type;
       __u32 len;
       __u8 contents[]; /* of size 'len' */
} __attribute__((packed));

To begin with we could define two types:

struct bpf_log_msg_string {
       __u16 type; /* BPF_LOG_MSG_TYPE_STRING */
       __u32 len;
       char message[];
}  __attribute__((packed));

struct bpf_log_msg_end {
       __u16 type; /* BPF_LOG_MSG_TYPE_END */
       __u32 len;
       __u16 num_truncations;
}  __attribute__((packed));

The TYPE_STRING would just be a wrapper for the existing text-based
messages, but delimited so userspace can pick them apart. And the second
one would solve your 'has the log been truncated' issue above; the
kernel simply always reserves eight bytes at the end of the buffer and
ends with writing a TYPE_END message with the number of messages that
were dropped due to lack of space. That would make it trivial for
userspace to detect truncation.

We could then add new message types later for machine-consumption. Say,
and extended error code, or offsets into the BTF information, or
whatever we end up needing. But just wrapping the existing log messages
in TLVs like the ones above could be fairly straight-forwardly
implemented with the existing bpf_log() infrastructure in the kernel,
without having to settle on which machine-readable information is useful
ahead of time... And the TLV format makes it easy for userspace to just
skip message types it doesn't understand.

WDYT?

> Of course, if user code cares about such detection of log truncation,
> it will need to set last/second-to-last bytes to zero before each
> syscall.
>
> Both approaches have their pros/cons, we can dig into those later, but
> I'd like to start this discussion and see what other people think. I
> also wonder if there are other syscalls with similarly advanced input
> arguments (like bpf_attr) and common logging, we could learn from
> those.

The first one that comes to mind is netlink extacks. Of course it's not
quite comparable since netlink already has message-based semantics, but
it does do sorta-kinda the same thing from a user PoV. The TLV format is
obviously inspired by netlink (or, well, binary networking protocols in
general).

-Toke

Powered by blists - more mailing lists