httpd-bugs mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bugzi...@apache.org
Subject [Bug 55669] Mod_Cache caching 503 Errors
Date Thu, 20 Nov 2014 18:59:26 GMT
https://issues.apache.org/bugzilla/show_bug.cgi?id=55669

Tod Schmidt <tschmidty@yahoo.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |REOPENED
         Resolution|FIXED                       |---

--- Comment #17 from Tod Schmidt <tschmidty@yahoo.com> ---
This is still a problem with 2.4.10

The problem is not that we are adding headers it is that it is still caching it
even without any headers that would allow it. Here are logs from two responses,
the first it gets a 503 and caches it, the second it serves that bad content.

[Thu Nov 20 17:52:42.184507 2014] [proxy_http:trace3] [pid 4506]
mod_proxy_http.c(1420): [client 10.3.0.203:33820] Status from backend: 503
[Thu Nov 20 17:52:42.184557 2014] [proxy_http:trace4] [pid 4506]
mod_proxy_http.c(1103): [client 10.3.0.203:33820] Headers received from
backend:
[Thu Nov 20 17:52:42.184578 2014] [proxy_http:trace4] [pid 4506]
mod_proxy_http.c(1105): [client 10.3.0.203:33820] Date: Thu, 20 Nov 2014
17:52:10 GMT
[Thu Nov 20 17:52:42.184605 2014] [proxy_http:trace4] [pid 4506]
mod_proxy_http.c(1105): [client 10.3.0.203:33820] Server: Apache
[Thu Nov 20 17:52:42.184623 2014] [proxy_http:trace4] [pid 4506]
mod_proxy_http.c(1105): [client 10.3.0.203:33820] Content-Type: text/html
[Thu Nov 20 17:52:42.184640 2014] [proxy_http:trace4] [pid 4506]
mod_proxy_http.c(1105): [client 10.3.0.203:33820] Content-Length: 237
[Thu Nov 20 17:52:42.184657 2014] [proxy_http:trace4] [pid 4506]
mod_proxy_http.c(1105): [client 10.3.0.203:33820] Connection: close
[Thu Nov 20 17:52:42.184698 2014] [proxy_http:trace3] [pid 4506]
mod_proxy_http.c(1671): [client 10.3.0.203:33820] start body send
[Thu Nov 20 17:52:42.185448 2014] [proxy:debug] [pid 4506] proxy_util.c(2146):
AH00943: http: has released connection for (consumption1.tnc.org)
[Thu Nov 20 17:52:42.185553 2014] [headers:trace2] [pid 4506]
mod_headers.c(874): AH01502: headers: ap_headers_output_filter()
[Thu Nov 20 17:52:42.186002 2014] [cache:debug] [pid 4506] mod_cache.c(1330):
[client 10.3.0.203:33820] AH00769: cache: Caching url: /
[Thu Nov 20 17:52:42.186018 2014] [cache:debug] [pid 4506] mod_cache.c(1336):
[client 10.3.0.203:33820] AH00770: cache: Removing CACHE_REMOVE_URL filter.
[Thu Nov 20 17:52:42.186445 2014] [http:trace3] [pid 4506]
http_filters.c(1008): [client 10.3.0.203:33820] Response sent with status 503,
headers:
[Thu Nov 20 17:52:42.186460 2014] [http:trace5] [pid 4506]
http_filters.c(1015): [client 10.3.0.203:33820]   Date: Thu, 20 Nov 2014
17:52:10 GMT
[Thu Nov 20 17:52:42.186472 2014] [http:trace5] [pid 4506]
http_filters.c(1018): [client 10.3.0.203:33820]   Server: Apache
[Thu Nov 20 17:52:42.186486 2014] [http:trace4] [pid 4506] http_filters.c(837):
[client 10.3.0.203:33820]   Content-Type: text/html
[Thu Nov 20 17:52:42.186498 2014] [http:trace4] [pid 4506] http_filters.c(837):
[client 10.3.0.203:33820]   Content-Length: 237
[Thu Nov 20 17:52:42.186510 2014] [http:trace4] [pid 4506] http_filters.c(837):
[client 10.3.0.203:33820]   Cache-Control: public,max-age=1800
[Thu Nov 20 17:52:42.186522 2014] [http:trace4] [pid 4506] http_filters.c(837):
[client 10.3.0.203:33820]   Connection: close
[Thu Nov 20 17:52:42.188022 2014] [cache_disk:debug] [pid 4506]
mod_cache_disk.c(1350): [client 10.3.0.203:33820] AH00737: commit_entity:
Headers and body for URL http://www.nature.org:80/? cached.
[Thu Nov 20 17:52:42.188105 2014] [proxy_http:trace2] [pid 4506]
mod_proxy_http.c(1810): [client 10.3.0.203:33820] end body send
[Thu Nov 20 17:52:42.188129 2014] [core:trace6] [pid 4506] core_filters.c(527):
[client 10.3.0.203:33820] core_output_filter: flushing because of FLUSH bucket
[Thu Nov 20 17:52:42.188212 2014] [log_debug:trace4] [pid 4506]
util_expr_eval.c(822): [client 10.3.0.203:33820] Evaluation of string
expression from /usr/local/apache2/conf.d/local-11g.conf:54 gave: Status
(cache): 503
[Thu Nov 20 17:52:42.188227 2014] [log_debug:info] [pid 4506] [client
10.3.0.203:33820] Status (cache): 503 (log_transaction hook,
/usr/local/apache2/conf.d/local-11g.conf:54)
[Thu Nov 20 17:52:42.188622 2014] [core:trace6] [pid 4506] core_filters.c(527):
[client 10.3.0.203:33820] core_output_filter: flushing because of FLUSH bucket




[Thu Nov 20 17:53:21.091484 2014] [core:trace5] [pid 4505] protocol.c(618):
[client 10.3.0.203:33822] Request received from client: GET / HTTP/1.1
[Thu Nov 20 17:53:21.091710 2014] [http:trace4] [pid 4505] http_request.c(301):
[client 10.3.0.203:33822] Headers received from client:
[Thu Nov 20 17:53:21.091728 2014] [http:trace4] [pid 4505] http_request.c(305):
[client 10.3.0.203:33822]   User-Agent: curl/7.15.5 (i386-redhat-linux-gnu)
libcurl/7.15.5 OpenSSL/0.9.8b zlib/1.2.3 libidn/0.6.5
[Thu Nov 20 17:53:21.091764 2014] [http:trace4] [pid 4505] http_request.c(305):
[client 10.3.0.203:33822]   Accept: */*
[Thu Nov 20 17:53:21.091777 2014] [http:trace4] [pid 4505] http_request.c(305):
[client 10.3.0.203:33822]   host: www.nature.org
[Thu Nov 20 17:53:21.091809 2014] [cache:debug] [pid 4505]
cache_storage.c(664): [client 10.3.0.203:33822] AH00698: cache: Key for entity
/?(null) is http://www.nature.org:80/?
[Thu Nov 20 17:53:21.091935 2014] [cache_disk:debug] [pid 4505]
mod_cache_disk.c(572): [client 10.3.0.203:33822] AH00709: Recalled cached URL
info header http://www.nature.org:80/?
[Thu Nov 20 17:53:21.091963 2014] [cache_disk:debug] [pid 4505]
mod_cache_disk.c(885): [client 10.3.0.203:33822] AH00720: Recalled headers for
URL http://www.nature.org:80/?
[Thu Nov 20 17:53:21.091995 2014] [log_debug:trace4] [pid 4505]
util_expr_eval.c(822): [client 10.3.0.203:33822] Evaluation of string
expression from /usr/local/apache2/conf.d/local-11g.conf:54 gave: Status
(cache): 200
[Thu Nov 20 17:53:21.092010 2014] [log_debug:info] [pid 4505] [client
10.3.0.203:33822] Status (cache): 200 (insert_filter hook,
/usr/local/apache2/conf.d/local-11g.conf:54)
[Thu Nov 20 17:53:21.092032 2014] [cache:debug] [pid 4505] mod_cache.c(652):
[client 10.3.0.203:33822] AH00763: cache: running CACHE_OUT filter
[Thu Nov 20 17:53:21.092048 2014] [cache:debug] [pid 4505] mod_cache.c(681):
[client 10.3.0.203:33822] AH00764: cache: serving /
[Thu Nov 20 17:53:21.092075 2014] [http:trace3] [pid 4505]
http_filters.c(1008): [client 10.3.0.203:33822] Response sent with status 503,
headers:
[Thu Nov 20 17:53:21.092088 2014] [http:trace5] [pid 4505]
http_filters.c(1015): [client 10.3.0.203:33822]   Date: Thu, 20 Nov 2014
17:53:21 GMT
[Thu Nov 20 17:53:21.092100 2014] [http:trace5] [pid 4505]
http_filters.c(1018): [client 10.3.0.203:33822]   Server: Apache
[Thu Nov 20 17:53:21.092115 2014] [http:trace4] [pid 4505] http_filters.c(837):
[client 10.3.0.203:33822]   Content-Length: 237
[Thu Nov 20 17:53:21.092127 2014] [http:trace4] [pid 4505] http_filters.c(837):
[client 10.3.0.203:33822]   Cache-Control: public,max-age=1800
[Thu Nov 20 17:53:21.092138 2014] [http:trace4] [pid 4505] http_filters.c(837):
[client 10.3.0.203:33822]   Age: 103
[Thu Nov 20 17:53:21.092150 2014] [http:trace4] [pid 4505] http_filters.c(837):
[client 10.3.0.203:33822]   Connection: close
[Thu Nov 20 17:53:21.092161 2014] [http:trace4] [pid 4505] http_filters.c(837):
[client 10.3.0.203:33822]   Content-Type: text/html
[Thu Nov 20 17:53:21.092264 2014] [core:trace6] [pid 4505] core_filters.c(527):
[client 10.3.0.203:33822] core_output_filter: flushing because of FLUSH bucket
[Thu Nov 20 17:53:21.092477 2014] [log_debug:trace4] [pid 4505]
util_expr_eval.c(822): [client 10.3.0.203:33822] Evaluation of string
expression from /usr/local/apache2/conf.d/local-11g.conf:54 gave: Status
(cache): 503
[Thu Nov 20 17:53:21.092494 2014] [log_debug:info] [pid 4505] [client
10.3.0.203:33822] Status (cache): 503 (log_transaction hook,
/usr/local/apache2/conf.d/local-11g.conf:54)
[Thu Nov 20 17:53:21.092544 2014] [core:trace6] [pid 4505] core_filters.c(527):
[client 10.3.0.203:33822] core_output_filter: flushing because of FLUSH bucket

I even went so far as to add an unset for the headers

Header always unset Cache-Control "expr=%{REQUEST_STATUS} == '503'"

Which would presumably unset any headers and is after any other header
directives

[Thu Nov 20 18:46:31.413346 2014] [headers:trace4] [pid 5598]
util_expr_eval.c(837): [client 10.3.0.203:33825] Evaluation of expression from
/usr/local/apache2/conf.d/local-11g.conf:49 gave: 1

This seems to indicate that the header would have been removed but no luck

However, adding that expression as != to my existing header declaration does
work and appropriately does not cache.

Header set Cache-Control public,max-age=1800 "expr=%{REQUEST_STATUS} != '503'"

[Thu Nov 20 18:53:59.783143 2014] [headers:trace4] [pid 5635]
util_expr_eval.c(837): [client 10.3.0.203:33832] Evaluation of expression from
/usr/local/apache2/conf.d/local-11g.conf:49 gave: 1
[Thu Nov 20 18:53:59.783168 2014] [headers:trace4] [pid 5635]
util_expr_eval.c(837): [client 10.3.0.203:33832] Evaluation of expression from
/usr/local/apache2/conf.d/local-11g.conf:44 gave: 0
[Thu Nov 20 18:53:59.783213 2014] [cache:debug] [pid 5635] mod_cache.c(1212):
[client 10.3.0.203:33832] AH00768: cache: / not cached. Reason: Response status
503

So the code from ylavic does not seem to catch the error condition and still
adds the cache control headers. But using this as a workaround will do the job
for me and I can add conditions for the other errors with a regex but I don't
think this is fully resolved. I will keep an eye on this if there is a
different patch you would like me to test

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


Mime
View raw message