Class: Rack::Timeout

Inherits:
Object
  • Object
show all
Defined in:
lib/rack/timeout.rb,
lib/rack/timeout/logger.rb

Defined Under Namespace

Classes: Error, Railtie, RequestDetails, RequestExpiryError, RequestTimeoutError, StageChangeLoggingObserver

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+)$/

Class Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(app) ⇒ Timeout

Returns a new instance of Timeout.



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

def initialize(app)
  @app = app
end

Class Attribute Details

.service_past_wait ⇒ Object

when false, reduces the request’s computed timeout from the service_timeout value if the complete request lifetime (wait + service) would have been longer than wait_timeout (+ wait_overtime when applicable). When true, always uses the service_timeout value.



56
57
58
 
# File 'lib/rack/timeout.rb', line 56

def service_past_wait
  @service_past_wait
end

Class Method Details

._read_x_request_start(env) ⇒ Object 



135
136
137
138
139
 
# File 'lib/rack/timeout.rb', line 135

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) 


143
144
145
146
147
148
 
# File 'lib/rack/timeout.rb', line 143

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 



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

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) 


162
163
164
165
166
 
# File 'lib/rack/timeout.rb', line 162

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

.set_timeout_property(property_name, value) ⇒ Object 



32
33
34
35
36
37
38
 
# File 'lib/rack/timeout.rb', line 32

def set_timeout_property(property_name, value)
  unless value == false || (value.is_a?(Numeric) && value >= 0)
    raise ArgumentError, "value for #{property_name} should be false, zero, or a positive number."
  end
  value = false if value && value.zero? # zero means we're disabling the feature
  instance_variable_set("@#{property_name}", value)
end

.timeout_property(property_name, start_value) ⇒ Object 



40
41
42
43
44
45
46
 
# File 'lib/rack/timeout.rb', line 40

def timeout_property(property_name, start_value)
  singleton_class.instance_eval do
    attr_reader property_name
    define_method("#{property_name}=") { |v| set_timeout_property(property_name, v) }
  end
  set_timeout_property(property_name, start_value)
end

.unregister_state_change_observer(id) ⇒ Object

Removes the observer with the given id



169
170
171
 
# File 'lib/rack/timeout.rb', line 169

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

Instance Method Details

#call(env) ⇒ Object 



65
66
67
68
69
70
71
72
73
74
75
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
 
# File 'lib/rack/timeout.rb', line 65

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 time the request started being processed by rack
  time_started_wait    = RT._read_x_request_start(env) # The time the request was initially receibed by the web server (if available)
  effective_overtime   = (RT.wait_overtime && RT._request_has_body?(env)) ? RT.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 && RT.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      = RT.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, "Request older than #{final_wait_timeout} seconds."
    end
  end

  # pass request through if service_timeout is false (i.e., don't time it out at all.)
  return @app.call(env) unless RT.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 = RT.service_timeout # nice and simple, when service_past_wait is true, not so much otherwise:
  info.timeout = seconds_service_left if !RT.service_past_wait && seconds_service_left && seconds_service_left > 0 && seconds_service_left < RT.service_timeout

  RT._set_state! env, :ready
  begin
    app_thread     = Thread.current
    timeout_thread = Thread.start do
      loop do
        info.service  = Time.now - time_started_service
        sleep_seconds = [1 - (info.service % 1), info.timeout - info.service].min
        break if sleep_seconds <= 0
        RT._set_state! env, :active
        sleep(sleep_seconds)
      end
      RT._set_state! env, :timed_out
      app_thread.raise(RequestTimeoutError, "Request #{"waited #{info.ms(:wait)} seconds, then " if info.wait}ran for longer than #{info.ms(:timeout)}")
    end
    response = @app.call(env)
  ensure
    timeout_thread.kill
    timeout_thread.join
  end

  info.service = Time.now - time_started_service
  RT._set_state! env, :completed
  response
end