Repository navigation
There appears to be a bug with the http2 header decoding #28632
Description
Activity
Do you happen to have some kind of reproduction for this?
Unfortunately, not yet. I was hoping that someone more familiar with the implementation might be able to see what the error is from the information I have.
@murgatroid99 Okay – this is happening on the client side and it is only happening with the
dateheader so far, correct? Do the invalid header names vary from process to process, or from request to request?@addaleax
We had this error re-surface since Oct 10th - same key across several containers (does not vary by process or by request){ Error: Metadata key "@���" contains illegal characters at Http2CallStream.call.on (/app/bundle/programs/server/npm/node_modules/@grpc/grpc-js/build/src/client.js:101:45) at emitOne (events.js:121:20) at Http2CallStream.emit (events.js:211:7) at process.nextTick (/app/bundle/programs/server/npm/node_modules/@grpc/grpc-js/build/src/call-stream.js:71:22) at _combinedTickCallback (internal/process/next_tick.js:132:7) at process._tickDomainCallback (internal/process/next_tick.js:219:9) code: 2, details: 'Metadata key "@\u0000\u0000\u0000" contains illegal characters', metadata: Metadata { options: undefined, internalRepr: Map {} }, note: 'Exception occurred in retry method that was not classified as transient' }I can't confirm this being a client side bug either - we are using Google PubSub.
Platform: node: 8-stretch (docker) image (one instance on 10-stretch)
one thing you can potentially try is setting up Wireshark to intercept the HTTPS secured HTTP/2 traffic flowing into the endpoint. Obviously that depends on your set up, but it would be interesting to see if the headers coming into our Header handling code are correct. Given the kind of corruption that is occurring in the examples, it almost looks like the pointers could be uninitialized, which means our ref counting may be off and nghttp2 could be freeing the buffers earlier than expected. That shouldn't be possible with the current implementation unless there's definitely something wrong and we very likely would have seen the bug crop up previously. If we can rule out errors in the inbound data, then that would help in lieu of a reproducible test case
Is this problem also present in node 12 ?
I'm not sure. We've had multiple recent reports of this error but they haven't specified the Node version.
Sounds like an encoding issue with a child dependency, not NodeJS. It does look like it's fixed now:
googleapis/nodejs-datastore#415
Edit: Unless we want NodeJS to do the urlencoding...
I don't think that gax-nodejs PR is at all related to this bug. And people have reported the bug to us much more recently than the last update in either of those issues, so I don't see any reason to think that this is resolved.
@murgatroid99 You might be right. The error is likely coming from:
Do you have an exact version of what version of
grpc-jsyou're using? It will help narrow down what's going on. Based on this code, which is the currentmasterbranch, it would be NodeJS that includes a mangled key name.To be clear, I am the author of
grpc-js, and I filed this issue because the mangled key names were reported to me, and I am sure they are coming from Node.5 remaining items
@murgatroid99 Sorry, I see. I was misinterpreting this as a server environment. In either cases, NodeJS isn't able to send request headers with the never-index flag.
It seems as though
nghttp2will prevent malformed headers from landing in NodeJS. The connection should actually fail before firing the'respond'event if theclientserver was responding with bad data. So it is probably a leak somewhere on the NodeJS C++ code. We are getting the headername, presumably fine, and the value of4for length whennghttp2gives it to us. But by the time it hits Javascript, it's gone and the reference is lost.In either cases, NodeJS isn't able to send request headers with the never-index flag.
The error in question is on response headers received by a Node client, sent by a different server. Those could be using any header encodings.
@murgatroid99 Yes. It's just that since NodeJS can't send
never-index, we can't build a self-contained test around it. So it likely can't be reproduced with just NodeJS code (eg: NodeJS client receiving data from a NodeJS Server). We need to incorporatenever-indexflag into outbound requests, so we can test around what would happen when a NodeJS stream (either client or server) receives headers with anever-indexflag. I'm going to start by filing that issue.If
never-indexbeing set causes this, then this particular issue here is most likely one in nghttp2, not Node.js itself. But yeah, Node.js should really provide a way to setnever-index.So, I've manually traced the events as:
- nghttp2 calls inflate_header_block
- nghttp2 calls session_call_on_header
- nghttp2 calls on_header_callback2
- nodejs captures the callback with OnHeaderCallback
- nodejs calls addHeader
- nodejs captures the callback with OnHeaderCallback
- nghttp2 calls on_header_callback2
- nghttp2, on an inflated header, calls nghttp2_hd_inflate_end_headers
- nghttp2 calls hd_inflate_keep_free
- nghttp2 calls nghttp2_rcbuf_decref on both name and value <-- OOPS
- nghttp2 sets null to both name and value
- nghttp2 calls hd_inflate_keep_free
- nghttp2 calls session_call_on_header
- nghttp2 calls session_after_header_block_received
- nghttp2 calls session_call_on_frame_received
- nghttp2 calls on_frame_recv_callback
- nodejs captures with OnFrameReceive
- nodejs calls HandleHeadersFrame
- nodejs calls GetName and GetValue on header
- nodejs calls reset() on the V8 Allocator
- nodejs calls inc() on NgRcBufPointer
- nodejs calls nghttp2_rcbuf_incref <-- TOO LATE
- nodejs calls inc() on NgRcBufPointer
- nodejs calls reset() on the V8 Allocator
- nodejs calls GetName and GetValue on header
- nodejs calls HandleHeadersFrame
- nodejs captures with OnFrameReceive
- nghttp2 calls on_frame_recv_callback
- nghttp2 calls session_call_on_frame_received
To my understanding, on inflated headers
nghttp2_rcbuf_increfis called far too late. It needs to be called withinOnHeaderCallback, or else it risks being garbage by the time it's sent to Javascript.- nghttp2 calls inflate_header_block
@clshortfuse Thanks for looking into this so thoroughly! Maybe I’m missing something, but the
Http2HeaderinHttp2Stream::AddHeader()does take ownership and callsincref()on the rcbufs it receives, right? And thereset()inGetName()/GetValue()decreases the refcount, but only if we really don’t use the rcbuf anymore (becauseGetInternalizedString()creates its own copy of the string data)?@addaleax I don't think
AddHeader()ever increments the buffer count. It adds it to a stack.OnFrameReceiveiterates through that stack and when it hands it off to V8, then the buffer count increments. But by then it's too late. I was clued into this by this comment:Lines 495 to 498 in 241ed44
It's very possible that on
nghttp(HTTP1.x) you don't have to worry aboutnghttpcallingnghttp2_rcbuf_decrefuntil you get all the headers. But fornghttp2, you can't wait for all headers before you callNgRcBufPointer::inc(). You need to call it per header (withinon_header_callback2). To clarify,on_headerhere means "on individual header" not, "on header collection".Yes, it's more efficient to hand over all the headers to JS once we're done getting them all, but seems like that won't work with inflated
HTTP2header items.Edit: Increment buffer count, not increase buffer
@addaleax Confusingly, despite its name,
.reset()will increase the buffer reference count on first call. It'll decrement when it's called again (by V8 Garbage collection). (Edit: Effectively, on first call. Technically if the pointer is still valid.)I don't think
AddHeader()ever increments the buffer count.To be clear, this is what I’m referring to here:
(gdb) bt #0 0x00005561981f0830 in nghttp2_rcbuf_incref () #1 0x0000556197311ee0 in node::http2::Http2RcBufferPointerTraits::inc (buf=0x55619ad87ac0 <static_table+384>) at ../src/node_http2.h:128 #2 0x0000556197320119 in node::NgRcBufPointer<node::http2::Http2RcBufferPointerTraits>::reset (this=0x7ffc8d595980, ptr=0x55619ad87ac0 <static_table+384>, internalizable=true) at ../src/node_http_common.h:356 #3 0x000055619731c9af in node::NgHeader<node::http2::Http2HeaderTraits>::NgHeader (this=0x7ffc8d595970, env=0x55619bdc44d0, token=-1, name=0x55619ad87ac0 <static_table+384>, value=0x55619ad87ae8 <static_table+424>, flags=0 '\000') at ../src/node_http_common-inl.h:124 #4 0x0000556197316a06 in node::NgHeader<node::http2::Http2HeaderTraits>::NgHeader (this=0x7ffc8d595970, env=0x55619bdc44d0, name=0x55619ad87ac0 <static_table+384>, value=0x55619ad87ae8 <static_table+424>, flags=0 '\000') at ../src/node_http_common-inl.h:113 #5 0x00005561972f52ef in node::http2::Http2Stream::AddHeader (this=0x55619c0da040, name=0x55619ad87ac0 <static_table+384>, value=0x55619ad87ae8 <static_table+424>, flags=0 '\000') at ../src/node_http2.cc:2218 #6 0x00005561972ee7ec in node::http2::Http2Session::OnHeaderCallback (handle=0x55619c054dd8, frame=0x55619c054f80, name=0x55619ad87ac0 <static_table+384>, value=0x55619ad87ae8 <static_table+424>, flags=0 '\000', user_data=0x55619c060050) at ../src/node_http2.cc:845 #7 0x00005561981f8fb5 in nghttp2_session_mem_recv () #8 0x00005561972ee338 in node::http2::Http2Session::ConsumeHTTP2Data (this=0x55619c060050) at ../src/node_http2.cc:744 #9 0x00005561972f2d5c in node::http2::Http2Session::OnStreamRead (this=0x55619c060050, nread=67, buf_=...) at ../src/node_http2.cc:1797 #10 0x0000556197236593 in node::StreamResource::EmitRead (this=0x55619c05fed8, nread=67, buf=...) at ../src/stream_base-inl.h:104 #11 0x000055619741cc78 in node::LibuvStreamWrap::OnUvRead (this=0x55619c05fe80, nread=67, buf=0x7ffc8d595e00) at ../src/stream_wrap.cc:283 #12 0x000055619741c856 in node::LibuvStreamWrap::<lambda(uv_stream_t*, ssize_t, const uv_buf_t*)>::operator()(uv_stream_t *, ssize_t, const uv_buf_t *) const (__closure=0x0, stream=0x55619c05ff20, nread=67, buf=0x7ffc8d595e00) at ../src/stream_wrap.cc:205 #13 0x000055619741c886 in node::LibuvStreamWrap::<lambda(uv_stream_t*, ssize_t, const uv_buf_t*)>::_FUN(uv_stream_t *, ssize_t, const uv_buf_t *) () at ../src/stream_wrap.cc:206 #14 0x0000556197d2f363 in uv__read (stream=stream@entry=0x55619c05ff20) at ../deps/uv/src/unix/stream.c:1239 #15 0x0000556197d2f8f8 in uv__stream_io (loop=<optimized out>, w=0x55619c05ffa8, events=1) at ../deps/uv/src/unix/stream.c:1306 #16 0x0000556197d362dd in uv__io_poll (loop=loop@entry=0x55619ae09280 <default_loop_struct>, timeout=767) at ../deps/uv/src/unix/linux-core.c:431 #17 0x0000556197d23c93 in uv_run (loop=0x55619ae09280 <default_loop_struct>, mode=UV_RUN_DEFAULT) at ../deps/uv/src/unix/core.c:381 #18 0x000055619733464e in node::NodeMainInstance::Run (this=0x7ffc8d599390) at ../src/node_main_instance.cc:130 #19 0x00005561972658ad in node::Start (argc=2, argv=0x7ffc8d5995a8) at ../src/node.cc:1083 #20 0x0000556198078b7b in main (argc=2, argv=0x7ffc8d5995a8) at ../src/node_main.cc:127i.e. yes,
AddHeader()(frame 5 here) does increment the reference count.@addaleax Confusingly, despite its name,
.reset()will increase the buffer reference count on first call.Not if it’s called without an argument.
I guess I was wrong about not being called. I missed the
node_http_common-inl.h. I see howreset()works now.I don't see why
name_.reset(name, true);is called twice:node/src/node_http_common-inl.h
Lines 122 to 127 in f89530f
But I don't think it really matters. I'll have to check another venue. Maybe I'm on the wrong track about the
nghttp2_rcbuf_decref.I don't see why
name_.reset(name, true);is called twice:Yeah, me neither. 😄
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.This issue has been automatically closed after 30 days of inactivity following its stale status (no activity for a total of 120 days).
If this is still relevant, feel free to reopen it or leave a comment with additional details so we can continue the discussion.
This comes from googleapis/nodejs-datastore#415. It looks like occasionally http2 headers objects are being provided from the
http2module with invalid and clearly incorrect header keys. For example, some bad headers objects look like thesewhile valid headers look like this:
In all of the cases we have seen, it looks like the
datekey is replace with this garbled nonsense. My guess is that it is relevant that that header is the one most likely to be encoded in the format Literal Header Field Never Indexed — Indexed Name because the value changes with every request.