samples/bpf: fix broken lightweight tunnel testing

The test_lwt_bpf is a script that tests the functionality of BPF through
the output of the ftrace with bpf_trace_printk. Currently, this program
is not operating normally for several reasons.

First of all, this test script can't parse the ftrace results properly.
GNU sed tries to be as greedy as possible when attempting pattern
matching. Due to this, cutting metadata (such as timestamp) from the
log entry of ftrace doesn't work properly, and also desired log isn't
extracted properly. To make sed stripping clearer, 'nocontext-info'
option with the ftrace has been used to remove metadata from the log.
Also, instead of using unclear pattern matching, this commit specifies
an explicit parse pattern.

Also, unlike before when this test was introduced, the way
bpf_trace_printk behaves has changed[1]. The previous bpf_trace_printk
had to always have '\n' in order to print newline, but now that the
bpf_trace_printk call includes newline by default, so '\n' is no longer
needed.

Lastly with the lwt ENCAP_BPF out, the context information with the
sk_buff protocol is preserved. Therefore, this commit changes the
previous test result from 'protocol 0' to 'protocol 8', which means
ETH_P_IP.

[1]: commit ac5a72ea ("bpf: Use dedicated bpf_trace_printk event instead of trace_printk()")
Signed-off-by: Daniel T. Lee <danieltimlee@gmail.com>
Link: https://lore.kernel.org/r/20230115071613.125791-4-danieltimlee@gmail.comSigned-off-by: Alexei Starovoitov <ast@kernel.org>

samples/bpf/test_lwt_bpf.c

@@ -44,9 +44,9 @@ SEC("test_ctx")
 int do_test_ctx(struct __sk_buff *skb)
 {
 	skb->cb[0] = CB_MAGIC;
-	printk("len %d hash %d protocol %d\n", skb->len, skb->hash,
+	printk("len %d hash %d protocol %d", skb->len, skb->hash,
 	       skb->protocol);
-	printk("cb %d ingress_ifindex %d ifindex %d\n", skb->cb[0],
+	printk("cb %d ingress_ifindex %d ifindex %d", skb->cb[0],
 	       skb->ingress_ifindex, skb->ifindex);
 
 	return BPF_OK;
@@ -56,9 +56,9 @@ int do_test_ctx(struct __sk_buff *skb)
 SEC("test_cb")
 int do_test_cb(struct __sk_buff *skb)
 {
-	printk("cb0: %x cb1: %x cb2: %x\n", skb->cb[0], skb->cb[1],
+	printk("cb0: %x cb1: %x cb2: %x", skb->cb[0], skb->cb[1],
 	       skb->cb[2]);
-	printk("cb3: %x cb4: %x\n", skb->cb[3], skb->cb[4]);
+	printk("cb3: %x cb4: %x", skb->cb[3], skb->cb[4]);
 
 	return BPF_OK;
 }
@@ -72,11 +72,11 @@ int do_test_data(struct __sk_buff *skb)
 	struct iphdr *iph = data;
 
 	if (data + sizeof(*iph) > data_end) {
-		printk("packet truncated\n");
+		printk("packet truncated");
 		return BPF_DROP;
 	}
 
-	printk("src: %x dst: %x\n", iph->saddr, iph->daddr);
+	printk("src: %x dst: %x", iph->saddr, iph->daddr);
 
 	return BPF_OK;
 }
@@ -97,7 +97,7 @@ static inline int rewrite(struct __sk_buff *skb, uint32_t old_ip,
 
 	ret = bpf_skb_load_bytes(skb, IP_PROTO_OFF, &proto, 1);
 	if (ret < 0) {
-		printk("bpf_l4_csum_replace failed: %d\n", ret);
+		printk("bpf_l4_csum_replace failed: %d", ret);
 		return BPF_DROP;
 	}
 
@@ -120,14 +120,14 @@ static inline int rewrite(struct __sk_buff *skb, uint32_t old_ip,
 		ret = bpf_l4_csum_replace(skb, off, old_ip, new_ip,
 					  flags | sizeof(new_ip));
 		if (ret < 0) {
-			printk("bpf_l4_csum_replace failed: %d\n");
+			printk("bpf_l4_csum_replace failed: %d");
 			return BPF_DROP;
 		}
 	}
 
 	ret = bpf_l3_csum_replace(skb, IP_CSUM_OFF, old_ip, new_ip, sizeof(new_ip));
 	if (ret < 0) {
-		printk("bpf_l3_csum_replace failed: %d\n", ret);
+		printk("bpf_l3_csum_replace failed: %d", ret);
 		return BPF_DROP;
 	}
 
@@ -137,7 +137,7 @@ static inline int rewrite(struct __sk_buff *skb, uint32_t old_ip,
 		ret = bpf_skb_store_bytes(skb, IP_SRC_OFF, &new_ip, sizeof(new_ip), 0);
 
 	if (ret < 0) {
-		printk("bpf_skb_store_bytes() failed: %d\n", ret);
+		printk("bpf_skb_store_bytes() failed: %d", ret);
 		return BPF_DROP;
 	}
 
@@ -153,12 +153,12 @@ int do_test_rewrite(struct __sk_buff *skb)
 
 	ret = bpf_skb_load_bytes(skb, IP_DST_OFF, &old_ip, 4);
 	if (ret < 0) {
-		printk("bpf_skb_load_bytes failed: %d\n", ret);
+		printk("bpf_skb_load_bytes failed: %d", ret);
 		return BPF_DROP;
 	}
 
 	if (old_ip == 0x2fea8c0) {
-		printk("out: rewriting from %x to %x\n", old_ip, new_ip);
+		printk("out: rewriting from %x to %x", old_ip, new_ip);
 		return rewrite(skb, old_ip, new_ip, 1);
 	}
 
@@ -173,7 +173,7 @@ static inline int __do_push_ll_and_redirect(struct __sk_buff *skb)
 
 	ret = bpf_skb_change_head(skb, 14, 0);
 	if (ret < 0) {
-		printk("skb_change_head() failed: %d\n", ret);
+		printk("skb_change_head() failed: %d", ret);
 	}
 
 	ehdr.h_proto = __constant_htons(ETH_P_IP);
@@ -182,7 +182,7 @@ static inline int __do_push_ll_and_redirect(struct __sk_buff *skb)
 
 	ret = bpf_skb_store_bytes(skb, 0, &ehdr, sizeof(ehdr), 0);
 	if (ret < 0) {
-		printk("skb_store_bytes() failed: %d\n", ret);
+		printk("skb_store_bytes() failed: %d", ret);
 		return BPF_DROP;
 	}
 
@@ -202,7 +202,7 @@ int do_push_ll_and_redirect(struct __sk_buff *skb)
 
 	ret = __do_push_ll_and_redirect(skb);
 	if (ret >= 0)
-		printk("redirected to %d\n", ifindex);
+		printk("redirected to %d", ifindex);
 
 	return ret;
 }
@@ -229,7 +229,7 @@ SEC("fill_garbage")
 int do_fill_garbage(struct __sk_buff *skb)
 {
 	__fill_garbage(skb);
-	printk("Set initial 96 bytes of header to FF\n");
+	printk("Set initial 96 bytes of header to FF");
 	return BPF_OK;
 }
 
@@ -238,7 +238,7 @@ int do_fill_garbage_and_redirect(struct __sk_buff *skb)
 {
 	int ifindex = DST_IFINDEX;
 	__fill_garbage(skb);
-	printk("redirected to %d\n", ifindex);
+	printk("redirected to %d", ifindex);
 	return bpf_redirect(ifindex, 0);
 }
 
@@ -246,7 +246,7 @@ int do_fill_garbage_and_redirect(struct __sk_buff *skb)
 SEC("drop_all")
 int do_drop_all(struct __sk_buff *skb)
 {
-	printk("dropping with: %d\n", BPF_DROP);
+	printk("dropping with: %d", BPF_DROP);
 	return BPF_DROP;
 }
 

samples/bpf/test_lwt_bpf.sh

@@ -22,6 +22,7 @@ IP_LOCAL="192.168.99.1"
 PROG_SRC="test_lwt_bpf.c"
 BPF_PROG="test_lwt_bpf.o"
 TRACE_ROOT=/sys/kernel/debug/tracing
+CONTEXT_INFO=$(cat ${TRACE_ROOT}/trace_options | grep context)
 
 function lookup_mac()
 {
@@ -98,7 +99,7 @@ function remove_prog {
 function filter_trace {
 	# Add newline to allow starting EXPECT= variables on newline
 	NL=$'\n'
-	echo "${NL}$*" | sed -e 's/^.*: : //g'
+	echo "${NL}$*" | sed -e 's/bpf_trace_printk: //g'
 }
 
 function expect_fail {
@@ -162,11 +163,11 @@ function test_ctx_out {
 		failure "test_ctx out: packets are dropped"
 	}
 	match_trace "$(get_trace)" "
-len 84 hash 0 protocol 0
+len 84 hash 0 protocol 8
 cb 1234 ingress_ifindex 0 ifindex 0
-len 84 hash 0 protocol 0
+len 84 hash 0 protocol 8
 cb 1234 ingress_ifindex 0 ifindex 0
-len 84 hash 0 protocol 0
+len 84 hash 0 protocol 8
 cb 1234 ingress_ifindex 0 ifindex 0" || exit 1
 	remove_prog out
 }
@@ -369,6 +370,7 @@ setup_one_veth $NS1 $VETH0 $VETH1 $IPVETH0 $IPVETH1 $IPVETH1b
 setup_one_veth $NS2 $VETH2 $VETH3 $IPVETH2 $IPVETH3
 ip netns exec $NS1 netserver
 echo 1 > ${TRACE_ROOT}/tracing_on
+echo nocontext-info > ${TRACE_ROOT}/trace_options
 
 DST_MAC=$(lookup_mac $VETH1 $NS1)
 SRC_MAC=$(lookup_mac $VETH0)
@@ -399,4 +401,5 @@ test_netperf_redirect
 
 cleanup
 echo 0 > ${TRACE_ROOT}/tracing_on
+echo $CONTEXT_INFO > ${TRACE_ROOT}/trace_options
 exit 0