http2 session closing after 2 minutes, even if activity

[akc42]

I have a client which sends a regular 1 minute api request to my http2 server.

On the server I have added on a listener for a session event, and on that session added a stream event listener. Then for each of the possible session events and stream events listed in the docs I have added listeners for those.

I am doing this in order to get better understanding as to why #14925 is happening

What I have discovered is that as the client makes its first heartbeat, the session is opened. Then at almost exactly ( within a millisecond) two minutes the session is closed regardless of the fact that at least one other request had been made on that session (at one minute from open).

I am also measuring the gap between closing the session and starting a new one, and that is just short of (to within 10 milliseconds) one minute. This indicates to me that the one minute heartbeat request is what is causing a new session to be made.

Is this is what is expected? I have tried reading the http2 spec, but its very light on what a session (I think it calls it a connection) is.

Because of the natural synchronisation of the heartbeat to the session boundaries, and the fact that I see an aborted event on the stream at the instance #14925 is triggered, I am wondering if its possible for session timeout (because thats what it appears to be ALTHOUGH no timeout event is fired) to be killing of the heartbeat request whilst it is in progress. If that IS the case, that seems to be very undesirable behaviour.

[akc42]

The gap between closing a session and starting a new one can sometimes be 2 milliseconds, even though normally its a minute +- 10 milliseconds. I still think that it the heartbeat re-opening the session, its just that in that instance the session closed fractionally before the heartbeat was due.

[akc42]

I have done some further experiments, and it is a socket timeout that is being fired, but http2 module fires the timeout event on the server. If I catch that and return true, the session doesn't then terminate.

The other strange this is that after this socket timeout occurs once and I catch it, it no longer times out again.

Still trying to find out why the socket timeout occurs in the first place.

[akc42]

One further datapoint. If I refresh the browser, I get a new session started, the socket timeout occurs once more (two minutes later) and then doesn't occur again.

[akc42]

And one more check. I changed the client so that after 15 minutes it changed the heartbeat rate to once every 5 minutes. That should have meant that the timeout should have fired once the rate dropped off. However after the first timeout event no further timeouts occurred.

[benjamingr]

Pinging @nodejs/http2, thanks a lot for your detailed report @akc42

Also pinging @phouri in case you want to take a (guided) stab at this.

[phouri]

Sure! I'll take a look today/tomorrow

[mcollina]

Are you using master? we landed some critical fixes on timeout and error handling from the latest release.

[akc42]

No this is on 8.4.0

[mcollina]

Can you verify if this behavior is still happening on master, or if it differs?

[akc42]

Just built node from master, and the session close is behaviour is exactly the same as described in my first post of this issue. I removed the timeout on server.

I'll now try the test with a timeout on server and with the heartbeat switching for minute to 5 minutes after 15 minutes

[akc42]

I now ran the test with a heartbeat at a minute for 15 minutes, and then switched the heartbeat to every 6 minutes.

The result was basically the same as the previous test, except I had two initial timeouts (at 2 and 4 minutes in) but then no more. So again, I expected that when the heartbeat switched out to 6 minutes the session would timeout, but it didn't

[apapirovski]

I can replicate this on a barebones implementation. Tracing it down.

[apapirovski]

@mcollina, @jasnell

So this is basically a result of setting a socket timeout but since nghttp2 manages the socket, the timeout is never _unrefActive and ends up always triggering after whatever the timeout setting is (default is 120 seconds). Do we even need a socket timeout? Shouldn't we just make do with a session timeout? And then we should also probably document that there's a default session timeout.

(The alternative is just to call _unrefActive(this[kSocket]) or _unrefActive(this[kOwner][kSocket]) a whole bunch of places.)

Happy to put together a PR if I can get some answers to the above.

Reference:

node/lib/internal/http2/core.js

Lines 2288 to 2291 in 8d5b013

	if (this.timeout) {
	socket.setTimeout(this.timeout);
	socket.on('timeout', socketOnTimeout);
	}

[mcollina]

1. can we keep the socket alive whenever one of its stream is active? Will it be no-overhead? If not, then we should not have a socket timeout.
2. I think we should not have a socket timeout by default, but rather a session timeout by default.

Anyway, start working on a PR!

[apapirovski]

@mcollina thanks. will submit a PR sometime today.

[jasnell]

+1 a PR would be great. I'll dig in on this a bit more tho, as there may still be some scenarios where the socket timeout is appropriate.