You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@httpd.apache.org by Kr...@ubizen.com on 2002/07/29 14:02:46 UTC
mod_cache not serving cached pages
Hi,
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.
The
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 rom 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
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
Re: mod_cache not serving cached pages
Posted by Kr...@ubizen.com.
I used Netscape :-) And no that is not the problem. I also
tried it with a telnet to port 80. The cached response is
not
returned because it is determined as not being fresh enough.
In the code there is the following line:
(info->expire != APR_DATE_BAD &&
age < (info->expire - info->date + maxstale - minfresh))
if I fill in the values returned by the debug output, I get:
(1028550883671195 != 0 &&
1027946098539476 < (1028550883671195 - 1027943206000000 +
0 - 0))
This will return false of course. The problem is that the
'age'
value is not calculated correctly because the info->req_t
and
info->rsp_t are not yet initialized when they are needed for
this
calculation.
Koen Vingerhoets wrote:
>
> Hi,
>
> you didn't checked the 'Every time I visit this page' cache setting in
> IExplorer I hope?
>
> Met vriendelijke groet,
>
> Koen Vingerhoets
>
> ***** UBench nv *****
> http://www.ubench.com
> ____________________________________________
> The information contained in this electronic mail message is privileged and
> confidential,
> and is intended only for use of the addressee. If you are not the intended
> recipient, you
> are hereby notified that any disclosure,reproduction, distribution or other
> use of this
> communication is strictly prohibited.
>
> If you have received this communication in error, please notify the sender
> by reply
> transmission and delete the message without copying or disclosing it.
>
> -----Original Message-----
> From: krisv@be.ubizen.com [mailto:krisv@be.ubizen.com]On Behalf Of
> Kris.Verbeeck@ubizen.com
> Sent: 29 July 2002 14:03
> To: users@httpd.apache.org
> Subject: mod_cache not serving cached pages
>
> Hi,
>
> 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.
> The
> 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 rom 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
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
> For additional commands, e-mail: users-help@httpd.apache.org
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
> For additional commands, e-mail: users-help@httpd.apache.org
--
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
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
RE: mod_cache not serving cached pages
Posted by Koen Vingerhoets <ko...@ubench.com>.
Hi,
you didn't checked the 'Every time I visit this page' cache setting in
IExplorer I hope?
Met vriendelijke groet,
Koen Vingerhoets
***** UBench nv *****
http://www.ubench.com
____________________________________________
The information contained in this electronic mail message is privileged and
confidential,
and is intended only for use of the addressee. If you are not the intended
recipient, you
are hereby notified that any disclosure,reproduction, distribution or other
use of this
communication is strictly prohibited.
If you have received this communication in error, please notify the sender
by reply
transmission and delete the message without copying or disclosing it.
-----Original Message-----
From: krisv@be.ubizen.com [mailto:krisv@be.ubizen.com]On Behalf Of
Kris.Verbeeck@ubizen.com
Sent: 29 July 2002 14:03
To: users@httpd.apache.org
Subject: mod_cache not serving cached pages
Hi,
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.
The
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 rom 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
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org