Network Tracing Hands on
eBPF
提問:以下哪個核心可以執行 ebpf?
- ZStack C74
- ZStack C76
- CentOS 7.7
- ZStack experimental repo 中的核心
(分別對應了 3.10.0-693 3.10.0-957 3.10.0-1062 4.18.0-240)
答案:有三個核心可以支援
C74 是不支援的,C76 有有限的支援,C77 支援程度更好一點,experimental kernel 裡是 4.18.0,對 ebpf 支援已經很完善(當然了,ebpf 還處於快速發展階段,因此還是版本越高越完善)
檢查自己安裝的核心:
grubby --info=ALL
在 ZStack 管理的計算節點上安裝來自 experimental 的 4.18 核心:
yum --disablerepo=\* --enablerepo=zstack-experimental-mn install kernel-4.18.0
在 ZStack 管理節點上安裝來自 experimental 的 4.18 核心:
yum --disablerepo=\* --enablerepo=zstack-experimental-mn install kernel-4.18.0
檢視核心編譯選項
[[email protected] ~]# cat /boot/config-3.10.0-1062.18.1.el7.x86\_64 | grep -i bpf CONFIG\_BPF=y CONFIG\_BPF\_SYSCALL=y CONFIG\_BPF\_JIT\_ALWAYS\_ON=y CONFIG\_NETFILTER\_XT\_MATCH\_BPF=m CONFIG\_NET\_CLS\_BPF=m CONFIG\_BPF\_JIT=y CONFIG\_HAVE\_EBPF\_JIT=y CONFIG\_BPF\_EVENTS=y CONFIG\_BPF\_KPROBE\_OVERRIDE=y
安裝 bcc,跑一個 ebpf demo
參考:https://github.com/iovisor/bcc/blob/master/INSTALL.md#rhel—binary
yum install bcc-tools
下載 bcc 原始碼:
git clone <https://github.com/iovisor/bcc.git>
執行 hello world(跟蹤系統呼叫 sys_clone):
python examples/hello\_world.py
在 hello world 上稍作修改,跟蹤 ipt_do_table 呼叫
修改 hello world,改成呼叫 ipt_do_table(進入 iptables 的時候)的時候列印 hello world
[[email protected] bcc]# cat examples/hello\_world.1.py #!/usr/bin/python from bcc import BPF BPF(text='int kprobe\_\_ipt\_do\_table(void \*ctx) { bpf\_trace\_printk("Hello, World!\\n"); return 0; }').trace\_print()
此時會發現指令碼會不斷列印 hello world
下面將 iptables 模組移除:
# **儲存一下之前的 iptables 內容:** [[email protected] ~]# iptables-save > ww.1.ipt # **準備一個空的 iptables 配置** [[email protected] ~]# cat ww.empty.ipt # Generated by iptables-save v1.4.21 on Thu Sep 23 10:24:35 2021 \*raw :PREROUTING ACCEPT [0:0] :OUTPUT ACCEPT [69467:48787226] COMMIT # Completed on Thu Sep 23 10:24:35 2021 # Generated by iptables-save v1.4.21 on Thu Sep 23 10:24:35 2021 \*filter :INPUT ACCEPT [81:6753] :FORWARD ACCEPT [0:0] :OUTPUT ACCEPT [69467:48787226] COMMIT # Completed on Thu Sep 23 10:24:35 2021 # Generated by iptables-save v1.4.21 on Thu Sep 23 10:24:35 2021 \*mangle :PREROUTING ACCEPT [76482:29150585] :INPUT ACCEPT [73927:27411897] :FORWARD ACCEPT [0:0] :OUTPUT ACCEPT [69467:48787226] :POSTROUTING ACCEPT [69467:48787226] COMMIT # Completed on Thu Sep 23 10:24:35 2021 # **停掉 zsn,將空配置匯入** [[email protected] ~]# systemctl stop zstack-network-agent [[email protected] ~]# cat ww.empty.ipt | iptables-restore [[email protected] ~]# lsmod | grep ipt ipt\_REJECT 16384 0 nf\_reject\_ipv4 16384 1 ipt\_REJECT iptable\_raw 16384 0 iptable\_filter 16384 0 iptable\_mangle 16384 0 ip\_tables 28672 3 iptable\_filter,iptable\_raw,iptable\_mangle` # **解除安裝模組** [[email protected] ~]# modprobe -r iptable\_raw [[email protected] ~]# modprobe -r iptable\_filter` [[email protected] ~]# modprobe -r iptable\_mangle [[email protected] ~]# modprobe -r ipt\_REJECT [[email protected] ~]# lsmod | grep ipt [[email protected] ~]#
發現不會再列印任何 hello world
類似的,可以跟蹤其他函式,例如網路路徑中的 iprcv、br_nf_forward 等等
複雜的例子:skbtracer
首先下載程式碼(原來的程式碼有一些問題,例如沒有 KBUILD_MODNAME,dropstack 存在 bug 無法使用等,我做了一些修復)
git clone [https://github.com/MatheMatrix/skbtracer](https://github.com/MatheMatrix/skbtracer/blob/main/skbtracer.c)
可以簡單看下命令介紹
python skbtracer.py --help
可以從 10.0.54.172 發個包文看下收包的路徑,skbtracer 可以指定協議、IP 等資訊做過濾
python skbtracer.py --proto=icmp -H 10.0.54.172
因為我的這個環境裡,地址配在了網橋上,我們可以看下地址配置網絡卡的收包過程
ip link add link eth0 name eth0.999 type vlan id 999 ip link set dev eth0.999 up ip a add 192.168.99.14/24 dev eth0.999
此外,我們可以在發包的虛擬機器配一個路由,例如
ip r add 192.168.100.10 via 192.168.99.14
然後往這個假的 192.168.100.10 地址發包,讓 192.168.99.14 起到一個路由的作用
skbtracer 能否同時 trace 函式和 netfilter?
此外,可以把 iptable 的 trace 開啟:
如果我通過 iptables INPUT 將報文 drop,可以看到 request 最後一步會顯示 INPUT drop:
如果我用 tc 來 drop 報文呢?
首先是準備工作
yum --enablerepo=zstack-experimental-mn install kernel-modules-extra tc qdisc add dev eth0.999 root netem loss 50%
然後發四個報文,其中 seq=2 被丟掉了
檢視 trace,發現相比正常 trace 痕跡,這裡少了一個 __dev_queue_xmit 把報文從 eth0.999 送到 eth0 的過程,進而也少了 eth0 packet_rcv 的過程,因此可以確認是 eth0.999 把包丟掉了
但如果是在 eth0 上丟包呢?
[[email protected] opensource]# tc qdisc add dev eth0 root netem loss 33% [[email protected] opensource]# [[email protected] opensource]# ping 10.0.54.172 -c 4 PING 10.0.54.172 (10.0.54.172) 56(84) bytes of data. 64 bytes from 10.0.54.172: icmp\_seq=1 ttl=64 time=0.346 ms 64 bytes from 10.0.54.172: icmp\_seq=2 ttl=64 time=0.445 ms 64 bytes from 10.0.54.172: icmp\_seq=4 ttl=64 time=0.470 ms --- 10.0.54.172 ping statistics --- 4 packets transmitted, 3 received, 25% packet loss, time 3052ms rtt min/avg/max/mdev = 0.346/0.420/0.470/0.056 ms
傳送四個報文,seq=3被丟棄了,但是從 trace 上看確實發出去了,沒有收到回包,說明我們的 trace 還不夠細緻,需要改造 skbtracer
如何改造 skbtracer 追蹤 tc?
通過對 tc 的原理進行分析可以知道 tc 本質上是在 qdisc 上做文章,通過 perf 可以查到 qdisc 也有相應的 tracepoint,因此我們可以通過在 skbtracer 增加 qdisc 的 tracepoint 來達到目的
[[email protected] skbtracer]# git diff diff --git a/skbtracer.c b/skbtracer.c index e62b542..e49c613 100644 --- a/skbtracer.c +++ b/skbtracer.c @@ -1,3 +1,5 @@ +#define KBUILD\_MODNAME "skbtracer" + #include <bcc/proto.h> #include <uapi/linux/ip.h> #include <uapi/linux/ipv6.h> **@@ -589,6 +591,10 @@ int kprobe\_\_ip\_finish\_output(struct pt\_regs \*ctx, struct net \*net, struct sock \*** **return do\_trace(ctx, skb, \_\_func\_\_+8, NULL);** **}** **+TRACEPOINT\_PROBE(qdisc, qdisc\_dequeue) {** **+ return do\_trace(args, (struct sk\_buff\*)args->skbaddr, \_\_func\_\_, NULL);** **+}** **+** **#endif** #if \_\_BCC\_iptable @@ -671,7 +677,7 @@ int kprobe\_\_\_\_kfree\_skb(struct pt\_regs \*ctx, struct sk\_buff \*skb) event.start\_ns = bpf\_ktime\_get\_ns(); bpf\_strncpy(event.func\_name, \_\_func\_\_+8, FUNCNAME\_MAX\_LEN); get\_stack(ctx, &event); - route\_event.perf\_submit(ctx, event, sizeof(\*event)); + route\_event.perf\_submit(ctx, &event, sizeof(event)); return 0; } #endif
為了方便,並沒有做什麼開關之類的,而是直接加到了 trace 裡,讓我們來再試一下
[[email protected] opensource]# ping 10.0.54.172 -c 4 PING 10.0.54.172 (10.0.54.172) 56(84) bytes of data. 64 bytes from 10.0.54.172: icmp\_seq=1 ttl=64 time=0.757 ms 64 bytes from 10.0.54.172: icmp\_seq=2 ttl=64 time=0.455 ms 64 bytes from 10.0.54.172: icmp\_seq=3 ttl=64 time=0.388 ms --- 10.0.54.172 ping statistics --- 4 packets transmitted, 3 received, 25% packet loss, time 3098ms rtt min/avg/max/mdev = 0.388/0.533/0.757/0.161 ms
這裡就很容易看到了,之前的報文都會經過 tracepoint__qdisc__qdisc_dequeue,而最後一個報文卻沒有到達 tracepoint__qdisc__qdisc_dequeue,也就是在 qdisc dequeue 之前被丟棄了,因此我們的排查方向就可以往 qdisc 的方向排查
對於更新的 kernel 版本,還提供了 qdisc_enqueue 的 tracepoint,就可以更明確的展示出是不是 qdisc 這塊搞鬼了
此外,如果你已經逐步的縮小了範圍,那麼可以通過檢查 /proc/kallsyms 裡的匯出函式或者 perf list 中的 tracepoint 進一步 trace,縮小調查範圍
思考題
目前 skbtracer 只做了 ip 層以下大部分和 iptables,如果想要跟蹤 ebtables 該怎麼改造?
拓展文章
iptables trace target
簡介
iptables 有海量的現成的 target extension,參考: https://ipset.netfilter.org/iptables-extensions.man.html 有很多 extension 其實很小眾但很有意思,過去的網路(裝置)公司很多報文的修改等花活都是在 netfilter 這個框架下加 extension 實現的,當然隨著裝置公司轉向使用者態協議棧等方案,netfilter 外掛技術也逐漸成文屠龍技了,但還是有很多很實用的可以多探索,例如 trace。
modprobe nf\_log\_ipv4 sysctl -w net.netfilter.nf\_log.2=nf\_log\_ipv4 iptables -t raw -I PREROUTING -p icmp -j TRACE # 根據需求修改過濾條件,這裡是針對收包的,maybe 你需要針對入包的
思考題
還能結合什麼其他 target extension 來實現 跟蹤報文在 iptables 的“流轉”過程嗎?
dropwatch
簡介
dropwatch 通過跟蹤 skb_free 來跟蹤丟包,不過功能相對有限,在高版本核心中,dropwatch 完全沒有 ebpf 來的靈活好用,但好處是 3.10.X 核心你就可以通過 dropwatch 簡單排查,有一個小 tip 是利用大量發報文定位到對應的 dropwatch。例如 iptables 丟包:
iptables -I INPUT -s 10.0.54.172 -j DROP
可以看到是 nf_hook_slow,其實根據函式名就能大致判斷是 iptables 丟包,當然也可以進入到對應版本核心程式碼檢視
用 perf 取代 dropwatch 獲取更詳細的資訊
前面有提到 dropwatch 本質上是 trace skb_free 的函式,那麼其實無論是 systemtap、ebpf、perf 等各種 trace 工具都可以做到類似的事情,下面我們演示用 perf 獲取發生 skb free 的更詳細的呼叫棧
[[email protected] skbtracer]# perf record -g -a -e skb:kfree_skb Lowering default frequency rate to 2000. Please consider tweaking /proc/sys/kernel/perf_event_max_sample_rate. ^C[ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.404 MB perf.data (453 samples) ] [[email protected] skbtracer]# perf script swapper 0 [000] 100201.435009: skb:kfree_skb: skbaddr=0xffff9b364e848b00 protocol=2048 location=0xffffffffb75ae9f7 ffffffffb7524bd3 kfree_skb+0x73 ([kernel.kallsyms]) ffffffffb7524bd3 kfree_skb+0x73 ([kernel.kallsyms]) ffffffffb75ae9f7 nf_hook_slow+0xa7 ([kernel.kallsyms]) ffffffffb75bb29c ip_local_deliver+0xcc ([kernel.kallsyms]) ffffffffc0b98191 ip_sabotage_in+0x41 ([kernel.kallsyms]) ffffffffb75ae994 nf_hook_slow+0x44 ([kernel.kallsyms]) ffffffffb75bb5bc ip_rcv+0x30c ([kernel.kallsyms]) ffffffffb753ebf7 __netif_receive_skb_core+0xb27 ([kernel.kallsyms]) ffffffffb753ed8d netif_receive_skb_internal+0x3d ([kernel.kallsyms]) ffffffffc0b6cf64 br_pass_frame_up+0xc4 ([kernel.kallsyms]) ffffffffc0b6d154 br_handle_frame_finish+0x164 ([kernel.kallsyms]) ffffffffc0b9907b br_nf_hook_thresh+0xdb ([kernel.kallsyms]) ffffffffc0b99a09 br_nf_pre_routing_finish+0x129 ([kernel.kallsyms]) ffffffffc0b99f91 br_nf_pre_routing+0x341 ([kernel.kallsyms]) ffffffffb75ae994 nf_hook_slow+0x44 ([kernel.kallsyms]) ffffffffc0b6d621 br_handle_frame+0x1f1 ([kernel.kallsyms]) ffffffffb753e767 __netif_receive_skb_core+0x697 ([kernel.kallsyms]) ffffffffb753ed8d netif_receive_skb_internal+0x3d ([kernel.kallsyms]) ffffffffb753f68a napi_gro_receive+0xba ([kernel.kallsyms]) ffffffffc031091e receive_buf+0x17e ([kernel.kallsyms]) ffffffffc0311413 virtnet_poll+0x153 ([kernel.kallsyms]) ffffffffb753fb89 net_rx_action+0x149 ([kernel.kallsyms]) ffffffffb7a000e4 __softirqentry_text_start+0xe4 ([kernel.kallsyms]) ffffffffb6ebc357 irq_exit+0xf7 ([kernel.kallsyms]) ffffffffb7801f9f do_IRQ+0x7f ([kernel.kallsyms]) ffffffffb7800a8f ret_from_intr+0x0 ([kernel.kallsyms]) ffffffffb76d832e native_safe_halt+0xe ([kernel.kallsyms]) ffffffffb76d7f9c __cpuidle_text_start+0x1c ([kernel.kallsyms]) ffffffffb6eebd37 do_idle+0x207 ([kernel.kallsyms]) ffffffffb6eebf8f cpu_startup_entry+0x6f ([kernel.kallsyms]) ffffffffb88a01e5 start_kernel+0x51e ([kernel.kallsyms]) ffffffffb6e000e7 secondary_startup_64+0xb7 ([kernel.kallsyms]) swapper 0 [000] 100201.438796: skb:kfree_skb: skbaddr=0xffff9b364e848b00 protocol=2048 location=0xffffffffb75bacad ffffffffb7524bd3 kfree_skb+0x73 ([kernel.kallsyms]) ffffffffb7524bd3 kfree_skb+0x73 ([kernel.kallsyms]) ffffffffb75bacad ip_rcv_finish+0x20d ([kernel.kallsyms]) ffffffffc0b98191 ip_sabotage_in+0x41 ([kernel.kallsyms]) ffffffffb75ae994 nf_hook_slow+0x44 ([kernel.kallsyms]) ffffffffb75bb5bc ip_rcv+0x30c ([kernel.kallsyms]) ffffffffb753ebf7 __netif_receive_skb_core+0xb27 ([kernel.kallsyms]) ffffffffb753ed8d netif_receive_skb_internal+0x3d ([kernel.kallsyms]) ffffffffc0b6cf64 br_pass_frame_up+0xc4 ([kernel.kallsyms]) ffffffffc0b6d154 br_handle_frame_finish+0x164 ([kernel.kallsyms]) ffffffffc0b9907b br_nf_hook_thresh+0xdb ([kernel.kallsyms]) ffffffffc0b99a09 br_nf_pre_routing_finish+0x129 ([kernel.kallsyms]) ffffffffc0b99f91 br_nf_pre_routing+0x341 ([kernel.kallsyms]) ffffffffb75ae994 nf_hook_slow+0x44 ([kernel.kallsyms]) ffffffffc0b6d621 br_handle_frame+0x1f1 ([kernel.kallsyms]) ffffffffb753e767 __netif_receive_skb_core+0x697 ([kernel.kallsyms]) ffffffffb753ed8d netif_receive_skb_internal+0x3d ([kernel.kallsyms]) ffffffffb753f68a napi_gro_receive+0xba ([kernel.kallsyms]) ffffffffc031091e receive_buf+0x17e ([kernel.kallsyms]) ffffffffc0311413 virtnet_poll+0x153 ([kernel.kallsyms]) ffffffffb753fb89 net_rx_action+0x149 ([kernel.kallsyms]) ffffffffb7a000e4 __softirqentry_text_start+0xe4 ([kernel.kallsyms]) ffffffffb6ebc357 irq_exit+0xf7 ([kernel.kallsyms]) ffffffffb7801f9f do_IRQ+0x7f ([kernel.kallsyms]) ffffffffb7800a8f ret_from_intr+0x0 ([kernel.kallsyms]) ffffffffb76d832e native_safe_halt+0xe ([kernel.kallsyms]) ffffffffb76d7f9c __cpuidle_text_start+0x1c ([kernel.kallsyms]) ffffffffb6eebd37 do_idle+0x207 ([kernel.kallsyms]) ffffffffb6eebf8f cpu_startup_entry+0x6f ([kernel.kallsyms]) ffffffffb88a01e5 start_kernel+0x51e ([kernel.kallsyms]) ffffffffb6e000e7 secondary_startup_64+0xb7 ([kernel.kallsyms]) swapper 0 [000] 100201.441461: skb:kfree_skb: skbaddr=0xffff9b364e848b00 protocol=2048 location=0xffffffffb75bb348 ffffffffb7524bd3 kfree_skb+0x73 ([kernel.kallsyms]) ffffffffb7524bd3 kfree_skb+0x73 ([kernel.kallsyms]) ffffffffb75bb348 ip_rcv+0x98 ([kernel.kallsyms]) ffffffffb753ebf7 __netif_receive_skb_core+0xb27 ([kernel.kallsyms]) ffffffffb753ed8d netif_receive_skb_internal+0x3d ([kernel.kallsyms]) ffffffffc0b6cf64 br_pass_frame_up+0xc4 ([kernel.kallsyms]) ffffffffc0b6d154 br_handle_frame_finish+0x164 ([kernel.kallsyms]) ffffffffc0b9907b br_nf_hook_thresh+0xdb ([kernel.kallsyms]) ffffffffc0b99a09 br_nf_pre_routing_finish+0x129 ([kernel.kallsyms]) ffffffffc0b99f91 br_nf_pre_routing+0x341 ([kernel.kallsyms]) ffffffffb75ae994 nf_hook_slow+0x44 ([kernel.kallsyms]) ffffffffc0b6d621 br_handle_frame+0x1f1 ([kernel.kallsyms]) ffffffffb753e34b __netif_receive_skb_core+0x27b ([kernel.kallsyms]) ffffffffb753ed8d netif_receive_skb_internal+0x3d ([kernel.kallsyms]) ffffffffb753f68a napi_gro_receive+0xba ([kernel.kallsyms]) ffffffffc031091e receive_buf+0x17e ([kernel.kallsyms]) ffffffffc0311413 virtnet_poll+0x153 ([kernel.kallsyms]) ffffffffb753fb89 net_rx_action+0x149 ([kernel.kallsyms]) ffffffffb7a000e4 __softirqentry_text_start+0xe4 ([kernel.kallsyms]) ffffffffb6ebc357 irq_exit+0xf7 ([kernel.kallsyms]) ffffffffb7801f9f do_IRQ+0x7f ([kernel.kallsyms]) ffffffffb7800a8f ret_from_intr+0x0 ([kernel.kallsyms]) ffffffffb76d832e native_safe_halt+0xe ([kernel.kallsyms]) ffffffffb76d7f9c __cpuidle_text_start+0x1c ([kernel.kallsyms]) ffffffffb6eebd37 do_idle+0x207 ([kernel.kallsyms]) ffffffffb6eebf8f cpu_startup_entry+0x6f ([kernel.kallsyms]) ffffffffb88a01e5 start_kernel+0x51e ([kernel.kallsyms]) ffffffffb6e000e7 secondary_startup_64+0xb7 ([kernel.kallsyms]) swapper 0 [000] 100201.445009: skb:kfree_skb: skbaddr=0xffff9b364e848b00 protocol=2054 location=0xffffffffc0b6d143 ffffffffb7524bd3 kfree_skb+0x73 ([kernel.kallsyms]) ffffffffb7524bd3 kfree_skb+0x73 ([kernel.kallsyms]) ffffffffc0b6d143 br_handle_frame_finish+0x153 ([kernel.kallsyms]) ffffffffc0b6d584 br_handle_frame+0x154 ([kernel.kallsyms]) ffffffffb753e767 __netif_receive_skb_core+0x697 ([kernel.kallsyms]) ffffffffb753ed8d netif_receive_skb_internal+0x3d ([kernel.kallsyms]) ffffffffb753f68a napi_gro_receive+0xba ([kernel.kallsyms]) ffffffffc031091e receive_buf+0x17e ([kernel.kallsyms]) ffffffffc0311413 virtnet_poll+0x153 ([kernel.kallsyms]) ffffffffb753fb89 net_rx_action+0x149 ([kernel.kallsyms]) ffffffffb7a000e4 __softirqentry_text_start+0xe4 ([kernel.kallsyms]) ffffffffb6ebc357 irq_exit+0xf7 ([kernel.kallsyms]) ffffffffb7801f9f do_IRQ+0x7f ([kernel.kallsyms]) ffffffffb7800a8f ret_from_intr+0x0 ([kernel.kallsyms]) ffffffffb76d832e native_safe_halt+0xe ([kernel.kallsyms]) ffffffffb76d7f9c __cpuidle_text_start+0x1c ([kernel.kallsyms]) ffffffffb6eebd37 do_idle+0x207 ([kernel.kallsyms]) ffffffffb6eebf8f cpu_startup_entry+0x6f ([kernel.kallsyms]) ffffffffb88a01e5 start_kernel+0x51e ([kernel.kallsyms]) ffffffffb6e000e7 secondary_startup_64+0xb7 ([kernel.kallsyms])
這裡是先用 perf record 記錄了 kfree_skb 的事件,同時用 -g 記錄了 call graph 方便我們追溯,最後用 perf script 自動處理記錄的資訊。
第一個報文,有一個 protocol 是 2048,可以在 https://www.iana.org/assignments/ieee-802-numbers/ieee-802-numbers.xhtml 查到就是 IP 報文,常用的,還有 2054 ARP
可以看到這個報文在 nf_hook_slow 之後就被呼叫了 kfree_skb,無疑就是我們上面分析的那種情況了
後面的幾個報文,nf_hook_slow 已經過去了,分別在 ip_rcv_finish、ip_rcv、br_handle_frame_finish 被丟棄,都是些個大函式,而且這些函式往往是通過 goto DROP 的方式丟包,裡面丟包的點很多,只能逐個分支分析情況了.
你可能能會想,這裡不是給出了偏移量了嗎?能否定位到某一行程式碼?這個留作思考題。
思考題
dropwatch 和 perf 給出來的偏移量能否定位都某一行程式碼?(提示:分兩種情況,如果有對應版本的 debuginfo,和沒有對應版本的 debuginfo)