CODEWITHSUNDEEP
ruby-on-railsheroku
Keith Schacht
Keith Schacht

Reputation: 1993

Interpreting heroku logs, is worker killed prematurely?

I'm trying to debug an issue with workers and I saw this message in my log file:

2013-07-14T21:59:07.024756+00:00 app[web.1]: E, [2013-07-14T14:59:07.024559 #2] ERROR -- : worker=1 PID:261 timeout (30s > 29s), killing
2013-07-14T21:59:07.067325+00:00 app[web.1]: E, [2013-07-14T14:59:07.066999 #2] ERROR -- : reaped #<Process::Status: pid 261 SIGKILL (signal 9)> worker=1
2013-07-14T21:59:07.070701+00:00 heroku[router]: at=error code=H13 desc="Connection closed without response" method=POST path=/photos/687 host=dev.tacktile.org fwd="199.83.223.92" dyno=web.1 connect=8ms service=29345ms status=503 bytes=0
2013-07-14T21:59:07.898048+00:00 app[web.1]: I, [2013-07-14T14:59:07.897739 #269]  INFO -- : worker=1 ready

If I'm reading this correctly, my worker was killed because it took longer than 30 seconds. I thought only web responses got killed if longer than 30 seconds. I'm putting this task into a delayed job and processing it with a worker because I know it's slow.

I hope I'm misunderstanding something.

Upvotes: 2

Views: 1020

Answers (2)

Nitzan Shaked
Nitzan Shaked

Reputation: 13598

I'm not a Ruby on Rails expert, but it seems like what you call "worker" is actually a web process (as evident by the dyno name, web.1). I am guessing you use Unicorn, which spawns several processes, each dealing with a single web request at a time. Each such process is termed a "worker", I guess, so it's really a matter of terminology.

As to why it happens: could it be that your web path actually waits for your real worker to complete the request, and thus it too is taking >30sec?

Upvotes: 1

Jon Mountjoy
Jon Mountjoy

Reputation: 4526

Your log indicates dyno=web.1 - so it looks like the web dyno connection was terminated after 30 seconds, not a worker dyno like you indicate. Have you read the note attached to the definition of the h13 error that indicates:

One example where this might happen is when a Unicorn web server is configured with a timeout shorter than 30s and a request has not been processed by a worker before the timeout happens. In this case, Unicorn closes the connection before any data is written, resulting in an H13.

Perhaps that's related?

PS. Editing my answer I see by "worker" you mean "Unicorn worker" I guess? Looks like your unicorn worker died for some reason (which is perhaps why you got the H13). Heroku won't explicitly kill a sub-process like that AFAIK.

Upvotes: 4

Related Questions