Each time rclone is run, 1/3 fails, 2/3 succeeds

asdffdsa · February 28, 2021, 12:31am

What is the problem you are having with rclone?

each time rclone is run, 1/3 fails, 2/3 succeeds
the same file is uploaded each time, the contents changes on each run
also, after the 2/3 transfer succeeds, there does not seem to be a hash check comparision.
i would expect something like

01.txt: MD5 = 8f14e45fceea167a5a36dedd4bea2543 OK
INFO  : 01.txt: Copied (replaced existing)

thanks in advance

What is your rclone version (output from `rclone version`)

rclone v1.54.0 - os/arch: windows/amd64 - go version: go1.15.7

Which OS you are using and how many bits (eg Windows 7, 64 bit)

W10.20H2.64bit

Which cloud storage system are you using? (eg Google Drive)

wasabi, s3 rclone

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

C:\data\rclone\scripts\rclone.exe copy  X:\test wasabi01:en07dataxhome/x --log-level=DEBUG --log-file=C:\data\rclone\logs\x_wasabi\20210227.191113\rclone.log

The rclone config contents with secrets removed.

[wasabi01]
type = s3
provider = Wasabi
access_key_id = 
secret_access_key = 
endpoint = s3.us-east-2.wasabisys.com

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

DEBUG : rclone: Version "v1.54.0" starting with parameters ["C:\\data\\rclone\\scripts\\rclone.exe" "copy" "X:\\test" "wasabi01:en07dataxhome/x" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\logs\\x_wasabi\\20210227.191113\\rclone.log"]
DEBUG : Creating backend with remote "X:\\test"
DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
DEBUG : fs cache: renaming cache item "X:\\test" to be canonical "//?/X:/test"
DEBUG : Creating backend with remote "wasabi01:en07dataxhome/x"
DEBUG : S3 bucket en07dataxhome path x: Waiting for checks to finish
DEBUG : 01.txt: Modification times differ by -24.9850004s: 2021-02-27 19:28:02.5661106 -0500 EST, 2021-02-27 19:27:37.5811102 -0500 EST
DEBUG : 01.txt: MD5 = cfcd208495d565ef66e7dff9f98764da (Local file system at //?/X:/test)
DEBUG : 01.txt: MD5 = 45c48cce2e2d7fbdea1afc51c7c6ad26 (S3 bucket en07dataxhome path x)
DEBUG : 01.txt: MD5 differ
DEBUG : S3 bucket en07dataxhome path x: Waiting for transfers to finish
DEBUG : 01.txt: MD5 = cfcd208495d565ef66e7dff9f98764da (Local file system at //?/X:/test)
DEBUG : 01.txt: MD5 = 45c48cce2e2d7fbdea1afc51c7c6ad26 (S3 bucket en07dataxhome path x)
ERROR : 01.txt: corrupted on transfer: MD5 hash differ "cfcd208495d565ef66e7dff9f98764da" vs "45c48cce2e2d7fbdea1afc51c7c6ad26"
INFO  : 01.txt: Removing failed copy
ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: MD5 hash differ "cfcd208495d565ef66e7dff9f98764da" vs "45c48cce2e2d7fbdea1afc51c7c6ad26"
DEBUG : S3 bucket en07dataxhome path x: Waiting for checks to finish
DEBUG : 01.txt: Size and modification time the same (differ by 0s, within tolerance 100ns)
DEBUG : 01.txt: Unchanged skipping
DEBUG : S3 bucket en07dataxhome path x: Waiting for transfers to finish
INFO  : There was nothing to transfer
ERROR : Attempt 2/3 succeeded
INFO  : 
Transferred:   	         1 / 1 Bytes, 100%, 4 Bytes/s, ETA 0s
Checks:                 2 / 2, 100%
Elapsed time:         0.4s

ncw · February 28, 2021, 12:22pm

So it appeared to do the upload but the md5 didn't change, indicating that maybe wasabi returned the old metadata

However when rclone retried it looked like the file had arrived properly hence there was nothing to transfer.

Does it do this all the time?

I take it your file is 1 byte long?

asdffdsa · February 28, 2021, 3:41pm

the file is 1 byte long but that is no the cause of the error.

actually what happened is that i noticed that issue in another script.
the script updates a .7z, copies it to wasabi.
so to highlight the problem, i wrote a simple script using a small one byte text file and that is what i posted up above.

here is the output of the full script where i first noticed the problem

DEBUG : rclone: Version "v1.54.0" starting with parameters ["C:\\data\\rclone\\scripts\\rclone.exe" "copy" "C:\\Users\\user01\\AppData\\Local\\Temp\\x\\zip\\x.20210228.103148.7z" "wasabi01:en07dataxhome/x/zip/backup" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\logs\\x_wasabi\\20210228.103148\\rclone.log"]
DEBUG : Creating backend with remote "C:\\Users\\user01\\AppData\\Local\\Temp\\x\\zip\\x.20210228.103148.7z"
DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
DEBUG : fs cache: adding new entry for parent of "C:\\Users\\user01\\AppData\\Local\\Temp\\x\\zip\\x.20210228.103148.7z", "//?/C:/Users/user01/AppData/Local/Temp/x/zip"
DEBUG : Creating backend with remote "wasabi01:en07dataxhome/x/zip/backup"
DEBUG : x.20210228.103148.7z: Modification times differ by -21.927575s: 2021-02-28 10:35:11.1857369 -0500 EST, 2021-02-28 10:34:49.2581619 -0500 EST
DEBUG : x.20210228.103148.7z: MD5 = 5fbf8ba53e8f57613324c4248d9db3bd (Local file system at //?/C:/Users/user01/AppData/Local/Temp/x/zip)
DEBUG : x.20210228.103148.7z: MD5 = cb55ad7635b0dd54d3513c94dfe6ee67 (S3 bucket en07dataxhome path x/zip/backup)
DEBUG : x.20210228.103148.7z: MD5 differ
DEBUG : x.20210228.103148.7z: MD5 = 5fbf8ba53e8f57613324c4248d9db3bd (Local file system at //?/C:/Users/user01/AppData/Local/Temp/x/zip)
DEBUG : x.20210228.103148.7z: MD5 = cb55ad7635b0dd54d3513c94dfe6ee67 (S3 bucket en07dataxhome path x/zip/backup)
ERROR : x.20210228.103148.7z: corrupted on transfer: MD5 hash differ "5fbf8ba53e8f57613324c4248d9db3bd" vs "cb55ad7635b0dd54d3513c94dfe6ee67"
INFO  : x.20210228.103148.7z: Removing failed copy
ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: MD5 hash differ "5fbf8ba53e8f57613324c4248d9db3bd" vs "cb55ad7635b0dd54d3513c94dfe6ee67"
DEBUG : x.20210228.103148.7z: Size and modification time the same (differ by 0s, within tolerance 100ns)
DEBUG : x.20210228.103148.7z: Unchanged skipping
ERROR : Attempt 2/3 succeeded
DEBUG : 6 go routines active
DEBUG : rclone: Version "v1.54.0" starting with parameters ["C:\\data\\rclone\\scripts\\rclone.exe" "check" "C:\\Users\\user01\\AppData\\Local\\Temp\\x\\zip\\x.20210228.103148.7z" "wasabi01:en07dataxhome/x/zip/backup" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\logs\\x_wasabi\\20210228.103148\\rclone.log"]
DEBUG : Creating backend with remote "C:\\Users\\user01\\AppData\\Local\\Temp\\x\\zip\\x.20210228.103148.7z"
DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
DEBUG : fs cache: adding new entry for parent of "C:\\Users\\user01\\AppData\\Local\\Temp\\x\\zip\\x.20210228.103148.7z", "//?/C:/Users/user01/AppData/Local/Temp/x/zip"
DEBUG : Creating backend with remote "wasabi01:en07dataxhome/x/zip/backup"
DEBUG : S3 bucket en07dataxhome path x/zip/backup: Waiting for checks to finish
DEBUG : x.20210228.103148.7z: MD5 = 5fbf8ba53e8f57613324c4248d9db3bd OK
DEBUG : x.20210228.103148.7z: OK
NOTICE: S3 bucket en07dataxhome path x/zip/backup: 0 differences found
NOTICE: S3 bucket en07dataxhome path x/zip/backup: 1 matching files
DEBUG : 5 go routines active

ncw · February 28, 2021, 6:25pm

I think this is probably Wasabi's eventual consistency in action.

Rclone does the upload, then tries to read the hash but gets the old hash because of eventual consistency.

How big the file is is probably irrelevant.

Does it do this every time, or only sometimes?

asdffdsa · February 28, 2021, 9:09pm

now, it is happening a lot of times, not every time.

if wasabi, then why just now, any ideas?

is there a way to test what is the real, underlying cause?

the thing is each time i run rclone, it is via a python script.
that script scans the log file of rclone, VSS, 7zip and fastcopy and i get an email summary.
i would have noticed this before.

ncw · March 1, 2021, 9:57am

That supports the theory that it is eventual consistency at work.

I'm guessing they tweaked their caching settings. More eventual consistency means they can cache things for longer, so lower load on their systems.

AWS guarantees that you will read the data from an object you've just written

They've always done that for objects, now they do that for listings too I think.

I suggest you ask Wasabi support about it.

asdffdsa · March 1, 2021, 11:59pm

over the weekend, i updated my rclone from v1.53.4 to v.1.54.0.
and that is when the problem started, never had problem before.

so i crafted a test,

update a .7z
copy .7z to wasabi
run the test dozens of times on v1.53.4 and v1.54.0

the result is always the same.
v1.53.4 - never an error
v1.54.0 - always an error

here is the log

2021/03/01 18:55:34 DEBUG : rclone: Version "v1.53.4" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.53.4.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/01 18:55:34 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/01 18:55:34 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/01 18:55:34 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/01 18:55:34 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/01 18:55:34 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/01 18:55:34 DEBUG : kdbx.7z: Sizes differ (src 894073 vs dst 894074)
2021/03/01 18:55:35 DEBUG : kdbx.7z: MD5 = 26235f56d1588e6bebd40df5866bc5a1 OK
2021/03/01 18:55:35 INFO  : kdbx.7z: Copied (replaced existing)
2021/03/01 18:55:35 DEBUG : 5 go routines active
2021/03/01 18:55:36 DEBUG : rclone: Version "v1.54.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.54.0.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/01 18:55:36 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/01 18:55:36 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/01 18:55:36 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/01 18:55:36 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/01 18:55:36 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/01 18:55:36 DEBUG : kdbx.7z: Sizes differ (src 894072 vs dst 894073)
2021/03/01 18:55:37 ERROR : kdbx.7z: corrupted on transfer: sizes differ 894072 vs 894073
2021/03/01 18:55:37 INFO  : kdbx.7z: Removing failed copy
2021/03/01 18:55:37 ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: sizes differ 894072 vs 894073
2021/03/01 18:55:37 DEBUG : kdbx.7z: Size and modification time the same (differ by 0s, within tolerance 100ns)
2021/03/01 18:55:37 DEBUG : kdbx.7z: Unchanged skipping
2021/03/01 18:55:37 ERROR : Attempt 2/3 succeeded
2021/03/01 18:55:37 DEBUG : 6 go routines active

sometimes the log looks like this

2021/03/01 19:11:37 DEBUG : rclone: Version "v1.53.4" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.53.4.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/01 19:11:37 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/01 19:11:37 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/01 19:11:37 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/01 19:11:37 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/01 19:11:37 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/01 19:11:37 DEBUG : kdbx.7z: Sizes differ (src 894073 vs dst 894072)
2021/03/01 19:11:37 DEBUG : kdbx.7z: MD5 = c8c61c2419c4aaaf561b81654e589650 OK
2021/03/01 19:11:37 INFO  : kdbx.7z: Copied (replaced existing)
2021/03/01 19:11:37 DEBUG : 5 go routines active
2021/03/01 19:11:39 DEBUG : rclone: Version "v1.54.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.54.0.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/01 19:11:39 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/01 19:11:39 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/01 19:11:39 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/01 19:11:39 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/01 19:11:39 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/01 19:11:39 DEBUG : kdbx.7z: Modification times differ by -2.0428185s: 2021-03-01 19:11:38.2959438 -0500 EST, 2021-03-01 19:11:36.2531253 -0500 EST
2021/03/01 19:11:39 DEBUG : kdbx.7z: MD5 = 92d27621fe2f7c00da82c78c9cc98476 (Local file system at //?/c:/data/rclone/scripts/test/7z)
2021/03/01 19:11:39 DEBUG : kdbx.7z: MD5 = c8c61c2419c4aaaf561b81654e589650 (S3 bucket kdbxtest)
2021/03/01 19:11:39 DEBUG : kdbx.7z: MD5 differ
2021/03/01 19:11:39 DEBUG : kdbx.7z: MD5 = 92d27621fe2f7c00da82c78c9cc98476 (Local file system at //?/c:/data/rclone/scripts/test/7z)
2021/03/01 19:11:39 DEBUG : kdbx.7z: MD5 = c8c61c2419c4aaaf561b81654e589650 (S3 bucket kdbxtest)
2021/03/01 19:11:39 ERROR : kdbx.7z: corrupted on transfer: MD5 hash differ "92d27621fe2f7c00da82c78c9cc98476" vs "c8c61c2419c4aaaf561b81654e589650"
2021/03/01 19:11:39 INFO  : kdbx.7z: Removing failed copy
2021/03/01 19:11:39 ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: MD5 hash differ "92d27621fe2f7c00da82c78c9cc98476" vs "c8c61c2419c4aaaf561b81654e589650"
2021/03/01 19:11:39 DEBUG : kdbx.7z: Size and modification time the same (differ by 0s, within tolerance 100ns)
2021/03/01 19:11:39 DEBUG : kdbx.7z: Unchanged skipping
2021/03/01 19:11:39 ERROR : Attempt 2/3 succeeded
2021/03/01 19:11:39 DEBUG : 6 go routines active

if i run the v1.54.0 then v1.53.4, same behavior.

2021/03/01 20:57:21 DEBUG : rclone: Version "v1.54.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.54.0.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/01 20:57:21 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/01 20:57:21 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/01 20:57:21 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/01 20:57:21 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/01 20:57:21 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/01 20:57:21 DEBUG : kdbx.7z: Sizes differ (src 894073 vs dst 894072)
2021/03/01 20:57:21 ERROR : kdbx.7z: corrupted on transfer: sizes differ 894073 vs 894072
2021/03/01 20:57:21 INFO  : kdbx.7z: Removing failed copy
2021/03/01 20:57:21 ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: sizes differ 894073 vs 894072
2021/03/01 20:57:21 DEBUG : kdbx.7z: Size and modification time the same (differ by 0s, within tolerance 100ns)
2021/03/01 20:57:21 DEBUG : kdbx.7z: Unchanged skipping
2021/03/01 20:57:21 ERROR : Attempt 2/3 succeeded
2021/03/01 20:57:21 DEBUG : 6 go routines active
2021/03/01 20:57:26 DEBUG : rclone: Version "v1.53.4" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.53.4.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/01 20:57:26 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/01 20:57:26 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/01 20:57:26 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/01 20:57:26 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/01 20:57:26 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/01 20:57:26 DEBUG : kdbx.7z: Sizes differ (src 894072 vs dst 894073)
2021/03/01 20:57:27 DEBUG : kdbx.7z: MD5 = 853577b5e254834a0efe3dbcc076ec87 OK
2021/03/01 20:57:27 INFO  : kdbx.7z: Copied (replaced existing)
2021/03/01 20:57:27 DEBUG : 4 go routines active

asdffdsa · March 2, 2021, 1:47pm

I have heard back from Wasabi.

they wrote a nice detailed email, but with no viable solution.
They offered to look deeper into their logs and get back to me.

They wrote that "S3 employed an eventual consistency model on PUTs for nearly 15 years since its launch in 2006, and only just recently in December of 2020 changed this to strong read-after-write consistency"

given i never had this problem before, it does seem to be some issue with rclone v1.54.0

Perhaps after AWS did that transition, they updated their S3 go library and rclone is affected by that?

sweh · March 2, 2021, 2:28pm

FWIW, https://aws.amazon.com/blogs/aws/amazon-s3-update-strong-read-after-write-consistency/ describes the AWS S3 read-after-write consistency model and what they changed in December 2020.

asdffdsa · March 2, 2021, 2:38pm

thanks much,
after the email from wasabi, i found and read that article.

if the rclone problem, as documented above, is due v1.54.0, then the question is:
what changed between versions v1.53.4 and v1.54.0?

ncw · March 2, 2021, 3:32pm

Interesting investigations.

The thing to do is to run with -vv --dump responses - that should show exactly what the difference between v1.53.4 and v1.54.0 is.

I tried to reproduce this with my wasabi test account but I couldn't.

Try using the flag --s3-no-head - I think you might need the latest beta for that. Does that help?

asdffdsa · March 2, 2021, 9:13pm

yes, it is interesting.

--s3-no-head was released in v1.54.0.

v1.53.4 - no error
v1.54.0 without --s3-no-head - there is an error
v1.54.0 with --s3-no-head - there is no error in the log, but that is due to rclone not checking.

there are a bunch of differences in rclone behavior between the two versions.
so as not to confuse the issue, i will not mention them now.

here is that log, have fun, thanks

2021/03/02 15:40:26 DEBUG : rclone: Version "v1.53.4" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.53.4.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--dump=responses" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/02 15:40:26 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/02 15:40:26 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/02 15:40:26 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/02 15:40:26 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/02 15:40:26 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/02 15:40:26 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/03/02 15:40:26 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:26 DEBUG : HTTP REQUEST (req 0xc000612e00)
2021/03/02 15:40:26 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.53.4
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210302T204026Z

2021/03/02 15:40:26 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:27 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:27 DEBUG : HTTP RESPONSE (req 0xc000612e00)
2021/03/02 15:40:27 DEBUG : HTTP/1.1 200 OK
Content-Length: 1437121
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Tue, 02 Mar 2021 20:40:28 GMT
Etag: "22a6d22b709821e99fd47cfd4e24b23b"
Last-Modified: Tue, 02 Mar 2021 20:38:53 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head4)
X-Amz-Id-2: IW9dq5+8Utlk9klPAmmIboYcYdsFXOmJqwzIm33jG/zgRmrt2onhsG39xl07X9NddTKxWq/VCMsZ
X-Amz-Meta-Mtime: 1614717530.1459497
X-Amz-Request-Id: 34CEB9CFEDF8351A

2021/03/02 15:40:27 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:27 DEBUG : kdbx.7z: Modification times differ by -1m36.0444671s: 2021-03-02 15:40:26.1904168 -0500 EST, 2021-03-02 15:38:50.1459497 -0500 EST
2021/03/02 15:40:27 DEBUG : kdbx.7z: MD5 = 33d6f4d1fcd9bc199ade786ad66c7d35 (Local file system at //?/c:/data/rclone/scripts/test/7z)
2021/03/02 15:40:27 DEBUG : kdbx.7z: MD5 = 22a6d22b709821e99fd47cfd4e24b23b (S3 bucket kdbxtest)
2021/03/02 15:40:27 DEBUG : kdbx.7z: MD5 differ
2021/03/02 15:40:27 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:27 DEBUG : HTTP REQUEST (req 0xc0004a2500)
2021/03/02 15:40:27 DEBUG : PUT /kdbxtest/kdbx.7z?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=____________________%2F20210302%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210302T204027Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=0651fbfccf42efb547ca00daa7fe42cc4fba43879cf867698c4f0593ef0ebae4 HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.53.4
Content-Length: 1437121
content-md5: M9b00fzZvBma3nhq1mx9NQ==
content-type: application/octet-stream
x-amz-acl: private
x-amz-meta-mtime: 1614717626.1904168
Accept-Encoding: gzip

2021/03/02 15:40:27 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:27 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:27 DEBUG : HTTP RESPONSE (req 0xc0004a2500)
2021/03/02 15:40:27 DEBUG : HTTP/1.1 200 OK
Content-Length: 0
Date: Tue, 02 Mar 2021 20:40:28 GMT
Etag: "33d6f4d1fcd9bc199ade786ad66c7d35"
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head4)
X-Amz-Id-2: GH5Vz9rrW74IVrndHSEkrTiBqYX3BO8EdQiZhkk3VeCOvG57ltLbgRGrkCZTjQFPB5QAbIE1Vukk
X-Amz-Request-Id: 8FE9E0211FAEAF18

2021/03/02 15:40:27 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:27 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:27 DEBUG : HTTP REQUEST (req 0xc0004a2400)
2021/03/02 15:40:27 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.53.4
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210302T204027Z

2021/03/02 15:40:27 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:27 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:27 DEBUG : HTTP RESPONSE (req 0xc0004a2400)
2021/03/02 15:40:27 DEBUG : HTTP/1.1 200 OK
Content-Length: 1437121
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Tue, 02 Mar 2021 20:40:28 GMT
Etag: "33d6f4d1fcd9bc199ade786ad66c7d35"
Last-Modified: Tue, 02 Mar 2021 20:40:28 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head4)
X-Amz-Id-2: jNCITKUbx0nc+6Iut8L0h/55tfu4o8GQ9IZsqM3SFTsW5YTDpwHTQBrBX6k+YAVGfOKgq/PwhEU8
X-Amz-Meta-Mtime: 1614717626.1904168
X-Amz-Request-Id: 2F9B800D588EECC9

2021/03/02 15:40:27 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:27 DEBUG : kdbx.7z: MD5 = 33d6f4d1fcd9bc199ade786ad66c7d35 OK
2021/03/02 15:40:27 INFO  : kdbx.7z: Copied (replaced existing)
2021/03/02 15:40:27 DEBUG : 5 go routines active
2021/03/02 15:40:28 DEBUG : rclone: Version "v1.54.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.54.0.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--dump=responses" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/02 15:40:28 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/02 15:40:28 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/02 15:40:28 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/02 15:40:28 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/02 15:40:28 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/02 15:40:28 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/03/02 15:40:28 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/03/02 15:40:28 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:28 DEBUG : HTTP REQUEST (req 0xc0006abe00)
2021/03/02 15:40:28 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210302T204028Z

2021/03/02 15:40:28 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 DEBUG : HTTP RESPONSE (req 0xc0006abe00)
2021/03/02 15:40:29 DEBUG : HTTP/1.1 200 OK
Content-Length: 1437121
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Tue, 02 Mar 2021 20:40:30 GMT
Etag: "33d6f4d1fcd9bc199ade786ad66c7d35"
Last-Modified: Tue, 02 Mar 2021 20:40:29 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head2)
X-Amz-Id-2: 9BaXosKsXdm9TiYMvieknKsV2ixkmr5UP5IrtXgHSgNl8Lb6zFtlUPy5smxYocRMEPBdoTVkSGsR
X-Amz-Meta-Mtime: 1614717626.1904168
X-Amz-Request-Id: 5594D1E6C628094C

2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 DEBUG : kdbx.7z: Sizes differ (src 1437120 vs dst 1437121)
2021/03/02 15:40:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : HTTP REQUEST (req 0xc0006abf00)
2021/03/02 15:40:29 DEBUG : PUT /kdbxtest/kdbx.7z?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=____________________%2F20210302%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210302T204029Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=ab278aebd5209f633a1af6bde1d73f2df6fc4383d5c1ef9cc5894193c95d4662 HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Content-Length: 1437120
content-md5: sRN/pBneqCO061EBGaZlgA==
content-type: application/octet-stream
x-amz-acl: private
x-amz-meta-mtime: 1614717628.0965133
Accept-Encoding: gzip

2021/03/02 15:40:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 DEBUG : HTTP RESPONSE (req 0xc0006abf00)
2021/03/02 15:40:29 DEBUG : HTTP/1.1 200 OK
Content-Length: 0
Date: Tue, 02 Mar 2021 20:40:30 GMT
Etag: "b1137fa419dea823b4eb510119a66580"
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head1)
X-Amz-Id-2: aDkdcsrsUTdvQpCcIMMESFPUgJAMWv+/APLfziDibABXQKBQSuxtnJoHgP/6VEzZ2dcP+rP2YC1r
X-Amz-Request-Id: EBE620B4E534C1AD

2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : HTTP REQUEST (req 0xc000838400)
2021/03/02 15:40:29 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210302T204029Z

2021/03/02 15:40:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 DEBUG : HTTP RESPONSE (req 0xc000838400)
2021/03/02 15:40:29 DEBUG : HTTP/1.1 200 OK
Content-Length: 1437121
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Tue, 02 Mar 2021 20:40:30 GMT
Etag: "33d6f4d1fcd9bc199ade786ad66c7d35"
Last-Modified: Tue, 02 Mar 2021 20:40:29 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head2)
X-Amz-Id-2: YXQv4FYI2B07VYcCshVVq1qJ6qnpqpS5ZE7ymUJt3MxHpCCliQ3kujYufJ7qVO4qwP/bJVBMyGvb
X-Amz-Meta-Mtime: 1614717626.1904168
X-Amz-Request-Id: 2D2CB2E69152DE36

2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 ERROR : kdbx.7z: corrupted on transfer: sizes differ 1437120 vs 1437121
2021/03/02 15:40:29 INFO  : kdbx.7z: Removing failed copy
2021/03/02 15:40:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : HTTP REQUEST (req 0xc0006c4400)
2021/03/02 15:40:29 DEBUG : DELETE /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210302T204029Z
Accept-Encoding: gzip

2021/03/02 15:40:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 DEBUG : HTTP RESPONSE (req 0xc0006c4400)
2021/03/02 15:40:29 DEBUG : HTTP/1.1 204 No Content
Date: Tue, 02 Mar 2021 20:40:30 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head2)
X-Amz-Id-2: YfYsvyK0H1ejC5J3qr0ZPJiHN61B6xGCGbaGgll7stArXwhXJkjeSc5a07CpbHtxlrhIFWheruwN
X-Amz-Request-Id: 0272E293671DA128

2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: sizes differ 1437120 vs 1437121
2021/03/02 15:40:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : HTTP REQUEST (req 0xc000838800)
2021/03/02 15:40:29 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210302T204029Z

2021/03/02 15:40:29 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 DEBUG : HTTP RESPONSE (req 0xc000838800)
2021/03/02 15:40:29 DEBUG : HTTP/1.1 200 OK
Content-Length: 1437120
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Tue, 02 Mar 2021 20:40:30 GMT
Etag: "b1137fa419dea823b4eb510119a66580"
Last-Modified: Tue, 02 Mar 2021 20:40:31 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head2)
X-Amz-Id-2: 8EQ6QLhyXynHu6Gtv3+qmGkRCNJy7LilHWEgCDr0pNcxDNsqhxksxtdTXTFWaBIDSIAFY3hhH5Ll
X-Amz-Meta-Mtime: 1614717628.0965133
X-Amz-Request-Id: 30E5E455A1D164D0

2021/03/02 15:40:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:29 DEBUG : kdbx.7z: Size and modification time the same (differ by 0s, within tolerance 100ns)
2021/03/02 15:40:29 DEBUG : kdbx.7z: Unchanged skipping
2021/03/02 15:40:29 ERROR : Attempt 2/3 succeeded
2021/03/02 15:40:29 DEBUG : 6 go routines active
2021/03/02 15:40:30 DEBUG : rclone: Version "v1.54.0" starting with parameters ["c:\\data\\rclone\\scripts\\rclone-1.54.0.exe" "copy" "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z" "wasabi01:kdbxtest" "--s3-no-head" "--dump=responses" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\scripts\\test\\rclone.log"]
2021/03/02 15:40:30 DEBUG : Creating backend with remote "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z"
2021/03/02 15:40:30 DEBUG : Using RCLONE_CONFIG_PASS password.
2021/03/02 15:40:30 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\rclone.conf"
2021/03/02 15:40:30 DEBUG : fs cache: adding new entry for parent of "c:\\data\\rclone\\scripts\\test\\7z\\kdbx.7z", "//?/c:/data/rclone/scripts/test/7z"
2021/03/02 15:40:30 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
2021/03/02 15:40:30 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/03/02 15:40:30 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/03/02 15:40:30 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:30 DEBUG : HTTP REQUEST (req 0xc00039bc00)
2021/03/02 15:40:30 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210302T204030Z

2021/03/02 15:40:30 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:30 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:30 DEBUG : HTTP RESPONSE (req 0xc00039bc00)
2021/03/02 15:40:30 DEBUG : HTTP/1.1 200 OK
Content-Length: 1437121
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Tue, 02 Mar 2021 20:40:31 GMT
Etag: "33d6f4d1fcd9bc199ade786ad66c7d35"
Last-Modified: Tue, 02 Mar 2021 20:40:28 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head4)
X-Amz-Id-2: urOFOdGPeD2pmoqCgDbBQU7SVArmMS345GdmclhKIlMa0rS9+04ep4U19Nd9isYRbiZEMzj9iPtV
X-Amz-Meta-Mtime: 1614717626.1904168
X-Amz-Request-Id: E028E4FEC264F6E9

2021/03/02 15:40:30 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:30 DEBUG : kdbx.7z: Sizes differ (src 1437120 vs dst 1437121)
2021/03/02 15:40:30 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:30 DEBUG : HTTP REQUEST (req 0xc00013cf00)
2021/03/02 15:40:30 DEBUG : PUT /kdbxtest/kdbx.7z?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=____________________%2F20210302%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210302T204030Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=40f8df6cb6ffb92e442b68c203493b75356f7e07f3037e72abe270d08ca98478 HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Content-Length: 1437120
content-md5: Aqc9ePGVFH+h4kxbB5XdUg==
content-type: application/octet-stream
x-amz-acl: private
x-amz-meta-mtime: 1614717630.0493645
Accept-Encoding: gzip

2021/03/02 15:40:30 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2021/03/02 15:40:30 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:30 DEBUG : HTTP RESPONSE (req 0xc00013cf00)
2021/03/02 15:40:30 DEBUG : HTTP/1.1 200 OK
Content-Length: 0
Date: Tue, 02 Mar 2021 20:40:31 GMT
Etag: "02a73d78f195147fa1e24c5b0795dd52"
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head5)
X-Amz-Id-2: 2FuDRLaFVNsM70qNmJ69juZWLbRE9eF+dgeB1uzGvHJdOhwXJNH3MUNRiz0aulVTdp/xuXXzy6dw
X-Amz-Request-Id: 1C5FB6A4AB74B6D5

2021/03/02 15:40:30 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2021/03/02 15:40:30 DEBUG : kdbx.7z: MD5 = 02a73d78f195147fa1e24c5b0795dd52 OK
2021/03/02 15:40:30 INFO  : kdbx.7z: Copied (replaced existing)
2021/03/02 15:40:30 DEBUG : 7 go routines active

ncw · March 3, 2021, 9:21am

Thanks for the logs.

Here is the failing sequence

Upload the file with 1.54

2021/03/02 15:40:29 DEBUG : PUT /kdbxtest/kdbx.7z?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=____________________%2F20210302%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210302T204029Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=ab278aebd5209f633a1af6bde1d73f2df6fc4383d5c1ef9cc5894193c95d4662 HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Content-Length: 1437120
content-md5: sRN/pBneqCO061EBGaZlgA==
content-type: application/octet-stream
x-amz-acl: private
x-amz-meta-mtime: 1614717628.0965133
Accept-Encoding: gzip

2021/03/02 15:40:29 DEBUG : HTTP RESPONSE (req 0xc0006abf00)
2021/03/02 15:40:29 DEBUG : HTTP/1.1 200 OK
Content-Length: 0
Date: Tue, 02 Mar 2021 20:40:30 GMT
Etag: "b1137fa419dea823b4eb510119a66580"
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head1)
X-Amz-Id-2: aDkdcsrsUTdvQpCcIMMESFPUgJAMWv+/APLfziDibABXQKBQSuxtnJoHgP/6VEzZ2dcP+rP2YC1r
X-Amz-Request-Id: EBE620B4E534C1AD

Note how the Etag was returned as b1137fa419dea823b4eb510119a66580
which is the correct value for the new upload. We can tell this
because the content-md5: that rclone sent sRN/pBneqCO061EBGaZlgA==
is b1137fa419dea823b4eb510119a66580 in hex (I checked with python).

Now do an after upload HEAD request

2021/03/02 15:40:29 DEBUG : HTTP REQUEST (req 0xc000838400)
2021/03/02 15:40:29 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210302T204029Z

2021/03/02 15:40:29 DEBUG : HTTP RESPONSE (req 0xc000838400)
2021/03/02 15:40:29 DEBUG : HTTP/1.1 200 OK
Content-Length: 1437121
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Tue, 02 Mar 2021 20:40:30 GMT
Etag: "33d6f4d1fcd9bc199ade786ad66c7d35"
Last-Modified: Tue, 02 Mar 2021 20:40:29 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head2)
X-Amz-Id-2: YXQv4FYI2B07VYcCshVVq1qJ6qnpqpS5ZE7ymUJt3MxHpCCliQ3kujYufJ7qVO4qwP/bJVBMyGvb
X-Amz-Meta-Mtime: 1614717626.1904168
X-Amz-Request-Id: 2D2CB2E69152DE36

Note here that the Etag is wrong 33d6f4d1fcd9bc199ade786ad66c7d35
and the size is wrong Content-Length: 1437121. Both of these are
from the previous object.

So this is the eventual consistency I was talking about. We uploaded a new object but HEAD on it gave the data from the previous version.

Amazon S3 has never had this problem (even with its previous consistency model which I can't find the docs for any more!) - a post upload HEAD request will always provide the correct answer.

So I think this is a Wasabi problem, and one that has likely been introduced recently.

I don't see any difference between the v1.53 and the v1.54 requests, so I reckon if you try it enough times v1.53 will fail in the same way.

The --s3-no-head option is a reasonable work around.

asdffdsa · March 3, 2021, 8:45pm

i can understand that logic.
tho if true, then why this never happen with any version of v1.5x.x that i have ever used.

that just hides that error and possible other errors; so i cannot use that.

never had any such issue ever with any version of rclone, until v1.54.0
i have run that test 50 times in a loop. always the same, v1.53.4 never fails, v1.54.0 fails every time.

each time i run rclone, i use my python script, it scans the logs of rclone, veeam, 7zip and fastcopy.
i get an email summary each and every time, in every computer/server i run it on.
any time is any ERROR with rclone, i get an alert.

i agree with that but it is rclone's response that concerns me.
i can live with that first error, adjust my script to ignore it when there is a matching Attempt 2/3 succeeded
but when rclone tries that second head, rclone responds with Size and modification time the same.
whereas, any other time, a new file is uploaded, rclone responds with a MD5 match.

DEBUG : kdbx.7z: MD5 = c8c61c2419c4aaaf561b81654e589650 OK
INFO  : kdbx.7z: Copied (replaced existing)

for me, this is a huge problem, that going forward, rclone and wasabi can no longer work together reliably.
i has contacted wasabi, they offered to look into their logs.
i replied to not spend the time yet, as i noticed that this only happens with v1.54.0
i will ask them if they are still willing to look into their logs.

is it possible that v1.54.0 uses a different aws s3 go package then v1.53.3?
please, can you tell me the versions used with each?

thanks much,

sweh · March 3, 2021, 10:02pm

It could be a timing issue; maybe 1.54 is just that 1ms quicker (or whatever) than 1.53 and so hitting the race condition.

asdffdsa · March 4, 2021, 1:55pm

good point, thanks,

ncw · March 4, 2021, 5:48pm

I can't get the test to fail ever with any version of rclone

Can you attach a script which shows the failing behaviour. Create any test files within the script or upload them somewhere I can download and I will do my best to reproduce with your script.

One thing I wonder - if it is all about timing?

Maybe you could try with --log-format time, microseconds -vv --dump requests so we can examine the exact timings working vs bad

For v1.54.0

github.com/aws/aws-sdk-go v1.35.17

For v1.53.4

github.com/aws/aws-sdk-go v1.32.11

asdffdsa · March 4, 2021, 9:50pm

i have simplified the command as much as i can.

rclone-1.54.0.exe copy kdbx.7z wasabi01:kdbxtest --log-file=log.log --log-format=time,microseconds --dump requests --log-level=DEBUG

i noticed that rclone will error two different ways
Attempt 1/3 failed with 1 errors and: corrupted on transfer: MD5 hash differ
Attempt 1/3 failed with 1 errors and: corrupted on transfer: sizes differ

here is the dump for Attempt 1/3 failed with 1 errors and: corrupted on transfer: MD5 hash differ

16:57:38.919182 DEBUG : rclone: Version "v1.54.0" starting with parameters ["rclone-1.54.0.exe" "copy" "kdbx.7z" "wasabi01:kdbxtest" "--log-file=log.log" "--log-format=time,microseconds" "--dump" "requests" "--log-level=DEBUG"]
16:57:38.920174 DEBUG : Creating backend with remote "kdbx.7z"
16:57:38.923786 DEBUG : Using RCLONE_CONFIG_PASS password.
16:57:38.923786 DEBUG : Using config file from "c:\\data\\rclone\\scripts\\test\\rclone.conf"
16:57:38.923786 DEBUG : fs cache: adding new entry for parent of "kdbx.7z", "//?/c:/data/rclone/scripts/test"
16:57:38.923786 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
16:57:38.924828 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.
16:57:38.924828 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.
16:57:38.925821 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:38.925821 DEBUG : HTTP REQUEST (req 0xc00001bf00)
16:57:38.925821 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210304T215738Z

16:57:38.925821 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.024233 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.037244 DEBUG : HTTP RESPONSE (req 0xc00001bf00)
16:57:39.037244 DEBUG : HTTP/1.1 200 OK
Content-Length: 206
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Thu, 04 Mar 2021 21:57:39 GMT
Etag: "3001de1aecff8d4850ffd4d53b93e95f"
Last-Modified: Thu, 04 Mar 2021 21:57:04 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head3)
X-Amz-Id-2: g7O4efV85qmZykAVbsrjlglma/TQwBKaQkX1yJ6WqMV35p/A1DpWJBnFxT9kUa6icWCav2yEC6cg
X-Amz-Meta-Mtime: 1614895021.6557263
X-Amz-Request-Id: 0BDDB3EE882AB7B9

16:57:39.037244 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.038248 DEBUG : kdbx.7z: Modification times differ by -36.4423316s: 2021-03-04 16:57:38.0980579 -0500 EST, 2021-03-04 16:57:01.6557263 -0500 EST
16:57:39.047247 DEBUG : kdbx.7z: MD5 = 42c302efbe246a4ec647415b6fa25369 (Local file system at //?/c:/data/rclone/scripts/test)
16:57:39.047247 DEBUG : kdbx.7z: MD5 = 3001de1aecff8d4850ffd4d53b93e95f (S3 bucket kdbxtest)
16:57:39.047247 DEBUG : kdbx.7z: MD5 differ
16:57:39.047247 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.047247 DEBUG : HTTP REQUEST (req 0xc00053e500)
16:57:39.047247 DEBUG : PUT /kdbxtest/kdbx.7z?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ZZZZZZZZZZZZZZZZZZZZ%2F20210304%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210304T215739Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=7f4bb5002d5e1ab5d9f1131dbbd2082a28024d56e5f22227fc942c8e675b53b3 HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Content-Length: 206
content-md5: QsMC774kak7GR0Fbb6JTaQ==
content-type: application/octet-stream
x-amz-acl: private
x-amz-meta-mtime: 1614895058.0980579
Accept-Encoding: gzip

7z¼¯' ª¾Y       !       wXÛ˜£™²Œ‘¤ÛƒÜ¦Ö¶jûë®  3a®Îò²a°ÃÚ÷_EŠ˜HJù\PÛpŒ†öíŸáÎ*29·Ý7º›?-=¼áû¨<LÀQaÐí¯Èdè.•¥P&91Îr.’ç¾Òûè|PÏÒŠ:ß#‰vkæþV' ·DQ_zÞ
ú#BLvøýÞúõh–¸<«  	} a #]   €–
ÔAf`  
16:57:39.047247 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.142644 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.142644 DEBUG : HTTP RESPONSE (req 0xc00053e500)
16:57:39.143645 DEBUG : HTTP/1.1 200 OK
Content-Length: 0
Date: Thu, 04 Mar 2021 21:57:39 GMT
Etag: "42c302efbe246a4ec647415b6fa25369"
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head2)
X-Amz-Id-2: 0aAcVL7Ts7ynPGBGfWlcvHWkOVbnGXepUFDV8jFnKRUHeVBvVqBDLR8A4U70nu2xusvnNRocmDDx
X-Amz-Request-Id: A89DD302640015E8

16:57:39.143645 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.143645 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.143645 DEBUG : HTTP REQUEST (req 0xc00053e400)
16:57:39.143645 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210304T215739Z

16:57:39.143645 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.157639 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.157639 DEBUG : HTTP RESPONSE (req 0xc00053e400)
16:57:39.157639 DEBUG : HTTP/1.1 200 OK
Content-Length: 206
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Thu, 04 Mar 2021 21:57:39 GMT
Etag: "3001de1aecff8d4850ffd4d53b93e95f"
Last-Modified: Thu, 04 Mar 2021 21:57:04 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head3)
X-Amz-Id-2: 5pSTscURi6sP7XX7Yw+d92P0tK5QDF1gOWUVe2mcGTwC+m3TLPmAton+w7LT6pKtCf1EbSzRSR05
X-Amz-Meta-Mtime: 1614895021.6557263
X-Amz-Request-Id: 67DBD0F89BF6DE5E

16:57:39.157639 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.157639 DEBUG : kdbx.7z: MD5 = 42c302efbe246a4ec647415b6fa25369 (Local file system at //?/c:/data/rclone/scripts/test)
16:57:39.157639 DEBUG : kdbx.7z: MD5 = 3001de1aecff8d4850ffd4d53b93e95f (S3 bucket kdbxtest)
16:57:39.157639 ERROR : kdbx.7z: corrupted on transfer: MD5 hash differ "42c302efbe246a4ec647415b6fa25369" vs "3001de1aecff8d4850ffd4d53b93e95f"
16:57:39.157639 INFO  : kdbx.7z: Removing failed copy
16:57:39.158638 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.158638 DEBUG : HTTP REQUEST (req 0xc00053ee00)
16:57:39.158638 DEBUG : DELETE /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210304T215739Z
Accept-Encoding: gzip

16:57:39.158638 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.175295 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.175295 DEBUG : HTTP RESPONSE (req 0xc00053ee00)
16:57:39.175295 DEBUG : HTTP/1.1 204 No Content
Date: Thu, 04 Mar 2021 21:57:40 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head3)
X-Amz-Id-2: aiAjTz5hPPAbWsHgJFsfMXvhg5nBwgVQ5VoHJ/I/yUYLAfmcFaYAG0MQujbLXiyAa6rJOEvDHFCf
X-Amz-Request-Id: 8D149C43C9254CAD

16:57:39.175295 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.175295 ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: MD5 hash differ "42c302efbe246a4ec647415b6fa25369" vs "3001de1aecff8d4850ffd4d53b93e95f"
16:57:39.176084 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.176084 DEBUG : HTTP REQUEST (req 0xc00053f300)
16:57:39.176084 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210304T215739Z

16:57:39.176084 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:57:39.190481 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.190481 DEBUG : HTTP RESPONSE (req 0xc00053f300)
16:57:39.190481 DEBUG : HTTP/1.1 200 OK
Content-Length: 206
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Thu, 04 Mar 2021 21:57:40 GMT
Etag: "42c302efbe246a4ec647415b6fa25369"
Last-Modified: Thu, 04 Mar 2021 21:57:40 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head3)
X-Amz-Id-2: 2oK0ypAIzWwgp5UxPaBBSNvePDnbvPUbLJUkruRjbRt+ov6tHjZEZCebFtA9A+2tk6AcZ/dbul2g
X-Amz-Meta-Mtime: 1614895058.0980579
X-Amz-Request-Id: 23AB5014E88138CA

16:57:39.190481 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
16:57:39.190481 DEBUG : kdbx.7z: Size and modification time the same (differ by 0s, within tolerance 100ns)
16:57:39.190481 DEBUG : kdbx.7z: Unchanged skipping
16:57:39.190481 ERROR : Attempt 2/3 succeeded
16:57:39.190481 INFO  : 
Transferred:   	       206 / 206 Bytes, 100%, 1.570 kBytes/s, ETA 0s
Checks:                 1 / 1, 100%
Elapsed time:         0.3s

and here is the dump log for Attempt 1/3 failed with 1 errors and: corrupted on transfer: sizes differ

17:25:57.126183 DEBUG : rclone: Version "v1.54.0" starting with parameters ["rclone-1.54.0.exe" "copy" "kdbx.7z" "wasabi01:kdbxtest" "--log-file=log.log" "--log-format=time,microseconds" "--dump" "requests" "--log-level=DEBUG"]
17:25:57.127176 DEBUG : Creating backend with remote "kdbx.7z"
17:25:57.127176 DEBUG : Using RCLONE_CONFIG_PASS password.
17:25:57.127176 DEBUG : Using config file from "c:\\data\\rclone\\scripts\\test\\rclone.conf"
17:25:57.128174 DEBUG : fs cache: adding new entry for parent of "kdbx.7z", "//?/c:/data/rclone/scripts/test"
17:25:57.128174 DEBUG : Creating backend with remote "wasabi01:kdbxtest"
17:25:57.128174 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.
17:25:57.129184 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.
17:25:57.129184 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.129184 DEBUG : HTTP REQUEST (req 0xc00081a300)
17:25:57.129184 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210304T222557Z

17:25:57.129184 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.250055 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.263412 DEBUG : HTTP RESPONSE (req 0xc00081a300)
17:25:57.263412 DEBUG : HTTP/1.1 200 OK
Content-Length: 206
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Thu, 04 Mar 2021 22:25:58 GMT
Etag: "d5ce036106449d406b9bc084d2b4d92e"
Last-Modified: Thu, 04 Mar 2021 22:25:54 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head4)
X-Amz-Id-2: 0/0l+PEQiVglwgLcSb2mI2wmdVKzQAROw1bqOVpQur9vfvfWVvEfCDHmMLqr1+wME1Z03P+DqujH
X-Amz-Meta-Mtime: 1614896752.1498285
X-Amz-Request-Id: 62DD587214691E95

17:25:57.263412 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.263412 DEBUG : kdbx.7z: Sizes differ (src 205 vs dst 206)
17:25:57.274634 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.274634 DEBUG : HTTP REQUEST (req 0xc000128900)
17:25:57.274634 DEBUG : PUT /kdbxtest/kdbx.7z?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ZZZZZZZZZZZZZZZZZZZZ%2F20210304%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20210304T222557Z&X-Amz-Expires=900&X-Amz-SignedHeaders=content-md5%3Bcontent-type%3Bhost%3Bx-amz-acl%3Bx-amz-meta-mtime&X-Amz-Signature=d07ea8473c9beb85bcf7f340de9eea27b619ab43ae13c62adbd2d83aa4933a88 HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Content-Length: 205
content-md5: X/BA8bFDxBQqQlb3pjJchg==
content-type: application/octet-stream
x-amz-acl: private
x-amz-meta-mtime: 1614896756.9722637
Accept-Encoding: gzip

7z¼¯' î_Œ       !       ‘ÌXsÖe÷a T(ß>US‘>ö  3a®Îò²a°ÃÚ÷_EŠ˜HJøø(àæ†@dD¢ÅJçõøˆ€þˆâ+}wè	ço!)Z‚'½tRÝs?äV’I1«\ã@sª,º!ÇanåÑwr`!àº@Ðˆ·xj”/ŒPd£²¡xÆòvß
H¬Uð  	| a #]   €–
¡:Ã3  
17:25:57.274634 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.404268 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.404268 DEBUG : HTTP RESPONSE (req 0xc000128900)
17:25:57.404268 DEBUG : HTTP/1.1 200 OK
Content-Length: 0
Date: Thu, 04 Mar 2021 22:25:58 GMT
Etag: "5ff040f1b143c4142a4256f7a6325c86"
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head6)
X-Amz-Id-2: Bc0MT/TaYZyXl5kzBJrv0KiTzQkCmhrXIP68rk1RAyLYILCYogZFwLQx6t3Y4PDj0jEtDkWOr0mL
X-Amz-Request-Id: FBA919E2190AA03B

17:25:57.404268 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.405278 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.405278 DEBUG : HTTP REQUEST (req 0xc000128800)
17:25:57.405278 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210304T222557Z

17:25:57.405278 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.420226 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.420226 DEBUG : HTTP RESPONSE (req 0xc000128800)
17:25:57.420226 DEBUG : HTTP/1.1 200 OK
Content-Length: 206
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Thu, 04 Mar 2021 22:25:58 GMT
Etag: "d5ce036106449d406b9bc084d2b4d92e"
Last-Modified: Thu, 04 Mar 2021 22:25:54 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head4)
X-Amz-Id-2: G93b8AmvNa6/zEg7gfkwrDP4+Z4arG1K88uP52dPEVPZsduBrgVTtz1SB7nIGM1sVOKcH1MjWzTd
X-Amz-Meta-Mtime: 1614896752.1498285
X-Amz-Request-Id: 1F9DDA47CA88E3FB

17:25:57.420226 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.420226 ERROR : kdbx.7z: corrupted on transfer: sizes differ 205 vs 206
17:25:57.420226 INFO  : kdbx.7z: Removing failed copy
17:25:57.421269 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.421269 DEBUG : HTTP REQUEST (req 0xc00081a400)
17:25:57.421269 DEBUG : DELETE /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210304T222557Z
Accept-Encoding: gzip

17:25:57.421269 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.590544 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.592363 DEBUG : HTTP RESPONSE (req 0xc00081a400)
17:25:57.592363 DEBUG : HTTP/1.1 204 No Content
Date: Thu, 04 Mar 2021 22:25:58 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head4)
X-Amz-Id-2: tcP463y7+simxaKYWf8pX8U2aA3iljisXYwu9rV8fAV9TekOGEtCbzjg2aoH+rRTdyKfs3zF1OC+
X-Amz-Request-Id: 3353C78245524C54

17:25:57.592363 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.592363 ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: sizes differ 205 vs 206
17:25:57.593375 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.593375 DEBUG : HTTP REQUEST (req 0xc000352600)
17:25:57.593375 DEBUG : HEAD /kdbxtest/kdbx.7z HTTP/1.1
Host: s3.us-east-2.wasabisys.com
User-Agent: rclone/v1.54.0
Authorization: XXXX
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20210304T222557Z

17:25:57.593375 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
17:25:57.594518 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.594518 DEBUG : HTTP RESPONSE (req 0xc000352600)
17:25:57.608933 DEBUG : HTTP/1.1 200 OK
Content-Length: 205
Accept-Ranges: bytes
Content-Type: application/octet-stream
Date: Thu, 04 Mar 2021 22:25:58 GMT
Etag: "5ff040f1b143c4142a4256f7a6325c86"
Last-Modified: Thu, 04 Mar 2021 22:25:58 GMT
Server: WasabiS3/6.2.4402-2021-02-17-138460b (head4)
X-Amz-Id-2: 5ul+QIrWE6G2waBy7X/9ZyGHxkHlsEO7qGsum+Z6z7v3Wvpspxi+OVId9MulYvSMnvHIYgAAFMN4
X-Amz-Meta-Mtime: 1614896756.9722637
X-Amz-Request-Id: 5B24699D7D4A6FBF

17:25:57.608933 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
17:25:57.612946 DEBUG : kdbx.7z: Size and modification time the same (differ by 0s, within tolerance 100ns)
17:25:57.612946 DEBUG : kdbx.7z: Unchanged skipping
17:25:57.612946 ERROR : Attempt 2/3 succeeded
17:25:57.612946 INFO  : 
Transferred:   	       205 / 205 Bytes, 100%, 623 Bytes/s, ETA 0s
Checks:                 1 / 1, 100%
Elapsed time:         0.5s

17:25:57.612946 DEBUG : 6 go routines active

ncw · March 5, 2021, 11:17am

This matches whether you changed the file or increased it length. It matches with the why rclone is transferring the file. This is consistent with the HEAD request returning the info for the previous object.

Oops, meant --dump responses here.

I have managed to replicate your problem

I can only replicate the problem with endpoint = s3.us-east-2.wasabisys.com and not with endpoint = s3.wasabisys.com which is what I normally use.

I did 100 tests for rclone-v1.53.4 and rclone-v1.54.0 like this

for i in `seq -w 100`; do echo -n a >> kdbx.7z ; ./rclone-v1.54.0 copy kdbx.7z wasabi-us-east-2:rclone-test-us-east2 "--log-format=," "--dump" "responses" "--log-level=DEBUG" 2>&1 | tee wasabi-v1.54.0-${i}.log ; done
for i in `seq -w 100`; do echo -n a >> kdbx.7z ; ./rclone-v1.53.4 copy kdbx.7z wasabi-us-east-2:rclone-test-us-east2 "--log-format=," "--dump" "responses" "--log-level=DEBUG" 2>&1 | tee wasabi-v1.53.4-${i}.log ; done

This gave 86% corrupted for v1.54.0 and 0% corrupted for v1.53.4 which matches your findings

$ grep -l corrupted wasabi-v1.54.0-*.log | wc -l
86
$ grep -l corrupted wasabi-v1.53.4-*.log | wc -l
0

I've stared at the diff between the two and I don't think anything is different in what rclone sends.

I tried reverting the AWS SDK but that didn't fix it.

So I then did a git bisection to find the point it started going wrong

It turns out that this is the commit that is causing the problem by @darthShadow

I eventually figured out that this commit introduces two http transports, and different transports are used for the HEAD and the PUT which means that they are likely talking to different servers, hence the version skew.

I've attempted to fix this here - can you give it a go?

v1.55.0-beta.5243.249a86f42.fix-s3-wasabi on branch fix-s3-wasabi (uploaded in 15-30 mins)

I have to say this was a pretty tricky bug to track down. I reviewed @darthShadow 's patch and I didn't notice that it was introducing a potential problem.

asdffdsa · March 5, 2021, 3:24pm

wow, that is some bug to find and fix.

i re-ran my test 2000 times, zero errors.

thanks much,