Merge 01a4cc8e96 into 9c3ef01017

lib/grape/middleware/logger.rb

@@ -20,20 +20,22 @@ class Grape::Middleware::Logger < Grape::Middleware::Globals
     super
     @options[:filter] ||= self.class.filter
     @logger = options[:logger] || self.class.logger || self.class.default_logger
+    @io = StringIO.new
   end
 
   def before
-    start_time
     # sets env['grape.*']
+    @io.reopen
     super
-    logger.info ''
+    # Pass along the configured logger
-    logger.info %Q(Started %s "%s" at %s) % [
+    env['grape.middleware.logger'] = @logger
+    @io.puts %Q(\nStarted %s "%s" at %s) % [
       env[Grape::Env::GRAPE_REQUEST].request_method,
       env[Grape::Env::GRAPE_REQUEST].path,
-      start_time.to_s
+      Time.now.to_s
     ]
-    logger.info %Q(Processing by #{processed_by})
+    @io.puts %Q(Processing by #{processed_by})
-    logger.info %Q(  Parameters: #{parameters})
+    @io.puts %Q(  Parameters: #{parameters})
   end
 
   # @note Error and exception handling are required for the +after+ hooks
@@ -55,15 +57,15 @@ class Grape::Middleware::Logger < Grape::Middleware::Globals
       after_failure(error)
       throw(:error, error)
     else
-      status, _, _ = *@app_response
+      after
-      after(status)
     end
     @app_response
   end
 
-  def after(status)
+  # Save the string to be flushed at the end of the request by Rack::Head(Override)
-    logger.info "Completed #{status} in #{((Time.now - start_time) * 1000).round(2)}ms"
+  def after
-    logger.info ''
+    env['grape.middleware.logger.text'] = @io.string
+    @io.close
   end
 
   #
@@ -71,13 +73,13 @@ class Grape::Middleware::Logger < Grape::Middleware::Globals
   #
 
   def after_exception(e)
-    logger.info %Q(  #{e.class.name}: #{e.message})
+    @io.puts %Q(  #{e.class.name}: #{e.message})
-    after(500)
+    after
   end
 
   def after_failure(error)
-    logger.info %Q(  Error: #{error[:message]}) if error[:message]
+    @io.puts %Q(  Error: #{error[:message]}) if error[:message]
-    after(error[:status])
+    after
   end
 
   def parameters
@@ -91,10 +93,6 @@ class Grape::Middleware::Logger < Grape::Middleware::Globals
     end
   end
 
-  def start_time
-    @start_time ||= Time.now
-  end
-
   def processed_by
     endpoint = env[Grape::Env::API_ENDPOINT]
     result = []
@@ -109,3 +107,8 @@ class Grape::Middleware::Logger < Grape::Middleware::Globals
 end
 
 require_relative 'logger/railtie' if defined?(Rails)
+
+# This is required to properly log the status code of the response
+# The Grape::Endpoint#build_stack method builds the default stack, including the necessary middlewares for Grape to work
+# At the top of the default middleware stack is Rack::Head
+require_relative 'logger/rack_head_override' if defined?(Rack::Head)

lib/grape/middleware/logger/rack_head_override.rb

@@ -0,0 +1,17 @@
+require 'rack/head'
+
+class Grape::Middleware::Logger
+  module RackHeadOverride
+    def call(env)
+      start_time = Time.now
+      response = super
+      if env && env['grape.middleware.logger.text']
+        env['grape.middleware.logger.text'] << "Completed #{response[0]} in #{((Time.now - start_time) * 1000).round(2)}ms\n"
+        env['grape.middleware.logger'].info env.delete('grape.middleware.logger.text')
+      end
+      response
+    end
+  end
+end
+
+Rack::Head.prepend Grape::Middleware::Logger::RackHeadOverride