Issues with bpf_trace_printk

Issues with bpf_trace_printk

[Zvi Effron]

Hello,

I'm having an issue where bpf_trace_printk seems to always print 0 for
values. I'm running the following xdp program:


#include <uapi/linux/bpf.h>

static int (*bpf_trace_printk)(const char *fmt, int fmt_size, ...) =
(void *) BPF_FUNC_trace_printk;

int xdp(struct xdp_md *ctx) {
    char format_string[] = "Data start: %x\tData end: %x\n";
    bpf_trace_printk(format_string, sizeof(format_string), ctx->data,
ctx->data_end);

    {
        char format_string[] = "Constant: %x\n";
        bpf_trace_printk(format_string, sizeof(format_string), 1);
    }

    if (ctx->data == 0) {
        char format_string[] = "Data starts at offset 0";
        bpf_trace_printk(format_string, sizeof(format_string));
    }
    if (ctx->data_end == 0) {
        char format_string[] = "Data ends at offset 0";
        bpf_trace_printk(format_string, sizeof(format_string));
    }
    return XDP_PASS;
}

char __attribute__((section("license"), used)) license[] = "GPL";


and I get the following output in /sys/kernel/debug/tracing/trace_pipe


            sshd-4824  [000] ..s1 67372.673714: : Data start: 0 Data end: 0
            sshd-4824  [000] ..s1 67372.673720: : Constant: 0
          <idle>-0     [000] ..s. 67372.675062: : Data start: 0 Data end: 0
          <idle>-0     [000] .Ns. 67372.675090: : Constant: 0
          <idle>-0     [000] .Ns. 67372.675116: : Data start: 0 Data end: 0
          <idle>-0     [000] .Ns. 67372.675117: : Constant: 0
          <idle>-0     [000] .Ns. 67372.675129: : Data start: 0 Data end: 0
          <idle>-0     [000] .Ns. 67372.675130: : Constant: 0
          <idle>-0     [000] .Ns. 67372.675136: : Data start: 0 Data end: 0
          <idle>-0     [000] .Ns. 67372.675137: : Constant: 0
          <idle>-0     [000] .Ns. 67372.675142: : Data start: 0 Data end: 0
          <idle>-0     [000] .Ns. 67372.675143: : Constant: 0
              ip-6458  [000] ..s. 67372.676083: : Data start: 0 Data end: 0
              ip-6458  [000] ..s. 67372.676084: : Constant: 0
              ip-6458  [000] ..s. 67372.676093: : Data start: 0 Data end: 0
              ip-6458  [000] ..s. 67372.676094: : Constant: 0


It looks like ctx->data and ctx->data_end are not 0, because the calls
to bpf_trace_printk in those ifs aren't being called, and the constant
is definitely not 0.

What might I be missing or doing incorrectly?

Thank you!
--Zvi

Re: Issues with bpf_trace_printk

[Daniel Borkmann]

On 08/28/2017 07:20 PM, Zvi Effron wrote:
> Hello,
>
> I'm having an issue where bpf_trace_printk seems to always print 0 for
> values. I'm running the following xdp program:
>
>
> #include <uapi/linux/bpf.h>
>
> static int (*bpf_trace_printk)(const char *fmt, int fmt_size, ...) =
> (void *) BPF_FUNC_trace_printk;
>
> int xdp(struct xdp_md *ctx) {
>      char format_string[] = "Data start: %x\tData end: %x\n";
>      bpf_trace_printk(format_string, sizeof(format_string), ctx->data,
> ctx->data_end);
>
>      {
>          char format_string[] = "Constant: %x\n";
>          bpf_trace_printk(format_string, sizeof(format_string), 1);
>      }
>
>      if (ctx->data == 0) {
>          char format_string[] = "Data starts at offset 0";
>          bpf_trace_printk(format_string, sizeof(format_string));
>      }
>      if (ctx->data_end == 0) {
>          char format_string[] = "Data ends at offset 0";
>          bpf_trace_printk(format_string, sizeof(format_string));
>      }
>      return XDP_PASS;
> }
>
> char __attribute__((section("license"), used)) license[] = "GPL";
>
>
> and I get the following output in /sys/kernel/debug/tracing/trace_pipe
>
>
>              sshd-4824  [000] ..s1 67372.673714: : Data start: 0 Data end: 0
>              sshd-4824  [000] ..s1 67372.673720: : Constant: 0
>            <idle>-0     [000] ..s. 67372.675062: : Data start: 0 Data end: 0
>            <idle>-0     [000] .Ns. 67372.675090: : Constant: 0
>            <idle>-0     [000] .Ns. 67372.675116: : Data start: 0 Data end: 0
>            <idle>-0     [000] .Ns. 67372.675117: : Constant: 0
>            <idle>-0     [000] .Ns. 67372.675129: : Data start: 0 Data end: 0
>            <idle>-0     [000] .Ns. 67372.675130: : Constant: 0
>            <idle>-0     [000] .Ns. 67372.675136: : Data start: 0 Data end: 0
>            <idle>-0     [000] .Ns. 67372.675137: : Constant: 0
>            <idle>-0     [000] .Ns. 67372.675142: : Data start: 0 Data end: 0
>            <idle>-0     [000] .Ns. 67372.675143: : Constant: 0
>                ip-6458  [000] ..s. 67372.676083: : Data start: 0 Data end: 0
>                ip-6458  [000] ..s. 67372.676084: : Constant: 0
>                ip-6458  [000] ..s. 67372.676093: : Data start: 0 Data end: 0
>                ip-6458  [000] ..s. 67372.676094: : Constant: 0
>
>
> It looks like ctx->data and ctx->data_end are not 0, because the calls
> to bpf_trace_printk in those ifs aren't being called, and the constant
> is definitely not 0.
>
> What might I be missing or doing incorrectly?

Are you on 32bit? Could you dump the verifier output?

Thanks,
Daniel

Re: Issues with bpf_trace_printk

[Zvi Effron]

64bit kernel (4.12.8-300.fc26.x86_64) running in a VM.

[root@localhost scratch]# ip link set dev eth0 xdp object
/root/xdp/xdp_test_kern.o section .text verbose

Prog section '.text' loaded (5)!
 - Type:         6
 - Instructions: 63 (0 over limit)
 - License:      GPL

Verifier analysis:

0: (bf) r6 = r1
1: (b7) r1 = 0
2: (73) *(u8 *)(r10 -4) = r1
3: (b7) r1 = 175645984
4: (63) *(u32 *)(r10 -8) = r1
5: (18) r1 = 0x3a646e6520617461
7: (7b) *(u64 *)(r10 -16) = r1
8: (18) r1 = 0x44097825203a7472
10: (7b) *(u64 *)(r10 -24) = r1
11: (18) r7 = 0x6174732061746144
13: (7b) *(u64 *)(r10 -32) = r7
14: (61) r4 = *(u32 *)(r6 +4)
15: (61) r3 = *(u32 *)(r6 +0)
16: (bf) r1 = r10
17: (07) r1 += -32
18: (b7) r2 = 29
19: (85) call bpf_trace_printk#6
20: (b7) r1 = 10
21: (6b) *(u16 *)(r10 -52) = r1
22: (b7) r1 = 2015699002
23: (63) *(u32 *)(r10 -56) = r1
24: (18) r1 = 0x746e6174736e6f43
26: (7b) *(u64 *)(r10 -64) = r1
27: (bf) r1 = r10
28: (07) r1 += -64
29: (b7) r2 = 14
30: (b7) r3 = 1
31: (85) call bpf_trace_printk#6
32: (61) r1 = *(u32 *)(r6 +0)
33: (55) if r1 != 0x0 goto pc+11
 R0=inv R1=pkt(id=0,off=0,r=0),min_value=0,max_value=0 R6=ctx
R7=imm7022364301888610628 R10=fp
34: (18) r1 = 0x30207465736666
36: (7b) *(u64 *)(r10 -48) = r1
37: (18) r1 = 0x6f20746120737472
39: (7b) *(u64 *)(r10 -56) = r1
40: (7b) *(u64 *)(r10 -64) = r7
41: (bf) r1 = r10
42: (07) r1 += -64
43: (b7) r2 = 24
44: (85) call bpf_trace_printk#6
45: (61) r1 = *(u32 *)(r6 +4)
46: (55) if r1 != 0x0 goto pc+14
 R0=inv R1=pkt_end,min_value=0,max_value=0 R6=ctx
R7=imm7022364301888610628 R10=fp
47: (b7) r1 = 48
48: (6b) *(u16 *)(r10 -44) = r1
49: (b7) r1 = 544499059
50: (63) *(u32 *)(r10 -48) = r1
51: (18) r1 = 0x66666f2074612073
53: (7b) *(u64 *)(r10 -56) = r1
54: (18) r1 = 0x646e652061746144
56: (7b) *(u64 *)(r10 -64) = r1
57: (bf) r1 = r10
58: (07) r1 += -64
59: (b7) r2 = 22
60: (85) call bpf_trace_printk#6
61: (b7) r0 = 2
62: (95) exit

from 46 to 61: safe

from 33 to 45: R0=inv R1=pkt(id=0,off=0,r=0) R6=ctx
R7=imm7022364301888610628 R10=fp
45: (61) r1 = *(u32 *)(r6 +4)
46: (55) if r1 != 0x0 goto pc+14
 R0=inv R1=pkt_end,min_value=0,max_value=0 R6=ctx
R7=imm7022364301888610628 R10=fp
47: (b7) r1 = 48
48: (6b) *(u16 *)(r10 -44) = r1
49: (b7) r1 = 544499059
50: (63) *(u32 *)(r10 -48) = r1
51: (18) r1 = 0x66666f2074612073
53: (7b) *(u64 *)(r10 -56) = r1
54: (18) r1 = 0x646e652061746144
56: (7b) *(u64 *)(r10 -64) = r1
57: (bf) r1 = r10
58: (07) r1 += -64
59: (b7) r2 = 22
60: (85) call bpf_trace_printk#6
61: (b7) r0 = 2
62: (95) exit

from 46 to 61: R0=inv R1=pkt_end R6=ctx R7=imm7022364301888610628 R10=fp
61: (b7) r0 = 2
62: (95) exit
processed 74 insns

Thanks!
--Zvi

On Mon, Aug 28, 2017 at 11:26 AM, Daniel Borkmann <daniel@iogearbox.net> wrote:
> On 08/28/2017 07:20 PM, Zvi Effron wrote:
>>
>> Hello,
>>
>> I'm having an issue where bpf_trace_printk seems to always print 0 for
>> values. I'm running the following xdp program:
>>
>>
>> #include <uapi/linux/bpf.h>
>>
>> static int (*bpf_trace_printk)(const char *fmt, int fmt_size, ...) =
>> (void *) BPF_FUNC_trace_printk;
>>
>> int xdp(struct xdp_md *ctx) {
>>      char format_string[] = "Data start: %x\tData end: %x\n";
>>      bpf_trace_printk(format_string, sizeof(format_string), ctx->data,
>> ctx->data_end);
>>
>>      {
>>          char format_string[] = "Constant: %x\n";
>>          bpf_trace_printk(format_string, sizeof(format_string), 1);
>>      }
>>
>>      if (ctx->data == 0) {
>>          char format_string[] = "Data starts at offset 0";
>>          bpf_trace_printk(format_string, sizeof(format_string));
>>      }
>>      if (ctx->data_end == 0) {
>>          char format_string[] = "Data ends at offset 0";
>>          bpf_trace_printk(format_string, sizeof(format_string));
>>      }
>>      return XDP_PASS;
>> }
>>
>> char __attribute__((section("license"), used)) license[] = "GPL";
>>
>>
>> and I get the following output in /sys/kernel/debug/tracing/trace_pipe
>>
>>
>>              sshd-4824  [000] ..s1 67372.673714: : Data start: 0 Data end:
>> 0
>>              sshd-4824  [000] ..s1 67372.673720: : Constant: 0
>>            <idle>-0     [000] ..s. 67372.675062: : Data start: 0 Data end:
>> 0
>>            <idle>-0     [000] .Ns. 67372.675090: : Constant: 0
>>            <idle>-0     [000] .Ns. 67372.675116: : Data start: 0 Data end:
>> 0
>>            <idle>-0     [000] .Ns. 67372.675117: : Constant: 0
>>            <idle>-0     [000] .Ns. 67372.675129: : Data start: 0 Data end:
>> 0
>>            <idle>-0     [000] .Ns. 67372.675130: : Constant: 0
>>            <idle>-0     [000] .Ns. 67372.675136: : Data start: 0 Data end:
>> 0
>>            <idle>-0     [000] .Ns. 67372.675137: : Constant: 0
>>            <idle>-0     [000] .Ns. 67372.675142: : Data start: 0 Data end:
>> 0
>>            <idle>-0     [000] .Ns. 67372.675143: : Constant: 0
>>                ip-6458  [000] ..s. 67372.676083: : Data start: 0 Data end:
>> 0
>>                ip-6458  [000] ..s. 67372.676084: : Constant: 0
>>                ip-6458  [000] ..s. 67372.676093: : Data start: 0 Data end:
>> 0
>>                ip-6458  [000] ..s. 67372.676094: : Constant: 0
>>
>>
>> It looks like ctx->data and ctx->data_end are not 0, because the calls
>> to bpf_trace_printk in those ifs aren't being called, and the constant
>> is definitely not 0.
>>
>> What might I be missing or doing incorrectly?
>
>
> Are you on 32bit? Could you dump the verifier output?
>
> Thanks,
> Daniel

Re: Issues with bpf_trace_printk

[Y Song]

bpf program itself is okay.
I replaced linux:samples/bpf/xdp1_kern.c with this program and the
bpf_trace_printk works fine.
It could be some setup issue. But in any case, data start and data end
are suspicious.
It would be good you list all steps which can reproduce the issue.

On Mon, Aug 28, 2017 at 10:20 AM, Zvi Effron <zeffron@riotgames.com> wrote:
> Hello,
>
> I'm having an issue where bpf_trace_printk seems to always print 0 for
> values. I'm running the following xdp program:
>
>
> #include <uapi/linux/bpf.h>
>
> static int (*bpf_trace_printk)(const char *fmt, int fmt_size, ...) =
> (void *) BPF_FUNC_trace_printk;
>
> int xdp(struct xdp_md *ctx) {
>     char format_string[] = "Data start: %x\tData end: %x\n";
>     bpf_trace_printk(format_string, sizeof(format_string), ctx->data,
> ctx->data_end);
>
>     {
>         char format_string[] = "Constant: %x\n";
>         bpf_trace_printk(format_string, sizeof(format_string), 1);
>     }
>
>     if (ctx->data == 0) {
>         char format_string[] = "Data starts at offset 0";
>         bpf_trace_printk(format_string, sizeof(format_string));
>     }
>     if (ctx->data_end == 0) {
>         char format_string[] = "Data ends at offset 0";
>         bpf_trace_printk(format_string, sizeof(format_string));
>     }
>     return XDP_PASS;
> }
>
> char __attribute__((section("license"), used)) license[] = "GPL";
>
>
> and I get the following output in /sys/kernel/debug/tracing/trace_pipe
>
>
>             sshd-4824  [000] ..s1 67372.673714: : Data start: 0 Data end: 0
>             sshd-4824  [000] ..s1 67372.673720: : Constant: 0
>           <idle>-0     [000] ..s. 67372.675062: : Data start: 0 Data end: 0
>           <idle>-0     [000] .Ns. 67372.675090: : Constant: 0
>           <idle>-0     [000] .Ns. 67372.675116: : Data start: 0 Data end: 0
>           <idle>-0     [000] .Ns. 67372.675117: : Constant: 0
>           <idle>-0     [000] .Ns. 67372.675129: : Data start: 0 Data end: 0
>           <idle>-0     [000] .Ns. 67372.675130: : Constant: 0
>           <idle>-0     [000] .Ns. 67372.675136: : Data start: 0 Data end: 0
>           <idle>-0     [000] .Ns. 67372.675137: : Constant: 0
>           <idle>-0     [000] .Ns. 67372.675142: : Data start: 0 Data end: 0
>           <idle>-0     [000] .Ns. 67372.675143: : Constant: 0
>               ip-6458  [000] ..s. 67372.676083: : Data start: 0 Data end: 0
>               ip-6458  [000] ..s. 67372.676084: : Constant: 0
>               ip-6458  [000] ..s. 67372.676093: : Data start: 0 Data end: 0
>               ip-6458  [000] ..s. 67372.676094: : Constant: 0
>
>
> It looks like ctx->data and ctx->data_end are not 0, because the calls
> to bpf_trace_printk in those ifs aren't being called, and the constant
> is definitely not 0.
>
> What might I be missing or doing incorrectly?
>
> Thank you!
> --Zvi

Re: Issues with bpf_trace_printk

[Zvi Effron]

Full reproduction instructions:

1) Install Fedora 26 server. I chose all of the default options,
except I chose to install latest packages from the network. Otherwise,
just run a dnf update after install. I installed into a VM running on
HyperV
2) Install clang, llvm, and kernel-devel:
    dnf install -y clang llvm kernel-devel
3) Copy the program to xdp_test_kern.c
4) Compile the program into an elf object file:
    clang -S -O2 -Wall -Werror -nostdinc -isystem $(clang
-print-file-name=include) -I /lib/modules/$(uname
-r)/build/arch/x86/include  -I /lib/modules/$(uname
-r)/build/arch/x86/include/generated/uapi  -I /lib/modules/$(uname
-r)/build/arch/x86/include/generated  -I /lib/modules/$(uname
-r)/build/include  -I /lib/modules/$(uname
-r)/build/arch/x86/include/uapi  -I /lib/modules/$(uname
-r)/build/include/uapi  -I /lib/modules/$(uname
-r)/build/include/generated/uapi -include  /lib/modules/$(uname
-r)/build/include/linux/kconfig.h -D __KERNEL__ -c -emit-llvm -o
xdp_test_kern.ll xdp_test_kern.c
    llc -march bpf -filetype obj -o xdp_test_kern.o xdp_test_kern.ll
5) Attach the program to eth0:
    ip link set dev eth0 xdp object xdp_test_kern.o section .text verbose
6) Notice only 0s being printed for data in /sys/kernel/debug/tracing/trace_pipe

As near as I can tell, the driver being used for eth0 is hv_netvsc, in
case it's an issue with the driver.

Thanks!
--Zvi

On Mon, Aug 28, 2017 at 2:16 PM, Y Song <ys114321@gmail.com> wrote:
> bpf program itself is okay.
> I replaced linux:samples/bpf/xdp1_kern.c with this program and the
> bpf_trace_printk works fine.
> It could be some setup issue. But in any case, data start and data end
> are suspicious.
> It would be good you list all steps which can reproduce the issue.
>
> On Mon, Aug 28, 2017 at 10:20 AM, Zvi Effron <zeffron@riotgames.com> wrote:
>> Hello,
>>
>> I'm having an issue where bpf_trace_printk seems to always print 0 for
>> values. I'm running the following xdp program:
>>
>>
>> #include <uapi/linux/bpf.h>
>>
>> static int (*bpf_trace_printk)(const char *fmt, int fmt_size, ...) =
>> (void *) BPF_FUNC_trace_printk;
>>
>> int xdp(struct xdp_md *ctx) {
>>     char format_string[] = "Data start: %x\tData end: %x\n";
>>     bpf_trace_printk(format_string, sizeof(format_string), ctx->data,
>> ctx->data_end);
>>
>>     {
>>         char format_string[] = "Constant: %x\n";
>>         bpf_trace_printk(format_string, sizeof(format_string), 1);
>>     }
>>
>>     if (ctx->data == 0) {
>>         char format_string[] = "Data starts at offset 0";
>>         bpf_trace_printk(format_string, sizeof(format_string));
>>     }
>>     if (ctx->data_end == 0) {
>>         char format_string[] = "Data ends at offset 0";
>>         bpf_trace_printk(format_string, sizeof(format_string));
>>     }
>>     return XDP_PASS;
>> }
>>
>> char __attribute__((section("license"), used)) license[] = "GPL";
>>
>>
>> and I get the following output in /sys/kernel/debug/tracing/trace_pipe
>>
>>
>>             sshd-4824  [000] ..s1 67372.673714: : Data start: 0 Data end: 0
>>             sshd-4824  [000] ..s1 67372.673720: : Constant: 0
>>           <idle>-0     [000] ..s. 67372.675062: : Data start: 0 Data end: 0
>>           <idle>-0     [000] .Ns. 67372.675090: : Constant: 0
>>           <idle>-0     [000] .Ns. 67372.675116: : Data start: 0 Data end: 0
>>           <idle>-0     [000] .Ns. 67372.675117: : Constant: 0
>>           <idle>-0     [000] .Ns. 67372.675129: : Data start: 0 Data end: 0
>>           <idle>-0     [000] .Ns. 67372.675130: : Constant: 0
>>           <idle>-0     [000] .Ns. 67372.675136: : Data start: 0 Data end: 0
>>           <idle>-0     [000] .Ns. 67372.675137: : Constant: 0
>>           <idle>-0     [000] .Ns. 67372.675142: : Data start: 0 Data end: 0
>>           <idle>-0     [000] .Ns. 67372.675143: : Constant: 0
>>               ip-6458  [000] ..s. 67372.676083: : Data start: 0 Data end: 0
>>               ip-6458  [000] ..s. 67372.676084: : Constant: 0
>>               ip-6458  [000] ..s. 67372.676093: : Data start: 0 Data end: 0
>>               ip-6458  [000] ..s. 67372.676094: : Constant: 0
>>
>>
>> It looks like ctx->data and ctx->data_end are not 0, because the calls
>> to bpf_trace_printk in those ifs aren't being called, and the constant
>> is definitely not 0.
>>
>> What might I be missing or doing incorrectly?
>>
>> Thank you!
>> --Zvi

Re: Issues with bpf_trace_printk

[Y Song]

I tried on my FC26 VM. I actually got permission denied.
I tried to attach the main interface enp0s3 (acting as eth0).

The kernel is 4.11. I think generic xdp support is not there.
Otherwise people can confirm?
The VM interface enp0s3 (or eth0) may not have driver support for XDP.

On Mon, Aug 28, 2017 at 3:12 PM, Zvi Effron <zeffron@riotgames.com> wrote:
> Full reproduction instructions:
>
> 1) Install Fedora 26 server. I chose all of the default options,
> except I chose to install latest packages from the network. Otherwise,
> just run a dnf update after install. I installed into a VM running on
> HyperV
> 2) Install clang, llvm, and kernel-devel:
>     dnf install -y clang llvm kernel-devel
> 3) Copy the program to xdp_test_kern.c
> 4) Compile the program into an elf object file:
>     clang -S -O2 -Wall -Werror -nostdinc -isystem $(clang
> -print-file-name=include) -I /lib/modules/$(uname
> -r)/build/arch/x86/include  -I /lib/modules/$(uname
> -r)/build/arch/x86/include/generated/uapi  -I /lib/modules/$(uname
> -r)/build/arch/x86/include/generated  -I /lib/modules/$(uname
> -r)/build/include  -I /lib/modules/$(uname
> -r)/build/arch/x86/include/uapi  -I /lib/modules/$(uname
> -r)/build/include/uapi  -I /lib/modules/$(uname
> -r)/build/include/generated/uapi -include  /lib/modules/$(uname
> -r)/build/include/linux/kconfig.h -D __KERNEL__ -c -emit-llvm -o
> xdp_test_kern.ll xdp_test_kern.c
>     llc -march bpf -filetype obj -o xdp_test_kern.o xdp_test_kern.ll
> 5) Attach the program to eth0:
>     ip link set dev eth0 xdp object xdp_test_kern.o section .text verbose
> 6) Notice only 0s being printed for data in /sys/kernel/debug/tracing/trace_pipe
>
> As near as I can tell, the driver being used for eth0 is hv_netvsc, in
> case it's an issue with the driver.
>
> Thanks!
> --Zvi
>
> On Mon, Aug 28, 2017 at 2:16 PM, Y Song <ys114321@gmail.com> wrote:
>> bpf program itself is okay.
>> I replaced linux:samples/bpf/xdp1_kern.c with this program and the
>> bpf_trace_printk works fine.
>> It could be some setup issue. But in any case, data start and data end
>> are suspicious.
>> It would be good you list all steps which can reproduce the issue.
>>
>> On Mon, Aug 28, 2017 at 10:20 AM, Zvi Effron <zeffron@riotgames.com> wrote:
>>> Hello,
>>>
>>> I'm having an issue where bpf_trace_printk seems to always print 0 for
>>> values. I'm running the following xdp program:
>>>
>>>
>>> #include <uapi/linux/bpf.h>
>>>
>>> static int (*bpf_trace_printk)(const char *fmt, int fmt_size, ...) =
>>> (void *) BPF_FUNC_trace_printk;
>>>
>>> int xdp(struct xdp_md *ctx) {
>>>     char format_string[] = "Data start: %x\tData end: %x\n";
>>>     bpf_trace_printk(format_string, sizeof(format_string), ctx->data,
>>> ctx->data_end);
>>>
>>>     {
>>>         char format_string[] = "Constant: %x\n";
>>>         bpf_trace_printk(format_string, sizeof(format_string), 1);
>>>     }
>>>
>>>     if (ctx->data == 0) {
>>>         char format_string[] = "Data starts at offset 0";
>>>         bpf_trace_printk(format_string, sizeof(format_string));
>>>     }
>>>     if (ctx->data_end == 0) {
>>>         char format_string[] = "Data ends at offset 0";
>>>         bpf_trace_printk(format_string, sizeof(format_string));
>>>     }
>>>     return XDP_PASS;
>>> }
>>>
>>> char __attribute__((section("license"), used)) license[] = "GPL";
>>>
>>>
>>> and I get the following output in /sys/kernel/debug/tracing/trace_pipe
>>>
>>>
>>>             sshd-4824  [000] ..s1 67372.673714: : Data start: 0 Data end: 0
>>>             sshd-4824  [000] ..s1 67372.673720: : Constant: 0
>>>           <idle>-0     [000] ..s. 67372.675062: : Data start: 0 Data end: 0
>>>           <idle>-0     [000] .Ns. 67372.675090: : Constant: 0
>>>           <idle>-0     [000] .Ns. 67372.675116: : Data start: 0 Data end: 0
>>>           <idle>-0     [000] .Ns. 67372.675117: : Constant: 0
>>>           <idle>-0     [000] .Ns. 67372.675129: : Data start: 0 Data end: 0
>>>           <idle>-0     [000] .Ns. 67372.675130: : Constant: 0
>>>           <idle>-0     [000] .Ns. 67372.675136: : Data start: 0 Data end: 0
>>>           <idle>-0     [000] .Ns. 67372.675137: : Constant: 0
>>>           <idle>-0     [000] .Ns. 67372.675142: : Data start: 0 Data end: 0
>>>           <idle>-0     [000] .Ns. 67372.675143: : Constant: 0
>>>               ip-6458  [000] ..s. 67372.676083: : Data start: 0 Data end: 0
>>>               ip-6458  [000] ..s. 67372.676084: : Constant: 0
>>>               ip-6458  [000] ..s. 67372.676093: : Data start: 0 Data end: 0
>>>               ip-6458  [000] ..s. 67372.676094: : Constant: 0
>>>
>>>
>>> It looks like ctx->data and ctx->data_end are not 0, because the calls
>>> to bpf_trace_printk in those ifs aren't being called, and the constant
>>> is definitely not 0.
>>>
>>> What might I be missing or doing incorrectly?
>>>
>>> Thank you!
>>> --Zvi

Re: Issues with bpf_trace_printk

[Zvi Effron]

Generic XDP driver was introduced in the 4.12 kernel.
https://kernelnewbies.org/Linux_4.12#head-9f96b5e8262772d5e1908bf335fd25f4c3eec15a
If you run dnf update, it should pull down the 4.12 kernel on Fedora 26.

--Zvi

On Mon, Aug 28, 2017 at 10:39 PM, Y Song <ys114321@gmail.com> wrote:
> I tried on my FC26 VM. I actually got permission denied.
> I tried to attach the main interface enp0s3 (acting as eth0).
>
> The kernel is 4.11. I think generic xdp support is not there.
> Otherwise people can confirm?
> The VM interface enp0s3 (or eth0) may not have driver support for XDP.
>
> On Mon, Aug 28, 2017 at 3:12 PM, Zvi Effron <zeffron@riotgames.com> wrote:
>> Full reproduction instructions:
>>
>> 1) Install Fedora 26 server. I chose all of the default options,
>> except I chose to install latest packages from the network. Otherwise,
>> just run a dnf update after install. I installed into a VM running on
>> HyperV
>> 2) Install clang, llvm, and kernel-devel:
>>     dnf install -y clang llvm kernel-devel
>> 3) Copy the program to xdp_test_kern.c
>> 4) Compile the program into an elf object file:
>>     clang -S -O2 -Wall -Werror -nostdinc -isystem $(clang
>> -print-file-name=include) -I /lib/modules/$(uname
>> -r)/build/arch/x86/include  -I /lib/modules/$(uname
>> -r)/build/arch/x86/include/generated/uapi  -I /lib/modules/$(uname
>> -r)/build/arch/x86/include/generated  -I /lib/modules/$(uname
>> -r)/build/include  -I /lib/modules/$(uname
>> -r)/build/arch/x86/include/uapi  -I /lib/modules/$(uname
>> -r)/build/include/uapi  -I /lib/modules/$(uname
>> -r)/build/include/generated/uapi -include  /lib/modules/$(uname
>> -r)/build/include/linux/kconfig.h -D __KERNEL__ -c -emit-llvm -o
>> xdp_test_kern.ll xdp_test_kern.c
>>     llc -march bpf -filetype obj -o xdp_test_kern.o xdp_test_kern.ll
>> 5) Attach the program to eth0:
>>     ip link set dev eth0 xdp object xdp_test_kern.o section .text verbose
>> 6) Notice only 0s being printed for data in /sys/kernel/debug/tracing/trace_pipe
>>
>> As near as I can tell, the driver being used for eth0 is hv_netvsc, in
>> case it's an issue with the driver.
>>
>> Thanks!
>> --Zvi
>>
>> On Mon, Aug 28, 2017 at 2:16 PM, Y Song <ys114321@gmail.com> wrote:
>>> bpf program itself is okay.
>>> I replaced linux:samples/bpf/xdp1_kern.c with this program and the
>>> bpf_trace_printk works fine.
>>> It could be some setup issue. But in any case, data start and data end
>>> are suspicious.
>>> It would be good you list all steps which can reproduce the issue.
>>>
>>> On Mon, Aug 28, 2017 at 10:20 AM, Zvi Effron <zeffron@riotgames.com> wrote:
>>>> Hello,
>>>>
>>>> I'm having an issue where bpf_trace_printk seems to always print 0 for
>>>> values. I'm running the following xdp program:
>>>>
>>>>
>>>> #include <uapi/linux/bpf.h>
>>>>
>>>> static int (*bpf_trace_printk)(const char *fmt, int fmt_size, ...) =
>>>> (void *) BPF_FUNC_trace_printk;
>>>>
>>>> int xdp(struct xdp_md *ctx) {
>>>>     char format_string[] = "Data start: %x\tData end: %x\n";
>>>>     bpf_trace_printk(format_string, sizeof(format_string), ctx->data,
>>>> ctx->data_end);
>>>>
>>>>     {
>>>>         char format_string[] = "Constant: %x\n";
>>>>         bpf_trace_printk(format_string, sizeof(format_string), 1);
>>>>     }
>>>>
>>>>     if (ctx->data == 0) {
>>>>         char format_string[] = "Data starts at offset 0";
>>>>         bpf_trace_printk(format_string, sizeof(format_string));
>>>>     }
>>>>     if (ctx->data_end == 0) {
>>>>         char format_string[] = "Data ends at offset 0";
>>>>         bpf_trace_printk(format_string, sizeof(format_string));
>>>>     }
>>>>     return XDP_PASS;
>>>> }
>>>>
>>>> char __attribute__((section("license"), used)) license[] = "GPL";
>>>>
>>>>
>>>> and I get the following output in /sys/kernel/debug/tracing/trace_pipe
>>>>
>>>>
>>>>             sshd-4824  [000] ..s1 67372.673714: : Data start: 0 Data end: 0
>>>>             sshd-4824  [000] ..s1 67372.673720: : Constant: 0
>>>>           <idle>-0     [000] ..s. 67372.675062: : Data start: 0 Data end: 0
>>>>           <idle>-0     [000] .Ns. 67372.675090: : Constant: 0
>>>>           <idle>-0     [000] .Ns. 67372.675116: : Data start: 0 Data end: 0
>>>>           <idle>-0     [000] .Ns. 67372.675117: : Constant: 0
>>>>           <idle>-0     [000] .Ns. 67372.675129: : Data start: 0 Data end: 0
>>>>           <idle>-0     [000] .Ns. 67372.675130: : Constant: 0
>>>>           <idle>-0     [000] .Ns. 67372.675136: : Data start: 0 Data end: 0
>>>>           <idle>-0     [000] .Ns. 67372.675137: : Constant: 0
>>>>           <idle>-0     [000] .Ns. 67372.675142: : Data start: 0 Data end: 0
>>>>           <idle>-0     [000] .Ns. 67372.675143: : Constant: 0
>>>>               ip-6458  [000] ..s. 67372.676083: : Data start: 0 Data end: 0
>>>>               ip-6458  [000] ..s. 67372.676084: : Constant: 0
>>>>               ip-6458  [000] ..s. 67372.676093: : Data start: 0 Data end: 0
>>>>               ip-6458  [000] ..s. 67372.676094: : Constant: 0
>>>>
>>>>
>>>> It looks like ctx->data and ctx->data_end are not 0, because the calls
>>>> to bpf_trace_printk in those ifs aren't being called, and the constant
>>>> is definitely not 0.
>>>>
>>>> What might I be missing or doing incorrectly?
>>>>
>>>> Thank you!
>>>> --Zvi

Re: Issues with bpf_trace_printk

[Y Song]

I tried the test with the following:
   . fc25 env but booted with latest net-next kernel (my developer env)
   . clang/llvm 5.0 (build from source)
   . latest iproute2 (build from source)
and it works fine.

I suggest you migrate to the latest (or above) environment and it should work.
Otherwise, you could bisect and debug to see which component may have issues.

On Mon, Aug 28, 2017 at 10:53 PM, Zvi Effron <zeffron@riotgames.com> wrote:
> Generic XDP driver was introduced in the 4.12 kernel.
> https://kernelnewbies.org/Linux_4.12#head-9f96b5e8262772d5e1908bf335fd25f4c3eec15a
> If you run dnf update, it should pull down the 4.12 kernel on Fedora 26.
>
> --Zvi
>
> On Mon, Aug 28, 2017 at 10:39 PM, Y Song <ys114321@gmail.com> wrote:
>> I tried on my FC26 VM. I actually got permission denied.
>> I tried to attach the main interface enp0s3 (acting as eth0).
>>
>> The kernel is 4.11. I think generic xdp support is not there.
>> Otherwise people can confirm?
>> The VM interface enp0s3 (or eth0) may not have driver support for XDP.
>>
>> On Mon, Aug 28, 2017 at 3:12 PM, Zvi Effron <zeffron@riotgames.com> wrote:
>>> Full reproduction instructions:
>>>
>>> 1) Install Fedora 26 server. I chose all of the default options,
>>> except I chose to install latest packages from the network. Otherwise,
>>> just run a dnf update after install. I installed into a VM running on
>>> HyperV
>>> 2) Install clang, llvm, and kernel-devel:
>>>     dnf install -y clang llvm kernel-devel
>>> 3) Copy the program to xdp_test_kern.c
>>> 4) Compile the program into an elf object file:
>>>     clang -S -O2 -Wall -Werror -nostdinc -isystem $(clang
>>> -print-file-name=include) -I /lib/modules/$(uname
>>> -r)/build/arch/x86/include  -I /lib/modules/$(uname
>>> -r)/build/arch/x86/include/generated/uapi  -I /lib/modules/$(uname
>>> -r)/build/arch/x86/include/generated  -I /lib/modules/$(uname
>>> -r)/build/include  -I /lib/modules/$(uname
>>> -r)/build/arch/x86/include/uapi  -I /lib/modules/$(uname
>>> -r)/build/include/uapi  -I /lib/modules/$(uname
>>> -r)/build/include/generated/uapi -include  /lib/modules/$(uname
>>> -r)/build/include/linux/kconfig.h -D __KERNEL__ -c -emit-llvm -o
>>> xdp_test_kern.ll xdp_test_kern.c
>>>     llc -march bpf -filetype obj -o xdp_test_kern.o xdp_test_kern.ll
>>> 5) Attach the program to eth0:
>>>     ip link set dev eth0 xdp object xdp_test_kern.o section .text verbose
>>> 6) Notice only 0s being printed for data in /sys/kernel/debug/tracing/trace_pipe
>>>
>>> As near as I can tell, the driver being used for eth0 is hv_netvsc, in
>>> case it's an issue with the driver.
>>>
>>> Thanks!
>>> --Zvi
>>>
>>> On Mon, Aug 28, 2017 at 2:16 PM, Y Song <ys114321@gmail.com> wrote:
>>>> bpf program itself is okay.
>>>> I replaced linux:samples/bpf/xdp1_kern.c with this program and the
>>>> bpf_trace_printk works fine.
>>>> It could be some setup issue. But in any case, data start and data end
>>>> are suspicious.
>>>> It would be good you list all steps which can reproduce the issue.
>>>>
>>>> On Mon, Aug 28, 2017 at 10:20 AM, Zvi Effron <zeffron@riotgames.com> wrote:
>>>>> Hello,
>>>>>
>>>>> I'm having an issue where bpf_trace_printk seems to always print 0 for
>>>>> values. I'm running the following xdp program:
>>>>>
>>>>>
>>>>> #include <uapi/linux/bpf.h>
>>>>>
>>>>> static int (*bpf_trace_printk)(const char *fmt, int fmt_size, ...) =
>>>>> (void *) BPF_FUNC_trace_printk;
>>>>>
>>>>> int xdp(struct xdp_md *ctx) {
>>>>>     char format_string[] = "Data start: %x\tData end: %x\n";
>>>>>     bpf_trace_printk(format_string, sizeof(format_string), ctx->data,
>>>>> ctx->data_end);
>>>>>
>>>>>     {
>>>>>         char format_string[] = "Constant: %x\n";
>>>>>         bpf_trace_printk(format_string, sizeof(format_string), 1);
>>>>>     }
>>>>>
>>>>>     if (ctx->data == 0) {
>>>>>         char format_string[] = "Data starts at offset 0";
>>>>>         bpf_trace_printk(format_string, sizeof(format_string));
>>>>>     }
>>>>>     if (ctx->data_end == 0) {
>>>>>         char format_string[] = "Data ends at offset 0";
>>>>>         bpf_trace_printk(format_string, sizeof(format_string));
>>>>>     }
>>>>>     return XDP_PASS;
>>>>> }
>>>>>
>>>>> char __attribute__((section("license"), used)) license[] = "GPL";
>>>>>
>>>>>
>>>>> and I get the following output in /sys/kernel/debug/tracing/trace_pipe
>>>>>
>>>>>
>>>>>             sshd-4824  [000] ..s1 67372.673714: : Data start: 0 Data end: 0
>>>>>             sshd-4824  [000] ..s1 67372.673720: : Constant: 0
>>>>>           <idle>-0     [000] ..s. 67372.675062: : Data start: 0 Data end: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675090: : Constant: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675116: : Data start: 0 Data end: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675117: : Constant: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675129: : Data start: 0 Data end: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675130: : Constant: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675136: : Data start: 0 Data end: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675137: : Constant: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675142: : Data start: 0 Data end: 0
>>>>>           <idle>-0     [000] .Ns. 67372.675143: : Constant: 0
>>>>>               ip-6458  [000] ..s. 67372.676083: : Data start: 0 Data end: 0
>>>>>               ip-6458  [000] ..s. 67372.676084: : Constant: 0
>>>>>               ip-6458  [000] ..s. 67372.676093: : Data start: 0 Data end: 0
>>>>>               ip-6458  [000] ..s. 67372.676094: : Constant: 0
>>>>>
>>>>>
>>>>> It looks like ctx->data and ctx->data_end are not 0, because the calls
>>>>> to bpf_trace_printk in those ifs aren't being called, and the constant
>>>>> is definitely not 0.
>>>>>
>>>>> What might I be missing or doing incorrectly?
>>>>>
>>>>> Thank you!
>>>>> --Zvi

Re: Issues with bpf_trace_printk

[Daniel Borkmann]

On 08/29/2017 11:56 PM, Y Song wrote:
> I tried the test with the following:
>     . fc25 env but booted with latest net-next kernel (my developer env)
>     . clang/llvm 5.0 (build from source)
>     . latest iproute2 (build from source)
> and it works fine.
>
> I suggest you migrate to the latest (or above) environment and it should work.
> Otherwise, you could bisect and debug to see which component may have issues.
>
> On Mon, Aug 28, 2017 at 10:53 PM, Zvi Effron <zeffron@riotgames.com> wrote:
>> Generic XDP driver was introduced in the 4.12 kernel.
>> https://kernelnewbies.org/Linux_4.12#head-9f96b5e8262772d5e1908bf335fd25f4c3eec15a
>> If you run dnf update, it should pull down the 4.12 kernel on Fedora 26.
>>
>> --Zvi
>>
>> On Mon, Aug 28, 2017 at 10:39 PM, Y Song <ys114321@gmail.com> wrote:
>>> I tried on my FC26 VM. I actually got permission denied.
>>> I tried to attach the main interface enp0s3 (acting as eth0).
>>>
>>> The kernel is 4.11. I think generic xdp support is not there.
>>> Otherwise people can confirm?
>>> The VM interface enp0s3 (or eth0) may not have driver support for XDP.
>>>
>>> On Mon, Aug 28, 2017 at 3:12 PM, Zvi Effron <zeffron@riotgames.com> wrote:
>>>> Full reproduction instructions:
>>>>
>>>> 1) Install Fedora 26 server. I chose all of the default options,
>>>> except I chose to install latest packages from the network. Otherwise,
>>>> just run a dnf update after install. I installed into a VM running on
>>>> HyperV
>>>> 2) Install clang, llvm, and kernel-devel:
>>>>      dnf install -y clang llvm kernel-devel
>>>> 3) Copy the program to xdp_test_kern.c
>>>> 4) Compile the program into an elf object file:
>>>>      clang -S -O2 -Wall -Werror -nostdinc -isystem $(clang
>>>> -print-file-name=include) -I /lib/modules/$(uname
>>>> -r)/build/arch/x86/include  -I /lib/modules/$(uname
>>>> -r)/build/arch/x86/include/generated/uapi  -I /lib/modules/$(uname
>>>> -r)/build/arch/x86/include/generated  -I /lib/modules/$(uname
>>>> -r)/build/include  -I /lib/modules/$(uname
>>>> -r)/build/arch/x86/include/uapi  -I /lib/modules/$(uname
>>>> -r)/build/include/uapi  -I /lib/modules/$(uname
>>>> -r)/build/include/generated/uapi -include  /lib/modules/$(uname
>>>> -r)/build/include/linux/kconfig.h -D __KERNEL__ -c -emit-llvm -o
>>>> xdp_test_kern.ll xdp_test_kern.c
>>>>      llc -march bpf -filetype obj -o xdp_test_kern.o xdp_test_kern.ll
>>>> 5) Attach the program to eth0:
>>>>      ip link set dev eth0 xdp object xdp_test_kern.o section .text verbose
>>>> 6) Notice only 0s being printed for data in /sys/kernel/debug/tracing/trace_pipe
>>>>
>>>> As near as I can tell, the driver being used for eth0 is hv_netvsc, in
>>>> case it's an issue with the driver.

Any chance you could provide the object file itself that was used
for loading?

So it's basically 4.12 kernel with generic XDP on that driver as
you mentioned, right (must be given hv_netvsc doesn't have native
XDP ...)? Which stable version of that kernel do you use (uname -a)
and which iproute2 version (ip -V)?

Can you reproduce it with a latest iproute2 version from the git
tree, so we can rule out the loader?

What's the output of: sysctl -a 2> /dev/null | grep bpf

Thanks

Re: Issues with bpf_trace_printk

[Zvi Effron]

I've uploaded the object file to
https://drive.google.com/file/d/0B-lMs4mJOgQBU090ZzNtSkVnMTQ/view?usp=sharing

uname -a output: Linux localhost.localdomain 4.12.8-300.fc26.x86_64 #1
SMP Thu Aug 17 15:30:20 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

ip -V output: ip utility, iproute2-ss170501

I tried with latest iproute2 built from source (ip -V output: ip
utility, iproute2-ss170705) and am still having the same issue. (I
also first noticed this with a custom loader I wrote, so I think the
loader can probably be ruled out.)

sysctl -a 2> /dev/null | grep bpf output:
kernel.unprivileged_bpf_disabled = 0
net.core.bpf_jit_enable = 0
net.core.bpf_jit_harden = 0
net.core.bpf_jit_kallsyms = 0

Thanks for helping look into this! Let me know if you need any more info.
--Zvi

On Tue, Aug 29, 2017 at 4:17 PM, Daniel Borkmann <daniel@iogearbox.net> wrote:
> On 08/29/2017 11:56 PM, Y Song wrote:
>>
>> I tried the test with the following:
>>     . fc25 env but booted with latest net-next kernel (my developer env)
>>     . clang/llvm 5.0 (build from source)
>>     . latest iproute2 (build from source)
>> and it works fine.
>>
>> I suggest you migrate to the latest (or above) environment and it should
>> work.
>> Otherwise, you could bisect and debug to see which component may have
>> issues.
>>
>> On Mon, Aug 28, 2017 at 10:53 PM, Zvi Effron <zeffron@riotgames.com>
>> wrote:
>>>
>>> Generic XDP driver was introduced in the 4.12 kernel.
>>>
>>> https://kernelnewbies.org/Linux_4.12#head-9f96b5e8262772d5e1908bf335fd25f4c3eec15a
>>> If you run dnf update, it should pull down the 4.12 kernel on Fedora 26.
>>>
>>> --Zvi
>>>
>>> On Mon, Aug 28, 2017 at 10:39 PM, Y Song <ys114321@gmail.com> wrote:
>>>>
>>>> I tried on my FC26 VM. I actually got permission denied.
>>>> I tried to attach the main interface enp0s3 (acting as eth0).
>>>>
>>>> The kernel is 4.11. I think generic xdp support is not there.
>>>> Otherwise people can confirm?
>>>> The VM interface enp0s3 (or eth0) may not have driver support for XDP.
>>>>
>>>> On Mon, Aug 28, 2017 at 3:12 PM, Zvi Effron <zeffron@riotgames.com>
>>>> wrote:
>>>>>
>>>>> Full reproduction instructions:
>>>>>
>>>>> 1) Install Fedora 26 server. I chose all of the default options,
>>>>> except I chose to install latest packages from the network. Otherwise,
>>>>> just run a dnf update after install. I installed into a VM running on
>>>>> HyperV
>>>>> 2) Install clang, llvm, and kernel-devel:
>>>>>      dnf install -y clang llvm kernel-devel
>>>>> 3) Copy the program to xdp_test_kern.c
>>>>> 4) Compile the program into an elf object file:
>>>>>      clang -S -O2 -Wall -Werror -nostdinc -isystem $(clang
>>>>> -print-file-name=include) -I /lib/modules/$(uname
>>>>> -r)/build/arch/x86/include  -I /lib/modules/$(uname
>>>>> -r)/build/arch/x86/include/generated/uapi  -I /lib/modules/$(uname
>>>>> -r)/build/arch/x86/include/generated  -I /lib/modules/$(uname
>>>>> -r)/build/include  -I /lib/modules/$(uname
>>>>> -r)/build/arch/x86/include/uapi  -I /lib/modules/$(uname
>>>>> -r)/build/include/uapi  -I /lib/modules/$(uname
>>>>> -r)/build/include/generated/uapi -include  /lib/modules/$(uname
>>>>> -r)/build/include/linux/kconfig.h -D __KERNEL__ -c -emit-llvm -o
>>>>> xdp_test_kern.ll xdp_test_kern.c
>>>>>      llc -march bpf -filetype obj -o xdp_test_kern.o xdp_test_kern.ll
>>>>> 5) Attach the program to eth0:
>>>>>      ip link set dev eth0 xdp object xdp_test_kern.o section .text
>>>>> verbose
>>>>> 6) Notice only 0s being printed for data in
>>>>> /sys/kernel/debug/tracing/trace_pipe
>>>>>
>>>>> As near as I can tell, the driver being used for eth0 is hv_netvsc, in
>>>>> case it's an issue with the driver.
>
>
> Any chance you could provide the object file itself that was used
> for loading?
>
> So it's basically 4.12 kernel with generic XDP on that driver as
> you mentioned, right (must be given hv_netvsc doesn't have native
> XDP ...)? Which stable version of that kernel do you use (uname -a)
> and which iproute2 version (ip -V)?
>
> Can you reproduce it with a latest iproute2 version from the git
> tree, so we can rule out the loader?
>
> What's the output of: sysctl -a 2> /dev/null | grep bpf
>
> Thanks

Re: Issues with bpf_trace_printk

[Zvi Effron]

I managed to set up my configuration with a VM on VMware Workstation,
and it did not reproduce the bug. I think it was using one of the
Intel drivers, though, instead of the generic. Is there a way to force
the use of the generic driver?

--Zvi

On Wed, Aug 30, 2017 at 2:25 PM, Daniel Borkmann <daniel@iogearbox.net> wrote:
> On 08/30/2017 07:53 PM, Zvi Effron wrote:
>>
>> I've uploaded the object file to
>>
>> https://drive.google.com/file/d/0B-lMs4mJOgQBU090ZzNtSkVnMTQ/view?usp=sharing
>>
>> uname -a output: Linux localhost.localdomain 4.12.8-300.fc26.x86_64 #1
>> SMP Thu Aug 17 15:30:20 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
>>
>> ip -V output: ip utility, iproute2-ss170501
>>
>> I tried with latest iproute2 built from source (ip -V output: ip
>> utility, iproute2-ss170705) and am still having the same issue. (I
>> also first noticed this with a custom loader I wrote, so I think the
>> loader can probably be ruled out.)
>>
>> sysctl -a 2> /dev/null | grep bpf output:
>> kernel.unprivileged_bpf_disabled = 0
>> net.core.bpf_jit_enable = 0
>> net.core.bpf_jit_harden = 0
>> net.core.bpf_jit_kallsyms = 0
>>
>> Thanks for helping look into this! Let me know if you need any more info.
>
>
> Here are my results with your object file; seems to work fine
> for me there, good but still strange. ;) I took the actual 4.12.8
> stable kernel.
>
> # uname -a
> Linux linux-2.home 4.12.8 #1 SMP Wed Aug 30 21:27:51 CEST 2017 x86_64 x86_64
> x86_64 GNU/Linux
> # ip -V
> ip utility, iproute2-ss170705
> # sysctl -a | grep bpf
> kernel.unprivileged_bpf_disabled = 0
> net.core.bpf_jit_enable = 0
> net.core.bpf_jit_harden = 0
> net.core.bpf_jit_kallsyms = 0
> # ip link set dev wlp4s0 xdpgeneric obj ./xdp_test_kern.o sec .text
> # tc exec bpf dbg                     # cmd is just finding mount and
> dumping trace pipe
> Running! Hang up with ^C!
>
>  irq/131-iwlwifi-710   [003] ....   892.116200: : Data start: 90941a    Data
> end: 909456
>  irq/131-iwlwifi-710   [003] ....   892.116216: : Constant: 1
>  irq/131-iwlwifi-710   [003] ....   893.346855: : Data start: 90801a    Data
> end: 908044
>  irq/131-iwlwifi-710   [003] ....   893.346871: : Constant: 1
>  irq/131-iwlwifi-710   [003] ....   893.346917: : Data start: 90801a    Data
> end: 908070
>  irq/131-iwlwifi-710   [003] ....   893.346921: : Constant: 1
>  irq/131-iwlwifi-710   [003] ....   893.654076: : Data start: 90801a    Data
> end: 908044
>  irq/131-iwlwifi-710   [003] ....   893.654092: : Constant: 1
>  irq/131-iwlwifi-710   [003] ....   901.333823: : Data start: 88dfc1a   Data
> end: 88dfcb8
>  irq/131-iwlwifi-710   [003] ....   901.333839: : Constant: 1
>  irq/131-iwlwifi-710   [003] ....   907.578693: : Data start: 90801a    Data
> end: 90804c
>  irq/131-iwlwifi-710   [003] ....   907.578722: : Constant: 1
>  irq/131-iwlwifi-710   [003] ....   908.192621: : Data start: 90801a    Data
> end: 908044
>  irq/131-iwlwifi-710   [003] ....   908.192634: : Constant: 1
>  irq/131-iwlwifi-710   [003] ....   908.192696: : Data start: 90801a    Data
> end: 908070
>  irq/131-iwlwifi-710   [003] ....   908.192701: : Constant: 1
>  irq/131-iwlwifi-710   [003] ....   908.920655: : Data start: 90801a    Data
> end: 908044
>  irq/131-iwlwifi-710   [003] ....   908.920661: : Constant: 1
> [...]
>
> I attached the config I used just in case you want to try
> building 4.12.8 kernel whether that changes anything. Would
> be interesting to see.

Re: Issues with bpf_trace_printk

[David Miller]

From: Zvi Effron <zeffron@riotgames.com>
Date: Wed, 30 Aug 2017 14:50:59 -0700

> I managed to set up my configuration with a VM on VMware Workstation,
> and it did not reproduce the bug. I think it was using one of the
> Intel drivers, though, instead of the generic. Is there a way to force
> the use of the generic driver?

Set XDP_FLAGS_SKB_MODE when you install the XDP program.

That will force generic XDP and bypass the device driver level
support.

Re: Issues with bpf_trace_printk

[Daniel Borkmann]

On 08/30/2017 11:50 PM, Zvi Effron wrote:
> I managed to set up my configuration with a VM on VMware Workstation,
> and it did not reproduce the bug. I think it was using one of the
> Intel drivers, though, instead of the generic. Is there a way to force
> the use of the generic driver?

I actually doubt that the trace printk issue you've seen has anything
to do with XDP native/generic side, but verifying it would be good
nevertheless.

For more recent iproute2, you can enforce either side (internally using
the XDP_FLAGS_DRV_MODE and XDP_FLAGS_SKB_MODE flags Dave just mentioned):

* Enforce native mode:

   ip link set dev foo xdpdrv obj ./xdp_test_kern.o sec .text

* Enforce generic mode:

   ip link set dev foo xdpgeneric obj ./xdp_test_kern.o sec .text

Did anything else change in your setup, like kernel config, etc, that
could play a role here?

Thanks,
Daniel

> On Wed, Aug 30, 2017 at 2:25 PM, Daniel Borkmann <daniel@iogearbox.net> wrote:
>> On 08/30/2017 07:53 PM, Zvi Effron wrote:
>>>
>>> I've uploaded the object file to
>>>
>>> https://drive.google.com/file/d/0B-lMs4mJOgQBU090ZzNtSkVnMTQ/view?usp=sharing
>>>
>>> uname -a output: Linux localhost.localdomain 4.12.8-300.fc26.x86_64 #1
>>> SMP Thu Aug 17 15:30:20 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
>>>
>>> ip -V output: ip utility, iproute2-ss170501
>>>
>>> I tried with latest iproute2 built from source (ip -V output: ip
>>> utility, iproute2-ss170705) and am still having the same issue. (I
>>> also first noticed this with a custom loader I wrote, so I think the
>>> loader can probably be ruled out.)
>>>
>>> sysctl -a 2> /dev/null | grep bpf output:
>>> kernel.unprivileged_bpf_disabled = 0
>>> net.core.bpf_jit_enable = 0
>>> net.core.bpf_jit_harden = 0
>>> net.core.bpf_jit_kallsyms = 0
>>>
>>> Thanks for helping look into this! Let me know if you need any more info.
>>
>> Here are my results with your object file; seems to work fine
>> for me there, good but still strange. ;) I took the actual 4.12.8
>> stable kernel.
>>
>> # uname -a
>> Linux linux-2.home 4.12.8 #1 SMP Wed Aug 30 21:27:51 CEST 2017 x86_64 x86_64
>> x86_64 GNU/Linux
>> # ip -V
>> ip utility, iproute2-ss170705
>> # sysctl -a | grep bpf
>> kernel.unprivileged_bpf_disabled = 0
>> net.core.bpf_jit_enable = 0
>> net.core.bpf_jit_harden = 0
>> net.core.bpf_jit_kallsyms = 0
>> # ip link set dev wlp4s0 xdpgeneric obj ./xdp_test_kern.o sec .text
>> # tc exec bpf dbg                     # cmd is just finding mount and
>> dumping trace pipe
>> Running! Hang up with ^C!
>>
>>   irq/131-iwlwifi-710   [003] ....   892.116200: : Data start: 90941a    Data
>> end: 909456
>>   irq/131-iwlwifi-710   [003] ....   892.116216: : Constant: 1
>>   irq/131-iwlwifi-710   [003] ....   893.346855: : Data start: 90801a    Data
>> end: 908044
>>   irq/131-iwlwifi-710   [003] ....   893.346871: : Constant: 1
>>   irq/131-iwlwifi-710   [003] ....   893.346917: : Data start: 90801a    Data
>> end: 908070
>>   irq/131-iwlwifi-710   [003] ....   893.346921: : Constant: 1
>>   irq/131-iwlwifi-710   [003] ....   893.654076: : Data start: 90801a    Data
>> end: 908044
>>   irq/131-iwlwifi-710   [003] ....   893.654092: : Constant: 1
>>   irq/131-iwlwifi-710   [003] ....   901.333823: : Data start: 88dfc1a   Data
>> end: 88dfcb8
>>   irq/131-iwlwifi-710   [003] ....   901.333839: : Constant: 1
>>   irq/131-iwlwifi-710   [003] ....   907.578693: : Data start: 90801a    Data
>> end: 90804c
>>   irq/131-iwlwifi-710   [003] ....   907.578722: : Constant: 1
>>   irq/131-iwlwifi-710   [003] ....   908.192621: : Data start: 90801a    Data
>> end: 908044
>>   irq/131-iwlwifi-710   [003] ....   908.192634: : Constant: 1
>>   irq/131-iwlwifi-710   [003] ....   908.192696: : Data start: 90801a    Data
>> end: 908070
>>   irq/131-iwlwifi-710   [003] ....   908.192701: : Constant: 1
>>   irq/131-iwlwifi-710   [003] ....   908.920655: : Data start: 90801a    Data
>> end: 908044
>>   irq/131-iwlwifi-710   [003] ....   908.920661: : Constant: 1
>> [...]
>>
>> I attached the config I used just in case you want to try
>> building 4.12.8 kernel whether that changes anything. Would
>> be interesting to see.

Re: Issues with bpf_trace_printk

[Zvi Effron]

> I actually doubt that the trace printk issue you've seen has anything
> to do with XDP native/generic side, but verifying it would be good
> nevertheless.
>
> For more recent iproute2, you can enforce either side (internally using
> the XDP_FLAGS_DRV_MODE and XDP_FLAGS_SKB_MODE flags Dave just mentioned):
>
> * Enforce native mode:
>
>   ip link set dev foo xdpdrv obj ./xdp_test_kern.o sec .text
>
> * Enforce generic mode:
>
>   ip link set dev foo xdpgeneric obj ./xdp_test_kern.o sec .text

Building the latest (same commit as I used on my HyperV VM) iproute2
tools on my VMware box resulted in "No ELF library support compiled
in." when trying to load an XDP program. I assume I'm missing some
library. I'll have to look into that later. I modified my custom
loader to use the flags and neither VM supports driver mode, so it
looks like both are using the generic XDP driver.

> Did anything else change in your setup, like kernel config, etc, that
> could play a role here?

Kernel configs are the same between VMs. Looking through the list of
installed packages, the only differences I see are that the HyperV VM
is using EFI and HyperV guest tools, and the VMware VM is using BIOS
and the VMware guest tools.

I haven't had a chance yet to try and build a kernel with the
configuration you provided.

Thanks,
--Zvi

On Wed, Aug 30, 2017 at 3:04 PM, Daniel Borkmann <daniel@iogearbox.net> wrote:
> On 08/30/2017 11:50 PM, Zvi Effron wrote:
>>
>> I managed to set up my configuration with a VM on VMware Workstation,
>> and it did not reproduce the bug. I think it was using one of the
>> Intel drivers, though, instead of the generic. Is there a way to force
>> the use of the generic driver?
>
>
> I actually doubt that the trace printk issue you've seen has anything
> to do with XDP native/generic side, but verifying it would be good
> nevertheless.
>
> For more recent iproute2, you can enforce either side (internally using
> the XDP_FLAGS_DRV_MODE and XDP_FLAGS_SKB_MODE flags Dave just mentioned):
>
> * Enforce native mode:
>
>   ip link set dev foo xdpdrv obj ./xdp_test_kern.o sec .text
>
> * Enforce generic mode:
>
>   ip link set dev foo xdpgeneric obj ./xdp_test_kern.o sec .text
>
> Did anything else change in your setup, like kernel config, etc, that
> could play a role here?
>
> Thanks,
> Daniel
>
>
>> On Wed, Aug 30, 2017 at 2:25 PM, Daniel Borkmann <daniel@iogearbox.net>
>> wrote:
>>>
>>> On 08/30/2017 07:53 PM, Zvi Effron wrote:
>>>>
>>>>
>>>> I've uploaded the object file to
>>>>
>>>>
>>>> https://drive.google.com/file/d/0B-lMs4mJOgQBU090ZzNtSkVnMTQ/view?usp=sharing
>>>>
>>>> uname -a output: Linux localhost.localdomain 4.12.8-300.fc26.x86_64 #1
>>>> SMP Thu Aug 17 15:30:20 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
>>>>
>>>> ip -V output: ip utility, iproute2-ss170501
>>>>
>>>> I tried with latest iproute2 built from source (ip -V output: ip
>>>> utility, iproute2-ss170705) and am still having the same issue. (I
>>>> also first noticed this with a custom loader I wrote, so I think the
>>>> loader can probably be ruled out.)
>>>>
>>>> sysctl -a 2> /dev/null | grep bpf output:
>>>> kernel.unprivileged_bpf_disabled = 0
>>>> net.core.bpf_jit_enable = 0
>>>> net.core.bpf_jit_harden = 0
>>>> net.core.bpf_jit_kallsyms = 0
>>>>
>>>> Thanks for helping look into this! Let me know if you need any more
>>>> info.
>>>
>>>
>>> Here are my results with your object file; seems to work fine
>>> for me there, good but still strange. ;) I took the actual 4.12.8
>>> stable kernel.
>>>
>>> # uname -a
>>> Linux linux-2.home 4.12.8 #1 SMP Wed Aug 30 21:27:51 CEST 2017 x86_64
>>> x86_64
>>> x86_64 GNU/Linux
>>> # ip -V
>>> ip utility, iproute2-ss170705
>>> # sysctl -a | grep bpf
>>> kernel.unprivileged_bpf_disabled = 0
>>> net.core.bpf_jit_enable = 0
>>> net.core.bpf_jit_harden = 0
>>> net.core.bpf_jit_kallsyms = 0
>>> # ip link set dev wlp4s0 xdpgeneric obj ./xdp_test_kern.o sec .text
>>> # tc exec bpf dbg                     # cmd is just finding mount and
>>> dumping trace pipe
>>> Running! Hang up with ^C!
>>>
>>>   irq/131-iwlwifi-710   [003] ....   892.116200: : Data start: 90941a
>>> Data
>>> end: 909456
>>>   irq/131-iwlwifi-710   [003] ....   892.116216: : Constant: 1
>>>   irq/131-iwlwifi-710   [003] ....   893.346855: : Data start: 90801a
>>> Data
>>> end: 908044
>>>   irq/131-iwlwifi-710   [003] ....   893.346871: : Constant: 1
>>>   irq/131-iwlwifi-710   [003] ....   893.346917: : Data start: 90801a
>>> Data
>>> end: 908070
>>>   irq/131-iwlwifi-710   [003] ....   893.346921: : Constant: 1
>>>   irq/131-iwlwifi-710   [003] ....   893.654076: : Data start: 90801a
>>> Data
>>> end: 908044
>>>   irq/131-iwlwifi-710   [003] ....   893.654092: : Constant: 1
>>>   irq/131-iwlwifi-710   [003] ....   901.333823: : Data start: 88dfc1a
>>> Data
>>> end: 88dfcb8
>>>   irq/131-iwlwifi-710   [003] ....   901.333839: : Constant: 1
>>>   irq/131-iwlwifi-710   [003] ....   907.578693: : Data start: 90801a
>>> Data
>>> end: 90804c
>>>   irq/131-iwlwifi-710   [003] ....   907.578722: : Constant: 1
>>>   irq/131-iwlwifi-710   [003] ....   908.192621: : Data start: 90801a
>>> Data
>>> end: 908044
>>>   irq/131-iwlwifi-710   [003] ....   908.192634: : Constant: 1
>>>   irq/131-iwlwifi-710   [003] ....   908.192696: : Data start: 90801a
>>> Data
>>> end: 908070
>>>   irq/131-iwlwifi-710   [003] ....   908.192701: : Constant: 1
>>>   irq/131-iwlwifi-710   [003] ....   908.920655: : Data start: 90801a
>>> Data
>>> end: 908044
>>>   irq/131-iwlwifi-710   [003] ....   908.920661: : Constant: 1
>>> [...]
>>>
>>> I attached the config I used just in case you want to try
>>> building 4.12.8 kernel whether that changes anything. Would
>>> be interesting to see.