Railsのlogger周りのコードリーディングをしました。
今回は以下を見ていきます。
- Rails.loggerがどこでどうやって設定されているか
- config.log_tagsの設定値がどこでどうやって利用されているか
- ActiveSupport::TaggedLoggingの実装
Rails.loggerについて
まずRails.loggerはRails::Application::Bootstrapモジュールのinitializerによって処理されます（Railtieのサブクラスの初期化と同じタイミングで処理されます）module Rails
class Application
module Bootstrap
initializer :initialize_logger, group: :all do
Rails.logger ||= config.logger || begin
path = config.paths["log"].first
unless File.exist? File.dirname path
FileUtils.mkdir_p File.dirname path
end
f = File.open path, "a"
f.binmode
f.sync = config.autoflush_log # if true make sure every write flushes
logger = ActiveSupport::Logger.new f
logger.formatter = config.log_formatter
logger = ActiveSupport::TaggedLogging.new(logger)
logger
# ...
end
Rails.logger.level = ActiveSupport::Logger.const_get(config.log_level.to_s.upcase)
end
config.loggerに設定されていればその値を使うし、そうでなければActiveSupport::LoggerのインスタンスをActiveSupport::TaggedLoggingでラップしたものをロガーとして使います。
formatterのデフォルト値は ActiveSupport::Logger::SimpleFormatterで、メッセージをそのままinspectで出力するようになっています。
module ActiveSupport
class Logger < ::Logger
class SimpleFormatter < ::Logger::Formatter
# This method is invoked when a log event occurs
def call(severity, timestamp, progname, msg)
"#{String === msg ? msg : msg.inspect}\n"
end
end
end
end
config.log_tags
config.log_tagsを使うことで指定したタグをログの中に仕込むことができます。config.log_tagsは::Rails::Rack::Loggerのミドルウェアのオプションとして利用されます。
module Rails
class Application
class DefaultMiddlewareStack
def build_stack
ActionDispatch::MiddlewareStack.new.tap do |middleware|
# ...
middleware.use ::Rails::Rack::Logger, config.log_tags
Rails::Rack::Loggerの引数は@taggersとしてタグの配列がセットされます。ActiveSupport::TaggedLoggingが利用されていればloggerはtaggedメソッドが実装されているので、logger.taggedで囲った上でapp.callします。
module Rails
module Rack
class Logger < ActiveSupport::LogSubscriber
def initialize(app, taggers = nil)
@app = app
@taggers = taggers || []
end
def call(env)
request = ActionDispatch::Request.new(env)
if logger.respond_to?(:tagged)
logger.tagged(compute_tags(request)) { call_app(request, env) }
else
call_app(request, env)
end
end
private
def compute_tags(request) # :doc:
@taggers.collect do |tag|
case tag
when Proc
tag.call(request)
when Symbol
request.send(tag)
else
tag
end
end
end
def logger
Rails.logger
end
#compute_tagsで生成されるタグ値はSymbolであればrequest変数のメソッドを呼ぶことになるので:request_idが入っていた場合はActionDispatch::Request#request_idがタグとして利用されます。
#call_appはActiveSupport::Notificationsを操作しつつ、startのログを出力します。Railsのログでよく見る Start GET /path for xxx.xxx.xxx.xxx at yyyy-mm-dd HH:MM:SSみたいなログはここで生成されていることになります。
def call_app(request, env) # :doc:
instrumenter = ActiveSupport::Notifications.instrumenter
instrumenter.start "request.action_dispatch", request: request
logger.info { started_request_message(request) }
resp = @app.call(env)
resp[2] = ::Rack::BodyProxy.new(resp[2]) { finish(request) }
resp
rescue Exception
finish(request)
raise
ensure
ActiveSupport::LogSubscriber.flush_all!
end
def started_request_message(request) # :doc:
'Started %s "%s" for %s at %s' % [
request.request_method,
request.filtered_path,
request.ip,
Time.now.to_default_s ]
end
def finish(request)
instrumenter = ActiveSupport::Notifications.instrumenter
instrumenter.finish "request.action_dispatch", request: request
end
ちなみにActionDispatch::Request#request_idは以下のような定義になっています。
module ActionDispatch
class Request
def request_id
get_header ACTION_DISPATCH_REQUEST_ID
end
def request_id=(id) # :nodoc:
set_header ACTION_DISPATCH_REQUEST_ID, id
end
このrequest_idはActionDispatch::RequestIdのミドルウェアによって設定されます。ActionDispatch::Requestのインスタンス経由でenv[ACTION_DISPATCH_REQUEST_ID]を書き換えつつ、レスポンスのHTTPヘッダであるX-Request-IdにリクエストIDをセットしています。
module ActionDispatch
class RequestId
X_REQUEST_ID = "X-Request-Id".freeze #:nodoc:
def call(env)
req = ActionDispatch::Request.new env
req.request_id = make_request_id(req.x_request_id)
@app.call(env).tap { |_status, headers, _body| headers[X_REQUEST_ID] = req.request_id }
end
private
def make_request_id(request_id)
if request_id.presence
request_id.gsub(/[^\w\-]/, "".freeze).first(255)
else
internal_request_id
end
end
def internal_request_id
SecureRandom.uuid
end
end
end
ActiveSupport::TaggedLogging
以下のような実装になっています。#taggedは#push_tags経由で#current_tagsに指定したタグを追加した後ブロックをyieldします。#callはtags_text付きでメッセージを表示し、#tags_textはcurrent_tagsの分、[#{tag}] の文字列を追加します。
module ActiveSupport
module TaggedLogging
module Formatter # :nodoc:
# This method is invoked when a log event occurs.
def call(severity, timestamp, progname, msg)
super(severity, timestamp, progname, "#{tags_text}#{msg}")
end
def tagged(*tags)
new_tags = push_tags(*tags)
yield self
ensure
pop_tags(new_tags.size)
end
def push_tags(*tags)
tags.flatten.reject(&:blank?).tap do |new_tags|
current_tags.concat new_tags
end
end
def current_tags
# We use our object ID here to avoid conflicting with other instances
thread_key = @thread_key ||= "activesupport_tagged_logging_tags:#{object_id}".freeze
Thread.current[thread_key] ||= []
end
def tags_text
tags = current_tags
if tags.any?
tags.collect { |tag| "[#{tag}] " }.join
end
end
end
def self.new(logger)
# Ensure we set a default formatter so we aren't extending nil!
logger.formatter ||= ActiveSupport::Logger::SimpleFormatter.new
logger.formatter.extend Formatter
logger.extend(self)
end
delegate :push_tags, :pop_tags, :clear_tags!, to: :formatter
def tagged(*tags)
formatter.tagged(*tags) { yield self }
end
