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"
