Bug 44592 - mod_proxy fails to send post request to backend server
Summary: mod_proxy fails to send post request to backend server
Status: RESOLVED WONTFIX
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_proxy (show other bugs)
Version: 2.2.9
Hardware: PC Windows Server 2003
: P1 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
: 52965 (view as bug list)
Depends on:
Blocks:
 
Reported: 2008-03-12 17:43 UTC by Arun
Modified: 2014-02-11 12:53 UTC (History)
7 users (show)



Attachments
Network capture Client to Apache (740.48 KB, application/x-gzip)
2008-06-23 03:26 UTC, Bernard Spil
Details
Network capture Apacheto Backend (222.96 KB, application/x-gzip)
2008-06-23 03:26 UTC, Bernard Spil
Details
http capture client to proxy (57.07 KB, application/x-gzip)
2008-06-24 08:01 UTC, Bernard Spil
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Arun 2008-03-12 17:43:15 UTC
Randomly, IE has to wait for 5 minutes for its request to be processed. After 5 mins, it gets a 500. Upon debugging, mod_proxy didnt send this request to backend server for processing. Instead it failed with 

[Wed Mar 12 09:21:08 2008] [error] (OS 10060)A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.  : proxy: prefetch request body failed to 10.33.35.97:8080 (usdawdev05.infor.com) from 10.33.130.130 ()

Any clues on how to resolve this? Thanks 

More snippets
=============
[Wed Mar 12 09:16:07 2008] [debug] mod_proxy_http.c(54): proxy: HTTP: canonicalising URL //usdawdev05.infor.com:8080/wmweb/wms/wmsapp.ctrl
[Wed Mar 12 09:16:07 2008] [debug] proxy_util.c(1412): [client 10.33.130.130] proxy: http: found worker http://usdawdev05.infor.com:8080/wmweb for http://usdawdev05.infor.com:8080/wmweb/wms/wmsapp.ctrl, referer: http://usdawdev05.infor.com/wmweb/wms/wmsapp.ctrl?S|G|loginRequest=1274
[Wed Mar 12 09:16:07 2008] [debug] mod_proxy.c(819): Running scheme http handler (attempt 0)
[Wed Mar 12 09:16:07 2008] [debug] mod_proxy_http.c(1693): proxy: HTTP: serving URL http://usdawdev05.infor.com:8080/wmweb/wms/wmsapp.ctrl
Sometime
[Wed Mar 12 09:16:07 2008] [debug] proxy_util.c(1852): proxy: HTTP: has acquired connection for (usdawdev05.infor.com)
[Wed Mar 12 09:16:07 2008] [debug] proxy_util.c(1913): proxy: connecting http://usdawdev05.infor.com:8080/wmweb/wms/wmsapp.ctrl to usdawdev05.infor.com:8080
[Wed Mar 12 09:16:07 2008] [debug] proxy_util.c(2012): proxy: connected /wmweb/wms/wmsapp.ctrl to usdawdev05.infor.com:8080
[Wed Mar 12 09:16:07 2008] [debug] proxy_util.c(2109): proxy: HTTP: backend socket is disconnected.
[Wed Mar 12 09:16:07 2008] [debug] proxy_util.c(2169): proxy: HTTP: fam 2 socket created to connect to usdawdev05.infor.com
[Wed Mar 12 09:16:07 2008] [debug] proxy_util.c(2266): proxy: HTTP: connection complete to 10.33.35.97:8080 (usdawdev05.infor.com)
[Wed Mar 12 09:21:08 2008] [error] (OS 10060)A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.  : proxy: prefetch request body failed to 10.33.35.97:8080 (usdawdev05.infor.com) from 10.33.130.130 ()
[Wed Mar 12 09:21:08 2008] [debug] proxy_util.c(1870): proxy: HTTP: has released connection for (usdawdev05.infor.com)
[Wed Mar 12 09:21:08 2008] [error] [client 10.33.130.130] Handler for proxy-server returned invalid result code 730060, referer: http://usdawdev05.infor.com/wmweb/wms/wmsapp.ctrl?S|G|loginRequest=1274
[Wed Mar 12 09:21:08 2008] [debug] mod_deflate.c(601): [client 10.33.130.130] Zlib: Compressed 535 to 322 : URL /wmweb/wms/wmsapp.ctrl, referer: http://usdawdev05.infor.com/wmweb/wms/wmsapp.ctrl?S|G|loginRequest=1274
Comment 1 Ruediger Pluem 2008-03-13 00:18:48 UTC
Your client at 10.33.130.130 did not sent the request body. I cannot tell if this is your IE or some other proxy in between.
Comment 2 Arun 2008-03-13 11:48:45 UTC
(In reply to comment #1)
> Your client at 10.33.130.130 did not sent the request body. I cannot tell if
> this is your IE or some other proxy in between.
> 

I am using httpwatch which captures what browser posts to the web server. There I clearly see the post data being sent. Do you want me to capture anything specific? Could this be the same issue as https://issues.apache.org/bugzilla/show_bug.cgi?id=37920.

Thanks

Comment 3 Ruediger Pluem 2008-03-13 12:55:49 UTC
(In reply to comment #2)
> (In reply to comment #1)
> > Your client at 10.33.130.130 did not sent the request body. I cannot tell if
> > this is your IE or some other proxy in between.
> > 
> 
> I am using httpwatch which captures what browser posts to the web server. There
> I clearly see the post data being sent. Do you want me to capture anything
> specific? Could this be the same issue as
> https://issues.apache.org/bugzilla/show_bug.cgi?id=37920.

No.
The error message on httpd side

[Wed Mar 12 09:21:08 2008] [error] (OS 10060)A connection attempt failed
because the connected party did not properly respond after a period of time, or
established connection failed because connected host has failed to respond.  :
proxy: prefetch request body failed to 10.33.35.97:8080 (usdawdev05.infor.com)
from 10.33.130.130 ()

clearly indicates that the data gets lost on its way to the server. Please use a network sniffer instead of httpwatch

1. On your client.
2. On your server running httpd

to verify that the data is really sent and attach the network dumps to this report for further analysis.


Comment 4 Jeff Lewis 2008-03-27 09:46:06 UTC
I am currently experiencing the same issue.  My set-up is:  Apache w/mod_proxy as a Reverse Proxy Server to IIS 6 on Windows 2003 on the back end.  (As such, this could be an issue with IIS 6...)

The Apache error.log is showing:
[Wed Mar 26 16:26:27 2008] [error] (OS 10060)A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.  : proxy: pass request body failed to 172.23.21.60:80 (172.23.21.60) from 63.175.160.199 ()
[Wed Mar 26 16:26:27 2008] [error] [client 63.175.160.199] Handler for proxy-server returned invalid result code 730060, referer: http://beta.xactcontents.com/contents/cc/ew/?id=2008-3-21-1031&readonly=0&prof=5L&comp=

The IIS error.log is showing:
#Fields: date time c-ip c-port s-ip s-port cs-version cs-method cs-uri sc-status s-siteid s-reason s-queuename
2008-03-26 20:46:43 207.14.128.6 4474 172.23.21.60 80 HTTP/1.1 POST /contents/cc/ew/ExcelFileLoader.aspx?id=TEST3&prof=5L - 1 Timer_EntityBody DefaultAppPool

IIS is saying that it never got the request body.  I am POST-ing a 1 Meg Excel file.  This works most of the time from the same network that the Apache server is on, but we almost always get this error from outside on the general internet.

Please let me know what additional information might be helpful...

Here are the changes I've made to httpd.config:
...
Win32DisableAcceptEx

ProxyRequests Off

<Proxy *>
Order deny,allow
Allow from all
</Proxy>

<VirtualHost _default_:80>
ProxyPass / http://172.23.21.60/
ProxyPassReverse / http://172.23.21.60/

<IfModule mod_cache.c>
	<IfModule mod_disk_cache.c>
		CacheRoot c:/cacheroot
		CacheEnable disk /contents/css
		CacheEnable disk /contents/img
		CacheEnable disk /contents/js
		CacheDirLevels 5
		CacheDirLength 3
	</IfModule> 
</IfModule> 



Comment 5 Jeff Lewis 2008-03-27 09:49:14 UTC
One additional piece of information:  Sometimes, when posting from the internet, I just get really slow upload performance:  12 Kb/s or so.
Comment 6 Marc Stern 2008-05-22 07:09:20 UTC
I have the same problem - at least I think so and I found a work-around which could help to trace the cause.
By setting "setenv proxy-sendcl", it solved the problem.
Comment 7 Bernard Spil 2008-06-23 03:26:14 UTC
Created attachment 22162 [details]
Network capture Client to Apache

Frame 289 is the POST request from the client (11:38:49.472677)
Comment 8 Bernard Spil 2008-06-23 03:26:55 UTC
Created attachment 22163 [details]
Network capture Apacheto Backend
Comment 9 Bernard Spil 2008-06-23 03:35:45 UTC
We are experiencing this issue on our reverse proxies. Meanwhile, we've confirmed this on
Apache-2.2.6/Windows Server 2003 (VS2008 build from apachelounge.com)
Apache-2.2.8/Windows Server 2003 (VS2008 build from apachelounge.com)
Apache-2.2.9/Windows Server 2003 (standard ASF build)
Apache-2.2.8/Ubuntu 8.04 (standard package)

This error is infrequent, ca. one POST request per 100 fails (1%). We've captured the network-data on our dev-box whilst triggering the error.

The request to Apache has a POST-body (see decrypted frame 289 below)

== Decrypted frame 289 ==
POST /sap(bD1lbiZjPTI1MCZkPW1pbiZpPTEmcz1TSUQlM2FBTk9OJTNhcGxzYXBkYzIwMF9EQzJfMDAlM2FWZ3VNRER3Mk1EbWpRdjJreHFBc2x5SUc1MFlvNmJFV0VWa2Zuc1hwLUFUVA==)/bc/bsp/sap/crm_ui_frame/bspwdapplication.do?id=218&target_id=MD-BP-OV&entity_name=BuilHeader&entity_key=FF060101010280003431303200000000010400000000100000003C030000000000000000000000000000000000000000004B00450059BC000000100A81BC7BA3914F67B4FE53F54883D55FBD04 HTTP/1.1
Accept: */*
Accept-Language: en,th;q=0.8,fr;q=0.7,pl;q=0.5,zh;q=0.3,nl;q=0.2
x-prototype-version: 1.3.1
Referer: https://www.dev.tradelink.com/sap(bD1FTiZjPTI1MCZkPW1pbiZpPTEmcz1TSUQlM2FBTk9OJTNhcGxzYXBkYzIwMF9EQzJfMDAlM2FWZ3VNRER3Mk1EbWpRdjJreHFBc2x5SUc1MFlvNmJFV0VWa2Zuc1hwLUFUVA==)/bc/bsp/sap/crm_ui_frame/bspwdapplication.do?id=238&target_id=TSEGFR_ED&entity_name=SEGSet&entity_key=FF060101010280003431303200000000010400000000100000003C030000000000000000000000000000000000000000004B00450059BC0000001046D9D464D19C0432E1008000828BF835BD04
x-requested-with: XMLHttpRequest
Content-Type: application/x-www-form-urlencoded
Accept-Encoding: gzip, deflate
User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322; .NET CLR 2.0.50727; InfoPath.1)
Host: www.dev.tradelink.com
Content-Length: 1153
Connection: Keep-Alive
Cache-Control: no-cache
Cookie: smuid=10032008-668-1301382274084061205134725; colstate=-#-#undefined#undefined#undefined#undefined#; sap-usercontext=sap-language=EN&sap-client=250; MYSAPSSO2=AjQxMDIBABgATgBMAFkAMgA2ADEAMAA0ACAAIAAgACACAAYAMgA1ADADABAARABDADIAIAAgACAAIAAgBAAYADIAMAAwADgAMAA2ADEANwAwADgAMwAzBQAEAAAACAYAAgBYCQACAEX%2fAZgwggGUBgkqhkiG9w0BBwKgggGFMIIBgQIBATELMAkGBSsOAwIaBQAwCwYJKoZIhvcNAQcBMYIBYDCCAVwCAQEwEzAOMQwwCgYDVQQDEwNNRUkCAQAwCQYFKw4DAhoFAKBdMBgGCSqGSIb3DQEJAzELBgkqhkiG9w0BBwEwHAYJKoZIhvcNAQkFMQ8XDTA4MDYxNzA4MzMwNFowIwYJKoZIhvcNAQkEMRYEFIDMRk8sRkKCPzZbn2yj8syOtZ6iMIGmBgUrDgMCGzCBnAJBAJQ%2f%21BvMlO438nBG1f0FClCbEbRI2SfTcTOJItOHZ6bWOXqux0Eh8ar%2fusZv21ME4zukJjnfB7ojFb3jqUuKgAsCFQDUmKLfAYXcLt7S0XDVjzPoiXBF9wJATF6H5rabRtyKht509WDmvyb0mneKh6WCwUVDjgybhnVZCWjiX7jA3CxmB2%2f05llqGpoLwmMfP0nwFbKMfcCEJwQvMC0CFQCT3xI6NJUwto4ha1Zc4TqatcCR7wIUPi348KqSKQdrfwT1xMKGX1DviHY%3d

htmlbevt_ty=thtmlb%3Alink%3Aclick%3A0&htmlbevt_frm=myFormId&htmlbevt_oid=C4_W14_V15_Z_SLS_OPP&htmlbevt_id=SLS-CYC-WC&htmlbevt_cnt=0&htmlbevt_par1=&htmlbevt_par2=&htmlbevt_par3=&htmlbevt_par4=&htmlbevt_par5=&htmlbevt_par6=&htmlbevt_par7=&htmlbevt_par8=&htmlbevt_par9=&onInputProcessing=htmlb&myFormId_complete=&sap-htmlb-design=&sap-ajaxtarget=C1_W1_V2_C4_W14_V15_MainNavigationLinks.do&sap-ajax_dh_mode=AUTO&thtmlbKeyboardFocusId=C4_W14_V15_Z_SLS_OPP&C6_W18_V19_selected_key=481371179A7A01E9E1008000828BF835&crmFrwScrollXPos=0&crmFrwScrollYPos=160&C1_W1_V2_V3_V20_bchistory_selection=&C20_W51_V52_0001_iscollapsed=&C20_W51_V52_0002_iscollapsed=&C20_W51_V52_0003_iscollapsed=&C20_W51_V52_0004_iscollapsed=&C20_W51_V52_0005_iscollapsed=&C20_W51_V52_0006_iscollapsed=X&C20_W51_V52_0007_iscollapsed=&C20_W51_V52_0008_iscollapsed=&C20_W51_V52_0009_iscollapsed=X&C20_W51_V52_0010_iscollapsed=X&C20_W51_V52_0014_iscollapsed=&thtmlbScrollAreaWidth=1107&thtmlbScrollAreaHeight=537&LTX_PREFIX_ID=C1_W1_V2_&C1_W1_V2_LTX_VETO_FLAG=&C1_W1_V2_ACTION_GUID=&C1_W1_V2_AC_OBJECT_KEY=&C1_W1_V2_AC_VALUE=&C1_W1_V2_AC_CONTAINER=&C1_W1_V2_MYITSLOCATION=&sap-ajax_request=X&_=
== End ==

access-log
130.144.209.17 - - [17/Jun/2008:11:38:38 +0200] "POST /sap(bD1lbiZjPTI1MCZkPW1pbiZpPTEmcz1TSUQlM2FBTk9OJTNhcGxzYXBkYzIwMF9EQzJfMDAlM2FWZ3VNRER3Mk1EbWpRdjJreHFBc2x5SUc1MFlvNmJFV0VWa2Zuc1hwLUFUVA==)/bc/bsp/sap/crm_ui_frame/bspwdapplication.do?id=218&target_id=MD-BP-OV&entity_name=BuilHeader&entity_key=FF060101010280003431303200000000010400000000100000003C030000000000000000000000000000000000000000004B00450059BC000000100A81BC7BA3914F67B4FE53F54883D55FBD04 HTTP/1.1" 200 105406
130.139.104.40 - - [17/Jun/2008:11:39:09 +0200] "GET /sap/public/myssocntl?sap-client=250 HTTP/1.1" 302 -
<snip>
130.139.104.40 - - [17/Jun/2008:11:43:42 +0200] "GET /sap(bD1lbiZjPTI1MA==)/bc/bsp/sap/zget_opp_order/result_header.htm?customer_number=0300095243&scope=Q HTTP/1.1" 200 195478
130.144.209.17 - - [17/Jun/2008:11:38:49 +0200] "POST /sap(bD1lbiZjPTI1MCZkPW1pbiZpPTEmcz1TSUQlM2FBTk9OJTNhcGxzYXBkYzIwMF9EQzJfMDAlM2FWZ3VNRER3Mk1EbWpRdjJreHFBc2x5SUc1MFlvNmJFV0VWa2Zuc1hwLUFUVA==)/bc/bsp/sap/crm_ui_frame/bspwdapplication.do?id=218&target_id=MD-BP-OV&entity_name=BuilHeader&entity_key=FF060101010280003431303200000000010400000000100000003C030000000000000000000000000000000000000000004B00450059BC000000100A81BC7BA3914F67B4FE53F54883D55FBD04 HTTP/1.1" 403 -
130.139.104.40 - - [17/Jun/2008:11:44:40 +0200] "GET /sap(bD1lbiZjPTI1MCZkPW1pbg==)/bc/bsp/sap/crm_ui_frame/sessionexit.gif?sap-contextid=SID%3aANON%3aplsapdc200_DC2_00%3aVguMDDx6dRfmx-zTCL3ffp8jf0Yo6bwQMln2UiQp-ATT&sap-sessioncmd=CLOSE HTTP/1.1" 200 -

error-log
[Tue Jun 17 11:43:49 2008] [error] (OS 10060)A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.  : proxy: prefetch request body failed to 130.144.0.220:8000 () from 130.144.209.17 ()
[Tue Jun 17 11:43:49 2008] [error] [client 130.144.209.17] Handler for proxy-server returned invalid result code 730060, referer: https://www.dev.tradelink.philips.com/sap(bD1FTiZjPTI1MCZkPW1pbiZpPTEmcz1TSUQlM2FBTk9OJTNhcGxzYXBkYzIwMF9EQzJfMDAlM2FWZ3VNRER3Mk1EbWpRdjJreHFBc2x5SUc1MFlvNmJFV0VWa2Zuc1hwLUFUVA==)/bc/bsp/sap/crm_ui_frame/bspwdapplication.do?id=238&target_id=TSEGFR_ED&entity_name=SEGSet&entity_key=FF060101010280003431303200000000010400000000100000003C030000000000000000000000000000000000000000004B00450059BC0000001046D9D464D19C0432E1008000828BF835BD04
 
Network Captures attached
Client-to-Apache.pcap: Frame 289 is the POST request from the client (11:38:49.472677)
Apache-to-Backend.pcap: No corresponding frame (frame 273 corresponds to the next GET request in Client-to-Apache dump)

Strangely, this capture show a 403 error whereas on our productive system this results in a 500 error (I did notice directory access for the error-docs was incorrect)
Comment 10 Ruediger Pluem 2008-06-23 06:20:38 UTC
(In reply to comment #9)

> 
> The request to Apache has a POST-body (see decrypted frame 289 below)

Can you try without SSL on the reverse proxy. This would give us more information about the packet flow times and would rule out that this the
fault of mod_ssl.
Please also sent the proxy configuration and your TimeOut settting


> 
> error-log
> [Tue Jun 17 11:43:49 2008] [error] (OS 10060)A connection attempt failed
> because the connected party did not properly respond after a period of time, or
> established connection failed because connected host has failed to respond.  :
> proxy: prefetch request body failed to 130.144.0.220:8000 () from
> 130.144.209.17 ()

This is a Windows specific error message. What error messages shows up if you use the Ubuntu Apache as reverse proxy?

Comment 11 Bernard Spil 2008-06-23 07:01:52 UTC
SSL:
We are currently building a small Java App to help us trigger the problem (takes ages to trigger error manually). When done, we'll trace a non-ssl error (if it then exists) and attach it to this bug.

TimeOut: 
TimeOut not specified, i.e. default 300 sec
ProxyTimeOut 600

Ubuntu error-log:
[Fri Jun 20 11:33:08 2008] [error] (70007)The timeout specified has expired: proxy: prefetch request body failed to 130.144.0.220:8000 (plsapdc200.local) from 127.0.0.1 ()
[Fri Jun 20 11:33:08 2008] [error] [client 127.0.0.1] Handler for proxy-server returned invalid result code 70007, referer: https://www.dev.tradelink.com/sap(bD1lbiZjPTI1MCZkPW1pbg==)/bc/bsp/sap/crm_ui_frame/bspwdapplication.do?id=31&target_id=TBT110APPC&entity_name=BTOrder&entity_key=FF060101010280003431303200000000010400000000100000003C030000000000000000000000000000000000000000004B00450059BC000000104782618331254037E1008000828BF835BD04

Config on dev machine:
NameVirtualHost *:443

<VirtualHost *:443>
ServerName www.dev.tradelink.com
ServerAlias www.dev.tradelink.com:443

BrowserMatch ".*MSIE.*" ssl-unclean-shutdown

SSLEngine On
# SSLOptions +StdEnvVars +ExportCertData
SSLCertificateFile conf/ssl/tradedev.crt
SSLCertificateKeyFile conf/ssl/tradedev.key

CustomLog logs/www.dev.tradelink.com/access_ssl_%y%m%d.log common
ErrorLog logs/www.dev.tradelink.com/error.log

#Reverse Proxy Configuration

DocumentRoot D:/htdocs

#   RewriteCond %{REQUEST_URI} !/maintenance.htm
#   RewriteRule ^.*$ /maintenance.htm [R]

SSLProxyEngine On

# ProxyPreserveHost Off
ProxyPreserveHost On
ProxyVia On
Header add vhost https-default
ProxyTimeout 600
RequestHeader set ClientProtocol https
RewriteEngine On

RewriteRule ^/sap(.*) http://plsapdc200.local:8000/sap$1 [P]
<Location /sap>
   ProxyPassReverse /sap
</Location>

RewriteRule ^/SAP(.*) http://plsapdc200.local:8000/sap$1 [P]
<Location /SAP>
   ProxyPassReverse /sap
</Location>

</VirtualHost>
Comment 12 Ruediger Pluem 2008-06-23 12:51:46 UTC
(In reply to comment #11)
> SSL:
> We are currently building a small Java App to help us trigger the problem
> (takes ages to trigger error manually). When done, we'll trace a non-ssl error
> (if it then exists) and attach it to this bug.

If you can reproduce the error it would be interesting to get a backtrace of the processing tread / process that is stalling. Please try to get one via gdb as described on http://httpd.apache.org/dev/debugging.html.

> 
> TimeOut: 
> TimeOut not specified, i.e. default 300 sec
> ProxyTimeOut 600

Does this mean you are waiting for 10 minutes with your browser until you give up?

> 
> Ubuntu error-log:
> [Fri Jun 20 11:33:08 2008] [error] (70007)The timeout specified has expired:
> proxy: prefetch request body failed to 130.144.0.220:8000 (plsapdc200.local)

Ok so httpd waits for reading data and then times out.

Comment 13 Bernard Spil 2008-06-24 08:01:42 UTC
Created attachment 22169 [details]
http capture client to proxy
Comment 14 Bernard Spil 2008-06-24 08:18:57 UTC
Completed one of the tests, which was capturing an error whilst not using ssl.

error.log
[Tue Jun 24 17:02:36 2008] [error] (70007)The timeout specified has expired: proxy: prefetch request body failed to 127.0.0.1:80 (www.dev.tradelink.com) from 130.144.213.244 ()
[Tue Jun 24 17:02:36 2008] [error] [client 130.144.213.244] Handler for proxy-server returned invalid result code 70007, referer: http://www.dev.tradelink.com/sap(bD1FTiZjPTI1MCZkPW1pbiZpPTEmcz1TSUQlM2FBTk9OJTNhcGxzYXBkYzIwMF9EQzJfMDAlM2EzS1hBejZVYkFmVjJibXM0cDljUkdmQ19uLXMyMldSRWZKRlBtQ2kxLUFUVA==)/bc/bsp/sap/crm_ui_frame/bspwdapplication.do?popup-name=_POPUP0004&

access.log
130.144.215.213 - - [24/Jun/2008:17:02:36 +0200] "GET http://www.dev.tradelink.com/SAP/BC/BSP/SAP/thtmlb_styles/sap_skins/thtmlb_core_stand.css HTTP/1.0" 200 84628
130.144.213.244 - - [24/Jun/2008:16:57:36 +0200] "POST http://www.dev.tradelink.com/sap(bD1FTiZjPTI1MCZkPW1pbiZpPTEmcz1TSUQlM2FBTk9OJTNhcGxzYXBkYzIwMF9EQzJfMDAlM2EzS1hBejZVYkFmVjJibXM0cDljUkdmQ19uLXMyMldSRWZKRlBtQ2kxLUFUVA==)/bc/bsp/sap/crm_ui_frame/bspwdapplication.do?popup-name=_POPUP0004& HTTP/1.1" 500 722
130.144.215.213 - - [24/Jun/2008:17:02:36 +0200] "GET http://www.dev.tradelink.com/SAP/BC/BSP/SAP/thtmlb_styles/sap_skins/thtmlb_visuals_stand.css HTTP/1.0" 200 10776

Attachment error2-client-213244.pcap is network between client and server (filtered only the client affected) frame 257 is the request and 271 the response.

The capture for proxy to backend I can't attach here, it is 11MB zipped (need a lot of cliking around to trigger the error).

We are aware of the 10min timeout (this is dev). The appserver behind the proxy may execute long-running queries on a database, and the end-users accept such a query time.

Hopefully I can trigger this on a single-process apache as well, debugable apache is installed. Takes 10 users about half an hour, so me alone would be.....

Hope this helps!
Comment 15 Ruediger Pluem 2008-06-24 12:51:50 UTC
(In reply to comment #14)

> 
> Attachment error2-client-213244.pcap is network between client and server
> (filtered only the client affected) frame 257 is the request and 271 the
> response.

Thanks for the dump. I evaluated the request send by the client and the client fails to send the request body:

00000786  63 4d 37 5a 49 33 59 25  33 64 0d 0a 0d 0a       cM7ZI3Y% 3d....

The string cM7ZI3Y%3d is the end of the value for the MYSAPSSO2 cookie. Afterwards the client sends \r\n\r\n which tells the server that the headers are now finished an that the request body follows next. But the client does not send a request body!
It seems that this request is sent via AJAX:

x-requested-with: XMLHttpRequest

Are you sure that there is no bug in your AJAX javascript? Using POST is not the typical way of using XMLHttpRequest. It requires some things to be done. Maybe something got wrong there in the javascript on the client side.

So in short: For this request httpd just works as designed besides that it should sent a 400 instead of a 500 return code. But I think this is fixed since 2.2.9.

Comment 16 Bernard Spil 2008-06-25 05:57:55 UTC
Still analyzing the captures. And not understanding what I see.

Seems that the POST header is in one SSL session, the POST body is in the next SSL session.

Example : Framenumber, Time, S(erver), C(lient):port

3045 C:1530->S POST /sap(<cookie>)/........
3046 C:1530->S continuation of 3045 upto end of headers + 0D0A0D0A
3047 C:1530->S [FIN,ACK]
3050 C:1531->S [SYN]
3052 S->C:1530 [ACK] 
3054 S->C:1531 [SYN,ACK]
3061 C:1531->S Client Hello
3062 S->C:1531 Server Hello
3063 C:1531->S Client Key Exchange
3064 S->C:1531 Change Cipher Spec, Finished
3065 C:1531->S POST body
3066 C:1531->S continuation of POST

Problem in the Wireshark (Win32 1.0.0) version is that the Decrypted SSL shows the complete POST (header and body) so we inadvertedly assumed the POST was complete. The payload of the header is 1460+61 bytes, the payload of the body 1948 bytes. Wireshark shows the complete POST whichever TCP stream I select, indicating that Wireshark is able to figure out that this is in fact one http request.

Is this an error with the client or is it an error with the server?

Comment 17 Bernard Spil 2008-06-30 12:38:58 UTC
It seems I have a problem with the Keep-Alive in conjunction with a changing order in sending and receiving of the TCP/IP frames.

We noticed that the last successful request from the client (as captured on the client) near to exactly 5 seconds before the first part of the next POST was sent by the client. Neither KeepAlive nor KeepAliveTimeout were set on Apache leaving it default 'on' and 5 seconds.

(numbering of frame differs from previous post in this bugreport)
Trace on client
30 10:05:39.241734 S->C HTTP/1.1 200 OK [PSH,ACK]
31 10:05:39.390101 C->S [ACK]
32 10:05:44.269173 C->S First frame of POST
33 10:05:44.269313 C->S First frame of POST
34 10:05:44.275964 S->C [FIN,ACK]

Trace on proxy (clocks NOT synchronized, frame matching on Seq en Ack in tcp)
1800 11:05:55.007933 S->C SSL Continuation (client trace frame 30)
1801 11:05:55.010493 C->S ACK
1802 11:05:55.013463 C->S ACK
1803 11:05:55.163385 C->S ACK
1804 10:05:59.981127 [FIN,ACK] (client trace frame 34)
1805 10:06:00.048579 SSL Unreassembled packet (client trace frame 32)
1807 10:06:00.049030 Continuation (client trace frame 33)

Due to the latency of the network the sending and receiving order on client and server-side have switched around.
My workaround was to set a specific KeepAliveTimeout in the Virtual Hosts affected (37 seconds) on the productive instance. After 2 hours I had 2 more errors:
- one where the previous request from the client was around 37 seconds before the failing POST request
- the other had 2 requests in short succesion from which the last one failed and the request before that was around 37 seconds earlier

The default Keep-Alive Time-Out of the Internet Explorer clients is 60 seconds (source http://support.microsoft.com/kb/813827). I am now switching the KeepAliveTimeout on the Apache servers to 67 seconds so it is longer than the Keep-Alive timeout on the client.

Additionally I found my bug described in http://support.microsoft.com/kb/921090, the PSH,ACK and FIN,ACK are listed in the client trace. I am told that wininet.dll builds after the one mentioned in this article can implement the fix by applying the registry setting FEATURE_HANDLE_SSL_CLOSE_NOTIFY_KB921090 from the MSKB article. Hopefully I can have this fix rolled out through the landscape (thousands of PC's) but that still won't fix issues with clients not under our control.

Some questions remain open
- What are the downsides of increasing the KeepAliveTimeout > 12 times?
- Is apache behaving as should be expected?
Comment 18 Ruediger Pluem 2008-06-30 13:14:10 UTC
Please also have a look at the following excerpt from the delivered httpd 
configuration:

#   SSL Protocol Adjustments:
#   The safe and default but still SSL/TLS standard compliant shutdown
#   approach is that mod_ssl sends the close notify alert but doesn't wait for
#   the close notify alert from client. When you need a different shutdown
#   approach you can use one of the following variables:
#   o ssl-unclean-shutdown:
#     This forces an unclean shutdown when the connection is closed, i.e. no
#     SSL close notify alert is send or allowed to received.  This violates
#     the SSL/TLS standard but is needed for some brain-dead browsers. Use
#     this when you receive I/O errors because of the standard approach where
#     mod_ssl sends the close notify alert.
#   o ssl-accurate-shutdown:
#     This forces an accurate shutdown when the connection is closed, i.e. a
#     SSL close notify alert is send and mod_ssl waits for the close notify
#     alert of the client. This is 100% SSL/TLS standard compliant, but in
#     practice often causes hanging connections with brain-dead browsers. Use
#     this only for browsers where you know that their SSL implementation
#     works correctly.
#   Notice: Most problems of broken clients are also related to the HTTP
#   keep-alive facility, so you usually additionally want to disable
#   keep-alive for those clients, too. Use variable "nokeepalive" for this.
#   Similarly, one has to force some clients to use HTTP/1.0 to workaround
#   their broken HTTP/1.1 implementation. Use variables "downgrade-1.0" and
#   "force-response-1.0" for this.
BrowserMatch ".*MSIE.*" \
         nokeepalive ssl-unclean-shutdown \
         downgrade-1.0 force-response-1.0

Maybe adding the BrowserMatch directive to your configuration helps.
Comment 19 Ruediger Pluem 2008-06-30 13:18:44 UTC
(In reply to comment #17)

> Some questions remain open
> - What are the downsides of increasing the KeepAliveTimeout > 12 times?

You bind resources (threads / processes) to connections on which nothing may happen for this time. So this

1. might require you to increase maximum number of clients.
2. increase the possibility for simple DoS attacks.

> - Is apache behaving as should be expected?
> 

See my previous post. IE + SSL + keepalive is a long known troublemaker and its an IE bug that causes this.

Comment 20 Bernard Spil 2008-06-30 14:02:21 UTC
My references to the Microsoft Knowledgebase Article 921090 seem to support labeling IE as having a buggy SSL implementation. I will be attempting to get Microsoft to support us in solving this problem as well (this might be a case where buying software pays off?), this problem seems to have enough 'management attention'.

Hopefully my post here helps other people struggling with similar issues.

When the KeepAliveTimeout adjustment is running a bit longer I will be able to see if there is an improvement in the number of occurences of the 'prefetch request body failed' vs the number of POST requests to the server. Will report back succes or failure to improve the situation.

In addition to these "hangs" as they're described by the users the users are reporting poor performance already with this service. Downgrading to HTTP/1.0 or disabling Keep-Alive will add an additional TCP and SSL negotiation step by for every request will not improve performance. (using curl --write-out "%{time_total}" on the server an SSL request takes at least .234 seconds for a local resource of 0 bytes).
Comment 21 Roy T. Fielding 2009-04-03 19:17:38 UTC
This doesn't seem to be a problem that Apache can fix.
Services generally expect a client to either make a fairly
regular set of requests over time (justifying a keepalive)
or to make big requests every once in a while (no keepalive).

I suggest a workaround: if you can't speed up the client so
that it doesn't delay for so long while constructing the request,
then send an OPTIONS request in a regular interval before
the huge POST so that the connection is primed and alive.

Alternatively, just use a long keepalive timeout since it
will only apply to SSL sessions that have already
successfully negotiated, and thus should not be as much
of a denial of service issue as it would for a normal
public-facing website.
Comment 22 Sylwek 2013-06-10 18:54:29 UTC
*** Bug 52965 has been marked as a duplicate of this bug. ***
Comment 23 Arindam 2014-02-11 12:44:08 UTC
Hi,

I am also facing the same issue. I am using it on the Windows 7 and my version is 2.2.11 for the HTTP Server. 

It is showing the below error:

(OS 10054)An existing connection was forcibly closed by the remote host.  : proxy: prefetch request body failed to 10.131.x.x:80 (10.131.x.x) from 10.131.y.y ()

I have tried adding the keep alive and other properties but it did not resolve my issue. Here is my httpd.config file changes:

<IfModule ssl_module>
    SSLRandomSeed startup builtin
    SSLRandomSeed connect builtin
    </IfModule>
    <IfModule mod_proxy.c>
    ProxyRequests On
    ProxyVia On
   </IfModule>

    <Proxy *>
        Order deny,allow
        Deny from all
        Allow from 10.131.x.x
    </Proxy>

Also added the below variables:

 KeepAlive On
 MaxKeepAliveRequests 0
 KeepAliveTimeout 15
 Listen 8080

I am using it forward proxy. So what can be the issue?

Note: I have tried with the Wireshark and noticed that it is connecting to my destination IP Address or server. But in the middle something is messing up the connection.

Thanks,
Arindam
Comment 24 Eric Covener 2014-02-11 12:53:40 UTC
If it's the same issue, the disposition doesn't change. 

If it's not, appending to this report is invalid.  

Either way, resetting status to WONTFIX.  I suggest taking your issue to users@ or serverfault if you want help interpreting your packet capture.