rails 源码解析之log notification/subscribe

我调试rails代码的习惯是边看代码边看日志，通过日志你可以看到每一处rails对DB的操作。这在web开发看来还是挺简单，只有在少数情况下才去使用pry或者debugger去调试代码。一来直接看日志就大致上可以看到你写的代码执行的逻辑，比如执行insert语句的时候你大概也能猜到应该是调用了 Model.create 方法。直接看日志这种方式比较便捷。但是默认rails是把所有的sql都显示在日志里面的，实际上我们关心的无非是insert/update/delete语句，至于select基本上不太关心了。但是项目逻辑一旦复杂，一个请求有上百条sql的时候，就不太容易找到insert/update/delete了。所以制作了一个gem，用来高亮insert/update/delete语句。自我感觉还不错，可以在github上找到（https://github.com/xumc/simple-debug-for-rails/tree/v1.0.0）。目前还比较简陋，以后慢慢完善。见图：

gem的事情暂且不表，下面讲讲rails中的log 相关代码。这也是为了写这个gem才看这部分代码。

涉及到log相关的rb文件如下图：

rails caicai$ tree -C -f|grep "subscribe\|notifications"
│   │   │   ├── ./actionmailer/lib/action_mailer/log_subscriber.rb
│       ├── ./actionmailer/test/log_subscriber_test.rb
│   │   │   ├── ./actionpack/lib/action_controller/log_subscriber.rb
│       │   ├── ./actionpack/test/controller/log_subscriber_test.rb
│   │   │   ├── ./actionview/lib/action_view/log_subscriber.rb
│       │   ├── ./actionview/test/template/log_subscriber_test.rb
│   │   │   ├── ./activerecord/lib/active_record/explain_subscriber.rb
│   │   │   ├── ./activerecord/lib/active_record/log_subscriber.rb
│       │   ├── ./activerecord/test/cases/explain_subscriber_test.rb
│       │   ├── ./activerecord/test/cases/log_subscriber_test.rb
│       │   ├── ./activerecord/test/fixtures/subscribers.yml
│       │   ├── ./activerecord/test/models/subscriber.rb
│   │   │   ├── ./activesupport/lib/active_support/log_subscriber
│   │   │   │   └── ./activesupport/lib/active_support/log_subscriber/test_helper.rb
│   │   │   ├── ./activesupport/lib/active_support/log_subscriber.rb
│   │   │   ├── ./activesupport/lib/active_support/notifications
│   │   │   │   ├── ./activesupport/lib/active_support/notifications/fanout.rb
│   │   │   │   └── ./activesupport/lib/active_support/notifications/instrumenter.rb
│   │   │   ├── ./activesupport/lib/active_support/notifications.rb
│   │   │   ├── ./activesupport/lib/active_support/subscriber.rb
│       ├── ./activesupport/test/log_subscriber_test.rb
│       ├── ./activesupport/test/notifications
│       │   ├── ./activesupport/test/notifications/evented_notification_test.rb
│       │   └── ./activesupport/test/notifications/instrumenter_test.rb
│       ├── ./activesupport/test/notifications_test.rb
│       ├── ./activesupport/test/subscriber_test.rb
│       │   │   └── ./railties/test/application/initializers/notifications_test.rb

很明显，rails会使用pub/sub方式记录日志。类似于消息队列的意思。 比如执行sql的时候会生成sql事件， log订阅者则能够接受到这些sql事件，并且把相关的信息记录到log中。这样就避免了在代码里面直接写logger.debug/info/error 等语句。将log和其他组件进行解耦。从上面的文件树可以看出rails的各大组件均有一个log_subscriber.rb文件。里面的代码便是捕获组件内部产生的event并且将event信息写到log文件的代码。

以/activerecord/lib/active_record/log_subscriber.rb为例：

module ActiveRecord
  class LogSubscriber < ActiveSupport::LogSubscriber
    IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"]


    def self.runtime=(value)
      ActiveRecord::RuntimeRegistry.sql_runtime = value
    end


    def self.runtime
      ActiveRecord::RuntimeRegistry.sql_runtime ||= 0
    end


    def self.reset_runtime
      rt, self.runtime = runtime, 0
      rt
    end


    def initialize
      super
      @odd = false
    end


    def render_bind(column, value)
      if column
        if column.binary?
          # This specifically deals with the PG adapter that casts bytea columns into a Hash.
          value = value[:value] if value.is_a?(Hash)
          value = value ? "<#{value.bytesize} bytes of binary data>" : "<NULL binary data>"
        end


        [column.name, value]
      else
        [nil, value]
      end
    end


    def sql(event)
      self.class.runtime += event.duration
      return unless logger.debug?


      payload = event.payload


      return if IGNORE_PAYLOAD_NAMES.include?(payload[:name])


      name  = "#{payload[:name]} (#{event.duration.round(1)}ms)"
      sql   = payload[:sql]
      binds = nil


      unless (payload[:binds] || []).empty?
        binds = "  " + payload[:binds].map { |col,v|
          render_bind(col, v)
        }.inspect
      end


      if odd?
        name = color(name, CYAN, true)
        sql  = color(sql, nil, true)
      else
        name = color(name, MAGENTA, true)
      end


      debug "  #{name}  #{sql}#{binds}"
    end


    def odd?
      @odd = !@odd
    end


    def logger
      ActiveRecord::Base.logger
    end
  end
end


ActiveRecord::LogSubscriber.attach_to :active_record

这个类继承自ActiveSupport::LogSubscriber这个类，联系到上面的文件结构，可以猜出ActiveSupport::LogSubscriber应该是rails各大组件中的LogSubscriber的基类。active_record中的这个类主要的函数sql(event)将event中的信息转换成伟log文本调用debug方式存储到log中。 文件最后一句使用 attach_to 意为用这个类来监听active_record产生的事件。

再来看看ActiveSupport::LogSubscriber这个类：

module ActiveSupport
 class LogSubscriber < Subscriber
    # Embed in a String to clear all previous ANSI sequences.
    CLEAR   = "\e[0m"
    BOLD    = "\e[1m"

    # Colors
    BLACK   = "\e[30m"
    RED     = "\e[31m"
    GREEN   = "\e[32m"
    YELLOW  = "\e[33m"
    BLUE    = "\e[34m"
    MAGENTA = "\e[35m"
    CYAN    = "\e[36m"
    WHITE   = "\e[37m"

    mattr_accessor :colorize_logging
    self.colorize_logging = true

    class << self
      def logger
        @logger ||= if defined?(Rails) && Rails.respond_to?(:logger)
          Rails.logger
        end
      end

      attr_writer :logger

      def log_subscribers
        subscribers
      end

      # Flush all log_subscribers' logger.
      def flush_all!
        logger.flush if logger.respond_to?(:flush)
      end
    end

    def logger
      LogSubscriber.logger
    end

    def start(name, id, payload)
      super if logger
    end

    def finish(name, id, payload)
      super if logger
    rescue Exception => e
      logger.error "Could not log #{name.inspect} event. #{e.class}: #{e.message} #{e.backtrace}"
    end

  protected

    %w(info debug warn error fatal unknown).each do |level|
      class_eval <<-METHOD, __FILE__, __LINE__ + 1
        def #{level}(progname = nil, &block)
          logger.#{level}(progname, &block) if logger
        end
      METHOD
    end

    # Set color by using a string or one of the defined constants. If a third
    # option is set to +true+, it also adds bold to the string. This is based
    # on the Highline implementation and will automatically append CLEAR to the
    # end of the returned String.
    def color(text, color, bold=false)
      return text unless colorize_logging
      color = self.class.const_get(color.upcase) if color.is_a?(Symbol)
      bold  = bold ? BOLD : ""
      "#{bold}#{color}#{text}#{CLEAR}"
    end
  end
end

其方法还算中规中矩的辅助方法， 这是这个类又继承自subscribe类，这里很明显了，这个subscribe类应该写着一个pub/sub机制的一些方法，并非仅仅是log机制使用。打开看看：

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 Active Record subscriber responsible for collecting
  # statistics about queries:
  #
  #   module ActiveRecord
  #     class StatsSubscriber < ActiveSupport::Subscriber
  #       def sql(event)
  #         Statsd.timing("sql.#{event.payload[:name]}", event.duration)
  #       end
  #     end
  #   end
  #
  # And it's finally registered as:
  #
  #   ActiveRecord::StatsSubscriber.attach_to :active_record
  #
  # Since we need to know all instance methods before attaching the log
  # subscriber, the line above should be called after your subscriber definition.
  #
  # 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

      protected

      attr_reader :subscriber, :notifier, :namespace

      def add_event_subscriber(event)
        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, Time.now, nil, id, payload)
      parent = event_stack.last
      parent << e if parent

      event_stack.push e
    end

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

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

    private

      def event_stack
        SubscriberQueueRegistry.instance.get_queue(@queue_key)
      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

也不是很难懂。 就是定义了公共的行为。