Honor Apache-formatted X-Request-Start header to enable wait_timeout …

…functionality

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=<microseconds>` format, to allow using `wait_timeout` functionality
 
 ## 0.6.3
 

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
 -----------------
 

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
 

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.

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

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