トップ > テック > RailsのLogSubscriberの仕組みを利用した不要なログ出力を止める方法

RailsのLogSubscriberの仕組みを利用した不要なログ出力を止める方法

テック ラクマ

https://cdn-ak.f.st-hatena.com/images/fotolife/R/Rakuma/20200908/20200908095133.png

こんにちは、ラクマのshoです。

 

Ruby on Railsはデフォルトでいろいろなログを出力しています。Railsで作ったサービスを運用していると、出力を止めたいログも出てくることと思います。

 

本記事ではRuby on RailsのLogSubscriberの仕組みを利用してログ出力を止める方法を紹介したいと思います。 （実際この仕組みはlogrageで使われています）

本記事の動作確認は5.2.3で行っています  

不要なログ出力を止めることで

  • データ量の削減に繋がりコスト削減に繋がる

  • ログを探す時、見通しが良くなる

などのメリットが生まれます。

 

api_1  | Processing by TasksController#index as HTML
api_1  |   User Load (0.5ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1
api_1  |   ↳ app/controllers/application_controller.rb:9
api_1  |   Rendering tasks/index.html.erb within layouts/application
api_1  |   Label Load (0.6ms)  SELECT `labels`.* FROM `labels`
api_1  |   ↳ app/views/tasks/index.html.erb:35
api_1  |   Task Load (0.6ms)  SELECT  `tasks`.* FROM `tasks` WHERE `tasks`.`user_id` = 1 ORDER BY `tasks`.`created_at` DESC LIMIT 2 OFFSET 0
api_1  |   ↳ app/views/tasks/index.html.erb:69
api_1  |   TaskLabel Load (0.5ms)  SELECT `task_labels`.* FROM `task_labels` WHERE `task_labels`.`task_id` = 1
api_1  |   ↳ app/views/tasks/index.html.erb:69
api_1  |   Rendered tasks/index.html.erb within layouts/application (514.0ms)
api_1  | Completed 200 OK in 3917ms (Views: 3839.3ms | ActiveRecord: 6.7ms)

 

例えば↑のログのRendered tasks/index.html.erb within layouts/application (514.0ms)のログはActionViewが出力しているログになりますが、grepするとActionView::LogSubscriberで出力していることが分かります。

 

LogSubscriberと言うのはActiveSupportの仕組みです、今回はRailsに元々備わっているActiveSupportのLogSubscriberの仕組みを使ってログ出力の停止を実現したいと思います。

 

ActionView::LogSubscriberを見て行きますと（参考に全部のコード載せてますが、最後の行まで飛ばしていただいて大丈夫です。）

# frozen_string_literal: true

require "active_support/log_subscriber"

module ActionView
  # = Action View Log Subscriber
  #
  # Provides functionality so that Rails can output logs from Action View.
  class LogSubscriber < ActiveSupport::LogSubscriber
    VIEWS_PATTERN = /^app\/views\//

    def initialize
      @root = nil
      super
    end

    def render_template(event)
      info do
        message = "  Rendered #{from_rails_root(event.payload[:identifier])}".dup
        message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
        message << " (#{event.duration.round(1)}ms)"
      end
    end

    def render_partial(event)
      info do
        message = "  Rendered #{from_rails_root(event.payload[:identifier])}".dup
        message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
        message << " (#{event.duration.round(1)}ms)"
        message << " #{cache_message(event.payload)}" unless event.payload[:cache_hit].nil?
        message
      end
    end

    def render_collection(event)
      identifier = event.payload[:identifier] || "templates"

      info do
        "  Rendered collection of #{from_rails_root(identifier)}" \
        " #{render_count(event.payload)} (#{event.duration.round(1)}ms)"
      end
    end

    def start(name, id, payload)
      if name == "render_template.action_view"
        log_rendering_start(payload)
      end

      super
    end

    def logger
      ActionView::Base.logger
    end

  private

    EMPTY = ""
    def from_rails_root(string) # :doc:
      string = string.sub(rails_root, EMPTY)
      string.sub!(VIEWS_PATTERN, EMPTY)
      string
    end

    def rails_root # :doc:
      @root ||= "#{Rails.root}/"
    end

    def render_count(payload) # :doc:
      if payload[:cache_hits]
        "[#{payload[:cache_hits]} / #{payload[:count]} cache hits]"
      else
        "[#{payload[:count]} times]"
      end
    end

    def cache_message(payload) # :doc:
      case payload[:cache_hit]
      when :hit
        "[cache hit]"
      when :miss
        "[cache miss]"
      end
    end

    def log_rendering_start(payload)
      info do
        message = "  Rendering #{from_rails_root(payload[:identifier])}".dup
        message << " within #{from_rails_root(payload[:layout])}" if payload[:layout]
        message
      end
    end
  end
end

ActionView::LogSubscriber.attach_to :action_view

 

最後にActionView::LogSubscriber.attach_to :action_viewとあります。

attach_toをgrepしてみると、定義はActiveSupport::Subscriberにある様です。 attach_toの最後にadd_event_subscriberが呼ばれています、最終的にnotifier.subscribe(pattern, subscriber)にたどり着く様です。

# frozen_string_literal: true

require "active_support/per_thread_registry"
require "active_support/notifications"

module ActiveSupport
  # ActiveSupport::Subscriber is an object set to consume
  # ActiveSupport::Notifications. The subscriber dispatches notifications to
  # a registered object based on its given namespace.
  #
  # An example would be an Active Record subscriber responsible for collecting
  # statistics about queries:
  #
  #   module ActiveRecord
  #     class StatsSubscriber < ActiveSupport::Subscriber
  #       attach_to :active_record
  #
  #       def sql(event)
  #         Statsd.timing("sql.#{event.payload[:name]}", event.duration)
  #       end
  #     end
  #   end
  #
  # After configured, whenever a "sql.active_record" notification is published,
  # it will properly dispatch the event (ActiveSupport::Notifications::Event) to
  # the +sql+ method.
  class Subscriber
    class << self
      # Attach the subscriber to a namespace.
      def attach_to(namespace, subscriber = new, notifier = ActiveSupport::Notifications)
        @namespace  = namespace
        @subscriber = subscriber
        @notifier   = notifier

        subscribers << subscriber

        # Add event subscribers for all existing methods on the class.
        subscriber.public_methods(false).each do |event|
          add_event_subscriber(event)
        end
      end

      # Adds event subscribers for all new methods added to the class.
      def method_added(event)
        # Only public methods are added as subscribers, and only if a notifier
        # has been set up. This means that subscribers will only be set up for
        # classes that call #attach_to.
        if public_method_defined?(event) && notifier
          add_event_subscriber(event)
        end
      end

      def subscribers
        @@subscribers ||= []
      end

      # TODO Change this to private once we've dropped Ruby 2.2 support.
      # Workaround for Ruby 2.2 "private attribute?" warning.
      protected

      attr_reader :subscriber, :notifier, :namespace

      private

      def add_event_subscriber(event) # :doc:
        return if %w{ start finish }.include?(event.to_s)

        pattern = "#{event}.#{namespace}"

        # Don't add multiple subscribers (eg. if methods are redefined).
        return if subscriber.patterns.include?(pattern)

        subscriber.patterns << pattern
        notifier.subscribe(pattern, subscriber)
      end
    end

    attr_reader :patterns # :nodoc:

    def initialize
      @queue_key = [self.class.name, object_id].join "-"
      @patterns  = []
      super
    end

    def start(name, id, payload)
      e = ActiveSupport::Notifications::Event.new(name, now, nil, id, payload)
      parent = event_stack.last
      parent << e if parent

      event_stack.push e
    end

    def finish(name, id, payload)
      finished  = now
      event     = event_stack.pop
      event.end = finished
      event.payload.merge!(payload)

      method = name.split(".".freeze).first
      send(method, event)
    end

    private

      def event_stack
        SubscriberQueueRegistry.instance.get_queue(@queue_key)
      end

      def now
        Process.clock_gettime(Process::CLOCK_MONOTONIC)
      end
  end

  # This is a registry for all the event stacks kept for subscribers.
  #
  # See the documentation of <tt>ActiveSupport::PerThreadRegistry</tt>
  # for further details.
  class SubscriberQueueRegistry # :nodoc:
    extend PerThreadRegistry

    def initialize
      @registry = {}
    end

    def get_queue(queue_key)
      @registry[queue_key] ||= []
    end
  end
end

ここではコードは貼りませんがActiveSupport::Notificationsにはsubscribeとunsubscribeが定義されています。

LogSubscriberをunsubscribeしてあげれば、ログはきれいになくなりそうです。

それではinitializerでunsubscribeしてみます。

Rails.application.config.to_prepare do
  ActiveSupport::LogSubscriber.log_subscribers.each do |subscriber|
    case subscriber
    when ActionView::LogSubscriber
      events = subscriber.public_methods(false).reject { |method| method.to_s == 'call' }
      events.each do |event|
        ActiveSupport::Notifications.notifier.listeners_for("#{event}.#{:action_view}").each do |listener|
          if listener.instance_variable_get('@delegate') == subscriber
            ActiveSupport::Notifications.unsubscribe listener
          end
        end
      end
    end
  end
end

Railsを起動して、同じコードを実行してログを見てみると

api_1  | Processing by TasksController#index as HTML
api_1  |   User Load (0.9ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1
api_1  |   ↳ app/controllers/application_controller.rb:9
api_1  |   Label Load (0.5ms)  SELECT `labels`.* FROM `labels`
api_1  |   ↳ app/views/tasks/index.html.erb:35
api_1  |   Task Load (0.4ms)  SELECT  `tasks`.* FROM `tasks` WHERE `tasks`.`user_id` = 1 ORDER BY `tasks`.`created_at` DESC LIMIT 2 OFFSET 0
api_1  |   ↳ app/views/tasks/index.html.erb:69
api_1  |   TaskLabel Load (0.3ms)  SELECT `task_labels`.* FROM `task_labels` WHERE `task_labels`.`task_id` = 1
api_1  |   ↳ app/views/tasks/index.html.erb:69
api_1  | Completed 200 OK in 4665ms (Views: 4574.4ms | ActiveRecord: 5.8ms)

 

ログの出力がされていないのが確認できました。

initializerのコード例を少しカスタマイズすれば、削除したいLogSubscriberや削除したいmethodだけ定義することが可能になります。

以上Railsの仕組みを利用した、ログ出力を止める方法の紹介でした。