aboutsummaryrefslogtreecommitdiffstats
path: root/activesupport
diff options
context:
space:
mode:
authorJosé Valim <jose.valim@gmail.com>2010-06-24 13:23:43 +0200
committerJosé Valim <jose.valim@gmail.com>2010-06-24 13:23:43 +0200
commit6788db824ab732b13493a9d702dd8fb89fa153c8 (patch)
treead9314fdd10b55ebb035959a71be0de921cb0d02 /activesupport
parent5441e082f9478ddb3c676c681b09786f1391483c (diff)
downloadrails-6788db824ab732b13493a9d702dd8fb89fa153c8.tar.gz
rails-6788db824ab732b13493a9d702dd8fb89fa153c8.tar.bz2
rails-6788db824ab732b13493a9d702dd8fb89fa153c8.zip
Move Rails::LogSubscriber to ActiveSupport::LogSubscriber, allowing frameworks like ActiveRecord and ActiveResource to log outsude Rails::Application [#4816 state:resolved]
Diffstat (limited to 'activesupport')
-rw-r--r--activesupport/lib/active_support.rb3
-rw-r--r--activesupport/lib/active_support/log_subscriber.rb114
-rw-r--r--activesupport/lib/active_support/log_subscriber/test_helper.rb90
-rw-r--r--activesupport/test/log_subscriber_test.rb123
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