Tune up Rails::Rack::Logger. Only put space between requests in development logs.

Author: jeremy

railties/lib/rails/rack/logger.rb

@@ -3,36 +3,45 @@
 
 module Rails
   module Rack
-    # Log the request started and flush all loggers after it.
+    # Sets log tags, logs the request, calls the app, and flushes the logs.
     class Logger < ActiveSupport::LogSubscriber
-      def initialize(app, tags=nil)
-        @app, @tags = app, tags.presence
+      def initialize(app, taggers = nil)
+        @app, @taggers = app, taggers || []
       end
 
       def call(env)
-        if @tags && Rails.logger.respond_to?(:tagged)
-          Rails.logger.tagged(compute_tags(env)) { call_app(env) }
+        request = ActionDispatch::Request.new(env)
+
+        # Put some space between requests in development logs.
+        Rails.logger.info "\n\n" if Rails.env.development?
+
+        if Rails.logger.respond_to?(:tagged)
+          Rails.logger.tagged(compute_tags(request)) { call_app(request, env) }
         else
-          call_app(env)
+          call_app(request, env)
         end
       end
 
     protected
 
-      def call_app(env)
-        request = ActionDispatch::Request.new(env)
-        path = request.filtered_path
-        Rails.logger.info "\n\n"
-        Rails.logger.info "Started #{request.request_method} \"#{path}\" for #{request.ip} at #{Time.now.to_default_s}"
+      def call_app(request, env)
+        Rails.logger.info started_request_message(request)
         @app.call(env)
       ensure
         ActiveSupport::LogSubscriber.flush_all!
       end
 
-      def compute_tags(env)
-        request = ActionDispatch::Request.new(env)
+      # Started GET "/session/new" for 127.0.0.1 at 2012-09-26 14:51:42 -0700
+      def started_request_message(request)
+        'Started %s "%s" for %s at %s' % [
+          request.request_method,
+          request.filtered_path,
+          request.ip,
+          Time.now.to_default_s ]
+      end
 
-        @tags.collect do |tag|
+      def compute_tags(request)
+        @taggers.collect do |tag|
           case tag
           when Proc
             tag.call(request)

railties/test/application/rack/logger_test.rb

@@ -23,31 +23,31 @@ def teardown
       end
 
       def logs
-        @logs ||= @logger.logged(:info)
+        @logs ||= @logger.logged(:info).join("\n")
       end
 
       test "logger logs proper HTTP GET verb and path" do
         get "/blah"
         wait
-        assert_match(/^Started GET "\/blah"/, logs[0])
+        assert_match 'Started GET "/blah"', logs
       end
 
       test "logger logs proper HTTP HEAD verb and path" do
         head "/blah"
         wait
-        assert_match(/^Started HEAD "\/blah"/, logs[0])
+        assert_match 'Started HEAD "/blah"', logs
       end
 
       test "logger logs HTTP verb override" do
-        post "/", {:_method => 'put'}
+        post "/", _method: 'put'
         wait
-        assert_match(/^Started PUT "\/"/, logs[0])
+        assert_match 'Started PUT "/"', logs
       end
 
       test "logger logs HEAD requests" do
-        post "/", {:_method => 'head'}
+        post "/", _method: 'head'
         wait
-        assert_match(/^Started HEAD "\/"/, logs[0])
+        assert_match 'Started HEAD "/"', logs
       end
     end
   end