DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT <http://issues.apache.org/bugzilla/show_bug.cgi?id=30419>. ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND INSERTED IN THE BUG DATABASE.
http://issues.apache.org/bugzilla/show_bug.cgi?id=30419 Weird caching behaviour of mod_cache and old Cookies Summary: Weird caching behaviour of mod_cache and old Cookies Product: Apache httpd-2.0 Version: 2.0.50 Platform: All OS/Version: All Status: NEW Severity: Normal Priority: Other Component: mod_cache AssignedTo: [email protected] ReportedBy: [EMAIL PROTECTED] Hi, I found some weird behaviour in mod_cache which I believe to be a bug. First of all my environment: I. Environment Apache: 2.0.50 OS: Linux Excerpt from my Apache configuration: <VirtualHost 192.168.2.4:80> ServerName www.something.de ServerAdmin [EMAIL PROTECTED] DocumentRoot "/var/httpd/test/www.something.de/docs" ErrorLog "|/opt/apache-2.0.50/bin/rotatelogs /var/httpd/test/www.something.de/lo gs/error_log 86400" CustomLog "|/opt/apache-2.0.50/bin/rotatelogs /var/httpd/test/www.something.de/l ogs/access_log 86400" combined <Directory /var/httpd/test/www.something.de/docs> Options None AllowOverride None </Directory> JkMount /* worker_ajp13 CacheRoot /var/httpd/test/cache CacheSize 256 CacheEnable disk /test CacheDirLevels 5 CacheDirLength 3 CacheMaxExpire 60 CacheIgnoreNoLastMod On CacheIgnoreCacheControl On CacheDefaultExpire 60 </VirtualHost> II. Problem description I try to use mod_cache to cache pages generated by Tomcat and delivered via Apache / mod_jk. On the Tomcat / mod_jk side I use: mod_jk: 1.2.5 Tomcat: 5.0.18 At first glance the configuration above does exactly what I want by caching the Tomcat generated response, but I noticed the following two weird behaviours: 1. If a cached document is outdated because it is expired, it will be requested again from Tomcat, which is completely correct. But this response contains two Set-Cookie headers, one from the cached headers (cross checked by a look to the .headers file) and one generated by the actual Tomcat request. The following excerpt from Mozilla's livehttpheaders shows this: http://192.168.2.4/test/test.jsp GET /test/test.jsp HTTP/1.1 Host: 192.168.2.4 User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.7) Gecko/20040616 Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plai n;q=0.8,image/png,*/*;q=0.5 Accept-Language: de,en;q=0.8,de-de;q=0.5,en-gb;q=0.3 Accept-Encoding: gzip,deflate Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 Keep-Alive: 300 Connection: keep-alive HTTP/1.x 200 OK Date: Fri, 30 Jul 2004 07:25:52 GMT Server: Apache/2.0.50 (Unix) mod_ssl/2.0.50 OpenSSL/0.9.6g DAV/2 mod_jk/1.2.5 Set-Cookie: JSESSIONID=39F12D5B8854DB7ED167B66506D2345A; Path=/test Set-Cookie: JSESSIONID=CA4640A1745F53FC27A07F3EA6362286; Path=/test Content-Length: 74 Content-Type: text/html; charset=ISO-8859-1 Keep-Alive: timeout=15, max=99 Connection: Keep-Alive It is worth to note that the first Set-Cookie header is the one from the previously cached headers and that the second Set-Cookie header is the one generated by the actual Tomcat request. It can be found alone in the updated .headers file after the request has been completed. 2. If the next request after 1. to the same URL is a request that would allow mod_cache to retrieve the cached document because - It contains no Cache-Control header - and the request is placed shortly after 1. such that the document is not expired already mod_cache decides that the cached version of the document is not fresh and has to be retrived again from Tomcat. Only the next request to this URL works correctly and delivers the cached version of this document. III. Problem analysis So I set the Loglevel to debug and added the following temporary patch to cache_util.c to get a better picture of what is going on: --- httpd-2.0.50/modules/experimental/cache_util.c.orig 2004-02-09 21:53:16.0000 00000 +0100 +++ httpd-2.0.50/modules/experimental/cache_util.c 2004-07-30 12:27:39.0000 00000 +0200 @@ -242,6 +242,18 @@ "proxy-revalidate", NULL)))) { maxstale = 0; } + { + + apr_int64_t zw,zw1; + + zw = apr_time_sec(info->expire - info->date); + zw1 = apr_time_sec(info->response_time - info->request_time); + +ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + "cache_util: age %lli, maxstale %lli, minfresh %lli, expir e %lli, date %lli, maxage %lli, zw %lli, smaxage %lli, response %lli, request %l li, zw1 %lli", + age,maxstale,minfresh,info->expire,info->date,maxage,zw,sm axage,info->response_time,info->request_time,zw1); + } + /* handle expiration */ if (((smaxage != -1) && (age < (smaxage - minfresh))) || This produced the following logging output: [Fri Jul 30 12:38:34 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(121): incoming request is asking for a uncached version of /test/test.jsp, but we know better and are ignoring it [Fri Jul 30 12:38:34 2004] [info] disk_cache: Serving Cached URL 192.168.2.4/tes t/test.jsp? [Fri Jul 30 12:38:34 2004] [info] disk_cache: Served headers for URL 192.168.2.4 /test/test.jsp? [Fri Jul 30 12:38:34 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/cache_util.c(252): cache_util: age 111, maxstale 0, minfresh 0, expire 1091183863743217, date 1091183803743217, maxage -1, zw 60, smaxage -1, response 1091183803743217, request 1091183803740783, zw1 0 [Fri Jul 30 12:38:34 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(218): cache: stale cache - test condi tional [Fri Jul 30 12:38:34 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(265): cache: nonconditional - no cach ed etag/lastmods - add cache_in and DECLINE [Fri Jul 30 12:38:34 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(406): cache: running CACHE_IN filter [Fri Jul 30 12:38:34 2004] [info] disk_cache: Caching URL 192.168.2.4/test/test. jsp? [Fri Jul 30 12:38:34 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(663): cache: Caching url: /test/test. jsp [Fri Jul 30 12:38:34 2004] [info] disk_cache: Caching headers for URL 192.168.2. 4/test/test.jsp? [Fri Jul 30 12:38:34 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(406): cache: running CACHE_IN filter [Fri Jul 30 12:38:34 2004] [info] disk_cache: Cached body for URL 192.168.2.4/te st/test.jsp? [Fri Jul 30 12:44:07 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(121): incoming request is asking for a uncached version of /test/test.jsp, but we know better and are ignoring it [Fri Jul 30 12:44:07 2004] [info] disk_cache: Serving Cached URL 192.168.2.4/tes t/test.jsp? [Fri Jul 30 12:44:07 2004] [info] disk_cache: Served headers for URL 192.168.2.4 /test/test.jsp? [Fri Jul 30 12:44:07 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/cache_util.c(252): cache_util: age 444, maxstale 0, minfresh 0, expire 1091183863000000, date 1091183803000000, maxage -1, zw 60, smaxage -1, response 1091183914921396, request 1091183914918844, zw1 0 [Fri Jul 30 12:44:07 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(218): cache: stale cache - test condi tional [Fri Jul 30 12:44:07 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(265): cache: nonconditional - no cach ed etag/lastmods - add cache_in and DECLINE [Fri Jul 30 12:44:07 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(406): cache: running CACHE_IN filter [Fri Jul 30 12:44:07 2004] [info] disk_cache: Caching URL 192.168.2.4/test/test. jsp? [Fri Jul 30 12:44:07 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(663): cache: Caching url: /test/test. jsp [Fri Jul 30 12:44:07 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(705): cache: Added date header [Fri Jul 30 12:44:07 2004] [info] disk_cache: Caching headers for URL 192.168.2. 4/test/test.jsp? [Fri Jul 30 12:44:07 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(406): cache: running CACHE_IN filter [Fri Jul 30 12:44:07 2004] [info] disk_cache: Cached body for URL 192.168.2.4/te st/test.jsp? [Fri Jul 30 12:44:10 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(121): incoming request is asking for a uncached version of /test/test.jsp, but we know better and are ignoring it [Fri Jul 30 12:44:10 2004] [info] disk_cache: Serving Cached URL 192.168.2.4/tes t/test.jsp? [Fri Jul 30 12:44:10 2004] [info] disk_cache: Served headers for URL 192.168.2.4 /test/test.jsp? [Fri Jul 30 12:44:10 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/cache_util.c(252): cache_util: age 3, maxstale 0, minfresh 0, expire 1091184307843266, date 1091184247843266, maxage -1, zw 60, s maxage -1, response 1091184247843266, request 1091184247840880, zw1 0 [Fri Jul 30 12:44:10 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(186): cache: fresh cache - add cache_ out filter and handle request [Fri Jul 30 12:44:10 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(323): cache: running CACHE_OUT filter [Fri Jul 30 12:44:10 2004] [debug] /usr/src/packages/BUILD/apache_aol-2.0.50/htt pd-2.0.50/modules/experimental/mod_cache.c(332): cache: serving /test/test.jsp It is notable that the values for expire / date of the 12:44:07 request are the values of the 12:38:34 request with their microseconds part striped off. This is wrong as the 12:38:34 request should have updated expire / date in the .headers file with the values actual during the 12:38:34 request and not set the values to the striped values of the cache entry expired at 12:38:34. One may also notice that the 12:44:07 request reports cache: Added date header whereas the 12:38:34 request does nothing of this kind. It is also notable that the .headers file does not contain a Date: header after the 12:38:34 request, but it does after the 12:44:07 request. IV. Conclusion To cut a long story short: I believe that 1. and 2. are caused by the same problem: The function cache_select_url called in line 152 of mod_cache.c already fills r->err_headers_out with the cached headers. If ap_cache_check_freshness called in line 167 detects that the cache object has expired this data is kept in r->err_headers_out during the further processing. This leads to the reusing of the old date in line 681 of mod_cache.c and explains the removal of the microseconds part which is done in line 689. During the further processing of the CACHE_IN filter at least mod_disk_cache only stores r->headers_out in the .headers file which explains why the Date header is missing in the .headers file after the 12:38:34 request. Furthermore r->err_headers_out and r->headers_out get merged later on where r->err_headers_out distributes the old (previously cached) Set-Cookie header and r->headers_out distributes the new Tomcat generated Set-Cookie header to the reponse. V. Solution proposal >From my limited view into Apache I cannot see a reason why the data in r->err_headers_out / r->headers_out should be used any longer if ap_cache_check_freshness detected that the cache object has expired. So I propose the following patch to mod_cache.c which clears the tables r->err_headers_out / r->headers_out: --- httpd-2.0.50/modules/experimental/mod_cache.c.orig 2004-02-09 21:53:16.0000 00000 +0100 +++ httpd-2.0.50/modules/experimental/mod_cache.c 2004-07-30 13:16:26.0000 00000 +0200 @@ -207,9 +207,13 @@ return OK; } else { + apr_table_clear(r->headers_out); if (!r->err_headers_out) { r->err_headers_out = apr_table_make(r->pool, 3); } + else { + apr_table_clear(r->err_headers_out); + } /* stale data available */ if (lookup) { return DECLINED; Applying this patch worked for me. Of course I do not know if it breaks something else as I did only limited testing. If it turns out that it is incorrect to clear the tables r->err_headers_out / r->headers_out then at least all "irrelevant data" (however this gets defined) that got added by cache_select_url must be removed after ap_cache_check_freshness detected that the cache object has expired. From my experience this should be at least the Set-Cookie and the Date headers. Depending on how "irrelevant data" gets defined this makes a solution and thus a patch more complex. Regards Rüdiger Plüm --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
