http2: fix several timeout related issues #16525

apapirovski · 2017-10-26T19:30:54Z

This resolves a couple of issues around timeouts in http2.

Upon start and stop of write, _unrefActive should be called both on stream and on session. I can't really create a good test case for this because it's way too reliant on timers. One can observe this by having a server receive a request, have a timeout of 1000ms on the session and delay the stream response (which has to last longer than 500ms) by 500ms. The session will timeout 500ms after the stream write starts (instead of 1000ms).
Long writes will always timeout because once the data is handed off to C++, JS loses all track of it. This is basically the same issue as the one recently patched in net & tls. Solution is a bit different because tracking writeQueueSize in C++ is not quite reliable due to framing headers and what not.

(Much like with tls/net, the solution isn't super straightforward because we don't want to completely tank the performance of requests that aren't likely to timeout.)

To test locally, you can use the following server:

'use strict';

const http2 = require('http2');

const server = http2.createServer((req, res) => {

  var content = Buffer.alloc(30000000, 0x44);

  res.writeHead(200, {
    'Content-Type': 'application/octet-stream',
    'Content-Length': content.length.toString(),
    'Vary': 'Accept-Encoding'
  });

  res.write(content);
  res.end();
});
server.setTimeout(1000);

server.listen(8000);

and run this in your terminal:

nghttp http://localhost:8000 | dd bs=1 of=/dev/null

A successful result would be 30000000+0 records in (and take around 40s) but it'll stop after only 1s with current versions of node.

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
commit message follows commit guidelines

Affected core subsystem(s)

http2, test

Currently reset timers on both session & stream when write starts and when it ends.

apapirovski · 2017-10-26T19:37:29Z

Also, needless to say, any and all input on the C++ end is appreciated. Still trying to get a handle on all of it.

When writing a large chunk of data in http2, once the data is handed off to C++, the JS session & stream lose all track of the write and will timeout if the write doesn't complete within the timeout window Fix this issue by tracking whether a write request is ongoing and also tracking how many chunks have been sent since the most recent write started. (Since each write call resets the timer.)

mcollina

LGTM

apapirovski · 2017-10-26T21:19:29Z

CI: https://ci.nodejs.org/job/node-test-pull-request/11005/ (edit: lone failure is unrelated)

apapirovski · 2017-10-28T19:19:35Z

@addaleax if you happen to have some spare bandwidth in the next few days, would appreciate a review both for C++ reasons and because you reviewed the net/tls version of this. Thanks!

(The tests are probably the longest part of this and are identical to the net/tls version so you can probably skip them. They're pretty verbose...)

addaleax

Nice work!

addaleax · 2017-10-28T19:39:36Z

lib/internal/http2/core.js

+function trackWriteState(stream, bytes) {
+  const session = stream[kSession];
+  stream[kState].writeQueueSize += bytes;
+  session[kState].writeQueueSize += bytes;


Any chance we could rename the property to writeQueueBytes if it’s counting bytes? My initial thought was it was counting the # of write reqs… I realize this makes sense because if it were trakcing the # of reqs, it would probaly be Length rather than Size, but maybe being even more explicit could be helpful?

It's currently the same name as net/tls but I can definitely rename if that's preferred.

Nah, if it’s for consistency then this is fine

addaleax · 2017-10-28T19:42:27Z

lib/internal/http2/core.js

+    if (this[kState].writeQueueSize > 0) {
+      const handle = this[kHandle];
+      if (handle !== undefined &&
+          handle.chunksSentSinceLastWrite !== handle.updateChunksSent()) {


The right side of this comparison modifies the left side, right? Could we maaaaybe store the left side in a variable? 😄

addaleax · 2017-10-28T20:11:56Z

src/node_http2.cc

@@ -811,6 +830,8 @@ int Http2Session::DoWrite(WriteWrap* req_wrap,
    }
  }

+  chunks_sent_since_last_write_ = 0;


Is my understanding correct that this and SubmitFile are the only parts of the HTTP2 source that can trigger Http2Session::Send to be called?

~~As far as I could tell, yes.~~ misleading

Sorry, to be clear: it doesn't quite matter if they're the only parts that can trigger it because any trigger of Send means that the connection is still active (in some form). The more important part of this is that only DoWrite and SubmitFile are triggered when a write occurs and hence the only ones that should reset chunks_sent_since_last_write_.

Hm, okay. My question wasn’t relevant to this particular PR – it just was kind of my hope that this meant the # of places that could schedule a write would be overseeable so that it would be easy to turn the uv_prepare_t we use on/off in those places

Right. I think that loop is a bit more complicated since nghttp2 manages the flow of data. The only place that can call Send is SendPendingData which requests it from nghttp2_session_mem_send. I think there are like 2-3 places that call SendPendingData.

Send itself is responsible for all the data going to the socket, which includes all the frames that nghttp2 itself manages. I think @jasnell might have more insight, I've only started figuring out nghttp2 in the last few weeks.

Yeah – basically, the question was if these were the only places that would make nghttp2 want to write something to the socket ;) I guess I can answer that for myself with a ”no”, in the end.

There are lots of things that could trigger Ng too want to write. Responding to ping frames, for instance, is handled entirely by Ng without any intervention from our code. There are also automatic error handing situations that do not bubble up to our code.

Responding to ping frames, for instance, is handled entirely by Ng without any intervention from our code.

How do we know we need to write to the socket in those cases?

That's currently why we attempt to send on every event loop tick. There is a want_write api, however that can be checked. It won't tell you how much data is pending to write, but it will answer true so long as there is data pending in the queue.

Thanks, makes sense!

apapirovski · 2017-10-28T20:33:10Z

Thanks for the review @addaleax & @mcollina! Implemented the tiny change request as per above.

apapirovski · 2017-10-29T16:18:28Z

I'll be merging this within the next hour or so (so it can make 9.0.0), barring any objections. It has 3 reviews + sat around for 3 days.

jasnell · 2017-10-29T16:20:58Z

merging it right now actually

jasnell · 2017-10-29T16:21:14Z

doing one last local make test then will be pushing

apapirovski · 2017-10-29T16:21:21Z

Awesome, thanks @jasnell!

* correctly reset write timers: currently reset timers on both session & stream when write starts and when it ends. * prevent large writes from timing out: when writing a large chunk of data in http2, once the data is handed off to C++, the JS session & stream lose all track of the write and will timeout if the write doesn't complete within the timeout window Fix this issue by tracking whether a write request is ongoing and also tracking how many chunks have been sent since the most recent write started. (Since each write call resets the timer.) PR-URL: #16525 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>

jasnell · 2017-10-29T17:02:31Z

Landed in ca82e30

* correctly reset write timers: currently reset timers on both session & stream when write starts and when it ends. * prevent large writes from timing out: when writing a large chunk of data in http2, once the data is handed off to C++, the JS session & stream lose all track of the write and will timeout if the write doesn't complete within the timeout window Fix this issue by tracking whether a write request is ongoing and also tracking how many chunks have been sent since the most recent write started. (Since each write call resets the timer.) PR-URL: #16525 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>

* correctly reset write timers: currently reset timers on both session & stream when write starts and when it ends. * prevent large writes from timing out: when writing a large chunk of data in http2, once the data is handed off to C++, the JS session & stream lose all track of the write and will timeout if the write doesn't complete within the timeout window Fix this issue by tracking whether a write request is ongoing and also tracking how many chunks have been sent since the most recent write started. (Since each write call resets the timer.) PR-URL: nodejs/node#16525 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>

http2: correctly reset write timers

a051ccc

Currently reset timers on both session & stream when write starts and when it ends.

apapirovski added c++ Issues and PRs that require attention from people who are familiar with C++. http2 Issues or PRs related to the http2 subsystem. labels Oct 26, 2017

apapirovski requested review from jasnell and addaleax October 26, 2017 19:30

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. labels Oct 26, 2017

apapirovski force-pushed the patch-http2-timeouts branch 2 times, most recently from 131b1a1 to 80c834d Compare October 26, 2017 19:32

apapirovski force-pushed the patch-http2-timeouts branch from 80c834d to 03d7e3f Compare October 26, 2017 19:38

apapirovski requested a review from mcollina October 26, 2017 19:42

mcollina approved these changes Oct 26, 2017

View reviewed changes

addaleax approved these changes Oct 28, 2017

View reviewed changes

[fixup] store chunksSentSinceLastWrite in var

809bb46

jasnell approved these changes Oct 28, 2017

View reviewed changes

apapirovski mentioned this pull request Oct 29, 2017

Proposal: 2017-10-31, Version 9.0.0 (Current) #15135

Merged

jasnell closed this Oct 29, 2017

apapirovski deleted the patch-http2-timeouts branch October 29, 2017 17:03

gibfahn mentioned this pull request Oct 31, 2017

v8.9.0 proposal #16630

Merged

fcicq mentioned this pull request Nov 5, 2017

http2: exception on stream destroy #16543

Closed

MylesBorins added the dont-land-on-v6.x label Nov 16, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

http2: fix several timeout related issues #16525

http2: fix several timeout related issues #16525

apapirovski commented Oct 26, 2017

apapirovski commented Oct 26, 2017

mcollina left a comment

apapirovski commented Oct 26, 2017 •

edited

Loading

apapirovski commented Oct 28, 2017

addaleax left a comment

addaleax Oct 28, 2017

apapirovski Oct 28, 2017

addaleax Oct 28, 2017

addaleax Oct 28, 2017

apapirovski Oct 28, 2017

addaleax Oct 28, 2017

apapirovski Oct 28, 2017 •

edited

Loading

apapirovski Oct 28, 2017 •

edited

Loading

addaleax Oct 28, 2017

apapirovski Oct 28, 2017

addaleax Oct 28, 2017

jasnell Oct 28, 2017

addaleax Oct 28, 2017

jasnell Oct 28, 2017

addaleax Oct 28, 2017

apapirovski commented Oct 28, 2017

apapirovski commented Oct 29, 2017

jasnell commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 29, 2017

jasnell commented Oct 29, 2017

http2: fix several timeout related issues #16525

http2: fix several timeout related issues #16525

Conversation

apapirovski commented Oct 26, 2017

Checklist

Affected core subsystem(s)

apapirovski commented Oct 26, 2017

mcollina left a comment

Choose a reason for hiding this comment

apapirovski commented Oct 26, 2017 • edited Loading

apapirovski commented Oct 28, 2017

addaleax left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

apapirovski Oct 28, 2017 • edited Loading

Choose a reason for hiding this comment

apapirovski Oct 28, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

apapirovski commented Oct 28, 2017

apapirovski commented Oct 29, 2017

jasnell commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 26, 2017 •

edited

Loading

apapirovski Oct 28, 2017 •

edited

Loading

apapirovski Oct 28, 2017 •

edited

Loading