From 6788db824ab732b13493a9d702dd8fb89fa153c8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Thu, 24 Jun 2010 13:23:43 +0200 Subject: Move Rails::LogSubscriber to ActiveSupport::LogSubscriber, allowing frameworks like ActiveRecord and ActiveResource to log outsude Rails::Application [#4816 state:resolved] --- activesupport/lib/active_support.rb | 3 +- activesupport/lib/active_support/log_subscriber.rb | 114 +++++++++++++++++++ .../active_support/log_subscriber/test_helper.rb | 90 +++++++++++++++ activesupport/test/log_subscriber_test.rb | 123 +++++++++++++++++++++ 4 files changed, 329 insertions(+), 1 deletion(-) create mode 100644 activesupport/lib/active_support/log_subscriber.rb create mode 100644 activesupport/lib/active_support/log_subscriber/test_helper.rb create mode 100644 activesupport/test/log_subscriber_test.rb (limited to 'activesupport') 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 -- cgit v1.2.3