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

   1 // SPDX-License-Identifier: GPL-2.0
   2 /* Copyright (c) 2023 Meta Platforms, Inc. and affiliates. */
   3
   4 #include <test_progs.h>
   5 #include <bpf/btf.h>
   6
   7 #include "test_log_buf.skel.h"
   8
   9
  10 static bool check_prog_load(int prog_fd, bool expect_err, const char *tag)
  11 {
  12         if (expect_err) {
  13                 if (!ASSERT_LT(prog_fd, 0, tag)) {
  14                         close(prog_fd);
  15                         return false;
  16                 }
  17         } else /* !expect_err */ {
  18                 if (!ASSERT_GT(prog_fd, 0, tag))
  19                         return false;
  20         }
  21         if (prog_fd >= 0)
  22                 close(prog_fd);
  23         return true;
  24 }
  25
  26 static struct {
  27         /* strategically placed before others to avoid accidental modification by kernel */
  28         char filler[1024];
  29         char buf[1024];
  30         /* strategically placed after buf[] to catch more accidental corruptions */
  31         char reference[1024];
  32 } logs;
  33 static const struct bpf_insn *insns;
  34 static size_t insn_cnt;
  35
  36 static int load_prog(struct bpf_prog_load_opts *opts, bool expect_load_error)
  37 {
  38         int prog_fd;
  39
  40         prog_fd = bpf_prog_load(BPF_PROG_TYPE_RAW_TRACEPOINT, "log_prog",
  41                                 "GPL", insns, insn_cnt, opts);
  42         check_prog_load(prog_fd, expect_load_error, "prog_load");
  43
  44         return prog_fd;
  45 }
  46
  47 static void verif_log_subtest(const char *name, bool expect_load_error, int log_level)
  48 {
  49         LIBBPF_OPTS(bpf_prog_load_opts, opts);
  50         char *exp_log, prog_name[16], op_name[32];
  51         struct test_log_buf *skel;
  52         struct bpf_program *prog;
  53         size_t fixed_log_sz;
  54         __u32 log_true_sz_fixed, log_true_sz_rolling;
  55         int i, mode, err, prog_fd, res;
  56
  57         skel = test_log_buf__open();
  58         if (!ASSERT_OK_PTR(skel, "skel_open"))
  59                 return;
  60
  61         bpf_object__for_each_program(prog, skel->obj) {
  62                 if (strcmp(bpf_program__name(prog), name) == 0)
  63                         bpf_program__set_autoload(prog, true);
  64                 else
  65                         bpf_program__set_autoload(prog, false);
  66         }
  67
  68         err = test_log_buf__load(skel);
  69         if (!expect_load_error && !ASSERT_OK(err, "unexpected_load_failure"))
  70                 goto cleanup;
  71         if (expect_load_error && !ASSERT_ERR(err, "unexpected_load_success"))
  72                 goto cleanup;
  73
  74         insns = bpf_program__insns(skel->progs.good_prog);
  75         insn_cnt = bpf_program__insn_cnt(skel->progs.good_prog);
  76
  77         opts.log_buf = logs.reference;
  78         opts.log_size = sizeof(logs.reference);
  79         opts.log_level = log_level | 8 /* BPF_LOG_FIXED */;
  80         load_prog(&opts, expect_load_error);
  81
  82         fixed_log_sz = strlen(logs.reference) + 1;
  83         if (!ASSERT_GT(fixed_log_sz, 50, "fixed_log_sz"))
  84                 goto cleanup;
  85         memset(logs.reference + fixed_log_sz, 0, sizeof(logs.reference) - fixed_log_sz);
  86
  87         /* validate BPF_LOG_FIXED works as verifier log used to work, that is:
  88          * we get -ENOSPC and beginning of the full verifier log. This only
  89          * works for log_level 2 and log_level 1 + failed program. For log
  90          * level 2 we don't reset log at all. For log_level 1 + failed program
  91          * we don't get to verification stats output. With log level 1
  92          * for successful program  final result will be just verifier stats.
  93          * But if provided too short log buf, kernel will NULL-out log->ubuf
  94          * and will stop emitting further log. This means we'll never see
  95          * predictable verifier stats.
  96          * Long story short, we do the following -ENOSPC test only for
  97          * predictable combinations.
  98          */
  99         if (log_level >= 2 || expect_load_error) {
 100                 opts.log_buf = logs.buf;
 101                 opts.log_level = log_level | 8; /* fixed-length log */
 102                 opts.log_size = 25;
 103
 104                 prog_fd = bpf_prog_load(BPF_PROG_TYPE_RAW_TRACEPOINT, "log_fixed25",
 105                                         "GPL", insns, insn_cnt, &opts);
 106                 if (!ASSERT_EQ(prog_fd, -ENOSPC, "unexpected_log_fixed_prog_load_result")) {
 107                         if (prog_fd >= 0)
 108                                 close(prog_fd);
 109                         goto cleanup;
 110                 }
 111                 if (!ASSERT_EQ(strlen(logs.buf), 24, "log_fixed_25"))
 112                         goto cleanup;
 113                 if (!ASSERT_STRNEQ(logs.buf, logs.reference, 24, "log_fixed_contents_25"))
 114                         goto cleanup;
 115         }
 116
 117         /* validate rolling verifier log logic: try all variations of log buf
 118          * length to force various truncation scenarios
 119          */
 120         opts.log_buf = logs.buf;
 121
 122         /* rotating mode, then fixed mode */
 123         for (mode = 1; mode >= 0; mode--) {
 124                 /* prefill logs.buf with 'A's to detect any write beyond allowed length */
 125                 memset(logs.filler, 'A', sizeof(logs.filler));
 126                 logs.filler[sizeof(logs.filler) - 1] = '\0';
 127                 memset(logs.buf, 'A', sizeof(logs.buf));
 128                 logs.buf[sizeof(logs.buf) - 1] = '\0';
 129
 130                 for (i = 1; i < fixed_log_sz; i++) {
 131                         opts.log_size = i;
 132                         opts.log_level = log_level | (mode ? 0 : 8 /* BPF_LOG_FIXED */);
 133
 134                         snprintf(prog_name, sizeof(prog_name),
 135                                  "log_%s_%d", mode ? "roll" : "fixed", i);
 136                         prog_fd = bpf_prog_load(BPF_PROG_TYPE_RAW_TRACEPOINT, prog_name,
 137                                                 "GPL", insns, insn_cnt, &opts);
 138
 139                         snprintf(op_name, sizeof(op_name),
 140                                  "log_%s_prog_load_%d", mode ? "roll" : "fixed", i);
 141                         if (!ASSERT_EQ(prog_fd, -ENOSPC, op_name)) {
 142                                 if (prog_fd >= 0)
 143                                         close(prog_fd);
 144                                 goto cleanup;
 145                         }
 146
 147                         snprintf(op_name, sizeof(op_name),
 148                                  "log_%s_strlen_%d", mode ? "roll" : "fixed", i);
 149                         ASSERT_EQ(strlen(logs.buf), i - 1, op_name);
 150
 151                         if (mode)
 152                                 exp_log = logs.reference + fixed_log_sz - i;
 153                         else
 154                                 exp_log = logs.reference;
 155
 156                         snprintf(op_name, sizeof(op_name),
 157                                  "log_%s_contents_%d", mode ? "roll" : "fixed", i);
 158                         if (!ASSERT_STRNEQ(logs.buf, exp_log, i - 1, op_name)) {
 159                                 printf("CMP:%d\nS1:'%s'\nS2:'%s'\n",
 160                                         strncmp(logs.buf, exp_log, i - 1),
 161                                         logs.buf, exp_log);
 162                                 goto cleanup;
 163                         }
 164
 165                         /* check that unused portions of logs.buf is not overwritten */
 166                         snprintf(op_name, sizeof(op_name),
 167                                  "log_%s_unused_%d", mode ? "roll" : "fixed", i);
 168                         if (!ASSERT_STREQ(logs.buf + i, logs.filler + i, op_name)) {
 169                                 printf("CMP:%d\nS1:'%s'\nS2:'%s'\n",
 170                                         strcmp(logs.buf + i, logs.filler + i),
 171                                         logs.buf + i, logs.filler + i);
 172                                 goto cleanup;
 173                         }
 174                 }
 175         }
 176
 177         /* (FIXED) get actual log size */
 178         opts.log_buf = logs.buf;
 179         opts.log_level = log_level | 8; /* BPF_LOG_FIXED */
 180         opts.log_size = sizeof(logs.buf);
 181         opts.log_true_size = 0;
 182         res = load_prog(&opts, expect_load_error);
 183         ASSERT_NEQ(res, -ENOSPC, "prog_load_res_fixed");
 184
 185         log_true_sz_fixed = opts.log_true_size;
 186         ASSERT_GT(log_true_sz_fixed, 0, "log_true_sz_fixed");
 187
 188         /* (FIXED, NULL) get actual log size */
 189         opts.log_buf = NULL;
 190         opts.log_level = log_level | 8; /* BPF_LOG_FIXED */
 191         opts.log_size = 0;
 192         opts.log_true_size = 0;
 193         res = load_prog(&opts, expect_load_error);
 194         ASSERT_NEQ(res, -ENOSPC, "prog_load_res_fixed_null");
 195         ASSERT_EQ(opts.log_true_size, log_true_sz_fixed, "log_sz_fixed_null_eq");
 196
 197         /* (ROLLING) get actual log size */
 198         opts.log_buf = logs.buf;
 199         opts.log_level = log_level;
 200         opts.log_size = sizeof(logs.buf);
 201         opts.log_true_size = 0;
 202         res = load_prog(&opts, expect_load_error);
 203         ASSERT_NEQ(res, -ENOSPC, "prog_load_res_rolling");
 204
 205         log_true_sz_rolling = opts.log_true_size;
 206         ASSERT_EQ(log_true_sz_rolling, log_true_sz_fixed, "log_true_sz_eq");
 207
 208         /* (ROLLING, NULL) get actual log size */
 209         opts.log_buf = NULL;
 210         opts.log_level = log_level;
 211         opts.log_size = 0;
 212         opts.log_true_size = 0;
 213         res = load_prog(&opts, expect_load_error);
 214         ASSERT_NEQ(res, -ENOSPC, "prog_load_res_rolling_null");
 215         ASSERT_EQ(opts.log_true_size, log_true_sz_rolling, "log_true_sz_null_eq");
 216
 217         /* (FIXED) expect -ENOSPC for one byte short log */
 218         opts.log_buf = logs.buf;
 219         opts.log_level = log_level | 8; /* BPF_LOG_FIXED */
 220         opts.log_size = log_true_sz_fixed - 1;
 221         opts.log_true_size = 0;
 222         res = load_prog(&opts, true /* should fail */);
 223         ASSERT_EQ(res, -ENOSPC, "prog_load_res_too_short_fixed");
 224
 225         /* (FIXED) expect *not* -ENOSPC with exact log_true_size buffer */
 226         opts.log_buf = logs.buf;
 227         opts.log_level = log_level | 8; /* BPF_LOG_FIXED */
 228         opts.log_size = log_true_sz_fixed;
 229         opts.log_true_size = 0;
 230         res = load_prog(&opts, expect_load_error);
 231         ASSERT_NEQ(res, -ENOSPC, "prog_load_res_just_right_fixed");
 232
 233         /* (ROLLING) expect -ENOSPC for one byte short log */
 234         opts.log_buf = logs.buf;
 235         opts.log_level = log_level;
 236         opts.log_size = log_true_sz_rolling - 1;
 237         res = load_prog(&opts, true /* should fail */);
 238         ASSERT_EQ(res, -ENOSPC, "prog_load_res_too_short_rolling");
 239
 240         /* (ROLLING) expect *not* -ENOSPC with exact log_true_size buffer */
 241         opts.log_buf = logs.buf;
 242         opts.log_level = log_level;
 243         opts.log_size = log_true_sz_rolling;
 244         opts.log_true_size = 0;
 245         res = load_prog(&opts, expect_load_error);
 246         ASSERT_NEQ(res, -ENOSPC, "prog_load_res_just_right_rolling");
 247
 248 cleanup:
 249         test_log_buf__destroy(skel);
 250 }
 251
 252 static const void *btf_data;
 253 static u32 btf_data_sz;
 254
 255 static int load_btf(struct bpf_btf_load_opts *opts, bool expect_err)
 256 {
 257         int fd;
 258
 259         fd = bpf_btf_load(btf_data, btf_data_sz, opts);
 260         if (fd >= 0)
 261                 close(fd);
 262         if (expect_err)
 263                 ASSERT_LT(fd, 0, "btf_load_failure");
 264         else /* !expect_err */
 265                 ASSERT_GT(fd, 0, "btf_load_success");
 266         return fd;
 267 }
 268
 269 static void verif_btf_log_subtest(bool bad_btf)
 270 {
 271         LIBBPF_OPTS(bpf_btf_load_opts, opts);
 272         struct btf *btf;
 273         struct btf_type *t;
 274         char *exp_log, op_name[32];
 275         size_t fixed_log_sz;
 276         __u32 log_true_sz_fixed, log_true_sz_rolling;
 277         int i, res;
 278
 279         /* prepare simple BTF contents */
 280         btf = btf__new_empty();
 281         if (!ASSERT_OK_PTR(btf, "btf_new_empty"))
 282                 return;
 283         res = btf__add_int(btf, "whatever", 4, 0);
 284         if (!ASSERT_GT(res, 0, "btf_add_int_id"))
 285                 goto cleanup;
 286         if (bad_btf) {
 287                 /* btf__add_int() doesn't allow bad value of size, so we'll just
 288                  * force-cast btf_type pointer and manually override size to invalid
 289                  * 3 if we need to simulate failure
 290                  */
 291                 t = (void *)btf__type_by_id(btf, res);
 292                 if (!ASSERT_OK_PTR(t, "int_btf_type"))
 293                         goto cleanup;
 294                 t->size = 3;
 295         }
 296
 297         btf_data = btf__raw_data(btf, &btf_data_sz);
 298         if (!ASSERT_OK_PTR(btf_data, "btf_data"))
 299                 goto cleanup;
 300
 301         load_btf(&opts, bad_btf);
 302
 303         opts.log_buf = logs.reference;
 304         opts.log_size = sizeof(logs.reference);
 305         opts.log_level = 1 | 8 /* BPF_LOG_FIXED */;
 306         load_btf(&opts, bad_btf);
 307
 308         fixed_log_sz = strlen(logs.reference) + 1;
 309         if (!ASSERT_GT(fixed_log_sz, 50, "fixed_log_sz"))
 310                 goto cleanup;
 311         memset(logs.reference + fixed_log_sz, 0, sizeof(logs.reference) - fixed_log_sz);
 312
 313         /* validate BPF_LOG_FIXED truncation works as verifier log used to work */
 314         opts.log_buf = logs.buf;
 315         opts.log_level = 1 | 8; /* fixed-length log */
 316         opts.log_size = 25;
 317         res = load_btf(&opts, true);
 318         ASSERT_EQ(res, -ENOSPC, "half_log_fd");
 319         ASSERT_EQ(strlen(logs.buf), 24, "log_fixed_25");
 320         ASSERT_STRNEQ(logs.buf, logs.reference, 24, op_name);
 321
 322         /* validate rolling verifier log logic: try all variations of log buf
 323          * length to force various truncation scenarios
 324          */
 325         opts.log_buf = logs.buf;
 326         opts.log_level = 1; /* rolling log */
 327
 328         /* prefill logs.buf with 'A's to detect any write beyond allowed length */
 329         memset(logs.filler, 'A', sizeof(logs.filler));
 330         logs.filler[sizeof(logs.filler) - 1] = '\0';
 331         memset(logs.buf, 'A', sizeof(logs.buf));
 332         logs.buf[sizeof(logs.buf) - 1] = '\0';
 333
 334         for (i = 1; i < fixed_log_sz; i++) {
 335                 opts.log_size = i;
 336
 337                 snprintf(op_name, sizeof(op_name), "log_roll_btf_load_%d", i);
 338                 res = load_btf(&opts, true);
 339                 if (!ASSERT_EQ(res, -ENOSPC, op_name))
 340                         goto cleanup;
 341
 342                 exp_log = logs.reference + fixed_log_sz - i;
 343                 snprintf(op_name, sizeof(op_name), "log_roll_contents_%d", i);
 344                 if (!ASSERT_STREQ(logs.buf, exp_log, op_name)) {
 345                         printf("CMP:%d\nS1:'%s'\nS2:'%s'\n",
 346                                 strcmp(logs.buf, exp_log),
 347                                 logs.buf, exp_log);
 348                         goto cleanup;
 349                 }
 350
 351                 /* check that unused portions of logs.buf are not overwritten */
 352                 snprintf(op_name, sizeof(op_name), "log_roll_unused_tail_%d", i);
 353                 if (!ASSERT_STREQ(logs.buf + i, logs.filler + i, op_name)) {
 354                         printf("CMP:%d\nS1:'%s'\nS2:'%s'\n",
 355                                 strcmp(logs.buf + i, logs.filler + i),
 356                                 logs.buf + i, logs.filler + i);
 357                         goto cleanup;
 358                 }
 359         }
 360
 361         /* (FIXED) get actual log size */
 362         opts.log_buf = logs.buf;
 363         opts.log_level = 1 | 8; /* BPF_LOG_FIXED */
 364         opts.log_size = sizeof(logs.buf);
 365         opts.log_true_size = 0;
 366         res = load_btf(&opts, bad_btf);
 367         ASSERT_NEQ(res, -ENOSPC, "btf_load_res_fixed");
 368
 369         log_true_sz_fixed = opts.log_true_size;
 370         ASSERT_GT(log_true_sz_fixed, 0, "log_true_sz_fixed");
 371
 372         /* (FIXED, NULL) get actual log size */
 373         opts.log_buf = NULL;
 374         opts.log_level = 1 | 8; /* BPF_LOG_FIXED */
 375         opts.log_size = 0;
 376         opts.log_true_size = 0;
 377         res = load_btf(&opts, bad_btf);
 378         ASSERT_NEQ(res, -ENOSPC, "btf_load_res_fixed_null");
 379         ASSERT_EQ(opts.log_true_size, log_true_sz_fixed, "log_sz_fixed_null_eq");
 380
 381         /* (ROLLING) get actual log size */
 382         opts.log_buf = logs.buf;
 383         opts.log_level = 1;
 384         opts.log_size = sizeof(logs.buf);
 385         opts.log_true_size = 0;
 386         res = load_btf(&opts, bad_btf);
 387         ASSERT_NEQ(res, -ENOSPC, "btf_load_res_rolling");
 388
 389         log_true_sz_rolling = opts.log_true_size;
 390         ASSERT_EQ(log_true_sz_rolling, log_true_sz_fixed, "log_true_sz_eq");
 391
 392         /* (ROLLING, NULL) get actual log size */
 393         opts.log_buf = NULL;
 394         opts.log_level = 1;
 395         opts.log_size = 0;
 396         opts.log_true_size = 0;
 397         res = load_btf(&opts, bad_btf);
 398         ASSERT_NEQ(res, -ENOSPC, "btf_load_res_rolling_null");
 399         ASSERT_EQ(opts.log_true_size, log_true_sz_rolling, "log_true_sz_null_eq");
 400
 401         /* (FIXED) expect -ENOSPC for one byte short log */
 402         opts.log_buf = logs.buf;
 403         opts.log_level = 1 | 8; /* BPF_LOG_FIXED */
 404         opts.log_size = log_true_sz_fixed - 1;
 405         opts.log_true_size = 0;
 406         res = load_btf(&opts, true);
 407         ASSERT_EQ(res, -ENOSPC, "btf_load_res_too_short_fixed");
 408
 409         /* (FIXED) expect *not* -ENOSPC with exact log_true_size buffer */
 410         opts.log_buf = logs.buf;
 411         opts.log_level = 1 | 8; /* BPF_LOG_FIXED */
 412         opts.log_size = log_true_sz_fixed;
 413         opts.log_true_size = 0;
 414         res = load_btf(&opts, bad_btf);
 415         ASSERT_NEQ(res, -ENOSPC, "btf_load_res_just_right_fixed");
 416
 417         /* (ROLLING) expect -ENOSPC for one byte short log */
 418         opts.log_buf = logs.buf;
 419         opts.log_level = 1;
 420         opts.log_size = log_true_sz_rolling - 1;
 421         res = load_btf(&opts, true);
 422         ASSERT_EQ(res, -ENOSPC, "btf_load_res_too_short_rolling");
 423
 424         /* (ROLLING) expect *not* -ENOSPC with exact log_true_size buffer */
 425         opts.log_buf = logs.buf;
 426         opts.log_level = 1;
 427         opts.log_size = log_true_sz_rolling;
 428         opts.log_true_size = 0;
 429         res = load_btf(&opts, bad_btf);
 430         ASSERT_NEQ(res, -ENOSPC, "btf_load_res_just_right_rolling");
 431
 432 cleanup:
 433         btf__free(btf);
 434 }
 435
 436 void test_verifier_log(void)
 437 {
 438         if (test__start_subtest("good_prog-level1"))
 439                 verif_log_subtest("good_prog", false, 1);
 440         if (test__start_subtest("good_prog-level2"))
 441                 verif_log_subtest("good_prog", false, 2);
 442         if (test__start_subtest("bad_prog-level1"))
 443                 verif_log_subtest("bad_prog", true, 1);
 444         if (test__start_subtest("bad_prog-level2"))
 445                 verif_log_subtest("bad_prog", true, 2);
 446         if (test__start_subtest("bad_btf"))
 447                 verif_btf_log_subtest(true /* bad btf */);
 448         if (test__start_subtest("good_btf"))
 449                 verif_btf_log_subtest(false /* !bad btf */);
 450 }