You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Arnauld Dravet <sm...@egocentrique.com> on 2002/06/13 16:12:34 UTC
problem with mod_cache
Hi,
I submitted this behaviour on modproxy-dev mailing list but no one replied
...
i added mod_cache on my reverse proxy, and i noticed a strange behaviour.
Here is how i use mod_cache:
<VirtualHost 192.168.100.19:80>
ServerName web1.test.com
ProxyPass / http://web1.test.com/
ProxyPassReverse / http://web1.test.com/
TransferLog /dev/null
ErrorLog /logs/1-error.log
CacheOn On
CacheEnable mem /
MCacheSize 64000
MCacheMaxObjectSize 100000
#CacheIgnoreCacheControl on
#CacheExpiryCheck off
</VirtualHost>
Now i tell a Lynx client to get http://web1.test.com/index.html.fr (default
apache page).
Here are the logs on the reverse proxy:
==> /logs/1-error.log <==
[Thu Jun 13 13:06:35 2002] [debug] mod_cache.c(109): cache: URL
/index.html.fr is being handled by mem
[Thu Jun 13 13:06:35 2002] [debug] mod_cache.c(194): cache: no cache - add
cache_in filter and DECLINE
[Thu Jun 13 13:06:35 2002] [debug] proxy_http.c(445): proxy: HTTP:
canonicalising URL //web1.test.com/index.html.fr
[Thu Jun 13 13:06:35 2002] [debug] mod_proxy.c(464): Trying to run
scheme_handler
[Thu Jun 13 13:06:35 2002] [debug] proxy_http.c(1462): proxy: HTTP: serving
URL http://web1.test.com/index.html.fr
[Thu Jun 13 13:06:35 2002] [debug] proxy_http.c(571): proxy: HTTP connecting
http://web1.test.com/index.html.fr to web1.test.com:80
[Thu Jun 13 13:06:35 2002] [debug] proxy_util.c(1210): proxy: HTTP: fam 2
socket created to connect to web1.test.com
[Thu Jun 13 13:06:35 2002] [debug] proxy_http.c(741): proxy: socket is
connected
[Thu Jun 13 13:06:35 2002] [debug] proxy_http.c(780): proxy: connection
complete to 192.168.100.5:80 (web1.test.com)
[Thu Jun 13 13:06:35 2002] [debug] proxy_http.c(1287): proxy: start body
send
[Thu Jun 13 13:06:35 2002] [debug] mod_cache.c(419): cache: running CACHE_IN
filter
[Thu Jun 13 13:06:35 2002] [debug] proxy_http.c(1352): proxy: end body send
Now i quit lynx, then i relaunch it and i make the same request. Here is the
reverse proxy log for the new request:
[Thu Jun 13 13:08:04 2002] [debug] mod_cache.c(109): cache: URL
/index.html.fr is being handled by mem
[Thu Jun 13 13:08:04 2002] [debug] mod_cache.c(194): cache: no cache - add
cache_in filter and DECLINE
[Thu Jun 13 13:08:04 2002] [debug] proxy_http.c(445): proxy: HTTP:
canonicalising URL //web1.test.com/index.html.fr
[Thu Jun 13 13:08:04 2002] [debug] mod_proxy.c(464): Trying to run
scheme_handler
[Thu Jun 13 13:08:04 2002] [debug] proxy_http.c(1462): proxy: HTTP: serving
URL http://web1.test.com/index.html.fr
[Thu Jun 13 13:08:04 2002] [debug] proxy_http.c(571): proxy: HTTP connecting
http://web1.test.com/index.html.fr to web1.test.com:80
[Thu Jun 13 13:08:04 2002] [debug] proxy_util.c(1210): proxy: HTTP: fam 2
socket created to connect to web1.test.com
[Thu Jun 13 13:08:04 2002] [debug] proxy_http.c(741): proxy: socket is
connected
[Thu Jun 13 13:08:04 2002] [debug] proxy_http.c(780): proxy: connection
complete to 192.168.100.5:80 (web1.test.com)
[Thu Jun 13 13:08:04 2002] [debug] proxy_http.c(1287): proxy: start body
send
[Thu Jun 13 13:08:04 2002] [debug] mod_cache.c(419): cache: running CACHE_IN
filter
[Thu Jun 13 13:08:04 2002] [debug] proxy_http.c(1352): proxy: end body send
As you can see, it's exactly the same as if the request had never been made
before ... mod_cache says the page is not known and not cached. But if i use
mod_disk instead of mod_mem, i can see the page requested inside the
CacheRoot directory.
Same problem with mod_disk:
[root]# du -abc /cache/
4096 /cache/web1
8192 /cache
8192 total
I launch the first lynx request, here are the logs on the reverse proxy:
==> /logs/1-error.log <==
[Thu Jun 13 13:22:43 2002] [debug] mod_cache.c(109): cache: URL
/index.html.fr is being handled by disk
[Thu Jun 13 13:22:43 2002] [debug] mod_cache.c(194): cache: no cache - add
cache_in filter and DECLINE
[Thu Jun 13 13:22:43 2002] [debug] proxy_http.c(445): proxy: HTTP:
canonicalising URL //web1.test.com/index.html.fr
[Thu Jun 13 13:22:43 2002] [debug] mod_proxy.c(464): Trying to run
scheme_handler
[Thu Jun 13 13:22:43 2002] [debug] proxy_http.c(1462): proxy: HTTP: serving
URL http://web1.test.com/index.html.fr
[Thu Jun 13 13:22:43 2002] [debug] proxy_http.c(571): proxy: HTTP connecting
http://web1.test.com/index.html.fr to web1.test.com:80
[Thu Jun 13 13:22:43 2002] [debug] proxy_util.c(1210): proxy: HTTP: fam 2
socket created to connect to web1.test.com
[Thu Jun 13 13:22:43 2002] [debug] proxy_http.c(741): proxy: socket is
connected
[Thu Jun 13 13:22:43 2002] [debug] proxy_http.c(780): proxy: connection
complete to 192.168.100.5:80 (web1.test.com)
[Thu Jun 13 13:22:43 2002] [debug] proxy_http.c(1287): proxy: start body
send
[Thu Jun 13 13:22:43 2002] [debug] mod_cache.c(419): cache: running CACHE_IN
filter
[Thu Jun 13 13:22:43 2002] [info] disk_cache: Caching URL /index.html.fr
[Thu Jun 13 13:22:43 2002] [debug] mod_cache.c(650): cache: Caching url:
/index.html.fr
[Thu Jun 13 13:22:43 2002] [info] disk_cache: Caching headers for URL
/index.html.fr
[Thu Jun 13 13:22:43 2002] [debug] mod_cache.c(419): cache: running CACHE_IN
filter
[Thu Jun 13 13:22:43 2002] [info] disk_cache: Cached body for URL
/index.html.fr
[Thu Jun 13 13:22:43 2002] [debug] proxy_http.c(1352): proxy: end body send
I close Lynx.
[root]# du -abc /cache/
4096 /cache/web1/ib/LS/NJ/Qa@o@lyqvU58VTJw.header
4096 /cache/web1/ib/LS/NJ/Qa@o@lyqvU58VTJw.data
12288 /cache/web1/ib/LS/NJ
16384 /cache/web1/ib/LS
20480 /cache/web1/ib
24576 /cache/web1
28672 /cache
28672 total
I start a second request, here are the logs:
[Thu Jun 13 13:23:52 2002] [debug] mod_cache.c(109): cache: URL
/index.html.fr is being handled by disk
[Thu Jun 13 13:23:52 2002] [debug] mod_cache.c(194): cache: no cache - add
cache_in filter and DECLINE
[Thu Jun 13 13:23:52 2002] [debug] proxy_http.c(445): proxy: HTTP:
canonicalising URL //web1.test.com/index.html.fr
[Thu Jun 13 13:23:52 2002] [debug] mod_proxy.c(464): Trying to run
scheme_handler
[Thu Jun 13 13:23:52 2002] [debug] proxy_http.c(1462): proxy: HTTP: serving
URL http://web1.test.com/index.html.fr
[Thu Jun 13 13:23:52 2002] [debug] proxy_http.c(571): proxy: HTTP connecting
http://web1.test.com/index.html.fr to web1.test.com:80
[Thu Jun 13 13:23:52 2002] [debug] proxy_util.c(1210): proxy: HTTP: fam 2
socket created to connect to web1.test.com
[Thu Jun 13 13:23:52 2002] [debug] proxy_http.c(741): proxy: socket is
connected
[Thu Jun 13 13:23:52 2002] [debug] proxy_http.c(780): proxy: connection
complete to 192.168.100.5:80 (web1.test.com)
[Thu Jun 13 13:23:52 2002] [debug] proxy_http.c(1287): proxy: start body
send
[Thu Jun 13 13:23:52 2002] [debug] mod_cache.c(419): cache: running CACHE_IN
filter
[Thu Jun 13 13:23:52 2002] [info] disk_cache: Caching URL /index.html.fr
[Thu Jun 13 13:23:52 2002] [debug] mod_cache.c(650): cache: Caching url:
/index.html.fr
[Thu Jun 13 13:23:53 2002] [info] disk_cache: Caching headers for URL
/index.html.fr
[Thu Jun 13 13:23:53 2002] [debug] mod_cache.c(419): cache: running CACHE_IN
filter
[Thu Jun 13 13:23:53 2002] [info] disk_cache: Cached body for URL
/index.html.fr
[Thu Jun 13 13:23:53 2002] [debug] proxy_http.c(1352): proxy: end body send
It still says the cache does not known this URL.
Server logs always display the same line:
192.168.100.19 - - [13/Jun/2002:13:23:35 +0200] "GET /index.html.fr
HTTP/1.1" 200 1505
I then found a little patch to adress te mod_disk problem by changing line
548 in mod_disk_cache.c, and it worked: the second request was fully handled
by cache, and no request was sent to the server. But i still can't use the
mod_mem_cache module ... I tried the CVS version of apache, and it broke
again mod_disk_cache :
1st request log:
[Thu Jun 13 15:50:06 2002] [debug] mod_cache.c(109): cache: URL
/index.html.fr is being handled by disk
[Thu Jun 13 15:50:06 2002] [info] disk_cache: Serving Cached URL
/index.html.fr
[Thu Jun 13 15:50:06 2002] [info] disk_cache: Served headers for URL
/index.html.fr
[Thu Jun 13 15:50:06 2002] [debug] mod_cache.c(247): cache: stale cache -
test conditional
[Thu Jun 13 15:50:06 2002] [debug] mod_cache.c(283): cache: nonconditional -
no cached etag/lastmods - add cache_in and DECLINE
[Thu Jun 13 15:50:06 2002] [debug] proxy_http.c(109): proxy: HTTP:
canonicalising URL //web1.test.com/index.html.fr
[Thu Jun 13 15:50:06 2002] [debug] mod_proxy.c(461): Trying to run
scheme_handler
[Thu Jun 13 15:50:06 2002] [debug] proxy_http.c(1040): proxy: HTTP: serving
URL http://web1.test.com/index.html.fr
[Thu Jun 13 15:50:06 2002] [debug] proxy_http.c(221): proxy: HTTP connecting
http://web1.test.com/index.html.fr to web1.test.com:80
[Thu Jun 13 15:50:06 2002] [debug] proxy_util.c(1167): proxy: HTTP: fam 2
socket created to connect to web1.test.com
[Thu Jun 13 15:50:06 2002] [debug] proxy_http.c(370): proxy: socket is
connected
[Thu Jun 13 15:50:06 2002] [debug] proxy_http.c(404): proxy: connection
complete to 192.168.100.5:80 (web1.test.com)
[Thu Jun 13 15:50:06 2002] [debug] proxy_http.c(882): proxy: start body send
[Thu Jun 13 15:50:06 2002] [debug] mod_cache.c(416): cache: running CACHE_IN
filter
[Thu Jun 13 15:50:06 2002] [info] disk_cache: Caching URL /index.html.fr
[Thu Jun 13 15:50:06 2002] [debug] mod_cache.c(647): cache: Caching url:
/index.html.fr
[Thu Jun 13 15:50:06 2002] [info] disk_cache: Caching headers for URL
/index.html.fr
[Thu Jun 13 15:50:06 2002] [debug] mod_cache.c(416): cache: running CACHE_IN
filter
[Thu Jun 13 15:50:06 2002] [info] disk_cache: Cached body for URL
/index.html.fr
[Thu Jun 13 15:50:06 2002] [debug] proxy_http.c(941): proxy: end body send
2nd request log:
[Thu Jun 13 15:50:28 2002] [debug] mod_cache.c(109): cache: URL
/index.html.fr is being handled by disk
[Thu Jun 13 15:50:28 2002] [info] disk_cache: Serving Cached URL
/index.html.fr
[Thu Jun 13 15:50:28 2002] [info] disk_cache: Served headers for URL
/index.html.fr
[Thu Jun 13 15:50:28 2002] [debug] mod_cache.c(247): cache: stale cache -
test conditional
[Thu Jun 13 15:50:28 2002] [debug] mod_cache.c(283): cache: nonconditional -
no cached etag/lastmods - add cache_in and DECLINE
[Thu Jun 13 15:50:28 2002] [debug] proxy_http.c(109): proxy: HTTP:
canonicalising URL //web1.test.com/index.html.fr
[Thu Jun 13 15:50:28 2002] [debug] mod_proxy.c(461): Trying to run
scheme_handler
[Thu Jun 13 15:50:28 2002] [debug] proxy_http.c(1040): proxy: HTTP: serving
URL http://web1.test.com/index.html.fr
[Thu Jun 13 15:50:28 2002] [debug] proxy_http.c(221): proxy: HTTP connecting
http://web1.test.com/index.html.fr to web1.test.com:80
[Thu Jun 13 15:50:28 2002] [debug] proxy_util.c(1167): proxy: HTTP: fam 2
socket created to connect to web1.test.com
[Thu Jun 13 15:50:28 2002] [debug] proxy_http.c(370): proxy: socket is
connected
[Thu Jun 13 15:50:28 2002] [debug] proxy_http.c(404): proxy: connection
complete to 192.168.100.5:80 (web1.test.com)
[Thu Jun 13 15:50:28 2002] [debug] proxy_http.c(882): proxy: start body send
[Thu Jun 13 15:50:28 2002] [debug] mod_cache.c(416): cache: running CACHE_IN
filter
[Thu Jun 13 15:50:28 2002] [info] disk_cache: Caching URL /index.html.fr
[Thu Jun 13 15:50:28 2002] [debug] mod_cache.c(647): cache: Caching url:
/index.html.fr
[Thu Jun 13 15:50:28 2002] [info] disk_cache: Caching headers for URL
/index.html.fr
[Thu Jun 13 15:50:28 2002] [debug] mod_cache.c(416): cache: running CACHE_IN
filter
[Thu Jun 13 15:50:28 2002] [info] disk_cache: Cached body for URL
/index.html.fr
[Thu Jun 13 15:50:28 2002] [debug] proxy_http.c(941): proxy: end body send
Now if i enable mem cache instead of disk cache:
[Thu Jun 13 16:10:31 2002] [debug] mod_cache.c(109): cache: URL
/index.html.fr is being handled by mem
[Thu Jun 13 16:10:31 2002] [debug] mod_cache.c(192): cache: no cache - add
cache_in filter and DECLINE
[Thu Jun 13 16:10:31 2002] [debug] proxy_http.c(109): proxy: HTTP:
canonicalising URL //web1.test.com/index.html.fr
[Thu Jun 13 16:10:31 2002] [debug] mod_proxy.c(461): Trying to run
scheme_handler
[Thu Jun 13 16:10:31 2002] [debug] proxy_http.c(1040): proxy: HTTP: serving
URL http://web1.test.com/index.html.fr
[Thu Jun 13 16:10:31 2002] [debug] proxy_http.c(221): proxy: HTTP connecting
http://web1.test.com/index.html.fr to web1.test.com:80
[Thu Jun 13 16:10:31 2002] [debug] proxy_util.c(1167): proxy: HTTP: fam 2
socket created to connect to web1.test.com
[Thu Jun 13 16:10:31 2002] [debug] proxy_http.c(370): proxy: socket is
connected
[Thu Jun 13 16:10:31 2002] [debug] proxy_http.c(404): proxy: connection
complete to 192.168.100.5:80 (web1.test.com)
[Thu Jun 13 16:10:31 2002] [debug] proxy_http.c(882): proxy: start body send
[Thu Jun 13 16:10:31 2002] [debug] mod_cache.c(416): cache: running CACHE_IN
filter
[Thu Jun 13 16:10:31 2002] [debug] mod_mem_cache.c(438): cache_mem: URL
/index.html.fr failed the size check, or is incomplete
[Thu Jun 13 16:10:31 2002] [debug] proxy_http.c(941): proxy: end body send
i'm lost :(
thanks for your help,
Arnauld Dravet
smurfie@egocentrique.com