[auto-ranged PUT]: CompleteMultipartUpload called while 1 multipart upload is missing

[awslabs]

[auto-ranged PUT]: CompleteMultipartUpload called while 1 multipart upload is missing

[grrtrr]

@waahm7 - the problem is not easily reproducible, it seems to be a timing-related problem. So far, after 10s of thousands of batch jobs, we have only data for this instance. (It is possible that this has happened more frequently in production, since batch jobs are retried on failure.).

With regard to the CRT logs, we log at WARN level to stderr; the only other log entry other than the above error trace was this one:

[ERROR] 2023-02-15 16:39:26.623 S3MetaRequest [140468667021056] id=0x7fc125951d00 Meta request cannot recover from error 14343 (Invalid response status from request). (request=0x7fc15e00a600, response status=400)
terminate called after throwing an instance of 'av::CheckException'
  what():  Check failure at perception/s2a/dataset_extraction/data_extraction_module.cc:574:
  Expected: 'x is ok', with x := 'output_blob_->close()' [av::status::Status]
  x = PutObject() failed
  where: cloud/aws/s3/s3_streambuf.cc:93
  extra: s3://perception-prod-training-data/opt/a831200c/s2a/2023-02-15-bless-collect_dking_updateOverlapFeb10_latestIssues/test/36c6f8923fe514d6b5a28ac5dbdea034.rats: HTTP response code: 400
Resolved remote host IP address: 
Request ID: 2BAQ8WRZGGH3PPG1
[... rest as above]

The following is the summary of a multi-week-long effort to narrow down the cause of the problem:

1. The CompleteMultipartUpload that failed with above error had the following data:

opt/a831200c/s2a/2023-02-15-bless-collect_dking_updateOverlapFeb10_latestIssues/test/36c6f8923fe514d6b5a28ac5dbdea034.rats
Object Size: -1 Bytes
Part Count: 1-2
Multipart Upload ID: bSMw15PyZS8eNZgoSxZ.qdZw4Awfm4beQGf9ERvdc8izMN5yFd6quULmunaMpJ8gUh2ZAjjidDlVr97lOBlSwhssgFeb_Zsb5CHN5fPYX6qHLjyRm7uxJZtnPerZGhbwsBU5xNStVDsjlr.Qnhe18s387J.7VybyeA2H9yrUnfk-

2. As per the Part Count field, it seemed to expect 2 parts. However, only one part was uploaded: the CompleteMultipartUpload with ID 2BAQ8WRZGGH3PPG1 was preceded by 1 UploadPart with ID 2BAR2P5XFDM71V14 on the same TCP connection. There was no trace of another UploadPart call.
3. The s3 key of the failed multipart upload did not show up in list-multipart-uploads or in list-parts.

Since the CompleteMultipartUpload request requires adding the ETag values returned by the individual UploadPart responses into the XML request body, the cause may be that either

• both UploadPart calls completed, but the second one failed after the API response returned the ETag (seems unlikely); or
• due some kind of race condition or unsuitable timing, the CompleteMultipartUpload "thought" there was only 1 instead of 2 ETags/UploadParts present, and thus tried to complete the multipart upload with a single UploadPart.

[waahm7]

Hi,

Thank you for reporting the issue. Could you please attach the full CRT logs and provide some reproduction steps? Thank you!

[waahm7]

Thank you for the details. Is the request getting paused and resumed later?

[grrtrr]

No, it does not use aws_s3_meta_request_pause.

[jmklix]

@grrtrr there have been some update since this issue was opened. Are you still running into this with the latest version of this repo?

[grrtrr]

@jmklix what are the updates and how do they fix the issue described here? In particular, have test cases been added to ensure the condition does not happen?