はじめまして、ユニファ株式会社のWEBエンジニアのチョウと申します。
こんなことがないでしょうか。突然調査依頼が来て、あるユーザーについて調べてほしいです。大量のログから掘り出してみましたが、ユーザー何人がアクセスするによってログが混じってしまいました。RailsのログにプロセスのIDが入ってますが、１つのプロセスは連続で複数ユーザーに使われて、リクエストとリクエストの境界が見づらく、時間かかるケースよくあります。もっと問題なのは、システムは必ず１つのログファイルに出力するわけではない。リクエストログは複数のファイルに分けられてしまったら、調査自体が邪魔されるといっても過言ではない。
ここで問題をまとめましょう。
- ユーザーあるいはユーザーのリクエストを特定したい
- １つのリクエストが複数のログファイルに分けても分かる
ここですぐ分かる方がいるかもしれません、１つのリクエストは複数行のログを出力しているので、この複数行のログをある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はリクエスト別で作成されましたので、要望１に合ってます。
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はアプリケーション内のログではなく、１つのリクエストが複数アプリケーションに関わる場合も利用できます。それは最初のアプリケーションあるいはWEBサーバーがRequest-Idを作成し、RPCのパラメータとしてほかのアプリケーションに通信し、処理のログを繋げます。つまり、request tracerみたいなものです。
最後に、以上の内容は役に立ちましたら幸いです。
