nginx core dump explodes

Thu Jun 23 17:40:46 UTC 2016

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: <removed>, server: <removed>, request: "GET <removed> HTTP/2.0", upstream: "http://<removed>:80<removed>", host: "<removed>", referrer: "<removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http run request: "<removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http upstream check client, write event:0, "<removed>"

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: "<removed>"
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="<removed>""
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: "Set-Cookie: <removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: "Set-Cookie: <removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: "Set-Cookie: <removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: "Set-Cookie: <removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http proxy header: "Set-Cookie: <removed>"
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="<removed>""
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: "set-cookie: <removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: "set-cookie: <removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: "set-cookie: <removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: "set-cookie: <removed>"
2016/06/19 19:53:11 [debug] 8724#0: *19047 http2 output header: "set-cookie: <removed>"
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, "<removed>" 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: "<removed>"
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