Rclone copy repeatedly copies some unchanged files

[Steve]

What is the problem you are having with rclone?

The rclone copy command that I am using should compare source and destination files and only copy updated or new files, within the specified time window, from the source to the destination. However, there are a few files which rclone repeatedly copies on every single run even though they have not been modified. To note this is only happening with two files within a specific directory out of several thousand files in each run. The behaviour with respect to the remaining files is as expected. The debug information given below focuses in on the bug and demonstrates it - it does not include the thousands of other files mentioned above.

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

rclone v1.57.0
- os/version: Microsoft Windows 10 Pro 2009 (64 bit)
- os/kernel: 10.0.19043.1466 (x86_64)
- os/type: windows
- os/arch: amd64
- go/version: go1.17.2
- go/linking: dynamic
- go/tags: cmount

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

Microsoft OneDrive - Business Account

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

rclone copy "%sourcepath%" "%destpath%" --max-age 14d --min-age 60m --no-traverse --drive-chunk-size 64M --checkers 7 --retries 1  --stats 10m --backup-dir="%archivepath%\%date%" --log-file="%logfilepath%\%logfilename%" --log-level=DEBUG

The rclone config contents with secrets removed.

[WitsOneDrive]
type = onedrive
drive_type = business
link_scope = organization

A log from the command with the -vv flag

There are three files in the directory which is being copied to OneDrive:

The following behaviour is expected with regard to these files, given that they do not exist at the destination, and that they are not modified:

1. default.html should be copied on the first run and skipped subsequently
2. strict.sty should be excluded as it falls outside the time window
3. test.log should be copied on the first run and skipped subsequently

What is actually happening is as follows:

1. default.html is always copied as a new file to the destination
2. strict.sty is correctly excluded
3. test.log is always copied as a new file to the destination

(As mentioned above, this example hones in on the bug. In my normal run, there are hundreds to thousands of other files which fall within the time window but have not been modified since the previous run and so are skipped as unchanged.)

Below are log files from two consecutive runs.
At this point, none of the files exist at the destination:

2022/02/18 10:27:00 DEBUG : --min-age 1h0m0s to 2022-02-18 09:27:00.7422054 +0200 SAST m=-3599.930229499
2022/02/18 10:27:00 DEBUG : --max-age 2w to 2022-02-04 10:27:00.7422054 +0200 SAST m=-1209599.930229499
2022/02/18 10:27:00 DEBUG : rclone: Version "v1.57.0" starting with parameters ["c:\\Program Files\\rclone/\\rclone" "copy" "c:/Data/WitsEIE/Ethics/ethics-www/_layouts/" "WitsOneDrive:/Elixir/Ethics/ethics-www/_layouts/" "--max-age" "14d" "--min-age" "60m" "--no-traverse" "--drive-chunk-size" "64M" "--checkers" "7" "--retries" "1" "--stats" "10m" "--backup-dir=WitsOneDrive:/Elixir-Archive\\2022.02.18-10.27" "--log-file=c:\\Data\\Config\\Scripts\\rclone-logs\\2022.02.18-10.27-rclone-copy-bug.log" "--log-level=DEBUG"]
2022/02/18 10:27:00 DEBUG : Creating backend with remote "c:/Data/WitsEIE/Ethics/ethics-www/_layouts/"
2022/02/18 10:27:00 DEBUG : Using config file from "C:\\Users\\Steve\\AppData\\Roaming\\rclone\\rclone.conf"
2022/02/18 10:27:00 DEBUG : fs cache: renaming cache item "c:/Data/WitsEIE/Ethics/ethics-www/_layouts/" to be canonical "//?/c:/Data/WitsEIE/Ethics/ethics-www/_layouts/"
2022/02/18 10:27:00 DEBUG : Creating backend with remote "WitsOneDrive:/Elixir/Ethics/ethics-www/_layouts/"
2022/02/18 10:27:05 DEBUG : fs cache: renaming cache item "WitsOneDrive:/Elixir/Ethics/ethics-www/_layouts/" to be canonical "WitsOneDrive:Elixir/Ethics/ethics-www/_layouts"
2022/02/18 10:27:05 DEBUG : Creating backend with remote "WitsOneDrive:/Elixir-Archive\\2022.02.18-10.27"
2022/02/18 10:27:10 DEBUG : fs cache: renaming cache item "WitsOneDrive:/Elixir-Archive\\2022.02.18-10.27" to be canonical "WitsOneDrive:Elixir-Archive/2022.02.18-10.27"
2022/02/18 10:27:10 DEBUG : strict.sty: Excluded
2022/02/18 10:27:13 DEBUG : One drive root 'Elixir/Ethics/ethics-www/_layouts': Waiting for checks to finish
2022/02/18 10:27:13 DEBUG : One drive root 'Elixir/Ethics/ethics-www/_layouts': Waiting for transfers to finish
2022/02/18 10:27:19 DEBUG : test.log: Starting multipart upload
2022/02/18 10:27:19 DEBUG : default.html: Starting multipart upload
2022/02/18 10:27:21 DEBUG : default.html: Uploading segment 0/2155 size 2155
2022/02/18 10:27:21 DEBUG : test.log: Uploading segment 0/1407 size 1407
2022/02/18 10:27:22 DEBUG : test.log: quickxor = 09c46f0cc87bbbb902f696b71d705afa7b68e6c6 OK
2022/02/18 10:27:22 INFO  : test.log: Copied (new)
2022/02/18 10:27:22 DEBUG : default.html: quickxor = 51d9a00ad3694d0b77284b2f9d4e21d0b7cdddbb OK
2022/02/18 10:27:22 INFO  : default.html: Copied (new)
2022/02/18 10:27:22 INFO  : 
Transferred:   	    3.479 KiB / 3.479 KiB, 100%, 393 B/s, ETA 0s
Transferred:            2 / 2, 100%
Elapsed time:        22.0s

2022/02/18 10:27:22 DEBUG : 8 go routines active

The destination now looks like this:

Running the same rclone copy command again:

2022/02/18 10:30:46 DEBUG : --min-age 1h0m0s to 2022-02-18 09:30:46.5675822 +0200 SAST m=-3599.926963699
2022/02/18 10:30:46 DEBUG : --max-age 2w to 2022-02-04 10:30:46.5675822 +0200 SAST m=-1209599.926963699
2022/02/18 10:30:46 DEBUG : rclone: Version "v1.57.0" starting with parameters ["c:\\Program Files\\rclone/\\rclone" "copy" "c:/Data/WitsEIE/Ethics/ethics-www/_layouts/" "WitsOneDrive:/Elixir/Ethics/ethics-www/_layouts/" "--max-age" "14d" "--min-age" "60m" "--no-traverse" "--drive-chunk-size" "64M" "--checkers" "7" "--retries" "1" "--stats" "10m" "--backup-dir=WitsOneDrive:/Elixir-Archive\\2022.02.18-10.30" "--log-file=c:\\Data\\Config\\Scripts\\rclone-logs\\2022.02.18-10.30-rclone-copy-bug.log" "--log-level=DEBUG"]
2022/02/18 10:30:46 DEBUG : Creating backend with remote "c:/Data/WitsEIE/Ethics/ethics-www/_layouts/"
2022/02/18 10:30:46 DEBUG : Using config file from "C:\\Users\\Steve\\AppData\\Roaming\\rclone\\rclone.conf"
2022/02/18 10:30:46 DEBUG : fs cache: renaming cache item "c:/Data/WitsEIE/Ethics/ethics-www/_layouts/" to be canonical "//?/c:/Data/WitsEIE/Ethics/ethics-www/_layouts/"
2022/02/18 10:30:46 DEBUG : Creating backend with remote "WitsOneDrive:/Elixir/Ethics/ethics-www/_layouts/"
2022/02/18 10:30:46 DEBUG : One drive root 'Elixir/Ethics/ethics-www/_layouts': Token expired but no uploads in progress - doing nothing
2022/02/18 10:30:46 DEBUG : WitsOneDrive: Loaded invalid token from config file - ignoring
2022/02/18 10:30:47 DEBUG : Saving config "token" in section "WitsOneDrive" of the config file
2022/02/18 10:30:47 DEBUG : Keeping previous permissions for config file: -rw-rw-rw-
2022/02/18 10:30:47 DEBUG : WitsOneDrive: Saved new token in config file
2022/02/18 10:30:52 DEBUG : fs cache: renaming cache item "WitsOneDrive:/Elixir/Ethics/ethics-www/_layouts/" to be canonical "WitsOneDrive:Elixir/Ethics/ethics-www/_layouts"
2022/02/18 10:30:52 DEBUG : Creating backend with remote "WitsOneDrive:/Elixir-Archive\\2022.02.18-10.30"
2022/02/18 10:30:58 DEBUG : fs cache: renaming cache item "WitsOneDrive:/Elixir-Archive\\2022.02.18-10.30" to be canonical "WitsOneDrive:Elixir-Archive/2022.02.18-10.30"
2022/02/18 10:30:58 DEBUG : strict.sty: Excluded
2022/02/18 10:31:01 DEBUG : One drive root 'Elixir/Ethics/ethics-www/_layouts': Waiting for checks to finish
2022/02/18 10:31:01 DEBUG : One drive root 'Elixir/Ethics/ethics-www/_layouts': Waiting for transfers to finish
2022/02/18 10:31:01 DEBUG : test.log: Starting multipart upload
2022/02/18 10:31:01 DEBUG : default.html: Starting multipart upload
2022/02/18 10:31:02 DEBUG : test.log: Uploading segment 0/1407 size 1407
2022/02/18 10:31:02 DEBUG : default.html: Uploading segment 0/2155 size 2155
2022/02/18 10:31:05 DEBUG : default.html: quickxor = 51d9a00ad3694d0b77284b2f9d4e21d0b7cdddbb OK
2022/02/18 10:31:05 INFO  : default.html: Copied (new)
2022/02/18 10:31:05 DEBUG : test.log: quickxor = 09c46f0cc87bbbb902f696b71d705afa7b68e6c6 OK
2022/02/18 10:31:05 INFO  : test.log: Copied (new)
2022/02/18 10:31:05 INFO  : 
Transferred:   	    3.479 KiB / 3.479 KiB, 100%, 894 B/s, ETA 0s
Transferred:            2 / 2, 100%
Elapsed time:        19.4s

2022/02/18 10:31:05 DEBUG : 13 go routines active

[ncw (Nick Craig-Wood)]

@Steve

2022/02/18 10:31:05 INFO  : default.html: Copied (new)
2022/02/18 10:31:05 INFO  : test.log: Copied (new)

The (new) means that rclone didn't see the file on the destination.

So if you do a list with the same parameters in the source and destination, which files do you see?

rclone lsl c:/Data/WitsEIE/Ethics/ethics-www/_layouts/ --max-age 14d --min-age 60m --no-traverse

rclone lsl WitsOneDrive:/Elixir/Ethics/ethics-www/_layouts/ --max-age 14d --min-age 60m --no-traverse

Can you also try without the --min-age flag.

Are the modification times on the uploaded files correct? As in do they match the source files?

[Steve]

Hi,

Thanks for responding!

Listing the files locally:

C:\Program Files\rclone>rclone lsl c:/Data/WitsEIE/Ethics/ethics-www/_layouts/ --max-age 14d --min-age 60m --no-traverse
     2155 2022-02-07 23:52:05.065475900 default.html
     1407 2022-02-07 23:52:12.289090000 test.log

Listing the files remotely:

C:\Program Files\rclone>rclone lsl WitsOneDrive:/Elixir/Ethics/ethics-www/_layouts/ --max-age 14d --min-age 60m --no-traverse
     2155 2022-02-07 23:52:05.000000000 default.html
     1407 2022-02-07 23:52:12.000000000 test.log

So there are sub-second differences in the timestamps. I'm assuming that is due to the time resolution of OneDrive.

@ncw

Can you also try without the --min-age flag.

The output is identical to that given above.

@ncw

Are the modification times on the uploaded files correct? As in do they match the source files?

As shown, there are sub-second differences.

[asdffdsa (jojothehumanmonkey)]

@Steve

I'm assuming that is due to the time resolution of OneDrive.

hi,
that is correct, as per the docs.
"OneDrive allows modification times to be set on objects accurate to 1 second"

check Precision, unit is nanosecond

rclone backend features onedrivevb:
{
        "Name": "onedrivevb",
        "Root": "",
        "String": "One drive root ''",
        "Precision": 1000000000,

[ncw (Nick Craig-Wood)]

Try your copy without --no-traverse that might be the difference.

Also try it without the min age.

[Steve]

Thanks for confirming.

[Steve]

@ncw

Try your copy without --no-traverse that might be the difference.

Okay, this works as expected! Here's the output with the --no-traverse flag removed:

2022/02/18 17:20:54 DEBUG : One drive root 'Elixir/Ethics/ethics-www/_layouts': Waiting for checks to finish
2022/02/18 17:20:54 DEBUG : default.html: Size and modification time the same (differ by -65.4759ms, within tolerance 1s)
2022/02/18 17:20:54 DEBUG : default.html: Unchanged skipping
2022/02/18 17:20:54 DEBUG : test.log: Size and modification time the same (differ by -289.09ms, within tolerance 1s)
2022/02/18 17:20:54 DEBUG : test.log: Unchanged skipping
2022/02/18 17:20:54 DEBUG : One drive root 'Elixir/Ethics/ethics-www/_layouts': Waiting for transfers to finish
2022/02/18 17:20:54 INFO  : There was nothing to transfer

Does this point to a bug when using --no-traverse?

@ncw

Also try it without the min age.

I tried that - there is no difference in the output when using the --no-traverse flag.

[Steve]

In addition to the fact that we have seen that this problem only occurs when the --no-traverse flag is used, I have done further testing and I think it is related to the directory path.

I copied the same two files test.log and default.html to a different directory. So now there are identical copies of each file with the same modification date and time. The pair of files in the _layouts directory is repeatedly copied on every run. The pair of files in the other directory (test-dir) is only copied on the first run. See the following logs.

2022/02/18 16:45:25 INFO  : WitsEIE/Ethics/ethics-www/_layouts/test.log: Copied (new)
2022/02/18 16:45:25 INFO  : WitsEIE/Ethics/ethics-www/_layouts/default.html: Copied (new)
2022/02/18 16:45:34 INFO  : Downloads/test-dir/test.log: Copied (new)
2022/02/18 16:45:52 INFO  : Downloads/test-dir/default.html: Copied (new)

In the _layout directory the files are copied erroneously as they already exist in the destination. The same files are copied correctly in the test-dir directory because they do not yet exist in the destination.

The log of the subsequent run is as follows:

2022/02/18 16:48:59 INFO  : WitsEIE/Ethics/ethics-www/_layouts/test.log: Copied (new)
2022/02/18 16:48:59 INFO  : WitsEIE/Ethics/ethics-www/_layouts/default.html: Copied (new)

The files in the layouts directory are erroneously copied. The files in the test-dir directory are not copied as they already exist at this destination. This seems to imply that there is an issue with the path as the files are identical.

[ncw (Nick Craig-Wood)]

It seems like we are getting somewhere!

I managed to reproduce this problem locally with onedrive business - it did not reproduce with onedrive personal.

cd /tmp
mkdir onedrive-issue
mkdir onedrive-issue/_layouts
echo hello > onedrive-issue/_layouts/test.log
echo hellohello > onedrive-issue/_layouts/default.html
rclone copy -vv --no-traverse  onedrive-issue onedrive:onedrive-issue
rclone copy -vv --no-traverse  onedrive-issue onedrive:onedrive-issue

This is making me think this is a bug in Onedrive Business (It wouln't be the first issue I've found with rclone!)

With --no-traverse rclone will check for the presense of each file individually, rather than listing the directory.

The call it uses is this

2022/02/21 11:54:37 DEBUG : HTTP REQUEST (req 0xc000736100)
2022/02/21 11:54:37 DEBUG : GET /v1.0/drives/b!tPczmrJTCE2ShO96VLAAn_DGv2_4eZJGl83N0OQe_t9LuHcGPileQ7YByS0_6_xp/root:/onedrive-issue/_layouts/default.html HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.58.0-beta.6000.04177102c.fix-5984-vfs-rename-open
Authorization: XXXX
Accept-Encoding: gzip

And the response from onedrive business is 404 not found

2022/02/21 11:54:38 DEBUG : HTTP RESPONSE (req 0xc000736100)
2022/02/21 11:54:38 DEBUG : HTTP/1.1 404 Not Found
Transfer-Encoding: chunked
Client-Request-Id: ca107748-f71a-4f2c-a492-76ce4057406a
Content-Type: application/json
Date: Mon, 21 Feb 2022 11:54:37 GMT
Request-Id: ca107748-f71a-4f2c-a492-76ce4057406a
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"UK South","Slice":"E","Ring":"3","ScaleUnit":"001","RoleInstance":"LN2PEPF00006112"}}

c9
{"error":{"code":"UnknownError","message":"","innerError":{"date":"2022-02-21T11:54:38","request-id":"ca107748-f71a-4f2c-a492-76ce4057406a","client-request-id":"ca107748-f71a-4f2c-a492-76ce4057406a"}}}
0

Whereas that same call on onedrive personal

2022/02/21 11:56:54 DEBUG : GET /v1.0/drives/71a96798e7b1d253/items/71A96798E7B1D253!724912:/_layouts/default.html: HTTP/1.1
Host: graph.microsoft.com
User-Agent: rclone/v1.58.0-beta.6000.04177102c.fix-5984-vfs-rename-open
Authorization: XXXX
Accept-Encoding: gzip

Works fine

2022/02/21 11:56:54 DEBUG : HTTP RESPONSE (req 0xc0008b6900)
2022/02/21 11:56:54 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Cache-Control: no-store
Client-Request-Id: 0ac91adf-3ae0-46c8-bcf9-b9274f41d3a7
Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
Date: Mon, 21 Feb 2022 11:56:54 GMT
Odata-Version: 4.0
Request-Id: 0ac91adf-3ae0-46c8-bcf9-b9274f41d3a7
Strict-Transport-Security: max-age=31536000
Vary: Accept-Encoding
X-Ms-Ags-Diagnostic: {"ServerInfo":{"DataCenter":"UK South","Slice":"E","Ring":"3","ScaleUnit":"002","RoleInstance":"LO1PEPF0000060D"}}

626
{"@odata.context":"https://graph.microsoft.com/v1.0/$metadata#drives('71a96798e7b1d253')/items/$entity","@microsoft.graph.downloadUrl":"https://public.am.files.1drv.com/y4m1eSC4--7KzWdY03mSCFiRhPygmE6-37Q_OU96B-C9HyHieiA9HZ33ajgXn-HDRgfttQ-abJhbpLC9K08P5xcriawxX4H-Ruyu1Xa9XN5k-Qm7U6co8ipx9oshiJQlaNM2LC5Qa7z-ot0ySQ9NjJrcEg7BFI_7I7sgKQDjZD060i0lN18t0daLb3Gm88PyQ8uHepnanEhPGKeosLIeHcQ0kkZEyA2tjVVBsWrHJigPW-xI6t3ZwGE_D-AxGp68CNqT5lNQ3ioc1oiisO-1B4EVk92lPCpXID3F-V5yuSLeDI","createdDateTime":"2022-02-21T11:45:20.927Z","cTag":"aYzo3MUE5Njc5OEU3QjFEMjUzITcyNDkxNS4yNTc","eTag":"aNzFBOTY3OThFN0IxRDI1MyE3MjQ5MTUuMQ","id":"71A96798E7B1D253!724915","lastModifiedDateTime":"2022-02-21T11:45:21.053Z","name":"default.html","size":11,"webUrl":"https://1drv.ms/u/s!AFPSseeYZ6lxrJ8z","reactions":{"commentCount":0},"createdBy":{"application":{"displayName":"rclone","id":"48211038"},"user":{"displayName":"Nick Craig-Wood","id":"71a96798e7b1d253"}},"lastModifiedBy":{"application":{"displayName":"rclone","id":"48211038"},"user":{"displayName":"Nick Craig-Wood","id":"71a96798e7b1d253"}},"parentReference":{"driveId":"71a96798e7b1d253","driveType":"personal","id":"71A96798E7B1D253!724913","name":"_layouts","path":"/drive/root:/onedrive-issue/_layouts"},"file":{"mimeType":"text/html","hashes":{"quickXorHash":"aCgDG9jwBjSUgQ1sc4MCAAAAAAA=","sha1Hash":"60E4CC679A5C273DF21513400CCC98DCF88F3DF1","sha256Hash":"0B9127C34F568B0C41DFA8CE74215BF3E4B66DDD6211563E1F3E0CE2F9AD8194"}},"fileSystemInfo":{"createdDateTime":"2022-02-21T11:45:15Z","lastModifiedDateTime":"2022-02-21T11:45:15Z"}}
0

In the microsoft docs _ is specifically declared a URL save character for the onedrive API

Address resources in a drive on OneDrive - Microsoft Graph

So I think this is a bug on Onedrive Business.

I reported it to Microsoft here: GET on existing file in Onedrive Business fails if directory starts with underscore · Issue #1568 · OneDrive/onedrive-api-docs · GitHub - please subscribe to that issue for updates.

[Steve]

Thanks so much for your detailed investigation and for taking the time to report the bug to Microsoft, given that this isn't actually an rclone issue.

Hopefully, Microsoft will address it.

[ncw (Nick Craig-Wood)]

Microsoft have addressed a number of bugs I've reported like that in the past, so I'm hopeful they'll fix it soon!

[ncw (Nick Craig-Wood)]

There has been a bit of movement on the issue. As part of that I found that it is only directories called _layouts which are affected - other directories starting with _ seem to be OK.