Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
MIME-Version: 1.0
References: <20210414185406.917890-1-revest@chromium.org> <20210414185406.917890-2-revest@chromium.org>
 <CAEf4BzYx-M7deKD9s8qFUwRyzgD5fvonkTpHO9ceXkQxgjBHBQ@mail.gmail.com> <CABRcYmKL4QO+S-raU6B1ZxCjdm7DFj-27XgEps8sZ8mU7_Hy4g@mail.gmail.com>
In-Reply-To: <CABRcYmKL4QO+S-raU6B1ZxCjdm7DFj-27XgEps8sZ8mU7_Hy4g@mail.gmail.com>
From:   Andrii Nakryiko <andrii.nakryiko@gmail.com>
Date:   Thu, 15 Apr 2021 15:37:55 -0700
Message-ID: <CAEf4BzYX1WCvj8c--nwP5YHre+xShAL6RST8vtgXtjm4dAzGhQ@mail.gmail.com>
Subject: Re: [PATCH bpf-next v4 1/6] bpf: Factorize bpf_trace_printk and bpf_seq_printf
To:     Florent Revest <revest@chromium.org>
Cc:     bpf <bpf@vger.kernel.org>, Alexei Starovoitov <ast@kernel.org>,
        Daniel Borkmann <daniel@iogearbox.net>,
        Andrii Nakryiko <andrii@kernel.org>,
        Yonghong Song <yhs@fb.com>, KP Singh <kpsingh@kernel.org>,
        Brendan Jackman <jackmanb@chromium.org>,
        open list <linux-kernel@vger.kernel.org>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

On Thu, Apr 15, 2021 at 2:33 AM Florent Revest <revest@chromium.org> wrote:
>
> On Thu, Apr 15, 2021 at 2:38 AM Andrii Nakryiko
> <andrii.nakryiko@gmail.com> wrote:
> > On Wed, Apr 14, 2021 at 11:54 AM Florent Revest <revest@chromium.org> wrote:
> > > +static int try_get_fmt_tmp_buf(char **tmp_buf)
> > > +{
> > > +       struct bpf_printf_buf *bufs;
> > > +       int used;
> > > +
> > > +       if (*tmp_buf)
> > > +               return 0;
> > > +
> > > +       preempt_disable();
> > > +       used = this_cpu_inc_return(bpf_printf_buf_used);
> > > +       if (WARN_ON_ONCE(used > 1)) {
> > > +               this_cpu_dec(bpf_printf_buf_used);
> >
> > this makes me uncomfortable. If used > 1, you won't preempt_enable()
> > here, but you'll decrease count. Then later bpf_printf_cleanup() will
> > be called (inside bpf_printf_prepare()) and will further decrease
> > count (which it didn't increase, so it's a mess now).
>
> Awkward, yes. :( This code is untested because it only covers a niche
> preempt_rt usecase that is hard to reproduce but I should have thought
> harder about these corner cases.
>
> > > +                       i += 2;
> > > +                       if (!final_args)
> > > +                               goto fmt_next;
> > > +
> > > +                       if (try_get_fmt_tmp_buf(&tmp_buf)) {
> > > +                               err = -EBUSY;
> > > +                               goto out;
> >
> > this probably should bypass doing bpf_printf_cleanup() and
> > try_get_fmt_tmp_buf() should enable preemption internally on error.
>
> Yes. I'll fix this and spend some more brain cycles thinking about
> what I'm doing. ;)
>
> > > -static __printf(1, 0) int bpf_do_trace_printk(const char *fmt, ...)
> > > +BPF_CALL_5(bpf_trace_printk, char *, fmt, u32, fmt_size, u64, arg1,
> > > +          u64, arg2, u64, arg3)
> > >  {
> > > +       u64 args[MAX_TRACE_PRINTK_VARARGS] = { arg1, arg2, arg3 };
> > > +       enum bpf_printf_mod_type mod[MAX_TRACE_PRINTK_VARARGS];
> > >         static char buf[BPF_TRACE_PRINTK_SIZE];
> > >         unsigned long flags;
> > > -       va_list ap;
> > >         int ret;
> > >
> > > -       raw_spin_lock_irqsave(&trace_printk_lock, flags);
> > > -       va_start(ap, fmt);
> > > -       ret = vsnprintf(buf, sizeof(buf), fmt, ap);
> > > -       va_end(ap);
> > > -       /* vsnprintf() will not append null for zero-length strings */
> > > +       ret = bpf_printf_prepare(fmt, fmt_size, args, args, mod,
> > > +                                MAX_TRACE_PRINTK_VARARGS);
> > > +       if (ret < 0)
> > > +               return ret;
> > > +
> > > +       ret = snprintf(buf, sizeof(buf), fmt, BPF_CAST_FMT_ARG(0, args, mod),
> > > +               BPF_CAST_FMT_ARG(1, args, mod), BPF_CAST_FMT_ARG(2, args, mod));
> > > +       /* snprintf() will not append null for zero-length strings */
> > >         if (ret == 0)
> > >                 buf[0] = '\0';
> > > +
> > > +       raw_spin_lock_irqsave(&trace_printk_lock, flags);
> > >         trace_bpf_trace_printk(buf);
> > >         raw_spin_unlock_irqrestore(&trace_printk_lock, flags);
> > >
> > > -       return ret;
> >
> > see here, no + 1 :(
>
> I wonder if it's a bug or a feature though. The helper documentation
> says the helper returns "the number of bytes written to the buffer". I
> am not familiar with the internals of trace_printk but if the
> terminating \0 is not outputted in the trace_printk buffer, then it
> kind of makes sense.
>
> Also, if anyone uses this return value, I can imagine that the usecase
> would be if (ret == 0) assume_nothing_was_written(). And if we
> suddenly output 1 here, we might break something.
>
> Because the helper is quite old, maybe we should improve the helper
> documentation instead? Your call :)

Yeah, let's make helper's doc a bit more precise, otherwise let's not
touch it. I doubt many users ever check return result of
bpf_trace_printk() at all, tbh.