Borg lock.exclusive recreated after vfs-write-back

What is the problem you are having with rclone?

Hi,

I use a rclone mounted cloud as Borg Backup target. Borg seems to exclusively lock the target directory as follows:

  • create a directory lock.exclusive.????????.tmp (???????? = random alphanumeric characters)
  • create a file in this directory hostname.domain@some-id.some-id-0
  • rename the lock.exclusive.????????.tmp to lock.exclusive
  • run the backup
  • delete the lock.exclusive when finished

Now, Borg often complains that the lock.exclusive already exists and either removes it as stale or fails.

Therefore, I tried to reproduce this with simple shell commands:
rclone -vv mount --cache-dir=/tmp/rclone_vfscache/ --vfs-cache-mode=writes --vfs-cache-max-age=10m --vfs-write-back=300s --vfs-cache-max-size 1G pCloud: /mnt/tmp

mkdir lock.exclusive.fqcy8a1x.tmp && echo dummy > lock.exclusive.fqcy8a1x.tmp/blub@blub.blub && mv lock.exclusive.fqcy8a1x.tmp lock.exclusive && sleep 15 && rm -rf lock.exclusive

At first, the result is as expected. The directory lock.exclusive with file blub@blub.blub is in the mount dir for about 15 seconds and then deleted.

But then, after the vfs-write-back-time of 5 minutes, the lock.exclusive with file blub@blub.blub magically reappears in the mount dir and also in the cloud.

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

rclone v1.61.1

  • os/version: debian 11.6 (64 bit)
  • os/kernel: 5.10.0-21-amd64 (x86_64)
  • os/type: linux
  • os/arch: amd64
  • go/version: go1.19.4
  • go/linking: static
  • go/tags: none

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

Seems to be independent of cloud storage.

  • pCloud
  • GMX via WebDAV
  • Getspace via WebDAV

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

rclone -vv mount --cache-dir=/tmp/rclone_vfscache/ --vfs-cache-mode=writes --vfs-cache-max-age=10m --vfs-write-back=300s --vfs-cache-max-size 1G pCloud: /mnt/tmp/

The rclone config contents with secrets removed.

[pCloud]
type = pcloud
hostname = eapi.pcloud.com
token = {"access_token":"xxx","token_type":"bearer","expiry":"0001-01-01T00:00:00Z"}

A log from the command with the -vv flag

See attachment (30000 characters limit)
rclone_full_log.txt (41.6 KB)

Here only without DEBUG:

root@jdr-z83:/# rclone -vv mount --cache-dir=/tmp/rclone_vfscache/ --vfs-cache-mode=writes --vfs-cache-max-age=10m --vfs-write-back=300s --vfs-cache-max-size 1G pCloud: /mnt/tmp/
2023/03/04 10:30:32 INFO  : pcloud root '': poll-interval is not supported by this remote
2023/03/04 10:30:32 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/03/04 10:31:31 INFO  : lock.exclusive.fqcy8a1x.tmp/blub@blub.blub: vfs cache: queuing for upload in 5m0s
2023/03/04 10:31:32 INFO  : lock.exclusive.fqcy8a1x.tmp/blub@blub.blub: vfs cache: renamed in cache to "lock.exclusive/blub@blub.blub"
2023/03/04 10:31:32 INFO  : lock.exclusive.fqcy8a1x.tmp: Removing directory
2023/03/04 10:31:32 INFO  : lock.exclusive.fqcy8a1x.tmp: Removing directory
2023/03/04 10:31:32 INFO  : lock.exclusive.fqcy8a1x.tmp/: vfs cache: renamed dir in cache to "lock.exclusive/"
2023/03/04 10:31:32 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 6 (was 6)
2023/03/04 10:32:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 1, to upload 1, uploading 0, total size 6 (was 6)
2023/03/04 10:33:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 1, to upload 1, uploading 0, total size 6 (was 6)
2023/03/04 10:34:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 1, to upload 1, uploading 0, total size 6 (was 6)
2023/03/04 10:35:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 1, to upload 1, uploading 0, total size 6 (was 6)
2023/03/04 10:36:32 INFO  : lock.exclusive/blub@blub.blub: Copied (new)
2023/03/04 10:36:32 INFO  : lock.exclusive/blub@blub.blub: vfs cache: upload succeeded try #1
2023/03/04 10:36:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 6 (was 6)
2023/03/04 10:37:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 6 (was 6)
2023/03/04 10:38:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 6 (was 6)
2023/03/04 10:39:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 6 (was 6)
2023/03/04 10:40:32 INFO  : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 6 (was 6)
2023/03/04 10:41:32 INFO  : lock.exclusive/blub@blub.blub: vfs cache: removed cache file as Removing old cache file not in use
2023/03/04 10:41:32 INFO  : vfs cache RemoveNotInUse (maxAge=600000000000, emptyOnly=false): item lock.exclusive/blub@blub.blub was removed, freed 6 bytes
2023/03/04 10:41:32 INFO  : vfs cache: cleaned: objects 1 (was 2) in use 0, to upload 0, uploading 0, total size 0 (was 6)
2023/03/04 10:42:32 INFO  : vfs cache RemoveNotInUse (maxAge=600000000000, emptyOnly=false): item lock.exclusive.fqcy8a1x.tmp/blub@blub.blub was removed, freed 0 bytes
2023/03/04 10:42:32 INFO  : vfs cache: cleaned: objects 0 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/03/04 10:43:32 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/03/04 10:44:32 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/03/04 10:45:32 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/03/04 10:46:32 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
^C2023/03/04 10:46:49 INFO  : Signal received: interrupt
2023/03/04 10:46:49 ERROR : /mnt/tmp/: Unmounted rclone mount
2023/03/04 10:46:49 INFO  : Exiting...

I opened an issue for this.

Thank you - you've made a nice repro in the bug report :slight_smile:

The fix is now merged in the latest beta and will be in v1.62