Rails - Feb 2007 - Intermittent Application Error (Rails) without reason

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


--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---

> 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


--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---

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

On Feb 20, 2007, at 1:58 PM, Aaron wrote:
>
>> 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
>
>
> 
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---

> 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


--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---