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

From: Arnaldo Carvalho de Melo <[email-masked]>
Date: Mon, 13 Nov 2017 11:30:47 -0300

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);
	return 1;
}
[root@jouet bpf]# perf trace -e open,open.c touch /etc/passwd
bpf: builtin compilation failed: -95, try external compiler
     0.000 ( 0.013 ms): touch/14403 open(filename: 0x2ff7ce37, flags: CLOEXEC                             ) ...
     0.013 (         ): __bpf_stdout__:/etc/ld.so.cache..B.................)
     0.015 (         ): perf_bpf_probe:prog:(ffffffffb4260ae0) filename=0x7f7a2ff7ce37)
     0.000 ( 0.021 ms): touch/14403  ... [continued]: open()) = 3
     0.042 ( 0.002 ms): touch/14403 open(filename: 0x30180640, flags: CLOEXEC                             ) ...
     0.044 (         ): __bpf_stdout__:/lib64/libc.so.6.. .......G.........)
     0.045 (         ): perf_bpf_probe:prog:(ffffffffb4260ae0) filename=0x7f7a30180640)
     0.042 ( 0.010 ms): touch/14403  ... [continued]: open()) = 3
     0.301 ( 0.003 ms): touch/14403 open(filename: 0x2fd26c70, flags: CLOEXEC                             ) ...
     0.305 (         ): __bpf_stdout__:/usr/lib/locale/locale-archive......)
     0.306 (         ): perf_bpf_probe:prog:(ffffffffb4260ae0) filename=0x7f7a2fd26c70)
     0.301 ( 0.011 ms): touch/14403  ... [continued]: open()) = 3
     0.360 ( 0.002 ms): touch/14403 open(filename: 0x681f20f3, flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) ...
     0.362 (         ): __bpf_stdout__:/etc/passwd....... .......D.........)
     0.363 (         ): perf_bpf_probe:prog:(ffffffffb4260ae0) filename=0x7ffe681f20f3)
     0.360 ( 0.010 ms): touch/14403  ... [continued]: open()) = 3
[root@jouet bpf]#

That bpf.h will set up the maps, etc, its attached if that may be needed
to help figure this out.

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);
	return 1;
}
[root@jouet bpf]# perf 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

(add -v to see detail)
Run 'perf list' for a list of valid events

 Usage: perf trace [<options>] [<command>]
    or: perf trace [<options>] -- <command> [<options>]
    or: perf trace record [<options>] [<command>]
    or: perf trace record [<options>] -- <command> [<options>]

    -e, --event <event>   event/syscall selector. use 'perf list' to list available events
[root@jouet bpf]#

When running this with -v we get the tools/lib/libbpf.c debug that may
help here:

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) r7 = r10
4: (07) r7 += -128
5: (bf) r1 = r7
6: (b7) r2 = 128
7: (85) call bpf_probe_read_str#45
8: (bf) r8 = r0
9: (67) r8 <<= 32
10: (77) r8 >>= 32
11: (85) call bpf_get_smp_processor_id#8
12: (bf) r1 = r6
13: (18) r2 = 0xffffa0b5958e16c0
15: (bf) r3 = r0
16: (bf) r4 = r7
17: (bf) r5 = r8
18: (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

I tried adding checks for len to try to somehow make sure its all bounds
checked, but couldn't get past that "invalid stack type R4", the problem seems
to be that access_size=0...

Ideas?

- Arnaldo