Demonstrate that queue time is not included in Unicorn's request timeout

README.md

Unicorn timeout test

Demonstrate that queue time is not included in Unicorn's timeout

Output

$ ruby unicorn_timeout_test.rb
starting unicorn {:worker_processes=>2, :timeout=>3}
[client] concurrently requesting /sleep/6, /sleep/4, /sleep/2, /sleep/0
[worker] got /sleep/6 after 0.00 sec queue, sleeping 6 sec..
[worker] got /sleep/4 after 0.00 sec queue, sleeping 4 sec..
[client] EOF after 3.91 sec waiting for /sleep/6
[client] EOF after 3.92 sec waiting for /sleep/4
[worker] got /sleep/0 after 3.91 sec queue, sleeping 0 sec..
[worker] got /sleep/2 after 3.91 sec queue, sleeping 2 sec..
[client] /sleep/0 200 OK after 3.92 sec
[client] /sleep/2 200 OK after 5.92 sec

Output (annotated)

$ ruby unicorn_timeout_test.rb

starting unicorn {:worker_processes=>2, :timeout=>3}
    run a unicorn server on localhost with 2 worker processes, 3 second timeout

[client] concurrently requesting /sleep/6, /sleep/4, /sleep/2, /sleep/0
    send multiple requests by forking a subprocess, spawning a thread per request

[worker] got /sleep/6 after 0.00 sec queue, sleeping 6 sec..
    worker A got one of the requests immediately, sleeps for requested time.
    we expect 6 seconds to exceed unicorn's timeout.

[worker] got /sleep/4 after 0.00 sec queue, sleeping 4 sec..
    worker B got one of the requests immediately.
    we expect 4 seconds to exceed unicorn's timeout.

[client] EOF after 3.91 sec waiting for /sleep/6
    unicorn kills worker A before 6 seconds elapses.
    the client sees EOF error; no HTTP response.
    worker C is spawned

[client] EOF after 3.92 sec waiting for /sleep/4
    unicorn kills worker B before 4 seconds elapses.
    the client sees EOF error; no HTTP response.
    worker D is spawned

[worker] got /sleep/0 after 3.91 sec queue, sleeping 0 sec..
    worker C gets request that has been waiting a while, responds immediately

[worker] got /sleep/2 after 3.91 sec queue, sleeping 2 sec..
    worker D gets request that has been waiting a while, responds after 2 seconds

[client] /sleep/0 200 OK after 3.92 sec
    client sees worker C response despite total time exceeding timeout

[client] /sleep/2 200 OK after 5.92 sec
    client sees worker D response despite total time exceeding timeout

Output (including Unicorn's log)

$ ruby unicorn_timeout_test.rb
starting unicorn {:worker_processes=>2, :timeout=>3}
I, [2018-11-13T00:18:24.564196 #26350]  INFO -- : listening on addr=0.0.0.0:11235 fd=9
I, [2018-11-13T00:18:24.564535 #26350]  INFO -- : worker=0 spawning...
I, [2018-11-13T00:18:24.565388 #26350]  INFO -- : worker=1 spawning...
I, [2018-11-13T00:18:24.566613 #26350]  INFO -- : master process ready
I, [2018-11-13T00:18:24.567199 #26352]  INFO -- : worker=0 spawned pid=26352
I, [2018-11-13T00:18:24.568138 #26352]  INFO -- : worker=0 ready
I, [2018-11-13T00:18:24.568565 #26353]  INFO -- : worker=1 spawned pid=26353
I, [2018-11-13T00:18:24.569715 #26353]  INFO -- : worker=1 ready
[client] concurrently requesting /sleep/6, /sleep/4, /sleep/2, /sleep/0
[worker] got /sleep/4 after 0.00 sec queue, sleeping 4 sec..
[worker] got /sleep/2 after 0.00 sec queue, sleeping 2 sec..
[worker] got /sleep/0 after 2.01 sec queue, sleeping 0 sec..
[worker] got /sleep/6 after 2.00 sec queue, sleeping 6 sec..
[client] /sleep/2 200 OK after 2.02 sec
[client] /sleep/0 200 OK after 2.01 sec
E, [2018-11-13T00:18:28.571244 #26350] ERROR -- : worker=1 PID:26353 timeout (4s > 3s), killing
[client] EOF after 3.90 sec waiting for /sleep/4
E, [2018-11-13T00:18:28.573287 #26350] ERROR -- : reaped #<Process::Status: pid 26353 SIGKILL (signal 9)> worker=1
I, [2018-11-13T00:18:28.573517 #26350]  INFO -- : worker=1 spawning...
I, [2018-11-13T00:18:28.579050 #26354]  INFO -- : worker=1 spawned pid=26354
I, [2018-11-13T00:18:28.580301 #26354]  INFO -- : worker=1 ready
E, [2018-11-13T00:18:30.583285 #26350] ERROR -- : worker=0 PID:26352 timeout (4s > 3s), killing
[client] EOF after 5.92 sec waiting for /sleep/6
E, [2018-11-13T00:18:30.586049 #26350] ERROR -- : reaped #<Process::Status: pid 26352 SIGKILL (signal 9)> worker=0
I, [2018-11-13T00:18:30.586495 #26350]  INFO -- : worker=0 spawning...
I, [2018-11-13T00:18:30.692668 #26350]  INFO -- : reaped #<Process::Status: pid 26355 exit 0> worker=0
I, [2018-11-13T00:18:30.693124 #26350]  INFO -- : reaped #<Process::Status: pid 26354 exit 0> worker=1
I, [2018-11-13T00:18:30.693883 #26350]  INFO -- : reaped #<Process::Status: pid 26351 exit 0> worker=unknown
I, [2018-11-13T00:18:30.694091 #26350]  INFO -- : master complete

Conclusion

Request queueing time within unicorn is not included in timeout

unicorn_timeout_test.rb

require "net/http"
require "unicorn"
require "uri"

PORT = 11235
OPTIONS = {
  listeners: [PORT],
  stderr_path: "/dev/null",
  timeout: 3,
  worker_processes: 2,
}

def get(path)
  t = Time.now
  Net::HTTP.start("localhost", PORT, max_retries: 0) do |http|
    req = Net::HTTP::Get.new(path).tap { |r| r["Timestamp"] = "%.8f" % Time.now }
    resp = http.request(req)
    puts("[client] #{path} #{resp.code} #{resp.message}")
  end
rescue EOFError
  puts("[client] EOF after %.2f sec waiting for #{path}" % [Time.now - t])
end

fork do
  sleep 0.1
  paths = [6, 4, 2, 0].map { |i| "/sleep/#{i}" }
  puts("[client] concurrently requesting #{paths.join(", ")}")
  paths.map { |p| Thread.new { get(p) } }.each(&:join)
  Process.kill(:TERM, Process.ppid) # stop unicorn
end

puts("starting unicorn %s" % OPTIONS.slice(:worker_processes, :timeout))
app = ->(env) do
  path = env["REQUEST_PATH"]
  queue_time = Time.now.to_f - Float(env["HTTP_TIMESTAMP"])
  sleep = Integer(path.match(%r{\A/sleep/(\d+)\z})&.[](1)&.to_i || 1)
  puts("[worker] got %s after %.2f sec queue, sleeping %d sec.." % [path, queue_time, sleep])
  sleep(sleep)
  [200, {}, []]
end
Unicorn::HttpServer.new(app, OPTIONS).start.join