Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

Andrii Nakryiko
2023-03-17T16:48:21Z

On Fri, Mar 17, 2023 at 8:05 AM Eduard Zingerman <eddyz87@gmail.com> wrote:
>
> On Thu, 2023-03-16 at 11:30 -0700, Andrii Nakryiko wrote:
> > Currently, if user-supplied log buffer to collect BPF verifier log turns
> > out to be too small to contain full log, bpf() syscall return -ENOSPC,
> > fails BPF program verification/load, but preserves first N-1 bytes of
> > verifier log (where N is the size of user-supplied buffer).
> >
> > This is problematic in a bunch of common scenarios, especially when
> > working with real-world BPF programs that tend to be pretty complex as
> > far as verification goes and require big log buffers. Typically, it's
> > when debugging tricky cases at log level 2 (verbose). Also, when BPF program
> > is successfully validated, log level 2 is the only way to actually see
> > verifier state progression and all the important details.
> >
> > Even with log level 1, it's possible to get -ENOSPC even if the final
> > verifier log fits in log buffer, if there is a code path that's deep
> > enough to fill up entire log, even if normally it would be reset later
> > on (there is a logic to chop off successfully validated portions of BPF
> > verifier log).
> >
> > In short, it's not always possible to pre-size log buffer. Also, in
> > practice, the end of the log most often is way more important than the
> > beginning.
> >
> > This patch switches BPF verifier log behavior to effectively behave as
> > rotating log. That is, if user-supplied log buffer turns out to be too
> > short, instead of failing with -ENOSPC, verifier will keep overwriting
> > previously written log, effectively treating user's log buffer as a ring
> > buffer.
> >
> > Importantly, though, to preserve good user experience and not require
> > every user-space application to adopt to this new behavior, before
> > exiting to user-space verifier will rotate log (in place) to make it
> > start at the very beginning of user buffer as a continuous
> > zero-terminated string. The contents will be a chopped off N-1 last
> > bytes of full verifier log, of course.
> >
> > Given beginning of log is sometimes important as well, we add
> > BPF_LOG_FIXED (which equals 8) flag to force old behavior, which allows
> > tools like veristat to request first part of verifier log, if necessary.
> >
> > On the implementation side, conceptually, it's all simple. We maintain
> > 64-bit logical start and end positions. If we need to truncate the log,
> > start position will be adjusted accordingly to lag end position by
> > N bytes. We then use those logical positions to calculate their matching
> > actual positions in user buffer and handle wrap around the end of the
> > buffer properly. Finally, right before returning from bpf_check(), we
> > rotate user log buffer contents in-place as necessary, to make log
> > contents contiguous. See comments in relevant functions for details.
> >
> > Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
>
> I tried bpf_verifier_vlog() and bpf_vlog_finalize() using some
> randomized testing + valgrind and everything seems to be fine.

Thanks for additional testing!

> Tbh, it seems to me that having kunit tests for things like this might
> be a good idea.

I found that this user-space driven testing using variable log_buf
size causes all the different corner cases, so felt confident enough
that match is right.

I missed the issue that Alexei caught because it never went past
user-space buffer (those 1K bytes), so it was poking zeros in
unused/unchecked portion of user-provided buffer. I'll add explicit
test that that contents is not modified (probably will fill with some
character and check that nothing changed. Hopefully that will be
enough to prevent any such issues in the future.

>
> Test script for reference:
>
> void once(char *in, size_t out_sz) {
> struct bpf_verifier_log log = {};
> char *out = calloc(out_sz, 1);
> size_t in_sz = strlen(in);
> size_t orig_out_sz = out_sz;
>
> log.ubuf = out;
> log.len_total = out_sz;
> log.level = 1 | 2 | 4;
>
> for (char *input = strtok(in, " "); input; input = strtok(NULL, " "))
> bpf_verifier_vlog(&log, input);
>
> bpf_vlog_finalize(&log);
>
> for (unsigned i = 0; i < in_sz; ++i)
> if (in[i] == 0)
> in[i] = ' ';
>
> out_sz = strlen(out);
> if (in_sz)
> --in_sz;
> if (out_sz)
> --out_sz;
> while (out_sz > 0 && in_sz > 0) {
> if (in[in_sz] == ' ') {
> --in_sz;
> continue;
> }
> if (in[in_sz] == out[out_sz]) {
> --in_sz;
> --out_sz;
> continue;
> }
> printf(" in: '%s'\n", in);
> printf(" out: '%s'\n", out);
> printf("err at: %lu\n", out_sz);
> printf("out_sz: %lu\n", orig_out_sz);
> break;
> }
>
> free(out);
> }
>
> void rnd_once() {
> char in[1024] = {};
> size_t out_sz = 1 + rand() % 100;
> size_t in_sz = rand() % (sizeof(in) - 1);
> int cnt = 0;
>
> for (unsigned i = 0; i < in_sz; ++i)
> if (rand() % 100 < 7)
> in[i] = ' ';
> else
> in[i] = 'a' + (rand() % 26);
>
> once(in, out_sz);
> }
>
> int main(int argc, char **argv) {
> if (argc == 3) {
> once(argv[2], atoi(argv[1]));
> } else {
> srand(clock());
> for (int i = 0; i < 100000; ++i)
> rnd_once();
> }
> }
>
> Tested-by: Eduard Zingerman <eddyz87@gmail.com>
>
> > ---
> > include/linux/bpf_verifier.h | 32 ++-
> > kernel/bpf/log.c | 182 +++++++++++++++++-
> > kernel/bpf/verifier.c | 17 +-
> > .../selftests/bpf/prog_tests/log_fixup.c | 1 +
> > 4 files changed, 209 insertions(+), 23 deletions(-)
> > …