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  endendActiveRecord::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  endend

其方法还算中规中矩的辅助方法， 这是这个类又继承自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  endend

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