NGINX does not update cached response of POST requests

[azhuchkov@…]

Recently I configured caching of POST requests. It's not user input, it is AJAX queries to build quite heavy UI, so I have just a few POST requests to cache. So, it works as expected, but NGINX does not update stale responses locking them forever (at least for days) and constantly returning x-cache-status: UPDATING.

What I've figured out:

Error records in log files (actually these are just several records that repeat):

...
2018/12/27 13:38:17 [alert] 28874#28874: ignore long locked inactive cache entry e1d0fe4a523e1b5245e4eb950e298ce0, count:1
2018/12/27 13:45:06 [alert] 28874#28874: ignore long locked inactive cache entry 56fc903ed9a8dccc1a788a42d4d93b0a, count:1
2018/12/27 13:45:06 [alert] 28874#28874: ignore long locked inactive cache entry c70cb1ddbef6ae13f513bfe14a5e430f, count:1
2018/12/27 13:45:08 [alert] 28874#28874: ignore long locked inactive cache entry 2f05b9d5547e361d6a3d910636b96948, count:1
2018/12/27 13:51:41 [alert] 28874#28874: ignore long locked inactive cache entry dc6f7d0f964d54df80f82c5728161ff0, count:1
2018/12/27 14:10:38 [alert] 28874#28874: ignore long locked inactive cache entry 81ef90871e9bbc0f9574054f0729933e, count:1
2018/12/27 14:11:05 [alert] 28874#28874: ignore long locked inactive cache entry d2e93972c8f7e14c29a837ff005e2648, count:1
2018/12/27 14:15:26 [alert] 28874#28874: ignore long locked inactive cache entry 1cef9ddcef8ba3cc6cc7b87dc0edc3d4, count:1
2018/12/27 14:38:17 [alert] 28874#28874: ignore long locked inactive cache entry e1d0fe4a523e1b5245e4eb950e298ce0, count:1
2018/12/27 14:45:06 [alert] 28874#28874: ignore long locked inactive cache entry 56fc903ed9a8dccc1a788a42d4d93b0a, count:1
2018/12/27 14:45:06 [alert] 28874#28874: ignore long locked inactive cache entry c70cb1ddbef6ae13f513bfe14a5e430f, count:1
...

Output of the sudo lsof | grep -i /tmp/nginx (I store my cache under /tmp):

nginx     28873             nginx   19r      REG              254,0      682     388945 /tmp/nginx/a/b0/56fc903ed9a8dccc1a788a42d4d93b0a
nginx     28873             nginx   22r      REG              254,0   128435     388951 /tmp/nginx/f/30/c70cb1ddbef6ae13f513bfe14a5e430f
nginx     28873             nginx   23r      REG              254,0   124038     389010 /tmp/nginx/8/94/2f05b9d5547e361d6a3d910636b96948
nginx     28873             nginx   24r      REG              254,0   127621     389411 /tmp/nginx/4/3d/1cef9ddcef8ba3cc6cc7b87dc0edc3d4
nginx     28873             nginx   25r      REG              254,0   119371     389441 /tmp/nginx/8/64/d2e93972c8f7e14c29a837ff005e2648
nginx     28873             nginx   26r      REG              254,0   113245     389451 /tmp/nginx/e/33/81ef90871e9bbc0f9574054f0729933e
nginx     28873             nginx   27r      REG              254,0    96842     389500 /tmp/nginx/0/ce/e1d0fe4a523e1b5245e4eb950e298ce0
nginx     28873             nginx   28r      REG              254,0   106964     389494 /tmp/nginx/0/ff/dc6f7d0f964d54df80f82c5728161ff0

Here we see that NGINX has opened cache entries and holds them (most likely) forever (all of them are POST responses).

Here is the output of the sudo pgrep -a nginx:

28871 nginx: master process /usr/sbin/nginx -c /etc/nginx/nginx.conf
28873 nginx: worker process
28874 nginx: cache manager process

Here is my config:

...
server {
    server_name  app;

    access_log /var/log/nginx/app/prod/access.log;
    error_log  /var/log/nginx/app/prod/error.log;

    location / {
        set $ae "";
        if ($http_accept_encoding ~* gzip) {
            set $ae "gzip";
        }

        proxy_pass         http://prod_backend;
        proxy_redirect     off;

        proxy_set_header   Host                 $host;
        proxy_set_header   X-Real-IP            $remote_addr;
        proxy_set_header   X-Forwarded-For      $proxy_add_x_forwarded_for;
        proxy_set_header   X-Forwarded-Proto    $scheme;

        proxy_cache                   app;
        proxy_cache_use_stale         error timeout updating http_500 http_502
                                      http_503 http_504;
        proxy_cache_methods           POST;
        proxy_cache_background_update on;
        #proxy_cache_lock              on;
        proxy_cache_valid             5s;
        proxy_cache_key               $ae$scheme$proxy_host$request_uri$request_body;

        add_header X-Cache-Status $upstream_cache_status;

        expires 5m;
    }
...  (SSL stuff ommited)      

So, I tried both options of the proxy_cache_lock and it did not help.

After restarting NGINX I still have stale responses with header x-cache-status: UPDATING. To get fresh values I need to drop the cache and restart NGINX.

Example of the POST request body:

{"output":{"id":"page-content","property":"children"},"inputs":[{"id":"url","property":"pathname"}]}

[azhuchkov@…]

Sorry, forgot to put cache and backend configs. Here they are:

upstream prod_backend {
    server unix:/tmp/app.prod.sock;
}

proxy_cache_path /tmp/nginx levels=1:2 keys_zone=app:1m max_size=100m
                 inactive=60m use_temp_path=off;

[azhuchkov@…]

I confirm the same issue for mainline version nginx/1.15.8: files of cached POST responses are shown as opened after first 2-3 site loadings.

[Maxim Dounin]

Could you please:

1. Make sure there are no 3rd party modules loaded. If there are any, please reproduce the problem without any 3rd party modules loaded.
2. Check if disabling proxy_cache_background_update changes anything. If you are able to reproduce the problem without background updates, please keep it disabled for the remaining steps.
3. Provide full configuration which triggers the problem, as printed by "nginx -T". (Please also consider reproducing the problem in test environment to minimize configuration needed.)
4. Provide ​debug log with at least one request which demonstrates the problem.

[Maxim Dounin]

Feedback timeout.