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