Google Drive: rclone rc operations/mkdir fails on repeats

1xe · July 9, 2020, 10:07pm

What is the problem you are having with rclone?

Using rclone rc operations/mkdir, creating a directory, deleting it, and then creating it again fails, and appears to do so silently (nothing in the log suggests a problem, at least to me).

Using rclone mkdir works correctly in this case.

What is your rclone version (output from `rclone version`)

rclone v1.52.2-132-g61e4b4db-beta
- os/arch: linux/amd64
- go version: go1.14.4

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

Devuan 3.0, 64 bit

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

Google Drive

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

$ rclone lsf drive:
rclone/
$ rclone rc operations/mkdir fs=drive: remote="test" -vv
2020/07/09 21:30:12 DEBUG : rclone: Version "v1.52.2-132-g61e4b4db-beta" starting with parameters ["rclone" "rc" "operations/mkdir" "fs=drive:" "remote=test" "-vv"]
{}
2020/07/09 21:30:13 DEBUG : 4 go routines active
$ rclone lsf drive:
rclone/
test/
$ rclone purge drive:test
$ rclone lsf drive:
rclone/
$ rclone rc operations/mkdir fs=drive: remote="test" -vv
2020/07/09 21:30:45 DEBUG : rclone: Version "v1.52.2-132-g61e4b4db-beta" starting with parameters ["rclone" "rc" "operations/mkdir" "fs=drive:" "remote=test" "-vv"]
{}
2020/07/09 21:30:45 DEBUG : 4 go routines active
$ rclone lsf drive:
rclone/
$ rclone purge drive:test
2020/07/09 21:31:01 ERROR : Attempt 1/3 failed with 1 errors and: directory not found
2020/07/09 21:31:01 ERROR : Attempt 2/3 failed with 1 errors and: directory not found
2020/07/09 21:31:02 ERROR : Attempt 3/3 failed with 1 errors and: directory not found
2020/07/09 21:31:02 Failed to purge: directory not found
$

The rclone config contents with secrets removed.

[drive]
type = drive
scope = drive,drive.appfolder
service_account_file = <file path>
impersonate = <email address>
server_side_across_configs = true

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

# rclone mount drive: /mnt/remote --rc --rc-no-auth -vv
2020/07/09 21:29:49 DEBUG : rclone: Version "v1.52.2-132-g61e4b4db-beta" starting with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]
2020/07/09 21:29:49 NOTICE: Serving remote control on http://127.0.0.1:5572/
2020/07/09 21:29:49 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/07/09 21:29:49 DEBUG : Google drive root '': Mounting on "/mnt/remote"
2020/07/09 21:29:49 DEBUG : Adding path "vfs/forget" to remote control registry
2020/07/09 21:29:49 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/07/09 21:29:49 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/07/09 21:29:49 DEBUG : : Root:
2020/07/09 21:29:49 DEBUG : : >Root: node=/, err=<nil>
2020/07/09 21:30:12 DEBUG : rc: "operations/mkdir": with parameters map[fs:drive: remote:test]
2020/07/09 21:30:12 DEBUG : test: Making directory
2020/07/09 21:30:13 DEBUG : rc: "operations/mkdir": reply map[]: <nil>
2020/07/09 21:30:45 DEBUG : rc: "operations/mkdir": with parameters map[fs:drive: remote:test]
2020/07/09 21:30:45 DEBUG : test: Making directory
2020/07/09 21:30:45 DEBUG : rc: "operations/mkdir": reply map[]: <nil>
2020/07/09 21:30:49 DEBUG : Google drive root '': Checking for changes on remote
2020/07/09 21:30:50 DEBUG : : changeNotify: relativePath="test", type=2
2020/07/09 21:30:50 DEBUG : : >changeNotify:
^C2020/07/09 21:31:06 DEBUG : rclone: Version "v1.52.2-132-g61e4b4db-beta" finishing with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]

ncw · July 10, 2020, 3:27pm

I tried to replicate this with the latest beta v1.52.2-211-g0792f472-beta but I couldn't replicate it.

Can you try that version?

I didn't see anything obvious in the change log which might fix it except for possibly 8d5bc7f28b8459a0e04fdbfd2dca43c5d9ec4555

1xe · July 10, 2020, 4:54pm

I just did. It didn't fix the problem. I still need to restart the server before each attempt to recreate the directory. Any other suggestions?

Here's an additional piece of information: the second (failing) call of operations/mkdir returns much faster than the first one, which suggests to me that the failing call generates no network traffic between my box and Google.

$ rclone lsf drive:
rclone/
$ time rclone rc operations/mkdir fs=drive: remote="test" -vv
2020/07/10 17:08:18 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "rc" "operations/mkdir" "fs=drive:" "remote=test" "-vv"]
{}
2020/07/10 17:08:20 DEBUG : 4 go routines active

real	0m1.261s
user	0m0.016s
sys	0m0.010s
$ rclone lsf drive:
rclone/
test/
$ rclone purge drive:test
$ rclone lsf drive:
rclone/
$ time rclone rc operations/mkdir fs=drive: remote="test" -vv
2020/07/10 17:08:52 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "rc" "operations/mkdir" "fs=drive:" "remote=test" "-vv"]
{}
2020/07/10 17:08:52 DEBUG : 4 go routines active

real	0m0.024s
user	0m0.021s
sys	0m0.011s
$ rclone lsf drive:
rclone/
$

ncw · July 10, 2020, 10:13pm

That probably means that the dir didn't get removed from the directory cache.

I tried this with a dir not at the root I just noticed. Can you try that too? It might be this is only a problem with things in the root.

1xe · July 11, 2020, 8:39am

I just did and it doesn't seem to make a difference (or I'm doing it wrong):

$ rclone lsf drive:
rclone/
$ time rclone rc operations/mkdir fs=drive: remote="dir1" -vv
2020/07/11 08:25:42 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "rc" "operations/mkdir" "fs=drive:" "remote=dir1" "-vv"]
{}
2020/07/11 08:25:43 DEBUG : 4 go routines active

real	0m0.933s
user	0m0.021s
sys	0m0.007s
$ rclone lsf drive:
dir1/
rclone/
$ time rclone rc operations/mkdir fs=drive: remote="dir1/dir2" -vv
2020/07/11 08:25:58 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "rc" "operations/mkdir" "fs=drive:" "remote=dir1/dir2" "-vv"]
{}
2020/07/11 08:25:59 DEBUG : 4 go routines active

real	0m1.040s
user	0m0.022s
sys	0m0.007s
$ rclone lsf drive:dir1
dir2/
$ rclone purge drive:dir1/dir2
$ rclone lsf drive:dir1
$ time rclone rc operations/mkdir fs=drive: remote="dir1/dir2" -vv
2020/07/11 08:26:40 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "rc" "operations/mkdir" "fs=drive:" "remote=dir1/dir2" "-vv"]
{}
2020/07/11 08:26:40 DEBUG : 4 go routines active

real	0m0.022s
user	0m0.021s
sys	0m0.010s
$ rclone lsf drive:dir1
$

# rclone mount drive: /mnt/remote --rc --rc-no-auth -vv
2020/07/11 08:25:29 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]
2020/07/11 08:25:29 NOTICE: Serving remote control on http://127.0.0.1:5572/
2020/07/11 08:25:29 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/07/11 08:25:30 DEBUG : Google drive root '': Mounting on "/mnt/remote"
2020/07/11 08:25:30 DEBUG : : Root: 
2020/07/11 08:25:30 DEBUG : : >Root: node=/, err=<nil>
2020/07/11 08:25:42 DEBUG : rc: "operations/mkdir": with parameters map[fs:drive: remote:dir1]
2020/07/11 08:25:42 DEBUG : dir1: Making directory
2020/07/11 08:25:43 DEBUG : rc: "operations/mkdir": reply map[]: <nil>
2020/07/11 08:25:58 DEBUG : rc: "operations/mkdir": with parameters map[fs:drive: remote:dir1/dir2]
2020/07/11 08:25:58 DEBUG : dir1/dir2: Making directory
2020/07/11 08:25:59 DEBUG : rc: "operations/mkdir": reply map[]: <nil>
2020/07/11 08:26:30 DEBUG : Google drive root '': Checking for changes on remote
2020/07/11 08:26:30 DEBUG : : changeNotify: relativePath="dir1", type=2
2020/07/11 08:26:30 DEBUG : : >changeNotify: 
2020/07/11 08:26:30 DEBUG : : changeNotify: relativePath="dir1/dir2", type=2
2020/07/11 08:26:30 DEBUG : : >changeNotify: 
2020/07/11 08:26:40 DEBUG : rc: "operations/mkdir": with parameters map[fs:drive: remote:dir1/dir2]
2020/07/11 08:26:40 DEBUG : dir1/dir2: Making directory
2020/07/11 08:26:40 DEBUG : rc: "operations/mkdir": reply map[]: <nil>
^C2020/07/11 08:26:57 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" finishing with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]

ncw · July 11, 2020, 10:43am

Oh. I see the difference.

I ran the purge via the RC - if you try that does it work?

So the problem here is that the change notify isn't removing the directory from the cache I think. Do you agree?

1xe · July 11, 2020, 12:19pm

Indeed it does!

Sounds about right.

Now, my original problem actually involved the FUSE client. Here's a session that shows how it doesn't pick up the second call to rc operations/mkdir:

# ll /mnt/remote
total 0
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
# rclone rc operations/mkdir fs=drive: remote="dir1/dir2"
{}
# ll /mnt/remote
total 0
drwxr-xr-x 1 root root 0 Jul 11 11:58 dir1
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
ll /mnt/remote/dir1/
total 0
drwxr-xr-x 1 root root 0 Jul 11 11:58 dir2
# ll /mnt/remote/dir1/dir2/
total 0
# rm -rf /mnt/remote/dir1/
# ll /mnt/remote/          
total 0
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
# rclone rc operations/mkdir fs=drive: remote="dir1/dir2"
{}
# ll /mnt/remote/
total 0
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
# ll /mnt/remote/
total 0
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
# ll /mnt/remote/
total 0
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone

# rclone mount drive: /mnt/remote --rc --rc-no-auth -vv
2020/07/11 11:57:26 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]
2020/07/11 11:57:26 NOTICE: Serving remote control on http://127.0.0.1:5572/
2020/07/11 11:57:26 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/07/11 11:57:26 DEBUG : Google drive root '': Mounting on "/mnt/remote"
2020/07/11 11:57:26 DEBUG : : Root: 
2020/07/11 11:57:26 DEBUG : : >Root: node=/, err=<nil>
2020/07/11 11:57:36 DEBUG : /: Attr: 
2020/07/11 11:57:36 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:57:36 DEBUG : /: ReadDirAll: 
2020/07/11 11:57:37 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2020/07/11 11:57:37 DEBUG : /: Lookup: name="rclone"
2020/07/11 11:57:37 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/11 11:57:37 DEBUG : rclone/: Attr: 
2020/07/11 11:57:37 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:00 DEBUG : rc: "operations/mkdir": with parameters map[fs:drive: remote:dir1/dir2]
2020/07/11 11:58:00 DEBUG : dir1/dir2: Making directory
2020/07/11 11:58:02 DEBUG : rc: "operations/mkdir": reply map[]: <nil>
2020/07/11 11:58:26 DEBUG : Google drive root '': Checking for changes on remote
2020/07/11 11:58:27 DEBUG : : changeNotify: relativePath="dir1", type=2
2020/07/11 11:58:27 DEBUG : : invalidating directory cache
2020/07/11 11:58:27 DEBUG : : >changeNotify: 
2020/07/11 11:58:27 DEBUG : : changeNotify: relativePath="dir1/dir2", type=2
2020/07/11 11:58:27 DEBUG : : >changeNotify: 
2020/07/11 11:58:34 DEBUG : /: Attr: 
2020/07/11 11:58:34 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:34 DEBUG : /: ReadDirAll: 
2020/07/11 11:58:34 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/07/11 11:58:34 DEBUG : /: Lookup: name="dir1"
2020/07/11 11:58:34 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/11 11:58:34 DEBUG : dir1/: Attr: 
2020/07/11 11:58:34 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:34 DEBUG : /: Lookup: name="rclone"
2020/07/11 11:58:34 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/11 11:58:34 DEBUG : rclone/: Attr: 
2020/07/11 11:58:34 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:38 DEBUG : /: Attr: 
2020/07/11 11:58:38 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:38 DEBUG : /: ReadDirAll: 
2020/07/11 11:58:38 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/07/11 11:58:38 DEBUG : /: Lookup: name="dir1"
2020/07/11 11:58:38 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/11 11:58:38 DEBUG : dir1/: Attr: 
2020/07/11 11:58:38 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:38 DEBUG : /: Attr: 
2020/07/11 11:58:38 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:38 DEBUG : /: ReadDirAll: 
2020/07/11 11:58:38 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/07/11 11:58:38 DEBUG : /: Attr: 
2020/07/11 11:58:38 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:38 DEBUG : dir1/: ReadDirAll: 
2020/07/11 11:58:39 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 11:58:39 DEBUG : dir1/: Lookup: name="dir2"
2020/07/11 11:58:39 DEBUG : dir1/: >Lookup: node=dir1/dir2/, err=<nil>
2020/07/11 11:58:39 DEBUG : dir1/dir2/: Attr: 
2020/07/11 11:58:39 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:39 DEBUG : /: Attr: 
2020/07/11 11:58:39 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:39 DEBUG : /: Lookup: name="dir1"
2020/07/11 11:58:39 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/11 11:58:39 DEBUG : dir1/: Attr: 
2020/07/11 11:58:39 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:39 DEBUG : dir1/: ReadDirAll: 
2020/07/11 11:58:39 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 11:58:39 DEBUG : dir1/: Attr: 
2020/07/11 11:58:39 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:39 DEBUG : dir1/: ReadDirAll: 
2020/07/11 11:58:39 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 11:58:39 DEBUG : dir1/: Attr: 
2020/07/11 11:58:39 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:40 DEBUG : dir1/: Lookup: name="dir2"
2020/07/11 11:58:40 DEBUG : dir1/: >Lookup: node=dir1/dir2/, err=<nil>
2020/07/11 11:58:40 DEBUG : dir1/dir2/: Attr: 
2020/07/11 11:58:40 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:40 DEBUG : dir1/dir2/: ReadDirAll: 
2020/07/11 11:58:40 DEBUG : dir1/dir2/: >ReadDirAll: item=0, err=<nil>
2020/07/11 11:58:54 DEBUG : /: Lookup: name="dir1"
2020/07/11 11:58:54 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/11 11:58:54 DEBUG : dir1/: Attr: 
2020/07/11 11:58:54 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:54 DEBUG : dir1/: ReadDirAll: 
2020/07/11 11:58:54 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 11:58:54 DEBUG : dir1/: Attr: 
2020/07/11 11:58:54 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:54 DEBUG : dir1/: ReadDirAll: 
2020/07/11 11:58:54 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 11:58:54 DEBUG : dir1/: Lookup: name="dir2"
2020/07/11 11:58:54 DEBUG : dir1/: >Lookup: node=dir1/dir2/, err=<nil>
2020/07/11 11:58:54 DEBUG : dir1/dir2/: Attr: 
2020/07/11 11:58:54 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:58:54 DEBUG : dir1/dir2/: ReadDirAll: 
2020/07/11 11:58:54 DEBUG : dir1/dir2/: >ReadDirAll: item=0, err=<nil>
2020/07/11 11:58:54 DEBUG : dir1/: Remove: name="dir2"
2020/07/11 11:58:55 DEBUG : dir1: Added virtual directory entry vDel: "dir2"
2020/07/11 11:58:55 DEBUG : dir1/: >Remove: err=<nil>
2020/07/11 11:58:55 DEBUG : /: Remove: name="dir1"
2020/07/11 11:58:55 DEBUG : dir1: Rmdir: contains trashed file: "dir2"
2020/07/11 11:58:55 DEBUG : : Added virtual directory entry vDel: "dir1"
2020/07/11 11:58:55 DEBUG : /: >Remove: err=<nil>
2020/07/11 11:59:04 DEBUG : /: Attr: 
2020/07/11 11:59:04 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:59:04 DEBUG : /: ReadDirAll: 
2020/07/11 11:59:04 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2020/07/11 11:59:04 DEBUG : /: Lookup: name="rclone"
2020/07/11 11:59:04 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/11 11:59:04 DEBUG : rclone/: Attr: 
2020/07/11 11:59:04 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:59:10 DEBUG : rc: "operations/mkdir": with parameters map[fs:drive: remote:dir1/dir2]
2020/07/11 11:59:10 DEBUG : dir1/dir2: Making directory
2020/07/11 11:59:12 DEBUG : rc: "operations/mkdir": reply map[]: <nil>
2020/07/11 11:59:26 DEBUG : Google drive root '': Checking for changes on remote
2020/07/11 11:59:27 DEBUG : : changeNotify: relativePath="dir1", type=2
2020/07/11 11:59:27 DEBUG : : invalidating directory cache
2020/07/11 11:59:27 DEBUG : : >changeNotify: 
2020/07/11 11:59:27 DEBUG : : changeNotify: relativePath="dir1/dir2", type=2
2020/07/11 11:59:27 DEBUG : : >changeNotify: 
2020/07/11 11:59:32 DEBUG : /: Attr: 
2020/07/11 11:59:32 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 11:59:32 DEBUG : /: ReadDirAll: 
2020/07/11 11:59:32 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2020/07/11 11:59:32 DEBUG : /: Lookup: name="rclone"
2020/07/11 11:59:32 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/11 11:59:32 DEBUG : rclone/: Attr: 
2020/07/11 11:59:32 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 12:00:26 DEBUG : Google drive root '': Checking for changes on remote
2020/07/11 12:00:35 DEBUG : /: Attr: 
2020/07/11 12:00:35 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 12:00:35 DEBUG : /: ReadDirAll: 
2020/07/11 12:00:35 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2020/07/11 12:00:35 DEBUG : /: Lookup: name="rclone"
2020/07/11 12:00:35 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/11 12:00:35 DEBUG : rclone/: Attr: 
2020/07/11 12:00:35 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 12:01:26 DEBUG : Google drive root '': Checking for changes on remote
2020/07/11 12:01:30 DEBUG : /: Attr: 
2020/07/11 12:01:30 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 12:01:30 DEBUG : /: ReadDirAll: 
2020/07/11 12:01:30 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2020/07/11 12:01:30 DEBUG : /: Lookup: name="rclone"
2020/07/11 12:01:30 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/11 12:01:30 DEBUG : rclone/: Attr: 
2020/07/11 12:01:30 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
^C2020/07/11 12:01:33 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" finishing with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]

ncw · July 11, 2020, 5:53pm

Nice demo. I think that is the same problem.

However since both the mount and the RC server are working on the same backend instance there could be an additional means of synchronization.

In general if you want things to be consistent then do everything through the mount. If you change stuff out side the mount then invalidate the directory with the VFS rc.

I should try to fix the changenotify interaction with the dircache though, that should be reasonably simple.

1xe · July 11, 2020, 7:15pm

I'd much prefer to do everything through the mount, but for my purposes it's simply too slow compared to using rc commands with _async. Also, I need to use the new shortcuts feature which is only accessible through the backend shortcut command.

I tried that too (rc vfs/refresh), but didn't have much luck. Maybe it's the same problem? Here's a sample session:

# ll /mnt/remote/
total 0
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
# mkdir -p /mnt/remote/dir1/dir2
# ll /mnt/remote/
total 0
drwxr-xr-x 1 root root 0 Jul 11 18:58 dir1
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 11 18:58 dir2
# rclone purge drive:dir1/dir2
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 11 18:58 dir2
# rclone rc vfs/refresh dir=dir1 recursive=true    
{
	"result": {
		"dir1": "OK"
	}
}
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 11 18:58 dir2
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 11 18:58 dir2
#

# rclone mount drive: /mnt/remote --rc --rc-no-auth -vv
2020/07/11 18:58:19 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]
2020/07/11 18:58:19 NOTICE: Serving remote control on http://127.0.0.1:5572/
2020/07/11 18:58:19 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/07/11 18:58:19 DEBUG : Google drive root '': Mounting on "/mnt/remote"
2020/07/11 18:58:20 DEBUG : : Root: 
2020/07/11 18:58:20 DEBUG : : >Root: node=/, err=<nil>
2020/07/11 18:58:23 DEBUG : /: Attr: 
2020/07/11 18:58:23 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:24 DEBUG : /: ReadDirAll: 
2020/07/11 18:58:24 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2020/07/11 18:58:24 DEBUG : /: Lookup: name="rclone"
2020/07/11 18:58:24 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/11 18:58:24 DEBUG : rclone/: Attr: 
2020/07/11 18:58:24 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:29 DEBUG : /: Lookup: name="dir1"
2020/07/11 18:58:29 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/07/11 18:58:29 DEBUG : /: Mkdir: name="dir1"
2020/07/11 18:58:30 DEBUG : : Added virtual directory entry vAdd: "dir1"
2020/07/11 18:58:30 DEBUG : /: >Mkdir: node=dir1/, err=<nil>
2020/07/11 18:58:30 DEBUG : dir1/: Attr: 
2020/07/11 18:58:30 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:30 DEBUG : dir1/: Lookup: name="dir2"
2020/07/11 18:58:30 DEBUG : dir1/: >Lookup: node=<nil>, err=no such file or directory
2020/07/11 18:58:30 DEBUG : dir1/: Mkdir: name="dir2"
2020/07/11 18:58:31 DEBUG : dir1: Added virtual directory entry vAdd: "dir2"
2020/07/11 18:58:31 DEBUG : dir1/: >Mkdir: node=dir1/dir2/, err=<nil>
2020/07/11 18:58:31 DEBUG : dir1/dir2/: Attr: 
2020/07/11 18:58:31 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:35 DEBUG : /: Attr: 
2020/07/11 18:58:35 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:35 DEBUG : /: ReadDirAll: 
2020/07/11 18:58:35 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/07/11 18:58:35 DEBUG : dir1/: Attr: 
2020/07/11 18:58:35 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:35 DEBUG : /: Lookup: name="rclone"
2020/07/11 18:58:35 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/11 18:58:35 DEBUG : rclone/: Attr: 
2020/07/11 18:58:35 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:38 DEBUG : dir1/: Attr: 
2020/07/11 18:58:38 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:38 DEBUG : dir1/: ReadDirAll: 
2020/07/11 18:58:38 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 18:58:38 DEBUG : dir1/dir2/: Attr: 
2020/07/11 18:58:38 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:48 DEBUG : dir1/: Attr: 
2020/07/11 18:58:48 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:48 DEBUG : dir1/: ReadDirAll: 
2020/07/11 18:58:48 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 18:58:48 DEBUG : dir1/dir2/: Attr: 
2020/07/11 18:58:48 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:58:57 DEBUG : rc: "vfs/refresh": with parameters map[dir:dir1 recursive:true]
2020/07/11 18:58:57 DEBUG : dir1: Reading directory tree
2020/07/11 18:58:57 DEBUG : dir1: Reading directory tree done in 246.886607ms
2020/07/11 18:58:57 DEBUG : rc: "vfs/refresh": reply map[result:map[dir1:OK]]: <nil>
2020/07/11 18:59:01 DEBUG : dir1/: Attr: 
2020/07/11 18:59:01 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:59:01 DEBUG : dir1/: ReadDirAll: 
2020/07/11 18:59:01 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 18:59:01 DEBUG : dir1/dir2/: Attr: 
2020/07/11 18:59:01 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:59:20 DEBUG : Google drive root '': Checking for changes on remote
2020/07/11 18:59:20 DEBUG : : changeNotify: relativePath="dir1", type=2
2020/07/11 18:59:20 DEBUG : : invalidating directory cache
2020/07/11 18:59:20 DEBUG : dir1: invalidating directory cache
2020/07/11 18:59:20 DEBUG : : >changeNotify: 
2020/07/11 18:59:20 DEBUG : : changeNotify: relativePath="dir1/dir2", type=2
2020/07/11 18:59:20 DEBUG : : >changeNotify: 
2020/07/11 18:59:25 DEBUG : dir1/: Attr: 
2020/07/11 18:59:25 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/11 18:59:25 DEBUG : dir1/: ReadDirAll: 
2020/07/11 18:59:26 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/11 18:59:26 DEBUG : dir1/dir2/: Attr: 
2020/07/11 18:59:26 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
^C2020/07/11 18:59:29 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" finishing with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]
#

Looking forward to it!

ncw · July 14, 2020, 2:52pm

Your example did work for me?

$ ls  /mnt/tmp/dir1
dir2
$ rclone purge  TestDrive:test/dir1/dir2
$ ls  /mnt/tmp/dir1
dir2
$ rclone rc vfs/refresh dir=dir1 recursive=true
{
	"result": {
		"dir1": "OK"
	}
}
$ ls  /mnt/tmp/dir1
$

Is it repeatable it going wrong or does it only sometimes go wrong?

1xe · July 14, 2020, 3:29pm

It fails consistently:

# ll /mnt/remote
total 0
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
# mkdir -p /mnt/remote/dir1/dir2
# ll /mnt/remote
total 0
drwxr-xr-x 1 root root 0 Jul 14 15:03 dir1
drwxr-xr-x 1 root root 0 Jun 14 17:58 rclone
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 14 15:03 dir2
# rclone purge drive:dir1/dir2
# rclone lsf drive:dir1 -R
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 14 15:03 dir2
# rclone rc vfs/refresh dir=dir1 recursive=true 
{
	"result": {
		"dir1": "OK"
	}
}
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 14 15:03 dir2
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 14 15:03 dir2
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 14 15:03 dir2
# ll /mnt/remote/dir1
total 0
drwxr-xr-x 1 root root 0 Jul 14 15:03 dir2
#

# rclone mount drive: /mnt/remote --rc --rc-no-auth -vv
2020/07/14 15:02:47 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" starting with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]
2020/07/14 15:02:47 NOTICE: Serving remote control on http://127.0.0.1:5572/
2020/07/14 15:02:47 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/07/14 15:02:47 DEBUG : Google drive root '': Mounting on "/mnt/remote"
2020/07/14 15:02:48 DEBUG : : Root: 
2020/07/14 15:02:48 DEBUG : : >Root: node=/, err=<nil>
2020/07/14 15:02:57 DEBUG : /: Attr: 
2020/07/14 15:02:57 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:02:57 DEBUG : /: ReadDirAll: 
2020/07/14 15:02:57 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2020/07/14 15:02:57 DEBUG : /: Lookup: name="rclone"
2020/07/14 15:02:57 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/14 15:02:57 DEBUG : rclone/: Attr: 
2020/07/14 15:02:57 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:03:09 DEBUG : /: Lookup: name="dir1"
2020/07/14 15:03:09 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/07/14 15:03:09 DEBUG : /: Mkdir: name="dir1"
2020/07/14 15:03:10 DEBUG : : Added virtual directory entry vAdd: "dir1"
2020/07/14 15:03:10 DEBUG : /: >Mkdir: node=dir1/, err=<nil>
2020/07/14 15:03:10 DEBUG : dir1/: Attr: 
2020/07/14 15:03:10 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:03:10 DEBUG : dir1/: Lookup: name="dir2"
2020/07/14 15:03:10 DEBUG : dir1/: >Lookup: node=<nil>, err=no such file or directory
2020/07/14 15:03:10 DEBUG : dir1/: Mkdir: name="dir2"
2020/07/14 15:03:11 DEBUG : dir1: Added virtual directory entry vAdd: "dir2"
2020/07/14 15:03:11 DEBUG : dir1/: >Mkdir: node=dir1/dir2/, err=<nil>
2020/07/14 15:03:11 DEBUG : dir1/dir2/: Attr: 
2020/07/14 15:03:11 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:03:18 DEBUG : /: Attr: 
2020/07/14 15:03:18 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:03:18 DEBUG : /: ReadDirAll: 
2020/07/14 15:03:18 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/07/14 15:03:18 DEBUG : dir1/: Attr: 
2020/07/14 15:03:18 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:03:18 DEBUG : /: Lookup: name="rclone"
2020/07/14 15:03:18 DEBUG : /: >Lookup: node=rclone/, err=<nil>
2020/07/14 15:03:18 DEBUG : rclone/: Attr: 
2020/07/14 15:03:18 DEBUG : rclone/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:03:28 DEBUG : dir1/: Attr: 
2020/07/14 15:03:28 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:03:28 DEBUG : dir1/: ReadDirAll: 
2020/07/14 15:03:28 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/14 15:03:28 DEBUG : dir1/dir2/: Attr: 
2020/07/14 15:03:28 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:03:48 DEBUG : Google drive root '': Checking for changes on remote
2020/07/14 15:03:48 DEBUG : : changeNotify: relativePath="dir1", type=2
2020/07/14 15:03:48 DEBUG : : invalidating directory cache
2020/07/14 15:03:48 DEBUG : dir1: invalidating directory cache
2020/07/14 15:03:48 DEBUG : : >changeNotify: 
2020/07/14 15:03:48 DEBUG : : changeNotify: relativePath="dir1/dir2", type=2
2020/07/14 15:03:48 DEBUG : : >changeNotify: 
2020/07/14 15:04:09 DEBUG : dir1/: Attr: 
2020/07/14 15:04:09 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:04:09 DEBUG : dir1/: ReadDirAll: 
2020/07/14 15:04:09 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/14 15:04:09 DEBUG : dir1/dir2/: Attr: 
2020/07/14 15:04:09 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:04:26 DEBUG : rc: "vfs/refresh": with parameters map[dir:dir1 recursive:true]
2020/07/14 15:04:27 DEBUG : : Removed virtual directory entry vAdd: "dir1"
2020/07/14 15:04:27 DEBUG : dir1: Reading directory tree
2020/07/14 15:04:27 DEBUG : dir1: Reading directory tree done in 248.569057ms
2020/07/14 15:04:27 DEBUG : rc: "vfs/refresh": reply map[result:map[dir1:OK]]: <nil>
2020/07/14 15:04:36 DEBUG : /: Lookup: name="dir1"
2020/07/14 15:04:36 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/14 15:04:36 DEBUG : dir1/: Attr: 
2020/07/14 15:04:36 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:04:36 DEBUG : dir1/: ReadDirAll: 
2020/07/14 15:04:36 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/14 15:04:36 DEBUG : dir1/: Lookup: name="dir2"
2020/07/14 15:04:36 DEBUG : dir1/: >Lookup: node=dir1/dir2/, err=<nil>
2020/07/14 15:04:36 DEBUG : dir1/dir2/: Attr: 
2020/07/14 15:04:36 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:04:48 DEBUG : Google drive root '': Checking for changes on remote
2020/07/14 15:04:56 DEBUG : /: Lookup: name="dir1"
2020/07/14 15:04:56 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/14 15:04:56 DEBUG : dir1/: Attr: 
2020/07/14 15:04:56 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:04:56 DEBUG : dir1/: ReadDirAll: 
2020/07/14 15:04:56 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/14 15:04:56 DEBUG : dir1/: Lookup: name="dir2"
2020/07/14 15:04:56 DEBUG : dir1/: >Lookup: node=dir1/dir2/, err=<nil>
2020/07/14 15:04:56 DEBUG : dir1/dir2/: Attr: 
2020/07/14 15:04:56 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:05:42 DEBUG : /: Lookup: name="dir1"
2020/07/14 15:05:42 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/14 15:05:42 DEBUG : dir1/: Attr: 
2020/07/14 15:05:42 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:05:42 DEBUG : dir1/: ReadDirAll: 
2020/07/14 15:05:42 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/14 15:05:42 DEBUG : dir1/: Lookup: name="dir2"
2020/07/14 15:05:42 DEBUG : dir1/: >Lookup: node=dir1/dir2/, err=<nil>
2020/07/14 15:05:42 DEBUG : dir1/dir2/: Attr: 
2020/07/14 15:05:42 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:05:48 DEBUG : Google drive root '': Checking for changes on remote
2020/07/14 15:06:04 DEBUG : /: Lookup: name="dir1"
2020/07/14 15:06:04 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/14 15:06:04 DEBUG : dir1/: Attr: 
2020/07/14 15:06:04 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/07/14 15:06:04 DEBUG : dir1/: ReadDirAll: 
2020/07/14 15:06:04 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>
2020/07/14 15:06:04 DEBUG : dir1/: Lookup: name="dir2"
2020/07/14 15:06:04 DEBUG : dir1/: >Lookup: node=dir1/dir2/, err=<nil>
2020/07/14 15:06:04 DEBUG : dir1/dir2/: Attr: 
2020/07/14 15:06:04 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
^C2020/07/14 15:06:08 DEBUG : rclone: Version "v1.52.2-211-g0792f472-beta" finishing with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--rc" "--rc-no-auth" "-vv"]

ncw · July 15, 2020, 1:59pm

I think this depends on the exact timing of when the changenotify comes in

If you do it like this

$ mkdir -p /mnt/tmp/dir1/dir2
$ # wait for changenotify
$ ls -l /mnt/tmp/dir1
total 0
drwxrwxr-x 1 ncw ncw 0 Jul 15 14:22 dir2
$ rclone purge TestDrive:dir1/dir2
$ ls -l /mnt/tmp/dir1
total 0
drwxrwxr-x 1 ncw ncw 0 Jul 15 14:22 dir2
$ rclone rc vfs/refresh dir=dir1 recursive=true 
{
	"result": {
		"dir1": "OK"
	}
}
$ ls -l /mnt/tmp/dir1
total 0
$

Then it works fine.

Here is the important bit of the log

2020/07/15 14:22:22 DEBUG : dir1/: Mkdir: name="dir2"
2020/07/15 14:22:23 DEBUG : dir1: Added virtual directory entry vAdd: "dir2"
2020/07/15 14:22:23 DEBUG : dir1/: >Mkdir: node=dir1/dir2/, err=<nil>
2020/07/15 14:22:23 DEBUG : dir1/dir2/: Attr: 
2020/07/15 14:22:23 DEBUG : dir1/dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/07/15 14:23:11 DEBUG : Google drive root '': Checking for changes on remote
2020/07/15 14:23:11 DEBUG : : changeNotify: relativePath="dir1/dir2", type=2
2020/07/15 14:23:11 DEBUG : dir1: invalidating directory cache
2020/07/15 14:23:11 DEBUG : : >changeNotify: 
2020/07/15 14:23:18 DEBUG : /: Lookup: name="dir1"
2020/07/15 14:23:18 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/07/15 14:23:18 DEBUG : dir1/: Attr: 
2020/07/15 14:23:18 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/07/15 14:23:18 DEBUG : dir1/: ReadDirAll: 
2020/07/15 14:23:18 DEBUG : dir1: Removed virtual directory entry vAdd: "dir2"
2020/07/15 14:23:18 DEBUG : dir1/: >ReadDirAll: item=1, err=<nil>

Note the added virtual directory entry and importantly the removed virtual directory entry.

The virtual entries are added when for example a file is created - you want the file to appear in the listing but it hasn't actually been uploaded to google drive yet so rclone needs to keep track of it.

Rclone does the same for directory entries - you don't want to have to re-list the directory just because you created a directory - you are happy to keep that on trust. Rclone normally removes the virtual entries when it sees the item in the directory listing. However in the case of directories on remotes which can have empty directories, I think it should be removing the virtual item on a directory listing - there is no way directory listings can be created asynchronously in the same way files can.

Give this a go... It should fix the virtual directories hanging around. Note that you need to use vfs/forget not vfs/refresh to clear the directory cache (my mistake).

v1.52.2-215-g394a4b0a-fix-vfs-vdir-beta on branch fix-vfs-vdir (uploaded in 15-30 mins)

1xe · July 15, 2020, 4:47pm

Not on my build. It fails quite consistently.

I'd love to, but the linux build seems to be missing.

Anyway, thank you for the insight into what's going on.

1xe · July 30, 2020, 10:15am

Any chance of a linux build?

ncw · July 31, 2020, 11:53am

Sorry I'm having trouble making this work! Making this small change causes tests to break elsewhere and I haven't figured out why yet.

1xe · July 31, 2020, 12:11pm

Well, I'm glad to hear that you did not just forget about this issue.

Do you think a fix will be in v1.52.3?

ncw · July 31, 2020, 2:10pm

If I can make it work, yes!

system · September 30, 2020, 10:10am

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