Class: Rack::Timeout

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

Defined Under Namespace

Modules: ClassLevelProperties, ExceptionWithEnv, Logger, MonotonicTime, Rollbar 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"
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+)$/

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: false) ⇒ Timeout

Returns a new instance of Timeout.



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

def initialize(app, service_timeout:nil, wait_timeout:nil, wait_overtime:nil, service_past_wait:false)
  @service_timeout   = read_timeout_property service_timeout, 15
  @wait_timeout      = read_timeout_property wait_timeout,    30
  @wait_overtime     = read_timeout_property wait_overtime,   60
  @service_past_wait = service_past_wait
  @app = app
end

Instance Attribute Details

#service_past_wait ⇒ Object (readonly)

Returns the value of attribute service_past_wait.



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

def service_past_wait
  @service_past_wait
end

#service_timeout ⇒ Object (readonly)

Returns the value of attribute service_timeout.



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

def service_timeout
  @service_timeout
end

#wait_overtime ⇒ Object (readonly)

Returns the value of attribute wait_overtime.



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

def wait_overtime
  @wait_overtime
end

#wait_timeout ⇒ Object (readonly)

Returns the value of attribute wait_timeout.



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

def wait_timeout
  @wait_timeout
end

Class Method Details

._read_x_request_start(env) ⇒ Object 



149
150
151
152
153
 
# File 'lib/rack/timeout/core.rb', line 149

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) 


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

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 



164
165
166
167
168
 
# File 'lib/rack/timeout/core.rb', line 164

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) 


176
177
178
179
180
 
# File 'lib/rack/timeout/core.rb', line 176

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



183
184
185
 
# File 'lib/rack/timeout/core.rb', line 183

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

Instance Method Details

#call(env) ⇒ Object 



76
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
 
# File 'lib/rack/timeout/core.rb', line 76

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

  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.



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

def read_timeout_property value, default
  case value
  when nil   ; 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