"./vfs.test -test.v -test.timeout 1h0m0s -remote TestCache: -verbose -test.run '^TestFileRename$/^minimal,forceCache=true$'" - Starting (try 5/5)
2020/07/24 10:27:16 DEBUG : TestCache: wrapped local:/tmp/rclone_cache_test/rclone-test-biyixor1fopaxaz1mezusug5 at root rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : TestCache: Cache DB path: /home/rclone/.cache/rclone/cache-backend/TestCache.db
2020/07/24 10:27:16 INFO  : TestCache: Cache chunk path: /home/rclone/.cache/rclone/cache-backend/TestCache
2020/07/24 10:27:16 INFO  : TestCache: Chunk Memory: true
2020/07/24 10:27:16 INFO  : TestCache: Chunk Size: 5M
2020/07/24 10:27:16 INFO  : TestCache: Chunk Total Size: 10G
2020/07/24 10:27:16 INFO  : TestCache: Chunk Clean Interval: 1m0s
2020/07/24 10:27:16 INFO  : TestCache: Workers: 4
2020/07/24 10:27:16 INFO  : TestCache: File Age: 6h0m0s
2020/07/24 10:27:16 DEBUG : Adding path "cache/expire" to remote control registry
2020/07/24 10:27:16 DEBUG : Adding path "cache/stats" to remote control registry
2020/07/24 10:27:16 DEBUG : Adding path "cache/fetch" to remote control registry
=== RUN   TestFileRename
=== RUN   TestFileRename/minimal,forceCache=true
2020/07/24 10:27:16 INFO  : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: poll-interval is not supported by this remote
2020/07/24 10:27:16 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-biyixor1fopaxaz1mezusug5"
2020/07/24 10:27:16 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-biyixor1fopaxaz1mezusug5"
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: mkdir ''
2020/07/24 10:27:16 DEBUG : : mkdir: created dir in source fs
2020/07/24 10:27:16 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/07/24 10:27:16 DEBUG : : mkdir: added to cache
2020/07/24 10:27:16 DEBUG : : cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : : mkdir: cache expired
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: put data at 'dir/file1'
2020/07/24 10:27:16 DEBUG : dir/file1: put: uploaded to remote fs
2020/07/24 10:27:16 DEBUG : dir/file1: put: added to cache
2020/07/24 10:27:16 DEBUG : dir: cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : dir: put: cache expired
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list ''
2020/07/24 10:27:16 DEBUG : : list: cold listing: 2020-07-24 04:27:16.418990254 +0000 UTC
2020/07/24 10:27:16 DEBUG : : list: read 1 from source
2020/07/24 10:27:16 DEBUG : : list: source entries: [dir]
2020/07/24 10:27:16 DEBUG : : list: cached directories: 1
2020/07/24 10:27:16 DEBUG : : list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5', cache ts: 2020-07-24 10:27:16.44402424 +0000 UTC m=+0.091460038
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list 'dir'
2020/07/24 10:27:16 DEBUG : dir: list: warm 1 from cache for: rclone-test-biyixor1fopaxaz1mezusug5/dir, expiring on: 2020-07-24 16:27:16.432539686 +0000 UTC
2020/07/24 10:27:16 DEBUG : dir: list: cached entries: [dir/file1]
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: f401d3a6
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list ''
2020/07/24 10:27:16 DEBUG : : list: warm 1 from cache for: rclone-test-biyixor1fopaxaz1mezusug5, expiring on: 2020-07-24 16:27:16.44402424 +0000 UTC
2020/07/24 10:27:16 DEBUG : : list: cached entries: [dir]
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list 'dir'
2020/07/24 10:27:16 DEBUG : dir: list: warm 1 from cache for: rclone-test-biyixor1fopaxaz1mezusug5/dir, expiring on: 2020-07-24 16:27:16.432539686 +0000 UTC
2020/07/24 10:27:16 DEBUG : dir: list: cached entries: [dir/file1]
2020/07/24 10:27:16 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2020/07/24 10:27:16 DEBUG : dir/file1: newRWFileHandle: 
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000092dc0): openPending: 
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint ""
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/07/24 10:27:16 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000092dc0): >openPending: err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/07/24 10:27:16 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/07/24 10:27:16 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/07/24 10:27:16 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000092dc0): _writeAt: size=14, off=0
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000092dc0): >_writeAt: n=14, err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000092dc0): close: 
2020/07/24 10:27:16 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:27:16.541893878 +0000 UTC m=+0.189329696
2020/07/24 10:27:16 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000092dc0): >close: err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/07/24 10:27:16 DEBUG : dir/file1: newRWFileHandle: 
2020/07/24 10:27:16 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000093080): _readAt: size=512, off=0
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000093080): openPending: 
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/07/24 10:27:16 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000093080): >openPending: err=<nil>
2020/07/24 10:27:16 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000093080): >_readAt: n=14, err=EOF
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000093080): close: 
2020/07/24 10:27:16 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:27:16.541893878 +0000 UTC m=+0.189329696
2020/07/24 10:27:16 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/07/24 10:27:16 DEBUG : dir/file1(0xc000093080): >close: err=<nil>
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list ''
2020/07/24 10:27:16 DEBUG : : list: warm 1 from cache for: rclone-test-biyixor1fopaxaz1mezusug5, expiring on: 2020-07-24 16:27:16.44402424 +0000 UTC
2020/07/24 10:27:16 DEBUG : : list: cached entries: [dir]
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list 'dir'
2020/07/24 10:27:16 DEBUG : dir: list: warm 1 from cache for: rclone-test-biyixor1fopaxaz1mezusug5/dir, expiring on: 2020-07-24 16:27:16.432539686 +0000 UTC
2020/07/24 10:27:16 DEBUG : dir: list: cached entries: [dir/file1]
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: new object 'newLeaf'
2020/07/24 10:27:16 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/07/24 10:27:16 DEBUG : find failed: not found in either local or remote fs
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: moving obj 'dir/file1' -> newLeaf
2020/07/24 10:27:16 DEBUG : newLeaf: move: file moved
2020/07/24 10:27:16 DEBUG : dir/file1: move: removed from cache
2020/07/24 10:27:16 DEBUG : dir: cache: expired rclone-test-biyixor1fopaxaz1mezusug5/dir
2020/07/24 10:27:16 DEBUG : dir: cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : dir: move: cache expired
2020/07/24 10:27:16 DEBUG : newLeaf: move: added to cache
2020/07/24 10:27:16 DEBUG : : cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : : move: cache expired
2020/07/24 10:27:16 INFO  : dir/file1: Moved (server side)
2020/07/24 10:27:16 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/07/24 10:27:16 DEBUG : newLeaf: Updating file with newLeaf 0xc000276600
2020/07/24 10:27:16 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/07/24 10:27:16 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list ''
2020/07/24 10:27:16 DEBUG : : list: cold listing: 2020-07-24 04:27:16.582950449 +0000 UTC
2020/07/24 10:27:16 DEBUG : : list: read 2 from source
2020/07/24 10:27:16 DEBUG : : list: source entries: [newLeaf dir]
2020/07/24 10:27:16 DEBUG : : list: cached object: newLeaf
2020/07/24 10:27:16 DEBUG : : list: cached directories: 0
2020/07/24 10:27:16 DEBUG : : list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5', cache ts: 2020-07-24 10:27:16.603594729 +0000 UTC m=+0.251030527
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list 'dir'
2020/07/24 10:27:16 DEBUG : dir: list: cold listing: 2020-07-24 04:27:16.562697889 +0000 UTC
2020/07/24 10:27:16 DEBUG : dir: list: read 0 from source
2020/07/24 10:27:16 DEBUG : dir: list: source entries: []
2020/07/24 10:27:16 DEBUG : dir: list: cached directories: 0
2020/07/24 10:27:16 DEBUG : dir: list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5/dir', cache ts: 2020-07-24 10:27:16.617489834 +0000 UTC m=+0.264925653
2020/07/24 10:27:16 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/07/24 10:27:16 DEBUG : newLeaf: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/07/24 10:27:16 DEBUG : newLeaf: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/07/24 10:27:16 DEBUG : newLeaf: object hash cached: f401d3a6
2020/07/24 10:27:16 DEBUG : newLeaf: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/07/24 10:27:16 DEBUG : newLeaf: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/07/24 10:27:16 DEBUG : newLeaf: vfs cache: starting upload
2020/07/24 10:27:16 DEBUG : newLeaf: updating object contents with size 14
2020/07/24 10:27:16 DEBUG : newLeaf: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: new object 'dir/file1'
2020/07/24 10:27:16 DEBUG : dir/file1: find: error: couldn't find object (file1)
2020/07/24 10:27:16 DEBUG : find failed: not found in either local or remote fs
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: moving obj 'newLeaf' -> dir/file1
2020/07/24 10:27:16 DEBUG : dir/file1: move: file moved
2020/07/24 10:27:16 ERROR : newLeaf: Failed to calculate dst hash: hash: failed to open: open /tmp/rclone_cache_test/rclone-test-biyixor1fopaxaz1mezusug5/newLeaf: no such file or directory
2020/07/24 10:27:16 ERROR : newLeaf: corrupted on transfer: MD5 hash differ "0ef726ce9b1a7692357ff70dd321d595" vs ""
2020/07/24 10:27:16 INFO  : newLeaf: Removing failed copy
2020/07/24 10:27:16 INFO  : newLeaf: Failed to remove failed copy: remove /tmp/rclone_cache_test/rclone-test-biyixor1fopaxaz1mezusug5/newLeaf: no such file or directory
2020/07/24 10:27:16 ERROR : newLeaf: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: corrupted on transfer: MD5 hash differ "0ef726ce9b1a7692357ff70dd321d595" vs ""
2020/07/24 10:27:16 DEBUG : newLeaf: move: removed from cache
2020/07/24 10:27:16 DEBUG : : cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : : move: cache expired
2020/07/24 10:27:16 DEBUG : dir/file1: move: added to cache
2020/07/24 10:27:16 DEBUG : dir: cache: expired rclone-test-biyixor1fopaxaz1mezusug5/dir
2020/07/24 10:27:16 DEBUG : dir: cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : dir: move: cache expired
2020/07/24 10:27:16 INFO  : newLeaf: Moved (server side)
2020/07/24 10:27:16 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2020/07/24 10:27:16 DEBUG : dir/file1: Updating file with dir/file1 0xc000276600
2020/07/24 10:27:16 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2020/07/24 10:27:16 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list ''
2020/07/24 10:27:16 DEBUG : : list: cold listing: 2020-07-24 04:27:16.749800253 +0000 UTC
2020/07/24 10:27:16 DEBUG : : list: read 1 from source
2020/07/24 10:27:16 DEBUG : : list: source entries: [dir]
2020/07/24 10:27:16 DEBUG : : list: cached directories: 0
2020/07/24 10:27:16 DEBUG : : list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5', cache ts: 2020-07-24 10:27:16.763441832 +0000 UTC m=+0.410877639
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list 'dir'
2020/07/24 10:27:16 DEBUG : dir: list: cold listing: 2020-07-24 04:27:16.749800253 +0000 UTC
2020/07/24 10:27:16 DEBUG : dir: list: read 1 from source
2020/07/24 10:27:16 DEBUG : dir: list: source entries: [dir/file1]
2020/07/24 10:27:16 DEBUG : dir: list: cached object: dir/file1
2020/07/24 10:27:16 DEBUG : dir: list: cached directories: 0
2020/07/24 10:27:16 DEBUG : dir: list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5/dir', cache ts: 2020-07-24 10:27:16.782641786 +0000 UTC m=+0.430077583
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: f401d3a6
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: starting upload
2020/07/24 10:27:16 DEBUG : dir/file1: updating object contents with size 14
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/07/24 10:27:16 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/07/24 10:27:16 DEBUG : dir/file1: newRWFileHandle: 
2020/07/24 10:27:16 DEBUG : dir/file1(0xc0003a9f40): openPending: 
2020/07/24 10:27:16 DEBUG : dir/file1: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2020/07/24 10:27:16 INFO  : dir/file1: Copied (replaced existing)
2020/07/24 10:27:16 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2020-07-24 10:27:16.541893878 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: removing cached entry as stale (remote fingerprint "14,2020-07-24 10:27:16.541893878 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" != cached fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595")
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc000246460 item 1
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: cancelling upload
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: fingerprint now "14,2020-07-24 10:27:16.541893878 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: writeback object to VFS layer
2020/07/24 10:27:16 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/07/24 10:27:16 INFO  : dir/file1: vfs cache: upload succeeded try #2
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: cancelled upload
2020/07/24 10:27:16 INFO  : dir/file1: vfs cache: removed cache file as stale (remote is different)
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: removed metadata from cache as stale (remote is different)
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/07/24 10:27:16 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/07/24 10:27:16 DEBUG : dir/file1(0xc0003a9f40): >openPending: err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/07/24 10:27:16 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/07/24 10:27:16 DEBUG : dir/file1(0xc0003a9f40): _writeAt: size=25, off=0
2020/07/24 10:27:16 DEBUG : dir/file1(0xc0003a9f40): >_writeAt: n=25, err=<nil>
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: new object 'newLeaf'
2020/07/24 10:27:16 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/07/24 10:27:16 DEBUG : find failed: not found in either local or remote fs
2020/07/24 10:27:16 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: moving obj 'dir/file1' -> newLeaf
2020/07/24 10:27:16 DEBUG : newLeaf: move: file moved
2020/07/24 10:27:16 DEBUG : dir/file1: move: removed from cache
2020/07/24 10:27:16 DEBUG : dir: cache: expired rclone-test-biyixor1fopaxaz1mezusug5/dir
2020/07/24 10:27:16 DEBUG : dir: cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : dir: move: cache expired
2020/07/24 10:27:16 DEBUG : newLeaf: move: added to cache
2020/07/24 10:27:16 DEBUG : : cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:16 INFO  : : move: cache expired
2020/07/24 10:27:16 INFO  : dir/file1: Moved (server side)
2020/07/24 10:27:16 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/07/24 10:27:16 DEBUG : newLeaf: Updating file with newLeaf 0xc000276600
2020/07/24 10:27:16 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/07/24 10:27:16 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/07/24 10:27:16 DEBUG : newLeaf(0xc0003a9f40): close: 
2020/07/24 10:27:16 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2020/07/24 10:27:16 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:27:16.916764648 +0000 UTC m=+0.564200454
2020/07/24 10:27:16 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2020/07/24 10:27:16 DEBUG : newLeaf(0xc0003a9f40): >close: err=<nil>
2020/07/24 10:27:16 DEBUG : WaitForWriters: timeout=10s
2020/07/24 10:27:16 DEBUG : dir: Looking for writers
2020/07/24 10:27:16 DEBUG : : Looking for writers
2020/07/24 10:27:16 DEBUG : dir: reading active writers
2020/07/24 10:27:16 DEBUG : newLeaf: reading active writers
2020/07/24 10:27:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/07/24 10:27:16 DEBUG : dir: Looking for writers
2020/07/24 10:27:16 DEBUG : : Looking for writers
2020/07/24 10:27:16 DEBUG : dir: reading active writers
2020/07/24 10:27:16 DEBUG : newLeaf: reading active writers
2020/07/24 10:27:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/07/24 10:27:17 DEBUG : dir: Looking for writers
2020/07/24 10:27:17 DEBUG : : Looking for writers
2020/07/24 10:27:17 DEBUG : newLeaf: reading active writers
2020/07/24 10:27:17 DEBUG : dir: reading active writers
2020/07/24 10:27:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/07/24 10:27:17 DEBUG : dir: Looking for writers
2020/07/24 10:27:17 DEBUG : : Looking for writers
2020/07/24 10:27:17 DEBUG : dir: reading active writers
2020/07/24 10:27:17 DEBUG : newLeaf: reading active writers
2020/07/24 10:27:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/07/24 10:27:17 DEBUG : newLeaf: vfs cache: starting upload
2020/07/24 10:27:17 DEBUG : newLeaf: updating object contents with size 25
2020/07/24 10:27:17 DEBUG : newLeaf: object hash cached: c7247bead226dfd7bd970c17229f4044
2020/07/24 10:27:17 DEBUG : newLeaf: MD5 = c7247bead226dfd7bd970c17229f4044 OK
2020/07/24 10:27:17 INFO  : newLeaf: Copied (replaced existing)
2020/07/24 10:27:17 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:27:16.916764648 +0000 UTC,c7247bead226dfd7bd970c17229f4044"
2020/07/24 10:27:17 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2020/07/24 10:27:17 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/07/24 10:27:17 INFO  : newLeaf: vfs cache: upload succeeded try #1
2020/07/24 10:27:17 DEBUG : dir: Looking for writers
2020/07/24 10:27:17 DEBUG : : Looking for writers
2020/07/24 10:27:17 DEBUG : dir: reading active writers
2020/07/24 10:27:17 DEBUG : newLeaf: reading active writers
2020/07/24 10:27:17 DEBUG : >WaitForWriters: 
2020/07/24 10:27:17 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list ''
2020/07/24 10:27:17 DEBUG : : list: cold listing: 2020-07-24 04:27:16.955404039 +0000 UTC
2020/07/24 10:27:17 DEBUG : : list: read 2 from source
2020/07/24 10:27:17 DEBUG : : list: source entries: [newLeaf dir]
2020/07/24 10:27:17 DEBUG : : list: cached object: newLeaf
2020/07/24 10:27:17 DEBUG : : list: cached directories: 0
2020/07/24 10:27:17 DEBUG : : list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5', cache ts: 2020-07-24 10:27:17.131645503 +0000 UTC m=+0.779081310
2020/07/24 10:27:17 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list 'dir'
2020/07/24 10:27:17 DEBUG : dir: list: cold listing: 2020-07-24 04:27:16.931175364 +0000 UTC
2020/07/24 10:27:17 DEBUG : dir: list: read 0 from source
2020/07/24 10:27:17 DEBUG : dir: list: source entries: []
2020/07/24 10:27:17 DEBUG : dir: list: cached directories: 0
2020/07/24 10:27:17 DEBUG : dir: list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5/dir', cache ts: 2020-07-24 10:27:17.141035318 +0000 UTC m=+0.788471116
2020/07/24 10:27:17 DEBUG : newLeaf: object hash cached: c7247bead226dfd7bd970c17229f4044
2020/07/24 10:27:17 DEBUG : newLeaf: object hash cached: f1f3d7db56f36d9a5a912b01803c2176a972b9b0
2020/07/24 10:27:17 DEBUG : newLeaf: object hash cached: 1db58adace4d798a32319ad95a298d8714268fa67a177378850892c9caaf4a51a10b8ffc1a9ffb9c77defb66c37d22019d36a931fe50c5f5d9d612c7291105b0
2020/07/24 10:27:17 DEBUG : newLeaf: object hash cached: e19d76ab
2020/07/24 10:27:17 DEBUG : newLeaf: object hash cached: c28ee946ceebc5dd7464b525fdfc3a480f47b2b22832edbfc4741c21a9d4c664
2020/07/24 10:27:17 DEBUG : newLeaf: object hash cached: 529d670c651f4f3f7011e4ab2d16332c1803bbe5
2020/07/24 10:27:17 DEBUG : newLeaf: object hash cached: 954e6302251b5e744b33bcf26f301bca00023794
2020/07/24 10:27:17 DEBUG : WaitForWriters: timeout=10s
2020/07/24 10:27:17 DEBUG : dir: Looking for writers
2020/07/24 10:27:17 DEBUG : : Looking for writers
2020/07/24 10:27:17 DEBUG : dir: reading active writers
2020/07/24 10:27:17 DEBUG : newLeaf: reading active writers
2020/07/24 10:27:17 DEBUG : >WaitForWriters: 
2020/07/24 10:27:17 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list ''
2020/07/24 10:27:17 DEBUG : vfs cache: cleaner exiting
2020/07/24 10:27:17 DEBUG : : list: warm 2 from cache for: rclone-test-biyixor1fopaxaz1mezusug5, expiring on: 2020-07-24 16:27:17.131645503 +0000 UTC
2020/07/24 10:27:17 DEBUG : : list: cached entries: [dir newLeaf]
2020/07/24 10:27:17 DEBUG : newLeaf: removing object
2020/07/24 10:27:17 DEBUG : : cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:17 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list 'dir'
2020/07/24 10:27:17 DEBUG : dir: list: empty listing
2020/07/24 10:27:17 DEBUG : dir: list: read 0 from source
2020/07/24 10:27:17 DEBUG : dir: list: source entries: []
2020/07/24 10:27:17 DEBUG : dir: list: cached directories: 0
2020/07/24 10:27:17 DEBUG : dir: list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5/dir', cache ts: 2020-07-24 10:27:17.278725248 +0000 UTC m=+0.926161049
2020/07/24 10:27:17 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: rmdir 'dir'
2020/07/24 10:27:17 DEBUG : dir: rmdir: removed dir in source fs
2020/07/24 10:27:17 DEBUG : dir: rmdir: removed from cache
2020/07/24 10:27:17 DEBUG : : cache: expired rclone-test-biyixor1fopaxaz1mezusug5
2020/07/24 10:27:17 INFO  : : rmdir: cache expired
2020/07/24 10:27:17 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: list ''
2020/07/24 10:27:17 DEBUG : : list: cold listing: 2020-07-24 04:27:17.292821059 +0000 UTC
2020/07/24 10:27:17 DEBUG : : list: read 0 from source
2020/07/24 10:27:17 DEBUG : : list: source entries: []
2020/07/24 10:27:17 DEBUG : : list: cached directories: 0
2020/07/24 10:27:17 DEBUG : : list: cached dir: 'rclone-test-biyixor1fopaxaz1mezusug5', cache ts: 2020-07-24 10:27:17.300126635 +0000 UTC m=+0.947562438
--- FAIL: TestFileRename (0.93s)
    --- FAIL: TestFileRename/minimal,forceCache=true (0.93s)
        run.go:176: Remote "Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5", Local "Local file system at /tmp/rclone337972805", Modify Window "1ns"
        fstest.go:124: 
            	Error Trace:	fstest.go:124
            	            				fstest.go:129
            	            				fstest.go:148
            	            				fstest.go:192
            	            				fstest.go:305
            	            				fstest.go:335
            	            				fstest.go:347
            	            				file_test.go:305
            	            				file_test.go:357
            	Error:      	Should be true
            	Test:       	TestFileRename/minimal,forceCache=true
            	Messages:   	dir/file1: Modification time difference too big |-170670h22m10.041893879s| > 1ns (want 2001-02-03 04:05:06.499999999 +0000 UTC vs got 2020-07-24 10:27:16.541893878 +0000 UTC) (precision 1ns)
FAIL
2020/07/24 10:27:17 DEBUG : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: Purge remote
2020/07/24 10:27:17 INFO  : Cache remote TestCache:rclone-test-biyixor1fopaxaz1mezusug5: purging cache
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestCache: -verbose -test.run '^TestFileRename$/^minimal,forceCache=true$'" - Finished ERROR in 965.693578ms (try 5/5): exit status 1: Failed [TestFileRename/minimal,forceCache=true]