451 lines · c
1// SPDX-License-Identifier: GPL-2.02/* 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 10static 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 26static 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;33static const struct bpf_insn *insns;34static size_t insn_cnt;35 36static 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 47static 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 else65 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 only89 * works for log_level 2 and log_level 1 + failed program. For log90 * level 2 we don't reset log at all. For log_level 1 + failed program91 * we don't get to verification stats output. With log level 192 * for successful program final result will be just verifier stats.93 * But if provided too short log buf, kernel will NULL-out log->ubuf94 * and will stop emitting further log. This means we'll never see95 * predictable verifier stats.96 * Long story short, we do the following -ENOSPC test only for97 * 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 buf118 * length to force various truncation scenarios119 */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 else154 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 248cleanup:249 test_log_buf__destroy(skel);250}251 252static const void *btf_data;253static u32 btf_data_sz;254 255static 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 269static 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 just288 * force-cast btf_type pointer and manually override size to invalid289 * 3 if we need to simulate failure290 */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 buf323 * length to force various truncation scenarios324 */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 432cleanup:433 btf__free(btf);434}435 436void 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}451