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 
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 
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(id=0,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 
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(id=0,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 
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;
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 
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