Hi,
First of all, I also posted this mail on the Apache users
mailing
list but did not receive any solution for my problem.
That's why
I'm trying the dev mailing list now.
I have a problem with letting Apache 2.0.39/mod_cache serve
cached
pages. When first requesting a page, the page is being
cached (a disk
file is present) but when performing a second request, the
cached page
is not returned but a fresh page is fetched. Is this a
configuration
issue or problem with mod_cache?
Relevant configuration section from httpd.conf:
<VirtualHost [ip]:[port]>
JkMount /* ajp13
ServerName [hostname]
<IfModule mod_ssl.c>
SSLEngine off
# 10
# [certificate]
# [key]
# [caCertificate]
# +StdEnvVars +CompatEnvVars +ExportCertData
</IfModule>
<IfModule mod_mime.c>
# AddOutputFilter DEFLATE [deflateExtensions]
</IfModule>
<IfModule mod_cache.c>
CacheOn On
CacheMaxExpire 604800
CacheDefaultExpire 3600
<IfModule mod_disk_cache.c>
CacheRoot /cache
CacheEnable disk /
</IfModule>
</IfModule>
</VirtualHost>
I have added some extra logging statements to the mod_cache
code to
check which 'age' values are being used/calculated for the
cached
page. Logging has been set to debug and when performing a
first
request for a page, the following lines are logged:
[Mon Jul 29 13:34:43 2002] [debug] mod_cache.c(109): cache:
URL /omega/perl/pod/perlfunc/symlink.html is being handled
by disk
[Mon Jul 29 13:34:43 2002] [debug] mod_cache.c(192): cache:
no cache - add cache_in filter and DECLINE
[Mon Jul 29 13:34:43 2002] [debug] mod_cache.c(416): cache:
running CACHE_IN filter
[Mon Jul 29 13:34:43 2002] [info] disk_cache: Caching URL
/omega/perl/pod/perlfunc/symlink.html
[Mon Jul 29 13:34:43 2002] [debug] mod_cache.c(643): cache:
Caching url: /omega/perl/pod/perlfunc/symlink.html
[Mon Jul 29 13:34:43 2002] [debug] mod_cache.c(684):
now = 1027946083671195
[Mon Jul 29 13:34:43 2002] [debug] mod_cache.c(685): set
rsp_t = 1027946083671195
[Mon Jul 29 13:34:43 2002] [info] disk_cache: Caching
headers for URL /omega/perl/pod/perlfunc/symlink.html
[Mon Jul 29 13:34:43 2002] [debug] mod_cache.c(416): cache:
running CACHE_IN filter
[Mon Jul 29 13:34:43 2002] [info] disk_cache: Cached body
for URL /omega/perl/pod/perlfunc/symlink.html
The lines with 'now =' and 'set rsp_t =' were added by me.
They
show the current time and response time (in usec since
1970).
Now, when performing a second request for the same page,
that page
should come from the cache. But:
[Mon Jul 29 13:34:58 2002] [debug] mod_cache.c(109): cache:
URL /omega/perl/pod/perlfunc/symlink.html is being handled
by disk
[Mon Jul 29 13:34:58 2002] [info] disk_cache: Serving Cached
URL /omega/perl/pod/perlfunc/symlink.html
[Mon Jul 29 13:34:58 2002] [info] disk_cache: Served headers
for URL /omega/perl/pod/perlfunc/symlink.html
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(253):
APR_DATE_BAD = 0
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(254):
age = 1027946098539476
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(255):
age_c = 0
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(256):
info->date = 1027943206000000
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(257):
info->expire = 1028550883671195
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(258):
info->req_t = 0
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(259):
info->rsp_t = 0
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(260):
minfresh = 0
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(261):
maxage = -1
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(262):
maxstale = 0
[Mon Jul 29 13:34:58 2002] [debug] cache_util.c(263):
smaxage = -1
[Mon Jul 29 13:34:58 2002] [debug] mod_cache.c(247): cache:
stale cache - test conditional
[Mon Jul 29 13:34:58 2002] [debug] mod_cache.c(283): cache:
nonconditional - no cached etag/lastmods - add cache_in and
DECLINE
[Mon Jul 29 13:34:58 2002] [debug] mod_cache.c(416): cache:
running CACHE_IN filter
[Mon Jul 29 13:34:58 2002] [info] disk_cache: Caching URL
/omega/perl/pod/perlfunc/symlink.html
[Mon Jul 29 13:34:58 2002] [debug] mod_cache.c(643): cache:
Caching url: /omega/perl/pod/perlfunc/symlink.html
[Mon Jul 29 13:34:58 2002] [debug] mod_cache.c(684):
now = 1027946098584206
[Mon Jul 29 13:34:58 2002] [debug] mod_cache.c(685): set
rsp_t = 1027946098584206
[Mon Jul 29 13:34:58 2002] [info] disk_cache: Caching
headers for URL /omega/perl/pod/perlfunc/symlink.html
[Mon Jul 29 13:34:58 2002] [debug] mod_cache.c(416): cache:
running CACHE_IN filter
[Mon Jul 29 13:34:58 2002] [info] disk_cache: Cached body
for URL /omega/perl/pod/perlfunc/symlink.html
>From line 4 to line 14 I printed some more debug values.
These values
are used to calculate the age of the request/response and to
check
whether the cached version is still fresh. The problem here
is that
the info->request_time and info->response_time are zero,
resulting in
a very large age value. These values are zero because they
are only
filled in later on, i.e. a few lines lower you have the 'set
rsp_t'
log entry.
Does mod_cache behave like this because I misconfigured
something? Or
is it a problem in the code itself??
--
ir. Kris Verbeeck
Development Engineer
Ubizen - Ubicenter - Philipssite 5 - 3001 Leuven - Belgium
T: +32 16 28 70 64
F: +32 16 28 70 77
Ubizen - We Secure e-business - www.ubizen.com
