Rclone not exiting on copy or sync (successful) to Dropbox crypt

What is the problem you are having with rclone?

The rclone cli copy and sync command are not returning when completing/successful from a local directory copy to a dropbox crypted secret store.

The copy is successful and, in fact, has copied and crypted over 125GB+ of data to Dropbox, but for some reason, the command will not finish and return control back to the terminal (I want to set up systemd to automate this copy every 6 hours so need to solve.).

I use fish for my shell so also tried running it in bash and additionally kicking out of tmux to a naked shell to also run it from fish and bash, but I still have the same problem. Using alacritty as my terminal. Gnome desktop in POPOS 20.04.

What is your rclone version (output from rclone version)

I was originally using the v1.50.2/go1.13.6 which is the stock install on POPOS 20.04 (based on Ubuntu 20.04) and seeing the same behaviour. I manually upgraded it to the latest 1.53.1, however and the behaviour remains, rclone does not come back:

 Ī» ~ rclone --version
rclone v1.53.1
- os/arch: linux/amd64
- go version: go1.15

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

POPOS 20.04 (Ubuntu 20.04 underneath).
It is currently completely up to date.

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

Dropbox
(And am copying to a crypted secret store which overlays that remote.).

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

rclone copy /home/daryl/ secret:/ --copy-links --filter-from /home/daryl/.config/rclone/exclusions.txt 

I've been following it with a --log-file=/home/daryl/rclone_log.txt to attempt to diagnose the issue.

The command has successfully copied everything over the last 48 hours, encrypted over to the store (as verified via rclone-browser checking and manual checking on Dropbox). It, however, from that original task and on updates to set up incremental backups will not come back to the terminal after CLI execution.

Note: The command runs successfully, it simply never returns control to the command line.

The rclone config contents with secrets removed.

[elcano_backups]
type = dropbox
token = {"access_token":"redacted","token_type":"bearer","expiry":"0001-01-01T00:00:00Z"}

[secret]
type = crypt
remote = elcano_backups:/Apps/RClone_Elcano
filename_encryption = standard
directory_name_encryption = true
password = <redacted>

A log from the command with the -vv flag

Since this is a full backup of my home directory, the -vv being pasted here is not feasible. Here's the -v though before it just stops returning anything. The entire command both syncs and copies without incident however. The Photo lib error (holdover from OSX) doesn't seem like it should be causing the issue and when I run the command often get a diff file that it errors on so expect it has to do with num files in that directory (I think at last count I had 45k photos).

 Ī» ~ tail -f rclone_log.txt
2020/09/14 11:52:27 INFO  : rclone_log.txt: Copied (new)
2020/09/14 11:53:19 ERROR : Pictures/Photos Library.photoslibrary/originals/6: error reading destination directory: list continue: http2: server sent GOAWAY and closed the connection; LastStreamID=1999, ErrCode=NO_ERROR, debug=""
2020/09/14 11:53:25 INFO  :
Transferred:            32 / 32 Bytes, 100%, 24 Bytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             27773 / 27773, 100%
Transferred:            1 / 1, 100%
Elapsed time:       1m0.8s

2020/09/14 11:53:44 INFO  : .local/share/gnome-shell/application_state: Copied (replaced existing)
2020/09/14 11:53:55 INFO  : .local/share/gvfs-metadata/root: Copied (replaced existing)
2020/09/14 11:53:55 INFO  : .local/share/gvfs-metadata/root-04245e47.log: Copied (new)
2020/09/14 11:54:25 INFO  :
Transferred:       35.298k / 35.298 kBytes, 100%, 6.298 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             51458 / 51458, 100%
Transferred:            4 / 4, 100%
Elapsed time:       2m0.8s

2020/09/14 11:55:25 INFO  :
Transferred:       35.298k / 35.298 kBytes, 100%, 6.298 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:             51458 / 51458, 100%
Transferred:            4 / 4, 100%
Elapsed time:       3m0.8s
... (etc... keep on getting repeat of the last block every minute and 0.8s ad infinitum)
...

I'd guess it's still checking but the -vv would show that. You really need to use the -vv flag to see what's going on.

Well, I will run it again with -vv to the log file, but I would be surprised considering how small the delta on the files would be that need to be rcloned (assuming it works similarly to rsync). Will check again. Would it be better to drop in a time flag like 24h or --no-traverse to ensure it "finishes" promptly so we can prove or disprove that as a possible issue?

@Animosity022
I am seeing some of this in the log when I -vv it towards the end where I see those repeat lines. Pacer? (is that related to rclone in some way or perhaps a gnome issue? (race/deadlocking?) I have a pretty speedy (new) laptop with a fast SSD but first time I've seen that ... though it is a heap of files I'm checking... ).

4985 2020/09/14 21:29:48 DEBUG : Code/dev/HelvetiCan-Taskpaper-theme/.git/objects/ca/f2e34495bb9771a001990141982b7313815150: Unchanged skippingĀ¬
244986 2020/09/14 21:29:48 DEBUG : too_many_requests/.: Too many requests or write operations. Trying again in 300 seconds.Ā¬
244987 2020/09/14 21:29:48 DEBUG : pacer: low level retry 1/10 (error too_many_requests/.)Ā¬
244988 2020/09/14 21:29:48 DEBUG : pacer: Rate limited, increasing sleep to 5m0sĀ¬
244989 2020/09/14 21:29:48 DEBUG : pacer: Reducing sleep to 3m45sĀ¬
244990 2020/09/14 21:29:48 DEBUG : Code/dev/go/spt/.git/objects/b0/29ed69f59e817ceb7d63e1a68552fbb5eaeac9: Size and modification time the same (differ by 0s, within tolerance 1s)Ā¬
244991 2020/09/14 21:29:48 DEBUG : Code/dev/go/spt/.git/objects/b0/29ed69f59e817ceb7d63e1a68552fbb5eaeac9: Unchanged skippingĀ¬
244992 2020/09/14 21:29:48 DEBUG : pacer: Reducing sleep to 2m48.75sĀ¬
244993 2020/09/14 21:29:48 DEBUG : .local/share/gnome-shell/extensions/openweather-extension@jenslody.de/locale/id/LC_MESSAGES/gnome-shell-extension-openweather.mo: Size and modification time the same (differ by 0       s, within tolerance 1s)Ā¬
244994 2020/09/14 21:29:48 DEBUG : .local/share/gnome-shell/extensions/openweather-extension@jenslody.de/locale/id/LC_MESSAGES/gnome-shell-extension-openweather.mo: Unchanged skippingĀ¬
244995 2020/09/14 21:29:48 DEBUG : too_many_requests/: Too many requests or write operations. Trying again in 300 seconds.Ā¬
244996 2020/09/14 21:29:48 DEBUG : pacer: low level retry 1/10 (error too_many_requests/)Ā¬
244997 2020/09/14 21:29:48 DEBUG : pacer: Rate limited, increasing sleep to 5m0sĀ¬
244998 2020/09/14 21:29:48 DEBUG : pacer: Reducing sleep to 3m45sĀ¬
244999 2020/09/14 21:29:48 DEBUG : pacer: Reducing sleep to 2m48.75sĀ¬
245000 2020/09/14 21:29:48 DEBUG : too_many_requests/: Too many requests or write operations. Trying again in 300 seconds.Ā¬
245001 2020/09/14 21:29:48 DEBUG : pacer: low level retry 1/10 (error too_many_requests/)Ā¬
245002 2020/09/14 21:29:48 DEBUG : too_many_requests/: Too many requests or write operations. Trying again in 300 seconds.Ā¬
245003 2020/09/14 21:29:48 DEBUG : pacer: low level retry 2/10 (error too_many_requests/)Ā¬
245004 2020/09/14 21:29:48 DEBUG : pacer: Rate limited, increasing sleep to 5m0sĀ¬
245005 2020/09/14 21:29:49 DEBUG : pacer: Reducing sleep to 3m45sĀ¬

The full log is really what's needed as clips hide things and I can't tell what was run.

It appears to be being rate limited by Dropbox in some way - perhaps related to this issue here?


as almost same issue by looks of things.

(the full log is 52MB at the point I killed it where you see the pacer and then everything afte that is the same messages I had posted previously in the -v output. Everything up to that appears to be just checks saying the file check is within tolerance and it is not copied. Except for the scant few files that needed to be copied.).

If you can share the full log, that would be great.

I've been working on improving the dropbox backend recently.

Rclone doesn't use dropbox batching and it really should.

Also the rate limits need tweaking....

So can you try this binary

https://beta.rclone.org/branch/fix-dropbox-batch/v1.54.0-beta.4758.c741c02fb.fix-dropbox-batch/

With the extra flags --dropbox-batch 1000 --tpslimit 12 and see if that helps.

You should find that it transfers things a lot quicker especially if you are transferring small files. It should avoid the retry-after lockouts also.

1 Like

@ncw @Animosity022

Grabbed the linux/amd64 deb and installed the 1.54.0-beta with the dropbox batch fix. Seems to have worked the charm. Rclone ran and exited normally with checks and the --progress flag. Thank you!

 Ī» ~ rclone copy /home/daryl/ secret:/ --copy-links --filter-from /home/daryl/.config/rclone/exclusions.txt --dropbox-batch 1000 --tpslimit 12 --progress
Transferred:      100.528k / 100.528 kBytes, 100%, 9.076 kBytes/s, ETA 0s
Checks:            199201 / 199201, 100%
Transferred:            8 / 8, 100%
Elapsed time:     24m32.1s

D.

1 Like

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