From b625767440c4ad15c973a7ad23466322919cd12e Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Mon, 4 May 2020 21:30:18 +0300
Subject: [PATCH 01/17] implement debug_logger

---
 lib/puma/debug_logger.rb  | 56 ++++++++++++++++++++++++++
 lib/puma/events.rb        | 13 +++---
 lib/puma/server.rb        | 55 ++++++++++++++++++--------
 test/test_debug_logger.rb | 83 +++++++++++++++++++++++++++++++++++++++
 4 files changed, 182 insertions(+), 25 deletions(-)
 create mode 100644 lib/puma/debug_logger.rb
 create mode 100644 test/test_debug_logger.rb

diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb
new file mode 100644
index 0000000000..52e69f7db0
--- /dev/null
+++ b/lib/puma/debug_logger.rb
@@ -0,0 +1,56 @@
+# frozen_string_literal: true
+
+module Puma
+  # The implementation of a logging in debug mode.
+  #
+  class DebugLogger
+    attr_reader :ioerr
+
+    def initialize(ioerr)
+      @ioerr = ioerr
+      @ioerr.sync = true
+
+      @debug = ENV.key? 'PUMA_DEBUG'
+    end
+
+    def self.stdio
+      new $stderr
+    end
+
+    # Any error has occured during debug mode.
+    # +error+ is an exception object, +env+ the request,
+    # +options+ hash with additional options:
+    # - +force+ (default nil) to log info even if debug mode is turned off
+    # - +print_title+ (default true) to log time and error object inspection
+    #   on the first line.
+    # - +custom_message+ (default nil) custom string to print after title
+    #   and before all remaining info.
+    #
+    def error_dump(error, env=nil, options={})
+      return unless @debug || options[:force]
+
+      options[:print_title] = true unless options.keys.include?(:print_title)
+
+      #
+      # TODO: add all info we have about request
+      #
+      string_block = []
+
+      if options[:print_title]
+        string_block << "#{Time.now}: #{error.inspect}"
+      end
+
+      if options[:custom_message]
+        string_block << "#{options[:custom_message]}"
+      end
+
+      if env
+        string_block << "Handling request { #{env['REQUEST_METHOD']} #{env['PATH_INFO']} }"
+      end
+
+      string_block << error.backtrace
+
+      ioerr.puts string_block.join("\n")
+    end
+  end
+end
diff --git a/lib/puma/events.rb b/lib/puma/events.rb
index b255f2613f..32786a792b 100644
--- a/lib/puma/events.rb
+++ b/lib/puma/events.rb
@@ -2,6 +2,7 @@
 
 require 'puma/const'
 require "puma/null_io"
+require 'puma/debug_logger'
 require 'stringio'
 
 module Puma
@@ -36,6 +37,7 @@ def initialize(stdout, stderr)
       @stderr.sync = true
 
       @debug = ENV.key? 'PUMA_DEBUG'
+      @debug_logger = DebugLogger.new(@stderr)
 
       @hooks = Hash.new { |h,k| h[k] = [] }
     end
@@ -97,6 +99,7 @@ def parse_error(server, env, error)
         "(#{env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR]}#{env[REQUEST_PATH]}): " \
         "#{error.inspect}" \
         "\n---\n"
+      @debug_logger.error_dump(error, env, print_title: false)
     end
 
     # An SSL error has occurred.
@@ -106,6 +109,7 @@ def parse_error(server, env, error)
     def ssl_error(server, peeraddr, peercert, error)
       subject = peercert ? peercert.subject : nil
       @stderr.puts "#{Time.now}: SSL error, peer: #{peeraddr}, peer cert: #{subject}, #{error.inspect}"
+      @debug_logger.error_dump(error, nil, print_title: false)
     end
 
     # An unknown error has occurred.
@@ -116,14 +120,7 @@ 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")
+        @debug_logger.error_dump(error, env, force: true, custom_message: kind)
       end
     end
 
diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index a467e23715..d59dd8a8ee 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -12,6 +12,7 @@
 require 'puma/accept_nonblock'
 require 'puma/util'
 require 'puma/io_buffer'
+require 'puma/debug_logger'
 
 require 'puma/puma_http11'
 
@@ -58,6 +59,7 @@ class Server
     def initialize(app, events=Events.stdio, options={})
       @app = app
       @events = events
+      @debug_logger = DebugLogger.stdio
 
       @check, @notify = Puma::Util.pipe
 
@@ -111,16 +113,18 @@ def inherit_binder(bind)
       def cork_socket(socket)
         begin
           socket.setsockopt(6, 3, 1) if socket.kind_of? TCPSocket
-        rescue IOError, SystemCallError
+        rescue IOError, SystemCallError => e
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
+          @debug_logger.error_dump(e)
         end
       end
 
       def uncork_socket(socket)
         begin
           socket.setsockopt(6, 3, 0) if socket.kind_of? TCPSocket
-        rescue IOError, SystemCallError
+        rescue IOError, SystemCallError => e
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
+          @debug_logger.error_dump(e)
         end
       end
 
@@ -214,7 +218,8 @@ def run(background=true)
           client.close
 
           @events.parse_error self, client.env, e
-        rescue ConnectionError, EOFError
+        rescue ConnectionError, EOFError => e
+          @debug_logger.error_dump(e, client.env)
           client.close
         else
           if process_now
@@ -293,14 +298,19 @@ def handle_servers
 
                     pool << client
                   end
-                rescue SystemCallError
+                rescue SystemCallError => e
+                  # TODO: check if we able to use client here
+                  @debug_logger.error_dump(e, client&.env)
                   # nothing
                 rescue Errno::ECONNABORTED
-                  # client closed the socket even before accept
+                  # TODO: check if we able to use client here
+                  @debug_logger.error_dump(e, client&.env, custom_message: 'Client closed the socket even before accept')
                   begin
                     io.close
-                  rescue
+                  rescue => e
                     Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
+                    # TODO: check if we able to use client here
+                    @debug_logger.error_dump(e, client&.env)
                   end
                 end
               end
@@ -319,8 +329,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
+        @debug_logger.error_dump(e, force: true, custom_message: 'Exception handling servers')
       ensure
         @check.close unless @check.closed? # Ruby 2.2 issue
         @notify.close
@@ -397,7 +406,8 @@ def process_client(client, buffer)
         end
 
       # The client disconnected while we were reading data
-      rescue ConnectionError
+      rescue ConnectionError => e
+        @debug_logger.error_dump(e, client.env, custom_message: 'The client disconnected while we were reading data')
         # Swallow them. The ensure tries to close +client+ down
 
       # SSL handshake error
@@ -433,8 +443,9 @@ def process_client(client, buffer)
 
         begin
           client.close if close_socket
-        rescue IOError, SystemCallError
+        rescue IOError, SystemCallError => e
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
+          @debug_logger.error_dump(e, client.env)
           # Already closed
         rescue StandardError => e
           @events.unknown_error self, e, "Client"
@@ -485,10 +496,11 @@ def normalize_env(env, client)
       unless env.key?(REMOTE_ADDR)
         begin
           addr = client.peerip
-        rescue Errno::ENOTCONN
+        rescue Errno::ENOTCONN => e
           # Client disconnects can result in an inability to get the
           # peeraddr from the socket; default to localhost.
           addr = LOCALHOST_IP
+          @debug_logger.error_dump(e, custom_message: 'Client disconnects can result in an inability to get the peeraddr from the socket')
         end
 
         # Set unix socket addrs to localhost
@@ -562,8 +574,9 @@ def handle_request(req, lines)
             end
 
             fast_write client, "\r\n".freeze
-          rescue ConnectionError
+          rescue ConnectionError => e
             # noop, if we lost the socket we just won't send the early hints
+            @debug_logger.error_dump(e, env)
           end
         }
       end
@@ -591,10 +604,12 @@ def handle_request(req, lines)
         rescue ThreadPool::ForceShutdown => e
           @events.unknown_error self, e, "Rack app", env
           @events.log "Detected force shutdown of a thread"
+          @debug_logger.error_dump(e, env)
 
           status, headers, res_body = lowlevel_error(e, env, 503)
         rescue Exception => e
           @events.unknown_error self, e, "Rack app", env
+          @debug_logger.error_dump(e, env)
 
           status, headers, res_body = lowlevel_error(e, env, 500)
         end
@@ -731,7 +746,8 @@ def handle_request(req, lines)
             fast_write client, CLOSE_CHUNKED
             client.flush
           end
-        rescue SystemCallError, IOError
+        rescue SystemCallError, IOError => e
+          @debug_logger.error_dump(e, env)
           raise ConnectionError, "Connection error detected during write"
         end
 
@@ -859,7 +875,8 @@ def graceful_shutdown
                 client = Client.new io, @binder.env(sock)
                 @thread_pool << client
               end
-            rescue SystemCallError
+            rescue SystemCallError => e
+              @debug_logger.error_dump(e)
             end
           end
         end
@@ -883,10 +900,12 @@ def graceful_shutdown
     def notify_safely(message)
       begin
         @notify << message
-      rescue IOError
+      rescue IOError => e
          # The server, in another thread, is shutting down
         Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
+        @debug_logger.error_dump(e)
       rescue RuntimeError => e
+        @debug_logger.error_dump(e)
         # Temporary workaround for https://bugs.ruby-lang.org/issues/13239
         if e.message.include?('IOError')
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
@@ -919,13 +938,15 @@ def fast_write(io, str)
       while true
         begin
           n = io.syswrite str
-        rescue Errno::EAGAIN, Errno::EWOULDBLOCK
+        rescue Errno::EAGAIN, Errno::EWOULDBLOCK => e
+          @debug_logger.error_dump(e)
           if !IO.select(nil, [io], nil, WRITE_TIMEOUT)
             raise ConnectionError, "Socket timeout writing data"
           end
 
           retry
-        rescue  Errno::EPIPE, SystemCallError, IOError
+        rescue  Errno::EPIPE, SystemCallError, IOError => e
+          @debug_logger.error_dump(e)
           raise ConnectionError, "Socket timeout writing data"
         end
 
diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb
new file mode 100644
index 0000000000..62d0566131
--- /dev/null
+++ b/test/test_debug_logger.rb
@@ -0,0 +1,83 @@
+require_relative "helper"
+
+class TestDebugLogger < Minitest::Test
+  def setup
+    @debug_logger = Puma::DebugLogger.stdio
+  end
+
+  def test_stdio
+    debug_logger = Puma::DebugLogger.stdio
+
+    assert_equal STDERR, debug_logger.ioerr
+  end
+
+  def test_error_dump_if_debug_false
+    _, err = capture_io do
+      @debug_logger.error_dump(StandardError.new('ready'))
+    end
+
+    assert_empty err
+  end
+
+  def test_error_dump_force
+    _, err = capture_io do
+      Puma::DebugLogger.stdio.error_dump(StandardError.new('ready'), nil, force: true)
+    end
+
+    assert_match %r!ready!, err
+  end
+
+  def test_error_dump_with_only_error
+    with_debug_mode do
+      _, err = capture_io do
+        Puma::DebugLogger.stdio.error_dump(StandardError.new('ready'), nil)
+      end
+
+      assert_match %r!#<StandardError: ready>!, err
+    end
+  end
+
+  def test_error_dump_with_env
+    with_debug_mode do
+      env = {
+        'REQUEST_METHOD' => 'GET',
+        'PATH_INFO' => '/debug'
+      }
+
+      _, err = capture_io do
+        Puma::DebugLogger.stdio.error_dump(StandardError.new, env)
+      end
+
+      assert_match %r!Handling request { GET /debug }!, err
+    end
+  end
+
+  def test_error_dump_without_title
+    with_debug_mode do
+      _, err = capture_io do
+        Puma::DebugLogger.stdio.error_dump(StandardError.new('ready'), nil, print_title: false)
+      end
+
+      refute_match %r!#<StandardError: ready>!, err
+    end
+  end
+
+  def test_error_dump_with_custom_message
+    with_debug_mode do
+      _, err = capture_io do
+        Puma::DebugLogger.stdio.error_dump(StandardError.new, nil, custom_message: 'The client disconnected while we were reading data')
+      end
+
+      assert_match %r!The client disconnected while we were reading data!, 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

From ec6bd0b1637dbb3d32a1fa9f1a9fd5eff24634db Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Mon, 4 May 2020 23:13:00 +0300
Subject: [PATCH 02/17] fix codestyle

---
 lib/puma/debug_logger.rb | 2 +-
 lib/puma/server.rb       | 6 +++---
 2 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb
index 52e69f7db0..1284ed6649 100644
--- a/lib/puma/debug_logger.rb
+++ b/lib/puma/debug_logger.rb
@@ -29,7 +29,7 @@ def self.stdio
     def error_dump(error, env=nil, options={})
       return unless @debug || options[:force]
 
-      options[:print_title] = true unless options.keys.include?(:print_title)
+      options[:print_title] = true unless options.key?(:print_title)
 
       #
       # TODO: add all info we have about request
diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index d59dd8a8ee..d46c841390 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -300,17 +300,17 @@ def handle_servers
                   end
                 rescue SystemCallError => e
                   # TODO: check if we able to use client here
-                  @debug_logger.error_dump(e, client&.env)
+                  @debug_logger.error_dump(e)
                   # nothing
                 rescue Errno::ECONNABORTED
                   # TODO: check if we able to use client here
-                  @debug_logger.error_dump(e, client&.env, custom_message: 'Client closed the socket even before accept')
+                  @debug_logger.error_dump(e, nil, custom_message: 'Client closed the socket even before accept')
                   begin
                     io.close
                   rescue => e
                     Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
                     # TODO: check if we able to use client here
-                    @debug_logger.error_dump(e, client&.env)
+                    @debug_logger.error_dump(e, nil)
                   end
                 end
               end

From 25bceedda4cd7e82592abd0c089cde7a810ac34c Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sat, 9 May 2020 17:30:48 +0300
Subject: [PATCH 03/17] use only debug_logger instead of stderr in events

---
 lib/puma/debug_logger.rb  | 19 +++++++------------
 lib/puma/events.rb        | 18 +++---------------
 test/test_debug_logger.rb | 23 +++++++++++------------
 test/test_events.rb       |  3 ++-
 4 files changed, 23 insertions(+), 40 deletions(-)

diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb
index 1284ed6649..29a4ae6d1e 100644
--- a/lib/puma/debug_logger.rb
+++ b/lib/puma/debug_logger.rb
@@ -1,9 +1,13 @@
 # frozen_string_literal: true
 
+require 'puma/const'
+
 module Puma
   # The implementation of a logging in debug mode.
   #
   class DebugLogger
+    include Const
+
     attr_reader :ioerr
 
     def initialize(ioerr)
@@ -21,31 +25,22 @@ def self.stdio
     # +error+ is an exception object, +env+ the request,
     # +options+ hash with additional options:
     # - +force+ (default nil) to log info even if debug mode is turned off
-    # - +print_title+ (default true) to log time and error object inspection
-    #   on the first line.
     # - +custom_message+ (default nil) custom string to print after title
     #   and before all remaining info.
     #
     def error_dump(error, env=nil, options={})
       return unless @debug || options[:force]
 
-      options[:print_title] = true unless options.key?(:print_title)
-
       #
       # TODO: add all info we have about request
       #
       string_block = []
 
-      if options[:print_title]
-        string_block << "#{Time.now}: #{error.inspect}"
-      end
-
-      if options[:custom_message]
-        string_block << "#{options[:custom_message]}"
-      end
+      custom_message = " #{options[:custom_message]}:" if options[:custom_message]
+      string_block << "#{Time.now}#{custom_message} #{error.inspect}"
 
       if env
-        string_block << "Handling request { #{env['REQUEST_METHOD']} #{env['PATH_INFO']} }"
+        string_block << "Handling request { #{env[REQUEST_METHOD]} #{env[REQUEST_PATH] || env[PATH_INFO]} } (#{env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR]})"
       end
 
       string_block << error.backtrace
diff --git a/lib/puma/events.rb b/lib/puma/events.rb
index 32786a792b..0bdc5f8174 100644
--- a/lib/puma/events.rb
+++ b/lib/puma/events.rb
@@ -1,6 +1,5 @@
 # frozen_string_literal: true
 
-require 'puma/const'
 require "puma/null_io"
 require 'puma/debug_logger'
 require 'stringio'
@@ -24,8 +23,6 @@ def call(str)
       end
     end
 
-    include Const
-
     # Create an Events object that prints to +stdout+ and +stderr+.
     #
     def initialize(stdout, stderr)
@@ -95,11 +92,7 @@ def format(str)
     # parsing exception.
     #
     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}" \
-        "\n---\n"
-      @debug_logger.error_dump(error, env, print_title: false)
+      @debug_logger.error_dump(error, env, custom_message: 'HTTP parse error, malformed request', force: true)
     end
 
     # An SSL error has occurred.
@@ -108,8 +101,7 @@ def parse_error(server, env, error)
     #
     def ssl_error(server, peeraddr, peercert, error)
       subject = peercert ? peercert.subject : nil
-      @stderr.puts "#{Time.now}: SSL error, peer: #{peeraddr}, peer cert: #{subject}, #{error.inspect}"
-      @debug_logger.error_dump(error, nil, print_title: false)
+      @debug_logger.error_dump(error, nil, custom_message: "SSL error, peer: #{peeraddr}, peer cert: #{subject}", force: true)
     end
 
     # An unknown error has occurred.
@@ -117,11 +109,7 @@ def ssl_error(server, peeraddr, peercert, error)
     # +kind+ some additional info, and +env+ the request.
     #
     def unknown_error(server, error, kind="Unknown", env=nil)
-      if error.respond_to? :render
-        error.render "#{Time.now}: #{kind} error", @stderr
-      else
-        @debug_logger.error_dump(error, env, force: true, custom_message: kind)
-      end
+      @debug_logger.error_dump(error, env, custom_message: kind, force: true)
     end
 
     def on_booted(&block)
diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb
index 62d0566131..b34a62160d 100644
--- a/test/test_debug_logger.rb
+++ b/test/test_debug_logger.rb
@@ -5,6 +5,14 @@ def setup
     @debug_logger = Puma::DebugLogger.stdio
   end
 
+  def test_other_io
+    with_debug_mode do
+      debug_logger = Puma::DebugLogger.new(StringIO.new)
+      debug_logger.error_dump(StandardError.new('ready'))
+      assert_match %r!#<StandardError: ready>!, debug_logger.ioerr.string
+    end
+  end
+
   def test_stdio
     debug_logger = Puma::DebugLogger.stdio
 
@@ -41,24 +49,15 @@ def test_error_dump_with_env
     with_debug_mode do
       env = {
         'REQUEST_METHOD' => 'GET',
-        'PATH_INFO' => '/debug'
+        'PATH_INFO' => '/debug',
+        'HTTP_X_FORWARDED_FOR' => '8.8.8.8'
       }
 
       _, err = capture_io do
         Puma::DebugLogger.stdio.error_dump(StandardError.new, env)
       end
 
-      assert_match %r!Handling request { GET /debug }!, err
-    end
-  end
-
-  def test_error_dump_without_title
-    with_debug_mode do
-      _, err = capture_io do
-        Puma::DebugLogger.stdio.error_dump(StandardError.new('ready'), nil, print_title: false)
-      end
-
-      refute_match %r!#<StandardError: ready>!, err
+      assert_match %r!Handling request { GET /debug } \(8\.8\.8\.8\)!, err
     end
   end
 
diff --git a/test/test_events.rb b/test/test_events.rb
index a749362330..a77f871584 100644
--- a/test/test_events.rb
+++ b/test/test_events.rb
@@ -175,7 +175,8 @@ def test_parse_error
     sock << "GET #{path}?a=#{params} HTTP/1.1\r\nConnection: close\r\n\r\n"
     sock.read
     sleep 0.1 # important so that the previous data is sent as a packet
-    assert_match %r!HTTP parse error, malformed request \(#{path}\)!, events.stderr.string
+    assert_match %r!HTTP parse error, malformed request!, events.stderr.string
+    assert_match %r!Handling request { GET #{path} }!, events.stderr.string
     server.stop(true)
   end
 end

From 4f632b9a52fef580b57a016f782e1a3638f7f957 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sat, 9 May 2020 17:50:29 +0300
Subject: [PATCH 04/17] remove logging where it is unnecessary

---
 lib/puma/server.rb | 6 ++----
 1 file changed, 2 insertions(+), 4 deletions(-)

diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index d46c841390..e9da2bcbe2 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -113,18 +113,16 @@ def inherit_binder(bind)
       def cork_socket(socket)
         begin
           socket.setsockopt(6, 3, 1) if socket.kind_of? TCPSocket
-        rescue IOError, SystemCallError => e
+        rescue IOError, SystemCallError
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
-          @debug_logger.error_dump(e)
         end
       end
 
       def uncork_socket(socket)
         begin
           socket.setsockopt(6, 3, 0) if socket.kind_of? TCPSocket
-        rescue IOError, SystemCallError => e
+        rescue IOError, SystemCallError
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
-          @debug_logger.error_dump(e)
         end
       end
 

From 607e24fe509c110043daf0c998843775e8b90f29 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sat, 9 May 2020 18:04:04 +0300
Subject: [PATCH 05/17] update error_dump interface

---
 lib/puma/debug_logger.rb  | 20 ++++++++++++--------
 lib/puma/events.rb        |  8 ++++----
 lib/puma/server.rb        | 34 +++++++++++++++++-----------------
 test/test_debug_logger.rb | 20 ++++++--------------
 4 files changed, 39 insertions(+), 43 deletions(-)

diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb
index 29a4ae6d1e..1a74f706c9 100644
--- a/lib/puma/debug_logger.rb
+++ b/lib/puma/debug_logger.rb
@@ -22,28 +22,32 @@ def self.stdio
     end
 
     # Any error has occured during debug mode.
-    # +error+ is an exception object, +env+ the request,
     # +options+ hash with additional options:
     # - +force+ (default nil) to log info even if debug mode is turned off
-    # - +custom_message+ (default nil) custom string to print after title
+    # - +error+ is an exception object
+    # - +env+ the request
+    # - +text+ (default nil) custom string to print in title
     #   and before all remaining info.
     #
-    def error_dump(error, env=nil, options={})
+    def error_dump(options={})
       return unless @debug || options[:force]
+      error = options[:error]
+      env = options[:env]
+      text = options[:text]
 
       #
       # TODO: add all info we have about request
       #
-      string_block = []
-
-      custom_message = " #{options[:custom_message]}:" if options[:custom_message]
-      string_block << "#{Time.now}#{custom_message} #{error.inspect}"
 
+      string_block = []
+      formatted_text = " #{text}:" if text
+      formatted_error = " #{error.inspect}" if error
+      string_block << "#{Time.now}#{text}#{error.inspect}"
       if env
         string_block << "Handling request { #{env[REQUEST_METHOD]} #{env[REQUEST_PATH] || env[PATH_INFO]} } (#{env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR]})"
       end
 
-      string_block << error.backtrace
+      string_block << error.backtrace if error
 
       ioerr.puts string_block.join("\n")
     end
diff --git a/lib/puma/events.rb b/lib/puma/events.rb
index 0bdc5f8174..040cb000eb 100644
--- a/lib/puma/events.rb
+++ b/lib/puma/events.rb
@@ -79,7 +79,7 @@ def debug(str)
     # Write +str+ to +@stderr+
     #
     def error(str)
-      @stderr.puts format("ERROR: #{str}")
+      @debug_logger.error_dump(text: format("ERROR: #{str}"))
       exit 1
     end
 
@@ -92,7 +92,7 @@ def format(str)
     # parsing exception.
     #
     def parse_error(server, env, error)
-      @debug_logger.error_dump(error, env, custom_message: 'HTTP parse error, malformed request', force: true)
+      @debug_logger.error_dump(error: error, env: env, text: 'HTTP parse error, malformed request', force: true)
     end
 
     # An SSL error has occurred.
@@ -101,7 +101,7 @@ def parse_error(server, env, error)
     #
     def ssl_error(server, peeraddr, peercert, error)
       subject = peercert ? peercert.subject : nil
-      @debug_logger.error_dump(error, nil, custom_message: "SSL error, peer: #{peeraddr}, peer cert: #{subject}", force: true)
+      @debug_logger.error_dump(error: error, text: "SSL error, peer: #{peeraddr}, peer cert: #{subject}", force: true)
     end
 
     # An unknown error has occurred.
@@ -109,7 +109,7 @@ def ssl_error(server, peeraddr, peercert, error)
     # +kind+ some additional info, and +env+ the request.
     #
     def unknown_error(server, error, kind="Unknown", env=nil)
-      @debug_logger.error_dump(error, env, custom_message: kind, force: true)
+      @debug_logger.error_dump(error: error, env: env, text: kind, force: true)
     end
 
     def on_booted(&block)
diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index e9da2bcbe2..ff271ff42a 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -217,7 +217,7 @@ def run(background=true)
 
           @events.parse_error self, client.env, e
         rescue ConnectionError, EOFError => e
-          @debug_logger.error_dump(e, client.env)
+          @debug_logger.error_dump(error: e, env: client.env)
           client.close
         else
           if process_now
@@ -298,17 +298,17 @@ def handle_servers
                   end
                 rescue SystemCallError => e
                   # TODO: check if we able to use client here
-                  @debug_logger.error_dump(e)
+                  @debug_logger.error_dump(error: e)
                   # nothing
                 rescue Errno::ECONNABORTED
                   # TODO: check if we able to use client here
-                  @debug_logger.error_dump(e, nil, custom_message: 'Client closed the socket even before accept')
+                  @debug_logger.error_dump(error: e, text: 'Client closed the socket even before accept')
                   begin
                     io.close
                   rescue => e
                     Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
                     # TODO: check if we able to use client here
-                    @debug_logger.error_dump(e, nil)
+                    @debug_logger.error_dump(error: e)
                   end
                 end
               end
@@ -327,7 +327,7 @@ def handle_servers
         end
         graceful_shutdown if @status == :stop || @status == :restart
       rescue Exception => e
-        @debug_logger.error_dump(e, force: true, custom_message: 'Exception handling servers')
+        @debug_logger.error_dump(error: e, force: true, text: 'Exception handling servers')
       ensure
         @check.close unless @check.closed? # Ruby 2.2 issue
         @notify.close
@@ -405,7 +405,7 @@ def process_client(client, buffer)
 
       # The client disconnected while we were reading data
       rescue ConnectionError => e
-        @debug_logger.error_dump(e, client.env, custom_message: 'The client disconnected while we were reading data')
+        @debug_logger.error_dump(error: e, env: client.env, text: 'The client disconnected while we were reading data')
         # Swallow them. The ensure tries to close +client+ down
 
       # SSL handshake error
@@ -443,7 +443,7 @@ def process_client(client, buffer)
           client.close if close_socket
         rescue IOError, SystemCallError => e
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
-          @debug_logger.error_dump(e, client.env)
+          @debug_logger.error_dump(error: e, env: client.env)
           # Already closed
         rescue StandardError => e
           @events.unknown_error self, e, "Client"
@@ -498,7 +498,7 @@ def normalize_env(env, client)
           # Client disconnects can result in an inability to get the
           # peeraddr from the socket; default to localhost.
           addr = LOCALHOST_IP
-          @debug_logger.error_dump(e, custom_message: 'Client disconnects can result in an inability to get the peeraddr from the socket')
+          @debug_logger.error_dump(error: e, text: 'Client disconnects can result in an inability to get the peeraddr from the socket')
         end
 
         # Set unix socket addrs to localhost
@@ -574,7 +574,7 @@ def handle_request(req, lines)
             fast_write client, "\r\n".freeze
           rescue ConnectionError => e
             # noop, if we lost the socket we just won't send the early hints
-            @debug_logger.error_dump(e, env)
+            @debug_logger.error_dump(error: e, env: env)
           end
         }
       end
@@ -602,12 +602,12 @@ def handle_request(req, lines)
         rescue ThreadPool::ForceShutdown => e
           @events.unknown_error self, e, "Rack app", env
           @events.log "Detected force shutdown of a thread"
-          @debug_logger.error_dump(e, env)
+          @debug_logger.error_dump(error: e, env: env)
 
           status, headers, res_body = lowlevel_error(e, env, 503)
         rescue Exception => e
           @events.unknown_error self, e, "Rack app", env
-          @debug_logger.error_dump(e, env)
+          @debug_logger.error_dump(error: e, env: env)
 
           status, headers, res_body = lowlevel_error(e, env, 500)
         end
@@ -745,7 +745,7 @@ def handle_request(req, lines)
             client.flush
           end
         rescue SystemCallError, IOError => e
-          @debug_logger.error_dump(e, env)
+          @debug_logger.error_dump(error: e, env: env)
           raise ConnectionError, "Connection error detected during write"
         end
 
@@ -874,7 +874,7 @@ def graceful_shutdown
                 @thread_pool << client
               end
             rescue SystemCallError => e
-              @debug_logger.error_dump(e)
+              @debug_logger.error_dump(error: e)
             end
           end
         end
@@ -901,9 +901,9 @@ def notify_safely(message)
       rescue IOError => e
          # The server, in another thread, is shutting down
         Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
-        @debug_logger.error_dump(e)
+        @debug_logger.error_dump(error: e)
       rescue RuntimeError => e
-        @debug_logger.error_dump(e)
+        @debug_logger.error_dump(error: e)
         # Temporary workaround for https://bugs.ruby-lang.org/issues/13239
         if e.message.include?('IOError')
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
@@ -937,14 +937,14 @@ def fast_write(io, str)
         begin
           n = io.syswrite str
         rescue Errno::EAGAIN, Errno::EWOULDBLOCK => e
-          @debug_logger.error_dump(e)
+          @debug_logger.error_dump(error: e)
           if !IO.select(nil, [io], nil, WRITE_TIMEOUT)
             raise ConnectionError, "Socket timeout writing data"
           end
 
           retry
         rescue  Errno::EPIPE, SystemCallError, IOError => e
-          @debug_logger.error_dump(e)
+          @debug_logger.error_dump(error: e)
           raise ConnectionError, "Socket timeout writing data"
         end
 
diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb
index b34a62160d..58bc96f9dd 100644
--- a/test/test_debug_logger.rb
+++ b/test/test_debug_logger.rb
@@ -5,14 +5,6 @@ def setup
     @debug_logger = Puma::DebugLogger.stdio
   end
 
-  def test_other_io
-    with_debug_mode do
-      debug_logger = Puma::DebugLogger.new(StringIO.new)
-      debug_logger.error_dump(StandardError.new('ready'))
-      assert_match %r!#<StandardError: ready>!, debug_logger.ioerr.string
-    end
-  end
-
   def test_stdio
     debug_logger = Puma::DebugLogger.stdio
 
@@ -21,7 +13,7 @@ def test_stdio
 
   def test_error_dump_if_debug_false
     _, err = capture_io do
-      @debug_logger.error_dump(StandardError.new('ready'))
+      @debug_logger.error_dump(text: 'blank')
     end
 
     assert_empty err
@@ -29,7 +21,7 @@ def test_error_dump_if_debug_false
 
   def test_error_dump_force
     _, err = capture_io do
-      Puma::DebugLogger.stdio.error_dump(StandardError.new('ready'), nil, force: true)
+      Puma::DebugLogger.stdio.error_dump(text: 'ready', force: true)
     end
 
     assert_match %r!ready!, err
@@ -38,7 +30,7 @@ def test_error_dump_force
   def test_error_dump_with_only_error
     with_debug_mode do
       _, err = capture_io do
-        Puma::DebugLogger.stdio.error_dump(StandardError.new('ready'), nil)
+        Puma::DebugLogger.stdio.error_dump(error: StandardError.new('ready'))
       end
 
       assert_match %r!#<StandardError: ready>!, err
@@ -54,17 +46,17 @@ def test_error_dump_with_env
       }
 
       _, err = capture_io do
-        Puma::DebugLogger.stdio.error_dump(StandardError.new, env)
+        Puma::DebugLogger.stdio.error_dump(error: StandardError.new, env: env)
       end
 
       assert_match %r!Handling request { GET /debug } \(8\.8\.8\.8\)!, err
     end
   end
 
-  def test_error_dump_with_custom_message
+  def test_error_dump_with_text
     with_debug_mode do
       _, err = capture_io do
-        Puma::DebugLogger.stdio.error_dump(StandardError.new, nil, custom_message: 'The client disconnected while we were reading data')
+        Puma::DebugLogger.stdio.error_dump(text: 'The client disconnected while we were reading data')
       end
 
       assert_match %r!The client disconnected while we were reading data!, err

From 49deca9093c7d455d38b60b181a3c67204ccdc03 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sat, 9 May 2020 19:03:32 +0300
Subject: [PATCH 06/17] unifying of events logging methods

---
 lib/puma/debug_logger.rb     |  2 +-
 lib/puma/events.rb           | 19 ++++++----
 lib/puma/reactor.rb          |  4 +--
 lib/puma/server.rb           | 67 +++++++++++++-----------------------
 test/test_puma_server_ssl.rb |  4 +--
 5 files changed, 42 insertions(+), 54 deletions(-)

diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb
index 1a74f706c9..fd74ddd7e8 100644
--- a/lib/puma/debug_logger.rb
+++ b/lib/puma/debug_logger.rb
@@ -42,7 +42,7 @@ def error_dump(options={})
       string_block = []
       formatted_text = " #{text}:" if text
       formatted_error = " #{error.inspect}" if error
-      string_block << "#{Time.now}#{text}#{error.inspect}"
+      string_block << "#{Time.now}#{formatted_text}#{formatted_error}"
       if env
         string_block << "Handling request { #{env[REQUEST_METHOD]} #{env[REQUEST_PATH] || env[PATH_INFO]} } (#{env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR]})"
       end
diff --git a/lib/puma/events.rb b/lib/puma/events.rb
index 040cb000eb..03a32ea539 100644
--- a/lib/puma/events.rb
+++ b/lib/puma/events.rb
@@ -87,28 +87,35 @@ def format(str)
       formatter.call(str)
     end
 
+    # An HTTP connection error has occurred.
+    # +error+ a connection exception, +env+ the request
+    #
+    def connection_error(error, env, text="HTTP connection error")
+      @debug_logger.error_dump(error: error, env: env, text: text)
+    end
+
     # An HTTP parse error has occurred.
-    # +server+ is the Server object, +env+ the request, and +error+ a
+    # +env+ the request, and +error+ a
     # parsing exception.
     #
-    def parse_error(server, env, error)
+    def parse_error(error, env)
       @debug_logger.error_dump(error: error, env: env, text: 'HTTP parse error, malformed request', force: true)
     end
 
     # An SSL error has occurred.
-    # +server+ is the Server object, +peeraddr+ peer address, +peercert+
+    # +peeraddr+ peer address, +peercert+
     # any peer certificate (if present), and +error+ an exception object.
     #
-    def ssl_error(server, peeraddr, peercert, error)
+    def ssl_error(error, peeraddr, peercert)
       subject = peercert ? peercert.subject : nil
       @debug_logger.error_dump(error: error, text: "SSL error, peer: #{peeraddr}, peer cert: #{subject}", force: true)
     end
 
     # An unknown error has occurred.
-    # +server+ is the Server object, +error+ an exception object,
+    # +error+ an exception object,
     # +kind+ some additional info, and +env+ the request.
     #
-    def unknown_error(server, error, kind="Unknown", env=nil)
+    def unknown_error(error, env=nil, kind="Unknown")
       @debug_logger.error_dump(error: error, env: env, text: kind, force: true)
     end
 
diff --git a/lib/puma/reactor.rb b/lib/puma/reactor.rb
index 7a4fce5cad..37b91b08bc 100644
--- a/lib/puma/reactor.rb
+++ b/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.env
               rescue StandardError => e
                 @server.lowlevel_error(e, c.env)
 
diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index ff271ff42a..985aa7ff06 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -12,7 +12,6 @@
 require 'puma/accept_nonblock'
 require 'puma/util'
 require 'puma/io_buffer'
-require 'puma/debug_logger'
 
 require 'puma/puma_http11'
 
@@ -59,7 +58,6 @@ class Server
     def initialize(app, events=Events.stdio, options={})
       @app = app
       @events = events
-      @debug_logger = DebugLogger.stdio
 
       @check, @notify = Puma::Util.pipe
 
@@ -210,15 +208,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
+          @events.parse_error e, client.env
         rescue ConnectionError, EOFError => e
-          @debug_logger.error_dump(error: e, env: client.env)
           client.close
+
+          @events.connection_error e, client.env
         else
           if process_now
             process_client client, buffer
@@ -296,25 +295,20 @@ def handle_servers
 
                     pool << client
                   end
-                rescue SystemCallError => e
-                  # TODO: check if we able to use client here
-                  @debug_logger.error_dump(error: e)
+                rescue SystemCallError
                   # nothing
                 rescue Errno::ECONNABORTED
-                  # TODO: check if we able to use client here
-                  @debug_logger.error_dump(error: e, text: 'Client closed the socket even before accept')
+                  # client closed the socket even before accept
                   begin
                     io.close
-                  rescue => e
+                  rescue
                     Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
-                    # TODO: check if we able to use client here
-                    @debug_logger.error_dump(error: e)
                   end
                 end
               end
             end
           rescue Object => e
-            @events.unknown_error self, e, "Listen loop"
+            @events.unknown_error e, nil, "Listen loop"
           end
         end
 
@@ -327,7 +321,7 @@ def handle_servers
         end
         graceful_shutdown if @status == :stop || @status == :restart
       rescue Exception => e
-        @debug_logger.error_dump(error: e, force: true, text: 'Exception handling servers')
+        @events.unknown_error e, nil, "Exception handling servers"
       ensure
         @check.close unless @check.closed? # Ruby 2.2 issue
         @notify.close
@@ -404,8 +398,7 @@ def process_client(client, buffer)
         end
 
       # The client disconnected while we were reading data
-      rescue ConnectionError => e
-        @debug_logger.error_dump(error: e, env: client.env, text: 'The client disconnected while we were reading data')
+      rescue ConnectionError
         # Swallow them. The ensure tries to close +client+ down
 
       # SSL handshake error
@@ -418,7 +411,7 @@ 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
@@ -426,7 +419,7 @@ def process_client(client, buffer)
 
         client.write_error(400)
 
-        @events.parse_error self, client.env, e
+        @events.parse_error e, client.env
 
       # Server error
       rescue StandardError => e
@@ -434,19 +427,17 @@ def process_client(client, buffer)
 
         client.write_error(500)
 
-        @events.unknown_error self, e, "Read"
-
+        @events.unknown_error e, nil, "Read"
       ensure
         buffer.reset
 
         begin
           client.close if close_socket
-        rescue IOError, SystemCallError => e
+        rescue IOError, SystemCallError
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
-          @debug_logger.error_dump(error: e, env: client.env)
           # Already closed
         rescue StandardError => e
-          @events.unknown_error self, e, "Client"
+          @events.unknown_error e, nil, "Client"
         end
       end
     end
@@ -494,11 +485,10 @@ def normalize_env(env, client)
       unless env.key?(REMOTE_ADDR)
         begin
           addr = client.peerip
-        rescue Errno::ENOTCONN => e
+        rescue Errno::ENOTCONN
           # Client disconnects can result in an inability to get the
           # peeraddr from the socket; default to localhost.
           addr = LOCALHOST_IP
-          @debug_logger.error_dump(error: e, text: 'Client disconnects can result in an inability to get the peeraddr from the socket')
         end
 
         # Set unix socket addrs to localhost
@@ -572,9 +562,8 @@ def handle_request(req, lines)
             end
 
             fast_write client, "\r\n".freeze
-          rescue ConnectionError => e
+          rescue ConnectionError
             # noop, if we lost the socket we just won't send the early hints
-            @debug_logger.error_dump(error: e, env: env)
           end
         }
       end
@@ -600,14 +589,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, env, "Rack app"
           @events.log "Detected force shutdown of a thread"
-          @debug_logger.error_dump(error: e, env: env)
 
           status, headers, res_body = lowlevel_error(e, env, 503)
         rescue Exception => e
-          @events.unknown_error self, e, "Rack app", env
-          @debug_logger.error_dump(error: e, env: env)
+          @events.unknown_error e, env, "Rack app"
 
           status, headers, res_body = lowlevel_error(e, env, 500)
         end
@@ -744,8 +731,7 @@ def handle_request(req, lines)
             fast_write client, CLOSE_CHUNKED
             client.flush
           end
-        rescue SystemCallError, IOError => e
-          @debug_logger.error_dump(error: e, env: env)
+        rescue SystemCallError, IOError
           raise ConnectionError, "Connection error detected during write"
         end
 
@@ -873,8 +859,7 @@ def graceful_shutdown
                 client = Client.new io, @binder.env(sock)
                 @thread_pool << client
               end
-            rescue SystemCallError => e
-              @debug_logger.error_dump(error: e)
+            rescue SystemCallError
             end
           end
         end
@@ -898,12 +883,10 @@ def graceful_shutdown
     def notify_safely(message)
       begin
         @notify << message
-      rescue IOError => e
+      rescue IOError
          # The server, in another thread, is shutting down
         Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
-        @debug_logger.error_dump(error: e)
       rescue RuntimeError => e
-        @debug_logger.error_dump(error: e)
         # Temporary workaround for https://bugs.ruby-lang.org/issues/13239
         if e.message.include?('IOError')
           Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue
@@ -936,15 +919,13 @@ def fast_write(io, str)
       while true
         begin
           n = io.syswrite str
-        rescue Errno::EAGAIN, Errno::EWOULDBLOCK => e
-          @debug_logger.error_dump(error: e)
+        rescue Errno::EAGAIN, Errno::EWOULDBLOCK
           if !IO.select(nil, [io], nil, WRITE_TIMEOUT)
             raise ConnectionError, "Socket timeout writing data"
           end
 
           retry
-        rescue  Errno::EPIPE, SystemCallError, IOError => e
-          @debug_logger.error_dump(error: e)
+        rescue  Errno::EPIPE, SystemCallError, IOError
           raise ConnectionError, "Socket timeout writing data"
         end
 
diff --git a/test/test_puma_server_ssl.rb b/test/test_puma_server_ssl.rb
index 26b54b158c..b42d5a5722 100644
--- a/test/test_puma_server_ssl.rb
+++ b/test/test_puma_server_ssl.rb
@@ -11,10 +11,10 @@
 class SSLEventsHelper < ::Puma::Events
   attr_accessor :addr, :cert, :error
 
-  def ssl_error(server, peeraddr, peercert, error)
+  def ssl_error(error, peeraddr, peercert)
+    self.error = error
     self.addr = peeraddr
     self.cert = peercert
-    self.error = error
   end
 end
 

From 067799405e0aade78fbaad37485d1e457025e8ec Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sat, 9 May 2020 19:11:44 +0300
Subject: [PATCH 07/17] add logging for fast_write ConnectionError

---
 lib/puma/server.rb | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index 985aa7ff06..80110e4dc9 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -562,7 +562,8 @@ def handle_request(req, lines)
             end
 
             fast_write client, "\r\n".freeze
-          rescue ConnectionError
+          rescue ConnectionError => e
+            @events.connection_error e, client.env
             # noop, if we lost the socket we just won't send the early hints
           end
         }

From c606471b5ae436a165ee2f083a35635c90a29b93 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sat, 9 May 2020 20:18:39 +0300
Subject: [PATCH 08/17] rubocop

---
 puma.gemspec | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/puma.gemspec b/puma.gemspec
index 7e31d6c84f..e323c45a14 100644
--- a/puma.gemspec
+++ b/puma.gemspec
@@ -18,7 +18,7 @@ Gem::Specification.new do |s|
   s.files = `git ls-files -- bin docs ext lib tools`.split("\n") +
             %w[History.md LICENSE README.md]
   s.homepage = "http://puma.io"
-  
+
   if s.respond_to?(:metadata=)
     s.metadata = {
       "bug_tracker_uri" => "https://github.com/puma/puma/issues",
@@ -27,7 +27,7 @@ Gem::Specification.new do |s|
       "source_code_uri" => "https://github.com/puma/puma"
     }
   end
-  
+
   s.license = "BSD-3-Clause"
   s.required_ruby_version = Gem::Requirement.new(">= 2.2")
 end

From 265f638d2beb9ee60d1af5e5c03ae876b0c3e4d8 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sat, 9 May 2020 22:29:56 +0300
Subject: [PATCH 09/17] force log connection error

---
 lib/puma/events.rb | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/puma/events.rb b/lib/puma/events.rb
index 03a32ea539..c603da29ef 100644
--- a/lib/puma/events.rb
+++ b/lib/puma/events.rb
@@ -91,7 +91,7 @@ def format(str)
     # +error+ a connection exception, +env+ the request
     #
     def connection_error(error, env, text="HTTP connection error")
-      @debug_logger.error_dump(error: error, env: env, text: text)
+      @debug_logger.error_dump(error: error, env: env, text: text, force: true)
     end
 
     # An HTTP parse error has occurred.

From 2d7ff5da5007dcaf8321601e77166c1c3391f3b9 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sun, 10 May 2020 18:43:42 +0300
Subject: [PATCH 10/17] fix server swallow connection error

---
 lib/puma/events.rb | 2 +-
 lib/puma/server.rb | 2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/lib/puma/events.rb b/lib/puma/events.rb
index c603da29ef..03a32ea539 100644
--- a/lib/puma/events.rb
+++ b/lib/puma/events.rb
@@ -91,7 +91,7 @@ def format(str)
     # +error+ a connection exception, +env+ the request
     #
     def connection_error(error, env, text="HTTP connection error")
-      @debug_logger.error_dump(error: error, env: env, text: text, force: true)
+      @debug_logger.error_dump(error: error, env: env, text: text)
     end
 
     # An HTTP parse error has occurred.
diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index 80110e4dc9..9273f196ea 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -563,7 +563,7 @@ def handle_request(req, lines)
 
             fast_write client, "\r\n".freeze
           rescue ConnectionError => e
-            @events.connection_error e, client.env
+            @events.connection_error e, nil
             # noop, if we lost the socket we just won't send the early hints
           end
         }

From f178dd52117f91a0d26472a7f763b6c05534a764 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sun, 10 May 2020 18:44:34 +0300
Subject: [PATCH 11/17] fix require in test_debug_logger

---
 test/test_debug_logger.rb | 1 +
 1 file changed, 1 insertion(+)

diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb
index 58bc96f9dd..b67250419f 100644
--- a/test/test_debug_logger.rb
+++ b/test/test_debug_logger.rb
@@ -1,3 +1,4 @@
+require 'puma/debug_logger'
 require_relative "helper"
 
 class TestDebugLogger < Minitest::Test

From c3d82818411fc5677e1a5ed87a465b448da65c6d Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Mon, 11 May 2020 13:19:53 +0300
Subject: [PATCH 12/17] add body & headers to request log

---
 lib/puma/debug_logger.rb  | 33 ++++++++++++++++++++++++++-------
 lib/puma/events.rb        | 18 +++++++++---------
 lib/puma/reactor.rb       |  2 +-
 lib/puma/server.rb        | 10 +++++-----
 test/test_debug_logger.rb | 12 +++++++++---
 test/test_events.rb       |  3 ++-
 6 files changed, 52 insertions(+), 26 deletions(-)

diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb
index fd74ddd7e8..3d01e80e4b 100644
--- a/lib/puma/debug_logger.rb
+++ b/lib/puma/debug_logger.rb
@@ -10,6 +10,8 @@ class DebugLogger
 
     attr_reader :ioerr
 
+    REQUEST_FORMAT = %{"%s %s%s" - (%s)}
+
     def initialize(ioerr)
       @ioerr = ioerr
       @ioerr.sync = true
@@ -25,31 +27,48 @@ def self.stdio
     # +options+ hash with additional options:
     # - +force+ (default nil) to log info even if debug mode is turned off
     # - +error+ is an exception object
-    # - +env+ the request
+    # - +req+ the http request
     # - +text+ (default nil) custom string to print in title
     #   and before all remaining info.
     #
     def error_dump(options={})
       return unless @debug || options[:force]
+
       error = options[:error]
-      env = options[:env]
+      req = options[:req]
+      env = req.env if req
       text = options[:text]
 
-      #
-      # TODO: add all info we have about request
-      #
-
       string_block = []
       formatted_text = " #{text}:" if text
       formatted_error = " #{error.inspect}" if error
       string_block << "#{Time.now}#{formatted_text}#{formatted_error}"
+
       if env
-        string_block << "Handling request { #{env[REQUEST_METHOD]} #{env[REQUEST_PATH] || env[PATH_INFO]} } (#{env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR]})"
+        string_block << "Handling request { #{request_title(env)} }"
+        string_block << "Headers: #{request_headers(env)}"
+        string_block << "Body: #{req.body}"
       end
 
       string_block << error.backtrace if error
 
       ioerr.puts string_block.join("\n")
     end
+
+    private
+
+    def request_title(env)
+      request_line = 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(env)
+      headers = env.select { |key, _| key.start_with?('HTTP_') }
+      headers.map { |key, value| [key[5..-1], value] }.to_h.inspect
+    end
   end
 end
diff --git a/lib/puma/events.rb b/lib/puma/events.rb
index 03a32ea539..18da74a07e 100644
--- a/lib/puma/events.rb
+++ b/lib/puma/events.rb
@@ -88,18 +88,18 @@ def format(str)
     end
 
     # An HTTP connection error has occurred.
-    # +error+ a connection exception, +env+ the request
+    # +error+ a connection exception, +req+ the request
     #
-    def connection_error(error, env, text="HTTP connection error")
-      @debug_logger.error_dump(error: error, env: env, text: text)
+    def connection_error(error, req, text="HTTP connection error")
+      @debug_logger.error_dump(error: error, req: req, text: text)
     end
 
     # An HTTP parse error has occurred.
-    # +env+ the request, and +error+ a
+    # +req+ the request, and +error+ a
     # parsing exception.
     #
-    def parse_error(error, env)
-      @debug_logger.error_dump(error: error, env: env, text: 'HTTP parse error, malformed request', force: true)
+    def parse_error(error, req)
+      @debug_logger.error_dump(error: error, req: req, text: 'HTTP parse error, malformed request', force: true)
     end
 
     # An SSL error has occurred.
@@ -113,10 +113,10 @@ def ssl_error(error, peeraddr, peercert)
 
     # An unknown error has occurred.
     # +error+ an exception object,
-    # +kind+ some additional info, and +env+ the request.
+    # +kind+ some additional info, and +req+ the request.
     #
-    def unknown_error(error, env=nil, kind="Unknown")
-      @debug_logger.error_dump(error: error, env: env, text: kind, force: true)
+    def unknown_error(error, req=nil, kind="Unknown")
+      @debug_logger.error_dump(error: error, req: req, text: kind, force: true)
     end
 
     def on_booted(&block)
diff --git a/lib/puma/reactor.rb b/lib/puma/reactor.rb
index 37b91b08bc..780903d296 100644
--- a/lib/puma/reactor.rb
+++ b/lib/puma/reactor.rb
@@ -263,7 +263,7 @@ def run_internal
 
                 clear_monitor mon
 
-                @events.parse_error e, c.env
+                @events.parse_error e, c
               rescue StandardError => e
                 @server.lowlevel_error(e, c.env)
 
diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index 9273f196ea..9278b1729f 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -213,11 +213,11 @@ def run(background=true)
           client.write_error(400)
           client.close
 
-          @events.parse_error e, client.env
+          @events.parse_error e, client
         rescue ConnectionError, EOFError => e
           client.close
 
-          @events.connection_error e, client.env
+          @events.connection_error e, client
         else
           if process_now
             process_client client, buffer
@@ -419,7 +419,7 @@ def process_client(client, buffer)
 
         client.write_error(400)
 
-        @events.parse_error e, client.env
+        @events.parse_error e, client
 
       # Server error
       rescue StandardError => e
@@ -590,12 +590,12 @@ def handle_request(req, lines)
             return :async
           end
         rescue ThreadPool::ForceShutdown => e
-          @events.unknown_error e, env, "Rack app"
+          @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 e, env, "Rack app"
+          @events.unknown_error e, req, "Rack app"
 
           status, headers, res_body = lowlevel_error(e, env, 500)
         end
diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb
index b67250419f..b01d2ecabc 100644
--- a/test/test_debug_logger.rb
+++ b/test/test_debug_logger.rb
@@ -2,6 +2,8 @@
 require_relative "helper"
 
 class TestDebugLogger < Minitest::Test
+  Req = Struct.new(:env, :body)
+
   def setup
     @debug_logger = Puma::DebugLogger.stdio
   end
@@ -38,19 +40,23 @@ def test_error_dump_with_only_error
     end
   end
 
-  def test_error_dump_with_env
+  def test_error_dump_with_request
     with_debug_mode do
+
       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::DebugLogger.stdio.error_dump(error: StandardError.new, env: env)
+        Puma::DebugLogger.stdio.error_dump(error: StandardError.new, req: req)
       end
 
-      assert_match %r!Handling request { GET /debug } \(8\.8\.8\.8\)!, err
+      assert_match %r!Handling request { "GET /debug" - \(8\.8\.8\.8\) }!, err
+      assert_match %r!Headers: {"X_FORWARDED_FOR"=>"8\.8\.8\.8"}!, err
+      assert_match %r!Body: {"hello":"world"}!, err
     end
   end
 
diff --git a/test/test_events.rb b/test/test_events.rb
index a77f871584..06afd695ec 100644
--- a/test/test_events.rb
+++ b/test/test_events.rb
@@ -1,3 +1,4 @@
+require 'puma/events'
 require_relative "helper"
 
 class TestEvents < Minitest::Test
@@ -176,7 +177,7 @@ def test_parse_error
     sock.read
     sleep 0.1 # important so that the previous data is sent as a packet
     assert_match %r!HTTP parse error, malformed request!, events.stderr.string
-    assert_match %r!Handling request { GET #{path} }!, events.stderr.string
+    assert_match %r!Handling request { "GET #{path}" - \(-\) }!, events.stderr.string
     server.stop(true)
   end
 end

From 0bcd428863319ce30f95a28f784160d518d8f57a Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Mon, 11 May 2020 16:56:54 +0300
Subject: [PATCH 13/17] rename debug_logger to error_logger; add levels; fix
 tests

---
 lib/puma/{debug_logger.rb => error_logger.rb} | 34 +++++---
 lib/puma/events.rb                            | 39 +++++----
 lib/puma/server.rb                            |  2 +-
 test/test_debug_logger.rb                     | 81 -------------------
 test/test_error_logger.rb                     | 72 +++++++++++++++++
 test/test_events.rb                           | 14 ++--
 6 files changed, 129 insertions(+), 113 deletions(-)
 rename lib/puma/{debug_logger.rb => error_logger.rb} (70%)
 delete mode 100644 test/test_debug_logger.rb
 create mode 100644 test/test_error_logger.rb

diff --git a/lib/puma/debug_logger.rb b/lib/puma/error_logger.rb
similarity index 70%
rename from lib/puma/debug_logger.rb
rename to lib/puma/error_logger.rb
index 3d01e80e4b..97695141f9 100644
--- a/lib/puma/debug_logger.rb
+++ b/lib/puma/error_logger.rb
@@ -5,7 +5,7 @@
 module Puma
   # The implementation of a logging in debug mode.
   #
-  class DebugLogger
+  class ErrorLogger
     include Const
 
     attr_reader :ioerr
@@ -23,25 +23,41 @@ def self.stdio
       new $stderr
     end
 
-    # Any error has occured during debug mode.
+    # Print occured error details.
     # +options+ hash with additional options:
-    # - +force+ (default nil) to log info even if debug mode is turned off
     # - +error+ is an exception object
     # - +req+ the http request
     # - +text+ (default nil) custom string to print in title
     #   and before all remaining info.
     #
-    def error_dump(options={})
-      return unless @debug || options[:force]
+    def info(options={})
+      error_dump(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_dump(options)
+    end
+
+    private
+
+    def error_dump(options={})
       error = options[:error]
       req = options[:req]
       env = req.env if req
       text = options[:text]
 
       string_block = []
-      formatted_text = " #{text}:" if text
-      formatted_error = " #{error.inspect}" if error
+      formatted_text = " #{text}" if text
+      formatted_error = ": #{error.inspect}" if error
       string_block << "#{Time.now}#{formatted_text}#{formatted_error}"
 
       if env
@@ -55,10 +71,8 @@ def error_dump(options={})
       ioerr.puts string_block.join("\n")
     end
 
-    private
-
     def request_title(env)
-      request_line = REQUEST_FORMAT % [
+      REQUEST_FORMAT % [
         env[REQUEST_METHOD],
         env[REQUEST_PATH] || env[PATH_INFO],
         env[QUERY_STRING] || "",
diff --git a/lib/puma/events.rb b/lib/puma/events.rb
index 18da74a07e..8c2323f73b 100644
--- a/lib/puma/events.rb
+++ b/lib/puma/events.rb
@@ -1,7 +1,7 @@
 # frozen_string_literal: true
 
 require "puma/null_io"
-require 'puma/debug_logger'
+require 'puma/error_logger'
 require 'stringio'
 
 module Puma
@@ -34,7 +34,7 @@ def initialize(stdout, stderr)
       @stderr.sync = true
 
       @debug = ENV.key? 'PUMA_DEBUG'
-      @debug_logger = DebugLogger.new(@stderr)
+      @error_logger = ErrorLogger.new(@stderr)
 
       @hooks = Hash.new { |h,k| h[k] = [] }
     end
@@ -79,7 +79,7 @@ def debug(str)
     # Write +str+ to +@stderr+
     #
     def error(str)
-      @debug_logger.error_dump(text: format("ERROR: #{str}"))
+      @error_logger.info(text: format("ERROR: #{str}"))
       exit 1
     end
 
@@ -88,35 +88,44 @@ def format(str)
     end
 
     # An HTTP connection error has occurred.
-    # +error+ a connection exception, +req+ the request
+    # +error+ a connection exception, +req+ the request,
+    # and +text+ additional info
     #
     def connection_error(error, req, text="HTTP connection error")
-      @debug_logger.error_dump(error: error, req: req, text: text)
+      @error_logger.info(error: error, req: req, text: text)
     end
 
     # An HTTP parse error has occurred.
-    # +req+ the request, and +error+ a
-    # parsing exception.
+    # +error+ a parsing exception,
+    # and +req+ the request.
     #
     def parse_error(error, req)
-      @debug_logger.error_dump(error: error, req: req, text: 'HTTP parse error, malformed request', force: true)
+      @error_logger.info(error: error, req: req, text: 'HTTP parse error, malformed request')
     end
 
     # An SSL error has occurred.
-    # +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(error, peeraddr, peercert)
       subject = peercert ? peercert.subject : nil
-      @debug_logger.error_dump(error: error, text: "SSL error, peer: #{peeraddr}, peer cert: #{subject}", force: true)
+      @error_logger.info(error: error, text: "SSL error, peer: #{peeraddr}, peer cert: #{subject}")
     end
 
     # An unknown error has occurred.
-    # +error+ an exception object,
-    # +kind+ some additional info, and +req+ the request.
+    # +error+ an exception object, +req+ the request,
+    # and +text+ additional info
     #
-    def unknown_error(error, req=nil, kind="Unknown")
-      @debug_logger.error_dump(error: error, req: req, text: kind, force: true)
+    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)
diff --git a/lib/puma/server.rb b/lib/puma/server.rb
index 9278b1729f..562985e67c 100644
--- a/lib/puma/server.rb
+++ b/lib/puma/server.rb
@@ -563,7 +563,7 @@ def handle_request(req, lines)
 
             fast_write client, "\r\n".freeze
           rescue ConnectionError => e
-            @events.connection_error e, nil
+            @events.debug_error e
             # noop, if we lost the socket we just won't send the early hints
           end
         }
diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb
deleted file mode 100644
index b01d2ecabc..0000000000
--- a/test/test_debug_logger.rb
+++ /dev/null
@@ -1,81 +0,0 @@
-require 'puma/debug_logger'
-require_relative "helper"
-
-class TestDebugLogger < Minitest::Test
-  Req = Struct.new(:env, :body)
-
-  def setup
-    @debug_logger = Puma::DebugLogger.stdio
-  end
-
-  def test_stdio
-    debug_logger = Puma::DebugLogger.stdio
-
-    assert_equal STDERR, debug_logger.ioerr
-  end
-
-  def test_error_dump_if_debug_false
-    _, err = capture_io do
-      @debug_logger.error_dump(text: 'blank')
-    end
-
-    assert_empty err
-  end
-
-  def test_error_dump_force
-    _, err = capture_io do
-      Puma::DebugLogger.stdio.error_dump(text: 'ready', force: true)
-    end
-
-    assert_match %r!ready!, err
-  end
-
-  def test_error_dump_with_only_error
-    with_debug_mode do
-      _, err = capture_io do
-        Puma::DebugLogger.stdio.error_dump(error: StandardError.new('ready'))
-      end
-
-      assert_match %r!#<StandardError: ready>!, err
-    end
-  end
-
-  def test_error_dump_with_request
-    with_debug_mode do
-
-      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::DebugLogger.stdio.error_dump(error: StandardError.new, req: req)
-      end
-
-      assert_match %r!Handling request { "GET /debug" - \(8\.8\.8\.8\) }!, err
-      assert_match %r!Headers: {"X_FORWARDED_FOR"=>"8\.8\.8\.8"}!, err
-      assert_match %r!Body: {"hello":"world"}!, err
-    end
-  end
-
-  def test_error_dump_with_text
-    with_debug_mode do
-      _, err = capture_io do
-        Puma::DebugLogger.stdio.error_dump(text: 'The client disconnected while we were reading data')
-      end
-
-      assert_match %r!The client disconnected while we were reading data!, 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
diff --git a/test/test_error_logger.rb b/test/test_error_logger.rb
new file mode 100644
index 0000000000..f95eef3350
--- /dev/null
+++ b/test/test_error_logger.rb
@@ -0,0 +1,72 @@
+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!Handling request { "GET /debug" - \(8\.8\.8\.8\) }!, err
+    assert_match %r!Headers: {"X_FORWARDED_FOR"=>"8\.8\.8\.8"}!, err
+    assert_match %r!Body: {"hello":"world"}!, 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
diff --git a/test/test_events.rb b/test/test_events.rb
index 06afd695ec..dc8459b538 100644
--- a/test/test_events.rb
+++ b/test/test_events.rb
@@ -120,14 +120,16 @@ def test_error_writes_to_stderr_and_exits
     did_exit = false
 
     _, err = capture_io do
-      Puma::Events.stdio.error("interrupted")
+      begin
+        Puma::Events.stdio.error("interrupted")
+      rescue SystemExit
+        did_exit = true
+      ensure
+        assert did_exit
+      end
     end
 
-    assert_equal "ERROR: interrupted", err
-  rescue SystemExit
-    did_exit = true
-  ensure
-    assert did_exit
+    assert_match %r!ERROR: interrupted!, err
   end
 
   def test_pid_formatter

From 556c4b238b1b1f5222d253a706116cbc5a22fd14 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sun, 17 May 2020 16:24:48 +0300
Subject: [PATCH 14/17] single-line info logs

---
 lib/puma/error_logger.rb  | 46 +++++++++++++++++++++------------------
 test/test_error_logger.rb |  2 +-
 test/test_events.rb       |  2 +-
 3 files changed, 27 insertions(+), 23 deletions(-)

diff --git a/lib/puma/error_logger.rb b/lib/puma/error_logger.rb
index 97695141f9..b6b7b7ba8a 100644
--- a/lib/puma/error_logger.rb
+++ b/lib/puma/error_logger.rb
@@ -31,7 +31,7 @@ def self.stdio
     #   and before all remaining info.
     #
     def info(options={})
-      error_dump(options)
+      ioerr.puts title(options)
     end
 
     # Print occured error details only if
@@ -44,34 +44,38 @@ def info(options={})
     #
     def debug(options={})
       return unless @debug
-      error_dump(options)
-    end
-
-    private
 
-    def error_dump(options={})
       error = options[:error]
       req = options[:req]
-      env = req.env if req
-      text = options[:text]
 
       string_block = []
-      formatted_text = " #{text}" if text
-      formatted_error = ": #{error.inspect}" if error
-      string_block << "#{Time.now}#{formatted_text}#{formatted_error}"
+      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
 
-      if env
-        string_block << "Handling request { #{request_title(env)} }"
-        string_block << "Headers: #{request_headers(env)}"
-        string_block << "Body: #{req.body}"
-      end
+    def title(options={})
+      text = options[:text]
+      req = options[:req]
+      error = options[:error]
 
-      string_block << error.backtrace if error
+      string_block = ["#{Time.now}"]
+      string_block << " #{text}" if text
+      string_block << " (#{request_title(req)})" if req
+      string_block << ": #{error.inspect}" if error
+      string_block.join('')
+    end
 
-      ioerr.puts string_block.join("\n")
+    def request_dump(req)
+      "Headers: #{request_headers(req)}\n" \
+      "Body: #{req.body}"
     end
 
-    def request_title(env)
+    def request_title(req)
+      env = req.env
+
       REQUEST_FORMAT % [
         env[REQUEST_METHOD],
         env[REQUEST_PATH] || env[PATH_INFO],
@@ -80,8 +84,8 @@ def request_title(env)
       ]
     end
 
-    def request_headers(env)
-      headers = env.select { |key, _| key.start_with?('HTTP_') }
+    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
   end
diff --git a/test/test_error_logger.rb b/test/test_error_logger.rb
index f95eef3350..34bea39da3 100644
--- a/test/test_error_logger.rb
+++ b/test/test_error_logger.rb
@@ -30,7 +30,7 @@ def test_info_with_request
       Puma::ErrorLogger.stdio.info(error: StandardError.new, req: req)
     end
 
-    assert_match %r!Handling request { "GET /debug" - \(8\.8\.8\.8\) }!, err
+    assert_match %r!\("GET /debug" - \(8\.8\.8\.8\)\)!, err
     assert_match %r!Headers: {"X_FORWARDED_FOR"=>"8\.8\.8\.8"}!, err
     assert_match %r!Body: {"hello":"world"}!, err
   end
diff --git a/test/test_events.rb b/test/test_events.rb
index dc8459b538..0a1003d74b 100644
--- a/test/test_events.rb
+++ b/test/test_events.rb
@@ -179,7 +179,7 @@ def test_parse_error
     sock.read
     sleep 0.1 # important so that the previous data is sent as a packet
     assert_match %r!HTTP parse error, malformed request!, events.stderr.string
-    assert_match %r!Handling request { "GET #{path}" - \(-\) }!, events.stderr.string
+    assert_match %r!\("GET #{path}" - \(-\)\)!, events.stderr.string
     server.stop(true)
   end
 end

From e3e61f24203e2bb85959964d7918f1988370dbe7 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sun, 17 May 2020 16:51:30 +0300
Subject: [PATCH 15/17] hotfix

---
 test/test_error_logger.rb | 2 --
 1 file changed, 2 deletions(-)

diff --git a/test/test_error_logger.rb b/test/test_error_logger.rb
index 34bea39da3..1ca19ec20e 100644
--- a/test/test_error_logger.rb
+++ b/test/test_error_logger.rb
@@ -31,8 +31,6 @@ def test_info_with_request
     end
 
     assert_match %r!\("GET /debug" - \(8\.8\.8\.8\)\)!, err
-    assert_match %r!Headers: {"X_FORWARDED_FOR"=>"8\.8\.8\.8"}!, err
-    assert_match %r!Body: {"hello":"world"}!, err
   end
 
   def test_info_with_text

From 1b0dd560fa38a12590b6905a2a05502adadb5620 Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sun, 7 Jun 2020 15:58:47 +0300
Subject: [PATCH 16/17] fix error_logger comment

---
 lib/puma/error_logger.rb | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/puma/error_logger.rb b/lib/puma/error_logger.rb
index b6b7b7ba8a..91ff1bbcd2 100644
--- a/lib/puma/error_logger.rb
+++ b/lib/puma/error_logger.rb
@@ -3,7 +3,7 @@
 require 'puma/const'
 
 module Puma
-  # The implementation of a logging in debug mode.
+  # The implementation of a detailed error logging.
   #
   class ErrorLogger
     include Const

From 2bbdbd2a2b8c9833cc96fa6013c582d20f5bfa4e Mon Sep 17 00:00:00 2001
From: Vyacheslav Alexeev <alexeev.corp@gmail.com>
Date: Sun, 7 Jun 2020 16:34:33 +0300
Subject: [PATCH 17/17] fix request logging

---
 lib/puma/error_logger.rb | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/lib/puma/error_logger.rb b/lib/puma/error_logger.rb
index 91ff1bbcd2..e9f2ad6478 100644
--- a/lib/puma/error_logger.rb
+++ b/lib/puma/error_logger.rb
@@ -63,7 +63,7 @@ def title(options={})
 
       string_block = ["#{Time.now}"]
       string_block << " #{text}" if text
-      string_block << " (#{request_title(req)})" if req
+      string_block << " (#{request_title(req)})" if request_parsed?(req)
       string_block << ": #{error.inspect}" if error
       string_block.join('')
     end
@@ -88,5 +88,9 @@ 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