Windows rclone mount S3 failed sync file renaming

Elisa_Francesconi · March 25, 2021, 3:09pm

HI

I have 2 windows EC2 instances, using the same S3 bucket to syncronize data.
This is the rclone mount command line

rclone.exe mount --config rclone.ini SESSIONNAME:BUCKETNAME/KEY FOLDER --dir-cache-time 1m0s --poll-interval 20s --async-read=false --vfs-cache-mode writes -v

What is the problem you are having with rclone?

In some circumstances, one of the 2 EC2 instances renames a file on local filesystem and it is correctly synchronized on S3.
Meanwhile, on the other EC2 instance, on filesystem we still have the previous file with the old name
but if we try to open or copy it, we get the following error from S3, because of course, the file does not actually exist

ERROR : IO error: NoSuchKey: The specified key does not exist.
status code: 404, request id:XXXXXXX host id: XXX

If we restart Rclone service the issue is fixed and we do not see anymore the file on the local file system (as it actually should be whitout restarting)

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

rclone v1.54.0-beta.4766.75de30cfa

os/arch: windows/amd64
go version: go1.15

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

Windows Server 2019, version 1809

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

S3 (AWS)

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

rclone.exe mount --config rclone.ini SESSIONNAME:BUCKETNAME/KEY FOLDER --dir-cache-time 1m0s --poll-interval 20s --async-read=false --vfs-cache-mode writes -v

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

DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: OpenEx: flags=0x0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Open: flags=O_RDONLY
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Open: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (r), err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Open: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (r), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenFile: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (r), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenFile: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (r), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenEx: errc=0, fh=0x2
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0x2
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Read: ofst=0, fh=0x2
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.openRange at 0 length 134217728
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.Read at 0 length 34332 chunkOffset 0 chunkSize 134217728
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Read: n=34332
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Flush: fh=0x2
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Flush: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Release: fh=0x2
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ReadFileHandle.Release closing
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Release: errc=0
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: OpenEx: flags=0x1
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: OpenFile: flags=O_WRONLY, perm=-rwxrwxrwx
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Open: flags=O_WRONLY
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: newRWFileHandle: 
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >newRWFileHandle: err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Open: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Open: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenFile: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenFile: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenEx: errc=0, fh=0x5
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Truncate: size=0, fh=0x5
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): openPending: 
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: checking remote fingerprint "34332,2021-03-25 14:16:33.2705993 +0000 UTC,4b7a86543eaf648c63cee15e841b87b0" against cached fingerprint ""
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: truncate to size=34332
DEBUG : Application/f5: Added virtual directory entry vAdd: "NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff"
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): >openPending: err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: truncate to size=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Truncate: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0x5
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0x5
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Write: ofst=0, fh=0x5
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): _writeAt: size=16384, off=0
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): >_writeAt: n=16384, err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Write: n=16384
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0x5
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Write: ofst=16384, fh=0x5
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): _writeAt: size=16384, off=16384
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): >_writeAt: n=16384, err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Write: n=16384
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0x5
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Write: ofst=32768, fh=0x5
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): _writeAt: size=1554, off=32768
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): >_writeAt: n=1554, err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Write: n=1554
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Flush: fh=0x5
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): RWFileHandle.Flush
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Flush: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Release: fh=0x5
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): RWFileHandle.Release
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): close: 
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: setting modification time to 2021-03-25 14:17:29.6421356 +0000 GMT m=+2115.153000501
INFO  : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: queuing for upload in 5s
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0003f6d00): >close: err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Release: errc=0
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: starting upload
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: MD5 = 4ad5dff7cf0b61e6e19787c109c2c697 OK
INFO  : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Copied (replaced existing)
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: fingerprint now "34322,2021-03-25 14:17:29.6421356 +0000 UTC,4ad5dff7cf0b61e6e19787c109c2c697"
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: writeback object to VFS layer
DEBUG : Application/f5: Added virtual directory entry vAdd: "NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff"
INFO  : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: upload succeeded try #1
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : Application/f5: Removed virtual directory entry vAdd: "NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff"
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: OpenEx: flags=0x0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Open: flags=O_RDONLY
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: newRWFileHandle: 
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >newRWFileHandle: err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Open: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Open: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenFile: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenFile: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenEx: errc=0, fh=0x2
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0x2
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Read: ofst=0, fh=0x2
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0006939c0): _readAt: size=34322, off=0
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0006939c0): openPending: 
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: checking remote fingerprint "34322,2021-03-25 14:17:29.6421356 +0000 UTC,4ad5dff7cf0b61e6e19787c109c2c697" against cached fingerprint "34322,2021-03-25 14:17:29.6421356 +0000 UTC,4ad5dff7cf0b61e6e19787c109c2c697"
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: truncate to size=34322
DEBUG : Application/f5: Added virtual directory entry vAdd: "NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff"
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0006939c0): >openPending: err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0006939c0): >_readAt: n=34322, err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Read: n=34322
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Flush: fh=0x2
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0006939c0): RWFileHandle.Flush
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Flush: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Release: fh=0x2
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0006939c0): RWFileHandle.Release
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0006939c0): close: 
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: setting modification time to 2021-03-25 14:17:29.6421356 +0000 GMT
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc0006939c0): >close: err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Release: errc=0
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff not removed, freed 0 bytes
DEBUG : Application/f5: Removed virtual directory entry vAdd: "NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff"
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0xFFFFFFFFFFFFFFFF
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: OpenEx: flags=0x0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Open: flags=O_RDONLY
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: newRWFileHandle: 
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >newRWFileHandle: err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Open: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Open: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenFile: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenFile: fd=Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff (rw), err=<nil>
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >OpenEx: errc=0, fh=0x2
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Getattr: fh=0x2
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: >Getattr: errc=0
DEBUG : /Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: Read: ofst=0, fh=0x2
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc000813e40): _readAt: size=34336, off=0
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc000813e40): openPending: 
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: checking remote fingerprint "34336,2021-03-25 14:32:48.7641484 +0000 UTC,75f40a06263aa0fb3949c5902cf784f6" against cached fingerprint "34322,2021-03-25 14:17:29.6421356 +0000 UTC,4ad5dff7cf0b61e6e19787c109c2c697"
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: removing cached entry as stale (remote fingerprint "34336,2021-03-25 14:32:48.7641484 +0000 UTC,75f40a06263aa0fb3949c5902cf784f6" != cached fingerprint "34322,2021-03-25 14:17:29.6421356 +0000 UTC,4ad5dff7cf0b61e6e19787c109c2c697")
INFO  : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: removed cache file as stale (remote is different)
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: removed metadata from cache as stale (remote is different)
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: truncate to size=34336
DEBUG : Application/f5: Added virtual directory entry vAdd: "NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff"
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff(0xc000813e40): >openPending: err=<nil>
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.RangeSeek from -1 to 0 length -1
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.openRange at 0 length 134217728
INFO  : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: downloader: error count now 1: vfs reader: failed to write to cache file: NoSuchKey: The specified key does not exist.
ERROR : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: failed to download: vfs reader: failed to write to cache file: NoSuchKey: The specified key does not exist.
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.RangeSeek from -1 to 0 length -1
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.openRange at 0 length 134217728
INFO  : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: downloader: error count now 2: vfs reader: failed to write to cache file: NoSuchKey: The specified key does not exist.
ERROR : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: failed to download: vfs reader: failed to write to cache file: NoSuchKey: The specified key does not exist.
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.RangeSeek from -1 to 0 length -1
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.openRange at 0 length 134217728
INFO  : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: downloader: error count now 3: vfs reader: failed to write to cache file: NoSuchKey: The specified key does not exist.
ERROR : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: failed to download: vfs reader: failed to write to cache file: NoSuchKey: The specified key does not exist.
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.RangeSeek from -1 to 0 length -1
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: ChunkedReader.openRange at 0 length 134217728
INFO  : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: downloader: error count now 4: vfs reader: failed to write to cache file: NoSuchKey: The specified key does not exist.
ERROR : Application/f5/NodeName_66fd0f4e-b0fc-4571-ad23-9bc95339c2f5_1.progress.tiff: vfs cache: failed to download: vfs reader: failed to write to cache file: NoSuchKey: The specified key does not exist.

asdffdsa · March 25, 2021, 4:06pm

hello and welcome to the forum,

with S3, pretty sure it is does not support polling.
the debug log would show that.

you cannot expect two rclone mounts, pointing to the same remote, to be in real-time sync

ncw · March 25, 2021, 4:46pm

This means cache each directory listing for 1 minute. You can reduce this number say to 1s at the cost of more S3 API calls.

Elisa_Francesconi · March 26, 2021, 10:48am

Hi guys,
thanks for your answers.

Unfortunately, I'm afraid that the real-time synch is not actually the issue.

Sorry if I was not clear, but in that specific circumstances the local file remains on local file system until we restart rclone service (no matter how long we wait)

Thanks

asdffdsa · March 26, 2021, 12:59pm

if a local process keeps that file open then rclone cannot remove it.

you can tweak that with
--vfs-cache-max-age duration
Max age of objects in the cache. (default 1h0m0s)

system · May 26, 2021, 9:00am

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