Merge remote-tracking branch 'origin/main'

Author: graywh

.github/workflows/check_changelog.yml

@@ -1,12 +1,22 @@
 name: Check Changelog
 
-on: [pull_request]
+on:
+  pull_request:
+    types: [opened, reopened, edited, labeled, unlabeled, synchronize]
 
 jobs:
-  build:
+  check-changelog:
     runs-on: ubuntu-latest
+    if: |
+      !contains(github.event.pull_request.body, '[skip changelog]') &&
+      !contains(github.event.pull_request.body, '[changelog skip]') &&
+      !contains(github.event.pull_request.body, '[skip ci]') &&
+      !contains(github.event.pull_request.labels.*.name, 'skip changelog') &&
+      !contains(github.event.pull_request.labels.*.name, 'dependencies') &&
+      !contains(github.event.pull_request.labels.*.name, 'automation')
     steps:
-    - uses: actions/checkout@v1
-    - name: Check that CHANGELOG is touched
-      run: |
-        cat $GITHUB_EVENT_PATH | jq .pull_request.title |  grep -i '\[\(\(changelog skip\)\|\(ci skip\)\)\]' ||  git diff remotes/origin/${{ github.base_ref }} --name-only | grep CHANGELOG.md
+      - uses: actions/checkout@v3
+      - name: Check that CHANGELOG is touched
+        run: |
+          git fetch origin ${{ github.base_ref }} --depth 1 && \
+          git diff remotes/origin/${{ github.base_ref }} --name-only | grep CHANGELOG.md

.github/workflows/ci.yml

@@ -6,20 +6,27 @@ on:
 
 jobs:
   test:
-    runs-on: ubuntu-latest
     strategy:
       fail-fast: false
       matrix:
+        os: [ ubuntu-latest, windows-latest ]
+        rack-version: ['~> 2.0', '~> 3.0']
         ruby:
-          - '2.2'
           - '2.3'
           - '2.4'
           - '2.5'
           - '2.6'
           - '2.7'
           - '3.0'
           - '3.1'
+          - '3.2'
           - 'head'
+        exclude:
+          - ruby: '2.3'
+            rack-version: '~> 3.0'
+    runs-on: ${{ matrix.os }}
+    env:
+      RACK_VERSION: ${{ matrix.rack-version }}
     steps:
       - name: Checkout code
         uses: actions/checkout@v3

CHANGELOG.md

@@ -1,4 +1,10 @@
-## HEAD (unreleased)
+## 0.7.0
+
+ - Honor an `X-Request-Start` header with the `t=<microseconds>` format, to allow using `wait_timeout` functionality with Apache (https://github.com/zombocom/rack-timeout/pull/210)
+ - Improve message when Terminate on Timeout is used on a platform that does not support it (eg. Windows or JVM) (https://github.com/zombocom/rack-timeout/pull/192)
+ - Fix a thread safety issue for forks that are not on the main thread (https://github.com/zombocom/rack-timeout/pull/212)
+ - Add compatibility with frozen_string_literal: true (https://github.com/zombocom/rack-timeout/pull/196)
+ - Fix if Rails is defined but Rails::VERSION is not defined (https://github.com/zombocom/rack-timeout/pull/191)
 
 ## 0.6.3
 

Gemfile

@@ -1,3 +1,5 @@
 source 'https://rubygems.org'
 
 gemspec
+
+gem 'rack', ENV['RACK_VERSION'] if ENV['RACK_VERSION']

README.md

@@ -47,7 +47,7 @@ only:              []     # RACK_TIMEOUT_ONLY
 
 Both `exclude` and `only` can be used at the same time, in this case excluded paths will be substracted from the `only` array.
 
-These settings can be overriden during middleware initialization or
+These settings can be overridden during middleware initialization or
 environment variables `RACK_TIMEOUT_*` mentioned above. Middleware
 parameters take precedence:
 
@@ -56,8 +56,41 @@ use Rack::Timeout::Select, service_timeout: 5, exclude: ["api"]
 ```
 [Demo application](https://github.com/mkrl/rack-timeout-test)
 
-Please note that you may have controller actions with names similar to your excludes/targets, use with wise.
+For more on these settings, please see [doc/settings](doc/settings.md).
+
+Further Documentation
+---------------------
+
+Please see the [doc](doc) folder for further documentation on:
+
+* [Risks and shortcomings of using Rack::Timeout](doc/risks.md)
+* [Understanding the request lifecycle](doc/request-lifecycle.md)
+* [Exceptions raised by Rack::Timeout](doc/exceptions.md)
+* [Rollbar fingerprinting](doc/rollbar.md)
+* [Observers](doc/observers.md)
+* [Settings](doc/settings.md)
+* [Logging](doc/logging.md)
+
+Additionally there is a [demo app](https://github.com/zombocom/rack_timeout_demos)
+that shows the impact of changing settings and how the library behaves
+when a timeout is hit.
+
+Contributing
+------------
+
+Run the test suite:
+
+```console
+bundle
+bundle exec rake test
+```
+
+Compatibility
+-------------
+
+This version of Rack::Timeout is compatible with Ruby 2.3 and up, and,
+for Rails apps, Rails 3.x and up.
 
 ---
 Copyright © 2010-2020 Caio Chassot, released under the MIT license
-<http://github.com/sharpstone/rack-timeout>
+<http://github.com/zombocom/rack-timeout>

doc/risks.md

@@ -5,7 +5,7 @@ Risks and shortcomings of using Rack::Timeout
 
 Sometimes a request is taking too long to complete because it's blocked waiting on synchronous IO. Such IO does not need to be file operations, it could be, say, network or database operations. If said IO is happening in a C library that's unaware of ruby's interrupt system (i.e. anything written without ruby in mind), calling `Thread#raise` (that's what rack-timeout uses) will not have effect until after the IO block is gone.
 
-At the moment rack-timeout does not try to address this issue. As a fail-safe against these cases, a blunter solution that kills the entire process is recommended, such as unicorn's timeouts.
+As a fail-safe against these cases, a blunter solution that kills the entire process is recommended, such as unicorn's timeouts. You can enable this process killing behavior by enabling `term_on_timeout` for more info see [setting][term-on-timeout].
 
 More detailed explanations of the issues surrounding timing out in ruby during IO blocks can be found at:
 
@@ -15,14 +15,16 @@ More detailed explanations of the issues surrounding timing out in ruby during I
 
 Raising mid-flight in stateful applications is inherently unsafe. A request can be aborted at any moment in the code flow, and the application can be left in an inconsistent state. There's little way rack-timeout could be aware of ongoing state changes. Applications that rely on a set of globals (like class variables) or any other state that lives beyond a single request may find those left in an unexpected/inconsistent state after an aborted request. Some cleanup code might not have run, or only half of a set of related changes may have been applied.
 
-A lot more can go wrong. An intricate explanation of the issue by JRuby's Charles Nutter can be found [here][broken-timeout].
+A lot more can go wrong. An intricate explanation of the issue by JRuby's Charles Nutter can be found [
+Ruby's Thread#raise, Thread#kill, timeout.rb, and net/protocol.rb libraries are broken][broken-timeout]. In addition Richard Schneeman talked about this issue in [The Oldest Bug In Ruby - Why Rack::Timeout Might Hose your Server][oldest-bug]. One solution from having `rack-timeout` corrupt process state is to restart the entire process on timeout. You can enable this behavior by setting [term_on_timeout][term-on-timeout].
 
-Ruby 2.1 provides a way to defer the result of raising exceptions through the [Thread.handle_interrupt][handle-interrupt] method. This could be used in critical areas of your application code to prevent Rack::Timeout from accidentally wreaking havoc by raising just in the wrong moment. That said, `handle_interrupt` and threads in general are hard to reason about, and detecting all cases where it would be needed in an application is a tall order, and the added code complexity is probably not worth the trouble.
+Ruby 2.1+ provides a way to defer the result of raising exceptions through the [Thread.handle_interrupt][handle-interrupt] method. This low level interface is meant more for library authors than higher level application developers. This interface could be used in critical areas of your application code to prevent Rack::Timeout from accidentally wreaking havoc by raising just in the wrong moment. That said, `handle_interrupt` and threads in general are hard to reason about, and detecting all cases where it would be needed in an application is a tall order, and the added code complexity is probably not worth the trouble.
 
 Your time is better spent ensuring requests run fast and don't need to timeout.
 
 That said, it's something to be aware of, and may explain some eerie wonkiness seen in logs.
 
+[oldest-bug]: https://www.schneems.com/2017/02/21/the-oldest-bug-in-ruby-why-racktimeout-might-hose-your-server/
 [broken-timeout]: http://headius.blogspot.de/2008/02/rubys-threadraise-threadkill-timeoutrb.html
 [handle-interrupt]: http://www.ruby-doc.org/core-2.1.3/Thread.html#method-c-handle_interrupt
 
@@ -33,3 +35,5 @@ Because of the aforementioned issues, it's recommended you set library-specific
 You'll want to set all relevant timeouts to something lower than Rack::Timeout's `service_timeout`. Generally you want them to be at least 1s lower, so as to account for time spent elsewhere during the request's lifetime while still giving libraries a chance to time out before Rack::Timeout.
 
 [ruby-timeouts]: https://github.com/ankane/the-ultimate-guide-to-ruby-timeouts
+[term-on-timeout]: https://github.com/zombocom/rack-timeout/blob/main/doc/settings.md#term-on-timeout
+

doc/settings.md

@@ -3,6 +3,9 @@
 Rack::Timeout has 4 settings, each of which impacts when Rack::Timeout
 will raise an exception, and which type of exception will be raised.
 
+
+Additionally there is a [demo app](https://github.com/zombocom/rack_timeout_demos) that shows the impact of changing settings and how the library behaves when a timeout is hit.
+
 ### Service Timeout
 
 `service_timeout` is the most important setting.
@@ -26,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.
+
+Compatible header string formats are:
+
+- `seconds.milliseconds`, e.g. `1700173924.763` - 10.3 digits (nginx format)
+- `t=seconds.milliseconds`, e.g. `t=1700173924.763` - 10.3 digits, nginx format with [New Relic recommended][new-relic-recommended-format] `t=` prefix
+- `milliseconds`, e.g. `1700173924763` - 13 digits (Heroku format)
+- `t=microseconds`, e.g. `t=1700173924763384` - 16 digits with `t=` prefix (Apache 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 `wait_timeout` handling is skipped entirely.
+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
 
@@ -55,7 +67,7 @@ If your application timeouts fire frequently then [they can cause your applicati
 - [Ruby Application Restart Behavior](https://devcenter.heroku.com/articles/what-happens-to-ruby-apps-when-they-are-restarted)
 - [License to SIGKILL](https://www.sitepoint.com/license-to-sigkill/)
 
-**Puma SIGTERM behavior** When a Puma worker receives a `SIGTERM` it will begin to shut down, but not exit right away. It stops accepting new requests and waits for any existing requests to finish before fully shutting down. This means that only the request that experiences a timeout will be interupted, all other in-flight requests will be allowed to run until they return or also are timed out.
+**Puma SIGTERM behavior** When a Puma worker receives a `SIGTERM` it will begin to shut down, but not exit right away. It stops accepting new requests and waits for any existing requests to finish before fully shutting down. This means that only the request that experiences a timeout will be interrupted, all other in-flight requests will be allowed to run until they return or also are timed out.
 
 After the worker process exists will Puma's parent process know to boot a replacement worker. While one process is restarting, another can still serve requests (if you have more than 1 worker process per server/dyno). Between when a process exits and when a new process boots, there will be a reduction in throughput. If all processes are restarting, then incoming requests will be blocked while new processes boot.
 

lib/rack-timeout.rb

@@ -1,2 +1,2 @@
 require_relative "rack/timeout/base"
-require_relative "rack/timeout/rails" if defined?(Rails) && Rails::VERSION::MAJOR >= 3
+require_relative "rack/timeout/rails" if defined?(Rails) && Rails.const_defined?(:VERSION) && Rails::VERSION::MAJOR >= 3

lib/rack/timeout/core.rb

@@ -100,9 +100,14 @@ def initialize(app, service_timeout:nil, wait_timeout:nil, wait_overtime:nil, se
       @exclude           = exclude == [] ?                        ENV.fetch("RACK_TIMEOUT_EXCLUDE", []) : exclude
       @only              = only == [] ?                           ENV.fetch("RACK_TIMEOUT_ONLY", []) : only
 
-      Thread.main['RACK_TIMEOUT_COUNT'] ||= 0
-      if @term_on_timeout
-        raise "Current Runtime does not support processes" unless ::Process.respond_to?(:fork)
+      if @term_on_timeout && !::Process.respond_to?(:fork)
+        raise(NotImplementedError, <<-MSG)
+The platform running your application does not support forking (i.e. Windows, JVM, etc).
+
+To avoid this error, either specify RACK_TIMEOUT_TERM_ON_TIMEOUT=0 or
+leave it as default (which will have the same result).
+
+MSG
       end
       @app = app
     end
@@ -124,7 +129,7 @@ def call(env)
         seconds_waited          = time_started_service - time_started_wait # how long it took between the web server first receiving the request and rack being able to handle it
         seconds_waited          = 0 if seconds_waited < 0                  # make up for potential time drift between the routing server and the application server
         final_wait_timeout      = wait_timeout + effective_overtime        # how long the request will be allowed to have waited
-        seconds_service_left    = final_wait_timeout - seconds_waited      # first calculation of service timeout (relevant if request doesn't get expired, may be overriden later)
+        seconds_service_left    = final_wait_timeout - seconds_waited      # first calculation of service timeout (relevant if request doesn't get expired, may be overridden later)
         info.wait               = seconds_waited                           # updating the info properties; info.timeout will be the wait timeout at this point
         info.timeout            = final_wait_timeout
 
@@ -154,13 +159,14 @@ def call(env)
       timeout = RT::Scheduler::Timeout.new do |app_thread|  # creates a timeout instance responsible for timing out the request. the given block runs if timed out
         register_state_change.call :timed_out
 
-        message = "Request "
+        message = +"Request "
         message << "waited #{info.ms(:wait)}, then " if info.wait
         message << "ran for longer than #{info.ms(:timeout)} "
         if term_on_timeout
+          Thread.main['RACK_TIMEOUT_COUNT'] ||= 0
           Thread.main['RACK_TIMEOUT_COUNT'] += 1
 
-          if Thread.main['RACK_TIMEOUT_COUNT'] >= @term_on_timeout
+          if Thread.main['RACK_TIMEOUT_COUNT'] >= term_on_timeout
             message << ", sending SIGTERM to process #{Process.pid}"
             Process.kill("SIGTERM", Process.pid)
           else
@@ -188,9 +194,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
@@ -199,11 +205,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.

lib/rack/timeout/logging-observer.rb

@@ -43,7 +43,7 @@ def log_state_change(env)
     info = env[::Rack::Timeout::ENV_INFO_KEY]
     level = STATE_LOG_LEVEL[info.state]
     logger(env).send(level) do
-      s  = "source=rack-timeout"
+      s  = +"source=rack-timeout"
       s << " id="      << info.id           if info.id
       s << " wait="    << info.ms(:wait)    if info.wait
       s << " timeout=" << info.ms(:timeout) if info.timeout