[DTrace-devel] [PATCH] Introduce 'bpflog' runtime option to request BPF verifier log
Kris Van Hees
kris.van.hees at oracle.com
Thu Jul 29 19:20:15 PDT 2021
On Sun, Jul 25, 2021 at 04:15:41PM -0400, Eugene Loh wrote:
> On 7/22/21 9:58 AM, Kris Van Hees wrote:
>
> > The default behaviour is to only print the BPF verifier log when a BPF
> > program fails to load. It is sometimes desirable to obtain the BPF
> > verifier log for successful prgoram loads to assist in debugging other
> prgoram->program
> > issues with BPF programs. Specifying -xbpflog=1 on the command line or
> Omit "=1" (as the tests do).
Thanks.
> > setting this option using a pragma will force printing of the BPF
> > verifier log for all program loads.
> >
> > Signed-off-by: Kris Van Hees<kris.van.hees at oracle.com>
> > ---
> > include/dtrace/options_defines.h | 3 +-
> > libdtrace/dt_bpf.c | 63 +++++++++++++-----------
> > libdtrace/dt_options.c | 1 +
> > test/unittest/misc/tst.bpflog-cmdline.sh | 13 +++++
> > test/unittest/misc/tst.bpflog-pragma.sh | 20 ++++++++
> > 5 files changed, 70 insertions(+), 30 deletions(-)
> > create mode 100755 test/unittest/misc/tst.bpflog-cmdline.sh
> > create mode 100755 test/unittest/misc/tst.bpflog-pragma.sh
> >
> > diff --git a/include/dtrace/options_defines.h b/include/dtrace/options_defines.h
> > index bda4f739..689607db 100644
> > --- a/include/dtrace/options_defines.h
> > +++ b/include/dtrace/options_defines.h
> > @@ -59,7 +59,8 @@
> > #define DTRACEOPT_PCAPSIZE 29 /* number of bytes to be captured */
> > #define DTRACEOPT_BPFLOGSIZE 30 /* BPF verifier log, max # bytes */
> > #define DTRACEOPT_MAXFRAMES 31 /* maximum number of stack frames */
> > -#define DTRACEOPT_MAX 32 /* number of options */
> > +#define DTRACEOPT_BPFLOG 32 /* always output BPF verifier log */
> > +#define DTRACEOPT_MAX 33 /* number of options */
> Since the MAX line is being touched anyhow, might as well replace spaces
> (before the comment) with a tab.
Done.
> >
> > #define DTRACEOPT_UNSET (dtrace_optval_t)-2 /* unset option */
> >
> > diff --git a/libdtrace/dt_bpf.c b/libdtrace/dt_bpf.c
> > index 17fc2428..a72b2efe 100644
> > --- a/libdtrace/dt_bpf.c
> > +++ b/libdtrace/dt_bpf.c
> > @@ -384,7 +384,7 @@ dt_bpf_load_prog(dtrace_hdl_t *dtp, const dt_probe_t *prp,
> > struct bpf_load_program_attr attr;
> > size_t logsz;
> > char *log;
> > - int rc;
> > + int rc, origerrno = 0;
> > const dtrace_probedesc_t *pdp = prp->desc;
> > char *p, *q;
> >
> > @@ -406,14 +406,14 @@ dt_bpf_load_prog(dtrace_hdl_t *dtp, const dt_probe_t *prp,
> > attr.insns_cnt = dp->dtdo_len;
> > attr.license = BPF_CG_LICENSE;
> >
> > - rc = bpf_load_program_xattr(&attr, NULL, 0);
> > - if (rc >= 0)
> > - return rc;
> > + if (dtp->dt_options[DTRACEOPT_BPFLOG] == DTRACEOPT_UNSET) {
> > + rc = bpf_load_program_xattr(&attr, NULL, 0);
> > + if (rc >= 0)
> > + return rc;
> > +
> > + origerrno = errno;
> > + }
> >
> > - /* if failure, note error and rerun with logging */
> > - dt_bpf_error(dtp, "BPF program load for '%s:%s:%s:%s' failed: %s\n",
> > - pdp->prv, pdp->mod, pdp->fun, pdp->prb,
> > - strerror(errno));
> > if (dtp->dt_options[DTRACEOPT_BPFLOGSIZE] != DTRACEOPT_UNSET)
> > logsz = dtp->dt_options[DTRACEOPT_BPFLOGSIZE];
> > else
> > @@ -422,34 +422,39 @@ dt_bpf_load_prog(dtrace_hdl_t *dtp, const dt_probe_t *prp,
> > log = dt_zalloc(dtp, logsz);
> > assert(log != NULL);
> > rc = bpf_load_program_xattr(&attr, log, logsz);
> > + if (rc < 0) {
> This is an interesting check. Let's say bpflog is unset. We fail to
> load the first time, but let's say, strangely, that we succeed on retry
> (with a log buffer specified). That is, the check rc<0 fails. We then
> print the log. We should not: bpflog was unset and the program was
> successfully loaded. The consequence of printing the log is that the
> user is inundated with a bunch of disconcerting output that they did not
> ask for and in all likelihood do not understand and is not meaningful.
> I do not know why the fail-then-load scenario would happen -- that is,
> why this rc<0 test should fail -- but since we test for it we might as
> well handle it meaningfully. (I do not claim that the existing
> behavior, assertion failure, is any better!)
Fixed.
>
> > + dt_bpf_error(dtp, "BPF program load for '%s:%s:%s:%s' failed: "
> > + "%s\n",
> > + pdp->prv, pdp->mod, pdp->fun, pdp->prb,
> > + strerror(origerrno ? origerrno : errno));
> Instead of splitting the line in the middle of an argument (in the
> middle of a string), split the line between function arguments.
Sure.
> > +
> > + /* check whether we have an incomplete BPF log */
> > + if (errno == ENOSPC) {
> > + fprintf(stderr,
> > + "BPF verifier log is incomplete and is not reported.\n"
> > + "Set DTrace option 'bpflogsize' to some greater size for more output.\n"
> > + "(Current size is %ld.)\n", logsz);
> > + goto out;
> > + }
> > + }
> >
> > - /* since it failed once, it should fail again */
> > - assert(rc < 0);
> > -
> > - /* check whether we have an incomplete BPF log */
> > - if (errno == ENOSPC) {
> > - fprintf(stderr,
> > - "BPF verifier log is incomplete and is not reported.\n"
> > - "Set DTrace option 'bpflogsize' to some greater size for more output.\n"
> > - "(Current size is %ld.)\n", logsz);
> > - } else {
> > - /*
> > - * If there is BPF verifier output, print it with a "BPF: "
> > - * prefix so it is easier to distinguish.
> > - */
> > - for (p = log; p && *p; p = q) {
> > - q = strchr(p, '\n');
> > + /*
> > + * If there is BPF verifier output, print it with a "BPF: "
> > + * prefix so it is easier to distinguish.
> > + */
> > + for (p = log; p && *p; p = q) {
> > + q = strchr(p, '\n');
> >
> > - if (q)
> > - *q++ = '\0';
> > + if (q)
> > + *q++ = '\0';
> >
> > - fprintf(stderr, "BPF: %s\n", p);
> > - }
> > + fprintf(stderr, "BPF: %s\n", p);
> > }
> >
> > +out:
> > dt_free(dtp, log);
> >
> > - return -1;
> > + return rc >= 0 ? rc : -1;
> > }
> >
> > /*
> > diff --git a/libdtrace/dt_options.c b/libdtrace/dt_options.c
> > index a8dd5829..62f356fa 100644
> > --- a/libdtrace/dt_options.c
> > +++ b/libdtrace/dt_options.c
> > @@ -1093,6 +1093,7 @@ static const dt_option_t _dtrace_ctoptions[] = {
> > */
> > static const dt_option_t _dtrace_rtoptions[] = {
> > { "aggsize", dt_opt_size, DTRACEOPT_AGGSIZE },
> > + { "bpflog", dt_opt_runtime, DTRACEOPT_BPFLOG},
> > { "bpflogsize", dt_opt_size, DTRACEOPT_BPFLOGSIZE },
> > { "bufsize", dt_opt_size, DTRACEOPT_BUFSIZE },
> > { "bufpolicy", dt_opt_bufpolicy, DTRACEOPT_BUFPOLICY },
> > diff --git a/test/unittest/misc/tst.bpflog-cmdline.sh b/test/unittest/misc/tst.bpflog-cmdline.sh
> These are very modest tests in two respects:
>
> 1) They only check for "^BPF: ". We might as well have stronger
> tests. We know some stuff will be in the output:
> - "BPF: func#0 @0"
> - "BPF: func#1 @"
> - "R10=fp0"
> - "(85) call bpf_map_lookup_elem"
> - "(85) call bpf_perf_event_output"
> - "R0=invP(id=0)"
> - "BPF: verification time [0-9]* usec"
> - "BPF: stack depth"
> - "BPF: processed"
Yes, because what matters is whether a log is output or not. The content of
the log is not something we validate because that is not the purpose of this
test (or patch). The subject matter is whether or not a BPF verifier log is
output when the bpflog option is specified.
> 2) It'd be nice to know what went wrong if something goes wrong:
> - Did DTrace fail?
> - What output did DTrace emit?
Sure, but that means that a ton of other tests already fail as well, so I don't
think there is a need to add more logic to these tests. The output from the
BPF verifier log is also rather extensive so I do not want to dump all that in
the runtest.log. So, I'd rather keep the tests as they are - minimal but very
much to the point.
> > new file mode 100755
> > index 00000000..6a1ee1e2
> > --- /dev/null
> > +++ b/test/unittest/misc/tst.bpflog-cmdline.sh
> > @@ -0,0 +1,13 @@
> > +#!/bin/bash
> > +#
> > +# Oracle Linux DTrace.
> > +# Copyright (c) 2021, Oracle and/or its affiliates. All rights reserved.
> > +# Licensed under the Universal Permissive License v 1.0 as shown at
> > +#http://oss.oracle.com/licenses/upl.
> > +#
> > +
> > +dtrace=$1
> > +
> > +$dtrace -xbpflog -qn 'BEGIN { exit(0); }' |& grep '^BPF: ' > /dev/null
> > +
> > +exit $?
> > diff --git a/test/unittest/misc/tst.bpflog-pragma.sh b/test/unittest/misc/tst.bpflog-pragma.sh
> > new file mode 100755
> > index 00000000..7e959184
> > --- /dev/null
> > +++ b/test/unittest/misc/tst.bpflog-pragma.sh
> > @@ -0,0 +1,20 @@
> > +#!/bin/bash
> > +#
> > +# Oracle Linux DTrace.
> > +# Copyright (c) 2021, Oracle and/or its affiliates. All rights reserved.
> > +# Licensed under the Universal Permissive License v 1.0 as shown at
> > +#http://oss.oracle.com/licenses/upl.
> > +#
> > +
> > +dtrace=$1
> > +
> > +$dtrace -qs /dev/stdin << EOT |& grep '^BPF: ' > /dev/null
> > +#pragma D option bpflog
> > +
> > +BEGIN
> > +{
> > + exit(0);
> > +}
> > +EOT
> > +
> > +exit $?
> > -- 2.32.0 _______________________________________________ DTrace-devel
> > mailing list DTrace-devel at oss.oracle.com
> > https://oss.oracle.com/mailman/listinfo/dtrace-devel
>
> _______________________________________________
> DTrace-devel mailing list
> DTrace-devel at oss.oracle.com
> https://oss.oracle.com/mailman/listinfo/dtrace-devel
More information about the DTrace-devel
mailing list