implement debug_logger

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

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 @@ module Puma
       @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 @@ module Puma
         "(#{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 @@ module Puma
     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 @@ module Puma
       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
 

lib/puma/server.rb

@@ -12,6 +12,7 @@ require 'puma/binder'
 require 'puma/accept_nonblock'
 require 'puma/util'
 require 'puma/io_buffer'
+require 'puma/debug_logger'
 
 require 'puma/puma_http11'
 
@@ -58,6 +59,7 @@ module Puma
     def initialize(app, events=Events.stdio, options={})
       @app = app
       @events = events
+      @debug_logger = DebugLogger.stdio
 
       @check, @notify = Puma::Util.pipe
 
@@ -111,16 +113,18 @@ module Puma
       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 @@ module Puma
           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 @@ module Puma
 
                     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 @@ module Puma
         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 @@ module Puma
         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 @@ module Puma
 
         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 @@ module Puma
       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 @@ module Puma
             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 @@ module Puma
         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 @@ module Puma
             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 @@ module Puma
                 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 @@ module Puma
     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 @@ module Puma
       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
 

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