RubyでWeb APIサーバ(非Rails)を作った際のロギングに関するメモ。

リクエスト毎にユニークなrequest idを発行し、そのリクエストに関わる処理に関してrequest idをつけてロギングしたい。またレスポンスヘッダにはX-Request-Id: <request id>をつけてクライアントに返したい。

request idでgrepすればログ調査しやすくなり、ログの中で処理全体を通してトラッキングできる。またクライアントにX-Request-Id:でidを返すことでクライアント側からの問い合わせに対して調査しやすくなる。

rack-request-idというrack middlewareで都度idを発行し、request_storeを経由してidをloggerに渡すようにしてみた。

実装

config.ru

# config.ru
use RequestStore::Middleware
use Rack::RequestId, storage: RequestStore

logger

# アプリのコードのlogger作成のところ。フォーマッタでrequest_idを埋め込む
log = Logger.new('log/app.log').tap do |logger|
  logger.formatter = proc{|severity, datetime, progname, message|
    "time:#{datetime.strftime("%FT%T%z")}\tlevel:#{severity}\trequest_id:#{RequestStore[:request_id] || '-'}\tprog:#{progname}\tmessage:#{message}\n"
}
end

log.warn "Hi!!!"
=> "time:2016-03-24T12:30:02+0900  
    level:WARN      request_id:e68d8328e4ea46137147728414b613f7
    prog:   message:Hi!!!"

use Rack::RequestIdすることで、リクエスト受信時にSecureRandomを使ってidを発行するようになる。発行したidは内部的にはデフォルトではThread.current[:request_id]に保存されるが、保存先はstorage:オプションで#[], #[]=メソッドを実装した任意のオブジェクトに変更可能(rack-request-id/#4。

上のコードではRequestStore経由へ保存するようにしている。ロガークラスでThread.current[:request_id]を直接参照させるよりも、実装を隠してRequestStoreを経由させることにした。

またuse RequestStore::Middlewareするとレスポンス処理の最後に保存されていたrequest idを消してくれる。同一のスレッド(もしくはプロセス)で続きざまにリクエストを処理する場合、前のリクエストのrequest idが残っていると問題になる可能性があるので、レスポンス処理最後に消す。

参考

リクエスト単位でグローバルな参照を持たせてAuditログをスッキリ実装したい