Intermittent Application Error (Rails) without reason

Rails
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

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