cache revalidation bug

Roman Arutyunyan arut at nginx.com
Mon Mar 2 16:53:27 UTC 2015


Hello Jeffrey K,

On Fri, Feb 27, 2015 at 09:16:27AM +0100, Jeffrey K. wrote:
> I’m experiencing an issue that cached 404 responses are revalidated when the requested file are available again on the backend server with an older time stamp. Hereby the details of my issue.
> 
> 
> 
> Nginx version/build details
> 
> 	# nginx -V
> 	nginx version: nginx/1.7.10
> 	built by gcc 4.8.2 (Ubuntu 4.8.2-19ubuntu1) 
> 	TLS SNI support enabled
> 	configure arguments: --prefix=/usr/share/nginx --sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-client-body-temp-path=/var/lib/nginx/body --http-log-path=/var/log/nginx/access.log --http-proxy-temp-path=/tmp --lock-path=/var/lock/nginx.lock --pid-path=/var/run/nginx.pid --without-http_fastcgi_module --without-http_uwsgi_module --without-http_scgi_module --with-http_flv_module --with-http_geoip_module --with-http_gzip_static_module --with-http_mp4_module --with-http_realip_module --with-http_secure_link_module --with-http_stub_status_module --with-http_ssl_module --with-ipv6 --with-sha1=/usr/include/openssl --with-md5=/usr/include/openssl --with-aio_module --with-file-aio --with-http_spdy_module --with-debug
> 
> 
> vhost is configured with 
> 
> 	server {
> 	    listen              80;
> 
> 	    server_name         test.domain.tld;
> 	    set $origin         backend.domain.tld;
> 
> 	    expires             off;
> 
> 	    location /
> 	    {
> 	        client_max_body_size        0;
> 	        client_body_buffer_size     8k;
> 	        proxy_connect_timeout       60;
> 	        proxy_send_timeout          60;
> 	        proxy_read_timeout          60;
> 	        proxy_buffer_size           16k;
> 	        proxy_buffers               256 16k;
> 	        proxy_buffering             on;
> 	        proxy_max_temp_file_size    1m;
> 	        proxy_ignore_client_abort   on;
> 	        proxy_intercept_errors      on;
> 	        proxy_next_upstream         error timeout invalid_header;
> 	        
> 	        proxy_cache                 one;
> 	        proxy_cache_min_uses        1;
> 	        proxy_cache_lock            off;
> 	        proxy_cache_lock_timeout    5s;
> 
> 	        proxy_cache_valid           200 302 301 1m;
> 	        proxy_cache_valid           404 5s;
> 	        proxy_cache_revalidate      on;
> 
> 	        proxy_set_header            Host                    $origin;
> 	        proxy_pass_header           Set-Cookie;       
> 
> 	        proxy_set_header            Range                   "";
> 	        proxy_set_header            Request-Range           "";
> 	        proxy_set_header            If-Range                "";
> 
> 	        proxy_cache_key             "$scheme://$host$uri";
> 	        proxy_pass                  http://$origin$uri;
> 	        proxy_redirect              off;
> 	    }
> 	}
> 
> 
> 
> 
> Log format used
> 
> 	¦$bytes_sent¦$remote_addr¦$msec¦$status¦$http_referer¦$http_user_agent¦$request_time¦$request_method $request_uri $server_protocol¦$server_port¦$upstream_cache_status¦$upstream_status¦$upstream_response_time¦$request_completion¦$backend_server¦
> 
> 
> 
> Requesting non-existen file. 404 will be cached for 5 second
> after 5 seconds its expires, file is fetched from backend that gives 404 again
> 
> 	¦469¦[remote.ip.addr]¦1424963103.586¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦MISS¦404¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963104.605¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963108.679¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963109.724¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦EXPIRED¦404¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963110.742¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963114.815¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963115.860¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦EXPIRED¦404¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963116.879¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963120.952¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 
> 
> [Placed file on backend server (move), file has timestamp of year 2013]
> 404 expires, file is fetched from backend and cached
> 
> 	¦49166¦[remote.ip.addr]¦1424963122.033¦200¦-¦curl/7.35.0¦0.063¦GET /pica.jpg HTTP/1.1¦80¦EXPIRED¦200¦0.063¦OK¦[backend.server]¦
> 	¦49162¦[remote.ip.addr]¦1424963123.037¦200¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦49162¦[remote.ip.addr]¦1424963181.036¦200¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 
> 
> File expires, revalidation is send to backend and cached file is updated
> 
> 	¦49170¦[remote.ip.addr]¦1424963182.081¦200¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦REVALIDATED¦304¦0.027¦OK¦[backend.server]¦
> 	¦49162¦[remote.ip.addr]¦1424963183.098¦200¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦49162¦[remote.ip.addr]¦1424963242.103¦200¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 
> 
> [File is removed from backend]
> File expires, file is fetched from backend that gives 404
> 
> 	¦469¦[remote.ip.addr]¦1424963243.148¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦EXPIRED¦404¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963244.167¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963248.240¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963249.285¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦EXPIRED¦404¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963250.304¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963254.376¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 
> 
> [Placed file back on backend server (move), file has timestamp of year 2013]
> 404 expires, revalidation is done, because times stamp of file is older then time the 404 was fetched/cached it revalidates??
> - bug? it should not revalidate 404, just expire and fetch actual file!
> 
> 	¦469¦[remote.ip.addr]¦1424963255.421¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦REVALIDATED¦304¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963256.439¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963260.514¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963261.559¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦REVALIDATED¦304¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963262.577¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963266.650¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963267.697¦404¦-¦curl/7.35.0¦0.029¦GET /pica.jpg HTTP/1.1¦80¦REVALIDATED¦304¦0.029¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963268.715¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963272.788¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 
> 
> [File is removed from backend]
> Now the File expires, file is fetched from backend that gives 404 (probably because timestamp is newer?)
> 
> 	¦469¦[remote.ip.addr]¦1424963291.224¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦EXPIRED¦404¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963292.242¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963296.315¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963297.360¦404¦-¦curl/7.35.0¦0.027¦GET /pica.jpg HTTP/1.1¦80¦EXPIRED¦404¦0.027¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963298.379¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 	¦469¦[remote.ip.addr]¦1424963302.457¦404¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 
> 
> [Placed file back on backend server (copy), file has timestamp of current time
> 404 expires, revalidation is done??, because times stamp of file is newer then time the 404 was fetched/cached it actually fetches the file
> 
> 	¦49166¦[remote.ip.addr]¦1424963303.537¦200¦-¦curl/7.35.0¦0.059¦GET /pica.jpg HTTP/1.1¦80¦EXPIRED¦200¦0.059¦OK¦[backend.server]¦
> 	¦49162¦[remote.ip.addr]¦1424963304.544¦200¦-¦curl/7.35.0¦0.000¦GET /pica.jpg HTTP/1.1¦80¦HIT¦-¦-¦OK¦[backend.server]¦
> 
> 
> Regards,
> 
> Jeffrey K.
> 
> 
> 
> _______________________________________________
> nginx-devel mailing list
> nginx-devel at nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx-devel

Thanks for your report.

We've just committed a fix for this.

-- 
Roman Arutyunyan



More information about the nginx-devel mailing list