Opened 6 weeks ago

Closed 3 weeks ago

Last modified 2 weeks ago

#2029 closed defect (fixed)

Cache miss due to "cache file .. has too long header" when using "Vary"

Reported by: João Salavessa Owned by:
Priority: major Milestone:
Component: nginx-module Version: 1.19.x
Keywords: proxy cache vary Cc: João Salavessa
uname -a: Linux nginx-54959fc7bf-ncmrh 4.19.114 #1 SMP Mon Aug 3 12:35:22 PDT 2020 x86_64 Linux
nginx -V: nginx version: nginx/1.19.2
built by gcc 9.3.0 (Alpine 9.3.0)
built with OpenSSL 1.1.1g 21 Apr 2020
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib/nginx/modules --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/a
ccess.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cach
e/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --with-perl_modules_path=/usr/lib/perl5/vendor_perl --user=nginx --group=nginx --with-compat -
-with-file-aio --with-threads --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_mp4_module
--with-http_random_index_module --with-http_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module -
-with-mail --with-mail_ssl_module --with-stream --with-stream_realip_module --with-stream_ssl_module --with-stream_ssl_preread_module --with-cc-opt='-Os -fomit-frame-pointer' --with-ld-opt=-Wl,--as-needed

Description

There are some cases when "Vary" header is present and it changes value in a consequent call then a perfectly valid newly updated cache file (e.g. from a MISS) can trigger another MISS on the next exact same call due to "cache file .. has too long header" check.

Attached "nginx.conf" and "test-cases.sh" which contains description of issue and functions with call sequences that consistently reproduce the issue (tested on the current latest nginx versions 1.18.0 and 1.19.2):

  • the "returnVary" req header asks the server to return the request header value as Vary response header value
  • the "xtra" req header header asks the server to include a "Xtra" response header with the respective value

To execute attached test cases just start a local nginx using the attached "nginx.conf" file and:

# test cases execution: "loop" executes function in first argument, 4 times with 3s sleep between each (nginx.conf cache TTL is 5s)

# source test case functions
. ./test-cases.sh

# execution command examples
loop tc1 #not ok
loop tc2 #not ok
loop tc3 #ok
loop tc4 #ok
loop tc5 #ok
tc3_5; sleep 6; tc4_5 #not ok

Attachments (2)

nginx.conf (590 bytes ) - added by João Salavessa 6 weeks ago.
test-cases.sh (1.7 KB ) - added by João Salavessa 6 weeks ago.

Download all attachments as: .zip

Change History (8)

by João Salavessa, 6 weeks ago

Attachment: nginx.conf added

by João Salavessa, 6 weeks ago

Attachment: test-cases.sh added

comment:1 by Sergey Kandaurov, 3 weeks ago

Please try these changes.

The first change is for a different issue previously reported.
It would be nice if you could test with both applied and report back.

# HG changeset patch
# User Sergey Kandaurov <pluknet@nginx.com>
# Date 1501864657 -10800
#      Fri Aug 04 19:37:37 2017 +0300
# Node ID 847fd35f94def5a75fe2c2809daea1928b33d262
# Parent  da5e3f5b16733167142b599b6af3ce9469a07d52
Cache: reset c->body_start when reading a variant on Vary mismatch.

Previously, a variant not present in shared memory and stored on disk using a
secondary key was read using c->body_start from a variant stored with a main
key.  This could result in critical errors "cache file .. has too long header".

diff --git a/src/http/ngx_http_cache.h b/src/http/ngx_http_cache.h
--- a/src/http/ngx_http_cache.h
+++ b/src/http/ngx_http_cache.h
@@ -80,6 +80,7 @@ struct ngx_http_cache_s {
     ngx_str_t                        vary;
     u_char                           variant[NGX_HTTP_CACHE_KEY_LEN];
 
+    size_t                           buffer_size;
     size_t                           header_start;
     size_t                           body_start;
     off_t                            length;
diff --git a/src/http/ngx_http_file_cache.c b/src/http/ngx_http_file_cache.c
--- a/src/http/ngx_http_file_cache.c
+++ b/src/http/ngx_http_file_cache.c
@@ -294,6 +294,8 @@ ngx_http_file_cache_open(ngx_http_reques
         cln->data = c;
     }
 
+    c->buffer_size = c->body_start;
+
     rc = ngx_http_file_cache_exists(cache, c);
 
     ngx_log_debug2(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
@@ -1230,7 +1232,7 @@ ngx_http_file_cache_reopen(ngx_http_requ
 
     c->secondary = 1;
     c->file.name.len = 0;
-    c->body_start = c->buf->end - c->buf->start;
+    c->body_start = c->buffer_size;
 
     ngx_memcpy(c->key, c->variant, NGX_HTTP_CACHE_KEY_LEN);
 
# HG changeset patch
# User Sergey Kandaurov <pluknet@nginx.com>
# Date 1599668787 -10800
#      Wed Sep 09 19:26:27 2020 +0300
# Node ID 3781de64e747505b6975d47fd9655b8730128d1c
# Parent  847fd35f94def5a75fe2c2809daea1928b33d262
Cache: keep c->body_start when Vary changes (ticket #2029).

If the variant hash doesn't match one we used as a secondary cache key,
we switch back to the original key.  In this case, c->body_start was kept
updated from an existing cache node overwriting the new response value.
After file cache update, it led to discrepancy between a cache node and
cache file seen as critical errors "file cache .. has too long header".

diff --git a/src/http/ngx_http_cache.h b/src/http/ngx_http_cache.h
--- a/src/http/ngx_http_cache.h
+++ b/src/http/ngx_http_cache.h
@@ -117,6 +117,7 @@ struct ngx_http_cache_s {
     unsigned                         purged:1;
     unsigned                         reading:1;
     unsigned                         secondary:1;
+    unsigned                         update_variant:1;
     unsigned                         background:1;
 
     unsigned                         stale_updating:1;
diff --git a/src/http/ngx_http_file_cache.c b/src/http/ngx_http_file_cache.c
--- a/src/http/ngx_http_file_cache.c
+++ b/src/http/ngx_http_file_cache.c
@@ -854,7 +854,7 @@ ngx_http_file_cache_exists(ngx_http_file
         if (fcn->exists || fcn->uses >= c->min_uses) {
 
             c->exists = fcn->exists;
-            if (fcn->body_start) {
+            if (fcn->body_start && !c->update_variant) {
                 c->body_start = fcn->body_start;
             }
 
@@ -1339,6 +1339,7 @@ ngx_http_file_cache_update_variant(ngx_h
     ngx_shmtx_unlock(&cache->shpool->mutex);
 
     c->file.name.len = 0;
+    c->update_variant = 1;
 
     ngx_memcpy(c->key, c->main, NGX_HTTP_CACHE_KEY_LEN);
 

comment:2 by Sergey Kandaurov, 3 weeks ago

Keywords: proxy cache added; ngx_http_proxy_module removed
Status: newaccepted

comment:3 by João Salavessa, 3 weeks ago

I had already made exhaustive checks with the first patch applied and didn't really make any difference for the reported issue - but it didn't make it any worse either.
I'll test nginx with both patches applied and get back with the result.
Thanks!

comment:4 by Sergey Kandaurov <pluknet@…>, 3 weeks ago

In 7705:3781de64e747/nginx:

Cache: keep c->body_start when Vary changes (ticket #2029).

If the variant hash doesn't match one we used as a secondary cache key,
we switch back to the original key. In this case, c->body_start was kept
updated from an existing cache node overwriting the new response value.
After file cache update, it led to discrepancy between a cache node and
cache file seen as critical errors "file cache .. has too long header".

comment:5 by Sergey Kandaurov, 3 weeks ago

Resolution: fixed
Status: acceptedclosed

For the record, both changes were committed and should appear in 1.19.3.
But still, feedback is always welcome.

in reply to:  1 comment:6 by João Salavessa, 2 weeks ago

Replying to Sergey Kandaurov:

Please try these changes.

The first change is for a different issue previously reported.
It would be nice if you could test with both applied and report back.
[...]

I can confirm that everything is working as expected after applying the two patches.
Thanks for the commit and sorry for the delay in the reply.

Note: See TracTickets for help on using tickets.