Large file download (above 50MB, without "range processing") results in HTTP2_PROTOCOL_ERROR in Chrome

[ackava]

I am occasionally getting HTTP2 Protocol Error in chrome when nodejs web application is setup as node cluster.

Upon investigation it is found that Large file download (above 50MB, without "range processing") results in HTTP2_PROTOCOL_ERROR in Chrome. With range processing everything works correctly.

t=295 [st=1008453]  HTTP2_SESSION_PING
                    --> is_ack = true
                    --> type = "received"
                    --> unique_id = 3
t=295 [st=1008453]  HTTP2_SESSION_RECV_RST_STREAM
                    --> error_code = "11 (ENHANCE_YOUR_CALM)"
                    --> stream_id = 45

[jackzhp]

@ackava I found my case is like this:

#1. 5MiB is enough to crash, though this is not the key.
#2. when the file is large enough, then the chrome will send another 2 request with range such as
Range: bytes=2000xxx-end
Range: bytes=5000000-end

Clearly, 3 responses will overlap (the original one without range so it is 0-end). I guess then Chrome will cancel some requests during transfer. and this caused node http2 module to crash.

#3. The Chrome must be from an android phone. Chrome on desktop or from iOS does not cause this problem for me.

node quit with "Segmentation fault (core dumped)"

I used gdb to check the dumped file, I got (It seems that my guess is right. Request is cancelled/finished, but still the code is trying to read from the large file and write to the pipe to the network.):

(gdb) bt
#0 0x00000000012656c4 in node::ReportWritesToJSStreamListener::OnStreamAfterReqFinished(node::StreamReq*, int) ()
#1 0x000000000126a0d8 in node::StreamPipe::ProcessData(unsigned long, std::unique_ptr<v8::BackingStore, std::default_deletev8::BackingStore >) ()
#2 0x000000000126a30f in node::StreamPipe::ReadableListener::OnStreamRead(long, uv_buf_t const&) ()
#3 0x00000000010cf639 in node::fs::FileHandle::ReadStart()::{lambda(uv_fs_s*)#1}::_FUN(uv_fs_s*) ()
#4 0x00000000010b691d in node::MakeLibuvRequestCallback<uv_fs_s, void ()(uv_fs_s)>::Wrapper(uv_fs_s*) ()
#5 0x000000000213f4cd in uv__work_done (handle=0x6ea0b10 <default_loop_struct+176>) at ../deps/uv/src/threadpool.c:330
#6 0x0000000002142e63 in uv__async_io (loop=0x6ea0a60 <default_loop_struct>, w=, events=) at ../deps/uv/src/unix/async.c:208
#7 0x000000000215990a in uv__io_poll (loop=loop@entry=0x6ea0a60 <default_loop_struct>, timeout=) at ../deps/uv/src/unix/linux.c:1565
#8 0x0000000002143b27 in uv_run (loop=0x6ea0a60 <default_loop_struct>, mode=UV_RUN_DEFAULT) at ../deps/uv/src/unix/core.c:460
#9 0x0000000000fa40b5 in node::SpinEventLoopInternal(node::Environment*) ()
#10 0x0000000001125ca2 in node::NodeMainInstance::Run() ()
#11 0x0000000001065bf2 in node::Start(int, char**) ()
#12 0x000071430482a1ca in __libc_start_call_main (main=main@entry=0xf97de0

, argc=argc@entry=7, argv=argv@entry=0x7ffc4861c188)
at ../sysdeps/nptl/libc_start_call_main.h:58
#13 0x000071430482a28b in __libc_start_main_impl (main=0xf97de0 , argc=7, argv=0x7ffc4861c188, init=, fini=,
rtld_fini=, stack_end=0x7ffc4861c178) at ../csu/libc-start.c:360
#14 0x0000000000f9fd4e in _start ()

[jackzhp]

You can increase HTTP/2 stream buffer size

I guess the crash resulted from the cancellation of some requests by Chrome. Node http2 module does not handle that case properly, hence crash.

Thought I am not able to investigate more on this issue.

Is it the same problem as this one: https://discuss.google.dev/t/my-nodejs-server-crashed-with-an-http-2-error/129828

[ackava]

@jackzhp

Its long since I posted this so I am not sure which chrome it was but I was testing this on desktop.

We found couple of more problems with http2 and ssl on nodejs, and both modules aren't production ready. TLS on session resumption looses sni servername, making sni extremely difficult. And with similar issues like this, we switched to dotnet's yarp proxy in front and using node's http only server.

[jackzhp]

stream_base.cc
755 void ReportWritesToJSStreamListener::OnStreamAfterReqFinished(
756 StreamReq* req_wrap, int status) {
757 StreamBase* stream = static_cast<StreamBase*>(stream_);
758 Environment* env = stream->stream_env();
759 if (!env->can_call_into_js()) return;
760 AsyncWrap* async_wrap = req_wrap->GetAsyncWrap();
761 HandleScope handle_scope(env->isolate());
762 Context::Scope context_scope(env->context());
763 CHECK(!async_wrap->persistent().IsEmpty());
764 Local req_wrap_obj = async_wrap->object();
765
766 Local argv[] = {
767 Integer::New(env->isolate(), status),
768 stream->GetObject(),
769 Undefined(env->isolate())
770 };
771
772 const char* msg = stream->Error();
773 if (msg != nullptr) {
774 argv[2] = OneByteString(env->isolate(), msg);
775 stream->ClearError();
776 }
777
778 if (req_wrap_obj->Has(env->context(), env->oncomplete_string()).FromJust())
779 async_wrap->MakeCallback(env->oncomplete_string(), arraysize(argv), argv);
780 }

stream_pipe.cc
141 void StreamPipe::ProcessData(size_t nread,
142 std::unique_ptr bs) {
143 CHECK(uses_wants_write_ || pending_writes_ == 0);
144 uv_buf_t buffer = uv_buf_init(static_cast<char*>(bs->Data()), nread);
145 StreamWriteResult res = sink()->Write(&buffer, 1);
146 pending_writes_++;
147 if (!res.async) {
148 writable_listener_.OnStreamAfterWrite(nullptr, res.err);
149 } else {
150 is_reading_ = false;
151 res.wrap->SetBackingStore(std::move(bs));
152 if (source() != nullptr)
153 source()->ReadStop();
154 }
155 }

I know it is with line 151, something will call OnStreamAfterReqFinished.
Later on, I found out that when it crashes, it was line 148 that was called. so what I guessed was wrong.

[jackzhp]

after spending lots of time to build v24.11.0, and eventually I found that

#0 0x000060a131d60e9a in node::ReportWritesToJSStreamListener::OnStreamAfterReqFinished (this=0x60a13b5346d8, req_wrap=0x0, status=-4095) at ../src/stream_base.cc:760
#1 0x000060a131d6112b in node::ReportWritesToJSStreamListener::OnStreamAfterWrite (this=0x60a13b5346d8, req_wrap=0x0, status=-4095) at ../src/stream_base.cc:784
#2 0x000060a131d61324 in node::StreamListener::OnStreamAfterWrite (this=0x60a13b5347d0, w=0x0, status=-4095) at ../src/stream_base.cc:814
#3 0x000060a131d667f3 in node::StreamPipe::WritableListener::OnStreamAfterWrite (this=0x60a13b539510, w=0x0, status=-4095) at ../src/stream_pipe.cc:186
#4 0x000060a131d66483 in node::StreamPipe::ProcessData (this=0x60a13b539490, nread=16384, bs=std::unique_ptrv8::BackingStore = {...}) at ../src/stream_pipe.cc:148

ReportWritesToJSStreamListener::OnStreamAfterReqFinished is called with req_wrap=0x0.
stream_pipe.cc

[github-actions]

This issue has been marked as stale due to 210 days of inactivity.
It will be automatically closed in 30 days if no further activity occurs. If this is still relevant, please leave a comment or update it to keep it open.

[github-actions]

This issue has been automatically closed after 30 days of inactivity following its stale status (no activity for a total of 240 days).
If this is still relevant, feel free to reopen it or leave a comment with additional details so we can continue the discussion.