S3 multipart upload fails with MalformedXML error

[sashakorman]

Issue description:
Multipart uploads (AWS.S3.ManagedUpload) of relatively big files 5GB and up periodically fail with MalformedXML error.
Digging deeper into this issue we found that the XML error is caused by the CompleteMultipartUpload request - it misses a number of ETags.
For example, this is the part of the request without ETag:
<Part><PartNumber>1388</PartNumber></Part>
Correct part looks like this:
<Part><ETag>"5f4253d8552e801f3c7965055a772612"</ETag><PartNumber>1389</PartNumber></Part>

How to reproduce:
The only way we were able to reproduce the problem, is by creating an environment with a high number of network errors and SDK retries.
Upload a 6GB file with a default part size (5MB) and 'queueSize' parameter set to 50 through a tinyproxy instance running on a low tier machine (t2.small)
Although we have a number of customers who experience the same issues without a proxy as well.

SDK version:
latest version

Node version:
8.12.0 and 10.12.0

What is the root cause for this issue:
In some cases we receive 2 responses for the same part.
I can see it in the logs based on the 'complete' event.

[2018-10-12T08:21:42.819] [INFO] COMPLETE <--- { statusCode: 200,
headers:
{ 'x-amz-id-2': 'CSov++GH99JPUfEUMvnNA0vLKTh7GvwWIPhKi7LNs8NjqZKq0gZc4bApW4k3CTiPWZytaIcQc0U=',
'x-amz-request-id': '9D62197D64AF41E7',
date: 'Fri, 12 Oct 2018 15:21:43 GMT',
etag: '"3df5d2a92abea5f190d79638576d8985"',
'x-amz-server-side-encryption': 'AES256',
'content-length': '0',
server: 'AmazonS3' },
body: ''}

[2018-10-12T08:21:43.317] [INFO] COMPLETE <--- { statusCode: 200,
headers:
{ 'x-amz-id-2': 'Xj/aOO5WkzfBTYD2Chzda4KWSp2kgMEaamWqqdXXMqiaMxmbKhiaxg5WPsV10Q4EwWyoYU/13Zg=',
'x-amz-request-id': 'CB1F77D0A359D027',
date: 'Fri, 12 Oct 2018 15:21:43 GMT',
etag: '"3df5d2a92abea5f190d79638576d8985"',
'x-amz-server-side-encryption': 'AES256',
'content-length': '0',
server: 'AmazonS3' },
body: ''}

Note the same etag and different request id.

SDK manages counter (doneParts) of responses, if one part receives 2 responses the counter is incremented twice, even though it should have only been incremented once. This results in the finishMultiPart function being invoked before all parts responses are received - hence the wrong ETags in the XML.
You can see it here: https://github.com/aws/aws-sdk-js/blob/master/lib/s3/managed_upload.js#L560

SDK fix:
Adding additional IF statement in the managed_upload.js resolves the issue.
Line:
https://github.com/aws/aws-sdk-js/blob/master/lib/s3/managed_upload.js#L558
IF statement:
if (self.completeInfo[partNumber] && self.completeInfo[partNumber].ETag !== null) return null;

[srchase]

Hello @sashakorman,

Thanks for reporting this issue.

Are you interested in submitting your fix as a PR?

[sashakorman]

@srchase Sure, will do. Thanks
Do you need to assign the issue to me and create a branch for the fix?

[AllanZhengYP]

I'm more curious about the root cause of sending a part twice. We do have logic to prevent part from being uploaded twice here and the part number is only monotonically increasing, so this is weird. Do you read the file stream or using buffer when trying to reporduce the issue? Can you try to log the uploadPart() parameters associated to uploading part with same ETag and make sure they have the same part number?

[sashakorman]

@AllanFly120 You are right, the root cause is not clear.
Yes, we using read stream. The parameters are the same.
The interesting part is that this part is retried twice, both with RequestTimeout error from S3 ("Your socket connection to the server was not read or written to within the timeout period").

[AllanZhengYP]

@sashakorman Hey the fix is merged in by the PR above. You are welcome to reply here if you have progress on finding the root cause for this issue.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs and link to relevant comments in this thread.