js_body_filter sends empty body response when buffering is on

[gnomeby]

Hello.

I have a django application. Let's assume I have empty django project created by:

mkdir nginxtest
cd nginxtest/
python -m venv .venv
source .venv/bin/activate
pip install -U pip wheel django

django-admin startproject mytest .  # See https://docs.djangoproject.com/en/3.2/intro/tutorial01/
./manage.py migrate

vim mytest/settings.py  # Add: STATIC_ROOT = './static/'
./manage.py collectstatic

./manage.py runserver 0.0.0.0:8000

On nginx side I have the following configuration:

        location / {
            proxy_connect_timeout 10s;
            #proxy_buffering off;

            proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
            proxy_set_header X-Forwarded-Proto $scheme;
            proxy_set_header Host $http_host;
            proxy_redirect off;
            proxy_cache_valid 2m;
            proxy_cache_valid 404 1m;
            proxy_cache_key $uri;
            proxy_cache_use_stale timeout updating error http_502 http_503;  
            proxy_cache       proxy_cache;
            js_header_filter utils.bohHeaderFilter;
            js_body_filter utils.bohBodyFilter;
            proxy_pass  http://192.168.56.101:8000;
        }

utils.js

function bohBodyFilter(r, data, flags) {
    r.sendBuffer(data, flags);
}
function bohHeaderFilter(r) {
}
export default { bohHeaderFilter, bohBodyFilter };

So when I request resource with Content-Type!=text/html I get normal headers and empty body.

wget -v -S http://localhost/static/admin/css/fonts.css

If I comment js_header_filter and js_body_filter - everything is OK.
If I comment proxy_cache_use_stale WGET just freezes on getting body.
If I uncomment "proxy_buffering off;" - everything is OK.

nginx 1.20.1
njs 0.6.1

[xeioex]

Hi @gnomeby,

Is it still an issue for you?

[gnomeby]

Not for me. I'm sending X-Accel-Buffering=yes to disable proxy_buffering in case when output is not text/html. But I think this is the bug in general.

[ap-wtioit]

Hit this one on our servers this week. When using a simple body filter like this:

function my_simple_body_filter(r, data, flags) {
        r.warn("got " + data.length + " chars, flags: " + flags.last);
        r.sendBuffer(data, flags);
}

Fetching the resource (around 1600kB js) with curl from localhost over its own ip, gets the following log (OK):

service_1                  | 2022-08-18 14:40:10,857 1 INFO redacted werkzeug: 1.2.3.4 - - [18/Aug/2022 14:40:10] "GET /path/to/js.js HTTP/1.0" 200 - 7 0.004 0.020
nginx_1                    | 2022/08/18 14:40:10 [warn] 27#27: *7 js: got 3279 chars, flags: [object Object]
....
nginx_1                    | 2022/08/18 14:40:10 [warn] 27#27: *7 js: got 4096 chars, flags: [object Object]
nginx_1                    | 2022/08/18 14:40:10 [warn] 27#27: *7 js: got 3382 chars, flags: [object Object]
nginx_1                    | 2022/08/18 14:40:10 [warn] 27#27: *7 js: got 0 chars, flags: [object Object]
nginx_1                    | 1.2.3.4 - - [18/Aug/2022:14:40:10 +0000] "GET /path/to/js.js HTTP/1.1" 200 1726981 "-" "curl/7.81.0" "-"

Fetching the same url from another host over the same ip, gets the following log (FAIL):

service_1                  | 2022-08-18 14:39:03,634 1 INFO redacted werkzeug: 1.2.3.4 - - [18/Aug/2022 14:39:03] "GET /path/to/js.js HTTP/1.0" 200 - 7 0.004 0.020
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 js: got 3279 chars, flags: [object Object]
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 js: got 4096 chars, flags: [object Object]
...
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 js: got 4096 chars, flags: [object Object]
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 an upstream response is buffered to a temporary file /var/cache/nginx/proxy_temp/1/00/0000000001 while reading upstream, client: 1.2.3.4, server: , request: "GET /path/to/js.js HTTP/1.1", upstream: "http://172.16.4.207:1234/path/to/js.js", host: "nginx-redacted.redacted"
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 js: got 0 chars, flags: [object Object]
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 js: got 4096 chars, flags: [object Object]
....
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 js: got 4096 chars, flags: [object Object]
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 js: got 3382 chars, flags: [object Object]
nginx_1                    | 2022/08/18 14:39:03 [warn] 24#24: *1 js: got 0 chars, flags: [object Object]
nginx_1                    | 1.2.3.4 - - [18/Aug/2022:14:39:03 +0000] "GET /path/to/js.js HTTP/1.1" 200 80389 "-" "curl/7.58.0" "-"

Which results in curl waiting for the remaining bytes (1726981 - 80389) until it times out, when nginx thinks it already has delivered the full response. Looking like this (received bytes don't match exactly as this was before i reproduced it locally):

user@anotherhost ~ $ curl --resolve "nginx-redacted.redacted:80:1.2.3.4" 'http://nginx-redacted.redacted/path/to/js.js' | wc -l
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 69 1686k   69 1174k    0     0  18489      0  0:01:33  0:01:05  0:00:28     0
curl: (18) transfer closed with 524288 bytes remaining to read

Repeated logs of 4096 were replaced by ... . To me it looks like if nginx begins buffering to a temporary file the stream of chunks of data to the body filter is interrupted and doesn't get all the data it needs.

Tested with nginx 1.22.0 from dockerhub (https://hub.docker.com/layers/nginx/library/nginx/1.22/images/sha256-813c400b452834cea3f6b3231168a64a4310369ba9f0c571b2bd11c437d4284a?context=explore) to be close to the installation on our server where we noticed this first.

As a workarround in my real body filter i mark all responses that i do not need to change with r.done as soon as possible, which prevents the problem on our servers for now:

function my_simple_body_filter(r, data, flags) {
        if (r.variables.my_condition_matches) {
                r.sendBuffer(data.replace(/foo/g,"bar"), flags);
        } else {
                r.sendBuffer(data, flags);
                // if any data chunk is received where the rewrite condition is not met, we can pass all the chunks for this
                // request without any filtering. so we are done for this request.
                r.done();
        }
}

[xeioex]

Hi @ap-wtioit,

Thank you for the report, will look into it.

[t0mtaylor]

Having same issue, is it due to content length changing?

As seen in this issue, if i delete the header for content length there is no issue:

delete r.headersOut['Content-Length'];

#387

[ap-wtioit]

@t0mtaylor tested deleting the Content-Length header in js_header_filter, the issue (not all content gets forwarded) is still present, but curl / wget are not longer able to detect that not all content is sent:

user@anotherhost ~ $ curl --resolve "nginx-redacted.redacted:80:1.2.3.4" 'http://nginx-redacted.redacted/path/to/js.js' | wc -l
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 80389    0 80389    0     0   436k      0 --:--:-- --:--:-- --:--:--  436k
206

As you can see in the curl progress output and wc -l we are nowhere near retrieving the full 1686k i get when proxy buffer temporary file is not created (e.g. when running curl on the same host)

user@host ~ $ curl --resolve "nginx-redacted.redacted:80:1.2.3.4" 'http://nginx-redacted.redacted/path/to/js.js' | wc -l
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1686k    0 1686k    0     0  52.2M      0 --:--:-- --:--:-- --:--:-- 53.1M
4053

Deleting the header only gets rid of the side effect that curl times out but the js file delivered is still garbage after most of it's contents are missing.