From 88dd60298ef393e2406ab543a1124a4304a19f61 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Fri, 15 Jan 2010 11:55:11 +0100 Subject: Do not send the whole controller in notifications, cherry pick required pieces. --- actionpack/lib/action_controller/base.rb | 2 +- .../metal/filter_parameter_logging.rb | 5 +++ .../lib/action_controller/metal/instrumentation.rb | 41 +++++++++++++++++----- .../lib/action_controller/railties/subscriber.rb | 17 ++++----- .../active_record/railties/controller_runtime.rb | 11 ++++-- 5 files changed, 54 insertions(+), 22 deletions(-) diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb index 4f564a6377..260e5da336 100644 --- a/actionpack/lib/action_controller/base.rb +++ b/actionpack/lib/action_controller/base.rb @@ -32,12 +32,12 @@ module ActionController include ActionController::Streaming include ActionController::HttpAuthentication::Basic::ControllerMethods include ActionController::HttpAuthentication::Digest::ControllerMethods - include ActionController::FilterParameterLogging include ActionController::Translation # 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 9e03f50759..0b1e1ee6ab 100644 --- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb +++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb @@ -58,6 +58,11 @@ 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 4549f6c451..7222b7b2fa 100644 --- a/actionpack/lib/action_controller/metal/instrumentation.rb +++ b/actionpack/lib/action_controller/metal/instrumentation.rb @@ -2,7 +2,10 @@ require 'abstract_controller/logger' module ActionController # Adds instrumentation to several ends in ActionController::Base. It also provides - # some hooks related with process_action logging and view runtime. + # some hooks related with process_action, this allows an ORM like ActiveRecord + # and/or DataMapper to plug in ActionController and show related information. + # + # Check ActiveRecord::Railties::ControllerRuntime for an example. module Instrumentation extend ActiveSupport::Concern @@ -13,9 +16,17 @@ module ActionController attr_internal :view_runtime def process_action(action, *args) - ActiveSupport::Notifications.instrument("action_controller.process_action", - :controller => self, :action => action) do - super + ActiveSupport::Notifications.instrument("action_controller.process_action") do |payload| + 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 end @@ -47,11 +58,16 @@ module ActionController end def redirect_to(*args) - super - ActiveSupport::Notifications.instrument("action_controller.redirect_to", - :status => self.status, :location => self.location) + ActiveSupport::Notifications.instrument("action_controller.redirect_to") do |payload| + result = super + payload[:status] = self.status + payload[:location] = self.location + result + end end + protected + # A hook which allows you to clean up any time taken into account in # views wrongly, like database querying time. # @@ -64,13 +80,20 @@ module ActionController yield end + # Everytime after an action is processed, this method is invoked + # with the payload, so you can add more information. + # :api: plugin + def append_info_to_payload(payload) #:nodoc: + payload[:view_runtime] = view_runtime + end + module ClassMethods # A hook which allows other frameworks to log what happened during # controller process action. This method should return an array # with the messages to be added. # :api: plugin - def log_process_action(controller) #:nodoc: - messages, view_runtime = [], controller.send(:view_runtime) + def log_process_action(payload) #:nodoc: + messages, view_runtime = [], payload[:view_runtime] messages << ("Views: %.1fms" % view_runtime.to_f) if view_runtime messages end diff --git a/actionpack/lib/action_controller/railties/subscriber.rb b/actionpack/lib/action_controller/railties/subscriber.rb index 0556c6b40e..a9f5d16c58 100644 --- a/actionpack/lib/action_controller/railties/subscriber.rb +++ b/actionpack/lib/action_controller/railties/subscriber.rb @@ -2,22 +2,19 @@ module ActionController module Railties class Subscriber < Rails::Subscriber def process_action(event) - controller = event.payload[:controller] - request = controller.request + payload = event.payload - info "\nProcessed #{controller.class.name}##{event.payload[:action]} " \ - "to #{request.formats.join(', ')} (for #{request.remote_ip} at #{event.time.to_s(:db)}) " \ - "[#{request.method.to_s.upcase}]" + 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}]" - params = controller.send(:filter_parameters, request.params) - info " Parameters: #{params.inspect}" unless params.empty? + info " Parameters: #{payload[:params].inspect}" unless payload[:params].blank? - additions = ActionController::Base.log_process_action(controller) + additions = ActionController::Base.log_process_action(payload) message = "Completed in %.0fms" % event.duration message << " (#{additions.join(" | ")})" unless additions.blank? - message << " | #{controller.response.status}" - message << " [#{request.request_uri rescue "unknown"}]\n\n" + message << " | #{payload[:status]} [#{payload[:request_uri]}]\n\n" info(message) end diff --git a/activerecord/lib/active_record/railties/controller_runtime.rb b/activerecord/lib/active_record/railties/controller_runtime.rb index a4f4e15c2e..aed1c59b00 100644 --- a/activerecord/lib/active_record/railties/controller_runtime.rb +++ b/activerecord/lib/active_record/railties/controller_runtime.rb @@ -5,6 +5,8 @@ module ActiveRecord module ControllerRuntime extend ActiveSupport::Concern + protected + attr_internal :db_runtime def cleanup_view_runtime @@ -19,9 +21,14 @@ module ActiveRecord end end + def append_info_to_payload(payload) + super + payload[:db_runtime] = db_runtime + end + module ClassMethods - def log_process_action(controller) - messages, db_runtime = super, controller.send(:db_runtime) + def log_process_action(payload) + messages, db_runtime = super, payload[:db_runtime] messages << ("ActiveRecord: %.1fms" % db_runtime.to_f) if db_runtime messages end -- cgit v1.2.3