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