You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by f_los_ch <f_...@yahoo.com> on 2011/11/18 20:50:23 UTC
corrupt brigades when using mod_cache in reverse proxy
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"
Re: corrupt brigades when using mod_cache in reverse proxy
Posted by "Florian S." <f_...@yahoo.com>.
Yes, I can confirm that this patch works for me, too.
And now I understand your point: Buffering/keeping back the output via
an additional brigade until a flush occurs isn't actually needed for the
cache-filter as it could simply be passed along immediately. Seems
pretty reasonable.
I'll use it in (semi-)production for the next days and keep an eye on it
(but probably not needed).
Thanks again for your effort & Kind regards:
Florian
Am Samstag, den 19.11.2011, 16:59 +0200 schrieb Graham Leggett:
> On 19 Nov 2011, at 3:56 PM, f_los_ch wrote:
>
> > Thanks for the reply and your patch - it worked!
> >
> > I could not longer reproduce diffs for cached/uncached files. The log
> > with dumped buckets according to my previous patch is again available
> > at: http://paste2.org/p/1785342
> >
> > Now, when the location is spotted, maybe I can also try to isolate the
> > bug even more via further debugging for developing some production-use
> > patch. In the hope that really the bug was in there and the continuous
> > flushing did not masquerade the underlying issue..?
> >
> > But that it is working for now is a real relief.
>
> Thanks for confirming it works. Would it be possible to try this
> alternative patch? Looking at the brigade inside h, it doesn't seem to
> be doing anything useful in this case, and was a hangup from older
> code. This new patch takes the intermediate brigade out completely,
> and should in theory use less memory and be slightly faster: What I
> need to do is find out why we haven't discovered this before.
>
> Index: modules/cache/mod_cache_disk.c
> ===================================================================
> --- modules/cache/mod_cache_disk.c (revision 1203646)
> +++ modules/cache/mod_cache_disk.c (working copy)
> @@ -1075,9 +1075,6 @@
> disk_cache_dir_conf *dconf = ap_get_module_config(r-
> >per_dir_config, &cache_disk_module);
> int seen_eos = 0;
>
> - if (!dobj->bb) {
> - dobj->bb = apr_brigade_create(r->pool, r->connection-
> >bucket_alloc);
> - }
> if (!dobj->offset) {
> dobj->offset = dconf->readsize;
> }
> @@ -1107,7 +1104,6 @@
> seen_eos = 1;
> dobj->done = 1;
> APR_BUCKET_REMOVE(e);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> APR_BRIGADE_INSERT_TAIL(out, e);
> break;
> }
> @@ -1115,7 +1111,6 @@
> /* honour flush buckets, we'll get called again */
> if (APR_BUCKET_IS_FLUSH(e)) {
> APR_BUCKET_REMOVE(e);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> APR_BRIGADE_INSERT_TAIL(out, e);
> break;
> }
> @@ -1123,21 +1118,20 @@
> /* metadata buckets are preserved as is */
> if (APR_BUCKET_IS_METADATA(e)) {
> APR_BUCKET_REMOVE(e);
> - APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
> + APR_BRIGADE_INSERT_TAIL(out, e);
> continue;
> }
>
> /* read the bucket, write to the cache */
> rv = apr_bucket_read(e, &str, &length, APR_BLOCK_READ);
> APR_BUCKET_REMOVE(e);
> - APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
> + APR_BRIGADE_INSERT_TAIL(out, e);
> if (rv != APR_SUCCESS) {
> ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
> "cache_disk: Error when reading bucket for URL
> %s",
> h->cache_obj->key);
> /* Remove the intermediate cache file and return non-
> APR_SUCCESS */
> apr_pool_destroy(dobj->data.pool);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> return rv;
> }
>
> @@ -1156,7 +1150,6 @@
> APR_BUFFERED | APR_EXCL, dobj-
> >data.pool);
> if (rv != APR_SUCCESS) {
> apr_pool_destroy(dobj->data.pool);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> return rv;
> }
> dobj->file_size = 0;
> @@ -1164,7 +1157,6 @@
> dobj->data.tempfd);
> if (rv != APR_SUCCESS) {
> apr_pool_destroy(dobj->data.pool);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> return rv;
> }
> dobj->disk_info.device = finfo.device;
> @@ -1180,7 +1172,6 @@
> h->cache_obj->key);
> /* Remove the intermediate cache file and return non-
> APR_SUCCESS */
> apr_pool_destroy(dobj->data.pool);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> return rv;
> }
> dobj->file_size += written;
> @@ -1191,7 +1182,6 @@
> h->cache_obj->key, dobj->file_size, dconf->maxfs);
> /* Remove the intermediate cache file and return non-
> APR_SUCCESS */
> apr_pool_destroy(dobj->data.pool);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> return APR_EGENERAL;
> }
>
> @@ -1203,12 +1193,10 @@
> dobj->offset -= length;
> if (dobj->offset <= 0) {
> dobj->offset = 0;
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> break;
> }
> if ((dconf->readtime && apr_time_now() > dobj->timeout)) {
> dobj->timeout = 0;
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> break;
> }
>
> Index: modules/cache/mod_cache_disk.h
> ===================================================================
> --- modules/cache/mod_cache_disk.h (revision 1203646)
> +++ modules/cache/mod_cache_disk.h (working copy)
> @@ -49,7 +49,6 @@
> const char *key; /* On-disk prefix; URI with Vary
> bits (if present) */
> apr_off_t file_size; /* File size of the cached data
> file */
> disk_cache_info_t disk_info; /* Header information. */
> - apr_bucket_brigade *bb; /* Set aside brigade */
> apr_table_t *headers_in; /* Input headers to save */
> apr_table_t *headers_out; /* Output headers to save */
> apr_off_t offset; /* Max size to set aside */
>
> Regards,
> Graham
> --
>
Re: corrupt brigades when using mod_cache in reverse proxy
Posted by Graham Leggett <mi...@sharp.fm>.
On 19 Nov 2011, at 3:56 PM, f_los_ch wrote:
> Thanks for the reply and your patch - it worked!
>
> I could not longer reproduce diffs for cached/uncached files. The log
> with dumped buckets according to my previous patch is again available
> at: http://paste2.org/p/1785342
>
> Now, when the location is spotted, maybe I can also try to isolate the
> bug even more via further debugging for developing some production-use
> patch. In the hope that really the bug was in there and the continuous
> flushing did not masquerade the underlying issue..?
>
> But that it is working for now is a real relief.
Thanks for confirming it works. Would it be possible to try this
alternative patch? Looking at the brigade inside h, it doesn't seem to
be doing anything useful in this case, and was a hangup from older
code. This new patch takes the intermediate brigade out completely,
and should in theory use less memory and be slightly faster: What I
need to do is find out why we haven't discovered this before.
Index: modules/cache/mod_cache_disk.c
===================================================================
--- modules/cache/mod_cache_disk.c (revision 1203646)
+++ modules/cache/mod_cache_disk.c (working copy)
@@ -1075,9 +1075,6 @@
disk_cache_dir_conf *dconf = ap_get_module_config(r-
>per_dir_config, &cache_disk_module);
int seen_eos = 0;
- if (!dobj->bb) {
- dobj->bb = apr_brigade_create(r->pool, r->connection-
>bucket_alloc);
- }
if (!dobj->offset) {
dobj->offset = dconf->readsize;
}
@@ -1107,7 +1104,6 @@
seen_eos = 1;
dobj->done = 1;
APR_BUCKET_REMOVE(e);
- APR_BRIGADE_CONCAT(out, dobj->bb);
APR_BRIGADE_INSERT_TAIL(out, e);
break;
}
@@ -1115,7 +1111,6 @@
/* honour flush buckets, we'll get called again */
if (APR_BUCKET_IS_FLUSH(e)) {
APR_BUCKET_REMOVE(e);
- APR_BRIGADE_CONCAT(out, dobj->bb);
APR_BRIGADE_INSERT_TAIL(out, e);
break;
}
@@ -1123,21 +1118,20 @@
/* metadata buckets are preserved as is */
if (APR_BUCKET_IS_METADATA(e)) {
APR_BUCKET_REMOVE(e);
- APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
+ APR_BRIGADE_INSERT_TAIL(out, e);
continue;
}
/* read the bucket, write to the cache */
rv = apr_bucket_read(e, &str, &length, APR_BLOCK_READ);
APR_BUCKET_REMOVE(e);
- APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
+ APR_BRIGADE_INSERT_TAIL(out, e);
if (rv != APR_SUCCESS) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
"cache_disk: Error when reading bucket for URL
%s",
h->cache_obj->key);
/* Remove the intermediate cache file and return non-
APR_SUCCESS */
apr_pool_destroy(dobj->data.pool);
- APR_BRIGADE_CONCAT(out, dobj->bb);
return rv;
}
@@ -1156,7 +1150,6 @@
APR_BUFFERED | APR_EXCL, dobj-
>data.pool);
if (rv != APR_SUCCESS) {
apr_pool_destroy(dobj->data.pool);
- APR_BRIGADE_CONCAT(out, dobj->bb);
return rv;
}
dobj->file_size = 0;
@@ -1164,7 +1157,6 @@
dobj->data.tempfd);
if (rv != APR_SUCCESS) {
apr_pool_destroy(dobj->data.pool);
- APR_BRIGADE_CONCAT(out, dobj->bb);
return rv;
}
dobj->disk_info.device = finfo.device;
@@ -1180,7 +1172,6 @@
h->cache_obj->key);
/* Remove the intermediate cache file and return non-
APR_SUCCESS */
apr_pool_destroy(dobj->data.pool);
- APR_BRIGADE_CONCAT(out, dobj->bb);
return rv;
}
dobj->file_size += written;
@@ -1191,7 +1182,6 @@
h->cache_obj->key, dobj->file_size, dconf->maxfs);
/* Remove the intermediate cache file and return non-
APR_SUCCESS */
apr_pool_destroy(dobj->data.pool);
- APR_BRIGADE_CONCAT(out, dobj->bb);
return APR_EGENERAL;
}
@@ -1203,12 +1193,10 @@
dobj->offset -= length;
if (dobj->offset <= 0) {
dobj->offset = 0;
- APR_BRIGADE_CONCAT(out, dobj->bb);
break;
}
if ((dconf->readtime && apr_time_now() > dobj->timeout)) {
dobj->timeout = 0;
- APR_BRIGADE_CONCAT(out, dobj->bb);
break;
}
Index: modules/cache/mod_cache_disk.h
===================================================================
--- modules/cache/mod_cache_disk.h (revision 1203646)
+++ modules/cache/mod_cache_disk.h (working copy)
@@ -49,7 +49,6 @@
const char *key; /* On-disk prefix; URI with Vary
bits (if present) */
apr_off_t file_size; /* File size of the cached data
file */
disk_cache_info_t disk_info; /* Header information. */
- apr_bucket_brigade *bb; /* Set aside brigade */
apr_table_t *headers_in; /* Input headers to save */
apr_table_t *headers_out; /* Output headers to save */
apr_off_t offset; /* Max size to set aside */
Regards,
Graham
--
Re: corrupt brigades when using mod_cache in reverse proxy
Posted by f_los_ch <f_...@yahoo.com>.
Hello,
Thanks for the reply and your patch - it worked!
I could not longer reproduce diffs for cached/uncached files. The log
with dumped buckets according to my previous patch is again available
at: http://paste2.org/p/1785342
Now, when the location is spotted, maybe I can also try to isolate the
bug even more via further debugging for developing some production-use
patch. In the hope that really the bug was in there and the continuous
flushing did not masquerade the underlying issue..?
But that it is working for now is a real relief.
Thanks again & kind regards:
Florian
Am Samstag, den 19.11.2011, 03:09 +0200 schrieb Graham Leggett:
> On 18 Nov 2011, at 9:50 PM, f_los_ch wrote:
>
> > 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.
>
> Can you confirm if the following patch makes any difference for you? I
> suspect the disk cache is finding a way to leave without passing all
> the saved buckets to out first.
>
> Index: modules/cache/mod_cache_disk.c
> ===================================================================
> --- modules/cache/mod_cache_disk.c (revision 1203646)
> +++ modules/cache/mod_cache_disk.c (working copy)
> @@ -1098,7 +1098,7 @@
> /* are we done completely? if so, pass any trailing buckets
> right through */
> if (dobj->done || !dobj->data.pool) {
> APR_BUCKET_REMOVE(e);
> - APR_BRIGADE_INSERT_TAIL(out, e);
> + APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
> continue;
> }
>
> @@ -1107,16 +1107,14 @@
> seen_eos = 1;
> dobj->done = 1;
> APR_BUCKET_REMOVE(e);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> - APR_BRIGADE_INSERT_TAIL(out, e);
> + APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
> break;
> }
>
> /* honour flush buckets, we'll get called again */
> if (APR_BUCKET_IS_FLUSH(e)) {
> APR_BUCKET_REMOVE(e);
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> - APR_BRIGADE_INSERT_TAIL(out, e);
> + APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
> break;
> }
>
> @@ -1203,17 +1201,18 @@
> dobj->offset -= length;
> if (dobj->offset <= 0) {
> dobj->offset = 0;
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> break;
> }
> if ((dconf->readtime && apr_time_now() > dobj->timeout)) {
> dobj->timeout = 0;
> - APR_BRIGADE_CONCAT(out, dobj->bb);
> break;
> }
>
> }
>
> + /* make sure we sweep all saved buckets to the out brigade */
> + APR_BRIGADE_CONCAT(out, dobj->bb);
> +
> /* Was this the final bucket? If yes, close the temp file and
> perform
> * sanity checks.
> */
>
> Regards,
> Graham
> --
>
Re: corrupt brigades when using mod_cache in reverse proxy
Posted by Graham Leggett <mi...@sharp.fm>.
On 18 Nov 2011, at 9:50 PM, f_los_ch wrote:
> 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.
Can you confirm if the following patch makes any difference for you? I
suspect the disk cache is finding a way to leave without passing all
the saved buckets to out first.
Index: modules/cache/mod_cache_disk.c
===================================================================
--- modules/cache/mod_cache_disk.c (revision 1203646)
+++ modules/cache/mod_cache_disk.c (working copy)
@@ -1098,7 +1098,7 @@
/* are we done completely? if so, pass any trailing buckets
right through */
if (dobj->done || !dobj->data.pool) {
APR_BUCKET_REMOVE(e);
- APR_BRIGADE_INSERT_TAIL(out, e);
+ APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
continue;
}
@@ -1107,16 +1107,14 @@
seen_eos = 1;
dobj->done = 1;
APR_BUCKET_REMOVE(e);
- APR_BRIGADE_CONCAT(out, dobj->bb);
- APR_BRIGADE_INSERT_TAIL(out, e);
+ APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
break;
}
/* honour flush buckets, we'll get called again */
if (APR_BUCKET_IS_FLUSH(e)) {
APR_BUCKET_REMOVE(e);
- APR_BRIGADE_CONCAT(out, dobj->bb);
- APR_BRIGADE_INSERT_TAIL(out, e);
+ APR_BRIGADE_INSERT_TAIL(dobj->bb, e);
break;
}
@@ -1203,17 +1201,18 @@
dobj->offset -= length;
if (dobj->offset <= 0) {
dobj->offset = 0;
- APR_BRIGADE_CONCAT(out, dobj->bb);
break;
}
if ((dconf->readtime && apr_time_now() > dobj->timeout)) {
dobj->timeout = 0;
- APR_BRIGADE_CONCAT(out, dobj->bb);
break;
}
}
+ /* make sure we sweep all saved buckets to the out brigade */
+ APR_BRIGADE_CONCAT(out, dobj->bb);
+
/* Was this the final bucket? If yes, close the temp file and
perform
* sanity checks.
*/
Regards,
Graham
--