Unicorn の timeout (61s > 60s), killing で worker が死なない件

Sinatra + Unicorn + Nginx で、重たい処理があって、タイムアウトをしたのは良いのですが、何故か Unicorn が エラーを吐いただけでワーカーが死んでくれなくて、ついには稼働可能なワーカーがなくなってアクセスできない現象がおきました。

＃ワーカーが死なないので、こんな感じで食い潰される。。。

E, [2020-12-28T16:40:26.120353 #3627] ERROR -- : worker=1 PID:3634 timeout (61s > 60s), killing
E, [2020-12-28T16:40:27.122323 #3627] ERROR -- : worker=1 PID:3634 timeout (62s > 60s), killing
E, [2020-12-28T16:40:28.124271 #3627] ERROR -- : worker=1 PID:3634 timeout (63s > 60s), killing
E, [2020-12-28T16:40:29.126276 #3627] ERROR -- : worker=1 PID:3634 timeout (64s > 60s), killing
...

unicorn-worker-killer

検索すると、だいたいが、タイムアウト時間の調整とか、そもそもタイムアウトするような処理にするな、とか、そういうものばかりでして、いや、どうしてもタイムアウトになってしまったらどうなのよ？、と思いながらも、調べていると、unicorn-woker-killerというものがあるらしく、ちょっとみてみましたが、どうやらこれは、指定回数ワーカーがアクセスされたら再起動、メモリ使用量が指定量を超えたら再起動、という感じで、タイムアウトしたら再起動、というものでは無いらしいことがわかりました。

むむむ。

困った時のソースコード

しばらく色々とやってみましたが、ダメでしたので、ソースコードを見ることにしました。

killing で検索すると /unicorn/lib/unicorn/http_server.rb に何かあるようです。

真ん中あたりにある def murder_lazy_workers の中に

logger.error "worker=#{worker.nr} PID:#{wpid} timeout " \
             "(#{diff}s > #{@timeout}s), killing"
kill_worker(:KILL, wpid) # take no prisoners for timeout violations

というコードが見つかりました。これはエラーログに出ている文言と一緒なので、ここで合っているっぽいです。
コメントに何が書いてあるかは良く分かりませんが、kill_worker(:KILL, wpid)でプロセスを殺してるのがわかります。

というわけで、kill_workerを見てみます。

ん！？

下の方に def kill_worker(signal, wpid)というメソッドがあるので、見ていきます。

def kill_worker(signal, wpid)
  Process.kill(signal, wpid)
rescue Errno::ESRCH
  worker = @workers.delete(wpid) and worker.close rescue nil
end

。。。ん！？ @workers から wpid を削除するのって、Process.killでエラーになった時だけなの？？？

こんな感じにしてみた

というわけで、config/unicorn.rb に以下を追加してみました。

unicorn.rb

class Unicorn::HttpServer
  def kill_worker(signal, wpid)
    Process.kill(signal, wpid)
    worker = @workers.delete(wpid) and worker.close rescue nil
  end
end

一応このメソッドが呼ばれるときに渡される signal が :TERMと:KILLしかないことも確認したので、大丈夫だと思いますが。。。

＃あーあれですかね、失敗したときにエラーを吐かないようにした方がいいかもですね？

動作確認

ということで、unicorn.rbのtimeout を短くして、わざとタイムアウトを発生させてみました。

E, [2020-12-28T16:43:53.212943 #4062] ERROR -- : worker=1 PID:4193 timeout (11s > 10s), killing
I, [2020-12-28T16:43:53.215218 #4230]  INFO -- : worker=1 spawned pid=4230
I, [2020-12-28T16:43:53.215512 #4230]  INFO -- : Refreshing Gem list
I, [2020-12-28T16:43:54.302023 #4230]  INFO -- : worker=1 ready

いい感じですね。
これで最悪タイムアウトが発生してもワーカーが食い尽くされることがなくなりました。

まとめ

タイムアウトでワーカーが死なない問題は一応解決しましたが、やっぱりあれですね、皆さんが仰る通り タイムアウトしないような作りにしなさい ですかね。。。

以上です。