diff --git a/lib/puma/error_logger.rb b/lib/puma/error_logger.rb new file mode 100644 index 0000000000..e9f2ad6478 --- /dev/null +++ b/lib/puma/error_logger.rb @@ -0,0 +1,96 @@ +# frozen_string_literal: true + +require 'puma/const' + +module Puma + # The implementation of a detailed error logging. + # + class ErrorLogger + include Const + + attr_reader :ioerr + + REQUEST_FORMAT = %{"%s %s%s" - (%s)} + + def initialize(ioerr) + @ioerr = ioerr + @ioerr.sync = true + + @debug = ENV.key? 'PUMA_DEBUG' + end + + def self.stdio + new $stderr + end + + # Print occured error details. + # +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 info(options={}) + ioerr.puts title(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 = options[:error] + req = options[:req] + + string_block = [] + string_block << title(options) + string_block << request_dump(req) if req + string_block << error_backtrace(options) if error + + ioerr.puts string_block.join("\n") + end + + def title(options={}) + text = options[:text] + req = options[:req] + error = options[:error] + + string_block = ["#{Time.now}"] + string_block << " #{text}" if text + string_block << " (#{request_title(req)})" if request_parsed?(req) + string_block << ": #{error.inspect}" if error + string_block.join('') + end + + def request_dump(req) + "Headers: #{request_headers(req)}\n" \ + "Body: #{req.body}" + end + + def request_title(req) + env = req.env + + REQUEST_FORMAT % [ + env[REQUEST_METHOD], + env[REQUEST_PATH] || env[PATH_INFO], + env[QUERY_STRING] || "", + env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR] || "-" + ] + end + + def request_headers(req) + headers = req.env.select { |key, _| key.start_with?('HTTP_') } + headers.map { |key, value| [key[5..-1], value] }.to_h.inspect + end + + def request_parsed?(req) + req && req.env[REQUEST_METHOD] + end + end +end diff --git a/lib/puma/events.rb b/lib/puma/events.rb index fac0c9f879..8c2323f73b 100644 --- a/lib/puma/events.rb +++ b/lib/puma/events.rb @@ -1,7 +1,7 @@ # frozen_string_literal: true -require 'puma/const' require "puma/null_io" +require 'puma/error_logger' require 'stringio' module Puma @@ -23,8 +23,6 @@ def call(str) end end - include Const - # Create an Events object that prints to +stdout+ and +stderr+. # def initialize(stdout, stderr) @@ -36,6 +34,7 @@ def initialize(stdout, stderr) @stderr.sync = true @debug = ENV.key? 'PUMA_DEBUG' + @error_logger = ErrorLogger.new(@stderr) @hooks = Hash.new { |h,k| h[k] = [] } end @@ -80,7 +79,7 @@ def debug(str) # Write +str+ to +@stderr+ # def error(str) - @stderr.puts format("ERROR: #{str}") + @error_logger.info(text: format("ERROR: #{str}")) exit 1 end @@ -88,42 +87,45 @@ def format(str) formatter.call(str) end + # An HTTP connection error has occurred. + # +error+ a connection exception, +req+ the request, + # and +text+ additional info + # + def connection_error(error, req, text="HTTP connection error") + @error_logger.info(error: error, req: req, text: text) + end + # An HTTP parse error has occurred. - # +server+ is the Server object, +env+ the request, and +error+ a - # parsing exception. + # +error+ a parsing exception, + # and +req+ the request. # - 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}" + def parse_error(error, req) + @error_logger.info(error: error, req: req, text: 'HTTP parse error, malformed request') end # An SSL error has occurred. - # +server+ is the Server object, +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(server, peeraddr, peercert, error) + def ssl_error(error, peeraddr, peercert) subject = peercert ? peercert.subject : nil - @stderr.puts "#{Time.now}: SSL error, peer: #{peeraddr}, peer cert: #{subject}, #{error.inspect}" + @error_logger.info(error: error, text: "SSL error, peer: #{peeraddr}, peer cert: #{subject}") end # An unknown error has occurred. - # +server+ is the Server object, +error+ an exception object, - # +kind+ some additional info, and +env+ the request. + # +error+ an exception object, +req+ the request, + # and +text+ additional info # - def unknown_error(server, error, kind="Unknown", env=nil) - 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") - end + 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/reactor.rb b/lib/puma/reactor.rb index 7a4fce5cad..780903d296 100644 --- a/lib/puma/reactor.rb +++ b/lib/puma/reactor.rb @@ -252,7 +252,7 @@ def run_internal c.close clear_monitor mon - @events.ssl_error @server, addr, cert, e + @events.ssl_error e, addr, cert # The client doesn't know HTTP well rescue HttpParserError => e @@ -263,7 +263,7 @@ def run_internal clear_monitor mon - @events.parse_error @server, c.env, e + @events.parse_error e, c rescue StandardError => e @server.lowlevel_error(e, c.env) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 8ec2a5b16f..0ef5aa55dc 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -207,14 +207,16 @@ def run(background=true) client.close - @events.ssl_error self, addr, cert, e + @events.ssl_error e, addr, cert rescue HttpParserError => e client.write_error(400) client.close - @events.parse_error self, client.env, e - rescue ConnectionError, EOFError + @events.parse_error e, client + rescue ConnectionError, EOFError => e client.close + + @events.connection_error e, client else if process_now process_client client, buffer @@ -300,7 +302,7 @@ def handle_servers end end rescue Object => e - @events.unknown_error self, e, "Listen loop" + @events.unknown_error e, nil, "Listen loop" end end @@ -313,8 +315,7 @@ def handle_servers end graceful_shutdown if @status == :stop || @status == :restart rescue Exception => e - STDERR.puts "Exception handling servers: #{e.message} (#{e.class})" - STDERR.puts e.backtrace + @events.unknown_error e, nil, "Exception handling servers" ensure @check.close unless @check.closed? # Ruby 2.2 issue @notify.close @@ -406,7 +407,7 @@ def process_client(client, buffer) close_socket = true - @events.ssl_error self, addr, cert, e + @events.ssl_error e, addr, cert # The client doesn't know HTTP well rescue HttpParserError => e @@ -414,7 +415,7 @@ def process_client(client, buffer) client.write_error(400) - @events.parse_error self, client.env, e + @events.parse_error e, client # Server error rescue StandardError => e @@ -422,8 +423,7 @@ def process_client(client, buffer) client.write_error(500) - @events.unknown_error self, e, "Read" - + @events.unknown_error e, nil, "Read" ensure buffer.reset @@ -433,7 +433,7 @@ def process_client(client, buffer) Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue # Already closed rescue StandardError => e - @events.unknown_error self, e, "Client" + @events.unknown_error e, nil, "Client" end end end @@ -558,7 +558,8 @@ def handle_request(req, lines) end fast_write client, "\r\n".freeze - rescue ConnectionError + rescue ConnectionError => e + @events.debug_error e # noop, if we lost the socket we just won't send the early hints end } @@ -616,12 +617,12 @@ def handle_request(req, lines) return :async end rescue ThreadPool::ForceShutdown => e - @events.unknown_error self, e, "Rack app", env + @events.unknown_error e, req, "Rack app" @events.log "Detected force shutdown of a thread" status, headers, res_body = lowlevel_error(e, env, 503) rescue Exception => e - @events.unknown_error self, e, "Rack app", env + @events.unknown_error e, req, "Rack app" status, headers, res_body = lowlevel_error(e, env, 500) end diff --git a/test/test_error_logger.rb b/test/test_error_logger.rb new file mode 100644 index 0000000000..1ca19ec20e --- /dev/null +++ b/test/test_error_logger.rb @@ -0,0 +1,70 @@ +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!\("GET /debug" - \(8\.8\.8\.8\)\)!, 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 a749362330..0a1003d74b 100644 --- a/test/test_events.rb +++ b/test/test_events.rb @@ -1,3 +1,4 @@ +require 'puma/events' require_relative "helper" class TestEvents < Minitest::Test @@ -119,14 +120,16 @@ def test_error_writes_to_stderr_and_exits 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 @@ -175,7 +178,8 @@ def test_parse_error 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!\("GET #{path}" - \(-\)\)!, events.stderr.string server.stop(true) end end diff --git a/test/test_puma_server_ssl.rb b/test/test_puma_server_ssl.rb index bdd017dd15..584ab44f5c 100644 --- a/test/test_puma_server_ssl.rb +++ b/test/test_puma_server_ssl.rb @@ -11,10 +11,10 @@ class SSLEventsHelper < ::Puma::Events attr_accessor :addr, :cert, :error - def ssl_error(server, peeraddr, peercert, error) + def ssl_error(error, peeraddr, peercert) + self.error = error self.addr = peeraddr self.cert = peercert - self.error = error end end