From d48ac135a45d846cb58df1b1bf0cb69b23058bbd Mon Sep 17 00:00:00 2001 From: Dan Buettner Date: Thu, 16 Nov 2023 16:58:21 -0600 Subject: [PATCH] Honor Apache-formatted X-Request-Start header to enable wait_timeout functionality --- CHANGELOG.md | 1 + UPGRADING.md | 13 +++++++++++++ doc/settings.md | 11 ++++++++++- lib/rack/timeout/core.rb | 12 ++++++++---- test/basic_test.rb | 7 +++++++ test/test_helper.rb | 5 +++++ 6 files changed, 44 insertions(+), 5 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..c54dd62 100644 --- a/doc/settings.md +++ b/doc/settings.md @@ -31,7 +31,16 @@ A request's computed wait time may affect the service timeout used for it. Basic 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.) -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` - 13.3 digits, nginx standard format +- `t=seconds.milliseconds`, e.g. `t=1700173924.763` - 13.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