Latency with crypt remote?

Suspected Bug
1

What is the problem you are having with rclone?

Is there an explanation for a ~ 5s-latency before a file can be accessed in a crypt remote ?

If needed I can post more details, but for now my question is more theoretical.
What I tried:

On the same computer, I have two rclone vfs crypt mounts

  • mounted on mount1 and mount2
  • using the same underlying local mount: source
  • using dir-cache-time=0s to discard the directory cache

The experiment:

If I copy a tiny file on mount1:

  • the file is not accessible nor readable on mount2: before ~ 5s
  • ls mount2 does not list the file before 5s
  • cat mount2/myfile returns an error before 5s

Is this latency expected or explainable ?

What is your rclone version (output from rclone version)

using rclone 1.55.1 and 1.56.0

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

ubuntu 16.04 64bits amd64

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

crypt over local

2

Without knowing your rclone.conf, rclone mount command and see a debug log, it's hard to see what's going on.

There isn't a 5 second latency with a crypt remote.

3

It's more complex than I anticipated:

On my computer, using a simple setting:

[crypt]
type = crypt
remote = encrypted/
filename_encryption = off
directory_name_encryption = false
# N.B: it is the cursory encryption of "toto" (not sensitive !!)
password = cZI9xrBcyNTt2c8zOm6vtJ_dNhk

that works fine.

The problem occurs in a setting where:

  • each mount runs in a separate docker container
  • both mounts are based on the same local docker volume, mounted as /storage
  • I checked that from both containers the /storage mount/volume is updated immediately (no lag)

the config is:

[local]
type = local

[crypt]
type = crypt
remote = local:/storage
filename_encryption = off
directory_name_encryption = false
# N.B: it is the cursory encryption of "toto" (not sensitive !!)
password = cZI9xrBcyNTt2c8zOm6vtJ_dNhk

the rclone mount commands are:
rclone mount --config rclone.conf crypt: decrypted2/ --dir-cache-time=0s -vv

the log from the receiver is:

> 2021/08/24 12:20:01 DEBUG : /: Lookup: name="date.txt"
> 2021/08/24 12:20:01 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
> 2021/08/24 12:20:03 DEBUG : /: Lookup: name="date.txt"
> 2021/08/24 12:20:03 DEBUG : : Re-reading directory (2.008578206s old)
> 2021/08/24 12:20:03 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
> 2021/08/24 12:20:05 DEBUG : /: Lookup: name="date.txt"
> 2021/08/24 12:20:05 DEBUG : : Re-reading directory (2.008604835s old)
> 2021/08/24 12:20:05 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
> 2021/08/24 12:20:07 DEBUG : /: Lookup: name="date.txt"
> 2021/08/24 12:20:07 DEBUG : : Re-reading directory (2.008533205s old)
> 2021/08/24 12:20:07 DEBUG : /: >Lookup: node=date.txt, err=<nil>
> 2021/08/24 12:20:07 DEBUG : date.txt: Attr: 
> 2021/08/24 12:20:07 DEBUG : date.txt: >Attr: a=valid=1s ino=0 size=29 mode=-rw-r--r--, err=<nil>

At 12:20:01 the file was already transferred and should have been available.
As you can see it was found only at 12:20:07.

Any idea ?

4

How is it copied there?

There's no log of anything being written. A file copy would look like:

felix@gemini:~$ rclone mount TEST: /test -vv --dir-cache-time 0s
2021/08/24 09:14:15 DEBUG : Setting --config "/opt/rclone/rclone.conf" from environment variable RCLONE_CONFIG="/opt/rclone/rclone.conf"
2021/08/24 09:14:15 DEBUG : Setting --user-agent "animosityapp" from environment variable RCLONE_USER_AGENT="animosityapp"
2021/08/24 09:14:15 DEBUG : Setting --rc-user "felix" from environment variable RCLONE_RC_USER="felix"
2021/08/24 09:14:15 DEBUG : Setting --rc-pass "felix" from environment variable RCLONE_RC_PASS="felix"
2021/08/24 09:14:15 DEBUG : Setting default for drive-pacer-min-sleep="10ms" from environment variable RCLONE_DRIVE_PACER_MIN_SLEEP
2021/08/24 09:14:15 DEBUG : Setting default for drive-pacer-burst="1000" from environment variable RCLONE_DRIVE_PACER_BURST
2021/08/24 09:14:15 DEBUG : rclone: Version "v1.56.0" starting with parameters ["rclone" "mount" "TEST:" "/test" "-vv" "--dir-cache-time" "0s"]
2021/08/24 09:14:15 DEBUG : Creating backend with remote "TEST:"
2021/08/24 09:14:15 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2021/08/24 09:14:15 DEBUG : Creating backend with remote "/home/felix/test"
2021/08/24 09:14:15 INFO  : Encrypted drive 'TEST:': poll-interval is not supported by this remote
2021/08/24 09:14:15 DEBUG : Encrypted drive 'TEST:': Mounting on "/test"
2021/08/24 09:14:15 DEBUG : : Root:
2021/08/24 09:14:15 DEBUG : : >Root: node=/, err=<nil>
2021/08/24 09:14:22 DEBUG : /: Attr:
2021/08/24 09:14:22 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/08/24 09:14:22 DEBUG : /: ReadDirAll:
2021/08/24 09:14:22 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2021/08/24 09:14:28 DEBUG : /: Attr:
2021/08/24 09:14:28 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/08/24 09:14:28 DEBUG : /: Lookup: name="hosts"
2021/08/24 09:14:28 DEBUG : : Re-reading directory (6.412827824s old)
2021/08/24 09:14:28 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2021/08/24 09:14:28 DEBUG : /: Lookup: name="hosts"
2021/08/24 09:14:28 DEBUG : : Re-reading directory (576.358µs old)
2021/08/24 09:14:28 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2021/08/24 09:14:28 DEBUG : /: Create: name="hosts"
2021/08/24 09:14:28 DEBUG : : Re-reading directory (537.165µs old)
2021/08/24 09:14:28 DEBUG : hosts: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2021/08/24 09:14:28 DEBUG : : Added virtual directory entry vAddFile: "hosts"
2021/08/24 09:14:28 DEBUG : hosts: >Open: fd=hosts (w), err=<nil>
2021/08/24 09:14:28 DEBUG : /: >Create: node=hosts, handle=&{hosts (w)}, err=<nil>
2021/08/24 09:14:28 DEBUG : hosts: Attr:
2021/08/24 09:14:28 DEBUG : hosts: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2021/08/24 09:14:28 DEBUG : &{hosts (w)}: Write: len=129, offset=0
2021/08/24 09:14:28 DEBUG : : Added virtual directory entry vAddFile: "hosts"
2021/08/24 09:14:28 DEBUG : &{hosts (w)}: >Write: written=129, err=<nil>
2021/08/24 09:14:28 DEBUG : &{hosts (w)}: Flush:
2021/08/24 09:14:28 DEBUG : Encrypted drive 'TEST:': File to upload is small (129 bytes), uploading instead of streaming
2021/08/24 09:14:28 DEBUG : hosts: md5 = 7c244f4f5e1c296b7dc7f13db8acac5e OK
2021/08/24 09:14:28 INFO  : hosts: Copied (new)
2021/08/24 09:14:28 DEBUG : : Added virtual directory entry vAddFile: "hosts"
2021/08/24 09:14:28 DEBUG : &{hosts (w)}: >Flush: err=<nil>
2021/08/24 09:14:28 DEBUG : &{hosts (w)}: Release:
2021/08/24 09:14:28 DEBUG : hosts: WriteFileHandle.Release nothing to do
2021/08/24 09:14:28 DEBUG : &{hosts (w)}: >Release: err=<nil>
2021/08/24 09:14:30 DEBUG : /: Attr:
2021/08/24 09:14:30 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/08/24 09:14:30 DEBUG : /: ReadDirAll:
2021/08/24 09:14:30 DEBUG : : Re-reading directory (1.83241075s old)
2021/08/24 09:14:30 DEBUG : : Removed virtual directory entry vAddFile: "hosts"
2021/08/24 09:14:30 DEBUG : /: >ReadDirAll: item=3, err=<nil>
2021/08/24 09:14:30 DEBUG : /: Attr:
2021/08/24 09:14:30 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2021/08/24 09:14:30 DEBUG : hosts: Attr:
2021/08/24 09:14:30 DEBUG : hosts: >Attr: a=valid=1s ino=0 size=129 mode=-rw-rw-r--, err=<nil>
5

this is the log of the second server (second mount).

6

I'm not following how the file is getting there or what's mounted as you have one log and no process flow.

can you share the full set of steps?

7
  • the date.txt file is copied to mount1/date.txt [in container1]
    • the rclone server1 intercepts it, encrypts it and stores it as /storage/date.txt.bin
  • after that I query that file: mount2/date.txt [in container2]
    • the rclone server2 intercepts it and looks if it can find the file (on its encrypted remote backend /storage [a docker volume, so basically a shared host folder between)
    • but it can not find it before a ~ 5s delay
    • I've checked that the /storage/date.txt.bin is immediately accessible from container2

So there are 2 rclone servers on the same backend. But copying to one does not update the other in a timely fashion, even though dir-cache-time=0s.

8

Works fine for me:

image
image1025×878 257 KB

I'd suggest validating it works without an overly complex setup and add pieces.

9

I'd suggest validating it works without an overly complex setup and add pieces.

makes sense. I was asking in case there was an obvious reason for that lag in that type of setting.
thanks.

10

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