You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Eric Covener <co...@gmail.com> on 2014/08/25 22:05:02 UTC

PR56729: reqtimeout bug with fast response and slow POST

I am looking at this PR which I was able to recreate:

https://issues.apache.org/bugzilla/show_bug.cgi?id=56729

mod_reqtimeout thinks the body is still being read when it gets called
with mode=AP_MODE_SPECULATIVE during check_pipeline() near the end of
a request

Since all of the handlers processing time has gone by, it thinks the
read of the body has timed out and it returns an error, setting
AP_CONN_CLOSE and a short linger time.

Since mod_reqtimeout is below the protocol level(AP_FTYPE_CONNECTION +
8), it cannot even see the HTTP input filters EOS bucket if it's
looking for it.  I was able to add a 2nd filter that shares the
conn_config with the normal filter and sits up higher looking for the
EOS -- this seems to work

http://people.apache.org/~covener/patches/2.4.x-reqtimeout_post_error.diff

But it seemed a little hokey, but I didn't really understand if we
could instead treat that speculative read as some kind of reset point
and couldn't think of any other hook to tell reqtimeout to bail out.

Any alternatives?

-- 
Eric Covener
covener@gmail.com

RE: PR56729: reqtimeout bug with fast response and slow POST

Posted by Plüm, Rüdiger, Vodafone Group <ru...@vodafone.com>.

> -----Original Message-----
> From: Eric Covener [mailto:covener@gmail.com]
> Sent: Montag, 25. August 2014 22:05
> To: Apache HTTP Server Development List
> Subject: PR56729: reqtimeout bug with fast response and slow POST
> 
> I am looking at this PR which I was able to recreate:
> 
> https://issues.apache.org/bugzilla/show_bug.cgi?id=56729
> 
> mod_reqtimeout thinks the body is still being read when it gets called
> with mode=AP_MODE_SPECULATIVE during check_pipeline() near the end of
> a request
> 
> Since all of the handlers processing time has gone by, it thinks the
> read of the body has timed out and it returns an error, setting
> AP_CONN_CLOSE and a short linger time.
> 
> Since mod_reqtimeout is below the protocol level(AP_FTYPE_CONNECTION +
> 8), it cannot even see the HTTP input filters EOS bucket if it's
> looking for it.  I was able to add a 2nd filter that shares the
> conn_config with the normal filter and sits up higher looking for the
> EOS -- this seems to work
> 
> http://people.apache.org/~covener/patches/2.4.x-reqtimeout_post_error.diff
> 
> But it seemed a little hokey, but I didn't really understand if we
> could instead treat that speculative read as some kind of reset point
> and couldn't think of any other hook to tell reqtimeout to bail out.
> 
> Any alternatives?

I thought about to look out for an EOR bucket in an output filter. But your approach seems better
as it detects faster the end of the input stream.
Speculative reads might be also used by the handler for some reason. So I don't think they can be used
as a signal to the mod_reqtimeout filter.
OTOH speculative reads are not handled by the HTTP_INPUT filter. Hence if a handler uses a speculative
read it doesn't get the dechunking from the HTTP_INPUT filter if applicable. This only seems to make sense
if the handler doesn't handle with any possibly chunked body for whatever reason.

Regards

Rüdiger



Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Yann Ylavic <yl...@gmail.com>.
On Sun, Nov 23, 2014 at 12:11 AM, Eric Covener <co...@gmail.com> wrote:
> On Thu, Nov 20, 2014 at 9:57 AM, Yann Ylavic <yl...@gmail.com> wrote:
>> On Wed, Nov 19, 2014 at 1:13 PM, Eric Covener <co...@gmail.com> wrote:
>>> On Wed, Nov 19, 2014 at 4:47 AM, Yann Ylavic <yl...@gmail.com> wrote:
>>>> Errr, this is in 2.2.x/STATUS only (not 2.4.x).
>>>> Is it already proposed/backported to 2.4.x (I can't find the commit)?
>>>
>>> I diff'ed trunk and 2.4 and It seems to be absent.
>>>
>>> I don't have the best handle on this, but if we're about to go down
>>> into a blocking read, wouldn't we want to check the time left and
>>> reduce the timeout?
>>
>> Yes, good point.
>>
>> Maybe this way then?
>>
>> Index: modules/filters/mod_reqtimeout.c
>> ===================================================================
>> --- modules/filters/mod_reqtimeout.c    (revision 1640032)
>> +++ modules/filters/mod_reqtimeout.c    (working copy)
>> @@ -311,7 +311,12 @@ static apr_status_t reqtimeout_filter(ap_filter_t
>>      else {
>>          /* mode != AP_MODE_GETLINE */
>>          rv = ap_get_brigade(f->next, bb, mode, block, readbytes);
>> -        if (ccfg->min_rate > 0 && rv == APR_SUCCESS) {
>> +        /* Don't extend the timeout in speculative mode, wait for
>> +         * the real (relevant) bytes to be asked later, within the
>> +         * currently alloted time.
>> +         */
>> +        if (ccfg->min_rate > 0 && rv == APR_SUCCESS
>> +                && mode != AP_MODE_SPECULATIVE) {
>>              extend_timeout(ccfg, bb);
>>          }
>>      }
>
> Looks good

Commited in r1641376.

However, I now think you were right with your original proposal to
bypass the filter based on EOS :p
I don't see any reason why we should not do the same for blocking and
nonblocking reads.
The call from check_pipeline() is an exception that shouldn't
interfere with the real calls from modules.

So the current code (including r1641376) is probably "good enough" for
2.2.x, but maybe we could make it better for trunk and 2.4.x.

A first proposal is straight forward from you original patch :
- bypass the filter when the request is over (base on EOS seen),
- check the timeout (but don't extend it) in speculative mode for both
blocking and nonblocking reads.
See httpd-trunk-reqtimeout_filter_eos.patch attached.

A second proposal would be to have an optional function from
mod_reqtimeout to (des)activate itself on demand.
Thus check_pipeline() can use it (if not NULL, ie. mod_reqtimeout
loaded) before/after the read to desactivate/reactivate the checks.
This is maybe more intrusive (requires a new
ap_init_request_processing() function is http_request.h) but is less
dependent on mod_reqtimeout seeing the EOS (and it could also be used
where currently mod_reqtimeout is forcibly removed from the chain).
See httpd-trunk-reqtimeout_set_inactive.patch attached.

WDYT?

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Eric Covener <co...@gmail.com>.
On Thu, Nov 20, 2014 at 9:57 AM, Yann Ylavic <yl...@gmail.com> wrote:
> On Wed, Nov 19, 2014 at 1:13 PM, Eric Covener <co...@gmail.com> wrote:
>> On Wed, Nov 19, 2014 at 4:47 AM, Yann Ylavic <yl...@gmail.com> wrote:
>>> Errr, this is in 2.2.x/STATUS only (not 2.4.x).
>>> Is it already proposed/backported to 2.4.x (I can't find the commit)?
>>
>> I diff'ed trunk and 2.4 and It seems to be absent.
>>
>> I don't have the best handle on this, but if we're about to go down
>> into a blocking read, wouldn't we want to check the time left and
>> reduce the timeout?
>
> Yes, good point.
>
> Maybe this way then?
>
> Index: modules/filters/mod_reqtimeout.c
> ===================================================================
> --- modules/filters/mod_reqtimeout.c    (revision 1640032)
> +++ modules/filters/mod_reqtimeout.c    (working copy)
> @@ -311,7 +311,12 @@ static apr_status_t reqtimeout_filter(ap_filter_t
>      else {
>          /* mode != AP_MODE_GETLINE */
>          rv = ap_get_brigade(f->next, bb, mode, block, readbytes);
> -        if (ccfg->min_rate > 0 && rv == APR_SUCCESS) {
> +        /* Don't extend the timeout in speculative mode, wait for
> +         * the real (relevant) bytes to be asked later, within the
> +         * currently alloted time.
> +         */
> +        if (ccfg->min_rate > 0 && rv == APR_SUCCESS
> +                && mode != AP_MODE_SPECULATIVE) {
>              extend_timeout(ccfg, bb);
>          }
>      }

Looks good

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Yann Ylavic <yl...@gmail.com>.
On Wed, Nov 19, 2014 at 1:13 PM, Eric Covener <co...@gmail.com> wrote:
> On Wed, Nov 19, 2014 at 4:47 AM, Yann Ylavic <yl...@gmail.com> wrote:
>> Errr, this is in 2.2.x/STATUS only (not 2.4.x).
>> Is it already proposed/backported to 2.4.x (I can't find the commit)?
>
> I diff'ed trunk and 2.4 and It seems to be absent.
>
> I don't have the best handle on this, but if we're about to go down
> into a blocking read, wouldn't we want to check the time left and
> reduce the timeout?

Yes, good point.

Maybe this way then?

Index: modules/filters/mod_reqtimeout.c
===================================================================
--- modules/filters/mod_reqtimeout.c    (revision 1640032)
+++ modules/filters/mod_reqtimeout.c    (working copy)
@@ -311,7 +311,12 @@ static apr_status_t reqtimeout_filter(ap_filter_t
     else {
         /* mode != AP_MODE_GETLINE */
         rv = ap_get_brigade(f->next, bb, mode, block, readbytes);
-        if (ccfg->min_rate > 0 && rv == APR_SUCCESS) {
+        /* Don't extend the timeout in speculative mode, wait for
+         * the real (relevant) bytes to be asked later, within the
+         * currently alloted time.
+         */
+        if (ccfg->min_rate > 0 && rv == APR_SUCCESS
+                && mode != AP_MODE_SPECULATIVE) {
             extend_timeout(ccfg, bb);
         }
     }

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Eric Covener <co...@gmail.com>.
On Wed, Nov 19, 2014 at 4:47 AM, Yann Ylavic <yl...@gmail.com> wrote:
> Errr, this is in 2.2.x/STATUS only (not 2.4.x).
> Is it already proposed/backported to 2.4.x (I can't find the commit)?

I diff'ed trunk and 2.4 and It seems to be absent.

I don't have the best handle on this, but if we're about to go down
into a blocking read, wouldn't we want to check the time left and
reduce the timeout?

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Yann Ylavic <yl...@gmail.com>.
On Wed, Nov 19, 2014 at 10:26 AM, Yann Ylavic <yl...@gmail.com> wrote:
> Eric, Jeff, since you already voted for r1621453 in 2.4.x/STATUS

Errr, this is in 2.2.x/STATUS only (not 2.4.x).
Is it already proposed/backported to 2.4.x (I can't find the commit)?

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Yann Ylavic <yl...@gmail.com>.
On Sat, Aug 30, 2014 at 3:19 PM, Yann Ylavic <yl...@gmail.com> wrote:
> On Sat, Aug 30, 2014 at 3:02 PM, Eric Covener <co...@gmail.com> wrote:
>> On Tue, Aug 26, 2014 at 5:22 AM, Yann Ylavic <yl...@gmail.com> wrote:
>>> I don't think mod_reqtimeout should handle/count speculative bytes,
>>> they ought to be read for real later (and taken into account then).
>>> Otherwise, the same bytes may be counted multiple times.
>>>
>>> How about simply forward the ap_get_brigade() call?
>>
>> Makes sense --  I did limit it to nonblock as well. Can you take a
>> look before I propose? http://svn.apache.org/r1621453
>
> I'm not sure we should limit it to nonblock, speculative mode is
> mainly to be used in non-blocking, but ap_rgetline_core() for example
> does not (when folding), so mod_reqtimeout may still count header
> bytes twice.

Eric, Jeff, since you already voted for r1621453 in 2.4.x/STATUS, how
about this additional patch?
As said above, IMHO we really shouldn't count any speculative bytes in
mod_reqtimeout (nonblocking or not), relevant data should be asked
"for real" soon or later.

Index: modules/filters/mod_reqtimeout.c
===================================================================
--- modules/filters/mod_reqtimeout.c    (revision 1640032)
+++ modules/filters/mod_reqtimeout.c    (working copy)
@@ -183,12 +183,13 @@ static apr_status_t reqtimeout_filter(ap_filter_t
         return ap_get_brigade(f->next, bb, mode, block, readbytes);
     }

-    if (block == APR_NONBLOCK_READ && mode == AP_MODE_SPECULATIVE) {
+    if (mode == AP_MODE_SPECULATIVE) {
         /*  The source of these above us in the core is check_pipeline(), which
          *  is between requests but before this filter knows to reset timeouts
-         *  during log_transaction().  If they appear elsewhere, just don't
-         *  check or extend the time since they won't block and we'll see the
-         *  bytes again later
+         *  during log_transaction(), or ap_rgetline_core() to handle headers'
+         *  folding (next char prefetch).  Likewise, if they appear elsewhere,
+         *  just don't check or extend the time since we should see the
+         *  relevant bytes again later.
          */
         return ap_get_brigade(f->next, bb, mode, block, readbytes);
     }
>
> Regards,
> Yann.

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Yann Ylavic <yl...@gmail.com>.
On Sat, Aug 30, 2014 at 3:02 PM, Eric Covener <co...@gmail.com> wrote:
> On Tue, Aug 26, 2014 at 5:22 AM, Yann Ylavic <yl...@gmail.com> wrote:
>> I don't think mod_reqtimeout should handle/count speculative bytes,
>> they ought to be read for real later (and taken into account then).
>> Otherwise, the same bytes may be counted multiple times.
>>
>> How about simply forward the ap_get_brigade() call?
>
> Makes sense --  I did limit it to nonblock as well. Can you take a
> look before I propose? http://svn.apache.org/r1621453

I'm not sure we should limit it to nonblock, speculative mode is
mainly to be used in non-blocking, but ap_rgetline_core() for example
does not (when folding), so mod_reqtimeout may still count header
bytes twice.

Otherwise, looks good to me.

Regards,
Yann.

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Eric Covener <co...@gmail.com>.
On Tue, Aug 26, 2014 at 5:22 AM, Yann Ylavic <yl...@gmail.com> wrote:
> On Mon, Aug 25, 2014 at 10:05 PM, Eric Covener <co...@gmail.com> wrote:
>> But it seemed a little hokey, but I didn't really understand if we
>> could instead treat that speculative read as some kind of reset point
>> and couldn't think of any other hook to tell reqtimeout to bail out.
>>
>> Any alternatives?
>
> I don't think mod_reqtimeout should handle/count speculative bytes,
> they ought to be read for real later (and taken into account then).
> Otherwise, the same bytes may be counted multiple times.
>
> How about simply forward the ap_get_brigade() call?

Makes sense --  I did limit it to nonblock as well. Can you take a
look before I propose? http://svn.apache.org/r1621453

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Yann Ylavic <yl...@gmail.com>.
On Mon, Aug 25, 2014 at 10:05 PM, Eric Covener <co...@gmail.com> wrote:
> But it seemed a little hokey, but I didn't really understand if we
> could instead treat that speculative read as some kind of reset point
> and couldn't think of any other hook to tell reqtimeout to bail out.
>
> Any alternatives?

I don't think mod_reqtimeout should handle/count speculative bytes,
they ought to be read for real later (and taken into account then).
Otherwise, the same bytes may be counted multiple times.

How about simply forward the ap_get_brigade() call?

Regards,
Yann.

Re: PR56729: reqtimeout bug with fast response and slow POST

Posted by Eric Covener <co...@gmail.com>.
On Mon, Aug 25, 2014 at 4:05 PM, Eric Covener <co...@gmail.com> wrote:
> I am looking at this PR which I was able to recreate:
>
> https://issues.apache.org/bugzilla/show_bug.cgi?id=56729


Whoops, I got the topic backwards. Fast post, slow response.

-- 
Eric Covener
covener@gmail.com