Bug 49113 - PDF's not reverse proxied / disk cached properly, and not accessible
Summary: PDF's not reverse proxied / disk cached properly, and not accessible
Status: RESOLVED FIXED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_cache (show other bugs)
Version: 2.2.15
Hardware: Sun Solaris
: P2 regression (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
: 49786 (view as bug list)
Depends on:
Blocks:
 
Reported: 2010-04-13 05:58 UTC by robert.blandward
Modified: 2012-05-29 20:01 UTC (History)
1 user (show)



Attachments
instance default access.log (1.60 KB, application/octet-stream)
2010-04-14 04:09 UTC, robert.blandward
Details
instance default error_log (296 bytes, application/octet-stream)
2010-04-14 04:09 UTC, robert.blandward
Details
initial v-host catch-all access_log (254 bytes, application/octet-stream)
2010-04-14 04:10 UTC, robert.blandward
Details
initial v-host catch-all error_log (360 bytes, application/octet-stream)
2010-04-14 04:10 UTC, robert.blandward
Details
main v-host client access v-host access_log (1.91 KB, application/octet-stream)
2010-04-14 04:12 UTC, robert.blandward
Details
main v-host client access v-host error_log (12.88 KB, application/octet-stream)
2010-04-14 04:13 UTC, robert.blandward
Details
proxypass and disk caching v-host access_log (735 bytes, application/octet-stream)
2010-04-14 04:15 UTC, robert.blandward
Details
proxypass and disk caching v-host error_log (8.87 KB, application/octet-stream)
2010-04-14 04:15 UTC, robert.blandward
Details
snoop output, non promiscuous, port 80, just for PDF access. (31.58 KB, application/octet-stream)
2010-04-14 04:17 UTC, robert.blandward
Details

Note You need to log in before you can comment on or make changes to this bug.
Description robert.blandward 2010-04-13 05:58:45 UTC
Hi,

I have recently re-compiled and make installed httpd 2.2.15 to upgrade our exisiting httpd 2.2.6 live environment. We use no third party modules.  Our config parameters (from our exisiting 2.2.6 config.nice) are:

"./configure" \
"--prefix=/usr/local/apache2_stellent" \
"--disable-ipv6" \
"--disable-auth" \
"--disable-autoindex" \
"--enable-cache" \
"--enable-disk-cache" \
"--enable-expires" \
"--enable-headers" \
"--enable-mime-magic" \
"--enable-proxy" \
"--enable-proxy-http" \
"--enable-rewrite" \
"--enable-vhost-alias" \
"$@"

I am building on Solaris 9 9/05, with Sunfreeware builds of gcc3.4.6 and libiconv 1.13.1.

configure, make and make install all work, and we are not modifying any makefiles.

We are using httpd in this case as a reverse proxy/httpd accellerator using disk-cache through to an Oracle/Stellent content manager (Win 2003SP2,IIS6)

What we are seeing though once using httpd 2.2.15 binaries, is that when accessing PDF's using firefox, the document window (viewing inside firefox) will display the first page, but when scrolling down it will lock temporarily (approx 3-4 minutes) and then error saying "There was an error reading this document (14)". That, or the document will immediately fail to load with the error "There was an error processing a page. There was a problem reading this document (109).

Viewing the same document in IE7, winxp sp2, the page does not load at all and says "Internet explorer cannot download xxx.pdf from xxx.  Internet explorer was not able to open this internet site.  The requested site is either unavailable or cannot be found.  Please try again later."

There is nothing in the error_log.  The access_log (for same document) only reports:

IE access entry:
*removed* - - [13/Apr/2010:10:41:51 +0100] "GET /consumption/groups/public/documents/article/ncc043240.pdf HTTP/1.1" 206 23801 "http://*removed*/consumption/idcplg?IdcService=SS_GET_PAGE&ssDocName=NCC007171" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729)"

Firefox access entries:
*removed* - - [13/Apr/2010:10:50:21 +0100] "GET /consumption/groups/public/documents/article/ncc043240.pdf HTTP/1.1" 206 23801 "http://*removed*/consumption/idcplg?IdcService=SS_GET_PAGE&ssDocName=NCC007171" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-GB; rv:1.9.2.3) Gecko/20100401 Firefox/3.6.3 (.NET CLR 3.5.30729)"
*removed* - - [13/Apr/2010:10:50:21 +0100] "GET /consumption/groups/public/documents/article/ncc043240.pdf HTTP/1.1" 206 23801 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-GB; rv:1.9.2.3) Gecko/20100401 Firefox/3.6.3 (.NET CLR 3.5.30729)"

The PDF being accesses above is multipage and colour, and above the filesize threshold so is being accessed using byterange requests.

In my investigation so far, I have compiled all versions of httpd 2.2.x since 2.2.6 to see when the problem appeared, and the last version it worked in was 2.2.11.  The problems first appeared in 2.2.12, and appear to be identical in minor version 13, 14 and 15.

Pease can we find out why this broke in builds after 11?

Regards,
Rob
Comment 1 Ruediger Pluem 2010-04-13 08:26:37 UTC
Does it work without caching enabled?
Comment 2 robert.blandward 2010-04-13 08:43:12 UTC
(In reply to comment #1)
> Does it work without caching enabled?

Yes.

I have commented out the disk caching v-host directives:

CacheRoot /apachedata/cache/wsaNCC
CacheEnable disk /
CacheDirLevels 5
CacheDirLength 3
CacheIgnoreNoLastMod On
CacheLastModifiedFactor 1
CacheDefaultExpire 79200
CacheMaxExpire 79200
CacheStorePrivate On

and the PDF's can be loaded multiple times, on multiple browsers without error, albeit slowly.
Comment 3 Ruediger Pluem 2010-04-13 11:21:35 UTC
Please do the following with caching enabled.

1. Set loglevel to debug and attach the output of the logfiles.
2. Capture the traffic for a failing document and attach the network snapshot.
3. Check if the files in the cache root are complete or if they were already corrupted during caching.

Question: Does it work for the first request, when the document is not cached yet?
Comment 4 Ruediger Pluem 2010-04-13 11:32:25 UTC
What is the complete size / length of the PDF requested in your logs?
Comment 5 Ruediger Pluem 2010-04-13 11:48:52 UTC
Does the following patch fix your issue?

Index: modules/cache/mod_cache.c
===================================================================
--- modules/cache/mod_cache.c   (revision 933687)
+++ modules/cache/mod_cache.c   (working copy)
@@ -473,7 +473,8 @@
          * We include 304 Not Modified here too as this is the origin server
          * telling us to serve the cached copy.
          */
-        if (exps != NULL || cc_out != NULL) {
+        if ((exps != NULL || cc_out != NULL)
+            && r->status != HTTP_PARTIAL_CONTENT) {
             /* We are also allowed to cache any response given that it has a
              * valid Expires or Cache Control header. If we find a either of
              * those here,  we pass request through the rest of the tests. From
@@ -486,6 +487,9 @@
              * include the following: an Expires header (section 14.21); a
              * "max-age", "s-maxage",  "must-revalidate", "proxy-revalidate",
              * "public" or "private" cache-control directive (section 14.9).
+             *
+             * But do NOT store 206 responses in any case since we
+             * don't (yet) cache partial responses.
              */
         }
         else {
Comment 6 Ruediger Pluem 2010-04-13 11:56:21 UTC
One last remark: Please clean your disk cache before testing the patch as it may contain corrupted versions of the PDF file.
Comment 7 robert.blandward 2010-04-14 04:09:21 UTC
Created attachment 25281 [details]
instance default access.log
Comment 8 robert.blandward 2010-04-14 04:09:53 UTC
Created attachment 25282 [details]
instance default error_log
Comment 9 robert.blandward 2010-04-14 04:10:33 UTC
Created attachment 25283 [details]
initial v-host catch-all access_log
Comment 10 robert.blandward 2010-04-14 04:10:55 UTC
Created attachment 25284 [details]
initial v-host catch-all error_log
Comment 11 robert.blandward 2010-04-14 04:12:52 UTC
Created attachment 25285 [details]
main v-host client access v-host access_log
Comment 12 robert.blandward 2010-04-14 04:13:17 UTC
Created attachment 25286 [details]
main v-host client access v-host error_log
Comment 13 robert.blandward 2010-04-14 04:15:19 UTC
Created attachment 25287 [details]
proxypass and disk caching v-host access_log
Comment 14 robert.blandward 2010-04-14 04:15:44 UTC
Created attachment 25288 [details]
proxypass and disk caching v-host error_log
Comment 15 robert.blandward 2010-04-14 04:17:53 UTC
Created attachment 25289 [details]
snoop output, non promiscuous, port 80, just for PDF access.
Comment 16 robert.blandward 2010-04-14 04:24:00 UTC
(In reply to comment #3)
> Please do the following with caching enabled.
> 
> 1. Set loglevel to debug and attach the output of the logfiles.
> 2. Capture the traffic for a failing document and attach the network snapshot.
> 3. Check if the files in the cache root are complete or if they were already
> corrupted during caching.
> 
> Question: Does it work for the first request, when the document is not cached
> yet?

1. Logfiles attached
2. Snoop output attached
3. The cache element 'data' portion is only 24K, and does contain PDF data, byterange, but is not complete due to its size. The PDF used in the examples above is 499132 bytes.

I have been clearing down the disk cache in-between each test, and can therefore confirm that the PDF is not in disk cache, and cannot be viewed on initial access.
Comment 17 robert.blandward 2010-04-14 06:05:51 UTC
(In reply to comment #5)
> Does the following patch fix your issue?
> 
> Index: modules/cache/mod_cache.c
> ===================================================================
> --- modules/cache/mod_cache.c   (revision 933687)
> +++ modules/cache/mod_cache.c   (working copy)
> @@ -473,7 +473,8 @@
>           * We include 304 Not Modified here too as this is the origin server
>           * telling us to serve the cached copy.
>           */
> -        if (exps != NULL || cc_out != NULL) {
> +        if ((exps != NULL || cc_out != NULL)
> +            && r->status != HTTP_PARTIAL_CONTENT) {
>              /* We are also allowed to cache any response given that it has a
>               * valid Expires or Cache Control header. If we find a either of
>               * those here,  we pass request through the rest of the tests.
> From
> @@ -486,6 +487,9 @@
>               * include the following: an Expires header (section 14.21); a
>               * "max-age", "s-maxage",  "must-revalidate", "proxy-revalidate",
>               * "public" or "private" cache-control directive (section 14.9).
> +             *
> +             * But do NOT store 206 responses in any case since we
> +             * don't (yet) cache partial responses.
>               */
>          }
>          else {


I have made these changes, and at first testing, they appear to have resolved the issue.  Not only that, but the entire PDF (approx 480k) is cached despite it being requested by byterange.

Is this a regression issue from 2.2.12 onwards, or was the caching of partial_content requests purposefully allowed as desirable functionality?
Comment 18 Ruediger Pluem 2010-04-14 08:01:35 UTC
(In reply to comment #17)

> I have made these changes, and at first testing, they appear to have resolved
> the issue.  Not only that, but the entire PDF (approx 480k) is cached despite
> it being requested by byterange.
> 
> Is this a regression issue from 2.2.12 onwards, or was the caching of
> partial_content requests purposefully allowed as desirable functionality?

This is a regression. Fixed in trunk as r933919.
Comment 19 robert.blandward 2010-04-14 08:12:26 UTC
(In reply to comment #18)
> (In reply to comment #17)
> 
> > I have made these changes, and at first testing, they appear to have resolved
> > the issue.  Not only that, but the entire PDF (approx 480k) is cached despite
> > it being requested by byterange.
> > 
> > Is this a regression issue from 2.2.12 onwards, or was the caching of
> > partial_content requests purposefully allowed as desirable functionality?
> 
> This is a regression. Fixed in trunk as r933919.

Great news.  Thanks for your time and help.
Comment 20 Ruediger Pluem 2010-08-20 02:45:38 UTC
*** Bug 49786 has been marked as a duplicate of this bug. ***
Comment 21 Duncan Harris 2011-09-06 08:36:05 UTC
When is this fix likely to be merged into 2.2.x ? Seems like a fairly serious regression and thus worth fixing in the current best version a.s.a.p. We are following the 2.2.x track and have had to manually apply the patch from r933919.
Comment 22 Ruediger Pluem 2011-09-06 12:04:43 UTC
(In reply to comment #21)
> When is this fix likely to be merged into 2.2.x ? Seems like a fairly serious
> regression and thus worth fixing in the current best version a.s.a.p. We are
> following the 2.2.x track and have had to manually apply the patch from
> r933919.

Proposed for backport as r1165626.
Comment 23 Colin Leroy 2012-05-02 12:21:18 UTC
(In reply to comment #22)
> (In reply to comment #21)
> > When is this fix likely to be merged into 2.2.x ? Seems like a fairly serious
> > regression and thus worth fixing in the current best version a.s.a.p. We are
> > following the 2.2.x track and have had to manually apply the patch from
> > r933919.
> 
> Proposed for backport as r1165626.

Is there any status update about this backport ? I'm bitten by that bug and manually patch Debian's Apache2 (2.2.16) each time the package is updated.

Thanks!
Comment 24 Stefan Fritsch 2012-05-29 20:01:20 UTC
will be in 2.2.23: r1343951