2021-04-18

Rack::Timeoutによるリクエストタイムアウトの仕組み

はじめに

Rackミドルウェアの一つであるRack::Timeoutを使うと、Rackアプリがリクエストを受け取ってから一定時間が経過すると、アプリのどの場所でコードが実行されていても、その場所からRack::Timeoutの例外RequestTimeoutExceptionが発生する。

サンプルコードと、タイムアウト時のスタックトレースは次のようになる。

require 'rack-timeout'
require_relative './app'

use Rack::Timeout, service_timeout: 5
run App

require 'sinatra/base'

class App < Sinatra::Base
  get '/timeout' do
    sleep 6
    'Time out'
  end
end

[2021-04-12 20:20:17] INFO  WEBrick::HTTPServer#start: pid=1362 port=9292
source=rack-timeout id=287a1d6a-d9b2-47b1-8d03-27094d707e9d timeout=5000ms state=ready at=info
source=rack-timeout id=287a1d6a-d9b2-47b1-8d03-27094d707e9d timeout=5000ms service=5006ms state=timed_out at=error
2021-04-12 20:20:44 - Rack::Timeout::RequestTimeoutException - Request ran for longer than 5000ms :
  /Users/kymmt90/path/to/app/app.rb:5:in `sleep'
  /Users/kymmt90/path/to/app/app.rb:5:in `block in <class:App>'
  /Users/kymmt90/path/to/app/vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1675:in `call'
(snip)
source=rack-timeout id=287a1d6a-d9b2-47b1-8d03-27094d707e9d timeout=5000ms service=5013ms state=completed at=info
::1 - - [12/Apr/2021:20:20:44 +0900] "GET /timeout HTTP/1.1" 500 30 5.0176

sleepしているapp.rbの13行目からRack::Attackの例外Rack::Timeout::RequestTimeoutExceptionが発生している。この仕組みが気になったので調べた。

先に結論

Rack::Timeoutでタイムアウトするとき、次のように動作する。

渡したブロックを一定時間後に実行できるスケジューラを作る
Rack::Timeoutの#callメソッドを呼ぶとき
- リクエストをハンドリングするスレッドでThread#raiseしてRack::Timeout::RequestTimeoutExceptionを発生させるブロックをスケジューラに渡す
- 先のRackアプリに対して#callを実行し、タイムアウトの時間が経過すると渡したブロックを実行する

こうして、一定時間以内にRackアプリがレスポンスを返せばそのレスポンスを返し、そうでなければスケジューラに渡したブロックがアプリのスレッドの外から例外を発生させている。

Rack::Timeoutの概要

目的

Rack::TimeoutのREADMEには、その目的がこう書いてある:

Rack::Timeout is not a solution to the problem of long-running requests, it’s a debug and remediation tool.

あくまでもタイムアウトをきっかけとしてアプリケーションを改善するために使っていこうというもの。

設定方法

Rack::RuntimeがRackミドルウェアとして入っているRackアプリなら、rack-timeoutをGemfileに追加するだけでRack::Timeoutの機能が追加される。そうでないときやRackミドルウェアスタックのどこにミドルウェアを入れたいかを制御したいなら自前で設定を書く必要がある。

設定項目の意味

Rack::Timeoutはさまざまな設定項目を持つ。それぞれの効果をあらためて確認した。

Service Timeout

Rackアプリの実行時間のタイムアウト。

Wait Timeout

リクエストがWebサーバのキューに入ってからRackアプリが処理し始めるまでの時間のタイムアウト。

たとえばHeroku Routerは30秒でタイムアウトするので、リクエストのキューに入って30秒たってからRackアプリが処理し始めるのは意味をなさない。そういうリクエストをRackアプリの手前で落としてRack::Timeout::RequestExpiryErrorをraiseする。

30秒のタイムアウトのとき、Rackアプリの前段で時間がかかって、Rackアプリの処理が始まるまでに20秒使ったら、service timeoutが実質10秒になってしまう。これを無効にするのが service_past_wait。

X-Request-Startを使ってリクエスト開始時間をUNIXエポックで取得しているので、このヘッダがなかったらwait timeoutは発生しない。

Wait Overtime

wait timeoutでX-Request-Startを使っていることもあって、ボディが大きなPOSTリクエスト（ファイルアップロードとか）で受信しはじめから受信終わりまでに時間がかかると、受信完了前にwait timeout扱いになることがある。これを防ぐために、wait timeoutに下駄を履かせる¹。

Term on timeout

たとえば1を設定すると、あるリクエストでタイムアウトしたらWebサーバにSIGTERMを送る。また、たとえば5を設定すると、5件のリクエストがタイムアウトするまでSIGTERMしない。

この機能はPumaなどWebサーバがマルチワーカーなときに使わないと、masterプロセスが終了してしまう。

コードの概要

この記事ではRack::Timeout v0.6.0を読む。コメントが豊富に書かれており、読みやすい。

lib/rack/timeout/core.rbにRackミドルウェアとしてのRack::Timeout#callが存在する。

module Rack
  class Timeout

  # ...

    RT = self # shorthand reference
    def call(env)
      # ...
    end

スケジューラRack::Timeout::Scheduler::Timeout（以下RT::Scheduler::Timeout）はタイムアウト処理を実現するにあたっての肝となるクラスである。Rack::Timeoutの#callでは、次のように次のミドルウェアまたはRackアプリに対しての#callをRT::Scheduler::Timeout#timeoutに渡すブロックで包むことでタイムアウト処理を実現している。これにより、一定時間以上でタイムアウトするRackアプリが完成する。

      timeout = RT::Scheduler::Timeout.new do |app_thread|
        # タイムアウトしたときの処理を設定する
      end

      # 一定時間経過したとき上で渡したブロックを実行するために、#timeoutに@app.callを実行するブロックを渡す
      response = timeout.timeout(info.timeout) do
        begin
          @app.call(env)
        rescue RequestTimeoutException => e
          raise RequestTimeoutError.new(env), e.message, e.backtrace
        ensure
          register_state_change.call :completed
        end
      end

lib/rack/timeout/support/scheduler.rbにあるRT::Scheduler::Timeout#timeoutは次のとおり。本質は@scheduler.run_inの部分で#run_inは渡した秒数が経つとブロックを実行する。つまり、タイムアウト用のブロックを実行する。ここで得ているThread.currentはRackアプリへのリクエストハンドリングを行っているスレッドとなるので、スタックトレース上はRackアプリ内でRequestTimeoutExceptionが発生する形となる。

  def timeout(secs, &block)
    return block.call if secs.nil? || secs.zero?
    thr = Thread.current
    job = @scheduler.run_in(secs) { @on_timeout.call thr }
    return block.call
  ensure
    job.cancel! if job
  end

#run_inは次のとおり。fsecsはmonotonic clock²から得られる時刻。スケジューラに渡せるイベントの一種としてRunEventがあり、これは渡された秒数経過後に1回処理を実行するというもの。

  def run_in(secs, &block)
    schedule RunEvent.new(fsecs + secs, block)
  end

#scheduleにイベントを渡すことで、Rack::Timeoutは新たなスレッドで無限ループしながら、実行が必要なイベントを随時実行する。

  def schedule(event)
    @mx_events.synchronize { @events << event }
    runner.run # 無限ループしながら実行が必要なイベントを実行するまで待つ#run_loop!を別スレッドで実行する
    return event
  end

#run_loop!は詳細は割愛するが、コメントが丁寧なのでやっていること自体は把握しやすい。現在実行すべきイベントを取り出して実行する、の繰り返しになっている。

ベストな解決策はS3などオブジェクトストレージへのダイレクトアップロード ↩
現実の時刻は閏年などで補正されたり巻き戻ったりすることがあるが、monotonic clockは単調増加する ↩