Debug linux drop packets

Linuxのパケットがドロップしてる時にどうすればいいのかなー？って言うのを事例ごとに説明してみたスライドです。社内での勉強会LTで話をしたスライドです。

Transcript

1. Debug linux drop packets
 Hayasaka Takeru(@takemioIO)
2. おまだれ？
 はやさか たける＠takemioIO （宮城出身->京都在住）
 前職: 新卒(21卒)でとある京都のゲーム会社でゲーム機を作ってた
 現職: に誘われて入社、とあるモバイルに関する開発担当 
 ↑の弟子やってます
 現職の最近: VPPというSW ルーターを改造してる 
 趣味: アニメ、漫画、散財.(annictで818->1クール4時間で3272時間...
 好きなプロトコル：SRv6, GTPv1-U
 よろしくお願いします＞＜

3. この発表で理解できること・出来ないこと
 - 🙆
 - linux kernelでのネットワークのデバッグツールの存在と利用イメージ
 - どういうシーンで使うのか、事例ごとを用意して説明します
 - 🙅
 - linux kernel でのパラメーターに関する詳しい説明
 - 細かいルーティングの話
 - skbにallocする前に観測するパターン
 - 以降は事例に合わせてどのようにデバッグするかを示します

4. 事例1: どうしてか SRv6 End.DX4 が動いてくれない
 - SRv6 End.DX4 functionと呼ばれるIPv6 overlayのOuter packetをDecap
 任意のIPv4のNexthopにIPv4 Inner packetをルーティングする仕組み
 - SRv6 overlayのエッジで動かされることが基本 
 - 以下は確認済み（以降この辺は基本操作なので「いつものやつ」として省略
 - 正しくコンフィグは設定はされている（はず）
 - ip r, ip r -6 を見ても経路はある
 - tcpdump -i eth1 とかするとそのノードまでパケットが着信してる
 - ip nでみると既にL2は解決されている
 - つまりなぜかnexthopにパケットが飛ばないというふうな感じ

5. SRv6 End.DX4の動作してそうな関数を探す
 -
6. End.DX4の動作してそうな関数にtrace-cmdを当てる
 - どうやらinput_action_end_dx4 これらしい
 - これに trace-cmd を当ててみる - カーネルトレーサー(ftrace のフロント実装）
 - https://lwn.net/Articles/410200/
 - こんな感じで当てて読み出してみる - trace-cmd record -p function_graph -g input_action_end_dx4 - trace-cmd report - ちなみに読み出せる関数かどうかはこんなふうに確認できる - cat /sys/kernel/debug/tracing/available_filter_functions | grep input_action_end_dx4
7. trace-cmdの結果から・・・
 - これでこの関数の実行処理が行われて いるときにどういうフローが流れている のかが可視化された - よくみてみるとこんなものが... ip_handle_martin_source.isra.40(); - martin packetとして処理されてて Dropしている！ 4724.772017: funcgraph_entry: | input_action_end_dx4() { 4724.772043: funcgraph_entry: | decap_and_validate() { 4724.772043: funcgraph_entry: | get_srh() { 4724.772044: funcgraph_entry: 0.698 us | ipv6_find_hdr(); 4724.772045: funcgraph_entry: 0.082 us | seg6_validate_srh(); 4724.772046: funcgraph_exit: 2.053 us | } 4724.772046: funcgraph_entry: 0.171 us | seg6_hmac_validate_skb(); 4724.772046: funcgraph_entry: 0.203 us | ipv6_find_hdr(); 4724.772047: funcgraph_exit: 3.766 us | } 4724.772047: funcgraph_entry: 0.058 us | dst_release(); 4724.772049: funcgraph_entry: | ip_route_input_noref() { 4724.772049: funcgraph_entry: | ip_route_input_rcu() { 4724.772051: funcgraph_entry: | make_kuid() { 4724.772051: funcgraph_entry: 0.472 us | map_id_range_down(); 4724.772052: funcgraph_exit: 1.000 us | } 4724.772052: funcgraph_entry: 3.247 us | fib_table_lookup(); 4724.772056: funcgraph_entry: | fib_validate_source() { 4724.772056: funcgraph_entry: 0.053 us | l3mdev_master_ifindex_rcu(); 4724.772057: funcgraph_entry: | make_kuid() { 4724.772057: funcgraph_entry: 0.055 us | map_id_range_down(); 4724.772057: funcgraph_exit: 0.457 us | } 4724.772058: funcgraph_entry: 0.820 us | fib_table_lookup(); 4724.772059: funcgraph_entry: 0.105 us | l3mdev_master_ifindex_rcu(); 4724.772059: funcgraph_exit: 3.146 us | } 4724.772060: funcgraph_entry: 0.066 us | ip_handle_martian_source.isra.40(); 4724.772060: funcgraph_exit: + 10.579 us | } 4724.772060: funcgraph_exit: + 11.295 us | } 4724.772060: funcgraph_entry: | kfree_skb() { 4724.772061: funcgraph_entry: | skb_release_all() { 4724.772061: funcgraph_entry: 0.098 us | skb_release_head_state(); 4724.772061: funcgraph_entry: | skb_release_data() { 4724.772062: funcgraph_entry: | skb_free_head() { 4724.772062: funcgraph_entry: 0.665 us | page_frag_free(); 4724.772063: funcgraph_exit: 1.184 us | } 4724.772063: funcgraph_exit: 1.788 us | } 4724.772063: funcgraph_exit: 2.793 us | } 4724.772064: funcgraph_entry: | kfree_skbmem() { 4724.772064: funcgraph_entry: 0.240 us | kmem_cache_free(); 4724.772065: funcgraph_exit: 0.758 us | } 4724.772065: funcgraph_exit: 4.366 us | } 4724.772065: funcgraph_exit: + 23.213 us | }
8. 無事解決（一件落着）
 - sysctl -w net.ipv4.conf.all.rp_filter=0
 - ルーティングをlinuxでやるとrp_filterにハマりがち...
 - ちなみにmartin packetは net.ipv4.conf.all.log_martings=1 とかでdmesgに出てきたり するのでそれで見ても良い
 問題解決ができて嬉しい 
 Linuxに詳しい水戸光圀の図 

9. 事例2: どうしてか SRv6 End が動いてくれない
 - SRv6 End functionと呼ばれるIPv6拡張ヘッター（SRH）の中にある IPv6アドレスのポインタを次に進めてルーティングする技術のこと - いつものやつはちゃんと確認ができてる。
 - よっしゃ！しらべたらinput_action_endっていうのがあるからトレースだ！
 

10. とりあえずtrace-cmdしてみた
 - トレース結果->（なにもでない...）
 - 何もわからない....
 - もしかしてこの処理の前に失敗してる？
 - ->違う方法で探してみよう
 雑にさっきの方法でなんとかなると 
 思ったがなんともならなかった 
 水戸光圀の図

11. ipftrace2を使ってみる
 - ipftrace2
 - sk_buff の metadata 領域に特定のアノテーションをつけることでパケットが 
 kernel の関数の中でどこを通ったがわかる便利ツール. eBPFを利用して実現してる 
 - https://github.com/YutaroHayakawa/ipftrace2 
 - sk_buff とはパケットを格納するためのカーネル内利用されるバッファー
 - metadata付ける方法は iptables や tc でつけることができる。
 - sudo ip6tables -t raw -A PREROUTING -d fc00:2::2 -j MARK --set-mark 0xdeadbeed 
 - sudo ipft -m 0xdeadbeed 
 https://wiki.bit-hive.com/linuxkernelmemo/pg/sk_buff
12. Network Network Routing Routing table: nat chain: PREROUTING table: filter chain: FORWARD table: filter chain: INPUT Routing table: nat chain: OUTPUT table: filter chain: OUTPUT Local Process table: nat chain: POSTROUTING パケット iptablesを基準にした Linuxのパケットフローの図 ここでアノテーション
 つければオッケー！
 余談
13. ipftrace2の結果から・・・
 - よくみてみるとこんなものが... nf_hook_slow - nf_* と書いてる場合は netfilter系の 仕組みを持つ - netfilter系の仕組みを持つものといえば？ - iptables, nftables, firewalld…etc - firewall-cmd --state →running - 😇 677084806878622 001 __skb_checksum_complete 677084806882860 001 kfree_skb 677084806887163 001 skb_release_head_state 677084806892984 001 skb_release_data 677084806897402 001 kfree_skbmem 677084836856575 001 ip6_route_input 677084836879043 001 ip6_input 677084836881744 001 nf_hook_slow 677084836895052 001 nf_ip6_checksum 677084836899705 001 __skb_checksum_complete 677084836903818 001 kfree_skb 677084836907878 001 skb_release_head_state 677084836913613 001 skb_release_data 677084836918676 001 kfree_skbmem 677084865837153 001 ip6_route_input 677084865860250 001 ip6_input 677084865863010 001 nf_hook_slow 677084865876901 001 nf_ip6_checksum 677084865881458 001 __skb_checksum_complete 677084865885631 001 kfree_skb 677084865889919 001 skb_release_head_state 677084865895676 001 skb_release_data 677084865900353 001 kfree_skbmem …
14. 無事解決（一件落着）
 - sudo systemctl stop firewalld
 - ルーティングをlinuxでやると謎のfwに人生を阻まれがち...
 
 fedora使えば起きることがわかってたのに またやらかしてしまった 
 水戸光圀の図

15. 事例3: どうしてか Wireguard が動いてくれない
 - wireguard と呼ばれるVPNの仕組み.OuterのパケットはUDPで動いている
 - シナリオとして、あるnodeにkvmで立ち上げたvmが存在していて、
 そこへのVMへの疎通性を得るためにVPNを貼りたい
 - 「いつものやつ(着信,L2,L3)」はちゃんとやってみたが問題なさそう
 - wireguard のエンドポイントに接続されているかを確認する
 - sudo wg で確認 -> ちゃんと繋がってそう
 ~$ sudo wg interface: wg0 public key: bkPuNW1FmBM+j8lqVdKSHX42neL04XHq9nHyKMUQPUs= private key: (hidden) listening port: 58120 peer: W7XO2zrw1o42PcmgrYSCTO0XwhALK9MTT6/hhfmEXnM= preshared key: (hidden) endpoint: 138.xx.xx.xx:48401 allowed ips: 10.0.0.3/32 latest handshake: 1 minute, 44 seconds ago transfer: 113.17 KiB received, 50.20 KiB sent
16. dropwatchを利用してみる
 - dropwatch
 - https://github.com/nhorman/dropwatch 
 - kfree_skbでskbがfreeされるが開放のタイミングでそれがTracePointになっている。 
 - 実装としてはnetlink 経由でメッセージを受け取り出力する形式である 
 - 利用方法はインタラクティブにおこなう。以下のようなイメージで動作
 
 
 ~$ sudo dropwatch -l kas Initializing kallsyms db dropwatch> start Enabling monitoring... Kernel monitoring activated. Issue Ctrl-C to stop monitoring 1 drops at sk_stream_kill_queues+55 (0xffffffffa22d9415) [software] …
17. dropwatchの結果
 
 
 
 :~$ sudo dropwatch -l kas Initializing kallsyms db dropwatch> start Enabling monitoring... Kernel monitoring activated. Issue Ctrl-C to stop monitoring 1 drops at nf_hook_slow+98 (0xffffffffa235be28) [software] 1 drops at nf_hook_slow+98 (0xffffffffa235be28) [software] 1 drops at nf_hook_slow+98 (0xffffffffa235be28) [software] 1 drops at nf_hook_slow+98 (0xffffffffa235be28) [software] 1 drops at nf_hook_slow+98 (0xffffffffa235be28) [software] 1 drops at nf_hook_slow+98 (0xffffffffa235be28) [software] … ~ ❯❯❯ ping 192.168.255.67 PING 192.168.255.67 (192.168.255.67): 56 data bytes Request timeout for icmp_seq 0 Request timeout for icmp_seq 1 Request timeout for icmp_seq 2 Request timeout for icmp_seq 3 Request timeout for icmp_seq 4 Request timeout for icmp_seq 5 Request timeout for icmp_seq 6 Request timeout for icmp_seq 7 Request timeout for icmp_seq 8 … VPNを貼ったまま remote server上のvmに対してping を打った際に
 remote serverでdropwatchを行ったときの様子の振る舞いが完全一致

18. ipftrace2の結果から・・・
 - よくみてみるとこんなものが... nf_hook_slow - nf_* と書いてる場合は netfilter系の 仕組みを持つ - netfilter系の仕組みを持つものといえば？ - iptables, nftables, firewalld…etc - firewall-cmd --state →running - 😇 677084806878622 001 __skb_checksum_complete 677084806882860 001 kfree_skb 677084806887163 001 skb_release_head_state 677084806892984 001 skb_release_data 677084806897402 001 kfree_skbmem 677084836856575 001 ip6_route_input 677084836879043 001 ip6_input 677084836881744 001 nf_hook_slow 677084836895052 001 nf_ip6_checksum 677084836899705 001 __skb_checksum_complete 677084836903818 001 kfree_skb 677084836907878 001 skb_release_head_state 677084836913613 001 skb_release_data 677084836918676 001 kfree_skbmem 677084865837153 001 ip6_route_input 677084865860250 001 ip6_input 677084865863010 001 nf_hook_slow 677084865876901 001 nf_ip6_checksum 677084865881458 001 __skb_checksum_complete 677084865885631 001 kfree_skb 677084865889919 001 skb_release_head_state 677084865895676 001 skb_release_data 677084865900353 001 kfree_skbmem … 再掲
19. 出てきたアドレスから探せないのか？
 0xffffffffa235be28が該当の関数
 のアドレスであるが、 kallsymsをみると、 nf_hook_slowとnetfilter_net_exitの間
 で定義されていることはわかるがシンボル
 が存在してない部分であることがわかる
 （そしておそらく kfree_skb_reason だと
 思われるが、コードを見るとエントリではplugin形 式でhookを受け入れて叩いてる
 だけなのでKGDBなどを使わない限り追うことは 厳しそう...)
 
 1 drops at nf_hook_slow+98 (0xffffffffa235be28) [software] … ~$ sudo grep -w -A 10 nf_hook_slow /proc/kallsyms ffffffffa235bd90 T nf_hook_slow ffffffffa235be40 t netfilter_net_exit ffffffffa235be60 t netfilter_net_init ffffffffa235bfa0 T nf_ct_attach ffffffffa235bfd0 T nf_conntrack_destroy ffffffffa235c000 t nf_hook_entries_free.part.0 …
20. iptablesのルールで落とされていないかを探す
 - iptables には pkts というカウンターがあり、今までそのルールにマッチしたパケットの 数をカウントアップしてくれるパラメータがある
 - sudo iptables -L -v -n をおもむろにしてみるとめっちゃある😇
 - ここからは気合
 - iptables -Z でpkts をクリア
 - iptables -L -v -n を叩きまくって
 カウンターが上がってないかを探す
 
 https://twitter.com/JOJOex_2018/status/969708956825407488 パ
 ケ
 ッ
 ト
 の
 数

21. なんだ親に向かってそのicmp-port-unreachableは！
 - 無事発見, pingを10発ほど送ったら
 10回カウントアップされてる→
 - ということでwireguardのPostUpにこんな 感じのを書いてあげる
 iptables -D LIBVIRT_FWI -i virbr0 -j REJECT --reject-with icmp-port-unreachable
 - libvirtのネットワーク構成の
 コンフィグがnatで構成されてると
 iptablesに勝手に書いてくるらしい
 ~$ sudo iptables -L -v -n|grep -A 10 LIBVIRT_FWI 20 1680 LIBVIRT_FWI all -- * * 0.0.0.0/0 0.0.0.0/0 1 84 LIBVIRT_FWO all -- * * 0.0.0.0/0 0.0.0.0/0 0 0 ACCEPT all -- * * 0.0.0.0/0 0.0.0.0/0 ctstate RELATED,ESTABLISHED,DNAT 0 0 ACCEPT all -- lo * 0.0.0.0/0 0.0.0.0/0 1 84 FORWARD_direct all -- * * 0.0.0.0/0 0.0.0.0/0 1 84 FORWARD_IN_ZONES all -- * * 0.0.0.0/0 0.0.0.0/0 0 0 FORWARD_OUT_ZONES all -- * * 0.0.0.0/0 0.0.0.0/0 0 0 DROP all -- * * 0.0.0.0/0 0.0.0.0/0 ctstate INVALID 0 0 REJECT all -- * * 0.0.0.0/0 0.0.0.0/0 reject-with icmp-host-prohibited 0 0 ACCEPT all -- wg0 virbr0 0.0.0.0/0 0.0.0.0/0 0 0 ACCEPT all -- wg0 * 0.0.0.0/0 0.0.0.0/0 -- Chain LIBVIRT_FWI (1 references) pkts bytes target prot opt in out source destination 0 0 REJECT all -- * ums-cb96fd17-5a 0.0.0.0/0 0.0.0.0/0 reject-with icmp-port-unreachable 9 756 ACCEPT all -- * virbr0 0.0.0.0/0 192.168.255.0/24 ctstate RELATED,ESTABLISHED 10 840 REJECT all -- virbr0 * 0.0.0.0/0 0.0.0.0/0 reject-with icmp-port-unreachable Chain LIBVIRT_FWO (1 references) pkts bytes target prot opt in out source destination 0 0 REJECT all -- ums-cb96fd17-5a * 0.0.0.0/0 0.0.0.0/0 reject-with icmp-port-unreachable 0 0 ACCEPT all -- virbr0 * 192.168.255.0/24 0.0.0.0/0 0 0 REJECT all -- virbr0 * 0.0.0.0/0 0.0.0.0/0 reject-with icmp-port-unreachable
22. まとめ
 - trace-cmd: 決められた関数を起点にして動作を確認する際に便利 
 - ipftrace2: 特定のパケットに対するカーネル内の動作に着目できる 
 - dropwatch: linux kernel の内部関数でdropされたメトリックに合わせて取得可能になる。なんか dropしてる箇所を知りたい時便利。
 - 紹介した方法を利用すればLinuxのNetworkingでハマった時に 
 便利に解決できるかもしれないです
 - Netlinkを使うケースの話？知らない子ですね... 
 - BPFを使うケースの話？知らない子ですね... 
 - TSO, GSOの効かないケース？ipftrace2を駆使してもらって... 
 - linux のネットワーキングは面白い;)
 
 
 linux kernel のnetworkingが 
 デカすぎてつらい気持ちの 
 水戸光圀の図

23. 参考リンク
 - https://jvns.ca/blog/2017/09/05/finding-out-where-packets-are-being-dropped/
 - https://huoding.com/2016/12/15/574
 - https://www.kimullaa.com/posts/202002230057/https://www.kimullaa.com/posts/202002230057/
 - https://takeio.hatenablog.com/entry/2021/01/25/131406