# Nginx core dump explodes **URL:** \ **Category:** NGINX\ **Created:** [June 17, 2016, 1:30pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802 "2016-06-17T13:30:51Z")\ **Posts on this page:** 17\ **Page:** 1
**Author:** ![Sadaf\_N](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/s/858c86/32.png) [@Sadaf\_N](https://www.ruby-forum.com/u/Sadaf_N)\ **Post date:** [June 17, 2016, 1:30pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/1 "2016-06-17T13:30:51Z")
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: > **[nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267669#msg-267669)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 20, 2016, 8:19pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/2 "2016-06-20T20:19:04Z")
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. > **[nginx](http://nginx.org/)** ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 21, 2016, 8:54am UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/3 "2016-06-21T08:54:46Z")
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: > **[Re: nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267742#msg-267742)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 21, 2016, 3:25pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/4 "2016-06-21T15:25:34Z")
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. > **[nginx](http://nginx.org/)** ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 22, 2016, 12:43pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/5 "2016-06-22T12:43:08Z")
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? > **[A debugging log](http://nginx.org/en/docs/debugging_log.html)** wbr, Valentin V. Bartenev ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 21, 2016, 10:01pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/6 "2016-06-21T22:01:38Z")
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: > **[Re: nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267748#msg-267748)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 22, 2016, 3:12pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/7 "2016-06-22T15:12:41Z")
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: > **[Re: nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267771#msg-267771)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 22, 2016, 4:27pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/8 "2016-06-22T16:27:27Z")
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 ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 22, 2016, 8:34pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/9 "2016-06-22T20:34:33Z")
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 ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 22, 2016, 8:50pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/10 "2016-06-22T20:50:54Z")
Here you go: [https://tempfile.me/dl/ES9tWLqjnFozdx/](https://tempfile.me/dl/ES9tWLqjnFozdx/) Thanks! Posted at Nginx Forum: > **[Re: nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267783#msg-267783)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 22, 2016, 5:32pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/11 "2016-06-22T17:32:17Z")
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: > **[Re: nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267779#msg-267779)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 22, 2016, 9:46pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/12 "2016-06-22T21:46:59Z")
On Wednesday 22 June 2016 14:50:27 martinproinity wrote: > Here you go: [https://tempfile.me/dl/ES9tWLqjnFozdx/](https://tempfile.me/dl/ES9tWLqjnFozdx/) > > Thanks! Please try the patch: [http://pp.nginx.com/vbart/patches/http2\_fix.txt](http://pp.nginx.com/vbart/patches/http2_fix.txt) wbr, Valentin V. Bartenev ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 23, 2016, 10:59am UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/13 "2016-06-23T10:59:06Z")
Wow, that was fast, thanks 🙂 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: > **[Re: nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267802#msg-267802)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 23, 2016, 7:58pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/14 "2016-06-23T19:58:32Z")
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: > **[Re: nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267843#msg-267843)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 23, 2016, 8:24pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/15 "2016-06-23T20:24:14Z")
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 ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 28, 2016, 8:30am UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/16 "2016-06-28T08:30:44Z")
I tested now the second patch as well. There are no more socket leaks with both fixes. Thanks! Posted at Nginx Forum: > **[Re: nginx core dump explodes](https://forum.nginx.org/read.php?2,267669,267928#msg-267928)** > > 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 --w ---
**Author:** ![martinproinity](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/m/9e8a1a/32.png) [@martinproinity](https://www.ruby-forum.com/u/martinproinity)\ **Post date:** [June 23, 2016, 7:41pm UTC](https://www.ruby-forum.com/t/nginx-core-dump-explodes/244802/17 "2016-06-23T19:41:01Z")
On Thursday 23 June 2016 04:58:23 martinproinity wrote: > Wow, that was fast, thanks 🙂 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: wbr, Valentin V. Bartenev