"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerMailru: -verbose -test.run '^(TestCaseSensitivity|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRename|TestRWCacheRename|TestRWFileHandleFlushRead|TestRWFileHandleFlushWrite|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleOpenTests|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleReleaseWrite|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeCreateNew|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestVFSNew|TestVFSNewWithOpts|TestVFSOpenFile|TestVFSRename|TestVFSRoot|TestVFSStat|TestVFSStatParent|TestVFSStatfs|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(full,forceCache=false|minimal,forceCache=true|writes,forceCache=false|writes,forceCache=true)$'" - Starting (try 4/5) === RUN TestFileRename === RUN TestFileRename/minimal,forceCache=true 2020/07/24 10:44:57 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:44:57 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:44:57 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:44:57 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:44:57 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: new meta server: https://cld-extapi1.datacloudmail.ru/meta/ 2020/07/24 10:44:58 INFO : dir/file1.rclone_chunk.001_z4bg59: Moved (server side) 2020/07/24 10:44:59 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/07/24 10:44:59 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092c80): openPending: 2020/07/24 10:44:59 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:44:59 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:44:59 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092c80): >openPending: err= 2020/07/24 10:44:59 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:44:59 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:44:59 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:44:59 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092c80): _writeAt: size=14, off=0 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092c80): >_writeAt: n=14, err= 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092c80): close: 2020/07/24 10:44:59 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:44:59 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:44:59.368811427 +0000 UTC m=+2.365551767 2020/07/24 10:44:59 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092c80): >close: err= 2020/07/24 10:44:59 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:44:59 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:44:59 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:44:59 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092f40): _readAt: size=512, off=0 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092f40): openPending: 2020/07/24 10:44:59 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2020/07/24 10:44:59 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:44:59 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092f40): >openPending: err= 2020/07/24 10:44:59 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092f40): >_readAt: n=14, err=EOF 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092f40): close: 2020/07/24 10:44:59 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:44:59 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:44:59.368811427 +0000 UTC m=+2.365551767 2020/07/24 10:44:59 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:44:59 DEBUG : dir/file1(0xc000092f40): >close: err= 2020/07/24 10:44:59 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:44:59 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:45:00 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:00 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:00 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 10:45:00 ERROR : dir/file1.rclone_chunk.001_z4bipa: Couldn't move: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:00 ERROR : dir/file1.rclone_chunk.001_z4bipa: Failed to remove temporary chunk: Post https://cloud.mail.ru/api/m1/file/remove?access_token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:00 ERROR : dir/file1: Failed to copy: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:00 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 10:45:00 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 10:45:00 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:45:00 DEBUG : newLeaf: Updating file with newLeaf 0xc0002ec3c0 2020/07/24 10:45:00 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:45:00 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:00 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:45:00 DEBUG : newLeaf: move non-chunked object... 2020/07/24 10:45:00 INFO : newLeaf: Moved (server side) 2020/07/24 10:45:00 INFO : newLeaf: Moved (server side) 2020/07/24 10:45:00 DEBUG : newLeaf: vfs cache: cancelling upload 2020/07/24 10:45:01 ERROR : newLeaf.rclone_chunk.001_z4bjlc: Couldn't move: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:01 ERROR : newLeaf.rclone_chunk.001_z4bjlc: Failed to remove temporary chunk: Post https://cloud.mail.ru/api/m1/file/remove?access_token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:01 ERROR : newLeaf: Failed to copy: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:01 INFO : newLeaf: vfs cache: upload canceled 2020/07/24 10:45:01 DEBUG : newLeaf: vfs cache: cancelled upload 2020/07/24 10:45:01 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:45:01 DEBUG : dir/file1: Updating file with dir/file1 0xc0002ec3c0 2020/07/24 10:45:01 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:45:01 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:01 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:45:01 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:45:01 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:45:01 DEBUG : dir/file1(0xc000155b80): openPending: 2020/07/24 10:45:01 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2020/07/24 10:45:01 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:45:01 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:01 DEBUG : dir/file1(0xc000155b80): >openPending: err= 2020/07/24 10:45:01 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:45:01 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc00020a850 item 1 2020/07/24 10:45:01 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 10:45:01 ERROR : dir/file1: Failed to copy: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:01 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 10:45:01 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 10:45:01 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:45:01 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:45:01 DEBUG : dir/file1(0xc000155b80): _writeAt: size=25, off=0 2020/07/24 10:45:01 DEBUG : dir/file1(0xc000155b80): >_writeAt: n=25, err= 2020/07/24 10:45:01 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:45:01 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:01 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:01 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:45:01 DEBUG : newLeaf: Updating file with newLeaf 0xc0002ec3c0 2020/07/24 10:45:01 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:45:01 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:01 DEBUG : newLeaf(0xc000155b80): close: 2020/07/24 10:45:01 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:45:01 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:45:01.427430566 +0000 UTC m=+4.424170932 2020/07/24 10:45:01 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:45:01 DEBUG : newLeaf(0xc000155b80): >close: err= 2020/07/24 10:45:01 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:45:01 DEBUG : dir: Looking for writers 2020/07/24 10:45:01 DEBUG : : Looking for writers 2020/07/24 10:45:01 DEBUG : dir: reading active writers 2020/07/24 10:45:01 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:45:01 DEBUG : dir: Looking for writers 2020/07/24 10:45:01 DEBUG : : Looking for writers 2020/07/24 10:45:01 DEBUG : dir: reading active writers 2020/07/24 10:45:01 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:45:02 DEBUG : dir: Looking for writers 2020/07/24 10:45:02 DEBUG : : Looking for writers 2020/07/24 10:45:02 DEBUG : dir: reading active writers 2020/07/24 10:45:02 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:45:02 DEBUG : dir: Looking for writers 2020/07/24 10:45:02 DEBUG : : Looking for writers 2020/07/24 10:45:02 DEBUG : dir: reading active writers 2020/07/24 10:45:02 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:45:02 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:45:02 DEBUG : dir: Looking for writers 2020/07/24 10:45:02 DEBUG : : Looking for writers 2020/07/24 10:45:02 DEBUG : dir: reading active writers 2020/07/24 10:45:02 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:45:02 DEBUG : dir: Looking for writers 2020/07/24 10:45:02 DEBUG : : Looking for writers 2020/07/24 10:45:02 DEBUG : dir: reading active writers 2020/07/24 10:45:02 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:45:02 DEBUG : newLeaf.rclone_chunk.001_z4blyn: File has been put by hash from source 2020/07/24 10:45:02 DEBUG : dir: Looking for writers 2020/07/24 10:45:02 DEBUG : : Looking for writers 2020/07/24 10:45:02 DEBUG : dir: reading active writers 2020/07/24 10:45:02 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:45:03 INFO : newLeaf: Deleted 2020/07/24 10:45:03 DEBUG : dir: Looking for writers 2020/07/24 10:45:03 DEBUG : : Looking for writers 2020/07/24 10:45:03 DEBUG : dir: reading active writers 2020/07/24 10:45:03 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:45:03 INFO : newLeaf.rclone_chunk.001_z4blyn: Moved (server side) 2020/07/24 10:45:03 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:45:03 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:45:01 +0000 UTC" 2020/07/24 10:45:03 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:45:03 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:03 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:45:04 DEBUG : dir: Looking for writers 2020/07/24 10:45:04 DEBUG : : Looking for writers 2020/07/24 10:45:04 DEBUG : dir: reading active writers 2020/07/24 10:45:04 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:04 DEBUG : >WaitForWriters: 2020/07/24 10:45:04 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:45:04 DEBUG : dir: Looking for writers 2020/07/24 10:45:04 DEBUG : : Looking for writers 2020/07/24 10:45:04 DEBUG : dir: reading active writers 2020/07/24 10:45:04 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:04 DEBUG : >WaitForWriters: 2020/07/24 10:45:04 DEBUG : vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=false 2020/07/24 10:45:16 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:45:16 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:45:16 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:45:16 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:45:17 INFO : dir/file1.rclone_chunk.001_z4bzex: Moved (server side) 2020/07/24 10:45:18 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:45:18 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:18 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:18 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:45:18 DEBUG : newLeaf: Updating file with newLeaf 0xc0002fe180 2020/07/24 10:45:18 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:45:18 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:19 DEBUG : newLeaf: move non-chunked object... 2020/07/24 10:45:19 INFO : newLeaf: Moved (server side) 2020/07/24 10:45:19 INFO : newLeaf: Moved (server side) 2020/07/24 10:45:19 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:45:19 DEBUG : dir/file1: Updating file with dir/file1 0xc0002fe180 2020/07/24 10:45:19 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:45:19 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:19 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:45:19 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:45:19 DEBUG : dir/file1(0xc0007802c0): openPending: 2020/07/24 10:45:19 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:45:19 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:45:19 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:19 DEBUG : dir/file1(0xc0007802c0): >openPending: err= 2020/07/24 10:45:19 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:45:19 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:45:19 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:45:19 DEBUG : dir/file1(0xc0007802c0): _writeAt: size=25, off=0 2020/07/24 10:45:19 DEBUG : dir/file1(0xc0007802c0): >_writeAt: n=25, err= 2020/07/24 10:45:20 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:45:20 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:20 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:20 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:45:20 DEBUG : newLeaf: Updating file with newLeaf 0xc0002fe180 2020/07/24 10:45:20 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:45:20 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:20 DEBUG : newLeaf(0xc0007802c0): close: 2020/07/24 10:45:20 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:45:20 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:45:19.999844315 +0000 UTC m=+22.996584660 2020/07/24 10:45:20 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:45:20 DEBUG : newLeaf(0xc0007802c0): >close: err= 2020/07/24 10:45:20 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:45:20 DEBUG : dir: Looking for writers 2020/07/24 10:45:20 DEBUG : : Looking for writers 2020/07/24 10:45:20 DEBUG : dir: reading active writers 2020/07/24 10:45:20 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:45:20 DEBUG : dir: Looking for writers 2020/07/24 10:45:20 DEBUG : : Looking for writers 2020/07/24 10:45:20 DEBUG : dir: reading active writers 2020/07/24 10:45:20 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:45:20 DEBUG : dir: Looking for writers 2020/07/24 10:45:20 DEBUG : : Looking for writers 2020/07/24 10:45:20 DEBUG : dir: reading active writers 2020/07/24 10:45:20 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:45:20 DEBUG : dir: Looking for writers 2020/07/24 10:45:20 DEBUG : : Looking for writers 2020/07/24 10:45:20 DEBUG : dir: reading active writers 2020/07/24 10:45:20 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:45:20 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:45:20 DEBUG : dir: Looking for writers 2020/07/24 10:45:20 DEBUG : : Looking for writers 2020/07/24 10:45:20 DEBUG : dir: reading active writers 2020/07/24 10:45:20 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:45:20 DEBUG : dir: Looking for writers 2020/07/24 10:45:20 DEBUG : : Looking for writers 2020/07/24 10:45:20 DEBUG : dir: reading active writers 2020/07/24 10:45:20 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:45:20 DEBUG : newLeaf.rclone_chunk.001_z4c394: File has been put by hash from source 2020/07/24 10:45:21 DEBUG : dir: Looking for writers 2020/07/24 10:45:21 DEBUG : : Looking for writers 2020/07/24 10:45:21 DEBUG : dir: reading active writers 2020/07/24 10:45:21 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:45:21 INFO : newLeaf: Deleted 2020/07/24 10:45:21 DEBUG : dir: Looking for writers 2020/07/24 10:45:21 DEBUG : : Looking for writers 2020/07/24 10:45:21 DEBUG : dir: reading active writers 2020/07/24 10:45:21 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:45:21 INFO : newLeaf.rclone_chunk.001_z4c394: Moved (server side) 2020/07/24 10:45:21 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:45:21 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:45:19 +0000 UTC" 2020/07/24 10:45:21 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:45:21 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:21 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:45:22 DEBUG : dir: Looking for writers 2020/07/24 10:45:22 DEBUG : : Looking for writers 2020/07/24 10:45:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:22 DEBUG : dir: reading active writers 2020/07/24 10:45:22 DEBUG : >WaitForWriters: 2020/07/24 10:45:22 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:45:22 DEBUG : dir: Looking for writers 2020/07/24 10:45:22 DEBUG : : Looking for writers 2020/07/24 10:45:22 DEBUG : dir: reading active writers 2020/07/24 10:45:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:22 DEBUG : >WaitForWriters: 2020/07/24 10:45:22 DEBUG : vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=true 2020/07/24 10:45:34 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:45:34 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:45:34 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:45:34 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:45:35 INFO : dir/file1.rclone_chunk.001_z4chmp: Moved (server side) 2020/07/24 10:45:36 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/07/24 10:45:36 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:45:36 DEBUG : dir/file1(0xc0004907c0): openPending: 2020/07/24 10:45:36 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:45:36 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:45:36 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:36 DEBUG : dir/file1(0xc0004907c0): >openPending: err= 2020/07/24 10:45:36 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:45:36 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:45:36 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:36 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:45:36 DEBUG : dir/file1(0xc0004907c0): _writeAt: size=14, off=0 2020/07/24 10:45:36 DEBUG : dir/file1(0xc0004907c0): >_writeAt: n=14, err= 2020/07/24 10:45:36 DEBUG : dir/file1(0xc0004907c0): close: 2020/07/24 10:45:36 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:45:36 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:45:36.264414976 +0000 UTC m=+39.261155331 2020/07/24 10:45:36 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:45:36 DEBUG : dir/file1(0xc0004907c0): >close: err= 2020/07/24 10:45:36 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:45:36 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:45:36 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:45:36 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:45:36 DEBUG : dir/file1(0xc000490b00): _readAt: size=512, off=0 2020/07/24 10:45:36 DEBUG : dir/file1(0xc000490b00): openPending: 2020/07/24 10:45:36 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2020/07/24 10:45:36 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:45:36 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:36 DEBUG : dir/file1(0xc000490b00): >openPending: err= 2020/07/24 10:45:36 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:45:36 DEBUG : dir/file1(0xc000490b00): >_readAt: n=14, err=EOF 2020/07/24 10:45:36 DEBUG : dir/file1(0xc000490b00): close: 2020/07/24 10:45:36 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:45:36 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:45:36.264414976 +0000 UTC m=+39.261155331 2020/07/24 10:45:36 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:45:36 DEBUG : dir/file1(0xc000490b00): >close: err= 2020/07/24 10:45:36 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:45:36 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:45:37 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:37 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:37 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 10:45:37 ERROR : dir/file1.rclone_chunk.001_z4cjfg: Couldn't move: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:37 ERROR : dir/file1.rclone_chunk.001_z4cjfg: Failed to remove temporary chunk: Post https://cloud.mail.ru/api/m1/file/remove?access_token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:37 ERROR : dir/file1: Failed to copy: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:37 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 10:45:37 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 10:45:37 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:45:37 DEBUG : newLeaf: Updating file with newLeaf 0xc0006d0240 2020/07/24 10:45:37 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:45:37 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:37 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:45:37 DEBUG : newLeaf: move non-chunked object... 2020/07/24 10:45:37 INFO : newLeaf: Moved (server side) 2020/07/24 10:45:37 INFO : newLeaf: Moved (server side) 2020/07/24 10:45:37 DEBUG : newLeaf: vfs cache: cancelling upload 2020/07/24 10:45:38 ERROR : newLeaf.rclone_chunk.001_z4ckom: Couldn't move: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:38 ERROR : newLeaf.rclone_chunk.001_z4ckom: Failed to remove temporary chunk: Post https://cloud.mail.ru/api/m1/file/remove?access_token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:38 ERROR : newLeaf: Failed to copy: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:38 INFO : newLeaf: vfs cache: upload canceled 2020/07/24 10:45:38 DEBUG : newLeaf: vfs cache: cancelled upload 2020/07/24 10:45:38 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:45:38 DEBUG : dir/file1: Updating file with dir/file1 0xc0006d0240 2020/07/24 10:45:38 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:45:38 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:38 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:45:38 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:45:38 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:45:38 DEBUG : dir/file1(0xc00094ce40): openPending: 2020/07/24 10:45:38 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2020/07/24 10:45:38 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:45:38 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:38 DEBUG : dir/file1(0xc00094ce40): >openPending: err= 2020/07/24 10:45:38 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:45:38 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc000452310 item 1 2020/07/24 10:45:38 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 10:45:38 ERROR : dir/file1.rclone_chunk.001_z4clrp: Couldn't move: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:38 ERROR : dir/file1.rclone_chunk.001_z4clrp: Failed to remove temporary chunk: Post https://cloud.mail.ru/api/m1/file/remove?access_token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:38 ERROR : dir/file1: Failed to copy: Post https://cld-extapi1.datacloudmail.ru/meta/?client_id=cloud-win&token=22cbff4897a67139a12972826d6a52208b6c82ba37363830: context canceled 2020/07/24 10:45:38 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 10:45:38 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 10:45:38 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:45:38 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:45:38 DEBUG : dir/file1(0xc00094ce40): _writeAt: size=25, off=0 2020/07/24 10:45:38 DEBUG : dir/file1(0xc00094ce40): >_writeAt: n=25, err= 2020/07/24 10:45:39 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:45:39 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:39 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:39 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:45:39 DEBUG : newLeaf: Updating file with newLeaf 0xc0006d0240 2020/07/24 10:45:39 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:45:39 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:39 DEBUG : newLeaf(0xc00094ce40): close: 2020/07/24 10:45:39 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:45:39 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:45:38.934888001 +0000 UTC m=+41.931628344 2020/07/24 10:45:39 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:45:39 DEBUG : newLeaf(0xc00094ce40): >close: err= 2020/07/24 10:45:39 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:45:39 DEBUG : dir: Looking for writers 2020/07/24 10:45:39 DEBUG : : Looking for writers 2020/07/24 10:45:39 DEBUG : dir: reading active writers 2020/07/24 10:45:39 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:45:39 DEBUG : dir: Looking for writers 2020/07/24 10:45:39 DEBUG : : Looking for writers 2020/07/24 10:45:39 DEBUG : dir: reading active writers 2020/07/24 10:45:39 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:45:39 DEBUG : dir: Looking for writers 2020/07/24 10:45:39 DEBUG : : Looking for writers 2020/07/24 10:45:39 DEBUG : dir: reading active writers 2020/07/24 10:45:39 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:45:39 DEBUG : dir: Looking for writers 2020/07/24 10:45:39 DEBUG : : Looking for writers 2020/07/24 10:45:39 DEBUG : dir: reading active writers 2020/07/24 10:45:39 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:45:39 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:45:39 DEBUG : dir: Looking for writers 2020/07/24 10:45:39 DEBUG : : Looking for writers 2020/07/24 10:45:39 DEBUG : dir: reading active writers 2020/07/24 10:45:39 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:45:39 DEBUG : dir: Looking for writers 2020/07/24 10:45:39 DEBUG : : Looking for writers 2020/07/24 10:45:39 DEBUG : dir: reading active writers 2020/07/24 10:45:39 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:45:39 DEBUG : newLeaf.rclone_chunk.001_z4cmt3: File has been put by hash from source 2020/07/24 10:45:39 DEBUG : dir: Looking for writers 2020/07/24 10:45:39 DEBUG : : Looking for writers 2020/07/24 10:45:39 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:39 DEBUG : dir: reading active writers 2020/07/24 10:45:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:45:40 INFO : newLeaf: Deleted 2020/07/24 10:45:40 DEBUG : dir: Looking for writers 2020/07/24 10:45:40 DEBUG : : Looking for writers 2020/07/24 10:45:40 DEBUG : dir: reading active writers 2020/07/24 10:45:40 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:45:40 INFO : newLeaf.rclone_chunk.001_z4cmt3: Moved (server side) 2020/07/24 10:45:40 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:45:40 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:45:38 +0000 UTC" 2020/07/24 10:45:40 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:45:40 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:40 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:45:41 DEBUG : dir: Looking for writers 2020/07/24 10:45:41 DEBUG : : Looking for writers 2020/07/24 10:45:41 DEBUG : dir: reading active writers 2020/07/24 10:45:41 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:41 DEBUG : >WaitForWriters: 2020/07/24 10:45:41 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:45:41 DEBUG : dir: Looking for writers 2020/07/24 10:45:41 DEBUG : : Looking for writers 2020/07/24 10:45:41 DEBUG : dir: reading active writers 2020/07/24 10:45:41 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:41 DEBUG : >WaitForWriters: 2020/07/24 10:45:41 DEBUG : vfs cache: cleaner exiting === RUN TestFileRename/full,forceCache=false 2020/07/24 10:45:54 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:45:54 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:45:54 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:45:54 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:45:55 INFO : dir/file1.rclone_chunk.001_z4d16l: Moved (server side) 2020/07/24 10:45:55 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:45:55 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:45:55 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:45:55 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:45:55 DEBUG : dir/file1(0xc0004914c0): _readAt: size=512, off=0 2020/07/24 10:45:55 DEBUG : dir/file1(0xc0004914c0): openPending: 2020/07/24 10:45:55 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:45:55 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:45:55 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:55 DEBUG : dir/file1(0xc0004914c0): >openPending: err= 2020/07/24 10:45:55 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [] - present false 2020/07/24 10:45:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:45:55 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:45:55 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:45:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Switch file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/, expiry "2020-07-24T10:48:55.580888568Z" 2020/07/24 10:45:56 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:45:56 DEBUG : dir/file1(0xc0004914c0): >_readAt: n=14, err=EOF 2020/07/24 10:45:56 DEBUG : dir/file1(0xc0004914c0): close: 2020/07/24 10:45:56 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/07/24 10:45:56 DEBUG : dir/file1(0xc0004914c0): >close: err= 2020/07/24 10:45:56 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:45:56 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:56 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:56 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:45:56 DEBUG : newLeaf: Updating file with newLeaf 0xc00017c300 2020/07/24 10:45:56 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:45:56 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:57 DEBUG : newLeaf: move non-chunked object... 2020/07/24 10:45:57 INFO : newLeaf: Moved (server side) 2020/07/24 10:45:57 INFO : newLeaf: Moved (server side) 2020/07/24 10:45:57 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:45:57 DEBUG : dir/file1: Updating file with dir/file1 0xc00017c300 2020/07/24 10:45:57 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:45:57 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:57 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:45:57 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:45:57 DEBUG : dir/file1(0xc000154300): openPending: 2020/07/24 10:45:57 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2020/07/24 10:45:57 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:45:57 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:45:57 DEBUG : dir/file1(0xc000154300): >openPending: err= 2020/07/24 10:45:57 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:45:57 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:45:57 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:45:57 DEBUG : dir/file1(0xc000154300): _writeAt: size=25, off=0 2020/07/24 10:45:57 DEBUG : dir/file1(0xc000154300): >_writeAt: n=25, err= 2020/07/24 10:45:57 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:45:58 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:58 INFO : dir/file1: Moved (server side) 2020/07/24 10:45:58 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:45:58 DEBUG : newLeaf: Updating file with newLeaf 0xc00017c300 2020/07/24 10:45:58 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:45:58 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:58 DEBUG : newLeaf(0xc000154300): close: 2020/07/24 10:45:58 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:45:58 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:45:57.727491009 +0000 UTC m=+60.724231349 2020/07/24 10:45:58 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:45:58 DEBUG : newLeaf(0xc000154300): >close: err= 2020/07/24 10:45:58 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:45:58 DEBUG : dir: Looking for writers 2020/07/24 10:45:58 DEBUG : : Looking for writers 2020/07/24 10:45:58 DEBUG : dir: reading active writers 2020/07/24 10:45:58 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:45:58 DEBUG : dir: Looking for writers 2020/07/24 10:45:58 DEBUG : : Looking for writers 2020/07/24 10:45:58 DEBUG : dir: reading active writers 2020/07/24 10:45:58 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:45:58 DEBUG : dir: Looking for writers 2020/07/24 10:45:58 DEBUG : : Looking for writers 2020/07/24 10:45:58 DEBUG : dir: reading active writers 2020/07/24 10:45:58 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:45:58 DEBUG : dir: Looking for writers 2020/07/24 10:45:58 DEBUG : : Looking for writers 2020/07/24 10:45:58 DEBUG : dir: reading active writers 2020/07/24 10:45:58 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:45:58 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:45:58 DEBUG : dir: Looking for writers 2020/07/24 10:45:58 DEBUG : : Looking for writers 2020/07/24 10:45:58 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:58 DEBUG : dir: reading active writers 2020/07/24 10:45:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:45:58 DEBUG : dir: Looking for writers 2020/07/24 10:45:58 DEBUG : : Looking for writers 2020/07/24 10:45:58 DEBUG : dir: reading active writers 2020/07/24 10:45:58 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:45:58 DEBUG : newLeaf.rclone_chunk.001_z4d5xz: File has been put by hash from source 2020/07/24 10:45:58 DEBUG : dir: Looking for writers 2020/07/24 10:45:58 DEBUG : : Looking for writers 2020/07/24 10:45:58 DEBUG : dir: reading active writers 2020/07/24 10:45:58 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:45:59 INFO : newLeaf: Deleted 2020/07/24 10:45:59 DEBUG : dir: Looking for writers 2020/07/24 10:45:59 DEBUG : : Looking for writers 2020/07/24 10:45:59 DEBUG : dir: reading active writers 2020/07/24 10:45:59 DEBUG : newLeaf: reading active writers 2020/07/24 10:45:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:45:59 INFO : newLeaf.rclone_chunk.001_z4d5xz: Moved (server side) 2020/07/24 10:45:59 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:45:59 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:45:57 +0000 UTC" 2020/07/24 10:45:59 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:45:59 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:45:59 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:46:00 DEBUG : dir: Looking for writers 2020/07/24 10:46:00 DEBUG : : Looking for writers 2020/07/24 10:46:00 DEBUG : dir: reading active writers 2020/07/24 10:46:00 DEBUG : newLeaf: reading active writers 2020/07/24 10:46:00 DEBUG : >WaitForWriters: 2020/07/24 10:46:00 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:46:00 DEBUG : dir: Looking for writers 2020/07/24 10:46:00 DEBUG : : Looking for writers 2020/07/24 10:46:00 DEBUG : dir: reading active writers 2020/07/24 10:46:00 DEBUG : newLeaf: reading active writers 2020/07/24 10:46:00 DEBUG : >WaitForWriters: 2020/07/24 10:46:00 DEBUG : vfs cache: cleaner exiting --- FAIL: TestFileRename (75.38s) --- FAIL: TestFileRename/minimal,forceCache=true (19.13s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 file_test.go:341 file_test.go:357 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileRename/minimal,forceCache=true Messages: directories --- FAIL: TestFileRename/writes,forceCache=false (18.10s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 file_test.go:341 file_test.go:357 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileRename/writes,forceCache=false Messages: directories --- FAIL: TestFileRename/writes,forceCache=true (19.38s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 file_test.go:341 file_test.go:357 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileRename/writes,forceCache=true Messages: directories --- FAIL: TestFileRename/full,forceCache=false (18.76s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 file_test.go:341 file_test.go:357 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileRename/full,forceCache=false Messages: directories === RUN TestRcGetVFS 2020/07/24 10:46:12 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:46:12 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:46:12 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:46:12 DEBUG : : Looking for writers 2020/07/24 10:46:12 DEBUG : >WaitForWriters: --- FAIL: TestRcGetVFS (12.18s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 rc_test.go:64 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRcGetVFS Messages: directories === RUN TestReadFileHandleMethods 2020/07/24 10:46:24 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:46:25 INFO : dir/file1.rclone_chunk.001_z4dv3s: Moved (server side) 2020/07/24 10:46:26 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:46:26 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:46:26 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:46:26 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:46:26 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:46:26 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:26 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/07/24 10:46:26 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728 2020/07/24 10:46:26 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:26 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:46:26 DEBUG : dir: Looking for writers 2020/07/24 10:46:26 DEBUG : file1: reading active writers 2020/07/24 10:46:26 DEBUG : : Looking for writers 2020/07/24 10:46:26 DEBUG : dir: reading active writers 2020/07/24 10:46:26 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleMethods (13.62s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:80 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleMethods Messages: directories === RUN TestReadFileHandleSeek 2020/07/24 10:46:38 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:46:39 INFO : dir/file1.rclone_chunk.001_z4e9gb: Moved (server side) 2020/07/24 10:46:39 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:46:40 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:46:40 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:46:40 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:46:40 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/07/24 10:46:40 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/07/24 10:46:40 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/07/24 10:46:40 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/07/24 10:46:40 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/07/24 10:46:40 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 2, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:40 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:40 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker) 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728 2020/07/24 10:46:40 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 2, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:40 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:40 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker) 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728 2020/07/24 10:46:40 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728 2020/07/24 10:46:40 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 2, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:40 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:40 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:40 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:46:40 DEBUG : dir: Looking for writers 2020/07/24 10:46:40 DEBUG : file1: reading active writers 2020/07/24 10:46:40 DEBUG : : Looking for writers 2020/07/24 10:46:40 DEBUG : dir: reading active writers 2020/07/24 10:46:40 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleSeek (14.07s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" read_test.go:92: Error Trace: read_test.go:92 Error: Not equal: expected: "5" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -5 +0 Test: TestReadFileHandleSeek read_test.go:98: Error Trace: read_test.go:98 Error: Not equal: expected: "3" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -3 +0 Test: TestReadFileHandleSeek read_test.go:104: Error Trace: read_test.go:104 Error: Not equal: expected: "d" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -d +0 Test: TestReadFileHandleSeek run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:123 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleSeek Messages: directories === RUN TestReadFileHandleReadAt 2020/07/24 10:46:52 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:46:53 INFO : dir/file1.rclone_chunk.001_z4enlb: Moved (server side) 2020/07/24 10:46:53 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:46:54 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:46:54 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:46:54 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:46:54 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/07/24 10:46:54 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/07/24 10:46:54 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/07/24 10:46:54 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/07/24 10:46:54 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/07/24 10:46:54 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 2, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:54 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:54 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker) 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728 2020/07/24 10:46:54 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 2, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:54 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:54 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms 2020/07/24 10:46:54 DEBUG : dir/file1: aborting in-sequence read wait, off=10 2020/07/24 10:46:54 DEBUG : dir/file1: failed to wait for in-sequence read to 10 2020/07/24 10:46:54 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker) 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:54 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:54 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 2, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker) 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 2, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 1/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 2/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 3/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 4/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 5/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 6/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 7/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 8/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:55 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 9/10: unexpected EOF 2020/07/24 10:46:55 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:55 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:55 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:56 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:56 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:56 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 10/10: unexpected EOF 2020/07/24 10:46:56 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/07/24 10:46:56 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/07/24 10:46:56 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:46:56 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:56 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:46:56 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:46:56 ERROR : dir/file1: ReadFileHandle.Read error: unexpected EOF 2020/07/24 10:46:56 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/07/24 10:46:56 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/07/24 10:46:56 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/07/24 10:46:56 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16 2020/07/24 10:46:56 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/07/24 10:46:56 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/07/24 10:46:56 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/07/24 10:46:56 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor 2020/07/24 10:46:56 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:46:56 DEBUG : dir: Looking for writers 2020/07/24 10:46:56 DEBUG : file1: reading active writers 2020/07/24 10:46:56 DEBUG : : Looking for writers 2020/07/24 10:46:56 DEBUG : dir: reading active writers 2020/07/24 10:46:56 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleReadAt (15.14s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" read_test.go:140: Error Trace: read_test.go:140 Error: Not equal: expected: "5" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -5 +0 Test: TestReadFileHandleReadAt read_test.go:146: Error Trace: read_test.go:146 Error: Not equal: expected: "1" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -1 +0 Test: TestReadFileHandleReadAt read_test.go:153: Error Trace: read_test.go:153 Error: Not equal: expected: "abcdef" actual : "012345" Diff: --- Expected +++ Actual @@ -1 +1 @@ -abcdef +012345 Test: TestReadFileHandleReadAt read_test.go:158: Error Trace: read_test.go:158 Error: Not equal: expected: &errors.errorString{s:"EOF"} actual : &errors.errorString{s:"unexpected EOF"} Diff: --- Expected +++ Actual @@ -1,3 +1,3 @@ (*errors.errorString)({ - s: (string) (len=3) "EOF" + s: (string) (len=14) "unexpected EOF" }) Test: TestReadFileHandleReadAt read_test.go:159: Error Trace: read_test.go:159 Error: Not equal: expected: 6 actual : 16 Test: TestReadFileHandleReadAt read_test.go:160: Error Trace: read_test.go:160 Error: Not equal: expected: "abcdef" actual : "0123456789abcdef" Diff: --- Expected +++ Actual @@ -1 +1 @@ -abcdef +0123456789abcdef Test: TestReadFileHandleReadAt run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:179 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleReadAt Messages: directories === RUN TestReadFileHandleFlush 2020/07/24 10:47:07 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:47:08 INFO : dir/file1.rclone_chunk.001_z4f2e4: Moved (server side) 2020/07/24 10:47:09 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:47:09 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:47:09 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:47:09 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:47:09 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:47:09 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:47:09 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2020/07/24 10:47:09 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:47:09 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:47:09 DEBUG : dir: Looking for writers 2020/07/24 10:47:09 DEBUG : file1: reading active writers 2020/07/24 10:47:09 DEBUG : : Looking for writers 2020/07/24 10:47:09 DEBUG : dir: reading active writers 2020/07/24 10:47:09 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleFlush (13.21s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:208 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleFlush Messages: directories === RUN TestReadFileHandleRelease 2020/07/24 10:47:20 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:47:21 INFO : dir/file1.rclone_chunk.001_z4ff22: Moved (server side) 2020/07/24 10:47:22 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:47:22 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:47:22 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:47:22 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:47:22 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:47:22 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:47:22 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2020/07/24 10:47:22 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:47:22 DEBUG : dir/file1: ReadFileHandle.Release closing 2020/07/24 10:47:22 DEBUG : dir/file1: ReadFileHandle.Release nothing to do 2020/07/24 10:47:22 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:47:22 DEBUG : dir: Looking for writers 2020/07/24 10:47:22 DEBUG : file1: reading active writers 2020/07/24 10:47:22 DEBUG : : Looking for writers 2020/07/24 10:47:22 DEBUG : dir: reading active writers 2020/07/24 10:47:22 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleRelease (13.34s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:234 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleRelease Messages: directories === RUN TestRWFileHandleMethodsRead 2020/07/24 10:47:34 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:47:34 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:47:34 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:47:34 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:47:35 INFO : dir/file1.rclone_chunk.001_z4ftwb: Moved (server side) 2020/07/24 10:47:35 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:47:35 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:47:35 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:47:35 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:47:35 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:47:35 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): _readAt: size=1, off=0 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): openPending: 2020/07/24 10:47:35 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:47:35 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:47:35 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): >openPending: err= 2020/07/24 10:47:35 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/07/24 10:47:35 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:47:35 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:47:35 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:47:35 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:47:35 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): >_readAt: n=1, err= 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): _readAt: size=256, off=1 2020/07/24 10:47:35 DEBUG : vfs cache: looking for range={Pos:1 Size:15} in [{Pos:0 Size:16}] - present true 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): >_readAt: n=15, err=EOF 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): _readAt: size=16, off=16 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): >_readAt: n=0, err=EOF 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): close: 2020/07/24 10:47:35 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): >close: err= 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): close: 2020/07/24 10:47:35 DEBUG : dir/file1(0xc000876c00): >close: err=file already closed 2020/07/24 10:47:35 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:47:35 DEBUG : dir: Looking for writers 2020/07/24 10:47:35 DEBUG : file1: reading active writers 2020/07/24 10:47:35 DEBUG : : Looking for writers 2020/07/24 10:47:35 DEBUG : dir: reading active writers 2020/07/24 10:47:35 DEBUG : >WaitForWriters: 2020/07/24 10:47:35 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleMethodsRead (13.36s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:117 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleMethodsRead Messages: directories === RUN TestRWFileHandleSeek 2020/07/24 10:47:47 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:47:47 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:47:47 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:47:47 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:47:48 INFO : dir/file1.rclone_chunk.001_z4g68f: Moved (server side) 2020/07/24 10:47:48 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:47:49 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:47:49 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:47:49 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:47:49 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:47:49 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): _readAt: size=1, off=0 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): openPending: 2020/07/24 10:47:49 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:47:49 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:47:49 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): >openPending: err= 2020/07/24 10:47:49 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/07/24 10:47:49 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:47:49 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:47:49 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:47:49 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:47:49 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): >_readAt: n=1, err= 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): _readAt: size=1, off=5 2020/07/24 10:47:49 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): >_readAt: n=1, err= 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): _readAt: size=1, off=3 2020/07/24 10:47:49 DEBUG : vfs cache: looking for range={Pos:3 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): >_readAt: n=1, err= 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): _readAt: size=1, off=13 2020/07/24 10:47:49 DEBUG : vfs cache: looking for range={Pos:13 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): >_readAt: n=1, err= 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): _readAt: size=16, off=100 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): >_readAt: n=0, err=EOF 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): close: 2020/07/24 10:47:49 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/07/24 10:47:49 DEBUG : dir/file1(0xc000490e00): >close: err= 2020/07/24 10:47:49 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:47:49 DEBUG : dir: Looking for writers 2020/07/24 10:47:49 DEBUG : file1: reading active writers 2020/07/24 10:47:49 DEBUG : : Looking for writers 2020/07/24 10:47:49 DEBUG : dir: reading active writers 2020/07/24 10:47:49 DEBUG : >WaitForWriters: 2020/07/24 10:47:49 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleSeek (13.78s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:167 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleSeek Messages: directories === RUN TestRWFileHandleReadAt 2020/07/24 10:48:01 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:48:01 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:48:01 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:48:01 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:48:02 INFO : dir/file1.rclone_chunk.001_z4gknf: Moved (server side) 2020/07/24 10:48:02 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:48:03 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:48:03 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:48:03 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:48:03 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:48:03 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): _readAt: size=1, off=0 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): openPending: 2020/07/24 10:48:03 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:48:03 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:48:03 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >openPending: err= 2020/07/24 10:48:03 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/07/24 10:48:03 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:48:03 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:48:03 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:48:03 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:48:03 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >_readAt: n=1, err= 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): _readAt: size=1, off=5 2020/07/24 10:48:03 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >_readAt: n=1, err= 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): _readAt: size=1, off=1 2020/07/24 10:48:03 DEBUG : vfs cache: looking for range={Pos:1 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >_readAt: n=1, err= 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): _readAt: size=6, off=10 2020/07/24 10:48:03 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >_readAt: n=6, err= 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): _readAt: size=256, off=10 2020/07/24 10:48:03 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >_readAt: n=6, err=EOF 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): _readAt: size=256, off=100 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >_readAt: n=0, err=EOF 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): close: 2020/07/24 10:48:03 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >close: err= 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): _readAt: size=256, off=100 2020/07/24 10:48:03 DEBUG : dir/file1(0xc00094c600): >_readAt: n=0, err=file already closed 2020/07/24 10:48:03 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:48:03 DEBUG : dir: Looking for writers 2020/07/24 10:48:03 DEBUG : file1: reading active writers 2020/07/24 10:48:03 DEBUG : : Looking for writers 2020/07/24 10:48:03 DEBUG : dir: reading active writers 2020/07/24 10:48:03 DEBUG : >WaitForWriters: 2020/07/24 10:48:03 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleReadAt (13.37s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:217 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleReadAt Messages: directories === RUN TestRWFileHandleFlushRead 2020/07/24 10:48:14 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:48:14 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:48:14 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:48:14 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:48:15 INFO : dir/file1.rclone_chunk.001_z4gxv0: Moved (server side) 2020/07/24 10:48:16 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:48:16 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:48:16 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:48:16 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:48:16 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:48:16 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): RWFileHandle.Flush 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): _readAt: size=256, off=0 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): openPending: 2020/07/24 10:48:16 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:48:16 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:48:16 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): >openPending: err= 2020/07/24 10:48:16 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2020/07/24 10:48:16 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:48:16 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:48:16 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:48:16 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:48:16 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): >_readAt: n=16, err=EOF 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): RWFileHandle.Flush 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): RWFileHandle.Flush 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): close: 2020/07/24 10:48:16 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/07/24 10:48:16 DEBUG : dir/file1(0xc0008240c0): >close: err= 2020/07/24 10:48:16 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:48:16 DEBUG : dir: Looking for writers 2020/07/24 10:48:16 DEBUG : file1: reading active writers 2020/07/24 10:48:16 DEBUG : : Looking for writers 2020/07/24 10:48:16 DEBUG : dir: reading active writers 2020/07/24 10:48:16 DEBUG : >WaitForWriters: 2020/07/24 10:48:16 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleFlushRead (13.24s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:246 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleFlushRead Messages: directories === RUN TestRWFileHandleReleaseRead 2020/07/24 10:48:28 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:48:28 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:48:28 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:48:28 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:48:29 INFO : dir/file1.rclone_chunk.001_z4hbmo: Moved (server side) 2020/07/24 10:48:29 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:48:30 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:48:30 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:48:30 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:48:30 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:48:30 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:48:30 DEBUG : dir/file1(0xc000824f80): _readAt: size=256, off=0 2020/07/24 10:48:30 DEBUG : dir/file1(0xc000824f80): openPending: 2020/07/24 10:48:30 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:48:30 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:48:30 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:48:30 DEBUG : dir/file1(0xc000824f80): >openPending: err= 2020/07/24 10:48:30 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2020/07/24 10:48:30 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:48:30 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:48:30 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:48:30 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:48:30 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo20.datacloudmail.ru/oauth-get/ 2020/07/24 10:48:30 DEBUG : dir/file1(0xc000824f80): >_readAt: n=16, err=EOF 2020/07/24 10:48:30 DEBUG : dir/file1(0xc000824f80): RWFileHandle.Release 2020/07/24 10:48:30 DEBUG : dir/file1(0xc000824f80): close: 2020/07/24 10:48:30 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/07/24 10:48:30 DEBUG : dir/file1(0xc000824f80): >close: err= 2020/07/24 10:48:30 DEBUG : dir/file1(0xc000824f80): RWFileHandle.Release 2020/07/24 10:48:30 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:48:30 DEBUG : dir: Looking for writers 2020/07/24 10:48:30 DEBUG : file1: reading active writers 2020/07/24 10:48:30 DEBUG : : Looking for writers 2020/07/24 10:48:30 DEBUG : dir: reading active writers 2020/07/24 10:48:30 DEBUG : >WaitForWriters: 2020/07/24 10:48:30 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleReleaseRead (13.74s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:267 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleReleaseRead Messages: directories === RUN TestRWFileHandleMethodsWrite 2020/07/24 10:48:41 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:48:41 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:48:41 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:48:41 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:48:41 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:48:41 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:48:41 DEBUG : file1: newRWFileHandle: 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): openPending: 2020/07/24 10:48:41 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:48:41 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): >openPending: err= 2020/07/24 10:48:41 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:48:41 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:48:41 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:48:41 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): _writeAt: size=5, off=0 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): >_writeAt: n=5, err= 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): _writeAt: size=7, off=5 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): >_writeAt: n=7, err= 2020/07/24 10:48:41 DEBUG : file1: vfs cache: truncate to size=11 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): close: 2020/07/24 10:48:41 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:48:41.971430533 +0000 UTC m=+224.968170908 2020/07/24 10:48:41 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): >close: err= 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): close: 2020/07/24 10:48:41 DEBUG : file1(0xc000092c80): >close: err=file already closed 2020/07/24 10:48:41 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:48:41 DEBUG : dir: Looking for writers 2020/07/24 10:48:41 DEBUG : : Looking for writers 2020/07/24 10:48:41 DEBUG : dir: reading active writers 2020/07/24 10:48:41 DEBUG : file1: reading active writers 2020/07/24 10:48:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:48:41 DEBUG : dir: Looking for writers 2020/07/24 10:48:41 DEBUG : : Looking for writers 2020/07/24 10:48:41 DEBUG : dir: reading active writers 2020/07/24 10:48:41 DEBUG : file1: reading active writers 2020/07/24 10:48:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:48:42 DEBUG : dir: Looking for writers 2020/07/24 10:48:42 DEBUG : : Looking for writers 2020/07/24 10:48:42 DEBUG : dir: reading active writers 2020/07/24 10:48:42 DEBUG : file1: reading active writers 2020/07/24 10:48:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:48:42 DEBUG : dir: Looking for writers 2020/07/24 10:48:42 DEBUG : : Looking for writers 2020/07/24 10:48:42 DEBUG : dir: reading active writers 2020/07/24 10:48:42 DEBUG : file1: reading active writers 2020/07/24 10:48:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:48:42 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:48:42 DEBUG : dir: Looking for writers 2020/07/24 10:48:42 DEBUG : : Looking for writers 2020/07/24 10:48:42 DEBUG : dir: reading active writers 2020/07/24 10:48:42 DEBUG : file1: reading active writers 2020/07/24 10:48:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:48:42 DEBUG : dir: Looking for writers 2020/07/24 10:48:42 DEBUG : : Looking for writers 2020/07/24 10:48:42 DEBUG : dir: reading active writers 2020/07/24 10:48:42 DEBUG : file1: reading active writers 2020/07/24 10:48:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:48:42 DEBUG : dir: Looking for writers 2020/07/24 10:48:42 DEBUG : : Looking for writers 2020/07/24 10:48:42 DEBUG : dir: reading active writers 2020/07/24 10:48:42 DEBUG : file1: reading active writers 2020/07/24 10:48:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:48:42 INFO : file1.rclone_chunk.001_z4hpfm: Moved (server side) 2020/07/24 10:48:42 INFO : file1: Copied (new) 2020/07/24 10:48:42 DEBUG : file1: vfs cache: fingerprint now "11,2020-07-24 10:48:41 +0000 UTC" 2020/07/24 10:48:42 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:48:42 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:48:42 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:48:43 DEBUG : dir: Looking for writers 2020/07/24 10:48:43 DEBUG : : Looking for writers 2020/07/24 10:48:43 DEBUG : dir: reading active writers 2020/07/24 10:48:43 DEBUG : file1: reading active writers 2020/07/24 10:48:43 DEBUG : >WaitForWriters: 2020/07/24 10:48:51 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:48:51 DEBUG : dir: Looking for writers 2020/07/24 10:48:51 DEBUG : : Looking for writers 2020/07/24 10:48:51 DEBUG : dir: reading active writers 2020/07/24 10:48:51 DEBUG : file1: reading active writers 2020/07/24 10:48:51 DEBUG : >WaitForWriters: 2020/07/24 10:48:51 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleMethodsWrite (21.09s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:339 Error: Not equal: expected: []string{"file1,11,false"} actual : []string{"dir,0,true", "file1,11,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=14) "file1,11,false" Test: TestRWFileHandleMethodsWrite fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 read_write_test.go:344 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleMethodsWrite Messages: directories run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:345 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleMethodsWrite Messages: directories === RUN TestRWFileHandleWriteAt 2020/07/24 10:49:02 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:49:02 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:49:02 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:49:02 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:49:02 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:49:03 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:49:03 DEBUG : file1: newRWFileHandle: 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): openPending: 2020/07/24 10:49:03 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:49:03 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): >openPending: err= 2020/07/24 10:49:03 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:49:03 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:03 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:49:03 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): _writeAt: size=7, off=0 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): >_writeAt: n=7, err= 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): _writeAt: size=6, off=5 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): >_writeAt: n=6, err= 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): close: 2020/07/24 10:49:03 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:49:03.168848546 +0000 UTC m=+246.165588887 2020/07/24 10:49:03 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): >close: err= 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): _writeAt: size=5, off=0 2020/07/24 10:49:03 DEBUG : file1(0xc000490880): >_writeAt: n=0, err=file already closed 2020/07/24 10:49:03 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:49:03 DEBUG : dir: Looking for writers 2020/07/24 10:49:03 DEBUG : : Looking for writers 2020/07/24 10:49:03 DEBUG : file1: reading active writers 2020/07/24 10:49:03 DEBUG : dir: reading active writers 2020/07/24 10:49:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:49:03 DEBUG : dir: Looking for writers 2020/07/24 10:49:03 DEBUG : : Looking for writers 2020/07/24 10:49:03 DEBUG : dir: reading active writers 2020/07/24 10:49:03 DEBUG : file1: reading active writers 2020/07/24 10:49:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:49:03 DEBUG : dir: Looking for writers 2020/07/24 10:49:03 DEBUG : : Looking for writers 2020/07/24 10:49:03 DEBUG : dir: reading active writers 2020/07/24 10:49:03 DEBUG : file1: reading active writers 2020/07/24 10:49:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:49:03 DEBUG : dir: Looking for writers 2020/07/24 10:49:03 DEBUG : : Looking for writers 2020/07/24 10:49:03 DEBUG : dir: reading active writers 2020/07/24 10:49:03 DEBUG : file1: reading active writers 2020/07/24 10:49:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:49:03 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:49:03 DEBUG : dir: Looking for writers 2020/07/24 10:49:03 DEBUG : : Looking for writers 2020/07/24 10:49:03 DEBUG : dir: reading active writers 2020/07/24 10:49:03 DEBUG : file1: reading active writers 2020/07/24 10:49:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:49:03 DEBUG : dir: Looking for writers 2020/07/24 10:49:03 DEBUG : : Looking for writers 2020/07/24 10:49:03 DEBUG : file1: reading active writers 2020/07/24 10:49:03 DEBUG : dir: reading active writers 2020/07/24 10:49:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:49:03 DEBUG : dir: Looking for writers 2020/07/24 10:49:03 DEBUG : : Looking for writers 2020/07/24 10:49:03 DEBUG : dir: reading active writers 2020/07/24 10:49:03 DEBUG : file1: reading active writers 2020/07/24 10:49:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:49:04 INFO : file1.rclone_chunk.001_z4iahb: Moved (server side) 2020/07/24 10:49:04 INFO : file1: Copied (new) 2020/07/24 10:49:04 DEBUG : file1: vfs cache: fingerprint now "11,2020-07-24 10:49:03 +0000 UTC" 2020/07/24 10:49:04 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:49:04 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:04 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:49:04 DEBUG : dir: Looking for writers 2020/07/24 10:49:04 DEBUG : : Looking for writers 2020/07/24 10:49:04 DEBUG : dir: reading active writers 2020/07/24 10:49:04 DEBUG : file1: reading active writers 2020/07/24 10:49:04 DEBUG : >WaitForWriters: 2020/07/24 10:49:12 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:49:12 DEBUG : dir: Looking for writers 2020/07/24 10:49:12 DEBUG : : Looking for writers 2020/07/24 10:49:12 DEBUG : file1: reading active writers 2020/07/24 10:49:12 DEBUG : dir: reading active writers 2020/07/24 10:49:12 DEBUG : >WaitForWriters: 2020/07/24 10:49:12 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleWriteAt (21.27s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:387 Error: Not equal: expected: []string{"file1,11,false"} actual : []string{"dir,0,true", "file1,11,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=14) "file1,11,false" Test: TestRWFileHandleWriteAt fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 read_write_test.go:392 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleWriteAt Messages: directories run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:393 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleWriteAt Messages: directories === RUN TestRWFileHandleWriteNoWrite 2020/07/24 10:49:24 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:49:24 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:49:24 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:49:24 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:49:24 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:49:24 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:49:24 DEBUG : file1: newRWFileHandle: 2020/07/24 10:49:24 DEBUG : file1(0xc000780440): openPending: 2020/07/24 10:49:24 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:49:24 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:24 DEBUG : file1(0xc000780440): >openPending: err= 2020/07/24 10:49:24 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:49:24 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:24 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:49:24 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:49:24 DEBUG : file1(0xc000780440): close: 2020/07/24 10:49:24 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:49:24.321522276 +0000 UTC m=+267.318262608 2020/07/24 10:49:24 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:49:24 DEBUG : file1(0xc000780440): >close: err= 2020/07/24 10:49:24 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:49:24 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/07/24 10:49:24 DEBUG : file2: newRWFileHandle: 2020/07/24 10:49:24 DEBUG : file2(0xc000780740): openPending: 2020/07/24 10:49:24 DEBUG : file2: vfs cache: truncate to size=0 2020/07/24 10:49:24 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/07/24 10:49:24 DEBUG : file2(0xc000780740): >openPending: err= 2020/07/24 10:49:24 DEBUG : file2: >newRWFileHandle: err= 2020/07/24 10:49:24 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/07/24 10:49:24 DEBUG : file2: >Open: fd=file2 (rw), err= 2020/07/24 10:49:24 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2020/07/24 10:49:24 DEBUG : file2(0xc000780740): RWFileHandle.Flush 2020/07/24 10:49:24 DEBUG : file2(0xc000780740): RWFileHandle.Release 2020/07/24 10:49:24 DEBUG : file2(0xc000780740): close: 2020/07/24 10:49:24 DEBUG : file2: vfs cache: setting modification time to 2020-07-24 10:49:24.322211906 +0000 UTC m=+267.318952252 2020/07/24 10:49:24 INFO : file2: vfs cache: queuing for upload in 100ms 2020/07/24 10:49:24 DEBUG : file2(0xc000780740): >close: err= 2020/07/24 10:49:24 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:49:24 DEBUG : dir: Looking for writers 2020/07/24 10:49:24 DEBUG : : Looking for writers 2020/07/24 10:49:24 DEBUG : dir: reading active writers 2020/07/24 10:49:24 DEBUG : file1: reading active writers 2020/07/24 10:49:24 DEBUG : file2: reading active writers 2020/07/24 10:49:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2020/07/24 10:49:24 DEBUG : dir: Looking for writers 2020/07/24 10:49:24 DEBUG : : Looking for writers 2020/07/24 10:49:24 DEBUG : dir: reading active writers 2020/07/24 10:49:24 DEBUG : file1: reading active writers 2020/07/24 10:49:24 DEBUG : file2: reading active writers 2020/07/24 10:49:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2020/07/24 10:49:24 DEBUG : dir: Looking for writers 2020/07/24 10:49:24 DEBUG : : Looking for writers 2020/07/24 10:49:24 DEBUG : dir: reading active writers 2020/07/24 10:49:24 DEBUG : file1: reading active writers 2020/07/24 10:49:24 DEBUG : file2: reading active writers 2020/07/24 10:49:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2020/07/24 10:49:24 DEBUG : dir: Looking for writers 2020/07/24 10:49:24 DEBUG : : Looking for writers 2020/07/24 10:49:24 DEBUG : dir: reading active writers 2020/07/24 10:49:24 DEBUG : file1: reading active writers 2020/07/24 10:49:24 DEBUG : file2: reading active writers 2020/07/24 10:49:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2020/07/24 10:49:24 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:49:24 DEBUG : file2: vfs cache: starting upload 2020/07/24 10:49:24 DEBUG : dir: Looking for writers 2020/07/24 10:49:24 DEBUG : : Looking for writers 2020/07/24 10:49:24 DEBUG : dir: reading active writers 2020/07/24 10:49:24 DEBUG : file1: reading active writers 2020/07/24 10:49:24 DEBUG : file2: reading active writers 2020/07/24 10:49:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2020/07/24 10:49:24 DEBUG : dir: Looking for writers 2020/07/24 10:49:24 DEBUG : : Looking for writers 2020/07/24 10:49:24 DEBUG : dir: reading active writers 2020/07/24 10:49:24 DEBUG : file1: reading active writers 2020/07/24 10:49:24 DEBUG : file2: reading active writers 2020/07/24 10:49:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2020/07/24 10:49:24 DEBUG : dir: Looking for writers 2020/07/24 10:49:24 DEBUG : : Looking for writers 2020/07/24 10:49:24 DEBUG : file2: reading active writers 2020/07/24 10:49:24 DEBUG : dir: reading active writers 2020/07/24 10:49:24 DEBUG : file1: reading active writers 2020/07/24 10:49:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2020/07/24 10:49:25 INFO : file1.rclone_chunk.001_z4ivye: Moved (server side) 2020/07/24 10:49:25 INFO : file1: Copied (new) 2020/07/24 10:49:25 DEBUG : file1: vfs cache: fingerprint now "0,2020-07-24 10:49:24 +0000 UTC" 2020/07/24 10:49:25 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:49:25 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:25 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:49:25 INFO : file2.rclone_chunk.001_z4iv6l: Moved (server side) 2020/07/24 10:49:25 INFO : file2: Copied (new) 2020/07/24 10:49:25 DEBUG : file2: vfs cache: fingerprint now "0,2020-07-24 10:49:24 +0000 UTC" 2020/07/24 10:49:25 DEBUG : file2: vfs cache: writeback object to VFS layer 2020/07/24 10:49:25 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/07/24 10:49:25 INFO : file2: vfs cache: upload succeeded try #1 2020/07/24 10:49:25 DEBUG : dir: Looking for writers 2020/07/24 10:49:25 DEBUG : : Looking for writers 2020/07/24 10:49:25 DEBUG : file1: reading active writers 2020/07/24 10:49:25 DEBUG : file2: reading active writers 2020/07/24 10:49:25 DEBUG : dir: reading active writers 2020/07/24 10:49:25 DEBUG : >WaitForWriters: 2020/07/24 10:49:33 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:49:33 DEBUG : dir: Looking for writers 2020/07/24 10:49:33 DEBUG : : Looking for writers 2020/07/24 10:49:33 DEBUG : dir: reading active writers 2020/07/24 10:49:33 DEBUG : file1: reading active writers 2020/07/24 10:49:33 DEBUG : file2: reading active writers 2020/07/24 10:49:33 DEBUG : >WaitForWriters: 2020/07/24 10:49:33 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleWriteNoWrite (21.29s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:420 Error: Not equal: expected: []string{"file1,0,false", "file2,0,false"} actual : []string{"dir,0,true", "file1,0,false", "file2,0,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=2) { +([]string) (len=3) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,0,false", Test: TestRWFileHandleWriteNoWrite fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 read_write_test.go:426 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleWriteNoWrite Messages: directories run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:427 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleWriteNoWrite Messages: directories === RUN TestRWFileHandleFlushWrite 2020/07/24 10:49:45 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:49:45 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:49:45 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:49:45 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:49:45 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:49:45 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:49:45 DEBUG : file1: newRWFileHandle: 2020/07/24 10:49:45 DEBUG : file1(0xc000490140): openPending: 2020/07/24 10:49:45 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:49:45 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:45 DEBUG : file1(0xc000490140): >openPending: err= 2020/07/24 10:49:45 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:49:45 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:45 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:49:45 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:49:45 DEBUG : file1(0xc000490140): _writeAt: size=5, off=0 2020/07/24 10:49:45 DEBUG : file1(0xc000490140): >_writeAt: n=5, err= 2020/07/24 10:49:45 DEBUG : file1(0xc000490140): RWFileHandle.Flush 2020/07/24 10:49:45 DEBUG : file1(0xc000490140): RWFileHandle.Flush 2020/07/24 10:49:45 DEBUG : file1(0xc000490140): close: 2020/07/24 10:49:45 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:49:45.603411093 +0000 UTC m=+288.600151433 2020/07/24 10:49:45 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:49:45 DEBUG : file1(0xc000490140): >close: err= 2020/07/24 10:49:45 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:49:45 DEBUG : dir: Looking for writers 2020/07/24 10:49:45 DEBUG : : Looking for writers 2020/07/24 10:49:45 DEBUG : dir: reading active writers 2020/07/24 10:49:45 DEBUG : file1: reading active writers 2020/07/24 10:49:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:49:45 DEBUG : dir: Looking for writers 2020/07/24 10:49:45 DEBUG : : Looking for writers 2020/07/24 10:49:45 DEBUG : dir: reading active writers 2020/07/24 10:49:45 DEBUG : file1: reading active writers 2020/07/24 10:49:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:49:45 DEBUG : dir: Looking for writers 2020/07/24 10:49:45 DEBUG : : Looking for writers 2020/07/24 10:49:45 DEBUG : dir: reading active writers 2020/07/24 10:49:45 DEBUG : file1: reading active writers 2020/07/24 10:49:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:49:45 DEBUG : dir: Looking for writers 2020/07/24 10:49:45 DEBUG : : Looking for writers 2020/07/24 10:49:45 DEBUG : dir: reading active writers 2020/07/24 10:49:45 DEBUG : file1: reading active writers 2020/07/24 10:49:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:49:45 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:49:45 DEBUG : dir: Looking for writers 2020/07/24 10:49:45 DEBUG : : Looking for writers 2020/07/24 10:49:45 DEBUG : dir: reading active writers 2020/07/24 10:49:45 DEBUG : file1: reading active writers 2020/07/24 10:49:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:49:45 DEBUG : dir: Looking for writers 2020/07/24 10:49:45 DEBUG : : Looking for writers 2020/07/24 10:49:45 DEBUG : dir: reading active writers 2020/07/24 10:49:45 DEBUG : file1: reading active writers 2020/07/24 10:49:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:49:46 DEBUG : dir: Looking for writers 2020/07/24 10:49:46 DEBUG : : Looking for writers 2020/07/24 10:49:46 DEBUG : dir: reading active writers 2020/07/24 10:49:46 DEBUG : file1: reading active writers 2020/07/24 10:49:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:49:46 INFO : file1.rclone_chunk.001_z4jg2s: Moved (server side) 2020/07/24 10:49:46 INFO : file1: Copied (new) 2020/07/24 10:49:46 DEBUG : file1: vfs cache: fingerprint now "5,2020-07-24 10:49:45 +0000 UTC" 2020/07/24 10:49:46 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:49:46 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:46 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:49:46 DEBUG : dir: Looking for writers 2020/07/24 10:49:46 DEBUG : : Looking for writers 2020/07/24 10:49:46 DEBUG : dir: reading active writers 2020/07/24 10:49:46 DEBUG : file1: reading active writers 2020/07/24 10:49:46 DEBUG : >WaitForWriters: 2020/07/24 10:49:46 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleFlushWrite (13.01s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:456 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleFlushWrite Messages: directories === RUN TestRWFileHandleReleaseWrite 2020/07/24 10:49:58 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:49:58 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:49:58 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:49:58 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:49:58 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:49:58 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:49:58 DEBUG : file1: newRWFileHandle: 2020/07/24 10:49:58 DEBUG : file1(0xc000491540): openPending: 2020/07/24 10:49:58 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:49:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:58 DEBUG : file1(0xc000491540): >openPending: err= 2020/07/24 10:49:58 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:49:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:49:58 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:49:58 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:49:58 DEBUG : file1(0xc000491540): _writeAt: size=5, off=0 2020/07/24 10:49:58 DEBUG : file1(0xc000491540): >_writeAt: n=5, err= 2020/07/24 10:49:58 DEBUG : file1(0xc000491540): RWFileHandle.Release 2020/07/24 10:49:58 DEBUG : file1(0xc000491540): close: 2020/07/24 10:49:58 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:49:58.624858293 +0000 UTC m=+301.621598632 2020/07/24 10:49:58 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:49:58 DEBUG : file1(0xc000491540): >close: err= 2020/07/24 10:49:58 DEBUG : file1(0xc000491540): RWFileHandle.Release 2020/07/24 10:49:58 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:49:58 DEBUG : dir: Looking for writers 2020/07/24 10:49:58 DEBUG : : Looking for writers 2020/07/24 10:49:58 DEBUG : file1: reading active writers 2020/07/24 10:49:58 DEBUG : dir: reading active writers 2020/07/24 10:49:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:49:58 DEBUG : dir: Looking for writers 2020/07/24 10:49:58 DEBUG : : Looking for writers 2020/07/24 10:49:58 DEBUG : dir: reading active writers 2020/07/24 10:49:58 DEBUG : file1: reading active writers 2020/07/24 10:49:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:49:58 DEBUG : dir: Looking for writers 2020/07/24 10:49:58 DEBUG : : Looking for writers 2020/07/24 10:49:58 DEBUG : dir: reading active writers 2020/07/24 10:49:58 DEBUG : file1: reading active writers 2020/07/24 10:49:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:49:58 DEBUG : dir: Looking for writers 2020/07/24 10:49:58 DEBUG : : Looking for writers 2020/07/24 10:49:58 DEBUG : dir: reading active writers 2020/07/24 10:49:58 DEBUG : file1: reading active writers 2020/07/24 10:49:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:49:58 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:49:58 DEBUG : dir: Looking for writers 2020/07/24 10:49:58 DEBUG : : Looking for writers 2020/07/24 10:49:58 DEBUG : dir: reading active writers 2020/07/24 10:49:58 DEBUG : file1: reading active writers 2020/07/24 10:49:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:49:58 DEBUG : dir: Looking for writers 2020/07/24 10:49:58 DEBUG : : Looking for writers 2020/07/24 10:49:58 DEBUG : dir: reading active writers 2020/07/24 10:49:58 DEBUG : file1: reading active writers 2020/07/24 10:49:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:49:59 DEBUG : dir: Looking for writers 2020/07/24 10:49:59 DEBUG : : Looking for writers 2020/07/24 10:49:59 DEBUG : dir: reading active writers 2020/07/24 10:49:59 DEBUG : file1: reading active writers 2020/07/24 10:49:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:49:59 DEBUG : dir: Looking for writers 2020/07/24 10:49:59 DEBUG : : Looking for writers 2020/07/24 10:49:59 DEBUG : dir: reading active writers 2020/07/24 10:49:59 DEBUG : file1: reading active writers 2020/07/24 10:49:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:50:00 INFO : file1.rclone_chunk.001_z4jtm2: Moved (server side) 2020/07/24 10:50:00 INFO : file1: Copied (new) 2020/07/24 10:50:00 DEBUG : file1: vfs cache: fingerprint now "5,2020-07-24 10:49:58 +0000 UTC" 2020/07/24 10:50:00 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:50:00 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:00 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:50:00 DEBUG : dir: Looking for writers 2020/07/24 10:50:00 DEBUG : : Looking for writers 2020/07/24 10:50:00 DEBUG : dir: reading active writers 2020/07/24 10:50:00 DEBUG : file1: reading active writers 2020/07/24 10:50:00 DEBUG : >WaitForWriters: 2020/07/24 10:50:00 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleReleaseWrite (14.15s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:476 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleReleaseWrite Messages: directories === RUN TestRWFileHandleSizeTruncateExisting 2020/07/24 10:50:12 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:50:12 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:50:12 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:50:12 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:50:13 INFO : dir/file1.rclone_chunk.001_z4k7uz: Moved (server side) 2020/07/24 10:50:13 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:50:14 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:50:14 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:50:14 DEBUG : dir/file1(0xc000825d00): openPending: 2020/07/24 10:50:14 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:50:14 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:50:14 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:14 DEBUG : dir/file1(0xc000825d00): >openPending: err= 2020/07/24 10:50:14 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:50:14 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:50:14 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:50:14 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:50:14 DEBUG : dir/file1(0xc000825d00): _writeAt: size=5, off=0 2020/07/24 10:50:14 DEBUG : dir/file1(0xc000825d00): >_writeAt: n=5, err= 2020/07/24 10:50:14 DEBUG : dir/file1(0xc000825d00): close: 2020/07/24 10:50:14 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true 2020/07/24 10:50:14 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:50:14.173759429 +0000 UTC m=+317.170499795 2020/07/24 10:50:14 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:50:14 DEBUG : dir/file1(0xc000825d00): >close: err= 2020/07/24 10:50:14 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:50:14 DEBUG : dir: Looking for writers 2020/07/24 10:50:14 DEBUG : file1: reading active writers 2020/07/24 10:50:14 DEBUG : : Looking for writers 2020/07/24 10:50:14 DEBUG : dir: reading active writers 2020/07/24 10:50:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:50:14 DEBUG : dir: Looking for writers 2020/07/24 10:50:14 DEBUG : file1: reading active writers 2020/07/24 10:50:14 DEBUG : : Looking for writers 2020/07/24 10:50:14 DEBUG : dir: reading active writers 2020/07/24 10:50:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:50:14 DEBUG : dir: Looking for writers 2020/07/24 10:50:14 DEBUG : file1: reading active writers 2020/07/24 10:50:14 DEBUG : : Looking for writers 2020/07/24 10:50:14 DEBUG : dir: reading active writers 2020/07/24 10:50:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:50:14 DEBUG : dir: Looking for writers 2020/07/24 10:50:14 DEBUG : file1: reading active writers 2020/07/24 10:50:14 DEBUG : : Looking for writers 2020/07/24 10:50:14 DEBUG : dir: reading active writers 2020/07/24 10:50:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:50:14 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:50:14 DEBUG : dir: Looking for writers 2020/07/24 10:50:14 DEBUG : file1: reading active writers 2020/07/24 10:50:14 DEBUG : : Looking for writers 2020/07/24 10:50:14 DEBUG : dir: reading active writers 2020/07/24 10:50:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:50:14 DEBUG : dir: Looking for writers 2020/07/24 10:50:14 DEBUG : file1: reading active writers 2020/07/24 10:50:14 DEBUG : : Looking for writers 2020/07/24 10:50:14 DEBUG : dir: reading active writers 2020/07/24 10:50:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:50:14 DEBUG : dir: Looking for writers 2020/07/24 10:50:14 DEBUG : file1: reading active writers 2020/07/24 10:50:14 DEBUG : : Looking for writers 2020/07/24 10:50:14 DEBUG : dir: reading active writers 2020/07/24 10:50:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:50:15 INFO : dir/file1: Deleted 2020/07/24 10:50:15 DEBUG : dir: Looking for writers 2020/07/24 10:50:15 DEBUG : file1: reading active writers 2020/07/24 10:50:15 DEBUG : : Looking for writers 2020/07/24 10:50:15 DEBUG : dir: reading active writers 2020/07/24 10:50:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:50:15 INFO : dir/file1.rclone_chunk.001_z4k9h8: Moved (server side) 2020/07/24 10:50:15 INFO : dir/file1: Copied (replaced existing) 2020/07/24 10:50:15 DEBUG : dir/file1: vfs cache: fingerprint now "5,2020-07-24 10:50:14 +0000 UTC" 2020/07/24 10:50:15 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/07/24 10:50:15 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:15 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/07/24 10:50:16 DEBUG : dir: Looking for writers 2020/07/24 10:50:16 DEBUG : file1: reading active writers 2020/07/24 10:50:16 DEBUG : : Looking for writers 2020/07/24 10:50:16 DEBUG : dir: reading active writers 2020/07/24 10:50:16 DEBUG : >WaitForWriters: 2020/07/24 10:50:16 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleSizeTruncateExisting (15.57s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:508 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleSizeTruncateExisting Messages: directories === RUN TestRWFileHandleSizeCreateExisting 2020/07/24 10:50:28 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:50:28 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:50:28 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:50:28 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:50:29 INFO : dir/file1.rclone_chunk.001_z4knql: Moved (server side) 2020/07/24 10:50:29 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:50:29 DEBUG : dir/file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:50:29 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:50:29 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:50:29 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:29 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:50:29 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:50:29 DEBUG : dir/file1(0xc000825980): _writeAt: size=5, off=0 2020/07/24 10:50:29 DEBUG : dir/file1(0xc000825980): openPending: 2020/07/24 10:50:29 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:50:29 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:50:29 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:29 DEBUG : dir/file1(0xc000825980): >openPending: err= 2020/07/24 10:50:29 DEBUG : dir/file1(0xc000825980): >_writeAt: n=5, err= 2020/07/24 10:50:29 DEBUG : dir/file1(0xc000825980): _writeAt: size=15, off=5 2020/07/24 10:50:29 DEBUG : dir/file1(0xc000825980): >_writeAt: n=15, err= 2020/07/24 10:50:29 DEBUG : dir/file1(0xc000825980): close: 2020/07/24 10:50:29 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [{Pos:0 Size:20}] - present true 2020/07/24 10:50:29 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:50:29.713705062 +0000 UTC m=+332.710445399 2020/07/24 10:50:29 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:50:29 DEBUG : dir/file1(0xc000825980): >close: err= 2020/07/24 10:50:29 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:50:29 DEBUG : dir: Looking for writers 2020/07/24 10:50:29 DEBUG : file1: reading active writers 2020/07/24 10:50:29 DEBUG : : Looking for writers 2020/07/24 10:50:29 DEBUG : dir: reading active writers 2020/07/24 10:50:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:50:29 DEBUG : dir: Looking for writers 2020/07/24 10:50:29 DEBUG : file1: reading active writers 2020/07/24 10:50:29 DEBUG : : Looking for writers 2020/07/24 10:50:29 DEBUG : dir: reading active writers 2020/07/24 10:50:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:50:29 DEBUG : dir: Looking for writers 2020/07/24 10:50:29 DEBUG : file1: reading active writers 2020/07/24 10:50:29 DEBUG : : Looking for writers 2020/07/24 10:50:29 DEBUG : dir: reading active writers 2020/07/24 10:50:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:50:29 DEBUG : dir: Looking for writers 2020/07/24 10:50:29 DEBUG : file1: reading active writers 2020/07/24 10:50:29 DEBUG : : Looking for writers 2020/07/24 10:50:29 DEBUG : dir: reading active writers 2020/07/24 10:50:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:50:29 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:50:29 DEBUG : dir: Looking for writers 2020/07/24 10:50:29 DEBUG : file1: reading active writers 2020/07/24 10:50:29 DEBUG : : Looking for writers 2020/07/24 10:50:29 DEBUG : dir: reading active writers 2020/07/24 10:50:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:50:30 DEBUG : dir: Looking for writers 2020/07/24 10:50:30 DEBUG : file1: reading active writers 2020/07/24 10:50:30 DEBUG : : Looking for writers 2020/07/24 10:50:30 DEBUG : dir: reading active writers 2020/07/24 10:50:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:50:30 DEBUG : dir: Looking for writers 2020/07/24 10:50:30 DEBUG : file1: reading active writers 2020/07/24 10:50:30 DEBUG : : Looking for writers 2020/07/24 10:50:30 DEBUG : dir: reading active writers 2020/07/24 10:50:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:50:30 INFO : dir/file1: Deleted 2020/07/24 10:50:30 DEBUG : dir: Looking for writers 2020/07/24 10:50:30 DEBUG : file1: reading active writers 2020/07/24 10:50:30 DEBUG : : Looking for writers 2020/07/24 10:50:30 DEBUG : dir: reading active writers 2020/07/24 10:50:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:50:30 INFO : dir/file1.rclone_chunk.001_z4kokq: Moved (server side) 2020/07/24 10:50:30 INFO : dir/file1: Copied (replaced existing) 2020/07/24 10:50:30 DEBUG : dir/file1: vfs cache: fingerprint now "20,2020-07-24 10:50:29 +0000 UTC" 2020/07/24 10:50:30 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/07/24 10:50:30 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:30 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/07/24 10:50:31 DEBUG : dir: Looking for writers 2020/07/24 10:50:31 DEBUG : file1: reading active writers 2020/07/24 10:50:31 DEBUG : : Looking for writers 2020/07/24 10:50:31 DEBUG : dir: reading active writers 2020/07/24 10:50:31 DEBUG : >WaitForWriters: 2020/07/24 10:50:31 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleSizeCreateExisting (15.50s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:538 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleSizeCreateExisting Messages: directories === RUN TestRWFileHandleSizeCreateNew 2020/07/24 10:50:43 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:50:43 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:50:43 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:50:43 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:50:43 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:50:43 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:50:43 DEBUG : file1: newRWFileHandle: 2020/07/24 10:50:43 DEBUG : file1(0xc000491f00): openPending: 2020/07/24 10:50:43 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:50:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:43 DEBUG : file1(0xc000491f00): >openPending: err= 2020/07/24 10:50:43 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:50:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:43 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:50:43 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:50:43 DEBUG : file1(0xc000491f00): _writeAt: size=5, off=0 2020/07/24 10:50:43 DEBUG : file1(0xc000491f00): >_writeAt: n=5, err= 2020/07/24 10:50:43 DEBUG : file1(0xc000491f00): close: 2020/07/24 10:50:43 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:50:43.84778356 +0000 UTC m=+346.844523917 2020/07/24 10:50:43 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:50:43 DEBUG : file1(0xc000491f00): >close: err= 2020/07/24 10:50:43 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:50:43 DEBUG : dir: Looking for writers 2020/07/24 10:50:43 DEBUG : : Looking for writers 2020/07/24 10:50:43 DEBUG : dir: reading active writers 2020/07/24 10:50:43 DEBUG : file1: reading active writers 2020/07/24 10:50:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:50:43 DEBUG : dir: Looking for writers 2020/07/24 10:50:43 DEBUG : : Looking for writers 2020/07/24 10:50:43 DEBUG : dir: reading active writers 2020/07/24 10:50:43 DEBUG : file1: reading active writers 2020/07/24 10:50:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:50:43 DEBUG : dir: Looking for writers 2020/07/24 10:50:43 DEBUG : : Looking for writers 2020/07/24 10:50:43 DEBUG : file1: reading active writers 2020/07/24 10:50:43 DEBUG : dir: reading active writers 2020/07/24 10:50:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:50:43 DEBUG : dir: Looking for writers 2020/07/24 10:50:43 DEBUG : : Looking for writers 2020/07/24 10:50:43 DEBUG : dir: reading active writers 2020/07/24 10:50:43 DEBUG : file1: reading active writers 2020/07/24 10:50:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:50:43 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:50:43 DEBUG : dir: Looking for writers 2020/07/24 10:50:43 DEBUG : : Looking for writers 2020/07/24 10:50:43 DEBUG : dir: reading active writers 2020/07/24 10:50:43 DEBUG : file1: reading active writers 2020/07/24 10:50:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:50:44 DEBUG : dir: Looking for writers 2020/07/24 10:50:44 DEBUG : : Looking for writers 2020/07/24 10:50:44 DEBUG : file1: reading active writers 2020/07/24 10:50:44 DEBUG : dir: reading active writers 2020/07/24 10:50:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:50:44 DEBUG : dir: Looking for writers 2020/07/24 10:50:44 DEBUG : : Looking for writers 2020/07/24 10:50:44 DEBUG : dir: reading active writers 2020/07/24 10:50:44 DEBUG : file1: reading active writers 2020/07/24 10:50:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:50:44 INFO : file1.rclone_chunk.001_z4l299: Moved (server side) 2020/07/24 10:50:44 INFO : file1: Copied (new) 2020/07/24 10:50:44 DEBUG : file1: vfs cache: fingerprint now "5,2020-07-24 10:50:43 +0000 UTC" 2020/07/24 10:50:44 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:50:44 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:50:44 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:50:45 DEBUG : dir: Looking for writers 2020/07/24 10:50:45 DEBUG : : Looking for writers 2020/07/24 10:50:45 DEBUG : dir: reading active writers 2020/07/24 10:50:45 DEBUG : file1: reading active writers 2020/07/24 10:50:45 DEBUG : >WaitForWriters: 2020/07/24 10:50:45 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleSizeCreateNew (13.29s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:563 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleSizeCreateNew Messages: directories === RUN TestRWFileHandleOpenTests 2020/07/24 10:50:56 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:50:56 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:50:56 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:50:56 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:50:57 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:50:57 DEBUG : : Looking for writers 2020/07/24 10:50:57 DEBUG : >WaitForWriters: 2020/07/24 10:50:57 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleOpenTests (11.64s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:657 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleOpenTests Messages: directories === RUN TestRWFileModTimeWithOpenWriters 2020/07/24 10:51:08 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:51:08 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:51:08 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:51:08 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:51:08 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:51:08 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:51:08 DEBUG : file1: newRWFileHandle: 2020/07/24 10:51:08 DEBUG : file1(0xc000824540): openPending: 2020/07/24 10:51:08 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:51:08 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:51:08 DEBUG : file1(0xc000824540): >openPending: err= 2020/07/24 10:51:08 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:51:08 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:51:08 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:51:08 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:51:09 INFO : time_test.rclone_chunk.001_z4lr9r: Moved (server side) 2020/07/24 10:51:10 DEBUG : Can set mod time: true 2020/07/24 10:51:10 DEBUG : file1(0xc000824540): _writeAt: size=2, off=0 2020/07/24 10:51:10 DEBUG : file1(0xc000824540): >_writeAt: n=2, err= 2020/07/24 10:51:10 DEBUG : file1(0xc000824540): RWFileHandle.Flush 2020/07/24 10:51:10 DEBUG : file1(0xc000824540): RWFileHandle.Release 2020/07/24 10:51:10 DEBUG : file1(0xc000824540): close: 2020/07/24 10:51:10 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:51:10.295367749 +0000 UTC m=+373.292108105 2020/07/24 10:51:10 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:51:10 DEBUG : file1(0xc000824540): >close: err= 2020/07/24 10:51:10 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:51:10 DEBUG : dir: Looking for writers 2020/07/24 10:51:10 DEBUG : : Looking for writers 2020/07/24 10:51:10 DEBUG : dir: reading active writers 2020/07/24 10:51:10 DEBUG : file1: reading active writers 2020/07/24 10:51:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:51:10 DEBUG : dir: Looking for writers 2020/07/24 10:51:10 DEBUG : : Looking for writers 2020/07/24 10:51:10 DEBUG : dir: reading active writers 2020/07/24 10:51:10 DEBUG : file1: reading active writers 2020/07/24 10:51:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:51:10 DEBUG : dir: Looking for writers 2020/07/24 10:51:10 DEBUG : : Looking for writers 2020/07/24 10:51:10 DEBUG : dir: reading active writers 2020/07/24 10:51:10 DEBUG : file1: reading active writers 2020/07/24 10:51:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:51:10 DEBUG : dir: Looking for writers 2020/07/24 10:51:10 DEBUG : : Looking for writers 2020/07/24 10:51:10 DEBUG : dir: reading active writers 2020/07/24 10:51:10 DEBUG : file1: reading active writers 2020/07/24 10:51:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:51:10 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:51:10 DEBUG : dir: Looking for writers 2020/07/24 10:51:10 DEBUG : : Looking for writers 2020/07/24 10:51:10 DEBUG : dir: reading active writers 2020/07/24 10:51:10 DEBUG : file1: reading active writers 2020/07/24 10:51:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:51:10 DEBUG : dir: Looking for writers 2020/07/24 10:51:10 DEBUG : : Looking for writers 2020/07/24 10:51:10 DEBUG : dir: reading active writers 2020/07/24 10:51:10 DEBUG : file1: reading active writers 2020/07/24 10:51:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:51:10 DEBUG : dir: Looking for writers 2020/07/24 10:51:10 DEBUG : : Looking for writers 2020/07/24 10:51:10 DEBUG : dir: reading active writers 2020/07/24 10:51:10 DEBUG : file1: reading active writers 2020/07/24 10:51:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:51:11 INFO : file1.rclone_chunk.001_z4ltco: Moved (server side) 2020/07/24 10:51:11 INFO : file1: Copied (new) 2020/07/24 10:51:11 DEBUG : file1: vfs cache: fingerprint now "2,2020-07-24 10:51:10 +0000 UTC" 2020/07/24 10:51:11 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:51:11 DEBUG : dir: Looking for writers 2020/07/24 10:51:11 DEBUG : : Looking for writers 2020/07/24 10:51:11 DEBUG : file1: reading active writers 2020/07/24 10:51:11 DEBUG : dir: reading active writers 2020/07/24 10:51:11 DEBUG : >WaitForWriters: 2020/07/24 10:51:11 DEBUG : file1: File._applyPendingModTime OK 2020/07/24 10:51:11 DEBUG : file1: vfs cache: fingerprint now "2,2012-11-18 17:32:31 +0000 UTC" 2020/07/24 10:51:11 DEBUG : file1: vfs cache: setting modification time to 2012-11-18 17:32:31 +0000 UTC 2020/07/24 10:51:11 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:51:11 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:51:11 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:51:11 DEBUG : dir: Looking for writers 2020/07/24 10:51:11 DEBUG : : Looking for writers 2020/07/24 10:51:11 DEBUG : dir: reading active writers 2020/07/24 10:51:11 DEBUG : file1: reading active writers 2020/07/24 10:51:11 DEBUG : >WaitForWriters: 2020/07/24 10:51:11 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileModTimeWithOpenWriters (15.04s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:694 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileModTimeWithOpenWriters Messages: directories === RUN TestRWCacheRename 2020/07/24 10:51:23 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:51:23 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:51:23 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerMailru/rclone-test-joxudam8modowex8haxaroc8" 2020/07/24 10:51:23 DEBUG : rename_me: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:51:23 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:51:23 DEBUG : rename_me: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:51:23 DEBUG : rename_me: newRWFileHandle: 2020/07/24 10:51:23 DEBUG : rename_me(0xc000825b80): openPending: 2020/07/24 10:51:23 DEBUG : rename_me: vfs cache: truncate to size=0 2020/07/24 10:51:23 DEBUG : : Added virtual directory entry vAdd: "rename_me" 2020/07/24 10:51:23 DEBUG : rename_me(0xc000825b80): >openPending: err= 2020/07/24 10:51:23 DEBUG : rename_me: >newRWFileHandle: err= 2020/07/24 10:51:23 DEBUG : : Added virtual directory entry vAdd: "rename_me" 2020/07/24 10:51:23 DEBUG : rename_me: >Open: fd=rename_me (rw), err= 2020/07/24 10:51:23 DEBUG : rename_me: >OpenFile: fd=rename_me (rw), err= 2020/07/24 10:51:23 DEBUG : rename_me(0xc000825b80): _writeAt: size=5, off=0 2020/07/24 10:51:23 DEBUG : rename_me(0xc000825b80): >_writeAt: n=5, err= 2020/07/24 10:51:23 DEBUG : rename_me(0xc000825b80): close: 2020/07/24 10:51:23 DEBUG : rename_me: vfs cache: setting modification time to 2020-07-24 10:51:23.819873579 +0000 UTC m=+386.816613918 2020/07/24 10:51:23 INFO : rename_me: vfs cache: queuing for upload in 100ms 2020/07/24 10:51:23 DEBUG : rename_me(0xc000825b80): >close: err= 2020/07/24 10:51:23 INFO : rename_me: vfs cache: renamed in cache to "i_was_renamed" 2020/07/24 10:51:23 DEBUG : i_was_renamed: Updating file with 0xc0002f6900 2020/07/24 10:51:23 DEBUG : : Added virtual directory entry vDel: "rename_me" 2020/07/24 10:51:23 DEBUG : : Added virtual directory entry vAdd: "i_was_renamed" 2020/07/24 10:51:23 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:51:23 DEBUG : dir: Looking for writers 2020/07/24 10:51:23 DEBUG : : Looking for writers 2020/07/24 10:51:23 DEBUG : dir: reading active writers 2020/07/24 10:51:23 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:51:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:51:23 DEBUG : dir: Looking for writers 2020/07/24 10:51:23 DEBUG : : Looking for writers 2020/07/24 10:51:23 DEBUG : dir: reading active writers 2020/07/24 10:51:23 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:51:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:51:23 DEBUG : dir: Looking for writers 2020/07/24 10:51:23 DEBUG : : Looking for writers 2020/07/24 10:51:23 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:51:23 DEBUG : dir: reading active writers 2020/07/24 10:51:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:51:23 DEBUG : dir: Looking for writers 2020/07/24 10:51:23 DEBUG : : Looking for writers 2020/07/24 10:51:23 DEBUG : dir: reading active writers 2020/07/24 10:51:23 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:51:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:51:23 DEBUG : i_was_renamed: vfs cache: starting upload 2020/07/24 10:51:23 DEBUG : dir: Looking for writers 2020/07/24 10:51:23 DEBUG : : Looking for writers 2020/07/24 10:51:23 DEBUG : dir: reading active writers 2020/07/24 10:51:23 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:51:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:51:24 DEBUG : dir: Looking for writers 2020/07/24 10:51:24 DEBUG : : Looking for writers 2020/07/24 10:51:24 DEBUG : dir: reading active writers 2020/07/24 10:51:24 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:51:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:51:24 DEBUG : dir: Looking for writers 2020/07/24 10:51:24 DEBUG : : Looking for writers 2020/07/24 10:51:24 DEBUG : dir: reading active writers 2020/07/24 10:51:24 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:51:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:51:24 INFO : i_was_renamed.rclone_chunk.001_z4m6kb: Moved (server side) 2020/07/24 10:51:24 INFO : i_was_renamed: Copied (new) 2020/07/24 10:51:24 DEBUG : i_was_renamed: vfs cache: fingerprint now "5,2020-07-24 10:51:23 +0000 UTC" 2020/07/24 10:51:24 DEBUG : i_was_renamed: vfs cache: writeback object to VFS layer 2020/07/24 10:51:24 DEBUG : : Added virtual directory entry vAdd: "i_was_renamed" 2020/07/24 10:51:24 INFO : i_was_renamed: vfs cache: upload succeeded try #1 2020/07/24 10:51:25 DEBUG : dir: Looking for writers 2020/07/24 10:51:25 DEBUG : : Looking for writers 2020/07/24 10:51:25 DEBUG : dir: reading active writers 2020/07/24 10:51:25 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:51:25 DEBUG : >WaitForWriters: 2020/07/24 10:51:25 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWCacheRename (13.25s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:726 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWCacheRename Messages: directories === RUN TestCaseSensitivity --- FAIL: TestCaseSensitivity (11.63s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" vfs_case_test.go:19: Can't test case sensitivity - this remote is officially not case-sensitive run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 panic.go:563 testing.go:742 testing.go:722 vfs_case_test.go:19 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestCaseSensitivity Messages: directories === RUN TestVFSNew 2020/07/24 10:51:48 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:51:48 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': Re-using VFS from active cache 2020/07/24 10:51:48 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:51:48 DEBUG : : Looking for writers 2020/07/24 10:51:48 DEBUG : >WaitForWriters: --- FAIL: TestVFSNew (11.57s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:161 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSNew Messages: directories === RUN TestVFSNewWithOpts 2020/07/24 10:52:00 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:52:00 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:52:00 DEBUG : : Looking for writers 2020/07/24 10:52:00 DEBUG : >WaitForWriters: --- FAIL: TestVFSNewWithOpts (11.78s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:177 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSNewWithOpts Messages: directories === RUN TestVFSRoot 2020/07/24 10:52:11 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:52:11 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:52:11 DEBUG : : Looking for writers 2020/07/24 10:52:11 DEBUG : >WaitForWriters: --- FAIL: TestVFSRoot (11.74s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:189 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSRoot Messages: directories === RUN TestVFSStat 2020/07/24 10:52:23 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:52:24 INFO : file1.rclone_chunk.001_z4nufv: Moved (server side) 2020/07/24 10:52:25 INFO : dir/file2.rclone_chunk.001_z4nvk6: Moved (server side) 2020/07/24 10:52:25 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:52:25 DEBUG : dir: Looking for writers 2020/07/24 10:52:25 DEBUG : file2: reading active writers 2020/07/24 10:52:25 DEBUG : : Looking for writers 2020/07/24 10:52:25 DEBUG : dir: reading active writers 2020/07/24 10:52:25 DEBUG : file1: reading active writers 2020/07/24 10:52:25 DEBUG : >WaitForWriters: --- FAIL: TestVFSStat (14.81s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:225 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSStat Messages: directories === RUN TestVFSStatParent 2020/07/24 10:52:38 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:52:39 INFO : file1.rclone_chunk.001_z4o9so: Moved (server side) 2020/07/24 10:52:40 INFO : dir/file2.rclone_chunk.001_z4oadn: Moved (server side) 2020/07/24 10:52:40 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:52:40 DEBUG : dir: Looking for writers 2020/07/24 10:52:40 DEBUG : : Looking for writers 2020/07/24 10:52:40 DEBUG : dir: reading active writers 2020/07/24 10:52:40 DEBUG : file1: reading active writers 2020/07/24 10:52:40 DEBUG : >WaitForWriters: --- FAIL: TestVFSStatParent (14.07s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:258 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSStatParent Messages: directories === RUN TestVFSOpenFile 2020/07/24 10:52:52 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:52:53 INFO : file1.rclone_chunk.001_z4on1s: Moved (server side) 2020/07/24 10:52:54 INFO : dir/file2.rclone_chunk.001_z4oo0r: Moved (server side) 2020/07/24 10:52:54 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:52:54 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:52:54 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:52:54 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:52:54 DEBUG : dir: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:52:54 DEBUG : dir: >OpenFile: fd=dir/ (r), err= 2020/07/24 10:52:54 DEBUG : dir/new_file.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:52:54 DEBUG : dir/new_file.txt: >OpenFile: fd=, err=file does not exist 2020/07/24 10:52:54 DEBUG : dir/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:52:54 DEBUG : dir/new_file.txt: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:52:54 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:52:54 DEBUG : dir/new_file.txt: >Open: fd=dir/new_file.txt (w), err= 2020/07/24 10:52:54 DEBUG : dir/new_file.txt: >OpenFile: fd=dir/new_file.txt (w), err= 2020/07/24 10:52:54 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:52:54 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:52:55 INFO : dir/new_file.txt.rclone_chunk.001_z4opz6: Moved (server side) 2020/07/24 10:52:55 INFO : dir/new_file.txt: Copied (new) 2020/07/24 10:52:55 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:52:55 DEBUG : not found/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:52:55 DEBUG : not found/new_file.txt: >OpenFile: fd=, err=file does not exist 2020/07/24 10:52:55 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:52:55 DEBUG : dir: Looking for writers 2020/07/24 10:52:55 DEBUG : file2: reading active writers 2020/07/24 10:52:55 DEBUG : new_file.txt: reading active writers 2020/07/24 10:52:55 DEBUG : : Looking for writers 2020/07/24 10:52:55 DEBUG : dir: reading active writers 2020/07/24 10:52:55 DEBUG : file1: reading active writers 2020/07/24 10:52:55 DEBUG : >WaitForWriters: --- FAIL: TestVFSOpenFile (15.61s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:293 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSOpenFile Messages: directories === RUN TestVFSRename 2020/07/24 10:53:08 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:53:09 INFO : dir/file2.rclone_chunk.001_z4p3n5: Moved (server side) 2020/07/24 10:53:09 DEBUG : dir/file2: move non-chunked object... 2020/07/24 10:53:09 INFO : dir/file2: Moved (server side) 2020/07/24 10:53:09 INFO : dir/file2: Moved (server side) 2020/07/24 10:53:09 DEBUG : dir/file1: Updating file with dir/file1 0xc00037e480 2020/07/24 10:53:09 DEBUG : dir: Added virtual directory entry vDel: "file2" 2020/07/24 10:53:09 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:10 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:53:10 INFO : dir/file1: Moved (server side) 2020/07/24 10:53:10 INFO : dir/file1: Moved (server side) 2020/07/24 10:53:10 DEBUG : file0: Updating file with file0 0xc00037e480 2020/07/24 10:53:10 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:53:10 DEBUG : : Added virtual directory entry vAdd: "file0" 2020/07/24 10:53:10 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:53:10 DEBUG : dir: Looking for writers 2020/07/24 10:53:10 DEBUG : : Looking for writers 2020/07/24 10:53:10 DEBUG : dir: reading active writers 2020/07/24 10:53:10 DEBUG : file0: reading active writers 2020/07/24 10:53:10 DEBUG : >WaitForWriters: --- FAIL: TestVFSRename (14.47s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:322 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSRename Messages: directories === RUN TestVFSStatfs 2020/07/24 10:53:22 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:53:22 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:53:22 DEBUG : : Looking for writers 2020/07/24 10:53:22 DEBUG : >WaitForWriters: --- FAIL: TestVFSStatfs (12.07s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:373 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSStatfs Messages: directories === RUN TestWriteFileHandleMethods 2020/07/24 10:53:34 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:53:34 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:53:34 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:53:34 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:34 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:53:34 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:53:34 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:34 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2020/07/24 10:53:34 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2020/07/24 10:53:34 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2020/07/24 10:53:34 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (5 bytes), uploading instead of streaming 2020/07/24 10:53:35 INFO : file1.rclone_chunk.001_z4pt67: Moved (server side) 2020/07/24 10:53:35 INFO : file1: Copied (new) 2020/07/24 10:53:35 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:43 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:53:43 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:53:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:43 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:53:43 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:53:43 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:53:43 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:53:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:43 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:53:43 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:53:43 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes 2020/07/24 10:53:43 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:53:43 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/07/24 10:53:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:43 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:53:43 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:53:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:43 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:53:44 INFO : file1: Deleted 2020/07/24 10:53:44 INFO : file1.rclone_chunk.001_z4q2bw: Moved (server side) 2020/07/24 10:53:44 INFO : file1: Copied (new) 2020/07/24 10:53:44 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:44 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:53:44 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/07/24 10:53:44 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:44 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:53:44 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:53:44 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:44 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (7 bytes), uploading instead of streaming 2020/07/24 10:53:45 INFO : file1: Deleted 2020/07/24 10:53:46 INFO : file1.rclone_chunk.001_z4q305: Moved (server side) 2020/07/24 10:53:46 INFO : file1: Copied (new) 2020/07/24 10:53:46 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:46 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:53:46 DEBUG : dir: Looking for writers 2020/07/24 10:53:46 DEBUG : : Looking for writers 2020/07/24 10:53:46 DEBUG : file1: reading active writers 2020/07/24 10:53:46 DEBUG : dir: reading active writers 2020/07/24 10:53:46 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleMethods (23.30s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:93 Error: Not equal: expected: []string{"file1,5,false"} actual : []string{"dir,0,true", "file1,5,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,5,false" Test: TestWriteFileHandleMethods fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 write_test.go:97 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleMethods Messages: directories dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:104 Error: Not equal: expected: []string{"file1,5,false"} actual : []string{"dir,0,true", "file1,5,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,5,false" Test: TestWriteFileHandleMethods dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:113 Error: Not equal: expected: []string{"file1,5,false"} actual : []string{"dir,0,true", "file1,5,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,5,false" Test: TestWriteFileHandleMethods dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:122 Error: Not equal: expected: []string{"file1,0,false"} actual : []string{"dir,0,true", "file1,0,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,0,false" Test: TestWriteFileHandleMethods dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:131 Error: Not equal: expected: []string{"file1,7,false"} actual : []string{"dir,0,true", "file1,7,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,7,false" Test: TestWriteFileHandleMethods run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:132 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleMethods Messages: directories === RUN TestWriteFileHandleWriteAt 2020/07/24 10:53:57 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:53:57 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:53:58 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:53:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:58 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:53:58 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:53:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:58 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2020/07/24 10:53:59 DEBUG : file1: aborting in-sequence write wait, off=100 2020/07/24 10:53:59 DEBUG : file1: failed to wait for in-sequence write to 100 2020/07/24 10:53:59 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2020/07/24 10:53:59 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (11 bytes), uploading instead of streaming 2020/07/24 10:53:59 INFO : file1.rclone_chunk.001_z4qing: Moved (server side) 2020/07/24 10:53:59 INFO : file1: Copied (new) 2020/07/24 10:53:59 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:53:59 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor 2020/07/24 10:54:07 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:54:07 DEBUG : dir: Looking for writers 2020/07/24 10:54:07 DEBUG : : Looking for writers 2020/07/24 10:54:07 DEBUG : dir: reading active writers 2020/07/24 10:54:07 DEBUG : file1: reading active writers 2020/07/24 10:54:07 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleWriteAt (21.52s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:172 Error: Not equal: expected: []string{"file1,11,false"} actual : []string{"dir,0,true", "file1,11,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=14) "file1,11,false" Test: TestWriteFileHandleWriteAt fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 write_test.go:176 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleWriteAt Messages: directories run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:177 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleWriteAt Messages: directories === RUN TestWriteFileHandleFlush 2020/07/24 10:54:19 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:54:19 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:54:19 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:54:19 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:19 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:54:19 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:54:19 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2020/07/24 10:54:19 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:19 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (5 bytes), uploading instead of streaming 2020/07/24 10:54:20 INFO : file1.rclone_chunk.001_z4r2xn: Moved (server side) 2020/07/24 10:54:20 INFO : file1: Copied (new) 2020/07/24 10:54:20 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:20 DEBUG : file1: WriteFileHandle.Flush nothing to do 2020/07/24 10:54:20 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:54:20 DEBUG : dir: Looking for writers 2020/07/24 10:54:20 DEBUG : : Looking for writers 2020/07/24 10:54:20 DEBUG : dir: reading active writers 2020/07/24 10:54:20 DEBUG : file1: reading active writers 2020/07/24 10:54:20 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleFlush (13.47s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:189 Error: Not equal: expected: []string{"file1,0,false"} actual : []string{"dir,0,true", "file1,0,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,0,false" Test: TestWriteFileHandleFlush dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:209 Error: Not equal: expected: []string{"file1,5,false"} actual : []string{"dir,0,true", "file1,5,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,5,false" Test: TestWriteFileHandleFlush run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:210 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleFlush Messages: directories === RUN TestWriteFileHandleRelease 2020/07/24 10:54:32 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:54:32 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:54:33 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:54:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:33 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:54:33 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:54:33 DEBUG : file1: WriteFileHandle.Release closing 2020/07/24 10:54:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:33 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:54:33 INFO : file1.rclone_chunk.001_z4rghi: Moved (server side) 2020/07/24 10:54:33 INFO : file1: Copied (new) 2020/07/24 10:54:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:33 DEBUG : file1: WriteFileHandle.Release nothing to do 2020/07/24 10:54:33 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:54:33 DEBUG : dir: Looking for writers 2020/07/24 10:54:33 DEBUG : : Looking for writers 2020/07/24 10:54:33 DEBUG : dir: reading active writers 2020/07/24 10:54:33 DEBUG : file1: reading active writers 2020/07/24 10:54:33 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleRelease (12.78s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:229 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleRelease Messages: directories === RUN TestWriteFileModTimeWithOpenWriters 2020/07/24 10:54:45 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:54:45 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:54:45 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:54:45 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:45 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:54:45 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:54:45 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:45 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (2 bytes), uploading instead of streaming 2020/07/24 10:54:46 INFO : file1.rclone_chunk.001_z4rs9t: Moved (server side) 2020/07/24 10:54:46 INFO : file1: Copied (new) 2020/07/24 10:54:46 DEBUG : file1: File._applyPendingModTime OK 2020/07/24 10:54:46 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:46 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:54:46 DEBUG : dir: Looking for writers 2020/07/24 10:54:46 DEBUG : : Looking for writers 2020/07/24 10:54:46 DEBUG : dir: reading active writers 2020/07/24 10:54:46 DEBUG : file1: reading active writers 2020/07/24 10:54:46 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileModTimeWithOpenWriters (12.71s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:286 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileModTimeWithOpenWriters Messages: directories === RUN TestFileReadAtZeroLength 2020/07/24 10:54:58 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:54:58 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:54:58 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:54:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:58 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:54:58 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:54:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:58 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:54:59 INFO : file1.rclone_chunk.001_z4s5l6: Moved (server side) 2020/07/24 10:54:59 INFO : file1: Copied (new) 2020/07/24 10:54:59 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:54:59 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/07/24 10:54:59 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:54:59 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:54:59 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:54:59 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:54:59 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Switch file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/, expiry "2020-07-24T10:57:59.657843171Z" 2020/07/24 10:55:00 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2020/07/24 10:55:00 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/07/24 10:55:00 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:55:00 DEBUG : dir: Looking for writers 2020/07/24 10:55:00 DEBUG : : Looking for writers 2020/07/24 10:55:00 DEBUG : dir: reading active writers 2020/07/24 10:55:00 DEBUG : file1: reading active writers 2020/07/24 10:55:00 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtZeroLength (13.51s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:322 write_test.go:325 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileReadAtZeroLength Messages: directories === RUN TestFileReadAtNonZeroLength 2020/07/24 10:55:11 INFO : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': poll-interval is not supported by this remote 2020/07/24 10:55:11 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:55:12 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:55:12 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:55:12 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:55:12 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:55:12 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:55:12 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': File to upload is small (100 bytes), uploading instead of streaming 2020/07/24 10:55:12 DEBUG : file1.rclone_chunk.001_z4sjpq: Cannot put by hash from source, performing upload 2020/07/24 10:55:12 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: new upload shard: https://cld-upload4.cloud.mail.ru/upload-web/ 2020/07/24 10:55:13 INFO : file1.rclone_chunk.001_z4sjpq: Moved (server side) 2020/07/24 10:55:13 INFO : file1: Copied (new) 2020/07/24 10:55:13 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:55:13 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/07/24 10:55:13 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:55:13 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:55:13 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:55:13 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:55:13 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/07/24 10:55:13 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2020/07/24 10:55:13 DEBUG : [rclone-test-joxudam8modowex8haxaroc8]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/07/24 10:55:13 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:55:13 DEBUG : dir: Looking for writers 2020/07/24 10:55:13 DEBUG : : Looking for writers 2020/07/24 10:55:13 DEBUG : dir: reading active writers 2020/07/24 10:55:13 DEBUG : file1: reading active writers 2020/07/24 10:55:13 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtNonZeroLength (13.41s) run.go:176: Remote "Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8'", Local "Local file system at /tmp/rclone859100847", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:322 write_test.go:329 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileReadAtNonZeroLength Messages: directories FAIL 2020/07/24 10:55:25 DEBUG : Chunked 'TestChunkerMailru:rclone-test-joxudam8modowex8haxaroc8': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerMailru: -verbose -test.run '^(TestCaseSensitivity|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRename|TestRWCacheRename|TestRWFileHandleFlushRead|TestRWFileHandleFlushWrite|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleOpenTests|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleReleaseWrite|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeCreateNew|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestVFSNew|TestVFSNewWithOpts|TestVFSOpenFile|TestVFSRename|TestVFSRoot|TestVFSStat|TestVFSStatParent|TestVFSStatfs|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(full,forceCache=false|minimal,forceCache=true|writes,forceCache=false|writes,forceCache=true)$'" - Finished ERROR in 10m28.648609323s (try 4/5): exit status 1: Failed [TestFileRename/minimal,forceCache=true TestFileRename/writes,forceCache=false TestFileRename/writes,forceCache=true TestFileRename/full,forceCache=false TestRcGetVFS TestReadFileHandleMethods TestReadFileHandleSeek TestReadFileHandleReadAt TestReadFileHandleFlush TestReadFileHandleRelease TestRWFileHandleMethodsRead TestRWFileHandleSeek TestRWFileHandleReadAt TestRWFileHandleFlushRead TestRWFileHandleReleaseRead TestRWFileHandleMethodsWrite TestRWFileHandleWriteAt TestRWFileHandleWriteNoWrite TestRWFileHandleFlushWrite TestRWFileHandleReleaseWrite TestRWFileHandleSizeTruncateExisting TestRWFileHandleSizeCreateExisting TestRWFileHandleSizeCreateNew TestRWFileHandleOpenTests TestRWFileModTimeWithOpenWriters TestRWCacheRename TestCaseSensitivity TestVFSNew TestVFSNewWithOpts TestVFSRoot TestVFSStat TestVFSStatParent TestVFSOpenFile TestVFSRename TestVFSStatfs TestWriteFileHandleMethods TestWriteFileHandleWriteAt TestWriteFileHandleFlush TestWriteFileHandleRelease TestWriteFileModTimeWithOpenWriters TestFileReadAtZeroLength TestFileReadAtNonZeroLength]