You are viewing a plain text version of this content. The canonical link for it is here.
Posted to modproxy-dev@apache.org by Arnauld Dravet <sm...@egocentrique.com> on 2002/06/13 13:31:41 UTC

Problem with mod_cache

hello,

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'm lost :(

thanks for your help,

Arnauld Dravet
smurfie@egocentrique.com