nginx >= 1.17.5 returns incomplete responses for certain proxied requests during reloads

[Jacob Henner]

nginx >= 1.17.5 is returning incomplete responses for a subset of proxied requests. My observations suggest this issue occurs when:

• nginx is handling a request proxied to an upstream
• The upstream's response is sufficiently large (exact size undetermined, the responses in my case were > 500Mi)
• The upstream's response triggers proxy buffering
• proxy_buffering is enabled (does not occur when buffering is disabled)
• There is a delay between the time nginx sends the request to the upstream, and the time at which the upstream returns data to nginx (e.g. the upstream service blocks on some computation before returning any data)
• During the delay between nginx's proxied request and the upstream's response, an nginx reload is triggered

Symptoms of the issue include:

• Incomplete response bodies - for example, truncated JSON
• Chunked responses where the last chunk sent does not match the chunk size specified (can be observed as a warning when curl runs in verbose mode).
• Socket leak entries in the nginx debug logs, for both the socket connecting to the client, and the socket connecting to the upstream
• Properly closed TCP connections - so no connection reset errors are propagated to the client

I first observed this issue in 1.20.2. I was able to reproduce it from 1.17.5 onward (spot checked), including the current mainline 1.23.0 and stable 1.22.0 versions. All reproductions occurred in the official docker-library nginx container images.

I suspect that the regression introduced in 1.17.5 that's described in ​https://mailman.nginx.org/pipermail/nginx-devel/2019-December/012829.html has a role here. It's my understanding that the regression was supposed to be fixed in 1.17.7, but perhaps that fix did not address this particular case. I speculate that a timer is missing, due to some issue with readv and event processing, which is causing the graceful shutdown process to prematurely terminate a worker process that's still returning buffered data to a client.

Additional details:

• TLS (SSL) is not in use
• aio is not enabled
• http2 is not enabled

I have attached nginx's configuration.

The socket leak log entries appear as:

`
10867:2022/07/08 19:52:49 [notice] 8799#0: exiting
10868:2022/07/08 19:52:49 [debug] 8799#0: flush files
10869:2022/07/08 19:52:49 [alert] 8799#0: *251 open socket #4 left in connection 2
10870:2022/07/08 19:52:49 [alert] 8799#0: *252 open socket #9 left in connection 4
10871:2022/07/08 19:52:49 [alert] 8799#0: aborting
`

[Jacob Henner]

As suggested in the nginx mailing list thread linked in my original submission, building nginx (1.20.2) with --with-cc-opt="-DNGX_HAVE_FIONREAD=0" appears to be a successful workaround for this issue as well.

[Maxim Dounin]

If are able to reproduce this, could you please provide ​debugging log? Likely it will be huge, given the size of responses involved, though should help to understand what goes wrong here.

[Jacob Henner]

Replying to Maxim Dounin:

If are able to reproduce this, could you please provide ​debugging log? Likely it will be huge, given the size of responses involved, though should help to understand what goes wrong here.

I've attached debug logs from an instance where this situation occurred. Some fields have been redacted, and only logs containing the PID of the affected worker process are shown. These logs were sourced from 1.20.2.

You may notice that these logs include references to several plugins, but the same issue was reproduced on many versions >= 1.17.5 with minimal configuration that included none of these plugins (see nginx.conf included with original report).

[Maxim Dounin]

Thanks for the log, it indeed helped a lot.

I think I understand what goes wrong here. Indeed, it's a regression introduced in efd71d49bde0, due to minor difference between ngx_readv_chain() and ngx_unix_recv() in EPOLLRDHUP handling. This also explains why the issue only appears with buffering enabled: non-buffered proxying uses ngx_unix_recv(), which works correctly.

Could you please test if the following patch helps?

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1657862022 -10800
#      Fri Jul 15 08:13:42 2022 +0300
# Node ID ce4ba7c0833536d567b623211e5a322b9786163a
# Parent  ae2d62bb12c00ebd014c147d7b37252ccfe72373
Events: fixed EPOLLRDHUP with FIONREAD (ticket #2367).

When reading exactly rev->available bytes, rev->available might become 0
after FIONREAD usage introduction in efd71d49bde0.  On the next call of
ngx_readv_chain() on systems with EPOLLRDHUP this resulted in return without
any actions, that is, with rev->ready set, and this in turn resulted in no
timers set in even pipe, leading to socket leaks.

Fix is to reset rev->ready in ngx_readv_chain() when returning due to
rev->available being 0 with EPOLLRDHUP, much like it is already done in
ngx_unix_recv().  This ensures that if rev->available will become 0, on
systems with EPOLLRDHUP support appropriate EPOLLRDHUP-specific handling
will happen on the next ngx_readv_chain() call.

While here, also synced ngx_readv_chain() to match ngx_unix_recv() and
reset rev->ready when returning due to rev->available being 0 with kqueue.
This is mostly cosmetic change, as rev->ready is anyway reset when
rev->available is set to 0.

diff --git a/src/os/unix/ngx_readv_chain.c b/src/os/unix/ngx_readv_chain.c
--- a/src/os/unix/ngx_readv_chain.c
+++ b/src/os/unix/ngx_readv_chain.c
@@ -46,6 +46,7 @@ ngx_readv_chain(ngx_connection_t *c, ngx
                 return 0;
 
             } else {
+                rev->ready = 0;
                 return NGX_AGAIN;
             }
         }
@@ -63,6 +64,7 @@ ngx_readv_chain(ngx_connection_t *c, ngx
                        rev->pending_eof, rev->available);
 
         if (rev->available == 0 && !rev->pending_eof) {
+            rev->ready = 0;
             return NGX_AGAIN;
         }
     }

[Sergey Kandaurov]

Replying to Maxim Dounin:

Thanks for the log, it indeed helped a lot.

I think I understand what goes wrong here. Indeed, it's a regression introduced in efd71d49bde0, due to minor difference between ngx_readv_chain() and ngx_unix_recv() in EPOLLRDHUP handling. This also explains why the issue only appears with buffering enabled: non-buffered proxying uses ngx_unix_recv(), which works correctly.

For the record, I couldn't find any traces in the internal review
why these checks were not implemented as part of f7849bfb6d21.

Could you please test if the following patch helps?

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1657862022 -10800
#      Fri Jul 15 08:13:42 2022 +0300
# Node ID ce4ba7c0833536d567b623211e5a322b9786163a
# Parent  ae2d62bb12c00ebd014c147d7b37252ccfe72373
Events: fixed EPOLLRDHUP with FIONREAD (ticket #2367).

When reading exactly rev->available bytes, rev->available might become 0
after FIONREAD usage introduction in efd71d49bde0.  On the next call of
ngx_readv_chain() on systems with EPOLLRDHUP this resulted in return without
any actions, that is, with rev->ready set, and this in turn resulted in no
timers set in even pipe, leading to socket leaks.
[...]

event

The patch looks good, tested with the below scenario I propose to commit:

# HG changeset patch
# User Sergey Kandaurov <pluknet@nginx.com>
# Date 1657891435 -14400
#      Fri Jul 15 17:23:55 2022 +0400
# Node ID 41e6aadc62e75a44f318ce62afd7357d015cc6d9
# Parent  f89770df737a8b034f47a885ed41dae090092c15
Tests: socket leaks with zero available bytes (ticket #2367).

diff -r f89770df737a -r 41e6aadc62e7 proxy_available.t
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/proxy_available.t	Fri Jul 15 17:23:55 2022 +0400
@@ -0,0 +1,137 @@
+#!/usr/bin/perl
+
+# (C) Sergey Kandaurov
+# (C) Nginx, Inc.
+
+# Tests for http proxy module with available bytes counting.
+
+###############################################################################
+
+use warnings;
+use strict;
+
+use Test::More;
+
+use IO::Select;
+
+BEGIN { use FindBin; chdir($FindBin::Bin); }
+
+use lib 'lib';
+use Test::Nginx qw/ :DEFAULT http_end /;
+
+###############################################################################
+
+select STDERR; $| = 1;
+select STDOUT; $| = 1;
+
+my $t = Test::Nginx->new()->has(qw/http proxy/)->plan(2);
+
+$t->write_file_expand('nginx.conf', <<'EOF');
+
+%%TEST_GLOBALS%%
+
+daemon off;
+
+events {
+}
+
+http {
+    %%TEST_GLOBALS_HTTP%%
+
+    server {
+        listen       127.0.0.1:8080;
+        server_name  localhost;
+
+        location /buffered {
+            proxy_pass http://127.0.0.1:8081;
+            proxy_buffer_size 512;
+        }
+
+        location /unbuffered {
+            proxy_pass http://127.0.0.1:8082;
+            proxy_buffer_size 512;
+            proxy_buffering off;
+        }
+    }
+}
+
+EOF
+
+$t->run_daemon(\&http_daemon, port(8081));
+$t->run_daemon(\&http_daemon, port(8082));
+$t->run();
+
+$t->waitforsocket('127.0.0.1:' . port(8081));
+$t->waitforsocket('127.0.0.1:' . port(8082));
+
+###############################################################################
+
+# ticket #2367: socket leaks with EPOLLRDHUP
+# due to missing rev->ready reset on rev->available == 0
+#
+# to reproduce leaks, the first part of the response should fit proxy buffer
+
+my $s = http_get('/buffered', start => 1);
+IO::Select->new($s)->can_read(3);
+
+$t->reload();
+
+TODO: {
+local $TODO = 'not yet' if $^O eq 'linux';
+
+like(http_end($s), qr/AND-THIS/, 'zero available - buffered');
+
+}
+
+$s = http_get('/unbuffered', start => 1);
+IO::Select->new($s)->can_read(3);
+
+$t->stop();
+
+like(http_end($s), qr/AND-THIS/, 'zero available - unbuffered');
+
+$t->todo_alerts() if $^O eq 'linux';
+
+###############################################################################
+
+sub http_daemon {
+	my ($port) = @_;
+
+	my $server = IO::Socket::INET->new(
+		Proto => 'tcp',
+		LocalHost => "127.0.0.1:$port",
+		Listen => 5,
+		Reuse => 1
+	)
+		or die "Can't create listening socket: $!\n";
+
+	local $SIG{PIPE} = 'IGNORE';
+
+	while (my $client = $server->accept()) {
+		$client->autoflush(1);
+
+		my $headers = '';
+		my $uri = '';
+
+		while (<$client>) {
+			$headers .= $_;
+			last if (/^\x0d?\x0a?$/);
+		}
+
+		next if $headers eq '';
+
+		my $r = <<EOF;
+HTTP/1.1 200 OK
+Connection: close
+
+EOF
+
+		$r = $r . 'x' x (512 - length($r));
+		print $client $r;
+
+		select undef, undef, undef, 1.1;
+		print $client 'AND-THIS';
+	}
+}
+
+###############################################################################

[Jacob Henner]

Replying to Maxim Dounin:

Thanks for the log, it indeed helped a lot.

I think I understand what goes wrong here. Indeed, it's a regression introduced in efd71d49bde0, due to minor difference between ngx_readv_chain() and ngx_unix_recv() in EPOLLRDHUP handling. This also explains why the issue only appears with buffering enabled: non-buffered proxying uses ngx_unix_recv(), which works correctly.

Could you please test if the following patch helps?

The proposed patch has been incorporated into a build of 1.20.2. After patching, I can no longer reproduce the issue as originally reported, which suggests that the patch has successfully addressed the issue.

[Maxim Dounin]

Replying to Sergey Kandaurov:

Replying to Maxim Dounin:

Thanks for the log, it indeed helped a lot.

I think I understand what goes wrong here. Indeed, it's a regression introduced in efd71d49bde0, due to minor difference between ngx_readv_chain() and ngx_unix_recv() in EPOLLRDHUP handling. This also explains why the issue only appears with buffering enabled: non-buffered proxying uses ngx_unix_recv(), which works correctly.

For the record, I couldn't find any traces in the internal review
why these checks were not implemented as part of f7849bfb6d21.

I believe I initially developed the FIONREAD code for ngx_unix_recv(). And since the code is generic for all platforms, I've avoided EPOLLRDHUP-specific checks for the rare case of rev->available == 0, and instead relied on the rev->ready to be set to 0 on the next call. I've overlooked that ngx_readv_chain() has slighly different EPOLLRDHUP handling, and none of the reviewers noticed this either.

Could you please test if the following patch helps?

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1657862022 -10800
#      Fri Jul 15 08:13:42 2022 +0300
# Node ID ce4ba7c0833536d567b623211e5a322b9786163a
# Parent  ae2d62bb12c00ebd014c147d7b37252ccfe72373
Events: fixed EPOLLRDHUP with FIONREAD (ticket #2367).

When reading exactly rev->available bytes, rev->available might become 0
after FIONREAD usage introduction in efd71d49bde0.  On the next call of
ngx_readv_chain() on systems with EPOLLRDHUP this resulted in return without
any actions, that is, with rev->ready set, and this in turn resulted in no
timers set in even pipe, leading to socket leaks.
[...]

event

Fixed, thnx.

The patch looks good,

Posted to nginx-devel@ and pushed to ​http://mdounin.ru/hg/nginx/.

tested with the below scenario I propose to commit:

# HG changeset patch
# User Sergey Kandaurov <pluknet@nginx.com>
# Date 1657891435 -14400
#      Fri Jul 15 17:23:55 2022 +0400
# Node ID 41e6aadc62e75a44f318ce62afd7357d015cc6d9
# Parent  f89770df737a8b034f47a885ed41dae090092c15
Tests: socket leaks with zero available bytes (ticket #2367).

diff -r f89770df737a -r 41e6aadc62e7 proxy_available.t
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/proxy_available.t	Fri Jul 15 17:23:55 2022 +0400
@@ -0,0 +1,137 @@
+#!/usr/bin/perl
+
+# (C) Sergey Kandaurov
+# (C) Nginx, Inc.
+
+# Tests for http proxy module with available bytes counting.
+
+###############################################################################
+
+use warnings;
+use strict;
+
+use Test::More;
+
+use IO::Select;
+
+BEGIN { use FindBin; chdir($FindBin::Bin); }
+
+use lib 'lib';
+use Test::Nginx qw/ :DEFAULT http_end /;
+
+###############################################################################
+
+select STDERR; $| = 1;
+select STDOUT; $| = 1;
+
+my $t = Test::Nginx->new()->has(qw/http proxy/)->plan(2);
+
+$t->write_file_expand('nginx.conf', <<'EOF');
+
+%%TEST_GLOBALS%%
+
+daemon off;
+
+events {
+}
+
+http {
+    %%TEST_GLOBALS_HTTP%%
+
+    server {
+        listen       127.0.0.1:8080;
+        server_name  localhost;
+
+        location /buffered {
+            proxy_pass http://127.0.0.1:8081;
+            proxy_buffer_size 512;
+        }
+
+        location /unbuffered {
+            proxy_pass http://127.0.0.1:8082;
+            proxy_buffer_size 512;
+            proxy_buffering off;
+        }
+    }
+}
+
+EOF
+
+$t->run_daemon(\&http_daemon, port(8081));
+$t->run_daemon(\&http_daemon, port(8082));
+$t->run();
+
+$t->waitforsocket('127.0.0.1:' . port(8081));
+$t->waitforsocket('127.0.0.1:' . port(8082));
+
+###############################################################################
+
+# ticket #2367: socket leaks with EPOLLRDHUP
+# due to missing rev->ready reset on rev->available == 0
+#
+# to reproduce leaks, the first part of the response should fit proxy buffer
+
+my $s = http_get('/buffered', start => 1);
+IO::Select->new($s)->can_read(3);
+
+$t->reload();
+
+TODO: {
+local $TODO = 'not yet' if $^O eq 'linux';
+
+like(http_end($s), qr/AND-THIS/, 'zero available - buffered');
+
+}
+
+$s = http_get('/unbuffered', start => 1);
+IO::Select->new($s)->can_read(3);
+
+$t->stop();
+
+like(http_end($s), qr/AND-THIS/, 'zero available - unbuffered');
+
+$t->todo_alerts() if $^O eq 'linux';
+
+###############################################################################
+
+sub http_daemon {
+	my ($port) = @_;
+
+	my $server = IO::Socket::INET->new(
+		Proto => 'tcp',
+		LocalHost => "127.0.0.1:$port",
+		Listen => 5,
+		Reuse => 1
+	)
+		or die "Can't create listening socket: $!\n";
+
+	local $SIG{PIPE} = 'IGNORE';
+
+	while (my $client = $server->accept()) {
+		$client->autoflush(1);
+
+		my $headers = '';
+		my $uri = '';
+
+		while (<$client>) {
+			$headers .= $_;
+			last if (/^\x0d?\x0a?$/);
+		}
+
+		next if $headers eq '';
+
+		my $r = <<EOF;
+HTTP/1.1 200 OK
+Connection: close
+
+EOF
+
+		$r = $r . 'x' x (512 - length($r));
+		print $client $r;
+
+		select undef, undef, undef, 1.1;
+		print $client 'AND-THIS';
+	}
+}
+
+###############################################################################

Looks good.

[Maxim Dounin]

Replying to Jacob Henner:

The proposed patch has been incorporated into a build of 1.20.2. After patching, I can no longer reproduce the issue as originally reported, which suggests that the patch has successfully addressed the issue.

Thanks for testing and thanks for reporting this.

[Maxim Dounin <mdounin@…>]

In 8058:f3510cb959d1/nginx:

Events: fixed EPOLLRDHUP with FIONREAD (ticket #2367).

When reading exactly rev->available bytes, rev->available might become 0
after FIONREAD usage introduction in efd71d49bde0. On the next call of
ngx_readv_chain() on systems with EPOLLRDHUP this resulted in return without
any actions, that is, with rev->ready set, and this in turn resulted in no
timers set in event pipe, leading to socket leaks.

Fix is to reset rev->ready in ngx_readv_chain() when returning due to
rev->available being 0 with EPOLLRDHUP, much like it is already done in
ngx_unix_recv(). This ensures that if rev->available will become 0, on
systems with EPOLLRDHUP support appropriate EPOLLRDHUP-specific handling
will happen on the next ngx_readv_chain() call.

While here, also synced ngx_readv_chain() to match ngx_unix_recv() and
reset rev->ready when returning due to rev->available being 0 with kqueue.
This is mostly cosmetic change, as rev->ready is anyway reset when
rev->available is set to 0.

[Maxim Dounin]

Fix committed, thanks for reporting this.

[Maxim Dounin]

See also #2411.