Bug 27791

Summary: mod_cache doesn't re-cache expired content
Product: Apache httpd-2 Reporter: Darron Wood <darron.wood>
Component: mod_cacheAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED LATER    
Severity: normal Keywords: MassUpdate, PatchAvailable
Priority: P3    
Version: 2.0.49   
Target Milestone: ---   
Hardware: Sun   
OS: other   
Bug Depends on:    
Bug Blocks: 30278    
Attachments: modified mod_cache.c file that is delivered with 2.0.49
modified mod_disk_cache.c file that is delivered with 2.0.49
Patch for mod_disk_cache.c
Patch for mod_cache.c

Description Darron Wood 2004-03-18 22:22:31 UTC 
It looks like mod_cache isn't discarding expired content in cache.  I increased 
the LogLevel to debug and below is what I see in the log file when the content 
is expired in cache.  It appears that mod_cache sees it is expired, then goes 
to revalidate the content from the application server but never caches the new 
version. If I run snoop on my Apache Reverse Proxy server while the content is 
expired in cache I see the request go to the application server when it is 
requested and the copy in cache never gets updated and the expiration date is 
not reset.


[Thu Mar 18 11:16:14 2004] [info] disk_cache: Serving Cached URL 
server.com/infocenter/images/file.gif?
[Thu Mar 18 11:16:14 2004] [info] disk_cache: Served headers for URL 
server.com/infocenter/images/file.gif?
[Thu Mar 18 11:16:14 2004] [debug] mod_cache.c(259): cache: stale cache - test 
conditional
[Thu Mar 18 11:16:14 2004] [debug] mod_cache.c(263): cache: conditional - add 
cache_in filter and DECLINE
[Thu Mar 18 11:16:14 2004] [debug] proxy_http.c(109): proxy: HTTP: 
canonicalising URL //serverx.com:8100/infocenter/images/file.gif
[Thu Mar 18 11:16:14 2004] [debug] mod_proxy.c(459): Trying to run 
scheme_handler
[Thu Mar 18 11:16:14 2004] [debug] proxy_http.c(1076): proxy: HTTP: serving URL 
http://serverx.com:8100/infocenter/images/file.gif
[Thu Mar 18 11:16:14 2004] [debug] proxy_http.c(221): proxy: HTTP connecting 
http://serverx.com:8100/infocenter/images/file.gif to serverx.com:8100
[Thu Mar 18 11:16:14 2004] [debug] proxy_util.c(1203): proxy: HTTP: fam 2 
socket created to connect to serverx.com
[Thu Mar 18 11:16:14 2004] [debug] proxy_http.c(370): proxy: socket is connected
[Thu Mar 18 11:16:14 2004] [debug] proxy_http.c(404): proxy: connection 
complete to xx.xx.xxx.xx:8100 (serverx.com)
[Thu Mar 18 11:16:14 2004] [debug] proxy_http.c(979): proxy: header only
[Thu Mar 18 11:16:14 2004] [debug] mod_cache.c(436): cache: running CACHE_IN 
filter
Comment 1 Darron Wood 2004-04-07 14:21:01 UTC 
I just tested this in 2.0.49 and the same issue exists in this version also.  
I'm updating this bug to reflect that it also exists in 2.0.49.
Comment 2 Darron Wood 2004-04-07 15:09:00 UTC 
Created attachment 11169 [details]
modified mod_cache.c file that is delivered with 2.0.49
Comment 3 Darron Wood 2004-04-07 15:11:08 UTC 
Created attachment 11170 [details]
modified mod_disk_cache.c file that is delivered with 2.0.49
Comment 4 Darron Wood 2004-04-07 15:14:25 UTC 
I modified the mod_cache.c and mod_disk_cache.c files that are delievered with 
2.0.49 and caching appears to be working now.  I've attached the modified 
mod_cache.c and mod_disk_cache.c files from 2.0.49 to this bug.  Could someone 
check out the changes I made and see if those are OK?
Comment 5 Darron Wood 2004-04-07 18:49:53 UTC 
Created attachment 11176 [details]
Patch for mod_disk_cache.c
Comment 6 Darron Wood 2004-04-07 18:50:34 UTC 
Created attachment 11177 [details]
Patch for mod_cache.c
Comment 7 Darron Wood 2004-04-07 18:52:17 UTC 
Attached diff output for both mod_cache.c and mod_disk_cache.c.
Comment 8 Axel-Stephane Smorgrav 2004-06-05 14:35:33 UTC 
I have installed the patches provided in this PR on Apache 2.0.49 and done 
extensive load testing. As far as I can tell, the cache now behaves correctly 
(both mem_cache and disk_cache). Expired files are updated. Thanks Darron, for 
providing the fixes.
Comment 9 Axel-Stephane Smorgrav 2004-06-07 17:20:04 UTC 
I may have rejoyced a little to quickly there...

The problem was mostly fixed by the patch provided. Unfortunately, there seems 
to be another problem.

On a reverse proxy, centuri, we have both disk cache and mem cache activated. 
The memory cache activated first and is only supposed to cache elements of size 
smaller than 10,000 bytes. The disk cache takes care of anything not cached by 
the memory cache.

Somehow, at one point a file of size smaller than 10,000 bytes ends up being 
cached by the disk cache. Don't ask me why (maybe the mem cache was filled up 
and the element ended up on disk?) - it's beyond the point. Eventually, the 
file in disk cache ends up stale. At than point, when the element (style.css) 
is requested, the disk cache responds that it is stale and a proxy request is 
issued to the backend server. The fresh element ends up being cached in memory, 
and the stale entry remains in the disk cache...

The logs below should clearly show what happens. mod_disk_cache does not appear 
to log the element as stale, but I know that the disk cache contains a stale 
copy of styles.css because I looked it up. Removing the element from the disk 
cache also removes the symptoms.

Please find below the log trace of two requests for the same element style.css 
on the reverse proxy centuri:3080. The backend server is backend:7010. The two 
requests are separated by some CRs.

[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(66): proxy: HTTP: 
canonicalising URL //centuri:3080/html/styles.css
[Mon Jun 07 08:48:57 2004] [debug] mod_proxy.c(416): Trying to run 
scheme_handler
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(1042): proxy: HTTP: serving URL 
http://centuri:3080/html/styles.css
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(178): proxy: HTTP connecting 
http://centuri:3080/html/styles.css to centuri.gsi.fr:3080
[Mon Jun 07 08:48:57 2004] [debug] proxy_util.c(1160): proxy: HTTP: fam 2 
socket created to connect to centuri
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(327): proxy: socket is connected
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(361): proxy: connection 
complete to 150.175.10.189:3080 (centuri)
[Mon Jun 07 08:48:57 2004] [debug] mod_cache.c(344): cache: stale cache - test 
conditional
[Mon Jun 07 08:48:57 2004] [debug] mod_cache.c(391): cache: nonconditional - no 
cached etag/lastmods - add cache_in and DECLINE
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(66): proxy: HTTP: 
canonicalising URL //backend:7010/html/styles.css
[Mon Jun 07 08:48:57 2004] [debug] mod_proxy.c(416): Trying to run 
scheme_handler
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(1042): proxy: HTTP: serving URL 
http://backend:7010/html/styles.css
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(178): proxy: HTTP connecting 
http://backend:7010/html/styles.css to backend:7010
[Mon Jun 07 08:48:57 2004] [debug] proxy_util.c(1160): proxy: HTTP: fam 2 
socket created to connect to backend
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(327): proxy: socket is connected
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(361): proxy: connection 
complete to backend:7010 (backend)
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(877): proxy: start body send
[Mon Jun 07 08:48:57 2004] [debug] mod_cache.c(532): cache: running CACHE_IN 
filter
[Mon Jun 07 08:48:57 2004] [debug] mod_cache.c(790): cache: Caching 
url: /html/styles.css
[Mon Jun 07 08:48:57 2004] [info] mem_cache: Cached url: 
centuri/html/styles.css?
[Mon Jun 07 08:48:57 2004] [debug] mod_headers.c(521): headers: 
ap_headers_output_filter()
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(936): proxy: end body send
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(877): proxy: start body send
[Mon Jun 07 08:48:57 2004] [debug] mod_headers.c(521): headers: 
ap_headers_output_filter()
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(936): proxy: end body send


[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(66): proxy: HTTP: 
canonicalising URL //centuri:3080/html/styles.css
[Mon Jun 07 08:48:57 2004] [debug] mod_proxy.c(416): Trying to run 
scheme_handler
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(1042): proxy: HTTP: serving URL 
http://centuri:3080/html/styles.css
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(178): proxy: HTTP connecting 
http://centuri:3080/html/styles.css to centuri.gsi.fr:3080
[Mon Jun 07 08:48:57 2004] [debug] proxy_util.c(1160): proxy: HTTP: fam 2 
socket created to connect to centuri
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(327): proxy: socket is connected
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(361): proxy: connection 
complete to 150.175.10.189:3080 (centuri)
[Mon Jun 07 08:48:57 2004] [debug] mod_cache.c(344): cache: stale cache - test 
conditional
[Mon Jun 07 08:48:57 2004] [debug] mod_cache.c(391): cache: nonconditional - no 
cached etag/lastmods - add cache_in and DECLINE
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(66): proxy: HTTP: 
canonicalising URL //backend:7010/html/styles.css
[Mon Jun 07 08:48:57 2004] [debug] mod_proxy.c(416): Trying to run 
scheme_handler
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(1042): proxy: HTTP: serving URL 
http://backend:7010/html/styles.css
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(178): proxy: HTTP connecting 
http://backend:7010/html/styles.css to backend:7010
[Mon Jun 07 08:48:57 2004] [debug] proxy_util.c(1160): proxy: HTTP: fam 2 
socket created to connect to backend
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(327): proxy: socket is connected
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(361): proxy: connection 
complete to backend:7010 (backend)
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(877): proxy: start body send
[Mon Jun 07 08:48:57 2004] [debug] mod_cache.c(532): cache: running CACHE_IN 
filter
[Mon Jun 07 08:48:57 2004] [debug] mod_cache.c(790): cache: Caching 
url: /html/styles.css
[Mon Jun 07 08:48:57 2004] [info] mem_cache: Cached url: 
centuri/html/styles.css?
[Mon Jun 07 08:48:57 2004] [debug] mod_headers.c(521): headers: 
ap_headers_output_filter()
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(936): proxy: end body send
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(877): proxy: start body send
[Mon Jun 07 08:48:57 2004] [debug] mod_headers.c(521): headers: 
ap_headers_output_filter()
[Mon Jun 07 08:48:57 2004] [debug] proxy_http.c(936): proxy: end body send


And the cache configuration:

            MCacheMaxObjectSize 10000
            MCacheSize          70000
            CacheEnable         mem /

            CacheRoot           /apache/cache
            CacheSize           150000
            CacheEnable         disk /
Comment 10 Bjorn Stabell 2004-07-27 04:00:50 UTC 
If this bug only affects you when you have both disk and mem cache enabled, I
say we should apply the patches above and make a new bug request for the
mem+disk cacheing bug.
Comment 11 Axel-Stephane Smorgrav 2004-07-28 14:19:06 UTC 
I agree. I'll create a new bug report. Should the status of the present be 
changed to FIXED?
Comment 12 Rüdiger Plüm 2004-08-18 11:56:47 UTC 
This may also fix 30278. So I mark 30278 dependent on this bug.
Comment 13 Axel-Stephane Smorgrav 2004-10-28 09:34:58 UTC 
I just tested Apache 2.0.52. It seems to me like this problem does not exist in 
that version.
Comment 14 Fr 2005-02-01 17:54:15 UTC 
Seems to still present in 2.0.52 on win32
Comment 15 Paul Querna 2005-06-03 03:25:20 UTC 
Can you test on 2.0.54?
Comment 16 Taisuke Yamada 2006-06-05 14:57:55 UTC 
I'm having similar issue with both 2.0.55 and SVN snapshot. It seems Apache 
fails to re-cache cachable content when mod_mem_cache is used (it doesn't 
happen with mod_cache + mod_disk_cache).

I have posted report of my investigation to 30370 (I didn't notice this report 
existed when I posted) - does it explain the issue? Though patch isn't 
available yet, I was able to fix the issue with the workaround I described in 
the posting.

- http://issues.apache.org/bugzilla/show_bug.cgi?id=30370
Comment 17 Terry Mueller 2007-07-24 18:53:40 UTC 
I recommend downloading 2.0.59 because older versions seem to be incomplete and 
not production-ready. 

If you a forced to run an older version of httpd then you can try compiling the 
2.0.59 source code and just using the mod_cache.so and mod_disk_cache.so files:

./configure --prefix=/tmp/httpd-2.0.59 --enable-cache=shared --enable-disk-
cache=shared --enable-mem-cache=shared 
make 
make install 

We are running 2.0.52 httpd with 2.0.59 mod_cache without any problems...
Comment 18 William A. Rowe Jr. 2018-11-07 21:08:50 UTC 
Please help us to refine our list of open and current defects; this is a mass update of old and inactive Bugzilla reports which reflect user error, already resolved defects, and still-existing defects in httpd.

As repeatedly announced, the Apache HTTP Server Project has discontinued all development and patch review of the 2.2.x series of releases. The final release 2.2.34 was published in July 2017, and no further evaluation of bug reports or security risks will be considered or published for 2.2.x releases. All reports older than 2.4.x have been updated to status RESOLVED/LATER; no further action is expected unless the report still applies to a current version of httpd.

If your report represented a question or confusion about how to use an httpd feature, an unexpected server behavior, problems building or installing httpd, or working with an external component (a third party module, browser etc.) we ask you to start by bringing your question to the User Support and Discussion mailing list, see [https://httpd.apache.org/lists.html#http-users] for details. Include a link to this Bugzilla report for completeness with your question.

If your report was clearly a defect in httpd or a feature request, we ask that you retest using a modern httpd release (2.4.33 or later) released in the past year. If it can be reproduced, please reopen this bug and change the Version field above to the httpd version you have reconfirmed with.

Your help in identifying defects or enhancements still applicable to the current httpd server software release is greatly appreciated.