Class: Rack::Timeout

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

Defined Under Namespace

Modules: AssertTypes, ExceptionWithEnv, Logger, 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+)$/

Class Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(app) ⇒ Timeout

Returns a new instance of Timeout.



74
75
76
 
# File 'lib/rack/timeout/core.rb', line 74

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.



70
71
72
 
# File 'lib/rack/timeout/core.rb', line 70

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

.set_timeout_property(property_name, value) ⇒ Object 



46
47
48
49
50
51
52
 
# File 'lib/rack/timeout/core.rb', line 46

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 



54
55
56
57
58
59
60
 
# File 'lib/rack/timeout/core.rb', line 54

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



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 



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

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 received 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.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 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                            # 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 = Time.now - time_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-reaise RequestTimeoutException as RequestTimeoutError
    end
  end

  register_state_change.call :completed
  response
end