http2: cannot handle session destroy error emitted by Http2Session.onGoawayData

[webcarrot]

• Version: v10.2.1
• Platform: Linux 4.9.0-6-amd64 SMP Debian 4.9.88-1 x86_64 GNU/Linux
• Subsystem: http2

Sorry for my english.

From time to time session emit error that is not handle by server/listener "error", "streamError" or "sessionError" handlers:

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

Error [ERR_HTTP2_SESSION_ERROR]: Session closed with error code 1
    at Http2Session.onGoawayData (internal/http2/core.js:477:21)
    at SocketProxy.ondata (internal/wrap_js_stream.js:62:22)
    at SocketProxy.emit (events.js:182:13)
    at addChunk (_stream_readable.js:279:12)
    at readableAddChunk (_stream_readable.js:264:11)
    at SocketProxy.Readable.push (_stream_readable.js:219:10)
    at SocketProxy._read (/xxx/node_modules/@webcarrot/server/lib/SocketProxy.js:81:21)
    at SocketProxy.tryRead (/xxx/node_modules/@webcarrot/server/lib/SocketProxy.js:99:12)
    at SocketProxy.addChunk (/xxx/node_modules/@webcarrot/server/lib/SocketProxy.js:92:10)
    at Socket.handleData (/xxx/node_modules/@webcarrot/server/lib/SocketProxy.js:26:61)
    at Socket.emit (events.js:182:13)
    at addChunk (_stream_readable.js:279:12)
    at readableAddChunk (_stream_readable.js:264:11)
    at Socket.Readable.push (_stream_readable.js:219:10)
    at Pipe.onread (net.js:636:20)
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)

Looks like session emit unhandled error on destroy.
This error should be handle by server sessionError to prevent app crash/restart.

---

More info:

@webcarrot/server/lib/SocketProxy (same name in wrap_js_stream 👎 ) is duplex stream that wrap connection stream ( #17132 ):
https://gist.github.com/webcarrot/353c2f275ab234f5dc68f9c7b32d40ea

Server class looks like (extends plain Http2Server):
https://gist.github.com/webcarrot/e61e78e4562bf843248bacedfe3663e8

PROXY protocol server wrapper (extends extended server class):
https://gist.github.com/webcarrot/9a6c0a3d4bc6f4665465ac57dd3be373

Simple usage (not real but probably work via haproxy or similar):

import proxyWrap from "./proxyWrap";
import { Server } from "./PlainHttp2";

const {createServer} = proxyWrap({
  Server
});

const h2Listener = createServer({
    allowHTTP1: true
}, (req, res) => {
  // some handler
  res.end("test");
});

h2Listener.addListener("error", err => console.error("server error", err));
h2Listener.addListener("streamError", err => console.error("stream error", err));
h2Listener.addListener("sessionError", err => console.error("session error", err));
h2Listener.listen("/unix/socket/etc", err => err && console.error("listen error", err));

[apapirovski]

I would suggest looking through your code and figuring out why the proper events aren't being bound to the session. It's likely there's an error in your flow somewhere. On the Node.js end, the way it works is pretty bulletproof but we can't really make any guarantees given the level of patching and accessing internals (Http2Server, etc.) you've done. Here's the relevant line that would handle all emitted errors:

node/lib/internal/http2/core.js

Line 2570 in 5624a6f

session.on('error', sessionOnError);

[webcarrot]

I will try to write clean tests - but this is problematic because this error is extremely rare.

[apapirovski]

@webcarrot Definitely understand but given the error handler I linked above, which is attached right after the Http2Session is created in connectionListener, I don't see how this could be an issue in Node.js core. The error is only thrown if no error listener exists and clearly in this case, for whatever reason, none does.

Happy to investigate further given new information that would indicate this is an issue in core code.

[webcarrot]

I will wrap connection stream for http2 session directly by StreamWrap from "_stream_wrap" and wait for "bug" on production servers for one week. If error does not occur, i will close this issue.

[webcarrot]

Its not related anyhow - _session is somehow invalid in ~Http2Stream - ~Http2Session should destroy related Http2Stream-s? My c/c++ skills are outdated - if its real bug make issue.

gdb backlog ("attack" server using firefox ctrl+f5 - fast open and close connections):

(gdb) handle SIGPIPE nostop
Signal        Stop	Print	Pass to program	Description
SIGPIPE       No	Yes	Yes		Broken pipe
(gdb) run
Starting program: /usr/bin/node ./node_modules/@webcarrot/bin/run/start.js --app @acme/app --env production
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7ffff6b73700 (LWP 31110)]
[New Thread 0x7ffff6372700 (LWP 31111)]
[New Thread 0x7ffff5b71700 (LWP 31112)]
[New Thread 0x7ffff5370700 (LWP 31113)]
[New Thread 0x7ffff7ff4700 (LWP 31114)]
[New Thread 0x7ffff48ae700 (LWP 31118)]
[New Thread 0x7fffe7fff700 (LWP 31119)]
[New Thread 0x7fffe77fe700 (LWP 31120)]
[New Thread 0x7fffe6ffd700 (LWP 31121)]
(node:31106) ExperimentalWarning: The http2 module is an experimental API.

Thread 1 "node" received signal SIGSEGV, Segmentation fault.
0x00000000008be685 in ?? ()
(gdb) backtrace
#0  0x00000000008be685 in ?? ()
#1  0x00000000008bea84 in node::http2::Http2Stream::~Http2Stream() ()
#2  0x0000000000e257c4 in v8::internal::GlobalHandles::DispatchPendingPhantomCallbacks(bool) ()
#3  0x0000000000e25a6a in v8::internal::GlobalHandles::PostGarbageCollectionProcessing(v8::internal::GarbageCollector, v8::GCCallbackFlags) ()
#4  0x0000000000e511a8 in v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) ()
#5  0x0000000000e523db in ?? ()
#6  0x0000000000e543d3 in v8::internal::Heap::FinalizeIncrementalMarkingIfComplete(v8::internal::GarbageCollectionReason) ()
#7  0x0000000000e55cc7 in v8::internal::IncrementalMarkingJob::Task::RunInternal() ()
#8  0x0000000000b52366 in v8::internal::CancelableTask::Run() ()
#9  0x00000000008dc5f8 in node::PerIsolatePlatformData::FlushForegroundTasksInternal() ()
#10 0x000000000099059f in ?? ()
#11 0x00000000009a1a68 in ?? ()
#12 0x0000000000990edb in uv_run ()
#13 0x000000000088a9ad in node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) ()
#14 0x0000000000889b66 in node::Start(int, char**) ()
#15 0x00007ffff6b942e1 in __libc_start_main (main=0x84db60 <main>, argc=6, argv=0x7fffffffe108, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffe0f8)
    at ../csu/libc-start.c:291
#16 0x000000000084dc95 in _start ()

[apapirovski]

That might be related to #21016, not sure. It's missing some bits in there that make it hard to figure out what's going on.

[webcarrot]

close - no such errors in logs after change (or node update).