From 7f78737b033ce0b139709af0d05440b7afcd4c2b Mon Sep 17 00:00:00 2001 From: Dan Buettner Date: Thu, 16 Nov 2023 16:53:34 -0600 Subject: [PATCH 1/4] Two requires needed to get rake to run tests --- test/test_helper.rb | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/test_helper.rb b/test/test_helper.rb index 08c45c7..949583c 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -1,5 +1,7 @@ require "test/unit" require "rack/test" +require "rack/builder" +require "rack/null_logger" require "rack-timeout" class RackTimeoutTest < Test::Unit::TestCase From 2799bae54aea85d4b8fa9d9aa6c084256fb4c7ff Mon Sep 17 00:00:00 2001 From: Dan Buettner Date: Thu, 16 Nov 2023 16:58:21 -0600 Subject: [PATCH 2/4] Honor Apache-formatted X-Request-Start header to enable wait_timeout functionality --- CHANGELOG.md | 1 + UPGRADING.md | 13 +++++++++++++ doc/settings.md | 13 +++++++++++-- lib/rack/timeout/core.rb | 12 ++++++++---- test/basic_test.rb | 7 +++++++ test/test_helper.rb | 5 +++++ 6 files changed, 45 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 72f9679..5e77a5a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,6 @@ ## HEAD (unreleased) - Improve message when Terminate on Timeout is used on a platform that does not support it (eg. Windows or JVM) + - Honor an `X-Request-Start` header with Apache's standard `t=` format, to allow using `wait_timeout` functionality ## 0.6.3 diff --git a/UPGRADING.md b/UPGRADING.md index 61fc66c..8f78f18 100644 --- a/UPGRADING.md +++ b/UPGRADING.md @@ -1,6 +1,19 @@ Upgrading ========= +From 0.6.3 or older +----------------- + +- Apache's `X-Request-Start` header is now recognized, which if present + will trigger the default `wait_timeout` behavior (unless you have changed + those settings or disabled it). + + Please review `wait_timeout` behavior in [doc/settings.md](doc/settings.md#wait-timeout). + + TL;DR -> set `wait_timeout` to `0` or `'false'` to disable it and maintain + your Apache setup's current behavior. + + From 0.4 or older ----------------- diff --git a/doc/settings.md b/doc/settings.md index 9a642c7..45afccf 100644 --- a/doc/settings.md +++ b/doc/settings.md @@ -29,9 +29,18 @@ Wait timeout can be disabled entirely by setting the property to `0` or `false`. A request's computed wait time may affect the service timeout used for it. Basically, a request's wait time plus service time may not exceed the wait timeout. The reasoning for that is based on Heroku router's behavior, that the request would be dropped anyway after the wait timeout. So, for example, with the default settings of `service_timeout=15`, `wait_timeout=30`, a request that had 20 seconds of wait time will not have a service timeout of 15, but instead of 10, as there are only 10 seconds left before `wait_timeout` is reached. This behavior can be disabled by setting `service_past_wait` to `true`. When set, the `service_timeout` setting will always be honored. Please note that if you're using the `RACK_TIMEOUT_SERVICE_PAST_WAIT` environment variable, any value different than `"false"` will be considered `true`. -The way we're able to infer a request's start time, and from that its wait time, is through the availability of the `X-Request-Start` HTTP header, which is expected to contain the time since epoch in milliseconds. (A concession is made for nginx's sec.msec notation.) +The way we're able to infer a request's start time, and from that its wait time, is through the availability of the `X-Request-Start` HTTP header, which is expected to contain the time since UNIX epoch in milliseconds or microseconds. -If the `X-Request-Start` header is not present `wait_timeout` handling is skipped entirely. +Compatible header string formats are: + +- `seconds.milliseconds`, e.g. `1700173924.763` - 10.3 digits, nginx standard format +- `t=seconds.milliseconds`, e.g. `t=1700173924.763` - 10.3 digits, nginx standard format with [New Relic recommended][new-relic-recommended-format] `t=` prefix +- `milliseconds`, e.g. `1700173924763` - 13 digits, Heroku standard format +- `t=microseconds`, e.g. `t=1700173924763384` - 16 digits with `t=` prefix, Apache standard format + +[new-relic-recommended-format]: https://docs.newrelic.com/docs/apm/applications-menu/features/request-queue-server-configuration-examples/ + +If the `X-Request-Start` header is not present, or does not match one of these formats, `wait_timeout` handling is skipped entirely. ### Wait Overtime diff --git a/lib/rack/timeout/core.rb b/lib/rack/timeout/core.rb index ae6247a..0e97810 100644 --- a/lib/rack/timeout/core.rb +++ b/lib/rack/timeout/core.rb @@ -167,9 +167,9 @@ def call(env) # X-Request-Start contains the time the request was first seen by the server. Format varies wildly amongst servers, yay! # - nginx gives the time since epoch as seconds.milliseconds[1]. New Relic documentation recommends preceding it with t=[2], so might as well detect it. # - Heroku gives the time since epoch in milliseconds. [3] - # - Apache uses t=microseconds[4], so we're not even going there. + # - Apache uses t=microseconds[4], so 16 digits (until November 2286). # - # The sane way to handle this would be by knowing the server being used, instead let's just hack around with regular expressions and ignore apache entirely. + # The sane way to handle this would be by knowing the server being used, instead let's just hack around with regular expressions. # [1]: http://nginx.org/en/docs/http/ngx_http_log_module.html#var_msec # [2]: https://docs.newrelic.com/docs/apm/other-features/request-queueing/request-queue-server-configuration-examples#nginx # [3]: https://devcenter.heroku.com/articles/http-routing#heroku-headers @@ -178,11 +178,15 @@ def call(env) # This is a code extraction for readability, this method is only called from a single point. RX_NGINX_X_REQUEST_START = /^(?:t=)?(\d+)\.(\d{3})$/ RX_HEROKU_X_REQUEST_START = /^(\d+)$/ + RX_APACHE_X_REQUEST_START = /^t=(\d{16})$/ HTTP_X_REQUEST_START = "HTTP_X_REQUEST_START".freeze def self._read_x_request_start(env) return unless s = env[HTTP_X_REQUEST_START] - return unless m = s.match(RX_HEROKU_X_REQUEST_START) || s.match(RX_NGINX_X_REQUEST_START) - Time.at(m[1,2].join.to_f / 1000) + if m = s.match(RX_HEROKU_X_REQUEST_START) || s.match(RX_NGINX_X_REQUEST_START) + Time.at(m[1,2].join.to_f / 1000) + elsif m = s.match(RX_APACHE_X_REQUEST_START) + Time.at(m[1].to_f / 1_000_000) + end end # This method determines if a body is present. requests with a body (generally POST, PUT) can have a lengthy body which may have taken a while to be received by the web server, inflating their computed wait time. This in turn could lead to unwanted expirations. See wait_overtime property as a way to overcome those. diff --git a/test/basic_test.rb b/test/basic_test.rb index 9c2f482..b744c81 100644 --- a/test/basic_test.rb +++ b/test/basic_test.rb @@ -20,4 +20,11 @@ def test_wait_timeout get "/", "", 'HTTP_X_REQUEST_START' => time_in_msec(Time.now - 100) end end + + def test_apache_formatted_header_wait_timeout + self.settings = { service_timeout: 1, wait_timeout: 15 } + assert_raises(Rack::Timeout::RequestExpiryError) do + get "/", "", 'HTTP_X_REQUEST_START' => "t=#{time_in_usec(Time.now - 100)}" + end + end end diff --git a/test/test_helper.rb b/test/test_helper.rb index 949583c..fd5e0ee 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -44,4 +44,9 @@ def with_env(hash) def time_in_msec(t = Time.now) "#{t.tv_sec}#{t.tv_usec/1000}" end + + def time_in_usec(t = Time.now) + # time in microseconds, currently 16 digits + "#{t.tv_sec}#{t.tv_usec}" + end end From 173d9d40498c48f4dcb473edc5eaecf4ffa61423 Mon Sep 17 00:00:00 2001 From: "Jonathan Dance (JD)" Date: Thu, 16 May 2024 19:30:56 +0300 Subject: [PATCH 3/4] Apply suggestions from code review --- CHANGELOG.md | 2 +- UPGRADING.md | 13 ------------- 2 files changed, 1 insertion(+), 14 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 5e77a5a..7e465ff 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ ## HEAD (unreleased) - Improve message when Terminate on Timeout is used on a platform that does not support it (eg. Windows or JVM) - - Honor an `X-Request-Start` header with Apache's standard `t=` format, to allow using `wait_timeout` functionality + - Honor an `X-Request-Start` header with the `t=` format, to allow using `wait_timeout` functionality with Apache ## 0.6.3 diff --git a/UPGRADING.md b/UPGRADING.md index 8f78f18..61fc66c 100644 --- a/UPGRADING.md +++ b/UPGRADING.md @@ -1,19 +1,6 @@ Upgrading ========= -From 0.6.3 or older ------------------ - -- Apache's `X-Request-Start` header is now recognized, which if present - will trigger the default `wait_timeout` behavior (unless you have changed - those settings or disabled it). - - Please review `wait_timeout` behavior in [doc/settings.md](doc/settings.md#wait-timeout). - - TL;DR -> set `wait_timeout` to `0` or `'false'` to disable it and maintain - your Apache setup's current behavior. - - From 0.4 or older ----------------- From f79119f116094b3c276242dad074a05f4a59f44c Mon Sep 17 00:00:00 2001 From: "Jonathan Dance (JD)" Date: Mon, 20 May 2024 21:02:17 +0300 Subject: [PATCH 4/4] change time_in_usec to use format string --- test/test_helper.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_helper.rb b/test/test_helper.rb index fd5e0ee..1864b9b 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -47,6 +47,6 @@ def time_in_msec(t = Time.now) def time_in_usec(t = Time.now) # time in microseconds, currently 16 digits - "#{t.tv_sec}#{t.tv_usec}" + "%d%06d" % [t.tv_sec, t.tv_usec] end end