use only debug_logger instead of stderr in events

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 @@ module Puma
     # +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

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 @@ module Puma
       end
     end
 
-    include Const
-
     # Create an Events object that prints to +stdout+ and +stderr+.
     #
     def initialize(stdout, stderr)
@@ -95,11 +92,7 @@ module Puma
     # 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 @@ 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)
+      @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 @@ module Puma
     # +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)

test/test_debug_logger.rb

@@ -5,6 +5,14 @@ class TestDebugLogger < Minitest::Test
     @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 @@ class TestDebugLogger < Minitest::Test
     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
 

test/test_events.rb

@@ -175,7 +175,8 @@ class TestEvents < Minitest::Test
     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