[DTrace-devel] [PATCH] Introduce 'bpflog' runtime option to request BPF verifier log
Eugene Loh
eugene.loh at oracle.com
Sun Jul 25 13:15:41 PDT 2021
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).
> 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.
>
> #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!)
> + 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.
> +
> + /* 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"
2) It'd be nice to know what went wrong if something goes wrong:
- Did DTrace fail?
- What output did DTrace emit?
> 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
More information about the DTrace-devel
mailing list