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.

[billywhizz]

I'm working on this branch for a PR: https://github.com/billywhizz/node/commits/fix-http-client-aborted. After a lot of investigation and testing i am pretty confident the fix is good.

I am not able to get an automated test that reliably reproduces the error as it seems to depend on how the server handles closing the TCP session. It might be possible to mock it if i can figure out exact sequence of events to make it happen. Any suggestions welcome.

If you want to make the error happen you can remove my commit and run this command and it should happen intermittently:

SPURIOUS_ABORTED_REMOTE=on python tools/test.py -J -v --repeat 10 --mode=release parallel/test-http-client-spurious-aborted.js

I haven't been able to make the error happen as yet on that test url when using my commit.

[mcollina]

I would recommend using the debugger to figure out the exact sequence of things that should happen, and approximate it at best. Worst case, set completed to true yourself and call the method.

We won’t accept a PR relying on an external service to run a test. Feel free to send a PR with what you have, and we can iterate from there.

[billywhizz]

I'll give it a go matteo. I think I have narrowed it down to the fact that when the error happens the socket close callback seems to fire pretty much immediately (maybe because server has already closed their end?).

this means the HTTP socket close function gets called before the stream is ended and cleaned up. that is why we see the "aborted" code being hit with the stream still in a readable state and is where my fix runs to check the incomingmessage is complete or not.

I am not sure if that is a bigger bug in how the closing of the socket is handled or not.

here are some debug logs which show the difference between a successful one:

NET 21924: close handle
STREAM 21924: endReadableNT false 0
STREAM 21924: endReadableNT true 0
STREAM 21924: pipeOnDrain 1
STREAM 21924: flow true
STREAM 21924: read undefined
STREAM 21924: endReadable false
STREAM 21924: endReadableNT false 0
STREAM 21924: onend
STREAM 21924: onfinish
STREAM 21924: unpipe
STREAM 21924: onunpipe
STREAM 21924: cleanup
NET 21924: emit close
HTTP 21924: CLIENT socket onClose

and the one that fails:

NET 22205: close handle
STREAM 22205: endReadableNT false 0
STREAM 22205: endReadableNT true 0
NET 22205: emit close
HTTP 22205: CLIENT socket onClose
HTTP 22205: removeSocket www.pdf995.com:80: writable: false
HTTP 22205: HTTP socket close
STREAM 22205: read undefined
STREAM 22205: endReadable true
STREAM 22205: pipeOnDrain 1
STREAM 22205: flow true
STREAM 22205: read undefined
STREAM 22205: endReadable false
STREAM 22205: endReadableNT false 0
STREAM 22205: onend
STREAM 22205: onfinish
STREAM 22205: unpipe
STREAM 22205: onunpipe
STREAM 22205: cleanup

[billywhizz]

@mcollina let me know what you think about this. maybe there is a better way to do it but with this i can reliably recreate the condition and have verified it fails test before my change and passes after: billywhizz@d54f7ba

[billywhizz]

let me know if you are happy for me to make the PR based on the above guys.

[mcollina]

Please fire a PR. It would be easier to review and gather feedback.

[billywhizz]

Pull Request created here: #18999