Bug 48315

Summary: End of file found: proxy: error reading status line from remote server localhost
Product: Apache httpd-2 Reporter: silicium
Component: mod_proxyAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED INVALID    
Severity: major CC: mustafa.topaloglu, silicium
Priority: P2    
Version: 2.2.9   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description silicium 2009-12-01 01:52:08 UTC
mod_proxy connectionproblems like [37770]

Environment:

- Connections comes from a properitary Loadbalancer.
- No SSL on the Machines
- Apache 2.2.9-10 (Debian Lenny)
- Apache2 with mod_proxy and proxy_http enabled vhost
...
       ProxyPass / http://localhost:8080/
       ProxyPassReverse / http://localhost:8080/
...

on 8080 runs a tomcat-6.0.18


Short Description:


Around 2-4 times a day, mod_proxy will close the connection and return a HTTP/Bad_Gateway.

also i benched our Stagingsystem with ApacheBench 1'000'000 Connections, 1000 Parallel was no Problem for the System and the Problem could not be reproduced.

Of course, Tomcat works fine and there are no errors or connection problems.


[Mon Nov 30 12:50:38 2009] [error] [client x.x.x.x] (70014)End of file found: proxy: error reading status line from remote server localhost, referer: http://foo.bar

[Mon Nov 30 12:50:38 2009] [error] [client x.x.x.x] proxy: Error reading from remote server returned by /LandingsGoogle.action, referer: http://foo.bar

----------




Debug Log Output:




[Mon Nov 30 12:50:37 2009] [debug] mod_proxy_http.c(1710): proxy: start body send
[Mon Nov 30 12:50:37 2009] [debug] mod_headers.c(740): headers: ap_headers_output_filter()
[Mon Nov 30 12:50:37 2009] [debug] mod_deflate.c(632): [client x.x.x.x] Zlib: Compressed 19277 to 5278 : URL /foo/bar
[Mon Nov 30 12:50:37 2009] [debug] mod_proxy_http.c(1803): proxy: end body send
[Mon Nov 30 12:50:37 2009] [debug] proxy_util.c(2008): proxy: HTTP: has released connection for (localhost)
[Mon Nov 30 12:50:38 2009] [debug] mod_proxy_http.c(60): proxy: HTTP: canonicalising URL //localhost:8080/Index.action
[Mon Nov 30 12:50:38 2009] [debug] proxy_util.c(1488): [client x.x.x.x] proxy: http: found worker http://localhost:8080/ for http://localhost:8080/Index.action?foo_bar
[Mon Nov 30 12:50:38 2009] [debug] mod_proxy.c(966): Running scheme http handler (attempt 0)
[Mon Nov 30 12:50:38 2009] [debug] mod_proxy_ajp.c(575): proxy: AJP: declining URL http://localhost:8080/Index.action?foo_bar
[Mon Nov 30 12:50:38 2009] [debug] mod_proxy_http.c(1937): proxy: HTTP: serving URL http://localhost:8080/Index.action?foo_bar
[Mon Nov 30 12:50:38 2009] [debug] proxy_util.c(1990): proxy: HTTP: has acquired connection for (localhost)
[Mon Nov 30 12:50:38 2009] [debug] proxy_util.c(2046): proxy: connecting http://localhost:8080/Index.action?foo_bar to localhost:8080
[Mon Nov 30 12:50:38 2009] [debug] proxy_util.c(2139): proxy: connected /Index.action?foo_bar to localhost:8080
[Mon Nov 30 12:50:38 2009] [debug] mod_proxy_http.c(1710): proxy: start body send
[Mon Nov 30 12:50:38 2009] [debug] mod_headers.c(740): headers: ap_headers_output_filter()
[Mon Nov 30 12:50:38 2009] [debug] mod_proxy_http.c(1803): proxy: end body send
[Mon Nov 30 12:50:38 2009] [debug] proxy_util.c(2008): proxy: HTTP: has released connection for (localhost)
[Mon Nov 30 12:50:38 2009] [error] [client x.x.x.x] (70014)End of file found: proxy: error reading status line from remote server localhost, referer: http://www.foo.bar/fnord?some_variables_and_awesome_stuff
[Mon Nov 30 12:50:38 2009] [debug] mod_proxy_http.c(1439): [client 92.116.109.83] proxy: NOT Closing connection to client although reading from backend server localhost failed., referer: http://www.foo.bar/fnord?some_variables_and_awesome_stuff
[Mon Nov 30 12:50:38 2009] [error] [client x.x.x.x] proxy: Error reading from remote server returned by /foobar.action, referer: http://www.foo.bar/fnord?some_variables_and_awesome_stuff
[Mon Nov 30 12:50:38 2009] [debug] proxy_util.c(2008): proxy: HTTP: has released connection for (localhost)
[Mon Nov 30 12:50:38 2009] [debug] mod_headers.c(740): headers: ap_headers_output_filter()
[Mon Nov 30 12:50:38 2009] [debug] mod_headers.c(740): headers: ap_headers_output_filter()
[Mon Nov 30 12:50:38 2009] [debug] mod_headers.c(740): headers: ap_headers_output_filter()
[Mon Nov 30 12:50:38 2009] [debug] mod_deflate.c(632): [client x.x.x.x] Zlib: Compressed 3075 to 1198 : URL /error/HTTP_BAD_GATEWAY.html.var, referer: http://www.foo.bar/fnord
Comment 1 Ruediger Pluem 2009-12-01 03:24:39 UTC
The remote (in this case Tomcat) has closed the connection before sending a response. There is nothing httpd can do about that.
Comment 2 silicium 2009-12-01 03:58:08 UTC
(In reply to comment #1)
> The remote (in this case Tomcat) has closed the connection before sending a
> response. There is nothing httpd can do about that.

but that should be written in the tomcat log

the tomcat doesnt show any connection errors.

I Allso captured with TCPDump, Tomcat sends the right answer
Comment 3 silicium 2009-12-01 04:01:43 UTC
(In reply to comment #2)
> (In reply to comment #1)
> > The remote (in this case Tomcat) has closed the connection before sending a
> > response. There is nothing httpd can do about that.
> 
> but that should be written in the tomcat log
> 
> the tomcat doesnt show any connection errors.
> 
> I Allso captured with TCPDump, Tomcat sends the right answer

I will doe this again and provide more informations
Comment 4 Mustafa Topaloglu 2009-12-09 08:20:34 UTC
Hi all,

I have the same problem with an another application server (Glassfish). Because it happens on a critical application I cannot wait long time for a patch. Are there workarounds in order to avoid that error ?

Regards
Mustafa
Comment 5 silicium 2009-12-09 09:37:43 UTC
hi there

short update:

it seems to be a Tomcat problem/bug.

the EOF occource because of an TCP/RST.
so, apache thinks about an not accessable proxy target.

There are maybe two ways to "fix"

Best way is to find out why Tomcat close the connection (it does for just one SYN! so there is not really a network issue)
so, the failure comes around 2 times per Day, this is realliy difficult to diagnost.
Also the Debug Logs would not say anything about that.

I Will look forward to fix it like a dirty way.
maybe it is possible to define a max_retry value for mod_proxy to retry the connection if a SYN/RST.


Marco
Comment 6 Peter Seong 2010-08-18 22:31:38 UTC
First, thanks for writing this!  It's solved a number of problems for 
me. 

I've run into a problem with one application.  The application allows 
the user to upload a file via a form, does some parsing/processing of 
the data, then redirects back to the index page.  Processing the data 
can take a few seconds and I've been randomly getting an apache proxy 
error during this operation.  The apache logs showed: 


(70014)End of file found: proxy: error reading status line from remote 
server localhost, referer: ... 


It appears that the following line from receive_data 


      # If data's still coming in but no HTTP header has been found 
within 5 seconds, close the connection 
      raise if (@request.start_time < (Time.now.to_i - 5)) 


is causing the connection to the back end to close before it's 
actually finished.  Increasing this to 15 seconds seems to have fixed 
my problem. 

orgin link : http://groups.google.com/group/switchpipe/browse_thread/thread/26328ed9af4da6a9
Comment 7 Ian Guerit 2010-12-10 03:37:12 UTC
We had a similar issue occurring with Apache 2.2.16 proxying to Apache 2.2.11

"This error occurs if the bytes recieved are less than 8192."
See bug #48656

Adding output buffering to the source server resolved the issue for us.
Comment 8 Ian Guerit 2010-12-10 04:43:05 UTC
(In reply to comment #7)
> We had a similar issue occurring with Apache 2.2.16 proxying to Apache 2.2.11
> 
> "This error occurs if the bytes received are less than 8192."
> See bug #48656
> 
> Adding output buffering to the source server resolved the issue for us.

This seemed to make the issue much better, however we are still having some trouble so have changed set up to avoid proxy.

Of interest:
 - Upgraded both servers so running 2.2.16
 - Timeout 30, KeepAlive On, MaxKeepAliveRequests 100, KeepAliveTimeout 2
Comment 9 Olivier BO√čL 2011-01-13 04:06:41 UTC
Hello, Gentlemen,


I've faced the same issue and, in my case, the problem seems to occur when the reverse proxy (RP) sends a request to the back-end server (using a previously establiseh connection) and, in the mean time (exactly), the back-end server closes the connection due to connection timeout (in my case, it is a Tomcat server with the default 20 seconds ConnectionTimeout).

To fix this, I've added "smax=0 ttl=7" (or any value less than the back-end connection timeout) to the ProxyPass directive.

I hope it helps.

Regards,


Olivier
Comment 10 Paul Davis 2011-02-02 19:42:33 UTC
I'm still seeing this issue with version: 2.2.3-43

Hitting the backend server directly always works fine. On a production system, I'm seeing one of these errors every 2-3 seconds.

None of the SetEnv hacks appear to have any affect nor the setting used by Olivier.
Comment 11 Paul Davis 2011-02-02 20:03:22 UTC
nevermind, just realized I'm running a 5 year version. doh!!
Comment 12 William A. Rowe Jr. 2011-02-02 20:46:37 UTC
Marking "nevermind"