tjh.dev
Linux kernel mirror (for testing)
git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel
os
linux
selftests/bpf: Add test for libbpf's custom log_buf behavior
Add a selftest that validates that per-program and per-object log_buf
overrides work as expected. Also test same logic for low-level
bpf_prog_load() and bpf_btf_load() APIs.
Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
Signed-off-by: Alexei Starovoitov <ast@kernel.org>
Link: https://lore.kernel.org/bpf/20211209193840.1248570-11-andrii@kernel.org
+300
+276
tools/testing/selftests/bpf/prog_tests/log_buf.c
+276
tools/testing/selftests/bpf/prog_tests/log_buf.c
···
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
+
}
+24
tools/testing/selftests/bpf/progs/test_log_buf.c
+24
tools/testing/selftests/bpf/progs/test_log_buf.c
···
1
+
// SPDX-License-Identifier: GPL-2.0
2
+
/* Copyright (c) 2021 Facebook */
3
+
4
+
#include <linux/bpf.h>
5
+
#include <bpf/bpf_helpers.h>
6
+
7
+
int a[4];
8
+
const volatile int off = 4000;
9
+
10
+
SEC("raw_tp/sys_enter")
11
+
int good_prog(const void *ctx)
12
+
{
13
+
a[0] = (int)(long)ctx;
14
+
return a[1];
15
+
}
16
+
17
+
SEC("raw_tp/sys_enter")
18
+
int bad_prog(const void *ctx)
19
+
{
20
+
/* out of bounds access */
21
+
return a[off];
22
+
}
23
+
24
+
char _license[] SEC("license") = "GPL";