Commit ad9a7f96 authored by Andrii Nakryiko's avatar Andrii Nakryiko
Browse files

libbpf: Improve logging around BPF program loading 



Add missing "prog '%s': " prefixes in few places and use consistently
markers for beginning and end of program load logs. Here's an example of
log output:

libbpf: prog 'handler': BPF program load failed: Permission denied
libbpf: -- BEGIN PROG LOAD LOG ---
arg#0 reference type('UNKNOWN ') size cannot be determined: -22
; out1 = in1;
0: (18) r1 = 0xffffc9000cdcc000
2: (61) r1 = *(u32 *)(r1 +0)

...

81: (63) *(u32 *)(r4 +0) = r5
 R1_w=map_value(id=0,off=16,ks=4,vs=20,imm=0) R4=map_value(id=0,off=400,ks=4,vs=16,imm=0)
invalid access to map value, value_size=16 off=400 size=4
R4 min value is outside of the allowed memory range
processed 63 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
 -- END PROG LOAD LOG --
libbpf: failed to load program 'handler'
libbpf: failed to load object 'test_skeleton'

The entire verifier log, including BEGIN and END markers are now always
youtput during a single print callback call. This should make it much
easier to post-process or parse it, if necessary. It's not an explicit
API guarantee, but it can be reasonably expected to stay like that.

Also __bpf_object__open is renamed to bpf_object_open() as it's always
an adventure to find the exact function that implements bpf_object's
open phase, so drop the double underscored and use internal libbpf
naming convention.

Signed-off-by: default avatarAndrii Nakryiko <andrii@kernel.org>
Signed-off-by: default avatarAlexei Starovoitov <ast@kernel.org>
Link: https://lore.kernel.org/bpf/20211209193840.1248570-6-andrii@kernel.org
parent e0e3ea88

tools/lib/bpf/libbpf.c

+19 −19
Original line number Diff line number Diff line
@@ -6662,8 +6662,10 @@ static int bpf_object_load_prog_instance(struct bpf_object *obj, struct bpf_prog 
	ret = bpf_prog_load(prog->type, prog_name, license, insns, insns_cnt, &load_attr);



	if (ret >= 0) {

		if (log_buf && load_attr.log_level)

			pr_debug("verifier log:\n%s", log_buf);

		if (log_buf && load_attr.log_level) {

			pr_debug("prog '%s': -- BEGIN PROG LOAD LOG --\n%s-- END PROG LOAD LOG --\n",

				 prog->name, log_buf);

		}



		if (obj->has_rodata && kernel_supports(obj, FEAT_PROG_BIND_MAP)) {

			struct bpf_map *map;
@@ -6676,8 +6678,8 @@ static int bpf_object_load_prog_instance(struct bpf_object *obj, struct bpf_prog 


				if (bpf_prog_bind_map(ret, bpf_map__fd(map), NULL)) {

					cp = libbpf_strerror_r(errno, errmsg, sizeof(errmsg));

					pr_warn("prog '%s': failed to bind .rodata map: %s\n",

						prog->name, cp);

					pr_warn("prog '%s': failed to bind map '%s': %s\n",

						prog->name, map->real_name, cp);

					/* Don't fail hard if can't bind rodata. */

				}

			}
@@ -6691,23 +6693,22 @@ static int bpf_object_load_prog_instance(struct bpf_object *obj, struct bpf_prog 
	if (!log_buf || errno == ENOSPC) {

		log_buf_size = max((size_t)BPF_LOG_BUF_SIZE,

				   log_buf_size << 1);



		free(log_buf);

		goto retry_load;

	}

	ret = errno ? -errno : -LIBBPF_ERRNO__LOAD;

	cp = libbpf_strerror_r(errno, errmsg, sizeof(errmsg));

	pr_warn("load bpf program failed: %s\n", cp);

	pr_warn("prog '%s': BPF program load failed: %s\n", prog->name, cp);

	pr_perm_msg(ret);



	if (log_buf && log_buf[0] != '\0') {

		ret = -LIBBPF_ERRNO__VERIFY;

		pr_warn("-- BEGIN DUMP LOG ---\n");

		pr_warn("\n%s\n", log_buf);

		pr_warn("-- END LOG --\n");

	} else if (insns_cnt >= BPF_MAXINSNS) {

		pr_warn("Program too large (%d insns), at most %d insns\n",

			insns_cnt, BPF_MAXINSNS);

		pr_warn("prog '%s': -- BEGIN PROG LOAD LOG --\n%s-- END PROG LOAD LOG --\n",

			prog->name, log_buf);

	}

	if (insns_cnt >= BPF_MAXINSNS) {

		pr_warn("prog '%s': program too large (%d insns), at most %d insns\n",

			prog->name, insns_cnt, BPF_MAXINSNS);

		ret = -LIBBPF_ERRNO__PROG2BIG;

	} else if (prog->type != BPF_PROG_TYPE_KPROBE) {

		/* Wrong program type? */
@@ -6931,8 +6932,7 @@ static int bpf_object_init_progs(struct bpf_object *obj, const struct bpf_object 
	return 0;

}



static struct bpf_object *

__bpf_object__open(const char *path, const void *obj_buf, size_t obj_buf_sz,

static struct bpf_object *bpf_object_open(const char *path, const void *obj_buf, size_t obj_buf_sz,

					  const struct bpf_object_open_opts *opts)

{

	const char *obj_name, *kconfig, *btf_tmp_path;
@@ -7033,7 +7033,7 @@ __bpf_object__open_xattr(struct bpf_object_open_attr *attr, int flags) 
		return NULL;



	pr_debug("loading %s\n", attr->file);

	return __bpf_object__open(attr->file, NULL, 0, &opts);

	return bpf_object_open(attr->file, NULL, 0, &opts);

}



struct bpf_object *bpf_object__open_xattr(struct bpf_object_open_attr *attr)
@@ -7059,7 +7059,7 @@ bpf_object__open_file(const char *path, const struct bpf_object_open_opts *opts) 


	pr_debug("loading %s\n", path);



	return libbpf_ptr(__bpf_object__open(path, NULL, 0, opts));

	return libbpf_ptr(bpf_object_open(path, NULL, 0, opts));

}



struct bpf_object *
@@ -7069,7 +7069,7 @@ bpf_object__open_mem(const void *obj_buf, size_t obj_buf_sz, 
	if (!obj_buf || obj_buf_sz == 0)

		return libbpf_err_ptr(-EINVAL);



	return libbpf_ptr(__bpf_object__open(NULL, obj_buf, obj_buf_sz, opts));

	return libbpf_ptr(bpf_object_open(NULL, obj_buf, obj_buf_sz, opts));

}



struct bpf_object *
@@ -7086,7 +7086,7 @@ bpf_object__open_buffer(const void *obj_buf, size_t obj_buf_sz, 
	if (!obj_buf || obj_buf_sz == 0)

		return errno = EINVAL, NULL;



	return libbpf_ptr(__bpf_object__open(NULL, obj_buf, obj_buf_sz, &opts));

	return libbpf_ptr(bpf_object_open(NULL, obj_buf, obj_buf_sz, &opts));

}



static int bpf_object_unload(struct bpf_object *obj)

tools/testing/selftests/bpf/prog_tests/bpf_tcp_ca.c

+4 −2
Original line number Diff line number Diff line
@@ -217,14 +217,16 @@ static bool found; 
static int libbpf_debug_print(enum libbpf_print_level level,

			      const char *format, va_list args)

{

	char *log_buf;

	const char *log_buf;



	if (level != LIBBPF_WARN ||

	    strcmp(format, "libbpf: \n%s\n")) {

	    !strstr(format, "-- BEGIN PROG LOAD LOG --")) {

		vprintf(format, args);

		return 0;

	}



	/* skip prog_name */

	va_arg(args, char *);

	log_buf = va_arg(args, char *);

	if (!log_buf)

		goto out;