Multiple --cache-dir subdirs for the same remote

Suspected Bug
1

What is the problem you are having with rclone?

I noticed that at some point I lost more disk space than expected.

I looked into rclone's --cache-dir that I set for a mount, and found 3 directories for the same remote:

$ du -sh RCloneCache/vfs/*
1.4T    RCloneCache/vfs/B2{AAAAA}
123G	RCloneCache/vfs/B2{BBBBB}
45G	    RCloneCache/vfs/B2{CCCCC}

$ du -sh RCloneCache/vfsMeta/*
13M	    RCloneCache/vfsMeta/B2{AAAAA}
9.3M	RCloneCache/vfsMeta/B2{BBBBB}
9.1M	RCloneCache/vfsMeta/B2{CCCCC}

(I redacted unique strings, because wasn't sure if they're safe to share.)

The mount has --vfs-cache-max-size 1400G, so cumulatively these 3 directories are over limit. Their content is mirroring the same remote, with different files stored locally.

How could I reunite them?

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

Note: I'm pretty sure this started before I switched to the "deadlock fix" version, but it may have started after the new B2 concurrency code. I'm not sure on the latter.

rclone v1.65.0-beta.7391.55c3c221b.fix-b2-upload-url-lock
- os/version: ubuntu 22.04 (64 bit)
- os/kernel: 5.15.0-84-generic (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)

B2

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

/usr/bin/rclone mount B2:Bucket/path /path/to/mount \
  --allow-other \
  --b2-chunk-size 50M \
  --b2-upload-concurrency 4 \
  --multi-thread-streams 40 \
  --b2-hard-delete \
  --buffer-size 50M \
  --bwlimit "07:00,1M:off 23:45,off" \
  --cache-dir /home/user/RCloneCache \
  --config /home/user/.config/rclone/rclone.conf \
  --dir-cache-time 87600h \
  --disable-http2 \
  --fast-list \
  --log-level DEBUG \
  --poll-interval 0 \
  --transfers 20 \
  --use-mmap \
  --vfs-cache-max-age 8760h \
  --vfs-cache-max-size 1400G \
  --vfs-cache-mode full \
  --vfs-write-back 15m \
  --vfs-read-ahead 200M \
  --vfs-read-chunk-size-limit 500M \
  --rc \
  --rc-no-auth

The rclone config contents with secrets removed.

[B2]
type = b2
account = *removed*
key = *removed*

A log from the command with the -vv flag

Didn't catch the issue when it occurred.

2

Odds are more likely you've changed the remote name/config as that would make a new entry like you are saying.

Your output doesn't make sense to me either as it should be just the remote name so "B2", nothing else after that.

Debug log would be great.

3

Just noticed that the 2 new directories were created Sep 23, 2023 and Sep 24, 2023. This was after I jumped to v1.65.0 (first time getting the refactored B2 code), but before I switched to deadlock fix branch.

The config hasn't been changed since 2019.

$ stat .config/rclone/rclone.conf
Access: 2023-09-25 23:37:14.503939021 -0400
Modify: 2019-06-29 14:31:50.273889934 -0400
Change: 2019-06-29 14:31:50.273889934 -0400
 Birth: 2019-06-27 00:53:52.983508710 -0400

I believe it uses its own digest / fingerprint value that it adds to the remote name. Remember seeing it in code a while ago.

I checked, and unfortunately journalctl in my case doesn't go back to Sep 23/24 already, probably because I enabled DEBUG mode for another issue and it since rotated logs due to increased volume.

Hm, could this issue happen if data on B2 remote was modified manually? Is that what the random string on the directory name represents — a digest of complete remote state?

4

The debug log would be superb as that shows it:

[felix@gemini ~]$ rclone mount DB: /home/felix/test --cache-dir /tmp --vfs-cache-mode full -vv
2023/09/27 14:48:16 DEBUG : Setting --config "/opt/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/opt/rclone/rclone.conf"
2023/09/27 14:48:16 DEBUG : rclone: Version "v1.64.0" starting with parameters ["rclone" "mount" "DB:" "/home/felix/test" "--cache-dir" "/tmp" "--vfs-cache-mode" "full" "-vv"]
2023/09/27 14:48:16 DEBUG : Creating backend with remote "DB:"
2023/09/27 14:48:16 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2023/09/27 14:48:16 DEBUG : DB: Loaded invalid token from config file - ignoring
2023/09/27 14:48:16 DEBUG : Saving config "token" in section "DB" of the config file
2023/09/27 14:48:16 DEBUG : Keeping previous permissions for config file: -rwxrwxr-x
2023/09/27 14:48:16 DEBUG : DB: Saved new token in config file
2023/09/27 14:48:16 DEBUG : vfs cache: root is "/tmp"
2023/09/27 14:48:16 DEBUG : vfs cache: data root is "/tmp/vfs/DB"
2023/09/27 14:48:16 DEBUG : vfs cache: metadata root is "/tmp/vfsMeta/DB"
2023/09/27 14:48:16 DEBUG : Creating backend with remote "/tmp/vfs/DB/"
2023/09/27 14:48:16 DEBUG : fs cache: renaming cache item "/tmp/vfs/DB/" to be canonical "/tmp/vfs/DB"
2023/09/27 14:48:16 DEBUG : Creating backend with remote "/tmp/vfsMeta/DB/"
2023/09/27 14:48:16 DEBUG : fs cache: renaming cache item "/tmp/vfsMeta/DB/" to be canonical "/tmp/vfsMeta/DB"
2023/09/27 14:48:16 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/09/27 14:48:16 DEBUG : Dropbox root '': Mounting on "/home/felix/test"
2023/09/27 14:48:16 DEBUG : : Root:
2023/09/27 14:48:16 DEBUG : : >Root: node=/, err=<nil>
^C2023/09/27 14:48:20 INFO  : Signal received: interrupt
2023/09/27 14:48:20 INFO  : Dropbox root '': Committing uploads - please wait...
2023/09/27 14:48:20 DEBUG : vfs cache: cleaner exiting
2023/09/27 14:48:20 ERROR : /home/felix/test: Unmounted rclone mount
2023/09/27 14:48:20 INFO  : Exiting...
2023/09/27 14:48:20 DEBUG : rclone: Version "v1.64.0" finishing with parameters ["rclone" "mount" "DB:" "/home/felix/test" "--cache-dir" "/tmp" "--vfs-cache-mode" "full" "-vv"]

In my case, the remote is DB and my cache dir is named the same as the remote.

Just a quick test to show.

If you run a quick test with debug, that would show the issue and if it's something odd with the beta branch or not.

5

I'm always running with debug currently. Just grepped the entire log history for the word canonical (goes back only a couple of days) and it did find this:

Sep 25 23:37:17 htpc rclone[252704]: DEBUG : fs cache: renaming cache item "B2:Bucket/path" to be canonical "B2{BBBBB}:Bucket/path"

BBBBB is 5 alphanumerics corresponding to the 123G RCloneCache/vfs/B2{BBBBB} directory from my original post.

P.S. Thank you for that log sample btw, it reminded me that it's called "canonical name". I was trying to search codebase for it.

6

If you can share the full log, I'm happy to help as I've asked a few times.

7

The full log is over 6 million lines over 2 days. I don't think I can share that. Trying to find a relevant part. Here are lines around "vfs cache: data root".

Sep 25 23:35:58 htpc rclone[164069]: INFO  : vfs cache: cleaned: objects 2011 (was 2011) in use 94, to upload 74, uploading 20, total size 63.731Gi (was 63.731Gi)
Sep 25 23:36:38 htpc systemd[1]: htpc-mount.service: Failed with result 'timeout'.
Sep 25 23:36:38 htpc systemd[1]: Stopped B2 HTPC Mount.
Sep 25 23:36:38 htpc systemd[1]: htpc-mount.service: Consumed 46min 3.574s CPU time.
Sep 25 23:37:16 htpc systemd[1]: Starting B2 HTPC Mount...
Sep 25 23:37:16 htpc rclone[252704]: INFO  : Starting bandwidth limiter at 1Mi:off Byte/s
Sep 25 23:37:16 htpc rclone[252704]: DEBUG : rclone: systemd logging support activated
Sep 25 23:37:16 htpc rclone[252704]: NOTICE: Serving remote control on http://127.0.0.1:5572/
Sep 25 23:37:16 htpc rclone[252704]: NOTICE: --fast-list does nothing on a mount
Sep 25 23:37:16 htpc rclone[252704]: DEBUG : Creating backend with remote "B2:Bucket/path"
Sep 25 23:37:16 htpc rclone[252704]: DEBUG : Using config file from "/home/htpc/.config/rclone/rclone.conf"
Sep 25 23:37:16 htpc rclone[252704]: DEBUG : B2: detected overridden config - adding "{BBBBB}" suffix to name
Sep 25 23:37:17 htpc rclone[252704]: DEBUG : Couldn't decode error response: EOF
Sep 25 23:37:17 htpc rclone[252704]: DEBUG : fs cache: renaming cache item "B2:Bucket/path" to be canonical "B2{BBBBB}:Bucket/path"
Sep 25 23:37:17 htpc rclone[252704]: DEBUG : vfs cache: root is "/home/htpc/RCloneCache"
Sep 25 23:37:17 htpc rclone[252704]: DEBUG : vfs cache: data root is "/home/htpc/RCloneCache/vfs/B2{BBBBB}/Bucket/path"
Sep 25 23:37:17 htpc rclone[252704]: DEBUG : vfs cache: metadata root is "/home/htpc/RCloneCache/vfsMeta/B2{BBBBB}/Bucket/path"
Sep 25 23:37:17 htpc rclone[252704]: DEBUG : Creating backend with remote "/home/htpc/RCloneCache/vfs/B2{BBBBB}/Bucket/path"
Sep 25 23:37:17 htpc rclone[252704]: DEBUG : Creating backend with remote "/home/htpc/RCloneCache/vfsMeta/B2{BBBBB}/Bucket/path"

After this, it goes on to work on specific files stored in the mount.

8

Right, I don't need the full log. Just a snippet with a test is fine.

Are you using any environment variables anywhere else to override the config?

9

No.

$ env | grep RCLONE
$

However, here's the rest of my systemd service:

[Unit]
Description=redacted
AssertPathIsDirectory=/home/htpc/path/to/mount

[Service]
Type=notify
ExecStart=*redacted, already pasted in OP*
ExecStop=/bin/fusermount -uz /home/htpc/path/to/mount
ExecStop=/bin/sh -c 'while kill -0 $MAINPID 2>/dev/null; do sleep 0.5; done'
ExecStartPost=/usr/bin/rclone rc vfs/refresh recursive=true --rc-addr 127.0.0.1:5572 _async=true
Restart=on-failure
RestartSec=10
User=htpc
Group=htpc
TimeoutStartSec=3600
TimeoutStopSec=300

[Install]
WantedBy=multi-user.target

I don't remember why I have ExecStartPost up there, and wonder if it might be relevant to the issue.

Update: I did restart the mount in those days, and I may have done it ungracefully, because something froze (as per another issue).

I'm very curious what is the basis for the canonical name string. Going to try dig into code.

10

I know it changed at some point over the last year or so and I thought my memory was that it was an environment variable overriding something so that's what is confusing to me.

11

Here:

12

You're right that it seems config-related. Maybe more config than I expected (not just the one in rclone/config file). In the past few days I did change the following mount parameters (due to that other issue):

--transfers
--buffer-size
--b2-upload-concurrency
--multi-thread-streams

And even though I haven't touched any --vfs-* parameters, this seems to suggest that any filesystem-related configs could affect it (I haven't gotten to the bottom of it yet, just making assumptions for now).

13

Yeah, based on this comment, it seems that overrides can come from command line flags too.

// Overridden discovers which config items have been overridden in the
// configmap passed in, either by the config string, command line
// flags or environment variables

That said, I'm struggling to follow this any deeper, to find out which exact arguments can have this effect. Also, this could still be a bug in that the canonical hex wasn't supposed to change from my actions.

I guess, I would just need to figure out which cache dir is being used now, and delete the other 2? Or stop the mount, copy the biggest cache into the dir being used, and start again? Going to hold off messing with it until we're more certain.

14

I think it just renames the remote name, but that would cause a problem with the cache dir changing as I think that's a bug/unintended impact (maybe). There might be a valid reason to not share the cache with certain parameters, but as I've not seen something like that prior to today so new to me as well.

15

Another part of the reason why it's a real issue: some files that were added to the mount, but haven't had a chance to get uploaded yet are now stuck in the old cache dir, so will never get uploaded. Will have to add them to the mount again manually to recover.

16

Added an issue about this.

17

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