OneDrive sync never completes with SHA-1 corrupted transfer with latest rclone

Help and Support
1

What is the problem you are having with rclone?

Unable to complete a 116GB upload to OneDrive anymore. This used to work for the last year or so, however since doing an apt-get upgrade it no longer seems to ever complete with constant corrupted on transfer: SHA-1 hash differ messages.

Run the command 'rclone version' and share the full output of the command.

rclone v1.55.1

  • os/type: linux
  • os/arch: amd64
  • go/version: go1.16.3
  • go/linking: static
  • go/tags: none

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

OneDrive

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

rclone sync /mnt/smb_pve_backups/ "onedrive:/Backups/PVE Backups" --exclude "/.recycle/**" --min-age 15m --bwlimit "08:00,0.4M 00:00,off" --onedrive-chunk-size 1280k --log-level INFO --log-file ~/pvebackups.rclone.log &

The rclone config contents with secrets removed.

[onedrive]
type = onedrive
token = REMOVED
drive_id = REMOVED
drive_type = personal

[crypt]
type = crypt
remote = onedrive:Backups/Archive
filename_encryption = obfuscate
directory_name_encryption = false
password = REMOVED

A log from the command with the -vv flag

2022/03/24 05:40:46 ERROR : dump/vzdump-qemu-107-2022_03_19-02_00_03.vma.zst: corrupted on transfer: SHA-1 hash differ "4ed4780309e547e848a6db94b3e563c89ddea7c3" vs "ab5b31734aaad82c6948c4e26b508831db5dd3cd"
2022/03/24 05:40:46 INFO  : dump/vzdump-qemu-107-2022_03_19-02_00_03.vma.zst: Removing failed copy
2022/03/24 05:40:46 ERROR : One drive root 'Backups/PVE Backups': not deleting files as there were IO errors
2022/03/24 05:40:46 ERROR : One drive root 'Backups/PVE Backups': not deleting directories as there were IO errors
2022/03/24 05:40:46 ERROR : Attempt 3/3 failed with 1 errors and: corrupted on transfer: SHA-1 hash differ "4ed4780309e547e848a6db94b3e563c89ddea7c3" vs "ab5b31734aaad82c6948c4e26b508831db5dd3cd"
2022/03/24 05:40:46 INFO  : 
Transferred:      116.185G / 116.185 GBytes, 100%, 763.561 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:                47 / 47, 100%
Transferred:            2 / 2, 100%
Elapsed time:  44h19m17.4s

2022/03/24 05:40:46 Failed to sync: corrupted on transfer: SHA-1 hash differ "4ed4780309e547e848a6db94b3e563c89ddea7c3" vs "ab5b31734aaad82c6948c4e26b508831db5dd3cd"

I know this isn't with the -vv flag so I can run it again later with that on, but I think this is probably enough information for someone to have an idea (I hope).

2

hello and welcome to the forum,

best to update to latest stable v1.58.0 and test again with a debug log.

any chance that the source file was modified during the time that rclone was uploading it?

3

I can update rclone and try again.

No, no chance the file was modified.

4

I see your sync takes 2 days. You could add —retries=1 to save some time while troubleshooting.

5

I am experiencing exact the same problem.

Command:

rclone sync -vv --transfers 1 /mnt/vzdump/ od_proxmox_enc:Proxmox |& tee rclone_log.txt

Transfer to encrypted remote on onedrive fails with

Failed to copy: corrupted on transfer: sha1 crypted hash differ src "4b3b2fe35083fd3b8b6f4d7dea7a970bcad28e11" vs dst "340bd2bbb62c31072d4558729f08147685988288"

I did a transfer with --vv option. The only problem I could see was this:

2022/03/30 11:13:36 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2022/03/30 11:13:36 DEBUG : pacer: low level retry 1/10 (error 503 Service Unavailable: )
2022/03/30 11:13:36 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2022/03/30 11:13:38 DEBUG : n20mpfa818tuusk9im8c6hgmbc/psufsgg933ffvpdb87qkflokguro9pdphu3vliic8lvpltipqj8cn659sfc5l3dp2ubviig7nprsk: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2022/03/30 11:13:38 DEBUG : pacer: Reducing sleep to 15ms
2022/03/30 11:13:38 DEBUG : n20mpfa818tuusk9im8c6hgmbc/psufsgg933ffvpdb87qkflokguro9pdphu3vliic8lvpltipqj8cn659sfc5l3dp2ubviig7nprsk: Read position 25583124480, chunk is 25574768640..25585254400, bytes to skip = 8355840
2022/03/30 11:13:38 DEBUG : pacer: low level retry 2/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2022/03/30 11:13:38 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2022/03/30 11:13:39 DEBUG : pacer: Reducing sleep to 22.5ms
2022/03/30 11:13:39 DEBUG : n20mpfa818tuusk9im8c6hgmbc/psufsgg933ffvpdb87qkflokguro9pdphu3vliic8lvpltipqj8cn659sfc5l3dp2ubviig7nprsk: Uploading segment 25585254400/30156156256 size 10485760
2022/03/30 11:13:41 DEBUG : pacer: Reducing sleep to 16.875ms
2022/03/30 11:13:41 DEBUG : n20mpfa818tuusk9im8c6hgmbc/psufsgg933ffvpdb87qkflokguro9pdphu3vliic8lvpltipqj8cn659sfc5l3dp2ubviig7nprsk: Uploading segment 25595740160/30156156256 size 10485760
2022/03/30 11:13:45 DEBUG : pacer: Reducing sleep to 12.65625ms
2022/03/30 11:13:45 DEBUG : n20mpfa818tuusk9im8c6hgmbc/psufsgg933ffvpdb87qkflokguro9pdphu3vliic8lvpltipqj8cn659sfc5l3dp2ubviig7nprsk: Uploading segment 25606225920/30156156256 size 10485760
2022/03/30 11:13:48 DEBUG : pacer: Reducing sleep to 10ms

I am using rclone version:
rclone v1.58.0

  • os/version: debian 11.3 (64 bit)
  • os/kernel: 5.13.19-6-pve (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.17.8
  • go/linking: static
  • go/tags: none

rclone_log.txt (575.2 KB)

6

This message is saying that the hash rclone calculated locally is different from the hash onedrive calculated remotely, so the file on the local disk isn't the same as the remote file.

This can be caused by quite a few things, but the most likely is the file changed on the local disk while it was being uploaded.

Is that possible? Did the file get updated in any way while it was being uploaded?

Another possibility is that it is a bug in rclone. This is actually the crypt backend checking the hash, so if the crypt backend is calculating the hash wrong (in the presense of retries maybe) then that could be a problem

In your log, the most significant part is this

This is rclone retrying a chunk (partially) so I wonder if rclone's (or onedrive's) hash calculation has gone wrong at that point.

Do you always see that kind of retry on a failed upload?

I had an investigate of the code paths and I can't see anything wrong. It is very difficult to replicate this problem though!

7

Thanks for the reply :blush:

The files are static backups of my proxmox containers. So they are not changed during the backup.

I found out that I have similar issues when backing up my (encrypted) TimeMachine unencrypted to OneDrive. Because the files are smaller (128MB) the retry mechanism did work it out.

I did not made a log to find out more.

I guess the problem exists on OneDrive side. With smaller files the retry will fix the problem, but large files have a problem when an error occurs.

These problems first occurred in last two weeks, maybe it‘s a stability issue at Microsoft.

In the meantime I implemented splitting the large backup files into 128MB files before syncing to OneDrive. So it will upload again with some retries.

I could do a Debug-Log of the failing unencrypted transfer if it would be helpful.

8

That's funny because my failure is also with proxmox backups, specifically some of the qemu VMs. I wonder if this is a coincidence or not.

9

That would be really helpful, thank you, as it would enable me to rule out the crypt checksum code.

If I can reproduce this then I'll fix rclone or report the bug to Microsoft as appropriate!

10

Synced again with debug option.

command:

rclone sync --transfers 1 -vv /mnt/timemachine/ od:TM-Pi |& tee rclone_unencrypted.log

I discovered different types of errors

2022/04/01 07:53:24 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2022/04/01 07:53:24 DEBUG : pacer: low level retry 1/10 (error 503 Service Unavailable: )
2022/04/01 07:53:24 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2022/04/01 07:53:29 DEBUG : pacer: Reducing sleep to 15ms
2022/04/01 07:53:29 DEBUG : Katrins MacBook.sparsebundle/bands/424: Uploading segment 62914560/134217728 size 10485760
2022/04/01 07:53:33 DEBUG : pacer: Reducing sleep to 11.25ms
2022/04/01 07:53:33 DEBUG : Katrins MacBook.sparsebundle/bands/424: Uploading segment 73400320/134217728 size 10485760
2022/04/01 07:53:38 DEBUG : pacer: Reducing sleep to 10ms
...
2022/04/01 08:00:22 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2022/04/01 08:00:22 DEBUG : pacer: low level retry 1/10 (error 503 Service Unavailable: )
2022/04/01 08:00:22 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2022/04/01 08:00:26 DEBUG : Katrins MacBook.sparsebundle/bands/459: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.
2022/04/01 08:00:27 DEBUG : pacer: Reducing sleep to 15ms
2022/04/01 08:00:27 DEBUG : Katrins MacBook.sparsebundle/bands/459: Read position 18841600, chunk is 10485760..20971520, bytes to skip = 8355840
2022/04/01 08:00:27 DEBUG : pacer: low level retry 2/10 (error retry this chunk skipping 8355840 bytes: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.)
2022/04/01 08:00:27 DEBUG : pacer: Rate limited, increasing sleep to 30ms
2022/04/01 08:00:28 DEBUG : pacer: Reducing sleep to 22.5ms
2022/04/01 08:00:28 DEBUG : Katrins MacBook.sparsebundle/bands/459: Uploading segment 20971520/134217728 size 10485760
2022/04/01 08:00:32 DEBUG : pacer: Reducing sleep to 16.875ms
2022/04/01 08:00:32 DEBUG : Katrins MacBook.sparsebundle/bands/459: Uploading segment 31457280/134217728 size 10485760
2022/04/01 08:00:37 DEBUG : pacer: Reducing sleep to 12.65625ms
2022/04/01 08:00:37 DEBUG : Katrins MacBook.sparsebundle/bands/459: Uploading segment 41943040/134217728 size 10485760
2022/04/01 08:00:42 DEBUG : pacer: Reducing sleep to 10ms
2022/04/01 08:00:42 DEBUG : Katrins MacBook.sparsebundle/bands/459: Uploading segment 52428800/134217728 size 10485760
...
2022/04/01 08:02:23 DEBUG : Katrins MacBook.sparsebundle/bands/45a: sha1 = 6aeb56adeebef4fdd7be9ebba599e69f07ba050d (Local file system at /mnt/timemachine/)
2022/04/01 08:02:23 DEBUG : Katrins MacBook.sparsebundle/bands/45a: sha1 = ec8763f5529430f0656457a5dfd0fe258568ecc8 (One drive root 'TM-Pi')
2022/04/01 08:02:23 ERROR : Katrins MacBook.sparsebundle/bands/45a: corrupted on transfer: sha1 hash differ "6aeb56adeebef4fdd7be9ebba599e69f07ba050d" vs "ec8763f5529430f0656457a5dfd0fe258568ecc8"
2022/04/01 08:02:23 INFO  : Katrins MacBook.sparsebundle/bands/45a: Removing failed copy
...
2022/04/01 08:13:30 DEBUG : pacer: low level retry 1/10 (error Put "https://api.onedrive.com/rup/8a470a0d8436c51b/eyJSZXNvdXJjZUlEIjoiOEE0NzBBMEQ4NDM2QzUxQiExNTQyMCIsIlJlbGF0aW9uc2hpcE5hbWUiOiI0OSJ9/4mM8aXUjptyGUJHsSs7hCX8PfhLswa5Mr1-WucBPsCFnn0SxzUd2lQRkHazlJfHx5wIrlAwTsZ-JodDfwl96m9AYr8YNOjVTdbSu2yV3vyBrc/eyJuYW1lIjoiNDkiLCJmaWxlU3lzdGVtSW5mbyI6eyJDcmVhdGVkRGF0ZVRpbWUiOiIyMDIyLTAzLTMxVDA1OjQ5OjQ2KzAwOjAwIiwiTGFzdE1vZGlmaWVkRGF0ZVRpbWUiOiIyMDIyLTAzLTMxVDA1OjQ5OjQ2KzAwOjAwIn0sIkBuYW1lLmNvbmZsaWN0QmVoYXZpb3IiOiJyZXBsYWNlIn0/4wuZ6LWPE5eZBK9Rjdb2UTIQXilbprlmO8sIS1RykXgbcOlCTmCzgGfgcO1ZIz3DTnujr_CHwP06E3S3Sz80t2Nd8zsqtlS-9JAnO-m-xxljhn2kcDzVq8D5PV8agsMBiT46wO2O4Y-gsw-xThCvkIoNQJVutZTER-3e4PVdlWTn7OMhIG35LBeYy1vpPwWjaGh9v0UYmc6OnXzwAGTtJ8nuLEf0aSFCMq2w6wgEjDXICU3BiL8W1rjYO9b_JZP-QHCD44CCMlI0XbPcYK_KYNxRP_k-94zcSqY3FiekO5p9vKHjbrEywLbQWnAoP-ETAaJi6PlK3kYPJNTzWhN6J1X6ekXMRD8WCFxupa1d0GBYBlRMNro3osvdg5QIISmQRrFR91pmPqfe7NYAlaerAM9hic00otSEzXehMKHczCf3xBHc5optti2yvrDUCECdKdK69WTxuIdwI88lp9AHsQ7qQy1fC1R4XroH1cQ2bhq08IcE2P9fYBlwC8AixL_ussZbeydsZ1Z28GpwDiC1h4QwLCS1IeyXnZjjV93KW0L88DkFr_Lt_UyZeGN0RV0ynV1guXAIf4wNO0B9pm4R0pu7zzXW8aLDg-qYbzI1XK2eY": unexpected EOF)
2022/04/01 08:13:30 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2022/04/01 08:13:35 DEBUG : pacer: Reducing sleep to 15ms
2022/04/01 08:13:35 DEBUG : Katrins MacBook.sparsebundle/bands/49: Uploading segment 73400320/134217728 size 10485760
2022/04/01 08:13:40 DEBUG : pacer: Reducing sleep to 11.25ms
2022/04/01 08:13:40 DEBUG : Katrins MacBook.sparsebundle/bands/49: Uploading segment 83886080/134217728 size 10485760
2022/04/01 08:13:45 DEBUG : pacer: Reducing sleep to 10ms
2022/04/01 08:13:45 DEBUG : Katrins MacBook.sparsebundle/bands/49: Uploading segment 94371840/134217728 size 10485760

Full log is attached.

I also did another encrypted sync. This time with only two errors like this one:

2022/04/01 07:53:24 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2022/04/01 07:53:24 DEBUG : pacer: low level retry 1/10 (error 503 Service Unavailable: )
2022/04/01 07:53:24 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2022/04/01 07:53:29 DEBUG : pacer: Reducing sleep to 15ms
2022/04/01 07:53:29 DEBUG : Katrins MacBook.sparsebundle/bands/424: Uploading segment 62914560/134217728 size 10485760
2022/04/01 07:53:33 DEBUG : pacer: Reducing sleep to 11.25ms
2022/04/01 07:53:33 DEBUG : Katrins MacBook.sparsebundle/bands/424: Uploading segment 73400320/134217728 size 10485760
2022/04/01 07:53:38 DEBUG : pacer: Reducing sleep to 10ms

Full log is also attached.

Hope this helps...
rclone_unencrytped.log (1.9 MB)
rclone_encrypted.log (937.5 KB)

11

I would like to check the SHA-1 sums in the log to see which value (if any) is correct.

Could you please execute these commands:

sha1sum "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/45a"
sha1sum "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/49b"
sha1sum "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/4ca"
sha1sum "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/4d2"

Please correct the commands if wrong, I am usually on Windows.

12

Hi, your commands are good :slight_smile:

sha1sum "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/45a"
6aeb56adeebef4fdd7be9ebba599e69f07ba050d  /mnt/timemachine/Katrins MacBook.sparsebundle/bands/45a

sha1sum "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/49b"
a7d3b5bad75a594f386642bb6d62dc48a9ee1132  /mnt/timemachine/Katrins MacBook.sparsebundle/bands/49b

sha1sum "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/4ca"
96f36a054fc6006a39bf2da9a6396dfc2001a8be  /mnt/timemachine/Katrins MacBook.sparsebundle/bands/4ca

sha1sum "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/4d2"
e0fcfee5e8a0fe6c294742ffb6bbfc3b20b31529  /mnt/timemachine/Katrins MacBook.sparsebundle/bands/4d2

I think the local sums are correct.

13

Great, I agree, let’s focus on the first file (45a)

Try executing this command twice:

rclone copy "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/45a" "od:TM-Pi/Katrins MacBook.sparsebundle/bands/" --ignore-times --retries=1 -vv

You may want to test it first with --dry-run, so we don’t accidently mess up your backups.

I am checking if the error is reproducible and results in the same (wrong) sha1sum on OneDrive.

14

Answering myself after looking more in the log. The error isn't consistently reproducible as can be seen later in the log:

2022/04/01 09:41:14 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Starting multipart upload
2022/04/01 09:41:15 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 0/134217728 size 10485760
2022/04/01 09:41:22 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 10485760/134217728 size 10485760
2022/04/01 09:41:27 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 20971520/134217728 size 10485760
2022/04/01 09:41:32 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 31457280/134217728 size 10485760
2022/04/01 09:41:37 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 41943040/134217728 size 10485760
2022/04/01 09:41:42 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 52428800/134217728 size 10485760
...
2022/04/01 09:41:47 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 62914560/134217728 size 10485760
2022/04/01 09:41:51 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 73400320/134217728 size 10485760
2022/04/01 09:41:56 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 83886080/134217728 size 10485760
2022/04/01 09:42:01 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 94371840/134217728 size 10485760
2022/04/01 09:42:05 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 104857600/134217728 size 10485760
2022/04/01 09:42:10 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 115343360/134217728 size 10485760
2022/04/01 09:42:15 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 125829120/134217728 size 8388608
2022/04/01 09:42:19 DEBUG : Katrins MacBook.sparsebundle/bands/45a: sha1 = 6aeb56adeebef4fdd7be9ebba599e69f07ba050d OK
2022/04/01 09:42:19 INFO  : Katrins MacBook.sparsebundle/bands/45a: Copied (new)
15

I agree. The retry will succeed in transferring.

Did the transfer again.

2022/04/01 12:14:11 DEBUG : rclone: Version "v1.58.0" starting with parameters ["rclone" "copy" "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/45a" "od:TM-Pi/Katrins MacBook.sparsebundle/bands/" "--ignore-times" "--retries=1" "-vv"]
2022/04/01 12:14:11 DEBUG : Creating backend with remote "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/45a"
2022/04/01 12:14:11 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2022/04/01 12:14:11 DEBUG : fs cache: adding new entry for parent of "/mnt/timemachine/Katrins MacBook.sparsebundle/bands/45a", "/mnt/timemachine/Katrins MacBook.sparsebundle/bands"
2022/04/01 12:14:11 DEBUG : Creating backend with remote "od:TM-Pi/Katrins MacBook.sparsebundle/bands/"
2022/04/01 12:14:17 DEBUG : fs cache: renaming cache item "od:TM-Pi/Katrins MacBook.sparsebundle/bands/" to be canonical "od:TM-Pi/Katrins MacBook.sparsebundle/bands"
2022/04/01 12:14:17 DEBUG : 45a: Transferring unconditionally as --ignore-times is in use
2022/04/01 12:14:17 DEBUG : 45a: Starting multipart upload
2022/04/01 12:14:17 DEBUG : 45a: Uploading segment 0/134217728 size 10485760
2022/04/01 12:14:23 DEBUG : 45a: Uploading segment 10485760/134217728 size 10485760
2022/04/01 12:14:27 DEBUG : 45a: Uploading segment 20971520/134217728 size 10485760
2022/04/01 12:14:32 DEBUG : 45a: Uploading segment 31457280/134217728 size 10485760
2022/04/01 12:14:37 DEBUG : 45a: Uploading segment 41943040/134217728 size 10485760
2022/04/01 12:14:41 DEBUG : 45a: Uploading segment 52428800/134217728 size 10485760
2022/04/01 12:14:46 DEBUG : 45a: Uploading segment 62914560/134217728 size 10485760
2022/04/01 12:14:51 DEBUG : 45a: Uploading segment 73400320/134217728 size 10485760
2022/04/01 12:14:56 DEBUG : 45a: Uploading segment 83886080/134217728 size 10485760
2022/04/01 12:15:00 DEBUG : 45a: Uploading segment 94371840/134217728 size 10485760
2022/04/01 12:15:05 DEBUG : 45a: Uploading segment 104857600/134217728 size 10485760
2022/04/01 12:15:09 DEBUG : 45a: Uploading segment 115343360/134217728 size 10485760
2022/04/01 12:15:14 DEBUG : 45a: Uploading segment 125829120/134217728 size 8388608
2022/04/01 12:15:17 INFO  :
Transferred:      125.465 MiB / 128 MiB, 98%, 2.131 MiB/s, ETA 1s
Transferred:            0 / 1, 0%
Elapsed time:       1m5.3s
Transferring:
 *                                           45a: 98% /128Mi, 2.131Mi/s, 1s

2022/04/01 12:15:18 DEBUG : 45a: sha1 = 6aeb56adeebef4fdd7be9ebba599e69f07ba050d OK
2022/04/01 12:15:18 INFO  : 45a: Copied (replaced existing)
2022/04/01 12:15:18 INFO  :
Transferred:          128 MiB / 128 MiB, 100%, 2.088 MiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:       1m7.0s

2022/04/01 12:15:18 DEBUG : 7 go routines active
16

Thanks, this is weird and may be hard to find/solve.

Let's check if the checksum remains the same after some time:

rclone sha1sum "od:TM-Pi/Katrins MacBook.sparsebundle/bands/45a"

also can I see the output from

rclone config show od:

please redact token etc.

17

Sure

rclone sha1sum "od:TM-Pi/Katrins MacBook.sparsebundle/bands/45a"
6aeb56adeebef4fdd7be9ebba599e69f07ba050d  45a

rclone config show od:
--------------------
[od]
type = onedrive
region = global
token = REMOVED
drive_id = REMOVED
drive_type = personal
--------------------

My guess is that it is a problem at Microsoft. This happened first time about two weeks ago and there where no changes on local side (except some system updates). The machine running the unencrypted sync at is a nearly bare Pi3 running only samba, wireguard and of course rclone on Debian 11.3 (armv7l).
The encrypted sync is running at a dedicated lxc-container on my Proxmox machine on Debian 11.3 (amd64).
I updated to rclone 1.58.0 on both machines after discovering the problem to see if it could solve the problem.

18

This is also my best guess. Perhaps a glitch while rushing data and services in safety from the Russian invasion of Ukraine.

19

Looking at the log (unencrypted) it seems that the error isn't correlated with this like I thought it would be

2022/04/01 08:00:26 DEBUG : Katrins MacBook.sparsebundle/bands/459: Received 416 error - reading current position from server: invalidRange: fragmentOverlap: The uploaded fragment overlaps with data that has already been received.

This file just gets uploaded with no low level retries

2022/04/01 08:01:19 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Starting multipart upload
2022/04/01 08:01:20 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 0/134217728 size 10485760
2022/04/01 08:01:27 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 10485760/134217728 size 10485760
2022/04/01 08:01:32 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 20971520/134217728 size 10485760
2022/04/01 08:01:36 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 31457280/134217728 size 10485760
2022/04/01 08:01:41 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 41943040/134217728 size 10485760
2022/04/01 08:01:45 INFO  : 
Transferred:        1.549 GiB / 10.625 GiB, 15%, 2.139 MiB/s, ETA 1h12m25s
Checks:              2415 / 2415, 100%
Transferred:           12 / 85, 14%
Elapsed time:      15m2.1s
Transferring:
 *        Katrins MacBook.sparsebundle/bands/45a: 38% /128Mi, 1.938Mi/s, 40s

2022/04/01 08:01:46 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 52428800/134217728 size 10485760
2022/04/01 08:01:50 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 62914560/134217728 size 10485760
2022/04/01 08:01:55 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 73400320/134217728 size 10485760
2022/04/01 08:02:00 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 83886080/134217728 size 10485760
2022/04/01 08:02:05 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 94371840/134217728 size 10485760
2022/04/01 08:02:10 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 104857600/134217728 size 10485760
2022/04/01 08:02:14 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 115343360/134217728 size 10485760
2022/04/01 08:02:19 DEBUG : Katrins MacBook.sparsebundle/bands/45a: Uploading segment 125829120/134217728 size 8388608
2022/04/01 08:02:23 DEBUG : Katrins MacBook.sparsebundle/bands/45a: sha1 = 6aeb56adeebef4fdd7be9ebba599e69f07ba050d (Local file system at /mnt/timemachine/)
2022/04/01 08:02:23 DEBUG : Katrins MacBook.sparsebundle/bands/45a: sha1 = ec8763f5529430f0656457a5dfd0fe258568ecc8 (One drive root 'TM-Pi')
2022/04/01 08:02:23 ERROR : Katrins MacBook.sparsebundle/bands/45a: corrupted on transfer: sha1 hash differ "6aeb56adeebef4fdd7be9ebba599e69f07ba050d" vs "ec8763f5529430f0656457a5dfd0fe258568ecc8"
2022/04/01 08:02:23 INFO  : Katrins MacBook.sparsebundle/bands/45a: Removing failed copy

Is there any chance those files are being modified while the backup is running? That would cause these symptoms too. Or might do anyway. You said no above, but this appears to be a different sort of file so just checking...

Assuming they aren't being modified this is looking increasingly like a problem at onedrive.

Can you run a sync with --ignore-checksum which will skip the post copy checksum check. This should allow the sync to complete.

Then could you use rclone check to find if any files have differing checksums.

Ideally then if you could download one of these files and diff it using a binary diff tool to find out where it differs that would shed a lot of light on what is going on.

As for how to do a binary diff? That isn't 100% straight forward but I usually dump the binary files to hex (using hd or hexdump) then diff those. You can do this all in one with something like

diff -u <(hd <original_file) <(hd <changed_file)

It might be that the files are identical, in which case all that is wrong is the metadata on onedrive. (you might have to use --ignore-checksum again if you are downloading the file with rclone).

20

@ncw Seems like you missed some of the above posts. The issue appears at random and has no relation to low-level retries or files being modified and the files often upload in the next attempt. It is therefore impossible to know if a file uploaded with --ignore-checksum has the issue or not; and yes we all guess it is OneDrive.

I therefore propose this sequence to provoke the problem and clarify if it is a pure metadata issue:

rclone sync --ignore-checksum --ignore-times --retries=1 --transfers=1 -vv "/mnt/timemachine/" "od:testfolder"
rclone check "/mnt/timemachine/" "od:testfolder"
rclone check "/mnt/timemachine/" "od:testfolder" --download

The sequence can be repeated until the issue appears. If the first check fails and the second pass, then it is (most likely) a metadata issue, otherwise proceed to do the download and binary diff.

1 Like