$30 off During Our Annual Pro Sale. View Details »

Debug linux drop packets

Debug linux drop packets

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

Takeru Hayasaka

May 01, 2023
Tweet

More Decks by Takeru Hayasaka

Other Decks in Programming

Transcript

  1. おまだれ?
 はやさか たける@takemioIO (宮城出身->京都在住)
 前職: 新卒(21卒)でとある京都のゲーム会社でゲーム機を作ってた
 現職: に誘われて入社、とあるモバイルに関する開発担当 
 ↑の弟子やってます


    現職の最近: VPPというSW ルーターを改造してる 
 趣味: アニメ、漫画、散財.(annictで818->1クール4時間で3272時間...
 好きなプロトコル:SRv6, GTPv1-U
 よろしくお願いします><

  2. この発表で理解できること・出来ないこと
 - 🙆
 - linux kernelでのネットワークのデバッグツールの存在と利用イメージ
 - どういうシーンで使うのか、事例ごとを用意して説明します
 - 🙅


    - linux kernel でのパラメーターに関する詳しい説明
 - 細かいルーティングの話
 - skbにallocする前に観測するパターン
 - 以降は事例に合わせてどのようにデバッグするかを示します

  3. 事例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にパケットが飛ばないというふうな感じ

  4. 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
  5. 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 | }
  6. 無事解決(一件落着)
 - sysctl -w net.ipv4.conf.all.rp_filter=0
 - ルーティングをlinuxでやるとrp_filterにハマりがち...
 - ちなみにmartin packetは

    net.ipv4.conf.all.log_martings=1 とかでdmesgに出てきたり するのでそれで見ても良い
 問題解決ができて嬉しい 
 Linuxに詳しい水戸光圀の図 

  7. 事例2: どうしてか SRv6 End が動いてくれない
 - SRv6 End functionと呼ばれるIPv6拡張ヘッター(SRH)の中にある IPv6アドレスのポインタを次に進めてルーティングする技術のこと

    - いつものやつはちゃんと確認ができてる。
 - よっしゃ!しらべたらinput_action_endっていうのがあるからトレースだ!
 

  8. 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
  9. 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のパケットフローの図 ここでアノテーション
 つければオッケー!
 余談
  10. 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 …
  11. 事例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
  12. 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] …
  13. 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を行ったときの様子の振る舞いが完全一致

  14. 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 … 再掲
  15. 出てきたアドレスから探せないのか?
 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 …
  16. iptablesのルールで落とされていないかを探す
 - iptables には pkts というカウンターがあり、今までそのルールにマッチしたパケットの 数をカウントアップしてくれるパラメータがある
 - sudo iptables

    -L -v -n をおもむろにしてみるとめっちゃある😇
 - ここからは気合
 - iptables -Z でpkts をクリア
 - iptables -L -v -n を叩きまくって
 カウンターが上がってないかを探す
 
 https://twitter.com/JOJOex_2018/status/969708956825407488 パ
 ケ
 ッ
 ト
 の
 数

  17. なんだ親に向かってその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
  18. まとめ
 - trace-cmd: 決められた関数を起点にして動作を確認する際に便利 
 - ipftrace2: 特定のパケットに対するカーネル内の動作に着目できる 
 -

    dropwatch: linux kernel の内部関数でdropされたメトリックに合わせて取得可能になる。なんか dropしてる箇所を知りたい時便利。
 - 紹介した方法を利用すればLinuxのNetworkingでハマった時に 
 便利に解決できるかもしれないです
 - Netlinkを使うケースの話?知らない子ですね... 
 - BPFを使うケースの話?知らない子ですね... 
 - TSO, GSOの効かないケース?ipftrace2を駆使してもらって... 
 - linux のネットワーキングは面白い;)
 
 
 linux kernel のnetworkingが 
 デカすぎてつらい気持ちの 
 水戸光圀の図