From cb58fc17e97a491ad88c7a7540f1ba1cebdbd5ee Mon Sep 17 00:00:00 2001 From: Daniel Huckstep Date: Sat, 13 Mar 2021 00:32:25 -0400 Subject: [PATCH 1/7] Add between_bytes_timeout to fix timing out when we get a slow request Regression in 5.0.3 --- lib/puma/dsl.rb | 6 ++++++ lib/puma/server.rb | 26 ++++++++++++++++---------- test/test_puma_server.rb | 30 ++++++++++++++++++++++++++++++ 3 files changed, 52 insertions(+), 10 deletions(-) diff --git a/lib/puma/dsl.rb b/lib/puma/dsl.rb index 236123d0d6..a790ebdd32 100644 --- a/lib/puma/dsl.rb +++ b/lib/puma/dsl.rb @@ -272,6 +272,12 @@ def first_data_timeout(seconds) @options[:first_data_timeout] = Integer(seconds) end + # Define how long the tcp socket stays open, once data has been received. + # @see Puma::Server.new + def between_bytes_timeout(seconds) + @options[:between_bytes_timeout] = Integer(seconds) + end + # Work around leaky apps that leave garbage in Thread locals # across requests. def clean_thread_locals(which=true) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index 8985b83c27..fa35c92b3d 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -40,12 +40,14 @@ class Server attr_reader :requests_count # @version 5.0.0 # @todo the following may be deprecated in the future - attr_reader :auto_trim_time, :early_hints, :first_data_timeout, + attr_reader :auto_trim_time, :early_hints, + :first_data_timeout, :between_bytes_timeout, :leak_stack_on_error, :persistent_timeout, :reaping_time # @deprecated v6.0.0 - attr_writer :auto_trim_time, :early_hints, :first_data_timeout, + attr_writer :auto_trim_time, :early_hints, + :first_data_timeout, :between_bytes_timeout, :leak_stack_on_error, :min_threads, :max_threads, :persistent_timeout, :reaping_time @@ -84,14 +86,15 @@ def initialize(app, events=Events.stdio, options={}) @options = options - @early_hints = options.fetch :early_hints, nil - @first_data_timeout = options.fetch :first_data_timeout, FIRST_DATA_TIMEOUT - @min_threads = options.fetch :min_threads, 0 - @max_threads = options.fetch :max_threads , (Puma.mri? ? 5 : 16) - @persistent_timeout = options.fetch :persistent_timeout, PERSISTENT_TIMEOUT - @queue_requests = options.fetch :queue_requests, true - @max_fast_inline = options.fetch :max_fast_inline, MAX_FAST_INLINE - @io_selector_backend = options.fetch :io_selector_backend, :auto + @early_hints = options.fetch :early_hints, nil + @first_data_timeout = options.fetch :first_data_timeout, FIRST_DATA_TIMEOUT + @between_bytes_timeout = options.fetch :between_bytes_timeout, @first_data_timeout + @min_threads = options.fetch :min_threads, 0 + @max_threads = options.fetch :max_threads , (Puma.mri? ? 5 : 16) + @persistent_timeout = options.fetch :persistent_timeout, PERSISTENT_TIMEOUT + @queue_requests = options.fetch :queue_requests, true + @max_fast_inline = options.fetch :max_fast_inline, MAX_FAST_INLINE + @io_selector_backend = options.fetch :io_selector_backend, :auto temp = !!(@options[:environment] =~ /\A(development|test)\z/) @leak_stack_on_error = @options[:environment] ? temp : true @@ -295,6 +298,9 @@ def reactor_wakeup(client) @thread_pool << client elsif shutdown || client.timeout == 0 client.timeout! + else + client.set_timeout(between_bytes_timeout) + false end rescue StandardError => e client_error(e, client) diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index eb05d1c9e0..0455afdf1e 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -393,6 +393,36 @@ def test_timeout_in_data_phase assert_equal "HTTP/1.1 408 Request Timeout\r\n", data end + def test_timeout_after_data_received + @server.first_data_timeout = 2 + @server.between_bytes_timeout = 2 + server_run + + sock = send_http "POST / HTTP/1.1\r\nHost: test.com\r\nContent-Type: text/plain\r\nContent-Length: 100\r\n\r\n" + + sock << "hello" + + data = sock.gets + + assert_equal "HTTP/1.1 408 Request Timeout\r\n", data + end + + def test_no_timeout_after_data_received + @server.first_data_timeout = 2 + @server.between_bytes_timeout = 30 + server_run + + sock = send_http "POST / HTTP/1.1\r\nHost: test.com\r\nContent-Type: text/plain\r\nContent-Length: 10\r\n\r\n" + + sock << "hello" + sleep 4 + sock << "world" + + data = sock.gets + + assert_equal "HTTP/1.1 200 OK\r\n", data + end + def test_timeout_data_no_queue @server = Puma::Server.new @app, @events, queue_requests: false test_timeout_in_data_phase From 7260b70444852ec835df9d36045c79907beeb125 Mon Sep 17 00:00:00 2001 From: Daniel Huckstep Date: Sat, 13 Mar 2021 00:44:48 -0400 Subject: [PATCH 2/7] update History.md for :between_bytes_timeout --- History.md | 1 + 1 file changed, 1 insertion(+) diff --git a/History.md b/History.md index 38e1004d97..59124061d1 100644 --- a/History.md +++ b/History.md @@ -4,6 +4,7 @@ * Your feature goes here (#Github Number) * Warn when running Cluster mode with a single worker (#2565) * Add reason to worker time out and startup time when worked boots ([#2528]) + * Add :between_bytes_timeout to prevent timeout during slow incoming requests (#2575) * Bugfixes * Your bugfix goes here (#Github Number) From e3219a518ce20c490f41627db5c4e61b7dd7e7a7 Mon Sep 17 00:00:00 2001 From: Daniel Huckstep Date: Sat, 13 Mar 2021 18:15:50 -0400 Subject: [PATCH 3/7] tests for between_bytes_timeout working appropriately --- test/test_puma_server.rb | 23 +++++++++++++++++------ 1 file changed, 17 insertions(+), 6 deletions(-) diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index 0455afdf1e..eacbe0d1f3 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -382,40 +382,51 @@ def test_status_hook_fires_when_server_changes_states assert_equal [:booting, :running, :stop, :done], states end + def assert_proper_timeout(expected, &block) + now = Time.now + ret = block.call + t = Time.now - now + assert_in_delta expected, t, 0.5, "unexpected timeout, #{t} instead of ~#{expected}" + ret + end + def test_timeout_in_data_phase @server.first_data_timeout = 2 server_run sock = send_http "POST / HTTP/1.1\r\nHost: test.com\r\nContent-Type: text/plain\r\nContent-Length: 5\r\n\r\n" - data = sock.gets + data = assert_proper_timeout(@server.first_data_timeout) { sock.gets } assert_equal "HTTP/1.1 408 Request Timeout\r\n", data end def test_timeout_after_data_received - @server.first_data_timeout = 2 + @server.first_data_timeout = 4 @server.between_bytes_timeout = 2 server_run sock = send_http "POST / HTTP/1.1\r\nHost: test.com\r\nContent-Type: text/plain\r\nContent-Length: 100\r\n\r\n" + sleep 0.1 sock << "hello" + sleep 0.1 - data = sock.gets + data = assert_proper_timeout(@server.between_bytes_timeout) { sock.gets } assert_equal "HTTP/1.1 408 Request Timeout\r\n", data end def test_no_timeout_after_data_received - @server.first_data_timeout = 2 - @server.between_bytes_timeout = 30 + @server.first_data_timeout = 10 + @server.between_bytes_timeout = 4 server_run sock = send_http "POST / HTTP/1.1\r\nHost: test.com\r\nContent-Type: text/plain\r\nContent-Length: 10\r\n\r\n" + sleep 0.1 sock << "hello" - sleep 4 + sleep 2 sock << "world" data = sock.gets From d249b75aca09b50bec736fe6a530f9612e0ca4bb Mon Sep 17 00:00:00 2001 From: Daniel Huckstep Date: Sat, 13 Mar 2021 18:18:52 -0400 Subject: [PATCH 4/7] rubocop fix --- test/test_puma_server.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index eacbe0d1f3..ab80a05413 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -382,9 +382,9 @@ def test_status_hook_fires_when_server_changes_states assert_equal [:booting, :running, :stop, :done], states end - def assert_proper_timeout(expected, &block) + def assert_proper_timeout(expected) now = Time.now - ret = block.call + ret = yield t = Time.now - now assert_in_delta expected, t, 0.5, "unexpected timeout, #{t} instead of ~#{expected}" ret From d6d515900d5f27a93eb85bb3c8c07d90175adabc Mon Sep 17 00:00:00 2001 From: Daniel Huckstep Date: Sat, 13 Mar 2021 18:38:16 -0400 Subject: [PATCH 5/7] handle between_bytes_timeout when queue_requests: false --- lib/puma/client.rb | 3 ++- lib/puma/server.rb | 2 +- test/test_puma_server.rb | 17 +++++++++++++++++ 3 files changed, 20 insertions(+), 2 deletions(-) diff --git a/lib/puma/client.rb b/lib/puma/client.rb index 5a937e7f79..e568b35a03 100644 --- a/lib/puma/client.rb +++ b/lib/puma/client.rb @@ -205,8 +205,9 @@ def eagerly_finish try_to_finish end - def finish(timeout) + def finish(first_data_timeout, between_bytes_timeout) return if @ready + timeout = @parsed_bytes > 0 ? first_data_timeout : between_bytes_timeout IO.select([@to_io], nil, nil, timeout) || timeout! until try_to_finish end diff --git a/lib/puma/server.rb b/lib/puma/server.rb index fa35c92b3d..e90f2e44ba 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -429,7 +429,7 @@ def process_client(client, buffer) end with_force_shutdown(client) do - client.finish(@first_data_timeout) + client.finish(@first_data_timeout, @between_bytes_timeout) end while true diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index ab80a05413..2447253919 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -417,6 +417,23 @@ def test_timeout_after_data_received assert_equal "HTTP/1.1 408 Request Timeout\r\n", data end + def test_timeout_after_data_received_no_queue + @server = Puma::Server.new @app, @events, queue_requests: false + @server.first_data_timeout = 4 + @server.between_bytes_timeout = 2 + server_run + + sock = send_http "POST / HTTP/1.1\r\nHost: test.com\r\nContent-Type: text/plain\r\nContent-Length: 100\r\n\r\n" + sleep 0.1 + + sock << "hello" + sleep 0.1 + + data = assert_proper_timeout(@server.between_bytes_timeout) { sock.gets } + + assert_equal "HTTP/1.1 408 Request Timeout\r\n", data + end + def test_no_timeout_after_data_received @server.first_data_timeout = 10 @server.between_bytes_timeout = 4 From 24556549a67a378ab38f890852b27afa6c72f39a Mon Sep 17 00:00:00 2001 From: Daniel Huckstep Date: Sat, 13 Mar 2021 19:13:17 -0400 Subject: [PATCH 6/7] use the proper timeout based on @parsed_bytes --- lib/puma/client.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/puma/client.rb b/lib/puma/client.rb index e568b35a03..281daa9145 100644 --- a/lib/puma/client.rb +++ b/lib/puma/client.rb @@ -207,7 +207,7 @@ def eagerly_finish def finish(first_data_timeout, between_bytes_timeout) return if @ready - timeout = @parsed_bytes > 0 ? first_data_timeout : between_bytes_timeout + timeout = @parsed_bytes > 0 ? between_bytes_timeout : first_data_timeout IO.select([@to_io], nil, nil, timeout) || timeout! until try_to_finish end From e438cb068c10c2065784e668a895544894af8ebf Mon Sep 17 00:00:00 2001 From: Daniel Huckstep Date: Sat, 13 Mar 2021 19:13:37 -0400 Subject: [PATCH 7/7] use instance variable, organize tests with no_queue --- lib/puma/server.rb | 2 +- test/test_puma_server.rb | 23 ++++++++--------------- 2 files changed, 9 insertions(+), 16 deletions(-) diff --git a/lib/puma/server.rb b/lib/puma/server.rb index e90f2e44ba..13cf1799dc 100644 --- a/lib/puma/server.rb +++ b/lib/puma/server.rb @@ -299,7 +299,7 @@ def reactor_wakeup(client) elsif shutdown || client.timeout == 0 client.timeout! else - client.set_timeout(between_bytes_timeout) + client.set_timeout(@between_bytes_timeout) false end rescue StandardError => e diff --git a/test/test_puma_server.rb b/test/test_puma_server.rb index 2447253919..edfbce8395 100644 --- a/test/test_puma_server.rb +++ b/test/test_puma_server.rb @@ -401,6 +401,11 @@ def test_timeout_in_data_phase assert_equal "HTTP/1.1 408 Request Timeout\r\n", data end + def test_timeout_data_no_queue + @server = Puma::Server.new @app, @events, queue_requests: false + test_timeout_in_data_phase + end + def test_timeout_after_data_received @server.first_data_timeout = 4 @server.between_bytes_timeout = 2 @@ -419,19 +424,7 @@ def test_timeout_after_data_received def test_timeout_after_data_received_no_queue @server = Puma::Server.new @app, @events, queue_requests: false - @server.first_data_timeout = 4 - @server.between_bytes_timeout = 2 - server_run - - sock = send_http "POST / HTTP/1.1\r\nHost: test.com\r\nContent-Type: text/plain\r\nContent-Length: 100\r\n\r\n" - sleep 0.1 - - sock << "hello" - sleep 0.1 - - data = assert_proper_timeout(@server.between_bytes_timeout) { sock.gets } - - assert_equal "HTTP/1.1 408 Request Timeout\r\n", data + test_timeout_after_data_received end def test_no_timeout_after_data_received @@ -451,9 +444,9 @@ def test_no_timeout_after_data_received assert_equal "HTTP/1.1 200 OK\r\n", data end - def test_timeout_data_no_queue + def test_no_timeout_after_data_received_no_queue @server = Puma::Server.new @app, @events, queue_requests: false - test_timeout_in_data_phase + test_no_timeout_after_data_received end def test_http_11_keep_alive_with_body