Show request details on timeout killing

Show request details on timeout killing

[Bráulio Bhavamitra]

Hello all,

Currently, unicorn kills a worker that reached timeout with the
following message:
E, [2014-12-04T19:12:23.646053 #32612] ERROR -- : worker=4 PID:11911
timeout (61s > 60s), killing

How can I see which URL was being processed by that worker?

I need to identify the problematic request.

cheers,
bráulio

Re: Show request details on timeout killing

[Eric Wong]

Bráulio Bhavamitra <braulio@eita.org.br> wrote:
> Hello all,
> 
> Currently, unicorn kills a worker that reached timeout with the
> following message:
> E, [2014-12-04T19:12:23.646053 #32612] ERROR -- : worker=4 PID:11911
> timeout (61s > 60s), killing
> 
> How can I see which URL was being processed by that worker?

I suggest adding better logging to your app, perhaps to log when
requests start.

> I need to identify the problematic request.

And to use application-level timeouts, see:

	http://unicorn.bogomips.org/Application_Timeouts.html

The SIGKILL timeout in unicorn is only a last resort when the Ruby VM
is broken beyond repair and cannot respond to any signals[1].

[1] SIGKILL and SIGSTOP are special signals which the kernel
    enforces, Ruby has no chance to block/catch/ignore them.

Re: Show request details on timeout killing

[Bráulio Bhavamitra]

Ok Eric, the problem is that some requests are in a infinite loop,
consuming a lot of resources.

Rails/nginx already log many request on production.log/access.log, but
I can't know which of them timeouted.

cheers,
bráulio

On Thu, Dec 4, 2014 at 10:06 PM, Eric Wong <e@80x24.org> wrote:
> Bráulio Bhavamitra <braulio@eita.org.br> wrote:
>> Hello all,
>>
>> Currently, unicorn kills a worker that reached timeout with the
>> following message:
>> E, [2014-12-04T19:12:23.646053 #32612] ERROR -- : worker=4 PID:11911
>> timeout (61s > 60s), killing
>>
>> How can I see which URL was being processed by that worker?
>
> I suggest adding better logging to your app, perhaps to log when
> requests start.
>
>> I need to identify the problematic request.
>
> And to use application-level timeouts, see:
>
>         http://unicorn.bogomips.org/Application_Timeouts.html
>
> The SIGKILL timeout in unicorn is only a last resort when the Ruby VM
> is broken beyond repair and cannot respond to any signals[1].
>
> [1] SIGKILL and SIGSTOP are special signals which the kernel
>     enforces, Ruby has no chance to block/catch/ignore them.

Re: Show request details on timeout killing

[Eric Wong]

Bráulio Bhavamitra <braulio@eita.org.br> wrote:
> Rails/nginx already log many request on production.log/access.log, but
> I can't know which of them timeouted.

Can't Rails log when a request starts and finishes?
(I haven't touched Rails in years)

Look for starts on PIDs without finishes.

Something along the lines of the following middlware (totally untested):

    class LogBeforeAfter
      def initialize(app)
        @app = app
      end

      def call(env)
        env["rack.logger"].info("#$$ start #{env['PATH_INFO']}")
        response = @app.call(env)
        env["rack.logger"].info("#$$   end #{env['PATH_INFO']}")
        response
      end
    end

    -------------- config.ru ---------------
    use LogBeforeAfter
    # other middlewares...
    run YourApp.new

See Rack::CommonLogger source for more examples/detail.