diff options
Diffstat (limited to 'actionpack/lib')
-rw-r--r-- | actionpack/lib/abstract_controller/logger.rb | 20 | ||||
-rw-r--r-- | actionpack/lib/action_controller/base.rb | 1 | ||||
-rw-r--r-- | actionpack/lib/action_controller/caching.rb | 11 | ||||
-rw-r--r-- | actionpack/lib/action_controller/caching/fragments.rb | 2 | ||||
-rw-r--r-- | actionpack/lib/action_controller/metal/active_record_runtime.rb | 27 | ||||
-rw-r--r-- | actionpack/lib/action_controller/metal/benchmarking.rb | 72 | ||||
-rw-r--r-- | actionpack/lib/action_controller/metal/filter_parameter_logging.rb | 22 | ||||
-rw-r--r-- | actionpack/lib/action_controller/metal/logger.rb | 70 | ||||
-rw-r--r-- | actionpack/lib/action_controller/rails.rb | 13 | ||||
-rw-r--r-- | actionpack/lib/action_view/render/rendering.rb | 9 |
10 files changed, 108 insertions, 139 deletions
diff --git a/actionpack/lib/abstract_controller/logger.rb b/actionpack/lib/abstract_controller/logger.rb index e3bcd28da7..a23a13e1d6 100644 --- a/actionpack/lib/abstract_controller/logger.rb +++ b/actionpack/lib/abstract_controller/logger.rb @@ -9,25 +9,5 @@ module AbstractController cattr_accessor :logger extend ActiveSupport::Benchmarkable end - - # A class that allows you to defer expensive processing - # until the logger actually tries to log. Otherwise, you are - # forced to do the processing in advance, and send the - # entire processed String to the logger, which might - # just discard the String if the log level is too low. - # - # TODO: Require that Rails loggers accept a block. - class DelayedLog < ActiveSupport::BasicObject - def initialize(&block) - @str, @block = nil, block - end - - def method_missing(*args, &block) - unless @str - @str, @block = @block.call, nil - end - @str.send(*args, &block) - end - end end end diff --git a/actionpack/lib/action_controller/base.rb b/actionpack/lib/action_controller/base.rb index dbba69f637..67656110c4 100644 --- a/actionpack/lib/action_controller/base.rb +++ b/actionpack/lib/action_controller/base.rb @@ -15,7 +15,6 @@ module ActionController include ActionController::ConditionalGet include ActionController::RackDelegation include ActionController::Logger - include ActionController::Benchmarking include ActionController::Configuration # Legacy modules diff --git a/actionpack/lib/action_controller/caching.rb b/actionpack/lib/action_controller/caching.rb index d784138ebe..69ed84da95 100644 --- a/actionpack/lib/action_controller/caching.rb +++ b/actionpack/lib/action_controller/caching.rb @@ -60,6 +60,17 @@ module ActionController #:nodoc: def cache_configured? perform_caching && cache_store end + + def log_event(name, before, after, instrumenter_id, payload) + if name.to_s =~ /(read|write|cache|expire|exist)_(fragment|page)\??/ + key_or_path = payload[:key] || payload[:path] + human_name = name.to_s.humanize + duration = (after - before) * 1000 + logger.info("#{human_name} #{key_or_path.inspect} (%.1fms)" % duration) + else + super + end + end end def caching_allowed? diff --git a/actionpack/lib/action_controller/caching/fragments.rb b/actionpack/lib/action_controller/caching/fragments.rb index 8c1167d526..f569d0dd8b 100644 --- a/actionpack/lib/action_controller/caching/fragments.rb +++ b/actionpack/lib/action_controller/caching/fragments.rb @@ -74,7 +74,7 @@ module ActionController #:nodoc: return unless cache_configured? key = fragment_cache_key(key) - ActiveSupport::Notifications.instrument(:fragment_exist?, :key => key) do + ActiveSupport::Notifications.instrument(:exist_fragment?, :key => key) do cache_store.exist?(key, options) end end diff --git a/actionpack/lib/action_controller/metal/active_record_runtime.rb b/actionpack/lib/action_controller/metal/active_record_runtime.rb new file mode 100644 index 0000000000..29f6dcc783 --- /dev/null +++ b/actionpack/lib/action_controller/metal/active_record_runtime.rb @@ -0,0 +1,27 @@ +module ActionController + module ActiveRecordRuntime + extend ActiveSupport::Concern + + attr_internal :db_runtime + + def cleanup_view_runtime + if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? + db_rt_before_render = ActiveRecord::Base.connection.reset_runtime + runtime = super + db_rt_after_render = ActiveRecord::Base.connection.reset_runtime + self.db_runtime = db_rt_before_render + db_rt_after_render + runtime - db_rt_after_render + else + super + end + end + + module ClassMethods + def process_log_action(controller) + super + db_runtime = controller.send :db_runtime + logger.info(" ActiveRecord runtime: %.1fms" % db_runtime.to_f) if db_runtime + end + end + end +end
\ No newline at end of file diff --git a/actionpack/lib/action_controller/metal/benchmarking.rb b/actionpack/lib/action_controller/metal/benchmarking.rb deleted file mode 100644 index f73f635b0d..0000000000 --- a/actionpack/lib/action_controller/metal/benchmarking.rb +++ /dev/null @@ -1,72 +0,0 @@ -require 'active_support/core_ext/benchmark' - -module ActionController #:nodoc: - # The benchmarking module times the performance of actions and reports to the logger. If the Active Record - # package has been included, a separate timing section for database calls will be added as well. - module Benchmarking #:nodoc: - extend ActiveSupport::Concern - - protected - def render(*args, &block) - if logger - if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? - db_runtime = ActiveRecord::Base.connection.reset_runtime - end - - render_output = nil - @view_runtime = Benchmark.ms { render_output = super } - - if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? - @db_rt_before_render = db_runtime - @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime - @view_runtime -= @db_rt_after_render - end - - render_output - else - super - end - end - - private - def process_action(*args) - if logger - ms = [Benchmark.ms { super }, 0.01].max - logging_view = defined?(@view_runtime) - logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected? - - log_message = 'Completed in %.0fms' % ms - - if logging_view || logging_active_record - log_message << " (" - log_message << view_runtime if logging_view - - if logging_active_record - log_message << ", " if logging_view - log_message << active_record_runtime + ")" - else - ")" - end - end - - log_message << " | #{response.status}" - log_message << " [#{complete_request_uri rescue "unknown"}]" - - logger.info(log_message) - else - super - end - end - - def view_runtime - "View: %.0f" % @view_runtime - end - - def active_record_runtime - db_runtime = ActiveRecord::Base.connection.reset_runtime - db_runtime += @db_rt_before_render if @db_rt_before_render - db_runtime += @db_rt_after_render if @db_rt_after_render - "DB: %.0f" % db_runtime - end - end -end diff --git a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb index a53c052075..59e200396a 100644 --- a/actionpack/lib/action_controller/metal/filter_parameter_logging.rb +++ b/actionpack/lib/action_controller/metal/filter_parameter_logging.rb @@ -2,8 +2,6 @@ module ActionController module FilterParameterLogging extend ActiveSupport::Concern - include AbstractController::Logger - module ClassMethods # Replace sensitive parameter data from the request log. # Filters parameters that have any of the arguments as a substring. @@ -54,23 +52,25 @@ module ActionController end protected :filter_parameters end - end - INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path] + protected - def process(*) - response = super - if logger - parameters = filter_parameters(params).except!(*INTERNAL_PARAMS) - logger.info { " Parameters: #{parameters.inspect}" } unless parameters.empty? + # 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 - response end + INTERNAL_PARAMS = [:controller, :action, :format, :_method, :only_path] + protected def filter_parameters(params) - params.dup + params.dup.except!(*INTERNAL_PARAMS) end end diff --git a/actionpack/lib/action_controller/metal/logger.rb b/actionpack/lib/action_controller/metal/logger.rb index 956d7dd371..5d14f6c9c9 100644 --- a/actionpack/lib/action_controller/metal/logger.rb +++ b/actionpack/lib/action_controller/metal/logger.rb @@ -1,34 +1,74 @@ require 'abstract_controller/logger' module ActionController + # Adds instrumentation to <tt>process_action</tt> and a <tt>log_event</tt> 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 - # Override process_action in the AbstractController::Base - # to log details about the method. + extend ActiveSupport::Concern + + attr_internal :view_runtime + def process_action(action) - result = ActiveSupport::Notifications.instrument(:process_action, - :controller => self, :action => action) do + ActiveSupport::Notifications.instrument(:process_action, :controller => self, :action => action) do super end + end + def render(*args, &block) if logger - log = AbstractController::Logger::DelayedLog.new do - "\n\nProcessing #{self.class.name}\##{action_name} " \ - "to #{request.formats} (for #{request_origin}) " \ - "[#{request.method.to_s.upcase}]" + render_output = nil + + self.view_runtime = cleanup_view_runtime do + Benchmark.ms { render_output = super } end - logger.info(log) + render_output + else + super end + end - result + def cleanup_view_runtime + yield end - private + module ClassMethods + def log_event(name, before, after, instrumenter_id, payload) + if name == :process_action + duration = [(after - before) * 1000, 0.01].max + controller = payload[:controller] + request = controller.request + + logger.info "\n\nProcessed #{controller.class.name}##{payload[:action]} " \ + "to #{request.formats} (for #{request.remote_ip} at #{before.to_s(:db)}) " \ + "[#{request.method.to_s.upcase}]" - # Returns the request origin with the IP and time. This needs to be cached, - # otherwise we would get different results for each time it calls. - def request_origin - @request_origin ||= "#{request.remote_ip} at #{Time.now.to_s(:db)}" + log_process_action(controller) + + message = "Completed in %.0fms" % duration + message << " | #{controller.response.status}" + message << " [#{request.request_uri rescue "unknown"}]" + + logger.info(message) + elsif name == :render_template + # TODO Make render_template logging work if you are using just ActionView + duration = (after - before) * 1000 + message = "Rendered #{payload[:identifier]}" + message << " within #{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. + 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 diff --git a/actionpack/lib/action_controller/rails.rb b/actionpack/lib/action_controller/rails.rb index 36a52b3149..e381828ee4 100644 --- a/actionpack/lib/action_controller/rails.rb +++ b/actionpack/lib/action_controller/rails.rb @@ -14,10 +14,6 @@ module ActionController end # Routing must be initialized after plugins to allow the former to extend the routes - # --- - # If Action Controller is not one of the loaded frameworks (Configuration#frameworks) - # this does nothing. Otherwise, it loads the routing definitions and sets up - # loading module used to lazily load controllers (Configuration#controller_paths). initializer "action_controller.initialize_routing" do |app| app.route_configuration_files << app.config.routes_configuration_file app.route_configuration_files << app.config.builtin_routes_configuration_file @@ -88,13 +84,8 @@ module ActionController initializer "action_controller.notifications" do |app| require 'active_support/notifications' - ActiveSupport::Notifications.subscribe(/(read|write|cache|expire|exist)_(fragment|page)\??/) do |*args| - event = ActiveSupport::Notifications::Event.new(*args) - - if logger = ActionController::Base.logger - human_name = event.name.to_s.humanize - logger.info("#{human_name} (%.1fms)" % event.duration) - end + ActiveSupport::Notifications.subscribe do |*args| + ActionController::Base.log_event(*args) if ActionController::Base.logger end end diff --git a/actionpack/lib/action_view/render/rendering.rb b/actionpack/lib/action_view/render/rendering.rb index 5e7dd3e2df..0302e44b4e 100644 --- a/actionpack/lib/action_view/render/rendering.rb +++ b/actionpack/lib/action_view/render/rendering.rb @@ -107,12 +107,6 @@ module ActionView end def _render_template(template, layout = nil, options = {}, partial = nil) - logger && logger.info do - msg = "Rendering #{template.inspect}" - msg << " (#{options[:status]})" if options[:status] - msg - end - locals = options[:locals] || {} content = ActiveSupport::Notifications.instrument(:render_template, @@ -124,8 +118,7 @@ module ActionView if layout @_layout = layout.identifier - logger.info("Rendering template within #{layout.inspect}") if logger - content = _render_layout(layout, locals) + content = _render_layout(layout, locals) end content |