Segmentation fault in http2 module when cancelling download in Chrome

[iczero]

• Version: v9.5.0, v9.6.1, and v10.0.0-pre commit 743f890
• Platform: linux 64-bit (kernel 4.4.0-116-generic from Ubuntu)
• Subsystem: http2

Steps to reproduce:

1. Serve a file from Node.js to Chrome using the http2 module
2. Cancel the download from Chrome

I have not been able to reproduce this problem locally, however.

This was the stacktrace which was generated by node-segfault-handler (Node.js v9.5.0):

PID 1371 received SIGSEGV for address: 0x0
/home/iczero/prj/buildserver/node_modules/segfault-handler/build/Release/segfault-handler.node(+0x1acd)[0x7fccc33beacd]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fccc59a0390]
node(_ZN4node5http212Http2Session22OnStreamAfterWriteImplEPNS_9WriteWrapEiPv+0x55)[0x90f4b5]
node(_ZN4node10StreamBase10AfterWriteEPNS_9WriteWrapEi+0xa0)[0x94c330]
node(_ZN4node7TLSWrap6EncOutEv+0xc5)[0x999075]
node(_ZN4node10StreamBase10AfterWriteEPNS_9WriteWrapEi+0xa0)[0x94c330]
node(_ZN4node15LibuvStreamWrap10AfterWriteEPNS_9WriteWrapEi+0x1b)[0x9502cb]
node(_ZN4node15LibuvStreamWrap12AfterUvWriteEP10uv_write_si+0x54)[0x950f14]
node[0x14240b9]
node[0x1424d74]
node[0x142ac58]
node(uv_run+0x156)[0x1419676]
node(_ZN4node5StartEP9uv_loop_siPKPKciS5_+0x4bd)[0x8d49ed]
node(_ZN4node5StartEiPPc+0x153)[0x8d12d3]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fccc55e5830]
node[0x89d7e1]

Relevant symbols demangled:

node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*)
node::StreamBase::AfterWrite(node::WriteWrap*, int)
node::TLSWrap::EncOut()
node::StreamBase::AfterWrite(node::WriteWrap*, int)
node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int)
node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int)

A small script that causes the segfault:

const http2 = require('http2');
const fs = require('fs');

const FILE = '/usr/bin/node';

// generate a self-signed cert first:
// $ openssl req -newkey rsa:2048 -nodes -keyout key.pem -x509 -days 365 -out cert.pem

let server = http2.createSecureServer({
  key: fs.readFileSync('./key.pem'),
  cert: fs.readFileSync('./cert.pem')
}, async (request, response) => {
  console.log('a request!');
  fs.createReadStream(FILE).pipe(response);
});
server.listen(9998);

[michael42]

It seems I'm hitting the same issue when trying an HTTP2 push when Chrome already closed the connection. gdb spits out a similar stack trace:

#0  0x0000000000911185 in node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*) ()
#1  0x000000000094e240 in node::StreamBase::AfterWrite(node::WriteWrap*, int) ()
#2  0x0000000000998cc4 in ?? ()
#3  0x000000000099b1cf in node::TLSWrap::EncOut() ()
#4  0x000000000094e240 in node::StreamBase::AfterWrite(node::WriteWrap*, int) ()
#5  0x0000000000952bc4 in node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) ()
#6  0x0000000001427019 in ?? ()
#7  0x0000000001427cd4 in ?? ()
#8  0x000000000141c57b in uv_run ()
#9  0x00000000008d74bd in node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) ()

I managed to reduce the code to following example:

const fs = require("fs");
const http2 = require("http2");

const options = {
    key: fs.readFileSync(`${__dirname}/localhost.key`),
    cert: fs.readFileSync(`${__dirname}/localhost.crt`)
};
const server = http2.createSecureServer(options, async (req, res) => {
    if (req.url !== "/") {
        res.writeHead(404);
        res.end();
        return;
    }

    // no crash when pushing a single response
    push(req, res, "/dummy1");
    push(req, res, "/dummy2");

    res.writeHead(200);
    res.write("test");
    res.end();
});

server.listen(8443);
console.log("Listening");

function push(req, res, path) {
    res.createPushResponse({":path": path}, (err, pushResponse) => {
        if (err)
            return console.error({err}, "createPushResponse failed");

        pushResponse.stream.on("error", (err) => {
            console.warn("Writing push failed", err);
            pushResponse.stream.end();
        });

        // no crash when immediately sending a response and closing the stream
        const readStream = fs.createReadStream(__filename);
        readStream.on("end", () => pushResponse.stream.end());
        pushResponse.writeHead(200, {});
        readStream.pipe(pushResponse.stream);
    });
}

Steps:

• run node ./index.js
• import a localhost certificate (I'm using a script that generates one with subjectAltName)
• load https://localhost:8443/ (Chrome Linux 64.0.3282.186)
• hit refresh
• node v9.6.1 should crashed at this point

[addaleax]

I couldn’t reproduce the segfault with either example yet. :/ If it is at all possible, can you try to reproduce this with Node-only code? I.e. a standalone script that crashes and doesn’t require a browser or other external HTTP/2 clients.

It would be appreciated if you could provide a core dump, or try to dig into this with a debugger if you can. Building a debug build of Node takes a bit, but it should be worth it.

If your local reproduction is reliable enough, you could probably also figure out something meaningful by attaching valgrind to the Node process.

What I can tell from the offsets in the stack traces is that most likely one of the stream_ fields of a WriteWrap created for an Http2Stream is invalid, but that’s not really very telling about the cause of the issue.

v10.0.0-pre commit 743f890

@iczero Does that mean that that commit fixes the issue for you, or that you didn’t try anything that includes that patch? It would be weird if that commit fixed things, the original PR that introduce that bug didn’t make it into Node 9.

[iczero]

@addaleax I meant that the problem still existed with that commit. Sorry for the confusion.

[addaleax]

@iczero @michael42 Could you check whether the patch from #18987 fixes this issue for you? That would be a huge help.

[michael42]

I think I can check it tomorrow. For now, I can't get it reproduced without Chrome, but here's the output from chrome://net-internals:

t= 2 [st= 0]  HTTP2_SESSION_SEND_HEADERS
              --> exclusive = true
              --> fin = true
              --> has_priority = true
              --> :method: GET
                  :authority: localhost:8443
                  :scheme: https
                  :path: /
                  cache-control: max-age=0
                  upgrade-insecure-requests: 1
                  user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.186 Safari/537.36
                  accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
                  dnt: 1
                  accept-encoding: gzip, deflate, br
                  accept-language: de,en;q=0.9,en-US;q=0.8
              --> parent_stream_id = 0
              --> source_dependency = 11872 (HTTP_STREAM_JOB)
              --> stream_id = 3
              --> weight = 256
t= 5 [st= 3]  HTTP2_SESSION_RECV_PUSH_PROMISE
              --> :scheme: https
                  :authority: localhost:8443
                  :method: GET
                  :path: /dummy1
              --> id = 3
              --> promised_stream_id = 6
t= 5 [st= 3]  HTTP2_SESSION_SEND_RST_STREAM
              --> description = "Duplicate pushed stream with url: https://localhost:8443/dummy1"
              --> error_code = "7 (REFUSED_STREAM)"
              --> stream_id = 6
t= 5 [st= 3]  HTTP2_SESSION_RECV_PUSH_PROMISE
              --> :scheme: https
                  :authority: localhost:8443
                  :method: GET
                  :path: /dummy2
              --> id = 3
              --> promised_stream_id = 8
t= 5 [st= 3]  HTTP2_SESSION_SEND_RST_STREAM
              --> description = "Duplicate pushed stream with url: https://localhost:8443/dummy2"
              --> error_code = "7 (REFUSED_STREAM)"
              --> stream_id = 8
t= 5 [st= 3]  HTTP2_SESSION_RECV_HEADERS
              --> fin = false
              --> :status: 200
                  date: Sun, 25 Feb 2018 21:13:13 GMT
              --> stream_id = 3
t= 5 [st= 3]  HTTP2_SESSION_RECV_HEADERS
              --> fin = false
              --> :status: 200
                  date: Sun, 25 Feb 2018 21:13:13 GMT
              --> stream_id = 6
t= 5 [st= 3]  HTTP2_SESSION_RECV_HEADERS
              --> fin = false
              --> :status: 200
                  date: Sun, 25 Feb 2018 21:13:13 GMT
              --> stream_id = 8
t= 5 [st= 3]  HTTP2_SESSION_RECV_DATA
              --> fin = false
              --> size = 4
              --> stream_id = 3
t= 5 [st= 3]  HTTP2_SESSION_UPDATE_RECV_WINDOW
              --> delta = -4
              --> window_size = 15726176
t= 5 [st= 3]  HTTP2_SESSION_RECV_DATA
              --> fin = true
              --> size = 0
              --> stream_id = 3
t= 6 [st= 4]  HTTP2_SESSION_UPDATE_RECV_WINDOW
              --> delta = 4
              --> window_size = 15726180
t=11 [st= 9]  HTTP2_SESSION_RECV_DATA
              --> fin = false
              --> size = 1230
              --> stream_id = 8
t=11 [st= 9]  HTTP2_SESSION_UPDATE_RECV_WINDOW
              --> delta = -1230
              --> window_size = 15724950
t=11 [st= 9]  HTTP2_SESSION_UPDATE_RECV_WINDOW
              --> delta = 1230
              --> window_size = 15726180
t=14 [st=12]  HTTP2_SESSION_CLOSE
              --> description = "Connection closed"
              --> net_error = -100 (ERR_CONNECTION_CLOSED)
t=14 [st=12]  HTTP2_STREAM_ERROR
              --> description = "Abandoned."
              --> net_error = "ERR_CONNECTION_CLOSED"
              --> stream_id = 2
t=14 [st=12]  HTTP2_SESSION_UPDATE_RECV_WINDOW
              --> delta = 1230
              --> window_size = 15727410
t=14 [st=12]  HTTP2_STREAM_ERROR
              --> description = "Abandoned."
              --> net_error = "ERR_CONNECTION_CLOSED"
              --> stream_id = 4
t=14 [st=12]  HTTP2_SESSION_UPDATE_RECV_WINDOW
              --> delta = 1230
              --> window_size = 15728640
t=14 [st=12]  HTTP2_SESSION_POOL_REMOVE_SESSION
t=14 [st=12] -HTTP2_SESSION

I also ran it under valgrind --leak-check=full (is that correct, never used it before?), but it doesn't crash in that case. It does report some possibly lost bytes (3,004 bytes in 15 blocks), though.

[iczero]

@addaleax It doesn't seem to fix the problem. :(

Thread 1 "node" received signal SIGSEGV, Segmentation fault.
0x000000000089ccba in node::http2::Http2Session::ClearOutgoing(int) ()

I'm going to try running node in gdb to see if I can isolate the problem.

[addaleax]

@michael42 Thanks for reporting back! Yes, it’s expected that there are some lost bytes since Node doesn’t fully clean up before process exit. It would be more interesting to know about any kind of uninitialized data usage.

@iczero Thanks for the info. :/ Do you think you could try a debug build of Node to possibly provide more context?

[iczero]

A better backtrace provided by the debug version:

#0  0x00000000014a613f in node::StreamResource::EmitAfterWrite (this=0x3e6d450, w=0x3e76040, status=0) at ../src/stream_base-inl.h:121
#1  0x00000000014a61dc in node::StreamBase::AfterWrite(node::WriteWrap*, int)::{lambda()#1}::operator()() const (__closure=0x7fffffff9b20) at ../src/stream_base-inl.h:138
#2  0x00000000014a6f0c in node::StreamBase::AfterRequest<node::WriteWrap, node::StreamBase::AfterWrite(node::WriteWrap*, int)::{lambda()#1}>(node::WriteWrap*, node::StreamBase::AfterWrite(node::WriteWrap*, int)::{lambda()#1}) (this=0x3e6d450, req_wrap=0x3e76040, emit=...) at ../src/stream_base-inl.h:155
#3  0x00000000014a622b in node::StreamBase::AfterWrite (this=0x3e6d450, req_wrap=0x3e76040, status=0) at ../src/stream_base-inl.h:137
#4  0x00000000014a6322 in node::WriteWrap::OnDone (this=0x3e76040, status=0) at ../src/stream_base-inl.h:413
#5  0x00000000014b43e4 in node::StreamReq::Done (this=0x3e76040, status=0, error_str=0x0) at ../src/stream_base-inl.h:424
#6  0x0000000001523680 in node::http2::Http2Session::ClearOutgoing (this=0x3e6cfb0, status=0) at ../src/node_http2.cc:1454

#0  0x00000000014a613f in node::StreamResource::EmitAfterWrite (this=0x3e6d450, w=0x3e76040, status=0) at ../src/stream_base-inl.h:121
121       listener_->OnStreamAfterWrite(w, status);
#1  0x00000000014a61dc in node::StreamBase::AfterWrite(node::WriteWrap*, int)::{lambda()#1}::operator()() const (__closure=0x7fffffff9b20) at ../src/stream_base-inl.h:138
138         EmitAfterWrite(req_wrap, status);
#2  0x00000000014a6f0c in node::StreamBase::AfterRequest<node::WriteWrap, node::StreamBase::AfterWrite(node::WriteWrap*, int)::{lambda()#1}>(node::WriteWrap*, node::StreamBase::AfterWrite(node::WriteWrap*, int)::{lambda()#1}) (this=0x3e6d450, req_wrap=0x3e76040, emit=...) at ../src/stream_base-inl.h:155
155       emit();
#3  0x00000000014a622b in node::StreamBase::AfterWrite (this=0x3e6d450, req_wrap=0x3e76040, status=0) at ../src/stream_base-inl.h:137
137       AfterRequest(req_wrap, [&]() {
#4  0x00000000014a6322 in node::WriteWrap::OnDone (this=0x3e76040, status=0) at ../src/stream_base-inl.h:413
413       stream()->AfterWrite(this, status);
#5  0x00000000014b43e4 in node::StreamReq::Done (this=0x3e76040, status=0, error_str=0x0) at ../src/stream_base-inl.h:424
424       OnDone(status);
#6  0x0000000001523680 in node::http2::Http2Session::ClearOutgoing (this=0x3e6cfb0, status=0) at ../src/node_http2.cc:1454
1454          wrap->Done(status);
#7  0x0000000001523389 in node::http2::Http2Session::OnStreamAfterWrite (this=0x3e6cfb0, w=0x3e77810, status=0) at ../src/node_http2.cc:1410
1410      ClearOutgoing(status);

[addaleax]

@iczero Can you figure out why that is crashing? Is listener_ null?

[iczero]

Seems like it:

(gdb) p listener_
$1 = (node::StreamListener *) 0x0

[addaleax]

@iczero Can you build with ./configure --debug-http2 and share the output for a crashing run, and ideally add logging like this:

--- a/src/node_http2.cc
+++ b/src/node_http2.cc
@@ -1755,2 +1755,3 @@ Http2Stream::Http2Stream(
 Http2Stream::~Http2Stream() {
+  DEBUG_HTTP2STREAM2(this, "tearing down stream");
   if (session_ != nullptr) {

listener_ == nullptr should basically never happen at that point, it means that all listeners have been removed, which means that the stream destructor has been called. So, it might be nice to figure out how that can happen…