Prefer to pass block when logging.

The Logger by default includes a guard which checks for the
logging level. By removing the custom logging guards, we can decouple
the logging guard from the logging action to be done.

This also follows the good practice listed on http://guides.rubyonrails.org/debugging_rails_applications.html#impact-of-logs-on-performance.

5 files changed, 46 insertions, 43 deletions

diff --git a/actionmailer/lib/action_mailer/log_subscriber.rb b/actionmailer/lib/action_mailer/log_subscriber.rb
index e4aaab34b1..5b57c75ec3 100644
--- a/actionmailer/lib/action_mailer/log_subscriber.rb
+++ b/actionmailer/lib/action_mailer/log_subscriber.rb
@@ -6,25 +6,27 @@ module ActionMailer
   class LogSubscriber < ActiveSupport::LogSubscriber
     # An email was delivered.
     def deliver(event)
-      return unless logger.info?
-      recipients = Array(event.payload[:to]).join(', ')
-      info("\nSent mail to #{recipients} (#{event.duration.round(1)}ms)")
-      debug(event.payload[:mail])
+      info do
+        recipients = Array(event.payload[:to]).join(', ')
+        "\nSent mail to #{recipients} (#{event.duration.round(1)}ms)"
+      end
+
+      debug { event.payload[:mail] }
     end
 
     # An email was received.
     def receive(event)
-      return unless logger.info?
-      info("\nReceived mail (#{event.duration.round(1)}ms)")
-      debug(event.payload[:mail])
+      info { "\nReceived mail (#{event.duration.round(1)}ms)" }
+      debug { event.payload[:mail] }
     end
 
     # An email was generated.
     def process(event)
-      return unless logger.debug?
-      mailer = event.payload[:mailer]
-      action = event.payload[:action]
-      debug("\n#{mailer}##{action}: processed outbound mail in #{event.duration.round(1)}ms")
+      debug do
+        mailer = event.payload[:mailer]
+        action = event.payload[:action]
+        "\n#{mailer}##{action}: processed outbound mail in #{event.duration.round(1)}ms"
+      end
     end
 
     # Use the logger configured for ActionMailer::Base
diff --git a/actionpack/lib/action_controller/log_subscriber.rb b/actionpack/lib/action_controller/log_subscriber.rb
index b1acca2435..89fa75f025 100644
--- a/actionpack/lib/action_controller/log_subscriber.rb
+++ b/actionpack/lib/action_controller/log_subscriber.rb
@@ -16,50 +16,51 @@ module ActionController
     end
 
     def process_action(event)
-      return unless logger.info?
-
-      payload   = event.payload
-      additions = ActionController::Base.log_process_action(payload)
-
-      status = payload[:status]
-      if status.nil? && payload[:exception].present?
-        exception_class_name = payload[:exception].first
-        status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
+      info do
+        payload   = event.payload
+        additions = ActionController::Base.log_process_action(payload)
+
+        status = payload[:status]
+        if status.nil? && payload[:exception].present?
+          exception_class_name = payload[:exception].first
+          status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
+        end
+        message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
+        message << " (#{additions.join(" | ")})" unless additions.blank?
+        message
       end
-      message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round}ms"
-      message << " (#{additions.join(" | ")})" unless additions.blank?
-
-      info(message)
     end
 
     def halted_callback(event)
-      info("Filter chain halted as #{event.payload[:filter].inspect} rendered or redirected")
+      info { "Filter chain halted as #{event.payload[:filter].inspect} rendered or redirected" }
     end
 
     def send_file(event)
-      info("Sent file #{event.payload[:path]} (#{event.duration.round(1)}ms)")
+      info { "Sent file #{event.payload[:path]} (#{event.duration.round(1)}ms)" }
     end
 
     def redirect_to(event)
-      info("Redirected to #{event.payload[:location]}")
+      info { "Redirected to #{event.payload[:location]}" }
     end
 
     def send_data(event)
-      info("Sent data #{event.payload[:filename]} (#{event.duration.round(1)}ms)")
+      info { "Sent data #{event.payload[:filename]} (#{event.duration.round(1)}ms)" }
     end
 
     def unpermitted_parameters(event)
-      unpermitted_keys = event.payload[:keys]
-      debug("Unpermitted parameter#{'s' if unpermitted_keys.size > 1}: #{unpermitted_keys.join(", ")}")
+      debug do
+        unpermitted_keys = event.payload[:keys]
+        "Unpermitted parameter#{'s' if unpermitted_keys.size > 1}: #{unpermitted_keys.join(", ")}"
+      end
     end
 
     def deep_munge(event)
-      message = "Value for params[:#{event.payload[:keys].join('][:')}] was set "\
-                "to nil, because it was one of [], [null] or [null, null, ...]. "\
-                "Go to http://guides.rubyonrails.org/security.html#unsafe-query-generation "\
-                "for more information."\
-
-      debug(message)
+      debug do
+        "Value for params[:#{event.payload[:keys].join('][:')}] was set "\
+        "to nil, because it was one of [], [null] or [null, null, ...]. "\
+        "Go to http://guides.rubyonrails.org/security.html#unsafe-query-generation "\
+        "for more information."\
+      end
     end
 
     %w(write_fragment read_fragment exist_fragment?
diff --git a/actionview/lib/action_view/log_subscriber.rb b/actionview/lib/action_view/log_subscriber.rb
index 6c8d9cb5bf..9047dbdd85 100644
--- a/actionview/lib/action_view/log_subscriber.rb
+++ b/actionview/lib/action_view/log_subscriber.rb
@@ -13,11 +13,11 @@ module ActionView
     end
 
     def render_template(event)
-      return unless logger.info?
-      message = "  Rendered #{from_rails_root(event.payload[:identifier])}"
-      message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
-      message << " (#{event.duration.round(1)}ms)"
-      info(message)
+      info do
+        message = "  Rendered #{from_rails_root(event.payload[:identifier])}"
+        message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
+        message << " (#{event.duration.round(1)}ms)"
+      end
     end
     alias :render_partial :render_template
     alias :render_collection :render_template
diff --git a/activesupport/lib/active_support/testing/tagged_logging.rb b/activesupport/lib/active_support/testing/tagged_logging.rb
index f4cee64091..843ce4a867 100644
--- a/activesupport/lib/active_support/testing/tagged_logging.rb
+++ b/activesupport/lib/active_support/testing/tagged_logging.rb
@@ -6,7 +6,7 @@ module ActiveSupport
       attr_writer :tagged_logger
 
       def before_setup
-        if tagged_logger
+        if tagged_logger && tagged_logger.info?
           heading = "#{self.class}: #{name}"
           divider = '-' * heading.size
           tagged_logger.info divider
diff --git a/railties/lib/rails/rack/logger.rb b/railties/lib/rails/rack/logger.rb
index 3b35798679..9962e6d943 100644
--- a/railties/lib/rails/rack/logger.rb
+++ b/railties/lib/rails/rack/logger.rb
@@ -34,7 +34,7 @@ module Rails
 
         instrumenter = ActiveSupport::Notifications.instrumenter
         instrumenter.start 'request.action_dispatch', request: request
-        logger.info started_request_message(request)
+        logger.info { started_request_message(request) }
         resp = @app.call(env)
         resp[2] = ::Rack::BodyProxy.new(resp[2]) { finish(request) }
         resp