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