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

[João Salavessa]

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

[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.

# 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);
 

[João Salavessa]

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!

[Sergey Kandaurov <pluknet@…>]

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".

[Sergey Kandaurov]

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

[João Salavessa]

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.