httpd-bugs mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bugzi...@apache.org
Subject DO NOT REPLY [Bug 39593] New: - mod_cache always misses mod_proxy_http files over SSL
Date Tue, 16 May 2006 21:08:55 GMT
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=39593>.
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=39593

           Summary: mod_cache always misses mod_proxy_http files over SSL
           Product: Apache httpd-2
           Version: 2.2.2
          Platform: PC
        OS/Version: Linux
            Status: NEW
          Severity: normal
          Priority: P2
         Component: mod_cache
        AssignedTo: bugs@httpd.apache.org
        ReportedBy: mhan@postini.com


I have Apache 2.2.2 with mod_ssl, mod_proxy (and mod_proxy_http) and mod_cache
(both mem & disk) on a RedHat EL4 U3 box. I have SSL termination enabled on my
_default_:443 vhost and proxypass to HTTP on a backend Apache server. Files
retrieved from the proxy endpoint are 100% cache miss in mod_cache. Relevant
vhost configuration stanza looks like:

SSLProxyEngine On
ProxyRequests Off
ProxyPass /s5/ http://rcdev1ws14/
CacheEnable disk /
CacheEnable disk http://rcdev1ws14/
CacheEnable mem /
CacheEnable mem http://rcdev1ws14/
CacheRoot /var/run/httpd/cache
CacheDirLength 1
CacheDirLevels 1
MCacheSize 20480
# The following are me getting increasingly desparate to make mod_cache hit
CacheIgnoreCacheControl On
CacheStorePrivate On
CacheStoreNoStore On
CacheIgnoreHeaders User-Agent Accept Max-Forwards X-Forwarded-For
X-Forwarded-Host X-Forwarded-Server Cookie Vary

What's interesting is that the same configuration directives on my _default_:80
vhost works properly. The cache hits.

I added additional debugging statements to mod_cache (inline diff included
below). Requesting the same file twice in a row, I grabbed the debug logs and
have included them below (removed ssl_engine_io and ssl_engine_shmcb class
messages, as they appear to be useless for current purposes). Notice that URL
canonicalisation is occurring AFTER mod_disk_cache attempts to look up the file
in cache, but then stores the file using a key generated from the canonicalised
URL. Clearly this must be the problem's root cause. I'm unclear about what needs
to be changed, though.

<<EndOfLogOutput
[Tue May 16 14:07:20 2006] [info] [client 172.16.0.44] Connection to child 2
established (server rcdev1ws18:443)
[Tue May 16 14:07:20 2006] [info] Seeding PRNG with 648 bytes of entropy
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1752): OpenSSL:
Handshake: start
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
before/accept initialization
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 read client hello A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write server hello A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write certificate A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write server done A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 flush data
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 read client key exchange A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 read finished A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write change cipher spec A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write finished A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 flush data
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1598): Inter-Process
Session Cache: request=SET status=OK
id=150FA988C7DB59F6F35666ECF91FD055478CC00399AEA87E4E6E803D8A275A10 timeout=300s
(session caching)
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1756): OpenSSL:
Handshake: done
[Tue May 16 14:07:20 2006] [info] Connection: Client IP: 172.16.0.44, Protocol:
TLSv1, Cipher: RC4-SHA (128/128 bits)
[Tue May 16 14:07:20 2006] [info] Initial (No.1) HTTPS request received for
child 2 (server rcdev1ws18:443)
[Tue May 16 14:07:20 2006] [error] disk_cache: Failed to open file
/var/run/httpd/cache/b/DgKJmDvOggzqD69@NEvzQ.header.
[Tue May 16 14:07:20 2006] [debug] cache_storage.c(311): cache_select(): Decline
to serve from provider (null).
[Tue May 16 14:07:20 2006] [debug] cache_storage.c(311): cache_select(): Decline
to serve from provider (null).
[Tue May 16 14:07:20 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /s5/images/login.gif
[Tue May 16 14:07:20 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /s5/images/login.gif
[Tue May 16 14:07:20 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //rcdev1ws14/images/login.gif
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1378): [client 172.16.0.44]
proxy: http: found worker http://rcdev1ws14/ for http://rcdev1ws14/images/login.gif
[Tue May 16 14:07:20 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Tue May 16 14:07:20 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://rcdev1ws14/images/login.gif
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (rcdev1ws14)
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1858): proxy: connecting
http://rcdev1ws14/images/login.gif to rcdev1ws14:80
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1951): proxy: connected
/images/login.gif to rcdev1ws14:80
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 172.16.100.164:80 (rcdev1ws14)
[Tue May 16 14:07:20 2006] [debug] mod_proxy_http.c(1448): proxy: start body send
[Tue May 16 14:07:20 2006] [debug] mod_cache.c(602): cache: Caching url:
/s5/images/login.gif
[Tue May 16 14:07:20 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Tue May 16 14:07:20 2006] [debug] mod_disk_cache.c(959): disk_cache: Stored
headers for URL http://rcdev1ws18:80/s5/images/login.gif?
[Tue May 16 14:07:20 2006] [debug] mod_disk_cache.c(1048): disk_cache: Body for
URL http://rcdev1ws18:80/s5/images/login.gif? cached.
[Tue May 16 14:07:20 2006] [debug] mod_proxy_http.c(1537): proxy: end body send
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (rcdev1ws14)
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1770): OpenSSL: Write:
SSL negotiation finished successfully
[Tue May 16 14:07:20 2006] [info] [client 172.16.0.44] Connection closed to
child 2 with standard shutdown (server rcdev1ws18:443)
[Tue May 16 14:07:20 2006] [info] [client 172.16.0.44] Connection to child 4
established (server rcdev1ws18:443)
[Tue May 16 14:07:20 2006] [info] Seeding PRNG with 648 bytes of entropy
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1752): OpenSSL:
Handshake: start
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
before/accept initialization
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 read client hello A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write server hello A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write certificate A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write server done A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 flush data
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 read client key exchange A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 read finished A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write change cipher spec A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 write finished A
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop:
SSLv3 flush data
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1598): Inter-Process
Session Cache: request=SET status=OK
id=E086C9A9C157DF5AC6383786D1E5D270DA92C697B085ACBE65F239390CED592E timeout=300s
(session caching)
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1756): OpenSSL:
Handshake: done
[Tue May 16 14:07:20 2006] [info] Connection: Client IP: 172.16.0.44, Protocol:
TLSv1, Cipher: RC4-SHA (128/128 bits)
[Tue May 16 14:07:20 2006] [info] Initial (No.1) HTTPS request received for
child 4 (server rcdev1ws18:443)
[Tue May 16 14:07:20 2006] [error] disk_cache: Failed to open file
/var/run/httpd/cache/b/DgKJmDvOggzqD69@NEvzQ.header.
[Tue May 16 14:07:20 2006] [debug] cache_storage.c(311): cache_select(): Decline
to serve from provider (null).
[Tue May 16 14:07:20 2006] [debug] cache_storage.c(311): cache_select(): Decline
to serve from provider (null).
[Tue May 16 14:07:20 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /s5/images/login.gif
[Tue May 16 14:07:20 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /s5/images/login.gif
[Tue May 16 14:07:20 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //rcdev1ws14/images/login.gif
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1378): [client 172.16.0.44]
proxy: http: found worker http://rcdev1ws14/ for http://rcdev1ws14/images/login.gif
[Tue May 16 14:07:20 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Tue May 16 14:07:20 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://rcdev1ws14/images/login.gif
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (rcdev1ws14)
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1858): proxy: connecting
http://rcdev1ws14/images/login.gif to rcdev1ws14:80
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1951): proxy: connected
/images/login.gif to rcdev1ws14:80
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 172.16.100.164:80 (rcdev1ws14)
[Tue May 16 14:07:20 2006] [debug] mod_proxy_http.c(1448): proxy: start body send
[Tue May 16 14:07:20 2006] [debug] mod_cache.c(602): cache: Caching url:
/s5/images/login.gif
[Tue May 16 14:07:20 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Tue May 16 14:07:20 2006] [debug] mod_disk_cache.c(959): disk_cache: Stored
headers for URL http://rcdev1ws18:80/s5/images/login.gif?
[Tue May 16 14:07:20 2006] [debug] mod_disk_cache.c(1048): disk_cache: Body for
URL http://rcdev1ws18:80/s5/images/login.gif? cached.
[Tue May 16 14:07:20 2006] [debug] mod_proxy_http.c(1537): proxy: end body send
[Tue May 16 14:07:20 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (rcdev1ws14)
[Tue May 16 14:07:20 2006] [debug] ssl_engine_kernel.c(1770): OpenSSL: Write:
SSL negotiation finished successfully
[Tue May 16 14:07:20 2006] [info] [client 172.16.0.44] Connection closed to
child 4 with standard shutdown (server rcdev1ws18:443)
EndOfLogOutput

--- mod_disk_cache.c 2006-04-21 18:53:06.000000000 -0700
+++ mod_disk_cache.c.new        2006-05-16 13:32:12.000000000 -0700
@@ -389,6 +389,7 @@
     flags = APR_READ|APR_BINARY|APR_BUFFERED;
     rc = apr_file_open(&dobj->hfd, dobj->hdrsfile, flags, 0, r->pool);
     if (rc != APR_SUCCESS) {
+        ap_log_error(APLOG_MARK, APLOG_ERR, 0, r->server, "disk_cache: Failed t
o open file %s.", dobj->hdrsfile);
         return DECLINED;
     }   

@@ -404,6 +405,7 @@
         apr_file_read_full(dobj->hfd, &expire, len, &len);

         if (expire < r->request_time) {
+            ap_log_error(APLOG_MARK, APLOG_ERR, 0, r->server, "disk_cache: File
 %s in cache has expired.", dobj->hdrsfile);
             return DECLINED;
         }   

@@ -426,6 +428,7 @@
         flags = APR_READ|APR_BINARY|APR_BUFFERED;
         rc = apr_file_open(&dobj->hfd, dobj->hdrsfile, flags, 0, r->pool);
         if (rc != APR_SUCCESS) {
+            ap_log_error(APLOG_MARK, APLOG_ERR, 0, r->server, "disk_cache: Fail
ed to open file %s.", dobj->hdrsfile);
             return DECLINED;
         }   
     }   
@@ -457,6 +460,7 @@
 #endif
     rc = apr_file_open(&dobj->fd, dobj->datafile, flags, 0, r->pool);
     if (rc != APR_SUCCESS) {
+        ap_log_error(APLOG_MARK, APLOG_ERR, 0, r->server, "disk_cache: Failed
to open file %s.", dobj->datafile);
         /* XXX: Log message */
         return DECLINED;
     }
@@ -470,6 +474,7 @@
     rc = file_cache_recall_mydata(dobj->hfd, info, dobj, r);
     if (rc != APR_SUCCESS) {
         /* XXX log message */
+        ap_log_error(APLOG_MARK, APLOG_ERR, 0, r->server, "disk_cache: Failed
to retrieve file %s bytes.", dobj->hdrsfile);
         return DECLINED;
     }

--- cache_storage.c  2006-04-21 18:53:06.000000000 -0700
+++ cache_storage.c.new 2006-05-16 13:32:28.000000000 -0700
@@ -195,6 +195,9 @@
             
             if (list->provider->recall_headers(h, r) != APR_SUCCESS) {
                 /* TODO: Handle this error */
+                ap_log_error(APLOG_MARK, APLOG_DEBUG, APR_SUCCESS,
+                             r->server,
+                             "cache_select(): Failed to recall_headers for
provider %s.", list->provider_name);
                 return DECLINED;
             }

@@ -305,6 +308,9 @@
         }
         case DECLINED: {
             /* try again with next cache type */
+            ap_log_error(APLOG_MARK, APLOG_DEBUG, APR_SUCCESS, r->server,
+                  "cache_select(): Decline to serve from provider %s.",
+                  cache->provider_name);
             list = list->next;
             continue;
         }

-- 
Configure bugmail: http://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


Mime
View raw message