Move Rails::LogSubscriber to ActiveSupport::LogSubscriber, allowing frameworks like ActiveRecord and ActiveResource to log outsude Rails::Application [#4816 state:resolved]

4 files changed, 329 insertions, 1 deletions

diff --git a/activesupport/lib/active_support.rb b/activesupport/lib/active_support.rb
index 3ce5476bbd..ba91e8bba3 100644
--- a/activesupport/lib/active_support.rb
+++ b/activesupport/lib/active_support.rb
@@ -41,6 +41,8 @@ module ActiveSupport
 
   autoload :DescendantsTracker
   autoload :FileUpdateChecker
+  autoload :LogSubscriber
+  autoload :Notifications
 
   # TODO: Narrow this list down
   eager_autoload do
@@ -64,7 +66,6 @@ module ActiveSupport
     autoload :OptionMerger
     autoload :OrderedHash
     autoload :OrderedOptions
-    autoload :Notifications
     autoload :Rescuable
     autoload :SecureRandom
     autoload :StringInquirer
diff --git a/activesupport/lib/active_support/log_subscriber.rb b/activesupport/lib/active_support/log_subscriber.rb
new file mode 100644
index 0000000000..a1ffb8eece
--- /dev/null
+++ b/activesupport/lib/active_support/log_subscriber.rb
@@ -0,0 +1,114 @@
+require 'active_support/core_ext/module/attribute_accessors'
+require 'active_support/core_ext/class/attribute'
+
+module ActiveSupport
+  # ActiveSupport::LogSubscriber is an object set to consume ActiveSupport::Notifications
+  # with solely purpose of logging. The log subscriber dispatches notifications to a
+  # regirested object based on its given namespace.
+  #
+  # An example would be Active Record log subscriber responsible for logging queries:
+  #
+  #   module ActiveRecord
+  #     class LogSubscriber < ActiveSupport::LogSubscriber
+  #       def sql(event)
+  #         "#{event.payload[:name]} (#{event.duration}) #{event.payload[:sql]}"
+  #       end
+  #     end
+  #   end
+  #
+  # And it's finally registed as:
+  #
+  #   ActiveRecord::LogSubscriber.attach_to :active_record
+  #
+  # Since we need to know all instance methods before attaching the log subscriber,
+  # the line above shuold be called after your ActiveRecord::LogSubscriber definition.
+  #
+  # After configured, whenever a "sql.active_record" notification is published,
+  # it will properly dispatch the event (ActiveSupport::Notifications::Event) to
+  # the sql method.
+  #
+  # Log subscriber also has some helpers to deal with logging and automatically flushes
+  # all logs when the request finishes (via action_dispatch.callback notification) in
+  # a Rails environment.
+  class LogSubscriber
+    mattr_accessor :colorize_logging
+    self.colorize_logging = true
+
+    class_attribute :logger
+
+    def self.logger
+      @logger ||= Rails.logger if defined?(Rails)
+    end
+
+    # 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"
+
+    def self.attach_to(namespace, log_subscriber=new, notifier=ActiveSupport::Notifications)
+      log_subscribers << log_subscriber
+      @@flushable_loggers = nil
+
+      log_subscriber.public_methods(false).each do |event|
+        notifier.subscribe("#{event}.#{namespace}") do |*args|
+          next if log_subscriber.logger.nil?
+
+          begin
+            log_subscriber.send(event, ActiveSupport::Notifications::Event.new(*args))
+          rescue Exception => e
+            log_subscriber.logger.error "Could not log #{args[0].inspect} event. #{e.class}: #{e.message}"
+          end
+        end
+      end
+    end
+
+    def self.log_subscribers
+      @@log_subscribers ||= []
+    end
+
+    def self.flushable_loggers
+      @@flushable_loggers ||= begin
+        loggers = log_subscribers.map(&:logger)
+        loggers.uniq!
+        loggers.select { |l| l.respond_to?(:flush) }
+      end
+    end
+
+    # Flush all log_subscribers' logger.
+    def self.flush_all!
+      flushable_loggers.each(&:flush)
+    end
+
+  protected
+
+    %w(info debug warn error fatal unknown).each do |level|
+      class_eval <<-METHOD, __FILE__, __LINE__ + 1
+        def #{level}(*args, &block)
+          return unless logger
+          logger.#{level}(*args, &block)
+        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 Highline implementation and it automatically appends 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.to_s.upcase) if color.is_a?(Symbol)
+      bold  = bold ? BOLD : ""
+      "#{bold}#{color}#{text}#{CLEAR}"
+    end
+  end
+end
diff --git a/activesupport/lib/active_support/log_subscriber/test_helper.rb b/activesupport/lib/active_support/log_subscriber/test_helper.rb
new file mode 100644
index 0000000000..96506a4b2b
--- /dev/null
+++ b/activesupport/lib/active_support/log_subscriber/test_helper.rb
@@ -0,0 +1,90 @@
+require 'active_support/log_subscriber'
+
+module ActiveSupport
+  class LogSubscriber
+    # Provides some helpers to deal with testing log subscribers by setting up
+    # notifications. Take for instance Active Record subscriber tests:
+    #
+    #   class SyncLogSubscriberTest < ActiveSupport::TestCase
+    #     include ActiveSupport::LogSubscriber::TestHelper
+    #
+    #     def setup
+    #       ActiveRecord::LogSubscriber.attach_to(:active_record)
+    #     end
+    # 
+    #     def test_basic_query_logging
+    #       Developer.all
+    #       wait
+    #       assert_equal 1, @logger.logged(:debug).size
+    #       assert_match /Developer Load/, @logger.logged(:debug).last
+    #       assert_match /SELECT \* FROM "developers"/, @logger.logged(:debug).last
+    #     end
+    #   end
+    #
+    # All you need to do is to ensure that your log subscriber is added to Rails::Subscriber,
+    # as in the second line of the code above. The test helpers is reponsible for setting
+    # up the queue, subscriptions and turning colors in logs off.
+    #
+    # The messages are available in the @logger instance, which is a logger with limited
+    # powers (it actually do not send anything to your output), and you can collect them
+    # doing @logger.logged(level), where level is the level used in logging, like info,
+    # debug, warn and so on.
+    #
+    module TestHelper
+      def setup
+        @logger   = MockLogger.new
+        @notifier = ActiveSupport::Notifications::Notifier.new(queue)
+
+        ActiveSupport::LogSubscriber.colorize_logging = false
+
+        set_logger(@logger)
+        ActiveSupport::Notifications.notifier = @notifier
+      end
+
+      def teardown
+        set_logger(nil)
+        ActiveSupport::Notifications.notifier = nil
+      end
+
+      class MockLogger
+        attr_reader :flush_count
+
+        def initialize
+          @flush_count = 0
+          @logged = Hash.new { |h,k| h[k] = [] }
+        end
+
+        def method_missing(level, message)
+          @logged[level] << message
+        end
+
+        def logged(level)
+          @logged[level].compact.map { |l| l.to_s.strip }
+        end
+
+        def flush
+          @flush_count += 1
+        end
+      end
+
+      # Wait notifications to be published.
+      def wait
+        @notifier.wait
+      end
+
+      # Overwrite if you use another logger in your log subscriber:
+      #
+      #   def logger
+      #     ActiveRecord::Base.logger = @logger
+      #   end
+      #
+      def set_logger(logger)
+        ActiveSupport::LogSubscriber.logger = logger
+      end
+
+      def queue
+        ActiveSupport::Notifications::Fanout.new
+      end
+    end
+  end
+end
\ No newline at end of file
diff --git a/activesupport/test/log_subscriber_test.rb b/activesupport/test/log_subscriber_test.rb
new file mode 100644
index 0000000000..0c1f3c51ed
--- /dev/null
+++ b/activesupport/test/log_subscriber_test.rb
@@ -0,0 +1,123 @@
+require 'abstract_unit'
+require 'active_support/log_subscriber/test_helper'
+
+class MyLogSubscriber < ActiveSupport::LogSubscriber
+  attr_reader :event
+
+  def some_event(event)
+    @event = event
+    info event.name
+  end
+
+  def foo(event)
+    debug "debug"
+    info "info"
+    warn "warn"
+  end
+
+  def bar(event)
+    info "#{color("cool", :red)}, #{color("isn't it?", :blue, true)}"
+  end
+
+  def puke(event)
+    raise "puke"
+  end
+end
+
+class SyncLogSubscriberTest < ActiveSupport::TestCase
+  include ActiveSupport::LogSubscriber::TestHelper
+
+  def setup
+    super
+    @log_subscriber = MyLogSubscriber.new
+  end
+
+  def teardown
+    super
+    ActiveSupport::LogSubscriber.log_subscribers.clear
+  end
+
+  def instrument(*args, &block)
+    ActiveSupport::Notifications.instrument(*args, &block)
+  end
+
+  def test_proxies_method_to_rails_logger
+    @log_subscriber.foo(nil)
+    assert_equal %w(debug), @logger.logged(:debug)
+    assert_equal %w(info), @logger.logged(:info)
+    assert_equal %w(warn), @logger.logged(:warn)
+  end
+
+  def test_set_color_for_messages
+    ActiveSupport::LogSubscriber.colorize_logging = true
+    @log_subscriber.bar(nil)
+    assert_equal "\e[31mcool\e[0m, \e[1m\e[34misn't it?\e[0m", @logger.logged(:info).last
+  end
+
+  def test_does_not_set_color_if_colorize_logging_is_set_to_false
+    @log_subscriber.bar(nil)
+    assert_equal "cool, isn't it?", @logger.logged(:info).last
+  end
+
+  def test_event_is_sent_to_the_registered_class
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    instrument "some_event.my_log_subscriber"
+    wait
+    assert_equal %w(some_event.my_log_subscriber), @logger.logged(:info)
+  end
+
+  def test_event_is_an_active_support_notifications_event
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    instrument "some_event.my_log_subscriber"
+    wait
+    assert_kind_of ActiveSupport::Notifications::Event, @log_subscriber.event
+  end
+
+  def test_does_not_send_the_event_if_it_doesnt_match_the_class
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    instrument "unknown_event.my_log_subscriber"
+    wait
+    # If we get here, it means that NoMethodError was not raised.
+  end
+
+  def test_does_not_send_the_event_if_logger_is_nil
+    ActiveSupport::LogSubscriber.logger = nil
+    @log_subscriber.expects(:some_event).never
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    instrument "some_event.my_log_subscriber"
+    wait
+  end
+
+  def test_does_not_fail_with_non_namespaced_events
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    instrument "whatever"
+    wait
+  end
+
+  def test_flushes_loggers
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    ActiveSupport::LogSubscriber.flush_all!
+    assert_equal 1, @logger.flush_count
+  end
+
+  def test_flushes_the_same_logger_just_once
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    ActiveSupport::LogSubscriber.attach_to :another, @log_subscriber
+    ActiveSupport::LogSubscriber.flush_all!
+    wait
+    assert_equal 1, @logger.flush_count
+  end
+
+  def test_logging_does_not_die_on_failures
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    instrument "puke.my_log_subscriber"
+    instrument "some_event.my_log_subscriber"
+    wait
+
+    assert_equal 1, @logger.logged(:info).size
+    assert_equal 'some_event.my_log_subscriber', @logger.logged(:info).last
+
+    assert_equal 1, @logger.logged(:error).size
+    assert_equal 'Could not log "puke.my_log_subscriber" event. RuntimeError: puke', @logger.logged(:error).last
+  end
+end
\ No newline at end of file