Bug 39647 - mod_cache sets incorrect Content-type headers for cached context with backend httpd 1.3.33 and mod_jk 1.2.15
Summary: mod_cache sets incorrect Content-type headers for cached context with backend...
Status: RESOLVED FIXED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_cache (show other bugs)
Version: 2.2.2
Hardware: Other FreeBSD
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2006-05-23 20:31 UTC by Christopher Shumway
Modified: 2007-02-09 21:36 UTC (History)
0 users



Attachments
Patch for additional Debug messages against 2.2.x (2.52 KB, patch)
2006-05-26 08:54 UTC, Ruediger Pluem
Details | Diff
Patch against trunk (1.02 KB, patch)
2006-05-26 22:49 UTC, Ruediger Pluem
Details | Diff
Patch against mod_jk.c (1.3 Version) of mod_jk 1.2.15 (911 bytes, patch)
2006-05-26 22:59 UTC, Ruediger Pluem
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Christopher Shumway 2006-05-23 20:31:27 UTC
This is similar, but does not appear to be the same as bug 39266.  I've applied
the patch to mod_mem_cache.c and it makes no diffrence.  It also does not matter
if the storage for mod_cache is disk or memory cache.

Here's the configuration:  Frontend reverse caching proxy server running httpd
2.2.2, prefork mpm.  The backend web server is httpd 1.3.36 with mod_jk 1.2.15.
 Mod_jk connects to Tomcat 5.0.30 via an ajp 1.3 connector. The namespace /res/*
is mounted into Tomcat via mod_jk's JKMount directive.

The first time content is accessed via the front end proxy, it sends the
approperate content-type header, e.g. 'image/jpeg'.  Further attempts to get the
same image usually return a content-type header of 'text/html'.

Here's the correct headers from the client and server:

GET /res/img/content/liferaft.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: TRNO=1127250133.198.144.205.133; NumAd=-1;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE];
fcP=C=133&T=1137020088512&V=1137020102487;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
RMFD=011FiFmA; RMID=c690cd854329f1d0; T3CK=TANT%3D1%7CTANO%3D0; s_cc=true;
s_sq=%5B%5BB%5D%5D; JSESSIONID=8870E2C3BE344A492CCC1DCCDE4036AC; PATHWAY=3
Pragma: no-cache
Cache-Control: no-cache

HTTP/1.x 200 OK
Date: Tue, 23 May 2006 20:22:31 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
Etag: W/"26797-1148335021000"
Content-Length: 26797
Expires: Wed, 24 May 2006 00:22:31 GMT
Content-Type: image/jpeg
Last-Modified: Mon, 22 May 2006 21:57:01 GMT
Keep-Alive: timeout=5, max=99
Connection: Keep-Alive

The next time the image is requested, the server returns the context-type as
'text/html', which causes the browser to try to render the image as if it where
html.

GET /res/img/content/liferaft.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: TRNO=1127250133.198.144.205.133; NumAd=-1;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE];
fcP=C=133&T=1137020088512&V=1137020102487;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
RMFD=011FiFmA; RMID=c690cd854329f1d0; T3CK=TANT%3D1%7CTANO%3D0; s_cc=true;
s_sq=%5B%5BB%5D%5D; JSESSIONID=8870E2C3BE344A492CCC1DCCDE4036AC; PATHWAY=3
Pragma: no-cache
Cache-Control: no-cache

HTTP/1.x 200 OK
Date: Tue, 23 May 2006 20:22:32 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
Etag: W/"26797-1148335021000"
Content-Length: 26797
Expires: Wed, 24 May 2006 00:22:32 GMT
Content-Type: text/html
Last-Modified: Mon, 22 May 2006 21:57:01 GMT
Keep-Alive: timeout=5, max=98
Connection: Keep-Alive

Here's another data point:  If the browser requests content that is not being
served by mod_jk, then it will work correctly every time.  For example, if the
browser requests images/reportcard.jpg, which is being served directly by the
backend web server, it will always send a content type of image/jpeg.

GET /images/reportcard.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: TRNO=1127250133.198.144.205.133; NumAd=-1;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE];
fcP=C=133&T=1137020088512&V=1137020102487;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
RMFD=011FiFmA; RMID=c690cd854329f1d0; T3CK=TANT%3D1%7CTANO%3D0; s_cc=true;
s_sq=%5B%5BB%5D%5D; JSESSIONID=8870E2C3BE344A492CCC1DCCDE4036AC; PATHWAY=3
Pragma: no-cache
Cache-Control: no-cache

HTTP/1.x 200 OK
Date: Tue, 23 May 2006 20:30:24 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
Cache-Control: max-age=21600
Expires: Wed, 24 May 2006 02:30:24 GMT
Etag: "1fae43-4487-3f4e92c4"
Accept-Ranges: bytes
Content-Length: 17543
Last-Modified: Thu, 28 Aug 2003 23:39:48 GMT
Keep-Alive: timeout=5, max=89
Connection: Keep-Alive
Content-Type: image/jpeg
Comment 1 Ruediger Pluem 2006-05-23 21:12:20 UTC
Please post your cache and proxy configuration here. Furthermore please set the
loglevel to debug on the proxy server and post the error_log of two subsequent
requests where the first one is served directly and the second one is served by
the cache with the wrong content-type.
Comment 2 Christopher Shumway 2006-05-23 21:27:13 UTC
Thank you for the follow up.  Here's some more information:

--- httpd.conf ---
ServerRoot "/usr/local"
Listen 80

LoadModule authn_file_module libexec/apache22/mod_authn_file.so
LoadModule authn_dbm_module libexec/apache22/mod_authn_dbm.so
LoadModule authn_anon_module libexec/apache22/mod_authn_anon.so
LoadModule authn_default_module libexec/apache22/mod_authn_default.so
LoadModule authz_host_module libexec/apache22/mod_authz_host.so
LoadModule authz_groupfile_module libexec/apache22/mod_authz_groupfile.so
LoadModule authz_user_module libexec/apache22/mod_authz_user.so
LoadModule authz_dbm_module libexec/apache22/mod_authz_dbm.so
LoadModule authz_owner_module libexec/apache22/mod_authz_owner.so
LoadModule authz_default_module libexec/apache22/mod_authz_default.so
LoadModule auth_basic_module libexec/apache22/mod_auth_basic.so
LoadModule auth_digest_module libexec/apache22/mod_auth_digest.so
LoadModule file_cache_module libexec/apache22/mod_file_cache.so
LoadModule cache_module libexec/apache22/mod_cache.so
LoadModule disk_cache_module libexec/apache22/mod_disk_cache.so
LoadModule mem_cache_module libexec/apache22/mod_mem_cache.so
LoadModule include_module libexec/apache22/mod_include.so
LoadModule filter_module libexec/apache22/mod_filter.so
LoadModule charset_lite_module libexec/apache22/mod_charset_lite.so
LoadModule deflate_module libexec/apache22/mod_deflate.so
LoadModule log_config_module libexec/apache22/mod_log_config.so
LoadModule logio_module libexec/apache22/mod_logio.so
LoadModule env_module libexec/apache22/mod_env.so
LoadModule mime_magic_module libexec/apache22/mod_mime_magic.so
LoadModule cern_meta_module libexec/apache22/mod_cern_meta.so
LoadModule expires_module libexec/apache22/mod_expires.so
LoadModule headers_module libexec/apache22/mod_headers.so
LoadModule usertrack_module libexec/apache22/mod_usertrack.so
LoadModule unique_id_module libexec/apache22/mod_unique_id.so
LoadModule setenvif_module libexec/apache22/mod_setenvif.so
LoadModule version_module libexec/apache22/mod_version.so
LoadModule proxy_module libexec/apache22/mod_proxy.so
LoadModule proxy_connect_module libexec/apache22/mod_proxy_connect.so
LoadModule proxy_ftp_module libexec/apache22/mod_proxy_ftp.so
LoadModule proxy_http_module libexec/apache22/mod_proxy_http.so
LoadModule proxy_ajp_module libexec/apache22/mod_proxy_ajp.so
LoadModule proxy_balancer_module libexec/apache22/mod_proxy_balancer.so
LoadModule ssl_module libexec/apache22/mod_ssl.so
LoadModule mime_module libexec/apache22/mod_mime.so
LoadModule dav_module libexec/apache22/mod_dav.so
LoadModule status_module libexec/apache22/mod_status.so
LoadModule autoindex_module libexec/apache22/mod_autoindex.so
LoadModule asis_module libexec/apache22/mod_asis.so
LoadModule info_module libexec/apache22/mod_info.so
LoadModule cgi_module libexec/apache22/mod_cgi.so
LoadModule dav_fs_module libexec/apache22/mod_dav_fs.so
LoadModule vhost_alias_module libexec/apache22/mod_vhost_alias.so
LoadModule negotiation_module libexec/apache22/mod_negotiation.so
LoadModule dir_module libexec/apache22/mod_dir.so
LoadModule imagemap_module libexec/apache22/mod_imagemap.so
LoadModule actions_module libexec/apache22/mod_actions.so
LoadModule speling_module libexec/apache22/mod_speling.so
LoadModule userdir_module libexec/apache22/mod_userdir.so
LoadModule alias_module libexec/apache22/mod_alias.so
LoadModule rewrite_module libexec/apache22/mod_rewrite.so

User www
Group www

ServerAdmin sysadmin@greatschools.net

<Directory />
  AllowOverride None
  Order deny,allow
  Deny from all
</Directory>

TypesConfig /usr/local/etc/apache22/mime.types

ErrorLog /var/log/httpd-error.log
LogLevel debug

# simulated proxy log
LogFormat "%h %u %X %t \"%r\" %s %b \"%{Referer}i\" \"%{User-Agent}i\"
\"%{Cookie}i\"" proxylog
customlog /var/log/apache/proxy.log proxylog

# proxy-level rewrites
RewriteEngine on

# return 403 forbidden if no user-agent specified
# but don't block our load balancers since they don't specify a user-agent
RewriteCond %{HTTP_USER_AGENT} =""
ReWriteCond %{REMOTE_ADDR} !207.33.22.13[34]
ReWriteRule ^/* / [L,F]

# cache
MCacheRemovalAlgorithm GDSF 
MCacheSize 786432
MCacheMaxObjectSize  256000
MCacheMaxObjectCount 65535
CacheDefaultExpire 14400
CacheEnable mem /

# proxy
ProxyRequests Off
ProxyPreserveHost on
ProxyPass / http://dev.greatschools.net/

<Proxy *>
  Order deny,allow
  Allow from all
</Proxy>

# mod_deflate
<Location />
  SetOutputFilter DEFLATE
  SetEnvIfNoCase Request_URI \.(?:gif|jpe?g|png)$ no-gzip dont-vary
  Header append Vary User-Agent env=!dont-vary
</Location>

---
Here's the relevent log for the working request:


[Tue May 23 14:23:20 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /res/img/content/liferaft.jpg
[Tue May 23 14:23:20 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /res/img/content/liferaft.jpg
[Tue May 23 14:23:20 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1378): [client 198.144.205.133]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:20 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Tue May 23 14:23:20 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1951): proxy: connected
/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(2045): proxy: HTTP: fam 2 socket
created to connect to dev.greatschools.net
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Tue May 23 14:23:20 2006] [debug] mod_proxy_http.c(1448): proxy: start body send
[Tue May 23 14:23:20 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Tue May 23 14:23:20 2006] [debug] mod_cache.c(602): cache: Caching url:
/res/img/content/liferaft.jpg
[Tue May 23 14:23:20 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Tue May 23 14:23:20 2006] [info] mem_cache: Cached url:
http://nuked.greatschools.net:80/res/img/content/liferaft.jpg?
[Tue May 23 14:23:20 2006] [debug] mod_proxy_http.c(1537): proxy: end body send
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 0 in child 63574 for worker http://dev.greatschools.net/
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1644): proxy: worker
http://dev.greatschools.net/ already initialized
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 0 in child 63574 for (dev.greatschools.net)
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 1 in child 63574 for worker proxy:reverse
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1644): proxy: worker
proxy:reverse already initialized
[Tue May 23 14:23:20 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 1 in child 63574 for (*)

Here's the relevent log for the non-working request:

[Tue May 23 14:23:24 2006] [debug] cache_storage.c(261): Cached response for
/res/img/content/liferaft.jpg isn't fresh.  Adding/replacing conditional request
headers.
[Tue May 23 14:23:24 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1378): [client 198.144.205.133]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Tue May 23 14:23:24 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1951): proxy: connected
/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Tue May 23 14:23:24 2006] [debug] mod_proxy_http.c(1541): proxy: header only
[Tue May 23 14:23:24 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Tue May 23 14:23:24 2006] [debug] mod_cache.c(602): cache: Caching url:
/res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Tue May 23 14:23:24 2006] [debug] cache_storage.c(261): Cached response for
/res/img/content/liferaft.jpg isn't fresh.  Adding/replacing conditional request
headers.
[Tue May 23 14:23:24 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1378): [client 198.144.205.133]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Tue May 23 14:23:24 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1951): proxy: connected
/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Tue May 23 14:23:24 2006] [debug] mod_proxy_http.c(1541): proxy: header only
[Tue May 23 14:23:24 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Tue May 23 14:23:24 2006] [debug] mod_cache.c(602): cache: Caching url:
/res/img/content/liferaft.jpg
[Tue May 23 14:23:24 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Tue May 23 14:23:24 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net) 
Comment 3 Christopher Shumway 2006-05-23 22:22:58 UTC
Heres some data from the log when fetching a stand-alone image, one not served
via mod_jk.  Interestingly I noticed when mem_cache cached the content, it added
a '?' at the end of the URI.  I added a '?' to the end of
/res/img/content/liferaft.jpg and it looks like it sent the headers correctly
every time.


[Tue May 23 15:15:20 2006] [info] mod_unique_id: using ip addr 198.144.205.144
[Tue May 23 15:15:21 2006] [info] Init: Seeding PRNG with 0 bytes of entropy
[Tue May 23 15:15:21 2006] [info] Init: Generating temporary RSA private keys
(512/1024 bits)
[Tue May 23 15:15:21 2006] [info] Init: Generating temporary DH parameters
(512/1024 bits)
[Tue May 23 15:15:21 2006] [warn] Init: Session Cache is not configured [hint:
SSLSessionCache]
[Tue May 23 15:15:21 2006] [info] Init: Initializing (virtual) servers for SSL
[Tue May 23 15:15:21 2006] [info] Server: Apache/2.2.2, Interface:
mod_ssl/2.2.2, Library: OpenSSL/0.9.7e-p1
[Tue May 23 15:15:21 2006] [info] mod_unique_id: using ip addr 198.144.205.144
[Tue May 23 15:15:22 2006] [info] Init: Seeding PRNG with 0 bytes of entropy
[Tue May 23 15:15:22 2006] [info] Init: Generating temporary RSA private keys
(512/1024 bits)
[Tue May 23 15:15:23 2006] [info] Init: Generating temporary DH parameters
(512/1024 bits)
[Tue May 23 15:15:23 2006] [info] Init: Initializing (virtual) servers for SSL
[Tue May 23 15:15:23 2006] [info] Server: Apache/2.2.2, Interface:
mod_ssl/2.2.2, Library: OpenSSL/0.9.7e-p1
[Tue May 23 15:15:23 2006] [notice] Digest: generating secret for digest
authentication ...
[Tue May 23 15:15:23 2006] [notice] Digest: done
[Tue May 23 15:15:23 2006] [notice] Apache/2.2.2 (FreeBSD) mod_ssl/2.2.2
OpenSSL/0.9.7e-p1 DAV/2 configured -- resuming normal operations
[Tue May 23 15:15:23 2006] [info] Server built: May 23 2006 12:40:34
[Tue May 23 15:15:23 2006] [debug] prefork.c(991): AcceptMutex: flock (default:
flock)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 0 in child 63711 for worker http://dev.greatschools.net/
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 0 in child 63711 for (dev.greatschools.net)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 1 in child 63711 for worker proxy:reverse
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 1 in child 63711 for (*)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 0 in child 63712 for worker http://dev.greatschools.net/
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1644): proxy: worker
http://dev.greatschools.net/ already initialized
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 0 in child 63712 for (dev.greatschools.net)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 1 in child 63712 for worker proxy:reverse
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1644): proxy: worker
proxy:reverse already initialized
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 1 in child 63712 for (*)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 0 in child 63715 for worker http://dev.greatschools.net/
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1644): proxy: worker
http://dev.greatschools.net/ already initialized
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 0 in child 63715 for (dev.greatschools.net)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 1 in child 63715 for worker proxy:reverse
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1644): proxy: worker
proxy:reverse already initialized
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 1 in child 63715 for (*)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 0 in child 63713 for worker http://dev.greatschools.net/
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1644): proxy: worker
http://dev.greatschools.net/ already initialized
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 0 in child 63713 for (dev.greatschools.net)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 1 in child 63713 for worker proxy:reverse
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1644): proxy: worker
proxy:reverse already initialized
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 1 in child 63713 for (*)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 0 in child 63714 for worker http://dev.greatschools.net/
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1644): proxy: worker
http://dev.greatschools.net/ already initialized
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 0 in child 63714 for (dev.greatschools.net)
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 1 in child 63714 for worker proxy:reverse
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1644): proxy: worker
proxy:reverse already initialized
[Tue May 23 15:15:23 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 1 in child 63714 for (*)
[Tue May 23 15:16:25 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /images/reportcard.jpg
[Tue May 23 15:16:25 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /images/reportcard.jpg
[Tue May 23 15:16:25 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/images/reportcard.jpg
[Tue May 23 15:16:25 2006] [debug] proxy_util.c(1378): [client 198.144.205.133]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/images/reportcard.jpg
[Tue May 23 15:16:25 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Tue May 23 15:16:25 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/images/reportcard.jpg
[Tue May 23 15:16:25 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Tue May 23 15:16:25 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/images/reportcard.jpg to dev.greatschools.net:80
[Tue May 23 15:16:25 2006] [debug] proxy_util.c(1951): proxy: connected
/images/reportcard.jpg to dev.greatschools.net:80
[Tue May 23 15:16:25 2006] [debug] proxy_util.c(2045): proxy: HTTP: fam 2 socket
created to connect to dev.greatschools.net
[Tue May 23 15:16:25 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Tue May 23 15:16:25 2006] [debug] mod_proxy_http.c(1448): proxy: start body send
[Tue May 23 15:16:25 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Tue May 23 15:16:25 2006] [debug] mod_cache.c(602): cache: Caching url:
/images/reportcard.jpg
[Tue May 23 15:16:25 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Tue May 23 15:16:25 2006] [info] mem_cache: Cached url:
http://nuked.greatschools.net:80/images/reportcard.jpg?
[Tue May 23 15:16:25 2006] [debug] mod_proxy_http.c(1537): proxy: end body send
[Tue May 23 15:16:25 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Tue May 23 15:16:26 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 0 in child 63719 for worker http://dev.greatschools.net/
[Tue May 23 15:16:26 2006] [debug] proxy_util.c(1644): proxy: worker
http://dev.greatschools.net/ already initialized
[Tue May 23 15:16:26 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 0 in child 63719 for (dev.greatschools.net)
[Tue May 23 15:16:26 2006] [debug] proxy_util.c(1625): proxy: grabbed scoreboard
slot 1 in child 63719 for worker proxy:reverse
[Tue May 23 15:16:26 2006] [debug] proxy_util.c(1644): proxy: worker
proxy:reverse already initialized
[Tue May 23 15:16:26 2006] [debug] proxy_util.c(1724): proxy: initialized single
connection worker 1 in child 63719 for (*)
[Tue May 23 15:16:41 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /images/reportcard.jpg
[Tue May 23 15:16:41 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /images/reportcard.jpg
[Tue May 23 15:16:41 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/images/reportcard.jpg
[Tue May 23 15:16:41 2006] [debug] proxy_util.c(1378): [client 198.144.205.133]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/images/reportcard.jpg
[Tue May 23 15:16:41 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Tue May 23 15:16:41 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/images/reportcard.jpg
[Tue May 23 15:16:41 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Tue May 23 15:16:41 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/images/reportcard.jpg to dev.greatschools.net:80
[Tue May 23 15:16:41 2006] [debug] proxy_util.c(1951): proxy: connected
/images/reportcard.jpg to dev.greatschools.net:80
[Tue May 23 15:16:41 2006] [debug] proxy_util.c(2045): proxy: HTTP: fam 2 socket
created to connect to dev.greatschools.net
[Tue May 23 15:16:41 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Tue May 23 15:16:41 2006] [debug] mod_proxy_http.c(1448): proxy: start body send
[Tue May 23 15:16:41 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Tue May 23 15:16:41 2006] [debug] mod_cache.c(602): cache: Caching url:
/images/reportcard.jpg
[Tue May 23 15:16:41 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Tue May 23 15:16:41 2006] [info] mem_cache: Cached url:
http://nuked.greatschools.net:80/images/reportcard.jpg?
[Tue May 23 15:16:41 2006] [debug] mod_proxy_http.c(1537): proxy: end body send
[Tue May 23 15:16:41 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)

Comment 4 Christopher Shumway 2006-05-24 01:17:13 UTC
Here's an interesting data point.  I was tinkering with this issue a bit more
today and discovered that I could hit the cached image that was origionally
served via mod_jk using wget all I want, and it would always return image/jpeg
as the content-type.  Once I loaded up firefox and hit ctrl+F5 (force refresh)
mod_cache started to return text/html as the content type.  So for some reason,
the act of force refreshing in firefox seems to be a trigger.
Comment 5 Ruediger Pluem 2006-05-25 11:37:07 UTC
You are correct that this has something to do with doing a refresh in Firefox.
Requesting a refresh in Firefox requires the cache to revalidate the cached
entity on the back end server. Something seems to go wrong during this process.
Currently I cannot decide if this is because something is wrong in the cache
code or because the backend delivers a bad response. So it would be most helpful
if you could sniff the network traffic between your proxy httpd and your backend
httpd, do a non working refresh request with Firefox and attach the results of
your sniffing to this report.
Comment 6 Christopher Shumway 2006-05-25 22:26:03 UTC
Thank you for the followup.  Here's some investigation with tcpdump and ethereal
from the proxy server.

The client is 198.144.205.133, the reverse proxy server is 198.144.205.144 and
the backend web server is 198.144.205.152.

Here is the client making the inital request for /res/img/content/liferaft.jpg.
13:39:20.748596 IP 198.144.205.133.3180 > 198.144.205.144.80: S
3335533019:3335533019(0) win 65535 <mss 1460,nop,nop,sackOK>

13:39:20.748697 IP 198.144.205.144.80 > 198.144.205.133.3180: S
876667792:876667792(0) ack 3335533020 win 65535 <mss 1460,sackOK,eol>

13:39:20.748824 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 1 win 65535

13:39:20.749129 IP 198.144.205.133.3180 > 198.144.205.144.80: P 1:834(833) ack 1
win 65535


Here are the headers the client sent to the proxy server.

GET /res/img/content/liferaft.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: T3CK=TANT%3D1%7CTANO%3D0; fcP=C=133&T=1137020088512&V=1137020102487;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE]; RMID=c690cd854329f1d0;
RMFD=011Fiz3b;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
TRNO=1127250133.198.144.205.133

Next, the proxy server makes a connection to the backend web server to fufill
the request:

13:39:20.751945 IP 198.144.205.144.55524 > 198.144.205.152.80: S
1402262641:1402262641(0) win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp
4082124725 0,sackOK,eol>
13:39:20.752099 IP 198.144.205.152.80 > 198.144.205.144.55524: S
2054288495:2054288495(0) ack 1402262642 win 57344 <mss 1460,nop,wscale
0,nop,nop,timestamp 1733763502 4082124725>
13:39:20.752170 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 1 win 33304
<nop,nop,timestamp 4082124725 1733763502>
13:39:20.752735 IP 198.144.205.144.55524 > 198.144.205.152.80: P 1:956(955) ack
1 win 33304 <nop,nop,timestamp 4082124726 1733763502>
13:39:20.757824 IP 198.144.205.152.80 > 198.144.205.144.55524: . 1:1449(1448)
ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124726>
13:39:20.757934 IP 198.144.205.152.80 > 198.144.205.144.55524: . 1449:2897(1448)
ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124726>
13:39:20.757977 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 2897 win
32580 <nop,nop,timestamp 4082124731 1733763503>
13:39:20.758057 IP 198.144.205.152.80 > 198.144.205.144.55524: . 2897:4345(1448)
ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124726>
13:39:20.758179 IP 198.144.205.152.80 > 198.144.205.144.55524: . 4345:5793(1448)
ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124726>
13:39:20.758211 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 5793 win
31132 <nop,nop,timestamp 4082124731 1733763503>
13:39:20.758313 IP 198.144.205.152.80 > 198.144.205.144.55524: . 5793:7241(1448)
ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124726>
13:39:20.758426 IP 198.144.205.152.80 > 198.144.205.144.55524: . 7241:8689(1448)
ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124731>
13:39:20.758462 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 8689 win
29684 <nop,nop,timestamp 4082124732 1733763503>
13:39:20.758549 IP 198.144.205.152.80 > 198.144.205.144.55524: .
8689:10137(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124731>
13:39:20.758675 IP 198.144.205.152.80 > 198.144.205.144.55524: .
10137:11585(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124731>
13:39:20.758715 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 11585 win
28236 <nop,nop,timestamp 4082124732 1733763503>
13:39:20.758796 IP 198.144.205.152.80 > 198.144.205.144.55524: .
11585:13033(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124731>
13:39:20.758918 IP 198.144.205.152.80 > 198.144.205.144.55524: .
13033:14481(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124731>
13:39:20.758953 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 14481 win
26788 <nop,nop,timestamp 4082124732 1733763503>
13:39:20.759041 IP 198.144.205.152.80 > 198.144.205.144.55524: .
14481:15929(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124731>
13:39:20.759168 IP 198.144.205.152.80 > 198.144.205.144.55524: .
15929:17377(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124732>
13:39:20.759211 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 17377 win
25340 <nop,nop,timestamp 4082124732 1733763503>
13:39:20.759288 IP 198.144.205.152.80 > 198.144.205.144.55524: .
17377:18825(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124732>
13:39:20.759411 IP 198.144.205.152.80 > 198.144.205.144.55524: .
18825:20273(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124732>
13:39:20.759448 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 20273 win
23892 <nop,nop,timestamp 4082124733 1733763503>
13:39:20.759536 IP 198.144.205.152.80 > 198.144.205.144.55524: .
20273:21721(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124732>
13:39:20.759656 IP 198.144.205.152.80 > 198.144.205.144.55524: .
21721:23169(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124732>
13:39:20.759697 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 23169 win
22444 <nop,nop,timestamp 4082124733 1733763503>
13:39:20.759780 IP 198.144.205.152.80 > 198.144.205.144.55524: .
23169:24617(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124732>
13:39:20.759903 IP 198.144.205.152.80 > 198.144.205.144.55524: .
24617:26065(1448) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124732>
13:39:20.759940 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 26065 win
20996 <nop,nop,timestamp 4082124733 1733763503>
13:39:20.759994 IP 198.144.205.152.80 > 198.144.205.144.55524: P
26065:27126(1061) ack 956 win 57920 <nop,nop,timestamp 1733763503 4082124732>
13:39:20.760244 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 27126 win
24465 <nop,nop,timestamp 4082124733 1733763503>
13:39:20.761346 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 27126 win
28465 <nop,nop,timestamp 4082124735 1733763503>
13:39:20.762105 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 27126 win
32465 <nop,nop,timestamp 4082124735 1733763503>
13:39:37.395766 IP 198.144.205.152.80 > 198.144.205.144.55524: F 27126:27126(0)
ack 956 win 57920 <nop,nop,timestamp 1733765167 4082124735>
13:39:37.395864 IP 198.144.205.144.55524 > 198.144.205.152.80: . ack 27127 win
33304 <nop,nop,timestamp 4082141370 1733765167>
13:40:46.519437 IP 198.144.205.144.55524 > 198.144.205.152.80: F 956:956(0) ack
27127 win 33304 <nop,nop,timestamp 4082210495 1733765167>
13:40:46.519586 IP 198.144.205.152.80 > 198.144.205.144.55524: . ack 957 win
57920 <nop,nop,timestamp 1733772078 4082210495>

Here are the headers that the proxy server sends to the backend for the request:

GET /res/img/content/liferaft.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Cookie: T3CK=TANT%3D1%7CTANO%3D0; fcP=C=133&T=1137020088512&V=1137020102487;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE]; RMID=c690cd854329f1d0;
RMFD=011Fiz3b;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
TRNO=1127250133.198.144.205.133
Max-Forwards: 10
X-Forwarded-For: 198.144.205.133
X-Forwarded-Host: nuked.greatschools.net
X-Forwarded-Server: nuked.greatschools.net.
Connection: Keep-Alive

Here are the headers the backend responds with:

HTTP/1.1 200 OK
Date: Thu, 25 May 2006 20:39:20 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
ETag: W/"26797-1148506126000"
Last-Modified: Wed, 24 May 2006 21:28:46 GMT
Content-Length: 26797
Keep-Alive: timeout=15, max=1000
Connection: Keep-Alive
Content-Type: image/jpeg


Then the proxy server responds to the client's request:

13:39:20.760358 IP 198.144.205.144.80 > 198.144.205.133.3180: . 1:1461(1460) ack
834 win 65535
13:39:20.760894 IP 198.144.205.144.80 > 198.144.205.133.3180: . 1461:2921(1460)
ack 834 win 65535
13:39:20.760919 IP 198.144.205.144.80 > 198.144.205.133.3180: . 2921:4381(1460)
ack 834 win 65535
13:39:20.760932 IP 198.144.205.144.80 > 198.144.205.133.3180: . 4381:5841(1460)
ack 834 win 65535
13:39:20.761507 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 2921 win 65535
13:39:20.761607 IP 198.144.205.144.80 > 198.144.205.133.3180: . 5841:7301(1460)
ack 834 win 65535
13:39:20.761621 IP 198.144.205.144.80 > 198.144.205.133.3180: . 7301:8761(1460)
ack 834 win 65535
13:39:20.761635 IP 198.144.205.144.80 > 198.144.205.133.3180: . 8761:10221(1460)
ack 834 win 65535
13:39:20.761719 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 5841 win 65535
13:39:20.761748 IP 198.144.205.144.80 > 198.144.205.133.3180: .
10221:11681(1460) ack 834 win 65535
13:39:20.761763 IP 198.144.205.144.80 > 198.144.205.133.3180: .
11681:13141(1460) ack 834 win 65535
13:39:20.761778 IP 198.144.205.144.80 > 198.144.205.133.3180: .
13141:14601(1460) ack 834 win 65535
13:39:20.763225 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 8761 win 65535
13:39:20.763468 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 11681 win 65535
13:39:20.763526 IP 198.144.205.144.80 > 198.144.205.133.3180: .
14601:16061(1460) ack 834 win 65535
13:39:20.763544 IP 198.144.205.144.80 > 198.144.205.133.3180: .
16061:17521(1460) ack 834 win 65535
13:39:20.763712 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 14601 win 65535
13:39:20.763735 IP 198.144.205.144.80 > 198.144.205.133.3180: .
17521:18981(1460) ack 834 win 65535
13:39:20.763748 IP 198.144.205.144.80 > 198.144.205.133.3180: .
18981:20441(1460) ack 834 win 65535
13:39:20.764661 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 17521 win 65535
13:39:20.764691 IP 198.144.205.144.80 > 198.144.205.133.3180: .
20441:21901(1460) ack 834 win 65535
13:39:20.764703 IP 198.144.205.144.80 > 198.144.205.133.3180: .
21901:23361(1460) ack 834 win 65535
13:39:20.764904 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 20441 win 65535
13:39:20.764924 IP 198.144.205.144.80 > 198.144.205.133.3180: .
23361:24821(1460) ack 834 win 65535
13:39:20.764937 IP 198.144.205.144.80 > 198.144.205.133.3180: .
24821:26281(1460) ack 834 win 65535
13:39:20.765177 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 23361 win 65535
13:39:20.765197 IP 198.144.205.144.80 > 198.144.205.133.3180: P 26281:27164(883)
ack 834 win 65535
13:39:20.765423 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 26281 win 65535
13:39:20.941506 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 27164 win 64652
13:39:25.763406 IP 198.144.205.144.80 > 198.144.205.133.3180: F 27164:27164(0)
ack 834 win 65535
13:39:25.763601 IP 198.144.205.133.3180 > 198.144.205.144.80: . ack 27165 win 64652
13:39:27.958133 IP 198.144.205.133.3180 > 198.144.205.144.80: F 834:834(0) ack
27165 win 64652
13:39:27.958237 IP 198.144.205.144.80 > 198.144.205.133.3180: . ack 835 win 65534

Here are the headers the proxy responds with:

HTTP/1.1 200 OK
Date: Thu, 25 May 2006 20:39:20 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
ETag: W/"26797-1148506126000"
Last-Modified: Wed, 24 May 2006 21:28:46 GMT
Content-Length: 26797
Content-Type: image/jpeg
Expires: Thu, 25 May 2006 22:58:23 GMT
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive

That transaction worked okay.  Here's one that didn't work:

13:41:01.094260 IP 198.144.205.133.3187 > 198.144.205.144.80: S
1953506917:1953506917(0) win 65535 <mss 1460,nop,nop,sackOK>
13:41:01.094354 IP 198.144.205.144.80 > 198.144.205.133.3187: S
1632330321:1632330321(0) ack 1953506918 win 65535 <mss 1460,sackOK,eol>
13:41:01.094490 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 1 win 65535
13:41:01.094805 IP 198.144.205.133.3187 > 198.144.205.144.80: P 1:877(876) ack 1
win 65535
13:41:01.102707 IP 198.144.205.144.80 > 198.144.205.133.3187: . 1:1461(1460) ack
877 win 65535
13:41:01.102733 IP 198.144.205.144.80 > 198.144.205.133.3187: . 1461:2921(1460)
ack 877 win 65535
13:41:01.103237 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 2921 win 65535
13:41:01.103328 IP 198.144.205.144.80 > 198.144.205.133.3187: . 2921:4381(1460)
ack 877 win 65535
13:41:01.103340 IP 198.144.205.144.80 > 198.144.205.133.3187: . 4381:5841(1460)
ack 877 win 65535
13:41:01.103354 IP 198.144.205.144.80 > 198.144.205.133.3187: . 5841:7301(1460)
ack 877 win 65535
13:41:01.103824 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 5841 win 65535
13:41:01.103847 IP 198.144.205.144.80 > 198.144.205.133.3187: . 7301:8761(1460)
ack 877 win 65535
13:41:01.103858 IP 198.144.205.144.80 > 198.144.205.133.3187: . 8761:10221(1460)
ack 877 win 65535
13:41:01.103870 IP 198.144.205.144.80 > 198.144.205.133.3187: .
10221:11681(1460) ack 877 win 65535
13:41:01.104210 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 8761 win 65535
13:41:01.104234 IP 198.144.205.144.80 > 198.144.205.133.3187: .
11681:13141(1460) ack 877 win 65535
13:41:01.104246 IP 198.144.205.144.80 > 198.144.205.133.3187: .
13141:14601(1460) ack 877 win 65535
13:41:01.104258 IP 198.144.205.144.80 > 198.144.205.133.3187: .
14601:16061(1460) ack 877 win 65535
13:41:01.104457 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 11681 win 65535
13:41:01.104481 IP 198.144.205.144.80 > 198.144.205.133.3187: .
16061:17521(1460) ack 877 win 65535
13:41:01.104495 IP 198.144.205.144.80 > 198.144.205.133.3187: .
17521:18981(1460) ack 877 win 65535
13:41:01.104507 IP 198.144.205.144.80 > 198.144.205.133.3187: .
18981:20441(1460) ack 877 win 65535
13:41:01.104724 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 14601 win 65535
13:41:01.104745 IP 198.144.205.144.80 > 198.144.205.133.3187: .
20441:21901(1460) ack 877 win 65535
13:41:01.104758 IP 198.144.205.144.80 > 198.144.205.133.3187: .
21901:23361(1460) ack 877 win 65535
13:41:01.104771 IP 198.144.205.144.80 > 198.144.205.133.3187: .
23361:24821(1460) ack 877 win 65535
13:41:01.104966 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 17521 win 65535
13:41:01.104985 IP 198.144.205.144.80 > 198.144.205.133.3187: .
24821:26281(1460) ack 877 win 65535
13:41:01.105004 IP 198.144.205.144.80 > 198.144.205.133.3187: P 26281:27164(883)
ack 877 win 65535
13:41:01.105213 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 20441 win 65535
13:41:01.105461 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 23361 win 65535
13:41:01.105706 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 26281 win 65535
13:41:01.237467 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 27164 win 64652
13:41:05.312399 IP 198.144.205.133.3187 > 198.144.205.144.80: P 877:1753(876)
ack 27164 win 64652
13:41:05.316143 IP 198.144.205.144.80 > 198.144.205.133.3187: .
27164:28624(1460) ack 1753 win 65535
13:41:05.316167 IP 198.144.205.144.80 > 198.144.205.133.3187: .
28624:30084(1460) ack 1753 win 65535
13:41:05.316187 IP 198.144.205.144.80 > 198.144.205.133.3187: .
30084:31544(1460) ack 1753 win 65535
13:41:05.316197 IP 198.144.205.144.80 > 198.144.205.133.3187: .
31544:33004(1460) ack 1753 win 65535
13:41:05.316217 IP 198.144.205.144.80 > 198.144.205.133.3187: .
33004:34464(1460) ack 1753 win 65535
13:41:05.316233 IP 198.144.205.144.80 > 198.144.205.133.3187: .
34464:35924(1460) ack 1753 win 65535
13:41:05.316242 IP 198.144.205.144.80 > 198.144.205.133.3187: .
35924:37384(1460) ack 1753 win 65535
13:41:05.316261 IP 198.144.205.144.80 > 198.144.205.133.3187: .
37384:38844(1460) ack 1753 win 65535
13:41:05.316278 IP 198.144.205.144.80 > 198.144.205.133.3187: .
38844:40304(1460) ack 1753 win 65535
13:41:05.316293 IP 198.144.205.144.80 > 198.144.205.133.3187: .
40304:41764(1460) ack 1753 win 65535
13:41:05.316302 IP 198.144.205.144.80 > 198.144.205.133.3187: .
41764:43224(1460) ack 1753 win 65535
13:41:05.316323 IP 198.144.205.144.80 > 198.144.205.133.3187: .
43224:44684(1460) ack 1753 win 65535
13:41:05.316679 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 30084 win 65535
13:41:05.316774 IP 198.144.205.144.80 > 198.144.205.133.3187: .
44684:46144(1460) ack 1753 win 65535
13:41:05.316785 IP 198.144.205.144.80 > 198.144.205.133.3187: .
46144:47604(1460) ack 1753 win 65535
13:41:05.316795 IP 198.144.205.144.80 > 198.144.205.133.3187: .
47604:49064(1460) ack 1753 win 65535
13:41:05.316874 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 33004 win 65535
13:41:05.316897 IP 198.144.205.144.80 > 198.144.205.133.3187: .
49064:50524(1460) ack 1753 win 65535
13:41:05.316910 IP 198.144.205.144.80 > 198.144.205.133.3187: .
50524:51984(1460) ack 1753 win 65535
13:41:05.316922 IP 198.144.205.144.80 > 198.144.205.133.3187: .
51984:53444(1460) ack 1753 win 65535
13:41:05.317132 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 35924 win 65535
13:41:05.317153 IP 198.144.205.144.80 > 198.144.205.133.3187: P 53444:54325(881)
ack 1753 win 65535
13:41:05.317382 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 38844 win 65535
13:41:05.317626 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 41764 win 65535
13:41:05.317868 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 44684 win 65535
13:41:05.318118 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 47604 win 65535
13:41:05.318363 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 50524 win 65535
13:41:05.318610 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 53444 win 65535
13:41:05.503052 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 54325 win 64654
13:41:05.629138 IP 198.144.205.133.3187 > 198.144.205.144.80: P 1753:2489(736)
ack 54325 win 64654
13:41:05.633724 IP 198.144.205.144.80 > 198.144.205.133.3187: P 54325:54883(558)
ack 2489 win 65535
13:41:05.831178 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 54883 win 64096
13:41:10.634808 IP 198.144.205.144.80 > 198.144.205.133.3187: F 54883:54883(0)
ack 2489 win 65535
13:41:10.634969 IP 198.144.205.133.3187 > 198.144.205.144.80: . ack 54884 win 64096
13:41:24.506079 IP 198.144.205.133.3187 > 198.144.205.144.80: F 2489:2489(0) ack
54884 win 64096
13:41:24.506191 IP 198.144.205.144.80 > 198.144.205.133.3187: . ack 2490 win 65534

This is actually two requests over a single tcp connection.  I assume firefox is
recycling a still connected keep alive session if the user hits ctrl+F5 fast enough.

The client / server headers:

GET /res/img/content/liferaft.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: T3CK=TANT%3D1%7CTANO%3D0; fcP=C=133&T=1137020088512&V=1137020102487;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE]; RMID=c690cd854329f1d0;
RMFD=011Fiz3b;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
TRNO=1127250133.198.144.205.133
Pragma: no-cache
Cache-Control: no-cache

HTTP/1.1 200 OK
Date: Thu, 25 May 2006 20:41:01 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
ETag: W/"26797-1148506126000"
Content-Length: 26797
Expires: Fri, 26 May 2006 00:41:01 GMT
Content-Type: image/jpeg
Last-Modified: Wed, 24 May 2006 21:28:46 GMT
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive

GET /res/img/content/liferaft.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Cookie: T3CK=TANT%3D1%7CTANO%3D0; fcP=C=133&T=1137020088512&V=1137020102487;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE]; RMID=c690cd854329f1d0;
RMFD=011Fiz3b;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
TRNO=1127250133.198.144.205.133
Pragma: no-cache
Cache-Control: no-cache

HTTP/1.1 200 OK
Date: Thu, 25 May 2006 20:41:05 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
ETag: W/"26797-1148506126000"
Content-Length: 26797
Expires: Fri, 26 May 2006 00:41:05 GMT
Content-Type: text/html
Last-Modified: Wed, 24 May 2006 21:28:46 GMT
Keep-Alive: timeout=5, max=99
Connection: Keep-Alive


The first request worked, but the second one was returned as text/html.

Meanwhile, the proxy server is making requests to the backend to handle the
client's request.

13:40:46.519646 IP 198.144.205.144.64919 > 198.144.205.152.80: S
755704577:755704577(0) win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp
4082210496 0,sackOK,eol>
13:40:46.519763 IP 198.144.205.152.80 > 198.144.205.144.64919: S
2886095240:2886095240(0) ack 755704578 win 57344 <mss 1460,nop,wscale
0,nop,nop,timestamp 1733772078 4082210496>
13:40:46.519805 IP 198.144.205.144.64919 > 198.144.205.152.80: . ack 1 win 33304
<nop,nop,timestamp 4082210496 1733772078>
13:40:46.520087 IP 198.144.205.144.64919 > 198.144.205.152.80: P 1:1089(1088)
ack 1 win 33304 <nop,nop,timestamp 4082210496 1733772078>
13:40:46.524652 IP 198.144.205.152.80 > 198.144.205.144.64919: P 1:257(256) ack
1089 win 57920 <nop,nop,timestamp 1733772079 4082210496>
13:40:46.624500 IP 198.144.205.144.64919 > 198.144.205.152.80: . ack 257 win
33304 <nop,nop,timestamp 4082210601 1733772079>
13:41:01.097038 IP 198.144.205.144.63148 > 198.144.205.152.80: F 999:999(0) ack
27127 win 33304 <nop,nop,timestamp 4082225073 1733765874>
13:41:01.097158 IP 198.144.205.152.80 > 198.144.205.144.63148: . ack 1000 win
57920 <nop,nop,timestamp 1733773536 4082225073>
13:41:01.097278 IP 198.144.205.144.55877 > 198.144.205.152.80: S
3660931143:3660931143(0) win 65535 <mss 1460,nop,wscale 1,nop,nop,timestamp
4082225074 0,sackOK,eol>
13:41:01.097392 IP 198.144.205.152.80 > 198.144.205.144.55877: S
1545466721:1545466721(0) ack 3660931144 win 57344 <mss 1460,nop,wscale
0,nop,nop,timestamp 1733773536 4082225074>
13:41:01.097431 IP 198.144.205.144.55877 > 198.144.205.152.80: . ack 1 win 33304
<nop,nop,timestamp 4082225074 1733773536>
13:41:01.097709 IP 198.144.205.144.55877 > 198.144.205.152.80: P 1:1089(1088)
ack 1 win 33304 <nop,nop,timestamp 4082225074 1733773536>
13:41:01.102080 IP 198.144.205.152.80 > 198.144.205.144.55877: P 1:257(256) ack
1089 win 57920 <nop,nop,timestamp 1733773536 4082225074>
13:41:01.202018 IP 198.144.205.144.55877 > 198.144.205.152.80: . ack 257 win
33304 <nop,nop,timestamp 4082225179 1733773536>
13:41:03.254784 IP 198.144.205.152.80 > 198.144.205.144.64919: F 257:257(0) ack
1089 win 57920 <nop,nop,timestamp 1733773752 4082210601>
13:41:03.254877 IP 198.144.205.144.64919 > 198.144.205.152.80: . ack 258 win
33304 <nop,nop,timestamp 4082227231 1733773752>
13:41:05.313389 IP 198.144.205.144.55877 > 198.144.205.152.80: P 1089:2177(1088)
ack 257 win 33304 <nop,nop,timestamp 4082229290 1733773536>
13:41:05.315555 IP 198.144.205.152.80 > 198.144.205.144.55877: P 257:512(255)
ack 2177 win 57920 <nop,nop,timestamp 1733773958 4082229290>
13:41:05.414874 IP 198.144.205.144.55877 > 198.144.205.152.80: . ack 512 win
33304 <nop,nop,timestamp 4082229392 1733773958>
13:41:05.629992 IP 198.144.205.144.55877 > 198.144.205.152.80: P 2177:3035(858)
ack 512 win 33304 <nop,nop,timestamp 4082229607 1733773958>
13:41:05.631281 IP 198.144.205.152.80 > 198.144.205.144.55877: P 512:1753(1241)
ack 3035 win 57920 <nop,nop,timestamp 1733773989 4082229607>
13:41:05.730896 IP 198.144.205.144.55877 > 198.144.205.152.80: . ack 1753 win
33304 <nop,nop,timestamp 4082229708 1733773989>
13:41:22.446789 IP 198.144.205.152.80 > 198.144.205.144.55877: F 1753:1753(0)
ack 3035 win 57920 <nop,nop,timestamp 1733775671 4082229708>
13:41:22.446885 IP 198.144.205.144.55877 > 198.144.205.152.80: . ack 1754 win
33304 <nop,nop,timestamp 4082246424 1733775671>

Here are the headers from the proxy -> backend conversation.

GET /res/img/content/liferaft.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Cookie: T3CK=TANT%3D1%7CTANO%3D0; fcP=C=133&T=1137020088512&V=1137020102487;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE]; RMID=c690cd854329f1d0;
RMFD=011Fiz3b;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
TRNO=1127250133.198.144.205.133
Pragma: no-cache
Cache-Control: no-cache
If-None-Match: W/"26797-1148506126000"
If-Modified-Since: Wed, 24 May 2006 21:28:46 GMT
Max-Forwards: 10
X-Forwarded-For: 198.144.205.133
X-Forwarded-Host: nuked.greatschools.net
X-Forwarded-Server: nuked.greatschools.net.
Connection: Keep-Alive

HTTP/1.1 304 Not Modified
Date: Thu, 25 May 2006 20:41:01 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
Content-Length: 0
Keep-Alive: timeout=15, max=1000
Connection: Keep-Alive
Content-Type: text/html

It looks like the backend is responding with http status code 304.  I'm
wondering if the text/html content-type from the 304 code is being erroniously
cached in this case?

I have the tcpdump capture file here.  If I can provide any more information or
perhaps put the capture file somewhere for download please don't hesitate to ask.
Comment 7 Christopher Shumway 2006-05-26 00:07:30 UTC
I just ran some tcpdump sniffing while pulling an image served directly by httpd
on the backend, not going through mod_jk.  It does not set the conent-type
header when it returns a 304 http status code.  Here are the headers from the
proxy -> backend conversation:

GET /images/reportcard.jpg HTTP/1.1
Host: nuked.greatschools.net
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.3)
Gecko/20060426 Firefox/1.5.0.3
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Cookie: TRNO=1127250133.198.144.205.133;
NXCLICK2=011FHWHwNX_mailing/gn/2006_02/ca/8951!y!01!4qcu!52qf!02!4qcv!52qhNX_mailing/gn/2006_02_21/ca/8427!y!01!4r4q!53Uk!02!4r4r!53UqNX_mailing/mss/2006_03/ca/8438.76346803398!y!02!4rJ8!53pF;
RMFD=011Fiz3b; NumAd=-1; RMID=c690cd854329f1d0;
s_vi=[CS]v1|43F0FFA7000062EC-A160B0300000792[CE]; T3CK=TANT%3D1%7CTANO%3D0;
fcP=C=133&T=1137020088512&V=1137020102487
Pragma: no-cache
Cache-Control: no-cache
If-None-Match: "1fae43-4487-3f4e92c4"
If-Modified-Since: Thu, 28 Aug 2003 23:39:48 GMT
Max-Forwards: 10
X-Forwarded-For: 198.144.205.133
X-Forwarded-Host: nuked.greatschools.net
X-Forwarded-Server: nuked.greatschools.net.
Connection: Keep-Alive


HTTP/1.1 304 Not Modified
Date: Thu, 25 May 2006 23:56:23 GMT
Server: Apache/1.3.33 (Unix) mod_perl/1.29 mod_ssl/2.8.22 OpenSSL/0.9.7d
mod_jk/1.2.15
Connection: Keep-Alive, Keep-Alive
Keep-Alive: timeout=15, max=998
ETag: "1fae43-4487-3f4e92c4"
Expires: Fri, 26 May 2006 05:56:23 GMT
Cache-Control: max-age=21600

Comment 8 Ruediger Pluem 2006-05-26 08:54:12 UTC
Created attachment 18353 [details]
Patch for additional Debug messages against 2.2.x

Thanks for the update. I think we are getting closer. Can you please apply the
attached patch, run a non working request and post the according error log?
The patch is only temporary and does not fix anything, but it should help me to
understand the problem better.
Comment 9 Christopher Shumway 2006-05-26 18:18:25 UTC
Here you go.  I applied the patch, and also the patch found in bug 39266.  Here
is a snipit from the debug log.

[Fri May 26 11:15:05 2006] [debug] cache_storage.c(261): Cached response for
/res/img/content/liferaft.jpg isn't fresh.  Adding/replacing conditional request
headers.
[Fri May 26 11:15:05 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /res/img/content/liferaft.jpg
[Fri May 26 11:15:05 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /res/img/content/liferaft.jpg
[Fri May 26 11:15:05 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/res/img/content/liferaft.jpg
[Fri May 26 11:15:05 2006] [debug] proxy_util.c(1378): [client 64.85.232.3]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/res/img/content/liferaft.jpg
[Fri May 26 11:15:05 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Fri May 26 11:15:05 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/res/img/content/liferaft.jpg
[Fri May 26 11:15:05 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Fri May 26 11:15:05 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Fri May 26 11:15:05 2006] [debug] proxy_util.c(1951): proxy: connected
/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Fri May 26 11:15:05 2006] [debug] proxy_util.c(2045): proxy: HTTP: fam 2 socket
created to connect to dev.greatschools.net
[Fri May 26 11:15:05 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Fri May 26 11:15:05 2006] [debug] mod_proxy_http.c(1541): proxy: header only
[Fri May 26 11:15:05 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Fri May 26 11:15:05 2006] [debug] mod_cache.c(602): cache: Caching url:
/res/img/content/liferaft.jpg
[Fri May 26 11:15:05 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Fri May 26 11:15:05 2006] [debug] mod_cache.c(726): cache: Content-Type
text/html text/html
[Fri May 26 11:15:05 2006] [debug] mod_cache.c(738): cache: Content-Type
text/html image/jpeg
[Fri May 26 11:15:05 2006] [debug] http_filters.c(990): http_filter:
Content-Type text/html image/jpeg
[Fri May 26 11:15:05 2006] [debug] http_filters.c(995): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:15:05 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Fri May 26 11:15:06 2006] [debug] cache_storage.c(261): Cached response for
/res/img/content/liferaft.jpg isn't fresh.  Adding/replacing conditional request
headers.
[Fri May 26 11:15:06 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /res/img/content/liferaft.jpg
[Fri May 26 11:15:06 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /res/img/content/liferaft.jpg
[Fri May 26 11:15:06 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/res/img/content/liferaft.jpg
[Fri May 26 11:15:06 2006] [debug] proxy_util.c(1378): [client 64.85.232.3]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/res/img/content/liferaft.jpg
[Fri May 26 11:15:06 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Fri May 26 11:15:06 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/res/img/content/liferaft.jpg
[Fri May 26 11:15:06 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Fri May 26 11:15:06 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Fri May 26 11:15:06 2006] [debug] proxy_util.c(1951): proxy: connected
/res/img/content/liferaft.jpg to dev.greatschools.net:80
[Fri May 26 11:15:06 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Fri May 26 11:15:06 2006] [debug] mod_proxy_http.c(1541): proxy: header only
[Fri May 26 11:15:06 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Fri May 26 11:15:06 2006] [debug] mod_cache.c(602): cache: Caching url:
/res/img/content/liferaft.jpg
[Fri May 26 11:15:06 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Fri May 26 11:15:06 2006] [debug] mod_cache.c(726): cache: Content-Type
text/html text/html
[Fri May 26 11:15:06 2006] [debug] mod_cache.c(738): cache: Content-Type
text/html text/html
[Fri May 26 11:15:06 2006] [debug] http_filters.c(990): http_filter:
Content-Type text/html text/html
[Fri May 26 11:15:06 2006] [debug] http_filters.c(995): http_filter:
Content-Type text/html text/html
[Fri May 26 11:15:06 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)

This is two requests over the same tcp keepalive connection from firefox.  The
first request seemed to work, the second one firefix tried to render the jpeg as
if it was html.
Comment 10 Christopher Shumway 2006-05-26 18:23:16 UTC
Just for comparison's sake, here is some debug log output while force-refreshing
an image being served directly by the backend httpd server, not through mod_jk.

[Fri May 26 11:20:28 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /images/reportcard.jpg
[Fri May 26 11:20:28 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /images/reportcard.jpg
[Fri May 26 11:20:28 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:28 2006] [debug] proxy_util.c(1378): [client 64.85.232.3]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:28 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Fri May 26 11:20:28 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:28 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Fri May 26 11:20:28 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:28 2006] [debug] proxy_util.c(1951): proxy: connected
/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:28 2006] [debug] proxy_util.c(2045): proxy: HTTP: fam 2 socket
created to connect to dev.greatschools.net
[Fri May 26 11:20:28 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Fri May 26 11:20:29 2006] [debug] mod_proxy_http.c(1448): proxy: start body send
[Fri May 26 11:20:29 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Fri May 26 11:20:29 2006] [debug] mod_cache.c(602): cache: Caching url:
/images/reportcard.jpg
[Fri May 26 11:20:29 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Fri May 26 11:20:29 2006] [debug] http_filters.c(990): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:20:29 2006] [debug] http_filters.c(995): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:20:29 2006] [info] mem_cache: Cached url:
http://nuked.greatschools.net:80/images/reportcard.jpg?
[Fri May 26 11:20:29 2006] [debug] mod_proxy_http.c(1537): proxy: end body send
[Fri May 26 11:20:29 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Fri May 26 11:20:38 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /images/reportcard.jpg
[Fri May 26 11:20:38 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /images/reportcard.jpg
[Fri May 26 11:20:38 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:38 2006] [debug] proxy_util.c(1378): [client 64.85.232.3]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:38 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Fri May 26 11:20:38 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:38 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Fri May 26 11:20:38 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:38 2006] [debug] proxy_util.c(1951): proxy: connected
/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:38 2006] [debug] proxy_util.c(2045): proxy: HTTP: fam 2 socket
created to connect to dev.greatschools.net
[Fri May 26 11:20:38 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Fri May 26 11:20:38 2006] [debug] mod_proxy_http.c(1448): proxy: start body send
[Fri May 26 11:20:38 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Fri May 26 11:20:38 2006] [debug] mod_cache.c(602): cache: Caching url:
/images/reportcard.jpg
[Fri May 26 11:20:38 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Fri May 26 11:20:38 2006] [debug] http_filters.c(990): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:20:38 2006] [debug] http_filters.c(995): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:20:38 2006] [info] mem_cache: Cached url:
http://nuked.greatschools.net:80/images/reportcard.jpg?
[Fri May 26 11:20:38 2006] [debug] mod_proxy_http.c(1537): proxy: end body send
[Fri May 26 11:20:38 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Fri May 26 11:20:39 2006] [debug] cache_storage.c(261): Cached response for
/images/reportcard.jpg isn't fresh.  Adding/replacing conditional request headers.
[Fri May 26 11:20:39 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /images/reportcard.jpg
[Fri May 26 11:20:39 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /images/reportcard.jpg
[Fri May 26 11:20:39 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:39 2006] [debug] proxy_util.c(1378): [client 64.85.232.3]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:39 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Fri May 26 11:20:39 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:39 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Fri May 26 11:20:39 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:39 2006] [debug] proxy_util.c(1951): proxy: connected
/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:39 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Fri May 26 11:20:39 2006] [debug] mod_proxy_http.c(1541): proxy: header only
[Fri May 26 11:20:39 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Fri May 26 11:20:39 2006] [debug] mod_cache.c(602): cache: Caching url:
/images/reportcard.jpg
[Fri May 26 11:20:39 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Fri May 26 11:20:39 2006] [debug] mod_cache.c(726): cache: Content-Type (null)
image/jpeg
[Fri May 26 11:20:39 2006] [debug] mod_cache.c(738): cache: Content-Type (null)
image/jpeg
[Fri May 26 11:20:39 2006] [debug] http_filters.c(990): http_filter:
Content-Type (null) image/jpeg
[Fri May 26 11:20:39 2006] [debug] http_filters.c(995): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:20:39 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Fri May 26 11:20:40 2006] [debug] cache_storage.c(261): Cached response for
/images/reportcard.jpg isn't fresh.  Adding/replacing conditional request headers.
[Fri May 26 11:20:40 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /images/reportcard.jpg
[Fri May 26 11:20:40 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /images/reportcard.jpg
[Fri May 26 11:20:40 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:40 2006] [debug] proxy_util.c(1378): [client 64.85.232.3]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:40 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Fri May 26 11:20:40 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:40 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Fri May 26 11:20:40 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:40 2006] [debug] proxy_util.c(1951): proxy: connected
/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:40 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Fri May 26 11:20:40 2006] [debug] mod_proxy_http.c(1541): proxy: header only
[Fri May 26 11:20:40 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Fri May 26 11:20:40 2006] [debug] mod_cache.c(602): cache: Caching url:
/images/reportcard.jpg
[Fri May 26 11:20:40 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Fri May 26 11:20:40 2006] [debug] mod_cache.c(726): cache: Content-Type (null)
image/jpeg
[Fri May 26 11:20:40 2006] [debug] mod_cache.c(738): cache: Content-Type (null)
image/jpeg
[Fri May 26 11:20:40 2006] [debug] http_filters.c(990): http_filter:
Content-Type (null) image/jpeg
[Fri May 26 11:20:40 2006] [debug] http_filters.c(995): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:20:40 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Fri May 26 11:20:41 2006] [debug] cache_storage.c(261): Cached response for
/images/reportcard.jpg isn't fresh.  Adding/replacing conditional request headers.
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1378): [client 64.85.232.3]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Fri May 26 11:20:41 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1951): proxy: connected
/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Fri May 26 11:20:41 2006] [debug] mod_proxy_http.c(1541): proxy: header only
[Fri May 26 11:20:41 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(602): cache: Caching url:
/images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(726): cache: Content-Type (null)
image/jpeg
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(738): cache: Content-Type (null)
image/jpeg
[Fri May 26 11:20:41 2006] [debug] http_filters.c(990): http_filter:
Content-Type (null) image/jpeg
[Fri May 26 11:20:41 2006] [debug] http_filters.c(995): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
[Fri May 26 11:20:41 2006] [debug] cache_storage.c(261): Cached response for
/images/reportcard.jpg isn't fresh.  Adding/replacing conditional request headers.
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(129): Adding CACHE_SAVE filter
for /images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(136): Adding CACHE_REMOVE_URL
filter for /images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] mod_proxy_http.c(54): proxy: HTTP:
canonicalising URL //dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1378): [client 64.85.232.3]
proxy: http: found worker http://dev.greatschools.net/ for
http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] mod_proxy.c(756): Running scheme http handler
(attempt 0)
[Fri May 26 11:20:41 2006] [debug] mod_proxy_http.c(1662): proxy: HTTP: serving
URL http://dev.greatschools.net/images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1798): proxy: HTTP: has acquired
connection for (dev.greatschools.net)
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1858): proxy: connecting
http://dev.greatschools.net/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1951): proxy: connected
/images/reportcard.jpg to dev.greatschools.net:80
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(2141): proxy: HTTP: connection
complete to 198.144.205.152:80 (dev.greatschools.net)
[Fri May 26 11:20:41 2006] [debug] mod_proxy_http.c(1541): proxy: header only
[Fri May 26 11:20:41 2006] [debug] mod_headers.c(612): headers:
ap_headers_output_filter()
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(602): cache: Caching url:
/images/reportcard.jpg
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(608): cache: Removing
CACHE_REMOVE_URL filter.
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(726): cache: Content-Type (null)
image/jpeg
[Fri May 26 11:20:41 2006] [debug] mod_cache.c(738): cache: Content-Type (null)
image/jpeg
[Fri May 26 11:20:41 2006] [debug] http_filters.c(990): http_filter:
Content-Type (null) image/jpeg
[Fri May 26 11:20:41 2006] [debug] http_filters.c(995): http_filter:
Content-Type image/jpeg image/jpeg
[Fri May 26 11:20:41 2006] [debug] proxy_util.c(1816): proxy: HTTP: has released
connection for (dev.greatschools.net)
Comment 11 Ruediger Pluem 2006-05-26 22:49:37 UTC
Created attachment 18357 [details]
Patch against trunk

I think I got it know. The attached patch should fix your problem. So could you
please do the following:

1. Start with clean sources (at least without the debug patch I sent earlier)
2. Apply the patch for 39266
3. Apply the attached patch
4. Compile
5. Test
6. Let me know the results :-).
Comment 12 Ruediger Pluem 2006-05-26 22:59:32 UTC
Created attachment 18358 [details]
Patch against mod_jk.c (1.3 Version) of mod_jk 1.2.15

Apart from the patch against 2.2.x I am pretty much sure that the behaviour of
the backend (sending Content-Length and Content-Type for a 304 response) is not
compliant with RFC 2616. 

10.3.5 in RFC 2616 states:

The 304 response MUST NOT contain a message-body, and thus is always terminated
by the first empty line after the header fields.

I read this as Content-Length and Content-Type header MUST NOT be sent with 304
responses and the behaviour of httpd 2.2.x and the http connector of Tomcat not
doing this seem to support this view.
From my limited point of view on httpd 1.3 this should be fixed inside mod_jk.
I  think that the attached patch, which is untested due to my lack of an
available httpd 1.3, does this without breaking other things.
So, if you like you can give the attached patch a try to make your backend RFC
2616 compliant again :-).
Comment 13 Christopher Shumway 2006-05-30 18:12:37 UTC
Hi there.  Thanks for your help on this issue.  The patch
modules/cache/cache_storage.c seems to do the trick!

I'll try out the patch to mod_jk too.  I agree, it seems like mod_jk is breaking
RFC 2616, I'll try out the patch on the backend web server and make sure it
doesn't break anything else.

Comment 14 Ruediger Pluem 2006-05-30 20:49:13 UTC
Committed to trunk as r410370 (http://svn.apache.org/viewvc?rev=410370&view=rev).
Comment 15 Christopher Shumway 2006-06-14 00:58:58 UTC
FYI I've been running the patch against mod_jk.c for about two weeks now with no
ill effects.
Comment 16 Ruediger Pluem 2006-07-26 13:13:11 UTC
Backported to 2.2.x as r425725 (http://svn.apache.org/viewvc?rev=425725&view=rev).
Comment 17 Mark Nottingham 2007-02-09 15:17:37 UTC
The resolution to this bug breaks a MUST-level requirement of RFC2616. From <http://www.w3.org/
Protocols/rfc2616/rfc2616-sec13.html#sec13.5.3>;

[[[
The end-to-end headers stored in the cache entry are used for the constructed response, except that
[...]
      - any end-to-end headers provided in the 304 or 206 response MUST
        replace the corresponding headers from the cache entry.
Unless the cache decides to remove the cache entry, it MUST also replace the end-to-end headers 
stored with the cache entry with corresponding headers received in the incoming response, except for 
Warning headers as described immediately above. If a header field- name in the incoming response 
matches more than one header in the cache entry, all such old headers MUST be replaced.

In other words, the set of end-to-end headers received in the incoming response overrides all 
corresponding end-to-end headers stored with the cache entry (except for stored Warning headers with 
warn-code 1xx, which are deleted even if not overridden).
]]]

The correct resolution was to fix mod_jk, which the reporter said worked for them.

Please back this patch out.
Comment 18 Ruediger Pluem 2007-02-09 15:55:21 UTC
I respectfully disagree here. According to 10.3.5 the response must not / should
not contain any entity headers (depending on the validator type). Furthermore
10.3.5 states that this should prevent inconsistencies between the cached entity
body and the updated header. Content-type is an entity header and changing the
Content-type clearly would create inconsistencies between the cached entity body
and the updated header. So we are generous in what we acccept.
If you still disagree please continue this discussion on the
dev@httpd.apache.org list.
Comment 19 Mark Nottingham 2007-02-09 21:36:18 UTC
10.3.5 says:
 
[[[
If the conditional GET used a strong cache validator (see section 13.3.3), the response SHOULD NOT 
include other entity-headers. Otherwise (i.e., the conditional GET used a weak validator), the response 
MUST NOT include other entity-headers; this prevents inconsistencies between cached entity-bodies 
and updated headers.
]]]

That applies to the responses; it doesn't specify the behaviour of the cache when it receives such 
responses.

10.3.5 goes on to say 

[[[
If a cache uses a received 304 response to update a cache entry, the cache MUST update the entry to 
reflect any new field values given in the response.
]]]

However, your reading does make sense. Rather than try and second-guess an apparent inconsistency 
in the spec, I"ll follow up with the HTTP-WG list.