monit 5.4 のバグ - マルチスレッドでfork(2)してデッドロック

プロダクション環境で使用していた monit 5.4 がデッドロックを起こしていたので調査をしていました。なお、本エントリで記述されているバグは monit 5.5 で修正されています

要約

長い内容なので最初にまとめておくと

• monit はマルチスレッドアプリケーションである
• monit 5.4 には fork(2) 後に localtime_r(3) を呼び出す処理があり、これらが稀にデッドロックを引き起こす
  • monit 5.5 系では fork(2) 前に 変更された。
• /usr/bin/gstack は便利ツール
• マルチスレッド + fork(2) でデッドロックするパターンに要要注意

これらの内容に興味がある方は読み進めていただければ ...

問題になった monit プロセスの運用について

該当の monit は 定期的に監視プロセスを再起動する役割で使われています。再起動をする際に monit restart <プロセス名> を実行しますが、その後 monit がコマンドに応答しなくなるという状態が報告されていました。

monit プロセスのプロセスツリーと strace の

問題が起きた時点での プロセスツリーは下記の様になっていると報告されていました。

root      4071  0.0  0.0 125096  1376 ?        Sl   Feb14   0:42 /usr/bin/monit
root     15415  0.0  0.0 125096   748 ?        S    05:00   0:00  \_ /usr/bin/monit

また strace の結果も上がっていて

• 親プロセスは waitpid(2) でブロック
• 子プロセスは futext(2) でブロック

という状態でした。初見では、なにかデッドロックしているのかな、という予想だけで原因は全然分かりませんでした。

monit 5.4 と monit 5.5 での CHANGES を調べた

プロダクションで利用してたのがバージョンが 5.4 だったので、(現時点で)最新のバージョン 5.5 の CHANGES を追ったところ下記の内容が見つかりました

BUGFIXES:

* Fix the rare hung on linux which may occur during program execution.
  Thanks to Nick Upson for report.

今回の現象に近い感じですが記述がちょいと不明瞭です。 rare hung とは何がどのタイミングで「ハング」するのかなと ? 加えて monit のソースはプライベートリポジトリで管理されており、この CHANGES がどの変更内容/コミットを指すのかが分かりませんでした。 ( なおバグレポートはちゃんとあってこのエントリを書いてる際に見つけました.... http://lists.gnu.org/archive/html/monit-general/2012-08/msg00020.html ぐぬぬ、検索力の低さが問題だったのか.... )

ここまで調べた内容で「とりあえずバージョンあげたら直るかも？」と issue にレス してみたのですが、RPMを入れ替えたりpuppet を更新してもらったりの作業をしてもらうには若干根拠レスで、もうちょっと粘って追って見ることにしました。 (結果バージョンアップで直ったので、この時点でアップグレードしていても「とりあえず直ったぽいねー」という解決になったでしょう)

/usr/bin/gstack でバックトレース解析

後日、同様の現象が再度起きたので /usr/bin/gstack ( gdb のRPMに付属 ) でバックトレースを取りました。便利〜

• 親プロセスのトレース

$ sudo gstack 28002
Thread 2 (Thread 0x41b4c940 (LWP 28003)):
#0  0x0000003d22ecae46 in poll () from /lib64/libc.so.6
#1  0x000000000041c143 in can_read_ms ()
#2  0x0000000000431a6c in start_httpd ()
#3  0x000000000041a528 in thread_wrapper ()
#4  0x0000003d23606617 in start_thread () from /lib64/libpthread.so.0
#5  0x0000003d22ed3c2d in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x2b358ae26cb0 (LWP 28002)):
#0  0x0000003d2360e4af in waitpid () from /lib64/libpthread.so.0
#1  0x0000000000420ca1 in spawn ()
#2  0x0000000000415aa6 in do_stop ()
#3  0x0000000000415dc2 in control_service ()
#4  0x0000000000429945 in do_scheduled_action ()
#5  0x0000000000429a38 in validate ()
#6  0x000000000041428d in do_action ()
#7  0x0000000000414c62 in main ()

• 子プロセスのトレース

$ sudo gstack 29473
#0  0x0000003d22edf9ee in __lll_lock_wait_private () from /lib64/libc.so.6
#1  0x0000003d22e8d0dd in _L_lock_1685 () from /lib64/libc.so.6
#2  0x0000003d22e8ce27 in __tz_convert () from /lib64/libc.so.6
#3  0x000000000043a8d5 in Time_string ()
#4  0x0000000000420ad5 in spawn ()
#5  0x0000000000415aa6 in do_stop ()
#6  0x0000000000415dc2 in control_service ()
#7  0x0000000000429945 in do_scheduled_action ()
#8  0x0000000000429a38 in validate ()
#9  0x000000000041428d in do_action ()
#10 0x0000000000414c62 in main ()

バックトレースがとれた事でバグを起こすまでの実行パスが明確になりました。

• 親プロセスは spawn() で 子プロセスを fork(2) して waitpid(2) で待ちブロックしている
• 子プロセスは spwan() で fork(2)後、 Time_string() 内のロック解放待ちでブロックしている
  • strace を取ると futex(, FUTEX_WAIT_PRIVATE, ...) でブロックしている

これらから monit は監視しているプロセスの起動/停止する際に設定ファイルに記述されたfork(2)+exec(2)してコマンドを実行するが、まれにデッドロックを起こすということまで分かりました。

Time_string の実装を追う

バックトレースに出て来る Time_string() の中で localtime_r(3) を呼び出しています。

char *Time_string(time_t time, char *result) {
#define i2a(i) (x[0]=(i/10)+'0', x[1]=(i%10)+'0')
        if (result) {
                char x[2];
                struct tm ts; 
                /* This implementation needs to be fast and is around 50%
                   faster than strftime */

                /* ココ */
                localtime_r((const time_t *)&time, &ts);
                memcpy(result, "aaa, xx aaa xxxx xx:xx:xx\0", 26);
                /*              0    5  8   1214 17 20 2326 */
                memcpy(result, days+3*ts.tm_wday, 3); 

localtime_r(3) 以下の libc の実装を追うのも億劫で、手がかりが無かったので localtime_r, __tz_convert といった単語で Google検索していたところ @IT のフォーラムで同種のデッドロック問題が記述されていました

マルチスレッド と fork(2) でのデッドロック

 glibcのソースを軽く眺めてみました。
 マルチスレッド動作の時には、localtime等のタイムゾーン情報を使う関数群は、共通のロックを使って排他制御し> ているようです。
 なので今回の症状からすると、そういった関数によって丁度ロックがかかっている状態で
 　1. fork により子プロセスを生成した
 　2. 非同期シグナル受信によりシグナルハンドラへ制御が移った
 のいずれかが発生し、更に localtime_r が ( 1. なら子プロセス、2. ならハンドラで ) 呼ばれてロックを取得しようとし、デッドロックに陥った、と考えられます。
 その原因としては、一つ前のコメントに挙げたサイトにあるような問題点を、そのアプリケーションが孕んでいたのではないでしょうか。

＠IT総合トップ > ＠IT CORE > 会議室 > Linux Square会議室 > localtime_r　ｺｰﾙ で応答なし より引用

また、フォーラムに貼られていたブログを読んだところ、マルチスレッド + fork(2) を使用する際 デッドロックを起こすパターンがあることを知りました

鉄則3: マルチスレッドのプログラムでのforkはやめよう


マルチスレッドのプログラムで、「自スレッド以外のスレッドが存在している状態」でfork*1を行うと、さまざまな問題を引き起こす可能性があります。「問題」の典型例としては、子プロセスのデッドロックが挙げられます。問題の詳細を把握しないまま、マルチスレッドのプログラムで不用意にforkするのはやめましょう！

memologue UNIX上でのC++ソフトウェア設計の定石 (3) より引用

これらを読んで今回の現象が マルチスレッド+fork(2) のデッドロックのパターンに該当することまで絞れました。

monit 5.4 と monit 5.5 の diff を確認

最新のリリースである 5.4系との diff を 改めて追ってみたところ下記の変更をみつけました

• 説明のために一部省略して記述

--- monit-5.4/src/spawn.c   2012-05-06 18:40:45.000000000 +0900
+++ monit-5.5/src/spawn.c   2012-08-20 23:39:52.000000000 +0900


+        Time_string(Time_now(), date);
         pid= fork();
         if(pid < 0) {
                 LogError("Cannot fork a new process\n");  
                 exit(1); 
         }

fork(2) する前に Time_string() -> localtime_r(3) を呼び出す変更になっています。この diff をもってして 冒頭の CHANGES に書かれていた Fix the rare hung on linux which may occur during program execution. が今回の検証に相当することに確信が持てました

その後の対応

ここに上げたことを GitHub の issue にレポートして monit 5.4 -> monit 5.5 のアップグレード作業を進めてもらうことになりました ( レポートした後すぐに @tnmt さんが電光石火の勢いでRPM作ったり yum install したりの作業していた!!! )

まとめ

過去のバグ、コミットのトレーサビリティ

プログラムにはバグがつきものですが、同種のバグを踏んだ人が解決を求める場合にコミットログや Changelogでもって十分に追跡可能にしておくには 一体全体どのようやったらよいものかな〜 ということを考えました。「git commit -m "うごかないの直した"」みたいなコミットログには積極的に椅子かヒートトマホークを投げつける人格が形成されそうです。

バグのパターン化

結果的に調査に時間がかかってしまいましたが、マルチスレッド+fork(2)+デッド ロック という特異なパターンなので今後は、同種のバグには鼻が利きそうです (期待含む)。これらの知見を同僚のエンジニアさんにフィードバックして何らかの糧にしようと思っています。

そんな経緯の長文乙ブログエントリでした。