Problems uploading Time Machine backup to B2 during backup

[natebrunette]

What is the problem you are having with rclone?

I backup with time machine to a NAS (raspberry pi + usb) and then use rclone to send those backups to B2. I seems like there are errors rclone can't recover from when a file is getting modified before it gets sent to b2. I've attached a log on a run while a TM backup was also happening. Is there any way to mitigate this issue?

What is your rclone version (output from rclone version)

rclone v1.50.2

• os/arch: linux/arm
• go version: go1.13.4

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

Raspbian GNU/Linux 10 (buster), 32 bit

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

Backblaze B2

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

sudo /usr/bin/rclone sync --transfers 32 --log-file ./rclone.log -vv /media/tm backblaze:natebackup

A log from the command with the -vv flag (eg output from rclone -vv copy /tmp remote:tmp)

https://gist.github.com/natebrunette/8f69a019538a76e0e673ef0ede0b5f09

[ncw]

Rclone will abort uploads if it notices the source file is being modified. You can stop it doing this with --local-no-check-updated and that will probably fix your problems, but the backup that gets uploaded will be corrupt...

However it should retry the upload either as a low level retry or a full scale retry later.

It looks like that the relatively new retry and seek on failure code is interfering with this by causing the file to be immediately retried

2019/12/01 17:26:23 DEBUG : MacBook Pro.backupbundle/bands/350: Reopening on read failure after 32501760 bytes: retry 1/10: can't copy - source file is being updated (mod time changed from 2019-12-01 17:11:28 -0600 CST to 2019-12-01 17:26:22 -0600 CST)

The whole file is then uploaded and then the SHA1 checksum fails (as expected).

Have a go with this

https://beta.rclone.org/branch/v1.50.2-075-g08139395-fix-3777-reopen-retries-beta/ (uploaded in 15-30 mins)

Which should fail the upload file straight away and not upload it then try again with a high level retry.

[natebrunette]

Thanks, I'll try this tonight and report back!

[natebrunette]

@ncw Sorry, took some time to get this together

https://gist.github.com/natebrunette/07ef37ebb0d332ebeb5bb9749a4dd723

I think it's still failing based on this

2019/12/03 11:06:53 ERROR : Attempt 3/3 failed with 60 errors and: Post https://pod-000-1133-11.backblaze.com/b2api/v1/b2_upload_file/b2d4434323a2582e62ef0613/c002_v0001133_t0001: can't copy - source file is being updated (mod time changed from 2019-12-03 10:28:32 -0600 CST to 2019-12-03 10:37:13 -0600 CST)
2019/12/03 11:06:53 Failed to sync with 60 errors: last error was: Post https://pod-000-1133-11.backblaze.com/b2api/v1/b2_upload_file/b2d4434323a2582e62ef0613/c002_v0001133_t0001: can't copy - source file is being updated (mod time changed from 2019-12-03 10:28:32 -0600 CST to 2019-12-03 10:37:13 -0600 CST)

[ncw]

Thanks for testing :-)

That is working much better now - it isn't trying to upload the open files over and over again.

So I've merged this to master now which means it will be in the latest beta in 15-30 mins and released in v1.51

The sync did fail. That is because rclone thinks these files are being updated and rclone doesn't want to upload a file that is being updated as it will be corrupted.

2019/12/03 09:39:50 ERROR : MacBook Pro.backupbundle/bands/1e: Failed to copy: Post XXX:
can't copy - source file is being updated (mod time changed from 2019-12-03 09:39:13 -0600 CST to 2019-12-03 09:39:47 -0600 CST)

So I guess the question is

Are these files actually open? Ie is there a backup running at the same time as rclone?

Can you stop time machine and try the sync?

Maybe you can run the sync when time machine isn't running?

[natebrunette]

There is a backup running at the same time as rclone. This is often the case, as I usually can't finish an rclone run in an hour with my upload speeds and time machine backs up every hour. It does finish if time machine isn't performing a backup. Maybe this could be handled with an --allow-modified-failure flag or something that would still retry modified files, but would skip uploading after the limit and not consider it a failure?

[ncw]

There is a backup running at the same time as rclone. This is often the case, as I usually can't finish an rclone run in an hour with my upload speeds and time machine backs up every hour. It does finish if time machine isn't performing a backup. Maybe this could be handled with an --allow-modified-failure flag or something that would still retry modified files, but would skip uploading after the limit and not consider it a failure?

Does rclone not finish if there are files in use?

Maybe you want to set --retries 1 so rclone only does one pass through the files then you can just run it again later?

Rclone will upload the files eventually once they stop being modified!

[natebrunette]

Based on the logs, it seems rclone considers it a failure if we exceed the retry limit, which could have ramifications for deletes, etc. Basically, I want to be able to tell it to not consider modified file errors as failures. Alternatively, the retries could happen at the end, when it’s much less likely the same file will be changed. Time machine runs every hour, so if my computer is left on overnight, it will always conflict at some point with the rclone backup.

[ncw]

Maybe this flag is the solution?

  --retries-sleep duration               Interval between retrying operations if they fail, e.g 500ms, 60s, 5m. (0 to disable)

Rclone should run through all the files, then do a high level retry. You could set this delay to 10m to give timemachine a chance to finish.

[dolphyvn]

can rclone tail only the last line and copy only when there is an update? I got same problem but none of the above methods solved the issue. As mine trying to sync logs file and it constantly gets updated.

[ncw]

As mine trying to sync logs file and it constantly gets updated.

The best thing to do with log files is to exclude them from the backup.

[ivandeex]

can rclone tail only the last line and copy only when there is an update? I got same problem but none of the above methods solved the issue. As mine trying to sync logs file and it constantly gets updated.

Not at the moment

[ivandeex]

I suggest adding a note about logs in the Caveats docs section.

[scolby33]

@natebrunette I'm using rclone in the same way as you, Time Machine -> samba -> RPi -> external drive -> rclone -> B2 and have noticed similar errors. What command line did you end up using for the moment?

[natebrunette]

@scolby33 I bought a mac mini and use the backblaze desktop client 🤣

[natebrunette]

@scolby33 for posterity’s sake, I use carbon copy cleaner as backblaze will ignore time machine. Being on Big Sur results in fairly small diffs, though. 2-3 GB instead of 60-70.

[phirestalker]

Ya, macOS does whatever it wants. Even if you disable Time Machine backups and manually unmount the bloody sparse files, it still says the mod time was updated. I am going to try with "--retries 1 --retries-sleep 5m" with version 1.50.2 and see if that will help.

[phirestalker]

Those two options worked great for me, but this was with Time Machine disabled on both computers.