bpf/prog_tests/log_buf.c

0001 // SPDX-License-Identifier: GPL-2.0
0002 /* Copyright (c) 2021 Facebook */
0003
0004 #include <test_progs.h>
0005 #include <bpf/btf.h>
0006
0007 #include "test_log_buf.skel.h"
0008
0009 static size_t libbpf_log_pos;
0010 static char libbpf_log_buf[1024 * 1024];
0011 static bool libbpf_log_error;
0012
0013 static int libbpf_print_cb(enum libbpf_print_level level, const char *fmt, va_list args)
0014 {
0015     int emitted_cnt;
0016     size_t left_cnt;
0017
0018     left_cnt = sizeof(libbpf_log_buf) - libbpf_log_pos;
0019     emitted_cnt = vsnprintf(libbpf_log_buf + libbpf_log_pos, left_cnt, fmt, args);
0020
0021     if (emitted_cnt < 0 || emitted_cnt + 1 > left_cnt) {
0022         libbpf_log_error = true;
0023         return 0;
0024     }
0025
0026     libbpf_log_pos += emitted_cnt;
0027     return 0;
0028 }
0029
0030 static void obj_load_log_buf(void)
0031 {
0032     libbpf_print_fn_t old_print_cb = libbpf_set_print(libbpf_print_cb);
0033     LIBBPF_OPTS(bpf_object_open_opts, opts);
0034     const size_t log_buf_sz = 1024 * 1024;
0035     struct test_log_buf* skel;
0036     char *obj_log_buf, *good_log_buf, *bad_log_buf;
0037     int err;
0038
0039     obj_log_buf = malloc(3 * log_buf_sz);
0040     if (!ASSERT_OK_PTR(obj_log_buf, "obj_log_buf"))
0041         return;
0042
0043     good_log_buf = obj_log_buf + log_buf_sz;
0044     bad_log_buf = obj_log_buf + 2 * log_buf_sz;
0045     obj_log_buf[0] = good_log_buf[0] = bad_log_buf[0] = '\0';
0046
0047     opts.kernel_log_buf = obj_log_buf;
0048     opts.kernel_log_size = log_buf_sz;
0049     opts.kernel_log_level = 4; /* for BTF this will turn into 1 */
0050
0051     /* In the first round every prog has its own log_buf, so libbpf logs
0052      * don't have program failure logs
0053      */
0054     skel = test_log_buf__open_opts(&opts);
0055     if (!ASSERT_OK_PTR(skel, "skel_open"))
0056         goto cleanup;
0057
0058     /* set very verbose level for good_prog so we always get detailed logs */
0059     bpf_program__set_log_buf(skel->progs.good_prog, good_log_buf, log_buf_sz);
0060     bpf_program__set_log_level(skel->progs.good_prog, 2);
0061
0062     bpf_program__set_log_buf(skel->progs.bad_prog, bad_log_buf, log_buf_sz);
0063     /* log_level 0 with custom log_buf means that verbose logs are not
0064      * requested if program load is successful, but libbpf should retry
0065      * with log_level 1 on error and put program's verbose load log into
0066      * custom log_buf
0067      */
0068     bpf_program__set_log_level(skel->progs.bad_prog, 0);
0069
0070     err = test_log_buf__load(skel);
0071     if (!ASSERT_ERR(err, "unexpected_load_success"))
0072         goto cleanup;
0073
0074     ASSERT_FALSE(libbpf_log_error, "libbpf_log_error");
0075
0076     /* there should be no prog loading log because we specified per-prog log buf */
0077     ASSERT_NULL(strstr(libbpf_log_buf, "-- BEGIN PROG LOAD LOG --"), "unexp_libbpf_log");
0078     ASSERT_OK_PTR(strstr(libbpf_log_buf, "prog 'bad_prog': BPF program load failed"),
0079               "libbpf_log_not_empty");
0080     ASSERT_OK_PTR(strstr(obj_log_buf, "DATASEC license"), "obj_log_not_empty");
0081     ASSERT_OK_PTR(strstr(good_log_buf, "0: R1=ctx(off=0,imm=0) R10=fp0"),
0082               "good_log_verbose");
0083     ASSERT_OK_PTR(strstr(bad_log_buf, "invalid access to map value, value_size=16 off=16000 size=4"),
0084               "bad_log_not_empty");
0085
0086     if (env.verbosity > VERBOSE_NONE) {
0087         printf("LIBBPF LOG:   \n=================\n%s=================\n", libbpf_log_buf);
0088         printf("OBJ LOG:      \n=================\n%s=================\n", obj_log_buf);
0089         printf("GOOD_PROG LOG:\n=================\n%s=================\n", good_log_buf);
0090         printf("BAD_PROG  LOG:\n=================\n%s=================\n", bad_log_buf);
0091     }
0092
0093     /* reset everything */
0094     test_log_buf__destroy(skel);
0095     obj_log_buf[0] = good_log_buf[0] = bad_log_buf[0] = '\0';
0096     libbpf_log_buf[0] = '\0';
0097     libbpf_log_pos = 0;
0098     libbpf_log_error = false;
0099
0100     /* In the second round we let bad_prog's failure be logged through print callback */
0101     opts.kernel_log_buf = NULL; /* let everything through into print callback */
0102     opts.kernel_log_size = 0;
0103     opts.kernel_log_level = 1;
0104
0105     skel = test_log_buf__open_opts(&opts);
0106     if (!ASSERT_OK_PTR(skel, "skel_open"))
0107         goto cleanup;
0108
0109     /* set normal verbose level for good_prog to check log_level is taken into account */
0110     bpf_program__set_log_buf(skel->progs.good_prog, good_log_buf, log_buf_sz);
0111     bpf_program__set_log_level(skel->progs.good_prog, 1);
0112
0113     err = test_log_buf__load(skel);
0114     if (!ASSERT_ERR(err, "unexpected_load_success"))
0115         goto cleanup;
0116
0117     ASSERT_FALSE(libbpf_log_error, "libbpf_log_error");
0118
0119     /* this time prog loading error should be logged through print callback */
0120     ASSERT_OK_PTR(strstr(libbpf_log_buf, "libbpf: prog 'bad_prog': -- BEGIN PROG LOAD LOG --"),
0121               "libbpf_log_correct");
0122     ASSERT_STREQ(obj_log_buf, "", "obj_log__empty");
0123     ASSERT_STREQ(good_log_buf, "processed 4 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0\n",
0124              "good_log_ok");
0125     ASSERT_STREQ(bad_log_buf, "", "bad_log_empty");
0126
0127     if (env.verbosity > VERBOSE_NONE) {
0128         printf("LIBBPF LOG:   \n=================\n%s=================\n", libbpf_log_buf);
0129         printf("OBJ LOG:      \n=================\n%s=================\n", obj_log_buf);
0130         printf("GOOD_PROG LOG:\n=================\n%s=================\n", good_log_buf);
0131         printf("BAD_PROG  LOG:\n=================\n%s=================\n", bad_log_buf);
0132     }
0133
0134 cleanup:
0135     free(obj_log_buf);
0136     test_log_buf__destroy(skel);
0137     libbpf_set_print(old_print_cb);
0138 }
0139
0140 static void bpf_prog_load_log_buf(void)
0141 {
0142     const struct bpf_insn good_prog_insns[] = {
0143         BPF_MOV64_IMM(BPF_REG_0, 0),
0144         BPF_EXIT_INSN(),
0145     };
0146     const size_t good_prog_insn_cnt = sizeof(good_prog_insns) / sizeof(struct bpf_insn);
0147     const struct bpf_insn bad_prog_insns[] = {
0148         BPF_EXIT_INSN(),
0149     };
0150     size_t bad_prog_insn_cnt = sizeof(bad_prog_insns) / sizeof(struct bpf_insn);
0151     LIBBPF_OPTS(bpf_prog_load_opts, opts);
0152     const size_t log_buf_sz = 1024 * 1024;
0153     char *log_buf;
0154     int fd = -1;
0155
0156     log_buf = malloc(log_buf_sz);
0157     if (!ASSERT_OK_PTR(log_buf, "log_buf_alloc"))
0158         return;
0159     opts.log_buf = log_buf;
0160     opts.log_size = log_buf_sz;
0161
0162     /* with log_level == 0 log_buf shoud stay empty for good prog */
0163     log_buf[0] = '\0';
0164     opts.log_level = 0;
0165     fd = bpf_prog_load(BPF_PROG_TYPE_SOCKET_FILTER, "good_prog", "GPL",
0166                good_prog_insns, good_prog_insn_cnt, &opts);
0167     ASSERT_STREQ(log_buf, "", "good_log_0");
0168     ASSERT_GE(fd, 0, "good_fd1");
0169     if (fd >= 0)
0170         close(fd);
0171     fd = -1;
0172
0173     /* log_level == 2 should always fill log_buf, even for good prog */
0174     log_buf[0] = '\0';
0175     opts.log_level = 2;
0176     fd = bpf_prog_load(BPF_PROG_TYPE_SOCKET_FILTER, "good_prog", "GPL",
0177                good_prog_insns, good_prog_insn_cnt, &opts);
0178     ASSERT_OK_PTR(strstr(log_buf, "0: R1=ctx(off=0,imm=0) R10=fp0"), "good_log_2");
0179     ASSERT_GE(fd, 0, "good_fd2");
0180     if (fd >= 0)
0181         close(fd);
0182     fd = -1;
0183
0184     /* log_level == 0 should fill log_buf for bad prog */
0185     log_buf[0] = '\0';
0186     opts.log_level = 0;
0187     fd = bpf_prog_load(BPF_PROG_TYPE_SOCKET_FILTER, "bad_prog", "GPL",
0188                bad_prog_insns, bad_prog_insn_cnt, &opts);
0189     ASSERT_OK_PTR(strstr(log_buf, "R0 !read_ok"), "bad_log_0");
0190     ASSERT_LT(fd, 0, "bad_fd");
0191     if (fd >= 0)
0192         close(fd);
0193     fd = -1;
0194
0195     free(log_buf);
0196 }
0197
0198 static void bpf_btf_load_log_buf(void)
0199 {
0200     LIBBPF_OPTS(bpf_btf_load_opts, opts);
0201     const size_t log_buf_sz = 1024 * 1024;
0202     const void *raw_btf_data;
0203     __u32 raw_btf_size;
0204     struct btf *btf;
0205     char *log_buf = NULL;
0206     int fd = -1;
0207
0208     btf = btf__new_empty();
0209     if (!ASSERT_OK_PTR(btf, "empty_btf"))
0210         return;
0211
0212     ASSERT_GT(btf__add_int(btf, "int", 4, 0), 0, "int_type");
0213
0214     raw_btf_data = btf__raw_data(btf, &raw_btf_size);
0215     if (!ASSERT_OK_PTR(raw_btf_data, "raw_btf_data_good"))
0216         goto cleanup;
0217
0218     log_buf = malloc(log_buf_sz);
0219     if (!ASSERT_OK_PTR(log_buf, "log_buf_alloc"))
0220         goto cleanup;
0221     opts.log_buf = log_buf;
0222     opts.log_size = log_buf_sz;
0223
0224     /* with log_level == 0 log_buf shoud stay empty for good BTF */
0225     log_buf[0] = '\0';
0226     opts.log_level = 0;
0227     fd = bpf_btf_load(raw_btf_data, raw_btf_size, &opts);
0228     ASSERT_STREQ(log_buf, "", "good_log_0");
0229     ASSERT_GE(fd, 0, "good_fd1");
0230     if (fd >= 0)
0231         close(fd);
0232     fd = -1;
0233
0234     /* log_level == 2 should always fill log_buf, even for good BTF */
0235     log_buf[0] = '\0';
0236     opts.log_level = 2;
0237     fd = bpf_btf_load(raw_btf_data, raw_btf_size, &opts);
0238     printf("LOG_BUF: %s\n", log_buf);
0239     ASSERT_OK_PTR(strstr(log_buf, "magic: 0xeb9f"), "good_log_2");
0240     ASSERT_GE(fd, 0, "good_fd2");
0241     if (fd >= 0)
0242         close(fd);
0243     fd = -1;
0244
0245     /* make BTF bad, add pointer pointing to non-existing type */
0246     ASSERT_GT(btf__add_ptr(btf, 100), 0, "bad_ptr_type");
0247
0248     raw_btf_data = btf__raw_data(btf, &raw_btf_size);
0249     if (!ASSERT_OK_PTR(raw_btf_data, "raw_btf_data_bad"))
0250         goto cleanup;
0251
0252     /* log_level == 0 should fill log_buf for bad BTF */
0253     log_buf[0] = '\0';
0254     opts.log_level = 0;
0255     fd = bpf_btf_load(raw_btf_data, raw_btf_size, &opts);
0256     printf("LOG_BUF: %s\n", log_buf);
0257     ASSERT_OK_PTR(strstr(log_buf, "[2] PTR (anon) type_id=100 Invalid type_id"), "bad_log_0");
0258     ASSERT_LT(fd, 0, "bad_fd");
0259     if (fd >= 0)
0260         close(fd);
0261     fd = -1;
0262
0263 cleanup:
0264     free(log_buf);
0265     btf__free(btf);
0266 }
0267
0268 void test_log_buf(void)
0269 {
0270     if (test__start_subtest("obj_load_log_buf"))
0271         obj_load_log_buf();
0272     if (test__start_subtest("bpf_prog_load_log_buf"))
0273         bpf_prog_load_log_buf();
0274     if (test__start_subtest("bpf_btf_load_log_buf"))
0275         bpf_btf_load_log_buf();
0276 }