After upgrade, rclone sync wants to do a full copy not just of deltas

TonyLewis · September 20, 2024, 7:06am

What is the problem you are having with rclone?

After an upgrade to the latest rclone, an rclone sync to an encrypted OneDrive remote is attempting upload everything again rather than only the deltas. This is going to take six weeks according to rclone's ETA.

The root cause seems to be that rclone is not recognising the remote files are there when doing a sync (but they are there when doing an ls or sha1sum.

I've reduced it to a sync of a single file which copies it again, even when I know it's there.

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

rclone v1.68.0
- os/version: ubuntu 22.04 (64 bit)
- os/kernel: 5.15.0-101-generic (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.23.1
- go/linking: static
- go/tags: none

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

OneDrive (encrypted)

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

First, confirm that the file is there and the hashes match:

borg@borghost:~$ rclone sha1sum --download ~/repos/photos/data/1/1202
35b9444a8d81a795605f1a56ef1eb6c974c85027  1202
borg@borghost:~$ rclone sha1sum --download onedrive:repos/photos/data/1/1202
35b9444a8d81a795605f1a56ef1eb6c974c85027  1202

Now try to sync that file. Should be a 'nothing to do' response

borg@borghost:~$ rclone sync -vv ~/repos/photos/data/1/1202 onedrive:repos/photos/data/1202
2024/09/20 16:38:10 DEBUG : rclone: Version "v1.68.0" starting with parameters ["rclone" "sync" "-vv" "/home/borg/repos/photos/data/1/1202" "onedrive:repos/photos/data/1202"]
2024/09/20 16:38:10 DEBUG : Creating backend with remote "/home/borg/repos/photos/data/1/1202"
2024/09/20 16:38:10 DEBUG : Using config file from "/home/borg/.config/rclone/rclone.conf"
2024/09/20 16:38:10 DEBUG : fs cache: adding new entry for parent of "/home/borg/repos/photos/data/1/1202", "/home/borg/repos/photos/data/1"
2024/09/20 16:38:10 DEBUG : Creating backend with remote "onedrive:repos/photos/data/1202"
2024/09/20 16:38:10 DEBUG : Creating backend with remote "onedriveunderlying:rclonebackups/qtvah5opb18p4g4ve2i0lh4mio/vptothej6ciusdjpca3agsgj5o/u58r1pkbe9ip1vlcarj5tntqqs/vknf9rh5le44k0v06gdv2ri0ts"
2024/09/20 16:38:16 DEBUG : 1202: Need to transfer - File not found at Destination
2024/09/20 16:38:16 DEBUG : vknf9rh5le44k0v06gdv2ri0ts: Starting multipart upload
2024/09/20 16:38:17 DEBUG : vknf9rh5le44k0v06gdv2ri0ts: Uploading segment 0/147937 size 147937
2024/09/20 16:38:19 DEBUG : 1202: quickxor = 95e2ea721717a53fd19078f121bff4caeab38aea OK
2024/09/20 16:38:19 INFO  : 1202: Copied (new)
2024/09/20 16:38:19 INFO  : 
Transferred:      144.470 KiB / 144.470 KiB, 100%, 48.156 KiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:         8.2s

Check that the file is still there, still with matching hash:

borg@borghost:~$ rclone sha1sum --download onedrive:repos/photos/data/1/1202
35b9444a8d81a795605f1a56ef1eb6c974c85027  1202

Interestingly when I do a second sync, it recognises the file is there, but then still goes and recopies it (I think):

borg@borghost:~$ rclone sync -vv ~/repos/photos/data/1/1202 onedrive:repos/photos/data/1202
2024/09/20 16:39:17 DEBUG : rclone: Version "v1.68.0" starting with parameters ["rclone" "sync" "-vv" "/home/borg/repos/photos/data/1/1202" "onedrive:repos/photos/data/1202"]
2024/09/20 16:39:17 DEBUG : Creating backend with remote "/home/borg/repos/photos/data/1/1202"
2024/09/20 16:39:17 DEBUG : Using config file from "/home/borg/.config/rclone/rclone.conf"
2024/09/20 16:39:17 DEBUG : fs cache: adding new entry for parent of "/home/borg/repos/photos/data/1/1202", "/home/borg/repos/photos/data/1"
2024/09/20 16:39:17 DEBUG : Creating backend with remote "onedrive:repos/photos/data/1202"
2024/09/20 16:39:17 DEBUG : Creating backend with remote "onedriveunderlying:rclonebackups/qtvah5opb18p4g4ve2i0lh4mio/vptothej6ciusdjpca3agsgj5o/u58r1pkbe9ip1vlcarj5tntqqs/vknf9rh5le44k0v06gdv2ri0ts"
2024/09/20 16:39:20 DEBUG : 1202: Modification times differ by -143.88454ms: 2023-02-17 21:00:17.14388454 +1100 AEDT, 2023-02-17 10:00:17 +0000 UTC
2024/09/20 16:39:20 DEBUG : vknf9rh5le44k0v06gdv2ri0ts: Starting multipart upload
2024/09/20 16:39:21 DEBUG : vknf9rh5le44k0v06gdv2ri0ts: Uploading segment 0/147937 size 147937
2024/09/20 16:39:22 DEBUG : 1202: quickxor = 8d6737714cdb2e8e583f30e796d0691e39a98b0f OK
2024/09/20 16:39:22 INFO  : 1202: Copied (replaced existing)
2024/09/20 16:39:22 INFO  : 
Transferred:      144.470 KiB / 144.470 KiB, 100%, 72.234 KiB/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:         4.7s

So for some reason even when I can hash the remote file and it matches, sync either thinks it's not there or that the mod time mismatches. In either case it looks like it is trying to do a full copy for every file, for every execution.

The rclone config contents with secrets removed.

[onedrive]
type = crypt
remote = onedriveunderlying:rclonebackups
filename_encryption = standard
directory_name_encryption = true
password = XXX
password2 = XXX

[onedriveunderlying]
type = onedrive
token = XXX
drive_id = XXX
drive_type = personal

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

Logs pasted above alongside the command.

But the interesting parts (to me) of the log files are as below. From the first sync command:

2024/09/20 16:38:16 DEBUG : 1202: Need to transfer - File not found at Destination
...
2024/09/20 16:38:19 INFO  : 1202: Copied (new)

and from the second:

2024/09/20 16:39:20 DEBUG : 1202: Modification times differ by -143.88454ms: 2023-02-17 21:00:17.14388454 +1100 AEDT, 2023-02-17 10:00:17 +0000 UTC
...
2024/09/20 16:39:22 INFO  : 1202: Copied (replaced existing)

TonyLewis · September 20, 2024, 7:09am

Also, my upgrade was necessitated because I was seeing authentication errors as discussed here.

If it matters, the version of rclone before upgrading was whatever came with the Ubuntu 22.04.2 LTS version, which appears to be 1.53.3, which I'd been using for a few years without issue.

kapitainsky · September 20, 2024, 9:02am

I have had similar issue. It was never followed up but in the meantime what worked for me was to add --modify-window 1s flag to my sync command.

Try maybe it will work for you too.

nielash · September 20, 2024, 10:27am

Possible explanation:

kapitainsky · September 20, 2024, 11:03am

Thanks for the explanation. Now it is clear why it plays havoc with overlays not supporting hashes (like crypt) causing files to be re-uploaded again.

sweh · September 20, 2024, 2:04pm

Snap; Rclone v1.68.0 release - #7 by sweh

If you can replicate this problem (I can't 'cos my uploads all completed) I'm sure @ncw would love to see some debug output

kapitainsky · September 20, 2024, 2:57pm

Debug is in my issue and I think it is exactly the same problem. Initially I thought that it is union causing it but now I fully understand that it is crypt over onedrive.

TonyLewis · September 22, 2024, 6:58am

Thanks all for the pointers, it is indeed a problem with matching the mtimes from onedrive.

I've submitted a bug:

github.com/rclone/rclone

rclone sync to onedrive keeps reuploading file because of the resolution of mtime

opened 06:57AM - 22 Sep 24 UTC

bigtonylewis

#### The associated forum post URL from `https://forum.rclone.org` https://forum.rclone.org/t/after-upgrade-rclone-sync-wants-to-do-a-full-copy-not-just-of-deltas/47864 https://forum.rclone.org/t/rclone-v1-68-0-release/47643/7 https://forum.rclone.org/t/onedrive-modified-time-tolerance-change/45356/2 #### What is the problem you are having with rclone? After an upgrade to the latest rclone, an rclone sync to an encrypted OneDrive remote is attempting upload everything again rather than only the deltas. This is going to take six weeks according to rclone's ETA. The root cause seems to be that the source file has mtime resolution down to milliseconds, but the file on onedrive only has resolution down to seconds. There is then a sub-second mismatch in mtime, causing the file to be reuploaded I've reduced it to a sync of a single file which copies it again, each time the command is run. I can do a workaround using `--modify-window 1s` but that surely isn't the proper way to solve this? #### What is your rclone version (output from `rclone version`) ``` rclone v1.68.0 - os/version: ubuntu 22.04 (64 bit) - os/kernel: 5.15.0-101-generic (x86_64) - os/type: linux - os/arch: amd64 - go/version: go1.23.1 - go/linking: static - go/tags: none ``` #### Which OS you are using and how many bits (e.g. Windows 7, 64 bit) Ubuntu 22.04.2 LTS, 64-bit #### Which cloud storage system are you using? (e.g. Google Drive) OneDrive (encrypted) #### The command you were trying to run (e.g. `rclone copy /tmp remote:tmp`) ``` borg@host:/tmp$ rclone -vv sync ~/repos/photos/data/1/1202 onedrive:repos/photos/data/1 ``` #### A log from the command with the `-vv` flag (e.g. output from `rclone -vv copy /tmp remote:tmp`) First run, showing time mismatch and therefore new upload ``` borg@host:/tmp$ rclone -vv sync ~/repos/photos/data/1/1202 onedrive:repos/photos/data/1 2024/09/22 16:48:07 DEBUG : rclone: Version "v1.68.0" starting with parameters ["rclone" "-vv" "sync" "/home/borg/repos/photos/data/1/1202" "onedrive:repos/photos/data/1"] 2024/09/22 16:48:07 DEBUG : Creating backend with remote "/home/borg/repos/photos/data/1/1202" 2024/09/22 16:48:07 DEBUG : Using config file from "/home/borg/.config/rclone/rclone.conf" 2024/09/22 16:48:07 DEBUG : fs cache: adding new entry for parent of "/home/borg/repos/photos/data/1/1202", "/home/borg/repos/photos/data/1" 2024/09/22 16:48:07 DEBUG : Creating backend with remote "onedrive:repos/photos/data/1" 2024/09/22 16:48:07 DEBUG : Creating backend with remote "onedriveunderlying:rclonebackups/qtvah5opb18p4g4ve2i0lh4mio/vptothej6ciusdjpca3agsgj5o/u58r1pkbe9ip1vlcarj5tntqqs/s4s1q07jvge4ij8b60qlddrsf8" 2024/09/22 16:48:10 DEBUG : 1202: Modification times differ by -143.88454ms: 2023-02-17 21:00:17.14388454 +1100 AEDT, 2023-02-17 10:00:17 +0000 UTC 2024/09/22 16:48:10 DEBUG : vknf9rh5le44k0v06gdv2ri0ts: Starting multipart upload 2024/09/22 16:48:10 DEBUG : vknf9rh5le44k0v06gdv2ri0ts: Uploading segment 0/147937 size 147937 2024/09/22 16:48:12 DEBUG : 1202: quickxor = cc7c7a7cd3296c4ce22217158ee76efcbec317c5 OK 2024/09/22 16:48:12 INFO : 1202: Copied (replaced existing) 2024/09/22 16:48:12 INFO : Transferred: 144.470 KiB / 144.470 KiB, 100%, 112.047 KiB/s, ETA 0s Transferred: 1 / 1, 100% Elapsed time: 4.6s 2024/09/22 16:48:12 DEBUG : 9 go routines active ``` Second run showing that even though it was uploaded the first time, it gets reuploaded: ``` borg@host:/tmp$ rclone -vv sync ~/repos/photos/data/1/1202 onedrive:repos/photos/data/1 2024/09/22 16:48:17 DEBUG : rclone: Version "v1.68.0" starting with parameters ["rclone" "-vv" "sync" "/home/borg/repos/photos/data/1/1202" "onedrive:repos/photos/data/1"] 2024/09/22 16:48:17 DEBUG : Creating backend with remote "/home/borg/repos/photos/data/1/1202" 2024/09/22 16:48:17 DEBUG : Using config file from "/home/borg/.config/rclone/rclone.conf" 2024/09/22 16:48:17 DEBUG : fs cache: adding new entry for parent of "/home/borg/repos/photos/data/1/1202", "/home/borg/repos/photos/data/1" 2024/09/22 16:48:17 DEBUG : Creating backend with remote "onedrive:repos/photos/data/1" 2024/09/22 16:48:17 DEBUG : Creating backend with remote "onedriveunderlying:rclonebackups/qtvah5opb18p4g4ve2i0lh4mio/vptothej6ciusdjpca3agsgj5o/u58r1pkbe9ip1vlcarj5tntqqs/s4s1q07jvge4ij8b60qlddrsf8" 2024/09/22 16:48:20 DEBUG : 1202: Modification times differ by -143.88454ms: 2023-02-17 21:00:17.14388454 +1100 AEDT, 2023-02-17 10:00:17 +0000 UTC 2024/09/22 16:48:20 DEBUG : vknf9rh5le44k0v06gdv2ri0ts: Starting multipart upload 2024/09/22 16:48:20 DEBUG : vknf9rh5le44k0v06gdv2ri0ts: Uploading segment 0/147937 size 147937 2024/09/22 16:48:21 DEBUG : 1202: quickxor = b93d44af98526f074f808342a06fcb2ccc70396b OK 2024/09/22 16:48:21 INFO : 1202: Copied (replaced existing) 2024/09/22 16:48:21 INFO : Transferred: 144.470 KiB / 144.470 KiB, 100%, 144.470 KiB/s, ETA 0s Transferred: 1 / 1, 100% Elapsed time: 4.0s 2024/09/22 16:48:21 DEBUG : 9 go routines active ``` Run using `--modify-window 1s`: ``` borg@host:/tmp$ rclone -vv sync --modify-window 1s ~/repos/photos/data/1/1202 onedrive:repos/photos/data/1 2024/09/22 16:48:32 DEBUG : rclone: Version "v1.68.0" starting with parameters ["rclone" "-vv" "sync" "--modify-window" "1s" "/home/borg/repos/photos/data/1/1202" "onedrive:repos/photos/data/1"] 2024/09/22 16:48:32 DEBUG : Creating backend with remote "/home/borg/repos/photos/data/1/1202" 2024/09/22 16:48:32 DEBUG : Using config file from "/home/borg/.config/rclone/rclone.conf" 2024/09/22 16:48:32 DEBUG : fs cache: adding new entry for parent of "/home/borg/repos/photos/data/1/1202", "/home/borg/repos/photos/data/1" 2024/09/22 16:48:32 DEBUG : Creating backend with remote "onedrive:repos/photos/data/1" 2024/09/22 16:48:32 DEBUG : Creating backend with remote "onedriveunderlying:rclonebackups/qtvah5opb18p4g4ve2i0lh4mio/vptothej6ciusdjpca3agsgj5o/u58r1pkbe9ip1vlcarj5tntqqs/s4s1q07jvge4ij8b60qlddrsf8" 2024/09/22 16:48:34 DEBUG : 1202: Size and modification time the same (differ by -143.88454ms, within tolerance 1s) 2024/09/22 16:48:34 DEBUG : 1202: Unchanged skipping 2024/09/22 16:48:34 INFO : Transferred: 0 B / 0 B, -, 0 B/s, ETA - Elapsed time: 2.4s 2024/09/22 16:48:34 DEBUG : 6 go routines active ``` `lsl` showing the mismatching modification times: ``` borg@host:/tmp$ rclone lsl onedrive:repos/photos/data/1/1202 147857 2023-02-17 21:00:17.000000000 1202 borg@host:/tmp$ rclone lsl ~/repos/photos/data/1/1202 147857 2023-02-17 21:00:17.143884540 1202 ``` #### How to use GitHub * Please use the 👍 [reaction](https://blog.github.com/2016-03-10-add-reactions-to-pull-requests-issues-and-comments/) to show that you are affected by the same issue. * Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue. * Subscribe to receive notifications on status change and new comments.

ncw · September 22, 2024, 10:35am

The precision for the onedrive personal backend changed from 1s to 1ms. Normally this wouldn't be a problem but if you are using crypt then it will exhibit this upload everything again problem. See Issue #8090 for more info.

However you should be able to fix with a one time sync using the --refresh-times flag which will update the timestamps.

sweh · October 9, 2024, 2:00pm

( A catchup for the people who didn't read the github issue; it looks like Microsoft are migrating some drives to a different backend infrastructure which only has 1s accuracy; the fix is to revert the 1ms timing; a work-around is to add --modify-window 1s )

But I just noticed another fun consequence to this migration.

I'd noticed on my "bad" drive that it was reporting nothing in trash

OneDriveBackups:        OneDriveBackups2:       OneDriveBackups3:
====================    ====================    ====================
Total:   1.005 TiB      Total:   1.005 TiB      Total:   1.005 TiB
Used:    965.400 GiB    Used:    773.100 GiB    Used:    230.800 GiB
Free:    63.600 GiB     Free:    255.900 GiB    Free:    798.200 GiB
Trashed: 1.686 TiB      Trashed: 239.269 GiB    Trashed: 0 B

This is clearly wrong; I can see stuff in there from the webUI

So I took a look at the dump body output of rclone about for a "good" and a "bad" (migrated) drive. In both cases the request is GET /v1.0/drives/xxxxx HTTP/1.1

But the responses...

Good (not migrated; 1ms drive):

{
  "@odata.context": "https://graph.microsoft.com/v1.0/$metadata#drives/$entity",
  "driveType": "personal",
  "id": "XXX",
  "owner": {
    "user": {
      "displayName": "XXX",
      "id": "XXX"
    }
  },
  "quota": {
    "deleted": 256913083688,
    "remaining": 274770532761,
    "state": "normal",
    "total": 1104880336896,
    "used": 830109804135,
    "storagePlanInformation": {
      "upgradeAvailable": false
    }
  }
}

And the bad (migrated, 1s accuracy)

{
  "@odata.context": "https://graph.microsoft.com/v1.0/$metadata#drives/$entity",
  "createdDateTime": "2024-09-22T13:48:05Z",
  "description": "",
  "id": "XXX",
  "lastModifiedDateTime": "2024-10-09T13:47:55Z",
  "name": "OneDrive",
  "webUrl": "https://my.microsoftpersonalcontent.com/personal/XXX/Documents",
  "driveType": "personal",
  "createdBy": {
    "user": {
      "displayName": "SharePoint App"
    }
  },
  "lastModifiedBy": {
    "user": {
      "displayName": "System Account"
    }
  },
  "owner": {
    "user": {
      "email": "XXX",
      "displayName": "XXX"
    }
  },
  "quota": {
    "deleted": 0,
    "remaining": 854591117721,
    "state": "normal",
    "total": 1104880336896,
    "used": 250289219175,
    "storagePlanInformation": {
      "upgradeAvailable": false
    }
  }
}

This really highlights the different backends cos the JSON is quite different.

And this definitely looks like a bug in the backend of the new migrated drive! The API is returning zero in the "deleted" attribute.

Thanks, Microsoft. You always make things "fun".

kapitainsky · October 9, 2024, 2:50pm

Thank you for sharing. Now it all makes perfect sense with OneDrives I work with. Clearly two different backend versions. Zero thrash issue started few month ago (of course on some only) but as I use personal accounts where thrash content does not count against quota I just slurred over it. These are exactly accounts where web GUI is different a bit than others. And GUI has bugs too:) another thing I ignore and do not use.