Is it possible to log better info in timeouts?

Is it possible to log better info in timeouts?

[Carlos Peñas]

Hi!

Recently we had an issue with an external service for an app served with
unicorn. And some of our requests died with unicorn's timeout because a
not properly secured call to this external service. We had 20s
timeout but in production with ten worker and a big percent of urls
hitting external services 20 secons of timeout sooner or later brings
down the entire site.

in the logs when this hapens this line is left for debugging:

E, [2013-12-25T23:56:49.363426 #26324] ERROR -- : worker=2 PID:27956 timeout (21s > 20s), killing
E, [2014-12-25T23:56:49.396005 #26324] ERROR -- : reaped #<Process::Status: pid 27956 SIGKILL (signal 9)> worker=2


Is it possible to opt to print to the error log some other info perhaps
the bactrace of the process or the offending request?

Even better whould be possible to hack a watchdog that could log "slow
requests" like mysql slow_queries?

I'm asking after look a bit the code but it's a bit far away for my
skills right now.

Thanks.

-- 
Carlos Peñas San José
carlos@adoptales.es

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: Is it possible to log better info in timeouts?

[Eric Wong]

Carlos Peñas <theistian@gmx.com> wrote:
> Recently we had an issue with an external service for an app served with
> unicorn. And some of our requests died with unicorn's timeout because a
> not properly secured call to this external service. We had 20s
> timeout but in production with ten worker and a big percent of urls
> hitting external services 20 secons of timeout sooner or later brings
> down the entire site.
> 
> in the logs when this hapens this line is left for debugging:
> 
> E, [2013-12-25T23:56:49.363426 #26324] ERROR -- : worker=2 PID:27956 timeout (21s > 20s), killing
> E, [2014-12-25T23:56:49.396005 #26324] ERROR -- : reaped #<Process::Status: pid 27956 SIGKILL (signal 9)> worker=2
> 
> 
> Is it possible to opt to print to the error log some other info perhaps
> the bactrace of the process or the offending request?

The SIGKILL sent by the master isn't avoidable/trapable in userspace,
the KILL-ed process has no chance to dump a backtrace.

> Even better whould be possible to hack a watchdog that could log "slow
> requests" like mysql slow_queries?

You need to do this in your application.  The timeout in unicorn is a
last resort: http://unicorn.bogomips.org/Application_Timeouts.html
I don't encourage relying on the unicorn timeout, it's a hack for broken
libraries or fatal bugs in Ruby (which are rarer nowadays).
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying