Tutorial: Tracing03 - debug print

In this lesson we will show how to print message from eBPF program into tracefs buffer.

Table of Contents

• eBPF trace printk helper
• The tracefs pipe reader
• Assignments
  • Assignment 1: Setting up your test lab
  • Assignment 2: Run debug code

eBPF trace printk helper

The bpf_trace_print helper function is very useful when debugging or when there’s need for immediate feedback from the eBPF program.

It offers limited trace_printk capability and basically stores message into the tracefs buffer.

The bpf_trace_printk interface is:

#define __bpf_printk(fmt, ...)					\
({												\
	BPF_PRINTK_FMT_MOD char ____fmt[] = fmt;	\
	bpf_trace_printk(____fmt, sizeof(____fmt),	\
			 ##__VA_ARGS__);					\
})

/*
 * __bpf_vprintk wraps the bpf_trace_vprintk helper with variadic arguments
 * instead of an array of u64.
 */
#define __bpf_vprintk(fmt, args...)						\
({														\
	static const char ___fmt[] = fmt;					\
	unsigned long long ___param[___bpf_narg(args)];		\
														\
	_Pragma("GCC diagnostic push")						\
	_Pragma("GCC diagnostic ignored \"-Wint-conversion\"")	\
	___bpf_fill(___param, args);						\
	_Pragma("GCC diagnostic pop")						\
														\
	bpf_trace_vprintk(___fmt, sizeof(___fmt),			\
			  ___param, sizeof(___param));				\
})

/* Use __bpf_printk when bpf_printk call has 3 or fewer fmt args
 * Otherwise use __bpf_vprintk
 */
#define ___bpf_pick_printk(...) \
	___bpf_nth(_, ##__VA_ARGS__, __bpf_vprintk, __bpf_vprintk, __bpf_vprintk,	\
		   __bpf_vprintk, __bpf_vprintk, __bpf_vprintk, __bpf_vprintk,		\
		   __bpf_vprintk, __bpf_vprintk, __bpf_printk /*3*/, __bpf_printk /*2*/,\
		   __bpf_printk /*1*/, __bpf_printk /*0*/)

/* Helper macro to print out debug messages */
#define bpf_printk(fmt, args...) ___bpf_pick_printk(args)(fmt, ##args)

Because the above interface requires to put the size of the format string it’s more convenient to use bpf_printk(fmt, args...) helper:

SEC("xdp")
int xdp_prog_simple(struct xdp_md *ctx)
{
        bpf_printk("...");
        return XDP_PASS;
}

The tracefs pipe reader

To retrieve the message printed by bpf_trace_printk, you can either read tracefs buffer directly:

$ sudo cat /sys/kernel/debug/tracing/trace_pipe

Or you can use standard C file-reading/parsing code to get the data:

stream = fopen(TRACEFS_PIPE, "r");

...

while ((nread = getline(&line, &len, stream)) != -1) {

for more details please check on trace_read.c file.

Assignments

Assignment 1: Setting up your test lab

In this lesson we will use the setup of the previous lesson: Basic02 - loading a program by name https://github.com/xdp-project/xdp-tutorial/tree/master/basic02-prog-by-name#assignment-2-add-xdp_abort-program

Setup the environment:

$ sudo ../testenv/testenv.sh setup --name veth-basic02

Load XDP program from xdp_prog_kern.o that will print ethernet header on every incoming packet:

$ sudo xdp-loader load veth-basic02 xdp_prog_kern.o -s xdp

and generate some packets:

$ sudo ../testenv/testenv.sh enter --name veth-basic02
# ping fc00:dead:cafe:1::1
PING fc00:dead:cafe:1::1(fc00:dead:cafe:1::1) 56 data bytes

Assignment 2: Run debug code

bpf_printk("src: %llu, dst: %llu, proto: %u\n",
           ether_addr_to_u64(eth->h_source),
           ether_addr_to_u64(eth->h_dest),
           bpf_ntohs(eth->h_proto));

You can monitor the message either via tracefs:

$ sudo cat /sys/kernel/debug/tracing/trace_pipe
ping-28172 [001] ..s1 155229.100016: 0: src: 99726513069783, dst: 63819112930922, proto: 56710
ping-28172 [001] ..s1 155230.124054: 0: src: 99726513069783, dst: 63819112930922, proto: 56710
ping-28172 [001] ..s1 155231.148018: 0: src: 99726513069783, dst: 63819112930922, proto: 56710
ping-28172 [001] ..s1 155232.172022: 0: src: 99726513069783, dst: 63819112930922, proto: 56710

or with the trace_read application:

$ sudo ./trace_read
src: 5a:b3:63:62:de:d7 dst: 3a:b:b:8e:5e:6a proto: 56710
src: 5a:b3:63:62:de:d7 dst: 3a:b:b:8e:5e:6a proto: 56710
src: 5a:b3:63:62:de:d7 dst: 3a:b:b:8e:5e:6a proto: 56710
...