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: [email protected] ReportedBy: [EMAIL PROTECTED] 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/[EMAIL PROTECTED] [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/[EMAIL PROTECTED] [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: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
