ユニファ開発者ブログ

ユニファ株式会社プロダクトデベロップメント本部メンバーによるブログです。

調査しやすくするためログにリクエストIDを入れましょう

はじめまして、ユニファ株式会社のWEBエンジニアのチョウと申します。

こんなことがないでしょうか。突然調査依頼が来て、あるユーザーについて調べてほしいです。大量のログから掘り出してみましたが、ユーザー何人がアクセスするによってログが混じってしまいました。RailsのログにプロセスのIDが入ってますが、1つのプロセスは連続で複数ユーザーに使われて、リクエストとリクエストの境界が見づらく、時間かかるケースよくあります。もっと問題なのは、システムは必ず1つのログファイルに出力するわけではない。リクエストログは複数のファイルに分けられてしまったら、調査自体が邪魔されるといっても過言ではない。

ここで問題をまとめましょう。

  1. ユーザーあるいはユーザーのリクエストを特定したい
  2. 1つのリクエストが複数のログファイルに分けても分かる

ここですぐ分かる方がいるかもしれません、1つのリクエストは複数行のログを出力しているので、この複数行のログをあるIDなどでつなげればいいのです。 もっと具体的には、リクエストごとにユニークをIDを作成し、ログを出力するところ、このIDを一緒に出せば連続の行でもわかります。

request-id-1: foo
request-id-2: bar
request-id-1: foo2

ここでrequest-id-1でgrepすればプロセスID関係なくこのリクエストのログだけフィルターできます。

Rails自体はlog_tagsという設定があります。

config.log_tags = [ :uuid ]

を有効にすれば、ログにX-Request-Idの内容を出力されます。X-Request-Idはリクエスト別で作成されましたので、要望1に合ってます。

Log tagging in Rails | We Are Stac

BEFORE

Started GET "/dashboard" for 127.0.0.1 at 2014-11-24 15:48:30 +0000

AFTER

[a00c54e0-874f-4358-a7b9-accef0c407c6] Started GET "/dashboard" for 127.0.0.1 at 2014-11-24 15:48:30 +0000

これで終わり?残念ながら、この方法はRails.loggerだけに効き、複数のログファイルに通用しないです。 しかし、log_tagsのように、ログ出力するとき、X-Request-Idを入れれば解決できると思います。

そもそもX-Request-Idはどこからですか。答えはRailsのRake Middleware:ActionDispatch::RequestIdです。このmiddlewareはX-Request-Idを決め、Rackのenvに設定してます。 envの中にあると、ログを出力するところ取得しにくいため、まずthread local variableとかに保存してみます。つまり、自分でmiddlewareを作り、X-Request-Idをthread local variableに設定します。

middlewareリスト

use ActionDispatch::Static
use Rack::Lock
use #<ActiveSupport::Cache::Strategy::LocalCache::Middleware:0x007f9112ed8258>
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::DebugExceptions
use BetterErrors::Middleware
use ActionDispatch::RemoteIp
use RailsDevTweaks::GranularAutoload::Middleware
use ActionDispatch::Callbacks
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Flash
use ActionDispatch::ParamsParser
use ActionDispatch::Head
use Rack::ConditionalGet
use Rack::ETag
use ActionDispatch::BestStandardsSupport
use ExceptionNotification::Rack
run Foo::Application.routes

application.rb

config.middleware.insert_after 'ActionDispatch::RequestId', 'MyLogContextCollector'
class MyLogContextCollector
  def initialize(app)
    @app = app
  end

  def call(env)
    # request id from ActionDispatch::RequestId
    request_id = env['action_dispatch.request_id']
    MyLogContext.set_current_request_id(request_id)
    @app.call(env)
  ensure
    MyLogContext.clear_current_request_id
  end
end

ここでenvからX-Request-Idを取り出し、MyLogContextのthread local variableに設定します。

class MyLogContext
  TRANS_VAR_REQUEST_ID = :request_id

  attr_reader :severity # String
  attr_reader :time # DateTime
  attr_reader :program_name # String
  attr_reader :message # Object

  # @param [String] severity
  # @param [DateTime] time
  # @param [String] program_name
  # @param [Object] message
  def initialize(severity, time, program_name, message)
    @severity = severity
    @time = time
    @program_name = program_name
    @message = message
  end

  # @return [Integer]
  def get_process_id
    $$
  end

  # @param [String] format
  # @return [String]
  def get_formatted_time(format = nil)
    return nil if @time.nil?
    return @time.strftime(format) if format

    "#{@time.strftime('%Y-%m-%d %H:%M:%S')}.#{'%06d' % @time.usec.to_s}"
  end

  # @return [String]
  def message2string
    case @message
      when ::String
        @message
      when ::Exception
        "#{ @message.message } (#{ @message.class })\n" <<
            (@message.backtrace || []).join("\n")
      else
        @message.inspect
    end
  end

  class << self
    # @param [String] request_id
    def set_current_request_id(request_id)
      set_trans_var(TRANS_VAR_REQUEST_ID, request_id)
    end

    # @return [String]
    def get_current_request_id
      get_trans_var(TRANS_VAR_REQUEST_ID)
    end

    def clear_current_request_id
      set_trans_var(TRANS_VAR_REQUEST_ID, nil)
    end

    # @param [Symbol] key
    # @param [Object] value
    def set_trans_var(key, value)
      ::Thread.current.thread_variable_set(key, value)
    end

    # @param [Symbol] key
    def get_trans_var(key)
      ::Thread.current.thread_variable_get(key)
    end
  end
end

ログを出力する時、都度thread local variableであるX-Request-Idを入れるのはしたくないため、log formatのところすこし改造してみました。

logger = Logger.new('log/foo.log')
logger.formatter = MyLogFormatter.new(lambda{|context|
  "[%s #%d] %5s -- %s: [%s] %s\n" % [
      context.get_formatted_time,
      context.get_process_id,
      context.severity,
      context.program_name,
      MyLogContext.get_current_request_id,
      context.message2string
  ]
})
class MyLogFormatter
  def initialize(lambda)
    @lambda = lambda
  end

  # @param [String] severity
  # @param [DateTime] time
  # @param [String] prog_name
  # @param [Object] msg
  # @return [String]
  def call(severity, time, prog_name, msg)
    context = ::Yoursmile::LogContext.new(severity, time, prog_name, msg)
    @lambda.call(context)
  end
end

これで全部終わりました。

==> log/1.log <==
[2016-11-25 17:26:11.350612 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 1
[2016-11-25 17:26:11.367210 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 2
[2016-11-25 17:26:11.367284 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 3
[2016-11-25 17:26:11.370316 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 4
[2016-11-25 17:26:11.372182 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 5
[2016-11-25 17:26:11.374109 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 6

==> log/2.log <==
[2016-11-25 17:26:11.383344 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 7

==> log/3.log <==
[2016-11-25 17:26:11.391745 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 8

==> log/1.log <==
[2016-11-25 17:26:11.415792 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 9
[2016-11-25 17:26:11.432047 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 10
[2016-11-25 17:26:11.441824 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 11
[2016-11-25 17:26:11.448600 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 12
[2016-11-25 17:26:11.450477 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 13
[2016-11-25 17:26:11.451106 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 14

よさそう。

まとめ

あとで本番にリリースし、調査がすこし楽になった感じがします。エラーはある原因で別のファイルに出力されましたから、本来エラーを起こすリクエストを特定するのは難しかったです。そこでこの機能のおかげて、エラーを出力する行のrequest idが分かればすぐgrepで見つかりました。

実際、X-Request-Idはアプリケーション内のログではなく、1つのリクエストが複数アプリケーションに関わる場合も利用できます。それは最初のアプリケーションあるいはWEBサーバーがRequest-Idを作成し、RPCのパラメータとしてほかのアプリケーションに通信し、処理のログを繋げます。つまり、request tracerみたいなものです。

最後に、以上の内容は役に立ちましたら幸いです。