Intermittent Application Error (Rails) without reason

rubyonrails-talk
1

Hey everyone:

I've got an intermittent Application Error (Rails) that doesn't seem possible. I have a method in my controller seems to execute completely, but I still get a page that says Application Error (Rails).

I know that the method executes completely because I have logging statements before and after each line of code:

:     logger.warn("Starting render.")     render :action => 'recipients', :layout => 'highlights'     logger.warn("Finished render.")   end

In my log file, I see "Starting render." and "Finished render." so I know that it executed fine. It succeeds about 80% of the time and I see the page recipients.html. However, 20% of the time I get the dreaded Application Error (Rails) message.

Here's some additional background about the method which may be helpful. The method is e-mailing a bunch of people and takes about 70 seconds to finish. Regardless of the result page, everyone in my list is sent the e-mail. I've wrapped the mailing process in a begin rescue block and trap for any exception, so I'm confident that any mail issues won't affect the execution. Log files support that conclusion.

Does anyone have any idea why or how a controller method can execute fully, including a render call, and still intermittently cause a Application Error?

Thanks,

-Anthony

2

I know that the method executes completely because I have logging statements before and after each line of code:

:     logger.warn("Starting render.")     render :action => 'recipients', :layout => 'highlights'     logger.warn("Finished render.")   end

In my log file, I see "Starting render." and "Finished render." so I know that it executed fine.

Anthony,

The logger lines above will execute no matter what happens with the render. If you look at the logs you'll notice that the two logger messages print before the render even starts.

Do you see any error messages in the logs when this happens? My bet is that whatever app you are using to load-balance (pound?) is timing out waiting for a response from rails. You can either up your timeout threshold (easier) or offload the email to a background process (better).

Aaron

3

Aaron:

Thanks for responding. Here's the relevant output from my logs:

BriefingsController#announce_availability: Starting render. Rendering actionrecipientslayoutfalse within layouts/highlights Rendering briefings/recipients BriefingsController#announce_availability: Finishing render. Completed in 70.56334 (0 reqs/sec) | Rendering: 0.37582 (0%) | DB:
0.03631 (0%) | 200 OK [http://www.example.com/app/briefings/ announce_availability/2007/02/20]

So, the two logger messages are actually _around_ the rendering. I
don't know why you expected them to be before the rendering, but it
looks like it's happening nonetheless. I even get a 200 http response
code!

Assuming you're right and that there's some kind of timeout going on,
allow me to explain my setup so that others might benefit from this.
I'm running Apache 1.3.x and fastcgi. In httpd.conf, there is a
FastCgiServer directive with a parameter called -idle-timeout. I've
bumped it up from 60s to 120s.

Upon further sleuthing around, I checked the apache error logs, and
it seems that the events were logged there. According to the docs for
the FastCgiServer directive, -idle-timeout is the number of seconds
of application inactivity allowed before the request is aborted and
the event is logged at the error LogLevel. I guess that's why the
errors get logged at the apache level, and not the rails log. Here's
the output of the apache log, in case anyone does a search on the
error message:

[Tue Feb 20 10:33:20 2007] [error] [client 166.3.13.58] FastCGI: comm
with server "/home/client/site/app/dispatch.fcgi" aborted: idle
timeout (60 sec) [Tue Feb 20 10:33:20 2007] [error] [client 166.3.13.58] FastCGI:
incomplete headers (0 bytes) received from server "/home/client/site/ app/dispatch.fcgi"

I'll keep my fingers crossed and let everyone know if this does not
work.

Thanks again,

-Anthony

4

So, the two logger messages are actually _around_ the rendering. I don't know why you expected them to be before the rendering, but it looks like it's happening nonetheless. I even get a 200 http response code!

That's interesting. I tested this out with a controller rendering an rhtml view and the logger messages printed before the render. But you must be rendering from an ActionMailer model, maybe that works differently?

Assuming you're right and that there's some kind of timeout going on, allow me to explain my setup so that others might benefit from this. I'm running Apache 1.3.x and fastcgi. In httpd.conf, there is a FastCgiServer directive with a parameter called -idle-timeout. I've bumped it up from 60s to 120s.

I bet that's it. In your original post you said the request took ~70 seconds which is close enough to 60 for it to work some of the time.

Aaron