Nginx core dump explodes

Server NGINX
1

nginx version: nginx/1.11.1
built with OpenSSL 1.0.2h 3 May 2016

I try to debug those alerts currently, which only appear after a reload:

2016/06/17 13:10:49 [alert] 14624#0: *15709 open socket #626 left in
connection 628

I compiled nginx with --with-debug and set the flags CFLAGS=“-g -O0”
./configure…

The following core dump settings are defined:

debug_points abort;
working_directory /var/tmp/cores/;
worker_rlimit_core 512M;
error_log /var/log/nginx/error.log debug;

I can see that it starts to generate the core file but it becomes very
large
(>500GB) and removes it at the end.

Any idea what I’m doing wrong here?

Thanks!

Posted at Nginx Forum:

2

Hello!

On Fri, Jun 17, 2016 at 07:30:26AM -0400, martinproinity wrote:

Any idea what I’m doing wrong here?
The “worker_rlimit_core 512M” line in your configuration suggests
that the kernel should not generate core files bigger than 512M.
If a worker process core takes more than that, the behaviour you
describe looks more or less normal.

–
Maxim D.
http://nginx.org/

3

Thanks, setting the value to 600G made it possible to get a dump. But it
took ages and the system became quite unstable.

What can cause the dump to become that large? There is almost no traffic
(<10Mbps) on this server with 32G memory.

Posted at Nginx Forum:

4

Hello!

On Tue, Jun 21, 2016 at 02:53:48AM -0400, martinproinity wrote:

Thanks, setting the value to 600G made it possible to get a dump. But it
took ages and the system became quite unstable.

What can cause the dump to become that large? There is almost no traffic
(<10Mbps) on this server with 32G memory.

You haven’t said how large the resulting dump, but in general a
dump reflects memory used by the process. Something like “top” or
“ps” should give you a good idea of how large a dump is expected to
be.

Most obvious reason why processes can use lots of memory is using
very big shared memory zones, e.g., in proxy_cache_path keys_zone.
Also, given the fact that you are debugging a socket leak (in a custom
module, I guess?), processes can be large due to leaks
accumulated.

–
Maxim D.
http://nginx.org/

5

On Tuesday 21 June 2016 16:00:53 martinproinity wrote:

The dump was 550GB large. So I guess the only explanation for this are the
accumulated keys_zone sizes.

There are no third-party modules. We only see the leaks for specific HTTP/2
traffic at every reload.

[…]

Could you collect a debug log with these leaks?
http://nginx.org/en/docs/debugging_log.html

wbr, Valentin V. Bartenev

6

The dump was 550GB large. So I guess the only explanation for this are
the
accumulated keys_zone sizes.

There are no third-party modules. We only see the leaks for specific
HTTP/2
traffic at every reload.

Posted at Nginx Forum:

7

I already did. Is there something specific I should look after in that
debug
log?

Here a little extract (note: I replaced the request with ):

…
2016/06/19 19:53:11 [debug] 8724#0: *19047 event timer: 63, old:
1466358851127, new: 1466358851267
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream exit:
0000000000000000
2016/06/19 19:53:11 [debug] 8724#0: *19047 finalize http upstream
request:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 finalize http proxy request
2016/06/19 19:53:11 [debug] 8724#0: *19047 free rr peer 1 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 close http upstream
connection:
63
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 0000000031A9EE00,
unused:
48
2016/06/19 19:53:11 [debug] 8724#0: *19047 event timer del: 63:
1466358851127
2016/06/19 19:53:11 [debug] 8724#0: *19047 reusable connection: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream temp fd: -1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http finalize request: 0,
“” a:1, c:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate request
count:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate cleanup
count:1
blk:0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http posted request:
“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate handler
count:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http request count:1 blk:0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 close stream 3, queued
0,
processing 1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http close request
2016/06/19 19:53:11 [debug] 8724#0: *19047 http log handler
2016/06/19 19:53:11 [debug] 8724#0: *19047 run cleanup: 000000002DDEE350
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000355360C0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000202F2600,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001E88A800,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002DDED500,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000207AF4B0,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002027BE40,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002FCE5840,
unused:
1348
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000003DABCC40
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001D295C40
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 0000000024A93CD0,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001D2E8D10,
unused:
828
2016/06/19 19:53:11 [debug] 8724#0: *19047 post event 000000000582ABD0
2016/06/19 19:53:11 [debug] 8724#0: *19047 delete posted event
000000000582ABD0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 handle connection
handler
2016/06/19 19:54:12 [alert] 8724#0: *19047 open socket #236 left in
connection 181
…

Posted at Nginx Forum:

8

On Wednesday 22 June 2016 09:11:55 martinproinity wrote:

I already did. Is there something specific I should look after in that debug
log?

Here a little extract (note: I replaced the request with ):

[…]

I need the full log since the moment when the socket was created and
till
the message when it was left.

I.e.:

2016/06/19 10:08:01 [debug] 9538#9538: *19047 accept: 127.0.0.1:46586
fd:236
…
2016/06/19 19:54:12 [alert] 9538#9538: *19047 open socket #236 left in
connection 181

wbr, Valentin V. Bartenev

9

On Wednesday 22 June 2016 11:31:27 martinproinity wrote:

Here more of the debug log. I had to shorten it as I did get this message
“Please shorten your messages, the body is too large”.
[…]

Partial log doesn’t help because I need to follow up all the events in
the
connection till it has lost.

You can upload your log to any file sharing service like Google Drive
and
post a link here.

wbr, Valentin V. Bartenev

10

Here you go: https://tempfile.me/dl/ES9tWLqjnFozdx/

Thanks!

Posted at Nginx Forum:

11

Here more of the debug log. I had to shorten it as I did get this
message
“Please shorten your messages, the body is too large”.

Thanks!

2016/06/19 19:53:09 [debug] 8724#0: *19047 accept: :54691
fd:236
2016/06/19 19:53:09 [debug] 8724#0: *19047 event timer add: 236:
60000:1466358849721
2016/06/19 19:53:09 [debug] 8724#0: *19047 reusable connection: 1
2016/06/19 19:53:09 [debug] 8724#0: *19047 epoll add event: fd:236 op:1
ev:80002001
2016/06/19 19:53:09 [debug] 8724#0: *19047 post event 000000000582ABD0
2016/06/19 19:53:09 [debug] 8724#0: *19047 delete posted event
000000000582ABD0
2016/06/19 19:53:09 [debug] 8724#0: *19047 http check ssl handshake
2016/06/19 19:53:09 [debug] 8724#0: *19047 http recv(): 1
2016/06/19 19:53:09 [debug] 8724#0: *19047 https ssl handshake: 0x16
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL server name: “”
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL certificate status
callback
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL ALPN supported by client:
h2
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL ALPN supported by client:
http/1.1
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL ALPN selected: h2
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL_do_handshake: -1
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL_get_error: 2
2016/06/19 19:53:09 [debug] 8724#0: *19047 reusable connection: 0
2016/06/19 19:53:09 [debug] 8724#0: *19047 post event 000000000582ABD0
2016/06/19 19:53:09 [debug] 8724#0: *19047 delete posted event
000000000582ABD0
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL handshake handler: 0
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL_do_handshake: 1
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL: TLSv1.2, cipher:
“ECDHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(256)
Mac=AEAD”
2016/06/19 19:53:09 [debug] 8724#0: *19047 init http2 connection
2016/06/19 19:53:09 [debug] 8724#0: *19047 posix_memalign:
000000001F3528D0:512 @16
2016/06/19 19:53:09 [debug] 8724#0: *19047 posix_memalign:
0000000032745F00:4096 @16
2016/06/19 19:53:09 [debug] 8724#0: *19047 add cleanup: 0000000025319398
2016/06/19 19:53:09 [debug] 8724#0: *19047 posix_memalign:
0000000030012A10:512 @16
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 send SETTINGS frame
ack:0
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 send WINDOW_UPDATE
frame
sid:0, window:2147418112
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 read handler
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL_read: 58
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL_read: -1
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL_get_error: 2
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 preface verified
2016/06/19 19:53:09 [debug] 8724#0: *19047 process http2 frame type:4
f:0
l:12 sid:0
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 send SETTINGS frame
ack:1
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 frame complete
pos:0000000003E1943D end:0000000003E1944A
2016/06/19 19:53:09 [debug] 8724#0: *19047 process http2 frame type:8
f:0
l:4 sid:0
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 WINDOW_UPDATE frame
sid:0
window:10420225
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 frame complete
pos:0000000003E1944A end:0000000003E1944A
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 frame out:
00000000327460B8
sid:0 bl:0 len:0
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 frame out:
0000000032746008
sid:0 bl:0 len:4
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 frame out:
0000000032745F50
sid:0 bl:0 len:18
2016/06/19 19:53:09 [debug] 8724#0: *19047 malloc:
00000000359DE090:16384
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL buf copy: 27
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL buf copy: 13
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL buf copy: 9
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL to write: 49
2016/06/19 19:53:09 [debug] 8724#0: *19047 SSL_write: 49
2016/06/19 19:53:09 [debug] 8724#0: *19047 tcp_nodelay
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 frame sent:
0000000032745F50 sid:0 bl:0 len:18
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 frame sent:
0000000032746008 sid:0 bl:0 len:4
2016/06/19 19:53:09 [debug] 8724#0: *19047 http2 frame sent:
00000000327460B8 sid:0 bl:0 len:0
2016/06/19 19:53:09 [debug] 8724#0: *19047 free: 0000000032745F00,
unused:
3495
2016/06/19 19:53:09 [debug] 8724#0: *19047 free: 00000000359DE090
2016/06/19 19:53:09 [debug] 8724#0: *19047 reusable connection: 1
2016/06/19 19:53:09 [debug] 8724#0: *19047 event timer del: 236:
1466358849721
2016/06/19 19:53:09 [debug] 8724#0: *19047 event timer add: 236:
180000:1466358969975
2016/06/19 19:53:10 [debug] 8724#0: *19047 post event 000000000582ABD0
2016/06/19 19:53:10 [debug] 8724#0: *19047 delete posted event
000000000582ABD0
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 idle handler
2016/06/19 19:53:10 [debug] 8724#0: *19047 reusable connection: 0
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
0000000024124080:4096 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 read handler
2016/06/19 19:53:10 [debug] 8724#0: *19047 SSL_read: -1
2016/06/19 19:53:10 [debug] 8724#0: *19047 SSL_get_error: 2
2016/06/19 19:53:10 [debug] 8724#0: *19047 free: 0000000024124080,
unused:
4016
2016/06/19 19:53:10 [debug] 8724#0: *19047 reusable connection: 1
2016/06/19 19:53:10 [debug] 8724#0: *19047 event timer: 236, old:
1466358969975, new: 1466358970001
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 idle handler
2016/06/19 19:53:10 [debug] 8724#0: *19047 reusable connection: 0
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
0000000024489380:4096 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 read handler
2016/06/19 19:53:10 [debug] 8724#0: *19047 SSL_read: 1947
2016/06/19 19:53:10 [debug] 8724#0: *19047 SSL_read: -1
2016/06/19 19:53:10 [debug] 8724#0: *19047 SSL_get_error: 2
2016/06/19 19:53:10 [debug] 8724#0: *19047 process http2 frame type:1
f:5
l:1938 sid:1
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 HEADERS frame sid:1 on
0
excl:0 weight:16
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
00000000254B06B0:1024 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
000000003D78A750:4096 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
000000003D8EA8E0:4096 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header
name: 2
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header: 4
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack encoded string
length: 610
2016/06/19 19:53:10 [debug] 8724#0: *19047 malloc: 000000001B070A80:977
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 add header to hpack
table:
“:path: ”
2016/06/19 19:53:10 [debug] 8724#0: *19047 malloc: 000000001F2E7E20:512
2016/06/19 19:53:10 [debug] 8724#0: *19047 malloc: 000000003D93F010:4096
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack table account:
826
free:4096
2016/06/19 19:53:10 [debug] 8724#0: *19047 http uri: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http args: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http exten: “php”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header: 1
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack encoded string
length: 10
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 add header to hpack
table:
“:authority: ”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack table account: 55
free:3270
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header
name: 7
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header: 19
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack encoded string
length: 37
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 add header to hpack
table:
“accept: text/html, application/xhtml+xml, image/jxr, /”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack table account: 86
free:3215
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 http header: “accept:
text/html, application/xhtml+xml, image/jxr, /”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header: 51
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack encoded string
length: 282
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 add header to hpack
table:
“referer: ”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack table account:
423
free:3129
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 http header: “referer:
”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header: 17
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack encoded string
length: 28
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 add header to hpack
table:
“accept-language: de-DE,de;q=0.8,en-US;q=0.5,en;q=0.3”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack table account: 82
free:2706
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 http header:
“accept-language: de-DE,de;q=0.8,en-US;q=0.5,en;q=0.3”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header: 58
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack encoded string
length: 97
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 add header to hpack
table:
“user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64)
AppleWebKit/537.36
(KHTML, like Gecko) Chrome/46.0.2486.0 Safari/537.36 Edge/13.10586”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack table account:
169
free:2624
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
0000000020C10000:512 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 http header:
“user-agent:
Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML,
like
Gecko) Chrome/46.0.2486.0 Safari/537.36 Edge/13.10586”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header
name:
16
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 http header:
“accept-encoding: gzip, deflate”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 get indexed header: 32
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack encoded string
length: 851
2016/06/19 19:53:10 [debug] 8724#0: *19047 malloc: 000000003DB55BC0:1362
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 add header to hpack
table:
“cookie: ”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 hpack table account:
1117
free:2455
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 http request line: “GET
HTTP/2.0”
2016/06/19 19:53:10 [debug] 8724#0: *19047 rewrite phase: 0
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script value:
“”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script set
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script value:
“”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script set
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var
2016/06/19 19:53:10 [debug] 8724#0: *19047 http map started
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “Mozilla/5.0
(Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko)
Chrome/46.0.2486.0 Safari/537.36 Edge/13.10586”
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
000000003D8FED10:4096 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 http map: “Mozilla/5.0
(Windows
NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko)
Chrome/46.0.2486.0 Safari/537.36 Edge/13.10586” “0”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “0”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script if
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script if: false
2016/06/19 19:53:10 [debug] 8724#0: *19047 test location: “/”
2016/06/19 19:53:10 [debug] 8724#0: *19047 test location: “robots.txt”
2016/06/19 19:53:10 [debug] 8724#0: *19047 test location: “error/”
2016/06/19 19:53:10 [debug] 8724#0: *19047 using configuration “/”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http cl:-1 max:10485760
2016/06/19 19:53:10 [debug] 8724#0: *19047 rewrite phase: 2
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script if
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script if: false
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script value:
“”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script set
2016/06/19 19:53:10 [debug] 8724#0: *19047 post rewrite phase: 3
2016/06/19 19:53:10 [debug] 8724#0: *19047 generic phase: 4
2016/06/19 19:53:10 [debug] 8724#0: *19047 generic phase: 5
2016/06/19 19:53:10 [debug] 8724#0: *19047 access phase: 6
2016/06/19 19:53:10 [debug] 8724#0: *19047 access phase: 7
2016/06/19 19:53:10 [debug] 8724#0: *19047 post access phase: 8
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http body new buf t:0 f:0
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2016/06/19 19:53:10 [debug] 8724#0: *19047 http init upstream, client
timer:
0
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
000000002152A130:4096 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http cache key: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 add cleanup: 000000003D8FFB60
2016/06/19 19:53:10 [debug] 8724#0: *19047 http file cache exists: -5
e:0
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream cache: 8
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy: "Host: "
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy: "
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy:
"X-Forwarded-Host: "
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy: "
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy:
"X-Forwarded-For: "
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy: "
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy:
"Accept-Encoding: gzip
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy:
“Connection:
close
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy:
“Content-Length: "
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script var: “0”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy: "
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http script copy: “”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “accept:
text/html, application/xhtml+xml, image/jxr, /”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “referer:
”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“accept-language: de-DE,de;q=0.8,en-US;q=0.5,en;q=0.3”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“user-agent:
Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML,
like
Gecko) Chrome/46.0.2486.0 Safari/537.36 Edge/13.10586”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “cookie:
”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
2016/06/19 19:53:10 [debug] 8724#0: *19047 http cleanup add:
000000003D8FFCB8
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream resolve:
“”
2016/06/19 19:53:10 [debug] 8724#0: *19047 name was resolved to

2016/06/19 19:53:10 [debug] 8724#0: *19047 get rr peer, try: 1
2016/06/19 19:53:10 [debug] 8724#0: *19047 stream socket 306
2016/06/19 19:53:10 [debug] 8724#0: *19047 epoll add connection: fd:306
ev:80002005
2016/06/19 19:53:10 [debug] 8724#0: *19047 connect to :80,
fd:306
#19097
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream connect: -2
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
000000001D23A100:128 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 event timer add: 306:
60000:1466358850013
2016/06/19 19:53:10 [debug] 8724#0: *19047 http finalize request: -4,
“” a:1, c:2
2016/06/19 19:53:10 [debug] 8724#0: *19047 http request count:2 blk:0
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 frame complete
pos:0000000003E19BAB end:0000000003E19BAB
2016/06/19 19:53:10 [debug] 8724#0: *19047 event timer del: 236:
1466358969975
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream request:
“”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream send request
handler
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream send request
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream send request
body
2016/06/19 19:53:10 [debug] 8724#0: *19047 chain writer buf fl:0 s:2734
2016/06/19 19:53:10 [debug] 8724#0: *19047 chain writer buf fl:1 s:0
2016/06/19 19:53:10 [debug] 8724#0: *19047 chain writer in:
000000002152B0B0
2016/06/19 19:53:10 [debug] 8724#0: *19047 writev: 2734 of 2734
2016/06/19 19:53:10 [debug] 8724#0: *19047 chain writer out:
0000000000000000
2016/06/19 19:53:10 [debug] 8724#0: *19047 event timer del: 306:
1466358850013
2016/06/19 19:53:10 [debug] 8724#0: *19047 event timer add: 306:
60000:1466358850118
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 read handler
2016/06/19 19:53:10 [debug] 8724#0: *19047 SSL_read: 9
2016/06/19 19:53:10 [debug] 8724#0: *19047 SSL_read: -1
2016/06/19 19:53:10 [debug] 8724#0: *19047 SSL_get_error: 2
2016/06/19 19:53:10 [debug] 8724#0: *19047 process http2 frame type:4
f:1
l:0 sid:0
2016/06/19 19:53:10 [debug] 8724#0: *19047 http2 frame complete
pos:0000000003E19419 end:0000000003E19419
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream request:
“”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http upstream process header
2016/06/19 19:53:10 [debug] 8724#0: *19047 malloc:
0000000030EB0420:16384
2016/06/19 19:53:10 [debug] 8724#0: *19047 posix_memalign:
0000000022657FD0:4096 @16
2016/06/19 19:53:10 [debug] 8724#0: *19047 recv: eof:0, avail:1
2016/06/19 19:53:10 [debug] 8724#0: *19047 recv: fd:306 2811 of 15427
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy status 200 “200
OK”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “Server:
Apache/2.2.22 (Debian)”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“X-Powered-By:
PHP/5.4.45-1~dotdeb+7.1”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “P3P:
CP=”””
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie:
”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie:
”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie:
”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie:
”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie:
”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Cache-Control: no-cache”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “Vary:
Accept-Encoding”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Content-Encoding: gzip”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Content-Type:
text/html”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Content-Length: 3582”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Accept-Ranges: bytes”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “Date:
Sun, 19
Jun 2016 17:53:10 GMT”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“X-Varnish:
491225986”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “Age: 0”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header: “Via: 1.1
varnish”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header:
“Connection:
close”
2016/06/19 19:53:10 [debug] 8724#0: *19047 http proxy header done

…

2016/06/19 19:53:11 [debug] 8724#0: *19047 http file cache free, fd: -1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy filter init s:200
h:0
c:0 l:3582
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream process
upstream
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe read upstream: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe preread: 572
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe buf free s:0 t:1 f:0
00000000355360C0, pos 00000000355367E4, size: 572 file: 0, size: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe length: 3582
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe write downstream: 1
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe write busy: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe write:
out:0000000000000000,
f:0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe read upstream: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe buf free s:0 t:1 f:0
00000000355360C0, pos 00000000355367E4, size: 572 file: 0, size: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe length: 3582
2016/06/19 19:53:11 [debug] 8724#0: *19047 event timer: 63, old:
1466358851127, new: 1466358851267
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream request:
“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream dummy handler
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream request:
“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream process
upstream
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe read upstream: 1
2016/06/19 19:53:11 [debug] 8724#0: *19047 readv: eof:1, avail:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 readv: 1, last:13984
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe recv chain: 3010
2016/06/19 19:53:11 [debug] 8724#0: *19047 readv: eof:1, avail:0
2016/06/19 19:53:11 [debug] 8724#0: *19047 readv: 1, last:10974
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe recv chain: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe buf free s:0 t:1 f:0
00000000355360C0, pos 00000000355367E4, size: 3582 file: 0, size: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe length: 3582
2016/06/19 19:53:11 [debug] 8724#0: *19047 input buf #0
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe write downstream: 1
2016/06/19 19:53:11 [debug] 8724#0: *19047 pipe write downstream flush
in
2016/06/19 19:53:11 [debug] 8724#0: *19047 http output filter
“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http copy filter: “”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http postpone filter
“”
000000002027C008
2016/06/19 19:53:11 [debug] 8724#0: *19047 http copy filter: -1
“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 event timer: 63, old:
1466358851127, new: 1466358851267
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream exit:
0000000000000000
2016/06/19 19:53:11 [debug] 8724#0: *19047 finalize http upstream
request:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 finalize http proxy request
2016/06/19 19:53:11 [debug] 8724#0: *19047 free rr peer 1 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 close http upstream
connection:
63
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 0000000031A9EE00,
unused:
48
2016/06/19 19:53:11 [debug] 8724#0: *19047 event timer del: 63:
1466358851127
2016/06/19 19:53:11 [debug] 8724#0: *19047 reusable connection: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream temp fd: -1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http finalize request: 0,
“” a:1, c:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate request
count:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate cleanup
count:1
blk:0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http posted request:
“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate handler
count:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http request count:1 blk:0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 close stream 3, queued
0,
processing 1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http close request
2016/06/19 19:53:11 [debug] 8724#0: *19047 http log handler
2016/06/19 19:53:11 [debug] 8724#0: *19047 run cleanup: 000000002DDEE350
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000355360C0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000202F2600,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001E88A800,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002DDED500,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000207AF4B0,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002027BE40,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002FCE5840,
unused:
1348
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000003DABCC40
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001D295C40
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 0000000024A93CD0,
unused:
0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001D2E8D10,
unused:
828
2016/06/19 19:53:11 [debug] 8724#0: *19047 post event 000000000582ABD0
2016/06/19 19:53:11 [debug] 8724#0: *19047 delete posted event
000000000582ABD0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 handle connection
handler
2016/06/19 19:54:12 [alert] 8724#0: *19047 open socket #236 left in
connection 181

Posted at Nginx Forum:

12

On Wednesday 22 June 2016 14:50:27 martinproinity wrote:

Here you go: https://tempfile.me/dl/ES9tWLqjnFozdx/

Thanks!

Please try the patch:
http://pp.nginx.com/vbart/patches/http2_fix.txt

wbr, Valentin V. Bartenev

13

Wow, that was fast, thanks :slight_smile: I’m doing tests now with the h2 fix. It
looks
promising so far. I will continue to run various test to see if there
are
scenarios that trigger an open socket leak.

  • At which point in the debug log did you know there is something going
    wrong?

  • Is there an explanation what went wrong and what the patch is fixing?

  • Are there other known cases that can cause open socket leaks?

Thanks Valentin!

Posted at Nginx Forum:

14

Thanks a lot for the detailed explanation. The first patch reduced the
socket leaks by >99%. I will run tests with second patch beginning next
week
and check if it goes down to 0 leaks.

Are does 2 fixes integrated in the next release 1.11.2?

Thanks!

Posted at Nginx Forum:

15

On Thursday 23 June 2016 13:58:08 martinproinity wrote:

Thanks a lot for the detailed explanation. The first patch reduced the
socket leaks by >99%. I will run tests with second patch beginning next week
and check if it goes down to 0 leaks.

Are does 2 fixes integrated in the next release 1.11.2?

[…]

Not sure about 1.11.2, since the patches need to pass the review process
first, but I’ll do my best to fix it soon.

wbr, Valentin V. Bartenev

16

I tested now the second patch as well. There are no more socket leaks
with
both fixes.

Thanks!

Posted at Nginx Forum:

17

On Thursday 23 June 2016 04:58:23 martinproinity wrote:

Wow, that was fast, thanks :slight_smile: I’m doing tests now with the h2 fix. It looks
promising so far. I will continue to run various test to see if there are
scenarios that trigger an open socket leak.

  • At which point in the debug log did you know there is something going
    wrong?

There was nothing interesting till these lines in the log:

2016/06/19 19:53:11 [debug] 8724#0: *19047 process http2 frame type:3
f:0 l:4 sid:3
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 RST_STREAM frame, sid:3
status:8
2016/06/19 19:53:11 [info] 8724#0: *19047 client canceled stream 3 while
connecting to upstream, client: , server: , request:
“GET HTTP/2.0”, upstream: “http://:80”,
host: “”, referrer: “”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http run request: “”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream check client,
write event:0, “”

Here the client had canceled the request that was already sent to
usptream.

But because the request was potentially cacheable, nginx in order to
cache the
response continued processing it.

[…]
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream request:
“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream process header
2016/06/19 19:53:11 [debug] 8724#0: *19047 malloc:
00000000355360C0:16384
2016/06/19 19:53:11 [debug] 8724#0: *19047 recv: eof:0, avail:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 recv: fd:63 1443 of 15427
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy status 200 “200
OK”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: “Server:
Apache/2.2.22 (Debian)”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“X-Powered-By: PHP/5.4.45-1~dotdeb+7.1”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: “P3P:
CP=”“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Set-Cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Cache-Control: no-cache”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: “Vary:
Accept-Encoding”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Content-Encoding: gzip”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Content-Type: text/html”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Content-Length: 3582”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Accept-Ranges: bytes”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: “Date:
Sun, 19 Jun 2016 17:53:11 GMT”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“X-Varnish: 1052777260”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: “Age: 0”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: “Via: 1.1
varnish”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header:
“Connection: close”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header done

Here the response was returned by upstream.

2016/06/19 19:53:11 [debug] 8724#0: *19047 http script var: “MISS”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 header filter
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“:status: 200”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: “server:
nginx”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: “date:
Sun, 19 Jun 2016 17:53:11 GMT”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“content-type: text/html”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“content-length: 3582”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: “vary:
Accept-Encoding”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“x-powered-by: PHP/5.4.45-1~dotdeb+7.1”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: “p3p:
CP=”“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“set-cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“set-cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“set-cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“set-cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“set-cookie: ”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“cache-control: no-cache”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“content-encoding: gzip”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“x-varnish: 1052777260”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: “age: 0”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: “via:
1.1 varnish”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header:
“accept-ranges: bytes”
2016/06/19 19:53:11 [debug] 8724#0: *19047 posix_memalign:
000000002FCE5840:4096 @16
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2:3 create HEADERS frame
000000002027CD90: len:641
2016/06/19 19:53:11 [debug] 8724#0: *19047 http cleanup add:
000000002027CE28
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 frame out:
000000002027CD90 sid:3 bl:1 len:641

The first problem was here: nginx created the HEADERS frame with the
response
for already canceled stream and passed it to the output queue.

2016/06/19 19:53:11 [debug] 8724#0: *19047 SSL buf copy: 9
2016/06/19 19:53:11 [debug] 8724#0: *19047 SSL buf copy: 641
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2:3 HEADERS frame
000000002027CD90 was sent
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 frame sent:
000000002027CD90 sid:3 bl:1 len:641

And the HEADERS frame was written to SSL buffer.

[…]
2016/06/19 19:53:11 [debug] 8724#0: *19047 http finalize request: 0,
“” a:1, c:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate request
count:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate cleanup
count:1 blk:0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http posted request:
“”
2016/06/19 19:53:11 [debug] 8724#0: *19047 http terminate handler
count:1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http request count:1 blk:0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 close stream 3, queued
0, processing 1
2016/06/19 19:53:11 [debug] 8724#0: *19047 http close request
2016/06/19 19:53:11 [debug] 8724#0: *19047 http log handler
2016/06/19 19:53:11 [debug] 8724#0: *19047 run cleanup: 000000002DDEE350
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000355360C0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000202F2600,
unused: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001E88A800,
unused: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002DDED500,
unused: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 00000000207AF4B0,
unused: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002027BE40,
unused: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000002FCE5840,
unused: 1348
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000003DABCC40
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001D295C40
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 0000000024A93CD0,
unused: 0
2016/06/19 19:53:11 [debug] 8724#0: *19047 free: 000000001D2E8D10,
unused: 828

Eventually the request was finalized and the stream was closed.

2016/06/19 19:53:11 [debug] 8724#0: *19047 post event 000000000582ABD0
2016/06/19 19:53:11 [debug] 8724#0: *19047 delete posted event
000000000582ABD0
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 handle connection
handler

But the connection was neither closed nor switched to idle state. That
was due
to data left in SSL buffer (there were no SSL_write() calls since the
HEADERS
frame was buffered).

2016/06/19 19:54:12 [alert] 8724#0: *19047 open socket #236 left in
connection 181

As a result there’s a connection left without any timeouts.

  • Is there an explanation what went wrong and what the patch is fixing?

  • Are there other known cases that can cause open socket leaks?

I’ve seen in the log at least two problems:

  1. The HEADERS frame was produced for already canceled stream (and the
    patch in the previous message fixes this particular problem by
    adding
    a corresponding check into the relevant place).

  2. A connection can be left without any timeouts set if there’s data
    buffered
    in the SSL buffer. Since there can be other cases that will lead to
    such
    situation, it should be fixed by another patch:

    http://pp.nginx.com/vbart/patches/http2_fix2.txt

wbr, Valentin V. Bartenev