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