Mailing-List: contact dev-help@httpd.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@httpd.apache.org
Received-SPF: pass (athena.apache.org: local policy)
Subject: corrupt brigades when using mod_cache in reverse proxy
From: f_los_ch <f_los_ch@yahoo.com>
To: dev@httpd.apache.org
Content-Type: text/plain; charset="UTF-8"
Date: Fri, 18 Nov 2011 20:50:23 +0100
Message-ID: <1321645823.3829.100.camel@florian-desktop>
Mime-Version: 1.0
Content-Transfer-Encoding: 7bit

Hi together,

I'm messing around with a strange bug now for a few days: 

When enabling mod_cache in my reverse-proxy scenario, the first file
with a filesize above some threshold gets delivered corrupted,
subsequent requests served from cache are fine.

I noticed it first with some broken images and I'm testing it now with
some debug file of ~same size: seq 1 100000 | head -c 113000

When using wget, this file is corrupted at multiple locations (only for
the first request), eg. it contains:
1885
1886
1887
2176
2177
2178

After several approaches, I finally added now extensive logging, with
dumping all the buckets of the three involved brigades into the log:
- in
- cache->handle->cache_obj->vobj->bb
- cache->out
at the places:
- beginning of cache_save_filter()
- beginning of cache_save_store()
- end of cache_save_store()

This showed some strange/buggy behavior (or at least I could not
understand it) of [i]n, [h]andle, and [o]ut brigades:

[...Stripped parts where everything seemed ok to me...]

cache_save_filter in:
i: [1888, 2175] #note that this are 1440 bytes
h: []
o: []

cache_save_store() in: same

cache_save_store() out: (consume it, do not flush to out)
i: []
h: [1888, 2175]
o: []

cache_save_filter in: Boom!
i: [2176, 3519], [3776, 3903] #8000 and 640 bytes
h: [2176, 2463] #1440 bytes
o: []

cache_save_store() in: same

[...]

As the disk_cache_object_t* vobj passed along to cache_save_filter
(-provider) is void* to others, I regard this function as kind of
re-entrant, so I assume, no one can intentionally touch vobj->bb as it
cannot be dereferenced. 

So, between the calls of the disk-provider, the 'h'-brigade should
remain untouched. That makes sense to me when looking at the code, and
other parts of the log showed that behavior.

But: when looking at above, the 1440 bytes 1888-2175 from the last run
of cache_save_store were replaced by 2176-2463, what is exactly the
observed behavior in the delivered file. In addition, there is a missing
part between 3519 and 3776 in the input brigade.

Any ideas, what could be responsible for that? I could reproduce it even
when not loading mod_deflate, mod_proxy_html, mod_substitute,
mod_headers et. al.

Log & patch available at: http://paste2.org/p/1784183 (~1MB)

Where could I debug further? mod_proxy? filters?

Any ideas would highly been appreciated.

Kind regards,
Florian


I noticed it already in 2.3.14-beta, and it still persists in 15-beta:
$ httpd -V
Server version: Apache/2.3.15 (Unix)
Server built: Nov 17 2011 17:32:34
Server's Module Magic Number: 20111025:2
Server loaded: APR 1.4.5, APR-UTIL 1.3.12
Compiled using: APR 1.4.5, APR-UTIL 1.3.12
Architecture: 32-bit
Server MPM: event
threaded: yes (fixed thread count)
forked: yes (variable process count)
Server compiled with....
-D APR_HAS_SENDFILE
-D APR_HAS_MMAP
-D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
-D APR_USE_SYSVSEM_SERIALIZE
-D APR_USE_PTHREAD_SERIALIZE
-D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
-D APR_HAS_OTHER_CHILD
-D AP_HAVE_RELIABLE_PIPED_LOGS
-D DYNAMIC_MODULE_LIMIT=256
-D HTTPD_ROOT="/apache"
-D SUEXEC_BIN="/apache/bin/suexec"
-D DEFAULT_PIDLOG="logs/httpd.pid"
-D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
-D DEFAULT_ERRORLOG="logs/error_log"
-D AP_TYPES_CONFIG_FILE="conf/mime.types"
-D SERVER_CONFIG_FILE="conf/httpd.conf"