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

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