Sync deleting a file it just copied to the local filesystem?

Help and Support
1

Hello!

I noticed a lot of seemingly random deletes at the end of a long sync job from Google Drive down to my local filesystem. Is this intended? A bug? I’m not clear what’s actually happening.

I can reproduce for a specific folder: rclone copies 2 files, and then immediately deletes 1 while it still exists on the source remote (Google Drive). It does this for different files although consistently the same ones.

I tried rclone dedupe pointing at the remote and it didn’t list those files.

I’m using the October 1st beta of 1.38: rclone-v1.38-010-ga1d942e5β-linux-amd64

Sync command I used:

rclone sync gd:Timelapse/2016-11/ /backup_usb/Timelapse/2016-11/ --drive-skip-gdocs --ignore-existing --log-level INFO --log-file /root/sync.log --exclude "/secret/**" --tpslimit 1

Output of sync command (ran twice in case of transient issue):

2017/10/01 21:47:06 INFO  : Starting HTTP transaction limiter: max 1 transactions/s with burst 1
2017/10/01 21:47:09 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Modify window is 1ms
2017/10/01 21:47:12 NOTICE: timelapse_2016-11-10-09-02-48.mkv: Duplicate object found in source - ignoring
2017/10/01 21:47:12 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for checks to finish
2017/10/01 21:47:12 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for transfers to finish
2017/10/01 21:47:18 INFO  : timelapse_2016-11-10-10-12-04.mkv: Copied (new)
2017/10/01 21:47:19 INFO  : timelapse_2016-11-10-09-37-27.mkv: Copied (new)
2017/10/01 21:47:19 INFO  : Waiting for deletions to finish
2017/10/01 21:47:19 INFO  : timelapse_2016-11-10-09-37-27.mkv: Deleted
2017/10/01 21:47:19 INFO  :
Transferred:   63.282 MBytes (4.685 MBytes/s)
Errors:                 0
Checks:              1114
Transferred:            2
Elapsed time:       13.5s

Second run:

2017/10/01 21:47:50 INFO  : Starting HTTP transaction limiter: max 1 transactions/s with burst 1
2017/10/01 21:47:53 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Modify window is 1ms
2017/10/01 21:47:57 NOTICE: timelapse_2016-11-10-09-02-48.mkv: Duplicate object found in source - ignoring
2017/10/01 21:47:57 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for checks to finish
2017/10/01 21:47:57 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for transfers to finish
2017/10/01 21:48:02 INFO  : timelapse_2016-11-10-09-37-27.mkv: Copied (new)
2017/10/01 21:48:04 INFO  : timelapse_2016-11-10-10-12-04.mkv: Copied (new)
2017/10/01 21:48:04 INFO  : Waiting for deletions to finish
2017/10/01 21:48:04 INFO  : timelapse_2016-11-10-10-12-04.mkv: Deleted
2017/10/01 21:48:04 INFO  :
Transferred:   63.282 MBytes (4.647 MBytes/s)
Errors:                 0
Checks:              1114
Transferred:            2
Elapsed time:       13.6s

Here’s the dedupe output run against the original Google Drive remote where the deleted files aren’t shown as duplicates (shouldn’t there be 2 filenames shown as it says “Found 2 duplicates” ?):

rclone -vv dedupe gd:Timelapse/2016-11/ --dry-run

2017/10/01 21:51:20 DEBUG : Using config file from "/root/.rclone.conf"
2017/10/01 21:51:20 DEBUG : rclone: Version "v1.38-010-ga1d942e5β" starting with parameters ["./rclone" "-vv" "dedupe" "gd:Timelapse/2016-11/" "--dry-run"]
2017/10/01 21:51:21 INFO  : Google drive root 'Timelapse/2016-11': Modify window is 1ms
2017/10/01 21:51:21 INFO  : Google drive root 'Timelapse/2016-11': Looking for duplicates using interactive mode.
2017/10/01 21:51:26 NOTICE: timelapse_2016-11-10-09-02-48.mkv: Found 2 duplicates - deleting identical copies
2017/10/01 21:51:26 NOTICE: timelapse_2016-11-10-09-02-48.mkv: Deleting 1/2 identical duplicates (md5sum "3cd6ef7026d3de2c24e05a2d0035155c")
2017/10/01 21:51:26 NOTICE: timelapse_2016-11-10-09-02-48.mkv: Not deleting as --dry-run
2017/10/01 21:51:26 NOTICE: timelapse_2016-11-10-09-02-48.mkv: All duplicates removed
2017/10/01 21:51:26 DEBUG : Go routines at exit 4
2017/10/01 21:51:26 DEBUG : rclone: Version "v1.38-010-ga1d942e5β" finishing with parameters ["./rclone" "-vv" "dedupe" "gd:Timelapse/2016-11/" "--dry-run"]
2

The symptoms look like duplicate files on Drive.

The dedupe run is odd though, not showing that particular file. There could be duplicate directories which are confusing things though.

Can you run an rclone dedupe gd:Timelapse and fix all the problems, then try the sync again?

3

Thanks for the reply @ncw.

I ran dedupe on the whole Timelapse path and it only found that 1 duplicate mentioned above. It deleted it automatically and exited without any other dupes.

I ran sync again 3 times (to be certain). The first time it copied 1 file, the 2nd and 3rd times it copied nothing. None of the 3 runs deleted any files. Weird given the seemingly unrelated dedupe actions, right?

Log output below, with rclone size as well for reference.

root@backup-vm:~/rclone-v1.38-010-ga1d942e5β-linux-amd64# ./rclone size gd:Timelapse

Total objects: 7870
Total size: 208.558 GBytes (223937329965 Bytes)

root@backup-vm:~/rclone-v1.38-010-ga1d942e5β-linux-amd64# ./rclone dedupe -vvvv --tpslimit 1 gd:Timelapse

2017/10/02 09:21:53 DEBUG : Using config file from "/root/.rclone.conf"
2017/10/02 09:21:53 INFO  : Starting HTTP transaction limiter: max 1 transactions/s with burst 1
2017/10/02 09:21:53 DEBUG : rclone: Version "v1.38-010-ga1d942e5β" starting with parameters ["./rclone" "dedupe" "-vvvv" "--tpslimit" "1" "gd:Timelapse"]
2017/10/02 09:21:55 INFO  : Google drive root 'Timelapse': Modify window is 1ms
2017/10/02 09:21:55 INFO  : Google drive root 'Timelapse': Looking for duplicates using interactive mode.
2017/10/02 09:22:29 NOTICE: 2016-11/timelapse_2016-11-10-09-02-48.mkv: Found 2 duplicates - deleting identical copies
2017/10/02 09:22:29 NOTICE: 2016-11/timelapse_2016-11-10-09-02-48.mkv: Deleting 1/2 identical duplicates (md5sum "3cd6ef7026d3de2c24e05a2d0035155c")
2017/10/02 09:22:31 INFO  : 2016-11/timelapse_2016-11-10-09-02-48.mkv: Deleted
2017/10/02 09:22:31 NOTICE: 2016-11/timelapse_2016-11-10-09-02-48.mkv: All duplicates removed
2017/10/02 09:22:31 DEBUG : Go routines at exit 8
2017/10/02 09:22:31 DEBUG : rclone: Version "v1.38-010-ga1d942e5β" finishing with parameters ["./rclone" "dedupe" "-vvvv" "--tpslimit" "1" "gd:Timelapse"]

root@backup-vm:~/rclone-v1.38-010-ga1d942e5β-linux-amd64# ./rclone sync gd:Timelapse/2016-11/ /backup_usb/Timelapse/2016-11/ --drive-skip-gdocs --ignore-existing --log-level INFO --log-file /root/sync.log --exclude "/secret/**" --tpslimit 1

2017/10/02 09:23:28 INFO  : Starting HTTP transaction limiter: max 1 transactions/s with burst 1
2017/10/02 09:23:31 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Modify window is 1ms
2017/10/02 09:23:34 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for checks to finish
2017/10/02 09:23:34 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for transfers to finish
2017/10/02 09:23:38 INFO  : timelapse_2016-11-10-10-12-04.mkv: Copied (new)
2017/10/02 09:23:38 INFO  : Waiting for deletions to finish
2017/10/02 09:23:38 INFO  :
Transferred:   34.531 MBytes (3.233 MBytes/s)
Errors:                 0
Checks:              1114
Transferred:            1
Elapsed time:       10.6s

root@backup-vm:~/rclone-v1.38-010-ga1d942e5β-linux-amd64# ./rclone sync gd:Timelapse/2016-11/ /backup_usb/Timelapse/2016-11/ --drive-skip-gdocs --ignore-existing --log-level INFO --log-file /root/sync.log --exclude "/secret/**" --tpslimit 1

2017/10/02 09:23:58 INFO  : Starting HTTP transaction limiter: max 1 transactions/s with burst 1
2017/10/02 09:24:02 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Modify window is 1ms
2017/10/02 09:24:05 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for checks to finish
2017/10/02 09:24:05 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for transfers to finish
2017/10/02 09:24:05 INFO  : Waiting for deletions to finish
2017/10/02 09:24:05 INFO  :
Transferred:      0 Bytes (0 Bytes/s)
Errors:                 0
Checks:              1115
Transferred:            0
Elapsed time:        6.2s

root@backup-vm:~/rclone-v1.38-010-ga1d942e5β-linux-amd64# ./rclone sync gd:Timelapse/2016-11/ /backup_usb/Timelapse/2016-11/ --drive-skip-gdocs --ignore-existing --log-level INFO --log-file /root/sync.log --exclude "/secret/**" --tpslimit 1

2017/10/02 09:24:52 INFO  : Starting HTTP transaction limiter: max 1 transactions/s with burst 1
2017/10/02 09:24:55 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Modify window is 1ms
2017/10/02 09:25:00 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for checks to finish
2017/10/02 09:25:00 INFO  : Local file system at /backup_usb/Timelapse/2016-11: Waiting for transfers to finish
2017/10/02 09:25:00 INFO  : Waiting for deletions to finish
2017/10/02 09:25:00 INFO  :
Transferred:      0 Bytes (0 Bytes/s)
Errors:                 0
Checks:              1115
Transferred:            0
Elapsed time:        7.9s
4

So would you say it is fixed now?

Yes. It as if the duplicated file at the start somehow put things out of sync. This of course should’t be possible so I wonder if there is a bug somewhere…

Can you send me a listing rclone ls gd:Timelapse/2016-11 so I can try making an equivalent directory and see if I can replicate the problem. I have tried but I haven’t succeeded yet!

5

Yes that is definitely a bug, I’ve managed to reproduce it :frowning:

Now to work out what is causing it!

6

This is now fixed. It turned out to be a corner case that somehow I didn’t have a unit test for!

I’ve added the unit test now and all seems to be well

Thanks for taking the time to think “that’s weird” - all the best bug reports start like that :slight_smile:

I realise now this bug has been grumbling on for ages so I’ll have to go back through the issues and reply to them all.

Find a new binary here

https://beta.rclone.org/v1.38-012-g00fe6d95/ (uploaded in 15-30 mins)

7

Happy to help! Trying out the new build now and will keep an eye for anything else weird. :smiley:

1 Like