You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Joe Orton <jo...@redhat.com> on 2005/10/25 11:33:11 UTC

Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

On Mon, Oct 24, 2005 at 03:33:17AM -0000, Brian Pane wrote:
> Author: brianp
> Date: Sun Oct 23 20:33:14 2005
> New Revision: 327945
> 
> URL: http://svn.apache.org/viewcvs?rev=327945&view=rev
> Log:
> Async write completion for Event MPM
> (backported from async-dev branch to 2.3 trunk)

httpd-test runs against the trunk are failing all over the place today, 
I guess caused by one of these changes...

prefork is failing like:

Failed Test                Stat Wstat Total Fail  Failed  List of Failed
-------------------------------------------------------------------------------
t/modules/proxy.t                        13   11  84.62%  1-9 12-13
t/modules/proxy_balancer.t                1    1 100.00%  1
t/modules/rewrite.t                      22    5  22.73%  17-18 20-22
t/protocol/echo.t           255 65280     8    8 100.00%  1-8
t/security/CAN-2005-2700.t                2    1  50.00%  1
... plus almost all of t/ssl/* fail

and similarly for worker, which also triggers a segfault in the proxy 
(attached the log output for worker)

joe

Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by Brian Pane <br...@apache.org>.
On Oct 30, 2005, at 4:17 AM, Joe Orton wrote:

> On Sun, Oct 30, 2005 at 09:56:45AM +0000, Joe Orton wrote:
>
>> On Sat, Oct 29, 2005 at 02:23:51PM -0700, Brian Pane wrote:
>>
>>> With fix 329484 committed, I'm now getting a clean test run of the
>>> perl_framework tests with --enable-pool-debug=all
>>>
>>
>> Thanks, all test runs passed last night here too.
>>
>
> Hmm, lots of segfaults from some manual testing though:
> ap_process_http_connection is using r after r->pool is destroyed:
>
> ...
>             ap_process_request(r);
>
>         if (ap_extended_status)
>             ap_increment_counts(c->sbh, r);
> ...
>         ap_update_child_status(c->sbh, SERVER_BUSY_KEEPALIVE, r);

The cleanest fix I can think of is to run the ap_increment_counts and
ap_update_child_status from the EOR bucket destruction function,
before r->pool is freed.  I'll implement the change later today.

Brian


Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by Joe Orton <jo...@redhat.com>.
On Sun, Oct 30, 2005 at 09:56:45AM +0000, Joe Orton wrote:
> On Sat, Oct 29, 2005 at 02:23:51PM -0700, Brian Pane wrote:
> > With fix 329484 committed, I'm now getting a clean test run of the
> > perl_framework tests with --enable-pool-debug=all
> 
> Thanks, all test runs passed last night here too.

Hmm, lots of segfaults from some manual testing though: 
ap_process_http_connection is using r after r->pool is destroyed:

...
            ap_process_request(r);

        if (ap_extended_status)
            ap_increment_counts(c->sbh, r);
...
        ap_update_child_status(c->sbh, SERVER_BUSY_KEEPALIVE, r);


joe

Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by Joe Orton <jo...@redhat.com>.
On Sat, Oct 29, 2005 at 02:23:51PM -0700, Brian Pane wrote:
> With fix 329484 committed, I'm now getting a clean test run of the
> perl_framework tests with --enable-pool-debug=all

Thanks, all test runs passed last night here too.

joe


Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by Brian Pane <br...@apache.org>.
On Oct 28, 2005, at 1:10 AM, Joe Orton wrote:

> There are still crashes in free() for an --enable-pool-debug build
> (prefork); backtraces like the below seem to show that r->pool is
> getting destroyed way too early by the looks of it.

I just figured out why this was happening.  The root cause ended
up being embarrassingly simple: r->pool was destroyed at the
expected spot, following the invocation of the logger, but the
very next operation in the core output filter referenced the
brigade that had contained the EOR bucket--a brigade that
had been allocated out of r->pool.

With fix 329484 committed, I'm now getting a clean test run of the
perl_framework tests with --enable-pool-debug=all

Thanks for catching the error!

Brian


Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by Joe Orton <jo...@redhat.com>.
On Thu, Oct 27, 2005 at 09:20:49PM -0700, Brian Pane wrote:
> I just committed a fix.  The problem was that the new 
> ap_core_output_filter was leaving the socket timeout set to zero.  In 
> situations where the output filter runs _before_ the input filter, 
> like the communication to the origin server in mod_proxy, the zero 
> timeout was causing reads in the input filter to fail.

There are still crashes in free() for an --enable-pool-debug build 
(prefork); backtraces like the below seem to show that r->pool is 
getting destroyed way too early by the looks of it.

#7  0x08070ecb in eor_bucket_destroy (data=0x89e8ff8) at eor_bucket.c:55
#8  0x0807138e in remove_empty_buckets (bb=0x89f21f8) at 
core_filters.c:611
#9  0x080713c6 in setaside_remaining_output (f=0x88de828, ctx=0x8a03910,
    bb=0x89f21f8, make_a_copy=1, c=0x8a13770) at core_filters.c:491
#10 0x08071afd in ap_core_output_filter (f=0x88de828, new_bb=0x89f21f8)
    at core_filters.c:479
#11 0x0807d33f in ap_process_async_request (r=0x89e8ff8) at 
http_request.c:260
#12 0x0807d41c in ap_process_request (r=0x0) at http_request.c:279
#13 0x0807afdb in ap_process_http_connection (c=0x8a13770) at 
http_core.c:166
#14 0x08077ce6 in ap_run_process_connection (c=0x8a13770) at 
connection.c:43


Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by Brian Pane <br...@apache.org>.
On Oct 25, 2005, at 2:33 AM, Joe Orton wrote:

> On Mon, Oct 24, 2005 at 03:33:17AM -0000, Brian Pane wrote:
>
>> Author: brianp
>> Date: Sun Oct 23 20:33:14 2005
>> New Revision: 327945
>>
>> URL: http://svn.apache.org/viewcvs?rev=327945&view=rev
>> Log:
>> Async write completion for Event MPM
>> (backported from async-dev branch to 2.3 trunk)
>>
>
> httpd-test runs against the trunk are failing all over the place  
> today,
> I guess caused by one of these changes...

I just committed a fix.  The problem was that the new  
ap_core_output_filter
was leaving the socket timeout set to zero.  In situations where the  
output
filter runs _before_ the input filter, like the communication to the  
origin
server in mod_proxy, the zero timeout was causing reads in the input
filter to fail.

Brian


Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by "William A. Rowe, Jr." <wr...@rowe-clan.net>.
William A. Rowe, Jr. wrote:
> 
> However, proxy_http (and possibly proxy_connect) fails to include the 
> following code fragment after invoking ap_proxy_connection_create();
> 
>         bb = apr_brigade_create(cdata->pool, cdata->bucket_alloc);
>         rv = ap_get_brigade(cdata->input_filters, bb, AP_MODE_INIT,
>                             APR_BLOCK_READ, 0);
>         apr_brigade_destroy(bb);
> 
>         if (rv != APR_SUCCESS) {
>             ap_log_error(APLOG_MARK, APLOG_ERR, rv, cdata->base_server,
>                          "Failed to initialize the proxy ssl data stream");
>             goto cleanup;
>         }

Footnote; if you want to inject this snippet in the if (!connection) block
after ap_proxy_connection_create() - be sure to use 'status' in place of 'rv'.

Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by "William A. Rowe, Jr." <wr...@rowe-clan.net>.
Brian Pane wrote:
> 
> It looks like the new core output filter is messing up the blocking mode
> when it's called during the sending of the request to the origin server.
> I'll continue tracking this down tomorrow.

Messing it up?  Or failing to set it up?

proxy_util.c invokes create_connection (which has some double-close socket
issues, if you follow the hook providers and then observe that we close the
socket locally in the proxy_util.c ap_proxy_connection_create).  When it
then runs the pre_connection hook, the initial blocking/timeout state is
set up correctly.

However, proxy_http (and possibly proxy_connect) fails to include the following
code fragment after invoking ap_proxy_connection_create();

         bb = apr_brigade_create(cdata->pool, cdata->bucket_alloc);
         rv = ap_get_brigade(cdata->input_filters, bb, AP_MODE_INIT,
                             APR_BLOCK_READ, 0);
         apr_brigade_destroy(bb);

         if (rv != APR_SUCCESS) {
             ap_log_error(APLOG_MARK, APLOG_ERR, rv, cdata->base_server,
                          "Failed to initialize the proxy ssl data stream");
             goto cleanup;
         }

so if the backend proxy connection is SSL, and we attempt to write before
we read (at least, that's http:) then the handshake isn't properly invoked.

I have to study proxy_connect to determine that we do a speculative read before
we attempt to write, such that we would always handshake SSL/TLS.

Bill

Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by Brian Pane <br...@apache.org>.
I think I know what the problem with proxy is.  When reading the  
response
header from the origin server, it falls out of ap_rgetline_core() at  
this point:

         /* Something horribly wrong happened.  Someone didn't block! */
         if (APR_BRIGADE_EMPTY(bb)) {
             return APR_EGENERAL;
         }

It looks like the new core output filter is messing up the blocking mode
when it's called during the sending of the request to the origin server.
I'll continue tracking this down tomorrow.

Brian

On Oct 25, 2005, at 7:06 PM, Brian Pane wrote:

> On Oct 25, 2005, at 2:33 AM, Joe Orton wrote:
>
>
>> httpd-test runs against the trunk are failing all over the place  
>> today,
>> I guess caused by one of these changes...
>>
>> prefork is failing like:
>>
>> Failed Test                Stat Wstat Total Fail  Failed  List of  
>> Failed
>> --------------------------------------------------------------------- 
>> ----------
>> t/modules/proxy.t                        13   11  84.62%  1-9 12-13
>> t/modules/proxy_balancer.t                1    1 100.00%  1
>> t/modules/rewrite.t                      22    5  22.73%  17-18 20-22
>> t/protocol/echo.t           255 65280     8    8 100.00%  1-8
>> t/security/CAN-2005-2700.t                2    1  50.00%  1
>> ... plus almost all of t/ssl/* fail
>>
>
> Sorry about that.  I didn't have proxy and ssl compiled in when I
> regression-tested with httpd-test.  I'll get started on a fix later  
> this
> evening.
>
> Brian
>
>


Re: svn commit: r327945 - in /httpd/httpd/trunk: CHANGES modules/http/http_core.c modules/http/http_request.c server/mpm/experimental/event/event.c

Posted by Brian Pane <br...@apache.org>.
On Oct 25, 2005, at 2:33 AM, Joe Orton wrote:

> httpd-test runs against the trunk are failing all over the place  
> today,
> I guess caused by one of these changes...
>
> prefork is failing like:
>
> Failed Test                Stat Wstat Total Fail  Failed  List of  
> Failed
> ---------------------------------------------------------------------- 
> ---------
> t/modules/proxy.t                        13   11  84.62%  1-9 12-13
> t/modules/proxy_balancer.t                1    1 100.00%  1
> t/modules/rewrite.t                      22    5  22.73%  17-18 20-22
> t/protocol/echo.t           255 65280     8    8 100.00%  1-8
> t/security/CAN-2005-2700.t                2    1  50.00%  1
> ... plus almost all of t/ssl/* fail

Sorry about that.  I didn't have proxy and ssl compiled in when I
regression-tested with httpd-test.  I'll get started on a fix later this
evening.

Brian