On Wed, Apr 5, 2023 at 10:28 AM Lorenz Bauer <lmb@xxxxxxxxxxxxx> wrote:
>
> On Tue, Apr 4, 2023 at 5:37 AM Andrii Nakryiko <andrii@xxxxxxxxxx> wrote:
> >
> > This turned into a pretty sizable patch set with lots of arithmetics, but
> > hopefully the set of features added to verifier log in this patch set are both
> > useful for BPF users and are self-contained and isolated enough to not cause
> > troubles going forward.
>
> Hi Andrii,
>
> Thanks for pushing this forward, this will make all of the log
> handling so much nicer. Sorry it took a while to review, but it's
> quite a chunky series as you point out yourself :) Maybe it makes
> sense to pull out some of the acked bits (moving code around, etc.)
> into a separate patch set?
>
> I'll send out individual reviews shortly, but wanted to put my my main
> proposal here. It's only compile tested, but it's hopefully clearer
> than my words. Note that I didn't fix up whitespace to make the diff
> smaller. It should apply on top of your branch.
>
> From 162afa86d109954a4951d052513580849bd5cc54 Mon Sep 17 00:00:00 2001
> From: Lorenz Bauer <lmb@xxxxxxxxxxxxx>
> Date: Wed, 5 Apr 2023 18:24:42 +0100
> Subject: [PATCH] bpf: simplify log nul termination and FIXED mode
>
> Signed-off-by: Lorenz Bauer <lmb@xxxxxxxxxxxxx>
> ---
> kernel/bpf/log.c | 105 ++++++++++++++++++++++-------------------------
> 1 file changed, 50 insertions(+), 55 deletions(-)
Thanks for the code, I do understand your idea much better now.
Basically, you are saying to tread FIXED as a partial case of rotating
by adjusting N to never go beyond the end of the buffer. While I do
find explicit FIXED code path in bpf_verifier_log() a bit easier to
reason about, I can see this as a conceptual simplification, yep. The
finalization/zero termination is still special-cased for fixed vs
rotating.
I still fail to see how zero termination every single time is
complicating everything, and even with your implementation we can
support this easily with no more code (just kbuf[n - 1] = 0; before we
delegate to bpf_vlog_emit()).
So all in all, looking at stats, I don't really see a big
simplification. On the other hand, I spent a considerable time
thinking, debugging, and testing my existing implementation
thoroughly. Then there is also interaction with log_buf==NULL &&
log_size==0 case, I'd need to re-analyze everything again.
How strong do you feel the need for me to redo this tricky part to
save a few lines of C code (and lose easy debuggability at least of
kbuf contents)? I'm a bit on the fence. I noted a few things I would
add (or remove) even to existing code and I'll apply that. But unless
someone comes out and says "let's do it this way", I'd rather not
waste half a day on debugging some random off-by-one error again.
>
> diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
> index ab8149448724..b6b59047a594 100644
> --- a/kernel/bpf/log.c
> +++ b/kernel/bpf/log.c
> @@ -54,45 +54,13 @@ static void bpf_vlog_update_len_max(struct
> bpf_verifier_log *log, u32 add_len)
> log->len_max = len;
> }
>
> -void bpf_verifier_vlog(struct bpf_verifier_log *log, const char *fmt,
> - va_list args)
> +static void bpf_vlog_emit(struct bpf_verifier_log *log, const char
> *kbuf, u32 n)
> {
> u64 cur_pos;
> - u32 new_n, n;
> -
> - n = vscnprintf(log->kbuf, BPF_VERIFIER_TMP_LOG_SIZE, fmt, args);
> -
> - WARN_ONCE(n >= BPF_VERIFIER_TMP_LOG_SIZE - 1,
> - "verifier log line truncated - local buffer too short\n");
> -
> - if (log->level == BPF_LOG_KERNEL) {
> - bool newline = n > 0 && log->kbuf[n - 1] == '\n';
> -
> - pr_err("BPF: %s%s", log->kbuf, newline ? "" : "\n");
> - return;
> - }
> -
> - n += 1; /* include terminating zero */
> - bpf_vlog_update_len_max(log, n);
> -
> - if (log->level & BPF_LOG_FIXED) {
> - /* check if we have at least something to put into user buf */
> - new_n = 0;
> - if (log->end_pos + 1 < log->len_total) {
> - new_n = min_t(u32, log->len_total - log->end_pos, n);
> - log->kbuf[new_n - 1] = '\0';
without this part I can't debug what kernel is actually emitting into
user-space with a simple printk()...
> - }
> - cur_pos = log->end_pos;
> - log->end_pos += n - 1; /* don't count terminating '\0' */
> -
> - if (log->ubuf && new_n &&
> - copy_to_user(log->ubuf + cur_pos, log->kbuf, new_n))
> - goto fail;
> - } else {
> u64 new_end, new_start;
> u32 buf_start, buf_end, new_n;
>
> - log->kbuf[n - 1] = '\0';
realized we don't really need this zero-termination for rotating case,
will drop it
> + bpf_vlog_update_len_max(log, n);
>
> new_end = log->end_pos + n;
> if (new_end - log->start_pos >= log->len_total)
> @@ -101,7 +69,7 @@ void bpf_verifier_vlog(struct bpf_verifier_log
> *log, const char *fmt,
> new_start = log->start_pos;
>
> log->start_pos = new_start;
> - log->end_pos = new_end - 1; /* don't count terminating '\0' */
> + log->end_pos = new_end;
>
> if (!log->ubuf)
> return;
> @@ -126,35 +94,60 @@ void bpf_verifier_vlog(struct bpf_verifier_log
> *log, const char *fmt,
> if (buf_start < buf_end) {
> /* message fits within contiguous chunk of ubuf */
> if (copy_to_user(log->ubuf + buf_start,
> - log->kbuf + n - new_n,
> + kbuf + n - new_n,
> buf_end - buf_start))
> goto fail;
> } else {
> /* message wraps around the end of ubuf, copy in two chunks */
> if (copy_to_user(log->ubuf + buf_start,
> - log->kbuf + n - new_n,
> + kbuf + n - new_n,
> log->len_total - buf_start))
> goto fail;
> if (copy_to_user(log->ubuf,
> - log->kbuf + n - buf_end,
> + kbuf + n - buf_end,
> buf_end))
> goto fail;
> }
> - }
> -
> return;
> fail:
> log->ubuf = NULL;
> }
>
> -void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos)
> +static u32 bpf_vlog_available(const struct bpf_verifier_log *log)
> {
> - char zero = 0;
> - u32 pos;
> + return log->len_total - (log->end_pos - log->start_pos);
> +}
> +
> +void bpf_verifier_vlog(struct bpf_verifier_log *log, const char *fmt,
> + va_list args)
> +{
> + /* NB: contrary to vsnprintf n can't be larger than sizeof(log->kbuf) */
it can't be even equal to sizeof(log->kbuf)
> + u32 n = vscnprintf(log->kbuf, sizeof(log->kbuf), fmt, args);
> +
> + if (log->level == BPF_LOG_KERNEL) {
> + bool newline = n > 0 && log->kbuf[n - 1] == '\n';
> +
> + pr_err("BPF: %s%s", log->kbuf, newline ? "" : "\n");
> + return;
> + }
>
> + if (log->level & BPF_LOG_FIXED) {
> + bpf_vlog_update_len_max(log, n);
this made me pause for a second to prove we are not double-accounting
something. We don't, but I find the argument of a simplification a bit
weaker due to this :)
> + /* avoid rotation by never emitting more than what's unused */
> + n = min_t(u32, n, bpf_vlog_available(log));
> + }
> +
> + bpf_vlog_emit(log, log->kbuf, n);
> +}
> +
> +void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos)
> +{
> if (!bpf_verifier_log_needed(log) || log->level == BPF_LOG_KERNEL)
> return;
>
> + if (WARN_ON_ONCE(new_pos > log->end_pos))
> + return;
will add this warn, good point
> +
> /* if position to which we reset is beyond current log window,
> * then we didn't preserve any useful content and should adjust
> * start_pos to end up with an empty log (start_pos == end_pos)
> @@ -162,17 +155,6 @@ void bpf_vlog_reset(struct bpf_verifier_log *log,
> u64 new_pos)
> log->end_pos = new_pos;
> if (log->end_pos < log->start_pos)
> log->start_pos = log->end_pos;
> -
> - if (!log->ubuf)
> - return;
> -
> - if (log->level & BPF_LOG_FIXED)
> - pos = log->end_pos + 1;
> - else
> - div_u64_rem(new_pos, log->len_total, &pos);
> -
> - if (pos < log->len_total && put_user(zero, log->ubuf + pos))
> - log->ubuf = NULL;
equivalent to what you do in vlog_finalize, right?
> }
>
> static void bpf_vlog_reverse_kbuf(char *buf, int len)
> @@ -228,6 +210,7 @@ static bool bpf_vlog_truncated(const struct
> bpf_verifier_log *log)
>
> int bpf_vlog_finalize(struct bpf_verifier_log *log, u32 *log_size_actual)
> {
> + char zero = 0;
> u32 sublen;
> int err;
>
> @@ -237,8 +220,20 @@ int bpf_vlog_finalize(struct bpf_verifier_log
> *log, u32 *log_size_actual)
>
> if (!log->ubuf)
> goto skip_log_rotate;
> +
> + if (log->level & BPF_LOG_FIXED) {
> + bpf_vlog_update_len_max(log, 1);
> +
> + /* terminate by (potentially) overwriting the last byte */
> + if (put_user(zero, log->ubuf + min_t(u32, log->end_pos,
> log->len_total-1))
> + return -EFAULT;
> + } else {
> + /* terminate by (potentially) rotating out the first byte */
> + bpf_vlog_emit(log, &zero, 1);
> + }
not a big fan of this part where we still do two separate handlings
for two modes
> +
> /* If we never truncated log, there is nothing to move around. */
> - if ((log->level & BPF_LOG_FIXED) || log->start_pos == 0)
> + if (log->start_pos == 0)
yep, BPF_LOG_FIXED implied start_pos == 0, unnecessary check
> goto skip_log_rotate;
>
> /* Otherwise we need to rotate log contents to make it start from the
> --
> 2.39.2
