Problem with mod_cache
am 13.06.2002 13:31:41 von Arnauld Dravethello,
i added mod_cache on my reverse proxy, and i noticed a strange behaviour.
Here is how i use mod_cache:
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
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'm lost :(
thanks for your help,
Arnauld Dravet
smurfie@egocentrique.com