mruby
ngx_mruby

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

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の割と重要な知識が出てきましたので、書いてみました。今日はそんな感じで...。