From 4ecd9359a87cd97fe81d51881468766fa49e671d Mon Sep 17 00:00:00 2001 From: Christian Bruckmayer Date: Mon, 9 Mar 2020 19:29:34 +0000 Subject: [PATCH 01/66] Log binding on http:// for TCP bindings to make it clickable Fix https://github.com/puma/puma/issues/2166 --- History.md | 1 + lib/puma/binder.rb | 2 +- test/test_binder.rb | 8 ++++---- 3 files changed, 6 insertions(+), 5 deletions(-) diff --git a/History.md b/History.md index 2555344d..95c7cd98 100644 --- a/History.md +++ b/History.md @@ -10,6 +10,7 @@ * Changed #connected_port to #connected_ports (#2076) * `--control` has been removed. Use `--control-url` (#1487) * `worker_directory` has been removed. Use `directory` + * Log binding on http:// for TCP bindings to make it clickable * Bugfixes * Windows update extconf.rb for use with ssp and varied Ruby/MSYS2 combinations (#2069) diff --git a/lib/puma/binder.rb b/lib/puma/binder.rb index 6749d16a..78d97f52 100644 --- a/lib/puma/binder.rb +++ b/lib/puma/binder.rb @@ -115,7 +115,7 @@ module Puma i.local_address.ip_unpack.join(':') end - logger.log "* #{log_msg} on tcp://#{addr}" + logger.log "* #{log_msg} on http://#{addr}" end end diff --git a/test/test_binder.rb b/test/test_binder.rb index 02e4c2e7..60da1dfa 100644 --- a/test/test_binder.rb +++ b/test/test_binder.rb @@ -64,7 +64,7 @@ class TestBinder < TestBinderBase def test_correct_zero_port @binder.parse ["tcp://localhost:0"], @events - m = %r!tcp://127.0.0.1:(\d+)!.match(@events.stdout.string) + m = %r!http://127.0.0.1:(\d+)!.match(@events.stdout.string) port = m[1].to_i refute_equal 0, port @@ -84,9 +84,9 @@ class TestBinder < TestBinderBase def test_logs_all_localhost_bindings @binder.parse ["tcp://localhost:0"], @events - assert_match %r!tcp://127.0.0.1:(\d+)!, @events.stdout.string + assert_match %r!http://127.0.0.1:(\d+)!, @events.stdout.string if Socket.ip_address_list.any? {|i| i.ipv6_loopback? } - assert_match %r!tcp://\[::1\]:(\d+)!, @events.stdout.string + assert_match %r!http://\[::1\]:(\d+)!, @events.stdout.string end end @@ -271,7 +271,7 @@ class TestBinder < TestBinderBase prepared_paths = { ssl: "ssl://127.0.0.1:#{UniquePort.call}?#{ssl_query}", - tcp: "tcp://127.0.0.1:#{UniquePort.call}", + tcp: "http://127.0.0.1:#{UniquePort.call}", unix: "unix://test/#{name}_server.sock" } From b625767440c4ad15c973a7ad23466322919cd12e Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Mon, 4 May 2020 21:30:18 +0300 Subject: [PATCH 02/66] 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 From ec6bd0b1637dbb3d32a1fa9f1a9fd5eff24634db Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Mon, 4 May 2020 23:13:00 +0300 Subject: [PATCH 03/66] fix codestyle --- lib/puma/debug_logger.rb | 2 +- lib/puma/server.rb | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb index 52e69f7d..1284ed66 100644 --- a/lib/puma/debug_logger.rb +++ b/lib/puma/debug_logger.rb @@ -29,7 +29,7 @@ module Puma def error_dump(error, env=nil, options={}) return unless @debug || options[:force] - options[:print_title] = true unless options.keys.include?(:print_title) + options[:print_title] = true unless options.key?(:print_title) # # TODO: add all info we have about request diff --git a/lib/puma/server.rb b/lib/puma/server.rb index d59dd8a8..d46c8413 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -300,17 +300,17 @@ module Puma end rescue SystemCallError => e # TODO: check if we able to use client here - @debug_logger.error_dump(e, client&.env) + @debug_logger.error_dump(e) # nothing rescue Errno::ECONNABORTED # 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') + @debug_logger.error_dump(e, nil, custom_message: '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, client&.env) + @debug_logger.error_dump(e, nil) end end end From 25bceedda4cd7e82592abd0c089cde7a810ac34c Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sat, 9 May 2020 17:30:48 +0300 Subject: [PATCH 04/66] use only debug_logger instead of stderr in events --- lib/puma/debug_logger.rb | 19 +++++++------------ lib/puma/events.rb | 18 +++--------------- test/test_debug_logger.rb | 23 +++++++++++------------ test/test_events.rb | 3 ++- 4 files changed, 23 insertions(+), 40 deletions(-) diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb index 1284ed66..29a4ae6d 100644 --- a/lib/puma/debug_logger.rb +++ b/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 diff --git a/lib/puma/events.rb b/lib/puma/events.rb index 32786a79..0bdc5f81 100644 --- a/lib/puma/events.rb +++ b/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) diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb index 62d05661..b34a6216 100644 --- a/test/test_debug_logger.rb +++ b/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!#!, 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!#!, err + assert_match %r!Handling request { GET /debug } \(8\.8\.8\.8\)!, err end end diff --git a/test/test_events.rb b/test/test_events.rb index a7493623..a77f8715 100644 --- a/test/test_events.rb +++ b/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 From 4f632b9a52fef580b57a016f782e1a3638f7f957 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sat, 9 May 2020 17:50:29 +0300 Subject: [PATCH 05/66] remove logging where it is unnecessary --- lib/puma/server.rb | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index d46c8413..e9da2bcb 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -113,18 +113,16 @@ module Puma def cork_socket(socket) begin socket.setsockopt(6, 3, 1) if socket.kind_of? TCPSocket - rescue IOError, SystemCallError => e + rescue IOError, SystemCallError 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 => e + rescue IOError, SystemCallError Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue - @debug_logger.error_dump(e) end end From 607e24fe509c110043daf0c998843775e8b90f29 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sat, 9 May 2020 18:04:04 +0300 Subject: [PATCH 06/66] 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 From 49deca9093c7d455d38b60b181a3c67204ccdc03 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sat, 9 May 2020 19:03:32 +0300 Subject: [PATCH 07/66] unifying of events logging methods --- lib/puma/debug_logger.rb | 2 +- lib/puma/events.rb | 19 ++++++---- lib/puma/reactor.rb | 4 +-- lib/puma/server.rb | 67 +++++++++++++----------------------- test/test_puma_server_ssl.rb | 4 +-- 5 files changed, 42 insertions(+), 54 deletions(-) diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb index 1a74f706..fd74ddd7 100644 --- a/lib/puma/debug_logger.rb +++ b/lib/puma/debug_logger.rb @@ -42,7 +42,7 @@ module Puma string_block = [] formatted_text = " #{text}:" if text formatted_error = " #{error.inspect}" if error - string_block << "#{Time.now}#{text}#{error.inspect}" + string_block << "#{Time.now}#{formatted_text}#{formatted_error}" if env string_block << "Handling request { #{env[REQUEST_METHOD]} #{env[REQUEST_PATH] || env[PATH_INFO]} } (#{env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR]})" end diff --git a/lib/puma/events.rb b/lib/puma/events.rb index 040cb000..03a32ea5 100644 --- a/lib/puma/events.rb +++ b/lib/puma/events.rb @@ -87,28 +87,35 @@ module Puma formatter.call(str) end + # An HTTP connection error has occurred. + # +error+ a connection exception, +env+ the request + # + def connection_error(error, env, text="HTTP connection error") + @debug_logger.error_dump(error: error, env: env, text: text) + end + # An HTTP parse error has occurred. - # +server+ is the Server object, +env+ the request, and +error+ a + # +env+ the request, and +error+ a # parsing exception. # - def parse_error(server, env, error) + def parse_error(error, env) @debug_logger.error_dump(error: error, env: env, text: 'HTTP parse error, malformed request', force: true) end # An SSL error has occurred. - # +server+ is the Server object, +peeraddr+ peer address, +peercert+ + # +peeraddr+ peer address, +peercert+ # any peer certificate (if present), and +error+ an exception object. # - def ssl_error(server, peeraddr, peercert, error) + 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) end # An unknown error has occurred. - # +server+ is the Server object, +error+ an exception object, + # +error+ an exception object, # +kind+ some additional info, and +env+ the request. # - def unknown_error(server, error, kind="Unknown", env=nil) + def unknown_error(error, env=nil, kind="Unknown") @debug_logger.error_dump(error: error, env: env, text: kind, force: true) end diff --git a/lib/puma/reactor.rb b/lib/puma/reactor.rb index 7a4fce5c..37b91b08 100644 --- a/lib/puma/reactor.rb +++ b/lib/puma/reactor.rb @@ -252,7 +252,7 @@ module Puma 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 @@ module Puma clear_monitor mon - @events.parse_error @server, c.env, e + @events.parse_error e, c.env rescue StandardError => e @server.lowlevel_error(e, c.env) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index ff271ff4..985aa7ff 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -12,7 +12,6 @@ require 'puma/binder' require 'puma/accept_nonblock' require 'puma/util' require 'puma/io_buffer' -require 'puma/debug_logger' require 'puma/puma_http11' @@ -59,7 +58,6 @@ module Puma def initialize(app, events=Events.stdio, options={}) @app = app @events = events - @debug_logger = DebugLogger.stdio @check, @notify = Puma::Util.pipe @@ -210,15 +208,16 @@ module Puma 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 + @events.parse_error e, client.env rescue ConnectionError, EOFError => e - @debug_logger.error_dump(error: e, env: client.env) client.close + + @events.connection_error e, client.env else if process_now process_client client, buffer @@ -296,25 +295,20 @@ module Puma pool << client end - rescue SystemCallError => e - # TODO: check if we able to use client here - @debug_logger.error_dump(error: e) + rescue SystemCallError # nothing rescue Errno::ECONNABORTED - # TODO: check if we able to use client here - @debug_logger.error_dump(error: e, text: 'Client closed the socket even before accept') + # client closed the socket even before accept begin io.close - rescue => e + rescue 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(error: e) end end end end rescue Object => e - @events.unknown_error self, e, "Listen loop" + @events.unknown_error e, nil, "Listen loop" end end @@ -327,7 +321,7 @@ module Puma end graceful_shutdown if @status == :stop || @status == :restart rescue Exception => e - @debug_logger.error_dump(error: e, force: true, text: 'Exception handling servers') + @events.unknown_error e, nil, "Exception handling servers" ensure @check.close unless @check.closed? # Ruby 2.2 issue @notify.close @@ -404,8 +398,7 @@ module Puma end # The client disconnected while we were reading data - rescue ConnectionError => e - @debug_logger.error_dump(error: e, env: client.env, text: 'The client disconnected while we were reading data') + rescue ConnectionError # Swallow them. The ensure tries to close +client+ down # SSL handshake error @@ -418,7 +411,7 @@ module Puma 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 @@ -426,7 +419,7 @@ module Puma client.write_error(400) - @events.parse_error self, client.env, e + @events.parse_error e, client.env # Server error rescue StandardError => e @@ -434,19 +427,17 @@ module Puma client.write_error(500) - @events.unknown_error self, e, "Read" - + @events.unknown_error e, nil, "Read" ensure buffer.reset begin client.close if close_socket - rescue IOError, SystemCallError => e + rescue IOError, SystemCallError Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue - @debug_logger.error_dump(error: e, env: client.env) # Already closed rescue StandardError => e - @events.unknown_error self, e, "Client" + @events.unknown_error e, nil, "Client" end end end @@ -494,11 +485,10 @@ module Puma unless env.key?(REMOTE_ADDR) begin addr = client.peerip - rescue Errno::ENOTCONN => e + rescue Errno::ENOTCONN # Client disconnects can result in an inability to get the # peeraddr from the socket; default to localhost. addr = LOCALHOST_IP - @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 @@ -572,9 +562,8 @@ module Puma end fast_write client, "\r\n".freeze - rescue ConnectionError => e + rescue ConnectionError # noop, if we lost the socket we just won't send the early hints - @debug_logger.error_dump(error: e, env: env) end } end @@ -600,14 +589,12 @@ module Puma return :async end rescue ThreadPool::ForceShutdown => e - @events.unknown_error self, e, "Rack app", env + @events.unknown_error e, env, "Rack app" @events.log "Detected force shutdown of a thread" - @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(error: e, env: env) + @events.unknown_error e, env, "Rack app" status, headers, res_body = lowlevel_error(e, env, 500) end @@ -744,8 +731,7 @@ module Puma fast_write client, CLOSE_CHUNKED client.flush end - rescue SystemCallError, IOError => e - @debug_logger.error_dump(error: e, env: env) + rescue SystemCallError, IOError raise ConnectionError, "Connection error detected during write" end @@ -873,8 +859,7 @@ module Puma client = Client.new io, @binder.env(sock) @thread_pool << client end - rescue SystemCallError => e - @debug_logger.error_dump(error: e) + rescue SystemCallError end end end @@ -898,12 +883,10 @@ module Puma def notify_safely(message) begin @notify << message - rescue IOError => e + rescue IOError # 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(error: e) rescue RuntimeError => 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 @@ -936,15 +919,13 @@ module Puma while true begin n = io.syswrite str - rescue Errno::EAGAIN, Errno::EWOULDBLOCK => e - @debug_logger.error_dump(error: e) + rescue Errno::EAGAIN, Errno::EWOULDBLOCK 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(error: e) + rescue Errno::EPIPE, SystemCallError, IOError raise ConnectionError, "Socket timeout writing data" end diff --git a/test/test_puma_server_ssl.rb b/test/test_puma_server_ssl.rb index 26b54b15..b42d5a57 100644 --- a/test/test_puma_server_ssl.rb +++ b/test/test_puma_server_ssl.rb @@ -11,10 +11,10 @@ require "net/http" 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 From 067799405e0aade78fbaad37485d1e457025e8ec Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sat, 9 May 2020 19:11:44 +0300 Subject: [PATCH 08/66] add logging for fast_write ConnectionError --- lib/puma/server.rb | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 985aa7ff..80110e4d 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -562,7 +562,8 @@ module Puma end fast_write client, "\r\n".freeze - rescue ConnectionError + rescue ConnectionError => e + @events.connection_error e, client.env # noop, if we lost the socket we just won't send the early hints end } From c606471b5ae436a165ee2f083a35635c90a29b93 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sat, 9 May 2020 20:18:39 +0300 Subject: [PATCH 09/66] rubocop --- puma.gemspec | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/puma.gemspec b/puma.gemspec index 7e31d6c8..e323c45a 100644 --- a/puma.gemspec +++ b/puma.gemspec @@ -18,7 +18,7 @@ Gem::Specification.new do |s| s.files = `git ls-files -- bin docs ext lib tools`.split("\n") + %w[History.md LICENSE README.md] s.homepage = "http://puma.io" - + if s.respond_to?(:metadata=) s.metadata = { "bug_tracker_uri" => "https://github.com/puma/puma/issues", @@ -27,7 +27,7 @@ Gem::Specification.new do |s| "source_code_uri" => "https://github.com/puma/puma" } end - + s.license = "BSD-3-Clause" s.required_ruby_version = Gem::Requirement.new(">= 2.2") end From 265f638d2beb9ee60d1af5e5c03ae876b0c3e4d8 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sat, 9 May 2020 22:29:56 +0300 Subject: [PATCH 10/66] force log connection error --- lib/puma/events.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/puma/events.rb b/lib/puma/events.rb index 03a32ea5..c603da29 100644 --- a/lib/puma/events.rb +++ b/lib/puma/events.rb @@ -91,7 +91,7 @@ module Puma # +error+ a connection exception, +env+ the request # def connection_error(error, env, text="HTTP connection error") - @debug_logger.error_dump(error: error, env: env, text: text) + @debug_logger.error_dump(error: error, env: env, text: text, force: true) end # An HTTP parse error has occurred. From 2d7ff5da5007dcaf8321601e77166c1c3391f3b9 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sun, 10 May 2020 18:43:42 +0300 Subject: [PATCH 11/66] fix server swallow connection error --- lib/puma/events.rb | 2 +- lib/puma/server.rb | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/puma/events.rb b/lib/puma/events.rb index c603da29..03a32ea5 100644 --- a/lib/puma/events.rb +++ b/lib/puma/events.rb @@ -91,7 +91,7 @@ module Puma # +error+ a connection exception, +env+ the request # def connection_error(error, env, text="HTTP connection error") - @debug_logger.error_dump(error: error, env: env, text: text, force: true) + @debug_logger.error_dump(error: error, env: env, text: text) end # An HTTP parse error has occurred. diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 80110e4d..9273f196 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, client.env + @events.connection_error e, nil # noop, if we lost the socket we just won't send the early hints end } From f178dd52117f91a0d26472a7f763b6c05534a764 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sun, 10 May 2020 18:44:34 +0300 Subject: [PATCH 12/66] fix require in test_debug_logger --- test/test_debug_logger.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb index 58bc96f9..b6725041 100644 --- a/test/test_debug_logger.rb +++ b/test/test_debug_logger.rb @@ -1,3 +1,4 @@ +require 'puma/debug_logger' require_relative "helper" class TestDebugLogger < Minitest::Test From c3d82818411fc5677e1a5ed87a465b448da65c6d Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Mon, 11 May 2020 13:19:53 +0300 Subject: [PATCH 13/66] add body & headers to request log --- lib/puma/debug_logger.rb | 35 +++++++++++++++++++++++++++-------- lib/puma/events.rb | 18 +++++++++--------- lib/puma/reactor.rb | 2 +- lib/puma/server.rb | 10 +++++----- test/test_debug_logger.rb | 12 +++++++++--- test/test_events.rb | 3 ++- 6 files changed, 53 insertions(+), 27 deletions(-) diff --git a/lib/puma/debug_logger.rb b/lib/puma/debug_logger.rb index fd74ddd7..3d01e80e 100644 --- a/lib/puma/debug_logger.rb +++ b/lib/puma/debug_logger.rb @@ -10,6 +10,8 @@ module Puma attr_reader :ioerr + REQUEST_FORMAT = %{"%s %s%s" - (%s)} + def initialize(ioerr) @ioerr = ioerr @ioerr.sync = true @@ -25,31 +27,48 @@ module Puma # +options+ hash with additional options: # - +force+ (default nil) to log info even if debug mode is turned off # - +error+ is an exception object - # - +env+ the request + # - +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] - error = options[:error] - env = options[:env] - text = options[:text] - # - # TODO: add all info we have about request - # + 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 string_block << "#{Time.now}#{formatted_text}#{formatted_error}" + if env - string_block << "Handling request { #{env[REQUEST_METHOD]} #{env[REQUEST_PATH] || env[PATH_INFO]} } (#{env[HTTP_X_FORWARDED_FOR] || env[REMOTE_ADDR]})" + string_block << "Handling request { #{request_title(env)} }" + string_block << "Headers: #{request_headers(env)}" + string_block << "Body: #{req.body}" end string_block << error.backtrace if error ioerr.puts string_block.join("\n") end + + private + + def request_title(env) + request_line = 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(env) + headers = env.select { |key, _| key.start_with?('HTTP_') } + headers.map { |key, value| [key[5..-1], value] }.to_h.inspect + end end end diff --git a/lib/puma/events.rb b/lib/puma/events.rb index 03a32ea5..18da74a0 100644 --- a/lib/puma/events.rb +++ b/lib/puma/events.rb @@ -88,18 +88,18 @@ module Puma end # An HTTP connection error has occurred. - # +error+ a connection exception, +env+ the request + # +error+ a connection exception, +req+ the request # - def connection_error(error, env, text="HTTP connection error") - @debug_logger.error_dump(error: error, env: env, text: text) + def connection_error(error, req, text="HTTP connection error") + @debug_logger.error_dump(error: error, req: req, text: text) end # An HTTP parse error has occurred. - # +env+ the request, and +error+ a + # +req+ the request, and +error+ a # parsing exception. # - def parse_error(error, env) - @debug_logger.error_dump(error: error, env: env, text: 'HTTP parse error, malformed request', force: true) + def parse_error(error, req) + @debug_logger.error_dump(error: error, req: req, text: 'HTTP parse error, malformed request', force: true) end # An SSL error has occurred. @@ -113,10 +113,10 @@ module Puma # An unknown error has occurred. # +error+ an exception object, - # +kind+ some additional info, and +env+ the request. + # +kind+ some additional info, and +req+ the request. # - def unknown_error(error, env=nil, kind="Unknown") - @debug_logger.error_dump(error: error, env: env, text: kind, force: true) + def unknown_error(error, req=nil, kind="Unknown") + @debug_logger.error_dump(error: error, req: req, text: kind, force: true) end def on_booted(&block) diff --git a/lib/puma/reactor.rb b/lib/puma/reactor.rb index 37b91b08..780903d2 100644 --- a/lib/puma/reactor.rb +++ b/lib/puma/reactor.rb @@ -263,7 +263,7 @@ module Puma clear_monitor mon - @events.parse_error e, c.env + @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 9273f196..9278b172 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -213,11 +213,11 @@ module Puma client.write_error(400) client.close - @events.parse_error e, client.env + @events.parse_error e, client rescue ConnectionError, EOFError => e client.close - @events.connection_error e, client.env + @events.connection_error e, client else if process_now process_client client, buffer @@ -419,7 +419,7 @@ module Puma client.write_error(400) - @events.parse_error e, client.env + @events.parse_error e, client # Server error rescue StandardError => e @@ -590,12 +590,12 @@ module Puma return :async end rescue ThreadPool::ForceShutdown => e - @events.unknown_error e, env, "Rack app" + @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 e, env, "Rack app" + @events.unknown_error e, req, "Rack app" status, headers, res_body = lowlevel_error(e, env, 500) end diff --git a/test/test_debug_logger.rb b/test/test_debug_logger.rb index b6725041..b01d2eca 100644 --- a/test/test_debug_logger.rb +++ b/test/test_debug_logger.rb @@ -2,6 +2,8 @@ require 'puma/debug_logger' require_relative "helper" class TestDebugLogger < Minitest::Test + Req = Struct.new(:env, :body) + def setup @debug_logger = Puma::DebugLogger.stdio end @@ -38,19 +40,23 @@ class TestDebugLogger < Minitest::Test end end - def test_error_dump_with_env + 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, env: env) + 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!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 diff --git a/test/test_events.rb b/test/test_events.rb index a77f8715..06afd695 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 @@ -176,7 +177,7 @@ class TestEvents < Minitest::Test sock.read sleep 0.1 # important so that the previous data is sent as a packet assert_match %r!HTTP parse error, malformed request!, events.stderr.string - assert_match %r!Handling request { GET #{path} }!, events.stderr.string + assert_match %r!Handling request { "GET #{path}" - \(-\) }!, events.stderr.string server.stop(true) end end From 0bcd428863319ce30f95a28f784160d518d8f57a Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Mon, 11 May 2020 16:56:54 +0300 Subject: [PATCH 14/66] rename debug_logger to error_logger; add levels; fix tests --- lib/puma/{debug_logger.rb => error_logger.rb} | 34 +++++--- lib/puma/events.rb | 39 +++++---- lib/puma/server.rb | 2 +- test/test_debug_logger.rb | 81 ------------------- test/test_error_logger.rb | 72 +++++++++++++++++ test/test_events.rb | 14 ++-- 6 files changed, 129 insertions(+), 113 deletions(-) rename lib/puma/{debug_logger.rb => error_logger.rb} (70%) delete mode 100644 test/test_debug_logger.rb create mode 100644 test/test_error_logger.rb 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 From e1e3134f8830fd7274ac9d6e8e7c349b03787c3b Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Thu, 14 May 2020 23:17:41 -0500 Subject: [PATCH 15/66] test_redirect_io.rb - fix teardown for skipped tests stops: warning: instance variable @old_err_file_path not initialized warning: instance variable @old_out_file_path not initialized --- test/test_redirect_io.rb | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/test/test_redirect_io.rb b/test/test_redirect_io.rb index 7600aa16..8a811922 100644 --- a/test/test_redirect_io.rb +++ b/test/test_redirect_io.rb @@ -17,7 +17,9 @@ class TestRedirectIO < TestIntegration def teardown super - paths = [@out_file_path, @err_file_path, @old_out_file_path, @old_err_file_path].compact + paths = (skipped? ? [@out_file_path, @err_file_path] : + [@out_file_path, @err_file_path, @old_out_file_path, @old_err_file_path]).compact + File.unlink(*paths) @out_file = nil @err_file = nil From d7f8df569dcbbaf60664463f3d56b11a55cc4d90 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Fri, 15 May 2020 10:45:06 -0500 Subject: [PATCH 16/66] test_binder.rb - add teardown to close sockets --- test/test_binder.rb | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/test/test_binder.rb b/test/test_binder.rb index 56eea2b8..344cd395 100644 --- a/test/test_binder.rb +++ b/test/test_binder.rb @@ -15,6 +15,13 @@ class TestBinderBase < Minitest::Test @binder = Puma::Binder.new(@events) end + def teardown + @binder.ios.reject! { |io| Minitest::Mock === io || io.to_io.closed? } + @binder.close + @binder.unix_paths.select! { |path| File.exist? path } + @binder.close_listeners + end + private def ssl_context_for_binder(binder = @binder) From 4297d794fffc8ab126ad7928bac9ef75defa4d82 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Fri, 15 May 2020 12:00:42 -0500 Subject: [PATCH 17/66] test_integration_single.rb - minor fixes test_term_not_accepts_new_connections - check correct pid, typo --- test/test_integration_single.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_integration_single.rb b/test/test_integration_single.rb index 35801c53..ce8158b7 100644 --- a/test/test_integration_single.rb +++ b/test/test_integration_single.rb @@ -70,7 +70,7 @@ class TestIntegrationSingle < TestIntegration _stdin, _stdout, rejected_curl_stderr, rejected_curl_wait_thread = Open3.popen3("curl #{HOST}:#{@tcp_port}") assert nil != Process.getpgid(@server.pid) # ensure server is still running - assert nil != Process.getpgid(rejected_curl_wait_thread[:pid]) # ensure first curl invokation still in progress + assert nil != Process.getpgid(curl_wait_thread[:pid]) # ensure first curl invocation still in progress curl_wait_thread.join rejected_curl_wait_thread.join From 2d9b72ecc1e5ae214a964b7d6b692f1740c584a3 Mon Sep 17 00:00:00 2001 From: Will Jordan Date: Fri, 15 May 2020 10:27:37 -0700 Subject: [PATCH 18/66] Fix for spawning subprocesses with fork_worker option --- lib/puma/cluster.rb | 9 ++++++--- test/test_integration_cluster.rb | 14 ++++++++++++++ 2 files changed, 20 insertions(+), 3 deletions(-) diff --git a/lib/puma/cluster.rb b/lib/puma/cluster.rb index 861b231a..4ffe0cc4 100644 --- a/lib/puma/cluster.rb +++ b/lib/puma/cluster.rb @@ -248,6 +248,7 @@ module Puma $0 = title Signal.trap "SIGINT", "IGNORE" + Signal.trap "SIGCHLD", "DEFAULT" fork_worker = @options[:fork_worker] && index == 0 @@ -284,9 +285,11 @@ module Puma if fork_worker restart_server.clear + worker_pids = [] Signal.trap "SIGCHLD" do - Process.wait(-1, Process::WNOHANG) rescue nil - wakeup! + wakeup! if worker_pids.reject! do |p| + Process.wait(p, Process::WNOHANG) rescue true + end end Thread.new do @@ -303,7 +306,7 @@ module Puma elsif idx == 0 # restart server restart_server << true << false else # fork worker - pid = spawn_worker(idx, master) + worker_pids << pid = spawn_worker(idx, master) @worker_write << "f#{pid}:#{idx}\n" rescue nil end end diff --git a/test/test_integration_cluster.rb b/test/test_integration_cluster.rb index 6c041505..524cd4ae 100644 --- a/test/test_integration_cluster.rb +++ b/test/test_integration_cluster.rb @@ -168,6 +168,20 @@ RUBY refute_includes pids, get_worker_pids(1, WORKERS - 1) end + def test_fork_worker_spawn + cli_server '', config: <'/dev/null') + sleep 0.01 + exitstatus = Process.detach(pid).value.exitstatus + [200, {}, [exitstatus.to_s]] +end +RUBY + assert_equal '0', read_body(connect) + end + def test_nakayoshi cli_server "-w #{WORKERS} test/rackup/hello.ru", config: < Date: Fri, 15 May 2020 14:03:31 -0400 Subject: [PATCH 19/66] Fix example for on_worker_boot --- lib/puma/dsl.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/puma/dsl.rb b/lib/puma/dsl.rb index c11b130c..3821656e 100644 --- a/lib/puma/dsl.rb +++ b/lib/puma/dsl.rb @@ -443,8 +443,8 @@ module Puma # # @note Cluster mode only. # @example - # on_worker_fork do - # puts 'Before worker fork...' + # on_worker_boot do + # puts 'Before worker boot...' # end def on_worker_boot(&block) @options[:before_worker_boot] ||= [] From aa0d83c786f58725fc9c03594fd8dc465e336558 Mon Sep 17 00:00:00 2001 From: Will Jordan Date: Fri, 15 May 2020 11:30:21 -0700 Subject: [PATCH 20/66] Update History.md --- History.md | 1 + 1 file changed, 1 insertion(+) diff --git a/History.md b/History.md index e34abaa3..387b4d56 100644 --- a/History.md +++ b/History.md @@ -45,6 +45,7 @@ * Fix `UserFileDefaultOptions#fetch` to properly use `default` (#2233) * Improvements to `out_of_band` hook (#2234) * Prefer the rackup file specified by the CLI (#2225) + * Fix for spawning subprocesses with fork_worker option (#2267) * Refactor * Remove unused loader argument from Plugin initializer (#2095) From 3cc1fb7d5c6f528b2c6e1e2c5d934ef84ba9c481 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Fri, 15 May 2020 16:49:35 -0500 Subject: [PATCH 21/66] test_thread_pool.rb - small JRuby fix test_shutdown_with_grace - JRuby - rescued array may contain threads that have been GC'd, and hence are nil? --- test/test_thread_pool.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_thread_pool.rb b/test/test_thread_pool.rb index edb753fa..697f5c46 100644 --- a/test/test_thread_pool.rb +++ b/test/test_thread_pool.rb @@ -264,6 +264,6 @@ class TestThreadPool < Minitest::Test end assert_equal 0, pool.spawned assert_equal 2, rescued.length - refute rescued.any?(&:alive?) + refute rescued.compact.any?(&:alive?) end end From 556c4b238b1b1f5222d253a706116cbc5a22fd14 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sun, 17 May 2020 16:24:48 +0300 Subject: [PATCH 22/66] single-line info logs --- lib/puma/error_logger.rb | 48 +++++++++++++++++++++------------------ test/test_error_logger.rb | 2 +- test/test_events.rb | 2 +- 3 files changed, 28 insertions(+), 24 deletions(-) diff --git a/lib/puma/error_logger.rb b/lib/puma/error_logger.rb index 97695141..b6b7b7ba 100644 --- a/lib/puma/error_logger.rb +++ b/lib/puma/error_logger.rb @@ -31,7 +31,7 @@ module Puma # and before all remaining info. # def info(options={}) - error_dump(options) + ioerr.puts title(options) end # Print occured error details only if @@ -44,34 +44,38 @@ module Puma # 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 - string_block << "#{Time.now}#{formatted_text}#{formatted_error}" - - if env - string_block << "Handling request { #{request_title(env)} }" - string_block << "Headers: #{request_headers(env)}" - string_block << "Body: #{req.body}" - end - - string_block << error.backtrace if error + 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 request_title(env) + 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 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], @@ -80,8 +84,8 @@ module Puma ] end - def request_headers(env) - headers = env.select { |key, _| key.start_with?('HTTP_') } + 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 end diff --git a/test/test_error_logger.rb b/test/test_error_logger.rb index f95eef33..34bea39d 100644 --- a/test/test_error_logger.rb +++ b/test/test_error_logger.rb @@ -30,7 +30,7 @@ class TestErrorLogger < Minitest::Test 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!\("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 diff --git a/test/test_events.rb b/test/test_events.rb index dc8459b5..0a1003d7 100644 --- a/test/test_events.rb +++ b/test/test_events.rb @@ -179,7 +179,7 @@ class TestEvents < Minitest::Test sock.read sleep 0.1 # important so that the previous data is sent as a packet assert_match %r!HTTP parse error, malformed request!, events.stderr.string - assert_match %r!Handling request { "GET #{path}" - \(-\) }!, events.stderr.string + assert_match %r!\("GET #{path}" - \(-\)\)!, events.stderr.string server.stop(true) end end From e3e61f24203e2bb85959964d7918f1988370dbe7 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sun, 17 May 2020 16:51:30 +0300 Subject: [PATCH 23/66] hotfix --- test/test_error_logger.rb | 2 -- 1 file changed, 2 deletions(-) diff --git a/test/test_error_logger.rb b/test/test_error_logger.rb index 34bea39d..1ca19ec2 100644 --- a/test/test_error_logger.rb +++ b/test/test_error_logger.rb @@ -31,8 +31,6 @@ class TestErrorLogger < Minitest::Test end assert_match %r!\("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 From 42bac4d8c7e4c858e4667c07ff5653baa3b1b9dc Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Tue, 19 May 2020 06:27:19 +0900 Subject: [PATCH 24/66] beta1 fix: nakayoshi_fork should default true when called --- lib/puma/dsl.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/puma/dsl.rb b/lib/puma/dsl.rb index c11b130c..c4da0ead 100644 --- a/lib/puma/dsl.rb +++ b/lib/puma/dsl.rb @@ -769,7 +769,7 @@ module Puma # also increase time to boot and fork. See your logs for details on how much # time this adds to your boot process. For most apps, it will be less than one # second. - def nakayoshi_fork(enabled=false) + def nakayoshi_fork(enabled=true) @options[:nakayoshi_fork] = enabled end end From 28c11b081b6c02ac60323be7d2bfde2971e77694 Mon Sep 17 00:00:00 2001 From: Will Jordan Date: Tue, 19 May 2020 10:43:15 -0700 Subject: [PATCH 25/66] Timeout unit tests on teardown Prevents hanging runner if teardown hangs after test. --- test/helper.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/helper.rb b/test/helper.rb index eda616b8..47240707 100644 --- a/test/helper.rb +++ b/test/helper.rb @@ -58,7 +58,7 @@ module TimeoutEveryTestCase class TestTookTooLong < Timeout::Error end - def run(*) + def capture_exceptions(*) ::Timeout.timeout(RUBY_ENGINE == 'ruby' ? 60 : 120, TestTookTooLong) { super } end end From 55a9864eaf8607911241875377cdbce8bb9fcf34 Mon Sep 17 00:00:00 2001 From: Will Jordan Date: Tue, 19 May 2020 11:32:02 -0700 Subject: [PATCH 26/66] Fix errors on test_halt_unix Prevent `IOError: closed stream` by stopping control during halt. Add test assertion to ensure no errors in stderr output. --- lib/puma/launcher.rb | 3 ++- lib/puma/runner.rb | 2 +- test/test_integration_pumactl.rb | 7 +++++-- 3 files changed, 8 insertions(+), 4 deletions(-) diff --git a/lib/puma/launcher.rb b/lib/puma/launcher.rb index 0c4e1dd3..b506ec70 100644 --- a/lib/puma/launcher.rb +++ b/lib/puma/launcher.rb @@ -172,12 +172,13 @@ module Puma case @status when :halt log "* Stopping immediately!" + @runner.stop_control when :run, :stop graceful_stop when :restart log "* Restarting..." ENV.replace(previous_env) - @runner.before_restart + @runner.stop_control restart! when :exit # nothing diff --git a/lib/puma/runner.rb b/lib/puma/runner.rb index 4695aa98..4a9a9c2a 100644 --- a/lib/puma/runner.rb +++ b/lib/puma/runner.rb @@ -30,7 +30,7 @@ module Puma @events.log str end - def before_restart + def stop_control @control.stop(true) if @control end diff --git a/test/test_integration_pumactl.rb b/test/test_integration_pumactl.rb index 6237bb1c..98557570 100644 --- a/test/test_integration_pumactl.rb +++ b/test/test_integration_pumactl.rb @@ -42,13 +42,16 @@ class TestIntegrationPumactl < TestIntegration def ctl_unix(signal='stop') skip UNIX_SKT_MSG unless UNIX_SKT_EXIST - cli_server "-q test/rackup/sleep.ru --control-url unix://#{@control_path} --control-token #{TOKEN} -S #{@state_path}", unix: true + stderr = Tempfile.new(%w(stderr .log)) + cli_server "-q test/rackup/sleep.ru --control-url unix://#{@control_path} --control-token #{TOKEN} -S #{@state_path}", + config: "stdout_redirect nil, '#{stderr.path}'", + unix: true cli_pumactl signal, unix: true _, status = Process.wait2(@pid) assert_equal 0, status - + refute_match 'error', File.read(stderr.path) @server = nil end From ce33a7bb52578e3cfea7379fa811a3fac452baaf Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Fri, 22 May 2020 06:19:02 +0900 Subject: [PATCH 27/66] Update History with 4.3.4/4.3.5/3.12.5/3.12.6. https://github.com/puma/puma/security/advisories/GHSA-x7jg-6pwg-fx5h https://github.com/puma/puma/security/advisories/GHSA-w64w-qqph-5gxm --- History.md | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/History.md b/History.md index 387b4d56..6f066bbd 100644 --- a/History.md +++ b/History.md @@ -57,6 +57,13 @@ * JSON parse cluster worker stats instead of regex (#2124) * Support parallel tests in verbose progress reporting (#2223) * Refactor error handling in server accept loop (#2239) + +## 4.3.4/4.3.5 and 3.12.5/3.12.6 / 2020-05-22 + +Each patchlevel release contains a separate security fix. We recommend simply upgrading to 4.3.5/3.12.6. + +* Security + * Fix: Fixed two separate HTTP smuggling vulnerabilities that used the Transfer-Encoding header. CVE-2020-11076 and CVE-2020-11077. ## 4.3.3 and 3.12.4 / 2020-02-28 From eeff5668869b2349f38d50fecfa3c809159e5d5c Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Mon, 18 May 2020 16:01:53 -0700 Subject: [PATCH 28/66] Better handle client input --- lib/puma/client.rb | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/lib/puma/client.rb b/lib/puma/client.rb index 324947b4..affae352 100644 --- a/lib/puma/client.rb +++ b/lib/puma/client.rb @@ -308,8 +308,16 @@ module Puma te = @env[TRANSFER_ENCODING2] - if te && CHUNKED.casecmp(te) == 0 - return setup_chunked_body(body) + if te + if te.include?(",") + te.split(",").each do |part| + if CHUNKED.casecmp(part.strip) == 0 + return setup_chunked_body(body) + end + end + elsif CHUNKED.casecmp(te) == 0 + return setup_chunked_body(body) + end end @chunked_body = false From ad8197e4d6e4fc9b11545f455387ff4739f24fdf Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Tue, 19 May 2020 15:20:10 -0700 Subject: [PATCH 29/66] Reduce ambiguity of headers --- ext/puma_http11/http11_parser.c | 4 +++- ext/puma_http11/http11_parser.rl | 4 +++- lib/puma/server.rb | 31 +++++++++++++++++++++++++++++++ 3 files changed, 37 insertions(+), 2 deletions(-) diff --git a/ext/puma_http11/http11_parser.c b/ext/puma_http11/http11_parser.c index 0b5fdabc..bf1dd89a 100644 --- a/ext/puma_http11/http11_parser.c +++ b/ext/puma_http11/http11_parser.c @@ -14,12 +14,14 @@ /* * capitalizes all lower-case ASCII characters, - * converts dashes to underscores. + * converts dashes to underscores, and underscores to commas. */ static void snake_upcase_char(char *c) { if (*c >= 'a' && *c <= 'z') *c &= ~0x20; + else if (*c == '_') + *c = ','; else if (*c == '-') *c = '_'; } diff --git a/ext/puma_http11/http11_parser.rl b/ext/puma_http11/http11_parser.rl index 880c1d40..62452ba7 100644 --- a/ext/puma_http11/http11_parser.rl +++ b/ext/puma_http11/http11_parser.rl @@ -12,12 +12,14 @@ /* * capitalizes all lower-case ASCII characters, - * converts dashes to underscores. + * converts dashes to underscores, and underscores to commas. */ static void snake_upcase_char(char *c) { if (*c >= 'a' && *c <= 'z') *c &= ~0x20; + else if (*c == '_') + *c = ','; else if (*c == '-') *c = '_'; } diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 70095577..19a279c6 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -564,6 +564,37 @@ module Puma } end + # Fixup any headers with , in the name to have _ now. We emit + # headers with , in them during the parse phase to avoid ambiguity + # with the - to _ conversion for critical headers. But here for + # compatibility, we'll convert them back. This code is written to + # avoid allocation in the common case (ie there are no headers + # with , in their names), that's why it has the extra conditionals. + + to_delete = nil + to_add = nil + + env.each do |k,v| + if k.start_with?("HTTP_") and k.include?(",") and k != "HTTP_TRANSFER,ENCODING" + if to_delete + to_delete << k + else + to_delete = [k] + end + + unless to_add + to_add = {} + end + + to_add[k.gsub(",", "_")] = v + end + end + + if to_delete + to_delete.each { |k| env.delete(k) } + env.merge! to_add + end + # A rack extension. If the app writes #call'ables to this # array, we will invoke them when the request is done. # From 2f1dfbcc142dbe3d2defc80cdc309dcb3a165bfd Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Tue, 19 May 2020 15:34:06 -0700 Subject: [PATCH 30/66] Adjust test to match real world value --- test/test_puma_server.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index 25252574..2d498ac2 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -153,7 +153,7 @@ class TestPumaServer < Minitest::Test req = Net::HTTP::Get.new("/") req['HOST'] = "example.com" - req['X_FORWARDED_PROTO'] = "https,http" + req['X-FORWARDED-PROTO'] = "https,http" port = @server.connected_ports[0] res = Net::HTTP.start @host, port do |http| From f71018f665f97b4c876a1548f1ffd43a042fb928 Mon Sep 17 00:00:00 2001 From: Yoann Lecuyer Date: Sat, 23 May 2020 19:27:51 +0200 Subject: [PATCH 31/66] Minor: Add running_from to state_file --- lib/puma/launcher.rb | 1 + lib/puma/state_file.rb | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/puma/launcher.rb b/lib/puma/launcher.rb index b506ec70..90646b7a 100644 --- a/lib/puma/launcher.rb +++ b/lib/puma/launcher.rb @@ -111,6 +111,7 @@ module Puma sf.pid = Process.pid sf.control_url = @options[:control_url] sf.control_auth_token = @options[:control_auth_token] + sf.running_from = File.expand_path('.') sf.save path, permission end diff --git a/lib/puma/state_file.rb b/lib/puma/state_file.rb index 6aa8fad4..9ea74a8c 100644 --- a/lib/puma/state_file.rb +++ b/lib/puma/state_file.rb @@ -19,7 +19,7 @@ module Puma @options = YAML.load File.read(path) end - FIELDS = %w!control_url control_auth_token pid! + FIELDS = %w!control_url control_auth_token pid running_from! FIELDS.each do |f| define_method f do From 24235fdeb5e0005cf639f883fa78b89cf0acca55 Mon Sep 17 00:00:00 2001 From: Yoann Lecuyer Date: Sat, 23 May 2020 20:59:44 +0200 Subject: [PATCH 32/66] Fix: Rubocop offence introduced in ad8197e --- lib/puma/server.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 19a279c6..8ec2a5b1 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -586,7 +586,7 @@ module Puma to_add = {} end - to_add[k.gsub(",", "_")] = v + to_add[k.tr(",", "_")] = v end end From bdcfb6011782be3a52e11733e2da31968edb1f11 Mon Sep 17 00:00:00 2001 From: Eugene Kenny Date: Fri, 29 May 2020 01:35:10 +0100 Subject: [PATCH 33/66] Set CONTENT_LENGTH for chunked requests Chunked requests don't contain a Content-Length header, but Puma buffers the entire request body upfront, which means it can determine the length before dispatching to the application. The Rack spec doesn't mandate the presence of the CONTENT_LENGTH header, but it does refer to it as a "CGI key" and draws a distinction between it and the HTTP Content-Length header: https://github.com/rack/rack/blob/v2.2.2/SPEC.rdoc > The environment must not contain the keys HTTP_CONTENT_TYPE or > HTTP_CONTENT_LENGTH (use the versions without HTTP_). The CGI keys > (named without a period) must have String values. RFC 3875, which defines the CGI protocol including CONTENT_LENGTH, says: https://tools.ietf.org/html/rfc3875#section-4.1.2 > The server MUST set this meta-variable if and only if the request is > accompanied by a message-body entity. The CONTENT_LENGTH value must > reflect the length of the message-body after the server has removed > any transfer-codings or content-codings. "Removing a transfer-coding" is precisely what Puma is doing when it parses a chunked request. RFC 7230, the most recent specification of HTTP 1.1, includes a pseudo- code algorithm for decoding chunked requests that roughly matches the behaviour implemented here: https://tools.ietf.org/html/rfc7230#section-4.1.3 --- History.md | 1 + lib/puma/client.rb | 25 +++++++++++++++++------- test/test_puma_server.rb | 41 ++++++++++++++++++++++++++++++++++++++++ 3 files changed, 60 insertions(+), 7 deletions(-) diff --git a/History.md b/History.md index 6f066bbd..517fb05d 100644 --- a/History.md +++ b/History.md @@ -46,6 +46,7 @@ * Improvements to `out_of_band` hook (#2234) * Prefer the rackup file specified by the CLI (#2225) * Fix for spawning subprocesses with fork_worker option (#2267) + * Set `CONTENT_LENGTH` for chunked requests (#2287) * Refactor * Remove unused loader argument from Plugin initializer (#2095) diff --git a/lib/puma/client.rb b/lib/puma/client.rb index affae352..f49bba61 100644 --- a/lib/puma/client.rb +++ b/lib/puma/client.rb @@ -420,7 +420,10 @@ module Puma raise EOFError end - return true if decode_chunk(chunk) + if decode_chunk(chunk) + @env[CONTENT_LENGTH] = @chunked_content_length + return true + end end end @@ -432,20 +435,28 @@ module Puma @body = Tempfile.new(Const::PUMA_TMP_BASE) @body.binmode @tempfile = @body + @chunked_content_length = 0 - return decode_chunk(body) + if decode_chunk(body) + @env[CONTENT_LENGTH] = @chunked_content_length + return true + end + end + + def write_chunk(str) + @chunked_content_length += @body.write(str) end def decode_chunk(chunk) if @partial_part_left > 0 if @partial_part_left <= chunk.size if @partial_part_left > 2 - @body << chunk[0..(@partial_part_left-3)] # skip the \r\n + write_chunk(chunk[0..(@partial_part_left-3)]) # skip the \r\n end chunk = chunk[@partial_part_left..-1] @partial_part_left = 0 else - @body << chunk if @partial_part_left > 2 # don't include the last \r\n + write_chunk(chunk) if @partial_part_left > 2 # don't include the last \r\n @partial_part_left -= chunk.size return false end @@ -492,12 +503,12 @@ module Puma case when got == len - @body << part[0..-3] # to skip the ending \r\n + write_chunk(part[0..-3]) # to skip the ending \r\n when got <= len - 2 - @body << part + write_chunk(part) @partial_part_left = len - part.size when got == len - 1 # edge where we get just \r but not \n - @body << part[0..-2] + write_chunk(part[0..-2]) @partial_part_left = len - part.size end else diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index 2d498ac2..58cd2f9b 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -498,8 +498,10 @@ EOF def test_chunked_request body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -507,12 +509,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal "hello", body + assert_equal 5, content_length end def test_chunked_request_pause_before_value body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -525,12 +530,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal "hello", body + assert_equal 5, content_length end def test_chunked_request_pause_between_chunks body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -543,12 +551,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal "hello", body + assert_equal 5, content_length end def test_chunked_request_pause_mid_count body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -561,12 +572,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal "hello", body + assert_equal 5, content_length end def test_chunked_request_pause_before_count_newline body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -579,12 +593,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal "hello", body + assert_equal 5, content_length end def test_chunked_request_pause_mid_value body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -597,12 +614,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal "hello", body + assert_equal 5, content_length end def test_chunked_request_pause_between_cr_lf_after_size_of_second_chunk body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -624,12 +644,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal (part1 + 'b'), body + assert_equal 4201, content_length end def test_chunked_request_pause_between_closing_cr_lf body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -643,12 +666,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal 'hello', body + assert_equal 5, content_length end def test_chunked_request_pause_before_closing_cr_lf body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -662,12 +688,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal 'hello', body + assert_equal 5, content_length end def test_chunked_request_header_case body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -675,12 +704,15 @@ EOF assert_equal "HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Length: 0\r\n\r\n", data assert_equal "hello", body + assert_equal 5, content_length end def test_chunked_keep_alive body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -690,14 +722,17 @@ EOF assert_equal ["HTTP/1.1 200 OK", "Content-Length: 0"], h assert_equal "hello", body + assert_equal 5, content_length sock.close end def test_chunked_keep_alive_two_back_to_back body = nil + content_length = nil server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] [200, {}, [""]] } @@ -715,6 +750,7 @@ EOF h = header(sock) assert_equal ["HTTP/1.1 200 OK", "Content-Length: 0"], h assert_equal "hello", body + assert_equal 5, content_length assert_equal true, last_crlf_written last_crlf_writer.join @@ -726,16 +762,19 @@ EOF assert_equal ["HTTP/1.1 200 OK", "Content-Length: 0"], h assert_equal "goodbye", body + assert_equal 7, content_length sock.close end def test_chunked_keep_alive_two_back_to_back_with_set_remote_address body = nil + content_length = nil remote_addr =nil @server = Puma::Server.new @app, @events, { remote_address: :header, remote_address_header: 'HTTP_X_FORWARDED_FOR'} server_run app: ->(env) { body = env['rack.input'].read + content_length = env['CONTENT_LENGTH'] remote_addr = env['REMOTE_ADDR'] [200, {}, [""]] } @@ -745,6 +784,7 @@ EOF h = header sock assert_equal ["HTTP/1.1 200 OK", "Content-Length: 0"], h assert_equal "hello", body + assert_equal 5, content_length assert_equal "127.0.0.1", remote_addr sock << "GET / HTTP/1.1\r\nX-Forwarded-For: 127.0.0.2\r\nConnection: Keep-Alive\r\nTransfer-Encoding: chunked\r\n\r\n4\r\ngood\r\n3\r\nbye\r\n0\r\n\r\n" @@ -754,6 +794,7 @@ EOF assert_equal ["HTTP/1.1 200 OK", "Content-Length: 0"], h assert_equal "goodbye", body + assert_equal 7, content_length assert_equal "127.0.0.2", remote_addr sock.close From 47f933d076c57d5c2500360b09e55630c5c4a3e2 Mon Sep 17 00:00:00 2001 From: Frank Lam Date: Mon, 1 Jun 2020 15:17:46 +0800 Subject: [PATCH 34/66] Resolve rack.multithread/rack.multiprocess using config --- lib/puma/binder.rb | 17 ++++++++++++++--- lib/puma/launcher.rb | 2 +- test/test_binder.rb | 29 +++++++++++++++++++++++++++++ 3 files changed, 44 insertions(+), 4 deletions(-) diff --git a/lib/puma/binder.rb b/lib/puma/binder.rb index 7759c85b..252e5564 100644 --- a/lib/puma/binder.rb +++ b/lib/puma/binder.rb @@ -6,6 +6,7 @@ require 'socket' require 'puma/const' require 'puma/util' require 'puma/minissl/context_builder' +require 'puma/configuration' module Puma class Binder @@ -13,18 +14,19 @@ module Puma RACK_VERSION = [1,6].freeze - def initialize(events) + def initialize(events, conf = Configuration.new) @events = events @listeners = [] @inherited_fds = {} @activated_sockets = {} @unix_paths = [] + @conf = conf @proto_env = { "rack.version".freeze => RACK_VERSION, "rack.errors".freeze => events.stderr, - "rack.multithread".freeze => true, - "rack.multiprocess".freeze => false, + "rack.multithread".freeze => resolve_option(:multithread, @conf), + "rack.multiprocess".freeze => resolve_option(:multiprocess, @conf), "rack.run_once".freeze => false, "SCRIPT_NAME".freeze => ENV['SCRIPT_NAME'] || "", @@ -383,5 +385,14 @@ module Puma def socket_activation_fd(int) int + 3 # 3 is the magic number you add to follow the SA protocol end + + def resolve_option(key, conf) + case key + when :multithread + conf.options[:max_threads] > 1 + when :multiprocess + conf.options[:workers] >= 1 + end + end end end diff --git a/lib/puma/launcher.rb b/lib/puma/launcher.rb index 90646b7a..3ec065aa 100644 --- a/lib/puma/launcher.rb +++ b/lib/puma/launcher.rb @@ -47,7 +47,7 @@ module Puma @original_argv = @argv.dup @config = conf - @binder = Binder.new(@events) + @binder = Binder.new(@events, conf) @binder.create_inherited_fds(ENV).each { |k| ENV.delete k } @binder.create_activated_fds(ENV).each { |k| ENV.delete k } diff --git a/test/test_binder.rb b/test/test_binder.rb index 344cd395..9c5bf848 100644 --- a/test/test_binder.rb +++ b/test/test_binder.rb @@ -6,6 +6,7 @@ require_relative "helpers/ssl" require "puma/binder" require "puma/puma_http11" require "puma/events" +require "puma/configuration" class TestBinderBase < Minitest::Test include SSLHelper @@ -295,6 +296,34 @@ class TestBinder < TestBinderBase File.unlink(path) rescue nil # JRuby race? end + def test_rack_multithread_default_configuration + binder = Puma::Binder.new(@events) + + assert binder.proto_env["rack.multithread"] + end + + def test_rack_multithread_custom_configuration + conf = Puma::Configuration.new(max_threads: 1) + + binder = Puma::Binder.new(@events, conf) + + refute binder.proto_env["rack.multithread"] + end + + def test_rack_multiprocess_default_configuration + binder = Puma::Binder.new(@events) + + refute binder.proto_env["rack.multiprocess"] + end + + def test_rack_multiprocess_custom_configuration + conf = Puma::Configuration.new(workers: 1) + + binder = Puma::Binder.new(@events, conf) + + assert binder.proto_env["rack.multiprocess"] + end + private def assert_activates_sockets(path: nil, port: nil, url: nil, sock: nil) From e9e38e46066a90c857e13decd3982fb934ba9241 Mon Sep 17 00:00:00 2001 From: Frank Lam Date: Mon, 1 Jun 2020 15:26:42 +0800 Subject: [PATCH 35/66] Add feature entry to history for rack.multithread/rack.multiprocess --- History.md | 1 + 1 file changed, 1 insertion(+) diff --git a/History.md b/History.md index 517fb05d..2bbc15c3 100644 --- a/History.md +++ b/History.md @@ -11,6 +11,7 @@ * Faster phased restart and worker timeout (#2220) * Added `state_permission` to config DSL to set state file permissions (#2238) * Added `Puma.stats_hash`, which returns a stats in Hash instead of a JSON string (#2086, #2253) + * `rack.multithread` and `rack.multiprocess` now dynamically resolved by `max_thread` and `workers` respectively (#2288) * Deprecations, Removals and Breaking API Changes * `--control` has been removed. Use `--control-url` (#1487) From 321b3fb951a18290ee3f5a20973f4611a4b20892 Mon Sep 17 00:00:00 2001 From: Frank Lam Date: Tue, 2 Jun 2020 09:53:08 +0800 Subject: [PATCH 36/66] Inline resolving of multithread/multiprocess --- lib/puma/binder.rb | 14 ++------------ 1 file changed, 2 insertions(+), 12 deletions(-) diff --git a/lib/puma/binder.rb b/lib/puma/binder.rb index 252e5564..3f1b5719 100644 --- a/lib/puma/binder.rb +++ b/lib/puma/binder.rb @@ -20,13 +20,12 @@ module Puma @inherited_fds = {} @activated_sockets = {} @unix_paths = [] - @conf = conf @proto_env = { "rack.version".freeze => RACK_VERSION, "rack.errors".freeze => events.stderr, - "rack.multithread".freeze => resolve_option(:multithread, @conf), - "rack.multiprocess".freeze => resolve_option(:multiprocess, @conf), + "rack.multithread".freeze => conf.options[:max_threads] > 1, + "rack.multiprocess".freeze => conf.options[:workers] >= 1, "rack.run_once".freeze => false, "SCRIPT_NAME".freeze => ENV['SCRIPT_NAME'] || "", @@ -385,14 +384,5 @@ module Puma def socket_activation_fd(int) int + 3 # 3 is the magic number you add to follow the SA protocol end - - def resolve_option(key, conf) - case key - when :multithread - conf.options[:max_threads] > 1 - when :multiprocess - conf.options[:workers] >= 1 - end - end end end From d45ea9471a7c04204f8aeb27b7b9270f7facfea6 Mon Sep 17 00:00:00 2001 From: Benoit Daloze Date: Wed, 6 May 2020 00:47:36 +0200 Subject: [PATCH 37/66] Run CI using the default version of Bundler * Which is Bundler on Ruby 2.2 and Bundler 2 on Ruby 2.3+. --- .github/workflows/puma.yml | 1 - 1 file changed, 1 deletion(-) diff --git a/.github/workflows/puma.yml b/.github/workflows/puma.yml index fe5132c8..a31ce3bf 100644 --- a/.github/workflows/puma.yml +++ b/.github/workflows/puma.yml @@ -37,7 +37,6 @@ jobs: uses: MSP-Greg/setup-ruby-pkgs@v1 with: ruby-version: ${{ matrix.ruby }} - bundler: 1 apt-get: ragel brew: ragel mingw: _upgrade_ openssl ragel From 12fea1fc5ada6683ebb1c5efccc341c15435f1eb Mon Sep 17 00:00:00 2001 From: Benoit Daloze Date: Sat, 6 Jun 2020 13:02:53 +0200 Subject: [PATCH 38/66] Do not set the --path for bundle install * This is buggy with Ruby 2.3 + Bundler 2.1.4, see https://github.com/ruby/setup-ruby/issues/51 --- .github/workflows/puma.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/puma.yml b/.github/workflows/puma.yml index a31ce3bf..4e534023 100644 --- a/.github/workflows/puma.yml +++ b/.github/workflows/puma.yml @@ -48,7 +48,7 @@ jobs: if ('${{ matrix.ruby }}' -lt '2.3') { gem update --system 2.7.10 --no-document } - bundle install --jobs 4 --retry 3 --path=.bundle/puma + bundle install --jobs 4 --retry 3 - name: compile run: bundle exec rake compile From 32ac93ab65622d24a01adb5dc9a87a6af6d45571 Mon Sep 17 00:00:00 2001 From: Mike Aleksiuk Date: Sat, 6 Jun 2020 15:27:38 -0700 Subject: [PATCH 39/66] Unskip two jruby ssl tests that were hanging. 1. Fix the conversion of a nil verify_mode to integer (was throwing 'no implicit conversion of nil into Integer') 2. Use the correct keystore password. 3. Use cipher suites that are supported in Java 8. --- ext/puma_http11/org/jruby/puma/MiniSSL.java | 2 +- test/helpers/ssl.rb | 4 ++-- test/test_binder.rb | 2 +- test/test_cli.rb | 1 - test/test_pumactl.rb | 1 - 5 files changed, 4 insertions(+), 6 deletions(-) diff --git a/ext/puma_http11/org/jruby/puma/MiniSSL.java b/ext/puma_http11/org/jruby/puma/MiniSSL.java index c8b92965..33b6d91a 100644 --- a/ext/puma_http11/org/jruby/puma/MiniSSL.java +++ b/ext/puma_http11/org/jruby/puma/MiniSSL.java @@ -173,7 +173,7 @@ public class MiniSSL extends RubyObject { engine.setEnabledProtocols(protocols); engine.setUseClientMode(false); - long verify_mode = miniSSLContext.callMethod(threadContext, "verify_mode").convertToInteger().getLongValue(); + long verify_mode = miniSSLContext.callMethod(threadContext, "verify_mode").convertToInteger("to_i").getLongValue(); if ((verify_mode & 0x1) != 0) { // 'peer' engine.setWantClientAuth(true); } diff --git a/test/helpers/ssl.rb b/test/helpers/ssl.rb index e9e7b24e..cfa5fec4 100644 --- a/test/helpers/ssl.rb +++ b/test/helpers/ssl.rb @@ -2,8 +2,8 @@ module SSLHelper def ssl_query @ssl_query ||= if Puma.jruby? @keystore = File.expand_path "../../../examples/puma/keystore.jks", __FILE__ - @ssl_cipher_list = "TLS_DHE_RSA_WITH_DES_CBC_SHA,TLS_DHE_RSA_WITH_3DES_EDE_CBC_SHA" - "keystore=#{@keystore}&keystore-pass=pswd&ssl_cipher_list=#{@ssl_cipher_list}" + @ssl_cipher_list = "TLS_DHE_RSA_WITH_AES_128_CBC_SHA,TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256" + "keystore=#{@keystore}&keystore-pass=blahblah&ssl_cipher_list=#{@ssl_cipher_list}" else @cert = File.expand_path "../../../examples/puma/cert_puma.pem", __FILE__ @key = File.expand_path "../../../examples/puma/puma_keypair.pem", __FILE__ diff --git a/test/test_binder.rb b/test/test_binder.rb index 9c5bf848..8341c586 100644 --- a/test/test_binder.rb +++ b/test/test_binder.rb @@ -367,7 +367,7 @@ end class TestBinderJRuby < TestBinderBase def test_binder_parses_jruby_ssl_options keystore = File.expand_path "../../examples/puma/keystore.jks", __FILE__ - ssl_cipher_list = "TLS_DHE_RSA_WITH_DES_CBC_SHA,TLS_DHE_RSA_WITH_3DES_EDE_CBC_SHA" + ssl_cipher_list = "TLS_DHE_RSA_WITH_AES_128_CBC_SHA,TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256" @binder.parse ["ssl://0.0.0.0:8080?#{ssl_query}"], @events diff --git a/test/test_cli.rb b/test/test_cli.rb index 22597f06..a2c39a55 100644 --- a/test/test_cli.rb +++ b/test/test_cli.rb @@ -66,7 +66,6 @@ class TestCLI < Minitest::Test end def test_control_for_ssl - skip_on :jruby # Hangs on CI, TODO fix require "net/http" control_port = UniquePort.call control_host = "127.0.0.1" diff --git a/test/test_pumactl.rb b/test/test_pumactl.rb index 27d4d392..96bafa28 100644 --- a/test/test_pumactl.rb +++ b/test/test_pumactl.rb @@ -150,7 +150,6 @@ class TestPumaControlCli < TestConfigFileBase end def test_control_ssl - skip_on :jruby # Hanging on JRuby, TODO fix host = "127.0.0.1" port = UniquePort.call url = "ssl://#{host}:#{port}?#{ssl_query}" From 1b0dd560fa38a12590b6905a2a05502adadb5620 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sun, 7 Jun 2020 15:58:47 +0300 Subject: [PATCH 40/66] fix error_logger comment --- lib/puma/error_logger.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/puma/error_logger.rb b/lib/puma/error_logger.rb index b6b7b7ba..91ff1bbc 100644 --- a/lib/puma/error_logger.rb +++ b/lib/puma/error_logger.rb @@ -3,7 +3,7 @@ require 'puma/const' module Puma - # The implementation of a logging in debug mode. + # The implementation of a detailed error logging. # class ErrorLogger include Const From 2bbdbd2a2b8c9833cc96fa6013c582d20f5bfa4e Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Sun, 7 Jun 2020 16:34:33 +0300 Subject: [PATCH 41/66] fix request logging --- lib/puma/error_logger.rb | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/lib/puma/error_logger.rb b/lib/puma/error_logger.rb index 91ff1bbc..e9f2ad64 100644 --- a/lib/puma/error_logger.rb +++ b/lib/puma/error_logger.rb @@ -63,7 +63,7 @@ module Puma string_block = ["#{Time.now}"] string_block << " #{text}" if text - string_block << " (#{request_title(req)})" if req + string_block << " (#{request_title(req)})" if request_parsed?(req) string_block << ": #{error.inspect}" if error string_block.join('') end @@ -88,5 +88,9 @@ module Puma 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 From 111874d8b57ed8772981d46091eb02e2e81344de Mon Sep 17 00:00:00 2001 From: Adam Markowitz Date: Fri, 1 Sep 2017 12:31:47 -0700 Subject: [PATCH 42/66] resolve waiting counter problem if a thread is in the wait state, but transitions into a killed state the waiting counter will not be decremented leaving the pool to believe there is a thread available and waiting to complete work when that is not the case. Introduce a begin..ensure block so that any thread exception raised while in the wait state properly balances the waiting counter. --- lib/puma/thread_pool.rb | 7 +++++-- test/test_thread_pool.rb | 20 ++++++++++++++++++++ 2 files changed, 25 insertions(+), 2 deletions(-) diff --git a/lib/puma/thread_pool.rb b/lib/puma/thread_pool.rb index c0bbedb1..bb6a73c7 100644 --- a/lib/puma/thread_pool.rb +++ b/lib/puma/thread_pool.rb @@ -122,8 +122,11 @@ module Puma @out_of_band_pending = false end not_full.signal - not_empty.wait mutex - @waiting -= 1 + begin + not_empty.wait mutex + ensure + @waiting -= 1 + end end work = todo.shift diff --git a/test/test_thread_pool.rb b/test/test_thread_pool.rb index 697f5c46..ccc07ae0 100644 --- a/test/test_thread_pool.rb +++ b/test/test_thread_pool.rb @@ -266,4 +266,24 @@ class TestThreadPool < Minitest::Test assert_equal 2, rescued.length refute rescued.compact.any?(&:alive?) end + + def test_correct_waiting_count_for_killed_threads + pool = new_pool(1, 1) { |_| } + + pause + + # simulate our waiting worker thread getting killed for whatever reason + pool.instance_eval { @workers[0].kill } + + pause + + pool.reap + + pause + + pool << 0 + + pause + assert_equal 0, pool.backlog + end end From 7f095b4445eabe70e2f4ae806b30ce7e26a20402 Mon Sep 17 00:00:00 2001 From: "John W. Phillips" Date: Wed, 10 Jun 2020 23:24:34 +0000 Subject: [PATCH 43/66] Resolve waiting counter issue --- History.md | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/History.md b/History.md index 6f066bbd..72752d6d 100644 --- a/History.md +++ b/History.md @@ -1,3 +1,7 @@ +### Master +* Bugfixes + * Resolve issue with threadpool waiting counter decrement when thread is killed + ## 5.0.0 * Features From 7dfd9fba25c61d37e17be4bb7935fd38aff11793 Mon Sep 17 00:00:00 2001 From: "John W. Phillips" Date: Wed, 10 Jun 2020 23:25:24 +0000 Subject: [PATCH 44/66] Update syntax of unit test. --- test/test_thread_pool.rb | 13 ++++--------- 1 file changed, 4 insertions(+), 9 deletions(-) diff --git a/test/test_thread_pool.rb b/test/test_thread_pool.rb index ccc07ae0..0e6f7645 100644 --- a/test/test_thread_pool.rb +++ b/test/test_thread_pool.rb @@ -269,21 +269,16 @@ class TestThreadPool < Minitest::Test def test_correct_waiting_count_for_killed_threads pool = new_pool(1, 1) { |_| } - - pause + sleep 1 # simulate our waiting worker thread getting killed for whatever reason pool.instance_eval { @workers[0].kill } - - pause - + sleep 1 pool.reap - - pause + sleep 1 pool << 0 - - pause + sleep 1 assert_equal 0, pool.backlog end end From eff4691b287240aeb4b8fed13d9453e24c58e979 Mon Sep 17 00:00:00 2001 From: Vyacheslav Alexeev Date: Tue, 30 Jun 2020 22:08:16 +0300 Subject: [PATCH 45/66] fix assert_parsing_logs_uri --- test/test_binder.rb | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/test/test_binder.rb b/test/test_binder.rb index a2c20898..2ca8f9e8 100644 --- a/test/test_binder.rb +++ b/test/test_binder.rb @@ -347,17 +347,21 @@ class TestBinder < TestBinderBase prepared_paths = { ssl: "ssl://127.0.0.1:#{UniquePort.call}?#{ssl_query}", - tcp: "http://127.0.0.1:#{UniquePort.call}", + tcp: "tcp://127.0.0.1:#{UniquePort.call}", unix: "unix://test/#{name}_server.sock" } + expected_logs = prepared_paths.dup.tap do |logs| + logs[:tcp] = logs[:tcp].gsub('tcp://', 'http://') + end + tested_paths = [prepared_paths[order[0]], prepared_paths[order[1]]] @binder.parse tested_paths, @events stdout = @events.stdout.string order.each do |prot| - assert_match prepared_paths[prot], stdout + assert_match expected_logs[prot], stdout end ensure @binder.close_listeners if order.include?(:unix) && UNIX_SKT_EXIST From a0de09505567b5ed1020f9bfb99b5924ea13a167 Mon Sep 17 00:00:00 2001 From: Utkarsh Gupta Date: Wed, 8 Jul 2020 23:10:22 +0530 Subject: [PATCH 46/66] Constrain rake-compiler version to 0.9.4 Fixes: #2301 Signed-off-by: Utkarsh Gupta --- Gemfile | 2 +- History.md | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/Gemfile b/Gemfile index 053d2cb0..521d91d8 100644 --- a/Gemfile +++ b/Gemfile @@ -3,7 +3,7 @@ source "https://rubygems.org" gemspec gem "rdoc" -gem "rake-compiler" +gem "rake-compiler", "~> 0.9.4" gem "nio4r", "~> 2.0" gem "rack", "~> 1.6" diff --git a/History.md b/History.md index 7a8ed7d6..991d7186 100644 --- a/History.md +++ b/History.md @@ -1,6 +1,7 @@ ### Master * Bugfixes * Resolve issue with threadpool waiting counter decrement when thread is killed + * Constrain rake-compiler version to 0.9.4 to fix `ClassNotFound` exception when using MiniSSL with Java8. ## 5.0.0 From 01669133187fcc48428ea4985991e99de77a21b3 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Sun, 19 Jul 2020 17:06:10 -0500 Subject: [PATCH 47/66] CI fixes - lib/puma/events.rb, lib/puma/server.rb --- lib/puma/events.rb | 3 ++- lib/puma/server.rb | 9 +++++++-- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/lib/puma/events.rb b/lib/puma/events.rb index 8c2323f7..c746c9d1 100644 --- a/lib/puma/events.rb +++ b/lib/puma/events.rb @@ -65,7 +65,8 @@ module Puma # Write +str+ to +@stdout+ # def log(str) - @stdout.puts format(str) + @stdout.puts format(str) if @stdout.respond_to? :puts + rescue Errno::EPIPE end def write(str) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 0ef5aa55..2ba99f52 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -317,7 +317,12 @@ module Puma rescue Exception => e @events.unknown_error e, nil, "Exception handling servers" ensure - @check.close unless @check.closed? # Ruby 2.2 issue + begin + @check.close unless @check.closed? + rescue Errno::EBADF, RuntimeError + # RuntimeError is Ruby 2.2 issue, can't modify frozen IOError + # Errno::EBADF is infrequently raised + end @notify.close @notify = nil @check = nil @@ -912,7 +917,7 @@ module Puma @check, @notify = Puma::Util.pipe unless @notify begin @notify << message - rescue IOError + rescue IOError, NoMethodError, Errno::EPIPE # The server, in another thread, is shutting down Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue rescue RuntimeError => e From 1f40ce031e7df67af4d43f37e295204e824e9b29 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Sun, 19 Jul 2020 17:07:06 -0500 Subject: [PATCH 48/66] CI fixes - test/helper.rb, test/test_integration.rb helper.rb Previous code used #capture_exceptions to add a timeout to every test. That method is called once for set methods and the test method, and once for the teardown methods. New code uses #time_it, which wraps all the methods in one timeout thread. test_integration.rb Add another error to UnixSocket tests. --- test/helper.rb | 7 +++++-- test/test_integration_cluster.rb | 2 +- 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/test/helper.rb b/test/helper.rb index 47240707..fa5cd20c 100644 --- a/test/helper.rb +++ b/test/helper.rb @@ -58,8 +58,11 @@ module TimeoutEveryTestCase class TestTookTooLong < Timeout::Error end - def capture_exceptions(*) - ::Timeout.timeout(RUBY_ENGINE == 'ruby' ? 60 : 120, TestTookTooLong) { super } + def time_it + t0 = Minitest.clock_time + ::Timeout.timeout(RUBY_ENGINE == 'ruby' ? 60 : 120, TestTookTooLong) { yield } + ensure + self.time = Minitest.clock_time - t0 end end diff --git a/test/test_integration_cluster.rb b/test/test_integration_cluster.rb index 524cd4ae..f409443c 100644 --- a/test/test_integration_cluster.rb +++ b/test/test_integration_cluster.rb @@ -387,7 +387,7 @@ RUBY # used with thread_run to define correct 'refused' errors def thread_run_refused(unix: false) if unix - DARWIN ? [Errno::ENOENT, IOError] : [Errno::ENOENT] + [Errno::ENOENT, IOError] else DARWIN ? [Errno::ECONNREFUSED, Errno::EPIPE, EOFError] : [Errno::ECONNREFUSED] From 4abe18b1f5c5e295f3591cf53c939638a82c5bcc Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Sun, 19 Jul 2020 19:32:33 -0500 Subject: [PATCH 49/66] Update History.md --- History.md | 1 + 1 file changed, 1 insertion(+) diff --git a/History.md b/History.md index 991d7186..28570e64 100644 --- a/History.md +++ b/History.md @@ -33,6 +33,7 @@ * Log binding on http:// for TCP bindings to make it clickable * Bugfixes + * Improve shutdown reliability (#2312) * Close client http connections made to an ssl server with TLSv1.3 (#2116) * Do not set user_config to quiet by default to allow for file config (#2074) * Always close SSL connection in Puma::ControlCLI (#2211) From 8ae0fbb00e8de89046c5f58177d4563df18c8329 Mon Sep 17 00:00:00 2001 From: Sai Ram Kunala Date: Mon, 20 Jul 2020 16:50:21 +0530 Subject: [PATCH 50/66] fix syntax for haproxy X-Request-Start configuration source: https://stackoverflow.com/questions/31036893/how-do-i-add-x-request-start-in-haproxy/50060498#50060498 --- docs/deployment.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/docs/deployment.md b/docs/deployment.md index c237f930..bb12eb8c 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -66,7 +66,8 @@ thread to become available. * Have your upstream proxy set a header with the time it received the request: * nginx: `proxy_set_header X-Request-Start "${msec}";` - * haproxy: `http-request set-header X-Request-Start "%t";` + * haproxy >= 1.9: `http-request set-header X-Request-Start t=%[date()]%[date_us()]` + * haproxy < 1.9: `http-request set-header X-Request-Start t=%[date()]` * In your Rack middleware, determine the amount of time elapsed since `X-Request-Start`. * To improve accuracy, you will want to subtract time spent waiting for slow clients: * `env['puma.request_body_wait']` contains the number of milliseconds Puma spent From c76172a9e50cde083e9bd2012bd19019a1a87040 Mon Sep 17 00:00:00 2001 From: MSP-Greg Date: Tue, 21 Jul 2020 11:53:34 -0500 Subject: [PATCH 51/66] test_cli.rb - fix bind port (9292 port in use errors) --- test/test_cli.rb | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/test/test_cli.rb b/test/test_cli.rb index a2c39a55..fa5a98f9 100644 --- a/test/test_cli.rb +++ b/test/test_cli.rb @@ -40,7 +40,8 @@ class TestCLI < Minitest::Test cntl = UniquePort.call url = "tcp://127.0.0.1:#{cntl}/" - cli = Puma::CLI.new [ "--control-url", url, + cli = Puma::CLI.new ["-b", "tcp://127.0.0.1:0", + "--control-url", url, "--control-token", "", "test/rackup/lobster.ru"], @events @@ -72,7 +73,8 @@ class TestCLI < Minitest::Test control_url = "ssl://#{control_host}:#{control_port}?#{ssl_query}" token = "token" - cli = Puma::CLI.new ["--control-url", control_url, + cli = Puma::CLI.new ["-b", "tcp://127.0.0.1:0", + "--control-url", control_url, "--control-token", token, "test/rackup/lobster.ru"], @events From 3e45bddfbeb1603faa88f4b6eb61ad9fe3526036 Mon Sep 17 00:00:00 2001 From: Elena Tanasoiu Date: Tue, 28 Jul 2020 18:59:43 +0100 Subject: [PATCH 52/66] Clarify how to run puma in single mode When starting to transition from Unicorn to Puma, I first tried out puma in development. I initially assumed from skimming the docs that the number of workers for single mode should be 1. This led to our developers not being able to kill their puma server properly in our dev environment via Ctrl+C since the master process would stick around and try to revive it. Upon reading the docs more carefully and checking out the issues, I found [I wasn't alone][issue-on-single-mode]. While it's obvious that 1 worker implies the existence of a master process, when you're just starting out it might take you a little while before you get your head around single mode versus cluster mode and having the configuration clearly stated helps with that imo. So to make it blatantly obvious how to run puma in single mode, I've added a line to the docs to explain it. [issue-on-single-mode]: https://github.com/puma/puma/issues/1364 --- docs/deployment.md | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/docs/deployment.md b/docs/deployment.md index bb12eb8c..29d1b4a2 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -20,7 +20,10 @@ Welcome back! Puma was originally conceived as a thread-only webserver, but grew the ability to also use processes in version 2. -Here are some rules of thumb: +To run puma in single mode (e.g. for a development environment) you will need to +set the number of workers to 0, anything above will run in cluster mode. + +Here are some rules of thumb for cluster mode: ### MRI From 2ffcf5609425c7f74f6861123556c49ee52ec7b9 Mon Sep 17 00:00:00 2001 From: Kapil Sachdev Date: Fri, 14 Aug 2020 00:20:07 +0530 Subject: [PATCH 53/66] fix: Update links to use TLS/SSL [ci skip] [changelog skip] --- README.md | 6 +++--- docs/architecture.md | 6 +++--- docs/signals.md | 8 ++++---- lib/puma/commonlogger.rb | 4 ++-- lib/puma/server.rb | 2 +- puma.gemspec | 4 ++-- 6 files changed, 15 insertions(+), 15 deletions(-) diff --git a/README.md b/README.md index acdbdc14..63bf299e 100644 --- a/README.md +++ b/README.md @@ -8,7 +8,7 @@ [![Code Climate](https://codeclimate.com/github/puma/puma.svg)](https://codeclimate.com/github/puma/puma) [![SemVer](https://api.dependabot.com/badges/compatibility_score?dependency-name=puma&package-manager=bundler&version-scheme=semver)](https://dependabot.com/compatibility-score.html?dependency-name=puma&package-manager=bundler&version-scheme=semver) -[![StackOverflow](http://img.shields.io/badge/stackoverflow-Puma-blue.svg)]( http://stackoverflow.com/questions/tagged/puma ) +[![StackOverflow](https://img.shields.io/badge/stackoverflow-Puma-blue.svg)]( https://stackoverflow.com/questions/tagged/puma ) Puma is a **simple, fast, multi-threaded, and highly concurrent HTTP 1.1 server for Ruby/Rack applications**. @@ -27,7 +27,7 @@ $ gem install puma $ puma ``` -Without arguments, puma will look for a rackup (.ru) file in +Without arguments, puma will look for a rackup (.ru) file in working directory called `config.ru`. ## Frameworks @@ -135,7 +135,7 @@ Preloading can’t be used with phased restart, since phased restart kills and r If puma encounters an error outside of the context of your application, it will respond with a 500 and a simple textual error message (see `lowlevel_error` in [this file](https://github.com/puma/puma/blob/master/lib/puma/server.rb)). You can specify custom behavior for this scenario. For example, you can report the error to your third-party -error-tracking service (in this example, [rollbar](http://rollbar.com)): +error-tracking service (in this example, [rollbar](https://rollbar.com)): ```ruby lowlevel_error_handler do |e| diff --git a/docs/architecture.md b/docs/architecture.md index 958c6a25..b5d6451f 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -2,7 +2,7 @@ ## Overview -![http://bit.ly/2iJuFky](images/puma-general-arch.png) +![https://bit.ly/2iJuFky](images/puma-general-arch.png) Puma is a threaded web server, processing requests across a TCP or UNIX socket. @@ -12,7 +12,7 @@ Clustered mode is shown/discussed here. Single mode is analogous to having a sin ## Connection pipeline -![http://bit.ly/2zwzhEK](images/puma-connection-flow.png) +![https://bit.ly/2zwzhEK](images/puma-connection-flow.png) * Upon startup, Puma listens on a TCP or UNIX socket. * The backlog of this socket is configured (with a default of 1024), determining how many established but unaccepted connections can exist concurrently. @@ -29,7 +29,7 @@ Clustered mode is shown/discussed here. Single mode is analogous to having a sin ### Disabling `queue_requests` -![http://bit.ly/2zxCJ1Z](images/puma-connection-flow-no-reactor.png) +![https://bit.ly/2zxCJ1Z](images/puma-connection-flow-no-reactor.png) The `queue_requests` option is `true` by default, enabling the separate thread used to buffer requests as described above. diff --git a/docs/signals.md b/docs/signals.md index 9661aa59..7026927b 100644 --- a/docs/signals.md +++ b/docs/signals.md @@ -1,8 +1,8 @@ -The [unix signal](http://en.wikipedia.org/wiki/Unix_signal) is a method of sending messages between [processes](http://en.wikipedia.org/wiki/Process_(computing)). When a signal is sent, the operating system interrupts the target process's normal flow of execution. There are standard signals that are used to stop a process but there are also custom signals that can be used for other purposes. This document is an attempt to list all supported signals that Puma will respond to. In general, signals need only be sent to the master process of a cluster. +The [unix signal](https://en.wikipedia.org/wiki/Unix_signal) is a method of sending messages between [processes](https://en.wikipedia.org/wiki/Process_(computing)). When a signal is sent, the operating system interrupts the target process's normal flow of execution. There are standard signals that are used to stop a process but there are also custom signals that can be used for other purposes. This document is an attempt to list all supported signals that Puma will respond to. In general, signals need only be sent to the master process of a cluster. ## Sending Signals -If you are new to signals it can be useful to see how they can be used. When a process is created in a *nix like operating system it will have a [PID - or process identifier](http://en.wikipedia.org/wiki/Process_identifier) that can be used to send signals to the process. For demonstration we will create an infinitely running process by tailing a file: +If you are new to signals it can be useful to see how they can be used. When a process is created in a *nix like operating system it will have a [PID - or process identifier](https://en.wikipedia.org/wiki/Process_identifier) that can be used to send signals to the process. For demonstration we will create an infinitely running process by tailing a file: ```sh $ echo "foo" >> my.log @@ -17,13 +17,13 @@ $ ps aux | grep tail schneems 87152 0.0 0.0 2432772 492 s032 S+ 12:46PM 0:00.00 tail -f my.log ``` -You can send a signal in Ruby using the [Process module](http://www.ruby-doc.org/core-2.1.1/Process.html#kill-method): +You can send a signal in Ruby using the [Process module](https://www.ruby-doc.org/core-2.1.1/Process.html#kill-method): ``` $ irb > puts pid => 87152 -Process.detach(pid) # http://ruby-doc.org/core-2.1.1/Process.html#method-c-detach +Process.detach(pid) # https://ruby-doc.org/core-2.1.1/Process.html#method-c-detach Process.kill("TERM", pid) ``` diff --git a/lib/puma/commonlogger.rb b/lib/puma/commonlogger.rb index 25989e72..4762be30 100644 --- a/lib/puma/commonlogger.rb +++ b/lib/puma/commonlogger.rb @@ -3,7 +3,7 @@ module Puma # Rack::CommonLogger forwards every request to the given +app+, and # logs a line in the - # {Apache common log format}[http://httpd.apache.org/docs/1.3/logs.html#common] + # {Apache common log format}[https://httpd.apache.org/docs/1.3/logs.html#common] # to the +logger+. # # If +logger+ is nil, CommonLogger will fall back +rack.errors+, which is @@ -16,7 +16,7 @@ module Puma # (which is called without arguments in order to make the error appear for # sure) class CommonLogger - # Common Log Format: http://httpd.apache.org/docs/1.3/logs.html#common + # Common Log Format: https://httpd.apache.org/docs/1.3/logs.html#common # # lilith.local - - [07/Aug/2006 23:58:02 -0400] "GET / HTTP/1.1" 500 - # diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 2ba99f52..c2364710 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -474,7 +474,7 @@ module Puma env[PATH_INFO] = env[REQUEST_PATH] - # From http://www.ietf.org/rfc/rfc3875 : + # From https://www.ietf.org/rfc/rfc3875 : # "Script authors should be aware that the REMOTE_ADDR and # REMOTE_HOST meta-variables (see sections 4.1.8 and 4.1.9) # may not identify the ultimate source of the request. diff --git a/puma.gemspec b/puma.gemspec index fad0d34c..44d16608 100644 --- a/puma.gemspec +++ b/puma.gemspec @@ -15,13 +15,13 @@ Gem::Specification.new do |s| end s.files = `git ls-files -- bin docs ext lib tools`.split("\n") + %w[History.md LICENSE README.md] - s.homepage = "http://puma.io" + s.homepage = "https://puma.io" if s.respond_to?(:metadata=) s.metadata = { "bug_tracker_uri" => "https://github.com/puma/puma/issues", "changelog_uri" => "https://github.com/puma/puma/blob/master/History.md", - "homepage_uri" => "http://puma.io", + "homepage_uri" => "https://puma.io", "source_code_uri" => "https://github.com/puma/puma" } end From 4537c8908694b8b0746409b87b1b62b79be39b7a Mon Sep 17 00:00:00 2001 From: Patrik Ragnarsson Date: Tue, 18 Aug 2020 17:59:56 +0200 Subject: [PATCH 54/66] Add #2338 to list of bugfixes [ci skip] --- History.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/History.md b/History.md index 28570e64..d7f22b3e 100644 --- a/History.md +++ b/History.md @@ -33,7 +33,7 @@ * Log binding on http:// for TCP bindings to make it clickable * Bugfixes - * Improve shutdown reliability (#2312) + * Improve shutdown reliability (#2312, #2338) * Close client http connections made to an ssl server with TLSv1.3 (#2116) * Do not set user_config to quiet by default to allow for file config (#2074) * Always close SSL connection in Puma::ControlCLI (#2211) From 489f9941b7c385d853a1acdbff87761777350ef2 Mon Sep 17 00:00:00 2001 From: Patrik Ragnarsson Date: Tue, 18 Aug 2020 18:09:05 +0200 Subject: [PATCH 55/66] [ci skip] Improve pull request template Make it more clear that the changelog check is skipped if CI is skipped. Useful when making doc fixes. (Having `[ci skip]` in the commit message wont stop the tests from running when you open a PR.) --- .github/pull_request_template.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/pull_request_template.md b/.github/pull_request_template.md index ca6f06dc..4effb5a4 100644 --- a/.github/pull_request_template.md +++ b/.github/pull_request_template.md @@ -5,7 +5,7 @@ Please describe your pull request. Thank you for contributing! You're the best. - [ ] I have reviewed the [guidelines for contributing](../blob/master/CONTRIBUTING.md) to this repository. -- [ ] I have added an entry to [History.md](../blob/master/History.md) if this PR fixes a bug or adds a feature. If it doesn't need an entry to HISTORY.md, I have added `[changelog skip]` the pull request title. +- [ ] I have added an entry to [History.md](../blob/master/History.md) if this PR fixes a bug or adds a feature. If it doesn't need an entry to HISTORY.md, I have added `[changelog skip]` or `[ci skip]` to the pull request title. - [ ] I have added appropriate tests if this PR fixes a bug or adds a feature. - [ ] My pull request is 100 lines added/removed or less so that it can be easily reviewed. - [ ] If this PR doesn't need tests (docs change), I added `[ci skip]` to the title of the PR. From 0b5db45d0dd06743ffd25c4ee5425cf4d8e3f9ff Mon Sep 17 00:00:00 2001 From: Patrik Ragnarsson Date: Sun, 23 Aug 2020 11:38:24 +0200 Subject: [PATCH 56/66] Fix typo in maximum URI path length Follow-up to https://github.com/puma/puma/pull/2168 --- History.md | 4 ++-- ext/puma_http11/puma_http11.c | 2 +- test/test_http11.rb | 4 ++-- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/History.md b/History.md index d7f22b3e..4e25ad6e 100644 --- a/History.md +++ b/History.md @@ -11,7 +11,7 @@ * EXPERIMENTAL: Added `nakayoshi_fork` option. Reduce memory usage in preloaded cluster-mode apps by GCing before fork and compacting, where available. (#2093, #2256) * Added pumactl `thread-backtraces` command to print thread backtraces (#2054) * Added incrementing `requests_count` to `Puma.stats`. (#2106) - * Increased maximum URI path length from 2048 to 8196 bytes (#2167) + * Increased maximum URI path length from 2048 to 8192 bytes (#2167, #2344) * `lowlevel_error_handler` is now called during a forced threadpool shutdown, and if a callable with 3 arguments is set, we now also pass the status code (#2203) * Faster phased restart and worker timeout (#2220) * Added `state_permission` to config DSL to set state file permissions (#2238) @@ -66,7 +66,7 @@ * JSON parse cluster worker stats instead of regex (#2124) * Support parallel tests in verbose progress reporting (#2223) * Refactor error handling in server accept loop (#2239) - + ## 4.3.4/4.3.5 and 3.12.5/3.12.6 / 2020-05-22 Each patchlevel release contains a separate security fix. We recommend simply upgrading to 4.3.5/3.12.6. diff --git a/ext/puma_http11/puma_http11.c b/ext/puma_http11/puma_http11.c index a2aedda6..962cb847 100644 --- a/ext/puma_http11/puma_http11.c +++ b/ext/puma_http11/puma_http11.c @@ -54,7 +54,7 @@ DEF_MAX_LENGTH(FIELD_NAME, 256); DEF_MAX_LENGTH(FIELD_VALUE, 80 * 1024); DEF_MAX_LENGTH(REQUEST_URI, 1024 * 12); DEF_MAX_LENGTH(FRAGMENT, 1024); /* Don't know if this length is specified somewhere or not */ -DEF_MAX_LENGTH(REQUEST_PATH, 8196); +DEF_MAX_LENGTH(REQUEST_PATH, 8192); DEF_MAX_LENGTH(QUERY_STRING, (1024 * 10)); DEF_MAX_LENGTH(HEADER, (1024 * (80 + 32))); diff --git a/test/test_http11.rb b/test/test_http11.rb index 267b8e8f..d8c51e1e 100644 --- a/test/test_http11.rb +++ b/test/test_http11.rb @@ -144,14 +144,14 @@ class Http11ParserTest < Minitest::Test parser = Puma::HttpParser.new req = {} - # Support URI path length to a max of 8196 + # Support URI path length to a max of 8192 path = "/" + rand_data(7000, 100) http = "GET #{path} HTTP/1.1\r\n\r\n" parser.execute(req, http, 0) assert_equal path, req['REQUEST_PATH'] parser.reset - # Raise exception if URI path length > 8196 + # Raise exception if URI path length > 8192 path = "/" + rand_data(9000, 100) http = "GET #{path} HTTP/1.1\r\n\r\n" assert_raises Puma::HttpParserError do From 67cecfb0f21d3ded798f11d8c977d5ec7fd0a2c4 Mon Sep 17 00:00:00 2001 From: Charles Oliver Nutter Date: Wed, 26 Aug 2020 15:43:04 -0500 Subject: [PATCH 57/66] Detect linux properly across all Ruby impls JRuby has used "java" for RUBY_PLATFORM for 15 years, so the best way to detect the host OS is to use RbConfig's "host_os" value. This allows JRuby to support the TCP_CORK hack and fix benchmarks of very small request/response cycles. See jruby/jruby#6366 for a more detailed discussion of TCP_CORK. --- lib/puma/server.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index c2364710..accd8708 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -101,7 +101,7 @@ module Puma # On Linux, use TCP_CORK to better control how the TCP stack # packetizes our stream. This improves both latency and throughput. # - if RUBY_PLATFORM =~ /linux/ + if RbConfig::CONFIG['host_os'] =~ /linux/ UNPACK_TCP_STATE_FROM_TCP_INFO = "C".freeze # 6 == Socket::IPPROTO_TCP From b6df9905fde8868e6a30a10adca767628c7d139f Mon Sep 17 00:00:00 2001 From: sumeka Date: Thu, 27 Aug 2020 16:00:25 +0530 Subject: [PATCH 58/66] [changelog skip] Move integration logging test to main test suite --- test/{shell => config}/t2_conf.rb | 0 test/shell/run.rb | 16 ++++------------ test/shell/t2.rb | 19 ------------------- test/test_integration_single.rb | 20 ++++++++++++++++++++ 4 files changed, 24 insertions(+), 31 deletions(-) rename test/{shell => config}/t2_conf.rb (100%) delete mode 100644 test/shell/t2.rb diff --git a/test/shell/t2_conf.rb b/test/config/t2_conf.rb similarity index 100% rename from test/shell/t2_conf.rb rename to test/config/t2_conf.rb diff --git a/test/shell/run.rb b/test/shell/run.rb index 58317f92..13d05836 100644 --- a/test/shell/run.rb +++ b/test/shell/run.rb @@ -1,18 +1,10 @@ require "puma" require "puma/detect" -TESTS_TO_RUN = if Process.respond_to?(:fork) - %w[t2 t3] -else - %w[t2] -end +return unless Process.respond_to?(:fork) -results = TESTS_TO_RUN.map do |test| - system("ruby -rrubygems test/shell/#{test}.rb ") # > /dev/null 2>&1 -end - -if results.any? { |r| r != true } - exit 1 -else +if system("ruby test/shell/t3.rb ") exit 0 +else + exit 1 end diff --git a/test/shell/t2.rb b/test/shell/t2.rb deleted file mode 100644 index c76a8b20..00000000 --- a/test/shell/t2.rb +++ /dev/null @@ -1,19 +0,0 @@ -system "ruby -rrubygems -Ilib bin/pumactl -F test/shell/t2_conf.rb start &" - -sleep 1 until system "curl http://localhost:10103/" - -out=`ruby -rrubygems -Ilib bin/pumactl -F test/shell/t2_conf.rb status` - -system "ruby -rrubygems -Ilib bin/pumactl -F test/shell/t2_conf.rb stop" - -sleep 1 - -log = File.read("t2-stdout") - -File.unlink "t2-stdout" if File.file? "t2-stdout" - -if log =~ %r(GET / HTTP/1\.1) && !File.file?("t2-pid") && out == "Puma is started\n" - exit 0 -else - exit 1 -end diff --git a/test/test_integration_single.rb b/test/test_integration_single.rb index ce8158b7..adcc75fa 100644 --- a/test/test_integration_single.rb +++ b/test/test_integration_single.rb @@ -131,4 +131,24 @@ class TestIntegrationSingle < TestIntegration assert_match(%r!GET / HTTP/1\.1!, log) end + + def test_puma_started_log_writing + suppress_output = '> /dev/null 2>&1' + + cli_server '-C test/config/t2_conf.rb test/rackup/hello.ru' + + system "curl http://localhost:#{@tcp_port}/ #{suppress_output}" + + out=`ruby -rrubygems -Ilib bin/pumactl -F test/config/t2_conf.rb status` + + stop_server + + log = File.read('t2-stdout') + + File.unlink 't2-stdout' if File.file? 't2-stdout' + + assert_match(%r!GET / HTTP/1\.1!, log) + assert(!File.file?("t2-pid")) + assert_equal("Puma is started\n", out) + end end From 96e37b6540b1a9d8f71be842cacf5576ffa09871 Mon Sep 17 00:00:00 2001 From: sumeka Date: Thu, 27 Aug 2020 16:09:53 +0530 Subject: [PATCH 59/66] skip test for systems which does not have TERM like windows. --- test/test_integration_single.rb | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/test_integration_single.rb b/test/test_integration_single.rb index adcc75fa..ec35b960 100644 --- a/test/test_integration_single.rb +++ b/test/test_integration_single.rb @@ -133,6 +133,8 @@ class TestIntegrationSingle < TestIntegration end def test_puma_started_log_writing + skip_unless_signal_exist? :TERM + suppress_output = '> /dev/null 2>&1' cli_server '-C test/config/t2_conf.rb test/rackup/hello.ru' From 5a87fa506c13a403477a30ee37e61f8ec40edaff Mon Sep 17 00:00:00 2001 From: sumeka Date: Thu, 27 Aug 2020 16:50:56 +0530 Subject: [PATCH 60/66] removed port binding --- test/config/t2_conf.rb | 1 - 1 file changed, 1 deletion(-) diff --git a/test/config/t2_conf.rb b/test/config/t2_conf.rb index 40937207..aabb44a4 100644 --- a/test/config/t2_conf.rb +++ b/test/config/t2_conf.rb @@ -1,5 +1,4 @@ log_requests stdout_redirect "t2-stdout" pidfile "t2-pid" -bind "tcp://0.0.0.0:10103" rackup File.expand_path('../rackup/hello.ru', File.dirname(__FILE__)) From b08672d5246d5f9d0d649472280d892c629ff57c Mon Sep 17 00:00:00 2001 From: sumeka Date: Thu, 27 Aug 2020 16:55:34 +0530 Subject: [PATCH 61/66] removed rackup from conf --- test/config/t2_conf.rb | 1 - 1 file changed, 1 deletion(-) diff --git a/test/config/t2_conf.rb b/test/config/t2_conf.rb index aabb44a4..35533397 100644 --- a/test/config/t2_conf.rb +++ b/test/config/t2_conf.rb @@ -1,4 +1,3 @@ log_requests stdout_redirect "t2-stdout" pidfile "t2-pid" -rackup File.expand_path('../rackup/hello.ru', File.dirname(__FILE__)) From 922c401f7b8690905dc3d07f5f09523101285460 Mon Sep 17 00:00:00 2001 From: sumeka Date: Thu, 27 Aug 2020 17:37:00 +0530 Subject: [PATCH 62/66] added BASE to change based on system --- test/test_integration_single.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_integration_single.rb b/test/test_integration_single.rb index ec35b960..1033320f 100644 --- a/test/test_integration_single.rb +++ b/test/test_integration_single.rb @@ -141,7 +141,7 @@ class TestIntegrationSingle < TestIntegration system "curl http://localhost:#{@tcp_port}/ #{suppress_output}" - out=`ruby -rrubygems -Ilib bin/pumactl -F test/config/t2_conf.rb status` + out=`#{BASE} bin/pumactl -F test/config/t2_conf.rb status` stop_server From 41631fa089074b2aac284e182ead5ae2343217b7 Mon Sep 17 00:00:00 2001 From: sumeka Date: Thu, 27 Aug 2020 18:22:09 +0530 Subject: [PATCH 63/66] rrubygems added back --- test/shell/run.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/shell/run.rb b/test/shell/run.rb index 13d05836..458f6400 100644 --- a/test/shell/run.rb +++ b/test/shell/run.rb @@ -3,7 +3,7 @@ require "puma/detect" return unless Process.respond_to?(:fork) -if system("ruby test/shell/t3.rb ") +if system("ruby -rrubygems test/shell/t3.rb ") exit 0 else exit 1 From 32067b11ad844375a37cef62dd911566ade59f15 Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Fri, 28 Aug 2020 09:35:09 -0500 Subject: [PATCH 64/66] JRuby test fix --- test/test_persistent.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_persistent.rb b/test/test_persistent.rb index 2e4c77e9..1c5d35a4 100644 --- a/test/test_persistent.rb +++ b/test/test_persistent.rb @@ -41,7 +41,7 @@ class TestPersistent < Minitest::Test def lines(count, s=@client) str = "".dup Timeout.timeout(5) do - count.times { str << s.gets } + count.times { str << (s.gets || "") } end str end From 9b86644d3fe0583efda3704cb9442bac9652130c Mon Sep 17 00:00:00 2001 From: Nate Berkopec Date: Fri, 28 Aug 2020 09:37:13 -0500 Subject: [PATCH 65/66] Re-add rubocop to CI --- .github/workflows/puma.yml | 1 - 1 file changed, 1 deletion(-) diff --git a/.github/workflows/puma.yml b/.github/workflows/puma.yml index 4e534023..a96e801b 100644 --- a/.github/workflows/puma.yml +++ b/.github/workflows/puma.yml @@ -54,7 +54,6 @@ jobs: run: bundle exec rake compile - name: rubocop - if: startsWith(matrix.ruby, '2.') run: bundle exec rake rubocop - name: test From 5a0012ac86aa45a7cb7b0ce910e0b70389c56a1d Mon Sep 17 00:00:00 2001 From: pavel Date: Sun, 30 Aug 2020 12:50:55 +0200 Subject: [PATCH 66/66] make sure that TCP_CORK is supported --- History.md | 1 + lib/puma/server.rb | 18 +++++++++++++++--- 2 files changed, 16 insertions(+), 3 deletions(-) diff --git a/History.md b/History.md index 4e25ad6e..8bb312ed 100644 --- a/History.md +++ b/History.md @@ -2,6 +2,7 @@ * Bugfixes * Resolve issue with threadpool waiting counter decrement when thread is killed * Constrain rake-compiler version to 0.9.4 to fix `ClassNotFound` exception when using MiniSSL with Java8. + * Ensure that TCP_CORK is usable ## 5.0.0 diff --git a/lib/puma/server.rb b/lib/puma/server.rb index accd8708..b9fa8f68 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -98,10 +98,22 @@ module Puma @binder = bind end + class << self + # :nodoc: + def tcp_cork_supported? + RbConfig::CONFIG['host_os'] =~ /linux/ && + Socket.const_defined?(:IPPROTO_TCP) && + Socket.const_defined?(:TCP_CORK) && + Socket.const_defined?(:SOL_TCP) && + Socket.const_defined?(:TCP_INFO) + end + private :tcp_cork_supported? + end + # On Linux, use TCP_CORK to better control how the TCP stack # packetizes our stream. This improves both latency and throughput. # - if RbConfig::CONFIG['host_os'] =~ /linux/ + if tcp_cork_supported? UNPACK_TCP_STATE_FROM_TCP_INFO = "C".freeze # 6 == Socket::IPPROTO_TCP @@ -109,7 +121,7 @@ module Puma # 1/0 == turn on/off def cork_socket(socket) begin - socket.setsockopt(6, 3, 1) if socket.kind_of? TCPSocket + socket.setsockopt(Socket::IPPROTO_TCP, Socket::TCP_CORK, 1) if socket.kind_of? TCPSocket rescue IOError, SystemCallError Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue end @@ -117,7 +129,7 @@ module Puma def uncork_socket(socket) begin - socket.setsockopt(6, 3, 0) if socket.kind_of? TCPSocket + socket.setsockopt(Socket::IPPROTO_TCP, Socket::TCP_CORK, 0) if socket.kind_of? TCPSocket rescue IOError, SystemCallError Thread.current.purge_interrupt_queue if Thread.current.respond_to? :purge_interrupt_queue end