I can recreate it as I just used a small file to produce the same results:
felix@gemini:~$ rclone mount gcrypt: /Test -vv --vfs-cache-mode writes
2020/01/18 13:43:00 DEBUG : rclone: Version "v1.50.2" starting with parameters ["rclone" "mount" "gcrypt:" "/Test" "-vv" "--vfs-cache-mode" "writes"]
2020/01/18 13:43:00 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2020/01/18 13:43:01 DEBUG : Encrypted drive 'gcrypt:': Mounting on "/Test"
2020/01/18 13:43:01 DEBUG : vfs cache root is "/home/felix/.cache/rclone/vfs/gcrypt"
2020/01/18 13:43:01 DEBUG : Adding path "vfs/forget" to remote control registry
2020/01/18 13:43:01 DEBUG : Adding path "vfs/refresh" to remote control registry
2020/01/18 13:43:01 DEBUG : Adding path "vfs/poll-interval" to remote control registry
2020/01/18 13:43:01 DEBUG : : Root:
2020/01/18 13:43:01 DEBUG : : >Root: node=/, err=<nil>
2020/01/18 13:43:01 DEBUG : hosts: updateTime: setting atime to 2020-01-18 12:52:29.160120652 -0500 EST
2020/01/18 13:43:01 INFO : Cleaned the cache: objects 2 (was 0), total size 227 (was 0)
2020/01/18 13:43:50 DEBUG : /: Attr:
2020/01/18 13:43:50 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/01/18 13:43:50 DEBUG : /: Lookup: name="test1"
2020/01/18 13:43:50 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:43:50 DEBUG : /: Lookup: name="test1"
2020/01/18 13:43:50 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:43:50 DEBUG : /: Lookup: name="test1"
2020/01/18 13:43:50 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:43:50 DEBUG : /: Create: name="test1"
2020/01/18 13:43:50 DEBUG : test1: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/18 13:43:50 DEBUG : test1(0xc001dbc120): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/18 13:43:50 DEBUG : test1: >Open: fd=test1 (rw), err=<nil>
2020/01/18 13:43:50 DEBUG : /: >Create: node=test1, handle=&{test1 (rw)}, err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Attr:
2020/01/18 13:43:50 DEBUG : test1: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2020/01/18 13:43:50 DEBUG : &{test1 (rw)}: Write: len=221, offset=0
2020/01/18 13:43:50 DEBUG : &{test1 (rw)}: >Write: written=221, err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Setattr: a=Setattr [ID=0x9 Node=0x2 Uid=1000 Gid=1000 Pid=4224] atime=2020-01-18 13:43:42.144765598 -0500 EST mtime=2019-11-29 10:03:32.235951748 -0500 EST handle=INVALID-0x0
2020/01/18 13:43:50 DEBUG : test1: >Setattr: err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Attr:
2020/01/18 13:43:50 DEBUG : test1: >Attr: a=valid=1s ino=0 size=221 mode=-rw-rw-r--, err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Setattr: a=Setattr [ID=0xb Node=0x2 Uid=1000 Gid=1000 Pid=4224] mode=-rw-rw-r-- handle=INVALID-0x0
2020/01/18 13:43:50 DEBUG : test1: >Setattr: err=<nil>
2020/01/18 13:43:50 DEBUG : test1: Attr:
2020/01/18 13:43:50 DEBUG : test1: >Attr: a=valid=1s ino=0 size=221 mode=-rw-rw-r--, err=<nil>
2020/01/18 13:43:50 DEBUG : &{test1 (rw)}: Flush:
2020/01/18 13:43:50 DEBUG : test1: Need to transfer - File not found at Destination
2020/01/18 13:43:52 INFO : test1: Copied (new)
2020/01/18 13:43:52 DEBUG : test1: File.applyPendingModTime OK
2020/01/18 13:43:52 DEBUG : test1: transferred to remote
2020/01/18 13:43:52 DEBUG : &{test1 (rw)}: >Flush: err=<nil>
2020/01/18 13:43:52 DEBUG : &{test1 (rw)}: Release:
2020/01/18 13:43:52 DEBUG : test1(0xc001dbc120): RWFileHandle.Release closing
2020/01/18 13:43:52 DEBUG : test1(0xc001dbc120): close:
2020/01/18 13:43:52 DEBUG : test1: File.delWriter couldn't find handle
2020/01/18 13:43:52 DEBUG : test1: Modification times differ by -1203h40m18.009798119s: 2020-01-18 13:43:50.244798119 -0500 EST, 2019-11-29 15:03:32.235 +0000 UTC
2020/01/18 13:43:53 INFO : test1: Copied (replaced existing)
2020/01/18 13:43:53 DEBUG : test1: transferred to remote
2020/01/18 13:43:53 DEBUG : test1(0xc001dbc120): >close: err=<nil>
2020/01/18 13:43:53 DEBUG : &{test1 (rw)}: >Release: err=<nil>
2020/01/18 13:44:01 DEBUG : Google drive root 'crypt': Checking for changes on remote
2020/01/18 13:44:01 INFO : Cleaned the cache: objects 3 (was 3), total size 448 (was 227)
2020/01/18 13:44:01 DEBUG : : changeNotify: relativePath="test1", type=3
2020/01/18 13:44:01 DEBUG : : invalidating directory cache
2020/01/18 13:44:01 DEBUG : : >changeNotify:
and if I do just a cp:
2020/01/18 13:46:00 DEBUG : /: Lookup: name="cptest"
2020/01/18 13:46:00 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:46:00 DEBUG : /: Lookup: name="cptest"
2020/01/18 13:46:00 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:46:00 DEBUG : /: Lookup: name="cptest"
2020/01/18 13:46:00 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2020/01/18 13:46:00 DEBUG : /: Create: name="cptest"
2020/01/18 13:46:00 DEBUG : cptest: Open: flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/18 13:46:00 DEBUG : cptest(0xc00008c180): Opening cached copy with flags=O_WRONLY|O_CREATE|O_EXCL
2020/01/18 13:46:00 DEBUG : cptest: >Open: fd=cptest (rw), err=<nil>
2020/01/18 13:46:00 DEBUG : /: >Create: node=cptest, handle=&{cptest (rw)}, err=<nil>
2020/01/18 13:46:00 DEBUG : cptest: Attr:
2020/01/18 13:46:00 DEBUG : cptest: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2020/01/18 13:46:00 DEBUG : &{cptest (rw)}: Write: len=227, offset=0
2020/01/18 13:46:00 DEBUG : &{cptest (rw)}: >Write: written=227, err=<nil>
2020/01/18 13:46:00 DEBUG : &{cptest (rw)}: Flush:
2020/01/18 13:46:00 DEBUG : cptest: Need to transfer - File not found at Destination
2020/01/18 13:46:01 DEBUG : Google drive root 'crypt': Checking for changes on remote
2020/01/18 13:46:01 DEBUG : cptest: updateTime: setting atime to 2020-01-18 13:46:00.697323085 -0500 EST
2020/01/18 13:46:01 INFO : Cleaned the cache: objects 4 (was 4), total size 675 (was 448)
2020/01/18 13:46:01 INFO : cptest: Copied (new)
2020/01/18 13:46:01 DEBUG : cptest: transferred to remote
2020/01/18 13:46:01 DEBUG : &{cptest (rw)}: >Flush: err=<nil>
2020/01/18 13:46:01 DEBUG : &{cptest (rw)}: Release:
2020/01/18 13:46:01 DEBUG : cptest(0xc00008c180): RWFileHandle.Release closing
2020/01/18 13:46:01 DEBUG : cptest(0xc00008c180): close:
2020/01/18 13:46:01 DEBUG : cptest: File.delWriter couldn't find handle
2020/01/18 13:46:01 DEBUG : cptest: Size and modification time the same (differ by -322.489µs, within tolerance 1ms)
2020/01/18 13:46:01 DEBUG : cptest: Unchanged skipping
2020/01/18 13:46:01 DEBUG : cptest: transferred to remote
2020/01/18 13:46:01 DEBUG : cptest(0xc00008c180): >close: err=<nil>
2020/01/18 13:46:01 DEBUG : &{cptest (rw)}: >Release: err=<nil>
That does seem to be a neat one.
@ncw - do you see something here as well? I think it merits a bug report.