Rclone sync bug: files are being erroneously erased/moved on the remote, causing subsequent rclone syncs to copy them over and over again (Was: Repeated "rclone sync" commands from a read-only local FS copying the same files over and over again?!)

Here is a beta which will log duplicate files in the sync - it would be interesting if you could use that instead.

https://beta.rclone.org/v1.36-231-g575e779b/ (uploaded in 15-30 mins)

I’m repeatedly trying with the new beta and am almost convinced that turning on the additional logging data prevents the problem from occurring (or it’s not getting logged in a way I can read). After multiple attempts (live and dry run) generating big logs but no obvious errors I decided on a whim to try a dry run without the additional logging and I’m again seeing files rclone claims it isn’t copying only because it’s a dry run. It appears to really like to pick on British singers named “Ian” as this time it’s saying that “Ian Dury” (the entire directory?) is a duplicate while also saying it wants to re-copy all the Ian Hunter even though it doesn’t need to:
http://www.wywh.com/rclonelogs/Aspire-R1600-2017-06-30_14-37-03.txt

This is the output from rclone ls “hubicrypt:WD6TBNAS01/Squeezebox Music/NotDTS/Ian Hunter”:
http://www.wywh.com/rclonelogs/IanHunterDir.txt

And the ouptut from rclone ls “hubicrypt:WD6TBNAS01/Squeezebox Music/NotDTS/Ian Dury”:
http://www.wywh.com/rclonelogs/IanDuryDir.txt

Here’s the cleaned and gzipped log from a subsequent heavily-commented run which I don’t believe shows the problem:
http://www.wywh.com/rclonelogs/Aspire-R1600-2017-06-30_14-56-20_clean.txt.gzip

I’d say that the fact it said Squeezebox Music/NotDTS/Ian Dury: Duplicate file found in destination - ignoring is evidence that the directory listing from hubic was corrupt, or rclone corrupted it. What it looks like to me is that instead of getting “Ian Dury”, “Ian Hunter” in the listing, it somehow got “Ian Dury”, “Ian Dury” which a) explains the duplicate and b) explains why all of “Ian Hunter” was missing.

I couldn’t see anything wrong with the listings., however there was one problem in the verbose log

2017/06/30 15:05:47 NOTICE: Squeezebox Music/NotDTS/Randy Newman/everyone_youve_ever_heard_of_19780211/Folder.jpg: Not copying as --dry-run

I thought that would be the key to crack it, but I forgot the directory listings were encrypted! So if you could run

rclone ls "hubicrypt:WD6TBNAS01/Squeezebox Music/NotDTS/Randy Newman/everyone_youve_ever_heard_of_19780211/Folder.jpg" --crypt-show-mapping

And tell me what filename on Hubic “hubicrypt:WD6TBNAS01/Squeezebox Music/NotDTS/Randy Newman/everyone_youve_ever_heard_of_19780211/Folder.jpg” maps to, then we can have a look in the verbose logs and see whether it is in the listing from hubic or not. If it is in the listing then it is probably an rclone problem, if not then it is a hubic problem.

I note that the last experiment used --fast-list which may or may not be more likely to show the problem.

I may have made things more confusing than they need to be. In the case of Folder.jpg for Randy Newman, I had arbitrarily picked that file to “sacrifice” in order to give rclone something to either upload or, in the case of a dry run, believe it needed to upload. I was trying to see if the outcome was different for runs that did or did not need to copy files.

As it stands at the moment, Folder.jpg is still not in that particular directory because I never did a live copy. But I will right now.

Just did a live backup that needed to copy the Randy Newman Folder.jpg. I don’t see anything unusual in the verbose log, which is at http://www.wywh.com/rclonelogs/Clean2.txt.gzip

However, I immediately did another live backup, this time non-verbose, and it appears to have copied several Ian Hunter files, even though the prior log didn’t show them as moved (that I saw) or missing or whatever. The log from that run is at http://www.wywh.com/rclonelogs/Aspire-R1600-2017-07-01_09-43-06.txt

I’ve also included the crypt mapping output for all the Ian Hunter files at http://www.wywh.com/rclonelogs/IanHunterCrypt.txt

This morning’s cron-scheduled dry run is reporting a combination of files that legitimately need to be uploaded (the Godfathers and Traffic) as well as Ian Hunter and now the Squirrels files that haven’t changed locally:
http://www.wywh.com/rclonelogs/Aspire-R1600-2017-07-02_06-02-33.txt

@atrocity I’ve had a look through your logs, unfortunately none of them have quite got what I need :frowning:

What I need is a run done with -vv --dump-bodies but without --fast-list. I don’t mind whether it is --dry-run or not. And if it does show a problem then I need the crypt mappings for the directory it declares as duplicate.

That will let me nail down whether this is an rclone or a hubic problem.

http://www.wywh.com/rclonelogs/Clean3.gz is a log for a dry run with the requested parameters. It shows that it wants to copy the Ian Hunter files again, so I’ve placed the Ian Hunter crypt mappings at http://www.wywh.com/rclonelogs/crypt.txt.

Just in case it helps, http://www.wywh.com/rclonelogs/localdir.txt has the results of ls -LRla “/mnt/WD6TBNAS01/Squeezebox Music/NotDTS/Ian Hunter”, mainly just to show that these really are old files that shouldn’t need re-uploading.

Thank you again!

@atrocity that is very useful thank you! Can you send me the crypt mappings for Squeezebox Music/NotDTS/Ian Dury as well please, then I think I will have enough information to track down what is happening :slight_smile:

that is very useful thank you! Can you send me the crypt mappings for Squeezebox Music/NotDTS/Ian Dury as well please, then I think I will have enough information to track down what is happening

I don’t know if it’s related, but several attempts to get this only returned:
Failed to create file system for
“hubicrypt:WD6TBNAS01/Squeezebox Music/NotDTS/Ian Dury”: failed to make remote
“hubic:default/Encrypted/dpu944o9e4q6khe1id5qe7g5hs/fs21bfj0b66sclla3eldm8amsmnlj
jsdv5km07a1uoaoop0llrvkg/9gchvbsi6baf2onkba2ijn5d38/rt8r5pnucq6qnon0kvj67cktfo”
to wrap: error authenticating swift connection: Get
https://api.hubic.com/1.0/account/credentials: invalid character ‘<’ looking for
beginning of value

But eventually it worked and I’ve placed the output at http://www.wywh.com/rclonelogs/IanDuryCrypt.txt

Thank you!

I’ve seen that before - I think it is the hubic server returning a 500 error… Not sure what I can do about that…

I’ve realised I need a bit more from you - I need the mapping of the “Ian Dury” directory itself too. I should have worked that out before, sorry!

Can you do an rclone lsd "hubicrypt:WD6TBNAS01/Squeezebox Music/NotDTS" --crypt-show-mapping which should show that please?

Can you do an rclone lsd “hubicrypt:WD6TBNAS01/Squeezebox Music/NotDTS” --crypt-show-mapping which should show that please?

Here you go:
http://www.wywh.com/rclonelogs/Mapping.txt

Thank you!

@atrocity

Thank you for your excellent work making logs for me.

I finally tracked down a bug in the listing paging code. Swift delivers listings in pages of 1,000 items. What was happening is that if the last item was a directory (in this case the encrypted “Ian Drury/”) then rclone removed the / from the name. However that name without the slash was used to get the next listing page which caused the encrypted “Ian Drury/” to be returned again - hence the duplicate we’ve been seeing in the log. I’m pretty sure (but not 100% confident) that this will cause the “Ian Hunter” directory not to be skipped too.

Here is a new beta which has that bug fix - this should definitely fix the duplicates, and I’m hoping it will fix the missing too! Done in commit ce1b9a7d.

https://beta.rclone.org/v1.36-237-gce1b9a7d/ (uploaded in 15-30 mins)

Let me know how you get on :slight_smile:

Note that this is a swift, hubic fix only so it doesn’t fix @durval problems. However I’m pretty sure that @durval problems are caused by duplicate files on drive which the new beta will warn about.

I’m giving it a try right now with a dry run. The log so far looks completely rational, but it’s taking an abnormally long time because it looks like hubiC is being slow this morning (well, morning for me!). I probably shouldn’t have bothered with a dry run.

Once (if!) the dry run completes I’ll do a live backup and then another dry run and report back.

Thank you for all your hard work!

1 Like

Everything looks good! The live backup transferred the files that had mistakenly been moved to the --backup-dir and the subsequent --dry-run didn’t find anything it needed to do.

Thank you for a great piece of software!

Excellent! Let me know if it does go wrong again.

That was quite a tricky bug to track down which has been in rclone probably since the very beginning!

You are welcome :slight_smile:

Folks,

Sorry for the long time before getting back on this.

I just posted an update, see https://github.com/ncw/rclone/issues/1431#issuecomment-321244537

In short, it seems that @ncw was right, and my entire trouble was due to duplicated directories.

I asked two questions, repeating them here for the sake of completeness (and possibly more eyeballs):

  1. How to solve that problem? Delete those duplicated directories and then repeat the sync? Would a simple “rclone purge” on each one of them (at the remote side, of course) suffice?

  2. I understand that Google Drive produces these duplicated directories “semi expontaneously” (ie, independent of rclone), is that correct? In that case, would running a rclone lsd --max-depth 999 egd: | cut -b 44- | sort | uniq -c | sort -n | grep -v ' *1 ' periodically (say, once a week) be enough to detect them so I could bring the above purgehammer to bear?

Thanks in advance for your response(s).

Cheers,
– Durval.

I wrote this on the issue, but I’ll repeat it here…

How to solve that problem? Delete those duplicated directories and then repeat the sync? Would a simple “rclone purge” on each one of them (on the remote side, of course) suffice?

If you try the latest beta you’ll find that rclone dedupe now merges identical directories. Try it with --dry-run first as it is new code!

I understand that Google Drive produces these duplicated directories “semi expontaneously”

Yes it seems to be random. I suspect some sort of not up to date caching in drive.

Running rclone dedupe --dry-run will detect them also quite well.

Hello Folks,

I just noticed I forgot to post the link to the github issue; here it is: https://github.com/ncw/rclone/issues/1431

Cheers,
– Durval.