Multipart uploads to GCS using S3 protocol fail with 400 error

tekkiwi · August 27, 2021, 3:35am

multipart uploads to GCS using S3 protocol fail with error:
Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument. status code: 400

Rclone version v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit (I realize this is a beta version, I previously had the same result on v1.56)

os/version: Microsoft Windows Server 2019 Standard 1809 (64 bit)

The target storage location for the upload is GCS using S3 protocol. I'm using S3 protocol with GCS for two reasons. The first is that we are migrating from an S3 compatible system to GCS and hence want to verify that GCS will actually work in S3 compatibility mode. The second is that when uploading large files to GCS using the native GCS protocol rclone does not do multi-part uploads and hence is very slow when uploading very large files over links with any latency. As far as I can tell this is due to lack of multipart support in the native GCS protocol.

rclone command used:

The rclone config contents with secrets removed.

[sa-test-s3compatibility]
type = s3
env_auth = false
access_key_id = S3GOOGLEKEYHERE
secret_access_key = S3GOOGLESECRETHERE
region = us-central1
endpoint = storage.googleapis.com
location_constraint = 
acl = private
server_side_encryption = 
storage_class =

A log from the command with the `-vv` flag

2021/08/26 20:19:23 DEBUG : rclone: Version "v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit" starting with parameters ["rclone" "copy" "D:\\deleteme\\" "sa-test-s3compatibility:test-s3compatibility/" "--log-level=DEBUG" "--modify-window=1s"]
2021/08/26 20:19:23 DEBUG : Creating backend with remote "D:\\deleteme\\"
2021/08/26 20:19:23 DEBUG : Using config file from "C:\\Users\\adm-pharvey\\.config\\rclone\\rclone.conf"
2021/08/26 20:19:23 DEBUG : fs cache: renaming cache item "D:\\deleteme\\" to be canonical "//?/D:/deleteme/"
2021/08/26 20:19:23 DEBUG : Creating backend with remote "sa-test-s3compatibility:test-s3compatibility/"
2021/08/26 20:19:23 DEBUG : fs cache: renaming cache item "sa-test-s3compatibility:test-s3compatibility/" to be canonical "sa-test-s3compatibility:test-s3compatibility"
2021/08/26 20:19:23 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/08/26 20:19:23 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/08/26 20:19:35 ERROR : largefile.iso: Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/08/26 20:19:35 ERROR : Attempt 1/3 failed with 1 errors and: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/08/26 20:19:35 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/08/26 20:19:35 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/08/26 20:19:46 ERROR : largefile.iso: Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/08/26 20:19:46 ERROR : Attempt 2/3 failed with 1 errors and: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/08/26 20:19:46 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/08/26 20:19:46 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/08/26 20:20:00 ERROR : largefile.iso: Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/08/26 20:20:00 ERROR : Attempt 3/3 failed with 1 errors and: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/08/26 20:20:00 INFO  :
Transferred:              0 / 0 Byte, -, 0 Byte/s, ETA -
Errors:                 1 (retrying may help)
Elapsed time:        36.9s

2021/08/26 20:20:00 DEBUG : 4 go routines active
2021/08/26 20:20:00 Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:

I will note that the google modern storage roles (non-legacy roles) don't allow storage.multipartUploads.abort
storage.multipartUploads.create
storage.multipartUploads.list
storage.multipartUploads.listParts
hence you need to either make a custom role or use the legacy roles, if you don't you will get a 403 when trying to start a multi-part upload.

I've made the user doing the upload Storage Legacy Bucket Owner and Storage Admin on the bucket to try to rule out rights issues. The same multi-part upload does work to GCS using S3 protocol using S3 browser.

I think this is actually a GCS bug rather than a rclone bug, but since it works in S3 browser I'm trying to figure out what exact call is triggering the 400 error.
My question is how can I find exactly what API call is triggering the 400 error so I can take this to Google as a bug?

Thanks.

asdffdsa · August 27, 2021, 11:59am

hi,
did not know gcs has a s3 mode.

if all the file sizes are less than 5GB, this might help, tho i see you are testing with largefile.iso
"rclone switches from single part uploads to multipart uploads at the point specified by --s3-upload-cutoff. This can be a maximum of 5 GiB and a minimum of 0 (ie always upload multipart files)."

for the api calls, you can add this to the command. as the output is verbose, i would try to copy a single file.
--dump=headers --retries=1 --low-level-retries=1 --log-level=DEBUG --log-file=rclone.log

tekkiwi · September 2, 2021, 12:41am

Thanks
jojothehumanmonkey
Headers posted below showing the issue.

tekkiwi · September 2, 2021, 12:42am

Here are headers showing the issue. I'm curious as to why it's using HTTP 1.1?

rclone copy D:\deleteme\ sa-test-s3compatibility:test-s3compatibility/  --log-level=DEBUG --modify-window=1s --dump=headers --retries=1 --low-level-retries=1
2021/09/01 17:53:43 DEBUG : rclone: Version "v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit" starting with parameters ["rclone" "copy" "D:\\deleteme\\" "sa-test-s3compatibility:test-s3compatibility/" "--log-level=DEBUG" "--modify-window=1s" "--dump=headers" "--retries=1" "--low-level-retries=1"]
2021/09/01 17:53:43 DEBUG : Creating backend with remote "D:\\deleteme\\"
2021/09/01 17:53:43 DEBUG : Using config file from "C:\\Users\\adm-pharvey\\.config\\rclone\\rclone.conf"
2021/09/01 17:53:43 DEBUG : fs cache: renaming cache item "D:\\deleteme\\" to be canonical "//?/D:/deleteme/"
2021/09/01 17:53:43 DEBUG : Creating backend with remote "sa-test-s3compatibility:test-s3compatibility/"
2021/09/01 17:53:43 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2021/09/01 17:53:43 DEBUG : fs cache: renaming cache item "sa-test-s3compatibility:test-s3compatibility/" to be canonical "sa-test-s3compatibility:test-s3compatibility"
2021/09/01 17:53:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 17:53:43 DEBUG : HTTP REQUEST (req 0xc0007a6c00)
2021/09/01 17:53:43 DEBUG : GET /test-s3compatibility?delimiter=%2F&max-keys=1000&prefix= HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210902T005343Z
Accept-Encoding: gzip

2021/09/01 17:53:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 17:53:43 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 17:53:43 DEBUG : HTTP RESPONSE (req 0xc0007a6c00)
2021/09/01 17:53:43 DEBUG : HTTP/2.0 200 OK
Content-Length: 751
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/xml; charset=UTF-8
Date: Thu, 02 Sep 2021 00:53:43 GMT
Expires: Thu, 02 Sep 2021 00:53:43 GMT
Server: UploadServer
X-Goog-Metageneration: 12
X-Guploader-Uploadid: ADPycdu_fuRTy0WOHz-pWqDTw0c9JbJ_tsfJZSI-uF27urp5OQ8DMEVzbpQKvM2FVSTz2AzKAzDCXSxGc9m8xW_KDF0

2021/09/01 17:53:43 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 17:53:43 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/09/01 17:53:43 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/09/01 17:53:53 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 17:53:53 DEBUG : HTTP REQUEST (req 0xc0007a6a00)
2021/09/01 17:53:53 DEBUG : POST /test-s3compatibility/largefile.iso?uploads= HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Content-Length: 0
Authorization: XXXX
Content-Type: application/octet-stream
X-Amz-Acl: private
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210902T005353Z
X-Amz-Meta-Md5chksum: piM0R6wpFB5C2PqPDTs3/A==
X-Amz-Meta-Mtime: 1597257858.1874249
Accept-Encoding: gzip

2021/09/01 17:53:53 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 17:53:53 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 17:53:53 DEBUG : HTTP RESPONSE (req 0xc0007a6a00)
2021/09/01 17:53:53 DEBUG : HTTP/2.0 400 Bad Request
Content-Length: 298
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Content-Type: application/xml; charset=UTF-8
Date: Thu, 02 Sep 2021 00:53:53 GMT
Server: UploadServer
Vary: Origin
X-Guploader-Uploadid: ADPycdstdk1zx_GEBJhX2Vo9y-xFg3YpKzmjvCCAFf1w-1lmEs9HIIHe9y68PwqtVFaiEGkhvfKrxBkdEef_bdpQdqk

2021/09/01 17:53:53 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 17:53:53 ERROR : largefile.iso: Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/09/01 17:53:53 ERROR : Attempt 1/1 failed with 1 errors and: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/09/01 17:53:53 INFO  :
Transferred:              0 / 0 Byte, -, 0 Byte/s, ETA -
Errors:                 1 (retrying may help)
Elapsed time:        10.4s

2021/09/01 17:53:53 DEBUG : 4 go routines active
2021/09/01 17:53:53 Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:

asdffdsa · September 2, 2021, 12:50am

one thing that looks strange is User-Agent: rclone/v1.46
as i am using v1.56.0, that output would be User-Agent: rclone/v1.56.0

fwiw, i never used beta software when there is a nice stable version...

tekkiwi · September 2, 2021, 12:56am

Realized I had posted the wrong log, corrected it. I was testing with various versions of rclone to see if the issue was the same in older versions. It seems to be the same issue on all versions I tested.

tekkiwi · September 2, 2021, 1:25am

As a comparison, when putting a smaller file that doesn't use MPU, it does this:

2021/09/01 18:20:51 DEBUG : PUT /test-s3compatibility/file.zip?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=GOOG1EOV5W4XTLER4IQVCLUWBJSYDDCYSZ3TVGLDHDNXFVPWOE6WIXTGXFCBA%2F20210902%2Fus-central1%2Fs3%2Faws4_request&X-Amz-Date=20210902T012051Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime%3Bx-amz-storage-class&X-Amz-Signature=b9c71c4671f60fa947706546b0f71932ca0241b7f9c61787df3c7b07a321ebbe HTTP/1.1

tekkiwi · September 2, 2021, 2:08am

Additional data points.
Uploads to GCS using rclone fail if the object exists and you try to overwrite it.
Rclone also seems to fail to set to the modtime at upload time. This means it will try to upload the same file over and over.

e.g.


c:\Users\adm-pharvey>"c:\program files\rclone\rclone.exe" copy D:\deleteme\ sa-test-s3compatibility:test-s3compatibility/  --log-level=DEBUG --modify-window=1s --dump=headers --retries=1 --low-level-retries=1 --s3-upload-cutoff 1M
2021/09/01 18:50:43 DEBUG : rclone: Version "v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit" starting with parameters ["c:\\program files\\rclone\\rclone.exe" "copy" "D:\\deleteme\\" "sa-test-s3compatibility:test-s3compatibility/" "--log-level=DEBUG" "--modify-window=1s" "--dump=headers" "--retries=1" "--low-level-retries=1" "--s3-upload-cutoff" "1M"]
2021/09/01 18:50:43 DEBUG : Creating backend with remote "D:\\deleteme\\"
2021/09/01 18:50:43 DEBUG : Using config file from "C:\\Users\\adm-pharvey\\.config\\rclone\\rclone.conf"
2021/09/01 18:50:43 DEBUG : fs cache: renaming cache item "D:\\deleteme\\" to be canonical "//?/D:/deleteme/"
2021/09/01 18:50:43 DEBUG : Creating backend with remote "sa-test-s3compatibility:test-s3compatibility/"
2021/09/01 18:50:43 DEBUG : sa-test-s3compatibility: detected overridden config - adding "{f81XM}" suffix to name
2021/09/01 18:50:43 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2021/09/01 18:50:43 DEBUG : fs cache: renaming cache item "sa-test-s3compatibility:test-s3compatibility/" to be canonical "sa-test-s3compatibility{f81XM}:test-s3compatibility"
2021/09/01 18:50:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:43 DEBUG : HTTP REQUEST (req 0xc0006c8600)
2021/09/01 18:50:43 DEBUG : GET /test-s3compatibility?delimiter=%2F&max-keys=1000&prefix= HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210902T015043Z
Accept-Encoding: gzip

2021/09/01 18:50:43 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:44 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:44 DEBUG : HTTP RESPONSE (req 0xc0006c8600)
2021/09/01 18:50:44 DEBUG : HTTP/2.0 200 OK
Content-Length: 751
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/xml; charset=UTF-8
Date: Thu, 02 Sep 2021 01:50:44 GMT
Expires: Thu, 02 Sep 2021 01:50:44 GMT
Server: UploadServer
X-Goog-Metageneration: 13
X-Guploader-Uploadid: ADPycdsg50L6S35VAEb_OPC1zaCbGT-BQ_VFDgMnXY5GdnqZ9HtW1U7mPDhrf-GyvWNDvTNWXDw66SDaXP-bdHvzBTs

2021/09/01 18:50:44 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:44 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/09/01 18:50:44 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/09/01 18:50:44 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:44 DEBUG : HTTP REQUEST (req 0xc0004cf500)
2021/09/01 18:50:44 DEBUG : POST /test-s3compatibility/file.zip?uploads= HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Content-Length: 0
Authorization: XXXX
Content-Type: application/zip
X-Amz-Acl: private
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210902T015044Z
X-Amz-Meta-Md5chksum: FobW6PEcINXdR3hyzxKP6Q==
X-Amz-Meta-Mtime: 1630439815.0598549
Accept-Encoding: gzip

2021/09/01 18:50:44 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:44 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:44 DEBUG : HTTP RESPONSE (req 0xc0004cf500)
2021/09/01 18:50:44 DEBUG : HTTP/2.0 400 Bad Request
Content-Length: 298
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Content-Type: application/xml; charset=UTF-8
Date: Thu, 02 Sep 2021 01:50:44 GMT
Server: UploadServer
Vary: Origin
X-Guploader-Uploadid: ADPycdtVMOIq_UzSPPPR7NiOxhyjlGH-o6vxn3AO208OyxZf51VPGG6TP7Pp2fQMmmlxQe5Tpki1JJXLAgcqP4GrZHg

2021/09/01 18:50:44 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:44 ERROR : file.zip: Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/09/01 18:50:44 ERROR : Attempt 1/1 failed with 1 errors and: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/09/01 18:50:44 INFO  :
Transferred:              0 / 0 Byte, -, 0 Byte/s, ETA -
Errors:                 1 (retrying may help)
Elapsed time:         0.3s

2021/09/01 18:50:44 DEBUG : 4 go routines active
2021/09/01 18:50:44 Failed to copy: multipart upload failed to initialise: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:

c:\Users\adm-pharvey>"c:\program files\rclone\rclone.exe" copy D:\deleteme\ sa-test-s3compatibility:test-s3compatibility/  --log-level=DEBUG --modify-window=1s --dump=headers --retries=1 --low-level-retries=1
2021/09/01 18:50:57 DEBUG : rclone: Version "v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit" starting with parameters ["c:\\program files\\rclone\\rclone.exe" "copy" "D:\\deleteme\\" "sa-test-s3compatibility:test-s3compatibility/" "--log-level=DEBUG" "--modify-window=1s" "--dump=headers" "--retries=1" "--low-level-retries=1"]
2021/09/01 18:50:57 DEBUG : Creating backend with remote "D:\\deleteme\\"
2021/09/01 18:50:57 DEBUG : Using config file from "C:\\Users\\adm-pharvey\\.config\\rclone\\rclone.conf"
2021/09/01 18:50:57 DEBUG : fs cache: renaming cache item "D:\\deleteme\\" to be canonical "//?/D:/deleteme/"
2021/09/01 18:50:57 DEBUG : Creating backend with remote "sa-test-s3compatibility:test-s3compatibility/"
2021/09/01 18:50:57 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2021/09/01 18:50:57 DEBUG : fs cache: renaming cache item "sa-test-s3compatibility:test-s3compatibility/" to be canonical "sa-test-s3compatibility:test-s3compatibility"
2021/09/01 18:50:57 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:57 DEBUG : HTTP REQUEST (req 0xc00013ab00)
2021/09/01 18:50:57 DEBUG : GET /test-s3compatibility?delimiter=%2F&max-keys=1000&prefix= HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210902T015057Z
Accept-Encoding: gzip

2021/09/01 18:50:57 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:57 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:57 DEBUG : HTTP RESPONSE (req 0xc00013ab00)
2021/09/01 18:50:57 DEBUG : HTTP/2.0 200 OK
Content-Length: 751
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/xml; charset=UTF-8
Date: Thu, 02 Sep 2021 01:50:57 GMT
Expires: Thu, 02 Sep 2021 01:50:57 GMT
Server: UploadServer
X-Goog-Metageneration: 13
X-Guploader-Uploadid: ADPycduWoWEaWKnxyz7blIamyRzb2QhkYqVBzqF2N1VRVkxL8Xvh_innM75CDApV5RjG8z1_mMetiFeihkp_9V6lcyE

2021/09/01 18:50:57 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:57 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/09/01 18:50:57 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/09/01 18:50:57 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:57 DEBUG : HTTP REQUEST (req 0xc00013a800)
2021/09/01 18:50:57 DEBUG : PUT /test-s3compatibility/file.zip?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=GOOG1EOV5W4XTLER4IQVCLUWBJSYDDCYSZ3TVGLDHDNXFVPWOE6WIXTGXFCBA%2F20210902%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210902T015057Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=6e1d6890a8ffdc9665c70a66d402c457059053f0dc7eb195c31725c69acbfd16 HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Content-Length: 9019415
content-md5: FobW6PEcINXdR3hyzxKP6Q==
content-type: application/zip
x-amz-acl: private
x-amz-meta-mtime: 1630439815.0598549
Accept-Encoding: gzip

2021/09/01 18:50:57 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:57 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:57 DEBUG : HTTP RESPONSE (req 0xc00013a800)
2021/09/01 18:50:57 DEBUG : HTTP/2.0 200 OK
Content-Length: 0
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Content-Type: text/html; charset=UTF-8
Date: Thu, 02 Sep 2021 01:50:57 GMT
Etag: "1686d6e8f11c20d5dd477872cf128fe9"
Server: UploadServer
Vary: Origin
X-Goog-Generation: 1630547457909932
X-Goog-Hash: crc32c=rJfBlQ==
X-Goog-Hash: md5=FobW6PEcINXdR3hyzxKP6Q==
X-Goog-Metageneration: 1
X-Goog-Stored-Content-Encoding: identity
X-Goog-Stored-Content-Length: 9019415
X-Guploader-Uploadid: ADPycds0cifWSfEGrTaBnHWEYo1bybMGbT33h4V7P3n4AwoEEdJeodGMjbU30IhunkhGjRc7jrX87b1bvehXHPJma7s

2021/09/01 18:50:57 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:57 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:57 DEBUG : HTTP REQUEST (req 0xc000426c00)
2021/09/01 18:50:57 DEBUG : HEAD /test-s3compatibility/file.zip HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210902T015057Z

2021/09/01 18:50:57 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:50:58 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:58 DEBUG : HTTP RESPONSE (req 0xc000426c00)
2021/09/01 18:50:58 DEBUG : HTTP/2.0 200 OK
Content-Length: 9019415
Accept-Ranges: bytes
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/zip
Date: Thu, 02 Sep 2021 01:50:58 GMT
Etag: "1686d6e8f11c20d5dd477872cf128fe9"
Expires: Thu, 02 Sep 2021 01:50:58 GMT
Last-Modified: Thu, 02 Sep 2021 01:50:57 GMT
Server: UploadServer
X-Goog-Hash: crc32c=rJfBlQ==
X-Goog-Hash: md5=FobW6PEcINXdR3hyzxKP6Q==
X-Goog-Storage-Class: NEARLINE
X-Guploader-Uploadid: ADPycdtlRHGE_UIg9zcjcg4hRFPkYy466DDfWq0HotrjdxbrQ18ko0BMVseRWAuX3tD37IaBkqxFuG0vx3_lAtvZyi0

2021/09/01 18:50:58 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:50:58 DEBUG : file.zip: md5 = 1686d6e8f11c20d5dd477872cf128fe9 OK
2021/09/01 18:50:58 INFO  : file.zip: Copied (new)
2021/09/01 18:50:58 INFO  :
Transferred:        8.602Mi / 8.602 MiByte, 100%, 0 Byte/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:         0.7s

2021/09/01 18:50:58 DEBUG : 4 go routines active

c:\Users\adm-pharvey>"c:\program files\rclone\rclone.exe" copy D:\deleteme\ sa-test-s3compatibility:test-s3compatibility/  --log-level=DEBUG --modify-window=1s --dump=headers --retries=1 --low-level-retries=1
2021/09/01 18:51:06 DEBUG : rclone: Version "v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit" starting with parameters ["c:\\program files\\rclone\\rclone.exe" "copy" "D:\\deleteme\\" "sa-test-s3compatibility:test-s3compatibility/" "--log-level=DEBUG" "--modify-window=1s" "--dump=headers" "--retries=1" "--low-level-retries=1"]
2021/09/01 18:51:06 DEBUG : Creating backend with remote "D:\\deleteme\\"
2021/09/01 18:51:06 DEBUG : Using config file from "C:\\Users\\adm-pharvey\\.config\\rclone\\rclone.conf"
2021/09/01 18:51:06 DEBUG : fs cache: renaming cache item "D:\\deleteme\\" to be canonical "//?/D:/deleteme/"
2021/09/01 18:51:06 DEBUG : Creating backend with remote "sa-test-s3compatibility:test-s3compatibility/"
2021/09/01 18:51:06 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2021/09/01 18:51:06 DEBUG : fs cache: renaming cache item "sa-test-s3compatibility:test-s3compatibility/" to be canonical "sa-test-s3compatibility:test-s3compatibility"
2021/09/01 18:51:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:51:06 DEBUG : HTTP REQUEST (req 0xc0000d5900)
2021/09/01 18:51:06 DEBUG : GET /test-s3compatibility?delimiter=%2F&max-keys=1000&prefix= HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210902T015106Z
Accept-Encoding: gzip

2021/09/01 18:51:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:51:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:51:06 DEBUG : HTTP RESPONSE (req 0xc0000d5900)
2021/09/01 18:51:06 DEBUG : HTTP/2.0 200 OK
Content-Length: 986
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/xml; charset=UTF-8
Date: Thu, 02 Sep 2021 01:51:06 GMT
Expires: Thu, 02 Sep 2021 01:51:06 GMT
Server: UploadServer
X-Goog-Metageneration: 13
X-Guploader-Uploadid: ADPycduVOuu9NIYB50xY_S8AT1OB2Ezk13ryNUVtGhluE3ZN7Ms-6XqobY-C6ZSeIzDIMNNMhqXFE8wrmCbtIoQbEyY

2021/09/01 18:51:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:51:06 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/09/01 18:51:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:51:06 DEBUG : HTTP REQUEST (req 0xc0007d5300)
2021/09/01 18:51:06 DEBUG : HEAD /test-s3compatibility/file.zip HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210902T015106Z

2021/09/01 18:51:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:51:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:51:06 DEBUG : HTTP RESPONSE (req 0xc0007d5300)
2021/09/01 18:51:06 DEBUG : HTTP/2.0 200 OK
Content-Length: 9019415
Accept-Ranges: bytes
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/zip
Date: Thu, 02 Sep 2021 01:51:06 GMT
Etag: "1686d6e8f11c20d5dd477872cf128fe9"
Expires: Thu, 02 Sep 2021 01:51:06 GMT
Last-Modified: Thu, 02 Sep 2021 01:50:57 GMT
Server: UploadServer
X-Goog-Hash: crc32c=rJfBlQ==
X-Goog-Hash: md5=FobW6PEcINXdR3hyzxKP6Q==
X-Goog-Storage-Class: NEARLINE
X-Guploader-Uploadid: ADPycdvuKzFfs4OtQMbA3RKjlV3TAqJ11cL87YZwVL8C1mhtXHijpchGA_BKiwb5rZYIztbvBXzd2LphSi1vFLY1KfU

2021/09/01 18:51:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:51:06 DEBUG : file.zip: Modification times differ by 29h54m1.9401451s: 2021-08-31 12:56:55.0598549 -0700 PDT, 2021-09-02 01:50:57 +0000 UTC
2021/09/01 18:51:06 DEBUG : file.zip: md5 = 1686d6e8f11c20d5dd477872cf128fe9 OK
2021/09/01 18:51:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:51:06 DEBUG : HTTP REQUEST (req 0xc0000d5e00)
2021/09/01 18:51:06 DEBUG : PUT /test-s3compatibility/file.zip HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Content-Length: 0
Authorization: XXXX
Content-Type: application/zip
X-Amz-Acl: private
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Copy-Source: test-s3compatibility/file.zip
X-Amz-Date: 20210902T015106Z
X-Amz-Meta-Mtime: 1630439815.0598549
X-Amz-Metadata-Directive: REPLACE
Accept-Encoding: gzip

2021/09/01 18:51:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/01 18:51:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:51:06 DEBUG : HTTP RESPONSE (req 0xc0000d5e00)
2021/09/01 18:51:06 DEBUG : HTTP/2.0 400 Bad Request
Content-Length: 302
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Content-Type: application/xml; charset=UTF-8
Date: Thu, 02 Sep 2021 01:51:06 GMT
Server: UploadServer
Vary: Origin
X-Guploader-Uploadid: ADPycdsV8lQiSeUCo77_TpCNo1FStgDoeDBhmvFs48D82FQPzz_kcZTlY6-Q-EA_2ixGNvCL-LEuYjQqYFKYA12OpFvV7zhxsQ

2021/09/01 18:51:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/01 18:51:06 ERROR : file.zip: Failed to set modification time: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/09/01 18:51:06 DEBUG : file.zip: Unchanged skipping
2021/09/01 18:51:06 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/09/01 18:51:06 INFO  : There was nothing to transfer
2021/09/01 18:51:06 ERROR : Attempt 1/1 failed with 1 errors and: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:
2021/09/01 18:51:06 INFO  :
Transferred:              0 / 0 Byte, -, 0 Byte/s, ETA -
Errors:                 1 (retrying may help)
Checks:                 1 / 1, 100%
Elapsed time:         0.4s

2021/09/01 18:51:06 DEBUG : 3 go routines active
2021/09/01 18:51:06 Failed to copy: InvalidArgument: Invalid argument.
        status code: 400, request id: , host id:

I'm planning to open a case with Google support but interested if anyone has any ideas on what exactly is causing Google to fail here. Is this a rclone bug, or GCS bug?

asdffdsa · September 2, 2021, 1:15pm

so no problems using s3browser, but problems with rclone?
interesting, i also use s3browser, and i find more often it is the problem.

rclone saves the modtime as metadata. the modtime via the google api might be the upload time
can you confirm that with rclone lsl sa-test-s3compatibility:test-s3compatibility

asdffdsa · September 2, 2021, 3:38pm

did some testing using

aws s3
wasabi, a s3 clone.

in your log

rclone makes a request with HTTP/1.1
google replies with HTTP/2.0

in my logs,

rclone makes a request with HTTP/1.1
aws/wasabi replies with HTTP/1.1

i would try --s3-disable-http2=true

tekkiwi · September 3, 2021, 4:14am

using the
--s3-disable-http2=true
caused GGC to return the exact same returns including the 400 error by HTTP 1.1 instead of HTTP2.

tekkiwi · September 3, 2021, 5:07am

GCS definitely is storing the modtime as the upload time, which seems like a bug. Straight after uploading file.zip with rclone, doing a lsl gives the upload time.

rclone.exe lsl sa-test-s3compatibility:test-s3compatibility
9019415 2021-09-02 21:16:41.000000000 file.zip

dir d:\deleteme
Directory of d:\deleteme
08/31/2021 12:56 PM 9,019,415 file.zip

asdffdsa · September 3, 2021, 1:16pm

at the gcs website, do they sugest any tools to use for the transfer?

sometimes, i use two other s3 tools that have free versions, perhaps test with them
s3 browser
cloudberry s3 explorer.

tekkiwi · September 6, 2021, 11:02pm

GCS support seem to be saying the 400 error on upload is a GCS bug, so hopefully they will fix that. However they are not yet saying the modtime not being stored is a bug. @ncw do you have any thoughts on GCS not storing x-amz-meta-mtime when you upload an object to GCS via S3 protocol.
e.g.

c:\Users\adm-pharvey>dir d:\deleteme\file.zip
 Volume in drive D is Data
 Volume Serial Number is D2F2-5EA9

 Directory of d:\deleteme

08/31/2021  12:56 PM         9,019,415 file.zip
               1 File(s)      9,019,415 bytes
               0 Dir(s)  92,924,738,273,280 bytes free

c:\Users\adm-pharvey>"c:\Program Files\Rclone\rclone.exe" delete sa-test-s3compatibility:test-s3compatibility/file.zip

c:\Users\adm-pharvey>"c:\program files\rclone\rclone.exe" copy D:\deleteme\ sa-test-s3compatibility:test-s3compatibility/  --log-level=DEBUG --modify-window=1s --dump=headers --retries=1 --low-level-retries=1
2021/09/06 15:29:10 DEBUG : rclone: Version "v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit" starting with parameters ["c:\\program files\\rclone\\rclone.exe" "copy" "D:\\deleteme\\" "sa-test-s3compatibility:test-s3compatibility/" "--log-level=DEBUG" "--modify-window=1s" "--dump=headers" "--retries=1" "--low-level-retries=1"]
2021/09/06 15:29:10 DEBUG : Creating backend with remote "D:\\deleteme\\"
2021/09/06 15:29:10 DEBUG : Using config file from "C:\\Users\\adm-pharvey\\.config\\rclone\\rclone.conf"
2021/09/06 15:29:10 DEBUG : fs cache: renaming cache item "D:\\deleteme\\" to be canonical "//?/D:/deleteme/"
2021/09/06 15:29:10 DEBUG : Creating backend with remote "sa-test-s3compatibility:test-s3compatibility/"
2021/09/06 15:29:10 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2021/09/06 15:29:10 DEBUG : fs cache: renaming cache item "sa-test-s3compatibility:test-s3compatibility/" to be canonical "sa-test-s3compatibility:test-s3compatibility"
2021/09/06 15:29:10 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:29:10 DEBUG : HTTP REQUEST (req 0xc000774600)
2021/09/06 15:29:10 DEBUG : GET /test-s3compatibility?delimiter=%2F&max-keys=1000&prefix= HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210906T222910Z
Accept-Encoding: gzip

2021/09/06 15:29:10 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:29:10 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:29:10 DEBUG : HTTP RESPONSE (req 0xc000774600)
2021/09/06 15:29:10 DEBUG : HTTP/2.0 200 OK
Content-Length: 268
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/xml; charset=UTF-8
Date: Mon, 06 Sep 2021 22:29:10 GMT
Expires: Mon, 06 Sep 2021 22:29:10 GMT
Server: UploadServer
X-Goog-Metageneration: 13
X-Guploader-Uploadid: ADPycdtg4Tq15FgCWM-A4BFM4rucFndpEjXGe6DFLDHzozYFnLdErIbP0ccBMcYWJKU18MtiGWlKWmbXii6FjWHHsjXMV3lMmQ

2021/09/06 15:29:10 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:29:10 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/09/06 15:29:10 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/09/06 15:29:10 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:29:10 DEBUG : HTTP REQUEST (req 0xc000774400)
2021/09/06 15:29:10 DEBUG : PUT /test-s3compatibility/file.zip?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=GOOG1EOV5W4XTLER4IQVCLUWBJSYDDCYSZ3TVGLDHDNXFVPWOE6WIXTGXFCBA%2F20210906%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210906T222910Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=da732b9b00f5ba10b687da41d03aa83c4eee2dd0efc9f9f6ee757e732b24df6f HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Content-Length: 9019415
content-md5: FobW6PEcINXdR3hyzxKP6Q==
content-type: application/zip
x-amz-acl: private
x-amz-meta-mtime: 1630439815.0598549
Accept-Encoding: gzip

2021/09/06 15:29:10 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:29:10 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:29:10 DEBUG : HTTP RESPONSE (req 0xc000774400)
2021/09/06 15:29:10 DEBUG : HTTP/2.0 200 OK
Content-Length: 0
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Content-Type: text/html; charset=UTF-8
Date: Mon, 06 Sep 2021 22:29:10 GMT
Etag: "1686d6e8f11c20d5dd477872cf128fe9"
Server: UploadServer
Vary: Origin
X-Goog-Generation: 1630967350537207
X-Goog-Hash: crc32c=rJfBlQ==
X-Goog-Hash: md5=FobW6PEcINXdR3hyzxKP6Q==
X-Goog-Metageneration: 1
X-Goog-Stored-Content-Encoding: identity
X-Goog-Stored-Content-Length: 9019415
X-Guploader-Uploadid: ADPycdsMBn9_e3K9_5AORZweZWBOtOF3mIbvgX1F0S76LqSKF-HnpMmqlpxtLRLL1O-6bqblv2cMKQqSJAiIv4ftdTJ1Nb7Dkw

2021/09/06 15:29:10 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:29:10 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:29:10 DEBUG : HTTP REQUEST (req 0xc000774800)
2021/09/06 15:29:10 DEBUG : HEAD /test-s3compatibility/file.zip HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210906T222910Z

2021/09/06 15:29:10 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:29:10 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:29:10 DEBUG : HTTP RESPONSE (req 0xc000774800)
2021/09/06 15:29:10 DEBUG : HTTP/2.0 200 OK
Content-Length: 9019415
Accept-Ranges: bytes
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/zip
Date: Mon, 06 Sep 2021 22:29:10 GMT
Etag: "1686d6e8f11c20d5dd477872cf128fe9"
Expires: Mon, 06 Sep 2021 22:29:10 GMT
Last-Modified: Mon, 06 Sep 2021 22:29:10 GMT
Server: UploadServer
X-Goog-Hash: crc32c=rJfBlQ==
X-Goog-Hash: md5=FobW6PEcINXdR3hyzxKP6Q==
X-Goog-Storage-Class: NEARLINE
X-Guploader-Uploadid: ADPycdtSC-tmxFYXYILKVob4GQHllR5I-Uq5GCTa9azUu-G-aXCs8KRLYXwjmG1UDYqFzSWdN4KdlXgP_75rFzmK37l3Sdrn3A

2021/09/06 15:29:10 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:29:10 DEBUG : file.zip: md5 = 1686d6e8f11c20d5dd477872cf128fe9 OK
2021/09/06 15:29:10 INFO  : file.zip: Copied (new)
2021/09/06 15:29:10 INFO  :
Transferred:        8.602Mi / 8.602 MiByte, 100%, 0 Byte/s, ETA -
Transferred:            1 / 1, 100%
Elapsed time:         0.6s

2021/09/06 15:29:10 DEBUG : 4 go routines active

c:\Users\adm-pharvey>"c:\Program Files\Rclone\rclone.exe" lsl sa-test-s3compatibility:test-s3compatibility
  9019415 2021-09-06 15:29:10.000000000 file.zip

If I'm reading that correctly rclone says it is sending the file modtime as 1 Sept 2021 UTC, which is probably correct (haven't converted the timezones), but GCS doesn't seem to store this metadata.
no custom time is set in the metadata if I read it with gsutil.

gsutil stat gs://test-s3compatibility/file.zip
gs://test-s3compatibility/file.zip:
    Creation time:          Mon, 06 Sep 2021 22:29:10 GMT
    Update time:            Mon, 06 Sep 2021 22:29:10 GMT
    Storage class:          NEARLINE
    Content-Length:         9019415
    Content-Type:           application/zip
    Hash (crc32c):          rJfBlQ==
    Hash (md5):             FobW6PEcINXdR3hyzxKP6Q==
    ETag:                   CPfXxuyy6/ICEAE=
    Generation:             1630967350537207
    Metageneration:         1

To test further I manually tried to add this metadata, which did something unexpected, it added not just the x-amz-meta-mtime but also sent Custom-Time, which was unexpected.

 gsutil stat gs://test-s3compatibility/file.zip
gs://test-s3compatibility/file.zip:
    Creation time:          Mon, 06 Sep 2021 22:41:35 GMT
    Update time:            Mon, 06 Sep 2021 22:44:50 GMT
    Storage class:          NEARLINE
    Content-Length:         9019415
    Content-Type:           application/zip
    Custom-Time:            1970-01-01 00:00:00+00:00
    Metadata:
        x-amz-meta-mtime:   1630439815.0598549
    Hash (crc32c):          rJfBlQ==
    Hash (md5):             FobW6PEcINXdR3hyzxKP6Q==
    ETag:                   CJji3s+16/ICEAI=
    Generation:             1630968095420696
    Metageneration:         2

And rclone did something even more unexpected with that, it now sees that metadata tag as:
X-Amz-Meta-X-Amz-Meta-Mtime: 1630439815.0598549
However it still seems to go off the upload time, which was expected if x-amz-meta-mtime is not set.

2021/09/06 15:45:13 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:45:13 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/09/06 15:45:13 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:45:13 DEBUG : HTTP REQUEST (req 0xc0007c7100)
2021/09/06 15:45:13 DEBUG : HEAD /test-s3compatibility/file.zip HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210906T224513Z

2021/09/06 15:45:13 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:45:13 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:45:13 DEBUG : HTTP RESPONSE (req 0xc0007c7100)
2021/09/06 15:45:13 DEBUG : HTTP/2.0 200 OK
Content-Length: 9019415
Accept-Ranges: bytes
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/zip
Date: Mon, 06 Sep 2021 22:45:13 GMT
Etag: "1686d6e8f11c20d5dd477872cf128fe9"
Expires: Mon, 06 Sep 2021 22:45:13 GMT
Last-Modified: Mon, 06 Sep 2021 22:41:35 GMT
Server: UploadServer
X-Amz-Meta-X-Amz-Meta-Mtime: 1630439815.0598549
X-Goog-Custom-Time: 1970-01-01T00:00:00Z
X-Goog-Hash: crc32c=rJfBlQ==
X-Goog-Hash: md5=FobW6PEcINXdR3hyzxKP6Q==
X-Goog-Storage-Class: NEARLINE
X-Guploader-Uploadid: ADPycduWmT6fzDn7vnmF5qrocmM2cBAPYQUMUIIjsXHtBDJybx6a1gssuQIJZWbFr1IiPSONFKdVsG_wgnWBt3O4AO0B_AlHtQ

2021/09/06 15:45:13 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:45:13 DEBUG : file.zip: Modification times differ by 146h44m39.9401451s: 2021-08-31 12:56:55.0598549 -0700 PDT, 2021-09-06 22:41:35 +0000 UTC
2021/09/06 15:45:13 DEBUG : file.zip: md5 = 1686d6e8f11c20d5dd477872cf128fe9 OK
2021/09/06 15:45:13 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

if I just set the metadata "mtime" then GCS seems to prepend the X-Amz-Meta- and then everything works as expected.

gsutil stat gs://test-s3compatibility/file.zip
gs://test-s3compatibility/file.zip:
    Creation time:          Mon, 06 Sep 2021 22:41:35 GMT
    Update time:            Mon, 06 Sep 2021 22:51:48 GMT
    Storage class:          NEARLINE
    Content-Length:         9019415
    Content-Type:           application/zip
    Custom-Time:            1970-01-01 00:00:00+00:00
    Metadata:
        mtime:              1630439815.0598549
    Hash (crc32c):          rJfBlQ==
    Hash (md5):             FobW6PEcINXdR3hyzxKP6Q==
    ETag:                   CJji3s+16/ICEAM=
    Generation:             1630968095420696
    Metageneration:         3

"c:\program files\rclone\rclone.exe" copy D:\deleteme\ sa-test-s3compatibility:test-s3compatibility/  --log-level=DEBUG --modify-window=1s --dump=headers --retries=1 --low-level-retries=1
2021/09/06 15:56:48 DEBUG : rclone: Version "v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit" starting with parameters ["c:\\program files\\rclone\\rclone.exe" "copy" "D:\\deleteme\\" "sa-test-s3compatibility:test-s3compatibility/" "--log-level=DEBUG" "--modify-window=1s" "--dump=headers" "--retries=1" "--low-level-retries=1"]
2021/09/06 15:56:48 DEBUG : Creating backend with remote "D:\\deleteme\\"
2021/09/06 15:56:48 DEBUG : Using config file from "C:\\Users\\adm-pharvey\\.config\\rclone\\rclone.conf"
2021/09/06 15:56:48 DEBUG : fs cache: renaming cache item "D:\\deleteme\\" to be canonical "//?/D:/deleteme/"
2021/09/06 15:56:48 DEBUG : Creating backend with remote "sa-test-s3compatibility:test-s3compatibility/"
2021/09/06 15:56:48 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2021/09/06 15:56:48 DEBUG : fs cache: renaming cache item "sa-test-s3compatibility:test-s3compatibility/" to be canonical "sa-test-s3compatibility:test-s3compatibility"
2021/09/06 15:56:48 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:56:48 DEBUG : HTTP REQUEST (req 0xc000716200)
2021/09/06 15:56:48 DEBUG : GET /test-s3compatibility?delimiter=%2F&max-keys=1000&prefix= HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210906T225648Z
Accept-Encoding: gzip

2021/09/06 15:56:48 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:56:48 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:56:48 DEBUG : HTTP RESPONSE (req 0xc000716200)
2021/09/06 15:56:48 DEBUG : HTTP/2.0 200 OK
Content-Length: 503
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/xml; charset=UTF-8
Date: Mon, 06 Sep 2021 22:56:48 GMT
Expires: Mon, 06 Sep 2021 22:56:48 GMT
Server: UploadServer
X-Goog-Metageneration: 15
X-Guploader-Uploadid: ADPycdvKBmEzNqW5tCyp0Kln9rXSQHA6O7qpR4UVUF0gz0vbmEzjw0dTtIQ7oG09_VQhue9agM70XW3RuOWPy1vd9ca1xFTHkQ

2021/09/06 15:56:48 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:56:48 DEBUG : S3 bucket test-s3compatibility: Waiting for checks to finish
2021/09/06 15:56:48 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:56:48 DEBUG : HTTP REQUEST (req 0xc0003c6400)
2021/09/06 15:56:48 DEBUG : HEAD /test-s3compatibility/file.zip HTTP/1.1
Host: storage.googleapis.com
User-Agent: rclone/v1.57.0-beta.5609.719949cf0.fix-5507-bwlimit
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210906T225648Z

2021/09/06 15:56:48 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/09/06 15:56:48 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:56:48 DEBUG : HTTP RESPONSE (req 0xc0003c6400)
2021/09/06 15:56:48 DEBUG : HTTP/2.0 200 OK
Content-Length: 9019415
Accept-Ranges: bytes
Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-T051=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0
Content-Type: application/zip
Date: Mon, 06 Sep 2021 22:56:48 GMT
Etag: "1686d6e8f11c20d5dd477872cf128fe9"
Expires: Mon, 06 Sep 2021 22:56:48 GMT
Last-Modified: Mon, 06 Sep 2021 22:41:35 GMT
Server: UploadServer
X-Amz-Meta-Mtime: 1630439815.0598549
X-Goog-Custom-Time: 1970-01-01T00:00:00Z
X-Goog-Hash: crc32c=rJfBlQ==
X-Goog-Hash: md5=FobW6PEcINXdR3hyzxKP6Q==
X-Goog-Storage-Class: NEARLINE
X-Guploader-Uploadid: ADPycdtDcbeY8Y7GCUU6wF_BxXGWhJonAeMYQhsBJuo3X757vOSnlBjpayvZlTQkvGLGm1Gx19LJsZgF7r7WY23bJilxKfsStw

2021/09/06 15:56:48 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/09/06 15:56:48 DEBUG : file.zip: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/09/06 15:56:48 DEBUG : file.zip: Unchanged skipping
2021/09/06 15:56:48 DEBUG : S3 bucket test-s3compatibility: Waiting for transfers to finish
2021/09/06 15:56:48 INFO  : There was nothing to transfer
2021/09/06 15:56:48 INFO  :
Transferred:              0 / 0 Byte, -, 0 Byte/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:         0.3s

2021/09/06 15:56:48 DEBUG : 3 go routines active

"c:\Program Files\Rclone\rclone.exe" lsl sa-test-s3compatibility:test-s3compatibility
  9019415 2021-08-31 12:56:55.059854900 file.zip

I suspect in the backend GCS is storing the mtime with x-goog-meta- and then translating that when rclone uses S3 protocol, but that doesn't explain why they don't store the metadata when rclone sends it.

I'm also going to update the GCP support case with all this extra info.

tekkiwi · September 7, 2021, 11:28pm

More info on the 400 errors. According to GCP support GSC is returning a 400 error because rclone is sending an ACL and the bucket is set to uniform access. What is interesting is that GCS accepts an ACL for a put of an object that doesn't exist and is uploaded in a single part, but not on object replacement or MPU uploads.
Is ACL required for S3 uploads? I notice that if you set acl to blank that rclone sends the string private, hence there doesn't seem to be any way to stop rclone sending a acl to a S3 backend. If ACL is not required on S3 then there should be a way in rclone to stop sending an ACL.
@ncw Any thoughts on if ACL is a required field for S3 backends? If so then GCS should accept this and just discard it, but if its not a required field then it's potentially acceptable to throw an error if it's passed as part of an upload to a bucket that is configured as uniform access only?

tekkiwi · September 8, 2021, 1:05am

From this page:
https://docs.aws.amazon.com/AmazonS3/latest/userguide/managing-acls.html

Access Control List (ACL)-Specific Request Headers

You can use headers to grant access control list (ACL)-based permissions. By default, all objects are private.

It looks like this commit

enforced ACLs by changing a blank ACL string to "private"

This change seems to resolve the 400 errors that GCS is throwing, although potentially this is just a work around to a GCS issue.

I do however think that explicitly passing the default acl, which is private, is not good practice and it's better to allow passing no ACL at all and allowing the system default behavior to happen.

tekkiwi · October 18, 2021, 12:56am

Keep open, not yet resolved.

system · December 17, 2021, 8:57pm

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.

Multipart uploads to GCS using S3 protocol fail with 400 error

The rclone config contents with secrets removed.

A log from the command with the -vv flag

Access Control List (ACL)-Specific Request Headers

A log from the command with the `-vv` flag