Produce 2 versions when overwrite an object in min.io

Suspected Bug
1

What is the problem you are having with rclone?

I'm using minio, with versioning. I've mounted a bucket as a folder in Windows 10.
When there overwrite a file, it will produce 2 versions of the object.

What is your rclone version (output from rclone version)

v1.53.1

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

Windows 10, 64 bit

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

minio (s3), with versioning

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

C:\rclone\rclone.exe mount bucket3v:bucket3v/ S: -vv --volname share --vfs-cache-mode full

The rclone config contents with secrets removed.

[bucket3v]
type = s3
provider = Minio
env_auth = false
access_key_id = ...
secret_access_key = ...
endpoint = http://....:9000
acl = bucket-owner-full-control

A log from the command with the -vv flag

2020/10/07 18:34:57 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:57 DEBUG : : Re-reading directory (39m42.9486846s old)
2020/10/07 18:34:57 DEBUG : : Removed virtual directory entry vAdd: "svg1.svg"
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: OpenEx: flags=0x0
2020/10/07 18:34:57 DEBUG : /svg1.svg: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:57 DEBUG : svg1.svg: Open: flags=O_RDONLY
2020/10/07 18:34:57 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:57 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:57 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:57 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:57 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba180): RWFileHandle.Flush
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:57 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba180): RWFileHandle.Release
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba180): close:
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba180): >close: err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: OpenEx: flags=0x0
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:57 DEBUG : svg1.svg: Open: flags=O_RDONLY
2020/10/07 18:34:57 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:57 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:57 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:57 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: Read: ofst=0, fh=0x2
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0005ae100): _readAt: size=8192, off=0
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0005ae100): openPending:
2020/10/07 18:34:57 DEBUG : svg1.svg: vfs cache: checking remote fingerprint "5871,2020-10-07 09:57:17.992 +0000 UTC,e4b25c7ed8db34764777ae85ca4e37fd" against cached fingerprint "5871,2020-10-07 09:57:17 +0000 UTC,e4b25c7ed8db34764777ae85ca4e37fd"
2020/10/07 18:34:57 DEBUG : svg1.svg: vfs cache: removing cached entry as stale (remote fingerprint "5871,2020-10-07 09:57:17.992 +0000 UTC,e4b25c7ed8db34764777ae85ca4e37fd" != cached fingerprint "5871,2020-10-07 09:57:17 +0000 UTC,e4b25c7ed8db34764777ae85ca4e37fd")
2020/10/07 18:34:57 INFO  : svg1.svg: vfs cache: removed cache file as stale (remote is different)
2020/10/07 18:34:57 DEBUG : svg1.svg: vfs cache: removed metadata from cache as stale (remote is different)
2020/10/07 18:34:57 DEBUG : svg1.svg: vfs cache: truncate to size=5871
2020/10/07 18:34:57 DEBUG : : Added virtual directory entry vAdd: "svg1.svg"
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0005ae100): >openPending: err=<nil>
2020/10/07 18:34:57 DEBUG : vfs cache: looking for range={Pos:0 Size:5871} in [] - present false
2020/10/07 18:34:57 DEBUG : svg1.svg: ChunkedReader.RangeSeek from -1 to 0 length -1
2020/10/07 18:34:57 DEBUG : svg1.svg: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2020/10/07 18:34:57 DEBUG : svg1.svg: ChunkedReader.openRange at 0 length 134217728
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0005ae100): >_readAt: n=5871, err=EOF
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Read: n=5871
2020/10/07 18:34:57 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0005ae100): RWFileHandle.Flush
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:57 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: OpenEx: flags=0x0
2020/10/07 18:34:57 DEBUG : /svg1.svg: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0005ae100): RWFileHandle.Release
2020/10/07 18:34:57 DEBUG : svg1.svg: Open: flags=O_RDONLY
2020/10/07 18:34:57 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:57 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0005ae100): close:
2020/10/07 18:34:57 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:57 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:57 DEBUG : svg1.svg: vfs cache: setting modification time to 2020-10-07 09:57:17.992 +0000 UTC
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0005ae100): >close: err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: Read: ofst=0, fh=0x2
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba340): _readAt: size=8192, off=0
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba340): openPending:
2020/10/07 18:34:57 DEBUG : svg1.svg: vfs cache: checking remote fingerprint "5871,2020-10-07 09:57:17.992 +0000 UTC,e4b25c7ed8db34764777ae85ca4e37fd" against cached fingerprint ""
2020/10/07 18:34:57 DEBUG : svg1.svg: vfs cache: truncate to size=5871
2020/10/07 18:34:57 DEBUG : : Added virtual directory entry vAdd: "svg1.svg"
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba340): >openPending: err=<nil>
2020/10/07 18:34:57 DEBUG : vfs cache: looking for range={Pos:0 Size:5871} in [{Pos:0 Size:5871}] - present true
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba340): >_readAt: n=5871, err=EOF
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Read: n=5871
2020/10/07 18:34:57 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba340): RWFileHandle.Flush
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:57 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba340): RWFileHandle.Release
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba340): close:
2020/10/07 18:34:57 DEBUG : svg1.svg: vfs cache: setting modification time to 2020-10-07 09:57:17.992 +0000 UTC
2020/10/07 18:34:57 DEBUG : svg1.svg(0xc0000ba340): >close: err=<nil>
2020/10/07 18:34:57 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenEx: flags=0x0
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:58 DEBUG : svg1.svg: Open: flags=O_RDONLY
2020/10/07 18:34:58 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:58 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:58 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae500): RWFileHandle.Flush
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae500): RWFileHandle.Release
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenEx: flags=0x1
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae500): close:
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenFile: flags=O_WRONLY, perm=-rwxrwxrwx
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae500): >close: err=<nil>
2020/10/07 18:34:58 DEBUG : svg1.svg: Open: flags=O_WRONLY
2020/10/07 18:34:58 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:34:58 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:58 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae580): RWFileHandle.Flush
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae580): RWFileHandle.Release
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae580): close:
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenEx: flags=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenFile: flags=O_RDWR, perm=-rwxrwxrwx
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae580): >close: err=<nil>
2020/10/07 18:34:58 DEBUG : svg1.svg: Open: flags=O_RDWR
2020/10/07 18:34:58 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:34:58 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:58 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: Truncate: size=0, fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): openPending:
2020/10/07 18:34:58 DEBUG : svg1.svg: vfs cache: checking remote fingerprint "5871,2020-10-07 09:57:17.992 +0000 UTC,e4b25c7ed8db34764777ae85ca4e37fd" against cached fingerprint "5871,2020-10-07 09:57:17.992 +0000 UTC,e4b25c7ed8db34764777ae85ca4e37fd"
2020/10/07 18:34:58 DEBUG : svg1.svg: vfs cache: truncate to size=5871
2020/10/07 18:34:58 DEBUG : : Added virtual directory entry vAdd: "svg1.svg"
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): >openPending: err=<nil>
2020/10/07 18:34:58 DEBUG : svg1.svg: vfs cache: truncate to size=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Truncate: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Truncate: size=291554, fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg: vfs cache: truncate to size=291554
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Truncate: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Write: ofst=0, fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): _writeAt: size=131072, off=0
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): >_writeAt: n=131072, err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Write: n=131072
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Write: ofst=131072, fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): _writeAt: size=131072, off=131072
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): >_writeAt: n=131072, err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Write: n=131072
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Write: ofst=262144, fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): _writeAt: size=29410, off=262144
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): >_writeAt: n=29410, err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Write: n=29410
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Utimens: tmsp=[{Sec:1602064637 Nsec:992000000} {Sec:1601892344 Nsec:0}]
2020/10/07 18:34:58 DEBUG : /svg1.svg: Utimens: SetModTime: 2020-10-05 18:05:44 +0800 CST
2020/10/07 18:34:58 DEBUG : svg1.svg: vfs cache: setting modification time to 2020-10-05 18:05:44 +0800 CST
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Utimens: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Read: ofst=0, fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): _readAt: size=32768, off=0
2020/10/07 18:34:58 DEBUG : vfs cache: looking for range={Pos:0 Size:32768} in [{Pos:0 Size:291554}] - present true
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): >_readAt: n=32768, err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Read: n=32768
2020/10/07 18:34:58 DEBUG : /svg1.svg: Read: ofst=262144, fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): _readAt: size=32768, off=262144
2020/10/07 18:34:58 DEBUG : vfs cache: looking for range={Pos:262144 Size:29410} in [{Pos:0 Size:291554}] - present true
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): >_readAt: n=29410, err=EOF
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Read: n=29410
2020/10/07 18:34:58 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): RWFileHandle.Flush
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): RWFileHandle.Release
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): close:
2020/10/07 18:34:58 DEBUG : vfs cache: looking for range={Pos:0 Size:291554} in [{Pos:0 Size:291554}] - present true
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : svg1.svg: vfs cache: setting modification time to 2020-10-05 18:05:44 +0800 CST
2020/10/07 18:34:58 INFO  : svg1.svg: vfs cache: queuing for upload in 5s
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0005ae5c0): >close: err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenEx: flags=0x0
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:58 DEBUG : svg1.svg: Open: flags=O_RDONLY
2020/10/07 18:34:58 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:58 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:58 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0000ba440): RWFileHandle.Flush
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0000ba440): RWFileHandle.Release
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0000ba440): close:
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0000ba440): >close: err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenEx: flags=0x0
2020/10/07 18:34:58 DEBUG : /svg1.svg: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:58 DEBUG : svg1.svg: Open: flags=O_RDONLY
2020/10/07 18:34:58 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:58 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:58 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: Getattr: fh=0x2
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0000ba480): RWFileHandle.Flush
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:58 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0000ba480): RWFileHandle.Release
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0000ba480): close:
2020/10/07 18:34:58 DEBUG : svg1.svg(0xc0000ba480): >close: err=<nil>
2020/10/07 18:34:58 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Opendir:
2020/10/07 18:34:59 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:59 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/10/07 18:34:59 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Releasedir: fh=0x2
2020/10/07 18:34:59 DEBUG : /: >Releasedir: errc=0
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Opendir:
2020/10/07 18:34:59 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:59 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/10/07 18:34:59 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/10/07 18:34:59 DEBUG : /: Releasedir: fh=0x2
2020/10/07 18:34:59 DEBUG : /: >Releasedir: errc=0
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Opendir:
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/10/07 18:34:59 DEBUG : /: >Opendir: errc=0, fh=0x2
2020/10/07 18:34:59 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Opendir:
2020/10/07 18:34:59 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:59 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2020/10/07 18:34:59 DEBUG : /: >Opendir: errc=0, fh=0x3
2020/10/07 18:34:59 DEBUG : /: Releasedir: fh=0x2
2020/10/07 18:34:59 DEBUG : /: >Releasedir: errc=0
2020/10/07 18:34:59 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /: Releasedir: fh=0x3
2020/10/07 18:34:59 DEBUG : /: >Releasedir: errc=0
2020/10/07 18:34:59 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /svg1.svg: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/10/07 18:34:59 DEBUG : /svg1.svg: >Getattr: errc=0
2020/10/07 18:34:59 DEBUG : /svg1.svg: OpenEx: flags=0x0
2020/10/07 18:34:59 DEBUG : /svg1.svg: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/10/07 18:34:59 DEBUG : svg1.svg: Open: flags=O_RDONLY
2020/10/07 18:34:59 DEBUG : svg1.svg: newRWFileHandle:
2020/10/07 18:34:59 DEBUG : svg1.svg: >newRWFileHandle: err=<nil>
2020/10/07 18:34:59 DEBUG : svg1.svg: >Open: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:59 DEBUG : /svg1.svg: >OpenFile: fd=svg1.svg (rw), err=<nil>
2020/10/07 18:34:59 DEBUG : /svg1.svg: >OpenEx: errc=0, fh=0x2
2020/10/07 18:34:59 DEBUG : /svg1.svg: Flush: fh=0x2
2020/10/07 18:34:59 DEBUG : svg1.svg(0xc0000ba4c0): RWFileHandle.Flush
2020/10/07 18:34:59 DEBUG : /svg1.svg: >Flush: errc=0
2020/10/07 18:34:59 DEBUG : /svg1.svg: Release: fh=0x2
2020/10/07 18:34:59 DEBUG : svg1.svg(0xc0000ba4c0): RWFileHandle.Release
2020/10/07 18:34:59 DEBUG : svg1.svg(0xc0000ba4c0): close:
2020/10/07 18:34:59 DEBUG : svg1.svg(0xc0000ba4c0): >close: err=<nil>
2020/10/07 18:34:59 DEBUG : /svg1.svg: >Release: errc=0
2020/10/07 18:35:03 DEBUG : svg1.svg: vfs cache: starting upload
2020/10/07 18:35:04 DEBUG : svg1.svg: MD5 = 293c2e0267014c17076426ddfdee3d50 OK
2020/10/07 18:35:04 INFO  : svg1.svg: Copied (replaced existing)
2020/10/07 18:35:04 DEBUG : svg1.svg: vfs cache: fingerprint now "291554,2020-10-07 10:35:03 +0000 UTC,293c2e0267014c17076426ddfdee3d50"
2020/10/07 18:35:04 DEBUG : svg1.svg: vfs cache: writeback object to VFS layer
2020/10/07 18:35:04 DEBUG : svg1.svg: Applied pending mod time 2020-10-05 18:05:44 +0800 CST OK
2020/10/07 18:35:04 DEBUG : : Added virtual directory entry vAdd: "svg1.svg"
2020/10/07 18:35:04 INFO  : svg1.svg: vfs cache: upload succeeded try #1
2020/10/07 18:35:11 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item rclone-bucket3v.cmd not removed, freed 0 bytes
2020/10/07 18:35:11 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item svg1.svg not removed, freed 0 bytes
2020/10/07 18:35:11 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item New Text Document.txt not removed, freed 0 bytes
2020/10/07 18:35:11 INFO  : vfs cache: cleaned: objects 3 (was 3) in use 0, to upload 0, uploading 0, total size 284.992k (was 6.005k)
2

This is probably the time being set causing another version - that would be my guess.

3

From server log, there show actions on putObject(...), then copyObject(...)

If your guess is correct, it means copyObject(...) for set the time as the last modified time of the file.

But, why not set the time together when putObject(...) ?

I've also tested with goofys in Linux, there are no such problem.

4

That is correct.

A good question...

It looks like that the program you are using to copy to the mount does

  • open file
  • write data
  • close file
  • set modtime

Which is the expected order of things. However it looks like rclone is setting the modification time twice, once on upload and once again after the upload.

Try this fix which checks first to see if the modification time needs changing.

v1.54.0-beta.4816.c039eec35.fix-vfs-modtime on branch fix-vfs-modtime (uploaded in 15-30 mins)

5

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

6

I've merged this to master now which means it will be in the latest beta in 15-30 mins and released in v1.555