Bug 41516 - some url encoded urls cached but not retrieved
Summary: some url encoded urls cached but not retrieved
Status: RESOLVED DUPLICATE of bug 41475
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_cache (show other bugs)
Version: 2.2.4
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2007-02-01 09:40 UTC by Dean Scothern
Modified: 2007-02-01 12:47 UTC (History)
0 users


Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Dean Scothern 2007-02-01 09:40:10 UTC 
I've been trying to setup a surrogate cache using apache 2.2.4 and been having
problems caching certain urls even though they should be cacheable.

(Its a simple arrangement with apache reverse proxying directly to one server.
apache = 10.20.22.46, other web server = 10.20.22.101)

for example:
This works:
1) wget -S 'http://10.20.22.46/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx'

[Thu Feb 01 17:24:28 2007] [debug] cache_storage.c(431): cache_storage: generate
key /~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:24:28 2007] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:24:28 2007] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:24:28 2007] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //10.20.22.101/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:24:28 2007] [debug] proxy_util.c(1378): [client 192.168.33.220]
proxy: http: found worker http://10.20.22.101/ for
http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:24:28 2007] [debug] mod_proxy.c(777): Running scheme http handler
(attempt 0)
[Thu Feb 01 17:24:28 2007] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:24:28 2007] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (10.20.22.101)
[Thu Feb 01 17:24:28 2007] [debug] proxy_util.c(1859): proxy: connecting
http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx to
10.20.22.101:80
[Thu Feb 01 17:24:28 2007] [debug] proxy_util.c(1955): proxy: connected
/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx to 10.20.22.101:80
[Thu Feb 01 17:24:28 2007] [debug] proxy_util.c(2050): proxy: HTTP: fam 2 socket
created to connect to 10.20.22.101
[Thu Feb 01 17:24:28 2007] [debug] proxy_util.c(2146): proxy: HTTP: connection
complete to 10.20.22.101:80 (10.20.22.101)
[Thu Feb 01 17:24:28 2007] [debug] mod_proxy_http.c(1448): proxy: start body send
[Thu Feb 01 17:24:28 2007] [debug] mod_headers.c(663): headers:
ap_headers_output_filter()
[Thu Feb 01 17:24:28 2007] [debug] cache_storage.c(431): cache_storage: generate
key /~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:24:28 2007] [debug] mod_cache.c(609): cache: Caching url:
/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:24:28 2007] [debug] mod_cache.c(615): cache: Removing
CACHE_REMOVE_URL filter.
[Thu Feb 01 17:24:28 2007] [debug] mod_disk_cache.c(954): disk_cache: Stored
headers for URL http://10.20.22.46:80/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx?
[Thu Feb 01 17:24:28 2007] [debug] mod_disk_cache.c(1043): disk_cache: Body for
URL http://10.20.22.46:80/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx? cached.
[Thu Feb 01 17:24:28 2007] [debug] mod_proxy_http.c(1537): proxy: end body send
[Thu Feb 01 17:24:28 2007] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (10.20.22.101)

and the second get:
[Thu Feb 01 17:25:23 2007] [debug] cache_storage.c(431): cache_storage: generate
key /~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:25:23 2007] [debug] mod_disk_cache.c(477): disk_cache: Recalled
cached URL info header
http://10.20.22.46:80/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx?
[Thu Feb 01 17:25:23 2007] [debug] mod_disk_cache.c(750): disk_cache: Recalled
headers for URL http://10.20.22.46:80/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx?
[Thu Feb 01 17:25:23 2007] [debug] mod_headers.c(663): headers:
ap_headers_output_filter()
[Thu Feb 01 17:25:23 2007] [debug] mod_cache.c(263): cache: running CACHE_OUT filter
[Thu Feb 01 17:25:23 2007] [debug] mod_cache.c(277): cache: serving
/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx

All well and good (I've added a extra debug line to show the key generated at
the end of cache-storage.c)

Unfortunately if the url is url encoded I get the following:

wget -S 'http://10.20.22.46/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx'


[Thu Feb 01 17:27:49 2007] [debug] cache_storage.c(431): cache_storage: generate
key /%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:27:49 2007] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:27:49 2007] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:27:49 2007] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //10.20.22.101/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:27:49 2007] [debug] proxy_util.c(1378): [client 192.168.33.220]
proxy: http: found worker http://10.20.22.101/ for
http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:27:49 2007] [debug] mod_proxy.c(777): Running scheme http handler
(attempt 0)
[Thu Feb 01 17:27:49 2007] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:27:49 2007] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (10.20.22.101)
[Thu Feb 01 17:27:49 2007] [debug] proxy_util.c(1859): proxy: connecting
http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx to
10.20.22.101:80
[Thu Feb 01 17:27:49 2007] [debug] proxy_util.c(1955): proxy: connected
/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx to 10.20.22.101:80
[Thu Feb 01 17:27:49 2007] [debug] proxy_util.c(2050): proxy: HTTP: fam 2 socket
created to connect to 10.20.22.101
[Thu Feb 01 17:27:49 2007] [debug] proxy_util.c(2146): proxy: HTTP: connection
complete to 10.20.22.101:80 (10.20.22.101)
[Thu Feb 01 17:27:49 2007] [debug] mod_proxy_http.c(1448): proxy: start body send
[Thu Feb 01 17:27:49 2007] [debug] mod_headers.c(663): headers:
ap_headers_output_filter()
[Thu Feb 01 17:27:49 2007] [debug] cache_storage.c(431): cache_storage: generate
key /~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:27:49 2007] [debug] mod_cache.c(609): cache: Caching url:
/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:27:49 2007] [debug] mod_cache.c(615): cache: Removing
CACHE_REMOVE_URL filter.
[Thu Feb 01 17:27:49 2007] [debug] mod_disk_cache.c(954): disk_cache: Stored
headers for URL http://10.20.22.46:80/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx?
[Thu Feb 01 17:27:49 2007] [debug] mod_disk_cache.c(1043): disk_cache: Body for
URL http://10.20.22.46:80/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx? cached.
[Thu Feb 01 17:27:49 2007] [debug] mod_proxy_http.c(1537): proxy: end body send
[Thu Feb 01 17:27:49 2007] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (10.20.22.101)

and the second time:
[Thu Feb 01 17:29:05 2007] [debug] cache_storage.c(431): cache_storage: generate
key /%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:29:05 2007] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:29:05 2007] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:29:05 2007] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //10.20.22.101/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:29:05 2007] [debug] proxy_util.c(1378): [client 192.168.33.220]
proxy: http: found worker http://10.20.22.101/ for
http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:29:05 2007] [debug] mod_proxy.c(777): Running scheme http handler
(attempt 0)
[Thu Feb 01 17:29:05 2007] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:29:05 2007] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (10.20.22.101)
[Thu Feb 01 17:29:05 2007] [debug] proxy_util.c(1859): proxy: connecting
http://10.20.22.101/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx to
10.20.22.101:80
[Thu Feb 01 17:29:05 2007] [debug] proxy_util.c(1955): proxy: connected
/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx to 10.20.22.101:80
[Thu Feb 01 17:29:05 2007] [debug] proxy_util.c(2050): proxy: HTTP: fam 2 socket
created to connect to 10.20.22.101
[Thu Feb 01 17:29:05 2007] [debug] proxy_util.c(2146): proxy: HTTP: connection
complete to 10.20.22.101:80 (10.20.22.101)
[Thu Feb 01 17:29:05 2007] [debug] mod_proxy_http.c(1448): proxy: start body send
[Thu Feb 01 17:29:05 2007] [debug] mod_headers.c(663): headers:
ap_headers_output_filter()
[Thu Feb 01 17:29:05 2007] [debug] cache_storage.c(431): cache_storage: generate
key /~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:29:05 2007] [debug] mod_cache.c(609): cache: Caching url:
/%7E/media/2B89E73DB97041B1A48D64BBE2126D10.ashx
[Thu Feb 01 17:29:05 2007] [debug] mod_cache.c(615): cache: Removing
CACHE_REMOVE_URL filter.
[Thu Feb 01 17:29:05 2007] [debug] mod_disk_cache.c(954): disk_cache: Stored
headers for URL http://10.20.22.46:80/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx?
[Thu Feb 01 17:29:05 2007] [debug] mod_disk_cache.c(1043): disk_cache: Body for
URL http://10.20.22.46:80/~/media/2B89E73DB97041B1A48D64BBE2126D10.ashx? cached.
[Thu Feb 01 17:29:05 2007] [debug] mod_proxy_http.c(1537): proxy: end body send
[Thu Feb 01 17:29:05 2007] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (10.20.22.101)

And the url is not delivered from the cache. It appears to be that the url used
for comparison has been converted back to the non encoded type, but I got
rapidly lost whilst trying to trace the logic. My C skills are very rusty.

I'll be happy to supply more data and check any suggested fix.

Best Regards
Comment 1 Ruediger Pluem 2007-02-01 12:47:38 UTC 

*** This bug has been marked as a duplicate of 41475 ***