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

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

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