[bpf-next,v3,05/15] selftests/bpf: utility functions to capture libbpf log in test_progs

Commit Message

Eduard Zingerman March 4, 2024, 10:51 p.m. UTC

Several test_progs tests already capture libbpf log in order to check
for some expected output, e.g bpf_tcp_ca.c, kfunc_dynptr_param.c,
log_buf.c and a few others.

This commit provides a, hopefully, simple API to capture libbpf log
w/o necessity to define new print callback in each test:

    /* Creates a global memstream capturing all output passed to
     * libbpf_print_fn.
     * Returns 0 on success, negative value on failure.
     * On failure the description is printed using PRINT_FAIL and
     * current test case is marked as fail.
     */
    int start_libbpf_log_capture(void)

    /* Destroys global memstream created by start_libbpf_log_capture().
     * Returns a pointer to captured data which has to be freed.
     * Returned buffer is null terminated.
     */
    char *stop_libbpf_log_capture(void)

The intended usage is as follows:

    if (start_libbpf_log_capture())
            return;
    use_libbpf();
    char *log = stop_libbpf_log_capture();
    ASSERT_HAS_SUBSTR(log, "... expected ...", "expected some message");
    free(log);

As a safety measure, free(start_libbpf_log_capture()) is invoked in the
epilogue of the test_progs.c:run_one_test().

Signed-off-by: Eduard Zingerman <[e-mail]>
---
 tools/testing/selftests/bpf/test_progs.c | 57 ++++++++++++++++++++++++
 tools/testing/selftests/bpf/test_progs.h |  3 ++
 2 files changed, 60 insertions(+)

Comments

Andrii Nakryiko March 5, 2024, 7:24 p.m. UTC | #1

On Mon, Mar 4, 2024 at 2:52 PM Eduard Zingerman <[e-mail]> wrote:
>
> Several test_progs tests already capture libbpf log in order to check
> for some expected output, e.g bpf_tcp_ca.c, kfunc_dynptr_param.c,
> log_buf.c and a few others.
>
> This commit provides a, hopefully, simple API to capture libbpf log
> w/o necessity to define new print callback in each test:
>
>     /* Creates a global memstream capturing all output passed to
>      * libbpf_print_fn.
>      * Returns 0 on success, negative value on failure.
>      * On failure the description is printed using PRINT_FAIL and
>      * current test case is marked as fail.
>      */
>     int start_libbpf_log_capture(void)
>
>     /* Destroys global memstream created by start_libbpf_log_capture().
>      * Returns a pointer to captured data which has to be freed.
>      * Returned buffer is null terminated.
>      */
>     char *stop_libbpf_log_capture(void)
>
> The intended usage is as follows:
>
>     if (start_libbpf_log_capture())
>             return;
>     use_libbpf();
>     char *log = stop_libbpf_log_capture();
>     ASSERT_HAS_SUBSTR(log, "... expected ...", "expected some message");
>     free(log);
>
> As a safety measure, free(start_libbpf_log_capture()) is invoked in the
> epilogue of the test_progs.c:run_one_test().
>
> Signed-off-by: Eduard Zingerman <[e-mail]>
> ---
>  tools/testing/selftests/bpf/test_progs.c | 57 ++++++++++++++++++++++++
>  tools/testing/selftests/bpf/test_progs.h |  3 ++
>  2 files changed, 60 insertions(+)
>

[...]

> +/* Destroys global memstream created by start_libbpf_log_capture().
> + * Returns a pointer to captured data which has to be freed.
> + * Returned buffer is null terminated.
> + */
> +char *stop_libbpf_log_capture(void)
> +{
> +       char *buf;
> +
> +       if (!libbpf_capture_stream)
> +               return NULL;
> +
> +       fputc(0, libbpf_capture_stream);
> +       fclose(libbpf_capture_stream);
> +       libbpf_capture_stream = NULL;
> +       /* get 'buf' after fclose(), see open_memstream() documentation */
> +       buf = libbpf_output_capture.buf;
> +       bzero(&libbpf_output_capture, sizeof(libbpf_output_capture));

please use memset():

$ rg -w memset | wc -l
355
$ rg -w bzero | wc -l
12


> +       return buf;
> +}
> +
>  static int libbpf_print_fn(enum libbpf_print_level level,
>                            const char *format, va_list args)
>  {
> +       if (libbpf_capture_stream) {
> +               va_list args2;
> +
> +               va_copy(args2, args);
> +               vfprintf(libbpf_capture_stream, format, args2);
> +       }

should we take into account verbosity settings? capturing LIBBPF_DEBUG
logs probably isn't very useful (but will make debugging harder,
probably)

> +
>         if (env.verbosity < VERBOSE_VERY && level == LIBBPF_DEBUG)
>                 return 0;
>         vfprintf(stdout, format, args);
> @@ -1081,6 +1137,7 @@ static void run_one_test(int test_num)
>                 cleanup_cgroup_environment();
>
>         stdio_restore();
> +       free(stop_libbpf_log_capture());
>
>         dump_test_log(test, state, false, false, NULL);
>  }
> diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
> index 80df51244886..0ba5a20b19ba 100644
> --- a/tools/testing/selftests/bpf/test_progs.h
> +++ b/tools/testing/selftests/bpf/test_progs.h
> @@ -397,6 +397,9 @@ int test__join_cgroup(const char *path);
>                 system(cmd);                                            \
>         })
>
> +int start_libbpf_log_capture(void);
> +char *stop_libbpf_log_capture(void);
> +
>  static inline __u64 ptr_to_u64(const void *ptr)
>  {
>         return (__u64) (unsigned long) ptr;
> --
> 2.43.0
>

Eduard Zingerman March 5, 2024, 11:58 p.m. UTC | #2

On Tue, 2024-03-05 at 11:24 -0800, Andrii Nakryiko wrote:
[...]

> > +char *stop_libbpf_log_capture(void)
> > +{
> > +       char *buf;
> > +
> > +       if (!libbpf_capture_stream)
> > +               return NULL;
> > +
> > +       fputc(0, libbpf_capture_stream);
> > +       fclose(libbpf_capture_stream);
> > +       libbpf_capture_stream = NULL;
> > +       /* get 'buf' after fclose(), see open_memstream() documentation */
> > +       buf = libbpf_output_capture.buf;
> > +       bzero(&libbpf_output_capture, sizeof(libbpf_output_capture));
> 
> please use memset():
> 
> $ rg -w memset | wc -l
> 355
> $ rg -w bzero | wc -l
> 12

Ok, will do

> > +       return buf;
> > +}
> > +
> >  static int libbpf_print_fn(enum libbpf_print_level level,
> >                            const char *format, va_list args)
> >  {
> > +       if (libbpf_capture_stream) {
> > +               va_list args2;
> > +
> > +               va_copy(args2, args);
> > +               vfprintf(libbpf_capture_stream, format, args2);
> > +       }
> 
> should we take into account verbosity settings? capturing LIBBPF_DEBUG
> logs probably isn't very useful (but will make debugging harder,
> probably)

LIBBPF_DEBUG messages are not necessary for my tests,
so I'll move this down after verbosity check,
could be changed later if need be.

Patch

diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
index 808550986f30..698c7387b310 100644
--- a/tools/testing/selftests/bpf/test_progs.c
+++ b/tools/testing/selftests/bpf/test_progs.c
@@ -683,9 +683,65 @@  static const struct argp_option opts[] = {
 	{},
 };
 
+static FILE *libbpf_capture_stream;
+
+static struct {
+	char *buf;
+	size_t buf_sz;
+} libbpf_output_capture;
+
+/* Creates a global memstream capturing all output passed to libbpf_print_fn.
+ * Returns 0 on success, negative value on failure.
+ * On failure the description is printed using PRINT_FAIL and
+ * current test case is marked as fail.
+ */
+int start_libbpf_log_capture(void)
+{
+	if (libbpf_capture_stream) {
+		PRINT_FAIL("%s: libbpf_capture_stream != NULL\n", __func__);
+		return -EINVAL;
+	}
+
+	libbpf_capture_stream = open_memstream(&libbpf_output_capture.buf,
+					       &libbpf_output_capture.buf_sz);
+	if (!libbpf_capture_stream) {
+		PRINT_FAIL("%s: open_memstream failed errno=%d\n", __func__, errno);
+		return -EINVAL;
+	}
+
+	return 0;
+}
+
+/* Destroys global memstream created by start_libbpf_log_capture().
+ * Returns a pointer to captured data which has to be freed.
+ * Returned buffer is null terminated.
+ */
+char *stop_libbpf_log_capture(void)
+{
+	char *buf;
+
+	if (!libbpf_capture_stream)
+		return NULL;
+
+	fputc(0, libbpf_capture_stream);
+	fclose(libbpf_capture_stream);
+	libbpf_capture_stream = NULL;
+	/* get 'buf' after fclose(), see open_memstream() documentation */
+	buf = libbpf_output_capture.buf;
+	bzero(&libbpf_output_capture, sizeof(libbpf_output_capture));
+	return buf;
+}
+
 static int libbpf_print_fn(enum libbpf_print_level level,
 			   const char *format, va_list args)
 {
+	if (libbpf_capture_stream) {
+		va_list args2;
+
+		va_copy(args2, args);
+		vfprintf(libbpf_capture_stream, format, args2);
+	}
+
 	if (env.verbosity < VERBOSE_VERY && level == LIBBPF_DEBUG)
 		return 0;
 	vfprintf(stdout, format, args);
@@ -1081,6 +1137,7 @@  static void run_one_test(int test_num)
 		cleanup_cgroup_environment();
 
 	stdio_restore();
+	free(stop_libbpf_log_capture());
 
 	dump_test_log(test, state, false, false, NULL);
 }
diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
index 80df51244886..0ba5a20b19ba 100644
--- a/tools/testing/selftests/bpf/test_progs.h
+++ b/tools/testing/selftests/bpf/test_progs.h
@@ -397,6 +397,9 @@  int test__join_cgroup(const char *path);
 		system(cmd);						\
 	})
 
+int start_libbpf_log_capture(void);
+char *stop_libbpf_log_capture(void);
+
 static inline __u64 ptr_to_u64(const void *ptr)
 {
 	return (__u64) (unsigned long) ptr;