Search code examples
rubysinatraunicornrainbows

Rainbows worker is being killed after timeout even though it replied

I have a Sinatra app running on Rainbows. I log the following :

before do
  logger.info("#{Process.pid} #{Time.now} #{request.ip} #{request.path_info} #  {params.to_s}")
end

and

after do
  logger.info("#{Process.pid} #{Time.now} #{request.ip} #{request.path_info} #{params.to_s} => #{response.headers['X-API-Status']} (#{response.successful?})")
end

and in my logs I can read:

25988 2012-11-13 11:57:52 +0100 192.168.90.1 /req {"u"=>"810000027"}
25988 2012-11-13 11:57:59 +0100 192.168.90.1 /req {"u"=>"810000027"} => 200 (true)
192.168.90.1 - - [13/Nov/2012 11:57:59] "POST /req HTTP/1.1" **200** 14 7.5862
25988 2012-11-13 11:57:59 +0100 192.168.90.1 /req {"u"=>"810000027"}
25988 2012-11-13 11:57:59 +0100 192.168.90.1 /req {"u"=>"810000027"} => 200 (true)
192.168.90.1 - - [13/Nov/2012 11:57:59] "POST /req HTTP/1.1" 200 14 0.0223
E, [2012-11-13T11:58:04.099913 #25875] ERROR -- : worker=2 PID:**25988** timeout (12s > 11s), killing
E, [2012-11-13T11:58:04.106428 #25875] ERROR -- : reaped #<Process::Status: pid 25988 SIGKILL (signal 9)> worker=2

My worker (pid 25988) is being killed as if it had not responded to the first request... But it has, obviously! It even handled another request (and I use Base concurrency model -> no concurrency)

My Rainbows configuration is:

Rainbows! do
 timeout(10) 
end

listen(3000)
pid('/tmp/rainbows.pid')
stderr_path('/var/log/rainbows.log')
stdout_path('/var/log/rainbows.log')
working_directory('/opt/app')
worker_processes(4)

Do you have any idea of what happens ? Or how I could investigate further ? Thanks !

Solution

  • Actually the issue lied in the request that was "kept alive" too long by the client (flash). Apparently there is no way to properly close the tcp connection in AS3...

    I fixed my issue with:

    Rainbows! do
  keepalive_timeout(0)
end

    which seems appropriate for me anyway.