diff options
Diffstat (limited to 'actionpack')
6 files changed, 52 insertions, 41 deletions
diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb index 260e5da336..f86a61d791 100644 --- a/actionpack/lib/action_controller/base.rb +++ b/actionpack/lib/action_controller/base.rb @@ -26,6 +26,7 @@ module ActionController include ActionController::Compatibility include ActionController::Cookies + include ActionController::FilterParameterLogging include ActionController::Flash include ActionController::Verification include ActionController::RequestForgeryProtection @@ -37,7 +38,6 @@ module ActionController # Add instrumentations hooks at the bottom, to ensure they instrument # all the methods properly. include ActionController::Instrumentation - include ActionController::FilterParameterLogging # TODO: Extract into its own module # This should be moved together with other normalizing behavior diff --git a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb index 0b1e1ee6ab..9e03f50759 100644 --- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb +++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb @@ -58,11 +58,6 @@ module ActionController protected - def append_info_to_payload(payload) - super - payload[:params] = filter_parameters(request.params) - end - def filter_parameters(params) params.dup.except!(*INTERNAL_PARAMS) end diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb index 876f778751..7b2b037c67 100644 --- a/actionpack/lib/action_controller/metal/instrumentation.rb +++ b/actionpack/lib/action_controller/metal/instrumentation.rb @@ -9,18 +9,24 @@ module ActionController module Instrumentation extend ActiveSupport::Concern - included do - include AbstractController::Logger - end + include AbstractController::Logger + include ActionController::FilterParameterLogging attr_internal :view_runtime def process_action(action, *args) - ActiveSupport::Notifications.instrument("action_controller.process_action") do |payload| + raw_payload = { + :controller => self.class.name, + :action => self.action_name, + :params => filter_parameters(params), + :formats => request.formats.map(&:to_sym) + } + + ActiveSupport::Notifications.instrument("action_controller.start_processing", raw_payload.dup) + + ActiveSupport::Notifications.instrument("action_controller.process_action", raw_payload) do |payload| result = super - payload[:controller] = self.class.name - payload[:action] = self.action_name - payload[:status] = response.status + payload[:status] = response.status append_info_to_payload(payload) result end diff --git a/actionpack/lib/action_controller/railties/subscriber.rb b/actionpack/lib/action_controller/railties/subscriber.rb index 6659e5df47..d257d6ac2c 100644 --- a/actionpack/lib/action_controller/railties/subscriber.rb +++ b/actionpack/lib/action_controller/railties/subscriber.rb @@ -1,15 +1,19 @@ module ActionController module Railties class Subscriber < Rails::Subscriber - def process_action(event) + def start_processing(event) payload = event.payload + info " Processing by #{payload[:controller]}##{payload[:action]} as #{payload[:formats].first.to_s.upcase}" info " Parameters: #{payload[:params].inspect}" unless payload[:params].blank? + end + def process_action(event) + payload = event.payload additions = ActionController::Base.log_process_action(payload) message = "Completed in %.0fms" % event.duration message << " (#{additions.join(" | ")})" unless additions.blank? - message << " by #{payload[:controller]}##{payload[:action]} [#{payload[:status]}]" + message << " with #{payload[:status]}" info(message) end diff --git a/actionpack/test/activerecord/controller_runtime_test.rb b/actionpack/test/activerecord/controller_runtime_test.rb index d6f7cd80ab..37c7738301 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 1, @logger.logged(:info).size - assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[0] + assert_equal 2, @logger.logged(:info).size + assert_match /\(Views: [\d\.]+ms | ActiveRecord: [\d\.]+ms\)/, @logger.logged(:info)[1] end class SyncSubscriberTest < ActionController::TestCase diff --git a/actionpack/test/controller/subscriber_test.rb b/actionpack/test/controller/subscriber_test.rb index 24132ee928..950eecaf6f 100644 --- a/actionpack/test/controller/subscriber_test.rb +++ b/actionpack/test/controller/subscriber_test.rb @@ -63,13 +63,19 @@ module ActionControllerSubscriberTest ActionController::Base.logger = logger end + def test_start_processing + get :show + wait + assert_equal 2, logs.size + assert_equal "Processing by Another::SubscribersController#show as HTML", logs.first + end + def test_process_action get :show wait - assert_equal 1, logs.size - assert_match /Completed/, logs.first - assert_match /\[200\]/, logs.first - assert_match /Another::SubscribersController#show/, logs.first + assert_equal 2, logs.size + assert_match /Completed/, logs.last + assert_match /with 200/, logs.last end def test_process_action_without_parameters @@ -82,14 +88,14 @@ module ActionControllerSubscriberTest get :show, :id => '10' wait - assert_equal 2, logs.size - assert_equal 'Parameters: {"id"=>"10"}', logs[0] + assert_equal 3, logs.size + assert_equal 'Parameters: {"id"=>"10"}', logs[1] end def test_process_action_with_view_runtime get :show wait - assert_match /\(Views: [\d\.]+ms\)/, logs[0] + assert_match /\(Views: [\d\.]+ms\)/, logs[1] end def test_process_action_with_filter_parameters @@ -98,7 +104,7 @@ module ActionControllerSubscriberTest get :show, :lifo => 'Pratik', :amount => '420', :step => '1' wait - params = logs[0] + params = logs[1] assert_match /"amount"=>"\[FILTERED\]"/, params assert_match /"lifo"=>"\[FILTERED\]"/, params assert_match /"step"=>"1"/, params @@ -108,34 +114,34 @@ module ActionControllerSubscriberTest get :redirector wait - assert_equal 2, logs.size - assert_equal "Redirected to http://foo.bar/", logs[0] + assert_equal 3, logs.size + assert_equal "Redirected to http://foo.bar/", logs[1] end def test_send_data get :data_sender wait - assert_equal 2, logs.size - assert_match /Sent data omg\.txt/, logs[0] + assert_equal 3, logs.size + assert_match /Sent data omg\.txt/, logs[1] end def test_send_file get :file_sender wait - assert_equal 2, logs.size - assert_match /Sent file/, logs[0] - assert_match /test\/fixtures\/company\.rb/, logs[0] + assert_equal 3, logs.size + assert_match /Sent file/, logs[1] + assert_match /test\/fixtures\/company\.rb/, logs[1] end def test_send_xfile get :xfile_sender wait - assert_equal 2, logs.size - assert_match /Sent X\-Sendfile header/, logs[0] - assert_match /test\/fixtures\/company\.rb/, logs[0] + assert_equal 3, logs.size + assert_match /Sent X\-Sendfile header/, logs[1] + assert_match /test\/fixtures\/company\.rb/, logs[1] end def test_with_fragment_cache @@ -143,9 +149,9 @@ module ActionControllerSubscriberTest get :with_fragment_cache wait - assert_equal 3, logs.size - assert_match /Exist fragment\? views\/foo/, logs[0] - assert_match /Write fragment views\/foo/, logs[1] + assert_equal 4, logs.size + assert_match /Exist fragment\? views\/foo/, logs[1] + assert_match /Write fragment views\/foo/, logs[2] ensure ActionController::Base.perform_caching = true end @@ -155,9 +161,9 @@ module ActionControllerSubscriberTest get :with_page_cache wait - assert_equal 2, logs.size - assert_match /Write page/, logs[0] - assert_match /\/index\.html/, logs[0] + assert_equal 3, logs.size + assert_match /Write page/, logs[1] + assert_match /\/index\.html/, logs[1] ensure ActionController::Base.perform_caching = true end |