Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

the Stream is closed if app pushes unused assets #20824

Closed
budarin opened this issue May 18, 2018 · 35 comments
Closed

the Stream is closed if app pushes unused assets #20824

budarin opened this issue May 18, 2018 · 35 comments
Assignees
Labels
confirmed-bug Issues with confirmed bugs. http2 Issues or PRs related to the http2 subsystem.

Comments

@budarin
Copy link

budarin commented May 18, 2018

  • 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 budarin changed the title Stream closes when app pushes unused assets the Stream is closed if app pushes unused assets May 18, 2018
@budarin
Copy link
Author

budarin commented May 19, 2018

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 ryzokuken added the http2 Issues or PRs related to the http2 subsystem. label May 21, 2018
@ryzokuken
Copy link
Contributor

/cc @nodejs/http2

@apapirovski
Copy link
Member

apapirovski commented May 21, 2018

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
Copy link
Author

budarin commented May 21, 2018

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

I don't quite understand what you mean.

@apapirovski
Copy link
Member

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

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

@budarin
Copy link
Author

budarin commented May 21, 2018

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
Copy link
Author

budarin commented May 21, 2018

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
Copy link
Member

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

ping @addaleax

@addaleax addaleax added the confirmed-bug Issues with confirmed bugs. label May 21, 2018
@ryzokuken
Copy link
Contributor

@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
Copy link
Author

budarin commented May 21, 2018

here is the repository for experiments and testing http2 project

@ryzokuken
Copy link
Contributor

@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
Copy link
Contributor

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

screen shot 2018-05-22 at 2 02 24 am

@budarin
Copy link
Author

budarin commented May 21, 2018

  • 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
Copy link
Author

budarin commented May 21, 2018

I have fixed readme for the repo

@ryzokuken
Copy link
Contributor

@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
Copy link
Contributor

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
Copy link
Member

apapirovski commented May 21, 2018

@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: #18936

@budarin
Copy link
Author

budarin commented May 21, 2018

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

@addaleax
Copy link
Member

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
Copy link
Author

budarin commented May 21, 2018

@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
Copy link
Contributor

@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
Copy link
Contributor

@addaleax
Copy link
Member

addaleax commented Jun 2, 2018

@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)

😕

@apapirovski
Copy link
Member

apapirovski commented Jun 2, 2018

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
Copy link
Member

addaleax commented Jun 2, 2018

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

@DaAitch
Copy link
Contributor

DaAitch commented Jun 2, 2018

Hey,

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

commit 65b17d4ddf3d104efdba837d6900ea893204b62a
Author: Anna Henningsen <anna@addaleax.net>
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
Copy link
Contributor

DaAitch commented Jun 2, 2018

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
Copy link
Contributor

DaAitch commented Jun 3, 2018

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
Copy link
Member

addaleax commented Jun 3, 2018

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
Copy link
Contributor

DaAitch commented Jun 3, 2018

@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
Copy link
Member

addaleax commented Jun 3, 2018

@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
Copy link
Contributor

DaAitch commented Jun 3, 2018

@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
Copy link

ariran5 commented Jun 20, 2018

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
Copy link
Member

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

@apapirovski apapirovski self-assigned this Jun 24, 2018
@apapirovski
Copy link
Member

@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...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
confirmed-bug Issues with confirmed bugs. http2 Issues or PRs related to the http2 subsystem.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants