You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Jeff Trawick <tr...@attglobal.net> on 2002/10/29 17:06:11 UTC
[PATCH] checking for failures encountered by core_output_filter
As one part of a fix to get scripts terminated if the connection
drops, the change below was required in the content length filter
(checking f->c->aborted). What worries me is that this check probably
needs to be added elsewhere as well.
core_output_filter was previously changed to return APR_SUCCESS on
failure in order to keep non-HTTP-status codes out of access_log
because the return value from the filter was getting logged instead of
r->status. Requiring filters to return HTTP status codes (or
APR_SUCCESS if the error won't map to HTTP status) flies in the face
of the documentation in util_filter.h. Also, many of these possible
errors are encountered after the header (and thus HTTP response code)
has already been passed down by the http header filter. But if we
already wrote "200 OK" (or whatever) to the client it doesn't seem
proper for a filter to subsequently return 500 when something blows up
and then for the 500 to be logged as the status of the request.
Somehow it seems more intuitive for J. Random Filter to be able to
set/check function return values and set r->status if necessary and
not worry about c->aborted (except for special filters like
core_output that need to set c->aborted sometimes).
Maybe I can find time to review any old discussion about this to see
if there were good reasons for changing the output filter interface :)
Index: server/protocol.c
===================================================================
RCS file: /home/cvs/httpd-2.0/server/protocol.c,v
retrieving revision 1.119
diff -u -r1.119 protocol.c
--- server/protocol.c 2 Oct 2002 13:41:45 -0000 1.119
+++ server/protocol.c 29 Oct 2002 15:12:35 -0000
@@ -1260,7 +1260,7 @@
APR_BRIGADE_INSERT_TAIL(b, flush);
rv = ap_pass_brigade(f->next, b);
- if (rv != APR_SUCCESS) {
+ if (rv != APR_SUCCESS || f->c->aborted) {
apr_brigade_destroy(split);
return rv;
}
--
Jeff Trawick | trawick@attglobal.net
Born in Roswell... married an alien...
Re: [PATCH] checking for failures encountered by
core_output_filter
Posted by "William A. Rowe, Jr." <wr...@apache.org>.
At 10:07 AM 11/4/2002, Jeff Trawick wrote:
>Justin Erenkrantz <je...@apache.org> writes:
>
>> >> I don't buy that logic at all. Why should we be returning
>> >> APR_SUCCESS here? We want to signal an error, so that the filters
>> >> stop what they are doing and exit.
>> >
>> > Talk to Ryan :)
>>
>> Well, he ain't here no more. Just us folks. Do you (or anyone else)
>> see a reason why we shouldn't change this?
>
>interpret "Talk to Ryan" as "I can't justify the current behavior" :)
>
>We should make the change to return an APR error code here.
Agreed. If we really have to dig through and find ALL of the areas where
the current behavior disagrees, this seems like the time to do it. Choose
one; return apr_status_t and pay attention only to r->status and c->aborted
for logging (the right decision IMHO) or return HTTP statuses (ick.)
Either way it's the same amount of work, no?
I'm discovering the same confusion in the SSL filter right now, which has
never paid attention to c->aborted within ssl_engine_io.c.
>> > I'm kinda stuck thinking that the philosophy should be that we log
>> > whatever was written to the client in the status line, but there are
>> > some implementation details with that one.
>>
>> How do we differentiate between a 200 that all the data was sent for
>> and a 200 where the client aborted? If someone looked at the access
>> logs, they would see that the transmitted length wasn't correct in the
>> aborted case. Perhaps that was Ryan's initial motivation - did he
>> want the length to be what we wanted to send not what we actually
>> sent? (mod_logio is bringing up some of these concerns as well.)
>>
>> I guess I'd like to see some notation in access log that indicates,
>> "Hey, we know we didn't send everything, but that's because they left
>> in the middle." Yes, it also might be noted in the error log, but I
>> gotta believe it's goodness to have tools looking at just the access
>> logs know that the client aborted.
>
>FWIW, this is what happens with 1.3 when the client drops the
>connection before reading the entire response. In this case, the
>client read several bytes of a 1MB response (though the client TCP
>accepted a lot more).
>
> [Mon Nov 4 10:31:22 2002] [info] [client 9.27.32.119] (32)Broken pipe:
> client stopped connection before send mmap completed
>
> 9.27.32.119 - - [04/Nov/2002:10:31:22 -0500] "GET /bigfile.html" 200 65536
>
>Even though Apache could have noticed that it sent only 64K out of
>1MB, it still logged 200. The 64K isn't even an indication of how
>much the client really read. It is simply how much TCP was willing to
>buffer. Also, I suspect that we can hit the first indication of a
>dropped connection after the previous response has been noted in the
>log.
Right, and that's good behavior. The REQUEST resulted in a 200. What
the RESPONSE did while serving it is another matter.
>I'm not sure what promises we can make about what is in the access
>log.
>
>> > One issue with that is that the filter that encounters the error
>> > really should do the logging so that the most specific information
>> > is available. If some other code also logs less-specific info,
>> > then it is all for naught.
>>
>> Makes sense. So, core_output_filter should be calling
>> ap_log_rerror. Hmm. Does it have access to the request_rec? Didn't
>> we change that? Or, was I vetoed on that? -- justin
>
>I don't recall that conversation. Regardless, I wonder how
>core_output_filter could know the r associated with a particular
>bucket?
It shouldn't need to... the response should probably percolate back
to the handler, via r->status, but the connection filter shouldn't need
to be aware of it. If you wanted to log the 'error' associated with the
request (e.g. transmission troubles), that would probably need to
percolate with the bucket.
Bill
Re: [PATCH] checking for failures encountered by core_output_filter
Posted by Jeff Trawick <tr...@attglobal.net>.
Justin Erenkrantz <je...@apache.org> writes:
> Makes sense. So, core_output_filter should be calling
> ap_log_rerror. Hmm. Does it have access to the request_rec? Didn't
> we change that? Or, was I vetoed on that? -- justin
why no ap_log_cerror() I wonder? at least that would be better than
ap_log_error() in that it can format the client address
--
Jeff Trawick | trawick@attglobal.net
Born in Roswell... married an alien...
Re: [PATCH] checking for failures encountered by core_output_filter
Posted by Jeff Trawick <tr...@attglobal.net>.
Justin Erenkrantz <je...@apache.org> writes:
> >> I don't buy that logic at all. Why should we be returning
> >> APR_SUCCESS here? We want to signal an error, so that the filters
> >> stop what they are doing and exit.
> >
> > Talk to Ryan :)
>
> Well, he ain't here no more. Just us folks. Do you (or anyone else)
> see a reason why we shouldn't change this?
interpret "Talk to Ryan" as "I can't justify the current behavior" :)
We should make the change to return an APR error code here.
> > I'm kinda stuck thinking that the philosophy should be that we log
> > whatever was written to the client in the status line, but there are
> > some implementation details with that one.
>
> How do we differentiate between a 200 that all the data was sent for
> and a 200 where the client aborted? If someone looked at the access
> logs, they would see that the transmitted length wasn't correct in the
> aborted case. Perhaps that was Ryan's initial motivation - did he
> want the length to be what we wanted to send not what we actually
> sent? (mod_logio is bringing up some of these concerns as well.)
>
> I guess I'd like to see some notation in access log that indicates,
> "Hey, we know we didn't send everything, but that's because they left
> in the middle." Yes, it also might be noted in the error log, but I
> gotta believe it's goodness to have tools looking at just the access
> logs know that the client aborted.
FWIW, this is what happens with 1.3 when the client drops the
connection before reading the entire response. In this case, the
client read several bytes of a 1MB response (though the client TCP
accepted a lot more).
[Mon Nov 4 10:31:22 2002] [info] [client 9.27.32.119] (32)Broken pipe:
client stopped connection before send mmap completed
9.27.32.119 - - [04/Nov/2002:10:31:22 -0500] "GET /bigfile.html" 200 65536
Even though Apache could have noticed that it sent only 64K out of
1MB, it still logged 200. The 64K isn't even an indication of how
much the client really read. It is simply how much TCP was willing to
buffer. Also, I suspect that we can hit the first indication of a
dropped connection after the previous response has been noted in the
log.
I'm not sure what promises we can make about what is in the access
log.
> > One issue with that is that the filter that encounters the error
> > really should do the logging so that the most specific information
> > is available. If some other code also logs less-specific info,
> > then it is all for naught.
>
> Makes sense. So, core_output_filter should be calling
> ap_log_rerror. Hmm. Does it have access to the request_rec? Didn't
> we change that? Or, was I vetoed on that? -- justin
I don't recall that conversation. Regardless, I wonder how
core_output_filter could know the r associated with a particular
bucket?
--
Jeff Trawick | trawick@attglobal.net
Born in Roswell... married an alien...
Re: [PATCH] checking for failures encountered by
core_output_filter
Posted by Justin Erenkrantz <je...@apache.org>.
--On Friday, November 1, 2002 11:13 AM -0500 Jeff Trawick
<tr...@attglobal.net> wrote:
> The only filter I changed was the content-length filter.
>
> But yes I would agree that in a commit which fixes our handlers as
> you mentioned we also fix the content-length filter to not worry
> about c->aborted.
>
> Note that I changed the mod_cgi handler to look at c->aborted as
> well as rv after ap_pass_brigade(). In all honesty I don't know
> who gets to set c->aborted and whether rv absolutely must be
> non-APR_SUCCESS if aborted is set. But I suspect that mod_cgi
> wouldn't have to check both rv and c->aborted to see if an error
> occurred talking to the client.
Right. That's why I'm saying we should change core_output_filter as
I described (so that it returns APR_ECONNABORTED in this case).
(Don't think we're disagreeing on that.)
>> I don't buy that logic at all. Why should we be returning
>> APR_SUCCESS here? We want to signal an error, so that the filters
>> stop what they are doing and exit.
>
> Talk to Ryan :)
Well, he ain't here no more. Just us folks. Do you (or anyone else)
see a reason why we shouldn't change this?
> I'm kinda stuck thinking that the philosophy should be that we log
> whatever was written to the client in the status line, but there are
> some implementation details with that one.
How do we differentiate between a 200 that all the data was sent for
and a 200 where the client aborted? If someone looked at the access
logs, they would see that the transmitted length wasn't correct in
the aborted case. Perhaps that was Ryan's initial motivation - did
he want the length to be what we wanted to send not what we actually
sent? (mod_logio is bringing up some of these concerns as well.)
I guess I'd like to see some notation in access log that indicates,
"Hey, we know we didn't send everything, but that's because they left
in the middle." Yes, it also might be noted in the error log, but I
gotta believe it's goodness to have tools looking at just the access
logs know that the client aborted.
> One issue with that is that the filter that encounters the error
> really should do the logging so that the most specific information
> is available. If some other code also logs less-specific info,
> then it is all for naught.
Makes sense. So, core_output_filter should be calling ap_log_rerror.
Hmm. Does it have access to the request_rec? Didn't we change that?
Or, was I vetoed on that? -- justin
Re: [PATCH] checking for failures encountered by core_output_filter
Posted by Jeff Trawick <tr...@attglobal.net>.
Justin Erenkrantz <je...@apache.org> writes:
> I think your commits to check c->aborted in various filters should be
> replaced by getting core_input_filter to return APR_ECONNABORTED.
The only filter I changed was the content-length filter.
But yes I would agree that in a commit which fixes our handlers as you
mentioned we also fix the content-length filter to not worry about
c->aborted.
Note that I changed the mod_cgi handler to look at c->aborted as well
as rv after ap_pass_brigade(). In all honesty I don't know who gets
to set c->aborted and whether rv absolutely must be non-APR_SUCCESS if
aborted is set. But I suspect that mod_cgi wouldn't have to check
both rv and c->aborted to see if an error occurred talking to the
client.
> Namely the following lines in core_output_filter (server/core.c:4002)
> are wrong:
>
> /* No need to check for SUCCESS, we did that above. */
> if (!APR_STATUS_IS_EAGAIN(rv)) {
> c->aborted = 1;
> }
>
> /* The client has aborted, but the request was successful. We
> * will report success, and leave it to the access and error
> * logs to note that the connection was aborted.
> */
> return APR_SUCCESS;
>
> I don't buy that logic at all. Why should we be returning APR_SUCCESS
> here? We want to signal an error, so that the filters stop what they
> are doing and exit.
Talk to Ryan :)
>
> Hmm. By what I just said for default_handler, if a client aborts,
> that would mean that the handler would be returning with a 500. Hmmm.
> Perhaps we could catch the c->aborted case in the default handler and
> just 'lie' and say that it would have been a 200. Hmm. Not sure about
> that one. Thoughts?
I'm kinda stuck thinking that the philosophy should be that we log
whatever was written to the client in the status line, but there are
some implementation details with that one.
> Random thought: define a new HTTP status code which means 'Client got
> the hell out of here, so we stopped early' (207??). Remember that
> this status code is only going to be presented via the access logs, so
> we really don't need 'support' from HTTP clients. That could solve
> our problem...
>
> > Code playing with HTTP status codes should be analyzed to ensure
> > that what is logged is what was written to the client (I guess?)
> > (i.e., some subsequent error doesn't overwrite r->status or
> > whatever is passed to the logger).
>
> Do we really want to be logging if a filter has an error?
What I meant by "what is logged" is "which HTTP status code ends up in
the access log". I didn't mean error log. We'll always write to the
access log (i.e., we'll always run that logging hook) for any request
that we actually read, right?
> Here's
> another random thought: introduce a logging filter at the top of the
> filter chain which will write a note to the error log if the filters
> return something other than APR_SUCCESS. This way we don't have to
> explicitly handle that in all of the handlers.
One issue with that is that the filter that encounters the error
really should do the logging so that the most specific information is
available. If some other code also logs less-specific info, then it
is all for naught.
I'll try not to think about this until Monday :)
--
Jeff Trawick | trawick@attglobal.net
Born in Roswell... married an alien...
Re: [PATCH] checking for failures encountered by
core_output_filter
Posted by Justin Erenkrantz <je...@apache.org>.
--On Thursday, October 31, 2002 4:58 PM -0500 Jeff Trawick
<tr...@attglobal.net> wrote:
> default_handler(), which should be returning HTTP status code,
> returns whatever ap_pass_brigade() returns. default_handler()
> would have to change too. Any other handlers as well (In the
> thread I pointed to, Ryan claimed that 99% of handlers return
> whatever ap_pass_brigade() returned. So I suspect that some other
> handlers need to be changed as well.)
Right, it's been a long-standing problem that this API is completely
horked (yet another reason I'm not overjoyed with the thought of
forcing the 2.0.43 module API on all developers until we release a
2.4/3.0). OtherBill just suggested to me a solution like changing
the default_handler line from:
return ap_pass_brigade(r->output_filters, bb);
to:
rv = ap_pass_brigade(r->output_filters, bb);
if (rv != APR_SUCCESS && r->status == HTTP_OK) {
return HTTP_INTERNAL_SERVER_ERROR;
}
else {
return r->status;
}
That way, if a filter does set r->status for some reason, we return
that value, otherwise we return 500.
Handlers should be returning HTTP status codes, while filters should
be returning APR status codes. I find myself believe that is the
right model, because in theory (gah!), the filters could be more than
just HTTP. Too bad we can't use enums for one of those status codes
and wash our hands of the whole deal by relying on type safety. Oh,
well.
I think your commits to check c->aborted in various filters should be
replaced by getting core_input_filter to return APR_ECONNABORTED.
Namely the following lines in core_output_filter (server/core.c:4002)
are wrong:
/* No need to check for SUCCESS, we did that above. */
if (!APR_STATUS_IS_EAGAIN(rv)) {
c->aborted = 1;
}
/* The client has aborted, but the request was successful. We
* will report success, and leave it to the access and error
* logs to note that the connection was aborted.
*/
return APR_SUCCESS;
I don't buy that logic at all. Why should we be returning
APR_SUCCESS here? We want to signal an error, so that the filters
stop what they are doing and exit.
Hmm. By what I just said for default_handler, if a client aborts,
that would mean that the handler would be returning with a 500.
Hmmm. Perhaps we could catch the c->aborted case in the default
handler and just 'lie' and say that it would have been a 200. Hmm.
Not sure about that one. Thoughts?
Random thought: define a new HTTP status code which means 'Client got
the hell out of here, so we stopped early' (207??). Remember that
this status code is only going to be presented via the access logs,
so we really don't need 'support' from HTTP clients. That could
solve our problem...
> Code playing with HTTP status codes should be analyzed to ensure
> that what is logged is what was written to the client (I guess?)
> (i.e., some subsequent error doesn't overwrite r->status or
> whatever is passed to the logger).
Do we really want to be logging if a filter has an error? Here's
another random thought: introduce a logging filter at the top of the
filter chain which will write a note to the error log if the filters
return something other than APR_SUCCESS. This way we don't have to
explicitly handle that in all of the handlers.
> clear as mud?
Oh, sure. -- justin
Re: [PATCH] checking for failures encountered by core_output_filter
Posted by Jeff Trawick <tr...@attglobal.net>.
Justin Erenkrantz <je...@apache.org> writes:
> --On Thursday, October 31, 2002 6:10 AM -0500 Jeff Trawick
> <tr...@attglobal.net> wrote:
>
> > incorrect doc (util_filter.h) which says that APR status codes
> > should be returned
>
> I'm confused. Why is that incorrect? APR status codes *should* be
> returned by the filters. If a filter has an error, it should be
> producing an error bucket, passing it down the chain, and then
> returning an APR error code (well, Ryan always said it should pass
> APR_SUCCESS back, but I never quite agreed with that).
>
> About the only filters that can't punt like that are the connection
> filters. They should be returning an APR error code in this
> case. Then, the http_output_filter (?) could detect the connection was
> aborted and set r->status to whatever it likes.
>
> To me, it sounds like when c->aborted is set, APR_SUCCESS is returned.
> That's the problem, isn't it?
First, I suspect that you and I widely agree on how it should work.
Most of your response is simply preaching to the choir :) I believe
that you and I probably interpret how it is "working" now differently
though.
This is an overall design issue which needs to be resolved. That one
line (what to return when the connection is reset) is not the entire
problem. We're at the point where Ryan's desired design isn't
completely implemented and how you think it works isn't completely
implemented either. Both designs are off by more than a couple lines
of code. Thus my message.
default_handler(), which should be returning HTTP status code, returns
whatever ap_pass_brigade() returns. default_handler() would have to
change too. Any other handlers as well (In the thread I pointed to,
Ryan claimed that 99% of handlers return whatever ap_pass_brigade()
returned. So I suspect that some other handlers need to be changed as
well.)
> > a filter can return non-200 after the status line has been
> > written to the network... what is the meaning of that w.r.t.
> > logging?
>
> How is that possible?
This point was a complaint against the design which Ryan espoused and
which is partially implemented, not against how you or I would like it
to work. An error can occur after the status line has been written
(e.g., db lookup fails or something when filtering... make something
up :) )... If the retcode of filters is logged (which it is), then
the filter has to report the failure in a way that causes a valid HTTP
status code to be logged. But like I say, what is the point of
returning non-200.
Code playing with HTTP status codes should be analyzed to ensure that
what is logged is what was written to the client (I guess?) (i.e.,
some subsequent error doesn't overwrite r->status or whatever is
passed to the logger).
clear as mud?
--
Jeff Trawick | trawick@attglobal.net
Born in Roswell... married an alien...
Re: [PATCH] checking for failures encountered by
core_output_filter
Posted by Justin Erenkrantz <je...@apache.org>.
--On Thursday, October 31, 2002 6:10 AM -0500 Jeff Trawick
<tr...@attglobal.net> wrote:
> incorrect doc (util_filter.h) which says that APR status codes
> should be returned
I'm confused. Why is that incorrect? APR status codes *should* be
returned by the filters. If a filter has an error, it should be
producing an error bucket, passing it down the chain, and then
returning an APR error code (well, Ryan always said it should pass
APR_SUCCESS back, but I never quite agreed with that).
About the only filters that can't punt like that are the connection
filters. They should be returning an APR error code in this case.
Then, the http_output_filter (?) could detect the connection was
aborted and set r->status to whatever it likes.
To me, it sounds like when c->aborted is set, APR_SUCCESS is
returned. That's the problem, isn't it?
> several troubling aspects of the interface:
>
> every filter that does further processing after
> ap_pass_brigade() (e.g., content-length filter) should check
> retcode and c->aborted after ap_pass_brigade() to see if it
> should continue processing
Again, why not return something other than APR_SUCCESS when
c->aborted is set?
> retcode type apr_status_t isn't the perfect match for HTTP
> status code... the HTTP status code could be stored in a user
> code range within apr_status_t but that isn't done now
Correct, but filters don't understand HTTP and never will. If you
restrict ourselves to HTTP-only, then how do we deal with other
protocols? In fact, there should only be one filter which has
knowledge of HTTP - the http_output_filter. Nothing else should be
aware of what protocol we're using.
> a filter can return non-200 after the status line has been
> written to the network... what is the meaning of that w.r.t.
> logging?
How is that possible?
> IMHO, real APR status codes *are* the natural thing to return
> from a filter... it isn't like bucket read returns an HTTP code
> :) it isn't like our portability layer maps local errors to
> HTTP codes either
Right, so I'm confused as to why you are trying to change it here.
> "bad" filters (return real APR status codes when the going gets
> tough):
No, I say they are the 'good' filters. =)
> "good" filters (return real HTTP codes when the going gets
> tough)
I say these are 'broken' filters.
> while core_output will rightfully set c->aborted if it
> encounters a dropped connection, and thus doesn't have to make
> up a bogus status code, how many other filters have that option?
Have it return APR_ECONNABORTED.
I'm really confused as to what your complaint is. -- justin
Re: [PATCH] checking for failures encountered by core_output_filter
Posted by Jeff Trawick <tr...@attglobal.net>.
Jeff Trawick <tr...@attglobal.net> writes:
> Maybe I can find time to review any old discussion about this to see
> if there were good reasons for changing the output filter interface :)
See the discussion back in March 2002 with subject
[PATCH] invalid HTTP status codes in access log
I don't see any consensus on how that problem should have been fixed
(which is perhaps a lame way of saying I don't like what was
committed). Something was commited and some important questions led
in other directions. Hopefully this can be resolved in 2.1 timeframe.
What we have now is:
incorrect doc (util_filter.h) which says that APR status codes
should be returned
several troubling aspects of the interface:
every filter that does further processing after ap_pass_brigade()
(e.g., content-length filter) should check retcode and c->aborted
after ap_pass_brigade() to see if it should continue processing
retcode type apr_status_t isn't the perfect match for HTTP status
code... the HTTP status code could be stored in a user code range
within apr_status_t but that isn't done now
a filter can return non-200 after the status line has been written
to the network... what is the meaning of that w.r.t. logging?
IMHO, real APR status codes *are* the natural thing to return
from a filter... it isn't like bucket read returns an HTTP code
:) it isn't like our portability layer maps local errors to HTTP
codes either
"bad" filters (return real APR status codes when the going gets tough):
content-length
deflate
include
mod_ext_filter
mod_charset_lite
"good" filters (return real HTTP codes when the going gets tough)
core-output
while core_output will rightfully set c->aborted if it encounters
a dropped connection, and thus doesn't have to make up a bogus
status code, how many other filters have that option?
--
Jeff Trawick | trawick@attglobal.net
Born in Roswell... married an alien...