[#JRUBY-1879] Random Empty Response with Rails 2.0

JRuby

Random Empty Response with Rails 2.0

Created: 03/Jan/08 10:09 PM Updated: 23/Apr/08 10:02 AM

Component/s:

Rails WAR Deployment

Affects Version/s:

None

Fix Version/s:

JRuby 1.1RC2

Time Tracking:

Not Specified

File Attachments:	1. build.xml (7 kB)
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

Description

« Hide

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

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

Show »

All

Comments

Work Log

Change History

Sort Order:

[ Permalink | « Hide ]

Charles Oliver Nutter added a comment - 04/Jan/08 09:24 PM

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.

[ Permalink | « Hide ]

Mike Herrick added a comment - 04/Jan/08 09:32 PM

Charles, well that is encouraging (your comment).

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

[ Permalink | « Hide ]

Mike Herrick added a comment - 05/Jan/08 12:57 PM

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?

[ Permalink | « Hide ]

Robert Egglestone added a comment - 05/Jan/08 03:09 PM

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.

[ Permalink | « Hide ]

Robert Egglestone added a comment - 05/Jan/08 05:36 PM

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.

[ Permalink | « Hide ]

Mike Herrick added a comment - 05/Jan/08 05:39 PM

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

[ Permalink | « Hide ]

Mike Herrick added a comment - 05/Jan/08 07:10 PM

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.

[ Permalink | « Hide ]

Mike Herrick added a comment - 05/Jan/08 07:16 PM

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

[ Permalink | « Hide ]

Robert Egglestone added a comment - 06/Jan/08 12:35 AM

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

[ Permalink | « Hide ]

Robert Egglestone added a comment - 06/Jan/08 12:54 AM

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.

[ Permalink | « Hide ]

Mike Herrick added a comment - 06/Jan/08 08:48 AM

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. _

[ Permalink | « Hide ]

Charles Oliver Nutter added a comment - 06/Jan/08 12:59 PM

Thanks for the wiki updates Mike!

[ Permalink | « Hide ]

David M. Holmes added a comment - 04/Feb/08 03:24 PM

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.

[ Permalink | « Hide ]

David M. Holmes added a comment - 05/Feb/08 11:18 AM

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

[ Permalink | « Hide ]

Robert Egglestone added a comment - 05/Feb/08 03:12 PM

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/ }