HTTP Client 'aborted' event fires even when request was ok

[billywhizz]

• Version: all versions from 4.x - > 9.x
• Platform: Linux/Ubuntu 16.04 x64
• Subsystem: http/https

We have been having issues with http/https downloads failing silently and the file being downloaded having an incorrect size for some time now. We are using axios library to do download and after some research and testing the only way we could get alerted about an incomplete download (connection is forcibly closed by server in middle of downloading body) was to handle the http response "aborted" event.

However, when we handled this we noticed we were having good downloads, where file contents were completely received, reported as "aborted".

Maybe this is intended behaviour but it makes more sense to me to only receive aborted event on a client response if the socket close happened before the active http response has been received completely. Currently, there is no check for the current active response having completed or not before firing the aborted event.

You can see the behaviour in this gist - the firing of the aborted event seems completely random and is likely due to timing of when the server closes the socket.

Our workaround is to use the commented code here to check if the current response is complete and ignore the aborted event if so.

Should the same logic be used in node.js core? Appreciate this could cause issues for existing libraries depending on current behaviour.

[bnoordhuis]

I can't reproduce what you're seeing, the file is the expected size and aborted === false in the finish callback. I tried a couple of node versions, including master.

all versions from 0.4.x - > 0.9.x

Is that a typo? Anything < v4.x is obsolete.

[billywhizz]

Yes, that's a typo. Fixed now. Sorry. If you leave the script running for a bit you should see some of the requests with aborted = true. here is my output running on Ubuntu/x64 with node v8.9.4:

error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: true, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: true, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994
error: false, complete: true, status: 200, aborted: false, size: 433994, connection: close, content-length: 433994

[apapirovski]

@billywhizz Chances are that we haven't received the final \r\n or something like that but the socket has already closed. If you look at the code where complete is set, it just means that the body has been fully received but it doesn't mean the response has actually ended. So if the socket closes prematurely at that point then I don't think there's a way we can tell if what we got was well-formed or not. I could be wrong, not an expert on the client implementation or the http spec.

/cc @nodejs/http @nodejs/http2

[dougwilson]

Chances are that we haven't received the final \r\n or something like that

It would have to be something else, because the code in the gist is printing out the Content-Length response header. The \r\n is only part of something like chunked transfer encoding, but that's not being used here since there is a Content-Length header -- the last byte of the body is the last byte of the response.

I see this in the RFC:

5. If a valid Content-Length header field is present without
   Transfer-Encoding, its decimal value defines the expected message
   body length in octets. If the sender closes the connection or
   the recipient times out before the indicated number of octets are
   received, the recipient MUST consider the message to be
   incomplete and close the connection.

But it seems like it's not closed before the last octet is received, since it's there in the download, it would seem. I haven't debugged through it yet, but it would seem that if the connection is aborted just after that last octet is received, it shouldn't emit aborted on the actual response object, since the response wasn't aborted (the connection was aborted after the response finished cleanly).

[apapirovski]

@dougwilson it seems you're right, if we receive a message body with a matching Content-Length then we shouldn't be emitting aborted under any circumstances.

I haven't even tried the sample script so not sure if I can reproduce. Might have time to look into it this coming weekend if no one else does.

[billywhizz]

for context, here are the tests we were trying to get passing. if we don't handle the 'aborted' event we occasionally get a completed download with no errors but the file size is truncated. if we handle the 'aborted' event and don't check for res.complete then more often we get good downloads being reported as aborted.

git clone https://gist.github.com/billywhizz/bf3367a6843f9fe64a089716ab167fe0
cd bf3367a6843f9fe64a089716ab167fe0
npm install && npm run test

if we change to not check the res.complete here we will get occasional errors in final two tests as in the earlier gist i posted.

[billywhizz]

This diff on node release v8.9.4 fixes the issue for my tests so i can just handle 'aborted' and it works as expected.

-diff --git a/lib/_http_client.js b/lib/_http_client.js
index fa9e4e2..a1d2580 100644
--- a/lib/_http_client.js
+++ b/lib/_http_client.js
@@ -350,7 +350,7 @@ function socketCloseListener() {
   req.emit('close');
   if (req.res && req.res.readable) {
     // Socket closed before we emitted 'end' below.
-    req.res.emit('aborted');
+    if (!req.res.complete) req.res.emit('aborted');
     var res = req.res;
     res.on('end', function() {
       res.emit('close');
a

[mcollina]

@billywhizz that was good research! Would you mind sending out a PR with a fix?

[billywhizz]

@mcollina sure thing. i should have one for you in morning. will read up on the guidelines first. i can likely also add some tests based on the ones i posted above.

[mcollina]

yes definitely!

@dougwilson what do you think of that proposed fix?

[dougwilson]

Trying it out with a test server, the behavior change with the patch looks like what I would expect 👍

[billywhizz]

i spent some time last night and was not able to reproduce the error using tests i wrote according to the ones that are currently there in nodejs repo. i am wondering if it's some weird edge case being caused by my other tests. will do some more digging and report back if i find anything useful.

[billywhizz]

I can now make the error happen in a test but using the external site to serve the file and only happens intermittently. i captured a debug trace to compare sequence of events when it fails and when it doesn't and you can see it here.

hopefully will be able to produce a test that triggers that condition reliably.