From 27d9836ad3519d57462b86a4e539c1aa176b6d95 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sun, 17 Jan 2010 12:41:55 +0100 Subject: [PATCH] Add ActionDispatch::Railties::Subscriber and finish tidying up the logging. --- .../metal/instrumentation.rb | 4 - actionpack/lib/action_controller/railtie.rb | 48 -------- .../action_controller/railties/subscriber.rb | 7 +- actionpack/lib/action_dispatch/railtie.rb | 58 +++++++++ .../action_dispatch/railties/subscriber.rb | 17 +++ .../activerecord/controller_runtime_test.rb | 4 +- actionpack/test/controller/subscriber_test.rb | 42 +++---- .../test/dispatch/notifications_test.rb | 69 ----------- actionpack/test/dispatch/subscriber_test.rb | 112 ++++++++++++++++++ .../lib/active_record/railties/subscriber.rb | 2 +- railties/lib/rails.rb | 5 +- 11 files changed, 208 insertions(+), 160 deletions(-) create mode 100644 actionpack/lib/action_dispatch/railtie.rb create mode 100644 actionpack/lib/action_dispatch/railties/subscriber.rb delete mode 100644 actionpack/test/dispatch/notifications_test.rb create mode 100644 actionpack/test/dispatch/subscriber_test.rb diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb index 7222b7b2fa..876f778751 100644 --- a/actionpack/lib/action_controller/metal/instrumentation.rb +++ b/actionpack/lib/action_controller/metal/instrumentation.rb @@ -20,11 +20,7 @@ module ActionController result = super payload[:controller] = self.class.name payload[:action] = self.action_name - payload[:formats] = request.formats.map(&:to_s) - payload[:remote_ip] = request.remote_ip - payload[:method] = request.method payload[:status] = response.status - payload[:request_uri] = request.request_uri rescue "unknown" append_info_to_payload(payload) result end diff --git a/actionpack/lib/action_controller/railtie.rb b/actionpack/lib/action_controller/railtie.rb index d93155e7a5..7ea64c1923 100644 --- a/actionpack/lib/action_controller/railtie.rb +++ b/actionpack/lib/action_controller/railtie.rb @@ -39,53 +39,5 @@ module ActionController ActionController::Base.view_paths = view_path if ActionController::Base.view_paths.blank? end - class MetalMiddlewareBuilder - def initialize(metals) - @metals = metals - end - - def new(app) - ActionDispatch::Cascade.new(@metals, app) - end - - def name - ActionDispatch::Cascade.name - end - alias_method :to_s, :name - end - - initializer "action_controller.initialize_metal" do |app| - metal_root = "#{Rails.root}/app/metal" - load_list = app.config.metals || Dir["#{metal_root}/**/*.rb"] - - metals = load_list.map { |metal| - metal = File.basename(metal.gsub("#{metal_root}/", ''), '.rb') - require_dependency metal - metal.camelize.constantize - }.compact - - middleware = MetalMiddlewareBuilder.new(metals) - app.config.middleware.insert_before(:"ActionDispatch::ParamsParser", middleware) - end - - # Prepare dispatcher callbacks and run 'prepare' callbacks - initializer "action_controller.prepare_dispatcher" do |app| - # TODO: This used to say unless defined?(Dispatcher). Find out why and fix. - # Notice that at this point, ActionDispatch::Callbacks were already loaded. - require 'rails/dispatcher' - - unless app.config.cache_classes - # Setup dev mode route reloading - routes_last_modified = app.routes_changed_at - reload_routes = lambda do - unless app.routes_changed_at == routes_last_modified - routes_last_modified = app.routes_changed_at - app.reload_routes! - end - end - ActionDispatch::Callbacks.before { |callbacks| reload_routes.call } - end - end - end end diff --git a/actionpack/lib/action_controller/railties/subscriber.rb b/actionpack/lib/action_controller/railties/subscriber.rb index a9f5d16c58..6659e5df47 100644 --- a/actionpack/lib/action_controller/railties/subscriber.rb +++ b/actionpack/lib/action_controller/railties/subscriber.rb @@ -3,18 +3,13 @@ module ActionController class Subscriber < Rails::Subscriber def process_action(event) payload = event.payload - - info "\nProcessed #{payload[:controller]}##{payload[:action]} " \ - "to #{payload[:formats].join(', ')} (for #{payload[:remote_ip]} at #{event.time.to_s(:db)}) " \ - "[#{payload[:method].to_s.upcase}]" - info " Parameters: #{payload[:params].inspect}" unless payload[:params].blank? additions = ActionController::Base.log_process_action(payload) message = "Completed in %.0fms" % event.duration message << " (#{additions.join(" | ")})" unless additions.blank? - message << " | #{payload[:status]} [#{payload[:request_uri]}]\n\n" + message << " by #{payload[:controller]}##{payload[:action]} [#{payload[:status]}]" info(message) end diff --git a/actionpack/lib/action_dispatch/railtie.rb b/actionpack/lib/action_dispatch/railtie.rb new file mode 100644 index 0000000000..9fd034cdd2 --- /dev/null +++ b/actionpack/lib/action_dispatch/railtie.rb @@ -0,0 +1,58 @@ +require "action_dispatch" +require "rails" + +module ActionDispatch + class Railtie < Rails::Railtie + plugin_name :action_dispatch + + require "action_dispatch/railties/subscriber" + subscriber ActionDispatch::Railties::Subscriber.new + + class MetalMiddlewareBuilder + def initialize(metals) + @metals = metals + end + + def new(app) + ActionDispatch::Cascade.new(@metals, app) + end + + def name + ActionDispatch::Cascade.name + end + alias_method :to_s, :name + end + + initializer "action_dispatch.initialize_metal" do |app| + metal_root = "#{Rails.root}/app/metal" + load_list = app.config.metals || Dir["#{metal_root}/**/*.rb"] + + metals = load_list.map { |metal| + metal = File.basename(metal.gsub("#{metal_root}/", ''), '.rb') + require_dependency metal + metal.camelize.constantize + }.compact + + middleware = MetalMiddlewareBuilder.new(metals) + app.config.middleware.insert_before(:"ActionDispatch::ParamsParser", middleware) + end + + # Prepare dispatcher callbacks and run 'prepare' callbacks + initializer "action_dispatch.prepare_dispatcher" do |app| + # TODO: This used to say unless defined?(Dispatcher). Find out why and fix. + require 'rails/dispatcher' + + unless app.config.cache_classes + # Setup dev mode route reloading + routes_last_modified = app.routes_changed_at + reload_routes = lambda do + unless app.routes_changed_at == routes_last_modified + routes_last_modified = app.routes_changed_at + app.reload_routes! + end + end + ActionDispatch::Callbacks.before { |callbacks| reload_routes.call } + end + end + end +end \ No newline at end of file diff --git a/actionpack/lib/action_dispatch/railties/subscriber.rb b/actionpack/lib/action_dispatch/railties/subscriber.rb new file mode 100644 index 0000000000..c08a844c6a --- /dev/null +++ b/actionpack/lib/action_dispatch/railties/subscriber.rb @@ -0,0 +1,17 @@ +module ActionDispatch + module Railties + class Subscriber < Rails::Subscriber + def before_dispatch(event) + request = Request.new(event.payload[:env]) + path = request.request_uri.inspect rescue "unknown" + + info "\n\nProcessing #{path} to #{request.formats.join(', ')} " << + "(for #{request.remote_ip} at #{event.time.to_s(:db)}) [#{request.method.to_s.upcase}]" + end + + def logger + ActionController::Base.logger + end + end + end +end \ No newline at end of file diff --git a/actionpack/test/activerecord/controller_runtime_test.rb b/actionpack/test/activerecord/controller_runtime_test.rb index 37c7738301..d6f7cd80ab 100644 --- a/actionpack/test/activerecord/controller_runtime_test.rb +++ b/actionpack/test/activerecord/controller_runtime_test.rb @@ -37,8 +37,8 @@ module ControllerRuntimeSubscriberTest get :show wait - assert_equal 2, @logger.logged(:info).size - assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[1] + assert_equal 1, @logger.logged(:info).size + assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[0] end class SyncSubscriberTest < ActionController::TestCase diff --git a/actionpack/test/controller/subscriber_test.rb b/actionpack/test/controller/subscriber_test.rb index ef1a325799..24132ee928 100644 --- a/actionpack/test/controller/subscriber_test.rb +++ b/actionpack/test/controller/subscriber_test.rb @@ -66,15 +66,10 @@ module ActionControllerSubscriberTest def test_process_action get :show wait - assert_equal 2, logs.size - assert_match /Processed\sAnother::SubscribersController#show/, logs[0] - end - - def test_process_action_formats - get :show - wait - assert_equal 2, logs.size - assert_match /text\/html/, logs[0] + assert_equal 1, logs.size + assert_match /Completed/, logs.first + assert_match /\[200\]/, logs.first + assert_match /Another::SubscribersController#show/, logs.first end def test_process_action_without_parameters @@ -87,23 +82,14 @@ module ActionControllerSubscriberTest get :show, :id => '10' wait - assert_equal 3, logs.size - assert_equal 'Parameters: {"id"=>"10"}', logs[1] + assert_equal 2, logs.size + assert_equal 'Parameters: {"id"=>"10"}', logs[0] end def test_process_action_with_view_runtime get :show wait - assert_match /\(Views: [\d\.]+ms\)/, logs[1] - end - - def test_process_action_with_status_and_request_uri - get :show - wait - last = logs.last - assert_match /Completed/, last - assert_match /200/, last - assert_match /another\/subscribers\/show/, last + assert_match /\(Views: [\d\.]+ms\)/, logs[0] end def test_process_action_with_filter_parameters @@ -112,7 +98,7 @@ module ActionControllerSubscriberTest get :show, :lifo => 'Pratik', :amount => '420', :step => '1' wait - params = logs[1] + params = logs[0] assert_match /"amount"=>"\[FILTERED\]"/, params assert_match /"lifo"=>"\[FILTERED\]"/, params assert_match /"step"=>"1"/, params @@ -122,7 +108,7 @@ module ActionControllerSubscriberTest get :redirector wait - assert_equal 3, logs.size + assert_equal 2, logs.size assert_equal "Redirected to http://foo.bar/", logs[0] end @@ -130,7 +116,7 @@ module ActionControllerSubscriberTest get :data_sender wait - assert_equal 3, logs.size + assert_equal 2, logs.size assert_match /Sent data omg\.txt/, logs[0] end @@ -138,7 +124,7 @@ module ActionControllerSubscriberTest get :file_sender wait - assert_equal 3, logs.size + assert_equal 2, logs.size assert_match /Sent file/, logs[0] assert_match /test\/fixtures\/company\.rb/, logs[0] end @@ -147,7 +133,7 @@ module ActionControllerSubscriberTest get :xfile_sender wait - assert_equal 3, logs.size + assert_equal 2, logs.size assert_match /Sent X\-Sendfile header/, logs[0] assert_match /test\/fixtures\/company\.rb/, logs[0] end @@ -157,7 +143,7 @@ module ActionControllerSubscriberTest get :with_fragment_cache wait - assert_equal 4, logs.size + assert_equal 3, logs.size assert_match /Exist fragment\? views\/foo/, logs[0] assert_match /Write fragment views\/foo/, logs[1] ensure @@ -169,7 +155,7 @@ module ActionControllerSubscriberTest get :with_page_cache wait - assert_equal 3, logs.size + assert_equal 2, logs.size assert_match /Write page/, logs[0] assert_match /\/index\.html/, logs[0] ensure diff --git a/actionpack/test/dispatch/notifications_test.rb b/actionpack/test/dispatch/notifications_test.rb deleted file mode 100644 index d834a734ef..0000000000 --- a/actionpack/test/dispatch/notifications_test.rb +++ /dev/null @@ -1,69 +0,0 @@ -require 'abstract_unit' - -class NotificationsMiddlewareTest < ActionController::IntegrationTest - Boomer = lambda do |env| - req = ActionDispatch::Request.new(env) - case req.path - when "/" - [200, {}, []] - else - raise "puke!" - end - end - - App = ActionDispatch::Notifications.new(Boomer) - - def setup - @queue = ActiveSupport::Notifications::Fanout.new - @notifier = ActiveSupport::Notifications::Notifier.new(@queue) - ActiveSupport::Notifications.notifier = @notifier - - @events = [] - ActiveSupport::Notifications.subscribe do |*args| - @events << args - end - - @app = App - end - - test "publishes notifications" do - get "/" - ActiveSupport::Notifications.notifier.wait - - assert_equal 2, @events.size - before, after = @events - - assert_equal 'action_dispatch.before_dispatch', before[0] - assert_kind_of Hash, before[4][:env] - assert_equal 'GET', before[4][:env]["REQUEST_METHOD"] - - assert_equal 'action_dispatch.after_dispatch', after[0] - assert_kind_of Hash, after[4][:env] - assert_equal 'GET', after[4][:env]["REQUEST_METHOD"] - end - - test "publishes notifications on failure" do - begin - get "/puke" - rescue - end - - ActiveSupport::Notifications.notifier.wait - - assert_equal 3, @events.size - before, after, exception = @events - - assert_equal 'action_dispatch.before_dispatch', before[0] - assert_kind_of Hash, before[4][:env] - assert_equal 'GET', before[4][:env]["REQUEST_METHOD"] - - assert_equal 'action_dispatch.after_dispatch', after[0] - assert_kind_of Hash, after[4][:env] - assert_equal 'GET', after[4][:env]["REQUEST_METHOD"] - - assert_equal 'action_dispatch.exception', exception[0] - assert_kind_of Hash, exception[4][:env] - assert_equal 'GET', exception[4][:env]["REQUEST_METHOD"] - assert_kind_of RuntimeError, exception[4][:exception] - end -end \ No newline at end of file diff --git a/actionpack/test/dispatch/subscriber_test.rb b/actionpack/test/dispatch/subscriber_test.rb new file mode 100644 index 0000000000..a7f1a2659a --- /dev/null +++ b/actionpack/test/dispatch/subscriber_test.rb @@ -0,0 +1,112 @@ +require "abstract_unit" +require "rails/subscriber/test_helper" +require "action_dispatch/railties/subscriber" + +module DispatcherSubscriberTest + Boomer = lambda do |env| + req = ActionDispatch::Request.new(env) + case req.path + when "/" + [200, {}, []] + else + raise "puke!" + end + end + + App = ActionDispatch::Notifications.new(Boomer) + + def setup + Rails::Subscriber.add(:action_dispatch, ActionDispatch::Railties::Subscriber.new) + @app = App + super + + @events = [] + ActiveSupport::Notifications.subscribe do |*args| + @events << args + end + end + + def set_logger(logger) + ActionController::Base.logger = logger + end + + def test_publishes_notifications + get "/" + wait + + assert_equal 2, @events.size + before, after = @events + + assert_equal 'action_dispatch.before_dispatch', before[0] + assert_kind_of Hash, before[4][:env] + assert_equal 'GET', before[4][:env]["REQUEST_METHOD"] + + assert_equal 'action_dispatch.after_dispatch', after[0] + assert_kind_of Hash, after[4][:env] + assert_equal 'GET', after[4][:env]["REQUEST_METHOD"] + end + + def test_publishes_notifications_even_on_failures + begin + get "/puke" + rescue + end + + wait + + assert_equal 3, @events.size + before, after, exception = @events + + assert_equal 'action_dispatch.before_dispatch', before[0] + assert_kind_of Hash, before[4][:env] + assert_equal 'GET', before[4][:env]["REQUEST_METHOD"] + + assert_equal 'action_dispatch.after_dispatch', after[0] + assert_kind_of Hash, after[4][:env] + assert_equal 'GET', after[4][:env]["REQUEST_METHOD"] + + assert_equal 'action_dispatch.exception', exception[0] + assert_kind_of Hash, exception[4][:env] + assert_equal 'GET', exception[4][:env]["REQUEST_METHOD"] + assert_kind_of RuntimeError, exception[4][:exception] + end + + def test_subscriber_logs_notifications + get "/" + wait + + log = @logger.logged(:info).first + assert_equal 1, @logger.logged(:info).size + + assert_match %r{^Processing "/" to text/html}, log + assert_match %r{\(for 127\.0\.0\.1}, log + assert_match %r{\[GET\]}, log + end + + def test_subscriber_has_its_logged_flushed_after_request + assert_equal 0, @logger.flush_count + get "/" + wait + assert_equal 1, @logger.flush_count + end + + def test_subscriber_has_its_logged_flushed_even_after_busted_requests + assert_equal 0, @logger.flush_count + begin + get "/puke" + rescue + end + wait + assert_equal 1, @logger.flush_count + end + + class SyncSubscriberTest < ActionController::IntegrationTest + include Rails::Subscriber::SyncTestHelper + include DispatcherSubscriberTest + end + + class AsyncSubscriberTest < ActionController::IntegrationTest + include Rails::Subscriber::AsyncTestHelper + include DispatcherSubscriberTest + end +end \ No newline at end of file diff --git a/activerecord/lib/active_record/railties/subscriber.rb b/activerecord/lib/active_record/railties/subscriber.rb index 7c2a10cf0f..fd873dbff8 100644 --- a/activerecord/lib/active_record/railties/subscriber.rb +++ b/activerecord/lib/active_record/railties/subscriber.rb @@ -12,7 +12,7 @@ module ActiveRecord name = color(name, :magenta, true) end - debug "#{name} #{sql}" + debug " #{name} #{sql}" end def odd? diff --git a/railties/lib/rails.rb b/railties/lib/rails.rb index 4ded2515fc..0bc7160815 100644 --- a/railties/lib/rails.rb +++ b/railties/lib/rails.rb @@ -1,9 +1,8 @@ -require "pathname" +require 'pathname' require 'active_support' require 'active_support/core_ext/kernel/reporting' require 'active_support/core_ext/logger' -require 'action_dispatch' require 'rails/initializable' require 'rails/application' @@ -18,6 +17,8 @@ require 'rails/deprecation' require 'rails/subscriber' require 'rails/ruby_version_check' +require 'action_dispatch/railtie' + # For Ruby 1.8, this initialization sets $KCODE to 'u' to enable the # multibyte safe operations. Plugin authors supporting other encodings # should override this behaviour and set the relevant +default_charset+