From da5978c22374b8a3b15a421ff4920e0940435253 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Wed, 13 Jan 2010 00:41:04 +0100 Subject: Add subscriber for ActionPack and move all logging inside it. --- .../metal/filter_parameter_logging.rb | 17 +--- .../lib/action_controller/metal/instrumentation.rb | 77 ++++++++++++++++++ actionpack/lib/action_controller/metal/logger.rb | 93 ---------------------- .../lib/action_controller/metal/redirecting.rb | 2 - .../lib/action_controller/metal/streaming.rb | 4 - 5 files changed, 80 insertions(+), 113 deletions(-) create mode 100644 actionpack/lib/action_controller/metal/instrumentation.rb delete mode 100644 actionpack/lib/action_controller/metal/logger.rb (limited to 'actionpack/lib/action_controller/metal') diff --git a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb index 59e200396a..9e03f50759 100644 --- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb +++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb @@ -2,6 +2,8 @@ module ActionController module FilterParameterLogging extend ActiveSupport::Concern + INTERNAL_PARAMS = %w(controller action format _method only_path) + module ClassMethods # Replace sensitive parameter data from the request log. # Filters parameters that have any of the arguments as a substring. @@ -48,25 +50,12 @@ module ActionController filtered_params[key] = value end - filtered_params + filtered_params.except!(*INTERNAL_PARAMS) end protected :filter_parameters end - - protected - - # Overwrite log_process_action to include parameters information. - # If this method is invoked, it means logger is defined, so don't - # worry with such scenario here. - def log_process_action(controller) #:nodoc: - params = controller.send(:filter_parameters, controller.request.params) - logger.info " Parameters: #{params.inspect}" unless params.empty? - super - end end - INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path] - protected def filter_parameters(params) diff --git a/actionpack/lib/action_controller/metal/instrumentation.rb b/actionpack/lib/action_controller/metal/instrumentation.rb new file mode 100644 index 0000000000..91d454f0c3 --- /dev/null +++ b/actionpack/lib/action_controller/metal/instrumentation.rb @@ -0,0 +1,77 @@ +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. + module Instrumentation + extend ActiveSupport::Concern + + included do + include AbstractController::Logger + end + + attr_internal :view_runtime + + def process_action(action, *args) + ActiveSupport::Notifications.instrument("action_controller.process_action", + :controller => self, :action => action) do + super + end + end + + def render(*args, &block) + if logger + render_output = nil + + self.view_runtime = cleanup_view_runtime do + Benchmark.ms { render_output = super } + end + + render_output + else + super + end + end + + def send_file(path, options={}) + ActiveSupport::Notifications.instrument("action_controller.send_file", + options.merge(:path => path)) do + super + end + end + + def send_data(data, options = {}) + ActiveSupport::Notifications.instrument("action_controller.send_data", options) do + super + end + end + + def redirect_to(*args) + super + ActiveSupport::Notifications.instrument("action_controller.redirect_to", + :status => self.status, :location => self.location) + end + + # A hook which allows you to clean up any time taken into account in + # views wrongly, like database querying time. + # + # def cleanup_view_runtime + # super - time_taken_in_something_expensive + # end + # + # :api: plugin + def cleanup_view_runtime #:nodoc: + yield + end + + module ClassMethods + # A hook which allows other frameworks to log what happened during + # controller process action. + # :api: plugin + def log_process_action(controller) #:nodoc: + view_runtime = controller.send :view_runtime + logger.info(" View runtime: %.1fms" % view_runtime.to_f) if view_runtime + end + end + end +end \ No newline at end of file diff --git a/actionpack/lib/action_controller/metal/logger.rb b/actionpack/lib/action_controller/metal/logger.rb deleted file mode 100644 index e995d6bcea..0000000000 --- a/actionpack/lib/action_controller/metal/logger.rb +++ /dev/null @@ -1,93 +0,0 @@ -require 'abstract_controller/logger' - -module ActionController - # Adds instrumentation to process_action and a log_event method - # responsible to log events from ActiveSupport::Notifications. This module handles - # :process_action and :render_template events but allows any other module to hook - # into log_event and provide its own logging facilities (as in ActionController::Caching). - module Logger - extend ActiveSupport::Concern - - included do - include AbstractController::Logger - end - - attr_internal :view_runtime - - def process_action(action) - ActiveSupport::Notifications.instrument("action_controller.process_action", - :controller => self, :action => action) do - super - end - end - - def render(*args, &block) - if logger - render_output = nil - - self.view_runtime = cleanup_view_runtime do - Benchmark.ms { render_output = super } - end - - render_output - else - super - end - end - - # If you want to remove any time taken into account in :view_runtime - # wrongly, you can do it here: - # - # def cleanup_view_runtime - # super - time_taken_in_something_expensive - # end - # - # :api: plugin - def cleanup_view_runtime #:nodoc: - yield - end - - module ClassMethods - # This is the hook invoked by ActiveSupport::Notifications.subscribe. - # If you need to log any event, overwrite the method and do it here. - def log_event(name, before, after, instrumenter_id, payload) #:nodoc: - if name == "action_controller.process_action" - duration = [(after - before) * 1000, 0.01].max - controller = payload[:controller] - request = controller.request - - logger.info "\nProcessed #{controller.class.name}##{payload[:action]} " \ - "to #{request.formats} (for #{request.remote_ip} at #{before.to_s(:db)}) " \ - "[#{request.method.to_s.upcase}]" - - log_process_action(controller) - - message = "Completed in %.0fms" % duration - message << " | #{controller.response.status}" - message << " [#{request.request_uri rescue "unknown"}]\n\n" - - logger.info(message) - elsif name == "action_view.render_template" - duration = (after - before) * 1000 - message = "Rendered #{from_rails_root(payload[:identifier])}" - message << " within #{from_rails_root(payload[:layout])}" if payload[:layout] - message << (" (%.1fms)" % duration) - logger.info(message) - end - end - - protected - - # A hook which allows logging what happened during controller process action. - # :api: plugin - def log_process_action(controller) #:nodoc: - view_runtime = controller.send :view_runtime - logger.info(" View runtime: %.1fms" % view_runtime.to_f) if view_runtime - end - - def from_rails_root(string) - defined?(Rails.root) ? string.sub("#{Rails.root}/app/views/", "") : string - end - end - end -end \ No newline at end of file diff --git a/actionpack/lib/action_controller/metal/redirecting.rb b/actionpack/lib/action_controller/metal/redirecting.rb index 7b277c0ae0..faf0589fd2 100644 --- a/actionpack/lib/action_controller/metal/redirecting.rb +++ b/actionpack/lib/action_controller/metal/redirecting.rb @@ -57,8 +57,6 @@ module ActionController self.status = _extract_redirect_to_status(options, response_status) self.location = _compute_redirect_to_location(options) self.response_body = "You are being redirected." - - logger.info("Redirected to #{location}") if logger && logger.info? end private diff --git a/actionpack/lib/action_controller/metal/streaming.rb b/actionpack/lib/action_controller/metal/streaming.rb index 288b5d7c99..8f03b8bb17 100644 --- a/actionpack/lib/action_controller/metal/streaming.rb +++ b/actionpack/lib/action_controller/metal/streaming.rb @@ -88,13 +88,11 @@ module ActionController #:nodoc: @performed_render = false if options[:x_sendfile] - logger.info "Sending #{X_SENDFILE_HEADER} header #{path}" if logger head options[:status], X_SENDFILE_HEADER => path else if options[:stream] # TODO : Make render :text => proc {} work with the new base render :status => options[:status], :text => Proc.new { |response, output| - logger.info "Streaming file #{path}" unless logger.nil? len = options[:buffer_size] || 4096 File.open(path, 'rb') do |file| while buf = file.read(len) @@ -103,7 +101,6 @@ module ActionController #:nodoc: end } else - logger.info "Sending file #{path}" unless logger.nil? File.open(path, 'rb') { |file| render :status => options[:status], :text => file.read } end end @@ -141,7 +138,6 @@ module ActionController #:nodoc: # data to the browser, then use render :text => proc { ... } # instead. See ActionController::Base#render for more information. def send_data(data, options = {}) #:doc: - logger.info "Sending data #{options[:filename]}" if logger send_file_headers! options.merge(:length => data.bytesize) render :status => options[:status], :text => data end -- cgit v1.2.3