sonots:blog

TL; DR

daemontools の multilog を落としていない && /service/$service_name/log ディレクトリの i-node が変わると起きる

再現を試みる

デーモンのプロセスだけ落として multilog のプロセスを落としていない疑惑があったので以下のようにして再現を試みた。

service_name=てきとうな名前
if [ -s /service/$service_name ]; then
  mv /service/$service_name /service/.$service_name
  svc -dx /service/.$service_name
  rm -f /service/.$service_name
fi

シンボリックリンクを貼って再起動させる

ln -s ~/$app_name/service /service/$service_name

これで再現できると思ったのだが、multilog が継続して利用され、defunct なプロセスが生成されなかった。

再現を試みる(2)

どうやらシンボリックリンク対象のディレクトリを新規に作れば(別の i-node にすれば)発生するようだ。

service_name=てきとうな名前
if [ -s /service/$service_name ]; then
  mv /service/$service_name /service/.$service_name
  svc -dx /service/.$service_name
  rm -f /service/.$service_name
fi

cp -a ~/$app_name/service /tmp/service
sudo rm -rf /tmp/service/supervise
sudo rm -rf /tmp/service/log/supervise

rm && cp でディレクトリを作り直す(疑似デプロイ)

rm -rf ~/$app_name/service
cp -a /tmp/service ~/$app_name/service

シンボリックリンクを貼る

ln -s ~/$app_name/service /service/$service_name

これで新しく生えた multilog が defunct になった。

[supervise] <defunct>

ps でみると [multilog] <defunct> ではなく [supervise] <defunct> になっている。 なぜ supervise の下に supervise がぶら下がっているのか気になって調べた。

$ ps auxwwf
root      4448  0.0  0.0   3984   368 ?        S     2013  88:09  |   \_ supervise $service_name
root     30562  0.0  0.0      0     0 ?        Z    22:18   0:00  |   |   \_ [supervise] <defunct>

結論からいうと、fork してから execve する前に死んでいたのでプロセスの名前が [supervise] のままになっていたのであろう。

$ sudo strace -f -p 4448
[pid 14161] <... rt_sigprocmask resumed> NULL, 8) = 0
[pid 14161] execve("./run", ["./run"], [/* 1 var */]) = -1 ENOENT (No such file or directory)
[pid 14161] write(2, "supervise: fatal: unable to star"..., 70) = 70

ちなみに該当ディレクトリのパスには run ファイルがある。にも関わらず No such file or directory と言われている。

これは、$ sudo ls -l /proc/4448/cwd するとシンボリック先が (deleted) となっているのが原因で、 どうやら daemontools はディレクトリのパスではなく i-node を追っているようだ。 追っている i-node のディレクトリが消えたので run ファイルが見えなくなり、No such file or directory といって落ちている。

rm && cp しないと defunct にならない件について

rm && cp しない場合は defunct 現象が発生せず、multilog が正常に動作してしまっていたのが解せなかったので調査した。 デーモンが TERM されていて、multilog だけが生きている状況で、どのように multilog への出力が継続されるのだろうか。

こちらに以下のような記述があった。http://www.unixuser.org/~euske/doc/daemontools/myfaq/faq-1.html

じつは svscan は supervise の終了を検知するようになっており、 既知のディレクトリに対しては何度 supervise を実行しても 同じパイプのファイル記述子を使うようになっている。これによって、 たとえばデーモン用の supervise が再起動しても、log 用の supervise は そのまま継続してこの新しい supervise からログを取ることができる。

svscan がパイプを管理していて、既知のディレクトリ(i-node で識別される)に対しては良きに計らってくれるようだ。しかし、i-node が変わると継続されずに新規に multilog の起動を試みるようになり、しかしすでに起動している multilog があるためすぐに死に、 親プロセスが wait して適切に処理してくれるまでは defunct になり、親に処理されては消え、そしてまた起動を試みられ、死ぬ、を繰り返し続けることになる。

確認してみたところ、確かに svscan が持っているパイプと supervise がもっているパイプが同じだった。

# svscan
$ sudo ls -l /proc/9402/fd
lr-x------ 1 root root 64  8月  6 03:51 0 -> /dev/null
l-wx------ 1 root root 64  8月  6 03:51 1 -> pipe:[1667674317]
l-wx------ 1 root root 64  8月  6 03:51 2 -> pipe:[1667674317]
lr-x------ 1 root root 64  8月  6 03:51 6 -> pipe:[1667703193] *
l-wx------ 1 root root 64  8月  6 03:51 7 -> pipe:[1667703193] *

# supervise daemon
$ sudo ls -l /proc/19999/fd
lr-x------ 1 root root 64  8月  6 03:51 0 -> /dev/null
l-wx------ 1 root root 64  8月  6 03:51 1 -> pipe:[1667703193] *
l-wx------ 1 root root 64  8月  6 03:51 2 -> pipe:[1667674317]
lr-x------ 1 root root 64  8月  6 03:51 3 -> pipe:[1667704094]
l-wx------ 1 root root 64  8月  6 03:51 4 -> pipe:[1667704094]

# supervise log
$ sudo ls -l /proc/20000/fd
lr-x------ 1 root root 64  8月  6 03:54 0 -> pipe:[1667703193] *
l-wx------ 1 root root 64  8月  6 03:54 1 -> pipe:[1667674317]
l-wx------ 1 root root 64  8月  6 03:54 2 -> pipe:[1667674317]
lr-x------ 1 root root 64  8月  6 03:54 3 -> pipe:[1667704095]
l-wx------ 1 root root 64  8月  6 03:54 4 -> pipe:[1667704095]

# daemon
$ sudo ls -l /proc/24839/fd
lr-x------ 1 root root 64  8月  6 03:54 0 -> /dev/null
l-wx------ 1 root root 64  8月  6 03:54 1 -> pipe:[1667703193] *
l-wx------ 1 root root 64  8月  6 03:54 2 -> pipe:[1667703193] *
lr-x------ 1 root root 64  8月  6 03:54 3 -> pipe:[1667725780]
l-wx------ 1 root root 64  8月  6 03:54 4 -> pipe:[1667725780]
lr-x------ 1 root root 64  8月  6 03:54 5 -> /dev/null
l-wx------ 1 root root 64  8月  6 03:54 6 -> /dev/null

# multilog
$ sudo ls -l /proc/20056/fd
lr-x------ 1 game game 64  8月  6 03:56 0 -> pipe:[1667703193] *
l-wx------ 1 game game 64  8月  6 03:56 1 -> pipe:[1667674317] 
l-wx------ 1 game game 64 8月 6 03:56 2 -> pipe:[1667674317]