tools/testing/selftests/bpf/prog_tests/log_buf.c

   1 // SPDX-License-Identifier: GPL-2.0
   2 /* Copyright (c) 2021 Facebook */
   3
   4 #include <test_progs.h>
   5 #include <bpf/btf.h>
   6
   7 #include "test_log_buf.skel.h"
   8 #include "bpf_util.h"
   9
  10 static size_t libbpf_log_pos;
  11 static char libbpf_log_buf[1024 * 1024];
  12 static bool libbpf_log_error;
  13
  14 static int libbpf_print_cb(enum libbpf_print_level level, const char *fmt, va_list args)
  15 {
  16         int emitted_cnt;
  17         size_t left_cnt;
  18
  19         left_cnt = sizeof(libbpf_log_buf) - libbpf_log_pos;
  20         emitted_cnt = vsnprintf(libbpf_log_buf + libbpf_log_pos, left_cnt, fmt, args);
  21
  22         if (emitted_cnt < 0 || emitted_cnt + 1 > left_cnt) {
  23                 libbpf_log_error = true;
  24                 return 0;
  25         }
  26
  27         libbpf_log_pos += emitted_cnt;
  28         return 0;
  29 }
  30
  31 static void obj_load_log_buf(void)
  32 {
  33         libbpf_print_fn_t old_print_cb = libbpf_set_print(libbpf_print_cb);
  34         LIBBPF_OPTS(bpf_object_open_opts, opts);
  35         const size_t log_buf_sz = 1024 * 1024;
  36         struct test_log_buf* skel;
  37         char *obj_log_buf, *good_log_buf, *bad_log_buf;
  38         int err;
  39
  40         obj_log_buf = malloc(3 * log_buf_sz);
  41         if (!ASSERT_OK_PTR(obj_log_buf, "obj_log_buf"))
  42                 return;
  43
  44         good_log_buf = obj_log_buf + log_buf_sz;
  45         bad_log_buf = obj_log_buf + 2 * log_buf_sz;
  46         obj_log_buf[0] = good_log_buf[0] = bad_log_buf[0] = '\0';
  47
  48         opts.kernel_log_buf = obj_log_buf;
  49         opts.kernel_log_size = log_buf_sz;
  50         opts.kernel_log_level = 4; /* for BTF this will turn into 1 */
  51
  52         /* In the first round every prog has its own log_buf, so libbpf logs
  53          * don't have program failure logs
  54          */
  55         skel = test_log_buf__open_opts(&opts);
  56         if (!ASSERT_OK_PTR(skel, "skel_open"))
  57                 goto cleanup;
  58
  59         /* set very verbose level for good_prog so we always get detailed logs */
  60         bpf_program__set_log_buf(skel->progs.good_prog, good_log_buf, log_buf_sz);
  61         bpf_program__set_log_level(skel->progs.good_prog, 2);
  62
  63         bpf_program__set_log_buf(skel->progs.bad_prog, bad_log_buf, log_buf_sz);
  64         /* log_level 0 with custom log_buf means that verbose logs are not
  65          * requested if program load is successful, but libbpf should retry
  66          * with log_level 1 on error and put program's verbose load log into
  67          * custom log_buf
  68          */
  69         bpf_program__set_log_level(skel->progs.bad_prog, 0);
  70
  71         err = test_log_buf__load(skel);
  72         if (!ASSERT_ERR(err, "unexpected_load_success"))
  73                 goto cleanup;
  74
  75         ASSERT_FALSE(libbpf_log_error, "libbpf_log_error");
  76
  77         /* there should be no prog loading log because we specified per-prog log buf */
  78         ASSERT_NULL(strstr(libbpf_log_buf, "-- BEGIN PROG LOAD LOG --"), "unexp_libbpf_log");
  79         ASSERT_OK_PTR(strstr(libbpf_log_buf, "prog 'bad_prog': BPF program load failed"),
  80                       "libbpf_log_not_empty");
  81         ASSERT_OK_PTR(strstr(obj_log_buf, "DATASEC license"), "obj_log_not_empty");
  82         ASSERT_OK_PTR(strstr(good_log_buf, "0: R1=ctx() R10=fp0"),
  83                       "good_log_verbose");
  84         ASSERT_OK_PTR(strstr(bad_log_buf, "invalid access to map value, value_size=16 off=16000 size=4"),
  85                       "bad_log_not_empty");
  86
  87         if (env.verbosity > VERBOSE_NONE) {
  88                 printf("LIBBPF LOG:   \n=================\n%s=================\n", libbpf_log_buf);
  89                 printf("OBJ LOG:      \n=================\n%s=================\n", obj_log_buf);
  90                 printf("GOOD_PROG LOG:\n=================\n%s=================\n", good_log_buf);
  91                 printf("BAD_PROG  LOG:\n=================\n%s=================\n", bad_log_buf);
  92         }
  93
  94         /* reset everything */
  95         test_log_buf__destroy(skel);
  96         obj_log_buf[0] = good_log_buf[0] = bad_log_buf[0] = '\0';
  97         libbpf_log_buf[0] = '\0';
  98         libbpf_log_pos = 0;
  99         libbpf_log_error = false;
 100
 101         /* In the second round we let bad_prog's failure be logged through print callback */
 102         opts.kernel_log_buf = NULL; /* let everything through into print callback */
 103         opts.kernel_log_size = 0;
 104         opts.kernel_log_level = 1;
 105
 106         skel = test_log_buf__open_opts(&opts);
 107         if (!ASSERT_OK_PTR(skel, "skel_open"))
 108                 goto cleanup;
 109
 110         /* set normal verbose level for good_prog to check log_level is taken into account */
 111         bpf_program__set_log_buf(skel->progs.good_prog, good_log_buf, log_buf_sz);
 112         bpf_program__set_log_level(skel->progs.good_prog, 1);
 113
 114         err = test_log_buf__load(skel);
 115         if (!ASSERT_ERR(err, "unexpected_load_success"))
 116                 goto cleanup;
 117
 118         ASSERT_FALSE(libbpf_log_error, "libbpf_log_error");
 119
 120         /* this time prog loading error should be logged through print callback */
 121         ASSERT_OK_PTR(strstr(libbpf_log_buf, "libbpf: prog 'bad_prog': -- BEGIN PROG LOAD LOG --"),
 122                       "libbpf_log_correct");
 123         ASSERT_STREQ(obj_log_buf, "", "obj_log__empty");
 124         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",
 125                      "good_log_ok");
 126         ASSERT_STREQ(bad_log_buf, "", "bad_log_empty");
 127
 128         if (env.verbosity > VERBOSE_NONE) {
 129                 printf("LIBBPF LOG:   \n=================\n%s=================\n", libbpf_log_buf);
 130                 printf("OBJ LOG:      \n=================\n%s=================\n", obj_log_buf);
 131                 printf("GOOD_PROG LOG:\n=================\n%s=================\n", good_log_buf);
 132                 printf("BAD_PROG  LOG:\n=================\n%s=================\n", bad_log_buf);
 133         }
 134
 135 cleanup:
 136         free(obj_log_buf);
 137         test_log_buf__destroy(skel);
 138         libbpf_set_print(old_print_cb);
 139 }
 140
 141 static void bpf_prog_load_log_buf(void)
 142 {
 143         const struct bpf_insn good_prog_insns[] = {
 144                 BPF_MOV64_IMM(BPF_REG_0, 0),
 145                 BPF_EXIT_INSN(),
 146         };
 147         const size_t good_prog_insn_cnt = ARRAY_SIZE(good_prog_insns);
 148         const struct bpf_insn bad_prog_insns[] = {
 149                 BPF_EXIT_INSN(),
 150         };
 151         size_t bad_prog_insn_cnt = ARRAY_SIZE(bad_prog_insns);
 152         LIBBPF_OPTS(bpf_prog_load_opts, opts);
 153         const size_t log_buf_sz = 1024 * 1024;
 154         char *log_buf;
 155         int fd = -1;
 156
 157         log_buf = malloc(log_buf_sz);
 158         if (!ASSERT_OK_PTR(log_buf, "log_buf_alloc"))
 159                 return;
 160         opts.log_buf = log_buf;
 161         opts.log_size = log_buf_sz;
 162
 163         /* with log_level == 0 log_buf should stay empty for good prog */
 164         log_buf[0] = '\0';
 165         opts.log_level = 0;
 166         fd = bpf_prog_load(BPF_PROG_TYPE_SOCKET_FILTER, "good_prog", "GPL",
 167                            good_prog_insns, good_prog_insn_cnt, &opts);
 168         ASSERT_STREQ(log_buf, "", "good_log_0");
 169         ASSERT_GE(fd, 0, "good_fd1");
 170         if (fd >= 0)
 171                 close(fd);
 172
 173         /* log_level == 2 should always fill log_buf, even for good prog */
 174         log_buf[0] = '\0';
 175         opts.log_level = 2;
 176         fd = bpf_prog_load(BPF_PROG_TYPE_SOCKET_FILTER, "good_prog", "GPL",
 177                            good_prog_insns, good_prog_insn_cnt, &opts);
 178         ASSERT_OK_PTR(strstr(log_buf, "0: R1=ctx() R10=fp0"), "good_log_2");
 179         ASSERT_GE(fd, 0, "good_fd2");
 180         if (fd >= 0)
 181                 close(fd);
 182
 183         /* log_level == 0 should fill log_buf for bad prog */
 184         log_buf[0] = '\0';
 185         opts.log_level = 0;
 186         fd = bpf_prog_load(BPF_PROG_TYPE_SOCKET_FILTER, "bad_prog", "GPL",
 187                            bad_prog_insns, bad_prog_insn_cnt, &opts);
 188         ASSERT_OK_PTR(strstr(log_buf, "R0 !read_ok"), "bad_log_0");
 189         ASSERT_LT(fd, 0, "bad_fd");
 190         if (fd >= 0)
 191                 close(fd);
 192
 193         free(log_buf);
 194 }
 195
 196 static void bpf_btf_load_log_buf(void)
 197 {
 198         LIBBPF_OPTS(bpf_btf_load_opts, opts);
 199         const size_t log_buf_sz = 1024 * 1024;
 200         const void *raw_btf_data;
 201         __u32 raw_btf_size;
 202         struct btf *btf;
 203         char *log_buf = NULL;
 204         int fd = -1;
 205
 206         btf = btf__new_empty();
 207         if (!ASSERT_OK_PTR(btf, "empty_btf"))
 208                 return;
 209
 210         ASSERT_GT(btf__add_int(btf, "int", 4, 0), 0, "int_type");
 211
 212         raw_btf_data = btf__raw_data(btf, &raw_btf_size);
 213         if (!ASSERT_OK_PTR(raw_btf_data, "raw_btf_data_good"))
 214                 goto cleanup;
 215
 216         log_buf = malloc(log_buf_sz);
 217         if (!ASSERT_OK_PTR(log_buf, "log_buf_alloc"))
 218                 goto cleanup;
 219         opts.log_buf = log_buf;
 220         opts.log_size = log_buf_sz;
 221
 222         /* with log_level == 0 log_buf should stay empty for good BTF */
 223         log_buf[0] = '\0';
 224         opts.log_level = 0;
 225         fd = bpf_btf_load(raw_btf_data, raw_btf_size, &opts);
 226         ASSERT_STREQ(log_buf, "", "good_log_0");
 227         ASSERT_GE(fd, 0, "good_fd1");
 228         if (fd >= 0)
 229                 close(fd);
 230         fd = -1;
 231
 232         /* log_level == 2 should always fill log_buf, even for good BTF */
 233         log_buf[0] = '\0';
 234         opts.log_level = 2;
 235         fd = bpf_btf_load(raw_btf_data, raw_btf_size, &opts);
 236         printf("LOG_BUF: %s\n", log_buf);
 237         ASSERT_OK_PTR(strstr(log_buf, "magic: 0xeb9f"), "good_log_2");
 238         ASSERT_GE(fd, 0, "good_fd2");
 239         if (fd >= 0)
 240                 close(fd);
 241         fd = -1;
 242
 243         /* make BTF bad, add pointer pointing to non-existing type */
 244         ASSERT_GT(btf__add_ptr(btf, 100), 0, "bad_ptr_type");
 245
 246         raw_btf_data = btf__raw_data(btf, &raw_btf_size);
 247         if (!ASSERT_OK_PTR(raw_btf_data, "raw_btf_data_bad"))
 248                 goto cleanup;
 249
 250         /* log_level == 0 should fill log_buf for bad BTF */
 251         log_buf[0] = '\0';
 252         opts.log_level = 0;
 253         fd = bpf_btf_load(raw_btf_data, raw_btf_size, &opts);
 254         printf("LOG_BUF: %s\n", log_buf);
 255         ASSERT_OK_PTR(strstr(log_buf, "[2] PTR (anon) type_id=100 Invalid type_id"), "bad_log_0");
 256         ASSERT_LT(fd, 0, "bad_fd");
 257         if (fd >= 0)
 258                 close(fd);
 259         fd = -1;
 260
 261 cleanup:
 262         free(log_buf);
 263         btf__free(btf);
 264 }
 265
 266 void test_log_buf(void)
 267 {
 268         if (test__start_subtest("obj_load_log_buf"))
 269                 obj_load_log_buf();
 270         if (test__start_subtest("bpf_prog_load_log_buf"))
 271                 bpf_prog_load_log_buf();
 272         if (test__start_subtest("bpf_btf_load_log_buf"))
 273                 bpf_btf_load_log_buf();
 274 }