Repository navigation
http2 session closing after 2 minutes, even if activity #15158
Description
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.
Activity
akc42 commentedon Sep 3, 2017
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 commentedon Sep 3, 2017
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 commentedon Sep 3, 2017
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 commentedon Sep 3, 2017
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 commentedon Sep 3, 2017
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 commentedon Sep 3, 2017
Sure! I'll take a look today/tomorrow
mcollina commentedon Sep 3, 2017
Are you using master? we landed some critical fixes on timeout and error handling from the latest release.
akc42 commentedon Sep 3, 2017
No this is on 8.4.0
mcollina commentedon Sep 3, 2017
Can you verify if this behavior is still happening on master, or if it differs?
akc42 commentedon Sep 3, 2017
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 commentedon Sep 3, 2017
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 commentedon Sep 3, 2017
I can replicate this on a barebones implementation. Tracing it down.
apapirovski commentedon Sep 3, 2017
@mcollina, @jasnell
So this is basically a result of setting a socket timeout but since nghttp2 manages the socket, the timeout is never
_unrefActiveand 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
mcollina commentedon Sep 4, 2017
Anyway, start working on a PR!
apapirovski commentedon Sep 4, 2017
@mcollina thanks. will submit a PR sometime today.
jasnell commentedon Sep 4, 2017
+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.
http2: use session not socket timeout, tests
http2: use session not socket timeout, tests
http2: use session not socket timeout, tests
http2: use session not socket timeout, tests
http2: use session not socket timeout, tests