From 607e24fe509c110043daf0c998843775e8b90f29 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sat, 9 May 2020 18:04:04 +0300 Subject: [PATCH] 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 29a4ae6d..1a74f706 100644 --- a/lib/puma/debug_logger.rb +++ b/lib/puma/debug_logger.rb @@ -22,28 +22,32 @@ module Puma 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}" - + 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 0bdc5f81..040cb000 100644 --- a/lib/puma/events.rb +++ b/lib/puma/events.rb @@ -79,7 +79,7 @@ module Puma # 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 @@ module Puma # 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 @@ module Puma # 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 @@ module Puma # +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 e9da2bcb..ff271ff4 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -217,7 +217,7 @@ module Puma @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 @@ module Puma 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 @@ module Puma 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 @@ module Puma # 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 @@ module Puma 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 @@ module Puma # 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 @@ module Puma 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 @@ 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) + @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 @@ module Puma 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 @@ module Puma @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 @@ module Puma 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 @@ module Puma 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 b34a6216..58bc96f9 100644 --- a/test/test_debug_logger.rb +++ b/test/test_debug_logger.rb @@ -5,14 +5,6 @@ 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!#!, debug_logger.ioerr.string - end - end - def test_stdio debug_logger = Puma::DebugLogger.stdio @@ -21,7 +13,7 @@ class TestDebugLogger < Minitest::Test 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 @@ class TestDebugLogger < Minitest::Test 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 @@ class TestDebugLogger < Minitest::Test 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!#!, err @@ -54,17 +46,17 @@ class TestDebugLogger < Minitest::Test } _, 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