Http 500 errors are not cached but go to the backend

brama · January 4, 2013, 2:39pm

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”

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:

brama · January 4, 2013, 11:31pm

Hello!

On Fri, Jan 04, 2013 at 08:38:53AM -0500, brama wrote:

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.

Just a side note: the fastcgi_cache_lock directive doesn’t affect
update of the cache, it only affects adding new items to the
cache. To handle cache updating the “fastcgi_cache_use_stale
updating” should be used (it’s actually already in your config).

[…]

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?

The

fastcgi_cache_use_stale http_500;

in your config instructs nginx to don’t cache 500 response but
return stale cached content instead. As soon as original cached
resource expires - nginx starts to ask backend about new response,
but since 500 is returned it returns stale response to clients
instead.

In your case the behaviour looks a bit confusing as “original
cached resource” above is the same 500 response (cached as
fastcgi_cache_use_stale don’t affect initial content caching), but
the behaviour is as expected with your configuration - when you
ask nginx to cache 500 responses and to don’t use 500 responses
for cache update at the same time.

–
Maxim D.

brama · January 8, 2013, 11:19am

Hi Maxim,

Just a side note: the fastcgi_cache_lock directive doesn’t affect
update of the cache, it only affects adding new items to the
cache. To handle cache updating the “fastcgi_cache_use_stale
updating” should be used (it’s actually already in your config).

Ok, that’s good to know.

In your case the behaviour looks a bit confusing as “original
cached resource” above is the same 500 response (cached as
fastcgi_cache_use_stale don’t affect initial content caching), but
the behaviour is as expected with your configuration - when you
ask nginx to cache 500 responses and to don’t use 500 responses
for cache update at the same time.

Ok, got it. That was indeed confusing. Thanks for your explanation.

Bram

Posted at Nginx Forum: