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?