Merge pull request #2250 from alexeevit/feature/unified-error-logging…

…-2235

Add unified detailed error logging

lib/puma/error_logger.rb

@@ -0,0 +1,96 @@
+# frozen_string_literal: true
+
+require 'puma/const'
+
+module Puma
+  # The implementation of a detailed error logging.
+  #
+  class ErrorLogger
+    include Const
+
+    attr_reader :ioerr
+
+    REQUEST_FORMAT = %{"%s %s%s" - (%s)}
+
+    def initialize(ioerr)
+      @ioerr = ioerr
+      @ioerr.sync = true
+
+      @debug = ENV.key? 'PUMA_DEBUG'
+    end
+
+    def self.stdio
+      new $stderr
+    end
+
+    # Print occured error details.
+    # +options+ hash with additional options:
+    # - +error+ is an exception object
+    # - +req+ the http request
+    # - +text+ (default nil) custom string to print in title
+    #   and before all remaining info.
+    #
+    def info(options={})
+      ioerr.puts title(options)
+    end
+
+    # Print occured error details only if
+    # environment variable PUMA_DEBUG is defined.
+    # +options+ hash with additional options:
+    # - +error+ is an exception object
+    # - +req+ the http request
+    # - +text+ (default nil) custom string to print in title
+    #   and before all remaining info.
+    #
+    def debug(options={})
+      return unless @debug
+
+      error = options[:error]
+      req = options[:req]
+
+      string_block = []
+      string_block << title(options)
+      string_block << request_dump(req) if req
+      string_block << error_backtrace(options) if error
+
+      ioerr.puts string_block.join("\n")
+    end
+
+    def title(options={})
+      text = options[:text]
+      req = options[:req]
+      error = options[:error]
+
+      string_block = ["#{Time.now}"]
+      string_block << " #{text}" if text
+      string_block << " (#{request_title(req)})" if request_parsed?(req)
+      string_block << ": #{error.inspect}" if error
+      string_block.join('')
+    end
+
+    def request_dump(req)
+      "Headers: #{request_headers(req)}\n" \
+      "Body: #{req.body}"
+    end
+
+    def request_title(req)
+      env = req.env
+
+      REQUEST_FORMAT % [
+        env[REQUEST_METHOD],
+        env[REQUEST_PATH] || env[PATH_INFO],
+        env[QUERY_STRING] || "",
+        env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR] || "-"
+      ]
+    end
+
+    def request_headers(req)
+      headers = req.env.select { |key, _| key.start_with?('HTTP_') }
+      headers.map { |key, value| [key[5..-1], value] }.to_h.inspect
+    end
+
+    def request_parsed?(req)
+      req && req.env[REQUEST_METHOD]
+    end
+  end
+end

lib/puma/events.rb

@@ -1,7 +1,7 @@
 # frozen_string_literal: true
 
-require 'puma/const'
 require "puma/null_io"
+require 'puma/error_logger'
 require 'stringio'
 
 module Puma
@@ -23,8 +23,6 @@ def call(str)
       end
     end
 
-    include Const
-
     # Create an Events object that prints to +stdout+ and +stderr+.
     #
     def initialize(stdout, stderr)
@@ -36,6 +34,7 @@ def initialize(stdout, stderr)
       @stderr.sync = true
 
       @debug = ENV.key? 'PUMA_DEBUG'
+      @error_logger = ErrorLogger.new(@stderr)
 
       @hooks = Hash.new { |h,k| h[k] = [] }
     end
@@ -80,50 +79,53 @@ def debug(str)
     # Write +str+ to +@stderr+
     #
     def error(str)
-      @stderr.puts format("ERROR: #{str}")
+      @error_logger.info(text: format("ERROR: #{str}"))
       exit 1
     end
 
     def format(str)
       formatter.call(str)
     end
 
+    # An HTTP connection error has occurred.
+    # +error+ a connection exception, +req+ the request,
+    # and +text+ additional info
+    #
+    def connection_error(error, req, text="HTTP connection error")
+      @error_logger.info(error: error, req: req, text: text)
+    end
+
     # An HTTP parse error has occurred.
-    # +server+ is the Server object, +env+ the request, and +error+ a
-    # parsing exception.
+    # +error+ a parsing exception,
+    # and +req+ the request.
     #
-    def parse_error(server, env, error)
-      @stderr.puts "#{Time.now}: HTTP parse error, malformed request " \
-        "(#{env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR]}#{env[REQUEST_PATH]}): " \
-        "#{error.inspect}"
+    def parse_error(error, req)
+      @error_logger.info(error: error, req: req, text: 'HTTP parse error, malformed request')
     end
 
     # An SSL error has occurred.
-    # +server+ is the Server object, +peeraddr+ peer address, +peercert+
-    # any peer certificate (if present), and +error+ an exception object.
+    # +error+ an exception object, +peeraddr+ peer address,
+    # and +peercert+ any peer certificate (if present).
     #
-    def ssl_error(server, peeraddr, peercert, error)
+    def ssl_error(error, peeraddr, peercert)
       subject = peercert ? peercert.subject : nil
-      @stderr.puts "#{Time.now}: SSL error, peer: #{peeraddr}, peer cert: #{subject}, #{error.inspect}"
+      @error_logger.info(error: error, text: "SSL error, peer: #{peeraddr}, peer cert: #{subject}")
     end
 
     # An unknown error has occurred.
-    # +server+ is the Server object, +error+ an exception object,
-    # +kind+ some additional info, and +env+ the request.
+    # +error+ an exception object, +req+ the request,
+    # and +text+ additional info
     #
-    def unknown_error(server, error, kind="Unknown", env=nil)
-      if error.respond_to? :render
-        error.render "#{Time.now}: #{kind} error", @stderr
-      else
-        if env
-          string_block = [ "#{Time.now}: #{kind} error handling request { #{env['REQUEST_METHOD']} #{env['PATH_INFO']} }" ]
-          string_block << error.inspect
-        else
-          string_block = [ "#{Time.now}: #{kind} error: #{error.inspect}" ]
-        end
-        string_block << error.backtrace
-        @stderr.puts string_block.join("\n")
-      end
+    def unknown_error(error, req=nil, text="Unknown error")
+      @error_logger.info(error: error, req: req, text: text)
+    end
+
+    # Log occurred error debug dump.
+    # +error+ an exception object, +req+ the request,
+    # and +text+ additional info
+    #
+    def debug_error(error, req=nil, text="")
+      @error_logger.debug(error: error, req: req, text: text)
     end
 
     def on_booted(&block)

lib/puma/reactor.rb

@@ -252,7 +252,7 @@ def run_internal
                 c.close
                 clear_monitor mon
 
-                @events.ssl_error @server, addr, cert, e
+                @events.ssl_error e, addr, cert
 
               # The client doesn't know HTTP well
               rescue HttpParserError => e
@@ -263,7 +263,7 @@ def run_internal
 
                 clear_monitor mon
 
-                @events.parse_error @server, c.env, e
+                @events.parse_error e, c
               rescue StandardError => e
                 @server.lowlevel_error(e, c.env)
 

lib/puma/server.rb

@@ -207,14 +207,16 @@ def run(background=true)
 
           client.close
 
-          @events.ssl_error self, addr, cert, e
+          @events.ssl_error e, addr, cert
         rescue HttpParserError => e
           client.write_error(400)
           client.close
 
-          @events.parse_error self, client.env, e
-        rescue ConnectionError, EOFError
+          @events.parse_error e, client
+        rescue ConnectionError, EOFError => e
           client.close
+
+          @events.connection_error e, client
         else
           if process_now
             process_client client, buffer
@@ -300,7 +302,7 @@ def handle_servers
               end
             end
           rescue Object => e
-            @events.unknown_error self, e, "Listen loop"
+            @events.unknown_error e, nil, "Listen loop"
           end
         end
 
@@ -313,8 +315,7 @@ def handle_servers
         end
         graceful_shutdown if @status == :stop || @status == :restart
       rescue Exception => e
-        STDERR.puts "Exception handling servers: #{e.message} (#{e.class})"
-        STDERR.puts e.backtrace
+        @events.unknown_error e, nil, "Exception handling servers"
       ensure
         @check.close unless @check.closed? # Ruby 2.2 issue
         @notify.close
@@ -406,24 +407,23 @@ def process_client(client, buffer)
 
         close_socket = true
 
-        @events.ssl_error self, addr, cert, e
+        @events.ssl_error e, addr, cert
 
       # The client doesn't know HTTP well
       rescue HttpParserError => e
         lowlevel_error(e, client.env)
 
         client.write_error(400)
 
-        @events.parse_error self, client.env, e
+        @events.parse_error e, client
 
       # Server error
       rescue StandardError => e
         lowlevel_error(e, client.env)
 
         client.write_error(500)
 
-        @events.unknown_error self, e, "Read"
-
+        @events.unknown_error e, nil, "Read"
       ensure
         buffer.reset
 
@@ -433,7 +433,7 @@ def process_client(client, buffer)
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
           # Already closed
         rescue StandardError => e
-          @events.unknown_error self, e, "Client"
+          @events.unknown_error e, nil, "Client"
         end
       end
     end
@@ -558,7 +558,8 @@ def handle_request(req, lines)
             end
 
             fast_write client, "\r\n".freeze
-          rescue ConnectionError
+          rescue ConnectionError => e
+            @events.debug_error e
             # noop, if we lost the socket we just won't send the early hints
           end
         }
@@ -616,12 +617,12 @@ def handle_request(req, lines)
             return :async
           end
         rescue ThreadPool::ForceShutdown => e
-          @events.unknown_error self, e, "Rack app", env
+          @events.unknown_error e, req, "Rack app"
           @events.log "Detected force shutdown of a thread"
 
           status, headers, res_body = lowlevel_error(e, env, 503)
         rescue Exception => e
-          @events.unknown_error self, e, "Rack app", env
+          @events.unknown_error e, req, "Rack app"
 
           status, headers, res_body = lowlevel_error(e, env, 500)
         end

test/test_error_logger.rb

@@ -0,0 +1,70 @@
+require 'puma/error_logger'
+require_relative "helper"
+
+class TestErrorLogger < Minitest::Test
+  Req = Struct.new(:env, :body)
+
+  def test_stdio
+    error_logger = Puma::ErrorLogger.stdio
+
+    assert_equal STDERR, error_logger.ioerr
+  end
+
+  def test_info_with_only_error
+    _, err = capture_io do
+      Puma::ErrorLogger.stdio.info(error: StandardError.new('ready'))
+    end
+
+    assert_match %r!#<StandardError: ready>!, err
+  end
+
+  def test_info_with_request
+    env = {
+      'REQUEST_METHOD' => 'GET',
+      'PATH_INFO' => '/debug',
+      'HTTP_X_FORWARDED_FOR' => '8.8.8.8'
+    }
+    req = Req.new(env, '{"hello":"world"}')
+
+    _, err = capture_io do
+      Puma::ErrorLogger.stdio.info(error: StandardError.new, req: req)
+    end
+
+    assert_match %r!\("GET /debug" - \(8\.8\.8\.8\)\)!, err
+  end
+
+  def test_info_with_text
+    _, err = capture_io do
+      Puma::ErrorLogger.stdio.info(text: 'The client disconnected while we were reading data')
+    end
+
+    assert_match %r!The client disconnected while we were reading data!, err
+  end
+
+  def test_debug_without_debug_mode
+    _, err = capture_io do
+      Puma::ErrorLogger.stdio.debug(text: 'blank')
+    end
+
+    assert_empty err
+  end
+
+  def test_debug_with_debug_mode
+    with_debug_mode do
+      _, err = capture_io do
+        Puma::ErrorLogger.stdio.debug(text: 'non-blank')
+      end
+
+      assert_match %r!non-blank!, err
+    end
+  end
+
+  private
+
+  def with_debug_mode
+    original_debug, ENV["PUMA_DEBUG"] = ENV["PUMA_DEBUG"], "1"
+    yield
+  ensure
+    ENV["PUMA_DEBUG"] = original_debug
+  end
+end