mruby
ngx_mruby

ngx_mrubyからデーモンを立ち上げる(?)時の罠について

More than 1 year has passed since last update.

mod/ngx_mruby カレンダーの... 7日目の記事だったはずですが... 22日が空いていたのでそのまま引っ越してきました。 @udzura です。

ngx_mruby からコマンドをキックしてデーモンを立ち上げると、非同期になって便利なことがあります。ですが、 Kernel#system メソッドからキックするといくつか罠があるので、そういう話と、それを解決する mruby-clean-spwan というmgemの紹介をします。


Nginxからデーモンを作成してみる

かなりマニア用途ですが、まず、デーモンは以下のRubyスクリプトにします。


/usr/local/bin/daemon.rb

#!/usr/bin/ruby

Process.daemon

require 'logger'
fd = Logger.new("/tmp/test.log.#{$$}")

loop do
fd.info "Test!! #{Time.now}"
sleep 1
end


ngx_mrubyの設定は以下のようにします。


/etc/nginx/conf.d/default.conf

server {

listen 80 default_server;
server_name *.example.com;
location / {
mruby_content_handler /var/lib/mruby/hook.rb;
}
}

フックスクリプトはこうです。


/var/lib/mruby/hook.rb

unless system "/bin/sh -c /usr/local/bin/daemon.rb"

Nginx.rputs '{"status": "FAILURE"}'
else
Nginx.rputs '{"status": "OK"}'
end

この状態でcurlしてみると、確かに何かしらデーモンができています。

ubuntu@ubuntu-zesty:~$ curl -s localhost | jq .

{
"status": "OK"
}
ubuntu@ubuntu-zesty:~$ ps auxf
...
nginx 15206 0.0 0.1 37176 1296 ? Ss 09:55 0:00 nginx: master process /usr/sbin/nginx -c /etc/nginx/nginx.conf
nginx 15207 0.0 0.3 37600 4028 ? S 09:55 0:00 \_ nginx: worker process
nginx 15218 0.0 0.7 40548 7272 ? Sl 09:55 0:00 /usr/bin/ruby /usr/local/bin/daemon.rb


一見良さそうだけど...

このデーモンは、NginxのFile descriptor一式をそのまんま継承しています。fd0 ~ fd2はデーモンなのでもちろん開き直していますが、それ以外はNginxそのまま...。

ubuntu@ubuntu-zesty:~$ sudo ls -l /proc/15218/fd

total 0
lrwx------ 1 nginx nginx 64 Dec 22 09:58 0 -> /dev/null
lrwx------ 1 nginx nginx 64 Dec 22 09:58 1 -> /dev/null
l-wx------ 1 nginx nginx 64 Dec 22 09:58 10 -> pipe:[48162]
l-wx------ 1 nginx nginx 64 Dec 22 09:58 11 -> /tmp/test.log.15218
lrwx------ 1 nginx nginx 64 Dec 22 09:58 2 -> /dev/null
lrwx------ 1 nginx nginx 64 Dec 22 09:58 3 -> socket:[48154]
lr-x------ 1 nginx nginx 64 Dec 22 09:58 4 -> pipe:[48161]
l-wx------ 1 nginx nginx 64 Dec 22 09:58 5 -> pipe:[48161]
lrwx------ 1 nginx nginx 64 Dec 22 09:58 6 -> socket:[46974]
lr-x------ 1 nginx nginx 64 Dec 22 09:58 7 -> pipe:[48162]
lrwx------ 1 nginx nginx 64 Dec 22 09:58 8 -> anon_inode:[eventpoll]
lrwx------ 1 nginx nginx 64 Dec 22 09:58 9 -> anon_inode:[eventfd]

mrubyのKernel#systemがそのまま使っているsystem(3)は、この辺の後処理をいい感じにしてくれないのでした。元のプロセスのfdが継承されている場合、子のプロセスの処理によっては危険な場合がありますね。


close-on-exec をしてくれるclean_spawn

そこで、clean_spawnを使って書き換えてみます。


/var/lib/mruby/hook.rb

unless clean_spawn "/bin/sh", "-c", "/usr/local/bin/daemon.rb"

Nginx.rputs '{"status": "FAILURE"}'
else
Nginx.rputs '{"status": "OK"}'
end

このフックから立ち上げたデーモンは、fdの様子が変わっていることがわかります。

nginx     15271  0.0  0.7  40504  7428 ?        Sl   10:02   0:00 /usr/bin/ruby /usr/local/bin/daemon.rb

ubuntu@ubuntu-zesty:~$ sudo ls -l /proc/15271/fd
total 0
lrwx------ 1 nginx nginx 64 Dec 22 10:02 0 -> /dev/null
lrwx------ 1 nginx nginx 64 Dec 22 10:02 1 -> /dev/null
lrwx------ 1 nginx nginx 64 Dec 22 10:02 2 -> /dev/null
lr-x------ 1 nginx nginx 64 Dec 22 10:02 3 -> pipe:[48379]
l-wx------ 1 nginx nginx 64 Dec 22 10:02 4 -> pipe:[48379]
lr-x------ 1 nginx nginx 64 Dec 22 10:02 5 -> pipe:[48380]
l-wx------ 1 nginx nginx 64 Dec 22 10:02 6 -> pipe:[48380]
l-wx------ 1 nginx nginx 64 Dec 22 10:02 7 -> /tmp/test.log.15271

このパイプ 3~6 はCRubyが作成するもので、7はログファイルとしてスクリプト内部で開いたものですね。つまり、Nginx由来のfdは一切なくなっています。

具体的には、clean_spawnの内部では、


  • forkをする

  • 既存のfile descriptorに全て close-on-exec フラグを立てる

  • execをする

ということを丁寧にやっています。


さらなる罠

ですが、ここでもう一つ罠があり、この状態でNginxを再起動すると、このデーモンは綺麗に消えてしまうのでした...。

ubuntu@ubuntu-zesty:~$ sudo systemctl restart nginx                                                                                               

ubuntu@ubuntu-zesty:~$ ps auxf | grep ruby
ubuntu 15298 0.0 0.1 12960 1028 pts/0 S+ 10:06 0:00 \_ grep --color=auto ruby

だれがkillしているのでしょうか。gdbを使うと追いかけることができるので、アタッチしてみます。

nginx     15360  0.0  0.7  40580  7592 ?        Sl   10:07   0:00 /usr/bin/ruby /usr/local/bin/daemon.rb                                           

ubuntu@ubuntu-zesty:~$ sudo gdb -p 15360
GNU gdb (Ubuntu 7.12.50.20170314-0ubuntu1.1) 7.12.50.20170314-git
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 15360
[New LWP 15362]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
225 ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S: No such file or directory.
(gdb) c
Continuing.

この状態で別のターミナルから systemctl restart nginx すると... SIGTERMが、PID = 1 すなわちsystemdから送られた、ということがわかりました。

Thread 2 "ruby-timer-thr" received signal SIGTERM, Terminated.           

[Switching to Thread 0x7f7fef5d7700 (LWP 15362)]
0x00007f7feec6cd8d in poll () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) ptype $_siginfo
type = struct {
int si_signo;
int si_errno;
int si_code;
union {
int _pad __attribute__ ((vector_size(28)));
struct {...} _kill;
struct {...} _timer;
struct {...} _rt;
struct {...} _sigchld;
struct {...} _sigfault;
struct {...} _sigpoll;
} _sifields;
}
(gdb) p $_siginfo._sifields._sigchld.si_pid
$1 = 1 <- !!!

これはどういうことでしょうか。実は、デーモンのcgroupが元のnginxサービスのcgroupと同一だから起きるのでした。

nginx     15703  0.0  0.1  37176  1296 ?        Ss   10:12   0:00 nginx: master process /usr/sbin/nginx -c /etc/nginx/nginx.conf

nginx 15705 0.0 0.3 37600 3972 ? S 10:12 0:00 \_ nginx: worker process
nginx 15718 0.0 0.7 40488 7340 ? Sl 10:14 0:00 /usr/bin/ruby /usr/local/bin/daemon.rb
ubuntu@ubuntu-zesty:~$ sudo grep systemd /proc/15703/cgroup
1:name=systemd:/system.slice/nginx.service
ubuntu@ubuntu-zesty:~$ sudo grep systemd /proc/15718/cgroup
1:name=systemd:/system.slice/nginx.service

systemdは、この systemd サブシステムを再起動時に参照しています。Unitファイルで直接管理されていないプロセスに関しても、グループに所属しているプロセスには、 SIGTERM -> SIGKILL の順番でシグナルを送っているのです。 参照#29枚目


cgroupのsystemdグループを変更させる

ということで、clean_spawnにはデーモンのcgroupを移動させるためのオプションがあります。

CleanSpawn.cgroup_root_path = "/sys/fs/cgroup/systemd"

unless clean_spawn "/bin/sh", "-c", "/usr/local/bin/daemon.rb"
Nginx.rputs '{"status": "FAILURE"}'
else
Nginx.rputs '{"status": "OK"}'
end

このオプションはNginxをrootで立ち上げていないと今のところ動きませんが...

これをセットしておけば、Nginxの再起動でデーモンに影響を与えずに済みます。めでたしめでたし...

ubuntu@ubuntu-zesty:~$ sudo systemctl restart nginx          

ubuntu@ubuntu-zesty:~$ ps auxf | grep ruby
ubuntu 15820 0.0 0.0 12960 936 pts/0 S+ 10:18 0:00 | \_ grep --color=auto ruby
root 15789 0.0 0.7 40500 7356 ? Sl 10:17 0:00 /usr/bin/ruby /usr/local/bin/daemon.rb


という感じで、ngx_mrubyのマニアック処理のためのmgemを紹介しました。

やりたいことはマニアとはいえ、その過程を辿ることでLinux/UNIXの割と重要な知識が出てきましたので、書いてみました。今日はそんな感じで...。