Opened 5 weeks ago

Closed 4 weeks ago

#2367 closed defect (fixed)

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

Reported by: Jacob Henner Owned by:
Priority: minor Milestone:
Component: nginx-core Version: 1.23.x
Keywords: Cc: Jacob Henner
uname -a: Linux fe6031582f6b 3.10.0-1160.15.2.el7.x86_64 #1 SMP Thu Jan 21 16:15:07 EST 2021 x86_64 GNU/Linux

Linux redacted 5.10.106-102.504.amzn2.x86_64 #1 SMP Tue Mar 29 23:15:13 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.17.5
built by gcc 8.3.0 (Debian 8.3.0-6)
built with OpenSSL 1.1.1c 28 May 2019 (running with OpenSSL 1.1.1d 10 Sep 2019)
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/access.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/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --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='-g -O2 -fdebug-prefix-map=/data/builder/debuild/nginx-1.17.5/debian/debuild-base/nginx-1.17.5=. -fstack-protector-strong -Wformat -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -fPIC' --with-ld-opt='-Wl,-z,relro -Wl,-z,now -Wl,--as-needed -pie'

nginx version: nginx/1.23.0
built by gcc 10.2.1 20210110 (Debian 10.2.1-6)
built with OpenSSL 1.1.1n 15 Mar 2022
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/access.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/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --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='-g -O2 -ffile-prefix-map=/data/builder/debuild/nginx-1.23.0/debian/debuild-base/nginx-1.23.0=. -fstack-protector-strong -Wformat -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -fPIC' --with-ld-opt='-Wl,-z,relro -Wl,-z,now -Wl,--as-needed -pie'

Description

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
`

Attachments (2)

nginx.conf (1.5 KB ) - added by Jacob Henner 5 weeks ago.
debug-logs-bad.txt (51.4 KB ) - added by Jacob Henner 4 weeks ago.

Download all attachments as: .zip

Change History (12)

by Jacob Henner, 5 weeks ago

Attachment: nginx.conf added

comment:1 by Jacob Henner, 5 weeks ago

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.

comment:2 by Maxim Dounin, 5 weeks ago

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.

by Jacob Henner, 4 weeks ago

Attachment: debug-logs-bad.txt added

in reply to:  2 comment:3 by Jacob Henner, 4 weeks ago

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

comment:4 by Maxim Dounin, 4 weeks ago

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;
         }
     }

in reply to:  4 ; comment:5 by Sergey Kandaurov, 4 weeks ago

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';
+	}
+}
+
+###############################################################################

in reply to:  4 ; comment:6 by Jacob Henner, 4 weeks ago

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.

Last edited 4 weeks ago by Jacob Henner (previous) (diff)

in reply to:  5 comment:7 by Maxim Dounin, 4 weeks ago

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.

in reply to:  6 comment:8 by Maxim Dounin, 4 weeks ago

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.

comment:9 by Maxim Dounin <mdounin@…>, 4 weeks ago

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.

comment:10 by Maxim Dounin, 4 weeks ago

Resolution: fixed
Status: newclosed

Fix committed, thanks for reporting this.

Note: See TracTickets for help on using tickets.