Rclone mount is not working when uploads are pending

dennis_de · October 18, 2022, 9:49am

What is the problem you are having with rclone?

When I run rclone mount and uploads from the VFS cache are pending, the mount does not start and "rclone rc vfs/stats" also loads forever with no response.

It also seems like the VFS stats in the log that you know before don't appear either.

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

rclone v1.59.2

os/version: ubuntu 20.04 (64 bit)
os/kernel: 5.4.0-128-generic (x86_64)
os/type: linux
os/arch: amd64
go/version: go1.18.6
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`)

/usr/bin/rclone mount \
  --user-agent 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36' \
  --config /mnt/local/rclone/config/rclone.conf \
  --allow-other \
  --allow-non-empty \
  --buffer-size 1M \
  --dir-cache-time 87600h \
  --poll-interval 1m \
  --timeout 15s \
  --vfs-cache-mode full \
  --vfs-cache-max-age 87600h \
  --vfs-write-back 5m \
  --cache-dir /mnt/local/rclone/cache \
  --attr-timeout 1s \
  --umask=002 \
  --use-mmap \
  --log-file /var/log/rclone/mount.log \
  --tpslimit 12 \
  --tpslimit-burst 12 \
  --transfers 32 \
  --dropbox-batch-mode async \
  --dropbox-batch-timeout 10s \
  --dropbox-batch-size 100 \
  -vvv \
  dbx_crypt: /mnt/path

The rclone config contents with secrets removed.

[dbx_base]
type = dropbox
client_id = secret
client_secret = secret
token = secret

[dbx_crypt]
type = crypt
remote = dbx_base:
filename_encryption = off
directory_name_encryption = false
password = secret
password2 = secret

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

2022/10/18 11:27:17 INFO  : Starting transaction limiter: max 12 transactions/s with burst 12
2022/10/18 11:27:17 DEBUG : rclone: Version "v1.59.2" starting with parameters ["/usr/bin/rclone" "mount" "--user-agent" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36" "-->
2022/10/18 11:27:17 DEBUG : Creating backend with remote "dbx_crypt:"
2022/10/18 11:27:17 DEBUG : Using config file from "/mnt/local/rclone/config/rclone.conf"
2022/10/18 11:27:17 DEBUG : Creating backend with remote "dbx_base:"
2022/10/18 11:27:17 DEBUG : dbx_base: detected overridden config - adding "{niIBy}" suffix to name
2022/10/18 11:27:17 DEBUG : fs cache: renaming cache item "dbx_base:" to be canonical "dbx_base{niIBy}:"
2022/10/18 11:27:18 DEBUG : vfs cache: root is "/mnt/local/rclone/cache"
2022/10/18 11:27:18 DEBUG : vfs cache: data root is "/mnt/local/rclone/cache/vfs/dbx_crypt"
2022/10/18 11:27:18 DEBUG : vfs cache: metadata root is "/mnt/local/rclone/cache/vfsMeta/dbx_crypt"
2022/10/18 11:27:18 DEBUG : Creating backend with remote "/mnt/local/rclone/cache/vfs/dbx_crypt/"
2022/10/18 11:27:18 DEBUG : Creating backend with remote "/mnt/local/rclone/cache/vfsMeta/dbx_crypt/"

Animosity022 · October 18, 2022, 11:16am

Is that all the log does as that's only 1 second? Does it just wait there forever and never do anything else?

dennis_de · October 18, 2022, 11:27am

Sorry, for the misunderstanding. No, it uploads normally. I have only omitted the entries now. However, I have so much in the backlog (I don't know the exact number) that it's been uploading for hours.

2022/10/18 11:27:18 DEBUG : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_224x224_right.jpg: vfs cache: truncate to size=6524
2022/10/18 11:27:18 DEBUG : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_224x224_right.jpg: vfs cache: setting modification time to 2022-10-18 09:24:19.521283519 +0200 CEST
2022/10/18 11:27:18 INFO  : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_224x224_right.jpg: vfs cache: queuing for upload in 5m0s
2022/10/18 11:27:20 DEBUG : cache/thumbnails/3/9/e: Added virtual directory entry vAddFile: "39e7df8e3a024bf9e168d54180506c8107b1cc21_224x224_right.jpg"
2022/10/18 11:27:20 DEBUG : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_3x3_resize.png: vfs cache: truncate to size=100
2022/10/18 11:27:20 DEBUG : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_3x3_resize.png: vfs cache: setting modification time to 2022-10-18 09:24:19.525507023 +0200 CEST
2022/10/18 11:27:20 INFO  : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_3x3_resize.png: vfs cache: queuing for upload in 5m0s
2022/10/18 11:27:20 DEBUG : cache/thumbnails/3/9/e: Added virtual directory entry vAddFile: "39e7df8e3a024bf9e168d54180506c8107b1cc21_3x3_resize.png"
2022/10/18 11:27:20 DEBUG : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_500x500_center.jpg: vfs cache: truncate to size=31974
2022/10/18 11:27:20 DEBUG : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_500x500_center.jpg: vfs cache: setting modification time to 2022-10-18 09:24:19.538947823 +0200 CEST
2022/10/18 11:27:20 INFO  : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_500x500_center.jpg: vfs cache: queuing for upload in 5m0s
2022/10/18 11:27:20 DEBUG : cache/thumbnails/3/9/e: Added virtual directory entry vAddFile: "39e7df8e3a024bf9e168d54180506c8107b1cc21_500x500_center.jpg"
2022/10/18 11:27:21 DEBUG : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_50x50_center.jpg: vfs cache: truncate to size=1063
2022/10/18 11:27:21 DEBUG : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_50x50_center.jpg: vfs cache: setting modification time to 2022-10-18 09:24:19.546047901 +0200 CEST
2022/10/18 11:27:21 INFO  : cache/thumbnails/3/9/e/39e7df8e3a024bf9e168d54180506c8107b1cc21_50x50_center.jpg: vfs cache: queuing for upload in 5m0s

[..]

2022/10/18 11:30:18 DEBUG : Dropbox root '': Checking for changes on remote
2022/10/18 11:30:18 DEBUG : Dropbox root '': Increasing poll interval to minimum 30s

[..]

2022/10/18 11:32:37 DEBUG : cache/thumbnails/3/a/b/3ab6c23e9860b1d145e4fab212397596b8755eb1_224x224_left.jpg: vfs cache: starting upload
2022/10/18 11:32:37 DEBUG : cache/thumbnails/3/a/a/3aac1f6b87c6d3fda2038c3102f3fd8aad6a4e31_3x3_resize.png.bin: Uploading chunk 2/1
2022/10/18 11:32:37 DEBUG : cache/thumbnails/3/a/a/3aac1f6b87c6d3fda2038c3102f3fd8aad6a4e31_500x500_center.jpg.bin: Uploading chunk 2/1

[..]

2022/10/18 11:32:36 INFO  : cache/thumbnails/3/a/a/3aac1f6b87c6d3fda2038c3102f3fd8aad6a4e31_100x100_center.jpg: Copied (new)
2022/10/18 11:32:36 DEBUG : cache/thumbnails/3/a/a/3aac1f6b87c6d3fda2038c3102f3fd8aad6a4e31_100x100_center.jpg: vfs cache: fingerprint now "3813,2022-10-18 07:11:35 +0000 UTC"
2022/10/18 11:32:36 INFO  : cache/thumbnails/3/a/a/3aac1f6b87c6d3fda2038c3102f3fd8aad6a4e31_100x100_center.jpg: vfs cache: upload succeeded try #1

Animosity022 · October 18, 2022, 11:30am

Sorry as I'm still confused.

The log file only has 1 second of a log and there isn't a rc command in what you posted.

What's the problem? Is the mount not ready?

Can you share the full log and not snippets?

dennis_de · October 18, 2022, 11:47am

Exactly, the mount is not available until all files that are pending have been uploaded. And it may be that I didn't have the test what the config excerpt is rc on, that was just a hint I noticed independently.

Animosity022 · October 18, 2022, 11:48am

Can you please share the full debug log?

dennis_de · October 18, 2022, 12:05pm

The complete file is just over 40 MB, here are the first 1000 lines... but also there nothing will be recognizable... except that the uploads are running...

I and colleagues have noticed this problem with rclone before, I just had the time to make an issue about it. When rclone exits and there are still uploads pending, the mount uploads before the next start.

rclone.log (155.6 KB)

Animosity022 · October 18, 2022, 12:18pm

There we go.

That's because it has to check each file against the backend to see if something changed.

Issue about that already:

Reduce startup time with vfs cache (writes/full) · Issue #4595 · rclone/rclone (github.com)

I don't see any numbers though on how many items as that's just a snippet of a log as well so that is what I'm assuming the issue is.

dennis_de · October 18, 2022, 12:38pm

Unfortunately, the number of entries does not appear in the log. That which is known (example):

2022/10/18 09:51:42 INFO  : vfs cache: cleaned: objects 47059 (was 47059) in use 41919, to upload 41887, uploading 32, total size 2.788Gi (was 2.788Gi)

The message does not appear until rclone is completely started. I understand that it needs to validate the files, but the fact that the upload must be completed is a hindrance.

Animosity022 · October 18, 2022, 1:04pm

The uploads don't need to be completed.

Each file needs to be checked against the backend to make sure what you have locally on disk hasn't changed on the remote.

Agree it's a hindrance and someone has to pick up the issue, find the time and fix it. There are many ways to assist in that as you can always submit a PR (not a developer myself), you can find someone else to submit a PR or fund someone to do a PR.

It's been open for 2 years so far so while annoying, doesn't seem to have caught much steam to fix.

dennis_de · October 18, 2022, 1:35pm

Are you sure about that? In my tests/experiences, it looks different.

Because when all the files are uploaded and I restart, the startup process takes a few seconds to probably synchronize the files once. Or does it not do that then?

I'm a developer but I'm not a Go developer and I don't know rclone well enough to support it, unfortunately. What I can participate financially as compensation.

Animosity022 · October 18, 2022, 1:48pm

Yes, very much so:

2022/10/18 09:47:14 INFO  : vfs cache: cleaned: objects 3467 (was 3467) in use 2, to upload 2, uploading 0, total size 499.974Gi (was 499.974Gi)

as my example and my mount is available.

I use an hour delay so I routinely don't upload things on reboots and such.

It's the # of files that are compared that is the challenge.

system · November 17, 2022, 1:49pm

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