Rclone S3 Deletion not replicated to server

I have a Windows 2012 r2 server with rclone (v1.53.2) mounting a drive to an AWS s3 bucket

Most of that functionality works in near real time with the exception of deletions from the S3 bucket not being replicated back to the server drive.

Can anyone please advise on what I have to do to be able to delete something on S3 and have that replicate to the server?

The drive is mounted by a scheduled task that runs as SYSTEM.

The configuration file is \\

[AWS-sftp]
type = s3
provider = AWS
env_auth = false
secret_access_key = XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
region = eu-west-2
location_constraint = eu-west-2
acl = private
server_side_encryption = AES256
access_key_id = XXXXXXXXXXXXXXXXXXXXX

The powershell script I use to launch the drive is \\

cd "C:\Program Files\rclone"
.\rclone.exe mount
AWS-sftp:/sftp-olmapps-co-uk-thc-live/bobi/nthcfs1/ X:
--allow-other --allow-non-empty
--dir-cache-time 40s --poll-interval 30s
--config "C:\Program Files\rclone\rclone.conf" --vfs-cache-mode full
--log-file ".\run-log" -v
-o "uid=197108,gid=197121,umask=0000"

Deletes should be synchronous back to the drive.

I suspect there is some permissions error.

Can you take a look in the log?

hello and welcome to the forum

these flags do nothing on windows
--allow-other
--allow-non-empty

for debug output, use --log-level=DEBUG

Thank you for replying, I've enabled --log-level=DEBUG and started everything up again.

Here is what happens when I create an object, have it replicate to my S3 bucket and then delete it from the bucket.

2020/11/09 09:21:49 DEBUG : MPtest0921.txt: MD5 = d41d8cd98f00b204e9800998ecf8427e OK
2020/11/09 09:21:49 INFO : MPtest0921.txt: Copied (new)
2020/11/09 09:21:49 DEBUG : MPtest0921.txt: vfs cache: fingerprint now "0,2020-11-09 09:08:08.3467389 +0000 UTC,d41d8cd98f00b204e9800998ecf8427e"
2020/11/09 09:21:49 DEBUG : MPtest0921.txt: vfs cache: writeback object to VFS layer
2020/11/09 09:21:49 DEBUG : MPtest0921.txt: Applied pending mod time 2020-11-09 09:08:08.3467389 +0000 GMT OK
2020/11/09 09:21:49 DEBUG : : Added virtual directory entry vAdd: "MPtest0921.txt"
2020/11/09 09:21:49 INFO : MPtest0921.txt: vfs cache: upload succeeded try #1
2020/11/09 09:22:23 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item MPtest0908.txt not removed, freed 0 bytes
2020/11/09 09:22:23 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item MPtest0921.txt not removed, freed 0 bytes
2020/11/09 09:22:23 INFO : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/11/09 09:22:37 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:22:37 DEBUG : /: >Getattr: errc=0
2020/11/09 09:22:37 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:22:37 DEBUG : /: >Getattr: errc=0
2020/11/09 09:22:37 DEBUG : /: Opendir:
2020/11/09 09:22:37 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:22:37 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:22:37 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:22:37 DEBUG : /: Statfs:
2020/11/09 09:22:37 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2020/11/09 09:22:37 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:22:37 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:22:37 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:22:37 DEBUG : /: >Getattr: errc=0
2020/11/09 09:22:37 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:22:37 DEBUG : /: >Getattr: errc=0
2020/11/09 09:22:37 DEBUG : /: Opendir:
2020/11/09 09:22:37 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:22:37 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:22:37 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:22:37 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:22:37 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:23:23 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item MPtest0908.txt not removed, freed 0 bytes
2020/11/09 09:23:23 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item MPtest0921.txt not removed, freed 0 bytes
2020/11/09 09:23:23 INFO : vfs cache: cleaned: objects 2 (was 2) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Opendir:
2020/11/09 09:23:54 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:23:54 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:23:54 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:23:54 DEBUG : /: Statfs:
2020/11/09 09:23:54 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2020/11/09 09:23:54 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:23:54 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:23:54 DEBUG : /desktop.ini: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : : Re-reading directory (2m9.8914617s old)
2020/11/09 09:23:54 DEBUG : /desktop.ini: >Getattr: errc=-2
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Opendir:
2020/11/09 09:23:54 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:23:54 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:23:54 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:23:54 DEBUG : /: Readdir: ofst=0, fh=0x2
2020/11/09 09:23:54 DEBUG : /: >Readdir: items=2, errc=0
2020/11/09 09:23:54 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:23:54 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Opendir:
2020/11/09 09:23:54 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:23:54 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:23:54 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:23:54 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:23:54 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Opendir:
2020/11/09 09:23:54 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:23:54 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:23:54 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:23:54 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:23:54 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Opendir:
2020/11/09 09:23:54 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:23:54 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:23:54 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:23:54 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:23:54 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:54 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:54 DEBUG : /: Opendir:
2020/11/09 09:23:54 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:23:54 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:23:54 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:23:54 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:23:54 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:23:55 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:55 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:55 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:55 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:55 DEBUG : /: Opendir:
2020/11/09 09:23:55 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:23:55 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:23:55 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:23:55 DEBUG : /: Statfs:
2020/11/09 09:23:55 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2020/11/09 09:23:55 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:23:55 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:23:55 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:55 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:55 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/11/09 09:23:55 DEBUG : /: >Getattr: errc=0
2020/11/09 09:23:55 DEBUG : /: Opendir:
2020/11/09 09:23:55 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/11/09 09:23:55 DEBUG : /: >OpenFile: fd=/ (r), err=
2020/11/09 09:23:55 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/11/09 09:23:55 DEBUG : /: Releasedir: fh=0x2
2020/11/09 09:23:55 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:24:01 DEBUG : /: Releasedir: fh=0x1
2020/11/09 09:24:01 DEBUG : /: >Releasedir: errc=0
2020/11/09 09:24:01 DEBUG : /: Releasedir: fh=0x0
2020/11/09 09:24:01 DEBUG : /: >Releasedir: errc=0

You are probably facing the same issue reported here:

I don't see any deletes in that log. How did you delete it? Did the delete not actually happen?

I deleted the file using the S3 interface.

I have two servers connected to this bucket with identical (as I can tell) configuration, one one of them deletions are replicated and on the other they are not.

I see!

S3 doesn't have a change notify protocol so to see changes on the remote then you need to wait for this timeout to expire

  --dir-cache-time duration                Time to cache directory entries for. (default 5m0s)

Thank you NCW, I have waited more than the 5 minute timeout and nothing changed.

The confusing bit is that one of my servers replicates these deletions and the other doesn't. Worse is that the working server is a clone of the non-working one, right down to having the same uid and gid.

Config for working server is:
cd "C:\Program Files\rclone"
.\rclone.exe mount
AWS-sftp:/sftp-olmapps-co-uk-thc-live/bobi/nthcfs1/ X:
--allow-other --allow-non-empty
--dir-cache-time 40s --poll-interval 30s
--config "C:\Program Files\rclone\rclone.conf" --vfs-cache-mode full
--log-file ".\run-log" --log-level=DEBUG
-o "uid=197108,gid=197121,umask=0000"

While config for non-working server is
cd "C:\Program Files\rclone"
.\rclone.exe mount
aws-sftp:/sftp-olmapps-co-uk-thc-live/bobi/nthcfs1/ X:
--allow-other --allow-non-empty
--dir-cache-time 40s --poll-interval 30s
--config "C:\Program Files\rclone\rclone.conf" --cache-dir "D:\olm\rclone\Cache"
--vfs-cache-mode full --log-file ".\run-log"
--log-level=DEBUG `
-o "uid=197108,gid=197121,umask=0000"

This log excerpt from my latest test might mean something:

20/11/09 11:32:51 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item MPtest1127.txt not removed, freed 0 bytes
2020/11/09 11:32:51 INFO : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0)

It says not removed but not why.

I've just observed something interesting, the deletion will not replicate to the server that copied the files in to the mounted drive but will to other places. How should I fix that?

This is probably related to: https://github.com/rclone/rclone/issues/4446 as stated above...

So you see virtual directory entries being created in the debug ? (Do a grep -i virtual file.log to see)

HI NCW, I don't see any virtual directory entries for files that I'm deleting from S3.

How do you suggest I solve this issue?

I assume this was the file created from the mount and then removed from the S3 bucket? If so, you will need to wait for the linked issue above to get resolved and do all your additions/deletions from your mount in the meanwhile.

Can you work out the exact sequence that causes the problem?

The sequence of the problem is

Copy file to mounted drive
File replicates to S3
Delete file from S3
Deletion replicated everywhere except the server that created it (I have two servers connected to the same bucket)

Thanks.

Ok so what you are doing is on two servers A & B

  • A: create a file
  • A: file gets uploaded to S3
  • B: delete file from S3
  • B: deletion is visible
  • A: deletion is never visible

Is that correct? If so then that is exactly the trouble spot that the issue above refers to. I can replicate that which is really useful...

I'm just going to have a look at a different way of fixing the problem.

To be more exact:

  • A: create a file
  • A: file gets uploaded to S3
  • AWS S3 interface: delete file from S3
  • B: deletion is visible
  • A: deletion is never visible

I have attempted to fix this here - testing appreciated :slight_smile:

v1.54.0-beta.4887.226018dc2.fix-4446-vfs-virtual on branch fix-4446-vfs-virtual (uploaded in 15-30 mins)

I will cheerfully test, do you have a compiled executable version or instructions on how to make one?

The builds are available at v1.54.0-beta.4887.226018dc2.fix-4446-vfs-virtual. You just need to download and unzip them to get the executable within.