Google Drive: directories with shortcuts cannot be removed via a mounted remote

Suspected Bug
1

What is the problem you are having with rclone?

Directories with shortcuts cannot be removed via a mounted remote.

What is your rclone version (output from rclone version)

rclone v1.52.0
- os/arch: linux/amd64
- go version: go1.14.3

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)

# cd /mnt/remote/
# mkdir dir1
# touch dir1/file
# mkdir dir2
# rclone backend shortcut drive: dir1/file dir2/shortcut
{}
# rm -rf dir2
rm: cannot remove 'dir2': Input/output error
# rclone purge drive:dir2 -vvv
2020/06/10 11:46:13 DEBUG : rclone: Version "v1.52.0" starting with parameters ["rclone" "purge" "drive:dir2" "-vvv"]
2020/06/10 11:46:13 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/06/10 11:46:14 DEBUG : 6 go routines active
# cd

The rclone config contents with secrets removed.

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

A log from the command with the -vv flag

# rclone mount drive: /mnt/remote --allow-other --dir-cache-time=8760h --async-read=false --fast-list --links --rc --rc-no-auth --use-mmap --vfs-read-chunk-size=32M -vvv
2020/06/10 11:43:35 DEBUG : rclone: Version "v1.52.0" starting with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--allow-other" "--dir-cache-time=8760h" "--async-read=false" "--fast-list" "--links" "--rc" "--rc-no-auth" "--use-mmap" "--vfs-read-chunk-size=32M" "-vvv"]
2020/06/10 11:43:35 NOTICE: Serving remote control on http://127.0.0.1:5572/
2020/06/10 11:43:35 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/06/10 11:43:35 DEBUG : Google drive root '': Mounting on "/mnt/remote"
2020/06/10 11:43:35 DEBUG : Adding path "vfs/forget" to remote control registry
2020/06/10 11:43:35 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/06/10 11:43:35 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/06/10 11:43:35 DEBUG : : Root: 
2020/06/10 11:43:35 DEBUG : : >Root: node=/, err=<nil>
2020/06/10 11:43:40 DEBUG : /: Attr: 
2020/06/10 11:43:40 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 11:43:46 DEBUG : : Statfs: 
2020/06/10 11:43:46 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:43:47 DEBUG : : Statfs: 
2020/06/10 11:43:47 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:43:48 DEBUG : : Statfs: 
2020/06/10 11:43:48 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:43:48 DEBUG : /: Lookup: name="dir1"
2020/06/10 11:43:48 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/06/10 11:43:48 DEBUG : /: Mkdir: name="dir1"
2020/06/10 11:43:49 DEBUG : : Statfs: 
2020/06/10 11:43:49 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:43:49 DEBUG : /: >Mkdir: node=dir1/, err=<nil>
2020/06/10 11:43:49 DEBUG : dir1/: Attr: 
2020/06/10 11:43:49 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
[SNIP]
2020/06/10 11:43:56 DEBUG : : Statfs: 
2020/06/10 11:43:56 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:43:56 DEBUG : dir1/: Lookup: name="file"
2020/06/10 11:43:57 DEBUG : : Statfs: 
2020/06/10 11:43:57 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:43:57 DEBUG : dir1/: >Lookup: node=<nil>, err=no such file or directory
2020/06/10 11:43:57 DEBUG : dir1/: Create: name="file"
2020/06/10 11:43:57 DEBUG : dir1/file: Open: flags=O_WRONLY|O_CREATE|0x800
2020/06/10 11:43:57 DEBUG : dir1/file: >Open: fd=dir1/file (w), err=<nil>
2020/06/10 11:43:57 DEBUG : dir1/: >Create: node=dir1/file, handle=&{dir1/file (w)}, err=<nil>
2020/06/10 11:43:57 DEBUG : dir1/file: Attr: 
2020/06/10 11:43:57 DEBUG : dir1/file: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/06/10 11:43:57 DEBUG : &{dir1/file (w)}: Flush: 
2020/06/10 11:43:57 DEBUG : dir1/file: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2020/06/10 11:43:57 DEBUG : &{dir1/file (w)}: >Flush: err=<nil>
2020/06/10 11:43:57 DEBUG : dir1/file: Setattr: a=Setattr [ID=0x2a Node=0x3 Uid=0 Gid=0 Pid=7917] atime=2020-06-10 11:43:57.064380411 +0000 UTC atime=now mtime=2020-06-10 11:43:57.064380411 +0000 UTC mtime=now handle=INVALID-0x0
2020/06/10 11:43:57 DEBUG : dir1/file: >Setattr: err=<nil>
2020/06/10 11:43:57 DEBUG : dir1/file: Attr: 
2020/06/10 11:43:57 DEBUG : dir1/file: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/06/10 11:43:57 DEBUG : &{dir1/file (w)}: Flush: 
2020/06/10 11:43:57 DEBUG : Google drive root '': File to upload is small (0 bytes), uploading instead of streaming
2020/06/10 11:43:58 DEBUG : : Statfs: 
2020/06/10 11:43:58 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:43:58 DEBUG : dir1/file: MD5 = d41d8cd98f00b204e9800998ecf8427e OK
2020/06/10 11:43:58 INFO  : dir1/file: Copied (new)
2020/06/10 11:43:59 DEBUG : : Statfs: 
2020/06/10 11:43:59 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:43:59 DEBUG : dir1/file: File._applyPendingModTime OK
2020/06/10 11:43:59 DEBUG : &{dir1/file (w)}: >Flush: err=<nil>
2020/06/10 11:43:59 DEBUG : &{dir1/file (w)}: Release: 
2020/06/10 11:43:59 DEBUG : dir1/file: WriteFileHandle.Release nothing to do
2020/06/10 11:43:59 DEBUG : &{dir1/file (w)}: >Release: err=<nil>
2020/06/10 11:44:00 DEBUG : : Statfs: 
2020/06/10 11:44:00 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:44:01 DEBUG : : Statfs: 
2020/06/10 11:44:01 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:44:02 DEBUG : : Statfs: 
2020/06/10 11:44:02 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:44:02 DEBUG : /: Lookup: name="dir2"
2020/06/10 11:44:02 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/06/10 11:44:02 DEBUG : /: Mkdir: name="dir2"
2020/06/10 11:44:03 DEBUG : : Statfs: 
2020/06/10 11:44:03 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:44:03 DEBUG : /: >Mkdir: node=dir2/, err=<nil>
2020/06/10 11:44:03 DEBUG : dir2/: Attr: 
2020/06/10 11:44:03 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
[SNIP]
2020/06/10 11:44:35 DEBUG : : Statfs: 
2020/06/10 11:44:35 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:44:35 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 11:44:36 DEBUG : : Statfs: 
2020/06/10 11:44:36 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:44:36 DEBUG : : changeNotify: relativePath="dir1", type=2
2020/06/10 11:44:36 DEBUG : : invalidating directory cache
2020/06/10 11:44:36 DEBUG : dir1: invalidating directory cache
2020/06/10 11:44:36 DEBUG : : >changeNotify: 
2020/06/10 11:44:36 DEBUG : : changeNotify: relativePath="dir1/file", type=3
2020/06/10 11:44:36 DEBUG : : >changeNotify: 
2020/06/10 11:44:36 DEBUG : : changeNotify: relativePath="dir2", type=2
2020/06/10 11:44:36 DEBUG : : >changeNotify: 
[SNIP]
2020/06/10 11:45:35 DEBUG : : Statfs: 
2020/06/10 11:45:35 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:45:35 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 11:45:36 DEBUG : : Statfs: 
2020/06/10 11:45:36 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:45:36 DEBUG : : changeNotify: relativePath="dir2/shortcut", type=3
2020/06/10 11:45:36 DEBUG : : >changeNotify: 
[SNIP]
2020/06/10 11:45:52 DEBUG : : Statfs: 
2020/06/10 11:45:52 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:45:52 DEBUG : /: Lookup: name="dir2"
2020/06/10 11:45:52 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 11:45:52 DEBUG : dir2/: Attr: 
2020/06/10 11:45:52 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 11:45:52 DEBUG : dir2/: ReadDirAll: 
2020/06/10 11:45:53 DEBUG : : Statfs: 
2020/06/10 11:45:53 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:45:53 DEBUG : dir2/: >ReadDirAll: item=1, err=<nil>
2020/06/10 11:45:53 DEBUG : dir2/: Attr: 
2020/06/10 11:45:53 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 11:45:53 DEBUG : dir2/: ReadDirAll: 
2020/06/10 11:45:53 DEBUG : dir2/: >ReadDirAll: item=1, err=<nil>
2020/06/10 11:45:53 DEBUG : dir2/: Lookup: name="shortcut"
2020/06/10 11:45:53 DEBUG : dir2/: >Lookup: node=dir2/shortcut, err=<nil>
2020/06/10 11:45:53 DEBUG : dir2/shortcut: Attr: 
2020/06/10 11:45:53 DEBUG : dir2/shortcut: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2020/06/10 11:45:53 DEBUG : dir2/: Remove: name="shortcut"
2020/06/10 11:45:53 DEBUG : dir2/: >Remove: err=<nil>
2020/06/10 11:45:53 DEBUG : /: Lookup: name="dir2"
2020/06/10 11:45:53 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 11:45:53 DEBUG : dir2/: Attr: 
2020/06/10 11:45:53 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 11:45:53 DEBUG : /: Remove: name="dir2"
2020/06/10 11:45:54 DEBUG : : Statfs: 
2020/06/10 11:45:54 DEBUG : : >Statfs: stat={Blocks:278929608797 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/06/10 11:45:54 DEBUG : dir2: Rmdir: contains file: "shortcut"
2020/06/10 11:45:54 ERROR : dir2/: Dir.Remove failed to remove directory: directory not empty
2020/06/10 11:45:54 DEBUG : /: >Remove: err=directory not empty
2

I can't seem to make this happen.

I tried doing:

rclone copy /etc/hosts GD:test
rclone mkdir GD:test1
rclone backend shortcut GD: test/hosts test1/testme
rclone mount GD: /home/felix/test -vv

and my delete worked.

felix@gemini:~/test$ ls
crypt  jellyfish-400-mbps-4k-uhd-hevc-10bit.mkv  restic  test  test1  test.mkv
felix@gemini:~/test$
felix@gemini:~/test$
felix@gemini:~/test$ rm -rf test1
felix@gemini:~/test$ fusermount -uz /home/felix/test
felix@gemini:~/test$ cd

Did I miss something in your steps to recreate it?

3

Interesting. I just tried again with a minimum of mount parameters (like you) and now I don't have the problem. Care to guess which one is the problem? :slight_smile:

4

Hmm, I ran with your exact mount command minus changing the rc-addr and it worked for me:

2020/06/10 09:43:45 DEBUG : rclone: Version "v1.52.0" finishing with parameters ["rclone" "mount" "GD:" "/home/felix/test" "--allow-other" "--dir-cache-time=8760h" "--async-read=false" "--fast-list" "--links" "--rc" "--rc-no-auth" "--use-mmap" "--vfs-read-chunk-size=32M" "-vvv" "--rc-addr" ":5582"]

I am not sure as I was hoping to figure out how to recreate it.

5

Well, I take back what I said about it working with fewer mount parameters. Now it fails consistently again...

Maybe it's a problem with my versions of FUSE and/or the kernel?

# dpkg -l | grep fuse
ii  fuse                                2.9.9-1+deb10u1                    amd64        Filesystem in Userspace
ii  libfuse2:amd64                      2.9.9-1+deb10u1                    amd64        Filesystem in Userspace (library)
# uname -r -v
5.5.0-0.bpo.2-amd64 #1 SMP Debian 5.5.17-1~bpo10+1 (2020-04-23)
6

I'm on a lower kernel version and fuse:

felix@gemini:~$ uname -a
Linux gemini 5.4.0-33-generic #37-Ubuntu SMP Thu May 21 12:53:59 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
felix@gemini:~$ dpkg -l | grep fuse
ii  fuse                                                        2.9.9-3                                                     amd64        Filesystem in Userspace
ii  libfuse2:amd64                                              2.9.9-3                                                     amd64        Filesystem in Userspace (library)

What happens if you just try to remove the shortcut on the mount?

7

More logs. The removal of the shortcut apparently succeeds, but then the removal of its directory fails because it's not empty...

# mkdir dir2
# rclone backend shortcut drive: dir1/file dir2/shortcut
{}
# rm -f dir2/shortcut 
# rm -rf dir2
rm: cannot remove 'dir2': Input/output error
# cd

# rclone mount drive: /mnt/remote --poll-interval 10s -vv
2020/06/10 14:40:49 DEBUG : rclone: Version "v1.52.0" starting with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--poll-interval" "10s" "-vv"]
2020/06/10 14:40:49 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/06/10 14:40:49 DEBUG : Google drive root '': Mounting on "/mnt/remote"
2020/06/10 14:40:49 DEBUG : Adding path "vfs/forget" to remote control registry
2020/06/10 14:40:49 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/06/10 14:40:49 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/06/10 14:40:49 DEBUG : : Root: 
2020/06/10 14:40:49 DEBUG : : >Root: node=/, err=<nil>
2020/06/10 14:40:59 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:41:09 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:41:11 DEBUG : /: Attr: 
2020/06/10 14:41:11 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:12 DEBUG : /: Attr: 
2020/06/10 14:41:12 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:12 DEBUG : /: ReadDirAll: 
2020/06/10 14:41:13 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:41:13 DEBUG : /: Lookup: name="dir1"
2020/06/10 14:41:13 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/06/10 14:41:13 DEBUG : dir1/: Attr: 
2020/06/10 14:41:13 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:13 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:41:13 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 14:41:13 DEBUG : dir2/: Attr: 
2020/06/10 14:41:13 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:19 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:41:26 DEBUG : /: Attr: 
2020/06/10 14:41:26 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:26 DEBUG : /: ReadDirAll: 
2020/06/10 14:41:26 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:41:26 DEBUG : /: Lookup: name="dir1"
2020/06/10 14:41:26 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/06/10 14:41:26 DEBUG : dir1/: Attr: 
2020/06/10 14:41:26 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:26 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:41:26 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 14:41:26 DEBUG : dir2/: Attr: 
2020/06/10 14:41:26 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:29 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:41:36 DEBUG : /: Attr: 
2020/06/10 14:41:36 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:36 DEBUG : /: ReadDirAll: 
2020/06/10 14:41:36 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:41:36 DEBUG : /: Lookup: name="dir1"
2020/06/10 14:41:36 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/06/10 14:41:36 DEBUG : dir1/: Attr: 
2020/06/10 14:41:36 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:36 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:41:36 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 14:41:36 DEBUG : dir2/: Attr: 
2020/06/10 14:41:36 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:37 DEBUG : /: Attr: 
2020/06/10 14:41:37 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:37 DEBUG : /: ReadDirAll: 
2020/06/10 14:41:37 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:41:37 DEBUG : /: Lookup: name="dir1"
2020/06/10 14:41:37 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/06/10 14:41:37 DEBUG : dir1/: Attr: 
2020/06/10 14:41:37 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:37 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:41:37 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 14:41:37 DEBUG : dir2/: Attr: 
2020/06/10 14:41:37 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:39 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:41:40 DEBUG : : changeNotify: relativePath="dir2", type=2
2020/06/10 14:41:40 DEBUG : : invalidating directory cache
2020/06/10 14:41:40 DEBUG : : >changeNotify: 
2020/06/10 14:41:41 DEBUG : /: Attr: 
2020/06/10 14:41:41 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:41 DEBUG : /: ReadDirAll: 
2020/06/10 14:41:43 DEBUG : /: >ReadDirAll: item=1, err=<nil>
2020/06/10 14:41:43 DEBUG : /: Lookup: name="dir1"
2020/06/10 14:41:43 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/06/10 14:41:43 DEBUG : dir1/: Attr: 
2020/06/10 14:41:43 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:49 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:41:51 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:41:51 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/06/10 14:41:51 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:41:51 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/06/10 14:41:51 DEBUG : /: Mkdir: name="dir2"
2020/06/10 14:41:51 DEBUG : /: >Mkdir: node=dir2/, err=<nil>
2020/06/10 14:41:51 DEBUG : dir2/: Attr: 
2020/06/10 14:41:51 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:41:59 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:42:09 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:42:11 DEBUG : : changeNotify: relativePath="dir2", type=2
2020/06/10 14:42:11 DEBUG : : invalidating directory cache
2020/06/10 14:42:11 DEBUG : : >changeNotify: 
2020/06/10 14:42:19 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:42:29 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:42:39 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:42:47 DEBUG : /: Attr: 
2020/06/10 14:42:47 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:47 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:48 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:48 DEBUG : /: Lookup: name="dir1"
2020/06/10 14:42:48 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/06/10 14:42:48 DEBUG : dir1/: Attr: 
2020/06/10 14:42:48 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:48 DEBUG : dir2/: Attr: 
2020/06/10 14:42:48 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:48 DEBUG : /: Attr: 
2020/06/10 14:42:48 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:48 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:48 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:49 DEBUG : /: Attr: 
2020/06/10 14:42:49 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:49 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:49 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:49 DEBUG : /: Attr: 
2020/06/10 14:42:49 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:49 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:49 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:49 DEBUG : /: Attr: 
2020/06/10 14:42:49 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:49 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:42:50 DEBUG : dir2/: Attr: 
2020/06/10 14:42:50 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:50 DEBUG : dir2/: ReadDirAll: 
2020/06/10 14:42:51 DEBUG : dir2/: >ReadDirAll: item=1, err=<nil>
2020/06/10 14:42:51 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:42:51 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 14:42:51 DEBUG : dir2/: Attr: 
2020/06/10 14:42:51 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : dir2/: Lookup: name="shortcut"
2020/06/10 14:42:51 DEBUG : dir2/: >Lookup: node=dir2/shortcut, err=<nil>
2020/06/10 14:42:51 DEBUG : dir2/shortcut: Attr: 
2020/06/10 14:42:51 DEBUG : dir2/shortcut: >Attr: a=valid=1s ino=0 size=4 mode=-rw-r--r--, err=<nil>
2020/06/10 14:42:51 DEBUG : /: Attr: 
2020/06/10 14:42:51 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : dir2/: ReadDirAll: 
2020/06/10 14:42:51 DEBUG : dir2/: >ReadDirAll: item=1, err=<nil>
2020/06/10 14:42:51 DEBUG : dir2/: Attr: 
2020/06/10 14:42:51 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:51 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:51 DEBUG : /: Lookup: name="dir1"
2020/06/10 14:42:51 DEBUG : /: >Lookup: node=dir1/, err=<nil>
2020/06/10 14:42:51 DEBUG : dir1/: Attr: 
2020/06/10 14:42:51 DEBUG : dir1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : /: Attr: 
2020/06/10 14:42:51 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:51 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:51 DEBUG : /: Attr: 
2020/06/10 14:42:51 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:51 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:51 DEBUG : /: Attr: 
2020/06/10 14:42:51 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:51 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:51 DEBUG : /: Attr: 
2020/06/10 14:42:51 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:51 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:51 DEBUG : /: Attr: 
2020/06/10 14:42:51 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:51 DEBUG : /: ReadDirAll: 
2020/06/10 14:42:51 DEBUG : /: >ReadDirAll: item=2, err=<nil>
2020/06/10 14:42:56 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:42:56 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 14:42:56 DEBUG : dir2/: Attr: 
2020/06/10 14:42:56 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:56 DEBUG : dir2/: Lookup: name="shortcut"
2020/06/10 14:42:56 DEBUG : dir2/: >Lookup: node=dir2/shortcut, err=<nil>
2020/06/10 14:42:56 DEBUG : dir2/shortcut: Attr: 
2020/06/10 14:42:56 DEBUG : dir2/shortcut: >Attr: a=valid=1s ino=0 size=4 mode=-rw-r--r--, err=<nil>
2020/06/10 14:42:58 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:42:58 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 14:42:58 DEBUG : dir2/: Attr: 
2020/06/10 14:42:58 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:42:58 DEBUG : dir2/: Lookup: name="shortcut"
2020/06/10 14:42:58 DEBUG : dir2/: >Lookup: node=dir2/shortcut, err=<nil>
2020/06/10 14:42:58 DEBUG : dir2/shortcut: Attr: 
2020/06/10 14:42:58 DEBUG : dir2/shortcut: >Attr: a=valid=1s ino=0 size=4 mode=-rw-r--r--, err=<nil>
2020/06/10 14:42:58 DEBUG : dir2/: Remove: name="shortcut"
2020/06/10 14:42:59 DEBUG : dir2/: >Remove: err=<nil>
2020/06/10 14:42:59 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:43:01 DEBUG : : changeNotify: relativePath="dir2/shortcut", type=3
2020/06/10 14:43:01 DEBUG : dir2: invalidating directory cache
2020/06/10 14:43:01 DEBUG : : >changeNotify: 
2020/06/10 14:43:09 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 14:43:10 DEBUG : /: Lookup: name="dir2"
2020/06/10 14:43:10 DEBUG : /: >Lookup: node=dir2/, err=<nil>
2020/06/10 14:43:10 DEBUG : dir2/: Attr: 
2020/06/10 14:43:10 DEBUG : dir2/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2020/06/10 14:43:10 DEBUG : dir2/: ReadDirAll: 
2020/06/10 14:43:10 DEBUG : dir2/: >ReadDirAll: item=0, err=<nil>
2020/06/10 14:43:10 DEBUG : /: Remove: name="dir2"
2020/06/10 14:43:11 DEBUG : dir2: Rmdir: contains file: "shortcut"
2020/06/10 14:43:11 ERROR : dir2/: Dir.Remove failed to remove directory: directory not empty
2020/06/10 14:43:11 DEBUG : /: >Remove: err=directory not empty
^C2020/06/10 14:43:18 DEBUG : rclone: Version "v1.52.0" finishing with parameters ["rclone" "mount" "drive:" "/mnt/remote" "--poll-interval" "10s" "-vv"]
8

After that, if you ls the directory, is it still there?

9

It appears not to be.

# mkdir dir2
# rclone backend shortcut drive: dir1/file dir2/shortcut
{}
# ll dir2
total 1
-rw-r--r-- 1 root root 4 Jun 10 13:24 shortcut
# rm -f dir2/shortcut 
# ll dir2
total 0
10

This is your poll finding it after it was deleted.

This says it found the file when I made it:

2020/06/10 11:32:17 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 11:32:17 DEBUG : : changeNotify: relativePath="test1/shortcut", type=3
2020/06/10 11:32:17 DEBUG : test1: invalidating directory cache
2020/06/10 11:32:17 DEBUG : : >changeNotify:

This is my remove command and two polls (I changed to 15s to speed up testing).

2020/06/10 11:32:45 DEBUG : test1/shortcut: >Attr: a=valid=1s ino=0 size=413 mode=-rw-rw-r--, err=<nil>
2020/06/10 11:32:45 DEBUG : test1/: Remove: name="shortcut"
2020/06/10 11:32:46 DEBUG : test1/: >Remove: err=<nil>
2020/06/10 11:32:47 DEBUG : Google drive root '': Checking for changes on remote
2020/06/10 11:33:02 DEBUG : test1/: Attr:
2020/06/10 11:33:02 DEBUG : test1/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/06/10 11:33:02 DEBUG : test1/: ReadDirAll:
2020/06/10 11:33:02 DEBUG : test1/: >ReadDirAll: item=0, err=<nil>
2020/06/10 11:33:02 DEBUG : Google drive root '': Checking for changes on remote

The issue is that you have it removed but a poll goes and finds it. Is it a team drive or a regular drive?
The last line seems to think something is there.

11

It's a regular drive.

12

Can you see if you can replicate this with a normal file instead of a shortcut?

Also can you give the latest beta a go which has quite a few VFS fixes.

13

I cannot replicate the problem with a normal file.

The latest beta doesn't seem to change things.

Anyway, here's a bit more data. Apparently, rm -f dir2/shortcut successfully removes the shortcut from the back end, but the following rm -rf dir2 still thinks it's there!

# mkdir dir2
# rclone backend shortcut drive: dir1/file dir2/shortcut
{}
# ll dir2/
total 1
-rw-r--r-- 1 root root 4 Jun 10 13:24 shortcut
# rm -f dir2/shortcut 
# ll dir2/
total 0
# rclone lsf drive: -R
dir2/
dir1/
dir1/file
# rm -rf dir2/
rm: cannot remove 'dir2/': Input/output error
14

The problem/challenge issue is right there though.

The file is removed.
The file is added back via changenotify.

We need to figure out why that happens.

15

Agreed. :slight_smile: The purpose of including the output of rclone lsf drive: -R was simply to suggest that this is a purely local problem, i.e., a problem that only exists in the FUSE client, if that makes sense.

16

THere is definitely something whacky going on here...

Here is the drive backend listing the directory after the file was deleted

2020/06/11 17:37:06 DEBUG : HTTP REQUEST (req 0xc000192f00)
2020/06/11 17:37:06 DEBUG : GET /drive/v3/files?alt=json&fields=files%28id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails%29%2CnextPageToken%2CincompleteSearch&includeItemsFromAllDrives=true&pageSize=1000&prettyPrint=false&q=trashed%3Dfalse+and+%28%271WYS8x2KhjWONsCnvZE47eywDMtFXl1FS%27+in+parents%29&supportsAllDrives=true HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.52.1-DEV
Authorization: XXXX
X-Goog-Api-Client: gl-go/1.14.3 gdcl/20200410
Accept-Encoding: gzip

2020/06/11 17:37:06 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/06/11 17:37:06 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/06/11 17:37:06 DEBUG : HTTP RESPONSE (req 0xc000192f00)
2020/06/11 17:37:06 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: h3-27=":443"; ma=2592000,h3-25=":443"; ma=2592000,h3-T050=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Security-Policy: frame-ancestors 'self'
Content-Type: application/json; charset=UTF-8
Date: Thu, 11 Jun 2020 16:37:06 GMT
Expires: Thu, 11 Jun 2020 16:37:06 GMT
Server: GSE
Vary: Origin
Vary: X-Origin
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Xss-Protection: 1; mode=block

25
{"incompleteSearch":false,"files":[]}
0

And here is the listing that RMdir does to check the directory is empty which has the shortcut file in! :confused:

2020/06/11 17:37:13 DEBUG : HTTP REQUEST (req 0xc000180700)
2020/06/11 17:37:13 DEBUG : GET /drive/v3/files?alt=json&fields=files%28id%2Cname%2Csize%2Cmd5Checksum%2Ctrashed%2CmodifiedTime%2CcreatedTime%2CmimeType%2Cparents%2CwebViewLink%2CshortcutDetails%29%2CnextPageToken%2CincompleteSearch&includeItemsFromAllDrives=true&pageSize=1000&prettyPrint=false&q=%28%271WYS8x2KhjWONsCnvZE47eywDMtFXl1FS%27+in+parents%29&supportsAllDrives=true HTTP/1.1
Host: www.googleapis.com
User-Agent: rclone/v1.52.1-DEV
Authorization: XXXX
X-Goog-Api-Client: gl-go/1.14.3 gdcl/20200410
Accept-Encoding: gzip

2020/06/11 17:37:13 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/06/11 17:37:13 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/06/11 17:37:13 DEBUG : HTTP RESPONSE (req 0xc000180700)
2020/06/11 17:37:13 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: h3-27=":443"; ma=2592000,h3-25=":443"; ma=2592000,h3-T050=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Security-Policy: frame-ancestors 'self'
Content-Type: application/json; charset=UTF-8
Date: Thu, 11 Jun 2020 16:37:13 GMT
Expires: Thu, 11 Jun 2020 16:37:13 GMT
Server: GSE
Vary: Origin
Vary: X-Origin
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Xss-Protection: 1; mode=block

1f8
{"incompleteSearch":false,"files":[{"id":"14uJxOaQvO_m9w1XcCl6Q7UgMy-6WrUtA","name":"shortcut","mimeType":"application/vnd.google-apps.shortcut","trashed":true,"parents":["1WYS8x2KhjWONsCnvZE47eywDMtFXl1FS"],"webViewLink":"https://drive.google.com/file/d/14uJxOaQvO_m9w1XcCl6Q7UgMy-6WrUtA/view?usp=drivesdk","createdTime":"2020-06-11T16:29:09.375Z","modifiedTime":"2020-06-11T16:29:09.260Z","shortcutDetails":{"targetId":"1FIFum-y8btuv8wjLQn-3oKxFu8WFpLVO","targetMimeType":"application/octet-stream"}}]}
0

I've just been called for dinner - can one of you figure out the difference in those requests before I get back :wink:

1 Like
17

THis:

trashed%3Dfalse+and

This looks like this:

Bypassing the trash leads to polling not working.

18

Where is the OP disabling the trash ?

19

I meant the http request is querying trashed=false. Looks related to that bug i meant.

20

Ah! Thanks, I see now.