Rclone sync dry run failing on size

Suspected Bug
1

What is the problem you are having with rclone?

I had files on a shared gdrive that I moved to my persona gdrive. both used the same crypt options. I moved the files using google's web ui from the shared gdrive to an unused path (so it wouldn't hide anything) in my local space.

I then tried to sync from my local store to the personal gdrive remote, and it fails a number of files because of size mismatch.

Howver, when I look at the files, everything seems fine.

Example: from log

2021-05-15 21:17:33 NOTICE: /S04/S04E26.mp4: Skipped copy as --dry-run is set (size 247.329M)

on local system

$ ls -l S04/S04E26.mp4
-rw-rw-r-- 1 spotter spotter 259343484 May 12 15:22 S04/S04E26.mp4

looking at it via rclone mount

$ ls -l S04/S04E26.mp4
-rw-r--r-- 1 spotter spotter 259343484 May 13 19:21 S04/S04E26.mp4

What is your rclone version (output from rclone version)

rclone v1.55.1

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

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

ubuntu 20.04

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

google drive

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

rclone sync -n -P --create-empty-src-dirs . gdrive:/ToSort/1 --drive-stop-on-upload-limit --transfers 30 --order-by size,mixed

The rclone config contents with secrets removed.

Paste config here

A log from the command with the -vv flag

Paste  log here
2

can you post the debug log.

3

so just tried with -vv, it doesn't seem to actually anything with -n -P which I already used.

as an example, this is grepping out all the DEBUG lines

rclone sync -vv -n -P --create-empty-src-dirs . gdrive:/ToSort/1 --drive-stop-on-upload-limit --transfers 30 --order-by size,mixed |grep DEBUG
2021/05/15 22:00:49 DEBUG : Using config file from "/home/spotter/.config/rclone/rclone.conf"
2021/05/15 22:00:49 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "sync" "-vv" "-n" "-P" "--create-empty-src-dirs" "." "gdrive:/ToSort/1" "--drive-stop-on-upload-limit" "--transfers" "30" "--order-by" "size,mixed"]
2021/05/15 22:00:49 DEBUG : Creating backend with remote "."
2021/05/15 22:00:49 DEBUG : fs cache: renaming cache item "." to be canonical "/data/To/Move/0"
2021/05/15 22:00:49 DEBUG : Creating backend with remote "gdrive:/ToSort/1"
2021/05/15 22:00:49 DEBUG : gdrive: detected overridden config - adding "{+LSY5}" suffix to name
2021/05/15 22:00:49 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2021/05/15 22:00:49 DEBUG : pacer: Rate limited, increasing sleep to 1.240429241s
2021/05/15 22:00:50 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2021/05/15 22:00:50 DEBUG : pacer: Rate limited, increasing sleep to 2.951997992s
2021/05/15 22:00:51 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2021/05/15 22:00:51 DEBUG : pacer: Rate limited, increasing sleep to 4.210958917s
2021/05/15 22:00:54 DEBUG : pacer: Reducing sleep to 0s
2021/05/15 22:00:58 DEBUG : fs cache: renaming cache item "gdrive:/ToSort/1" to be canonical "gdrive{+LSY5}:ToSort/1"
2021-05-15 22:00:58 DEBUG : Google drive root 'ToSort/1': Waiting for checks to finish
2021-05-15 22:00:58 DEBUG : Google drive root 'ToSort/1': Waiting for transfers to finish
2021-05-15 22:01:00 DEBUG : Waiting for deletions to finish

with grep NOTICE | grep -v size, no skip lines are printed (i.e. they are all about size calculations)

4

If you pick the one file that was going to be copied and re-run that copy with debug and no dry-run, it'll tell you specifically why it was being copied.

5

A quick guess:

I assume you mean that the sync dry run says a file will transferred, despite the files having same size. The sync command also checks for the modification time of the files, and they are different.

6

I showed that above, this (and many others) is the line that is printed. its a size mismatch, but as far as I can tell the size is correct.

7

the ls -l I show are different, yes. but if its wanting to sync because of date, it should say that, not size I'd think? i.e. it should print out why its choosing it's sync operation ("copying as destination size, date ... is different, deleting as no longer exists on source....) it doesn't give me that info

8

The sync command generally just inform that a file is transferred, not why.

I do understand, that the size added to the dry-run skip message may give you the impression that it was due to size, but in that case I would have expected two sizes.

What information do your get about the reason, if grepping for all debug lines about the file?

9

it doesn't show any, I grepped them all out above. there's no info in them.

10

Ahh OK, sorry I missed that.

Did you try this:

11

oh, I see "no dry run", I wasn't able to do that, as was over quota, so wouldn't have helped me directly. I realy do think the decision to copy/delete should always be printed and dry run just sort circuit the action. The fact that we dont know why its happening with dry run is a bug (IMO).

12

It is in the log.

felix@gemini:~$ rclone copy /etc/hosts GD: -vv --dry-run
2021/05/16 06:41:04 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2021/05/16 06:41:04 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "copy" "/etc/hosts" "GD:" "-vv" "--dry-run"]
2021/05/16 06:41:04 DEBUG : Creating backend with remote "/etc/hosts"
2021/05/16 06:41:04 DEBUG : fs cache: adding new entry for parent of "/etc/hosts", "/etc"
2021/05/16 06:41:04 DEBUG : Creating backend with remote "GD:"
2021/05/16 06:41:04 DEBUG : hosts: Sizes differ (src 130 vs dst 129)
2021/05/16 06:41:04 NOTICE: hosts: Skipped copy as --dry-run is set (size 130)
2021/05/16 06:41:04 NOTICE:
Transferred:   	       130 / 130 Bytes, 100%, 5.714 MBytes/s, ETA 0s
Transferred:            1 / 1, 100%
Elapsed time:         0.3s

2021/05/16 06:41:04 DEBUG : 4 go routines active

In my example, the file sizes are different.

The one copy command just makes it easier to check for one file rather than redoing the sync, which is why I asked.

13

that doesn't happen for me on sync, again here's grep'ing out all the DEBUG lines (i.e. yours that show the reason)

spotter@yucs:/data/To/Move/0$ rclone sync -vv -n -P --create-empty-src-dirs . gdrive:/ToSort/1 --drive-stop-on-upload-limit --transfers 30 --order-by size,mixed |grep DEBUG
2021/05/15 22:00:49 DEBUG : Using config file from "/home/spotter/.config/rclone/rclone.conf"
2021/05/15 22:00:49 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "sync" "-vv" "-n" "-P" "--create-empty-src-dirs" "." "gdrive:/ToSort/1" "--drive-stop-on-upload-limit" "--transfers" "30" "--order-by" "size,mixed"]
2021/05/15 22:00:49 DEBUG : Creating backend with remote "."
2021/05/15 22:00:49 DEBUG : fs cache: renaming cache item "." to be canonical "/data/To/Move/0"
2021/05/15 22:00:49 DEBUG : Creating backend with remote "gdrive:/ToSort/1"
2021/05/15 22:00:49 DEBUG : gdrive: detected overridden config - adding "{+LSY5}" suffix to name
2021/05/15 22:00:49 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2021/05/15 22:00:49 DEBUG : pacer: Rate limited, increasing sleep to 1.240429241s
2021/05/15 22:00:50 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2021/05/15 22:00:50 DEBUG : pacer: Rate limited, increasing sleep to 2.951997992s
2021/05/15 22:00:51 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2021/05/15 22:00:51 DEBUG : pacer: Rate limited, increasing sleep to 4.210958917s
2021/05/15 22:00:54 DEBUG : pacer: Reducing sleep to 0s
2021/05/15 22:00:58 DEBUG : fs cache: renaming cache item "gdrive:/ToSort/1" to be canonical "gdrive{+LSY5}:ToSort/1"
2021-05-15 22:00:58 DEBUG : Google drive root 'ToSort/1': Waiting for checks to finish
2021-05-15 22:00:58 DEBUG : Google drive root 'ToSort/1': Waiting for transfers to finish
2021-05-15 22:01:00 DEBUG : Waiting for deletions to finish
2021/05/15 22:01:00 NOTICE: 
Transferred:   	    2.961T / 2.961 TBytes, 100%, 2.176 TBytes/s, ETA 0s
Transferred:          708 / 708, 100%
Elapsed time:        10.6s

I'm wondering if the last notice printed out stderr and hence why it appeared in my output?

14

It's in both the output and in a log file.

You'd want to include the full logs.

felix@gemini:~/test$ rclone sync -vv /home/felix/test GD:test --dry-run
2021/05/16 07:09:25 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2021/05/16 07:09:25 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "sync" "-vv" "/home/felix/test" "GD:test" "--dry-run"]
2021/05/16 07:09:25 DEBUG : Creating backend with remote "/home/felix/test"
2021/05/16 07:09:25 DEBUG : Creating backend with remote "GD:test"
2021/05/16 07:09:26 DEBUG : Google drive root 'test': Waiting for checks to finish
2021/05/16 07:09:26 DEBUG : hosts: Sizes differ (src 130 vs dst 129)
2021/05/16 07:09:26 DEBUG : Google drive root 'test': Waiting for transfers to finish
2021/05/16 07:09:26 NOTICE: hosts: Skipped copy as --dry-run is set (size 130)
2021/05/16 07:09:26 DEBUG : Waiting for deletions to finish
2021/05/16 07:09:26 NOTICE:
Transferred:   	       130 / 130 Bytes, 100%, 335.941 kBytes/s, ETA 0s
Checks:                 1 / 1, 100%
Transferred:            1 / 1, 100%
Elapsed time:         0.7s

2021/05/16 07:09:26 DEBUG : 4 go routines active
felix@gemini:~/test$ rclone sync -vv /home/felix/test GD:test --dry-run --log-file test.log
felix@gemini:~/test$ cat test.log
2021/05/16 07:09:49 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2021/05/16 07:09:49 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "sync" "-vv" "/home/felix/test" "GD:test" "--dry-run" "--log-file" "test.log"]
2021/05/16 07:09:49 DEBUG : Creating backend with remote "/home/felix/test"
2021/05/16 07:09:49 DEBUG : Creating backend with remote "GD:test"
2021/05/16 07:09:50 NOTICE: test.log: Skipped copy as --dry-run is set (size 388)
2021/05/16 07:09:50 DEBUG : Google drive root 'test': Waiting for checks to finish
2021/05/16 07:09:50 DEBUG : hosts: Sizes differ (src 130 vs dst 129)
2021/05/16 07:09:50 NOTICE: hosts: Skipped copy as --dry-run is set (size 130)
2021/05/16 07:09:50 DEBUG : Google drive root 'test': Waiting for transfers to finish
2021/05/16 07:09:50 DEBUG : Waiting for deletions to finish
2021/05/16 07:09:50 NOTICE:
Transferred:   	       518 / 518 Bytes, 100%, 1.416 MBytes/s, ETA 0s
Checks:                 1 / 1, 100%
Transferred:            2 / 2, 100%
Elapsed time:         0.5s

2021/05/16 07:09:50 DEBUG : 4 go routines active
felix@gemini:~/test$
15

I'm not logging to file, are you saying that if one doesn't log to file, less is printed to screen than would go to file?

16

I shared both examples as all the output was in both.

17

so I have no idea why it didn't show for me.

18

Run the command and log to a file and share the full file...

19

while it was repeatable before on that set of data, I haven't been able to repeat it since. I'll try to get better logs if it happens again

20

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.