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

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:

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

opened 06:57AM - 22 Sep 24 UTC

#### 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.