"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bBox: -verbose -size-limit 1024 -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 3/5) === RUN TestFileRename === RUN TestFileRename/minimal,forceCache=true 2020/07/24 10:13:41 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:13:41 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:13:41 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:13: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:13:46 INFO : dir/file1.rclone_chunk.001_z2vdgh: Moved (server side) 2020/07/24 10:13:47 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/07/24 10:13:47 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9800): openPending: 2020/07/24 10:13:47 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:13:47 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:13:47 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9800): >openPending: err= 2020/07/24 10:13:47 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:13:47 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:13:47 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:13:47 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9800): _writeAt: size=14, off=0 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9800): >_writeAt: n=14, err= 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9800): close: 2020/07/24 10:13:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:13:47 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:13:47.294161481 +0000 UTC m=+6.773421313 2020/07/24 10:13:47 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9800): >close: err= 2020/07/24 10:13:47 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:13:47 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:13:47 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:13:47 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9b40): _readAt: size=512, off=0 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9b40): openPending: 2020/07/24 10:13:47 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:13:47 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:13:47 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9b40): >openPending: err= 2020/07/24 10:13:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9b40): >_readAt: n=14, err=EOF 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9b40): close: 2020/07/24 10:13:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:13:47 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:13:47.294161481 +0000 UTC m=+6.773421313 2020/07/24 10:13:47 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:13:47 DEBUG : dir/file1(0xc0003f9b40): >close: err= 2020/07/24 10:13:47 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:13:48 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:13:49 INFO : dir/file1: Moved (server side) 2020/07/24 10:13:49 INFO : dir/file1: Moved (server side) 2020/07/24 10:13:49 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 10:13:49 ERROR : dir/file1: Failed to copy: Post https://upload.box.com/api/2.0/files/content: context canceled 2020/07/24 10:13:49 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 10:13:49 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 10:13:49 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:13:49 DEBUG : newLeaf: Updating file with newLeaf 0xc000626180 2020/07/24 10:13:49 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:13:49 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:13:49 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:13:50 DEBUG : newLeaf: move non-chunked object... 2020/07/24 10:13:51 INFO : newLeaf: Moved (server side) 2020/07/24 10:13:51 INFO : newLeaf: Moved (server side) 2020/07/24 10:13:51 DEBUG : newLeaf: vfs cache: cancelling upload 2020/07/24 10:13:51 ERROR : newLeaf: Failed to copy: Post https://upload.box.com/api/2.0/files/content: context canceled 2020/07/24 10:13:51 INFO : newLeaf: vfs cache: upload canceled 2020/07/24 10:13:51 DEBUG : newLeaf: vfs cache: cancelled upload 2020/07/24 10:13:51 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:13:51 DEBUG : dir/file1: Updating file with dir/file1 0xc000626180 2020/07/24 10:13:51 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:13:51 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:13:51 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:13:51 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:13:51 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:13:51 DEBUG : dir/file1(0xc0000923c0): openPending: 2020/07/24 10:13:51 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:13:51 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:13:51 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:13:51 DEBUG : dir/file1(0xc0000923c0): >openPending: err= 2020/07/24 10:13:51 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:13:51 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc00059c8c0 item 1 2020/07/24 10:13:51 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 10:13:51 ERROR : dir/file1: Failed to copy: couldn't list files: Get https://api.box.com/2.0/folders/118648162280/items?fields=type%2Cid%2Csequence_id%2Cetag%2Csha1%2Cname%2Csize%2Ccreated_at%2Cmodified_at%2Ccontent_created_at%2Ccontent_modified_at%2Citem_status%2Cshared_link&limit=1000&offset=0: context canceled 2020/07/24 10:13:51 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 10:13:51 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 10:13:51 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:13:51 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:13:51 DEBUG : dir/file1(0xc0000923c0): _writeAt: size=25, off=0 2020/07/24 10:13:51 DEBUG : dir/file1(0xc0000923c0): >_writeAt: n=25, err= 2020/07/24 10:13:52 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:13:52 INFO : dir/file1: Moved (server side) 2020/07/24 10:13:52 INFO : dir/file1: Moved (server side) 2020/07/24 10:13:52 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:13:52 DEBUG : newLeaf: Updating file with newLeaf 0xc000626180 2020/07/24 10:13:52 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:13:52 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:13:52 DEBUG : newLeaf(0xc0000923c0): close: 2020/07/24 10:13:52 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:13:52 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:13:51.720139953 +0000 UTC m=+11.199399788 2020/07/24 10:13:52 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:13:52 DEBUG : newLeaf(0xc0000923c0): >close: err= 2020/07/24 10:13:52 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:13:52 DEBUG : dir: Looking for writers 2020/07/24 10:13:52 DEBUG : : Looking for writers 2020/07/24 10:13:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:52 DEBUG : dir: reading active writers 2020/07/24 10:13:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:13:52 DEBUG : dir: Looking for writers 2020/07/24 10:13:52 DEBUG : : Looking for writers 2020/07/24 10:13:52 DEBUG : dir: reading active writers 2020/07/24 10:13:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:13:52 DEBUG : dir: Looking for writers 2020/07/24 10:13:52 DEBUG : : Looking for writers 2020/07/24 10:13:52 DEBUG : dir: reading active writers 2020/07/24 10:13:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:13:52 DEBUG : dir: Looking for writers 2020/07/24 10:13:52 DEBUG : : Looking for writers 2020/07/24 10:13:52 DEBUG : dir: reading active writers 2020/07/24 10:13:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:13:52 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:13:52 DEBUG : dir: Looking for writers 2020/07/24 10:13:52 DEBUG : : Looking for writers 2020/07/24 10:13:52 DEBUG : dir: reading active writers 2020/07/24 10:13:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:13:53 DEBUG : dir: Looking for writers 2020/07/24 10:13:53 DEBUG : : Looking for writers 2020/07/24 10:13:53 DEBUG : dir: reading active writers 2020/07/24 10:13:53 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:13:53 DEBUG : dir: Looking for writers 2020/07/24 10:13:53 DEBUG : : Looking for writers 2020/07/24 10:13:53 DEBUG : dir: reading active writers 2020/07/24 10:13:53 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:13:54 DEBUG : dir: Looking for writers 2020/07/24 10:13:54 DEBUG : : Looking for writers 2020/07/24 10:13:54 DEBUG : dir: reading active writers 2020/07/24 10:13:54 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:13:55 DEBUG : dir: Looking for writers 2020/07/24 10:13:55 DEBUG : : Looking for writers 2020/07/24 10:13:55 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:55 DEBUG : dir: reading active writers 2020/07/24 10:13:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:13:56 DEBUG : dir: Looking for writers 2020/07/24 10:13:56 DEBUG : : Looking for writers 2020/07/24 10:13:56 DEBUG : dir: reading active writers 2020/07/24 10:13:56 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:13:56 INFO : newLeaf: Deleted 2020/07/24 10:13:56 INFO : newLeaf.rclone_chunk.001_z2vnbj: Moved (server side) 2020/07/24 10:13:56 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:13:56 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:13:51 +0000 UTC" 2020/07/24 10:13:56 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:13:56 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:13:56 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:13:57 DEBUG : dir: Looking for writers 2020/07/24 10:13:57 DEBUG : : Looking for writers 2020/07/24 10:13:57 DEBUG : dir: reading active writers 2020/07/24 10:13:57 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:57 DEBUG : >WaitForWriters: 2020/07/24 10:13:57 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:13:57 DEBUG : dir: Looking for writers 2020/07/24 10:13:57 DEBUG : : Looking for writers 2020/07/24 10:13:57 DEBUG : dir: reading active writers 2020/07/24 10:13:57 DEBUG : newLeaf: reading active writers 2020/07/24 10:13:57 DEBUG : >WaitForWriters: 2020/07/24 10:13:57 DEBUG : vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=false 2020/07/24 10:14:11 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:14:11 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:14:11 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:14:11 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:14:14 INFO : dir/file1.rclone_chunk.001_z2w67c: Moved (server side) 2020/07/24 10:14:16 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:14:18 INFO : dir/file1: Moved (server side) 2020/07/24 10:14:18 INFO : dir/file1: Moved (server side) 2020/07/24 10:14:18 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:14:18 DEBUG : newLeaf: Updating file with newLeaf 0xc0007203c0 2020/07/24 10:14:18 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:14:18 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:14:19 DEBUG : newLeaf: move non-chunked object... 2020/07/24 10:14:20 INFO : newLeaf: Moved (server side) 2020/07/24 10:14:20 INFO : newLeaf: Moved (server side) 2020/07/24 10:14:20 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:14:20 DEBUG : dir/file1: Updating file with dir/file1 0xc0007203c0 2020/07/24 10:14:20 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:14:20 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:14:21 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:14:21 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:14:21 DEBUG : dir/file1(0xc0003f8c00): openPending: 2020/07/24 10:14:21 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:14:21 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:14:21 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:14:21 DEBUG : dir/file1(0xc0003f8c00): >openPending: err= 2020/07/24 10:14:21 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:14:21 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:14:21 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:14:21 DEBUG : dir/file1(0xc0003f8c00): _writeAt: size=25, off=0 2020/07/24 10:14:21 DEBUG : dir/file1(0xc0003f8c00): >_writeAt: n=25, err= 2020/07/24 10:14:21 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:14:22 INFO : dir/file1: Moved (server side) 2020/07/24 10:14:22 INFO : dir/file1: Moved (server side) 2020/07/24 10:14:22 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:14:22 DEBUG : newLeaf: Updating file with newLeaf 0xc0007203c0 2020/07/24 10:14:22 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:14:22 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:14:22 DEBUG : newLeaf(0xc0003f8c00): close: 2020/07/24 10:14:22 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:14:22 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:14:21.077701736 +0000 UTC m=+40.556961567 2020/07/24 10:14:22 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:14:22 DEBUG : newLeaf(0xc0003f8c00): >close: err= 2020/07/24 10:14:22 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:14:22 DEBUG : dir: Looking for writers 2020/07/24 10:14:22 DEBUG : : Looking for writers 2020/07/24 10:14:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:22 DEBUG : dir: reading active writers 2020/07/24 10:14:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:14:22 DEBUG : dir: Looking for writers 2020/07/24 10:14:22 DEBUG : : Looking for writers 2020/07/24 10:14:22 DEBUG : dir: reading active writers 2020/07/24 10:14:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:14:22 DEBUG : dir: Looking for writers 2020/07/24 10:14:22 DEBUG : : Looking for writers 2020/07/24 10:14:22 DEBUG : dir: reading active writers 2020/07/24 10:14:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:14:22 DEBUG : dir: Looking for writers 2020/07/24 10:14:22 DEBUG : : Looking for writers 2020/07/24 10:14:22 DEBUG : dir: reading active writers 2020/07/24 10:14:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:14:22 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:14:22 DEBUG : dir: Looking for writers 2020/07/24 10:14:22 DEBUG : : Looking for writers 2020/07/24 10:14:22 DEBUG : dir: reading active writers 2020/07/24 10:14:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:14:22 DEBUG : dir: Looking for writers 2020/07/24 10:14:22 DEBUG : : Looking for writers 2020/07/24 10:14:22 DEBUG : dir: reading active writers 2020/07/24 10:14:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:14:22 DEBUG : dir: Looking for writers 2020/07/24 10:14:22 DEBUG : : Looking for writers 2020/07/24 10:14:22 DEBUG : dir: reading active writers 2020/07/24 10:14:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:14:23 DEBUG : dir: Looking for writers 2020/07/24 10:14:23 DEBUG : : Looking for writers 2020/07/24 10:14:23 DEBUG : dir: reading active writers 2020/07/24 10:14:23 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:14:24 DEBUG : dir: Looking for writers 2020/07/24 10:14:24 DEBUG : : Looking for writers 2020/07/24 10:14:24 DEBUG : dir: reading active writers 2020/07/24 10:14:24 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:14:25 DEBUG : dir: Looking for writers 2020/07/24 10:14:25 DEBUG : : Looking for writers 2020/07/24 10:14:25 DEBUG : dir: reading active writers 2020/07/24 10:14:25 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:14:26 INFO : newLeaf: Deleted 2020/07/24 10:14:26 DEBUG : dir: Looking for writers 2020/07/24 10:14:26 DEBUG : : Looking for writers 2020/07/24 10:14:26 DEBUG : dir: reading active writers 2020/07/24 10:14:26 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:14:26 INFO : newLeaf.rclone_chunk.001_z2whh6: Moved (server side) 2020/07/24 10:14:26 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:14:26 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:14:21 +0000 UTC" 2020/07/24 10:14:26 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:14:26 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:14:26 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:14:27 DEBUG : dir: Looking for writers 2020/07/24 10:14:27 DEBUG : : Looking for writers 2020/07/24 10:14:27 DEBUG : dir: reading active writers 2020/07/24 10:14:27 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:27 DEBUG : >WaitForWriters: 2020/07/24 10:14:28 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:14:28 DEBUG : dir: Looking for writers 2020/07/24 10:14:28 DEBUG : : Looking for writers 2020/07/24 10:14:28 DEBUG : dir: reading active writers 2020/07/24 10:14:28 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:28 DEBUG : >WaitForWriters: 2020/07/24 10:14:28 DEBUG : vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=true 2020/07/24 10:14:42 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:14:42 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:14:42 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:14:42 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:14:46 INFO : dir/file1.rclone_chunk.001_z2x1nt: Moved (server side) 2020/07/24 10:14:47 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/07/24 10:14:47 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:14:47 DEBUG : dir/file1(0xc000674600): openPending: 2020/07/24 10:14:47 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:14:47 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:14:47 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:14:47 DEBUG : dir/file1(0xc000674600): >openPending: err= 2020/07/24 10:14:47 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:14:47 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:14:47 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:14:47 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:14:47 DEBUG : dir/file1(0xc000674600): _writeAt: size=14, off=0 2020/07/24 10:14:47 DEBUG : dir/file1(0xc000674600): >_writeAt: n=14, err= 2020/07/24 10:14:47 DEBUG : dir/file1(0xc000674600): close: 2020/07/24 10:14:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:14:47 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:14:47.398912387 +0000 UTC m=+66.878172225 2020/07/24 10:14:47 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:14:47 DEBUG : dir/file1(0xc000674600): >close: err= 2020/07/24 10:14:47 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:14:47 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:14:47 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:14:47 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:14:47 DEBUG : dir/file1(0xc0006748c0): _readAt: size=512, off=0 2020/07/24 10:14:47 DEBUG : dir/file1(0xc0006748c0): openPending: 2020/07/24 10:14:47 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:14:47 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:14:47 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:14:47 DEBUG : dir/file1(0xc0006748c0): >openPending: err= 2020/07/24 10:14:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:14:47 DEBUG : dir/file1(0xc0006748c0): >_readAt: n=14, err=EOF 2020/07/24 10:14:47 DEBUG : dir/file1(0xc0006748c0): close: 2020/07/24 10:14:47 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:14:47 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:14:47.398912387 +0000 UTC m=+66.878172225 2020/07/24 10:14:47 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:14:47 DEBUG : dir/file1(0xc0006748c0): >close: err= 2020/07/24 10:14:47 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:14:48 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:14:49 INFO : dir/file1: Moved (server side) 2020/07/24 10:14:49 INFO : dir/file1: Moved (server side) 2020/07/24 10:14:49 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 10:14:49 ERROR : dir/file1: Failed to copy: Post https://upload.box.com/api/2.0/files/content: context canceled 2020/07/24 10:14:49 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 10:14:49 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 10:14:49 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:14:49 DEBUG : newLeaf: Updating file with newLeaf 0xc000720180 2020/07/24 10:14:49 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:14:49 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:14:49 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:14:50 DEBUG : newLeaf: move non-chunked object... 2020/07/24 10:14:50 INFO : newLeaf: Moved (server side) 2020/07/24 10:14:50 INFO : newLeaf: Moved (server side) 2020/07/24 10:14:50 DEBUG : newLeaf: vfs cache: cancelling upload 2020/07/24 10:14:50 ERROR : newLeaf: Failed to copy: Post https://upload.box.com/api/2.0/files/content: context canceled 2020/07/24 10:14:50 INFO : newLeaf: vfs cache: upload canceled 2020/07/24 10:14:50 DEBUG : newLeaf: vfs cache: cancelled upload 2020/07/24 10:14:50 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:14:50 DEBUG : dir/file1: Updating file with dir/file1 0xc000720180 2020/07/24 10:14:50 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:14:50 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:14:50 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:14:51 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:14:51 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:14:51 DEBUG : dir/file1(0xc000092200): openPending: 2020/07/24 10:14:51 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:14:51 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:14:51 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:14:51 DEBUG : dir/file1(0xc000092200): >openPending: err= 2020/07/24 10:14:51 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:14:51 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc0002a6770 item 1 2020/07/24 10:14:51 DEBUG : dir/file1: vfs cache: cancelling upload 2020/07/24 10:14:51 ERROR : dir/file1: Failed to copy: Post https://upload.box.com/api/2.0/files/content: context canceled 2020/07/24 10:14:51 INFO : dir/file1: vfs cache: upload canceled 2020/07/24 10:14:51 DEBUG : dir/file1: vfs cache: cancelled upload 2020/07/24 10:14:51 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:14:51 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:14:51 DEBUG : dir/file1(0xc000092200): _writeAt: size=25, off=0 2020/07/24 10:14:51 DEBUG : dir/file1(0xc000092200): >_writeAt: n=25, err= 2020/07/24 10:14:52 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:14:52 INFO : dir/file1: Moved (server side) 2020/07/24 10:14:52 INFO : dir/file1: Moved (server side) 2020/07/24 10:14:52 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:14:52 DEBUG : newLeaf: Updating file with newLeaf 0xc000720180 2020/07/24 10:14:52 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:14:52 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:14:52 DEBUG : newLeaf(0xc000092200): close: 2020/07/24 10:14:52 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:14:52 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:14:51.781142833 +0000 UTC m=+71.260402688 2020/07/24 10:14:52 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:14:52 DEBUG : newLeaf(0xc000092200): >close: err= 2020/07/24 10:14:52 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:14:52 DEBUG : dir: Looking for writers 2020/07/24 10:14:52 DEBUG : : Looking for writers 2020/07/24 10:14:52 DEBUG : dir: reading active writers 2020/07/24 10:14:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:14:52 DEBUG : dir: Looking for writers 2020/07/24 10:14:52 DEBUG : : Looking for writers 2020/07/24 10:14:52 DEBUG : dir: reading active writers 2020/07/24 10:14:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:14:52 DEBUG : dir: Looking for writers 2020/07/24 10:14:52 DEBUG : : Looking for writers 2020/07/24 10:14:52 DEBUG : dir: reading active writers 2020/07/24 10:14:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:14:52 DEBUG : dir: Looking for writers 2020/07/24 10:14:52 DEBUG : : Looking for writers 2020/07/24 10:14:52 DEBUG : dir: reading active writers 2020/07/24 10:14:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:14:52 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:14:52 DEBUG : dir: Looking for writers 2020/07/24 10:14:52 DEBUG : : Looking for writers 2020/07/24 10:14:52 DEBUG : dir: reading active writers 2020/07/24 10:14:52 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:14:53 DEBUG : dir: Looking for writers 2020/07/24 10:14:53 DEBUG : : Looking for writers 2020/07/24 10:14:53 DEBUG : dir: reading active writers 2020/07/24 10:14:53 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:14:53 DEBUG : dir: Looking for writers 2020/07/24 10:14:53 DEBUG : : Looking for writers 2020/07/24 10:14:53 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:53 DEBUG : dir: reading active writers 2020/07/24 10:14:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:14:54 DEBUG : dir: Looking for writers 2020/07/24 10:14:54 DEBUG : : Looking for writers 2020/07/24 10:14:54 DEBUG : dir: reading active writers 2020/07/24 10:14:54 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:14:55 DEBUG : dir: Looking for writers 2020/07/24 10:14:55 DEBUG : : Looking for writers 2020/07/24 10:14:55 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:55 DEBUG : dir: reading active writers 2020/07/24 10:14:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:14:56 DEBUG : dir: Looking for writers 2020/07/24 10:14:56 DEBUG : : Looking for writers 2020/07/24 10:14:56 DEBUG : dir: reading active writers 2020/07/24 10:14:56 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:14:56 INFO : newLeaf: Deleted 2020/07/24 10:14:57 INFO : newLeaf.rclone_chunk.001_z2xbuc: Moved (server side) 2020/07/24 10:14:57 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:14:57 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:14:51 +0000 UTC" 2020/07/24 10:14:57 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:14:57 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:14:57 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:14:57 DEBUG : dir: Looking for writers 2020/07/24 10:14:57 DEBUG : : Looking for writers 2020/07/24 10:14:57 DEBUG : dir: reading active writers 2020/07/24 10:14:57 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:57 DEBUG : >WaitForWriters: 2020/07/24 10:14:57 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:14:57 DEBUG : dir: Looking for writers 2020/07/24 10:14:57 DEBUG : : Looking for writers 2020/07/24 10:14:57 DEBUG : dir: reading active writers 2020/07/24 10:14:57 DEBUG : newLeaf: reading active writers 2020/07/24 10:14:57 DEBUG : >WaitForWriters: 2020/07/24 10:14:57 DEBUG : vfs cache: cleaner exiting === RUN TestFileRename/full,forceCache=false 2020/07/24 10:15:11 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:15:11 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:15:11 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:15:11 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:15:14 INFO : dir/file1.rclone_chunk.001_z2xulv: Moved (server side) 2020/07/24 10:15:15 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:15:15 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:15:15 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:15:15 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:15:15 DEBUG : dir/file1(0xc0007dc300): _readAt: size=512, off=0 2020/07/24 10:15:15 DEBUG : dir/file1(0xc0007dc300): openPending: 2020/07/24 10:15:15 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:15:15 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:15:15 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:15:15 DEBUG : dir/file1(0xc0007dc300): >openPending: err= 2020/07/24 10:15:15 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [] - present false 2020/07/24 10:15:15 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:15:15 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:15:15 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:15:16 DEBUG : dir/file1(0xc0007dc300): >_readAt: n=14, err=EOF 2020/07/24 10:15:16 DEBUG : dir/file1(0xc0007dc300): close: 2020/07/24 10:15:16 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-02 20:05:06 -0800 -0800 2020/07/24 10:15:16 DEBUG : dir/file1(0xc0007dc300): >close: err= 2020/07/24 10:15:17 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:15:17 INFO : dir/file1: Moved (server side) 2020/07/24 10:15:17 INFO : dir/file1: Moved (server side) 2020/07/24 10:15:17 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:15:17 DEBUG : newLeaf: Updating file with newLeaf 0xc00021c540 2020/07/24 10:15:17 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:15:17 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:15:18 DEBUG : newLeaf: move non-chunked object... 2020/07/24 10:15:19 INFO : newLeaf: Moved (server side) 2020/07/24 10:15:19 INFO : newLeaf: Moved (server side) 2020/07/24 10:15:19 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:15:19 DEBUG : dir/file1: Updating file with dir/file1 0xc00021c540 2020/07/24 10:15:19 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:15:19 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:15:20 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:15:20 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:15:20 DEBUG : dir/file1(0xc00013e4c0): openPending: 2020/07/24 10:15:20 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:15:20 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:15:20 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:15:20 DEBUG : dir/file1(0xc00013e4c0): >openPending: err= 2020/07/24 10:15:20 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:15:20 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:15:20 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:15:20 DEBUG : dir/file1(0xc00013e4c0): _writeAt: size=25, off=0 2020/07/24 10:15:20 DEBUG : dir/file1(0xc00013e4c0): >_writeAt: n=25, err= 2020/07/24 10:15:20 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:15:21 INFO : dir/file1: Moved (server side) 2020/07/24 10:15:21 INFO : dir/file1: Moved (server side) 2020/07/24 10:15:21 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:15:21 DEBUG : newLeaf: Updating file with newLeaf 0xc00021c540 2020/07/24 10:15:21 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:15:21 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:15:21 DEBUG : newLeaf(0xc00013e4c0): close: 2020/07/24 10:15:21 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:15:21 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:15:20.356275433 +0000 UTC m=+99.835535273 2020/07/24 10:15:21 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:15:21 DEBUG : newLeaf(0xc00013e4c0): >close: err= 2020/07/24 10:15:21 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:15:21 DEBUG : dir: Looking for writers 2020/07/24 10:15:21 DEBUG : : Looking for writers 2020/07/24 10:15:21 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:21 DEBUG : dir: reading active writers 2020/07/24 10:15:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:15:21 DEBUG : dir: Looking for writers 2020/07/24 10:15:21 DEBUG : : Looking for writers 2020/07/24 10:15:21 DEBUG : dir: reading active writers 2020/07/24 10:15:21 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:15:21 DEBUG : dir: Looking for writers 2020/07/24 10:15:21 DEBUG : : Looking for writers 2020/07/24 10:15:21 DEBUG : dir: reading active writers 2020/07/24 10:15:21 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:15:21 DEBUG : dir: Looking for writers 2020/07/24 10:15:21 DEBUG : : Looking for writers 2020/07/24 10:15:21 DEBUG : dir: reading active writers 2020/07/24 10:15:21 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:15:21 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:15:21 DEBUG : dir: Looking for writers 2020/07/24 10:15:21 DEBUG : : Looking for writers 2020/07/24 10:15:21 DEBUG : dir: reading active writers 2020/07/24 10:15:21 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:15:21 DEBUG : dir: Looking for writers 2020/07/24 10:15:21 DEBUG : : Looking for writers 2020/07/24 10:15:21 DEBUG : dir: reading active writers 2020/07/24 10:15:21 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:15:22 DEBUG : dir: Looking for writers 2020/07/24 10:15:22 DEBUG : : Looking for writers 2020/07/24 10:15:22 DEBUG : dir: reading active writers 2020/07/24 10:15:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:15:22 DEBUG : dir: Looking for writers 2020/07/24 10:15:22 DEBUG : : Looking for writers 2020/07/24 10:15:22 DEBUG : dir: reading active writers 2020/07/24 10:15:22 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:15:23 DEBUG : dir: Looking for writers 2020/07/24 10:15:23 DEBUG : : Looking for writers 2020/07/24 10:15:23 DEBUG : dir: reading active writers 2020/07/24 10:15:23 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:15:24 DEBUG : dir: Looking for writers 2020/07/24 10:15:24 DEBUG : : Looking for writers 2020/07/24 10:15:24 DEBUG : dir: reading active writers 2020/07/24 10:15:24 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:15:25 INFO : newLeaf: Deleted 2020/07/24 10:15:25 INFO : newLeaf.rclone_chunk.001_z2y4yt: Moved (server side) 2020/07/24 10:15:25 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:15:25 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:15:20 +0000 UTC" 2020/07/24 10:15:25 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:15:25 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:15:25 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:15:25 DEBUG : dir: Looking for writers 2020/07/24 10:15:25 DEBUG : : Looking for writers 2020/07/24 10:15:25 DEBUG : dir: reading active writers 2020/07/24 10:15:25 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:25 DEBUG : >WaitForWriters: 2020/07/24 10:15:26 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:15:26 DEBUG : dir: Looking for writers 2020/07/24 10:15:26 DEBUG : : Looking for writers 2020/07/24 10:15:26 DEBUG : newLeaf: reading active writers 2020/07/24 10:15:26 DEBUG : dir: reading active writers 2020/07/24 10:15:26 DEBUG : >WaitForWriters: 2020/07/24 10:15:26 DEBUG : vfs cache: cleaner exiting --- FAIL: TestFileRename (120.16s) --- FAIL: TestFileRename/minimal,forceCache=true (30.43s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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 (30.35s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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 (29.58s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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 (29.79s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:15:41 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:15:41 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:15:41 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:15:41 DEBUG : : Looking for writers 2020/07/24 10:15:41 DEBUG : >WaitForWriters: --- FAIL: TestRcGetVFS (13.33s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:15:54 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:15:57 INFO : dir/file1.rclone_chunk.001_z2z18v: Moved (server side) 2020/07/24 10:15:58 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:15:58 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:15:58 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:15:58 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:15:58 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:15:59 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/07/24 10:15:59 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728 2020/07/24 10:15:59 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:15:59 DEBUG : dir: Looking for writers 2020/07/24 10:15:59 DEBUG : file1: reading active writers 2020/07/24 10:15:59 DEBUG : : Looking for writers 2020/07/24 10:15:59 DEBUG : dir: reading active writers 2020/07/24 10:15:59 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleMethods (19.93s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:16:14 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:16:17 INFO : dir/file1.rclone_chunk.001_z2zljy: Moved (server side) 2020/07/24 10:16:18 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:16:18 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:16:18 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:16:18 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:16:18 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:16:19 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/07/24 10:16:19 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/07/24 10:16:19 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/07/24 10:16:19 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/07/24 10:16:19 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/07/24 10:16:19 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/07/24 10:16:19 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/07/24 10:16:19 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/07/24 10:16:19 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker) 2020/07/24 10:16:19 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1 2020/07/24 10:16:19 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728 2020/07/24 10:16:19 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728 2020/07/24 10:16:20 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker) 2020/07/24 10:16:20 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1 2020/07/24 10:16:20 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728 2020/07/24 10:16:20 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728 2020/07/24 10:16:21 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:16:21 DEBUG : dir: Looking for writers 2020/07/24 10:16:21 DEBUG : file1: reading active writers 2020/07/24 10:16:21 DEBUG : : Looking for writers 2020/07/24 10:16:21 DEBUG : dir: reading active writers 2020/07/24 10:16:21 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleSeek (20.37s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:16:35 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:16:38 INFO : dir/file1.rclone_chunk.001_z306lo: Moved (server side) 2020/07/24 10:16:38 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:16:39 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:16:39 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:16:39 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:16:39 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:16:40 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/07/24 10:16:40 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/07/24 10:16:40 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/07/24 10:16:40 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/07/24 10:16:40 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/07/24 10:16:40 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/07/24 10:16:40 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/07/24 10:16:40 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/07/24 10:16:41 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker) 2020/07/24 10:16:41 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1 2020/07/24 10:16:41 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728 2020/07/24 10:16:41 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728 2020/07/24 10:16:42 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms 2020/07/24 10:16:42 DEBUG : dir/file1: aborting in-sequence read wait, off=10 2020/07/24 10:16:42 DEBUG : dir/file1: failed to wait for in-sequence read to 10 2020/07/24 10:16:42 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker) 2020/07/24 10:16:42 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1 2020/07/24 10:16:42 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728 2020/07/24 10:16:42 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:16:42 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker) 2020/07/24 10:16:42 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1 2020/07/24 10:16:42 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:16:42 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:16:43 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/07/24 10:16:43 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/07/24 10:16:43 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/07/24 10:16:43 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16 2020/07/24 10:16:43 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/07/24 10:16:43 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/07/24 10:16:43 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/07/24 10:16:43 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor 2020/07/24 10:16:43 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:16:43 DEBUG : dir: Looking for writers 2020/07/24 10:16:43 DEBUG : file1: reading active writers 2020/07/24 10:16:43 DEBUG : : Looking for writers 2020/07/24 10:16:43 DEBUG : dir: reading active writers 2020/07/24 10:16:43 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleReadAt (22.67s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:16:57 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:17:01 INFO : dir/file1.rclone_chunk.001_z30ske: Moved (server side) 2020/07/24 10:17:01 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:17:02 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:17:02 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:17:02 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:17:02 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:17:03 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2020/07/24 10:17:03 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:17:03 DEBUG : dir: Looking for writers 2020/07/24 10:17:03 DEBUG : file1: reading active writers 2020/07/24 10:17:03 DEBUG : : Looking for writers 2020/07/24 10:17:03 DEBUG : dir: reading active writers 2020/07/24 10:17:03 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleFlush (19.25s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:17:17 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:17:20 INFO : dir/file1.rclone_chunk.001_z31cly: Moved (server side) 2020/07/24 10:17:20 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:17:21 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:17:21 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:17:21 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:17:21 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:17:22 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2020/07/24 10:17:22 DEBUG : dir/file1: ReadFileHandle.Release closing 2020/07/24 10:17:22 DEBUG : dir/file1: ReadFileHandle.Release nothing to do 2020/07/24 10:17:22 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:17:22 DEBUG : dir: Looking for writers 2020/07/24 10:17:22 DEBUG : file1: reading active writers 2020/07/24 10:17:22 DEBUG : : Looking for writers 2020/07/24 10:17:22 DEBUG : dir: reading active writers 2020/07/24 10:17:22 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleRelease (20.23s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:17:37 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:17:37 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:17:37 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:17:37 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:17:40 INFO : dir/file1.rclone_chunk.001_z31wa4: Moved (server side) 2020/07/24 10:17:40 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:17:41 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:17:41 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:17:41 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:17:41 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:17:41 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): _readAt: size=1, off=0 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): openPending: 2020/07/24 10:17:41 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:17:41 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:17:41 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): >openPending: err= 2020/07/24 10:17:41 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/07/24 10:17:41 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:17:41 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:17:41 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): >_readAt: n=1, err= 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): _readAt: size=256, off=1 2020/07/24 10:17:41 DEBUG : vfs cache: looking for range={Pos:1 Size:15} in [{Pos:0 Size:16}] - present true 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): >_readAt: n=15, err=EOF 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): _readAt: size=16, off=16 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): >_readAt: n=0, err=EOF 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): close: 2020/07/24 10:17:41 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-02 20:05:06 -0800 -0800 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): >close: err= 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): close: 2020/07/24 10:17:41 DEBUG : dir/file1(0xc0007dc7c0): >close: err=file already closed 2020/07/24 10:17:41 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:17:41 DEBUG : dir: Looking for writers 2020/07/24 10:17:41 DEBUG : file1: reading active writers 2020/07/24 10:17:41 DEBUG : : Looking for writers 2020/07/24 10:17:41 DEBUG : dir: reading active writers 2020/07/24 10:17:41 DEBUG : >WaitForWriters: 2020/07/24 10:17:41 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleMethodsRead (18.76s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:17:56 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:17:56 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:17:56 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:17: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:18:00 INFO : dir/file1.rclone_chunk.001_z32fso: Moved (server side) 2020/07/24 10:18:01 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:18:02 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:18:02 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:18:02 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:18:02 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:18:02 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): _readAt: size=1, off=0 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): openPending: 2020/07/24 10:18:02 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:18:02 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:18:02 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): >openPending: err= 2020/07/24 10:18:02 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/07/24 10:18:02 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:18:02 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:18:02 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): >_readAt: n=1, err= 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): _readAt: size=1, off=5 2020/07/24 10:18:02 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): >_readAt: n=1, err= 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): _readAt: size=1, off=3 2020/07/24 10:18:02 DEBUG : vfs cache: looking for range={Pos:3 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): >_readAt: n=1, err= 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): _readAt: size=1, off=13 2020/07/24 10:18:02 DEBUG : vfs cache: looking for range={Pos:13 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): >_readAt: n=1, err= 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): _readAt: size=16, off=100 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): >_readAt: n=0, err=EOF 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): close: 2020/07/24 10:18:02 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-02 20:05:06 -0800 -0800 2020/07/24 10:18:02 DEBUG : dir/file1(0xc0001ece00): >close: err= 2020/07/24 10:18:02 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:18:02 DEBUG : dir: Looking for writers 2020/07/24 10:18:02 DEBUG : file1: reading active writers 2020/07/24 10:18:02 DEBUG : : Looking for writers 2020/07/24 10:18:02 DEBUG : dir: reading active writers 2020/07/24 10:18:02 DEBUG : >WaitForWriters: 2020/07/24 10:18:02 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleSeek (20.75s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:18:16 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:18:16 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:18:16 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:18: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:18:19 INFO : dir/file1.rclone_chunk.001_z32zap: Moved (server side) 2020/07/24 10:18:20 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:18:21 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:18:21 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:18:21 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:18:21 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:18:21 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): _readAt: size=1, off=0 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): openPending: 2020/07/24 10:18:21 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:18:21 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:18:21 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >openPending: err= 2020/07/24 10:18:21 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/07/24 10:18:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:18:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:18:21 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >_readAt: n=1, err= 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): _readAt: size=1, off=5 2020/07/24 10:18:21 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >_readAt: n=1, err= 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): _readAt: size=1, off=1 2020/07/24 10:18:21 DEBUG : vfs cache: looking for range={Pos:1 Size:1} in [{Pos:0 Size:16}] - present true 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >_readAt: n=1, err= 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): _readAt: size=6, off=10 2020/07/24 10:18:21 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >_readAt: n=6, err= 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): _readAt: size=256, off=10 2020/07/24 10:18:21 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >_readAt: n=6, err=EOF 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): _readAt: size=256, off=100 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >_readAt: n=0, err=EOF 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): close: 2020/07/24 10:18:21 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-02 20:05:06 -0800 -0800 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >close: err= 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): _readAt: size=256, off=100 2020/07/24 10:18:21 DEBUG : dir/file1(0xc00013e9c0): >_readAt: n=0, err=file already closed 2020/07/24 10:18:21 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:18:21 DEBUG : dir: Looking for writers 2020/07/24 10:18:21 DEBUG : file1: reading active writers 2020/07/24 10:18:21 DEBUG : : Looking for writers 2020/07/24 10:18:21 DEBUG : dir: reading active writers 2020/07/24 10:18:21 DEBUG : >WaitForWriters: 2020/07/24 10:18:21 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleReadAt (20.26s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:18:37 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:18:37 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:18:37 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:18:37 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:18:40 INFO : dir/file1.rclone_chunk.001_z33kct: Moved (server side) 2020/07/24 10:18:41 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:18:41 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:18:41 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:18:41 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:18:41 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:18:41 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:18:41 DEBUG : dir/file1(0xc00075eac0): RWFileHandle.Flush 2020/07/24 10:18:41 DEBUG : dir/file1(0xc00075eac0): _readAt: size=256, off=0 2020/07/24 10:18:41 DEBUG : dir/file1(0xc00075eac0): openPending: 2020/07/24 10:18:41 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:18:41 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:18:41 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:18:41 DEBUG : dir/file1(0xc00075eac0): >openPending: err= 2020/07/24 10:18:41 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2020/07/24 10:18:41 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:18:41 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:18:41 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:18:42 DEBUG : dir/file1(0xc00075eac0): >_readAt: n=16, err=EOF 2020/07/24 10:18:42 DEBUG : dir/file1(0xc00075eac0): RWFileHandle.Flush 2020/07/24 10:18:42 DEBUG : dir/file1(0xc00075eac0): RWFileHandle.Flush 2020/07/24 10:18:42 DEBUG : dir/file1(0xc00075eac0): close: 2020/07/24 10:18:42 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-02 20:05:06 -0800 -0800 2020/07/24 10:18:42 DEBUG : dir/file1(0xc00075eac0): >close: err= 2020/07/24 10:18:42 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:18:42 DEBUG : dir: Looking for writers 2020/07/24 10:18:42 DEBUG : file1: reading active writers 2020/07/24 10:18:42 DEBUG : : Looking for writers 2020/07/24 10:18:42 DEBUG : dir: reading active writers 2020/07/24 10:18:42 DEBUG : >WaitForWriters: 2020/07/24 10:18:42 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleFlushRead (19.37s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:18:56 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:18:56 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:18:56 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:18: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:18:59 INFO : dir/file1.rclone_chunk.001_z343oi: Moved (server side) 2020/07/24 10:18:59 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:19:00 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:19:00 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:19:00 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:19:00 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:19:00 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:19:00 DEBUG : dir/file1(0xc0001ede80): _readAt: size=256, off=0 2020/07/24 10:19:00 DEBUG : dir/file1(0xc0001ede80): openPending: 2020/07/24 10:19:00 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:19:00 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:19:00 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:19:00 DEBUG : dir/file1(0xc0001ede80): >openPending: err= 2020/07/24 10:19:00 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2020/07/24 10:19:00 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/07/24 10:19:00 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/07/24 10:19:00 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:19:01 DEBUG : dir/file1(0xc0001ede80): >_readAt: n=16, err=EOF 2020/07/24 10:19:01 DEBUG : dir/file1(0xc0001ede80): RWFileHandle.Release 2020/07/24 10:19:01 DEBUG : dir/file1(0xc0001ede80): close: 2020/07/24 10:19:01 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-02 20:05:06 -0800 -0800 2020/07/24 10:19:01 DEBUG : dir/file1(0xc0001ede80): >close: err= 2020/07/24 10:19:01 DEBUG : dir/file1(0xc0001ede80): RWFileHandle.Release 2020/07/24 10:19:01 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:19:01 DEBUG : dir: Looking for writers 2020/07/24 10:19:01 DEBUG : file1: reading active writers 2020/07/24 10:19:01 DEBUG : : Looking for writers 2020/07/24 10:19:01 DEBUG : dir: reading active writers 2020/07/24 10:19:01 DEBUG : >WaitForWriters: 2020/07/24 10:19:01 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleReleaseRead (18.60s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:19:14 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:19:14 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:19:14 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:19:14 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:19: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:19:15 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:19:15 DEBUG : file1: newRWFileHandle: 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): openPending: 2020/07/24 10:19:15 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:19:15 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): >openPending: err= 2020/07/24 10:19:15 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:19:15 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:19:15 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:19:15 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): _writeAt: size=5, off=0 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): >_writeAt: n=5, err= 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): _writeAt: size=7, off=5 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): >_writeAt: n=7, err= 2020/07/24 10:19:15 DEBUG : file1: vfs cache: truncate to size=11 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): close: 2020/07/24 10:19:15 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:19:15.321773136 +0000 UTC m=+334.801033002 2020/07/24 10:19:15 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): >close: err= 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): close: 2020/07/24 10:19:15 DEBUG : file1(0xc000674140): >close: err=file already closed 2020/07/24 10:19:15 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:19:15 DEBUG : dir: Looking for writers 2020/07/24 10:19:15 DEBUG : : Looking for writers 2020/07/24 10:19:15 DEBUG : dir: reading active writers 2020/07/24 10:19:15 DEBUG : file1: reading active writers 2020/07/24 10:19:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:19:15 DEBUG : dir: Looking for writers 2020/07/24 10:19:15 DEBUG : : Looking for writers 2020/07/24 10:19:15 DEBUG : dir: reading active writers 2020/07/24 10:19:15 DEBUG : file1: reading active writers 2020/07/24 10:19:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:19:15 DEBUG : dir: Looking for writers 2020/07/24 10:19:15 DEBUG : : Looking for writers 2020/07/24 10:19:15 DEBUG : dir: reading active writers 2020/07/24 10:19:15 DEBUG : file1: reading active writers 2020/07/24 10:19:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:19:15 DEBUG : dir: Looking for writers 2020/07/24 10:19:15 DEBUG : : Looking for writers 2020/07/24 10:19:15 DEBUG : dir: reading active writers 2020/07/24 10:19:15 DEBUG : file1: reading active writers 2020/07/24 10:19:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:19:15 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:19:15 DEBUG : dir: Looking for writers 2020/07/24 10:19:15 DEBUG : : Looking for writers 2020/07/24 10:19:15 DEBUG : dir: reading active writers 2020/07/24 10:19:15 DEBUG : file1: reading active writers 2020/07/24 10:19:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:19:15 DEBUG : dir: Looking for writers 2020/07/24 10:19:15 DEBUG : : Looking for writers 2020/07/24 10:19:15 DEBUG : dir: reading active writers 2020/07/24 10:19:15 DEBUG : file1: reading active writers 2020/07/24 10:19:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:19:15 DEBUG : dir: Looking for writers 2020/07/24 10:19:15 DEBUG : : Looking for writers 2020/07/24 10:19:15 DEBUG : dir: reading active writers 2020/07/24 10:19:15 DEBUG : file1: reading active writers 2020/07/24 10:19:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:19:16 DEBUG : dir: Looking for writers 2020/07/24 10:19:16 DEBUG : : Looking for writers 2020/07/24 10:19:16 DEBUG : dir: reading active writers 2020/07/24 10:19:16 DEBUG : file1: reading active writers 2020/07/24 10:19:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:19:17 DEBUG : dir: Looking for writers 2020/07/24 10:19:17 DEBUG : : Looking for writers 2020/07/24 10:19:17 DEBUG : dir: reading active writers 2020/07/24 10:19:17 DEBUG : file1: reading active writers 2020/07/24 10:19:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:19:18 DEBUG : dir: Looking for writers 2020/07/24 10:19:18 DEBUG : : Looking for writers 2020/07/24 10:19:18 DEBUG : dir: reading active writers 2020/07/24 10:19:18 DEBUG : file1: reading active writers 2020/07/24 10:19:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:19:19 INFO : file1.rclone_chunk.001_z34mst: Moved (server side) 2020/07/24 10:19:19 INFO : file1: Copied (new) 2020/07/24 10:19:19 DEBUG : file1: vfs cache: fingerprint now "11,2020-07-24 10:19:15 +0000 UTC" 2020/07/24 10:19:19 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:19:19 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:19:19 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:19:19 DEBUG : dir: Looking for writers 2020/07/24 10:19:19 DEBUG : : Looking for writers 2020/07/24 10:19:19 DEBUG : dir: reading active writers 2020/07/24 10:19:19 DEBUG : file1: reading active writers 2020/07/24 10:19:19 DEBUG : >WaitForWriters: 2020/07/24 10:19:28 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:19:28 DEBUG : dir: Looking for writers 2020/07/24 10:19:28 DEBUG : : Looking for writers 2020/07/24 10:19:28 DEBUG : dir: reading active writers 2020/07/24 10:19:28 DEBUG : file1: reading active writers 2020/07/24 10:19:28 DEBUG : >WaitForWriters: 2020/07/24 10:19:28 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleMethodsWrite (27.97s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", 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: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:19:42 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:19:42 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:19:42 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:19:42 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:19:42 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:19:43 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:19:43 DEBUG : file1: newRWFileHandle: 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): openPending: 2020/07/24 10:19:43 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:19:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): >openPending: err= 2020/07/24 10:19:43 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:19:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:19:43 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:19:43 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): _writeAt: size=7, off=0 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): >_writeAt: n=7, err= 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): _writeAt: size=6, off=5 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): >_writeAt: n=6, err= 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): close: 2020/07/24 10:19:43 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:19:43.255457379 +0000 UTC m=+362.734717210 2020/07/24 10:19:43 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): >close: err= 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): _writeAt: size=5, off=0 2020/07/24 10:19:43 DEBUG : file1(0xc00013e640): >_writeAt: n=0, err=file already closed 2020/07/24 10:19:43 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:19:43 DEBUG : dir: Looking for writers 2020/07/24 10:19:43 DEBUG : : Looking for writers 2020/07/24 10:19:43 DEBUG : dir: reading active writers 2020/07/24 10:19:43 DEBUG : file1: reading active writers 2020/07/24 10:19:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:19:43 DEBUG : dir: Looking for writers 2020/07/24 10:19:43 DEBUG : : Looking for writers 2020/07/24 10:19:43 DEBUG : dir: reading active writers 2020/07/24 10:19:43 DEBUG : file1: reading active writers 2020/07/24 10:19:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:19:43 DEBUG : dir: Looking for writers 2020/07/24 10:19:43 DEBUG : : Looking for writers 2020/07/24 10:19:43 DEBUG : dir: reading active writers 2020/07/24 10:19:43 DEBUG : file1: reading active writers 2020/07/24 10:19:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:19:43 DEBUG : dir: Looking for writers 2020/07/24 10:19:43 DEBUG : : Looking for writers 2020/07/24 10:19:43 DEBUG : dir: reading active writers 2020/07/24 10:19:43 DEBUG : file1: reading active writers 2020/07/24 10:19:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:19:43 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:19:43 DEBUG : dir: Looking for writers 2020/07/24 10:19:43 DEBUG : : Looking for writers 2020/07/24 10:19:43 DEBUG : dir: reading active writers 2020/07/24 10:19:43 DEBUG : file1: reading active writers 2020/07/24 10:19:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:19:43 DEBUG : dir: Looking for writers 2020/07/24 10:19:43 DEBUG : : Looking for writers 2020/07/24 10:19:43 DEBUG : dir: reading active writers 2020/07/24 10:19:43 DEBUG : file1: reading active writers 2020/07/24 10:19:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:19:43 DEBUG : dir: Looking for writers 2020/07/24 10:19:43 DEBUG : : Looking for writers 2020/07/24 10:19:43 DEBUG : dir: reading active writers 2020/07/24 10:19:43 DEBUG : file1: reading active writers 2020/07/24 10:19:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:19:44 DEBUG : dir: Looking for writers 2020/07/24 10:19:44 DEBUG : : Looking for writers 2020/07/24 10:19:44 DEBUG : dir: reading active writers 2020/07/24 10:19:44 DEBUG : file1: reading active writers 2020/07/24 10:19:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:19:45 DEBUG : dir: Looking for writers 2020/07/24 10:19:45 DEBUG : : Looking for writers 2020/07/24 10:19:45 DEBUG : dir: reading active writers 2020/07/24 10:19:45 DEBUG : file1: reading active writers 2020/07/24 10:19:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:19:46 INFO : file1.rclone_chunk.001_z35er6: Moved (server side) 2020/07/24 10:19:46 INFO : file1: Copied (new) 2020/07/24 10:19:46 DEBUG : file1: vfs cache: fingerprint now "11,2020-07-24 10:19:43 +0000 UTC" 2020/07/24 10:19:46 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:19:46 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:19:46 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:19:46 DEBUG : dir: Looking for writers 2020/07/24 10:19:46 DEBUG : : Looking for writers 2020/07/24 10:19:46 DEBUG : dir: reading active writers 2020/07/24 10:19:46 DEBUG : file1: reading active writers 2020/07/24 10:19:46 DEBUG : >WaitForWriters: 2020/07/24 10:19:56 DEBUG : pacer: low level retry 1/10 (error Error "service_unavailable" (503): Service Unavailable) 2020/07/24 10:19:56 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2020/07/24 10:19:57 DEBUG : pacer: Reducing sleep to 15ms 2020/07/24 10:20:01 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:20:01 DEBUG : dir: Looking for writers 2020/07/24 10:20:01 DEBUG : : Looking for writers 2020/07/24 10:20:01 DEBUG : dir: reading active writers 2020/07/24 10:20:01 DEBUG : file1: reading active writers 2020/07/24 10:20:01 DEBUG : >WaitForWriters: 2020/07/24 10:20:01 DEBUG : vfs cache: cleaner exiting 2020/07/24 10:20:01 DEBUG : pacer: Reducing sleep to 11.25ms 2020/07/24 10:20:02 DEBUG : pacer: Reducing sleep to 10ms --- FAIL: TestRWFileHandleWriteAt (32.26s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", 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: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:20:15 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:20:15 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:20:15 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:20:15 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:20:15 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:20:15 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:20:15 DEBUG : file1: newRWFileHandle: 2020/07/24 10:20:15 DEBUG : file1(0xc00013ed00): openPending: 2020/07/24 10:20:15 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:20:15 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:20:15 DEBUG : file1(0xc00013ed00): >openPending: err= 2020/07/24 10:20:15 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:20:15 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:20:15 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:20:15 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:20:15 DEBUG : file1(0xc00013ed00): close: 2020/07/24 10:20:15 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:20:15.508352266 +0000 UTC m=+394.987612098 2020/07/24 10:20:15 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:20:15 DEBUG : file1(0xc00013ed00): >close: err= 2020/07/24 10:20:15 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:20:15 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/07/24 10:20:15 DEBUG : file2: newRWFileHandle: 2020/07/24 10:20:15 DEBUG : file2(0xc00013f000): openPending: 2020/07/24 10:20:15 DEBUG : file2: vfs cache: truncate to size=0 2020/07/24 10:20:15 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/07/24 10:20:15 DEBUG : file2(0xc00013f000): >openPending: err= 2020/07/24 10:20:15 DEBUG : file2: >newRWFileHandle: err= 2020/07/24 10:20:15 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/07/24 10:20:15 DEBUG : file2: >Open: fd=file2 (rw), err= 2020/07/24 10:20:15 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2020/07/24 10:20:15 DEBUG : file2(0xc00013f000): RWFileHandle.Flush 2020/07/24 10:20:15 DEBUG : file2(0xc00013f000): RWFileHandle.Release 2020/07/24 10:20:15 DEBUG : file2(0xc00013f000): close: 2020/07/24 10:20:15 DEBUG : file2: vfs cache: setting modification time to 2020-07-24 10:20:15.509186667 +0000 UTC m=+394.988446500 2020/07/24 10:20:15 INFO : file2: vfs cache: queuing for upload in 100ms 2020/07/24 10:20:15 DEBUG : file2(0xc00013f000): >close: err= 2020/07/24 10:20:15 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:20:15 DEBUG : dir: Looking for writers 2020/07/24 10:20:15 DEBUG : : Looking for writers 2020/07/24 10:20:15 DEBUG : file2: reading active writers 2020/07/24 10:20:15 DEBUG : dir: reading active writers 2020/07/24 10:20:15 DEBUG : file1: reading active writers 2020/07/24 10:20:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2020/07/24 10:20:15 DEBUG : dir: Looking for writers 2020/07/24 10:20:15 DEBUG : : Looking for writers 2020/07/24 10:20:15 DEBUG : file2: reading active writers 2020/07/24 10:20:15 DEBUG : dir: reading active writers 2020/07/24 10:20:15 DEBUG : file1: reading active writers 2020/07/24 10:20:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2020/07/24 10:20:15 DEBUG : dir: Looking for writers 2020/07/24 10:20:15 DEBUG : : Looking for writers 2020/07/24 10:20:15 DEBUG : dir: reading active writers 2020/07/24 10:20:15 DEBUG : file1: reading active writers 2020/07/24 10:20:15 DEBUG : file2: reading active writers 2020/07/24 10:20:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2020/07/24 10:20:15 DEBUG : dir: Looking for writers 2020/07/24 10:20:15 DEBUG : : Looking for writers 2020/07/24 10:20:15 DEBUG : dir: reading active writers 2020/07/24 10:20:15 DEBUG : file1: reading active writers 2020/07/24 10:20:15 DEBUG : file2: reading active writers 2020/07/24 10:20:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2020/07/24 10:20:15 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:20:15 DEBUG : file2: vfs cache: starting upload 2020/07/24 10:20:15 DEBUG : dir: Looking for writers 2020/07/24 10:20:15 DEBUG : : Looking for writers 2020/07/24 10:20:15 DEBUG : dir: reading active writers 2020/07/24 10:20:15 DEBUG : file1: reading active writers 2020/07/24 10:20:15 DEBUG : file2: reading active writers 2020/07/24 10:20:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2020/07/24 10:20:15 DEBUG : dir: Looking for writers 2020/07/24 10:20:15 DEBUG : : Looking for writers 2020/07/24 10:20:15 DEBUG : dir: reading active writers 2020/07/24 10:20:15 DEBUG : file1: reading active writers 2020/07/24 10:20:15 DEBUG : file2: reading active writers 2020/07/24 10:20:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2020/07/24 10:20:16 DEBUG : dir: Looking for writers 2020/07/24 10:20:16 DEBUG : : Looking for writers 2020/07/24 10:20:16 DEBUG : dir: reading active writers 2020/07/24 10:20:16 DEBUG : file1: reading active writers 2020/07/24 10:20:16 DEBUG : file2: reading active writers 2020/07/24 10:20:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2020/07/24 10:20:16 DEBUG : dir: Looking for writers 2020/07/24 10:20:16 DEBUG : : Looking for writers 2020/07/24 10:20:16 DEBUG : dir: reading active writers 2020/07/24 10:20:16 DEBUG : file1: reading active writers 2020/07/24 10:20:16 DEBUG : file2: reading active writers 2020/07/24 10:20:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2020/07/24 10:20:17 DEBUG : dir: Looking for writers 2020/07/24 10:20:17 DEBUG : : Looking for writers 2020/07/24 10:20:17 DEBUG : file2: reading active writers 2020/07/24 10:20:17 DEBUG : dir: reading active writers 2020/07/24 10:20:17 DEBUG : file1: reading active writers 2020/07/24 10:20:17 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2020/07/24 10:20:18 INFO : file2.rclone_chunk.001_z36a8c: Moved (server side) 2020/07/24 10:20:18 INFO : file2: Copied (new) 2020/07/24 10:20:18 DEBUG : file2: vfs cache: fingerprint now "0,2020-07-24 10:20:15 +0000 UTC" 2020/07/24 10:20:18 DEBUG : file2: vfs cache: writeback object to VFS layer 2020/07/24 10:20:18 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/07/24 10:20:18 INFO : file2: vfs cache: upload succeeded try #1 2020/07/24 10:20:18 INFO : file1.rclone_chunk.001_z36a9g: Moved (server side) 2020/07/24 10:20:18 INFO : file1: Copied (new) 2020/07/24 10:20:18 DEBUG : file1: vfs cache: fingerprint now "0,2020-07-24 10:20:15 +0000 UTC" 2020/07/24 10:20:18 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:20:18 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:20:18 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:20:18 DEBUG : dir: Looking for writers 2020/07/24 10:20:18 DEBUG : : Looking for writers 2020/07/24 10:20:18 DEBUG : dir: reading active writers 2020/07/24 10:20:18 DEBUG : file1: reading active writers 2020/07/24 10:20:18 DEBUG : file2: reading active writers 2020/07/24 10:20:18 DEBUG : >WaitForWriters: 2020/07/24 10:20:27 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:20:27 DEBUG : dir: Looking for writers 2020/07/24 10:20:27 DEBUG : : Looking for writers 2020/07/24 10:20:27 DEBUG : dir: reading active writers 2020/07/24 10:20:27 DEBUG : file1: reading active writers 2020/07/24 10:20:27 DEBUG : file2: reading active writers 2020/07/24 10:20:27 DEBUG : >WaitForWriters: 2020/07/24 10:20:27 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleWriteNoWrite (27.49s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", 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: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:20:42 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:20:42 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:20:42 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:20:42 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:20:42 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:20:42 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:20:42 DEBUG : file1: newRWFileHandle: 2020/07/24 10:20:42 DEBUG : file1(0xc00075e100): openPending: 2020/07/24 10:20:42 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:20:42 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:20:42 DEBUG : file1(0xc00075e100): >openPending: err= 2020/07/24 10:20:42 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:20:42 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:20:42 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:20:42 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:20:42 DEBUG : file1(0xc00075e100): _writeAt: size=5, off=0 2020/07/24 10:20:42 DEBUG : file1(0xc00075e100): >_writeAt: n=5, err= 2020/07/24 10:20:42 DEBUG : file1(0xc00075e100): RWFileHandle.Flush 2020/07/24 10:20:42 DEBUG : file1(0xc00075e100): RWFileHandle.Flush 2020/07/24 10:20:42 DEBUG : file1(0xc00075e100): close: 2020/07/24 10:20:42 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:20:42.999091992 +0000 UTC m=+422.478351999 2020/07/24 10:20:42 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:20:42 DEBUG : file1(0xc00075e100): >close: err= 2020/07/24 10:20:42 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:20:42 DEBUG : dir: Looking for writers 2020/07/24 10:20:42 DEBUG : : Looking for writers 2020/07/24 10:20:42 DEBUG : dir: reading active writers 2020/07/24 10:20:42 DEBUG : file1: reading active writers 2020/07/24 10:20:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:20:43 DEBUG : dir: Looking for writers 2020/07/24 10:20:43 DEBUG : : Looking for writers 2020/07/24 10:20:43 DEBUG : dir: reading active writers 2020/07/24 10:20:43 DEBUG : file1: reading active writers 2020/07/24 10:20:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:20:43 DEBUG : dir: Looking for writers 2020/07/24 10:20:43 DEBUG : : Looking for writers 2020/07/24 10:20:43 DEBUG : dir: reading active writers 2020/07/24 10:20:43 DEBUG : file1: reading active writers 2020/07/24 10:20:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:20:43 DEBUG : dir: Looking for writers 2020/07/24 10:20:43 DEBUG : : Looking for writers 2020/07/24 10:20:43 DEBUG : dir: reading active writers 2020/07/24 10:20:43 DEBUG : file1: reading active writers 2020/07/24 10:20:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:20:43 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:20:43 DEBUG : dir: Looking for writers 2020/07/24 10:20:43 DEBUG : : Looking for writers 2020/07/24 10:20:43 DEBUG : dir: reading active writers 2020/07/24 10:20:43 DEBUG : file1: reading active writers 2020/07/24 10:20:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:20:43 DEBUG : dir: Looking for writers 2020/07/24 10:20:43 DEBUG : : Looking for writers 2020/07/24 10:20:43 DEBUG : dir: reading active writers 2020/07/24 10:20:43 DEBUG : file1: reading active writers 2020/07/24 10:20:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:20:43 DEBUG : dir: Looking for writers 2020/07/24 10:20:43 DEBUG : : Looking for writers 2020/07/24 10:20:43 DEBUG : dir: reading active writers 2020/07/24 10:20:43 DEBUG : file1: reading active writers 2020/07/24 10:20:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:20:44 DEBUG : dir: Looking for writers 2020/07/24 10:20:44 DEBUG : : Looking for writers 2020/07/24 10:20:44 DEBUG : dir: reading active writers 2020/07/24 10:20:44 DEBUG : file1: reading active writers 2020/07/24 10:20:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:20:45 DEBUG : dir: Looking for writers 2020/07/24 10:20:45 DEBUG : : Looking for writers 2020/07/24 10:20:45 DEBUG : dir: reading active writers 2020/07/24 10:20:45 DEBUG : file1: reading active writers 2020/07/24 10:20:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:20:46 DEBUG : dir: Looking for writers 2020/07/24 10:20:46 DEBUG : : Looking for writers 2020/07/24 10:20:46 DEBUG : dir: reading active writers 2020/07/24 10:20:46 DEBUG : file1: reading active writers 2020/07/24 10:20:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:20:46 INFO : file1.rclone_chunk.001_z372yc: Moved (server side) 2020/07/24 10:20:46 INFO : file1: Copied (new) 2020/07/24 10:20:46 DEBUG : file1: vfs cache: fingerprint now "5,2020-07-24 10:20:42 +0000 UTC" 2020/07/24 10:20:46 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:20:46 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:20:46 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:20:47 DEBUG : dir: Looking for writers 2020/07/24 10:20:47 DEBUG : : Looking for writers 2020/07/24 10:20:47 DEBUG : dir: reading active writers 2020/07/24 10:20:47 DEBUG : file1: reading active writers 2020/07/24 10:20:47 DEBUG : >WaitForWriters: 2020/07/24 10:20:47 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleFlushWrite (18.94s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:21:01 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:21:01 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:21:01 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:21:01 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:21: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:21:01 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:21:01 DEBUG : file1: newRWFileHandle: 2020/07/24 10:21:01 DEBUG : file1(0xc0003f8240): openPending: 2020/07/24 10:21:01 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:21:01 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:21:01 DEBUG : file1(0xc0003f8240): >openPending: err= 2020/07/24 10:21:01 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:21:01 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:21:01 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:21:01 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:21:01 DEBUG : file1(0xc0003f8240): _writeAt: size=5, off=0 2020/07/24 10:21:01 DEBUG : file1(0xc0003f8240): >_writeAt: n=5, err= 2020/07/24 10:21:01 DEBUG : file1(0xc0003f8240): RWFileHandle.Release 2020/07/24 10:21:01 DEBUG : file1(0xc0003f8240): close: 2020/07/24 10:21:01 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:21:01.942316336 +0000 UTC m=+441.421576181 2020/07/24 10:21:01 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:21:01 DEBUG : file1(0xc0003f8240): >close: err= 2020/07/24 10:21:01 DEBUG : file1(0xc0003f8240): RWFileHandle.Release 2020/07/24 10:21:01 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:21:01 DEBUG : dir: Looking for writers 2020/07/24 10:21:01 DEBUG : : Looking for writers 2020/07/24 10:21:01 DEBUG : dir: reading active writers 2020/07/24 10:21:01 DEBUG : file1: reading active writers 2020/07/24 10:21:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:21:01 DEBUG : dir: Looking for writers 2020/07/24 10:21:01 DEBUG : : Looking for writers 2020/07/24 10:21:01 DEBUG : dir: reading active writers 2020/07/24 10:21:01 DEBUG : file1: reading active writers 2020/07/24 10:21:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:21:01 DEBUG : dir: Looking for writers 2020/07/24 10:21:01 DEBUG : : Looking for writers 2020/07/24 10:21:01 DEBUG : dir: reading active writers 2020/07/24 10:21:01 DEBUG : file1: reading active writers 2020/07/24 10:21:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:21:02 DEBUG : dir: Looking for writers 2020/07/24 10:21:02 DEBUG : : Looking for writers 2020/07/24 10:21:02 DEBUG : dir: reading active writers 2020/07/24 10:21:02 DEBUG : file1: reading active writers 2020/07/24 10:21:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:21:02 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:21:02 DEBUG : dir: Looking for writers 2020/07/24 10:21:02 DEBUG : : Looking for writers 2020/07/24 10:21:02 DEBUG : dir: reading active writers 2020/07/24 10:21:02 DEBUG : file1: reading active writers 2020/07/24 10:21:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:21:02 DEBUG : dir: Looking for writers 2020/07/24 10:21:02 DEBUG : : Looking for writers 2020/07/24 10:21:02 DEBUG : file1: reading active writers 2020/07/24 10:21:02 DEBUG : dir: reading active writers 2020/07/24 10:21:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:21:02 DEBUG : dir: Looking for writers 2020/07/24 10:21:02 DEBUG : : Looking for writers 2020/07/24 10:21:02 DEBUG : dir: reading active writers 2020/07/24 10:21:02 DEBUG : file1: reading active writers 2020/07/24 10:21:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:21:03 DEBUG : dir: Looking for writers 2020/07/24 10:21:03 DEBUG : : Looking for writers 2020/07/24 10:21:03 DEBUG : dir: reading active writers 2020/07/24 10:21:03 DEBUG : file1: reading active writers 2020/07/24 10:21:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:21:04 DEBUG : dir: Looking for writers 2020/07/24 10:21:04 DEBUG : : Looking for writers 2020/07/24 10:21:04 DEBUG : dir: reading active writers 2020/07/24 10:21:04 DEBUG : file1: reading active writers 2020/07/24 10:21:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:21:05 INFO : file1.rclone_chunk.001_z37lxd: Moved (server side) 2020/07/24 10:21:05 INFO : file1: Copied (new) 2020/07/24 10:21:05 DEBUG : file1: vfs cache: fingerprint now "5,2020-07-24 10:21:01 +0000 UTC" 2020/07/24 10:21:05 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:21:05 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:21:05 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:21:05 DEBUG : dir: Looking for writers 2020/07/24 10:21:05 DEBUG : : Looking for writers 2020/07/24 10:21:05 DEBUG : dir: reading active writers 2020/07/24 10:21:05 DEBUG : file1: reading active writers 2020/07/24 10:21:05 DEBUG : >WaitForWriters: 2020/07/24 10:21:05 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleReleaseWrite (17.68s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:21:19 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:21:19 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:21:19 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:21:19 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:21:23 INFO : dir/file1.rclone_chunk.001_z3820n: Moved (server side) 2020/07/24 10:21:24 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:21:24 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:21:24 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:21:24 DEBUG : dir/file1(0xc00013e5c0): openPending: 2020/07/24 10:21:24 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/07/24 10:21:24 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:21:24 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:21:24 DEBUG : dir/file1(0xc00013e5c0): >openPending: err= 2020/07/24 10:21:24 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:21:24 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:21:24 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:21:24 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:21:24 DEBUG : dir/file1(0xc00013e5c0): _writeAt: size=5, off=0 2020/07/24 10:21:24 DEBUG : dir/file1(0xc00013e5c0): >_writeAt: n=5, err= 2020/07/24 10:21:24 DEBUG : dir/file1(0xc00013e5c0): close: 2020/07/24 10:21:24 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true 2020/07/24 10:21:24 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:21:24.730505206 +0000 UTC m=+464.209765039 2020/07/24 10:21:24 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:21:24 DEBUG : dir/file1(0xc00013e5c0): >close: err= 2020/07/24 10:21:24 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:21:24 DEBUG : dir: Looking for writers 2020/07/24 10:21:24 DEBUG : file1: reading active writers 2020/07/24 10:21:24 DEBUG : : Looking for writers 2020/07/24 10:21:24 DEBUG : dir: reading active writers 2020/07/24 10:21:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:21:24 DEBUG : dir: Looking for writers 2020/07/24 10:21:24 DEBUG : file1: reading active writers 2020/07/24 10:21:24 DEBUG : : Looking for writers 2020/07/24 10:21:24 DEBUG : dir: reading active writers 2020/07/24 10:21:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:21:24 DEBUG : dir: Looking for writers 2020/07/24 10:21:24 DEBUG : file1: reading active writers 2020/07/24 10:21:24 DEBUG : : Looking for writers 2020/07/24 10:21:24 DEBUG : dir: reading active writers 2020/07/24 10:21:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:21:24 DEBUG : dir: Looking for writers 2020/07/24 10:21:24 DEBUG : file1: reading active writers 2020/07/24 10:21:24 DEBUG : : Looking for writers 2020/07/24 10:21:24 DEBUG : dir: reading active writers 2020/07/24 10:21:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:21:24 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:21:24 DEBUG : dir: Looking for writers 2020/07/24 10:21:24 DEBUG : file1: reading active writers 2020/07/24 10:21:24 DEBUG : : Looking for writers 2020/07/24 10:21:24 DEBUG : dir: reading active writers 2020/07/24 10:21:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:21:25 DEBUG : dir: Looking for writers 2020/07/24 10:21:25 DEBUG : file1: reading active writers 2020/07/24 10:21:25 DEBUG : : Looking for writers 2020/07/24 10:21:25 DEBUG : dir: reading active writers 2020/07/24 10:21:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:21:25 DEBUG : dir: Looking for writers 2020/07/24 10:21:25 DEBUG : file1: reading active writers 2020/07/24 10:21:25 DEBUG : : Looking for writers 2020/07/24 10:21:25 DEBUG : dir: reading active writers 2020/07/24 10:21:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:21:26 DEBUG : dir: Looking for writers 2020/07/24 10:21:26 DEBUG : file1: reading active writers 2020/07/24 10:21:26 DEBUG : : Looking for writers 2020/07/24 10:21:26 DEBUG : dir: reading active writers 2020/07/24 10:21:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:21:27 DEBUG : dir: Looking for writers 2020/07/24 10:21:27 DEBUG : file1: reading active writers 2020/07/24 10:21:27 DEBUG : : Looking for writers 2020/07/24 10:21:27 DEBUG : dir: reading active writers 2020/07/24 10:21:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:21:28 DEBUG : dir: Looking for writers 2020/07/24 10:21:28 DEBUG : file1: reading active writers 2020/07/24 10:21:28 DEBUG : : Looking for writers 2020/07/24 10:21:28 DEBUG : dir: reading active writers 2020/07/24 10:21:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:21:28 INFO : dir/file1: Deleted 2020/07/24 10:21:28 INFO : dir/file1.rclone_chunk.001_z387fj: Moved (server side) 2020/07/24 10:21:28 INFO : dir/file1: Copied (replaced existing) 2020/07/24 10:21:28 DEBUG : dir/file1: vfs cache: fingerprint now "5,2020-07-24 10:21:24 +0000 UTC" 2020/07/24 10:21:28 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/07/24 10:21:28 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:21:28 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/07/24 10:21:29 DEBUG : dir: Looking for writers 2020/07/24 10:21:29 DEBUG : file1: reading active writers 2020/07/24 10:21:29 DEBUG : : Looking for writers 2020/07/24 10:21:29 DEBUG : dir: reading active writers 2020/07/24 10:21:29 DEBUG : >WaitForWriters: 2020/07/24 10:21:29 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleSizeTruncateExisting (23.87s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:21:43 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:21:43 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:21:43 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:21: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:21:46 INFO : dir/file1.rclone_chunk.001_z38q8n: Moved (server side) 2020/07/24 10:21:48 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:21:49 DEBUG : dir/file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:21:49 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:21:49 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:21:49 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:21:49 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:21:49 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:21:49 DEBUG : dir/file1(0xc0003f8b00): _writeAt: size=5, off=0 2020/07/24 10:21:49 DEBUG : dir/file1(0xc0003f8b00): openPending: 2020/07/24 10:21: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:21:49 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:21:49 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:21:49 DEBUG : dir/file1(0xc0003f8b00): >openPending: err= 2020/07/24 10:21:49 DEBUG : dir/file1(0xc0003f8b00): >_writeAt: n=5, err= 2020/07/24 10:21:49 DEBUG : dir/file1(0xc0003f8b00): _writeAt: size=15, off=5 2020/07/24 10:21:49 DEBUG : dir/file1(0xc0003f8b00): >_writeAt: n=15, err= 2020/07/24 10:21:49 DEBUG : dir/file1(0xc0003f8b00): close: 2020/07/24 10:21:49 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [{Pos:0 Size:20}] - present true 2020/07/24 10:21:49 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:21:49.410160863 +0000 UTC m=+488.889420760 2020/07/24 10:21:49 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:21:49 DEBUG : dir/file1(0xc0003f8b00): >close: err= 2020/07/24 10:21:49 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:21:49 DEBUG : dir: Looking for writers 2020/07/24 10:21:49 DEBUG : file1: reading active writers 2020/07/24 10:21:49 DEBUG : : Looking for writers 2020/07/24 10:21:49 DEBUG : dir: reading active writers 2020/07/24 10:21:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:21:49 DEBUG : dir: Looking for writers 2020/07/24 10:21:49 DEBUG : file1: reading active writers 2020/07/24 10:21:49 DEBUG : : Looking for writers 2020/07/24 10:21:49 DEBUG : dir: reading active writers 2020/07/24 10:21:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:21:49 DEBUG : dir: Looking for writers 2020/07/24 10:21:49 DEBUG : file1: reading active writers 2020/07/24 10:21:49 DEBUG : : Looking for writers 2020/07/24 10:21:49 DEBUG : dir: reading active writers 2020/07/24 10:21:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:21:49 DEBUG : dir: Looking for writers 2020/07/24 10:21:49 DEBUG : file1: reading active writers 2020/07/24 10:21:49 DEBUG : : Looking for writers 2020/07/24 10:21:49 DEBUG : dir: reading active writers 2020/07/24 10:21:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:21:49 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:21:49 DEBUG : dir: Looking for writers 2020/07/24 10:21:49 DEBUG : file1: reading active writers 2020/07/24 10:21:49 DEBUG : : Looking for writers 2020/07/24 10:21:49 DEBUG : dir: reading active writers 2020/07/24 10:21:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:21:49 DEBUG : dir: Looking for writers 2020/07/24 10:21:49 DEBUG : file1: reading active writers 2020/07/24 10:21:49 DEBUG : : Looking for writers 2020/07/24 10:21:49 DEBUG : dir: reading active writers 2020/07/24 10:21:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:21:50 DEBUG : dir: Looking for writers 2020/07/24 10:21:50 DEBUG : file1: reading active writers 2020/07/24 10:21:50 DEBUG : : Looking for writers 2020/07/24 10:21:50 DEBUG : dir: reading active writers 2020/07/24 10:21:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:21:50 DEBUG : dir: Looking for writers 2020/07/24 10:21:50 DEBUG : file1: reading active writers 2020/07/24 10:21:50 DEBUG : : Looking for writers 2020/07/24 10:21:50 DEBUG : dir: reading active writers 2020/07/24 10:21:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:21:51 DEBUG : dir: Looking for writers 2020/07/24 10:21:51 DEBUG : file1: reading active writers 2020/07/24 10:21:51 DEBUG : : Looking for writers 2020/07/24 10:21:51 DEBUG : dir: reading active writers 2020/07/24 10:21:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:21:52 DEBUG : dir: Looking for writers 2020/07/24 10:21:52 DEBUG : file1: reading active writers 2020/07/24 10:21:52 DEBUG : : Looking for writers 2020/07/24 10:21:52 DEBUG : dir: reading active writers 2020/07/24 10:21:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:21:53 INFO : dir/file1: Deleted 2020/07/24 10:21:53 INFO : dir/file1.rclone_chunk.001_z38w5b: Moved (server side) 2020/07/24 10:21:53 INFO : dir/file1: Copied (replaced existing) 2020/07/24 10:21:53 DEBUG : dir/file1: vfs cache: fingerprint now "20,2020-07-24 10:21:49 +0000 UTC" 2020/07/24 10:21:53 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/07/24 10:21:53 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:21:53 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/07/24 10:21:53 DEBUG : dir: Looking for writers 2020/07/24 10:21:53 DEBUG : file1: reading active writers 2020/07/24 10:21:53 DEBUG : : Looking for writers 2020/07/24 10:21:53 DEBUG : dir: reading active writers 2020/07/24 10:21:53 DEBUG : >WaitForWriters: 2020/07/24 10:21:53 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleSizeCreateExisting (24.45s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:22:07 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:22:07 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:22:07 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:22:07 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:22:07 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:22:07 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:22:07 DEBUG : file1: newRWFileHandle: 2020/07/24 10:22:07 DEBUG : file1(0xc00013e180): openPending: 2020/07/24 10:22:07 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:22:07 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:22:07 DEBUG : file1(0xc00013e180): >openPending: err= 2020/07/24 10:22:07 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:22:07 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:22:07 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:22:07 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:22:07 DEBUG : file1(0xc00013e180): _writeAt: size=5, off=0 2020/07/24 10:22:07 DEBUG : file1(0xc00013e180): >_writeAt: n=5, err= 2020/07/24 10:22:07 DEBUG : file1(0xc00013e180): close: 2020/07/24 10:22:07 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:22:07.936402991 +0000 UTC m=+507.415662817 2020/07/24 10:22:07 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:22:07 DEBUG : file1(0xc00013e180): >close: err= 2020/07/24 10:22:07 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:22:07 DEBUG : dir: Looking for writers 2020/07/24 10:22:07 DEBUG : : Looking for writers 2020/07/24 10:22:07 DEBUG : file1: reading active writers 2020/07/24 10:22:07 DEBUG : dir: reading active writers 2020/07/24 10:22:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:22:07 DEBUG : dir: Looking for writers 2020/07/24 10:22:07 DEBUG : : Looking for writers 2020/07/24 10:22:07 DEBUG : dir: reading active writers 2020/07/24 10:22:07 DEBUG : file1: reading active writers 2020/07/24 10:22:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:22:07 DEBUG : dir: Looking for writers 2020/07/24 10:22:07 DEBUG : : Looking for writers 2020/07/24 10:22:07 DEBUG : dir: reading active writers 2020/07/24 10:22:07 DEBUG : file1: reading active writers 2020/07/24 10:22:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:22:08 DEBUG : dir: Looking for writers 2020/07/24 10:22:08 DEBUG : : Looking for writers 2020/07/24 10:22:08 DEBUG : dir: reading active writers 2020/07/24 10:22:08 DEBUG : file1: reading active writers 2020/07/24 10:22:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:22:08 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:22:08 DEBUG : dir: Looking for writers 2020/07/24 10:22:08 DEBUG : : Looking for writers 2020/07/24 10:22:08 DEBUG : dir: reading active writers 2020/07/24 10:22:08 DEBUG : file1: reading active writers 2020/07/24 10:22:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:22:08 DEBUG : dir: Looking for writers 2020/07/24 10:22:08 DEBUG : : Looking for writers 2020/07/24 10:22:08 DEBUG : dir: reading active writers 2020/07/24 10:22:08 DEBUG : file1: reading active writers 2020/07/24 10:22:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:22:08 DEBUG : dir: Looking for writers 2020/07/24 10:22:08 DEBUG : : Looking for writers 2020/07/24 10:22:08 DEBUG : dir: reading active writers 2020/07/24 10:22:08 DEBUG : file1: reading active writers 2020/07/24 10:22:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:22:09 DEBUG : dir: Looking for writers 2020/07/24 10:22:09 DEBUG : : Looking for writers 2020/07/24 10:22:09 DEBUG : dir: reading active writers 2020/07/24 10:22:09 DEBUG : file1: reading active writers 2020/07/24 10:22:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:22:10 DEBUG : dir: Looking for writers 2020/07/24 10:22:10 DEBUG : : Looking for writers 2020/07/24 10:22:10 DEBUG : dir: reading active writers 2020/07/24 10:22:10 DEBUG : file1: reading active writers 2020/07/24 10:22:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:22:11 INFO : file1.rclone_chunk.001_z39fe9: Moved (server side) 2020/07/24 10:22:11 INFO : file1: Copied (new) 2020/07/24 10:22:11 DEBUG : file1: vfs cache: fingerprint now "5,2020-07-24 10:22:07 +0000 UTC" 2020/07/24 10:22:11 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:22:11 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:22:11 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:22:11 DEBUG : dir: Looking for writers 2020/07/24 10:22:11 DEBUG : : Looking for writers 2020/07/24 10:22:11 DEBUG : dir: reading active writers 2020/07/24 10:22:11 DEBUG : file1: reading active writers 2020/07/24 10:22:11 DEBUG : >WaitForWriters: 2020/07/24 10:22:11 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleSizeCreateNew (17.34s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:22:24 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:22:24 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:22:24 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:22:25 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:22:25 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:22:25 DEBUG : : Looking for writers 2020/07/24 10:22:25 DEBUG : >WaitForWriters: 2020/07/24 10:22:25 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileHandleOpenTests (13.44s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:22:38 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:22:38 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:22:38 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:22:38 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:22:38 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:22:38 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:22:38 DEBUG : file1: newRWFileHandle: 2020/07/24 10:22:38 DEBUG : file1(0xc0003f8080): openPending: 2020/07/24 10:22:38 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:22:38 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:22:38 DEBUG : file1(0xc0003f8080): >openPending: err= 2020/07/24 10:22:38 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:22:38 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:22:38 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:22:38 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:22:41 INFO : time_test.rclone_chunk.001_z3a9fd: Moved (server side) 2020/07/24 10:22:43 DEBUG : Can set mod time: true 2020/07/24 10:22:43 DEBUG : file1(0xc0003f8080): _writeAt: size=2, off=0 2020/07/24 10:22:43 DEBUG : file1(0xc0003f8080): >_writeAt: n=2, err= 2020/07/24 10:22:43 DEBUG : file1(0xc0003f8080): RWFileHandle.Flush 2020/07/24 10:22:43 DEBUG : file1(0xc0003f8080): RWFileHandle.Release 2020/07/24 10:22:43 DEBUG : file1(0xc0003f8080): close: 2020/07/24 10:22:43 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:22:43.204046496 +0000 UTC m=+542.683306325 2020/07/24 10:22:43 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:22:43 DEBUG : file1(0xc0003f8080): >close: err= 2020/07/24 10:22:43 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:22:43 DEBUG : dir: Looking for writers 2020/07/24 10:22:43 DEBUG : : Looking for writers 2020/07/24 10:22:43 DEBUG : file1: reading active writers 2020/07/24 10:22:43 DEBUG : dir: reading active writers 2020/07/24 10:22:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:22:43 DEBUG : dir: Looking for writers 2020/07/24 10:22:43 DEBUG : : Looking for writers 2020/07/24 10:22:43 DEBUG : dir: reading active writers 2020/07/24 10:22:43 DEBUG : file1: reading active writers 2020/07/24 10:22:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:22:43 DEBUG : dir: Looking for writers 2020/07/24 10:22:43 DEBUG : : Looking for writers 2020/07/24 10:22:43 DEBUG : dir: reading active writers 2020/07/24 10:22:43 DEBUG : file1: reading active writers 2020/07/24 10:22:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:22:43 DEBUG : dir: Looking for writers 2020/07/24 10:22:43 DEBUG : : Looking for writers 2020/07/24 10:22:43 DEBUG : dir: reading active writers 2020/07/24 10:22:43 DEBUG : file1: reading active writers 2020/07/24 10:22:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:22:43 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:22:43 DEBUG : dir: Looking for writers 2020/07/24 10:22:43 DEBUG : : Looking for writers 2020/07/24 10:22:43 DEBUG : file1: reading active writers 2020/07/24 10:22:43 DEBUG : dir: reading active writers 2020/07/24 10:22:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:22:43 DEBUG : dir: Looking for writers 2020/07/24 10:22:43 DEBUG : : Looking for writers 2020/07/24 10:22:43 DEBUG : dir: reading active writers 2020/07/24 10:22:43 DEBUG : file1: reading active writers 2020/07/24 10:22:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:22:43 DEBUG : dir: Looking for writers 2020/07/24 10:22:43 DEBUG : : Looking for writers 2020/07/24 10:22:43 DEBUG : dir: reading active writers 2020/07/24 10:22:43 DEBUG : file1: reading active writers 2020/07/24 10:22:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:22:44 DEBUG : dir: Looking for writers 2020/07/24 10:22:44 DEBUG : : Looking for writers 2020/07/24 10:22:44 DEBUG : dir: reading active writers 2020/07/24 10:22:44 DEBUG : file1: reading active writers 2020/07/24 10:22:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:22:45 DEBUG : dir: Looking for writers 2020/07/24 10:22:45 DEBUG : : Looking for writers 2020/07/24 10:22:45 DEBUG : dir: reading active writers 2020/07/24 10:22:45 DEBUG : file1: reading active writers 2020/07/24 10:22:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:22:46 DEBUG : dir: Looking for writers 2020/07/24 10:22:46 DEBUG : : Looking for writers 2020/07/24 10:22:46 DEBUG : dir: reading active writers 2020/07/24 10:22:46 DEBUG : file1: reading active writers 2020/07/24 10:22:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:22:46 INFO : file1.rclone_chunk.001_z3ae7c: Moved (server side) 2020/07/24 10:22:46 INFO : file1: Copied (new) 2020/07/24 10:22:46 DEBUG : file1: vfs cache: fingerprint now "2,2020-07-24 10:22:43 +0000 UTC" 2020/07/24 10:22:46 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:22:47 DEBUG : file1: File._applyPendingModTime OK 2020/07/24 10:22:47 DEBUG : file1: vfs cache: fingerprint now "2,2012-11-18 17:32:31 +0000 UTC" 2020/07/24 10:22:47 DEBUG : file1: vfs cache: setting modification time to 2012-11-18 17:32:31 +0000 UTC 2020/07/24 10:22:47 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:22:47 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:22:47 DEBUG : dir: Looking for writers 2020/07/24 10:22:47 DEBUG : : Looking for writers 2020/07/24 10:22:47 DEBUG : dir: reading active writers 2020/07/24 10:22:47 DEBUG : file1: reading active writers 2020/07/24 10:22:47 DEBUG : >WaitForWriters: 2020/07/24 10:22:48 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:22:48 DEBUG : dir: Looking for writers 2020/07/24 10:22:48 DEBUG : : Looking for writers 2020/07/24 10:22:48 DEBUG : dir: reading active writers 2020/07/24 10:22:48 DEBUG : file1: reading active writers 2020/07/24 10:22:48 DEBUG : >WaitForWriters: 2020/07/24 10:22:48 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileModTimeWithOpenWriters (23.58s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:23:02 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:23:02 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:23:02 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bBox/rclone-test-dacesey9sazifev8jotomov9" 2020/07/24 10:23:02 DEBUG : rename_me: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:23: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:23:02 DEBUG : rename_me: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:23:02 DEBUG : rename_me: newRWFileHandle: 2020/07/24 10:23:02 DEBUG : rename_me(0xc00075e100): openPending: 2020/07/24 10:23:02 DEBUG : rename_me: vfs cache: truncate to size=0 2020/07/24 10:23:02 DEBUG : : Added virtual directory entry vAdd: "rename_me" 2020/07/24 10:23:02 DEBUG : rename_me(0xc00075e100): >openPending: err= 2020/07/24 10:23:02 DEBUG : rename_me: >newRWFileHandle: err= 2020/07/24 10:23:02 DEBUG : : Added virtual directory entry vAdd: "rename_me" 2020/07/24 10:23:02 DEBUG : rename_me: >Open: fd=rename_me (rw), err= 2020/07/24 10:23:02 DEBUG : rename_me: >OpenFile: fd=rename_me (rw), err= 2020/07/24 10:23:02 DEBUG : rename_me(0xc00075e100): _writeAt: size=5, off=0 2020/07/24 10:23:02 DEBUG : rename_me(0xc00075e100): >_writeAt: n=5, err= 2020/07/24 10:23:02 DEBUG : rename_me(0xc00075e100): close: 2020/07/24 10:23:02 DEBUG : rename_me: vfs cache: setting modification time to 2020-07-24 10:23:02.318505374 +0000 UTC m=+561.797765216 2020/07/24 10:23:02 INFO : rename_me: vfs cache: queuing for upload in 100ms 2020/07/24 10:23:02 DEBUG : rename_me(0xc00075e100): >close: err= 2020/07/24 10:23:02 INFO : rename_me: vfs cache: renamed in cache to "i_was_renamed" 2020/07/24 10:23:02 DEBUG : i_was_renamed: Updating file with 0xc00021c540 2020/07/24 10:23:02 DEBUG : : Added virtual directory entry vDel: "rename_me" 2020/07/24 10:23:02 DEBUG : : Added virtual directory entry vAdd: "i_was_renamed" 2020/07/24 10:23:02 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:23:02 DEBUG : dir: Looking for writers 2020/07/24 10:23:02 DEBUG : : Looking for writers 2020/07/24 10:23:02 DEBUG : dir: reading active writers 2020/07/24 10:23:02 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:23:02 DEBUG : dir: Looking for writers 2020/07/24 10:23:02 DEBUG : : Looking for writers 2020/07/24 10:23:02 DEBUG : dir: reading active writers 2020/07/24 10:23:02 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:23:02 DEBUG : dir: Looking for writers 2020/07/24 10:23:02 DEBUG : : Looking for writers 2020/07/24 10:23:02 DEBUG : dir: reading active writers 2020/07/24 10:23:02 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:23:02 DEBUG : dir: Looking for writers 2020/07/24 10:23:02 DEBUG : : Looking for writers 2020/07/24 10:23:02 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:02 DEBUG : dir: reading active writers 2020/07/24 10:23:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:23:02 DEBUG : i_was_renamed: vfs cache: starting upload 2020/07/24 10:23:02 DEBUG : dir: Looking for writers 2020/07/24 10:23:02 DEBUG : : Looking for writers 2020/07/24 10:23:02 DEBUG : dir: reading active writers 2020/07/24 10:23:02 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:23:02 DEBUG : dir: Looking for writers 2020/07/24 10:23:02 DEBUG : : Looking for writers 2020/07/24 10:23:02 DEBUG : dir: reading active writers 2020/07/24 10:23:02 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:23:02 DEBUG : dir: Looking for writers 2020/07/24 10:23:02 DEBUG : : Looking for writers 2020/07/24 10:23:02 DEBUG : dir: reading active writers 2020/07/24 10:23:02 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/07/24 10:23:03 DEBUG : dir: Looking for writers 2020/07/24 10:23:03 DEBUG : : Looking for writers 2020/07/24 10:23:03 DEBUG : dir: reading active writers 2020/07/24 10:23:03 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:23:04 DEBUG : dir: Looking for writers 2020/07/24 10:23:04 DEBUG : : Looking for writers 2020/07/24 10:23:04 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:04 DEBUG : dir: reading active writers 2020/07/24 10:23:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:23:05 DEBUG : dir: Looking for writers 2020/07/24 10:23:05 DEBUG : : Looking for writers 2020/07/24 10:23:05 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:05 DEBUG : dir: reading active writers 2020/07/24 10:23:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:23:06 DEBUG : dir: Looking for writers 2020/07/24 10:23:06 DEBUG : : Looking for writers 2020/07/24 10:23:06 DEBUG : dir: reading active writers 2020/07/24 10:23:06 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/07/24 10:23:07 INFO : i_was_renamed.rclone_chunk.001_z3ax2n: Moved (server side) 2020/07/24 10:23:07 INFO : i_was_renamed: Copied (new) 2020/07/24 10:23:07 DEBUG : i_was_renamed: vfs cache: fingerprint now "5,2020-07-24 10:23:02 +0000 UTC" 2020/07/24 10:23:07 DEBUG : i_was_renamed: vfs cache: writeback object to VFS layer 2020/07/24 10:23:07 DEBUG : : Added virtual directory entry vAdd: "i_was_renamed" 2020/07/24 10:23:07 INFO : i_was_renamed: vfs cache: upload succeeded try #1 2020/07/24 10:23:07 DEBUG : dir: Looking for writers 2020/07/24 10:23:07 DEBUG : : Looking for writers 2020/07/24 10:23:07 DEBUG : dir: reading active writers 2020/07/24 10:23:07 DEBUG : i_was_renamed: reading active writers 2020/07/24 10:23:07 DEBUG : >WaitForWriters: 2020/07/24 10:23:07 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWCacheRename (19.75s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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 (13.68s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", 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: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:23:35 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:23:35 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': Re-using VFS from active cache 2020/07/24 10:23:35 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:23:35 DEBUG : : Looking for writers 2020/07/24 10:23:35 DEBUG : >WaitForWriters: --- FAIL: TestVFSNew (15.23s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:23:50 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:23:50 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:23:50 DEBUG : : Looking for writers 2020/07/24 10:23:50 DEBUG : >WaitForWriters: --- FAIL: TestVFSNewWithOpts (13.27s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:24:03 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:24:03 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:24:03 DEBUG : : Looking for writers 2020/07/24 10:24:03 DEBUG : >WaitForWriters: --- FAIL: TestVFSRoot (15.68s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:24:19 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:24:22 INFO : file1.rclone_chunk.001_z3d214: Moved (server side) 2020/07/24 10:24:26 INFO : dir/file2.rclone_chunk.001_z3d5pn: Moved (server side) 2020/07/24 10:24:27 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:24:27 DEBUG : dir: Looking for writers 2020/07/24 10:24:27 DEBUG : file2: reading active writers 2020/07/24 10:24:27 DEBUG : : Looking for writers 2020/07/24 10:24:27 DEBUG : dir: reading active writers 2020/07/24 10:24:27 DEBUG : file1: reading active writers 2020/07/24 10:24:27 DEBUG : >WaitForWriters: --- FAIL: TestVFSStat (23.90s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:24:43 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:24:46 INFO : file1.rclone_chunk.001_z3dquw: Moved (server side) 2020/07/24 10:24:49 INFO : dir/file2.rclone_chunk.001_z3dtx5: Moved (server side) 2020/07/24 10:24:50 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:24:50 DEBUG : dir: Looking for writers 2020/07/24 10:24:50 DEBUG : : Looking for writers 2020/07/24 10:24:50 DEBUG : dir: reading active writers 2020/07/24 10:24:50 DEBUG : file1: reading active writers 2020/07/24 10:24:50 DEBUG : >WaitForWriters: --- FAIL: TestVFSStatParent (23.73s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:25:07 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:25:10 INFO : file1.rclone_chunk.001_z3ee0u: Moved (server side) 2020/07/24 10:25:13 INFO : dir/file2.rclone_chunk.001_z3ehry: Moved (server side) 2020/07/24 10:25:13 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:25:14 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:25:14 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:25:14 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:25:14 DEBUG : dir: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:25:14 DEBUG : dir: >OpenFile: fd=dir/ (r), err= 2020/07/24 10:25:14 DEBUG : dir/new_file.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:25:14 DEBUG : dir/new_file.txt: >OpenFile: fd=, err=file does not exist 2020/07/24 10:25:14 DEBUG : dir/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:25:14 DEBUG : dir/new_file.txt: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:25:14 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:25:14 DEBUG : dir/new_file.txt: >Open: fd=dir/new_file.txt (w), err= 2020/07/24 10:25:14 DEBUG : dir/new_file.txt: >OpenFile: fd=dir/new_file.txt (w), err= 2020/07/24 10:25:14 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:25:14 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:25:17 INFO : dir/new_file.txt.rclone_chunk.001_z3el4c: Moved (server side) 2020/07/24 10:25:17 INFO : dir/new_file.txt: Copied (new) 2020/07/24 10:25:17 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:25:17 DEBUG : not found/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:25:17 DEBUG : not found/new_file.txt: >OpenFile: fd=, err=file does not exist 2020/07/24 10:25:17 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:25:17 DEBUG : dir: Looking for writers 2020/07/24 10:25:17 DEBUG : file2: reading active writers 2020/07/24 10:25:17 DEBUG : new_file.txt: reading active writers 2020/07/24 10:25:17 DEBUG : : Looking for writers 2020/07/24 10:25:17 DEBUG : dir: reading active writers 2020/07/24 10:25:17 DEBUG : file1: reading active writers 2020/07/24 10:25:17 DEBUG : >WaitForWriters: --- FAIL: TestVFSOpenFile (25.54s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:25:32 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:25:37 INFO : dir/file2.rclone_chunk.001_z3f38v: Moved (server side) 2020/07/24 10:25:40 DEBUG : dir/file2: move non-chunked object... 2020/07/24 10:25:40 INFO : dir/file2: Moved (server side) 2020/07/24 10:25:40 INFO : dir/file2: Moved (server side) 2020/07/24 10:25:40 DEBUG : dir/file1: Updating file with dir/file1 0xc000834000 2020/07/24 10:25:40 DEBUG : dir: Added virtual directory entry vDel: "file2" 2020/07/24 10:25:40 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:25:41 DEBUG : dir/file1: move non-chunked object... 2020/07/24 10:25:42 INFO : dir/file1: Moved (server side) 2020/07/24 10:25:42 INFO : dir/file1: Moved (server side) 2020/07/24 10:25:42 DEBUG : file0: Updating file with file0 0xc000834000 2020/07/24 10:25:42 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:25:42 DEBUG : : Added virtual directory entry vAdd: "file0" 2020/07/24 10:25:43 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:25:43 DEBUG : dir: Looking for writers 2020/07/24 10:25:43 DEBUG : : Looking for writers 2020/07/24 10:25:43 DEBUG : dir: reading active writers 2020/07/24 10:25:43 DEBUG : file0: reading active writers 2020/07/24 10:25:43 DEBUG : >WaitForWriters: --- FAIL: TestVFSRename (24.60s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:25:57 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:25:57 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:25:57 DEBUG : : Looking for writers 2020/07/24 10:25:57 DEBUG : >WaitForWriters: --- FAIL: TestVFSStatfs (15.14s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:26:12 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:26:12 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:26:12 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:26:12 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:12 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:26:12 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:26:12 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:12 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2020/07/24 10:26:12 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2020/07/24 10:26:12 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2020/07/24 10:26:12 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (5 bytes), uploading instead of streaming 2020/07/24 10:26:16 INFO : file1.rclone_chunk.001_z3g7wm: Moved (server side) 2020/07/24 10:26:16 INFO : file1: Copied (new) 2020/07/24 10:26:16 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:25 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:26:25 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:26:25 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:25 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:26:25 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:26:25 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:26:25 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:26:25 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:25 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:26:25 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:26:25 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes 2020/07/24 10:26:25 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:26:25 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/07/24 10:26:25 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:25 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:26:25 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:26:25 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:25 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:26:29 INFO : file1: Deleted 2020/07/24 10:26:30 INFO : file1.rclone_chunk.001_z3gk9k: Moved (server side) 2020/07/24 10:26:30 INFO : file1: Copied (new) 2020/07/24 10:26:30 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:26:30 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/07/24 10:26:30 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:30 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:26:30 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:26:30 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:30 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (7 bytes), uploading instead of streaming 2020/07/24 10:26:34 INFO : file1: Deleted 2020/07/24 10:26:34 INFO : file1.rclone_chunk.001_z3gp90: Moved (server side) 2020/07/24 10:26:34 INFO : file1: Copied (new) 2020/07/24 10:26:34 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:34 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:26:34 DEBUG : dir: Looking for writers 2020/07/24 10:26:34 DEBUG : : Looking for writers 2020/07/24 10:26:34 DEBUG : dir: reading active writers 2020/07/24 10:26:34 DEBUG : file1: reading active writers 2020/07/24 10:26:34 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleMethods (36.75s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", 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: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:26:49 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:26:49 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:26:49 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:26:49 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:49 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:26:49 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:26:49 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:49 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2020/07/24 10:26:50 DEBUG : file1: aborting in-sequence write wait, off=100 2020/07/24 10:26:50 DEBUG : file1: failed to wait for in-sequence write to 100 2020/07/24 10:26:50 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2020/07/24 10:26:50 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (11 bytes), uploading instead of streaming 2020/07/24 10:26:53 INFO : file1.rclone_chunk.001_z3h9ht: Moved (server side) 2020/07/24 10:26:53 INFO : file1: Copied (new) 2020/07/24 10:26:53 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:26:53 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor 2020/07/24 10:27:02 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:02 DEBUG : dir: Looking for writers 2020/07/24 10:27:02 DEBUG : : Looking for writers 2020/07/24 10:27:02 DEBUG : dir: reading active writers 2020/07/24 10:27:02 DEBUG : file1: reading active writers 2020/07/24 10:27:02 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleWriteAt (27.50s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", 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: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:27:16 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:27:16 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:27:17 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:27:17 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:17 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:27:17 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:27:17 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2020/07/24 10:27:17 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:17 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (5 bytes), uploading instead of streaming 2020/07/24 10:27:20 INFO : file1.rclone_chunk.001_z3i0b2: Moved (server side) 2020/07/24 10:27:20 INFO : file1: Copied (new) 2020/07/24 10:27:20 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:20 DEBUG : file1: WriteFileHandle.Flush nothing to do 2020/07/24 10:27:20 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:20 DEBUG : dir: Looking for writers 2020/07/24 10:27:20 DEBUG : : Looking for writers 2020/07/24 10:27:20 DEBUG : dir: reading active writers 2020/07/24 10:27:20 DEBUG : file1: reading active writers 2020/07/24 10:27:20 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleFlush (17.40s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", 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: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:27:34 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:27:34 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:27:34 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:27:34 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:34 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:27:34 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:27:34 DEBUG : file1: WriteFileHandle.Release closing 2020/07/24 10:27:34 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:34 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:27:38 INFO : file1.rclone_chunk.001_z3ihvz: Moved (server side) 2020/07/24 10:27:38 INFO : file1: Copied (new) 2020/07/24 10:27:38 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:38 DEBUG : file1: WriteFileHandle.Release nothing to do 2020/07/24 10:27:38 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:38 DEBUG : dir: Looking for writers 2020/07/24 10:27:38 DEBUG : : Looking for writers 2020/07/24 10:27:38 DEBUG : file1: reading active writers 2020/07/24 10:27:38 DEBUG : dir: reading active writers 2020/07/24 10:27:38 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleRelease (20.97s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:27:55 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:27:55 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:27:55 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:27:55 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:55 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:27:55 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:27:55 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:55 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (2 bytes), uploading instead of streaming 2020/07/24 10:27:58 INFO : file1.rclone_chunk.001_z3j20g: Moved (server side) 2020/07/24 10:27:58 INFO : file1: Copied (new) 2020/07/24 10:27:59 DEBUG : file1: File._applyPendingModTime OK 2020/07/24 10:27:59 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:59 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:59 DEBUG : dir: Looking for writers 2020/07/24 10:27:59 DEBUG : : Looking for writers 2020/07/24 10:27:59 DEBUG : dir: reading active writers 2020/07/24 10:27:59 DEBUG : file1: reading active writers 2020/07/24 10:27:59 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileModTimeWithOpenWriters (17.88s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:28:13 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:28:13 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:28:13 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:28:13 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:13 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:28:13 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:28:13 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:13 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:28:16 INFO : file1.rclone_chunk.001_z3jkwm: Moved (server side) 2020/07/24 10:28:16 INFO : file1: Copied (new) 2020/07/24 10:28:16 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:16 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/07/24 10:28:16 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:28:16 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:28:16 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:28:16 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:16 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:16 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:16 DEBUG : dir: Looking for writers 2020/07/24 10:28:16 DEBUG : : Looking for writers 2020/07/24 10:28:16 DEBUG : dir: reading active writers 2020/07/24 10:28:16 DEBUG : file1: reading active writers 2020/07/24 10:28:16 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtZeroLength (18.60s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:28:31 INFO : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': poll-interval is not supported by this remote 2020/07/24 10:28:31 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:28:31 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:28:31 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:31 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:28:31 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:28:31 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:31 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': File to upload is small (100 bytes), uploading instead of streaming 2020/07/24 10:28:36 INFO : file1.rclone_chunk.001_z3k2w4: Moved (server side) 2020/07/24 10:28:36 INFO : file1.rclone_chunk.002_z3k2w4: Moved (server side) 2020/07/24 10:28:38 INFO : file1: Copied (new) 2020/07/24 10:28:38 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:38 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/07/24 10:28:38 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:28:38 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:28:38 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:28:38 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:41 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:41 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:41 DEBUG : dir: Looking for writers 2020/07/24 10:28:41 DEBUG : : Looking for writers 2020/07/24 10:28:41 DEBUG : file1: reading active writers 2020/07/24 10:28:41 DEBUG : dir: reading active writers 2020/07/24 10:28:41 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtNonZeroLength (26.32s) run.go:176: Remote "Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9'", Local "Local file system at /tmp/rclone769904233", Modify Window "1s" run.go:121: removing dir "dir" failed - try 1/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 2/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:121: removing dir "dir" failed - try 3/3: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder not empty run.go:124: removing dir "dir" failed: rmdir failed: Error "folder_not_empty" (400): Cannot delete - folder 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:28:57 DEBUG : Chunked 'TestChunkerChunk50bBox:rclone-test-dacesey9sazifev8jotomov9': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bBox: -verbose -size-limit 1024 -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 15m18.637784171s (try 3/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]