ミドルウェアのソースコードリーディングのすすめ

この記事は freee Developers Advent Calendar 2020 の 21 日目です。

プロダクト基盤本部で本部長をしています浅羽と申します。プロダクト基盤は文字通りプロダクトの基盤を作っており、SRE、アカウントアグリゲーション基盤、セキュリティ、アプリケーションの基盤、品質、Eng企画と多岐にわたるチームになっています。普段は組織運営であったり困ったことに相談乗ったり、暇を見つけてコード書いたりしています。よろしくおねがいします！

freeeではサービスの安定稼働を重視しており、SREではデプロイの高速化やカナリアリリースなどのような「仮にまずいリリースがでてもすぐに引っ込める」仕組みの開発をしています。もちろんサービス障害が発生しないようにQAチーム中心に対策していますが、失敗はある前提の元でいかにリカバリを素早くできるかも大切にしています。これはこれでどこかで記事にしたいですが、今回は別の話です。

障害が発生しないように対策していますが、それでもサービスの進化とともに課題も生まれてきて予期せぬサービス障害を引き起こすケースがまれに発生します。障害の根本原因はさまざまです。そこで、サービス障害が発生したらなぜそれが発生したのだろう？というのを振り返り、組織的な課題や技術的な課題を見つけて改善していきます。

社内では「なぜなぜ分析」と呼び、社内で定義した障害レベルに応じて「なぜ？」とN階層まで深ぼっていきます。経験的には3階層くらい深堀ると徐々に本質的な課題が見えてくるので、発生した現象に対して「なぜ？」を3階層以上問い続けるのをオススメします。これはこれでどこかで記事にしたいですが、今回は別の話です。

サービス障害の原因の一つとしてミドルウェア起因の障害があるかと思います。超意訳で「ちゃんとドキュメントを読んで、ちゃんと使いましょう」みたいな振り返りで解決するケースもありますが、ミドルウェアの挙動をしっかり追いかけて特性を理解することは結構大事だと思っています。また障害に限らず、新しいミドルウェアを導入する際にある程度検証するかと思いますが、検証しているなかでどうしても不可解な挙動に悩まされることは経験ある方もいるかと思います。なので、色々学びがある（それ以上に楽しい！）のでミドルウェアのソースコードを一緒に読んでみましょう、というのを社内でたまにやります。いくつかのミドルウェアのソースコードリーディングの事例を紹介したいと思います。

なお、この記事で取り上げているソースコードのバージョンが古いものもありますが、過去に調べたものを使っているためです。現時点で使っているバージョンではないのでその点はご承知おきください。

ソースコードリーディングの準備

大抵のミドルウェアのコードはそこそこ大きいです。先頭から読み始めるとすぐに挫折するので興味あるところだけに絞るとよいです。例えば「xxの機能が想定しない挙動をした」という場合は、xxの機能のエントリポイントを見つけてそこだけを深ぼっていきます（これはミドルウェアに限った話ではないですね）。過去の経験からこんな感じで読んだり、読む準備をすると良いんじゃないかなというのをご紹介します。

デバッグビルドとデバッガで止める方法を探す

エディタだけでコードを読むのは結構大変です。動かしながらコード追いかけるのをおすすめします。

• 大抵の場合はデバッグビルドをするためのオプションが用意されているので、configureを動かす前にオプションを探す
• C/C++の場合、コンパイラの最適化が走らないようにオプションを制御します（CFLAGSで無理やり-O0を渡すとか）
  • 最適化が効いた状態でデバッガを起動するとレジスタに書かれたりして変数のダンプが大変になります
• 勇気を持って必要ないところ（もしくは細かすぎる挙動のところ）は読まない、というのも大事
• データ構造等は紙とペンつかって書き出すのも大事

あると便利ツール

コマンド名	用途
lsof	開いているファイルやソケットを調べる
procfs	プロセスの状態を色々調べたいときにみる
netstat, ss	ネットワークの接続状況などを調べる
tcpdump	何送っているんだろう？と調べたい場合。暗号化されたら見てもわからない
ipcs	shared memoryを調べたい場合（めったに使わない）
strace	システムコールをトレース

知っておくとあたりを付けやすい

• 読みたい機能に関連したシステムコールからbreakpointを貼ることで目的の場所に早く行くことができるので、システムコール名と役割はなんとなく知っていると良い
  • たとえば詳解UNIXプログラミング
  • シグナル
• サーバー実装のテクニック
  • self pipe trick
  • Cの場合はメモリプール
  • daemon処理
  • マルチスレッド、マルチプロセス(都度forkする、pre-fork)
  • などなどあるが、いくつかコードを読むと「あ、このテクニックどこかでもみたことある」と気づけるはず

ではいくつかやっていきましょう。

nginx

まだALBが存在していない時期になりますが、とある社内のサービスでCLBの前段にnginxを置きたい要件がありました。nginxがinternal CLBにproxy passするという設定を入れていたのですが、CLBのインスタンスが入れ替わってIPアドレスも変わった場合に、接続タイムアウトが頻発する問題が発生しました。挙動的にCNAMEの結果をTTL無視してキャッシュしているんだろうなと想像したのですが、念のため確認することにしました。ちなみに最新のコードでどのような挙動になっているかは確認していません。ぜひ確認してみてください。

debug build

1.11.12ですが最新版でも恐らく同じような方法です。

wget https://github.com/nginx/nginx/archive/release-1.11.12.tar.gz
tar zxvf release-1.11.12.tar.gz
cd nginx-release-1.11.12
sudo apt-get install gdb emacs make libzip-dev
./auto/configure --prefix=$HOME/nginx --with-debug --without-http_rewrite_module
make install

起動

こんな感じなのを設定します。resolverはresolv.confにかいてあるアドレスを書いてください。

events {
  worker_connections  4096;
}

http {
  server {
    listen 8800;
    location / {
      resolver xx.xx.xx.xx valid=30s; # ここは自宅の環境等のresolv.confを調べてください
      resolver_timeout 3s;
      proxy_pass http://www.freee.co.jp; # これは適当
    }
  }
}

以下のコマンドでnginxを立ち上げます。親プロセスと子プロセスが一個立ち上がります。子プロセスが実際のworkerです。

% ~/nginx/sbin/nginx
% ps auwwfx (MacOSのpsだと f オプションないです) で、子プロセスのPIDをメモってください。
% gdb -p 上のpid

breakpoint

proxy passするということは、とうぜんconnect(2)をどこかで呼び出しているはずなので、まずはソースコードをざっくり検索します。

 % grep -r 'connect(' .
./event/ngx_event_openssl_stapling.c:static void ngx_ssl_ocsp_connect(ngx_ssl_ocsp_ctx_t *ctx);
./event/ngx_event_openssl_stapling.c:    ngx_ssl_ocsp_connect(ctx);
...
./http/ngx_http_upstream.c:static void ngx_http_upstream_connect(ngx_http_request_t *r,
./http/ngx_http_upstream.c:static ngx_int_t ngx_http_upstream_test_connect(ngx_connection_t *c);
./http/ngx_http_upstream.c:            ngx_http_upstream_connect(r, u);
./http/ngx_http_upstream.c:    ngx_http_upstream_connect(r, u);
./http/ngx_http_upstream.c:    ngx_http_upstream_connect(r, u);
./http/ngx_http_upstream.c:ngx_http_upstream_connect(ngx_http_request_t *r, ngx_http_upstream_t *u)
./http/ngx_http_upstream.c:    if (ngx_http_upstream_test_connect(c) != NGX_OK) {
./http/ngx_http_upstream.c:    if (!u->request_sent && ngx_http_upstream_test_connect(c) != NGX_OK) {
./http/ngx_http_upstream.c:    if (!u->request_sent && ngx_http_upstream_test_connect(c) != NGX_OK) {
./http/ngx_http_upstream.c:ngx_http_upstream_test_connect(ngx_connection_t *c)
./http/ngx_http_upstream.c:                                    "kevent() reported that connect() failed");
./http/ngx_http_upstream.c:            (void) ngx_connection_error(c, err, "connect() failed");
./http/ngx_http_upstream.c:    ngx_http_upstream_connect(r, u);
...

なんとなくupstreamに対してconnectしている↑のあたりが怪しいと推測できるので、片っ端からbreakpointを貼っていきます。

• 読みたい処理が決まったら、多分通るんだろうなと思う関数を見つけてbreakpointを貼ってみる
• 止まらなかった場合は別にbreakpointを貼る
  • 止まったらbacktraceを bt コマンドで取る
• debuggerだけでなく、他のツールも組み合わせて読む
  • 今回の場合はupstreamへのconnect(2)のタイミングを知りたかった
• gdbでstep実行しつつ、netstat -ntで、www.freee.co.jpに接続する(ESTABLISHED)タイミングをみつける
• primitiveなところまでたどり着いたら、今度は逆に抽象度を上げていって、必要なさそうな箇所はすっとばす
• いい具合で調査を切り上げる（はまってそのまま読み続けてもok）

proxy passの挙動

コードを読んで見るとproxy_passの名前解決は2つ挙動があることがわかりました。

• proxy_passに直接proxy先を書いてある場合は、nginx起動時にgethostbyname()をやって、TTL無視してそのまま再利用する(いままでの設定)
• proxy先を一旦変数に入れてやると、resolverの設定を使って自前でDNSに問い合わせる

DNS lookupを自前でする箇所

• gethostbyname()を使わずに、nginxのソースコード内でDNS queryを組み立ててUDP(or TCP)で指定したDNS serverへ送る
• DNSへ送るデータのフォーマットはRFC1035を見てみてください

(gdb) bt
#0  ngx_resolve_name (ctx=0xc72570) at src/core/ngx_resolver.c:412
#1  0x00000000004573bc in ngx_http_upstream_init_request (r=r@entry=0xc78730) at src/http/ngx_http_upstream.c:750
#2  0x0000000000457d02 in ngx_http_upstream_init (r=r@entry=0xc78730) at src/http/ngx_http_upstream.c:532
#3  0x000000000044af39 in ngx_http_read_client_request_body (r=r@entry=0xc78730,
    post_handler=0x457c1f <ngx_http_upstream_init>) at src/http/ngx_http_request_body.c:84
#4  0x0000000000478054 in ngx_http_proxy_handler (r=0xc78730) at src/http/modules/ngx_http_proxy_module.c:929
#5  0x000000000043e22c in ngx_http_core_content_phase (r=0xc78730, ph=<optimized out>)
    at src/http/ngx_http_core_module.c:1386
#6  0x0000000000438f33 in ngx_http_core_run_phases (r=r@entry=0xc78730) at src/http/ngx_http_core_module.c:860
#7  0x0000000000439042 in ngx_http_handler (r=r@entry=0xc78730) at src/http/ngx_http_core_module.c:843
#8  0x0000000000441540 in ngx_http_process_request (r=r@entry=0xc78730) at src/http/ngx_http_request.c:1921
#9  0x00000000004441f2 in ngx_http_process_request_headers (rev=rev@entry=0x7fa63bdd20d0)
    at src/http/ngx_http_request.c:1348
#10 0x0000000000444507 in ngx_http_process_request_line (rev=rev@entry=0x7fa63bdd20d0)
    at src/http/ngx_http_request.c:1028
#11 0x0000000000444f1c in ngx_http_wait_request_handler (rev=0x7fa63bdd20d0) at src/http/ngx_http_request.c:503
#12 0x0000000000435b66 in ngx_epoll_process_events (cycle=0xc72f10, timer=<optimized out>, flags=<optimized out>)
    at src/event/modules/ngx_epoll_module.c:902
#13 0x000000000042bc3a in ngx_process_events_and_timers (cycle=cycle@entry=0xc72f10) at src/event/ngx_event.c:242
#14 0x0000000000433630 in ngx_worker_process_cycle (cycle=0xc72f10, data=<optimized out>)
    at src/os/unix/ngx_process_cycle.c:749
#15 0x0000000000431f92 in ngx_spawn_process (cycle=cycle@entry=0xc72f10,
    proc=proc@entry=0x43359d <ngx_worker_process_cycle>, data=data@entry=0x0,
    name=name@entry=0x48b72f "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:198
#16 0x0000000000433795 in ngx_start_worker_processes (cycle=cycle@entry=0xc72f10, n=1, type=type@entry=-3)
    at src/os/unix/ngx_process_cycle.c:358
#17 0x0000000000434226 in ngx_master_process_cycle (cycle=cycle@entry=0xc72f10) at src/os/unix/ngx_process_cycle.c:130
#18 0x000000000040c854 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:375

upstreamにconnect(2)するところ

(gdb) bt
#0  ngx_event_connect_peer (pc=pc@entry=0xc79720) at src/event/ngx_event_connect.c:172
#1  0x0000000000456265 in ngx_http_upstream_connect (r=r@entry=0xc78730, u=u@entry=0xc79710)
    at src/http/ngx_http_upstream.c:1485
#2  0x000000000045778d in ngx_http_upstream_resolve_handler (ctx=0xc72570) at src/http/ngx_http_upstream.c:1210
#3  0x000000000042683a in ngx_resolver_process_a (ans=<optimized out>, trunc=<optimized out>, nan=<optimized out>,
    qtype=<optimized out>, code=<optimized out>, ident=<optimized out>, n=<optimized out>, buf=0x7fff6eabf670 "",
    r=0xc8b3a0) at src/core/ngx_resolver.c:2440
#4  ngx_resolver_process_response (r=0xc8b3a0, buf=buf@entry=0x7fff6eabf750 "}\223\201\200", n=<optimized out>,
    tcp=tcp@entry=0) at src/core/ngx_resolver.c:1844
#5  0x0000000000427d68 in ngx_resolver_udp_read (rev=0x7fa63bdd2130) at src/core/ngx_resolver.c:1585
#6  0x0000000000435b66 in ngx_epoll_process_events (cycle=0xc72f10, timer=<optimized out>, flags=<optimized out>)
    at src/event/modules/ngx_epoll_module.c:902
#7  0x000000000042bc3a in ngx_process_events_and_timers (cycle=cycle@entry=0xc72f10) at src/event/ngx_event.c:242
#8  0x0000000000433630 in ngx_worker_process_cycle (cycle=0xc72f10, data=<optimized out>)
    at src/os/unix/ngx_process_cycle.c:749
#9  0x0000000000431f92 in ngx_spawn_process (cycle=cycle@entry=0xc72f10,
    proc=proc@entry=0x43359d <ngx_worker_process_cycle>, data=data@entry=0x0,
    name=name@entry=0x48b72f "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:198
#10 0x0000000000433795 in ngx_start_worker_processes (cycle=cycle@entry=0xc72f10, n=1, type=type@entry=-3)
    at src/os/unix/ngx_process_cycle.c:358
#11 0x0000000000434226 in ngx_master_process_cycle (cycle=cycle@entry=0xc72f10) at src/os/unix/ngx_process_cycle.c:130
#12 0x000000000040c854 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:375

なので、当時の回避策として以下のような設定をしました。

events {
  worker_connections  4096;
}

http {
  server {
    listen 8800;
    location / {
      resolver xx.xx.xx.xx valid=30s;
      resolver_timeout 3s;
      set $server "www.freee.co.jp"; #これは適当に
      proxy_pass http://$server;
    }
  }
}

unicorn

unicornはRubyで書かれたRackアプリケーションサーバーです。freeeで使っています。unicornは以下の特徴を持っています。

• multi processでpre fork型
• hot restartができる

このhot restartは実際にどういう挙動で、本番に入れる際にどういうリスクがありそうか調べることにしました。

debug準備

ダミーアプリの準備

unicornを動かすためにrailsアプリを生成します。

bundle exec rails new . -B -d mysql --skip-turbolinks --skip-test

Gemfileに以下の行を追加してbundle installします。

gem 'pry'
gem 'pry-remote'
gem 'pry-byebug'
gem 'unicorn'

config/unicorn.rb

こんな感じのを用意します。

worker_processes Integer(ENV["WEB_CONCURRENCY"] || 3)
timeout 15
preload_app true

remote_pryを仕込む

bundle installしてインストールしたunicornのソースコードを直接編集します。例えばSIGUSR2の挙動を調べたい場合はhttp.rbの以下のあたりのコードを追加します。

@@ -305,6 +305,8 @@
         logger.info "master done reopening logs"
         soft_kill_each_worker(:USR1)
       when :USR2 # exec binary, stay alive in case something went wrong
+        require 'pry-remote'
+        binding.remote_pry
         reexec
       when :WINCH
         if $stdin.tty?

修正したらunicornを立ち上げます。

% bundle exec unicorn_rails -c config/unicorn.rb -E development

リモートデバッグする

ps auwwfxで親プロセスのPIDを探し、 kill -USR2 pid でシグナルを送ります。そうするとunicorn側で以下のようなログが出ます。

[pry-remote] Waiting for client on druby://127.0.0.1:9876

でたら、remote debugの準備で以下のコマンドを叩きます。

 % bundle exec pry-remote

そうするとunicornを起動したコンソールがdebug可能状態になります。

[pry-remote] Client received, starting remote session
[pry-remote] Remote session terminated
[pry-remote] Ensure stop service

From: /home/y-asaba/dev/testapp/vendor/bundle/ruby/2.4.0/gems/pry-remote-0.1.8/lib/pry-remote.rb @ line 321 Object#remote_pry:

    319: def remote_pry(host = PryRemote::DefaultHost, port = PryRemote::DefaultPort, options = {})
    320:   PryRemote::Server.new(self, host, port, options).run
 => 321: end

[1] pry(#<Binding>)>

あとはお好きにどうぞ。

Redis

O(n)の処理を呼んでしまったためにパフォーマンスが劣化した障害がありました。振り返り後に社内で勉強会を開催しました。Cで書かれておりだいたいnginxと同じような感じで読みすすめることができます。細かい手順は以下のスライドに書いてあるのでそちらをご覧ください。

speakerdeck.com

環境作るのが面倒な場合はDockerfileも用意してありますのでご自由にお使いください。

github.com

MySQL

freeeではMySQLを使っています。instant add columnのニュースが来たときは「これは使えれば最高だが本当に大丈夫？」と思い、2018年のadvent calendarで書きました。（裏advent calendarなので公式blogではないです）

y-asaba.hatenablog.com

MySQLはこのなかで一番巨大なので、ソースコードを見る前にRDBMSのなんとなくの構造を先に理解しておくと捗るかと思います。コードを見つつ以下の資料を参考にしてみてください。

• MySQL :: MySQL Internals Manual
• https://www.amazon.co.jp/Database-Internals-Distributed-Systems-English-ebook/dp/B07XW76VHZ/

おわりに

デバッガを使うことで動かしながらコードを読む方法をいくつか紹介しました。大抵の挙動はドキュメントに書かれていることが多いですが、細かいところはコード見ないとようわからんというケースも一方では僅かではありますがありますので、今回紹介した手法を用いてぜひミドルウェアのソースコードリーディングを楽しんでみてください！不具合を見つけてPull Requestも送ってあげれば喜ばれると思います。

次回は会計freeeのフロントエンドからバックエンドまで開発しまくっているkemuridama氏です。お楽しみに！