From b625767440c4ad15c973a7ad23466322919cd12e Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Mon, 4 May 2020 21:30:18 +0300 Subject: [PATCH] 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 00000000..52e69f7d --- /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 b255f261..32786a79 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 @@ 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 diff --git a/lib/puma/server.rb b/lib/puma/server.rb index a467e237..d59dd8a8 100644 --- a/lib/puma/server.rb +++ b/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 diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb new file mode 100644 index 00000000..62d05661 --- /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!#!, 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!#!, 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