"./vfs.test -test.v -test.timeout 1h0m0s -remote TestCache: -verbose -test.run '^TestFileRename$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Starting (try 3/5)
2020/08/16 05:30:07 DEBUG : TestCache: wrapped local:/tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8 at root rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:07 INFO  : TestCache: Cache DB path: /home/rclone/.cache/rclone/cache-backend/TestCache.db
2020/08/16 05:30:07 INFO  : TestCache: Cache chunk path: /home/rclone/.cache/rclone/cache-backend/TestCache
2020/08/16 05:30:07 INFO  : TestCache: Chunk Memory: true
2020/08/16 05:30:07 INFO  : TestCache: Chunk Size: 5M
2020/08/16 05:30:07 INFO  : TestCache: Chunk Total Size: 10G
2020/08/16 05:30:07 INFO  : TestCache: Chunk Clean Interval: 1m0s
2020/08/16 05:30:07 INFO  : TestCache: Workers: 4
2020/08/16 05:30:07 INFO  : TestCache: File Age: 6h0m0s
2020/08/16 05:30:07 DEBUG : Adding path "cache/expire" to remote control registry
2020/08/16 05:30:07 DEBUG : Adding path "cache/stats" to remote control registry
2020/08/16 05:30:07 DEBUG : Adding path "cache/fetch" to remote control registry
=== RUN   TestFileRename
=== RUN   TestFileRename/minimal,forceCache=true
    run.go:176: Remote "Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8", Local "Local file system at /tmp/rclone171872084", Modify Window "1ns"
2020/08/16 05:30:07 INFO  : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: poll-interval is not supported by this remote
2020/08/16 05:30:07 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-cojavel6horopoq1kifexof8"
2020/08/16 05:30:07 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-cojavel6horopoq1kifexof8"
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: mkdir ''
2020/08/16 05:30:07 DEBUG : : mkdir: created dir in source fs
2020/08/16 05:30:07 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/08/16 05:30:07 DEBUG : : mkdir: added to cache
2020/08/16 05:30:07 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:07 INFO  : : mkdir: cache expired
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: put data at 'dir/file1'
2020/08/16 05:30:07 DEBUG : dir/file1: put: uploaded to remote fs
2020/08/16 05:30:07 DEBUG : dir/file1: put: added to cache
2020/08/16 05:30:07 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:07 INFO  : dir: put: cache expired
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:07 DEBUG : : list: cold listing: 2020-08-15 23:30:07.577596717 +0000 UTC
2020/08/16 05:30:07 DEBUG : : list: read 1 from source
2020/08/16 05:30:07 DEBUG : : list: source entries: [dir]
2020/08/16 05:30:07 DEBUG : : list: cached directories: 1
2020/08/16 05:30:07 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:07.597616245 +0000 UTC m=+0.079671752
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:07 DEBUG : dir: list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8/dir, expiring on: 2020-08-16 11:30:07.588522716 +0000 UTC
2020/08/16 05:30:07 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:07 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:07 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:07 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:07 DEBUG : dir/file1: object hash cached: f401d3a6
2020/08/16 05:30:07 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:07 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:07 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:07 DEBUG : : list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8, expiring on: 2020-08-16 11:30:07.597616245 +0000 UTC
2020/08/16 05:30:07 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:07 DEBUG : dir: list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8/dir, expiring on: 2020-08-16 11:30:07.588522716 +0000 UTC
2020/08/16 05:30:07 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:07 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2020/08/16 05:30:07 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:07 DEBUG : dir/file1(0xc000428640): openPending: 
2020/08/16 05:30:07 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint ""
2020/08/16 05:30:07 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:07 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:07 DEBUG : dir/file1(0xc000428640): >openPending: err=<nil>
2020/08/16 05:30:07 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/08/16 05:30:07 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:07 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:07 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:07 DEBUG : dir/file1(0xc000428640): _writeAt: size=14, off=0
2020/08/16 05:30:07 DEBUG : dir/file1(0xc000428640): >_writeAt: n=14, err=<nil>
2020/08/16 05:30:07 DEBUG : dir/file1(0xc000428640): close: 
2020/08/16 05:30:07 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:07 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 05:30:07.701644155 +0000 UTC m=+0.183699676
2020/08/16 05:30:07 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:07 DEBUG : dir/file1(0xc000428640): >close: err=<nil>
2020/08/16 05:30:07 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/08/16 05:30:07 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:07 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:07 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:07 DEBUG : dir/file1(0xc0004286c0): _readAt: size=512, off=0
2020/08/16 05:30:07 DEBUG : dir/file1(0xc0004286c0): openPending: 
2020/08/16 05:30:07 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/08/16 05:30:07 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:07 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:07 DEBUG : dir/file1(0xc0004286c0): >openPending: err=<nil>
2020/08/16 05:30:07 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:07 DEBUG : dir/file1(0xc0004286c0): >_readAt: n=14, err=EOF
2020/08/16 05:30:07 DEBUG : dir/file1(0xc0004286c0): close: 
2020/08/16 05:30:07 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:07 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 05:30:07.701644155 +0000 UTC m=+0.183699676
2020/08/16 05:30:07 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:07 DEBUG : dir/file1(0xc0004286c0): >close: err=<nil>
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:07 DEBUG : : list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8, expiring on: 2020-08-16 11:30:07.597616245 +0000 UTC
2020/08/16 05:30:07 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:07 DEBUG : dir: list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8/dir, expiring on: 2020-08-16 11:30:07.588522716 +0000 UTC
2020/08/16 05:30:07 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: new object 'newLeaf'
2020/08/16 05:30:07 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/08/16 05:30:07 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: moving obj 'dir/file1' -> newLeaf
2020/08/16 05:30:07 DEBUG : newLeaf: move: file moved
2020/08/16 05:30:07 DEBUG : dir/file1: move: removed from cache
2020/08/16 05:30:07 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8/dir
2020/08/16 05:30:07 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:07 INFO  : dir: move: cache expired
2020/08/16 05:30:07 DEBUG : newLeaf: move: added to cache
2020/08/16 05:30:07 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:07 INFO  : : move: cache expired
2020/08/16 05:30:07 INFO  : dir/file1: Moved (server side)
2020/08/16 05:30:07 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/08/16 05:30:07 DEBUG : newLeaf: Updating file with newLeaf 0xc00030c600
2020/08/16 05:30:07 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/08/16 05:30:07 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:07 DEBUG : : list: cold listing: 2020-08-15 23:30:07.747637003 +0000 UTC
2020/08/16 05:30:07 DEBUG : : list: read 2 from source
2020/08/16 05:30:07 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:07 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:07 DEBUG : : list: cached directories: 0
2020/08/16 05:30:07 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:07.780466281 +0000 UTC m=+0.262521789
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:07 DEBUG : dir: list: cold listing: 2020-08-15 23:30:07.721834029 +0000 UTC
2020/08/16 05:30:07 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:07 DEBUG : dir: list: source entries: []
2020/08/16 05:30:07 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:07 DEBUG : dir: list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8/dir', cache ts: 2020-08-16 05:30:07.79876695 +0000 UTC m=+0.280822464
2020/08/16 05:30:07 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:07 DEBUG : newLeaf: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:07 DEBUG : newLeaf: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:07 DEBUG : newLeaf: vfs cache: starting upload
2020/08/16 05:30:07 DEBUG : newLeaf: updating object contents with size 14
2020/08/16 05:30:07 DEBUG : newLeaf: object hash cached: f401d3a6
2020/08/16 05:30:07 DEBUG : newLeaf: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:07 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:07 DEBUG : newLeaf: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2020/08/16 05:30:07 INFO  : newLeaf: Copied (replaced existing)
2020/08/16 05:30:07 DEBUG : newLeaf: vfs cache: fingerprint now "14,2020-08-16 05:30:07.701644155 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2020/08/16 05:30:07 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2020/08/16 05:30:07 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:07 INFO  : newLeaf: vfs cache: upload succeeded try #1
2020/08/16 05:30:07 DEBUG : newLeaf: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:07 DEBUG : newLeaf: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: new object 'dir/file1'
2020/08/16 05:30:07 DEBUG : dir/file1: find: error: couldn't find object (file1)
2020/08/16 05:30:07 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: moving obj 'newLeaf' -> dir/file1
2020/08/16 05:30:07 DEBUG : dir/file1: move: file moved
2020/08/16 05:30:07 DEBUG : newLeaf: move: removed from cache
2020/08/16 05:30:07 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:07 INFO  : : move: cache expired
2020/08/16 05:30:07 DEBUG : dir/file1: move: added to cache
2020/08/16 05:30:07 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8/dir
2020/08/16 05:30:07 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:07 INFO  : dir: move: cache expired
2020/08/16 05:30:07 INFO  : newLeaf: Moved (server side)
2020/08/16 05:30:07 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2020/08/16 05:30:07 DEBUG : dir/file1: Updating file with dir/file1 0xc00030c600
2020/08/16 05:30:07 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2020/08/16 05:30:07 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:07 DEBUG : : list: cold listing: 2020-08-15 23:30:07.975395644 +0000 UTC
2020/08/16 05:30:07 DEBUG : : list: read 1 from source
2020/08/16 05:30:07 DEBUG : : list: source entries: [dir]
2020/08/16 05:30:07 DEBUG : : list: cached directories: 0
2020/08/16 05:30:07 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:07.987120855 +0000 UTC m=+0.469176362
2020/08/16 05:30:07 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:07 DEBUG : dir: list: cold listing: 2020-08-15 23:30:07.975395644 +0000 UTC
2020/08/16 05:30:07 DEBUG : dir: list: read 1 from source
2020/08/16 05:30:07 DEBUG : dir: list: source entries: [dir/file1]
2020/08/16 05:30:08 DEBUG : dir: list: cached object: dir/file1
2020/08/16 05:30:08 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:08 DEBUG : dir: list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8/dir', cache ts: 2020-08-16 05:30:08.008341844 +0000 UTC m=+0.490397354
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: f401d3a6
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
    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 |-171217h25m1.201644156s| > 1ns (want 2001-02-03 04:05:06.499999999 +0000 UTC vs got 2020-08-16 05:30:07.701644155 +0000 UTC) (precision 1ns)
2020/08/16 05:30:08 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/08/16 05:30:08 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:08 DEBUG : dir/file1(0xc00020f180): openPending: 
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2020-08-16 05:30:07.701644155 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2020-08-16 05:30:07.701644155 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:08 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:08 DEBUG : dir/file1(0xc00020f180): >openPending: err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/08/16 05:30:08 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1(0xc00020f180): _writeAt: size=25, off=0
2020/08/16 05:30:08 DEBUG : dir/file1(0xc00020f180): >_writeAt: n=25, err=<nil>
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: new object 'newLeaf'
2020/08/16 05:30:08 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/08/16 05:30:08 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: moving obj 'dir/file1' -> newLeaf
2020/08/16 05:30:08 DEBUG : newLeaf: move: file moved
2020/08/16 05:30:08 DEBUG : dir/file1: move: removed from cache
2020/08/16 05:30:08 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8/dir
2020/08/16 05:30:08 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 INFO  : dir: move: cache expired
2020/08/16 05:30:08 DEBUG : newLeaf: move: added to cache
2020/08/16 05:30:08 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 INFO  : : move: cache expired
2020/08/16 05:30:08 INFO  : dir/file1: Moved (server side)
2020/08/16 05:30:08 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/08/16 05:30:08 DEBUG : newLeaf: Updating file with newLeaf 0xc00030c600
2020/08/16 05:30:08 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/08/16 05:30:08 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:08 DEBUG : newLeaf(0xc00020f180): close: 
2020/08/16 05:30:08 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2020/08/16 05:30:08 DEBUG : newLeaf: vfs cache: setting modification time to 2020-08-16 05:30:08.113407655 +0000 UTC m=+0.595463186
2020/08/16 05:30:08 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:08 DEBUG : newLeaf(0xc00020f180): >close: err=<nil>
2020/08/16 05:30:08 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:30:08 DEBUG : newLeaf: vfs cache: starting upload
2020/08/16 05:30:08 DEBUG : newLeaf: updating object contents with size 25
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: c7247bead226dfd7bd970c17229f4044
2020/08/16 05:30:08 DEBUG : newLeaf: MD5 = c7247bead226dfd7bd970c17229f4044 OK
2020/08/16 05:30:08 INFO  : newLeaf: Copied (replaced existing)
2020/08/16 05:30:08 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-08-16 05:30:08.113407655 +0000 UTC,c7247bead226dfd7bd970c17229f4044"
2020/08/16 05:30:08 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2020/08/16 05:30:08 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:08 INFO  : newLeaf: vfs cache: upload succeeded try #1
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:08 DEBUG : >WaitForWriters: 
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:08 DEBUG : : list: cold listing: 2020-08-15 23:30:08.146023675 +0000 UTC
2020/08/16 05:30:08 DEBUG : : list: read 2 from source
2020/08/16 05:30:08 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:08 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:08 DEBUG : : list: cached directories: 0
2020/08/16 05:30:08 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:08.32086067 +0000 UTC m=+0.802916179
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:08 DEBUG : dir: list: cold listing: 2020-08-15 23:30:08.124646842 +0000 UTC
2020/08/16 05:30:08 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:08 DEBUG : dir: list: source entries: []
2020/08/16 05:30:08 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:08 DEBUG : dir: list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8/dir', cache ts: 2020-08-16 05:30:08.335479115 +0000 UTC m=+0.817534629
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: c7247bead226dfd7bd970c17229f4044
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: f1f3d7db56f36d9a5a912b01803c2176a972b9b0
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: 1db58adace4d798a32319ad95a298d8714268fa67a177378850892c9caaf4a51a10b8ffc1a9ffb9c77defb66c37d22019d36a931fe50c5f5d9d612c7291105b0
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: e19d76ab
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: c28ee946ceebc5dd7464b525fdfc3a480f47b2b22832edbfc4741c21a9d4c664
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: 529d670c651f4f3f7011e4ab2d16332c1803bbe5
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: 954e6302251b5e744b33bcf26f301bca00023794
2020/08/16 05:30:08 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:08 DEBUG : >WaitForWriters: 
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:08 DEBUG : : list: warm 2 from cache for: rclone-test-cojavel6horopoq1kifexof8, expiring on: 2020-08-16 11:30:08.32086067 +0000 UTC
2020/08/16 05:30:08 DEBUG : : list: cached entries: [dir newLeaf]
2020/08/16 05:30:08 DEBUG : vfs cache: cleaner exiting
2020/08/16 05:30:08 DEBUG : newLeaf: removing object
2020/08/16 05:30:08 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:08 DEBUG : dir: list: empty listing
2020/08/16 05:30:08 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:08 DEBUG : dir: list: source entries: []
2020/08/16 05:30:08 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:08 DEBUG : dir: list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8/dir', cache ts: 2020-08-16 05:30:08.478431446 +0000 UTC m=+0.960486958
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: rmdir 'dir'
2020/08/16 05:30:08 DEBUG : dir: rmdir: removed dir in source fs
2020/08/16 05:30:08 DEBUG : dir: rmdir: removed from cache
2020/08/16 05:30:08 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 INFO  : : rmdir: cache expired
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:08 DEBUG : : list: cold listing: 2020-08-15 23:30:08.493427562 +0000 UTC
2020/08/16 05:30:08 DEBUG : : list: read 0 from source
2020/08/16 05:30:08 DEBUG : : list: source entries: []
2020/08/16 05:30:08 DEBUG : : list: cached directories: 0
2020/08/16 05:30:08 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:08.499453831 +0000 UTC m=+0.981509344
=== RUN   TestFileRename/writes,forceCache=true
    run.go:176: Remote "Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8", Local "Local file system at /tmp/rclone171872084", Modify Window "1ns"
2020/08/16 05:30:08 INFO  : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: poll-interval is not supported by this remote
2020/08/16 05:30:08 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-cojavel6horopoq1kifexof8"
2020/08/16 05:30:08 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-cojavel6horopoq1kifexof8"
2020/08/16 05:30:08 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: put data at 'dir/file1'
2020/08/16 05:30:08 DEBUG : dir/file1: put: uploaded to remote fs
2020/08/16 05:30:08 DEBUG : dir/file1: put: added to cache
2020/08/16 05:30:08 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 INFO  : dir: put: cache expired
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:08 DEBUG : : list: cold listing: 2020-08-15 23:30:08.518638055 +0000 UTC
2020/08/16 05:30:08 DEBUG : : list: read 1 from source
2020/08/16 05:30:08 DEBUG : : list: source entries: [dir]
2020/08/16 05:30:08 DEBUG : : list: cached directories: 1
2020/08/16 05:30:08 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:08.536934874 +0000 UTC m=+1.018990382
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:08 DEBUG : dir: list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8/dir, expiring on: 2020-08-16 11:30:08.527733635 +0000 UTC
2020/08/16 05:30:08 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: f401d3a6
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:08 DEBUG : : list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8, expiring on: 2020-08-16 11:30:08.536934874 +0000 UTC
2020/08/16 05:30:08 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:08 DEBUG : dir: list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8/dir, expiring on: 2020-08-16 11:30:08.527733635 +0000 UTC
2020/08/16 05:30:08 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:08 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2020/08/16 05:30:08 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428780): openPending: 
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint ""
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:08 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428780): >openPending: err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/08/16 05:30:08 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:08 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:08 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428780): _writeAt: size=14, off=0
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428780): >_writeAt: n=14, err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428780): close: 
2020/08/16 05:30:08 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 05:30:08.612944165 +0000 UTC m=+1.094999701
2020/08/16 05:30:08 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428780): >close: err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/08/16 05:30:08 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:08 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428800): _readAt: size=512, off=0
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428800): openPending: 
2020/08/16 05:30:08 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/08/16 05:30:08 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:08 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428800): >openPending: err=<nil>
2020/08/16 05:30:08 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428800): >_readAt: n=14, err=EOF
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428800): close: 
2020/08/16 05:30:08 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 05:30:08.612944165 +0000 UTC m=+1.094999701
2020/08/16 05:30:08 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000428800): >close: err=<nil>
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:08 DEBUG : : list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8, expiring on: 2020-08-16 11:30:08.536934874 +0000 UTC
2020/08/16 05:30:08 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:08 DEBUG : dir: list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8/dir, expiring on: 2020-08-16 11:30:08.527733635 +0000 UTC
2020/08/16 05:30:08 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: new object 'newLeaf'
2020/08/16 05:30:08 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/08/16 05:30:08 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: moving obj 'dir/file1' -> newLeaf
2020/08/16 05:30:08 DEBUG : newLeaf: move: file moved
2020/08/16 05:30:08 DEBUG : dir/file1: move: removed from cache
2020/08/16 05:30:08 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8/dir
2020/08/16 05:30:08 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 INFO  : dir: move: cache expired
2020/08/16 05:30:08 DEBUG : newLeaf: move: added to cache
2020/08/16 05:30:08 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 INFO  : : move: cache expired
2020/08/16 05:30:08 INFO  : dir/file1: Moved (server side)
2020/08/16 05:30:08 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/08/16 05:30:08 DEBUG : newLeaf: Updating file with newLeaf 0xc000378240
2020/08/16 05:30:08 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/08/16 05:30:08 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:08 DEBUG : : list: cold listing: 2020-08-15 23:30:08.647005096 +0000 UTC
2020/08/16 05:30:08 DEBUG : : list: read 2 from source
2020/08/16 05:30:08 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:08 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:08 DEBUG : : list: cached directories: 0
2020/08/16 05:30:08 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:08.663037006 +0000 UTC m=+1.145092516
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:08 DEBUG : dir: list: cold listing: 2020-08-15 23:30:08.631714748 +0000 UTC
2020/08/16 05:30:08 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:08 DEBUG : dir: list: source entries: []
2020/08/16 05:30:08 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:08 DEBUG : dir: list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8/dir', cache ts: 2020-08-16 05:30:08.670672103 +0000 UTC m=+1.152727610
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: f401d3a6
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: new object 'dir/file1'
2020/08/16 05:30:08 DEBUG : dir/file1: find: error: couldn't find object (file1)
2020/08/16 05:30:08 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: moving obj 'newLeaf' -> dir/file1
2020/08/16 05:30:08 DEBUG : dir/file1: move: file moved
2020/08/16 05:30:08 DEBUG : newLeaf: move: removed from cache
2020/08/16 05:30:08 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 INFO  : : move: cache expired
2020/08/16 05:30:08 DEBUG : newLeaf: vfs cache: starting upload
2020/08/16 05:30:08 DEBUG : newLeaf: updating object contents with size 14
2020/08/16 05:30:08 DEBUG : dir/file1: move: added to cache
2020/08/16 05:30:08 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8/dir
2020/08/16 05:30:08 DEBUG : dir: cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 INFO  : dir: move: cache expired
2020/08/16 05:30:08 INFO  : newLeaf: Moved (server side)
2020/08/16 05:30:08 DEBUG : newLeaf: vfs cache: cancelling upload
2020/08/16 05:30:08 ERROR : newLeaf: Failed to calculate src hash: hash: failed to open: open /home/rclone/.cache/rclone/vfs/TestCache/rclone-test-cojavel6horopoq1kifexof8/newLeaf: no such file or directory
2020/08/16 05:30:08 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:08 ERROR : newLeaf: corrupted on transfer: MD5 hash differ "" vs "0ef726ce9b1a7692357ff70dd321d595"
2020/08/16 05:30:08 INFO  : newLeaf: Removing failed copy
2020/08/16 05:30:08 DEBUG : newLeaf: removing object
2020/08/16 05:30:08 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:08 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 "" vs "0ef726ce9b1a7692357ff70dd321d595"
2020/08/16 05:30:08 DEBUG : newLeaf: vfs cache: cancelled upload
2020/08/16 05:30:08 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2020/08/16 05:30:08 DEBUG : dir/file1: Updating file with dir/file1 0xc000378240
2020/08/16 05:30:08 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2020/08/16 05:30:08 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:08 DEBUG : : list: cold listing: 2020-08-15 23:30:08.795080076 +0000 UTC
2020/08/16 05:30:08 DEBUG : : list: read 1 from source
2020/08/16 05:30:08 DEBUG : : list: source entries: [dir]
2020/08/16 05:30:08 DEBUG : : list: cached directories: 0
2020/08/16 05:30:08 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:08.802395806 +0000 UTC m=+1.284451316
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:08 DEBUG : dir: list: cold listing: 2020-08-15 23:30:08.759719181 +0000 UTC
2020/08/16 05:30:08 DEBUG : dir: list: read 1 from source
2020/08/16 05:30:08 DEBUG : dir: list: source entries: [dir/file1]
2020/08/16 05:30:08 DEBUG : dir: list: cached object: dir/file1
2020/08/16 05:30:08 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:08 DEBUG : dir: list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8/dir', cache ts: 2020-08-16 05:30:08.817987284 +0000 UTC m=+1.300042791
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: f401d3a6
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:08 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/08/16 05:30:08 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000091bc0): openPending: 
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: starting upload
2020/08/16 05:30:08 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:08 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/08/16 05:30:08 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:08 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000091bc0): >openPending: err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc000138930 item 1
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: cancelling upload
2020/08/16 05:30:08 DEBUG : dir/file1: updating object contents with size 0
2020/08/16 05:30:08 NOTICE: dir/file1: Removing partially written file on error: context canceled
2020/08/16 05:30:08 ERROR : dir/file1: error updating source: context canceled
2020/08/16 05:30:08 ERROR : dir/file1: Failed to copy: context canceled
2020/08/16 05:30:08 INFO  : dir/file1: vfs cache: upload canceled
2020/08/16 05:30:08 DEBUG : dir/file1: vfs cache: cancelled upload
2020/08/16 05:30:08 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000091bc0): _writeAt: size=25, off=0
2020/08/16 05:30:08 DEBUG : dir/file1(0xc000091bc0): >_writeAt: n=25, err=<nil>
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: new object 'newLeaf'
2020/08/16 05:30:08 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/08/16 05:30:08 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:08 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: moving obj 'dir/file1' -> newLeaf
2020/08/16 05:30:08 ERROR : dir/file1: error moving: rename /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/dir/file1 /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/newLeaf: no such file or directory
2020/08/16 05:30:08 ERROR : dir/file1: Couldn't move: rename /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/dir/file1 /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/newLeaf: no such file or directory
2020/08/16 05:30:08 ERROR : newLeaf: File.Rename error: rename /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/dir/file1 /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/newLeaf: no such file or directory
2020/08/16 05:30:08 ERROR : dir/file1: Dir.Rename error: rename /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/dir/file1 /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/newLeaf: no such file or directory
    file_test.go:322: 
        	Error Trace:	file_test.go:322
        	            				file_test.go:357
        	Error:      	Received unexpected error:
        	            	rename /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/dir/file1 /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8/newLeaf: no such file or directory
        	Test:       	TestFileRename/writes,forceCache=true
2020/08/16 05:30:08 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : file1: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : Still 1 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : file1: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : Still 1 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : file1: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : Still 1 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:30:08 DEBUG : dir: Looking for writers
2020/08/16 05:30:08 DEBUG : file1: reading active writers
2020/08/16 05:30:08 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:08 DEBUG : : Looking for writers
2020/08/16 05:30:08 DEBUG : dir: reading active writers
2020/08/16 05:30:08 DEBUG : Still 1 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:30:09 DEBUG : dir: Looking for writers
2020/08/16 05:30:09 DEBUG : file1: reading active writers
2020/08/16 05:30:09 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:09 DEBUG : : Looking for writers
2020/08/16 05:30:09 DEBUG : dir: reading active writers
2020/08/16 05:30:09 DEBUG : Still 1 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:30:09 DEBUG : dir: Looking for writers
2020/08/16 05:30:09 DEBUG : file1: reading active writers
2020/08/16 05:30:09 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:09 DEBUG : : Looking for writers
2020/08/16 05:30:09 DEBUG : dir: reading active writers
2020/08/16 05:30:09 DEBUG : Still 1 writers active and 1 cache items in use, waiting 320ms
2020/08/16 05:30:09 DEBUG : dir: Looking for writers
2020/08/16 05:30:09 DEBUG : file1: reading active writers
2020/08/16 05:30:09 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:09 DEBUG : : Looking for writers
2020/08/16 05:30:09 DEBUG : dir: reading active writers
2020/08/16 05:30:09 DEBUG : Still 1 writers active and 1 cache items in use, waiting 640ms
2020/08/16 05:30:10 DEBUG : dir: Looking for writers
2020/08/16 05:30:10 DEBUG : file1: reading active writers
2020/08/16 05:30:10 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:10 DEBUG : : Looking for writers
2020/08/16 05:30:10 DEBUG : dir: reading active writers
2020/08/16 05:30:10 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:11 DEBUG : dir: Looking for writers
2020/08/16 05:30:11 DEBUG : file1: reading active writers
2020/08/16 05:30:11 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:11 DEBUG : : Looking for writers
2020/08/16 05:30:11 DEBUG : dir: reading active writers
2020/08/16 05:30:11 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:12 DEBUG : dir: Looking for writers
2020/08/16 05:30:12 DEBUG : file1: reading active writers
2020/08/16 05:30:12 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:12 DEBUG : : Looking for writers
2020/08/16 05:30:12 DEBUG : dir: reading active writers
2020/08/16 05:30:12 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:13 DEBUG : dir: Looking for writers
2020/08/16 05:30:13 DEBUG : file1: reading active writers
2020/08/16 05:30:13 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:13 DEBUG : : Looking for writers
2020/08/16 05:30:13 DEBUG : dir: reading active writers
2020/08/16 05:30:13 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:14 DEBUG : dir: Looking for writers
2020/08/16 05:30:14 DEBUG : file1: reading active writers
2020/08/16 05:30:14 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:14 DEBUG : : Looking for writers
2020/08/16 05:30:14 DEBUG : dir: reading active writers
2020/08/16 05:30:14 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:15 DEBUG : dir: Looking for writers
2020/08/16 05:30:15 DEBUG : file1: reading active writers
2020/08/16 05:30:15 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:15 DEBUG : : Looking for writers
2020/08/16 05:30:15 DEBUG : dir: reading active writers
2020/08/16 05:30:15 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:16 DEBUG : dir: Looking for writers
2020/08/16 05:30:16 DEBUG : file1: reading active writers
2020/08/16 05:30:16 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:16 DEBUG : : Looking for writers
2020/08/16 05:30:16 DEBUG : dir: reading active writers
2020/08/16 05:30:16 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:17 DEBUG : dir: Looking for writers
2020/08/16 05:30:17 DEBUG : file1: reading active writers
2020/08/16 05:30:17 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:17 DEBUG : : Looking for writers
2020/08/16 05:30:17 DEBUG : dir: reading active writers
2020/08/16 05:30:17 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:18 DEBUG : dir: Looking for writers
2020/08/16 05:30:18 DEBUG : file1: reading active writers
2020/08/16 05:30:18 DEBUG : newLeaf: active writers 1
2020/08/16 05:30:18 DEBUG : : Looking for writers
2020/08/16 05:30:18 DEBUG : dir: reading active writers
2020/08/16 05:30:18 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s
2020/08/16 05:30:18 ERROR : Exiting even though 1 writers active and 1 cache items in use after 10s
Cache{
	"dir/file1": &{c:0xc0001bbe60 mu:{state:0 sema:0} name:dir/file1 opens:1 downloaders:0xc000030840 o:0xc000658280 fd:0xc000010220 metaDirty:true modified:true info:{ModTime:{wall:13818819334595387725 ext:1385641634 loc:0x25a1860} ATime:{wall:13818819334595387725 ext:1385641634 loc:0x25a1860} Size:25 Rs:[{Pos:0 Size:25}] Fingerprint:14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595 Dirty:true} writeBackID:1},
}
2020/08/16 05:30:18 DEBUG : >WaitForWriters: 
2020/08/16 05:30:18 DEBUG : vfs cache: cleaner exiting
2020/08/16 05:30:18 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:18 DEBUG : : list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8, expiring on: 2020-08-16 11:30:08.802395806 +0000 UTC
2020/08/16 05:30:18 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:18 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list 'dir'
2020/08/16 05:30:18 DEBUG : dir: list: warm 1 from cache for: rclone-test-cojavel6horopoq1kifexof8/dir, expiring on: 2020-08-16 11:30:08.817987284 +0000 UTC
2020/08/16 05:30:18 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:18 ERROR : dir/file1: error refreshing object in : in cache fs Local file system at /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8: object not found
    run.go:121: removing file "dir/file1" failed - try 1/3: in cache fs Local file system at /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8: object not found
2020/08/16 05:30:19 ERROR : dir/file1: error refreshing object in : in cache fs Local file system at /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8: object not found
    run.go:121: removing file "dir/file1" failed - try 2/3: in cache fs Local file system at /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8: object not found
2020/08/16 05:30:20 ERROR : dir/file1: error refreshing object in : in cache fs Local file system at /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8: object not found
    run.go:121: removing file "dir/file1" failed - try 3/3: in cache fs Local file system at /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8: object not found
    run.go:124: removing file "dir/file1" failed: in cache fs Local file system at /tmp/rclone_cache_test/rclone-test-cojavel6horopoq1kifexof8: object not found
2020/08/16 05:30:21 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: rmdir 'dir'
2020/08/16 05:30:21 DEBUG : dir: rmdir: removed dir in source fs
2020/08/16 05:30:21 DEBUG : dir: rmdir: removed from cache
2020/08/16 05:30:21 DEBUG : : cache: expired rclone-test-cojavel6horopoq1kifexof8
2020/08/16 05:30:21 INFO  : : rmdir: cache expired
2020/08/16 05:30:21 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: list ''
2020/08/16 05:30:21 DEBUG : : list: cold listing: 2020-08-15 23:30:21.916890768 +0000 UTC
2020/08/16 05:30:21 DEBUG : : list: read 0 from source
2020/08/16 05:30:21 DEBUG : : list: source entries: []
2020/08/16 05:30:21 DEBUG : : list: cached directories: 0
2020/08/16 05:30:21 DEBUG : : list: cached dir: 'rclone-test-cojavel6horopoq1kifexof8', cache ts: 2020-08-16 05:30:21.930604816 +0000 UTC m=+14.412660323
--- FAIL: TestFileRename (14.39s)
    --- FAIL: TestFileRename/minimal,forceCache=true (0.96s)
    --- FAIL: TestFileRename/writes,forceCache=true (13.43s)
FAIL
2020/08/16 05:30:21 DEBUG : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: Purge remote
2020/08/16 05:30:21 INFO  : Cache remote TestCache:rclone-test-cojavel6horopoq1kifexof8: purging cache
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestCache: -verbose -test.run '^TestFileRename$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Finished ERROR in 14.43586966s (try 3/5): exit status 1: Failed [TestFileRename/minimal,forceCache=true TestFileRename/writes,forceCache=true]