Class: Rack::Timeout

Inherits:
Object
  • Object
show all
Includes:
MonotonicTime
Defined in:
lib/rack/timeout/core.rb,
lib/rack/timeout/support/namespace.rb

Defined Under Namespace

Modules: ExceptionWithEnv, Logger, MonotonicTime Classes: Error, Railtie, RequestDetails, RequestExpiryError, RequestTimeoutError, RequestTimeoutException, Scheduler, StateChangeLoggingObserver

Constant Summary collapse

VALID_STATES = 
[
:expired,   # The request was too old by the time it reached rack (see wait_timeout, wait_overtime)
:ready,     # We're about to start processing this request
:active,    # This request is currently being handled
:timed_out, # This request has run for too long and we're raising a timeout error in it
:completed, # We're done with this request (also set after having timed out a request)
]
ENV_INFO_KEY =

key under which each request’s RequestDetails instance is stored in its env.

"rack-timeout.info".freeze
HTTP_X_REQUEST_ID =

key where request id is stored if generated by upstream client/proxy

"HTTP_X_REQUEST_ID".freeze
ACTION_DISPATCH_REQUEST_ID =

key where request id is stored if generated by action dispatch

"action_dispatch.request_id".freeze
RT =

shorthand reference

self
RX_NGINX_X_REQUEST_START =

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.

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. [1]: nginx.org/en/docs/http/ngx_http_log_module.html#var_msec [2]: docs.newrelic.com/docs/apm/other-features/request-queueing/request-queue-server-configuration-examples#nginx [3]: devcenter.heroku.com/articles/http-routing#heroku-headers [4]: httpd.apache.org/docs/current/mod/mod_headers.html#header

This is a code extraction for readability, this method is only called from a single point.

/^(?:t=)?(\d+)\.(\d{3})$/
RX_HEROKU_X_REQUEST_START = 
/^(\d+)$/
HTTP_X_REQUEST_START = 
"HTTP_X_REQUEST_START".freeze

Instance Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Methods included from MonotonicTime

#fsecs_java, #fsecs_mono

Constructor Details

#initialize(app, service_timeout: nil, wait_timeout: nil, wait_overtime: nil, service_past_wait: "not_specified") ⇒ Timeout

Returns a new instance of Timeout.



67
68
69
70
71
72
73
 
# File 'lib/rack/timeout/core.rb', line 67

def initialize(app, service_timeout:nil, wait_timeout:nil, wait_overtime:nil, service_past_wait:"not_specified")
  @service_timeout   = read_timeout_property service_timeout, ENV.fetch("RACK_TIMEOUT_SERVICE_TIMEOUT", 15).to_i
  @wait_timeout      = read_timeout_property wait_timeout,    ENV.fetch("RACK_TIMEOUT_WAIT_TIMEOUT", 30).to_i
  @wait_overtime     = read_timeout_property wait_overtime,   ENV.fetch("RACK_TIMEOUT_WAIT_OVERTIME", 60).to_i
  @service_past_wait = service_past_wait == "not_specified" ? ENV.fetch("RACK_TIMEOUT_SERVICE_PAST_WAIT", false).to_s != "false" : service_past_wait
  @app = app
end

Instance Attribute Details

#service_past_wait ⇒ Object (readonly)

Returns the value of attribute service_past_wait.



61
62
63
 
# File 'lib/rack/timeout/core.rb', line 61

def service_past_wait
  @service_past_wait
end

#service_timeout ⇒ Object (readonly)

Returns the value of attribute service_timeout.



61
62
63
 
# File 'lib/rack/timeout/core.rb', line 61

def service_timeout
  @service_timeout
end

#wait_overtime ⇒ Object (readonly)

Returns the value of attribute wait_overtime.



61
62
63
 
# File 'lib/rack/timeout/core.rb', line 61

def wait_overtime
  @wait_overtime
end

#wait_timeout ⇒ Object (readonly)

Returns the value of attribute wait_timeout.



61
62
63
 
# File 'lib/rack/timeout/core.rb', line 61

def wait_timeout
  @wait_timeout
end

Class Method Details

._read_x_request_start(env) ⇒ Object 



151
152
153
154
155
 
# File 'lib/rack/timeout/core.rb', line 151

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

._request_has_body?(env) ⇒ Boolean

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. This is a code extraction for readability, this method is only called from a single point.

Returns:

  • (Boolean) 


159
160
161
162
163
164
 
# File 'lib/rack/timeout/core.rb', line 159

def self._request_has_body?(env)
  return true  if env["HTTP_TRANSFER_ENCODING"] == "chunked"
  return false if env["CONTENT_LENGTH"].nil?
  return false if env["CONTENT_LENGTH"].to_i.zero?
  true
end

._set_state!(env, state) ⇒ Object 



166
167
168
169
170
 
# File 'lib/rack/timeout/core.rb', line 166

def self._set_state!(env, state)
  raise "Invalid state: #{state.inspect}" unless VALID_STATES.include? state
  env[ENV_INFO_KEY].state = state
  notify_state_change_observers(env)
end

.register_state_change_observer(id, &callback) ⇒ Object

Registers a block to be called back when a request changes state in rack-timeout. The block will receive the request’s env.

‘id` is anything that uniquely identifies this particular callback, mostly so it may be removed via `unregister_state_change_observer`.

Raises:

  • (RuntimeError) 


178
179
180
181
182
 
# File 'lib/rack/timeout/core.rb', line 178

def self.register_state_change_observer(id, &callback)
  raise RuntimeError, "An observer with the id #{id.inspect} is already set." if @state_change_observers.key? id
  raise ArgumentError, "A callback block is required." unless callback
  @state_change_observers[id] = callback
end

.unregister_state_change_observer(id) ⇒ Object

Removes the observer with the given id



185
186
187
 
# File 'lib/rack/timeout/core.rb', line 185

def self.unregister_state_change_observer(id)
  @state_change_observers.delete(id)
end

Instance Method Details

#call(env) ⇒ Object 



77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
 
# File 'lib/rack/timeout/core.rb', line 77

def call(env)
  info      = (env[ENV_INFO_KEY] ||= RequestDetails.new)
  info.id ||= env[HTTP_X_REQUEST_ID] || env[ACTION_DISPATCH_REQUEST_ID] || SecureRandom.uuid

  time_started_service = Time.now                      # The wall time the request started being processed by rack
  ts_started_service   = fsecs                         # The monotonic time the request started being processed by rack
  time_started_wait    = RT._read_x_request_start(env) # The time the request was initially received by the web server (if available)
  effective_overtime   = (wait_overtime && RT._request_has_body?(env)) ? wait_overtime : 0 # additional wait timeout (if set and applicable)
  seconds_service_left = nil

  # if X-Request-Start is present and wait_timeout is set, expire requests older than wait_timeout (+wait_overtime when applicable)
  if time_started_wait && wait_timeout
    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)
    info.wait, info.timeout = seconds_waited, final_wait_timeout       # updating the info properties; info.timeout will be the wait timeout at this point
    if seconds_service_left <= 0 # expire requests that have waited for too long in the queue (as they are assumed to have been dropped by the web server / routing layer at this point)
      RT._set_state! env, :expired
      raise RequestExpiryError.new(env), "Request older than #{info.ms(:timeout)}."
    end
  end

  # pass request through if service_timeout is false (i.e., don't time it out at all.)
  return @app.call(env) unless service_timeout

  # compute actual timeout to be used for this request; if service_past_wait is true, this is just service_timeout. If false (the default), and wait time was determined, we'll use the shortest value between seconds_service_left and service_timeout. See comment above at service_past_wait for justification.
  info.timeout = service_timeout # nice and simple, when service_past_wait is true, not so much otherwise:
  info.timeout = seconds_service_left if !service_past_wait && seconds_service_left && seconds_service_left > 0 && seconds_service_left < service_timeout

  RT._set_state! env, :ready                            # we're good to go, but have done nothing yet

  heartbeat_event = nil                                 # init var so it's in scope for following proc
  register_state_change = ->(status = :active) {        # updates service time and state; will run every second
    heartbeat_event.cancel! if status != :active        # if the request is no longer active we should stop updating every second
    info.service = fsecs - ts_started_service           # update service time
    RT._set_state! env, status                          # update status
  }
  heartbeat_event = RT::Scheduler.run_every(1) { register_state_change.call :active }  # start updating every second while active; if log level is debug, this will log every sec

  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
    app_thread.raise(RequestTimeoutException.new(env), "Request #{"waited #{info.ms(:wait)}, then " if info.wait}ran for longer than #{info.ms(:timeout)}")
  end

  response = timeout.timeout(info.timeout) do           # perform request with timeout
    begin  @app.call(env)                               # boom, send request down the middleware chain
    rescue RequestTimeoutException => e                 # will actually hardly ever get to this point because frameworks tend to catch this. see README for more
      raise RequestTimeoutError.new(env), e.message, e.backtrace  # but in case it does get here, re-raise RequestTimeoutException as RequestTimeoutError
    ensure
      register_state_change.call :completed
    end
  end

  response
end

#read_timeout_property(value, default) ⇒ Object

helper methods to read timeout properties. Ensure they’re always positive numbers or false. When set to false (or 0), their behaviour is disabled.



50
51
52
53
54
55
56
57
58
59
 
# File 'lib/rack/timeout/core.rb', line 50

def read_timeout_property value, default
  case value
  when nil   ; read_timeout_property default, default
  when false ; false
  when 0     ; false
  else
    value.is_a?(Numeric) && value > 0 or raise ArgumentError, "value #{value.inspect} should be false, zero, or a positive number."
    value
  end
end