http 500 errors are not cached but go to the backend
brama
nginx-forum at nginx.us
Fri Jan 4 13:38:53 UTC 2013
Hi,
I've set up nginx (tested with 1.2.6 and 1.3.10) to cache all requests to
our fastcgi backends. If a cache entry expires, stale entries wil be served
while nginx is updating the cache. I'm using the fastcgi_cache_lock feature
to make sure only 1 request will be sent to the backend to update the
cache.
This works fine for everything but http 500 errors. If the backend produces
a http 500 result, it will initially be cached for the fastcgi_cache_valid
500 time (1 minute in my example), but when that expires, ALL requests for
that document will go to the backend, instead of coming out of the cache.
Also, the cache entry is never updated anymore, until it is removed from the
cache altogether after 10 minutes (the value of 'inactive' in
fastcgi_cache_path).
My cache config:
# in http context
fastcgi_cache_path /var/nginx/cache/content levels=1:2 keys_zone=content:24m
inactive=10m max_size=512M;
# in location context:
fastcgi_cache content;
# cache entire url, but only sig&exp query string parameters
fastcgi_cache_key $scheme|$host|$uri?sig=$arg_sig&exp=$arg_exp;
# Ignore caching headers from the response so that clients will not cache
# the results; nginx, however, will cache everything
fastcgi_ignore_headers Expires Cache-Control;
fastcgi_cache_valid 500 1m;
fastcgi_cache_valid any 1m;
# start caching at the first request
fastcgi_cache_min_uses 1;
# serve stale cache entries if the fastcgi backend acts up, and also while
# a new entry is being generated
# XXX for some reason, if http_500 is included here, EACH hit will go to
the
# backend as soon as the initial cache entry becomes stale. Bug?
fastcgi_cache_use_stale error timeout invalid_header updating http_500;
# only allow 1 backend request to generate a cache entry at any time; all
other
# connections wait for it.
fastcgi_cache_lock on;
# wait max 20s for a cache entry to be generated
fastcgi_cache_lock_timeout 20s;
As an example, I made the fastcgi backend log each & every request it
receives. I am hammering the server with ab -c100 -n500000 and this is what
the backend logs (each request produces a http 500):
# I start hammering here with 100 concurrent requests. Only 1 request is
received at the backend:
2013-01-03 22:00:33 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
# Now, it's quiet for exactly 1 minute, and then ALL requests go to the
backend:
2013-01-03 22:01:34 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
2013-01-03 22:01:34 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
2013-01-03 22:01:34 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
2013-01-03 22:01:34 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
2013-01-03 22:01:34 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
2013-01-03 22:01:34 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
2013-01-03 22:01:34 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
2013-01-03 22:01:34 content_server.dynamic.main:344 INFO CONTENT SERVER
BACKEND REQUEST FOR: http://myserver.localhost/dynamic/http_500.js
I've logged the cache status results in the logfile, and this is the
contents of the access log at the time the cache entry expires at 22:01:34:
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "STALE"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "STALE"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "STALE"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:01:34 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
<etc>
If I remove http_500 from fastcgi_cache_use_stale, THEN only 1 entry will go
to the backend if it expires, as desired. The access log then looks like
this as soon as the cache entry expires:
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:53 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:53 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:53 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:53 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:53 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "UPDATING"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "EXPIRED"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
"192.168.63.171" myserver.localhost - [03/Jan/2013:22:14:54 +0000] "GET
/dynamic/http_500.js HTTP/1.0" 500 31 "-" "ApacheBench/2.3" "HIT"
This seems counter-intuitive. If the http 500 document expires, nginx should
serve the stale cache entry until it has updated the cache entry. However,
with http_500 included in fastcgi_cache_use_stale, it never appears to
update the cache entry at all. Bug?
Posted at Nginx Forum: http://forum.nginx.org/read.php?2,234691,234691#msg-234691
More information about the nginx
mailing list