Bug 36780 - Apache crashes while processing a request whose connection has been forcibly closed by IExplorer
Summary: Apache crashes while processing a request whose connection has been forcibly ...
Status: RESOLVED FIXED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: Core (show other bugs)
Version: 2.0.54
Hardware: PC Windows XP
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords: PatchAvailable
: 39738 (view as bug list)
Depends on:
Blocks:
 
Reported: 2005-09-23 14:21 UTC by Birgit Dreyer
Modified: 2009-08-03 05:34 UTC (History)
2 users (show)



Attachments
patch against 2.0.x for core_output_filter (533 bytes, patch)
2005-09-23 16:52 UTC, Joe Orton
Details | Diff
patch against 2.0.x for buffer_output (835 bytes, patch)
2005-09-26 07:13 UTC, Rüdiger Plüm
Details | Diff
patch against trunk for ap_filter_flush (823 bytes, patch)
2005-09-26 14:15 UTC, Joe Orton
Details | Diff
fix for 2.2.x (848 bytes, patch)
2009-08-03 03:48 UTC, Joe Orton
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Birgit Dreyer 2005-09-23 14:21:36 UTC
we are using Windows XP resp. Windows 2000 with  Apache/2.0.54 (Win32)
mod_ssl/2.0.54 OpenSSL/0.9.7g mod_python/3.1.3 Python/2.3.5 (httpd.conf see
appendix)

Apache crashes while processing a request whose connection has been forcibly
closed by the IExplorer. This occurs while the request handler tries to write a
large amount of data for the answer.

Apache crashes in  following scenario: Apache is processing a request. Our
handler tries to write a large amount of data ( in our case  ~960000 bytes) to
the request. To do this apache calls the function apr_brigade_write. If the
amount of data is large a transient bucket with the user data address will be
created. 

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
apr_brigade.c:
APU_DECLARE(apr_status_t) apr_brigade_write(apr_bucket_brigade *b,
                                            apr_brigade_flush flush,
                                            void *ctx,
                                            const char *str, apr_size_t nbyte)
{
 ...
    if (nbyte > remaining) {
        /* either a buffer bucket exists but is full,
         * or no buffer bucket exists and the data is too big
         * to buffer.  In either case, we should flush.  */
        if (flush) {
            e = apr_bucket_transient_create(str, nbyte, b->bucket_alloc);
            APR_BRIGADE_INSERT_TAIL(b, e);
           return flush(b, ctx);
           ...
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

This bucket will be send to the next filters. In our case Mod_Deflate fragments
it in a loop to 8000 byte pieces and send it to the next filter 

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
(mod_deflate.c / line 553 : 
static apr_status_t deflate_out_filter(ap_filter_t *f,
                                       apr_bucket_brigade *bb)
{
   ...
        while (ctx->stream.avail_in != 0) {
            if (ctx->stream.avail_out == 0) {
                apr_status_t rv;

                ctx->stream.next_out = ctx->buffer;
                len = c->bufferSize - ctx->stream.avail_out;

                b = apr_bucket_heap_create((char *)ctx->buffer, len,
                                           NULL, f->c->bucket_alloc);
                APR_BRIGADE_INSERT_TAIL(ctx->bb, b);
                ctx->stream.avail_out = c->bufferSize;
                /* Send what we have right now to the next filter. */
                rv = ap_pass_brigade(f->next, ctx->bb);
                if (rv != APR_SUCCESS) {
                    return rv;
                }
            }
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

At last SSL tries to write on the connection. But in the meantime IExplorer has
closed the connection (e.g. because the user trigger a further request in the
same frame). Thus SSL_Write fails:

error.log (loglevel info):
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
[Thu Aug 25 13:20:19 2005] [info] Subsequent (No.142) HTTPS request received for
child 0 (server PDDEKA-W1165:443)
[Thu Aug 25 13:20:20 2005] [info] Subsequent (No.134) HTTPS request received for
child 1 (server PDDEKA-W1165:443)
[Thu Aug 25 13:20:20 2005] [info] (OS 10054)An existing connection was forcibly
closed by the remote host.  : core_output_filter: writing data to the network
[Thu Aug 25 13:20:20 2005] [info] (620019)APR does not understand this error
code: SSL output filter write failed.
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

The processing aborts. But unfortunately the transient buckets of apr_bucket.c
will not deleted. Because this bucket resp. its brigade will be referenced in
the ctx and this will be processed later at the finalizing of the request:
In succession of the call of ap_finalize_request_protocol(r) of this request
ap_old_write_filter  will be called. 

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
protocol.c:
AP_CORE_DECLARE_NONSTD(apr_status_t) ap_old_write_filter(
    ap_filter_t *f, apr_bucket_brigade *bb)
{
    old_write_filter_ctx *ctx = f->ctx;

    AP_DEBUG_ASSERT(ctx);

    if (ctx->bb != 0) {
        /* whatever is coming down the pipe (we don't care), we
         * can simply insert our buffered data at the front and
         * pass the whole bundle down the chain.
         */
        APR_BRIGADE_CONCAT(ctx->bb, bb);
        bb = ctx->bb;
        ctx->bb = NULL;
    }

    return ap_pass_brigade(f->next, bb);
}
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Because ctx->bb contains the "transient" bucket containing a data address which
no more exists the processing of the bucket crashes.


Following solution does solve our problem:
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
apr_brigade.c:
APU_DECLARE(apr_status_t) apr_brigade_write(apr_bucket_brigade *b,
                                            apr_brigade_flush flush,
                                            void *ctx,
                                            const char *str, apr_size_t nbyte)
{
 ...
    if (nbyte > remaining) {
        /* either a buffer bucket exists but is full,
         * or no buffer bucket exists and the data is too big
         * to buffer.  In either case, we should flush.  */
        if (flush) {
            apr_status_t rv = 0;

            e = apr_bucket_transient_create(str, nbyte, b->bucket_alloc);
            APR_BRIGADE_INSERT_TAIL(b, e);
            rv = flush(b, ctx);

            if (rv != APR_SUCCESS) {
              apr_bucket_delete(e);
              apr_brigade_cleanup(b);
            }
            return rv;
...
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Appendix: httpd.conf
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Timeout 300
KeepAlive On
MaxKeepAliveRequests 0
KeepAliveTimeout 90
<IfModule mpm_winnt.c>
ThreadsPerChild 100
MaxRequestsPerChild  0
Win32DisableAcceptEx ON
</IfModule>
LoadModule access_module modules/mod_access.so
LoadModule alias_module modules/mod_alias.so
LoadModule dir_module modules/mod_dir.so
LoadModule headers_module modules/mod_headers.so
LoadModule include_module modules/mod_include.so
LoadModule log_config_module modules/mod_log_config.so
LoadModule mime_module modules/mod_mime.so
LoadModule negotiation_module modules/mod_negotiation.so
LoadModule setenvif_module modules/mod_setenvif.so
LoadModule deflate_module modules/mod_deflate.so
<IfDefine SSL>
LoadModule ssl_module modules/mod_ssl.so
</IfDefine>
LoadModule python_module modules/mod_python.so
UseCanonicalName Off
AddType application/x-javascript .js
<Directory "/">
    AddOutputFilterByType DEFLATE text/html text/plain text/css
application/x-javascript
    Header append Vary User-Agent env=!dont-vary
    AllowOverride None
    Order allow,deny
    Allow from all
</Directory>
DirectoryIndex index.html index.html.var
AccessFileName .htaccess
<Files ~ "^\.ht">
    Order allow,deny
    Deny from all
</Files>
TypesConfig conf/mime.types
DefaultType text/plain
HostnameLookups Off
LogLevel info
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
LogFormat "%h %l %u %t \"%r\" %>s %b" common
LogFormat "%{Referer}i -> %U" referer
LogFormat "%{User-agent}i" agent
ServerTokens Full
ServerSignature On
AddLanguage da .dk
AddLanguage nl .nl
AddLanguage en .en
AddLanguage et .et
AddLanguage fr .fr
AddLanguage de .de
AddLanguage he .he
AddLanguage el .el
AddLanguage it .it
AddLanguage ja .ja
AddLanguage pl .po
AddLanguage ko .ko
AddLanguage pt .pt
AddLanguage nn .nn
AddLanguage no .no
AddLanguage pt-br .pt-br
AddLanguage ltz .ltz
AddLanguage ca .ca
AddLanguage es .es
AddLanguage sv .sv
AddLanguage cs .cz .cs
AddLanguage ru .ru
AddLanguage zh-CN .zh-cn
AddLanguage zh-TW .zh-tw
AddLanguage hr .hr
LanguagePriority en da nl et fr de el it ja ko no pl pt pt-br ltz ca es sv tw
ForceLanguagePriority Prefer Fallback
AddDefaultCharset ISO-8859-1
AddCharset ISO-8859-1  .iso8859-1 .latin1
AddCharset ISO-8859-2  .iso8859-2 .latin2 .cen
AddCharset ISO-8859-3  .iso8859-3 .latin3
AddCharset ISO-8859-4  .iso8859-4 .latin4
AddCharset ISO-8859-5  .iso8859-5 .latin5 .cyr .iso-ru
AddCharset ISO-8859-6  .iso8859-6 .latin6 .arb
AddCharset ISO-8859-7  .iso8859-7 .latin7 .grk
AddCharset ISO-8859-8  .iso8859-8 .latin8 .heb
AddCharset ISO-8859-9  .iso8859-9 .latin9 .trk
AddCharset ISO-2022-JP .iso2022-jp .jis
AddCharset ISO-2022-KR .iso2022-kr .kis
AddCharset ISO-2022-CN .iso2022-cn .cis
AddCharset Big5        .Big5       .big5
AddCharset WINDOWS-1251 .cp-1251   .win-1251
AddCharset CP866       .cp866
AddCharset KOI8-r      .koi8-r .koi8-ru
AddCharset KOI8-ru     .koi8-uk .ua
AddCharset ISO-10646-UCS-2 .ucs2
AddCharset ISO-10646-UCS-4 .ucs4
AddCharset UTF-8       .utf8
AddCharset GB2312      .gb2312 .gb
AddCharset utf-7       .utf7
AddCharset utf-8       .utf8
AddCharset big5        .big5 .b5
AddCharset EUC-TW      .euc-tw
AddCharset EUC-JP      .euc-jp
AddCharset EUC-KR      .euc-kr
AddCharset shift_jis   .sjis
AddType application/x-tar .tgz
AddType image/x-icon .ico
AddHandler type-map var
BrowserMatch "Mozilla/2" nokeepalive
BrowserMatch "MSIE 4\.0b2;" nokeepalive downgrade-1.0 force-response-1.0
BrowserMatch "RealPlayer 4\.0" force-response-1.0
BrowserMatch "Java/1\.0" force-response-1.0
BrowserMatch "JDK/1\.0" force-response-1.0
BrowserMatch "Microsoft Data Access Internet Publishing Provider" redirect-carefully
BrowserMatch "^WebDrive" redirect-carefully
BrowserMatch "^WebDAVFS/1.[012]" redirect-carefully
BrowserMatch "^gnome-vfs" redirect-carefully
<IfModule mod_ssl.c>
    Include conf/ssl.conf
</IfModule>
Comment 1 Joe Orton 2005-09-23 14:59:06 UTC
Interesting report and great analysis, thanks a lot.

I don't think it's necessarily correct to fix this in apr_brigade_write.

If you instead change the core_output_filter to add a call to:

  apr_brigade_cleanup(b);

on the error path, does that work too?
Comment 2 Birgit Dreyer 2005-09-23 16:46:28 UTC
Thanks for the quick answer.
Could you please state your solution more precisely? Where exactly should i add 
the apr_brigade_cleanup call in core_output_filter. Sorry for inconvenience, 
but i am not an Apache specialist.


Comment 3 Joe Orton 2005-09-23 16:52:46 UTC
Created attachment 16502 [details]
patch against 2.0.x for core_output_filter

Well if we gave out badges you'd win an "I'm an Apache expert" badge for
tracking down a bug like this ;)

Attached is a patch against 2.0.x to implement what I suggested; don't forget
to revert your apr_brigade_write() change when testing this out.
Comment 4 Rüdiger Plüm 2005-09-26 06:39:44 UTC
Birgit excellent report. This is what the guys love here :-).
Joe, I had a look in the core output filter and apr_brigade_destroy(b) is called
a few lines above (4255 for 2.0.54, 4285 in 291543) regardless of the value of
rv. So does the call of apr_brigade_cleanup in your patch really change things?
Sorry, I am not so deep in the details of the filters, but isn't the core output
filter the very last one in the chain? If so I guess we do not see the original
brigade / buckets here because they have been transformed by mod_deflate and
mod_ssl on their way.
Birgit does this crash also happen without mod_deflate and mod_ssl (This is not
a solution proposal, I just try to narrow things :-))?
Comment 5 Rüdiger Plüm 2005-09-26 07:13:09 UTC
Created attachment 16524 [details]
patch against 2.0.x for buffer_output

I tried solve it after the return from apr_brigade_write. Reminder: Don't
forget to revert your apr_brigade_write() change when testing this out.
Comment 6 Joe Orton 2005-09-26 12:34:43 UTC
Ah, good point too.

But then this problem is not not really specific to the old_write_filter.  It is
a problem which is intrisic to the way that apr_brigade_write/ap_f* work.

If the ap_filter_flush() call fails, the transient bucket which is left in the
brigade may *immediately* fall out of scope; it is never really save for ap_f*
to leave that bucket in the brigade.

So maybe the best place to fix this is in ap_filter_flush().
Comment 7 Birgit Dreyer 2005-09-26 12:54:38 UTC
The patch in core_output_filter doesn't solve the problem but the patch in 
server.c does it :)
This crash doesn't happen without mod_deflate and mod_ssl in my test program. 
But i think it is more diffcult to create the error case without mod_deflate 
and mod_ssl. 
Comment 8 Rüdiger Plüm 2005-09-26 13:49:20 UTC
Birgit, do you mean my patch? I was confused because it patches protocol.c.
Joe, seems reasonable to me to fix this in ap_filter_flush. What should be the
approach?
Destroy the bucket brigade if ap_pass_brigade does not return APR_SUCCESS? Or
should we only remove and destroy the transient bucket (this seems a bit tricky
to me and I am currently very unsure about the sideeffects)?
BTW: I would guess that this problem also occurs on the trunk.
So should we also be aware of APR_EAGAIN in preparation for the async IO branch?
Comment 9 Joe Orton 2005-09-26 14:15:41 UTC
Created attachment 16530 [details]
patch against trunk for ap_filter_flush

This is what I'd propose.  I'm going to write a test case for this to reproduce
the bug and confirm the fix.
Comment 10 Birgit Dreyer 2005-09-26 14:51:40 UTC
oh, sorry I meant server/protocol.c resp. your patch Rüdiger solves the problem.
Comment 11 Birgit Dreyer 2005-09-26 16:17:38 UTC
The patch in server/util_filter.c of ap_filter_flush works too.
Comment 12 Joe Orton 2007-10-11 06:22:41 UTC
*** Bug 39738 has been marked as a duplicate of this bug. ***
Comment 13 Joe Orton 2007-10-11 06:26:54 UTC
*** Bug 43533 has been marked as a duplicate of this bug. ***
Comment 14 Noah Williamsson 2007-10-11 11:52:35 UTC
(In reply to comment #13)
> *** Bug 43533 has been marked as a duplicate of this bug. ***


I applied Joe's patch in comment 9 but I'm still getting crashes.


We do use mod_deflate and mod_ssl but I don't think we've got much traffic on
the SSL site.

We too get a lot of "core_output_filter: writing data to the network .. broken
pipe" log messages if that's interesting in any way.



------------
crashdump[3845]: Thread 17 Crashed:
crashdump[3845]: 0   httpd                      0x00004780 bndm + 120
(mod_include.c:317)
crashdump[3845]: 1   httpd                      0x0000a0e0 find_start_sequence +
136 (mod_include.c:2388)
crashdump[3845]: 2   httpd                      0x0000bab0 send_parsed_content +
1288 (mod_include.c:3054)
crashdump[3845]: 3   httpd                      0x0000dbd8 includes_filter +
1468 (mod_include.c:3591)
crashdump[3845]: 4   httpd                      0x00068e10 ap_pass_brigade + 236
(util_filter.c:512)
--
crashdump[10232]: Thread 1 Crashed:
crashdump[10232]: 0   httpd                     0x00004780 bndm + 120
(mod_include.c:317)
crashdump[10232]: 1   httpd                     0x0000a0e0 find_start_sequence +
136 (mod_include.c:2388)
crashdump[10232]: 2   httpd                     0x0000bab0 send_parsed_content +
1288 (mod_include.c:3054)
crashdump[10232]: 3   httpd                     0x0000dbd8 includes_filter +
1468 (mod_include.c:3591)
crashdump[10232]: 4   httpd                     0x00068e10 ap_pass_brigade + 236
(util_filter.c:512)
--
crashdump[12500]: Thread 13 Crashed:
crashdump[12500]: 0   httpd                     0x00004780 bndm + 120
(mod_include.c:317)
crashdump[12500]: 1   httpd                     0x0000a0e0 find_start_sequence +
136 (mod_include.c:2388)
crashdump[12500]: 2   httpd                     0x0000bab0 send_parsed_content +
1288 (mod_include.c:3054)
crashdump[12500]: 3   httpd                     0x0000dbd8 includes_filter +
1468 (mod_include.c:3591)
crashdump[12500]: 4   httpd                     0x00068e10 ap_pass_brigade + 236
(util_filter.c:512)
--
crashdump[13586]: Thread 10 Crashed:
crashdump[13586]: 0   <<00000000>>      0xffff8a2c __memcpy + 652
(cpu_capabilities.h:189)
crashdump[13586]: 1   libz.1.dylib              0x911156bc read_buf + 144
crashdump[13586]: 2   libz.1.dylib              0x911155b8 fill_window + 256
crashdump[13586]: 3   libz.1.dylib              0x91117300 deflate_fast + 64
crashdump[13586]: 4   libz.1.dylib              0x91114c34 deflate + 2148
--
crashdump[13589]: Thread 4 Crashed:
crashdump[13589]: 0   libz.1.dylib              0x911116d8 crc32_big + 72
crashdump[13589]: 1   mod_deflate.so            0x0060e4b8 deflate_out_filter +
4336 (mod_deflate.c:545)
crashdump[13589]: 2   httpd                     0x00068e10 ap_pass_brigade + 236
(util_filter.c:512)
crashdump[13589]: 3   httpd                     0x0005121c
ap_sub_req_output_filter + 216 (request.c:1539)
crashdump[13589]: 4   httpd                     0x00068e10 ap_pass_brigade + 236
(util_filter.c:512)
--
crashdump[14742]: Thread 12 Crashed:
crashdump[14742]: 0   httpd                     0x0000ab28 find_tail + 184
(mod_include.c:2675)
crashdump[14742]: 1   httpd                     0x0000c38c send_parsed_content +
3556 (mod_include.c:3201)
crashdump[14742]: 2   httpd                     0x0000dbd8 includes_filter +
1468 (mod_include.c:3591)
crashdump[14742]: 3   httpd                     0x00068e10 ap_pass_brigade + 236
(util_filter.c:512)
crashdump[14742]: 4   httpd                     0x0004a5a8 default_handler +
1888 (core.c:3648)
Comment 15 Noah Williamsson 2007-10-11 16:26:30 UTC
(In reply to comment #14)
> (In reply to comment #13)
> > *** Bug 43533 has been marked as a duplicate of this bug. ***
> 
> 
> I applied Joe's patch in comment 9 but I'm still getting crashes.

Noticed I forgot to apply "patch against 2.0.x for buffer_output". Did that too
but I'm still experiencing the same crashes.
Comment 16 Joe Orton 2009-08-03 03:48:48 UTC
Created attachment 24087 [details]
fix for 2.2.x

Attached proposed backport of fix for 2.2.x.
Comment 17 Joe Orton 2009-08-03 05:34:40 UTC
Fixed in trunk:

r583817
r583830

Fixed in 2.2.x:

r800333