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