Aws-sdk-go: [S3] RequestError with UploadPart call

[arjunmahishi]

Please fill out the sections below to help us address your issue.

Version of AWS SDK for Go?

v1.18.2

Version of Go (go version)?

go version go1.10.4

What issue did you see?

We are using MultipartUpload for uploading some mp3 files to S3. At times, the S3.UploadPart function throws the following error:

RequestError: send request failed
caused by: Put https://<bucket_name>.s3.ap-southeast-1.amazonaws.com/filename.mp3?partNumber=1&uploadId=FQEnFylcgwfiSyqAFJSAaBPujuG_ooLOCrPnHv5vO_Un0W5_Ml8DYeqB4xx7US_IFbcdkjrWZqizTemAKyx3MNYwku6BPRqvLz3eGxAqndFUUw--: http: Request.ContentLength=4674720 with nil Body

Here is the code the code that handles the uploading part:

func uploadPart(svc *s3.S3, resp *s3.CreateMultipartUploadOutput, fileBytes []byte, partNumber int) (*s3.CompletedPart, error) {
    tryNum := 1

    body := bytes.NewReader(fileBytes)
    partInput := &s3.UploadPartInput{
        Body:          body,
        Bucket:        resp.Bucket,
        Key:           resp.Key,
        PartNumber:    aws.Int64(int64(partNumber)),
        UploadId:      resp.UploadId,
        ContentLength: aws.Int64(int64(len(fileBytes))),
    }

    for tryNum <= maxRetries {
        uploadResult, err := svc.UploadPart(partInput)
        if err != nil {
            if tryNum == maxRetries {
                if aerr, ok := err.(awserr.Error); ok {
                    return nil, aerr
                }
                return nil, err
            }
            log.Printf("Retrying to upload part #%v\n", partNumber)
            tryNum++
        } else {
            return &s3.CompletedPart{
                ETag:       uploadResult.ETag,
                PartNumber: aws.Int64(int64(partNumber)),
            }, nil
        }
    }
    return nil, nil
}

Steps to reproduce

Not reproducable. Happens only some times. The body is not actually nil. Made sure of it by checking it in the logs.

[jasdel]

Thanks for reaching out to us @arjunmahishi. Do you see this issue without the retry logic around the UploadPart operation call? The SDK will automatically retry the operation if it fails to upload.

Is it possible that the body bytes.Reader value needs to be seeked to the beginning of the byte buffer before retrying?

Also, have you checked out the SDK's provided S3 Upload Manager? It provides the logic to wrap multi-part upload. The uploader is also able to handle multi-part uploads from a input file. The Uploader will automatically split the file into parts for concurrent uploads.

[arjunmahishi]

@jasdel Trying it. Does it use multipart upload if the files size is more than the given partSize?

[diehlaws]

@arjunmahishi Yes, conversely if the file size is smaller than the PartSize specified for the uploader then the file will be uploaded in a single PUT request rather than a multipart upload.

[arjunmahishi]

RequestError: send request failed caused by: Put https://<bucket_name>.s3.ap-southeast-1.amazonaws.com/filename.mp3?partNumber=1&uploadId=FQEnFylcgwfiSyqAFJSAaBPujuG_ooLOCrPnHv5vO_Un0W5_Ml8DYeqB4xx7US_IFbcdkjrWZqizTemAKyx3MNYwku6BPRqvLz3eGxAqndFUUw--: http: Request.ContentLength=4674720 with nil Body

This is fixed now thank you so much for the help! :smile:

[arjunmahishi]

I don't think the issue is resolved. Now it says

2019/03/29 11:02:07 Error occurred while uploading /var/recordings/98a8d64ab5d01c9e00ba4ca1e292ce61.mp3 . Error : RequestError: send request failed
caused by: Put https://<bucketName>.s3.ap-southeast-1.amazonaws.com/98a8d64ab5d01c9e00ba4ca1e292ce61.mp3: EOF Current file size:  678071

This is happening as often as before. And it is only happening for files that are smaller than the defined PartSize

[jasdel]

Thanks for the update @arjunmahishi the SDK's S3 Uploader will automatically use a normal PutObject operation if the uploader can determine that the size to put is smaller than PartSize. Do you have a code sample that using the Uploader?

From the error message this suggests that the content uploaded does not match the size specified when the upload started.

[arjunmahishi]

Input

fileReader := bytes.NewReader(buffer)
input := &s3manager.UploadInput{
    Bucket:      aws.String(awsBucketName),
    Key:         aws.String(filename),
    ContentType: aws.String(fileType),
    ACL:         aws.String("public-read"),
    Body:        fileReader,
}

Upload function

func upload(svc s3iface.S3API, input *s3manager.UploadInput) (*s3manager.UploadOutput, error) {
    if input.Body == nil {
        return nil, fmt.Errorf("the body provided in input is nil")
    }

    uploader := s3manager.NewUploaderWithClient(svc, func(uploader *s3manager.Uploader) {
        uploader.PartSize = maxPartSize
        uploader.LeavePartsOnError = false
    })

    uploadOutput, err := uploader.Upload(input)
    if err != nil {
        return nil, err
    }
    return uploadOutput, nil
} 

More context

• buffer is a byte array of the entire file
• maxPartSize is 5242880

[arjunmahishi]

From the error message this suggests that the content uploaded does not match the size specified when the upload started.

I don't think we are specifying the file size anywhere.

[arjunmahishi]

Any insight on this? It's a little urgent.
@jasdel @diehlaws

[diehlaws]

Thanks for the update @arjunmahishi. Unfortunately I haven't been able to reproduce this behavior with the most recent code snippet you provided.

• How are you opening these files before sending their contents to buffer as a byte array?
• What is the origin of the files being uploaded in relation to the host running your code (local / networked storage, streamed from external source, etc)?
• Is there any chance something else is interacting with these files as they are being uploaded to S3 by the SDK?
• Can you enable debug logging on your session and provide the output corresponding to an upload that fails as described? LogDebug should be sufficient, however LogDebugWithRequestErrors may give us additional information relevant to this behavior.

[arjunmahishi]

• Opening the file:

file, err := os.Open(path)
if err != nil {
    log.Printf("err opening file: %s", err)
    return err
}
defer file.Close()
fileInfo, _ := file.Stat()
size := fileInfo.Size()
buffer := make([]byte, size)
file.Read(buffer)

• The files are stored locally on disk
• Nothing else is interacting with the files
• Ok. I'll enable the debug logs and update

[jasdel]

@arjunmahishi thanks for the update. Out of curiosity, does your code check that the number of bytes read return parameter of Read equal the size value determined earlier? It is possible for a file.Read to return early without reading all the bytes.

Instead of using file.Read directly I suggest using io.Copy to copy from the file reader to the buffer.

var buffer bytes.Buffer
n, err := io.Copy(&buffer, file)
if err != nil && err != io.EOF {
    // error hanlding
}
if n != size {
    // Error, expected to read size, got n bytes
}

you could also pre-allocate the bytes.Buffer byte slice as well as an optimization.

buffer := bytes.NewBuffer(make([]byte, size))

[arjunmahishi]

Sure. Will try this and get back!

[arjunmahishi]

Instead of using file.Read directly I suggest using io.Copy to copy from the file reader to the buffer.

var buffer bytes.Buffer
n, err := io.Copy(&buffer, file)
if err != nil && err != io.EOF {
    // error hanlding
}
if n != size {
    // Error, expected to read size, got n bytes
}

you could also pre-allocate the bytes.Buffer byte slice as well as an optimization.

buffer := bytes.NewBuffer(make([]byte, size))

Followed the above suggestion. But it is still happening. It gives the same error.

I have added this,

if n != size {
    log.Printf("files size is not consistent. determined size: %d, actual size: %d", size, n)
}

This is never logged, which means size is always consistent.

[jasdel]

Thanks for the update @arjunmahishi. Out of curiosity do you experience the same behavior if you don't set uploader.PartSize, and provide the file value for the UploadInput.Body parameter, instead of using the byte buffer?

[arjunmahishi]

Ok...trying. Will it still be multipart in case of bigger files?

[arjunmahishi]

Now I am passing the file value directly to UploadInput.Body. Still, the same error is coming.

This mentions something about throttling. Could that be the reason?

[arjunmahishi]

Any update on this?
@jasdel @diehlaws

[jasdel]

Thanks for the update @arjunmahishi could you provide an updated example usign the file directly? We've not had success reproducing this issue yet. In addition does your application set the ContentLength property of the UploadInput type?

The S3 Upload manager should use multipart upload for all files larger than 5MB or, if the uploader is unable to determine the length of the content to be uploaded, (e.g. body that is not seekable, nor has a Len method)

[arjunmahishi]

How input object is created

file, err := os.Open(path)
filename := filepath.Base(path)
if err != nil {
    log.Printf("err opening file: %s", err)
    return err
}
defer file.Close()

fileType := "audio/mpeg"
input := &s3manager.UploadInput{
    Bucket:      aws.String(awsBucketName),
    Key:         aws.String(filename),
    ContentType: aws.String(fileType),
    ACL:         aws.String("public-read"),
    Body:        file,
}

Upload handling function

func upload(svc s3iface.S3API, input *s3manager.UploadInput) (*s3manager.UploadOutput, error) {
    if input.Body == nil {
        return nil, fmt.Errorf("the body provided in input is nil")
    }

    uploader := s3manager.NewUploaderWithClient(svc, func(uploader *s3manager.Uploader) {
        uploader.PartSize = maxPartSize
        uploader.LeavePartsOnError = false
    })

    uploadOutput, err := uploader.Upload(input)
    if err != nil {
        return nil, err
    }
    return uploadOutput, nil
}

As you can see, we are not setting the ContentLength

[jasdel]

Thanks for the updated example code @arjunmahishi. Couple clarification questions:

• Does your application by chance reuse the passed in input for s3manager.UploadInput parameter?
• Are your upload function being called concurrently?
• If upload is being used concurrently, how is the input parameter constructed?

We're investigating this issue. A non-deterministic issue like this sounds like either something is modifying the input, one of its parameters, or the SDK is potentially having issues with correctly handling retries.

[arjunmahishi]

• No, I just verified, the input not being reused anywhere. It is just being passed to the upload function.
• Yes, upload is called concurrently
• input is constructed locally within the goroutine. So, it is definitely not shared across multiple goroutines

Like I mentioned above, input is only being passed to the upload function. So, no way for it to be modified.

[jasdel]

Thanks for the update @arjunmahishi. We're working to reproduce and investigate this issue.

What level of concurrency are you performing these upload with? Such as how many concurrent gorountines are uploading at once. This may help us in reproducing this issue.

[arjunmahishi]

We have a queue with file paths queued in it. A goroutine picks up a file path, creates the input object and uploads it. We have limited the number of goroutines to 12.

[jasdel]

@arjunmahishi thanks for the update. Was the number of goroutines reduced to 12 or always limited to 12? If it was reduced did the occurrence of the problem also reduce?

In addition, you mentioned nothing else was interacting with the files. Is there by chance anything that might be reusing the file between tasks? Such as two different processes/goroutines opening/editing the same filename?

[arjunmahishi]

No. The number of goroutines was always 12. The only way two different goroutines can open the same file is if there are duplicate jobs in the queue. I'll check if that is happening.

[arjunmahishi]

@jasdel Just tried to enqueue multiple jobs for the same file. As in, multiple goroutines were trying to upload the same file at the same time. It did not break. All the goroutines succeeded. In the bucket, the file was overwritten.

So, it's probably not a goroutines problem.

[arjunmahishi]

Any update @jasdel ?

[jasdel]

Hi @arjunmahishi I apologize we're still unable to reproduce this issue. We've been trying to reproduce this issue, but have not been able to yet. We did discover an interesting issue with CompleteMultipartUpload not being idempotent, but not an issue with the UploadPart operation yet.

Do you have a larger sample of the code that reproduces the issue that you're able to share?

In addition, is the code using a *os.File or *bytes.Buffer, as the value for the UploadInput.Body parameter?

[jasdel]

In addition, would you be able to enable debug logging for your application. This logging will log the SDK's behavior and retries performed for API operations. This can be limited to S3 uploads as well.

uploaderSvc := s3.New(sess, &aws.Config{
    LogLevel: aws.LogLevel(aws.LogDebugWithRequestRetries | aws.LogDebugWithRequestErrors),
})


resp, err := upload(uploaderSvc, params)

Your upload function stays the same. This may produce a significant amount of debug logs so you might want to pipe your application's output to a file.

[arjunmahishi]

HI @jasdel, we are using *os.File for the Body.

For the code sample, I can create a private gist and send it to you personally.

[jasdel]

Thanks for the update @arjunmahishi. Please send the gist when you're able.

[arjunmahishi]

@jasdel how do I send the gist link to you?

[jasdel]

Thanks @arjunmahishi you can send it to me at jasdel at amazon

[arjunmahishi]

@jasdel Sent

[arjunmahishi]

@jasdel @diehlaws any update? does the recent commit help?

[jasdel]

@arjunmahishi, we're still attempting to reproduce this issue. I'm working on a io.ReadSeeker wrapper with additional debug/logging information that will attempt to log Seeks and reads of the underlying reader in hopes of providing insight into what/where the issue is occurring.

The change in #2636 Added unit tests to the S3 Upload manager's error/retry behavior, asserting that the retry's offset seeking behavior works as expected.

I think the best bet we'll have to gain more insight into what the issue is, is to get this debug wrapper out to you to log how the file handle is being used.

[arjunmahishi]

Any update @jasdel ?

[knrt10]

@jasdel this is an issue for me too. I have the same case as @arjunmahishi. I am trying to upload the file concurrently from a queue. I am also using a retry logic. Sometimes file gets uploaded on first retry but sometimes it throws the error same as @arjunmahishi stated on the start of this issue about nil body length and sometimes I get The request signature we calculated does not match the signature you provided, but on retires it is getting uploaded. This is a problem cause my graylog gets filled with error that should not be there. Locally it is working fine. But when I am running my container from kubernetes and try to access by file from NFS I get this error.

[jasdel]

Thanks for the the additional information @knrt10 . I'm working on a utility to help debug this issue by logging the SDK's seek/read usage of a file while uploading it. I'm hoping to have this finished early next week.

@arjunmahishi are you also running your application in Kubernetes as well?

[arjunmahishi]

@jasdel No, we are not running it on kubernetes or any kind of container.

[jasdel]

@knrt10 to clarify, are you experiencing both the nil body request failure, and the request signature error? For the request signature error, could you post the full error value including the prefix before the colon (:).

[knrt10]

@jasdel I am sorry that is not possible now. But I somehow solved the issue. Instead of opening the file like os.Open I used os.OpenFile along with some permissions and everything seemed to work fine.

[jasdel]

thanks for the update @knrt10 Let us know if you run into the issue in the future.

@arjunmahishi I created PR #2696 that fixes the SDK's request handling to always check for error when seeking a request body. there were several cases where an error that occurred would be eaten leading to unexpected behavior. In addition the Pr includes an Example for wrapping your file with a logger that will log stack traces when read/seek errors occur.

[jasdel]

Hi @arjunmahishi and @knrt10 Were you able to update your applications to use the latest version of the SDK (at least v1.21.2) ? If so was there any improvement in your application's behavior?

PR #2696 fixed several cases in the SDK where the SDK would silently ignore errors when attempting to seek the file passed in when handling requests. These errors could cause the file's offset to get into an unexpected state causing the put object or upload part operation to fail with errors similar to the ones you've mentioned.

[arjunmahishi]

Will check soon and update. Can we keep this issue open till then?

[cedricve]

Tested with latest version 1.22.1, still got an error.

21:43:36.164 startUpload ▶ ERRO 42f Uploading:%!(EXTRA *s3manager.multiUploadError=MultipartUpload: upload multipart failed
upload id: XYXFfwDFhv8a9YPUvJUnDsuQDrcOPJeCLj49VEw6ZhsE7wnsX.pRGsl9itCda8rsr10qEnwWcr_2qBfmY8NSD6HePxEBA2WOd6Gh3ON1rz9geIsNMBWQah2Mb_qAXf3o
caused by: RequestError: send request failed
caused by: Put....partNumber=2&uploadId=XYXFfwDFhv8a9YPUvJUnDsuQDrcOPJeCLj49VEw6ZhsE7wnsX.pRGsl9itCda8rsr10qEnwWcr_2qBfmY8NSD6HePxEBA2WOd6Gh3ON1rz9geIsNMBWQah2Mb_qAXf3o: read tcp 192.168.0.163:59978->51.15.115.122:80: read: connection reset by peer)
21:43:37.170 startUpload ▶ INF

[jasdel]

Thanks for the update @cedricve. I think the read: connection reset by peer error you're seeing is due to a different issue than the signature and incorrect body lengths in this issue.

With that said, the S3 Upload manager should be updated to retry read: connection reset by peer errors. Generally the SDK is unable to retry this error, because it doesn't know if the service has processed the request or not, but in the specific use case of S3 UploadPart the Upload Manager does have the context it needs and should retry. I created #2737 to track this issue.

[cedricve]

thanks :) indeed might be the case. I will add some information to the newly created ticket. Thanks @jasdel

[arjunmahishi]

@jasdel still getting this error (afer pulling the latest version of the SDK)

2019/08/13 05:45:09 [s3uploader] Error during upload: RequestError: send request failed
caused by: Put https://<becketname>.s3.ap-southeast-1.amazonaws.com/<filename>.mp3: EOF
2019/08/13 05:45:09 Error occurred while uploading /var/log/exotel/recordings/<filename>.mp3 . Error : RequestError: send request failed
caused by: Put https://<bucketname>.s3.ap-southeast-1.amazonaws.com/<filename>.mp3: EOF Current file 

[jasdel]

thanks for the update @arjunmahishi, is the error occurring just as often? Were you able to have a take a look at the loggingUploadObjectReadBehavior example that adds logging to the uploader by wrapping the passed in io.ReadSeeker?

This example provides a wrapper for an io.ReadSeeker that provides a call stack when ever an error is encountered when reading or seeking the underlying file.

[arjunmahishi]

ok. Will explore this and get back.

[jasdel]

Hi @arjunmahishi were you able to investigate the behavior of your application and the SDK's UPloader using the logger?

[arjunmahishi]

I haven't been able to do this yet. You can go ahead and close the issue. I'll reopen it when I get a chance to explore this further.

[diehlaws]

Thanks for the update! We'll close the issue out for now as suggested, please don't hesitate to reach back out and/or re-open this issue to continue working with us on this.