Node: the Stream is closed if app pushes unused assets

[budarin]

• Version: 10.1.0
• Platform: Windows Server 2008R2 64
• Subsystem: any browser any OS

If push some assets which will not be used with browser - stream closes on the second request
Page requires only <script src="script.js"></script>, but if to push something that is not using on the page - the next page refresh will close the http2 stream

        const pushAsset = (stream, file) => {
            const filePath = path.resolve(file.filePath);

            stream.pushStream({ [HTTP2_HEADER_PATH]: file.path }, (err, pushStream) => {
                pushStream.respondWithFile(filePath, file.headers, {
                    onError: (err) => {
                        respondToStreamError(err, stream);
                    }
                });
            });
        };

        const cssFile = {
            path: '/style.css',
            filePath: './style.css',
            headers: {
                'content-type': 'text/css'
            }
        };
        const cssFile1 = {
            path: '/style1.css',
            filePath: './style1.css',
            headers: {
                'content-type': 'text/css'
            }
        };
        const jsFile = {
            path: '/script.js',
            filePath: './script.js',
            headers: {
                'content-type': 'application/javascript'
            }
        };

        pushAsset(stream, jsFile);
        pushAsset(stream, cssFile);   //<-- unused
        pushAsset(stream, cssFile1);   //<-- unused

The error:

events.js:167
      throw er; // Unhandled 'error' event
      ^

Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_REFUSED_STREAM
    at ServerHttp2Stream._destroy (internal/http2/core.js:1871:13)
    at ServerHttp2Stream.destroy (internal/streams/destroy.js:32:8)
    at ServerHttp2Stream.[maybe-destroy] (internal/http2/core.js:1887:12)
    at Http2Stream.onStreamClose [as onstreamclose] (internal/http2/core.js:346:26)
Emitted 'error' event at:
    at emitErrorNT (internal/streams/destroy.js:82:8)
    at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
    at process._tickCallback (internal/process/next_tick.js:63:19)

Declaration of extra assets should not crush the tream

[budarin]

Here is the demo project

try to uncomment these lines:

        // pushAsset(stream, jsFile1);
        // pushAsset(stream, jsFile2);

and make some quick page refreshes - it makes the error.

[ryzokuken]

/cc @nodejs/http2

[apapirovski]

This seems as expected to me. Add an error handler that ignores NGHTTP2_REFUSED_STREAM errors. See the spec: https://http2.github.io/http2-spec/#rfc.section.7

[budarin]

@apapirovski
I'm sorry, could you provide the code, please.

I don't quite understand what you mean.

[apapirovski]

Sorry, should've been clearer, you can use something like this to make sure those errors don't take down your app:

```js
pushStream.on('error', (err) => {
const isRefusedStream = err.code === 'ERR_HTTP2_STREAM_ERROR' &&
pushStream.rstCode === NGHTTP2_REFUSED_STREAM;
if (!isRefusedStream)
throw err;
});

[budarin]

It didnt helped - after some refreshes here is another error:

npm[10144]: src\node_file.cc:215: Assertion `!reading_' failed.
 1: node::DecodeWrite
 2: node::DecodeWrite
 3: uv_loop_fork
 4: uv_loop_fork
 5: v8::internal::interpreter::BytecodeDecoder::Decode
 6: v8::internal::RegExpImpl::Exec
 7: v8::internal::RegExpImpl::Exec
 8: v8::internal::RegExpImpl::Exec
 9: 000000B116304281

Please review the code:

const pushAsset = (stream, file) => {
    const filePath = path.resolve(path.join(serverRoot, file.filePath));

    stream.pushStream({ [HTTP2_HEADER_PATH]: file.path }, { parent: stream.id }, (err, pushStream) => {
        if (!err) {
            console.log(">> Pushing:", file.path);

            pushStream.on('error', (err) => {
                console.log('pushStream.on error', err);

                const isRefusedStream = err.code === 'ERR_HTTP2_STREAM_ERROR' &&
                    pushStream.rstCode === NGHTTP2_REFUSED_STREAM;

                if (isRefusedStream)  {
                    return;
                }

                respondToStreamError(err, pushStream);
            });

            pushStream.respondWithFile(filePath, file.headers);
        }

        if (err) {
            console.log(">> Pushing error:", err);
        }
    });
};

[budarin]

And even not pushing unnessesary assets, but quickly refresh the page - you will get the error:

npm[5912]: src\node_http2.cc:1934: Assertion `!this->IsDestroyed()' failed.
 1: node::DecodeWrite
 2: node::DecodeWrite
 3: ENGINE_get_ctrl_function
 4: DH_get0_engine
 5: std::basic_ostream<char,std::char_traits<char> >::basic_ostream<char,std::char_traits<char> >
 6: uv_loop_fork
 7: uv_fs_get_statbuf
 8: uv_dlerror
 9: node::CreatePlatform
10: node::CreatePlatform
11: node::Start
12: v8::SnapshotCreator::`default constructor closure'
13: v8::internal::AsmJsScanner::IsNumberStart
14: BaseThreadInitThunk
15: RtlUserThreadStart

[apapirovski]

Sounds like there are potentially issues in our C++ pipe code.

ping @addaleax

[ryzokuken]

@budarin I could take a look into this, but could you bring me up to speed by sharing the complete relevant code for the server script? Or is the stream object a simple newly initialized stream?

[budarin]

here is the repository for experiments and testing http2 project

[ryzokuken]

@budarin Umm, I uncommented the two lines and reloaded, the page loads up as expected. That said, I'm using chrome to connect. Hope that's not an issue?

[ryzokuken]

The two JavaScript files don't show up here, though? I think that's expected anyway.

[budarin]

• script1 & script2 - are unnessesary assets in browser - this is not actual problem - sckip it
• try to hold the key combination cmd+R for some time to have the error

[budarin]

I have fixed readme for the repo

[ryzokuken]

@budarin had been holding the keys for a minute or two, noticed nothing, realized I was using Node 8.

Switched to Node 10, didn't take me more than a few seconds to get a crash. Maybe this was broken fairly recently in some related change?

[ryzokuken]

FWIW: It throws on my computer with:

respondToStreamError Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_REFUSED_STREAM
    at ServerHttp2Stream._destroy (internal/http2/core.js:1871:13)
    at ServerHttp2Stream.destroy (internal/streams/destroy.js:32:8)
    at ServerHttp2Stream.[maybe-destroy] (internal/http2/core.js:1887:12)
    at Http2Stream.onStreamClose [as onstreamclose] (internal/http2/core.js:346:26)
respondToStreamError Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_REFUSED_STREAM
    at ServerHttp2Stream._destroy (internal/http2/core.js:1871:13)
    at ServerHttp2Stream.destroy (internal/streams/destroy.js:32:8)
    at ServerHttp2Stream.[maybe-destroy] (internal/http2/core.js:1887:12)
    at Http2Stream.onStreamClose [as onstreamclose] (internal/http2/core.js:346:26)
respondToStreamError Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_REFUSED_STREAM
    at ServerHttp2Stream._destroy (internal/http2/core.js:1871:13)
    at ServerHttp2Stream.destroy (internal/streams/destroy.js:32:8)
    at ServerHttp2Stream.[maybe-destroy] (internal/http2/core.js:1887:12)
    at Http2Stream.onStreamClose [as onstreamclose] (internal/http2/core.js:346:26)
respondToStreamError Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_REFUSED_STREAM
    at ServerHttp2Stream._destroy (internal/http2/core.js:1871:13)
    at ServerHttp2Stream.destroy (internal/streams/destroy.js:32:8)
    at ServerHttp2Stream.[maybe-destroy] (internal/http2/core.js:1887:12)
    at Http2Stream.onStreamClose [as onstreamclose] (internal/http2/core.js:346:26)
node[4367]: ../src/node_file.cc:215:MaybeLocal<v8::Promise> node::fs::FileHandle::ClosePromise(): Assertion `!reading_' failed.
 1: node::Abort() [/Users/ryzokuken/.nvm/versions/node/v10.1.0/bin/node]
 2: node::InternalCallbackScope::~InternalCallbackScope() [/Users/ryzokuken/.nvm/versions/node/v10.1.0/bin/node]
 3: void node::StreamBase::AddMethods<node::fs::FileHandle>(node::Environment*, v8::Local<v8::FunctionTemplate>, int) [/Users/ryzokuken/.nvm/versions/node/v10.1.0/bin/node]
 4: node::fs::FileHandle::Close(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/ryzokuken/.nvm/versions/node/v10.1.0/bin/node]
 5: v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/Users/ryzokuken/.nvm/versions/node/v10.1.0/bin/node]
 6: v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/ryzokuken/.nvm/versions/node/v10.1.0/bin/node]
 7: v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/ryzokuken/.nvm/versions/node/v10.1.0/bin/node]
 8: 0x68d9810427d

[apapirovski]

@ryzokuken It's because it pipes the file entirely through C++ now. I pinged @addaleax because she worked on that code. I don't know if anyone else knows that code well enough. I unfortunately won't have the time to spend learning & debugging it in the next few weeks. Feel free to take a stab at it. The PR that introduced that code was here: https://github.com/nodejs/node/pull/18936

[budarin]

I began try http2 recently with Node version 10.1.0 - so I can not say anything (

[addaleax]

Yeah, this is on my radar – I’ve been able to reproduce it locally, just haven’t gotten around to anything yet. This should not be too hard to fix, though.

It seems like there are race conditions between the StreamPipe mechanism and HTTP/2 shutting down; on the HTTP/2 side, it might be as easy as turning the failing !this->IsDestroyed() check into an early return.

On the FileHandle side, it would be good to get a proper JS stack trace for the site of the assertion.

(Happy to guide you through this, @ryzokuken, if you’re interested and okay with me having somewhat limited bandwith to spend on it)

[budarin]

@ryzokuken but with those two lines commented out - it takes much more time to get the error
maybe pushing unused assets also affect the error.
Or maybe there are two different error types....

[ryzokuken]

@budarin maybe that's just because the amount of requests is low enough? Maybe it reaches some sort of critical mass once two more requests are performed per reload.

I'd be trying to hack up a simpler and smaller test case in the morning, let's see how it goes.

[ryzokuken]

@budarin Okay, I think I'm done.

@budarin @apapirovski @addaleax check out https://gist.github.com/ryzokuken/71392a6cc0a962b5c0ea0662e8a3ae6a

[addaleax]

@ryzokuken I’ve just tried that, but I couldn’t really get it to crash or to run – it always ends up on

Error [ERR_HTTP2_SESSION_ERROR]: Session closed with error code 1
    at Http2Session.onGoawayData [as ongoawaydata] (internal/http2/core.js:477:21)

:confused:

[apapirovski]

I think this got fixed but not in a release yet? I could be wrong. Perhaps @budarin can verify when we cut the next release (10.4.0?).

[addaleax]

@apapirovski I managed to get a reproduction on master, so, unfortunately no.

[DaAitch]

Hey,

I can confirm this, testing it with latest master (as of now 2. Jun 18 23:11+0200).

commit 65b17d4ddf3d104efdba837d6900ea893204b62a
Author: Anna Henningsen <[email protected]>
Date:   Sat Jun 2 16:01:58 2018 +0200

test: minor adjustments to test-http2-respond-file

See my MCVE gist

My tests show:

• push + pushStream.end is fine
• push + respondWithFile crashed
• push + respondWithFD crashed

[DaAitch]

I also put all frames Chrome is logging to the gist. In the gist you can see the last Refresh, before it crashed and I think respondWithFile or respondWithFD with HTTP2_SESSION_SEND_RST_STREAM gets any race condition.

[DaAitch]

I try to create a red test, but unfortunately I can't find a way with the client to cancel a server push? I can only listen on it docs

[addaleax]

I think this would work:

'use strict';

const common = require('../common');
if (!common.hasCrypto)
  common.skip('missing crypto');
const http2 = require('http2');
const net = require('net');

const {
  HTTP2_HEADER_CONTENT_TYPE
} = http2.constants;

const server = http2.createServer();
server.on('stream', common.mustCall((stream) => {
  stream.respondWithFile(process.execPath, {
    [HTTP2_HEADER_CONTENT_TYPE]: 'application/octet-stream'
  });
}));

server.listen(0, common.mustCall(() => {
  const client = http2.connect(`http://localhost:${server.address().port}`);
  const req = client.request();

  req.on('response', common.mustCall(() => {}));
  req.on('data', common.mustCall(() => {
    net.Socket.prototype.destroy.call(client.socket);
    server.close();
  }));
  req.end();
}));

It only creates one of the failure modes, though.

[DaAitch]

@addaleax you're right it failes:
node[9901]: ../src/node_file.cc:220:v8::MaybeLocal<v8::Promise> node::fs::FileHandle::ClosePromise(): Assertion '!reading_' failed.

I'm wondering if CHECK(!reading_); is correct in FileHandle::ClosePromise, since AfterClose will handle a FileHandle being in reading state.

void FileHandle::AfterClose() {
  closing_ = false;
  closed_ = true;
  if (reading_ && !persistent().IsEmpty())
    EmitRead(UV_EOF);
}

And how do we get this second error I was talking about?
node[4683]: ../src/node_http2.cc:1966:virtual int node::http2::Http2Stream::DoWrite(node::WriteWrap*, uv_buf_t*, size_t, uv_stream_t*): Assertion '!this->IsDestroyed()' failed.

[addaleax]

@DaAitch I think the check is correct, it’s rather that the StreamPipe implementation shouldn’t keep reading if there was an error on the writable side. This is a patch that fixes this problem, but it’s (obviously?) not an ideal solution:

diff --git a/src/stream_pipe.cc b/src/stream_pipe.cc
index bfe7d4297257..1d80592b3e75 100644
--- a/src/stream_pipe.cc
+++ b/src/stream_pipe.cc
@@ -161,2 +161,3 @@ void StreamPipe::WritableListener::OnStreamAfterWrite(WriteWrap* w,
     pipe->ShutdownWritable();
+    pipe->source()->ReadStop();
     pipe->Unpipe();
@@ -168,2 +169,3 @@ void StreamPipe::WritableListener::OnStreamAfterWrite(WriteWrap* w,
     StreamListener* prev = previous_listener_;
+    pipe->source()->ReadStop();
     pipe->Unpipe();
@@ -179,2 +181,3 @@ void StreamPipe::WritableListener::OnStreamAfterShutdown(ShutdownWrap* w,
   StreamListener* prev = previous_listener_;
+  pipe->source()->ReadStop();
   pipe->Unpipe();
@@ -193,2 +196,3 @@ void StreamPipe::WritableListener::OnStreamDestroy() {
   pipe->is_eof_ = true;
+  pipe->source()->ReadStop();
   pipe->Unpipe();
@@ -238,2 +242,3 @@ void StreamPipe::Unpipe(const FunctionCallbackInfo<Value>& args) {
   ASSIGN_OR_RETURN_UNWRAP(&pipe, args.Holder());
+  pipe->source()->ReadStop();
   pipe->Unpipe();

That second error is probably coming from a similar condition as the one from that test, but with different timing properties (but I’m not sure about that).

[DaAitch]

@addaleax the patch you provided gives me a green test, but segfaults in my manual test.

edited: I only pasted SIGPIPE, forgot to continue to SIGSEGV.

(gdb) run ../http2/examples/src/index.js file
Starting program: /home/aitch/Code/node-fork/node_g ../http2/examples/src/index.js file
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7ffff6b42700 (LWP 19087)]
[New Thread 0x7ffff6341700 (LWP 19088)]
[New Thread 0x7ffff5b40700 (LWP 19089)]
[New Thread 0x7ffff533f700 (LWP 19090)]
[New Thread 0x7ffff7ff6700 (LWP 19091)]
running with push:  file
(node:19083) ExperimentalWarning: The http2 module is an experimental API.

Thread 1 "node_g" received signal SIGPIPE, Broken pipe.
0x00007ffff6f1d4bd in write () at ../sysdeps/unix/syscall-template.S:84
84      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) continue
Continuing.

Thread 1 "node_g" received signal SIGPIPE, Broken pipe.
0x00007ffff6f1d4bd in write () at ../sysdeps/unix/syscall-template.S:84
84      in ../sysdeps/unix/syscall-template.S
(gdb) continue
Continuing.
respond /
push allowed
push stream
respond /index.css
[New Thread 0x7ffff4b3e700 (LWP 19136)]
[New Thread 0x7fffe7fff700 (LWP 19137)]
[New Thread 0x7fffe77fe700 (LWP 19138)]
[New Thread 0x7fffe6ffd700 (LWP 19140)]
respond / stream closed
respond /index.css

Thread 1 "node_g" received signal SIGSEGV, Segmentation fault.
0x00000000018f461c in node::StreamPipe::WritableListener::OnStreamAfterWrite (this=0x4213698, w=0x42136f0, status=0)
    at ../src/stream_pipe.cc:162
162         pipe->source()->ReadStop();

[ariran5]

I have this problem too

if add this code

pushStream.on('error', (err) => {
  const isRefusedStream = err.code === 'ERR_HTTP2_STREAM_ERROR' &&
                          pushStream.rstCode === NGHTTP2_REFUSED_STREAM;
  if (!isRefusedStream)
    throw err;
});

its work, but if i often reload page then node crash

node[17568]: ../src/node_file.cc:220:MaybeLocal<v8::Promise> node::fs::FileHandle::ClosePromise(): Assertion `!reading_' failed.
 1: node::Abort() [/usr/local/bin/node]
 2: node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, char const*, int, v8::Local<v8::Value>*, node::async_context) [/usr/local/bin/node]
 3: node::fs::FileHandle::ClosePromise() [/usr/local/bin/node]
 4: node::fs::FileHandle::Close(v8::FunctionCallbackInfo<v8::Value> const&) [/usr/local/bin/node]
 5: v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/usr/local/bin/node]
 6: v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/usr/local/bin/node]
 7: v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/usr/local/bin/node]
 8: 0x138017d041bd
Abort trap: 6

[apapirovski]

I'm going to spend some time with this today, hopefully I'll get to the point where I can make a PR.

[apapirovski]

@addaleax Are you still able to reproduce? Because I tried against 10.5.0 with all 3 examples in this thread and I can't get it to fail...