httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Arnauld Dravet" <smur...@egocentrique.com>
Subject problem with mod_cache
Date Thu, 13 Jun 2002 14:12:34 GMT
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



Mime
View raw message