Subject: Re: len = bpf_probe_read_str(); bpf_perf_event_output(... len) == FAIL

From: Arnaldo Carvalho de Melo <[email-masked]>
Date: Mon, 13 Nov 2017 12:08:20 -0300

Em Mon, Nov 13, 2017 at 03:56:14PM +0100, Daniel Borkmann escreveu:
> On 11/13/2017 03:30 PM, Arnaldo Carvalho de Melo wrote:
> > Hi,
> > 
> > 	In a5e8c07059d0 ("bpf: add bpf_probe_read_str helper") you
> > state:
> > 
> >    "This is suboptimal because the size of the string needs to be estimated
> >     at compile time, causing more memory to be copied than often necessary,
> >     and can become more problematic if further processing on buf is done,
> >     for example by pushing it to userspace via bpf_perf_event_output(),
> >     since the real length of the string is unknown and the entire buffer
> >     must be copied (and defining an unrolled strnlen() inside the bpf
> >     program is a very inefficient and unfeasible approach)."
> > 
> > So I went on to try this with 'perf trace' but it isn't working if I use
> > the return from bpf_probe_read_str(), I must be missing something
> > here... 
> > 
> > I.e. this works:
> > 
> > [root@jouet bpf]# cat open.c
> > #include "bpf.h"
> > 
> > SEC("prog=do_sys_open filename")
> > int prog(void *ctx, int err, const char __user *filename_ptr)
> > {
> > 	char filename[128];
> > 	const unsigned len = bpf_probe_read_str(filename, sizeof(filename), filename_ptr);
> > 	perf_event_output(ctx, &__bpf_stdout__, get_smp_processor_id(), filename, 32);
> 
> By the way, you can just use BPF_F_CURRENT_CPU flag instead of the helper
> call get_smp_processor_id() to get current CPU.

Thanks, switched to it.

> > But then if I use the return value to push just the string lenght, it
> > doesn't work:
> > 
> > [root@jouet bpf]# cat open.c
> > #include "bpf.h"
> > 
> > SEC("prog=do_sys_open filename")
> > int prog(void *ctx, int err, const char __user *filename_ptr)
> > {
> > 	char filename[128];
> > 	const unsigned len = bpf_probe_read_str(filename, sizeof(filename), filename_ptr);
> > 	perf_event_output(ctx, &__bpf_stdout__, get_smp_processor_id(), filename, len);
> 
> The below issue 'invalid stack type R4 off=-128 access_size=0' is basically that
> unsigned len is unknown at verification time, thus unbounded. Can you try the
> following to see if that passes?
> 
> if (len > 0 && len <= sizeof(filename))
>     perf_event_output(ctx, &__bpf_stdout__, get_smp_processor_id(), filename, len);

I had it like:

	if (len > 0 && len < 32)

And it didn't helped, now I did exactly as you suggested:

[root@jouet bpf]# cat open.c
#include "bpf.h"

SEC("prog=do_sys_open filename")
int prog(void *ctx, int err, const char __user *filename_ptr)
{
	char filename[128];
	const unsigned len = bpf_probe_read_str(filename, sizeof(filename), filename_ptr);
	if (len > 0 && len <= sizeof(filename))
		perf_event_output(ctx, &__bpf_stdout__, BPF_F_CURRENT_CPU, filename, len);
	return 1;
}
[root@jouet bpf]# trace -e open,open.c touch /etc/passwd
bpf: builtin compilation failed: -95, try external compiler
event syntax error: 'open.c'
                     \___ Kernel verifier blocks program loading
<SNIP>
[root@jouet bpf]# 

The -v output looks the same:

[root@jouet bpf]# trace -v -e open,open.c touch /etc/passwd
bpf: builtin compilation failed: -95, try external compiler
Kernel build dir is set to /lib/modules/4.14.0-rc6+/build
set env: KBUILD_DIR=/lib/modules/4.14.0-rc6+/build
unset env: KBUILD_OPTS
include option is set to  -nostdinc -isystem /usr/lib/gcc/x86_64-redhat-linux/7/include -I/home/acme/git/linux/arch/x86/include -I./arch/x86/include/generated  -I/home/acme/git/linux/include -I./include -I/home/acme/git/linux/arch/x86/include/uapi -I./arch/x86/include/generated/uapi -I/home/acme/git/linux/include/uapi -I./include/generated/uapi -include /home/acme/git/linux/include/linux/kconfig.h 
set env: NR_CPUS=4
set env: LINUX_VERSION_CODE=0x40e00
set env: CLANG_EXEC=/usr/local/bin/clang
unset env: CLANG_OPTIONS
set env: KERNEL_INC_OPTIONS= -nostdinc -isystem /usr/lib/gcc/x86_64-redhat-linux/7/include -I/home/acme/git/linux/arch/x86/include -I./arch/x86/include/generated  -I/home/acme/git/linux/include -I./include -I/home/acme/git/linux/arch/x86/include/uapi -I./arch/x86/include/generated/uapi -I/home/acme/git/linux/include/uapi -I./include/generated/uapi -include /home/acme/git/linux/include/linux/kconfig.h 
set env: WORKING_DIR=/lib/modules/4.14.0-rc6+/build
set env: CLANG_SOURCE=/home/acme/bpf/open.c
llvm compiling command template: $CLANG_EXEC -D__KERNEL__ -D__NR_CPUS__=$NR_CPUS -DLINUX_VERSION_CODE=$LINUX_VERSION_CODE $CLANG_OPTIONS $KERNEL_INC_OPTIONS -Wno-unused-value -Wno-pointer-sign -working-directory $WORKING_DIR -c "$CLANG_SOURCE" -target bpf -O2 -o -
libbpf: loading object 'open.c' from buffer
libbpf: section .strtab, size 103, link 0, flags 0, type=3
libbpf: section .text, size 0, link 0, flags 6, type=1
libbpf: section prog=do_sys_open filename, size 184, link 0, flags 6, type=1
libbpf: found program prog=do_sys_open filename
libbpf: section .relprog=do_sys_open filename, size 16, link 8, flags 0, type=9
libbpf: section maps, size 16, link 0, flags 3, type=1
libbpf: section license, size 4, link 0, flags 3, type=1
libbpf: license of open.c is GPL
libbpf: section version, size 4, link 0, flags 3, type=1
libbpf: kernel version of open.c is 40e00
libbpf: section .symtab, size 144, link 1, flags 0, type=2
libbpf: maps in open.c: 1 maps in 16 bytes
libbpf: map 0 is "__bpf_stdout__"
libbpf: collecting relocating info for: 'prog=do_sys_open filename'
libbpf: relocation: insn_idx=15
libbpf: relocation: find map 0 (__bpf_stdout__) for insn 15
bpf: config program 'prog=do_sys_open filename'
symbol:do_sys_open file:(null) line:0 offset:0 return:0 lazy:(null)
parsing arg: filename into filename
bpf: config 'prog=do_sys_open filename' is ok
Looking at the vmlinux_path (8 entries long)
Using /lib/modules/4.14.0-rc6+/build/vmlinux for symbols
Open Debuginfo file: /lib/modules/4.14.0-rc6+/build/vmlinux
Try to find probe point from debuginfo.
Matched function: do_sys_open [2a2bbbe]
Probe point found: do_sys_open+0
Searching 'filename' variable in context.
Converting variable filename into trace event.
filename type is (null).
Opening /sys/kernel/debug/tracing//README write=0
Found 1 probe_trace_events.
Opening /sys/kernel/debug/tracing//kprobe_events write=1
Writing event: p:perf_bpf_probe/prog _text+2493152 filename=%si:x64
In map_prologue, ntevs=1
mapping[0]=0
libbpf: create map __bpf_stdout__: fd=3
prologue: pass validation
prologue: fast path
libbpf: load bpf program failed: Permission denied
libbpf: -- BEGIN DUMP LOG ---
libbpf: 
0: (79) r3 = *(u64 *)(r1 +104)
1: (b7) r2 = 0
2: (bf) r6 = r1
3: (bf) r1 = r10
4: (07) r1 += -128
5: (b7) r2 = 128
6: (85) call bpf_probe_read_str#45
7: (bf) r1 = r0
8: (07) r1 += -1
9: (67) r1 <<= 32
10: (77) r1 >>= 32
11: (25) if r1 > 0x7f goto pc+11
 R0=inv(id=0) R1=inv(id=0,umax_value=127,var_off=(0x0; 0x7f)) R6=ctx(id=0,off=0,imm=0) R10=fp0
12: (67) r0 <<= 32
13: (77) r0 >>= 32
14: (bf) r4 = r10
15: (07) r4 += -128
16: (bf) r1 = r6
17: (18) r2 = 0xffffa0b74ba91000
19: (18) r3 = 0xffffffff
21: (bf) r5 = r0
22: (85) call bpf_perf_event_output#25
invalid stack type R4 off=-128 access_size=0

libbpf: -- END LOG --
libbpf: Loading the 0th instance of program 'prog=do_sys_open filename' failed
libbpf: failed to load program 'prog=do_sys_open filename'
libbpf: failed to load object 'open.c'
bpf: load objects failed
event syntax error: 'open.c'
                     \___ Kernel verifier blocks program loading

Also:

[root@jouet bpf]# clang -v
clang version 4.0.0 (http://llvm.org/git/clang.git f5be8ba13adc4ba1011a7ccd60c844bd60427c1c) (http://llvm.org/git/llvm.git efca1a37676f4cd276d947658cf90b0fb625abfd)
Target: x86_64-unknown-linux-gnu
Thread model: posix
InstalledDir: /usr/local/bin
Found candidate GCC installation: /usr/lib/gcc/x86_64-redhat-linux/7
Selected GCC installation: /usr/lib/gcc/x86_64-redhat-linux/7
Candidate multilib: .;@m64
Candidate multilib: 32;@m32
Selected multilib: .;@m64
[root@jouet bpf]#

And now I've really attached that bpf.h header I use.

- Arnaldo