Bug 48364 - PHP-generated pages are not cached in spite of pertinent header entries
Summary: PHP-generated pages are not cached in spite of pertinent header entries
Status: REOPENED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_cache (show other bugs)
Version: 2.2.13
Hardware: Sun Solaris
: P2 normal with 4 votes (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-12-10 03:02 UTC by HWS
Modified: 2015-05-20 13:32 UTC (History)
5 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description HWS 2009-12-10 03:02:42 UTC
Whereas Apache 2.2.x mod_cache (with mod_disk_cache) works with both static files and CGI scripts (including such with #!/path/to/php-cgi), I have never been able to cache output of PHP (5.2.x) scripts handled by the handler+action method. Of course, I added pertinent header entries (Last-Modified, Expires, Cache-Control) by the PHP function header(), which were correct as shown by network sniffing and caused the browser cache to behave as expected. But no cache files appeared in the CacheRoot directory. Also directives CacheIgnoreCacheControl On, CacheIgnoreNoLastMod On, CacheStoreNoStore On have been tried, with no effect.
I did not use mod_php but one CGI and two FastCGI methods (alternatively) in the following ways (schematic):
# Common
 <FilesMatch "\.php$">
  SetHandler dophp
 </FilesMatch>
 Action dophp /phpact
 CacheRoot /somedir
 CacheEnable disk /
# For CGI:
 ScriptAlias /phpact /path/to/php-cgi
# For FastCGI with mod_fastcgi:
 ScriptAlias /phpact /path/to/php-fcgi
 FastCgiIpcDir /otherdir
 FastCgiServer /path/to/php-fcgi further_arguments
# For FastCGI with mod_proxy_fcgi (php-fcgi started separately with -b 54321):
 ProxyRequests Off
 ProxyPassMatch ^/phpact/(.+)$ fcgi://localhost:54321/$1

Note that PHP as such works perfectly in all three configurations (with cgi.fix_pathinfo=1 and cgi.force_redirect=1).
I searched the bug database and the documentation but could not find any hint.
Comment 1 Ruediger Pluem 2009-12-10 03:54:17 UTC
Please set the loglevl to debug, request one of your php pages and provide the log file.
Comment 2 HWS 2009-12-10 05:21:12 UTC
For CGI as well as for FastCGI with mod_fastcgi (have not tried mod_proxy_fcgi now), the only debug log entries are (both with identical time stamps):
[debug] mod_cache.c(131): Adding CACHE_SAVE filter for /test/tt.php
[debug] mod_cache.c(138): Adding CACHE_REMOVE_URL filter for /test/tt.php

The content of tt.php was (the Cache-Control line does not change anything):

<?php
header('Last-Modified: '.gmdate('D, d M Y H:i:s \G\M\T',filemtime('/docroot/test/tt.php')-10));
header('Expires: '.gmdate('D, d M Y H:i:s \G\M\T',time()+60));
#header('Cache-Control: public,max-age=60,must-revalidate');
ob_start();
?>
<html>
<head><title>Environment</title></head>
<body>
<h2>Environment Variables:</h2>
<?php
echo("TZ=".$_ENV["TZ"]."<br>");
echo("LC_CTYPE=".$_ENV["LC_CTYPE"]."<br>");
<!-- some more echo lines -->
?>
</body>
</html><?php header('Content-Length: '.ob_get_length()); ob_flush(); ?>
Comment 3 HWS 2009-12-10 07:29:22 UTC
CONJECTURE: "Action dophp /phpact" causes /test/tt.php to be internally rewritten to /phpact/test/tt.php (otherwise the functioning of "ProxyPassMatch ^/phpact/(.+)$ fcgi://localhost:54321/$1" would be incomprehensible). In fact, mod_action.c contains a call to ap_internal_redirect_handler which seems to do this. Then the cache might not recognize that the action-script output is related to the original URL. (I remember there are several caching issues in the bug database concerning mod_rewrite, which have been fixed. May be mod_action has to be treated in a similar way.)
Comment 4 Ruediger Pluem 2009-12-10 09:00:00 UTC
Please provide ALL log entries not only the debug ones.
Comment 5 HWS 2009-12-10 09:15:11 UTC
> Please provide ALL log entries not only the debug ones.
There are practically none. Graceful restart after setting LogLevel debug, with mod_fastcgi:

[Thu Dec 10 13:54:33 2009] [notice] suEXEC mechanism enabled (wrapper: /opt/dpiw
ww/apache2/sbin/suexec)
[Thu Dec 10 13:54:34 2009] [notice] Apache/2.2.13 (Unix) mod_fastcgi/2.4.6 confi
gured -- resuming normal operations
[Thu Dec 10 13:54:34 2009] [notice] FastCGI: process manager initialized (pid 23
046)
[Thu Dec 10 13:54:34 2009] [warn] FastCGI: server "/opt/dpiwww/php5/bin/php-fcgi
" started (pid 23052)
[Thu Dec 10 13:55:43 2009] [debug] mod_cache.c(131): Adding CACHE_SAVE filter fo
r /test/tt.php
[Thu Dec 10 13:55:43 2009] [debug] mod_cache.c(138): Adding CACHE_REMOVE_URL fil
ter for /test/tt.php

The last two lines repeat for each access of /test/tt.php, nothing else is logged.
Comment 6 Michael Stillwell 2010-02-21 12:15:56 UTC
I'm experiencing the same problem.  Here's the relevant logfile entries.  (LogLevel debug.)

First CGI load:

[Sun Feb 21 12:10:26 2010] [debug] mod_cache.c(131): Adding CACHE_SAVE filter for /scratch/cachetest.cgi
[Sun Feb 21 12:10:26 2010] [debug] mod_cache.c(138): Adding CACHE_REMOVE_URL filter for /scratch/cachetest.cgi
[Sun Feb 21 12:10:26 2010] [debug] mod_deflate.c(619): [client 10.0.2.2] Zlib: Compressed 15 to 17 : URL /scratch/cachetest.cgi
[Sun Feb 21 12:10:26 2010] [debug] mod_cache.c(633): cache: Caching url: /scratch/cachetest.cgi
[Sun Feb 21 12:10:26 2010] [debug] mod_cache.c(639): cache: Removing CACHE_REMOVE_URL filter.
[Sun Feb 21 12:10:26 2010] [info] mem_cache: Cached url: http://beebo.local:8080/scratch/cachetest.cgi?

Second CGI load (looks okay to me, and the CGI file itself is not hit):

[Sun Feb 21 12:10:34 2010] [debug] mod_cache.c(282): cache: running CACHE_OUT filter
[Sun Feb 21 12:10:34 2010] [debug] mod_cache.c(296): cache: serving /scratch/cachetest.cgi

First PHP load:

[Sun Feb 21 12:10:46 2010] [debug] mod_cache.c(131): Adding CACHE_SAVE filter for /scratch/cachetest.php
[Sun Feb 21 12:10:46 2010] [debug] mod_cache.c(138): Adding CACHE_REMOVE_URL filter for /scratch/cachetest.php

Second PHP load (identical to first):

[Sun Feb 21 12:10:56 2010] [debug] mod_cache.c(131): Adding CACHE_SAVE filter for /scratch/cachetest.php
[Sun Feb 21 12:10:56 2010] [debug] mod_cache.c(138): Adding CACHE_REMOVE_URL filter for /scratch/cachetest.php

Contents of cachetest.cgi:

#!/usr/bin/env bash

echo "Cache-Control: max-age=3600, public"
echo "Content-type: text/plain"
echo
echo "CGI cache test"

Full headers returned:

HTTP/1.1 200 OK
Date: Sun, 21 Feb 2010 12:11:29 GMT
Server: Apache/2.2.8 (Ubuntu) mod_fastcgi/2.4.6
Cache-Control: max-age=3600, public
Vary: Accept-Encoding
Content-Length: 15
Content-Type: text/plain; charset=utf-8

Contents of cachetest.php:

<?php

header("Cache-Control: max-age=3600, public");
header("Content-Type: text/plain");

echo "PHP cache test";

Full headers returned:

HTTP/1.1 200 OK
Date: Sun, 21 Feb 2010 12:11:18 GMT
Server: Apache/2.2.8 (Ubuntu) mod_fastcgi/2.4.6
X-Powered-By: PHP/5.3.1
Cache-Control: max-age=3600, public
Vary: Accept-Encoding
Transfer-Encoding: chunked
Content-Type: text/plain;charset=utf-8
X-Pad: avoid browser bug

In my case the PHP file is being served via FastCGI, if that makes a difference.
Comment 7 Ruediger Pluem 2010-02-21 13:14:29 UTC
(In reply to comment #6)
> I'm experiencing the same problem.  Here's the relevant logfile entries. 
> (LogLevel debug.)
> 
> First CGI load:
> 
> [Sun Feb 21 12:10:26 2010] [debug] mod_cache.c(131): Adding CACHE_SAVE filter
> for /scratch/cachetest.cgi
> [Sun Feb 21 12:10:26 2010] [debug] mod_cache.c(138): Adding CACHE_REMOVE_URL
> filter for /scratch/cachetest.cgi
> [Sun Feb 21 12:10:26 2010] [debug] mod_deflate.c(619): [client 10.0.2.2] Zlib:
> Compressed 15 to 17 : URL /scratch/cachetest.cgi
> [Sun Feb 21 12:10:26 2010] [debug] mod_cache.c(633): cache: Caching url:
> /scratch/cachetest.cgi
> [Sun Feb 21 12:10:26 2010] [debug] mod_cache.c(639): cache: Removing
> CACHE_REMOVE_URL filter.
> [Sun Feb 21 12:10:26 2010] [info] mem_cache: Cached url:
> http://beebo.local:8080/scratch/cachetest.cgi?

No you are not hitting the same problem since you use mod_mem_cache which has a process local cache. So you most likely hit a different httpd process in your second request. Try using mod_disk_cache and come back if the problem persists.
Comment 8 Michael Stillwell 2010-02-21 13:27:34 UTC
Yes you're right, that example was the memory cache.  (I was trying both.)  I get exactly the same results for the disk cache though:

First CGI:

[Sun Feb 21 13:23:54 2010] [debug] mod_cache.c(131): Adding CACHE_SAVE filter for /scratch/cachetest.cgi
[Sun Feb 21 13:23:54 2010] [debug] mod_cache.c(138): Adding CACHE_REMOVE_URL filter for /scratch/cachetest.cgi
[Sun Feb 21 13:23:54 2010] [debug] mod_cache.c(633): cache: Caching url: /scratch/cachetest.cgi
[Sun Feb 21 13:23:54 2010] [debug] mod_cache.c(639): cache: Removing CACHE_REMOVE_URL filter.
[Sun Feb 21 13:23:54 2010] [debug] mod_disk_cache.c(962): disk_cache: Stored headers for URL http://beebo.local:8080/scratch/cachetest.cgi?
[Sun Feb 21 13:23:54 2010] [debug] mod_disk_cache.c(1051): disk_cache: Body for URL http://beebo.local:8080/scratch/cachetest.cgi? cached.

Second CGI:

[Sun Feb 21 13:24:04 2010] [debug] mod_disk_cache.c(476): disk_cache: Recalled cached URL info header http://beebo.local:8080/scratch/cachetest.cgi?
[Sun Feb 21 13:24:04 2010] [debug] mod_disk_cache.c(749): disk_cache: Recalled headers for URL http://beebo.local:8080/scratch/cachetest.cgi?
[Sun Feb 21 13:24:04 2010] [debug] mod_cache.c(282): cache: running CACHE_OUT filter
[Sun Feb 21 13:24:04 2010] [debug] mod_cache.c(296): cache: serving /scratch/cachetest.cgi

First PHP:

[Sun Feb 21 13:24:31 2010] [debug] mod_cache.c(131): Adding CACHE_SAVE filter for /scratch/cachetest.php
[Sun Feb 21 13:24:31 2010] [debug] mod_cache.c(138): Adding CACHE_REMOVE_URL filter for /scratch/cachetest.php

Second PHP:

[Sun Feb 21 13:24:40 2010] [debug] mod_cache.c(131): Adding CACHE_SAVE filter for /scratch/cachetest.php
[Sun Feb 21 13:24:40 2010] [debug] mod_cache.c(138): Adding CACHE_REMOVE_URL filter for /scratch/cachetest.php

In the case of the CGI request, files are created in /var/cache/apache2/mod_disk_cache, as I'd expect.  In the case of the PHP request, they're not.
Comment 9 Ruediger Pluem 2010-02-21 14:04:07 UTC
(In reply to comment #8)
> Yes you're right, that example was the memory cache.  (I was trying both.)  I
> get exactly the same results for the disk cache though:

Please provide more debug output in the php case. I vaguely remember a PHP bug that mod_php sets r->no_cache and thus causing all content to be uncachable.
Comment 10 Michael Stillwell 2010-02-21 14:09:31 UTC
Thanks for looking into this. How do I get more debug output? I'm already at LogLevel debug.  There's a bug report on bugs.php.net that initially seemed somewhat related[1] but I think that one involves mod_php whereas I and the original reporter are both using mod_fastcgi.  Is there some way to turn on mod_fastcgi logging?

[1] http://bugs.php.net/bug.php?id=49106
Comment 11 Ruediger Pluem 2010-02-21 15:05:31 UTC
(In reply to comment #10)
> Thanks for looking into this. How do I get more debug output? I'm already at

There should be more debug lines from the cache in the log. Please copy and paste them here.

> LogLevel debug.  There's a bug report on bugs.php.net that initially seemed
> somewhat related[1] but I think that one involves mod_php whereas I and the
> original reporter are both using mod_fastcgi.  Is there some way to turn on
> mod_fastcgi logging?
> 
> [1] http://bugs.php.net/bug.php?id=49106

I guess this is the one I meant. Does the problem only happen if you execute the PHP script via mod_fastcgi and not if you use mod_cgi(d)?
Comment 12 HWS 2010-02-22 08:20:21 UTC
Let me remind that the problem seems not to be due to PHP as such (as initially reported, caching works for simple PHP CGI scripts) but occurs only with the Action mechanism, regardless whether CGI, FastCGI, or even mod_proxy_fcgi are used. Thus I still think (see Comment 3) that the problem is actually with mod_action and the comments for this bug should also be mailed to the people in charge for mod_action.
Comment 13 Graham Leggett 2010-10-18 19:50:45 UTC
I suspect the key reason that we're not seeing any debug output is potentially because the php stack is removing the existing filters from the stack, so the cache never gets an opportunity to run.

Closing this as worksforme for now, as we'd need clarification that php isn't doing this before we could debug this further. Please reopen if it turns out mod_cache needs to be looked at again.
Comment 14 HWS 2010-10-22 06:44:48 UTC
> because the php stack is removing the existing filters from the stack

What does this mean? The php processes are independent of the httpd process, since no Apache PHP module was used but external CGI or FastCGI php processes. I do not see how these could influence the Apache filter stack.
Comment 15 Ruediger Pluem 2010-10-22 08:44:49 UTC
Please retry with 2.2.17 as there are some fixes regarding the filter stack and internal redirects.
Comment 16 HWS 2010-10-25 06:56:14 UTC
There are no improvements with 2.2.17. Moreover, I now proved that the bug is not PHP related at all but due to the redirection by an Action+Handler. For this purpose, I made two simple CGI shell scripts tt.cgi (executable) and tt.msh of equal contents:
#!/bin/sh
LC_TIME=C date -u|awk '{print "Last-Modified: " $1 ", " $3 " " $2 " " $6 " " $4 " " $5}'
echo 'Cache-Control: public,max-age=60'
echo 'Content-type: text/html; charset=iso-8859-1'
echo
echo "<p>DOCUMENT_ROOT=$DOCUMENT_ROOT<br>
PATH_INFO=$PATH_INFO<br>
PATH_TRANSLATED=$PATH_TRANSLATED<br>
SCRIPT_NAME=$SCRIPT_NAME<br>
SCRIPT_FILENAME=$SCRIPT_FILENAME<br>
REQUEST_URI=$REQUEST_URI<br>
REDIRECT_URL=$REDIRECT_URL</p>"
# End of script

tt.cgi was run directly, whereas tt.msh was assigned a Handler and Action with another CGI shell script mysh taking the role of php-cgi:
  <FilesMatch "\.msh$">
    SetHandler mycgi
  </FilesMatch>
  Action mycgi /XyCgi
  ScriptAlias /XyCgi "/path/to/cgi-bin/mysh"
The script mysh contained:
#!/bin/sh
if [ -f "$PATH_TRANSLATED" ]
then . "$PATH_TRANSLATED"
else
echo 'Content-type: text/html


<h2>Not found</h2>'
fi
# End of script

The directly executed tt.cgi correctly entered and used cache entries:

[Mon Oct 25 12:17:13 2010] [debug] mod_disk_cache.c(977): disk_cache: Stored headers for URL http://dali.physik3.gwdg.de:8080/test/tt.cgi?
[Mon Oct 25 12:17:13 2010] [debug] mod_disk_cache.c(1079): disk_cache: Body for URL http://dali.physik3.gwdg.de:8080/test/tt.cgi? cached.
[Mon Oct 25 12:20:06 2010] [debug] mod_disk_cache.c(485): disk_cache: Recalled cached URL info header http://dali.physik3.gwdg.de:8080/test/tt.cgi?
[Mon Oct 25 12:20:06 2010] [debug] mod_disk_cache.c(758): disk_cache: Recalled headers for URL http://dali.physik3.gwdg.de:8080/test/tt.cgi?
[Mon Oct 25 12:20:06 2010] [debug] cache_util.c(591): Cache lock obtained for stale cached URL, revalidating entry: /test/tt.cgi
[Mon Oct 25 12:20:06 2010] [debug] cache_storage.c(272): Cached response for /test/tt.cgi isn't fresh.  Adding/replacing conditional request headers.
[Mon Oct 25 12:20:06 2010] [debug] mod_cache.c(141): Adding CACHE_SAVE filter for /test/tt.cgi
[Mon Oct 25 12:20:06 2010] [debug] mod_cache.c(148): Adding CACHE_REMOVE_URL filter for /test/tt.cgi
[Mon Oct 25 12:20:06 2010] [debug] mod_cache.c(705): cache: Caching url: /test/tt.cgi
[Mon Oct 25 12:20:06 2010] [debug] mod_cache.c(711): cache: Removing CACHE_REMOVE_URL filter.

The script tt.msh called through the Action did not cache; the only log entries were (as described in Comment 2 for PHP):
[Mon Oct 25 12:20:33 2010] [debug] mod_cache.c(141): Adding CACHE_SAVE filter for /test/tt.msh
[Mon Oct 25 12:20:33 2010] [debug] mod_cache.c(148): Adding CACHE_REMOVE_URL filter for /test/tt.msh

Thus this issue has nothing to do with PHP, but with Handler+Action, as already conjectured in my Comment 3. The Issue should be renamed or reopened under a different name.
Comment 17 Dave Taylor 2015-05-20 13:32:33 UTC
Apologies for resurrecting an oldish bug, but I've hit this in Apache 2.2.27 (and from looking at the relevant bits of code in 2.2.29 I can't see anything that's changed that would fix it).

From a bit of investigation it looks like what happens is:

1. mod_cache, in its quick handler, adds an output filter CACHE_SAVE to the request.
2. action_handler() in mod_actions calls ap_internal_redirect_handler() using the path that was set up in the "Action" directive.
3. ap_internal_redirect_handler() in turn calls internal_internal_redirect() to create a new request_rec, which strips off *all* the resource-specific output filters - including CACHE_SAVE.
4. ap_internal_redirect_handler() then *doesn't* call ap_run_quick_handler() for the new request_rec, so mod_cache doesn't get a look at the new request at all. N.b. this is different to the behaviour of ap_internal_redirect(), but perhaps deliberately so?

So it might be possible to resolve this by allowing ap_internal_redirect_handler() to run the quick handler against the new request_rec (but that might have unintended consequences for quick handlers in other modules than mod_cache?) Or it could perhaps be resolved by backporting CacheQuickHandler to 2.2.x so that mod_cache doesn't have to run "quick".

Or I may have misunderstood what's going on entirely(!)