Summarizing, to reproduce this crash it is essential to:

1.       Use a subrequest to generate contents for the URL which is configured to be cached using mod_cache. While creating subrequest it is essential to pass main request’s output filters:
 
request_rec *rr = ap_sub_req_lookup_uri("/cache", r, r->output_filters);
This causes “cache_save_filter” to be invoked on each ap_rwrite/ap_rflush

2.       There should be multiple calls to ap_rwrites from within the sub_request

3.        And finally, send 2 requests for exactly same URL (to be cached) simultaneously.

 

This is what I am trying to achieve here:

I have a set of public facing URLs which are generated dynamically. These URLs are configured to be cached for public contents. Now, these URLs need be authorized by a  handler which then generates a new URL containing the actual location of the content sought. Now to fetch this content, request need be transferred to this new URL. External redirects for these URLs is not an option as they are private URLs. Response from Internal-transfer to these URLs cannot be cached as part of original URL. The only option here is to use sub requests to which I am passing main URL’s output filters to facilitate caching.

 

It will be great if someone can point me how to fix this in case I am using subrequests in an exceptional way.

 

Tx,

-Shashwat

 

From: Shashwat Agarwal [mailto:shashwata@decho.com]
Sent: 11 February 2010 PM 10:54
To: dev@httpd.apache.org
Cc: 'Suresh Krishnappa'; 'L. Suresh'; 'Vinay Y S'
Subject: FW: mod_cache with sub_request crashing

 

Hi,

 

mod_cache is crashing when with a sub request. PFA the source of the module causing the crash (mod_subreq.c). I am using httpd-2.2.8 with following details:

 

Server version: Apache/2.2.8 (Unix)

Server built:   Jan 24 2008 10:45:24

Server's Module Magic Number: 20051115:11

Server loaded:  APR 1.2.8, APR-Util 1.2.10

Compiled using: APR 1.2.8, APR-Util 1.2.10

Architecture:   32-bit

Server MPM:     Worker

  threaded:     yes (fixed thread count)

    forked:     yes (variable process count)

Server compiled with....

 

Scenario is like this:

There is a URL: /hello for which cache is configured (see attached httpd.conf). And the content for /hello is being generated using a sub_request to url: /cache as:

        request_rec *rr = ap_sub_req_lookup_uri("/cache", r, r->output_filters);

        if(!rr)

        {

            ...

        }

 

Now when two requests to /hello are issued simultaneously,  apache is crashing with the following call stack:

 

#0  0x00927b5c in cache_save_filter (f=0xb4707ea0, in=0xb470a940) at /usr/src/debug/httpd-2.2.8/modules/cache/mod_cache.c:368

 364     if (cache->in_checked) {

 365         /* pass the brigades into the cache, then pass them

 366          * up the filter stack

 367          */

 368         rv = cache->provider->store_body(cache->handle, r, in); <<< crashing here because of NULL cache->provider

 369         if (rv != APR_SUCCESS) {

 370             ap_log_error(APLOG_MARK, APLOG_DEBUG, rv, r->server,

 371                          "cache: Cache provider's store_body failed!");

 372             ap_remove_output_filter(f);

 373         }

 374         return ap_pass_brigade(f->next, in);

 375     }

#1  0xb7ef7b60 in ap_pass_brigade (next=0xb4707df8, bb=0xb470a940) at /usr/src/debug/httpd-2.2.8/server/util_filter.c:526

#2  0xb7ee7db7 in ap_sub_req_output_filter (f=0xb4709560, bb=0xb470a940) at /usr/src/debug/httpd-2.2.8/server/request.c:1553

#3  0xb7ef7b60 in ap_pass_brigade (next=0xb4707df8, bb=0xb470a940) at /usr/src/debug/httpd-2.2.8/server/util_filter.c:526

#4  0xb7ede3d1 in ap_old_write_filter (f=0xb470a908, bb=0xb470a940) at /usr/src/debug/httpd-2.2.8/server/protocol.c:1405

#5  0xb7ef7b60 in ap_pass_brigade (next=0xb4707df8, bb=0xb470a940) at /usr/src/debug/httpd-2.2.8/server/util_filter.c:526

#6  0xb7ede349 in ap_rflush (r=0xb4709090) at /usr/src/debug/httpd-2.2.8/server/protocol.c:1609

#7  0x00dee4fc in modsubreq_handler_impl () from /etc/httpd/modules/libmod_subrequest.so

#8  0x00dee039 in modsubreq_handler () from /etc/httpd/modules/libmod_subrequest.so

#9  0xb7eec52d in ap_run_handler (r=0xb4709090) at /usr/src/debug/httpd-2.2.8/server/config.c:157

#10 0xb7eefef7 in ap_invoke_handler (r=0xb4709090) at /usr/src/debug/httpd-2.2.8/server/config.c:372

#11 0xb7ee79a9 in ap_run_sub_req (r=0xb4709090) at /usr/src/debug/httpd-2.2.8/server/request.c:1880

#12 0x00dee8f0 in modsubreq_handler_impl () from /etc/httpd/modules/libmod_subrequest.so

#13 0x00dee039 in modsubreq_handler () from /etc/httpd/modules/libmod_subrequest.so

#14 0xb7eec52d in ap_run_handler (r=0xb47071a8) at /usr/src/debug/httpd-2.2.8/server/config.c:157

#15 0xb7eefef7 in ap_invoke_handler (r=0xb47071a8) at /usr/src/debug/httpd-2.2.8/server/config.c:372

#16 0xb7efbe24 in ap_internal_redirect (new_uri=0xb470902c "/hello?s=1", r=0xb4703040) at /usr/src/debug/httpd-2.2.8/modules/http/http_request.c:477

#17 0x00dee713 in modsubreq_handler_impl () from /etc/httpd/modules/libmod_subrequest.so

#18 0x00dee039 in modsubreq_handler () from /etc/httpd/modules/libmod_subrequest.so

#19 0xb7eec52d in ap_run_handler (r=0xb4703040) at /usr/src/debug/httpd-2.2.8/server/config.c:157

#20 0xb7eefef7 in ap_invoke_handler (r=0xb4703040) at /usr/src/debug/httpd-2.2.8/server/config.c:372

#21 0xb7efbfde in ap_process_request (r=0xb4703040) at /usr/src/debug/httpd-2.2.8/modules/http/http_request.c:258

#22 0xb7ef8d6f in ap_process_http_connection (c=0xb8c5fe20) at /usr/src/debug/httpd-2.2.8/modules/http/http_core.c:190

#23 0xb7ef466d in ap_run_process_connection (c=0xb8c5fe20) at /usr/src/debug/httpd-2.2.8/server/connection.c:43

#24 0xb7ef476c in ap_process_connection (c=0xb8c5fe20, csd=0xb8c5fc70) at /usr/src/debug/httpd-2.2.8/server/connection.c:178

#25 0xb7f0171f in worker_thread (thd=0xb8a0cd98, dummy=0xb4700508) at /usr/src/debug/httpd-2.2.8/server/mpm/worker/worker.c:544

#26 0x00394b86 in dummy_worker (opaque=0xb8a0cd98) at threadproc/unix/thread.c:138

#27 0x003a444b in start_thread () from /lib/libpthread.so.0

 

The crash is happening because of NULL cache->provider in mod_cache.c:368. Following is the reason why cache->provider is NULL:

In response to ‘/cache’ (sub)request, modsubreq_handler_impl() reads a file and writes to ap_rwrite() in chunks of 16KB.

When first chunk is written, mod_cache ‘s "cache_save_filter()" is invoked which calls "cache_create_entity()" which in-turn iterates over all cache->providers (which are “mem”, “disk” etc) and call each ‘provider’s create_entity() to create "cache_entity" per provider. Now specifically for mod_mem_cache, mod_mem_cache creates unique entity per url; so, for 2 requests for same url, only one request will be able to create a cache-entity and the other request will be declined. This declined request does an early return as follows:

 

619    /* no cache handle, create a new entity only for non-HEAD requests */

620    if (!cache->handle && !r->header_only) {

621        rv = cache_create_entity(r, size);

622        info = apr_pcalloc(r->pool, sizeof(cache_info));

623        /* We only set info->status upon the initial creation. */

624        info->status = r->status;

625    }

626

627    if (rv != OK) {

628        /* Caching layer declined the opportunity to cache the response */

629        ap_remove_output_filter(f);

630        return ap_pass_brigade(f->next, in);

631    }

 

 

and causes (struct cache_request_rec*) cache in inconsistent state with cache->in_checked = 1 but cache->provider = NULL. Now, when second chunk is written to the formerly 'declined' request, the if-check:

 

364 if (cache->in_checked ) {

...

368  rv = cache->provider->store_body(cache->handle, r, in);

...

}

causes crash.

 

Did I missed something about subrequest/mod_cache?

Let me know if any more information is needed.

 

 

Thanks,

Shashwat