Strange mod_cache & expires header interaction

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi httpd users,

I've been testing Apache httpd 2.2.4 as a reverse-caching proxy server but I've ran into some odd behavior with how its handling expired content. Currently I'm using the worker MPM and mod_mem_cache to provide the storage. I haven't tested this with prefork or mod_disk_cache yet, but if its worth it I can test that configuration too. Here are some entries from the error log with loglevel debug:

[Thu May 24 15:20:07 2007] [debug] mod_cache.c(129): Adding CACHE_SAVE filter for /cgi-bin/showarticle/ca/259
[Thu May 24 15:20:07 2007] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL filter for /cgi-bin/showarticle/ca/259
[Thu May 24 15:20:07 2007] [debug] mod_proxy_http.c(54): proxy: HTTP: canonicalising URL //staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:20:07 2007] [debug] proxy_util.c(1378): [client 198.144.205.143] proxy: http: found worker http://staging.greatschools.net/ for http://staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:20:07 2007] [debug] mod_proxy.c(777): Running scheme http handler (attempt 0)
[Thu May 24 15:20:07 2007] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving URL http://staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:20:07 2007] [debug] proxy_util.c(1798): proxy: HTTP: has acquired connection for (staging.greatschools.net)
[Thu May 24 15:20:07 2007] [debug] proxy_util.c(1859): proxy: connecting http://staging.greatschools.net/cgi-bin/showarticle/ca/259 to staging.greatschools.net:80
[Thu May 24 15:20:07 2007] [debug] proxy_util.c(1955): proxy: connected /cgi-bin/showarticle/ca/259 to staging.greatschools.net:80
[Thu May 24 15:20:07 2007] [debug] proxy_util.c(2050): proxy: HTTP: fam 2 socket created to connect to staging.greatschools.net
[Thu May 24 15:20:07 2007] [debug] proxy_util.c(2146): proxy: HTTP: connection complete to 198.144.205.147:80 (staging.greatschools.net)
[Thu May 24 15:20:07 2007] [debug] mod_proxy_http.c(1448): proxy: start body send
[Thu May 24 15:20:07 2007] [debug] mod_headers.c(663): headers: ap_headers_output_filter()
[Thu May 24 15:20:07 2007] [debug] mod_cache.c(609): cache: Caching url: /cgi-bin/showarticle/ca/259
[Thu May 24 15:20:07 2007] [debug] mod_cache.c(615): cache: Removing CACHE_REMOVE_URL filter.
[Thu May 24 15:20:07 2007] [info] mem_cache: Cached url: http://yahooed.nuked.greatschools.net:80/cgi-bin/showarticle/ca/259?
[Thu May 24 15:20:07 2007] [debug] mod_proxy_http.c(1537): proxy: end body send
[Thu May 24 15:20:07 2007] [debug] proxy_util.c(1816): proxy: HTTP: has released connection for (staging.greatschools.net)

When the server is first started, and content is requested from a client, it fetches the content from the backend server (staging.greatschools.net) and stores it in memory cache from mod_mem_cache.


[Thu May 24 15:20:10 2007] [debug] mod_cache.c(263): cache: running CACHE_OUT filter
[Thu May 24 15:20:10 2007] [debug] mod_cache.c(277): cache: serving /cgi-bin/showarticle/ca/259
[Thu May 24 15:20:10 2007] [debug] mod_cache.c(263): cache: running CACHE_OUT filter
[Thu May 24 15:20:10 2007] [debug] mod_cache.c(277): cache: serving /cgi-bin/showarticle/ca/259
[Thu May 24 15:20:11 2007] [debug] mod_cache.c(263): cache: running CACHE_OUT filter
[Thu May 24 15:20:11 2007] [debug] mod_cache.c(277): cache: serving /cgi-bin/showarticle/ca/259
[Thu May 24 15:20:11 2007] [debug] mod_cache.c(263): cache: running CACHE_OUT filter
[Thu May 24 15:20:11 2007] [debug] mod_cache.c(277): cache: serving /cgi-bin/showarticle/ca/259


Further requests are serviced directly from the cache, which is what I want.


[Thu May 24 15:33:50 2007] [debug] cache_storage.c(272): Cached response for /cgi-bin/showarticle/ca/259 isn't fresh.  Adding/replacing conditional request headers.
[Thu May 24 15:33:50 2007] [debug] mod_cache.c(129): Adding CACHE_SAVE filter for /cgi-bin/showarticle/ca/259
[Thu May 24 15:33:50 2007] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL filter for /cgi-bin/showarticle/ca/259
[Thu May 24 15:33:50 2007] [debug] mod_proxy_http.c(54): proxy: HTTP: canonicalising URL //staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:33:50 2007] [debug] proxy_util.c(1378): [client 198.144.205.143] proxy: http: found worker http://staging.greatschools.net/ for http://staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:33:50 2007] [debug] mod_proxy.c(777): Running scheme http handler (attempt 0)
[Thu May 24 15:33:50 2007] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving URL http://staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:33:50 2007] [debug] proxy_util.c(1798): proxy: HTTP: has acquired connection for (staging.greatschools.net)
[Thu May 24 15:33:50 2007] [debug] proxy_util.c(1859): proxy: connecting http://staging.greatschools.net/cgi-bin/showarticle/ca/259 to staging.greatschools.net:80
[Thu May 24 15:33:50 2007] [debug] proxy_util.c(1955): proxy: connected /cgi-bin/showarticle/ca/259 to staging.greatschools.net:80
[Thu May 24 15:33:50 2007] [debug] proxy_util.c(2050): proxy: HTTP: fam 2 socket created to connect to staging.greatschools.net
[Thu May 24 15:33:50 2007] [debug] proxy_util.c(2146): proxy: HTTP: connection complete to 198.144.205.147:80 (staging.greatschools.net)
[Thu May 24 15:33:50 2007] [debug] mod_proxy_http.c(1448): proxy: start body send
[Thu May 24 15:33:50 2007] [debug] mod_headers.c(663): headers: ap_headers_output_filter()
[Thu May 24 15:33:50 2007] [debug] mod_proxy_http.c(1537): proxy: end body send
[Thu May 24 15:33:50 2007] [debug] proxy_util.c(1816): proxy: HTTP: has released connection for (staging.greatschools.net)


The content, via the "Expires" header is set to expire in 10 minutes after the request. Apache httpd correctly notes that the content is expired and requests fresh content from the backend.


[Thu May 24 15:33:51 2007] [debug] cache_storage.c(272): Cached response for /cgi-bin/showarticle/ca/259 isn't fresh.  Adding/replacing conditional request headers.
[Thu May 24 15:33:51 2007] [debug] mod_cache.c(129): Adding CACHE_SAVE filter for /cgi-bin/showarticle/ca/259
[Thu May 24 15:33:51 2007] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL filter for /cgi-bin/showarticle/ca/259
[Thu May 24 15:33:51 2007] [debug] mod_proxy_http.c(54): proxy: HTTP: canonicalising URL //staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:33:51 2007] [debug] proxy_util.c(1378): [client 198.144.205.143] proxy: http: found worker http://staging.greatschools.net/ for http://staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:33:51 2007] [debug] mod_proxy.c(777): Running scheme http handler (attempt 0)
[Thu May 24 15:33:51 2007] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving URL http://staging.greatschools.net/cgi-bin/showarticle/ca/259
[Thu May 24 15:33:51 2007] [debug] proxy_util.c(1798): proxy: HTTP: has acquired connection for (staging.greatschools.net)
[Thu May 24 15:33:51 2007] [debug] proxy_util.c(1859): proxy: connecting http://staging.greatschools.net/cgi-bin/showarticle/ca/259 to staging.greatschools.net:80
[Thu May 24 15:33:51 2007] [debug] proxy_util.c(1955): proxy: connected /cgi-bin/showarticle/ca/259 to staging.greatschools.net:80
[Thu May 24 15:33:51 2007] [debug] proxy_util.c(2050): proxy: HTTP: fam 2 socket created to connect to staging.greatschools.net
[Thu May 24 15:33:51 2007] [debug] proxy_util.c(2146): proxy: HTTP: connection complete to 198.144.205.147:80 (staging.greatschools.net)
[Thu May 24 15:33:51 2007] [debug] mod_proxy_http.c(1448): proxy: start body send
[Thu May 24 15:33:51 2007] [debug] mod_headers.c(663): headers: ap_headers_output_filter()
[Thu May 24 15:33:51 2007] [debug] mod_proxy_http.c(1537): proxy: end body send
[Thu May 24 15:33:51 2007] [debug] proxy_util.c(1816): proxy: HTTP: has released connection for (staging.greatschools.net)


Here's where things get interesting. It appears the refreshed content is never re-stored in the storage. Every request after this point needs to contact the backend server to refresh the content until the server is restarted.

Here are the headers the script I'm trying to cache is outputting for reference:

HTTP/1.x 200 OK
Date: Thu, 24 May 2007 23:22:50 GMT
Server: Apache/1.3.37 (Unix) mod_perl/1.29 mod_ssl/2.8.28 OpenSSL/0.9.7e-p1 mod_jk/1.2.21
Expires: Thu, 24 May 2007 23:32:50 GMT
Cache-Control: public
P3P: policyref="http://dev.greatschools.net/w3c/p3p.xml";, CP="ALL DSP COR CUR DEVi PSA IVAi IVDi CONi OUR IND UNI", policyref="http://dev.greatschools.net/w3c/p3p.xml";, CP="ALL DSP COR CUR DEVi PSA IVAi IVDi CONi OUR IND UNI"
Content-Type: text/html; charset=ISO-8859-1
Vary: Accept-Encoding,User-Agent
Content-Encoding: gzip
Content-Length: 22468
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive


Note that the Content-Encoding gzip is actually from Apache 2.2.4 not the backend.

---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@xxxxxxxxxxxxxxxx
  "   from the digest: users-digest-unsubscribe@xxxxxxxxxxxxxxxx
For additional commands, e-mail: users-help@xxxxxxxxxxxxxxxx


[Index of Archives]     [Open SSH Users]     [Linux ACPI]     [Linux Kernel]     [Linux Laptop]     [Kernel Newbies]     [Security]     [Netfilter]     [Bugtraq]     [Squid]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Samba]     [Video 4 Linux]     [Device Mapper]

  Powered by Linux