Rclone mount in systemd is not working when uploads are pending

gustafsonja · September 13, 2023, 7:01pm

What is the problem you are having with rclone?

I am using rclone mount via systemd, with a large VFS cache and with a crypt layer. After the mount is stopped with pending uploads, when it is started again, the mount won't become ready and will time out, even though its logs show that it seems to be running fine. When I run rclone mount myself outside of systemd with the same arguments, I get the same log output from rclone, and the mount works. As a workaround, I'm just running my mount command manually outside systemd for now.

Run the command 'rclone version' and share the full output of the command.

rclone v1.64.0-beta.7351.fa4d171f6
- os/version: debian 11.7 (64 bit)
- os/kernel: 5.10.0-23-amd64 (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.21.1
- go/linking: static
- go/tags: none

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

Dropbox

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

I am using this systemd mount:

[Unit]
After=network-online.target

[Mount]
Type=rclone
What=mntb:
Where=/mnt/b
Options=rw,allow_other,default_permissions,umask=0007,gid=998,syslog,vv,vfs-cache-mode=full,vfs-cache-max-age=168h,vfs-cache-max-size=1.9T,cache-dir=/mnt/rclonecache/mntb,vfs-write-back=5m,config=/etc/rclone.conf[,daemon-wait=5m]
[TimeoutSec=5m]

The parts in square brackets I have tried adding, which had the effect of making the mount take 5 minutes to fail instead of a shorter amount of time.

(This mount is triggered by a trivial automount:)

[Unit]
Requires=network-online.target
Before=remote-fs.target
[Automount]
Where=/mnt/b
[Install]
WantedBy=multi-user.target

The command I have tried outside of systemd that works:

sudo rclone mount mntb: /mnt/b --allow-other --default-permissions --umask=0007 --gid=998 -v --vfs-cache-mode=full --vfs-cache-max-age=168h --vfs-cache-max-size=1.9T --cache-dir=/mnt/rclonecache/mntb --vfs-write-back=5m --config=/etc/rclone.conf [--daemon]

(I have verified that it works fine with and without --daemon because it appears that this flag is added automatically somewhere in the systemd mount process.)

The rclone config contents with secrets removed.

[mntb]
type = crypt
remote = dbx-rclone-union:mntb

[dbx-rclone-union]
type = union
upstreams = dbx-rclone-0:rclone dbx-rclone-1:rclone dbx-rclone-2:rclone dbx-rclone-3:rclone
create_policy = mfs

[dbx-rclone-0]
type = dropbox

[dbx-rclone-1]
type = dropbox

[dbx-rclone-2]
type = dropbox

[dbx-rclone-3]
type = dropbox

A log from the command with the `-vv` flag

Sep 13 11:27:05 square systemd[1]: Mounting /mnt/b...
Sep 13 11:27:05 square mount.rclone[479540]: rclone: Version "v1.64.0-beta.7351.fa4d171f6" starting with parameters ["/sbin/mount.rclone" "mount" "mntb:" "/mnt/b" "--allow-other" "--default-permissions" "--umask=0007" "--gid=998" "--syslog" "--vfs-cache-mode=full" "--vfs-cache-max-age=168h" "--vfs-cache-max-size=1.9T" "--cache-dir=/mnt/rclonecache/mntb" "--vfs-write-back=5m" "--config=/etc/rclone.conf" "--verbose=2" "--daemon"]
Sep 13 11:27:05 square mount.rclone[479540]: Using fallback PATH to run fusermount
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "mntb:"
Sep 13 11:27:05 square mount.rclone[479540]: Using config file from "/etc/rclone.conf"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-union:mntb"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-3:rclone"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-2:rclone"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-1:rclone"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-0:rclone"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-2:rclone/mntb"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-0:rclone/mntb"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-3:rclone/mntb"
Sep 13 11:27:05 square mount.rclone[479540]: Creating backend with remote "dbx-rclone-1:rclone/mntb"
Sep 13 11:27:06 square mount.rclone[479540]: union root 'mntb': actionPolicy = *policy.EpAll, createPolicy = *policy.Mfs, searchPolicy = *policy.FF
Sep 13 11:27:06 square rclone[479559]: rclone: Version "v1.64.0-beta.7351.fa4d171f6" starting with parameters ["/usr/bin/rclone" "mount" "mntb:" "/mnt/b" "--allow-other" "--default-permissions" "--umask=0007" "--gid=998" "--syslog" "--vfs-cache-mode=full" "--vfs-cache-max-age=168h" "--vfs-cache-max-size=1.9T" "--cache-dir=/mnt/rclonecache/mntb" "--vfs-write-back=5m" "--config=/etc/rclone.conf" "--verbose=2" "--daemon"]
Sep 13 11:27:06 square rclone[479559]: Creating backend with remote "mntb:"
Sep 13 11:27:06 square rclone[479559]: Using config file from "/etc/rclone.conf"
Sep 13 11:27:06 square rclone[479559]: Creating backend with remote "dbx-rclone-union:mntb"
Sep 13 11:27:06 square rclone[479559]: Creating backend with remote "dbx-rclone-3:rclone"
Sep 13 11:27:06 square rclone[479559]: Creating backend with remote "dbx-rclone-1:rclone"
Sep 13 11:27:06 square rclone[479559]: Creating backend with remote "dbx-rclone-2:rclone"
Sep 13 11:27:06 square rclone[479559]: Creating backend with remote "dbx-rclone-0:rclone"
Sep 13 11:27:07 square rclone[479559]: Creating backend with remote "dbx-rclone-3:rclone/mntb"
Sep 13 11:27:07 square rclone[479559]: Creating backend with remote "dbx-rclone-0:rclone/mntb"
Sep 13 11:27:07 square rclone[479559]: Creating backend with remote "dbx-rclone-2:rclone/mntb"
Sep 13 11:27:07 square rclone[479559]: Creating backend with remote "dbx-rclone-1:rclone/mntb"
Sep 13 11:27:07 square rclone[479559]: union root 'mntb': actionPolicy = *policy.EpAll, createPolicy = *policy.Mfs, searchPolicy = *policy.FF
Sep 13 11:27:07 square rclone[479559]: vfs cache: root is "/mnt/rclonecache/mntb"
Sep 13 11:27:07 square rclone[479559]: vfs cache: data root is "/mnt/rclonecache/mntb/vfs/mntb"
Sep 13 11:27:07 square rclone[479559]: vfs cache: metadata root is "/mnt/rclonecache/mntb/vfsMeta/mntb"
Sep 13 11:27:07 square rclone[479559]: Creating backend with remote "/mnt/rclonecache/mntb/vfs/mntb/"
Sep 13 11:27:07 square rclone[479559]: fs cache: renaming cache item "/mnt/rclonecache/mntb/vfs/mntb/" to be canonical "/mnt/rclonecache/mntb/vfs/mntb"
Sep 13 11:27:07 square rclone[479559]: Creating backend with remote "/mnt/rclonecache/mntb/vfsMeta/mntb/"
Sep 13 11:27:07 square rclone[479559]: fs cache: renaming cache item "/mnt/rclonecache/mntb/vfsMeta/mntb/" to be canonical "/mnt/rclonecache/mntb/vfsMeta/mntb"
Sep 13 11:27:07 square rclone[479559]: dir1/downloads/dir2/dir3/file1: vfs cache: checking remote fingerprint "21023432043,2023-09-12 12:58:51 +0000 UTC" against cached fingerprint "21023432043,2023-09-12 12:58:51 +0000 UTC"
Sep 13 11:27:07 square rclone[479559]: dir1/downloads/dir2/dir3/file1: vfs cache: truncate to size=21023432043 (not needed as size correct)
Sep 13 11:27:07 square rclone[479559]: vfs cache: looking for range={Pos:0 Size:21023432043} in [{Pos:0 Size:21023432043}] - present true
Sep 13 11:27:07 square rclone[479559]: dir1/downloads/dir2/dir3/file1: vfs cache: setting modification time to 2023-09-12 23:49:33.774604237 -0700 PDT
Sep 13 11:27:07 square rclone[479559]: dir1/downloads/dir2/dir3/file1: vfs cache: queuing for upload in 5m0s
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir3: Added virtual directory entry vAddFile: "file1"
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir4/file2: vfs cache: truncate to size=16178083428 (not needed as size correct)
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir4/file2: vfs cache: setting modification time to 2023-09-12 23:49:34.193953403 -0700 PDT
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir4/file2: vfs cache: queuing for upload in 5m0s
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir4: Added virtual directory entry vAddFile: "file2"
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir5/file3: vfs cache: checking remote fingerprint "18435752249,2023-09-11 22:17:36 +0000 UTC" against cached fingerprint "18435752249,2023-09-11 22:17:36 +0000 UTC"
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir5/file3: vfs cache: truncate to size=18435752249 (not needed as size correct)
Sep 13 11:27:09 square rclone[479559]: vfs cache: looking for range={Pos:0 Size:18435752249} in [{Pos:0 Size:18435752249}] - present true
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir5/file3: vfs cache: setting modification time to 2023-09-12 23:49:33.767652992 -0700 PDT
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir5/file3: vfs cache: queuing for upload in 5m0s
Sep 13 11:27:09 square rclone[479559]: dir1/downloads/dir2/dir5: Added virtual directory entry vAddFile: "file3"
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir6/file4: vfs cache: checking remote fingerprint "17879927663,2023-09-12 02:32:05 +0000 UTC" against cached fingerprint "17879927663,2023-09-12 02:32:05 +0000 UTC"
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir6/file4: vfs cache: truncate to size=17879927663 (not needed as size correct)
Sep 13 11:27:10 square rclone[479559]: vfs cache: looking for range={Pos:0 Size:17879927663} in [{Pos:0 Size:17879927663}] - present true
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir6/file4: vfs cache: setting modification time to 2023-09-12 23:49:33.99180657 -0700 PDT
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir6/file4: vfs cache: queuing for upload in 5m0s
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir6: Added virtual directory entry vAddFile: "file4"
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir7/file5: vfs cache: checking remote fingerprint "18843492031,2023-09-12 04:34:25 +0000 UTC" against cached fingerprint "18843492031,2023-09-12 04:34:25 +0000 UTC"
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir7/file5: vfs cache: truncate to size=18843492031 (not needed as size correct)
Sep 13 11:27:10 square rclone[479559]: vfs cache: looking for range={Pos:0 Size:18843492031} in [{Pos:0 Size:18843492031}] - present true
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir7/file5: vfs cache: setting modification time to 2023-09-12 23:49:34.629136165 -0700 PDT
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir7/file5: vfs cache: queuing for upload in 5m0s
Sep 13 11:27:10 square rclone[479559]: dir1/downloads/dir2/dir7: Added virtual directory entry vAddFile: "file5"
Sep 13 11:27:10 square rclone[479559]: vfs cache RemoveNotInUse (maxAge=604800000000000, emptyOnly=false): item dir1/downloads/dir2/dir8/file6 not removed, freed 0 bytes
Sep 13 11:27:10 square rclone[479559]: vfs cache RemoveNotInUse (maxAge=604800000000000, emptyOnly=false): item dir1/downloads/dir2/dir9/file7 not removed, freed 0 bytes
Sep 13 11:27:10 square rclone[479559]: vfs cache RemoveNotInUse (maxAge=604800000000000, emptyOnly=false): item dir1/downloads/dir2/dir10/file8 not removed, freed 0 bytes
Sep 13 11:27:10 square rclone[479559]: Encrypted drive 'mntb:': Mounting on "/mnt/b"
Sep 13 11:27:10 square rclone[479559]: vfs cache RemoveNotInUse (maxAge=604800000000000, emptyOnly=false): item dir1/downloads/dir2/dir11/file9 not removed, freed 0 bytes
Sep 13 11:27:10 square rclone[479559]: vfs cache RemoveNotInUse (maxAge=604800000000000, emptyOnly=false): item dir1/downloads/dir2/dir12/file10 not removed, freed 0 bytes
Sep 13 11:27:10 square rclone[479559]: vfs cache: cleaned: objects 10 (was 10) in use 5, to upload 5, uploading 0, total size 737.863Gi (was 737.863Gi)
Sep 13 11:27:10 square rclone[479559]: : Root:
Sep 13 11:27:10 square rclone[479559]: : >Root: node=/, err=<nil>
Sep 13 11:28:06 square mount.rclone[479540]: Daemon timed out. Terminating daemon pid 479559
Sep 13 11:28:06 square mount.rclone[479540]: Fatal error: mount not ready: /mnt/b
Sep 13 11:28:06 square rclone[479559]: Signal received: interrupt
Sep 13 11:28:06 square rclone[479559]: Dropbox root 'rclone': Committing uploads - please wait...
Sep 13 11:28:06 square rclone[479559]: Dropbox root 'rclone/mntb': Committing uploads - please wait...
Sep 13 11:28:06 square rclone[479559]: Dropbox root 'rclone/mntb': Committing uploads - please wait...
Sep 13 11:28:06 square rclone[479559]: Dropbox root 'rclone/mntb': Committing uploads - please wait...
Sep 13 11:28:06 square rclone[479559]: /mnt/b: Unmounted externally. Just exit now.
Sep 13 11:28:06 square rclone[479559]: Dropbox root 'rclone': Committing uploads - please wait...
Sep 13 11:28:06 square rclone[479559]: Dropbox root 'rclone': Committing uploads - please wait...
Sep 13 11:28:06 square rclone[479559]: Dropbox root 'rclone/mntb': Committing uploads - please wait...
Sep 13 11:28:06 square rclone[479559]: Dropbox root 'rclone': Committing uploads - please wait...
Sep 13 11:28:06 square rclone[479559]: Exiting...
Sep 13 11:28:06 square systemd[1]: mnt-b.mount: Mount process exited, code=exited, status=1/FAILURE
Sep 13 11:28:06 square systemd[1]: Mounted /mnt/b.

asdffdsa · September 13, 2023, 7:07pm

might try --daemon-wait=0

gustafsonja · September 13, 2023, 7:10pm

With this, I hit systemd timeouts, even if I bump those. I don't think that I need to give the daemon more time to start up, since the logs seem to suggest that it's finished checking its vfs entries and is doing nothing for minutes until it hits some timeout and is killed. And when invoking the same command outside systemd, the mount is working and available in just a few seconds.

asdffdsa · September 13, 2023, 7:12pm

yes, i agree and that is not what that link is suggesting, maybe i am confused.
did you click on the link i shared? from ncw, the primary author of rclone.

Animosity022 · September 13, 2023, 7:13pm

When you have queued uploads, it has to check all the items in the cache against the remote so it's not the size of the items, but the count of the items that it has to go through.

I really wouldn't recommend using daemon with systemd as it's easier/more stable to make a service file instead of a mount.

You also want to configure client ID and secrets for all your remotes. You also want to limit the TPS or it's going to break pretty fast too with retries.

gustafsonja · September 13, 2023, 7:20pm

You are right, I'm sorry. I did try that before, and I found my logs from using --daemon-wait=0:

Sep 13 10:46:33 square systemd[1]: Mounting /mnt/b...
Sep 13 10:46:33 square mount.rclone[468885]: rclone: Version "v1.64.0-beta.7351.fa4d171f6" starting with parameters ["/sbin/mount.rclone" "mount" "mntb:" "/mnt/b" "--allow-other" "--default-permissions" "--umask=0007" "--gid=998" "--syslog" "--vfs-cache-mode=full" "--vfs-cache-max-age=168h" "--vfs-cache-max-size=1.9T" "--cache-dir=/mnt/rclonecache/mntb" "--vfs-write-back=5m" "--config=/etc/rclone.conf" "--daemon-wait=0" "--verbose=2" "--daemon"]
Sep 13 10:46:33 square mount.rclone[468885]: Using fallback PATH to run fusermount
Sep 13 10:46:33 square mount.rclone[468885]: Creating backend with remote "mntb:"
Sep 13 10:46:33 square mount.rclone[468885]: Using config file from "/etc/rclone.conf"
Sep 13 10:46:33 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-union:mntb"
Sep 13 10:46:33 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-3:rclone"
Sep 13 10:46:33 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-1:rclone"
Sep 13 10:46:33 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-2:rclone"
Sep 13 10:46:33 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-0:rclone"
Sep 13 10:46:34 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-1:rclone/mntb"
Sep 13 10:46:34 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-3:rclone/mntb"
Sep 13 10:46:34 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-2:rclone/mntb"
Sep 13 10:46:34 square mount.rclone[468885]: Creating backend with remote "dbx-rclone-0:rclone/mntb"
Sep 13 10:46:34 square mount.rclone[468885]: union root 'mntb': actionPolicy = *policy.EpAll, createPolicy = *policy.Mfs, searchPolicy = *policy.FF
Sep 13 10:46:34 square mount.rclone[468885]: rclone: Version "v1.64.0-beta.7351.fa4d171f6" finishing with parameters ["/usr/bin/rclone" "mount" "mntb:" "/mnt/b" "--allow-other" "--default-permissions" "--umask=0007" "--gid=998" "--syslog" "--vfs-cache-mode=full" "--vfs-cache-max-age=168h" "--vfs-cache-max-size=1.9T" "--cache-dir=/mnt/rclonecache/mntb" "--vfs-write-back=5m" "--config=/etc/rclone.conf" "--daemon-wait=0" "--verbose=2" "--daemon"]
Sep 13 10:46:34 square mount.rclone[468885]: Dropbox root 'rclone/mntb': Committing uploads - please wait...
Sep 13 10:46:34 square mount.rclone[468885]: Dropbox root 'rclone/mntb': Committing uploads - please wait...
Sep 13 10:46:34 square mount.rclone[468885]: Dropbox root 'rclone': Committing uploads - please wait...
Sep 13 10:46:34 square mount.rclone[468885]: Dropbox root 'rclone': Committing uploads - please wait...
Sep 13 10:46:34 square mount.rclone[468885]: Dropbox root 'rclone': Committing uploads - please wait...
Sep 13 10:46:34 square mount.rclone[468885]: Dropbox root 'rclone': Committing uploads - please wait...
Sep 13 10:46:34 square mount.rclone[468885]: Dropbox root 'rclone/mntb': Committing uploads - please wait...
Sep 13 10:46:34 square mount.rclone[468885]: Dropbox root 'rclone/mntb': Committing uploads - please wait...
Sep 13 10:46:34 square systemd[1]: mnt-b.mount: Mount process finished, but there is no mount.
Sep 13 10:46:34 square systemd[1]: mnt-b.mount: Failed with result 'protocol'.
Sep 13 10:46:34 square systemd[1]: mnt-b.mount: Unit process 468894 (rclone) remains running after unit stopped.
Sep 13 10:46:34 square systemd[1]: Failed to mount /mnt/b.
Sep 13 10:46:34 square rclone[468894]: rclone: Version "v1.64.0-beta.7351.fa4d171f6" starting with parameters ["/usr/bin/rclone" "mount" "mntb:" "/mnt/b"]
Sep 13 10:46:34 square rclone[468894]: Creating backend with remote "mntb:"
Sep 13 10:46:34 square rclone[468894]: Using config file from "/etc/rclone.conf"
[... more logs from the remaining background rclone process, but the mount is considered "failed" already ...]

gustafsonja · September 13, 2023, 7:31pm

We can see in the logs, both inside and outside systemd, that it finishes checking all the items in the cache in just a few seconds, so it doesn't make sense to me why that would be the cause, especially when the problem doesn't happen when invoking rclone mount manually.

I'm not intentionally using daemon in my configs at all. It's apparently being added somewhere between my systemd mount config and the rclone invocation.

I may try out using a systemd service file instead of a mount file. Is there an example somewhere? I've been using a systemd mount file because of the clear example provided at rclone mount. I find systemd configs rather confusing to figure out from scratch. (It is also nice to be able to use automount with a mount file, so I don't have to figure out how to configure dependencies between services to prevent things from trying to use the mount before it's ready.)

Animosity022 · September 14, 2023, 3:10am

The ones I use are here:

It's a good investment as I didn't like systemd at first, but got the hang of it and haven't looked back. If something isn't working, just post as we can help figure it out.

Daemonizing rclone has been problematic for a bit, but generally not that bad on Linux.

Issue for that is here -> mount: improve implementation of --daemon mode · Issue #5664 · rclone/rclone · GitHub

system · October 14, 2023, 3:10am

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