ebpf: where verifier prints its messages?

Question

Where does the verifier print its messages? I have a simple code embedded in struct bpf_insn which I load and attach as BPF_PROG_TYPE_SOCKET_FILTER type:

struct bpf_insn prog[] = {
   BPF_MOV64_REG(BPF_REG_6, BPF_REG_1),
   BPF_EXIT_INSN(),
};

This code is intentionally made wrong (R0 is not initialized before the exit). bpf_prog_load() returns EACCESS error and fails to load, which is expected, but I wanted to the verifier messages (nothing in dmesg or console).

It prints them to the verifier's log buffer. It is up to the loader to provide a buffer for the verifier to fill, and then to dump it to the console. How do you load your program? — Qeole, May 05 '21 at 19:04
@Qeole, Yes you're right, `man bpf` is very clear about that. However it does not seem to be enough to make it work. I also took the kernel's `samples/bpf/sock_example.c` and shrunk the bpf program code to minimum, as mine, rebuilt and launched the prog -- it does return `EACCESS` but does not print any verifier messages. — Mark, May 05 '21 at 20:51
`samples/bpf/sock_example.c` does pass a buffer to the verifier: `bpf_load_program(..., bpf_log_buf, BPF_LOG_BUF_SIZE)`. But it does not seem to _print_ the contents of that buffer when loading fails, just the `strerror(errno)`, so you don't get verfier's output. You probably just need to add something like `printf("%s", bpf_log_buf);` when `prog_fd < 0`. — Qeole, May 06 '21 at 09:19

Qeole · Accepted Answer · 2021-05-06T20:14:18.960

When attempting to load an eBPF program, it is up to the loader to pass a buffer to the kernel verifier and to later print it to get the verifier's output.

The verifier will use this buffer provided by the user space program and print all its logs in it. Excepted for a very few specific messages, it will not print anything to the kernel logs or to the console (which is handled by your shell, not the kernel directly).

Let's have a look at a snippet from samples/bpf/sock_example.c, that you mentioned in the comments.

    prog_fd = bpf_load_program(BPF_PROG_TYPE_SOCKET_FILTER, prog, insns_cnt,
                   "GPL", 0, bpf_log_buf, BPF_LOG_BUF_SIZE);
    if (prog_fd < 0) {
        printf("failed to load prog '%s'\n", strerror(errno));
        goto cleanup;
    }

This is the part where we attempt to load the program. We call bpf_load_program() from libbpf, and we pass it, in this order, the program type, the instructions, the number of instructions, the license string, some flag related to kernel versions, and at last: an empty buffer and its size. The size BPF_LOG_BUF_SIZE is non-null (defined in tools/lib/bpf/bpf as (UINT32_MAX >> 8)).

The function bpf_load_program() will pass all this information, including the pointer to the buffer, to the bpf() system call, which will attempt to load the program. The verifier will populate the buffer with logs (whether the load succeeds or not, but see note at the bottom). Then it is up to the loader program, again, to use these logs. The function bpf_load_program() is low-level, it does nothing with the verifier's logs in the buffer, even on failure to load. It leaves it to the caller to process or dump the logs. The sample application that you attempt to run does nothing either; therefore, the buffer is unused, and you don't get to see the logs in the console.

To see the logs, in your case, you probably just need to dump this buffer. Something as simple as the following should work:

    ...
    if (prog_fd < 0) {
        printf("failed to load prog '%s'\n", strerror(errno));
        printf("%s", bpf_log_buf);
        goto cleanup;
    }

Note: In addition to the buffer and the size of the buffer, the loader must pass a log_level integer to the verifier, to tell it what level of verbosity it should use. If the value is at 0, the verifier prints nothing to the buffer. In the current case, we do not handle the log_level directly. bpf_load_program() does not either and sets the value to 0, but it ends up calling libbpf__bpf_prog_load() in libbpf. That function tries to load the program a first time without changing the log_level, but in case of failure, it does a new attempt with the log_level set at 1 - See Mark's pointers in the comments for details. The different values for log_level are defined in internal kernel headers and are not part of the user API, meaning the behaviour of the verifier regarding log verbosity may vary between kernel versions.

precisely, thank you! Also, it is worthy to mention that this would work with log_level > 0. — Mark, May 06 '21 at 12:38
Ah, right. Did you have to bring additional changes? Did you switch to `bpf_load_program_xattr()` maybe? It looks like `bpf_load_program()` only sets the `log_level` at 0? — Qeole, May 06 '21 at 14:08
I didn't make changes. However, I looked at the `bpf_load_program()` code https://elixir.bootlin.com/linux/latest/source/tools/lib/bpf/bpf.c#L375 where it calls `bpf_load_program_xattr()` which eventually calls `libbpf__bpf_prog_load()` (https://elixir.bootlin.com/linux/latest/source/tools/lib/bpf/bpf.c#L221). If I read `libbpf__bpf_prog_load()` correctly, it will explicitly set log_level to 1 in case of sys_bpf failure, and call sys_bpf again. — Mark, May 06 '21 at 16:41
Ah right sounds correct, I forgot about that. Good work on the code reading :). I'll update the answer to mention the `log_level`. — Qeole, May 06 '21 at 20:05

ebpf: where verifier prints its messages?

1 Answers1