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 3d01e80e..97695141 100644 --- a/lib/puma/debug_logger.rb +++ b/lib/puma/error_logger.rb @@ -5,7 +5,7 @@ require 'puma/const' module Puma # The implementation of a logging in debug mode. # - class DebugLogger + class ErrorLogger include Const attr_reader :ioerr @@ -23,25 +23,41 @@ module Puma 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 @@ module Puma 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 18da74a0..8c2323f7 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 @@ module Puma @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 @@ module Puma # 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 @@ module Puma 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 9278b172..562985e6 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -563,7 +563,7 @@ module Puma 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 b01d2eca..00000000 --- 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!#!, 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 00000000..f95eef33 --- /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!#!, 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 06afd695..dc8459b5 100644 --- a/test/test_events.rb +++ b/test/test_events.rb @@ -120,14 +120,16 @@ class TestEvents < Minitest::Test 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