| Message ID | 20190727190150.649137-1-andriin@fb.com |
|---|---|
| Headers | show |
| Series | Revamp test_progs as a test running framework | expand |
On Sat, Jul 27, 2019 at 12:02 PM Andrii Nakryiko <andriin@fb.com> wrote: > > This patch set makes a number of changes to test_progs selftest, which is > a collection of many other tests (and sometimes sub-tests as well), to provide > better testing experience and allow to start convering many individual test > programs under selftests/bpf into a single and convenient test runner. I really like the patches, but something isn't right: #16 raw_tp_writable_reject_nbd_invalid:OK #17 raw_tp_writable_test_run:OK #18 reference_tracking:OK [ 87.715996] test_progs[2200]: segfault at 2f ip 00007f56aeea347b sp 00007ffce9720980 error 4 in libc-2.23.so[7f56aee5b000+198000] [ 87.717316] Code: ff ff 44 89 8d 30 fb ff ff e8 01 74 fd ff 44 8b 8d 30 fb ff ff 4c 8b 85 28 fb ff ff e9 fd eb ff ff 31 c0 48 83 c9 ff 4c 89 df <f2> ae c7 85 28 fb ff ff 00 00 00 00 48 89 c8 48 f7 d0 4c 8f [ 87.719493] audit: type=1701 audit(1564276195.971:5): auid=0 uid=0 gid=0 ses=1 subj=kernel pid=2200 comm="test_progs" exe="/data/users/ast/net-next/tools/testing/selftests/bpf/test_progs" sig=11 res=1 Segmentation fault (core dumped) Under gdb fault is different: #23 stacktrace_build_id:OK Detaching after fork from child process 2276. Detaching after fork from child process 2278. [ 149.013116] perf: interrupt took too long (6799 > 6713), lowering kernel.perf_event_max_sample_rate to 29000 [ 149.014634] perf: interrupt took too long (8511 > 8498), lowering kernel.perf_event_max_sample_rate to 23000 [ 149.017038] perf: interrupt took too long (10649 > 10638), lowering kernel.perf_event_max_sample_rate to 18000 [ 149.021901] perf: interrupt took too long (13322 > 13311), lowering kernel.perf_event_max_sample_rate to 15000 [ 149.042946] perf: interrupt took too long (16660 > 16652), lowering kernel.perf_event_max_sample_rate to 12000 Detaching after fork from child process 2279. #24 stacktrace_build_id_nmi:OK #25 stacktrace_map:OK #26 stacktrace_map_raw_tp:OK Program received signal SIGSEGV, Segmentation fault. 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6 (gdb) bt #0 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6 #1 0x00007ffff72655a9 in vsnprintf () from /usr/lib/libc.so.6 #2 0x0000000000403100 in test__vprintf (fmt=0x426754 "%s:PASS:%s %d nsec\n", args=0x7fffffffe878) at test_progs.c:114 #3 0x000000000040325c in test__printf (fmt=fmt@entry=0x426754 "%s:PASS:%s %d nsec\n") at test_progs.c:147 #4 0x000000000042222d in test_task_fd_query_rawtp () at prog_tests/task_fd_query_rawtp.c:19 #5 0x0000000000402c76 in main (argc=<optimized out>, argv=<optimized out>) at test_progs.c:501 (gdb) info threads Id Target Id Frame * 1 Thread 0x7ffff7fea700 (LWP 2245) "test_progs" 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6
On Sat, Jul 27, 2019 at 6:12 PM Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote: > > On Sat, Jul 27, 2019 at 12:02 PM Andrii Nakryiko <andriin@fb.com> wrote: > > > > This patch set makes a number of changes to test_progs selftest, which is > > a collection of many other tests (and sometimes sub-tests as well), to provide > > better testing experience and allow to start convering many individual test > > programs under selftests/bpf into a single and convenient test runner. > > I really like the patches, but something isn't right: Argh... Uninitialized `int ret` in test__vprintf(). Should be initialized to zero, otherwise in some corner cases when log buffer is completely full and ret's initial value is sufficiently large negative number, it can underflow env.log_cnt, silently skipping one log output, and then crashing on next one. You've somehow encountered a fascinating series of conditions that I've never stumbled upon running my code dozens of times. Fixing, sorry about that! > #16 raw_tp_writable_reject_nbd_invalid:OK > #17 raw_tp_writable_test_run:OK > #18 reference_tracking:OK > [ 87.715996] test_progs[2200]: segfault at 2f ip 00007f56aeea347b sp > 00007ffce9720980 error 4 in libc-2.23.so[7f56aee5b000+198000] > [ 87.717316] Code: ff ff 44 89 8d 30 fb ff ff e8 01 74 fd ff 44 8b > 8d 30 fb ff ff 4c 8b 85 28 fb ff ff e9 fd eb ff ff 31 c0 48 83 c9 ff > 4c 89 df <f2> ae c7 85 28 fb ff ff 00 00 00 00 48 89 c8 48 f7 d0 4c 8f > [ 87.719493] audit: type=1701 audit(1564276195.971:5): auid=0 uid=0 > gid=0 ses=1 subj=kernel pid=2200 comm="test_progs" > exe="/data/users/ast/net-next/tools/testing/selftests/bpf/test_progs" > sig=11 res=1 > Segmentation fault (core dumped) > > Under gdb fault is different: > #23 stacktrace_build_id:OK > Detaching after fork from child process 2276. > Detaching after fork from child process 2278. > [ 149.013116] perf: interrupt took too long (6799 > 6713), lowering > kernel.perf_event_max_sample_rate to 29000 > [ 149.014634] perf: interrupt took too long (8511 > 8498), lowering > kernel.perf_event_max_sample_rate to 23000 > [ 149.017038] perf: interrupt took too long (10649 > 10638), lowering > kernel.perf_event_max_sample_rate to 18000 > [ 149.021901] perf: interrupt took too long (13322 > 13311), lowering > kernel.perf_event_max_sample_rate to 15000 > [ 149.042946] perf: interrupt took too long (16660 > 16652), lowering > kernel.perf_event_max_sample_rate to 12000 > Detaching after fork from child process 2279. > #24 stacktrace_build_id_nmi:OK > #25 stacktrace_map:OK > #26 stacktrace_map_raw_tp:OK > > Program received signal SIGSEGV, Segmentation fault. > 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6 > (gdb) bt > #0 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6 > #1 0x00007ffff72655a9 in vsnprintf () from /usr/lib/libc.so.6 > #2 0x0000000000403100 in test__vprintf (fmt=0x426754 "%s:PASS:%s %d > nsec\n", args=0x7fffffffe878) at test_progs.c:114 > #3 0x000000000040325c in test__printf (fmt=fmt@entry=0x426754 > "%s:PASS:%s %d nsec\n") at test_progs.c:147 > #4 0x000000000042222d in test_task_fd_query_rawtp () at > prog_tests/task_fd_query_rawtp.c:19 > #5 0x0000000000402c76 in main (argc=<optimized out>, argv=<optimized > out>) at test_progs.c:501 > (gdb) info threads > Id Target Id Frame > * 1 Thread 0x7ffff7fea700 (LWP 2245) "test_progs" > 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6
On Sat, Jul 27, 2019 at 7:16 PM Andrii Nakryiko <andrii.nakryiko@gmail.com> wrote: > > On Sat, Jul 27, 2019 at 6:12 PM Alexei Starovoitov > <alexei.starovoitov@gmail.com> wrote: > > > > On Sat, Jul 27, 2019 at 12:02 PM Andrii Nakryiko <andriin@fb.com> wrote: > > > > > > This patch set makes a number of changes to test_progs selftest, which is > > > a collection of many other tests (and sometimes sub-tests as well), to provide > > > better testing experience and allow to start convering many individual test > > > programs under selftests/bpf into a single and convenient test runner. > > > > I really like the patches, but something isn't right: > > Argh... Uninitialized `int ret` in test__vprintf(). Should be > initialized to zero, otherwise in some corner cases when log buffer is > completely full and ret's initial value is sufficiently large negative > number, it can underflow env.log_cnt, silently skipping one log > output, and then crashing on next one. You've somehow encountered a > fascinating series of conditions that I've never stumbled upon running > my code dozens of times. Fixing, sorry about that! Ok, I doubt it was that specific bug (even though it is a bug). Turns out that you can't call vprintf with the same va_list twice, as it consumes it, so I have to do va_copy() if I might call vprintf multiple times. So fixing that now. > > > #16 raw_tp_writable_reject_nbd_invalid:OK > > #17 raw_tp_writable_test_run:OK > > #18 reference_tracking:OK > > [ 87.715996] test_progs[2200]: segfault at 2f ip 00007f56aeea347b sp > > 00007ffce9720980 error 4 in libc-2.23.so[7f56aee5b000+198000] > > [ 87.717316] Code: ff ff 44 89 8d 30 fb ff ff e8 01 74 fd ff 44 8b > > 8d 30 fb ff ff 4c 8b 85 28 fb ff ff e9 fd eb ff ff 31 c0 48 83 c9 ff > > 4c 89 df <f2> ae c7 85 28 fb ff ff 00 00 00 00 48 89 c8 48 f7 d0 4c 8f > > [ 87.719493] audit: type=1701 audit(1564276195.971:5): auid=0 uid=0 > > gid=0 ses=1 subj=kernel pid=2200 comm="test_progs" > > exe="/data/users/ast/net-next/tools/testing/selftests/bpf/test_progs" > > sig=11 res=1 > > Segmentation fault (core dumped) > > > > Under gdb fault is different: > > #23 stacktrace_build_id:OK > > Detaching after fork from child process 2276. > > Detaching after fork from child process 2278. > > [ 149.013116] perf: interrupt took too long (6799 > 6713), lowering > > kernel.perf_event_max_sample_rate to 29000 > > [ 149.014634] perf: interrupt took too long (8511 > 8498), lowering > > kernel.perf_event_max_sample_rate to 23000 > > [ 149.017038] perf: interrupt took too long (10649 > 10638), lowering > > kernel.perf_event_max_sample_rate to 18000 > > [ 149.021901] perf: interrupt took too long (13322 > 13311), lowering > > kernel.perf_event_max_sample_rate to 15000 > > [ 149.042946] perf: interrupt took too long (16660 > 16652), lowering > > kernel.perf_event_max_sample_rate to 12000 > > Detaching after fork from child process 2279. > > #24 stacktrace_build_id_nmi:OK > > #25 stacktrace_map:OK > > #26 stacktrace_map_raw_tp:OK > > > > Program received signal SIGSEGV, Segmentation fault. > > 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6 > > (gdb) bt > > #0 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6 > > #1 0x00007ffff72655a9 in vsnprintf () from /usr/lib/libc.so.6 > > #2 0x0000000000403100 in test__vprintf (fmt=0x426754 "%s:PASS:%s %d > > nsec\n", args=0x7fffffffe878) at test_progs.c:114 > > #3 0x000000000040325c in test__printf (fmt=fmt@entry=0x426754 > > "%s:PASS:%s %d nsec\n") at test_progs.c:147 > > #4 0x000000000042222d in test_task_fd_query_rawtp () at > > prog_tests/task_fd_query_rawtp.c:19 > > #5 0x0000000000402c76 in main (argc=<optimized out>, argv=<optimized > > out>) at test_progs.c:501 > > (gdb) info threads > > Id Target Id Frame > > * 1 Thread 0x7ffff7fea700 (LWP 2245) "test_progs" > > 0x00007ffff723f47b in vfprintf () from /usr/lib/libc.so.6
This patch set makes a number of changes to test_progs selftest, which is a collection of many other tests (and sometimes sub-tests as well), to provide better testing experience and allow to start convering many individual test programs under selftests/bpf into a single and convenient test runner. Patch #1 fixes issue with Makefile, which makes prog_tests/test.h compiled as a C code. This fix allows to change how test.h is generated, providing ability to have more control on what and how tests are run. Patch #2 changes how test.h is auto-generated, which allows to have test definitions, instead of just running test functions. This gives ability to do more complicated test run policies. Patch #3 adds `-t <test-name>` and `-n <test-num>` selectors to run only subset of tests. Patch #4 changes libbpf_set_print() to return previously set print callback, allowing to temporarily replace current print callback and then set it back. This is necessary for some tests that want more control over libbpf logging. Patch #5 sets up and takes over libbpf logging from individual tests to test_prog runner, adding -vv verbosity to capture debug output from libbpf. This is useful when debugging failing tests. Patch #6 furthers test output management and buffers it by default, emitting log output only if test fails. This give succinct and clean default test output. It's possible to bypass this behavior with -v flag, which will turn off test output buffering. Patch #7 adds support for sub-tests. It also enhances -t and -n selectors to both support ability to specify sub-test selectors, as well as enhancing number selector to accept sets of test, instead of just individual test number. Patch #8 converts bpf_verif_scale.c test to use sub-test APIs. Patch #9 converts send_signal.c tests to use sub-test APIs. v1->v2: - drop libbpf_swap_print, instead return previous function from libbpf_set_print (Stanislav); Andrii Nakryiko (9): selftests/bpf: prevent headers to be compiled as C code selftests/bpf: revamp test_progs to allow more control selftests/bpf: add test selectors by number and name to test_progs libbpf: return previous print callback from libbpf_set_print selftest/bpf: centralize libbpf logging management for test_progs selftests/bpf: abstract away test log output selftests/bpf: add sub-tests support for test_progs selftests/bpf: convert bpf_verif_scale.c to sub-tests API selftests/bpf: convert send_signal.c to use subtests tools/lib/bpf/libbpf.c | 5 +- tools/lib/bpf/libbpf.h | 2 +- tools/testing/selftests/bpf/Makefile | 14 +- .../selftests/bpf/prog_tests/bpf_obj_id.c | 6 +- .../bpf/prog_tests/bpf_verif_scale.c | 90 +++-- .../bpf/prog_tests/get_stack_raw_tp.c | 4 +- .../selftests/bpf/prog_tests/l4lb_all.c | 2 +- .../selftests/bpf/prog_tests/map_lock.c | 10 +- .../bpf/prog_tests/reference_tracking.c | 15 +- .../selftests/bpf/prog_tests/send_signal.c | 17 +- .../selftests/bpf/prog_tests/spinlock.c | 2 +- .../bpf/prog_tests/stacktrace_build_id.c | 4 +- .../bpf/prog_tests/stacktrace_build_id_nmi.c | 4 +- .../selftests/bpf/prog_tests/xdp_noinline.c | 3 +- tools/testing/selftests/bpf/test_progs.c | 373 +++++++++++++++++- tools/testing/selftests/bpf/test_progs.h | 45 ++- 16 files changed, 492 insertions(+), 104 deletions(-)