"./vfs.test -test.v -test.timeout 1h0m0s -remote TestCache: -verbose -test.run '^TestFileRename$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Starting (try 5/5)
2020/08/16 05:30:39 DEBUG : TestCache: wrapped local:/tmp/rclone_cache_test/rclone-test-jesoker1xojekix1tihibor2 at root rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:39 INFO  : TestCache: Cache DB path: /home/rclone/.cache/rclone/cache-backend/TestCache.db
2020/08/16 05:30:39 INFO  : TestCache: Cache chunk path: /home/rclone/.cache/rclone/cache-backend/TestCache
2020/08/16 05:30:39 INFO  : TestCache: Chunk Memory: true
2020/08/16 05:30:39 INFO  : TestCache: Chunk Size: 5M
2020/08/16 05:30:39 INFO  : TestCache: Chunk Total Size: 10G
2020/08/16 05:30:39 INFO  : TestCache: Chunk Clean Interval: 1m0s
2020/08/16 05:30:39 INFO  : TestCache: Workers: 4
2020/08/16 05:30:39 INFO  : TestCache: File Age: 6h0m0s
2020/08/16 05:30:39 DEBUG : Adding path "cache/expire" to remote control registry
2020/08/16 05:30:39 DEBUG : Adding path "cache/stats" to remote control registry
2020/08/16 05:30:39 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-jesoker1xojekix1tihibor2", Local "Local file system at /tmp/rclone679379229", Modify Window "1ns"
2020/08/16 05:30:39 INFO  : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: poll-interval is not supported by this remote
2020/08/16 05:30:39 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-jesoker1xojekix1tihibor2"
2020/08/16 05:30:39 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-jesoker1xojekix1tihibor2"
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: mkdir ''
2020/08/16 05:30:39 DEBUG : : mkdir: created dir in source fs
2020/08/16 05:30:39 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:39 DEBUG : : mkdir: added to cache
2020/08/16 05:30:39 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:39 INFO  : : mkdir: cache expired
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: put data at 'dir/file1'
2020/08/16 05:30:39 DEBUG : dir/file1: put: uploaded to remote fs
2020/08/16 05:30:39 DEBUG : dir/file1: put: added to cache
2020/08/16 05:30:39 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:39 INFO  : dir: put: cache expired
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:39 DEBUG : : list: cold listing: 2020-08-15 23:30:39.469234221 +0000 UTC
2020/08/16 05:30:39 DEBUG : : list: read 1 from source
2020/08/16 05:30:39 DEBUG : : list: source entries: [dir]
2020/08/16 05:30:39 DEBUG : : list: cached directories: 1
2020/08/16 05:30:39 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:39.487646602 +0000 UTC m=+0.078664669
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:39 DEBUG : dir: list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2/dir, expiring on: 2020-08-16 11:30:39.478542009 +0000 UTC
2020/08/16 05:30:39 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:39 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:39 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:39 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:39 DEBUG : dir/file1: object hash cached: f401d3a6
2020/08/16 05:30:39 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:39 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:39 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:39 DEBUG : : list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2, expiring on: 2020-08-16 11:30:39.487646602 +0000 UTC
2020/08/16 05:30:39 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:39 DEBUG : dir: list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2/dir, expiring on: 2020-08-16 11:30:39.478542009 +0000 UTC
2020/08/16 05:30:39 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:39 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2020/08/16 05:30:39 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000230a80): openPending: 
2020/08/16 05:30:39 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:39 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:39 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000230a80): >openPending: err=<nil>
2020/08/16 05:30:39 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/08/16 05:30:39 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:39 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:39 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000230a80): _writeAt: size=14, off=0
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000230a80): >_writeAt: n=14, err=<nil>
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000230a80): close: 
2020/08/16 05:30:39 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:39 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 05:30:39.760881321 +0000 UTC m=+0.351899380
2020/08/16 05:30:39 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000230a80): >close: err=<nil>
2020/08/16 05:30:39 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/08/16 05:30:39 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:39 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:39 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000231b40): _readAt: size=512, off=0
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000231b40): openPending: 
2020/08/16 05:30:39 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:39 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:39 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000231b40): >openPending: err=<nil>
2020/08/16 05:30:39 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000231b40): >_readAt: n=14, err=EOF
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000231b40): close: 
2020/08/16 05:30:39 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:39 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 05:30:39.760881321 +0000 UTC m=+0.351899380
2020/08/16 05:30:39 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:39 DEBUG : dir/file1(0xc000231b40): >close: err=<nil>
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:39 DEBUG : : list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2, expiring on: 2020-08-16 11:30:39.487646602 +0000 UTC
2020/08/16 05:30:39 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:39 DEBUG : dir: list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2/dir, expiring on: 2020-08-16 11:30:39.478542009 +0000 UTC
2020/08/16 05:30:39 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: new object 'newLeaf'
2020/08/16 05:30:39 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/08/16 05:30:39 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: moving obj 'dir/file1' -> newLeaf
2020/08/16 05:30:39 DEBUG : newLeaf: move: file moved
2020/08/16 05:30:39 DEBUG : dir/file1: move: removed from cache
2020/08/16 05:30:39 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2/dir
2020/08/16 05:30:39 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:39 INFO  : dir: move: cache expired
2020/08/16 05:30:39 DEBUG : newLeaf: move: added to cache
2020/08/16 05:30:39 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:39 INFO  : : move: cache expired
2020/08/16 05:30:39 INFO  : dir/file1: Moved (server side)
2020/08/16 05:30:39 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/08/16 05:30:39 DEBUG : newLeaf: Updating file with newLeaf 0xc0002d8180
2020/08/16 05:30:39 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/08/16 05:30:39 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:39 DEBUG : : list: cold listing: 2020-08-15 23:30:39.795716691 +0000 UTC
2020/08/16 05:30:39 DEBUG : : list: read 2 from source
2020/08/16 05:30:39 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:39 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:39 DEBUG : : list: cached directories: 0
2020/08/16 05:30:39 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:39.813900504 +0000 UTC m=+0.404918562
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:39 DEBUG : dir: list: cold listing: 2020-08-15 23:30:39.77948721 +0000 UTC
2020/08/16 05:30:39 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:39 DEBUG : dir: list: source entries: []
2020/08/16 05:30:39 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:39 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:39.82166773 +0000 UTC m=+0.412685790
2020/08/16 05:30:39 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:39 DEBUG : newLeaf: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:39 DEBUG : newLeaf: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:39 DEBUG : newLeaf: object hash cached: f401d3a6
2020/08/16 05:30:39 DEBUG : newLeaf: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:39 DEBUG : newLeaf: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:39 DEBUG : newLeaf: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: new object 'dir/file1'
2020/08/16 05:30:39 DEBUG : dir/file1: find: error: couldn't find object (file1)
2020/08/16 05:30:39 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: moving obj 'newLeaf' -> dir/file1
2020/08/16 05:30:39 DEBUG : dir/file1: move: file moved
2020/08/16 05:30:39 DEBUG : newLeaf: vfs cache: starting upload
2020/08/16 05:30:39 DEBUG : newLeaf: updating object contents with size 14
2020/08/16 05:30:39 DEBUG : newLeaf: move: removed from cache
2020/08/16 05:30:39 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:39 INFO  : : move: cache expired
2020/08/16 05:30:39 DEBUG : dir/file1: move: added to cache
2020/08/16 05:30:39 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:39 DEBUG : newLeaf: MD5 = 0ef726ce9b1a7692357ff70dd321d595 OK
2020/08/16 05:30:39 INFO  : newLeaf: Copied (replaced existing)
2020/08/16 05:30:39 DEBUG : newLeaf: vfs cache: fingerprint now "14,2020-08-16 05:30:39.760881321 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2020/08/16 05:30:39 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2020/08/16 05:30:39 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:39 INFO  : newLeaf: vfs cache: upload succeeded try #1
2020/08/16 05:30:39 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2/dir
2020/08/16 05:30:39 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:39 INFO  : dir: move: cache expired
2020/08/16 05:30:39 INFO  : newLeaf: Moved (server side)
2020/08/16 05:30:39 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2020/08/16 05:30:39 DEBUG : dir/file1: Updating file with dir/file1 0xc0002d8180
2020/08/16 05:30:39 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2020/08/16 05:30:39 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:39 DEBUG : : list: cold listing: 2020-08-15 23:30:39.943941634 +0000 UTC
2020/08/16 05:30:39 DEBUG : : list: read 2 from source
2020/08/16 05:30:39 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:39 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:39 DEBUG : : list: cached directories: 0
2020/08/16 05:30:39 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:39.968893095 +0000 UTC m=+0.559911153
2020/08/16 05:30:39 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:39 DEBUG : dir: list: cold listing: 2020-08-15 23:30:39.943941634 +0000 UTC
2020/08/16 05:30:39 DEBUG : dir: list: read 1 from source
2020/08/16 05:30:39 DEBUG : dir: list: source entries: [dir/file1]
2020/08/16 05:30:39 DEBUG : dir: list: cached object: dir/file1
2020/08/16 05:30:39 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:39 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:39.984352621 +0000 UTC m=+0.575370679
    fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:298: Flushing the directory cache
2020/08/16 05:30:40 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:40 DEBUG : : list: error: couldn't open bucket (rclone-test-jesoker1xojekix1tihibor2)
2020/08/16 05:30:40 DEBUG : : list: read 2 from source
2020/08/16 05:30:40 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:41 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:41 DEBUG : : list: cached directories: 1
2020/08/16 05:30:41 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:41.175718996 +0000 UTC m=+1.766737054
2020/08/16 05:30:41 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:41 DEBUG : dir: list: empty listing
2020/08/16 05:30:41 DEBUG : dir: list: read 1 from source
2020/08/16 05:30:41 DEBUG : dir: list: source entries: [dir/file1]
2020/08/16 05:30:41 DEBUG : dir: list: cached object: dir/file1
2020/08/16 05:30:41 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:41 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:41.192298655 +0000 UTC m=+1.783316713
    fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:298: Flushing the directory cache
2020/08/16 05:30:43 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:43 DEBUG : : list: error: couldn't open bucket (rclone-test-jesoker1xojekix1tihibor2)
2020/08/16 05:30:43 DEBUG : : list: read 2 from source
2020/08/16 05:30:43 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:43 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:43 DEBUG : : list: cached directories: 1
2020/08/16 05:30:43 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:43.226622413 +0000 UTC m=+3.817640479
2020/08/16 05:30:43 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:43 DEBUG : dir: list: empty listing
2020/08/16 05:30:43 DEBUG : dir: list: read 1 from source
2020/08/16 05:30:43 DEBUG : dir: list: source entries: [dir/file1]
2020/08/16 05:30:43 DEBUG : dir: list: cached object: dir/file1
2020/08/16 05:30:43 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:43 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:43.244189398 +0000 UTC m=+3.835207456
    fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:298: Flushing the directory cache
    fstest.go:302: 
        	Error Trace:	fstest.go:302
        	            				fstest.go:335
        	            				fstest.go:347
        	            				file_test.go:305
        	            				file_test.go:357
        	Error:      	Should be true
        	Test:       	TestFileRename/minimal,forceCache=true
        	Messages:   	listing wrong, want
        	            	  dir/file1 (14) got
        	            	  dir/file1 (14), newLeaf (14)
    fstest.go:188: 
        	Error Trace:	fstest.go:188
        	            				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:   	Unexpected file "newLeaf"
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: f401d3a6
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:47 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/08/16 05:30:47 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:47 DEBUG : dir/file1(0xc0000915c0): openPending: 
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:47 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" against cached fingerprint "14,2020-08-16 05:30:39.760881321 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595"
2020/08/16 05:30:47 DEBUG : dir/file1: vfs cache: removing cached entry as stale (remote fingerprint "14,2001-02-03 04:05:06.499999999 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595" != cached fingerprint "14,2020-08-16 05:30:39.760881321 +0000 UTC,0ef726ce9b1a7692357ff70dd321d595")
2020/08/16 05:30:47 INFO  : dir/file1: vfs cache: removed cache file as stale (remote is different)
2020/08/16 05:30:47 DEBUG : dir/file1: vfs cache: removed metadata from cache as stale (remote is different)
2020/08/16 05:30:47 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:47 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:47 DEBUG : dir/file1(0xc0000915c0): >openPending: err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/08/16 05:30:47 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1(0xc0000915c0): _writeAt: size=25, off=0
2020/08/16 05:30:47 DEBUG : dir/file1(0xc0000915c0): >_writeAt: n=25, err=<nil>
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: new object 'newLeaf'
2020/08/16 05:30:47 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/08/16 05:30:47 DEBUG : newLeaf: find: cached object
2020/08/16 05:30:47 DEBUG : newLeaf: removing object
2020/08/16 05:30:47 INFO  : newLeaf: Deleted
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: moving obj 'dir/file1' -> newLeaf
2020/08/16 05:30:47 DEBUG : newLeaf: move: file moved
2020/08/16 05:30:47 DEBUG : dir/file1: move: removed from cache
2020/08/16 05:30:47 INFO  : dir: move: cache expired
2020/08/16 05:30:47 DEBUG : newLeaf: move: added to cache
2020/08/16 05:30:47 INFO  : : move: cache expired
2020/08/16 05:30:47 INFO  : dir/file1: Moved (server side)
2020/08/16 05:30:47 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/08/16 05:30:47 DEBUG : newLeaf: Updating file with newLeaf 0xc0002d8180
2020/08/16 05:30:47 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/08/16 05:30:47 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:47 DEBUG : newLeaf(0xc0000915c0): close: 
2020/08/16 05:30:47 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2020/08/16 05:30:47 DEBUG : newLeaf: vfs cache: setting modification time to 2020-08-16 05:30:47.331579712 +0000 UTC m=+7.922597796
2020/08/16 05:30:47 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:47 DEBUG : newLeaf(0xc0000915c0): >close: err=<nil>
2020/08/16 05:30:47 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:30:47 DEBUG : dir: Looking for writers
2020/08/16 05:30:47 DEBUG : : Looking for writers
2020/08/16 05:30:47 DEBUG : dir: reading active writers
2020/08/16 05:30:47 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:30:47 DEBUG : dir: Looking for writers
2020/08/16 05:30:47 DEBUG : : Looking for writers
2020/08/16 05:30:47 DEBUG : dir: reading active writers
2020/08/16 05:30:47 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:30:47 DEBUG : dir: Looking for writers
2020/08/16 05:30:47 DEBUG : : Looking for writers
2020/08/16 05:30:47 DEBUG : dir: reading active writers
2020/08/16 05:30:47 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:30:47 DEBUG : dir: Looking for writers
2020/08/16 05:30:47 DEBUG : : Looking for writers
2020/08/16 05:30:47 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:47 DEBUG : dir: reading active writers
2020/08/16 05:30:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:30:47 DEBUG : newLeaf: vfs cache: starting upload
2020/08/16 05:30:47 DEBUG : newLeaf: updating object contents with size 25
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: c7247bead226dfd7bd970c17229f4044
2020/08/16 05:30:47 DEBUG : newLeaf: MD5 = c7247bead226dfd7bd970c17229f4044 OK
2020/08/16 05:30:47 INFO  : newLeaf: Copied (replaced existing)
2020/08/16 05:30:47 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-08-16 05:30:47.331579712 +0000 UTC,c7247bead226dfd7bd970c17229f4044"
2020/08/16 05:30:47 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2020/08/16 05:30:47 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:47 INFO  : newLeaf: vfs cache: upload succeeded try #1
2020/08/16 05:30:47 DEBUG : dir: Looking for writers
2020/08/16 05:30:47 DEBUG : : Looking for writers
2020/08/16 05:30:47 DEBUG : dir: reading active writers
2020/08/16 05:30:47 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:47 DEBUG : >WaitForWriters: 
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:47 DEBUG : : list: error: missing cached dir: 
2020/08/16 05:30:47 DEBUG : : list: read 2 from source
2020/08/16 05:30:47 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:47 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:47 DEBUG : : list: cached directories: 1
2020/08/16 05:30:47 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:47.5567478 +0000 UTC m=+8.147765858
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:47 DEBUG : dir: list: empty listing
2020/08/16 05:30:47 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:47 DEBUG : dir: list: source entries: []
2020/08/16 05:30:47 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:47 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:47.565871162 +0000 UTC m=+8.156889221
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: c7247bead226dfd7bd970c17229f4044
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: f1f3d7db56f36d9a5a912b01803c2176a972b9b0
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: 1db58adace4d798a32319ad95a298d8714268fa67a177378850892c9caaf4a51a10b8ffc1a9ffb9c77defb66c37d22019d36a931fe50c5f5d9d612c7291105b0
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: e19d76ab
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: c28ee946ceebc5dd7464b525fdfc3a480f47b2b22832edbfc4741c21a9d4c664
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: 529d670c651f4f3f7011e4ab2d16332c1803bbe5
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: 954e6302251b5e744b33bcf26f301bca00023794
2020/08/16 05:30:47 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:30:47 DEBUG : dir: Looking for writers
2020/08/16 05:30:47 DEBUG : : Looking for writers
2020/08/16 05:30:47 DEBUG : dir: reading active writers
2020/08/16 05:30:47 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:47 DEBUG : >WaitForWriters: 
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:47 DEBUG : vfs cache: cleaner exiting
2020/08/16 05:30:47 DEBUG : : list: warm 2 from cache for: rclone-test-jesoker1xojekix1tihibor2, expiring on: 2020-08-16 11:30:47.5567478 +0000 UTC
2020/08/16 05:30:47 DEBUG : : list: cached entries: [dir newLeaf]
2020/08/16 05:30:47 DEBUG : newLeaf: removing object
2020/08/16 05:30:47 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:47 DEBUG : dir: list: empty listing
2020/08/16 05:30:47 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:47 DEBUG : dir: list: source entries: []
2020/08/16 05:30:47 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:47 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:47.677790851 +0000 UTC m=+8.268809010
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: rmdir 'dir'
2020/08/16 05:30:47 DEBUG : dir: rmdir: removed dir in source fs
2020/08/16 05:30:47 DEBUG : dir: rmdir: removed from cache
2020/08/16 05:30:47 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:47 INFO  : : rmdir: cache expired
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:47 DEBUG : : list: cold listing: 2020-08-15 23:30:47.691751175 +0000 UTC
2020/08/16 05:30:47 DEBUG : : list: read 0 from source
2020/08/16 05:30:47 DEBUG : : list: source entries: []
2020/08/16 05:30:47 DEBUG : : list: cached directories: 0
2020/08/16 05:30:47 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:47.698297336 +0000 UTC m=+8.289315457
=== RUN   TestFileRename/writes,forceCache=true
    run.go:176: Remote "Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2", Local "Local file system at /tmp/rclone679379229", Modify Window "1ns"
2020/08/16 05:30:47 INFO  : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: poll-interval is not supported by this remote
2020/08/16 05:30:47 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-jesoker1xojekix1tihibor2"
2020/08/16 05:30:47 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestCache/rclone-test-jesoker1xojekix1tihibor2"
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: put data at 'dir/file1'
2020/08/16 05:30:47 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:47 DEBUG : dir/file1: put: uploaded to remote fs
2020/08/16 05:30:47 DEBUG : dir/file1: put: added to cache
2020/08/16 05:30:47 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:47 INFO  : dir: put: cache expired
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:47 DEBUG : : list: cold listing: 2020-08-15 23:30:47.716725894 +0000 UTC
2020/08/16 05:30:47 DEBUG : : list: read 1 from source
2020/08/16 05:30:47 DEBUG : : list: source entries: [dir]
2020/08/16 05:30:47 DEBUG : : list: cached directories: 1
2020/08/16 05:30:47 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:47.733294967 +0000 UTC m=+8.324313034
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:47 DEBUG : dir: list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2/dir, expiring on: 2020-08-16 11:30:47.725263328 +0000 UTC
2020/08/16 05:30:47 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: f401d3a6
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:47 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:47 DEBUG : : list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2, expiring on: 2020-08-16 11:30:47.733294967 +0000 UTC
2020/08/16 05:30:47 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:47 DEBUG : dir: list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2/dir, expiring on: 2020-08-16 11:30:47.725263328 +0000 UTC
2020/08/16 05:30:47 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:47 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2020/08/16 05:30:47 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b640): openPending: 
2020/08/16 05:30:47 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:47 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:47 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b640): >openPending: err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/08/16 05:30:47 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:47 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:47 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b640): _writeAt: size=14, off=0
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b640): >_writeAt: n=14, err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b640): close: 
2020/08/16 05:30:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:47 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 05:30:47.818319874 +0000 UTC m=+8.409337925
2020/08/16 05:30:47 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b640): >close: err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1: Open: flags=O_RDONLY
2020/08/16 05:30:47 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:47 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b6c0): _readAt: size=512, off=0
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b6c0): openPending: 
2020/08/16 05:30:47 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:47 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:47 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b6c0): >openPending: err=<nil>
2020/08/16 05:30:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b6c0): >_readAt: n=14, err=EOF
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b6c0): close: 
2020/08/16 05:30:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true
2020/08/16 05:30:47 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 05:30:47.818319874 +0000 UTC m=+8.409337925
2020/08/16 05:30:47 INFO  : dir/file1: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:47 DEBUG : dir/file1(0xc00041b6c0): >close: err=<nil>
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:47 DEBUG : : list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2, expiring on: 2020-08-16 11:30:47.733294967 +0000 UTC
2020/08/16 05:30:47 DEBUG : : list: cached entries: [dir]
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:47 DEBUG : dir: list: warm 1 from cache for: rclone-test-jesoker1xojekix1tihibor2/dir, expiring on: 2020-08-16 11:30:47.725263328 +0000 UTC
2020/08/16 05:30:47 DEBUG : dir: list: cached entries: [dir/file1]
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: new object 'newLeaf'
2020/08/16 05:30:47 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/08/16 05:30:47 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: moving obj 'dir/file1' -> newLeaf
2020/08/16 05:30:47 DEBUG : newLeaf: move: file moved
2020/08/16 05:30:47 DEBUG : dir/file1: move: removed from cache
2020/08/16 05:30:47 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2/dir
2020/08/16 05:30:47 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:47 INFO  : dir: move: cache expired
2020/08/16 05:30:47 DEBUG : newLeaf: move: added to cache
2020/08/16 05:30:47 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:47 INFO  : : move: cache expired
2020/08/16 05:30:47 INFO  : dir/file1: Moved (server side)
2020/08/16 05:30:47 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/08/16 05:30:47 DEBUG : newLeaf: Updating file with newLeaf 0xc000340540
2020/08/16 05:30:47 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/08/16 05:30:47 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:47 DEBUG : : list: cold listing: 2020-08-15 23:30:47.858027467 +0000 UTC
2020/08/16 05:30:47 DEBUG : : list: read 2 from source
2020/08/16 05:30:47 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:47 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:47 DEBUG : : list: cached directories: 0
2020/08/16 05:30:47 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:47.87580519 +0000 UTC m=+8.466823248
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:47 DEBUG : dir: list: cold listing: 2020-08-15 23:30:47.83770242 +0000 UTC
2020/08/16 05:30:47 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:47 DEBUG : dir: list: source entries: []
2020/08/16 05:30:47 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:47 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:47.883442992 +0000 UTC m=+8.474461050
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: f401d3a6
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: new object 'dir/file1'
2020/08/16 05:30:47 DEBUG : dir/file1: find: error: couldn't find object (file1)
2020/08/16 05:30:47 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:47 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: moving obj 'newLeaf' -> dir/file1
2020/08/16 05:30:47 DEBUG : dir/file1: move: file moved
2020/08/16 05:30:47 DEBUG : newLeaf: move: removed from cache
2020/08/16 05:30:47 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:47 INFO  : : move: cache expired
2020/08/16 05:30:47 DEBUG : dir/file1: move: added to cache
2020/08/16 05:30:47 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2/dir
2020/08/16 05:30:47 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:47 DEBUG : newLeaf: vfs cache: starting upload
2020/08/16 05:30:47 DEBUG : newLeaf: updating object contents with size 14
2020/08/16 05:30:47 INFO  : dir: move: cache expired
2020/08/16 05:30:47 INFO  : newLeaf: Moved (server side)
2020/08/16 05:30:47 DEBUG : newLeaf: vfs cache: cancelling upload
2020/08/16 05:30:47 ERROR : newLeaf: Failed to calculate src hash: hash: failed to open: open /home/rclone/.cache/rclone/vfs/TestCache/rclone-test-jesoker1xojekix1tihibor2/newLeaf: no such file or directory
2020/08/16 05:30:47 DEBUG : newLeaf: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:47 ERROR : newLeaf: corrupted on transfer: MD5 hash differ "" vs "0ef726ce9b1a7692357ff70dd321d595"
2020/08/16 05:30:47 INFO  : newLeaf: Removing failed copy
2020/08/16 05:30:47 DEBUG : newLeaf: removing object
2020/08/16 05:30:48 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:48 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:48 DEBUG : newLeaf: vfs cache: cancelled upload
2020/08/16 05:30:48 INFO  : newLeaf: vfs cache: renamed in cache to "dir/file1"
2020/08/16 05:30:48 DEBUG : dir/file1: Updating file with dir/file1 0xc000340540
2020/08/16 05:30:48 DEBUG : : Added virtual directory entry vDel: "newLeaf"
2020/08/16 05:30:48 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:48 DEBUG : : list: cold listing: 2020-08-15 23:30:48.006357176 +0000 UTC
2020/08/16 05:30:48 DEBUG : : list: read 1 from source
2020/08/16 05:30:48 DEBUG : : list: source entries: [dir]
2020/08/16 05:30:48 DEBUG : : list: cached directories: 0
2020/08/16 05:30:48 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:48.013923868 +0000 UTC m=+8.604941928
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:48 DEBUG : dir: list: cold listing: 2020-08-15 23:30:47.966168295 +0000 UTC
2020/08/16 05:30:48 DEBUG : dir: list: read 1 from source
2020/08/16 05:30:48 DEBUG : dir: list: source entries: [dir/file1]
2020/08/16 05:30:48 DEBUG : dir: list: cached object: dir/file1
2020/08/16 05:30:48 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:48 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:48.030772105 +0000 UTC m=+8.621790170
2020/08/16 05:30:48 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:48 DEBUG : dir/file1: object hash cached: a379624177abc4679cafafa8eae1d73e1478aaa6
2020/08/16 05:30:48 DEBUG : dir/file1: object hash cached: 91aee57ad1d095bdded6f312b2e49431989f288d32f6b9a0dd0066b0350ffcf6a42c98605a2a58a80f1ee0ce11820da6617a8538f9b057a3721b3a9783d22e1c
2020/08/16 05:30:48 DEBUG : dir/file1: object hash cached: f401d3a6
2020/08/16 05:30:48 DEBUG : dir/file1: object hash cached: d4b8d7e13c592e454a060a60b4606d5e5c5a03b023d97e24bf4682e9535a8778
2020/08/16 05:30:48 DEBUG : dir/file1: object hash cached: 66696c653120636f6e74656e7473000000000000
2020/08/16 05:30:48 DEBUG : dir/file1: object hash cached: 6648031bca1003108ce10d6eae4319dc40873900
2020/08/16 05:30:48 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC
2020/08/16 05:30:48 DEBUG : dir/file1: newRWFileHandle: 
2020/08/16 05:30:48 DEBUG : dir/file1(0xc000090d00): openPending: 
2020/08/16 05:30:48 DEBUG : dir/file1: object hash cached: 0ef726ce9b1a7692357ff70dd321d595
2020/08/16 05:30:48 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:48 DEBUG : dir/file1: vfs cache: truncate to size=14
2020/08/16 05:30:48 DEBUG : dir: Added virtual directory entry vAdd: "file1"
2020/08/16 05:30:48 DEBUG : dir/file1(0xc000090d00): >openPending: err=<nil>
2020/08/16 05:30:48 DEBUG : dir/file1: vfs cache: truncate to size=0
2020/08/16 05:30:48 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading false) 0xc000193c00 item 1
2020/08/16 05:30:48 DEBUG : dir/file1: >newRWFileHandle: err=<nil>
2020/08/16 05:30:48 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err=<nil>
2020/08/16 05:30:48 DEBUG : dir/file1(0xc000090d00): _writeAt: size=25, off=0
2020/08/16 05:30:48 DEBUG : dir/file1(0xc000090d00): >_writeAt: n=25, err=<nil>
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: new object 'newLeaf'
2020/08/16 05:30:48 DEBUG : newLeaf: find: error: couldn't find object (newLeaf)
2020/08/16 05:30:48 DEBUG : find failed: not found in either local or remote fs
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: moving obj 'dir/file1' -> newLeaf
2020/08/16 05:30:48 DEBUG : newLeaf: move: file moved
2020/08/16 05:30:48 DEBUG : dir/file1: move: removed from cache
2020/08/16 05:30:48 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2/dir
2020/08/16 05:30:48 DEBUG : dir: cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:48 INFO  : dir: move: cache expired
2020/08/16 05:30:48 DEBUG : newLeaf: move: added to cache
2020/08/16 05:30:48 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:48 INFO  : : move: cache expired
2020/08/16 05:30:48 INFO  : dir/file1: Moved (server side)
2020/08/16 05:30:48 INFO  : dir/file1: vfs cache: renamed in cache to "newLeaf"
2020/08/16 05:30:48 DEBUG : newLeaf: Updating file with newLeaf 0xc000340540
2020/08/16 05:30:48 DEBUG : dir: Added virtual directory entry vDel: "file1"
2020/08/16 05:30:48 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:48 DEBUG : newLeaf(0xc000090d00): close: 
2020/08/16 05:30:48 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true
2020/08/16 05:30:48 DEBUG : newLeaf: vfs cache: setting modification time to 2020-08-16 05:30:48.103743746 +0000 UTC m=+8.694761827
2020/08/16 05:30:48 INFO  : newLeaf: vfs cache: queuing for upload in 100ms
2020/08/16 05:30:48 DEBUG : newLeaf(0xc000090d00): >close: err=<nil>
2020/08/16 05:30:48 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:30:48 DEBUG : dir: Looking for writers
2020/08/16 05:30:48 DEBUG : : Looking for writers
2020/08/16 05:30:48 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:48 DEBUG : dir: reading active writers
2020/08/16 05:30:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2020/08/16 05:30:48 DEBUG : dir: Looking for writers
2020/08/16 05:30:48 DEBUG : : Looking for writers
2020/08/16 05:30:48 DEBUG : dir: reading active writers
2020/08/16 05:30:48 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2020/08/16 05:30:48 DEBUG : dir: Looking for writers
2020/08/16 05:30:48 DEBUG : : Looking for writers
2020/08/16 05:30:48 DEBUG : dir: reading active writers
2020/08/16 05:30:48 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2020/08/16 05:30:48 DEBUG : dir: Looking for writers
2020/08/16 05:30:48 DEBUG : : Looking for writers
2020/08/16 05:30:48 DEBUG : dir: reading active writers
2020/08/16 05:30:48 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2020/08/16 05:30:48 DEBUG : newLeaf: vfs cache: starting upload
2020/08/16 05:30:48 DEBUG : newLeaf: updating object contents with size 25
2020/08/16 05:30:48 DEBUG : dir: Looking for writers
2020/08/16 05:30:48 DEBUG : : Looking for writers
2020/08/16 05:30:48 DEBUG : dir: reading active writers
2020/08/16 05:30:48 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2020/08/16 05:30:48 DEBUG : newLeaf: object hash cached: c7247bead226dfd7bd970c17229f4044
2020/08/16 05:30:48 DEBUG : newLeaf: MD5 = c7247bead226dfd7bd970c17229f4044 OK
2020/08/16 05:30:48 INFO  : newLeaf: Copied (replaced existing)
2020/08/16 05:30:48 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-08-16 05:30:48.103743746 +0000 UTC,c7247bead226dfd7bd970c17229f4044"
2020/08/16 05:30:48 DEBUG : newLeaf: vfs cache: writeback object to VFS layer
2020/08/16 05:30:48 DEBUG : : Added virtual directory entry vAdd: "newLeaf"
2020/08/16 05:30:48 INFO  : newLeaf: vfs cache: upload succeeded try #1
2020/08/16 05:30:48 DEBUG : dir: Looking for writers
2020/08/16 05:30:48 DEBUG : : Looking for writers
2020/08/16 05:30:48 DEBUG : dir: reading active writers
2020/08/16 05:30:48 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:48 DEBUG : >WaitForWriters: 
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:48 DEBUG : : list: cold listing: 2020-08-15 23:30:48.130288482 +0000 UTC
2020/08/16 05:30:48 DEBUG : : list: read 2 from source
2020/08/16 05:30:48 DEBUG : : list: source entries: [newLeaf dir]
2020/08/16 05:30:48 DEBUG : : list: cached object: newLeaf
2020/08/16 05:30:48 DEBUG : : list: cached directories: 0
2020/08/16 05:30:48 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:48.4668038 +0000 UTC m=+9.057821865
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:48 DEBUG : dir: list: cold listing: 2020-08-15 23:30:48.111128826 +0000 UTC
2020/08/16 05:30:48 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:48 DEBUG : dir: list: source entries: []
2020/08/16 05:30:48 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:48 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:48.474181518 +0000 UTC m=+9.065199583
2020/08/16 05:30:48 DEBUG : newLeaf: object hash cached: c7247bead226dfd7bd970c17229f4044
2020/08/16 05:30:48 DEBUG : newLeaf: object hash cached: f1f3d7db56f36d9a5a912b01803c2176a972b9b0
2020/08/16 05:30:48 DEBUG : newLeaf: object hash cached: 1db58adace4d798a32319ad95a298d8714268fa67a177378850892c9caaf4a51a10b8ffc1a9ffb9c77defb66c37d22019d36a931fe50c5f5d9d612c7291105b0
2020/08/16 05:30:48 DEBUG : newLeaf: object hash cached: e19d76ab
2020/08/16 05:30:48 DEBUG : newLeaf: object hash cached: c28ee946ceebc5dd7464b525fdfc3a480f47b2b22832edbfc4741c21a9d4c664
2020/08/16 05:30:48 DEBUG : newLeaf: object hash cached: 529d670c651f4f3f7011e4ab2d16332c1803bbe5
2020/08/16 05:30:48 DEBUG : newLeaf: object hash cached: 954e6302251b5e744b33bcf26f301bca00023794
2020/08/16 05:30:48 DEBUG : WaitForWriters: timeout=10s
2020/08/16 05:30:48 DEBUG : dir: Looking for writers
2020/08/16 05:30:48 DEBUG : : Looking for writers
2020/08/16 05:30:48 DEBUG : dir: reading active writers
2020/08/16 05:30:48 DEBUG : newLeaf: reading active writers
2020/08/16 05:30:48 DEBUG : >WaitForWriters: 
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:48 DEBUG : : list: warm 2 from cache for: rclone-test-jesoker1xojekix1tihibor2, expiring on: 2020-08-16 11:30:48.4668038 +0000 UTC
2020/08/16 05:30:48 DEBUG : : list: cached entries: [dir newLeaf]
2020/08/16 05:30:48 DEBUG : vfs cache: cleaner exiting
2020/08/16 05:30:48 DEBUG : newLeaf: removing object
2020/08/16 05:30:48 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list 'dir'
2020/08/16 05:30:48 DEBUG : dir: list: empty listing
2020/08/16 05:30:48 DEBUG : dir: list: read 0 from source
2020/08/16 05:30:48 DEBUG : dir: list: source entries: []
2020/08/16 05:30:48 DEBUG : dir: list: cached directories: 0
2020/08/16 05:30:48 DEBUG : dir: list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2/dir', cache ts: 2020-08-16 05:30:48.569499352 +0000 UTC m=+9.160517410
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: rmdir 'dir'
2020/08/16 05:30:48 DEBUG : dir: rmdir: removed dir in source fs
2020/08/16 05:30:48 DEBUG : dir: rmdir: removed from cache
2020/08/16 05:30:48 DEBUG : : cache: expired rclone-test-jesoker1xojekix1tihibor2
2020/08/16 05:30:48 INFO  : : rmdir: cache expired
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: list ''
2020/08/16 05:30:48 DEBUG : : list: cold listing: 2020-08-15 23:30:48.586265594 +0000 UTC
2020/08/16 05:30:48 DEBUG : : list: read 0 from source
2020/08/16 05:30:48 DEBUG : : list: source entries: []
2020/08/16 05:30:48 DEBUG : : list: cached directories: 0
2020/08/16 05:30:48 DEBUG : : list: cached dir: 'rclone-test-jesoker1xojekix1tihibor2', cache ts: 2020-08-16 05:30:48.592306765 +0000 UTC m=+9.183324823
--- FAIL: TestFileRename (9.16s)
    --- FAIL: TestFileRename/minimal,forceCache=true (8.27s)
    --- PASS: TestFileRename/writes,forceCache=true (0.89s)
FAIL
2020/08/16 05:30:48 DEBUG : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: Purge remote
2020/08/16 05:30:48 INFO  : Cache remote TestCache:rclone-test-jesoker1xojekix1tihibor2: purging cache
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestCache: -verbose -test.run '^TestFileRename$/^(minimal,forceCache=true|writes,forceCache=true)$'" - Finished ERROR in 9.202365652s (try 5/5): exit status 1: Failed [TestFileRename/minimal,forceCache=true]