2018-02-23

Railsのlogger周りのコードリーディング

Railsのlogger周りのコードリーディングをしました。

今回は以下を見ていきます。

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

 

このエントリーをはてなブックマークに追加