RailsのデプロイとUnicornのトラブルシューティング

デプロイしたけど何かおかしい？

先日、Unicornを採用しているウェブアプリで問題が発生しました。デプロイした最新のコードが実行されているように見えますが、時々古いコードの挙動を見せるのです。

今回はそのトラブルシューティングの一部始終を紹介しながら、Unicornのホットデプロイ（ダウンタイムなしでアプリケーションを更新すること）の仕組みをおさらいします。担当は私、去年KRAYに入社しました@irohirokiです。よろしくお願いします。

問題

まずはデプロイ先のサーバにSSHして、Unicornのプロセスを調べてみました。

$ ps ax -H
  PID TTY      STAT   TIME COMMAND
 3159 ?        Sl     0:00   unicorn master (old) -c unicorn.conf -D
 3162 ?        Sl     0:00     unicorn worker[0] -c unicorn.conf -D
 3164 ?        Sl     0:00     unicorn worker[1] -c unicorn.conf -D
 3169 ?        Sl     0:00     unicorn master -c unicorn.conf -D
 3173 ?        Sl     0:00       unicorn worker[0] -c unicorn.conf -D
 3175 ?        Sl     0:00       unicorn worker[1] -c unicorn.conf -D

無関係な部分は省いてありますが、だいたい上のような状態でした。Unicornは複数のworkerプロセスを一つのmasterプロセスが管理する構成です。ところが問題発生時は上の通り、本物のmasterプロセスとは別に、(old)のついたmasterプロセスとそのworkerが存在していました。これはデプロイ前の古いコードを走らせているプロセスです。そのため、HTTPリクエストを新旧２系統のunicornが取り合って、新しいコードが実行されたり古いコードが実行されたりしていました。正常ならば下のようになるはずです。

$ ps ax -H
  PID TTY      STAT   TIME COMMAND
 3169 ?        Sl     0:00   unicorn master -c unicorn.conf -D
 3173 ?        Sl     0:00     unicorn worker[0] -c unicorn.conf -D
 3175 ?        Sl     0:00     unicorn worker[1] -c unicorn.conf -D

ホットデプロイの流れ

ここでUnicornの正常なホットデプロイの流れをおさらいしておきます。

1. 新しいmasterを生成
   masterプロセスにUSR2シグナルを送ると、masterプロセスは新しいmasterプロセスを生成して、自分と同じコマンドを最初から実行させます。
2. 新しいworker誕生
   新しいmasterプロセスの実行に問題がなければ、自動的に設定した数のworkerプロセスが新masterから生まれます。
3. 古いworker終了
   新しいworkerが無事誕生したら、古いmasterにQUITシグナルを送ります。QUITシグナルを受け取ったmasterプロセスは、自分のworkerたちに同じくQUITシグナルを送ります。そうするとworkerプロセスたちは、自分が現在処理中のリクエストを処理し終わった時点で終了します。
4. 古いmaster停止
   QUITを受け取ったmasterは、workerが終了したのを確認して自分自身も終了します。

よってホットデプロイを成功させるには、まずmasterにUSR2を送り、新しいmasterおよびworkerが正常に起動できたことを確認して、古いmasterにQUITを送る、となります。

しかしこれらの作業を手でやることはありません。まっとうなWeb developerなら必ず自動化します。ではその自動化ツールと、上記の具体的な実施箇所を見てみましょう。

capistrano-unicorn

Capistranoは伝統的なデプロイの自動化ツールです。Rubyの表現力を生かして、言わば“実行できる設定ファイル”を書くことができます。capistrano-unicornは、CapistranoでUnicornをサポートするための拡張です。

早速ホットデプロイに関係する部分を見てみましょう。

  desc 'Reload Unicorn'
  task :reload, :roles => :app, :except => {:no_release => true} do
    if remote_file_exists?(unicorn_pid)
      logger.important("Stopping...", "Unicorn")
      run "#{try_sudo} kill -s USR2 `cat #{unicorn_pid}`"
    else
      logger.important("No PIDs found. Starting Unicorn server...", "Unicorn")
      # （略）
    end
  end

（https://github.com/sosedoff/capistrano-unicorn/blob/master/lib/capistrano-unicorn/capistrano_integration.rb#L57周辺）

中程でunicornプロセスにUSR2を送っているのがわかります。（よく見るとログのメッセージが間違ってますが、これは後で作者にパッチを送ります。）このtaskはunicornという名前空間にあるので、cap unicorn:reloadでUSR2を送れることになります。

続いてQUITを送る必要がありますが、これはcapistranoのtaskではなく、Unicornの設定ファイルの中に書きます。

preload_app true

before_fork do |server, worker|
  old_pid = "#{server.config[:pid]}.oldbin"
  if File.exists?(old_pid) && server.pid != old_pid
    begin
      Process.kill("QUIT", File.read(old_pid).to_i)
    rescue Errno::ENOENT, Errno::ESRCH
      # someone else did our job for us
    end
  end
end

（https://github.com/sosedoff/capistrano-unicorn/blob/master/examples/rails3.rb#L36周辺を改変）

before_forkというフックの中で古いmasterのプロセスIDを読み込んでQUITを送っています。before_forkは、masterがworkerを産む直前に実行する処理を登録するメソッドです。こうして古いworkerとmasterは削除されます。

しかし、上で述べたホットデプロイの手順には「新しいmasterおよびworkerが正常に起動できたことの確認」があります。before_forkの時点でその確認はできているのでしょうか？

実はそれを担保するのが、上のスニペットの先頭にあるpreload_app trueです。この設定により、masterがworkerを産む前に新しいコードがロードされ、初期化が実行されます。よってbefore_forkが実行される時には、HTTPリクエストを受け付ける準備ができていると考えられるのです。これでホットデプロイがcapistrano-unicornでどのように実現されているかがわかりました。

仮説と検証

以上の調査結果と理論を照らし合わせて、問題が発生する経緯について仮説を立ててみます。

Unicornのプロセスを見ると、新しいmasterとworkerが動作していますので、USR2を受け取って新しいコードをロードし、forkまでしていることがわかります。しかし、before_forkで送られたはずのQUITの効果が見られません。つまりQUITシグナルがどこかで失われたと考えられます。

そこで、新しいコードと使用しているgemを「QUIT」で検索してみたところ、gtk2 gemがQUITを無視していることがわかりました。

#else
        sigfunc[0] = signal(SIGHUP, SIG_IGN);
        sigfunc[1] = signal(SIGINT, SIG_IGN);
        sigfunc[2] = signal(SIGQUIT, SIG_IGN);
        sigfunc[3] = signal(SIGBUS, SIG_IGN);
        sigfunc[4] = signal(SIGSEGV, SIG_IGN);
        sigfunc[5] = signal(SIGPIPE, SIG_IGN);

（http://ruby-gnome2.svn.sourceforge.net/viewvc/ruby-gnome2/ruby-gnome2/trunk/gtk2/ext/gtk2/rbgtkmain.c?revision=4697&view=markup）

対策

この問題を解決するには、gtk2 gemを改造するか、QUITを使わない方法を考えだすしかありません。他人のgemを安易に修正するのはトラブルの元なので、自分のコードで何とかすることにします。

実はUnicornはWINCHというシグナルにもハンドラが設定されており、masterがこれを受け取るとworkerを行儀よく終了させます。つまりQUITの仕事の一部を達成できます。ではWINCHを使うことにして、あとはどうやって古いmasterを停止するかです。

gtk2はINTやHUP、TERMといった一般的な停止シグナルを全て無視するので、KILLを送ることにします。しかし、WINCHを送った後もworkerはやりかけの処理を続けますから、KILLを送るのが早過ぎるとworkerを看取る人がいなくなってしまい、うまくありません。

一般的に、ウェブアプリケーションサーバにはタイムアウトがあります。HTTPリクエストに対する処理時間が長過ぎる場合に、エラーとして処理する作法です。本アプリケーションの場合、タイムアウトは30秒になっていました。つまりWINCHを送ってから30秒後には、どんなworkerも終了またはエラーとして処理されているわけです。よってWINCHを送ってから30秒後にKILLを送ることにします。

以上のことを踏まえてbefore_forkを書いてみます。

before_fork do |server, worker|
  old_pid = "#{server.config[:pid]}.oldbin"
  if File.exists?(old_pid) && server.pid != old_pid
    begin
      Process.kill("WINCH", File.read(old_pid).to_i)
      sleep 30
      Process.kill("KILL", File.read(old_pid).to_i)
    rescue Errno::ENOENT, Errno::ESRCH
      # someone else did our job for us
    end
  end
end

WINCHを送り、30秒後にKILLを送るようにしました。しかしこれは不正解です。これではせっかくmasterが起動してもforkまでに30秒空費することになります。その点を考慮したのが下の設定です。

before_fork do |server, worker|
  old_pid = "#{server.config[:pid]}.oldbin"
  if File.exists?(old_pid) && server.pid != old_pid
    begin
      Process.kill("WINCH", File.read(old_pid).to_i)
      Thread.new {
        sleep 30
        Process.kill("KILL", File.read(old_pid).to_i)
      }
    rescue Errno::ENOENT, Errno::ESRCH
      # someone else did our job for us
    end
  end
end

30秒待つのは別のスレッドにしました。これでQUITを使わずにホットデプロイを達成できました。

gtk2はマルチプラットフォームのGUIウィジェットや音声・動画処理フレームワークなどを提供する優れたライブラリです。今回のプロジェクトではPDF文書をパース／生成するのに利用しました。このような強力なライブラリとUnicornを併用できないのは勿体ないことだと思います。gtk2との併用に限らず、本エントリがUnicornの理解に役立てば幸いです。