Hi I have an apache 2.0.49 in reverse proxy SSL mode and a iis behind . Lot of errors ( 70007 ) occured when POST request . it's a upload script ( ASP ) running on the iis . sometimes iis generates a 500 error code( timeout of the asp script execution ) which generates a 500 error ( apache logs ) "POST /wp_doc_upload.asp?PID=987665 HTTP/1.1" 500 490 https://aa.com/test .asp" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.0; Hotbar 4.5.1.0)" or 70007 error "POST /wp_doc_upload.asp?PID=987665 HTTP/1.1" 70007 23 "https://aa.com/tes t.asp" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.0; Hotbar 4.5.1.0)" After reading bugs 22030, 19315, 22030, i can't find similar behaviour between these bugs and mine .
Add-on ssl request from the client to the apache, and no ssl between apache and IIS
Firstly, please try upgrading to 2.0.52, there have been quite a few mod_ssl changes since 2.0.49. Secondly, please include the complete error messages logged to error_log.
[Tue Oct 19 14:52:30 2004] [info] (70007)The timeout specified has expired: SSL input filter read failed.
without mod_ssl, i have 70007 return code in the access_log, but nothing in the error_log like in the previous post, except a lot of : [Tue Oct 19 15:55:14 2004] [info] (32)Broken pipe: core_output_filter: writing data to the network
10.50.8.69 - - [19/Oct/2004:15:31:35 +0200] "POST /wp_doc_upload.asp?PID=987665 HTTP/1.1" 70007 538
I have same errors with 2.0.50 2.0.52 without mod_ssl . "POST /wp_doc_upload.asp?PID=987665 HTTP/1.1" 70007 538 what is the difference between the 70007 return code in the access_log and the (70007) return code in the error_log ?
There is a bug in mod_ssl somewhere which means that the APR error code 70007 is being returned in the wrong place, which is why it gets logged in access_log. But it's still not clear to me: what actual problems are you seeing other than the oddity in the logging?
(In reply to comment #7) > There is a bug in mod_ssl somewhere which means that the APR error code 70007 is > being returned in the wrong place, which is why it gets logged in access_log. > But it's still not clear to me: what actual problems are you seeing other than > the oddity in the logging? In the error_log , lot of errors like [info] (70007)The timeout specified has expired: SSL input filter read failed. In the access_log : some 70007 : POST /wp_doc_upload.asp?PID=987665 HTTP/1.1" 70007 23 "https://aa.com/test.asp" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.0; Hotbar 4.5.1.0)" each time a 70007 or 500 error occured, ie is out ( blank page ) . On version 1.3.31, there are only 500 error code ( asp script time out ), but no 70007 error code .
(In reply to comment #8) > (In reply to comment #7) > > There is a bug in mod_ssl somewhere which means that the APR error code 70007 > is > > being returned in the wrong place, which is why it gets logged in access_log. > > But it's still not clear to me: what actual problems are you seeing other than > > the oddity in the logging? > > > In the error_log , lot of errors like [info] (70007)The timeout specified has > expired: SSL input filter read failed. > > In the access_log : some 70007 : POST /wp_doc_upload.asp?PID=987665 HTTP/1.1" > 70007 23 "https://aa.com/test.asp" "Mozilla/4.0 (compatible; MSIE 6.0; Windows > NT 5.0; Hotbar 4.5.1.0)" > > each time a 70007 or 500 error occured, ie is out ( blank page ) . > > On version 1.3.31, there are only 500 error code ( asp script time out ), but > no 70007 error code . I have log entries with http error code 70007, too, but I don't have any entries in the error_log. mod_ssl isn't used. here the errors come from POST requests apache 2.0.54 / php 4.4.0 LogLevel warn
This is a bug in the default_handler, not in mod_ssl. The default_handler itself returns the ap_pass_brigade return value; the handler hook is supposed to return an OK/DECLINED/HTTP_* error code, so this is broken.
*** Bug 36828 has been marked as a duplicate of this bug. ***
Since Joe claims that this is where the logging bug should be followed up, I'm continuing conversation here. If this is the same problem as reported, this problem affects EVERY request, not just reverse proxy. (if not, then Joe referred me incorrectly) This is currently affecting roughly 2k log entries per night on my personal colo machine. It's tens of thousands more on real production websites. It's a fatal flaw in one of Apache's most basic operations -- log the request. What do we need to do to get developers to stop playing with grand new features that aren't crucial to basic operation, and fix the core?
Here's a patch to default handler to try: Index: server/core.c =================================================================== --- server/core.c (revision 386843) +++ server/core.c (working copy) @@ -3645,7 +3645,17 @@ e = apr_bucket_eos_create(c->bucket_alloc); APR_BRIGADE_INSERT_TAIL(bb, e); - return ap_pass_brigade(r->output_filters, bb); + status = ap_pass_brigade(r->output_filters, bb); + if (status == APR_SUCCESS + || c->aborted) { /* broken I/O isn't an HTTP issue, so no + * error status applies + */ + return OK; + } + else { + /* no way to know what type of error occurred */ + return HTTP_INTERNAL_SERVER_ERROR; + } } else { /* unusual method (not GET or POST) */ if (r->method_number == M_INVALID) { >What do we need to do to get developers to stop playing >with grand new features that aren't crucial to basic >operation, and fix the core? what can you do to help? * please refrain from complaining or otherwise expressing frustration via the PR database... that sends a signal to those who volunteer their time that their effort is inadequate... while that may be true for your problem, overall there are many problems diagnosed and solved via the PR database, and there is no benefit from airing your grievance... * continue to submit problem reports... every one is looked at even if there doesn't appear to be any activity on it... * help us out as much as possible with your report... this includes providing relevant documentation when you create the report as well as trying to respond quickly to questions we ask or suggestions we make... if you aren't willing to help us work on your issue, why are we wasting our time in the first place? * use the source... you have access to the source code... you (or someone you know or can hire with the proper skills) have the opportunity to find the code that is causing you a problem and fix it, even if the fix is particular to your environment and not suitable for general distribution * if your company depends on Apache httpd, consider sponsoring a skilled developer to get involved in the maintenance and ongoing development of Apache httpd * consider paying for support from one of the companies that sells support for Apache httpd (or servers based on Apache httpd) and contributes to the open source development effort of Apache httpd
Thanks Jeff. I couldn't really convince myself what the correct behaviour was when I looked at this before. If there is a 404 response which suffers from an SSL-layer error, why is it better to log a 500 than a 404; i.e. is it better to just log r->status in the non-success case? The real response code might be a useful diagnostic.
Also thanks from me Jeff. I guess it is a good idea to log the original return code in the error log in the INTERNAL_SERVER_ERROR case. I think it should be sufficient to log this for DEBUG loglevel only. Thoughts?
(based on Joe's comments) >If there is a 404 response which suffers from an SSL-layer >error, why is it better to log a 500 than a 404 It isn't, but that doesn't go through this path. (default handler will return HTTP_NOT_FOUND instead of calling ap_pass_brigade() with a file bucket) but a filter could have modified r->status to indicate an error (e.g., invalid range) >i.e. is it better to just log r->status in the non-success case? Agreed in general. I'm still nervous about r->status still OK when we get here. So that last issue leaves us with this so far: Index: server/core.c =================================================================== --- server/core.c (revision 386843) +++ server/core.c (working copy) @@ -3645,7 +3645,16 @@ e = apr_bucket_eos_create(c->bucket_alloc); APR_BRIGADE_INSERT_TAIL(bb, e); - return ap_pass_brigade(r->output_filters, bb); + status = ap_pass_brigade(r->output_filters, bb); + if (status == APR_SUCCESS + || r->status != HTTP_OK + || c->aborted) { + return r->status; + } + else { + /* no way to know what type of error occurred */ + return HTTP_INTERNAL_SERVER_ERROR; + } } else { /* unusual method (not GET or POST) */ if (r->method_number == M_INVALID) { If any kind of client communication error occurred, c->aborted should be set, right? If any kind of HTTP error occurred, r->status should have been modified, right? Perhaps we should log a message here in the other situations but still return OK, to make sure that the processing problem doesn't always go unnoticed? (example of interest to me at the moment: a filter gets APR_EOF from bucket-read because a file has been truncated during request processing)
Ruediger's comments: >I guess it is a good idea to log the original return >code in the error log in the INTERNAL_SERVER_ERROR case. Agreed. Perhaps it is okay not to even return 500 as long as we log something. >I think it should be sufficient to log this for DEBUG >loglevel only. Thoughts? I think INFO is the appropriate level, just like the expected "core_output_filter: writing data to network" messages. Some of these odd cases are probably much less expected than a user hitting the stop button.
(In reply to comment #16) > (based on Joe's comments) > >If there is a 404 response which suffers from an SSL-layer > >error, why is it better to log a 500 than a 404 > > It isn't, but that doesn't go through this path. (default handler will return > HTTP_NOT_FOUND instead of calling ap_pass_brigade() with a file bucket) good point sir > If any kind of client communication error occurred, c->aborted should be set, right? > If any kind of HTTP error occurred, r->status should have been modified, right? Both sound right to me. > Perhaps we should log a message here in the other situations but still return > OK, to make sure that the processing problem doesn't always go unnoticed? > > (example of interest to me at the moment: a filter gets APR_EOF from bucket-read > because a file has been truncated during request processing) I'm not sure about this. It would be better to avoid having such errors logged N times by all N filters in the output chain, that kind of thing creates confusion.
moving discussion to dev@httpd for the time being...
The latest patch fails. Every third or fourth request of plain ol' html files in normal HTTP mode generates 500 errors and garbage in the HTTP header. I never even got to testing SSL or CGI responses. Plain, simple HTTP fails. Any chance to get a tested and working patch?
FYI I see no discussion in the dev mailing list of this topic.
(In reply to comment #21) > FYI I see no discussion in the dev mailing list of this topic. http://mail-archives.apache.org/mod_mbox/httpd-dev/200603.mbox/%3ccc67648e0603310853m2e05c13cn9f883821a88aa3e1@mail.gmail.com%3e
(In reply to comment #20) > The latest patch fails. Every third or fourth request of plain ol' html files > in normal HTTP mode generates 500 errors and garbage in the HTTP header. I > never even got to testing SSL or CGI responses. Plain, simple HTTP fails. > > Any chance to get a tested and working patch? Please use the following patch instead and set the LogLevel to debug: Index: server/core.c =================================================================== --- server/core.c (Revision 390677) +++ server/core.c (Arbeitskopie) @@ -3646,6 +3646,20 @@ APR_BRIGADE_INSERT_TAIL(bb, e); return ap_pass_brigade(r->output_filters, bb); + status = ap_pass_brigade(r->output_filters, bb); + if (status == APR_SUCCESS + || r->status != HTTP_OK + || c->aborted) { + return r->status; + } + else { + /* no way to know what type of error occurred */ + ap_log_rerror(APLOG_MARK, APLOG_DEBUG, status, r, + "default_handler: ap_pass_brigade returned %i", + status); + return HTTP_INTERNAL_SERVER_ERROR; + } + } else { /* unusual method (not GET or POST) */ if (r->method_number == M_INVALID) { Furthermore please post the garbled HTTP header.
About the patch: It needs to return OK instead of r->status. Otherwise, an error is triggered. OK will allow r->status to be respected when appropriate. if (status == APR_SUCCESS || r->status != HTTP_OK || c->aborted) { return OK; /* r->status will be respected */ When returning r->status, you can get a complete 200 response then a 500 error document ;)
Confirmed -- that's exactly what we were seeing. 200 return code, with the text of the 500 error message at the top or bottom of pages, or in random frame windows.
Here's the patch committed to trunk (as before with the change to return OK instead of r->status): http://svn.apache.org/viewcvs.cgi?rev=390922&view=rev
(In reply to comment #26) > > http://svn.apache.org/viewcvs.cgi?rev=390922&view=rev > Please also apply http://svn.apache.org/viewcvs?rev=391025&view=rev as the previous one has a small bug that is fixed by r391025.
Proposed for backport to 2.2.x as r392700 (http://svn.apache.org/viewcvs?rev=392700&view=rev) and to 2.0.x as r392701 (http://svn.apache.org/viewcvs?rev=392701&view=rev)
Backported to 2.2.x as r393005 (http://svn.apache.org/viewcvs?rev=393005&view=rev).
*** Bug 39405 has been marked as a duplicate of this bug. ***
Will this get backported to 2.0.x?
This has been backported. It is part of 2.0.56 and later.
I thought that this was fixed in 2.2.2 but testing with a PUT handler today demonstrates that it's not fixed everywhere -- result code 70007 has been logged here. 64.13.135.30 - - [12/Sep/2006:11:28:40 -0700] "PUT /polycom/extensions/0004f204217c-app.log HTTP/1.1" 70007 - "-" "Polycom-FileManager/1.0 (libcurl/7.12.1 OpenSSL/0.9.7d) (SIP-1.6.5:0043;SPIPPolycomSoundPointIP-SPIP_501)" arran.svcolo.com 64.13.135.30 - - [12/Sep/2006:11:30:43 -0700] "PUT /polycom/extensions/0004f204217c-app.log HTTP/1.1" 70007 - "-" "Polycom-FileManager/1.0 (libcurl/7.12.1 OpenSSL/0.9.7d) (SIP-1.6.5:0043;SPIPPolycomSoundPointIP-SPIP_501)" arran.svcolo.com
It is fixed in the default handler. It is up to each handler to return the correct value. Simply returning the return value from ap_pass_brigade is wrong and leads to this errors. Please fix your PUT handler.
The PUT handler is a small 10 line script. It absolutely doesn't return a code 70007 or anything other than 0 no matter how it finishes. This is not resolved nor fixed.
(In reply to comment #35) > The PUT handler is a small 10 line script. It absolutely doesn't return a code > 70007 or anything other than 0 no matter how it finishes. Your script isn't the issue. It's the apache or third-party handler it's running under that wants fixing. If it's apache's mod_cgi or mod_cgid, it's an apache bug. Otherwise you need to look elsewhere.
I'm sorry, but I'm confused. You are saying this isn't an Apache bug... but it might be an Apache bug, report it to them? Huh? (yes I'm being a little dense on purpose, but it is honestly confusing) This is a bone stock apache configuration. No external modules. This is an Apache bug one way or the other, and reported in the apache bugzilla... how is it that you are claiming "not your bug?"
(In reply to comment #37) > I'm sorry, but I'm confused. You are saying this isn't an Apache bug... but it > might be an Apache bug, report it to them? Huh? The default handler (which *this* bug report references) doesn't handle PUT. So what you're describing is either a different bug or a notabug. It absolutely cannot be *this* bug, though it could be the same thing in another handler. > This is a bone stock apache configuration. No external modules. You need to tell us what your script is running under. Is it mod_cgi or mod_cgid?
Not cgid. I assume it's part of mod_cgi. It's really just Script PUT /path/to/put-handler.pl To what extent is this changed if *.pl is handled by AddHandler cgiwrapper *.cgi *.pl Action cgiwrapper /path/to/wrapper And again, it still seems like the it's using the return code (which is very OS-dependent) instead of a result code returned by the application.
(In reply to comment #32) > This has been backported. It is part of 2.0.56 and later. Thanks for the reply. The reason I asked is that I am seeing the following with 2.0.59: 68.174.9.93 - - [13/Sep/2006:16:57:24 +0100] "POST /articles/comment/66 HTTP/1.1" 70007 607 "http://typo.submonkey.net/articles/2006/03/09/setting-interface-link-settings-in-suns-openboot" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; MRA 4.3 (build 01218))" The target URL of the post is proxied by mod_proxy to a lighttpd backend (which is probably not working properly).
This bug has been fixed. But after yesterday's exchange with Jo Rhett, I looked at mod_cgi and mod_cgid, and found what appears to be a similar problem in both of them, when they return an error status from the *input* filters if they fail to read a request body (as in a POST/PUT request). I've fixed that similar bug - which I think you're both describing - in http://svn.apache.org/viewvc?view=rev&revision=442758
You jumped right to the chase -- I was busy building a test case to prove that effect to you. Looks good! Obviously update this when it hits a release...
(In reply to comment #41) > I've fixed that similar bug - which I think you're both describing - in > http://svn.apache.org/viewvc?view=rev&revision=442758 Thanks. I've applied those patches but still see the issue as per the access log extract above.
(In reply to comment #43) > (In reply to comment #41) > > > I've fixed that similar bug - which I think you're both describing - in > > http://svn.apache.org/viewvc?view=rev&revision=442758 > > Thanks. I've applied those patches but still see the issue as per the access > log extract above. Ah. I read your mention of POST as meaning you were using CGI. But looking up at comment #40, it was the proxy, so patching mod_cgi has no effect on you. I've just looked at mod_proxy in 2.0, and there is indeed the same bug there yet again (though it's deeper - in the mod_proxy_http provider). It's also rather more complex, but always (AFAICT) comes from ap_proxy_http_request, which in fact returns apr_status_t values. So you can fix it by applying the same fix at line 1899 of proxy_http.c.
(In reply to comment #44) > (In reply to comment #43) > > (In reply to comment #41) > > > > > I've fixed that similar bug - which I think you're both describing - in > > > http://svn.apache.org/viewvc?view=rev&revision=442758 > > > > Thanks. I've applied those patches but still see the issue as per the > access > > log extract above. > > Ah. I read your mention of POST as meaning you were using CGI. But looking > up at comment #40, it was the proxy, so patching mod_cgi has no effect on you. I did wonder :) > > I've just looked at mod_proxy in 2.0, and there is indeed the same bug there > yet again (though it's deeper - in the mod_proxy_http provider). It's also > rather more complex, but always (AFAICT) comes from ap_proxy_http_request, > which in fact returns apr_status_t values. So you can fix it by applying the > same fix at line 1899 of proxy_http.c. OK, that seems to have got it, thanks.
FWIW, I've implemented a higher-level fix, so that if this bug turns up in yet more handlers, apache will handle it internally rather than send a bogus response to the client. See http://svn.apache.org/viewvc?view=rev&revision=448711 http://svn.apache.org/viewvc?view=rev&revision=450808
Thanks Nick, that looks like the most sensible fix.