JRuby

Random Empty Response with Rails 2.0

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: None
  • Fix Version/s: JRuby 1.1RC2
  • Component/s: Rails WAR Deployment
  • Labels:
    None
  • Environment:
    java version "1.6.0_03"
    Java(TM) SE Runtime Environment (build 1.6.0_03-b05)
    Java HotSpot(TM) Server VM (build 1.6.0_03-b05, mixed mode)
    Ubuntu 7.10
  • Number of attachments :
    1

Description

Rails 2.0 app works fine on C Ruby & Webbrick, but seemingly frequently responds with empty page bodies.

Saw behavior in 1.0.3 and verified that it is also in trunk JRuby (as of 03-JAN) & rails-integrations project (goldspike) r864.

Example headers:

#### Good Response

http://localhost:8080/nedss/cmrs/1

GET /nedss/cmrs/1 HTTP/1.1
Host: localhost:8080
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.11) Gecko/20071204 Ubuntu/7.10 (gutsy) Firefox/2.0.0.11
Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: _nedss_session=BAh7ByIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo%250ASGFzaHsABjoKQHVzZWR7ADoMY3NyZl9pZCIlNTIyM2FjNGEzY2E2MDAzMTg5%250AMTM5MTZlNGEwY2M2YjU%253D--db5074183aa40e86f68b88f8784e0143a20930d1

HTTP/1.x 200 OK
Server: Apache-Coyote/1.1
Cache-Control: private, max-age=0, must-revalidate
X-Runtime: 0.07500
Etag: "3f1cf0aadcaee7a89c477f5f93bc301b"
Content-Type: text/html;charset=utf-8
Content-Length: 3674
Date: Fri, 04 Jan 2008 01:40:32 GMT
----------------------------------------------------------

#### Blank Response (Bad)
http://localhost:8080/nedss/cmrs

GET /nedss/cmrs HTTP/1.1
Host: localhost:8080
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.11) Gecko/20071204 Ubuntu/7.10 (gutsy) Firefox/2.0.0.11
Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Referer: http://localhost:8080/nedss/cmrs/1
Cookie: _nedss_session=BAh7ByIKZmxhc2hJQzonQWN0aW9uQ29udHJvbGxlcjo6Rmxhc2g6OkZsYXNo%250ASGFzaHsABjoKQHVzZWR7ADoMY3NyZl9pZCIlNTIyM2FjNGEzY2E2MDAzMTg5%250AMTM5MTZlNGEwY2M2YjU%253D--db5074183aa40e86f68b88f8784e0143a20930d1
If-None-Match: "afa932214d05665054faadf7ebaea1d0"

HTTP/1.x 200 OK
Server: Apache-Coyote/1.1
Content-Length: 0
Date: Fri, 04 Jan 2008 01:41:04 GMT
---------------------------------------------------------- 

Stefan Thomas Landro reports seeing similar behavior:

I'm seeing the same issue on my Windows box in both tomcat and jetty. Seems like a header issue:

In this case I get an empty body after doing a standard refresh (f5) in my browser:

http://localhost:8080/bp_rbac/sessions/login_rbac

GET /bp_rbac/sessions/login_rbac HTTP/1.1
Host: localhost:8080
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.11 ) Gecko/20071127 Firefox/2.0.0.11
Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q= 0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: JSESSIONID=BB9A6322ACCF6F68C6C40E1D9F86CA04; _bp_rbac_session_id=f65bf4157dac17f9539e5c4e051648ab
If-None-Match: "c87bc98ba6bf6a36ef0e4bb4863bc908"
Cache-Control: max-age=0

HTTP/1.x 200 OK
Server: Apache-Coyote/1.1
Content-Length: 0
Date: Thu, 03 Jan 2008 09:43:38 GMT
----------------------------------------------------------

The next time I press f5 I get this back:

http://localhost:8080/bp_rbac/sessions/login_rbac

GET /bp_rbac/sessions/login_rbac HTTP/1.1
Host: localhost:8080
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.11) Gecko/20071127 Firefox/2.0.0.11
Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q= 0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: JSESSIONID=BB9A6322ACCF6F68C6C40E1D9F86CA04; _bp_rbac_session_id=f65bf4157dac17f9539e5c4e051648ab
Cache-Control: max-age=0

HTTP/1.x 200 OK
Server: Apache-Coyote/1.1
Set-Cookie: _bp_rbac_session_id=f65bf4157dac17f9539e5c4e051648ab; path=/
Etag: "c87bc98ba6bf6a36ef0e4bb4863bc908"
X-Runtime: 0.00010
Cache-Control: private, max-age=0, must-revalidate
Content-Type: text/html;charset=utf-8
Content-Length: 1428
Date: Thu, 03 Jan 2008 09:44:23 GMT

--------------------------------------------------------------------

A Ctrl+f5 is also ok:

http://localhost:8080/bp_rbac/sessions/login_rbac

GET /bp_rbac/sessions/login_rbac HTTP/1.1
Host: localhost:8080
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.11) Gecko/20071127 Firefox/2.0.0.11
Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q= 0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: JSESSIONID=BB9A6322ACCF6F68C6C40E1D9F86CA04; _bp_rbac_session_id=f65bf4157dac17f9539e5c4e051648ab
Pragma: no-cache
Cache-Control: no-cache

HTTP/1.x 200 OK
Server: Apache-Coyote/1.1
Set-Cookie: _bp_rbac_session_id=f65bf4157dac17f9539e5c4e051648ab; path=/
Etag: "c87bc98ba6bf6a36ef0e4bb4863bc908"
X-Runtime: 0.03100
Cache-Control: private, max-age=0, must-revalidate
Content-Type: text/html;charset=utf-8
Content-Length: 1428
Date: Thu, 03 Jan 2008 09:45:25 GMT

Activity

Hide
Charles Oliver Nutter added a comment -

Hmmm, ugly. Can you provide a sample app (great) or WAR file (ok) and instructions on how to reproduce? There are others using JRuby + Rails 2 and having no issues like this.

Show
Charles Oliver Nutter added a comment - Hmmm, ugly. Can you provide a sample app (great) or WAR file (ok) and instructions on how to reproduce? There are others using JRuby + Rails 2 and having no issues like this.
Hide
Mike Herrick added a comment -

Charles, well that is encouraging (your comment).

I can work on getting you something this weekend (an app).

Show
Mike Herrick added a comment - Charles, well that is encouraging (your comment). I can work on getting you something this weekend (an app).
Hide
Mike Herrick added a comment -

Well, I built I did a really simple Rails 2.0 app off of trunk & latest Goldspike and I was unable to reproduce. So that is good, but my real app is still doing (a little more complicated). I will try messing with it a bit. Rather than posting it here (the app) can I share it with one person on the Goldspike team to help me?

Show
Mike Herrick added a comment - Well, I built I did a really simple Rails 2.0 app off of trunk & latest Goldspike and I was unable to reproduce. So that is good, but my real app is still doing (a little more complicated). I will try messing with it a bit. Rather than posting it here (the app) can I share it with one person on the Goldspike team to help me?
Hide
Robert Egglestone added a comment -

If you'd like to send it through to me I'll give it a go and see if I can see what's going on.
I can be reached at r.egglestone@auckland.ac.nz

We had an issue much earlier where exceptions would be thrown, but the Rails exception handling was failing, so we got empty responses. It's possible that something similar is happening with Rails 2.

Show
Robert Egglestone added a comment - If you'd like to send it through to me I'll give it a go and see if I can see what's going on. I can be reached at r.egglestone@auckland.ac.nz We had an issue much earlier where exceptions would be thrown, but the Rails exception handling was failing, so we got empty responses. It's possible that something similar is happening with Rails 2.
Hide
Robert Egglestone added a comment -

I've made some changes to Goldspike (r868), and I'm not seeing the empty pages anymore.
Could you please try it out with the latest snapshot?

The changes made were:
+ I've added a finally block to ensure that the output stream is always closed. Previously I was assuming that Rails would always close the stream, but it looks like it isn't happening in this case.
+ I've tweaked the way 304 and flush is handled to ensure that multiple sets of headers can never be sent.

Show
Robert Egglestone added a comment - I've made some changes to Goldspike (r868), and I'm not seeing the empty pages anymore. Could you please try it out with the latest snapshot? The changes made were: + I've added a finally block to ensure that the output stream is always closed. Previously I was assuming that Rails would always close the stream, but it looks like it isn't happening in this case. + I've tweaked the way 304 and flush is handled to ensure that multiple sets of headers can never be sent.
Hide
Mike Herrick added a comment -

Robert - great news - I'll try it right now & report back my findings.

Show
Mike Herrick added a comment - Robert - great news - I'll try it right now & report back my findings.
Hide
Mike Herrick added a comment -

The fix resolved the issue. The checkin has in issue in that I think the fix depends on 1.0.3, but the build script was pointed at 1.0.1. Maven had 1.0.3, but Ant had 1.0.1. I patched that locally and got it to build. Then I ran it and I no longer saw the Random Empty Response with Rails 2.0 behavior.

I am seeing:

6-Jan-2008 1:05:53 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet files threw exception
java.lang.NoSuchMethodError: org.jruby.RubyIO.closed()Lorg/jruby/RubyBoolean;
        at org.jruby.webapp.RailsServlet.dispatchRequest(RailsServlet.java:108)
        at org.jruby.webapp.RailsServlet.serviceRequest(RailsServlet.java:58)
        at org.jruby.webapp.RailsServlet.service(RailsServlet.java:42)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:654)
        at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:445)
        at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:343)
        at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:292)
        at org.jruby.webapp.FileServlet.service(FileServlet.java:208)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:263)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:584)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
        at java.lang.Thread.run(Thread.java:619)

in the Tomcat logs now so it looks like there is a (hopefully small) new problem.

Show
Mike Herrick added a comment - The fix resolved the issue. The checkin has in issue in that I think the fix depends on 1.0.3, but the build script was pointed at 1.0.1. Maven had 1.0.3, but Ant had 1.0.1. I patched that locally and got it to build. Then I ran it and I no longer saw the Random Empty Response with Rails 2.0 behavior. I am seeing:
6-Jan-2008 1:05:53 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet files threw exception
java.lang.NoSuchMethodError: org.jruby.RubyIO.closed()Lorg/jruby/RubyBoolean;
        at org.jruby.webapp.RailsServlet.dispatchRequest(RailsServlet.java:108)
        at org.jruby.webapp.RailsServlet.serviceRequest(RailsServlet.java:58)
        at org.jruby.webapp.RailsServlet.service(RailsServlet.java:42)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:654)
        at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:445)
        at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:343)
        at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:292)
        at org.jruby.webapp.FileServlet.service(FileServlet.java:208)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:263)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:584)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
        at java.lang.Thread.run(Thread.java:619)
in the Tomcat logs now so it looks like there is a (hopefully small) new problem.
Hide
Mike Herrick added a comment -

The attached build.xml will fix the currently broken build.

Show
Mike Herrick added a comment - The attached build.xml will fix the currently broken build.
Hide
Robert Egglestone added a comment -

Thanks, I've updated build.xml in the repository.

Show
Robert Egglestone added a comment - Thanks, I've updated build.xml in the repository.
Hide
Robert Egglestone added a comment -

By the way, that stack trace is caused by running with JRuby < 1.0.3.

It needs to be both built and run with 1.0.3, to do this add this line to config/warble.rb:
config.java_libs.reject! {|lib| lib =~ /jruby-complete|goldspike/ }

And then put the jruby-complete-1.0.3 and goldspike-1.4-snapshot jars in the lib directory.

Show
Robert Egglestone added a comment - By the way, that stack trace is caused by running with JRuby < 1.0.3. It needs to be both built and run with 1.0.3, to do this add this line to config/warble.rb: config.java_libs.reject! {|lib| lib =~ /jruby-complete|goldspike/ } And then put the jruby-complete-1.0.3 and goldspike-1.4-snapshot jars in the lib directory.
Hide
Mike Herrick added a comment -

Robert's fix resolved the issue.

Some notes from an email between Robert and I that may be useful. I'll update the wiki with some of the other bits.

_To identify the problem, after duplicating the bug using Jetty and
Firefox, I started the IntelliJ with remote debugging, and Jetty with
the Java debugger enabled. A few breakpoints showed that on every
"If-None-Match" request it would write some headers, which ended up in
the HttpOutput buffer, but these were never being pushed out to the
response. This shows that close was not being done, so RailsServlet was
modified to call close if Rails didn't do so. _

Show
Mike Herrick added a comment - Robert's fix resolved the issue. Some notes from an email between Robert and I that may be useful. I'll update the wiki with some of the other bits. _To identify the problem, after duplicating the bug using Jetty and Firefox, I started the IntelliJ with remote debugging, and Jetty with the Java debugger enabled. A few breakpoints showed that on every "If-None-Match" request it would write some headers, which ended up in the HttpOutput buffer, but these were never being pushed out to the response. This shows that close was not being done, so RailsServlet was modified to call close if Rails didn't do so. _
Hide
Charles Oliver Nutter added a comment -

Thanks for the wiki updates Mike!

Show
Charles Oliver Nutter added a comment - Thanks for the wiki updates Mike!
Hide
David M. Holmes added a comment -

I'm having the same issue (HTTP 200, Content-length:0) with Tomcat and builds from latest JRuby (5816) and Goldspike (886). It appears to not be quite fixed.

Show
David M. Holmes added a comment - I'm having the same issue (HTTP 200, Content-length:0) with Tomcat and builds from latest JRuby (5816) and Goldspike (886). It appears to not be quite fixed.
Hide
David M. Holmes added a comment -

Cancel that. My warble reverted back to an old goldspike...

Show
David M. Holmes added a comment - Cancel that. My warble reverted back to an old goldspike...
Hide
Robert Egglestone added a comment -

If you drop the desired Goldspike and JRuby jars in webapp/lib, and then add this line to config/warbler.rb, it'll always use them rather than the version bundled with the current Warbler gem:
config.java_libs.reject! {|lib| lib =~ /jruby-complete|goldspike/ }

Show
Robert Egglestone added a comment - If you drop the desired Goldspike and JRuby jars in webapp/lib, and then add this line to config/warbler.rb, it'll always use them rather than the version bundled with the current Warbler gem: config.java_libs.reject! {|lib| lib =~ /jruby-complete|goldspike/ }

People

Vote (0)
Watch (4)

Dates

  • Created:
    Updated:
    Resolved: