S3 CompleteMultipartUpload returning err with 200 response

[purohit]

Hello,

Since today at 4pm UTC my Travis-CI test using the s3 library has been failing, because I have code like this:

out, err := client.CompleteMultipartUpload(params)
if err != nil {
    log.Fatalf("Couldn't complete multipart upload: %s", err)
}

And the status code seems to be 200, but there's still an error issued; the output is:

2016/01/13 23:38:55 Couldn't complete multipart upload: 200OK: 200 OK
    status code: 200, request id: 3A8F6E6D0A95AA3C

I feel like there shouldn't be an error returned on a 200. Can you let me know how I should be handling errors, or if this is a bug?

Thanks!

[jasdel]

Thanks for contacting us @purohit. In this case 200 status code is valid. For long running operations S3 needs to send back the a response or clients will timeout. In these cases the initial API request was successful, such as auth, resource found, ect. Then S3 sends back the status code to prevent the client from disconnecting due to read deadlines. If these long running operations fail after the status code is sent there is no way to send a new status code, so just the error body is returned.

It is interesting no Exception code and message are being included in that error message. Could you enable debug logging (aws.LogDebugWithHTTPBody)so we can see the body of the S3 response. Which region are you using?

svc := s3.New(session.New(), aws.NewConfig().WithLogLevel(aws.LogDebugWithHTTPBody))
// make requests

There doesn't appear to be any outages so I suggest contacting customer support.

[jasdel]

Also, what size of file are you uploading, and are you specifying the PartSize, Concurrency, or MaxUploadParts ?

[purohit]

Hi @jasdel,

Region: us-west-2.

Thanks for the fast response! It turns out the problem only happens on our Travis-CI builds, not local ones -- which was strange. That indicated that while previously err == nil on a 200, perhaps the behavior was updated in some commit in aws-sdk-go that changed it to report an error. Travis-CI pulls the latest aws-sdk-go, while locally we run an older version.

It initially was hard to get the logs because Travis-CI stops logging after 4MB of data, and S3 requires a minimum of 5MB for a multipart upload! But I just modified the client on the fly right before the CompleteMultipartUpload request, and here are the results

With Travis (err != nil):

2016/01/14 02:26:20 DEBUG: Response s3/CompleteMultipartUpload Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: application/xml
Date: Thu, 14 Jan 2016 02:26:21 GMT
Server: AmazonS3
X-Amz-Id-2: hfyBiKFUbdt+qZlyPI+R0CzPR9CuzZQUgXMx6GrEFPf8XgVyh9PoGJSIhEdZCvFCGVw0kqLcDiI=
X-Amz-Request-Id: 440D3953A7724A06
185
<?xml version="1.0" encoding="UTF-8"?>
<CompleteMultipartUploadResult xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Location>https://our-test-files.s3-us-west-2.amazonaws.com/s3-test-1452738376130177164</Location><Bucket>our-test-files</Bucket><Key>s3-test-1452738376130177164</Key><ETag>&quot;db3d92caa11d0fe265f5752d43f9fcf0-5&quot;</ETag></CompleteMultipartUploadResult>

Locally (err == nil):

2016/01/13 19:02:03 DEBUG: Response s3/CompleteMultipartUpload Details:                                                                                                                           
---[ RESPONSE ]--------------------------------------                                                                                                                                             
HTTP/1.1 200 OK^M                                                                                                                                                                                 
Transfer-Encoding: chunked^M                                                                                                                                                                      
Content-Type: application/xml^M                                                                                                                                                                   
Date: Thu, 14 Jan 2016 02:02:27 GMT^M                                                                                                                                                             
Server: AmazonS3^M                                                                                                                                                                                
X-Amz-Id-2: h6FtAB55A4gFLWPb3b9AK0FDxF9jd2Qg/hVdTmAqcoim/0trOVXO1j11G6fI9I3cOZqNPaPwxNg=^M                                                                                                        
X-Amz-Request-Id: 801850193878E42C^M                                                                                                                                                              
^M                                                                                                                                                                                                
185^M                                                                                                                                                                                             
<?xml version="1.0" encoding="UTF-8"?>                                                                                                                                                            

<CompleteMultipartUploadResult xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Location>https://our-test-files.s3-us-west-2.amazonaws.com/s3-test-1452736919985166867</Location><Bucket>our-test-files</Bucket><Key>s3-test-1452736919985166867</Key><ETag>&quot;39f6fbf954e0596a853b128b2cc35ba3-5&quot;</ETag></CompleteMultipartUploadResult>

The file is there from either version, so it seems clear that nothing is actually wrong -- the multipart upload works. I will investigate tomorrow with bisect to see if I can find which commit in aws-sdk-go is causing me problems, if that is the cause.

Thanks for the tip on the WithLogLevel(aws.LogDebugWithHTTPBody), that helped a lot.

[jasdel]

@purohit thanks for the update! that was very helpful. I wasn't up to date locally here so missed the change that caused this issue. Looks like the fix to error handling in a3ecfb4 may of caused this bug.

Specifically changing the service/s3/unmarshal_error.go's r.HTTPResponse.ContentLength check to <=1`. from == 0. This looks to be a conflict between 200 status code successful request with no body nor content length set, and a 4xx status code which is an error and no body also

[jasdel]

Hi @purohit thanks again for reporting this. This was a regression in the change I mentioned above. 6811074 fixes this by correcting the ContentLength check and adds additional test cases to cover these conditions in the future.

[purohit]

I can confirm this also fixed the regression on my end. Thanks for taking care of it.