aboutsummaryrefslogtreecommitdiffstats
path: root/actionpack
diff options
context:
space:
mode:
authorJosé Valim <jose.valim@gmail.com>2010-01-19 12:52:10 +0100
committerJosé Valim <jose.valim@gmail.com>2010-01-19 15:35:24 +0100
commita8e25a518ae8df1682c84affa3b986ca3627da12 (patch)
tree363327cc6832cd7b0f2727cebe6ed0c1fe30b831 /actionpack
parent5a81dbf4894f112b73da160611c8be28b44c261f (diff)
downloadrails-a8e25a518ae8df1682c84affa3b986ca3627da12.tar.gz
rails-a8e25a518ae8df1682c84affa3b986ca3627da12.tar.bz2
rails-a8e25a518ae8df1682c84affa3b986ca3627da12.zip
Move parameters to the top on logging.
Diffstat (limited to 'actionpack')
-rw-r--r--actionpack/lib/action_controller/base.rb2
-rw-r--r--actionpack/lib/action_controller/metal/filter_parameter_logging.rb5
-rw-r--r--actionpack/lib/action_controller/metal/instrumentation.rb20
-rw-r--r--actionpack/lib/action_controller/railties/subscriber.rb8
-rw-r--r--actionpack/test/activerecord/controller_runtime_test.rb4
-rw-r--r--actionpack/test/controller/subscriber_test.rb54
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