"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bMailru: -verbose -size-limit 10240 -test.run '^(TestCaseSensitivity|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRename|TestRWCacheRename|TestRWFileHandleFlushRead|TestRWFileHandleFlushWrite|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleOpenTests|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleReleaseWrite|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeCreateNew|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestVFSNew|TestVFSNewWithOpts|TestVFSOpenFile|TestVFSRename|TestVFSRoot|TestVFSStat|TestVFSStatParent|TestVFSStatfs|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(full,forceCache=false|minimal,forceCache=true|writes,forceCache=false|writes,forceCache=true)$'" - Starting (try 4/5) === RUN TestFileRename === RUN TestFileRename/minimal,forceCache=true run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:03:22 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:03:22 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:03:22 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:03:22 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:03:22 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: new meta server: https://cld-extapi2.datacloudmail.ru/meta/ 2020/08/16 06:03:23 INFO : dir/file1.rclone_chunk.001_5cmkdm: Moved (server side) 2020/08/16 06:03:24 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/08/16 06:03:24 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510880): openPending: 2020/08/16 06:03:24 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:03:24 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:03:24 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510880): >openPending: err= 2020/08/16 06:03:24 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:03:24 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:03:24 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:24 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510880): _writeAt: size=14, off=0 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510880): >_writeAt: n=14, err= 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510880): close: 2020/08/16 06:03:24 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:03:24 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:03:24.498782314 +0000 UTC m=+2.417260852 2020/08/16 06:03:24 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510880): >close: err= 2020/08/16 06:03:24 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:03:24 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:03:24 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:03:24 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510b00): _readAt: size=512, off=0 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510b00): openPending: 2020/08/16 06:03:24 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/08/16 06:03:24 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:03:24 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510b00): >openPending: err= 2020/08/16 06:03:24 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510b00): >_readAt: n=14, err=EOF 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510b00): close: 2020/08/16 06:03:24 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:03:24 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:03:24.498782314 +0000 UTC m=+2.417260852 2020/08/16 06:03:24 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:03:24 DEBUG : dir/file1(0xc000510b00): >close: err= 2020/08/16 06:03:24 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:03:24 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:03:25 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:25 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:25 DEBUG : dir/file1: vfs cache: cancelling upload 2020/08/16 06:03:25 ERROR : dir/file1.rclone_chunk.001_5cml08: Couldn't move: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:25 ERROR : dir/file1.rclone_chunk.001_5cml08: Failed to remove temporary chunk: Post "https://cloud.mail.ru/api/m1/file/remove?access_token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:25 ERROR : dir/file1: Failed to copy: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:25 INFO : dir/file1: vfs cache: upload canceled 2020/08/16 06:03:25 DEBUG : dir/file1: vfs cache: cancelled upload 2020/08/16 06:03:25 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:03:25 DEBUG : newLeaf: Updating file with newLeaf 0xc00019e600 2020/08/16 06:03:25 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:03:25 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:03:25 DEBUG : newLeaf: vfs cache: starting upload 2020/08/16 06:03:25 DEBUG : newLeaf: move non-chunked object... 2020/08/16 06:03:26 INFO : newLeaf: Moved (server side) 2020/08/16 06:03:26 INFO : newLeaf: Moved (server side) 2020/08/16 06:03:26 DEBUG : newLeaf: vfs cache: cancelling upload 2020/08/16 06:03:26 ERROR : newLeaf.rclone_chunk.001_5cmm5l: Couldn't move: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:26 ERROR : newLeaf.rclone_chunk.001_5cmm5l: Failed to remove temporary chunk: Post "https://cloud.mail.ru/api/m1/file/remove?access_token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:26 ERROR : newLeaf: Failed to copy: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:26 INFO : newLeaf: vfs cache: upload canceled 2020/08/16 06:03:26 DEBUG : newLeaf: vfs cache: cancelled upload 2020/08/16 06:03:26 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/08/16 06:03:26 DEBUG : dir/file1: Updating file with dir/file1 0xc00019e600 2020/08/16 06:03:26 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/08/16 06:03:26 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:26 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:03:26 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/08/16 06:03:26 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:03:26 DEBUG : dir/file1(0xc000090500): openPending: 2020/08/16 06:03:26 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/08/16 06:03:26 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:03:26 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:26 DEBUG : dir/file1(0xc000090500): >openPending: err= 2020/08/16 06:03:26 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:03:26 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc0001985b0 item 1 2020/08/16 06:03:26 DEBUG : dir/file1: vfs cache: cancelling upload 2020/08/16 06:03:26 ERROR : dir/file1: Failed to copy: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:26 INFO : dir/file1: vfs cache: upload canceled 2020/08/16 06:03:26 DEBUG : dir/file1: vfs cache: cancelled upload 2020/08/16 06:03:26 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:03:26 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:03:26 DEBUG : dir/file1(0xc000090500): _writeAt: size=25, off=0 2020/08/16 06:03:26 DEBUG : dir/file1(0xc000090500): >_writeAt: n=25, err= 2020/08/16 06:03:26 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:03:27 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:27 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:27 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:03:27 DEBUG : newLeaf: Updating file with newLeaf 0xc00019e600 2020/08/16 06:03:27 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:03:27 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:03:27 DEBUG : newLeaf(0xc000090500): close: 2020/08/16 06:03:27 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/08/16 06:03:27 DEBUG : newLeaf: vfs cache: setting modification time to 2020-08-16 06:03:26.473025925 +0000 UTC m=+4.391504450 2020/08/16 06:03:27 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/08/16 06:03:27 DEBUG : newLeaf(0xc000090500): >close: err= 2020/08/16 06:03:27 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:03:27 DEBUG : dir: Looking for writers 2020/08/16 06:03:27 DEBUG : : Looking for writers 2020/08/16 06:03:27 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:27 DEBUG : dir: reading active writers 2020/08/16 06:03:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:03:27 DEBUG : dir: Looking for writers 2020/08/16 06:03:27 DEBUG : : Looking for writers 2020/08/16 06:03:27 DEBUG : dir: reading active writers 2020/08/16 06:03:27 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:03:27 DEBUG : dir: Looking for writers 2020/08/16 06:03:27 DEBUG : : Looking for writers 2020/08/16 06:03:27 DEBUG : dir: reading active writers 2020/08/16 06:03:27 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:03:27 DEBUG : dir: Looking for writers 2020/08/16 06:03:27 DEBUG : : Looking for writers 2020/08/16 06:03:27 DEBUG : dir: reading active writers 2020/08/16 06:03:27 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:03:27 DEBUG : newLeaf: vfs cache: starting upload 2020/08/16 06:03:27 DEBUG : dir: Looking for writers 2020/08/16 06:03:27 DEBUG : : Looking for writers 2020/08/16 06:03:27 DEBUG : dir: reading active writers 2020/08/16 06:03:27 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:03:27 DEBUG : dir: Looking for writers 2020/08/16 06:03:27 DEBUG : : Looking for writers 2020/08/16 06:03:27 DEBUG : dir: reading active writers 2020/08/16 06:03:27 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:03:27 DEBUG : newLeaf.rclone_chunk.001_5cmo8l: File has been put by hash from source 2020/08/16 06:03:27 DEBUG : dir: Looking for writers 2020/08/16 06:03:27 DEBUG : : Looking for writers 2020/08/16 06:03:27 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:27 DEBUG : dir: reading active writers 2020/08/16 06:03:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:03:28 INFO : newLeaf: Deleted 2020/08/16 06:03:28 INFO : newLeaf.rclone_chunk.001_5cmo8l: Moved (server side) 2020/08/16 06:03:28 INFO : newLeaf: Copied (replaced existing) 2020/08/16 06:03:28 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-08-16 06:03:26 +0000 UTC" 2020/08/16 06:03:28 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/08/16 06:03:28 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:03:28 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/08/16 06:03:28 DEBUG : dir: Looking for writers 2020/08/16 06:03:28 DEBUG : : Looking for writers 2020/08/16 06:03:28 DEBUG : dir: reading active writers 2020/08/16 06:03:28 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:28 DEBUG : >WaitForWriters: 2020/08/16 06:03:28 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:03:28 DEBUG : dir: Looking for writers 2020/08/16 06:03:28 DEBUG : : Looking for writers 2020/08/16 06:03:28 DEBUG : dir: reading active writers 2020/08/16 06:03:28 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:28 DEBUG : >WaitForWriters: 2020/08/16 06:03:28 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 file_test.go:341 file_test.go:357 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileRename/minimal,forceCache=true Messages: directories === RUN TestFileRename/writes,forceCache=false run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:03:40 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:03:40 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:03:40 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:03:40 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:03:41 INFO : dir/file1.rclone_chunk.001_5cn145: Moved (server side) 2020/08/16 06:03:41 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:03:42 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:42 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:42 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:03:42 DEBUG : newLeaf: Updating file with newLeaf 0xc00014e3c0 2020/08/16 06:03:42 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:03:42 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:03:42 DEBUG : newLeaf: move non-chunked object... 2020/08/16 06:03:42 INFO : newLeaf: Moved (server side) 2020/08/16 06:03:42 INFO : newLeaf: Moved (server side) 2020/08/16 06:03:42 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/08/16 06:03:42 DEBUG : dir/file1: Updating file with dir/file1 0xc00014e3c0 2020/08/16 06:03:42 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/08/16 06:03:42 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:43 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/08/16 06:03:43 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:03:43 DEBUG : dir/file1(0xc0003b4300): openPending: 2020/08/16 06:03:43 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:03:43 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:03:43 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:43 DEBUG : dir/file1(0xc0003b4300): >openPending: err= 2020/08/16 06:03:43 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:03:43 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:03:43 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:03:43 DEBUG : dir/file1(0xc0003b4300): _writeAt: size=25, off=0 2020/08/16 06:03:43 DEBUG : dir/file1(0xc0003b4300): >_writeAt: n=25, err= 2020/08/16 06:03:43 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:03:43 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:43 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:43 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:03:43 DEBUG : newLeaf: Updating file with newLeaf 0xc00014e3c0 2020/08/16 06:03:43 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:03:43 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:03:43 DEBUG : newLeaf(0xc0003b4300): close: 2020/08/16 06:03:43 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/08/16 06:03:43 DEBUG : newLeaf: vfs cache: setting modification time to 2020-08-16 06:03:43.122815856 +0000 UTC m=+21.041294402 2020/08/16 06:03:43 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/08/16 06:03:43 DEBUG : newLeaf(0xc0003b4300): >close: err= 2020/08/16 06:03:43 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:03:43 DEBUG : dir: Looking for writers 2020/08/16 06:03:43 DEBUG : : Looking for writers 2020/08/16 06:03:43 DEBUG : dir: reading active writers 2020/08/16 06:03:43 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:03:43 DEBUG : dir: Looking for writers 2020/08/16 06:03:43 DEBUG : : Looking for writers 2020/08/16 06:03:43 DEBUG : dir: reading active writers 2020/08/16 06:03:43 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:03:43 DEBUG : dir: Looking for writers 2020/08/16 06:03:43 DEBUG : : Looking for writers 2020/08/16 06:03:43 DEBUG : dir: reading active writers 2020/08/16 06:03:43 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:03:43 DEBUG : dir: Looking for writers 2020/08/16 06:03:43 DEBUG : : Looking for writers 2020/08/16 06:03:43 DEBUG : dir: reading active writers 2020/08/16 06:03:43 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:03:43 DEBUG : newLeaf: vfs cache: starting upload 2020/08/16 06:03:43 DEBUG : dir: Looking for writers 2020/08/16 06:03:43 DEBUG : : Looking for writers 2020/08/16 06:03:43 DEBUG : dir: reading active writers 2020/08/16 06:03:43 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:03:43 DEBUG : dir: Looking for writers 2020/08/16 06:03:43 DEBUG : : Looking for writers 2020/08/16 06:03:43 DEBUG : dir: reading active writers 2020/08/16 06:03:43 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:03:43 DEBUG : newLeaf.rclone_chunk.001_5cn4gj: File has been put by hash from source 2020/08/16 06:03:44 DEBUG : dir: Looking for writers 2020/08/16 06:03:44 DEBUG : : Looking for writers 2020/08/16 06:03:44 DEBUG : dir: reading active writers 2020/08/16 06:03:44 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:03:44 INFO : newLeaf: Deleted 2020/08/16 06:03:44 INFO : newLeaf.rclone_chunk.001_5cn4gj: Moved (server side) 2020/08/16 06:03:44 INFO : newLeaf: Copied (replaced existing) 2020/08/16 06:03:44 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-08-16 06:03:43 +0000 UTC" 2020/08/16 06:03:44 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/08/16 06:03:44 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:03:44 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/08/16 06:03:44 DEBUG : dir: Looking for writers 2020/08/16 06:03:44 DEBUG : : Looking for writers 2020/08/16 06:03:44 DEBUG : dir: reading active writers 2020/08/16 06:03:44 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:44 DEBUG : >WaitForWriters: 2020/08/16 06:03:44 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:03:44 DEBUG : dir: Looking for writers 2020/08/16 06:03:44 DEBUG : : Looking for writers 2020/08/16 06:03:44 DEBUG : dir: reading active writers 2020/08/16 06:03:44 DEBUG : newLeaf: reading active writers 2020/08/16 06:03:44 DEBUG : >WaitForWriters: 2020/08/16 06:03:44 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 file_test.go:341 file_test.go:357 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileRename/writes,forceCache=false Messages: directories === RUN TestFileRename/writes,forceCache=true run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:03:56 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:03:56 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:03:56 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:03:56 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:03:57 INFO : dir/file1.rclone_chunk.001_5cnh66: Moved (server side) 2020/08/16 06:03:57 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/08/16 06:03:57 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822d40): openPending: 2020/08/16 06:03:57 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:03:57 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:03:57 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822d40): >openPending: err= 2020/08/16 06:03:57 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:03:57 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:03:57 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:57 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822d40): _writeAt: size=14, off=0 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822d40): >_writeAt: n=14, err= 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822d40): close: 2020/08/16 06:03:57 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:03:57 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:03:57.943592143 +0000 UTC m=+35.862070664 2020/08/16 06:03:57 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822d40): >close: err= 2020/08/16 06:03:57 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:03:57 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:03:57 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:03:57 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822e00): _readAt: size=512, off=0 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822e00): openPending: 2020/08/16 06:03:57 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2020/08/16 06:03:57 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:03:57 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822e00): >openPending: err= 2020/08/16 06:03:57 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822e00): >_readAt: n=14, err=EOF 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822e00): close: 2020/08/16 06:03:57 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:03:57 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:03:57.943592143 +0000 UTC m=+35.862070664 2020/08/16 06:03:57 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:03:57 DEBUG : dir/file1(0xc000822e00): >close: err= 2020/08/16 06:03:58 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:03:58 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:03:58 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:58 INFO : dir/file1: Moved (server side) 2020/08/16 06:03:58 DEBUG : dir/file1: vfs cache: cancelling upload 2020/08/16 06:03:58 ERROR : dir/file1.rclone_chunk.001_5cnjy3: Couldn't move: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:58 ERROR : dir/file1.rclone_chunk.001_5cnjy3: Failed to remove temporary chunk: Post "https://cloud.mail.ru/api/m1/file/remove?access_token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:58 ERROR : dir/file1: Failed to copy: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:58 INFO : dir/file1: vfs cache: upload canceled 2020/08/16 06:03:58 DEBUG : dir/file1: vfs cache: cancelled upload 2020/08/16 06:03:58 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:03:58 DEBUG : newLeaf: Updating file with newLeaf 0xc000752540 2020/08/16 06:03:58 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:03:58 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:03:58 DEBUG : newLeaf: vfs cache: starting upload 2020/08/16 06:03:59 DEBUG : newLeaf: move non-chunked object... 2020/08/16 06:03:59 INFO : newLeaf: Moved (server side) 2020/08/16 06:03:59 INFO : newLeaf: Moved (server side) 2020/08/16 06:03:59 DEBUG : newLeaf: vfs cache: cancelling upload 2020/08/16 06:03:59 ERROR : newLeaf.rclone_chunk.001_5cnj2s: Couldn't move: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:59 ERROR : newLeaf.rclone_chunk.001_5cnj2s: Failed to remove temporary chunk: Post "https://cloud.mail.ru/api/m1/file/remove?access_token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:59 ERROR : newLeaf: Failed to copy: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:59 INFO : newLeaf: vfs cache: upload canceled 2020/08/16 06:03:59 DEBUG : newLeaf: vfs cache: cancelled upload 2020/08/16 06:03:59 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/08/16 06:03:59 DEBUG : dir/file1: Updating file with dir/file1 0xc000752540 2020/08/16 06:03:59 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/08/16 06:03:59 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:59 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:03:59 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/08/16 06:03:59 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:03:59 DEBUG : dir/file1(0xc000090640): openPending: 2020/08/16 06:03:59 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "14,2001-02-03 04:05:06 +0000 UTC" 2020/08/16 06:03:59 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:03:59 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:03:59 DEBUG : dir/file1(0xc000090640): >openPending: err= 2020/08/16 06:03:59 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:03:59 DEBUG : dir/file1: vfs cache: cancelling writeback (uploading true) 0xc00018ae00 item 1 2020/08/16 06:03:59 DEBUG : dir/file1: vfs cache: cancelling upload 2020/08/16 06:03:59 ERROR : dir/file1: Failed to copy: Post "https://cld-extapi2.datacloudmail.ru/meta/?client_id=cloud-win&token=311ec5b30ccb7b2280d7b973525b6a198b6c82ba37363830": context canceled 2020/08/16 06:03:59 INFO : dir/file1: vfs cache: upload canceled 2020/08/16 06:03:59 DEBUG : dir/file1: vfs cache: cancelled upload 2020/08/16 06:03:59 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:03:59 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:03:59 DEBUG : dir/file1(0xc000090640): _writeAt: size=25, off=0 2020/08/16 06:03:59 DEBUG : dir/file1(0xc000090640): >_writeAt: n=25, err= 2020/08/16 06:04:00 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:04:00 INFO : dir/file1: Moved (server side) 2020/08/16 06:04:00 INFO : dir/file1: Moved (server side) 2020/08/16 06:04:00 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:04:00 DEBUG : newLeaf: Updating file with newLeaf 0xc000752540 2020/08/16 06:04:00 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:04:00 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:04:00 DEBUG : newLeaf(0xc000090640): close: 2020/08/16 06:04:00 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/08/16 06:04:00 DEBUG : newLeaf: vfs cache: setting modification time to 2020-08-16 06:03:59.905520732 +0000 UTC m=+37.823999266 2020/08/16 06:04:00 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/08/16 06:04:00 DEBUG : newLeaf(0xc000090640): >close: err= 2020/08/16 06:04:00 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:04:00 DEBUG : dir: Looking for writers 2020/08/16 06:04:00 DEBUG : : Looking for writers 2020/08/16 06:04:00 DEBUG : dir: reading active writers 2020/08/16 06:04:00 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:04:00 DEBUG : dir: Looking for writers 2020/08/16 06:04:00 DEBUG : : Looking for writers 2020/08/16 06:04:00 DEBUG : dir: reading active writers 2020/08/16 06:04:00 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:04:00 DEBUG : dir: Looking for writers 2020/08/16 06:04:00 DEBUG : : Looking for writers 2020/08/16 06:04:00 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:00 DEBUG : dir: reading active writers 2020/08/16 06:04:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:04:00 DEBUG : dir: Looking for writers 2020/08/16 06:04:00 DEBUG : : Looking for writers 2020/08/16 06:04:00 DEBUG : dir: reading active writers 2020/08/16 06:04:00 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:04:00 DEBUG : newLeaf: vfs cache: starting upload 2020/08/16 06:04:00 DEBUG : dir: Looking for writers 2020/08/16 06:04:00 DEBUG : : Looking for writers 2020/08/16 06:04:00 DEBUG : dir: reading active writers 2020/08/16 06:04:00 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:04:00 DEBUG : dir: Looking for writers 2020/08/16 06:04:00 DEBUG : : Looking for writers 2020/08/16 06:04:00 DEBUG : dir: reading active writers 2020/08/16 06:04:00 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:04:00 DEBUG : newLeaf.rclone_chunk.001_5cnlc1: File has been put by hash from source 2020/08/16 06:04:01 DEBUG : dir: Looking for writers 2020/08/16 06:04:01 DEBUG : : Looking for writers 2020/08/16 06:04:01 DEBUG : dir: reading active writers 2020/08/16 06:04:01 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:04:01 INFO : newLeaf: Deleted 2020/08/16 06:04:01 INFO : newLeaf.rclone_chunk.001_5cnlc1: Moved (server side) 2020/08/16 06:04:01 INFO : newLeaf: Copied (replaced existing) 2020/08/16 06:04:01 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-08-16 06:03:59 +0000 UTC" 2020/08/16 06:04:01 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/08/16 06:04:01 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:04:01 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/08/16 06:04:01 DEBUG : dir: Looking for writers 2020/08/16 06:04:01 DEBUG : : Looking for writers 2020/08/16 06:04:01 DEBUG : dir: reading active writers 2020/08/16 06:04:01 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:01 DEBUG : >WaitForWriters: 2020/08/16 06:04:01 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:04:01 DEBUG : dir: Looking for writers 2020/08/16 06:04:01 DEBUG : : Looking for writers 2020/08/16 06:04:01 DEBUG : dir: reading active writers 2020/08/16 06:04:01 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:01 DEBUG : >WaitForWriters: 2020/08/16 06:04:01 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 file_test.go:341 file_test.go:357 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileRename/writes,forceCache=true Messages: directories === RUN TestFileRename/full,forceCache=false run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:04:13 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:04:13 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:04:13 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:04:13 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:04:14 INFO : dir/file1.rclone_chunk.001_5cnywn: Moved (server side) 2020/08/16 06:04:14 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:04:14 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:04:14 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:04:14 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:04:14 DEBUG : dir/file1(0xc0007aadc0): _readAt: size=512, off=0 2020/08/16 06:04:14 DEBUG : dir/file1(0xc0007aadc0): openPending: 2020/08/16 06:04:14 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:04:14 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:04:14 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:04:14 DEBUG : dir/file1(0xc0007aadc0): >openPending: err= 2020/08/16 06:04:14 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [] - present false 2020/08/16 06:04:14 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:04:14 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:04:14 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:04:15 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Switch file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/, expiry "2020-08-16T06:07:14.893086596Z" 2020/08/16 06:04:15 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:04:15 DEBUG : dir/file1(0xc0007aadc0): >_readAt: n=14, err=EOF 2020/08/16 06:04:15 DEBUG : dir/file1(0xc0007aadc0): close: 2020/08/16 06:04:15 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/08/16 06:04:15 DEBUG : dir/file1(0xc0007aadc0): >close: err= 2020/08/16 06:04:15 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:04:16 INFO : dir/file1: Moved (server side) 2020/08/16 06:04:16 INFO : dir/file1: Moved (server side) 2020/08/16 06:04:16 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:04:16 DEBUG : newLeaf: Updating file with newLeaf 0xc00019e9c0 2020/08/16 06:04:16 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:04:16 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:04:16 DEBUG : newLeaf: move non-chunked object... 2020/08/16 06:04:16 INFO : newLeaf: Moved (server side) 2020/08/16 06:04:16 INFO : newLeaf: Moved (server side) 2020/08/16 06:04:16 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/08/16 06:04:16 DEBUG : dir/file1: Updating file with dir/file1 0xc00019e9c0 2020/08/16 06:04:16 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/08/16 06:04:16 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:04:16 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/08/16 06:04:16 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:04:16 DEBUG : dir/file1(0xc0003b5d00): openPending: 2020/08/16 06:04:16 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/08/16 06:04:16 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:04:16 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:04:16 DEBUG : dir/file1(0xc0003b5d00): >openPending: err= 2020/08/16 06:04:16 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:04:16 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:04:16 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:04:16 DEBUG : dir/file1(0xc0003b5d00): _writeAt: size=25, off=0 2020/08/16 06:04:16 DEBUG : dir/file1(0xc0003b5d00): >_writeAt: n=25, err= 2020/08/16 06:04:17 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:04:17 INFO : dir/file1: Moved (server side) 2020/08/16 06:04:17 INFO : dir/file1: Moved (server side) 2020/08/16 06:04:17 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:04:17 DEBUG : newLeaf: Updating file with newLeaf 0xc00019e9c0 2020/08/16 06:04:17 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:04:17 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:04:17 DEBUG : newLeaf(0xc0003b5d00): close: 2020/08/16 06:04:17 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/08/16 06:04:17 DEBUG : newLeaf: vfs cache: setting modification time to 2020-08-16 06:04:16.954653803 +0000 UTC m=+54.873132341 2020/08/16 06:04:17 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/08/16 06:04:17 DEBUG : newLeaf(0xc0003b5d00): >close: err= 2020/08/16 06:04:17 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:04:17 DEBUG : dir: Looking for writers 2020/08/16 06:04:17 DEBUG : : Looking for writers 2020/08/16 06:04:17 DEBUG : dir: reading active writers 2020/08/16 06:04:17 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:04:17 DEBUG : dir: Looking for writers 2020/08/16 06:04:17 DEBUG : : Looking for writers 2020/08/16 06:04:17 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:17 DEBUG : dir: reading active writers 2020/08/16 06:04:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:04:17 DEBUG : dir: Looking for writers 2020/08/16 06:04:17 DEBUG : : Looking for writers 2020/08/16 06:04:17 DEBUG : dir: reading active writers 2020/08/16 06:04:17 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:04:17 DEBUG : dir: Looking for writers 2020/08/16 06:04:17 DEBUG : : Looking for writers 2020/08/16 06:04:17 DEBUG : dir: reading active writers 2020/08/16 06:04:17 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:04:17 DEBUG : newLeaf: vfs cache: starting upload 2020/08/16 06:04:17 DEBUG : dir: Looking for writers 2020/08/16 06:04:17 DEBUG : : Looking for writers 2020/08/16 06:04:17 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:17 DEBUG : dir: reading active writers 2020/08/16 06:04:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:04:17 DEBUG : dir: Looking for writers 2020/08/16 06:04:17 DEBUG : : Looking for writers 2020/08/16 06:04:17 DEBUG : dir: reading active writers 2020/08/16 06:04:17 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:04:17 DEBUG : newLeaf.rclone_chunk.001_5co2xv: File has been put by hash from source 2020/08/16 06:04:17 DEBUG : dir: Looking for writers 2020/08/16 06:04:17 DEBUG : : Looking for writers 2020/08/16 06:04:17 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:17 DEBUG : dir: reading active writers 2020/08/16 06:04:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:04:18 INFO : newLeaf: Deleted 2020/08/16 06:04:18 INFO : newLeaf.rclone_chunk.001_5co2xv: Moved (server side) 2020/08/16 06:04:18 INFO : newLeaf: Copied (replaced existing) 2020/08/16 06:04:18 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-08-16 06:04:16 +0000 UTC" 2020/08/16 06:04:18 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/08/16 06:04:18 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:04:18 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/08/16 06:04:18 DEBUG : dir: Looking for writers 2020/08/16 06:04:18 DEBUG : : Looking for writers 2020/08/16 06:04:18 DEBUG : dir: reading active writers 2020/08/16 06:04:18 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:18 DEBUG : >WaitForWriters: 2020/08/16 06:04:18 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:04:18 DEBUG : dir: Looking for writers 2020/08/16 06:04:18 DEBUG : : Looking for writers 2020/08/16 06:04:18 DEBUG : dir: reading active writers 2020/08/16 06:04:18 DEBUG : newLeaf: reading active writers 2020/08/16 06:04:18 DEBUG : >WaitForWriters: 2020/08/16 06:04:18 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 file_test.go:341 file_test.go:357 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileRename/full,forceCache=false Messages: directories --- FAIL: TestFileRename (67.97s) --- FAIL: TestFileRename/minimal,forceCache=true (17.71s) --- FAIL: TestFileRename/writes,forceCache=false (16.38s) --- FAIL: TestFileRename/writes,forceCache=true (16.97s) --- FAIL: TestFileRename/full,forceCache=false (16.91s) === RUN TestRcGetVFS run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:04:30 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:04:30 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:04:30 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:04:30 DEBUG : : Looking for writers 2020/08/16 06:04:30 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 rc_test.go:64 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRcGetVFS Messages: directories --- FAIL: TestRcGetVFS (11.47s) === RUN TestReadFileHandleMethods run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:04:41 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:04:42 INFO : dir/file1.rclone_chunk.001_5coq1k: Moved (server side) 2020/08/16 06:04:43 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:04:43 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:04:43 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/08/16 06:04:43 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/08/16 06:04:43 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:04:43 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:04:43 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/08/16 06:04:43 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728 2020/08/16 06:04:43 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:04:43 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:04:43 DEBUG : dir: Looking for writers 2020/08/16 06:04:43 DEBUG : file1: reading active writers 2020/08/16 06:04:43 DEBUG : : Looking for writers 2020/08/16 06:04:43 DEBUG : dir: reading active writers 2020/08/16 06:04:43 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:80 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleMethods Messages: directories --- FAIL: TestReadFileHandleMethods (12.94s) === RUN TestReadFileHandleSeek run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:04:54 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:04:55 INFO : dir/file1.rclone_chunk.001_5cp3n8: Moved (server side) 2020/08/16 06:04:55 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:04:56 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:04:56 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/08/16 06:04:56 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:04:56 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/08/16 06:04:56 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/08/16 06:04:56 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/08/16 06:04:56 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/08/16 06:04:56 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/08/16 06:04:56 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 2, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:04:56 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ read_test.go:92: Error Trace: read_test.go:92 Error: Not equal: expected: "5" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -5 +0 Test: TestReadFileHandleSeek 2020/08/16 06:04:56 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker) 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728 2020/08/16 06:04:56 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 2, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:04:56 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ read_test.go:98: Error Trace: read_test.go:98 Error: Not equal: expected: "3" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -3 +0 Test: TestReadFileHandleSeek 2020/08/16 06:04:56 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker) 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728 2020/08/16 06:04:56 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728 2020/08/16 06:04:56 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 2, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:04:57 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ read_test.go:104: Error Trace: read_test.go:104 Error: Not equal: expected: "d" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -d +0 Test: TestReadFileHandleSeek 2020/08/16 06:04:57 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:04:57 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:04:57 DEBUG : dir: Looking for writers 2020/08/16 06:04:57 DEBUG : file1: reading active writers 2020/08/16 06:04:57 DEBUG : : Looking for writers 2020/08/16 06:04:57 DEBUG : dir: reading active writers 2020/08/16 06:04:57 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:123 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleSeek Messages: directories --- FAIL: TestReadFileHandleSeek (13.77s) === RUN TestReadFileHandleReadAt run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:05:08 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:05:09 INFO : dir/file1.rclone_chunk.001_5cphws: Moved (server side) 2020/08/16 06:05:09 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:05:10 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:05:10 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/08/16 06:05:10 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:05:10 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/08/16 06:05:10 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/08/16 06:05:10 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/08/16 06:05:10 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/08/16 06:05:10 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/08/16 06:05:10 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 2, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:10 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ read_test.go:140: Error Trace: read_test.go:140 Error: Not equal: expected: "5" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -5 +0 Test: TestReadFileHandleReadAt 2020/08/16 06:05:10 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker) 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728 2020/08/16 06:05:10 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 2, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:10 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ read_test.go:146: Error Trace: read_test.go:146 Error: Not equal: expected: "1" actual : "0" Diff: --- Expected +++ Actual @@ -1 +1 @@ -1 +0 Test: TestReadFileHandleReadAt 2020/08/16 06:05:10 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms 2020/08/16 06:05:10 DEBUG : dir/file1: aborting in-sequence read wait, off=10 2020/08/16 06:05:10 DEBUG : dir/file1: failed to wait for in-sequence read to 10 2020/08/16 06:05:10 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker) 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:10 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:10 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 2, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ read_test.go:153: Error Trace: read_test.go:153 Error: Not equal: expected: "abcdef" actual : "012345" Diff: --- Expected +++ Actual @@ -1 +1 @@ -abcdef +012345 Test: TestReadFileHandleReadAt 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker) 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 2, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 1/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 2/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 3/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 4/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 5/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 6/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 7/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 8/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 9/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: low level retry 10/10: unexpected EOF 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.seek from 10 to 10 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 10 length -1 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 DEBUG : dir/file1: ChunkedReader.Read at 10 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:05:11 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: unexpected EOF read_test.go:158: Error Trace: read_test.go:158 Error: Not equal: expected: &errors.errorString{s:"EOF"} actual : &errors.errorString{s:"unexpected EOF"} Diff: --- Expected +++ Actual @@ -1,3 +1,3 @@ (*errors.errorString)({ - s: (string) (len=3) "EOF" + s: (string) (len=14) "unexpected EOF" }) Test: TestReadFileHandleReadAt read_test.go:159: Error Trace: read_test.go:159 Error: Not equal: expected: 6 actual : 16 Test: TestReadFileHandleReadAt read_test.go:160: Error Trace: read_test.go:160 Error: Not equal: expected: "abcdef" actual : "0123456789abcdef" Diff: --- Expected +++ Actual @@ -1 +1 @@ -abcdef +0123456789abcdef Test: TestReadFileHandleReadAt 2020/08/16 06:05:11 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/08/16 06:05:11 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/08/16 06:05:11 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/08/16 06:05:11 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16 2020/08/16 06:05:11 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/08/16 06:05:11 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/08/16 06:05:11 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/08/16 06:05:11 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor 2020/08/16 06:05:11 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:05:11 DEBUG : dir: Looking for writers 2020/08/16 06:05:11 DEBUG : file1: reading active writers 2020/08/16 06:05:11 DEBUG : : Looking for writers 2020/08/16 06:05:11 DEBUG : dir: reading active writers 2020/08/16 06:05:11 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:179 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleReadAt Messages: directories --- FAIL: TestReadFileHandleReadAt (14.99s) === RUN TestReadFileHandleFlush run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:05:23 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:05:24 INFO : dir/file1.rclone_chunk.001_5cpw1t: Moved (server side) 2020/08/16 06:05:24 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:05:25 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:05:25 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/08/16 06:05:25 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/08/16 06:05:25 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:05:25 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:25 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2020/08/16 06:05:25 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:25 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:05:25 DEBUG : dir: Looking for writers 2020/08/16 06:05:25 DEBUG : file1: reading active writers 2020/08/16 06:05:25 DEBUG : : Looking for writers 2020/08/16 06:05:25 DEBUG : dir: reading active writers 2020/08/16 06:05:25 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:208 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleFlush Messages: directories --- FAIL: TestReadFileHandleFlush (13.05s) === RUN TestReadFileHandleRelease run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:05:36 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:05:37 INFO : dir/file1.rclone_chunk.001_5cq9or: Moved (server side) 2020/08/16 06:05:37 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:05:38 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:05:38 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/08/16 06:05:38 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/08/16 06:05:38 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:05:38 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:38 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2020/08/16 06:05:38 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:38 DEBUG : dir/file1: ReadFileHandle.Release closing 2020/08/16 06:05:38 DEBUG : dir/file1: ReadFileHandle.Release nothing to do 2020/08/16 06:05:38 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:05:38 DEBUG : dir: Looking for writers 2020/08/16 06:05:38 DEBUG : file1: reading active writers 2020/08/16 06:05:38 DEBUG : : Looking for writers 2020/08/16 06:05:38 DEBUG : dir: reading active writers 2020/08/16 06:05:38 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty 2020/08/16 06:05:40 DEBUG : TestMailru: Loaded fresh token from config file 2020/08/16 06:05:40 DEBUG : TestMailru: Saved new token in config file run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_test.go:234 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestReadFileHandleRelease Messages: directories --- FAIL: TestReadFileHandleRelease (13.08s) === RUN TestRWFileHandleMethodsRead run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:05:49 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:05:49 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:05:49 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:05:49 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:05:50 INFO : dir/file1.rclone_chunk.001_5cqmz2: Moved (server side) 2020/08/16 06:05:50 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:05:51 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:05:51 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:05:51 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:05:51 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:05:51 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): _readAt: size=1, off=0 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): openPending: 2020/08/16 06:05:51 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:05:51 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:05:51 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): >openPending: err= 2020/08/16 06:05:51 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/08/16 06:05:51 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:05:51 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:05:51 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:05:51 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:51 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): >_readAt: n=1, err= 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): _readAt: size=256, off=1 2020/08/16 06:05:51 DEBUG : vfs cache: looking for range={Pos:1 Size:15} in [{Pos:0 Size:16}] - present true 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): >_readAt: n=15, err=EOF 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): _readAt: size=16, off=16 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): >_readAt: n=0, err=EOF 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): close: 2020/08/16 06:05:51 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): >close: err= 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): close: 2020/08/16 06:05:51 DEBUG : dir/file1(0xc00079bd40): >close: err=file already closed 2020/08/16 06:05:51 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:05:51 DEBUG : dir: Looking for writers 2020/08/16 06:05:51 DEBUG : file1: reading active writers 2020/08/16 06:05:51 DEBUG : : Looking for writers 2020/08/16 06:05:51 DEBUG : dir: reading active writers 2020/08/16 06:05:51 DEBUG : >WaitForWriters: 2020/08/16 06:05:51 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:117 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleMethodsRead Messages: directories --- FAIL: TestRWFileHandleMethodsRead (13.72s) === RUN TestRWFileHandleSeek run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:06:03 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:06:03 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:03 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:03 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:06:04 INFO : dir/file1.rclone_chunk.001_5cr0lz: Moved (server side) 2020/08/16 06:06:04 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:06:04 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:06:04 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:06:04 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:06:04 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:06:04 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): _readAt: size=1, off=0 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): openPending: 2020/08/16 06:06:04 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:06:04 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:06:04 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): >openPending: err= 2020/08/16 06:06:04 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/08/16 06:06:04 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:06:04 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:06:04 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:06:04 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:06:04 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): >_readAt: n=1, err= 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): _readAt: size=1, off=5 2020/08/16 06:06:04 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): >_readAt: n=1, err= 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): _readAt: size=1, off=3 2020/08/16 06:06:04 DEBUG : vfs cache: looking for range={Pos:3 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): >_readAt: n=1, err= 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): _readAt: size=1, off=13 2020/08/16 06:06:04 DEBUG : vfs cache: looking for range={Pos:13 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): >_readAt: n=1, err= 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): _readAt: size=16, off=100 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): >_readAt: n=0, err=EOF 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): close: 2020/08/16 06:06:04 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/08/16 06:06:04 DEBUG : dir/file1(0xc0003c1b80): >close: err= 2020/08/16 06:06:04 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:04 DEBUG : dir: Looking for writers 2020/08/16 06:06:04 DEBUG : file1: reading active writers 2020/08/16 06:06:04 DEBUG : : Looking for writers 2020/08/16 06:06:04 DEBUG : dir: reading active writers 2020/08/16 06:06:04 DEBUG : >WaitForWriters: 2020/08/16 06:06:04 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:167 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleSeek Messages: directories --- FAIL: TestRWFileHandleSeek (13.08s) === RUN TestRWFileHandleReadAt run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:06:16 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:06:16 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:16 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:16 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:06:17 INFO : dir/file1.rclone_chunk.001_5crdmz: Moved (server side) 2020/08/16 06:06:17 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:06:18 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:06:18 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:06:18 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:06:18 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:06:18 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): _readAt: size=1, off=0 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): openPending: 2020/08/16 06:06:18 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:06:18 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:06:18 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >openPending: err= 2020/08/16 06:06:18 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/08/16 06:06:18 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:06:18 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:06:18 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:06:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:06:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >_readAt: n=1, err= 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): _readAt: size=1, off=5 2020/08/16 06:06:18 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >_readAt: n=1, err= 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): _readAt: size=1, off=1 2020/08/16 06:06:18 DEBUG : vfs cache: looking for range={Pos:1 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >_readAt: n=1, err= 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): _readAt: size=6, off=10 2020/08/16 06:06:18 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >_readAt: n=6, err= 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): _readAt: size=256, off=10 2020/08/16 06:06:18 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >_readAt: n=6, err=EOF 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): _readAt: size=256, off=100 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >_readAt: n=0, err=EOF 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): close: 2020/08/16 06:06:18 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >close: err= 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): _readAt: size=256, off=100 2020/08/16 06:06:18 DEBUG : dir/file1(0xc000822940): >_readAt: n=0, err=file already closed 2020/08/16 06:06:18 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:18 DEBUG : dir: Looking for writers 2020/08/16 06:06:18 DEBUG : file1: reading active writers 2020/08/16 06:06:18 DEBUG : : Looking for writers 2020/08/16 06:06:18 DEBUG : dir: reading active writers 2020/08/16 06:06:18 DEBUG : >WaitForWriters: 2020/08/16 06:06:18 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:217 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleReadAt Messages: directories --- FAIL: TestRWFileHandleReadAt (13.28s) === RUN TestRWFileHandleFlushRead run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:06:29 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:06:29 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:29 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:29 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:06:30 INFO : dir/file1.rclone_chunk.001_5crq6w: Moved (server side) 2020/08/16 06:06:30 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:06:31 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:06:31 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:06:31 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:06:31 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:06:31 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): RWFileHandle.Flush 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): _readAt: size=256, off=0 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): openPending: 2020/08/16 06:06:31 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:06:31 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:06:31 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): >openPending: err= 2020/08/16 06:06:31 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2020/08/16 06:06:31 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:06:31 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:06:31 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:06:31 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:06:31 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): >_readAt: n=16, err=EOF 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): RWFileHandle.Flush 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): RWFileHandle.Flush 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): close: 2020/08/16 06:06:31 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/08/16 06:06:31 DEBUG : dir/file1(0xc0000901c0): >close: err= 2020/08/16 06:06:31 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:31 DEBUG : dir: Looking for writers 2020/08/16 06:06:31 DEBUG : file1: reading active writers 2020/08/16 06:06:31 DEBUG : : Looking for writers 2020/08/16 06:06:31 DEBUG : dir: reading active writers 2020/08/16 06:06:31 DEBUG : >WaitForWriters: 2020/08/16 06:06:31 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:246 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleFlushRead Messages: directories --- FAIL: TestRWFileHandleFlushRead (13.19s) === RUN TestRWFileHandleReleaseRead run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:06:43 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:06:43 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:43 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:43 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:06:43 INFO : dir/file1.rclone_chunk.001_5cs41z: Moved (server side) 2020/08/16 06:06:44 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:06:44 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:06:44 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:06:44 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:06:44 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:06:44 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:06:44 DEBUG : dir/file1(0xc000511a80): _readAt: size=256, off=0 2020/08/16 06:06:44 DEBUG : dir/file1(0xc000511a80): openPending: 2020/08/16 06:06:44 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:06:44 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:06:44 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:06:44 DEBUG : dir/file1(0xc000511a80): >openPending: err= 2020/08/16 06:06:44 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2020/08/16 06:06:44 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:06:44 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:06:44 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:06:44 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:06:44 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo21.datacloudmail.ru/oauth-get/ 2020/08/16 06:06:44 DEBUG : dir/file1(0xc000511a80): >_readAt: n=16, err=EOF 2020/08/16 06:06:44 DEBUG : dir/file1(0xc000511a80): RWFileHandle.Release 2020/08/16 06:06:44 DEBUG : dir/file1(0xc000511a80): close: 2020/08/16 06:06:44 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06 +0000 UTC 2020/08/16 06:06:44 DEBUG : dir/file1(0xc000511a80): >close: err= 2020/08/16 06:06:44 DEBUG : dir/file1(0xc000511a80): RWFileHandle.Release 2020/08/16 06:06:44 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:44 DEBUG : dir: Looking for writers 2020/08/16 06:06:44 DEBUG : file1: reading active writers 2020/08/16 06:06:44 DEBUG : : Looking for writers 2020/08/16 06:06:44 DEBUG : dir: reading active writers 2020/08/16 06:06:44 DEBUG : >WaitForWriters: 2020/08/16 06:06:44 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:267 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleReleaseRead Messages: directories --- FAIL: TestRWFileHandleReleaseRead (13.04s) === RUN TestRWFileHandleMethodsWrite run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:06:56 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:06:56 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:56 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:06:56 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:06:56 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:06:56 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:06:56 DEBUG : file1: newRWFileHandle: 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): openPending: 2020/08/16 06:06:56 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:06:56 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): >openPending: err= 2020/08/16 06:06:56 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:06:56 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:06:56 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:06:56 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): _writeAt: size=5, off=0 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): >_writeAt: n=5, err= 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): _writeAt: size=7, off=5 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): >_writeAt: n=7, err= 2020/08/16 06:06:56 DEBUG : file1: vfs cache: truncate to size=11 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): close: 2020/08/16 06:06:56 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:06:56.207176635 +0000 UTC m=+214.125655174 2020/08/16 06:06:56 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): >close: err= 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): close: 2020/08/16 06:06:56 DEBUG : file1(0xc0003c04c0): >close: err=file already closed 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 2020/08/16 06:06:56 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:56 DEBUG : dir: Looking for writers 2020/08/16 06:06:56 DEBUG : : Looking for writers 2020/08/16 06:06:56 DEBUG : dir: reading active writers 2020/08/16 06:06:56 DEBUG : file1: reading active writers 2020/08/16 06:06:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:06:56 DEBUG : dir: Looking for writers 2020/08/16 06:06:56 DEBUG : : Looking for writers 2020/08/16 06:06:56 DEBUG : dir: reading active writers 2020/08/16 06:06:56 DEBUG : file1: reading active writers 2020/08/16 06:06:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:06:56 DEBUG : dir: Looking for writers 2020/08/16 06:06:56 DEBUG : : Looking for writers 2020/08/16 06:06:56 DEBUG : dir: reading active writers 2020/08/16 06:06:56 DEBUG : file1: reading active writers 2020/08/16 06:06:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:06:56 DEBUG : dir: Looking for writers 2020/08/16 06:06:56 DEBUG : : Looking for writers 2020/08/16 06:06:56 DEBUG : dir: reading active writers 2020/08/16 06:06:56 DEBUG : file1: reading active writers 2020/08/16 06:06:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:06:56 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:06:56 DEBUG : dir: Looking for writers 2020/08/16 06:06:56 DEBUG : : Looking for writers 2020/08/16 06:06:56 DEBUG : dir: reading active writers 2020/08/16 06:06:56 DEBUG : file1: reading active writers 2020/08/16 06:06:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:06:56 DEBUG : dir: Looking for writers 2020/08/16 06:06:56 DEBUG : : Looking for writers 2020/08/16 06:06:56 DEBUG : dir: reading active writers 2020/08/16 06:06:56 DEBUG : file1: reading active writers 2020/08/16 06:06:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:06:56 DEBUG : dir: Looking for writers 2020/08/16 06:06:56 DEBUG : : Looking for writers 2020/08/16 06:06:56 DEBUG : dir: reading active writers 2020/08/16 06:06:56 DEBUG : file1: reading active writers 2020/08/16 06:06:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:06:57 INFO : file1.rclone_chunk.001_5csh0p: Moved (server side) 2020/08/16 06:06:57 INFO : file1: Copied (new) 2020/08/16 06:06:57 DEBUG : file1: vfs cache: fingerprint now "11,2020-08-16 06:06:56 +0000 UTC" 2020/08/16 06:06:57 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:06:57 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:06:57 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:06:57 DEBUG : dir: Looking for writers 2020/08/16 06:06:57 DEBUG : : Looking for writers 2020/08/16 06:06:57 DEBUG : dir: reading active writers 2020/08/16 06:06:57 DEBUG : file1: reading active writers 2020/08/16 06:06:57 DEBUG : >WaitForWriters: 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 2020/08/16 06:07:05 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:05 DEBUG : dir: Looking for writers 2020/08/16 06:07:05 DEBUG : : Looking for writers 2020/08/16 06:07:05 DEBUG : dir: reading active writers 2020/08/16 06:07:05 DEBUG : file1: reading active writers 2020/08/16 06:07:05 DEBUG : >WaitForWriters: 2020/08/16 06:07:05 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:345 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleMethodsWrite Messages: directories --- FAIL: TestRWFileHandleMethodsWrite (20.73s) === RUN TestRWFileHandleWriteAt run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:07:16 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:07:16 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:07:16 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:07:16 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:07:16 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:07:16 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:07:16 DEBUG : file1: newRWFileHandle: 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): openPending: 2020/08/16 06:07:16 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:07:16 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): >openPending: err= 2020/08/16 06:07:16 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:07:16 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:16 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:07:16 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): _writeAt: size=7, off=0 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): >_writeAt: n=7, err= 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): _writeAt: size=6, off=5 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): >_writeAt: n=6, err= 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): close: 2020/08/16 06:07:16 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:07:16.937994293 +0000 UTC m=+234.856472813 2020/08/16 06:07:16 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): >close: err= 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): _writeAt: size=5, off=0 2020/08/16 06:07:16 DEBUG : file1(0xc0003c0880): >_writeAt: n=0, err=file already closed 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 2020/08/16 06:07:16 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:16 DEBUG : dir: Looking for writers 2020/08/16 06:07:16 DEBUG : : Looking for writers 2020/08/16 06:07:16 DEBUG : dir: reading active writers 2020/08/16 06:07:16 DEBUG : file1: reading active writers 2020/08/16 06:07:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:07:16 DEBUG : dir: Looking for writers 2020/08/16 06:07:16 DEBUG : : Looking for writers 2020/08/16 06:07:16 DEBUG : dir: reading active writers 2020/08/16 06:07:16 DEBUG : file1: reading active writers 2020/08/16 06:07:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:07:16 DEBUG : dir: Looking for writers 2020/08/16 06:07:16 DEBUG : : Looking for writers 2020/08/16 06:07:16 DEBUG : dir: reading active writers 2020/08/16 06:07:16 DEBUG : file1: reading active writers 2020/08/16 06:07:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:07:17 DEBUG : dir: Looking for writers 2020/08/16 06:07:17 DEBUG : : Looking for writers 2020/08/16 06:07:17 DEBUG : dir: reading active writers 2020/08/16 06:07:17 DEBUG : file1: reading active writers 2020/08/16 06:07:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:07:17 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:07:17 DEBUG : dir: Looking for writers 2020/08/16 06:07:17 DEBUG : : Looking for writers 2020/08/16 06:07:17 DEBUG : dir: reading active writers 2020/08/16 06:07:17 DEBUG : file1: reading active writers 2020/08/16 06:07:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:07:17 DEBUG : dir: Looking for writers 2020/08/16 06:07:17 DEBUG : : Looking for writers 2020/08/16 06:07:17 DEBUG : dir: reading active writers 2020/08/16 06:07:17 DEBUG : file1: reading active writers 2020/08/16 06:07:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:07:17 DEBUG : dir: Looking for writers 2020/08/16 06:07:17 DEBUG : : Looking for writers 2020/08/16 06:07:17 DEBUG : dir: reading active writers 2020/08/16 06:07:17 DEBUG : file1: reading active writers 2020/08/16 06:07:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:07:17 INFO : file1.rclone_chunk.001_5ct249: Moved (server side) 2020/08/16 06:07:17 INFO : file1: Copied (new) 2020/08/16 06:07:17 DEBUG : file1: vfs cache: fingerprint now "11,2020-08-16 06:07:16 +0000 UTC" 2020/08/16 06:07:17 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:07:17 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:17 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:07:18 DEBUG : dir: Looking for writers 2020/08/16 06:07:18 DEBUG : : Looking for writers 2020/08/16 06:07:18 DEBUG : dir: reading active writers 2020/08/16 06:07:18 DEBUG : file1: reading active writers 2020/08/16 06:07:18 DEBUG : >WaitForWriters: 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 2020/08/16 06:07:26 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:26 DEBUG : dir: Looking for writers 2020/08/16 06:07:26 DEBUG : : Looking for writers 2020/08/16 06:07:26 DEBUG : dir: reading active writers 2020/08/16 06:07:26 DEBUG : file1: reading active writers 2020/08/16 06:07:26 DEBUG : >WaitForWriters: 2020/08/16 06:07:26 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:393 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleWriteAt Messages: directories --- FAIL: TestRWFileHandleWriteAt (20.82s) === RUN TestRWFileHandleWriteNoWrite run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:07:37 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:07:37 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:07:37 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:07:37 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:07:37 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:07:37 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:07:37 DEBUG : file1: newRWFileHandle: 2020/08/16 06:07:37 DEBUG : file1(0xc0001e6840): openPending: 2020/08/16 06:07:37 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:07:37 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:37 DEBUG : file1(0xc0001e6840): >openPending: err= 2020/08/16 06:07:37 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:07:37 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:37 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:07:37 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:07:37 DEBUG : file1(0xc0001e6840): close: 2020/08/16 06:07:37 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:07:37.753270571 +0000 UTC m=+255.671749088 2020/08/16 06:07:37 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:07:37 DEBUG : file1(0xc0001e6840): >close: err= 2020/08/16 06:07:37 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/08/16 06:07:37 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/08/16 06:07:37 DEBUG : file2: newRWFileHandle: 2020/08/16 06:07:37 DEBUG : file2(0xc0001e6a00): openPending: 2020/08/16 06:07:37 DEBUG : file2: vfs cache: truncate to size=0 2020/08/16 06:07:37 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/08/16 06:07:37 DEBUG : file2(0xc0001e6a00): >openPending: err= 2020/08/16 06:07:37 DEBUG : file2: >newRWFileHandle: err= 2020/08/16 06:07:37 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/08/16 06:07:37 DEBUG : file2: >Open: fd=file2 (rw), err= 2020/08/16 06:07:37 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2020/08/16 06:07:37 DEBUG : file2(0xc0001e6a00): RWFileHandle.Flush 2020/08/16 06:07:37 DEBUG : file2(0xc0001e6a00): RWFileHandle.Release 2020/08/16 06:07:37 DEBUG : file2(0xc0001e6a00): close: 2020/08/16 06:07:37 DEBUG : file2: vfs cache: setting modification time to 2020-08-16 06:07:37.754093812 +0000 UTC m=+255.672572338 2020/08/16 06:07:37 INFO : file2: vfs cache: queuing for upload in 100ms 2020/08/16 06:07:37 DEBUG : file2(0xc0001e6a00): >close: err= 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 2020/08/16 06:07:37 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:37 DEBUG : dir: Looking for writers 2020/08/16 06:07:37 DEBUG : : Looking for writers 2020/08/16 06:07:37 DEBUG : file1: reading active writers 2020/08/16 06:07:37 DEBUG : file2: reading active writers 2020/08/16 06:07:37 DEBUG : dir: reading active writers 2020/08/16 06:07:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2020/08/16 06:07:37 DEBUG : dir: Looking for writers 2020/08/16 06:07:37 DEBUG : : Looking for writers 2020/08/16 06:07:37 DEBUG : dir: reading active writers 2020/08/16 06:07:37 DEBUG : file1: reading active writers 2020/08/16 06:07:37 DEBUG : file2: reading active writers 2020/08/16 06:07:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2020/08/16 06:07:37 DEBUG : dir: Looking for writers 2020/08/16 06:07:37 DEBUG : : Looking for writers 2020/08/16 06:07:37 DEBUG : dir: reading active writers 2020/08/16 06:07:37 DEBUG : file1: reading active writers 2020/08/16 06:07:37 DEBUG : file2: reading active writers 2020/08/16 06:07:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2020/08/16 06:07:37 DEBUG : dir: Looking for writers 2020/08/16 06:07:37 DEBUG : : Looking for writers 2020/08/16 06:07:37 DEBUG : dir: reading active writers 2020/08/16 06:07:37 DEBUG : file1: reading active writers 2020/08/16 06:07:37 DEBUG : file2: reading active writers 2020/08/16 06:07:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2020/08/16 06:07:37 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:07:37 DEBUG : file2: vfs cache: starting upload 2020/08/16 06:07:37 DEBUG : dir: Looking for writers 2020/08/16 06:07:37 DEBUG : : Looking for writers 2020/08/16 06:07:37 DEBUG : dir: reading active writers 2020/08/16 06:07:37 DEBUG : file1: reading active writers 2020/08/16 06:07:37 DEBUG : file2: reading active writers 2020/08/16 06:07:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2020/08/16 06:07:38 DEBUG : dir: Looking for writers 2020/08/16 06:07:38 DEBUG : : Looking for writers 2020/08/16 06:07:38 DEBUG : dir: reading active writers 2020/08/16 06:07:38 DEBUG : file1: reading active writers 2020/08/16 06:07:38 DEBUG : file2: reading active writers 2020/08/16 06:07:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2020/08/16 06:07:38 DEBUG : dir: Looking for writers 2020/08/16 06:07:38 DEBUG : : Looking for writers 2020/08/16 06:07:38 DEBUG : dir: reading active writers 2020/08/16 06:07:38 DEBUG : file1: reading active writers 2020/08/16 06:07:38 DEBUG : file2: reading active writers 2020/08/16 06:07:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2020/08/16 06:07:38 INFO : file1.rclone_chunk.001_5ctmi8: Moved (server side) 2020/08/16 06:07:38 INFO : file1: Copied (new) 2020/08/16 06:07:38 DEBUG : file1: vfs cache: fingerprint now "0,2020-08-16 06:07:37 +0000 UTC" 2020/08/16 06:07:38 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:07:38 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:38 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:07:38 INFO : file2.rclone_chunk.001_5ctmtd: Moved (server side) 2020/08/16 06:07:38 INFO : file2: Copied (new) 2020/08/16 06:07:38 DEBUG : file2: vfs cache: fingerprint now "0,2020-08-16 06:07:37 +0000 UTC" 2020/08/16 06:07:38 DEBUG : file2: vfs cache: writeback object to VFS layer 2020/08/16 06:07:38 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/08/16 06:07:38 INFO : file2: vfs cache: upload succeeded try #1 2020/08/16 06:07:39 DEBUG : dir: Looking for writers 2020/08/16 06:07:39 DEBUG : : Looking for writers 2020/08/16 06:07:39 DEBUG : dir: reading active writers 2020/08/16 06:07:39 DEBUG : file1: reading active writers 2020/08/16 06:07:39 DEBUG : file2: reading active writers 2020/08/16 06:07:39 DEBUG : >WaitForWriters: 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 2020/08/16 06:07:46 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:46 DEBUG : dir: Looking for writers 2020/08/16 06:07:46 DEBUG : : Looking for writers 2020/08/16 06:07:46 DEBUG : file2: reading active writers 2020/08/16 06:07:46 DEBUG : dir: reading active writers 2020/08/16 06:07:46 DEBUG : file1: reading active writers 2020/08/16 06:07:46 DEBUG : >WaitForWriters: 2020/08/16 06:07:46 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:427 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleWriteNoWrite Messages: directories --- FAIL: TestRWFileHandleWriteNoWrite (20.90s) === RUN TestRWFileHandleFlushWrite run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:07:58 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:07:58 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:07:58 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:07:58 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:07:58 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:07:58 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:07:58 DEBUG : file1: newRWFileHandle: 2020/08/16 06:07:58 DEBUG : file1(0xc0007aa140): openPending: 2020/08/16 06:07:58 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:07:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:58 DEBUG : file1(0xc0007aa140): >openPending: err= 2020/08/16 06:07:58 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:07:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:58 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:07:58 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:07:58 DEBUG : file1(0xc0007aa140): _writeAt: size=5, off=0 2020/08/16 06:07:58 DEBUG : file1(0xc0007aa140): >_writeAt: n=5, err= 2020/08/16 06:07:58 DEBUG : file1(0xc0007aa140): RWFileHandle.Flush 2020/08/16 06:07:58 DEBUG : file1(0xc0007aa140): RWFileHandle.Flush 2020/08/16 06:07:58 DEBUG : file1(0xc0007aa140): close: 2020/08/16 06:07:58 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:07:58.668151176 +0000 UTC m=+276.586629702 2020/08/16 06:07:58 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:07:58 DEBUG : file1(0xc0007aa140): >close: err= 2020/08/16 06:07:58 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:58 DEBUG : dir: Looking for writers 2020/08/16 06:07:58 DEBUG : : Looking for writers 2020/08/16 06:07:58 DEBUG : dir: reading active writers 2020/08/16 06:07:58 DEBUG : file1: reading active writers 2020/08/16 06:07:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:07:58 DEBUG : dir: Looking for writers 2020/08/16 06:07:58 DEBUG : : Looking for writers 2020/08/16 06:07:58 DEBUG : dir: reading active writers 2020/08/16 06:07:58 DEBUG : file1: reading active writers 2020/08/16 06:07:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:07:58 DEBUG : dir: Looking for writers 2020/08/16 06:07:58 DEBUG : : Looking for writers 2020/08/16 06:07:58 DEBUG : dir: reading active writers 2020/08/16 06:07:58 DEBUG : file1: reading active writers 2020/08/16 06:07:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:07:58 DEBUG : dir: Looking for writers 2020/08/16 06:07:58 DEBUG : : Looking for writers 2020/08/16 06:07:58 DEBUG : dir: reading active writers 2020/08/16 06:07:58 DEBUG : file1: reading active writers 2020/08/16 06:07:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:07:58 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:07:58 DEBUG : dir: Looking for writers 2020/08/16 06:07:58 DEBUG : : Looking for writers 2020/08/16 06:07:58 DEBUG : dir: reading active writers 2020/08/16 06:07:58 DEBUG : file1: reading active writers 2020/08/16 06:07:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:07:58 DEBUG : dir: Looking for writers 2020/08/16 06:07:58 DEBUG : : Looking for writers 2020/08/16 06:07:58 DEBUG : dir: reading active writers 2020/08/16 06:07:58 DEBUG : file1: reading active writers 2020/08/16 06:07:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:07:59 DEBUG : dir: Looking for writers 2020/08/16 06:07:59 DEBUG : : Looking for writers 2020/08/16 06:07:59 DEBUG : dir: reading active writers 2020/08/16 06:07:59 DEBUG : file1: reading active writers 2020/08/16 06:07:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:07:59 INFO : file1.rclone_chunk.001_5cu7iq: Moved (server side) 2020/08/16 06:07:59 INFO : file1: Copied (new) 2020/08/16 06:07:59 DEBUG : file1: vfs cache: fingerprint now "5,2020-08-16 06:07:58 +0000 UTC" 2020/08/16 06:07:59 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:07:59 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:59 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:07:59 DEBUG : dir: Looking for writers 2020/08/16 06:07:59 DEBUG : : Looking for writers 2020/08/16 06:07:59 DEBUG : dir: reading active writers 2020/08/16 06:07:59 DEBUG : file1: reading active writers 2020/08/16 06:07:59 DEBUG : >WaitForWriters: 2020/08/16 06:07:59 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:456 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleFlushWrite Messages: directories --- FAIL: TestRWFileHandleFlushWrite (12.99s) === RUN TestRWFileHandleReleaseWrite run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:08:11 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:08:11 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:08:11 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:08:11 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:08:11 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:08:11 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:08:11 DEBUG : file1: newRWFileHandle: 2020/08/16 06:08:11 DEBUG : file1(0xc00011ae40): openPending: 2020/08/16 06:08:11 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:08:11 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:11 DEBUG : file1(0xc00011ae40): >openPending: err= 2020/08/16 06:08:11 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:08:11 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:11 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:08:11 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:08:11 DEBUG : file1(0xc00011ae40): _writeAt: size=5, off=0 2020/08/16 06:08:11 DEBUG : file1(0xc00011ae40): >_writeAt: n=5, err= 2020/08/16 06:08:11 DEBUG : file1(0xc00011ae40): RWFileHandle.Release 2020/08/16 06:08:11 DEBUG : file1(0xc00011ae40): close: 2020/08/16 06:08:11 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:08:11.64599165 +0000 UTC m=+289.564470172 2020/08/16 06:08:11 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:11 DEBUG : file1(0xc00011ae40): >close: err= 2020/08/16 06:08:11 DEBUG : file1(0xc00011ae40): RWFileHandle.Release 2020/08/16 06:08:11 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:11 DEBUG : dir: Looking for writers 2020/08/16 06:08:11 DEBUG : : Looking for writers 2020/08/16 06:08:11 DEBUG : dir: reading active writers 2020/08/16 06:08:11 DEBUG : file1: reading active writers 2020/08/16 06:08:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:11 DEBUG : dir: Looking for writers 2020/08/16 06:08:11 DEBUG : : Looking for writers 2020/08/16 06:08:11 DEBUG : file1: reading active writers 2020/08/16 06:08:11 DEBUG : dir: reading active writers 2020/08/16 06:08:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:11 DEBUG : dir: Looking for writers 2020/08/16 06:08:11 DEBUG : : Looking for writers 2020/08/16 06:08:11 DEBUG : dir: reading active writers 2020/08/16 06:08:11 DEBUG : file1: reading active writers 2020/08/16 06:08:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:11 DEBUG : dir: Looking for writers 2020/08/16 06:08:11 DEBUG : : Looking for writers 2020/08/16 06:08:11 DEBUG : dir: reading active writers 2020/08/16 06:08:11 DEBUG : file1: reading active writers 2020/08/16 06:08:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:11 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:08:11 DEBUG : dir: Looking for writers 2020/08/16 06:08:11 DEBUG : : Looking for writers 2020/08/16 06:08:11 DEBUG : dir: reading active writers 2020/08/16 06:08:11 DEBUG : file1: reading active writers 2020/08/16 06:08:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:11 DEBUG : dir: Looking for writers 2020/08/16 06:08:11 DEBUG : : Looking for writers 2020/08/16 06:08:11 DEBUG : dir: reading active writers 2020/08/16 06:08:11 DEBUG : file1: reading active writers 2020/08/16 06:08:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:12 DEBUG : dir: Looking for writers 2020/08/16 06:08:12 DEBUG : : Looking for writers 2020/08/16 06:08:12 DEBUG : dir: reading active writers 2020/08/16 06:08:12 DEBUG : file1: reading active writers 2020/08/16 06:08:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:08:12 INFO : file1.rclone_chunk.001_5cuk8n: Moved (server side) 2020/08/16 06:08:12 INFO : file1: Copied (new) 2020/08/16 06:08:12 DEBUG : file1: vfs cache: fingerprint now "5,2020-08-16 06:08:11 +0000 UTC" 2020/08/16 06:08:12 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:12 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:12 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:12 DEBUG : dir: Looking for writers 2020/08/16 06:08:12 DEBUG : : Looking for writers 2020/08/16 06:08:12 DEBUG : dir: reading active writers 2020/08/16 06:08:12 DEBUG : file1: reading active writers 2020/08/16 06:08:12 DEBUG : >WaitForWriters: 2020/08/16 06:08:12 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:476 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleReleaseWrite Messages: directories --- FAIL: TestRWFileHandleReleaseWrite (13.15s) === RUN TestRWFileHandleSizeTruncateExisting run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:08:24 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:08:24 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:08:24 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:08:24 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:08:25 INFO : dir/file1.rclone_chunk.001_5cux3n: Moved (server side) 2020/08/16 06:08:25 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rwxrwxrwx 2020/08/16 06:08:26 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/08/16 06:08:26 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:08:26 DEBUG : dir/file1(0xc0007aa900): openPending: 2020/08/16 06:08:26 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:08:26 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:08:26 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:26 DEBUG : dir/file1(0xc0007aa900): >openPending: err= 2020/08/16 06:08:26 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:08:26 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:08:26 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:08:26 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:08:26 DEBUG : dir/file1(0xc0007aa900): _writeAt: size=5, off=0 2020/08/16 06:08:26 DEBUG : dir/file1(0xc0007aa900): >_writeAt: n=5, err= 2020/08/16 06:08:26 DEBUG : dir/file1(0xc0007aa900): close: 2020/08/16 06:08:26 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true 2020/08/16 06:08:26 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:08:26.097557948 +0000 UTC m=+304.016036477 2020/08/16 06:08:26 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:26 DEBUG : dir/file1(0xc0007aa900): >close: err= 2020/08/16 06:08:26 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:26 DEBUG : dir: Looking for writers 2020/08/16 06:08:26 DEBUG : file1: reading active writers 2020/08/16 06:08:26 DEBUG : : Looking for writers 2020/08/16 06:08:26 DEBUG : dir: reading active writers 2020/08/16 06:08:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:26 DEBUG : dir: Looking for writers 2020/08/16 06:08:26 DEBUG : file1: reading active writers 2020/08/16 06:08:26 DEBUG : : Looking for writers 2020/08/16 06:08:26 DEBUG : dir: reading active writers 2020/08/16 06:08:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:26 DEBUG : dir: Looking for writers 2020/08/16 06:08:26 DEBUG : file1: reading active writers 2020/08/16 06:08:26 DEBUG : : Looking for writers 2020/08/16 06:08:26 DEBUG : dir: reading active writers 2020/08/16 06:08:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:26 DEBUG : dir: Looking for writers 2020/08/16 06:08:26 DEBUG : file1: reading active writers 2020/08/16 06:08:26 DEBUG : : Looking for writers 2020/08/16 06:08:26 DEBUG : dir: reading active writers 2020/08/16 06:08:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:26 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:08:26 DEBUG : dir: Looking for writers 2020/08/16 06:08:26 DEBUG : file1: reading active writers 2020/08/16 06:08:26 DEBUG : : Looking for writers 2020/08/16 06:08:26 DEBUG : dir: reading active writers 2020/08/16 06:08:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:26 DEBUG : dir: Looking for writers 2020/08/16 06:08:26 DEBUG : file1: reading active writers 2020/08/16 06:08:26 DEBUG : : Looking for writers 2020/08/16 06:08:26 DEBUG : dir: reading active writers 2020/08/16 06:08:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:26 DEBUG : dir: Looking for writers 2020/08/16 06:08:26 DEBUG : file1: reading active writers 2020/08/16 06:08:26 DEBUG : : Looking for writers 2020/08/16 06:08:26 DEBUG : dir: reading active writers 2020/08/16 06:08:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:08:27 INFO : dir/file1: Deleted 2020/08/16 06:08:27 INFO : dir/file1.rclone_chunk.001_5cuzvq: Moved (server side) 2020/08/16 06:08:27 INFO : dir/file1: Copied (replaced existing) 2020/08/16 06:08:27 DEBUG : dir/file1: vfs cache: fingerprint now "5,2020-08-16 06:08:26 +0000 UTC" 2020/08/16 06:08:27 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:27 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:27 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:27 DEBUG : dir: Looking for writers 2020/08/16 06:08:27 DEBUG : file1: reading active writers 2020/08/16 06:08:27 DEBUG : : Looking for writers 2020/08/16 06:08:27 DEBUG : dir: reading active writers 2020/08/16 06:08:27 DEBUG : >WaitForWriters: 2020/08/16 06:08:27 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:508 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleSizeTruncateExisting Messages: directories --- FAIL: TestRWFileHandleSizeTruncateExisting (14.24s) === RUN TestRWFileHandleSizeCreateExisting run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:08:38 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:08:38 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:08:38 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:08:38 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:08:39 INFO : dir/file1.rclone_chunk.001_5cvb9w: Moved (server side) 2020/08/16 06:08:40 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:08:40 DEBUG : dir/file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:08:40 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:08:40 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:08:40 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:40 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:08:40 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:08:40 DEBUG : dir/file1(0xc0003b4780): _writeAt: size=5, off=0 2020/08/16 06:08:40 DEBUG : dir/file1(0xc0003b4780): openPending: 2020/08/16 06:08:40 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06 +0000 UTC" against cached fingerprint "" 2020/08/16 06:08:40 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:08:40 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:40 DEBUG : dir/file1(0xc0003b4780): >openPending: err= 2020/08/16 06:08:40 DEBUG : dir/file1(0xc0003b4780): >_writeAt: n=5, err= 2020/08/16 06:08:40 DEBUG : dir/file1(0xc0003b4780): _writeAt: size=15, off=5 2020/08/16 06:08:40 DEBUG : dir/file1(0xc0003b4780): >_writeAt: n=15, err= 2020/08/16 06:08:40 DEBUG : dir/file1(0xc0003b4780): close: 2020/08/16 06:08:40 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [{Pos:0 Size:20}] - present true 2020/08/16 06:08:40 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:08:40.326301077 +0000 UTC m=+318.244779604 2020/08/16 06:08:40 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:40 DEBUG : dir/file1(0xc0003b4780): >close: err= 2020/08/16 06:08:40 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:40 DEBUG : dir: Looking for writers 2020/08/16 06:08:40 DEBUG : file1: reading active writers 2020/08/16 06:08:40 DEBUG : : Looking for writers 2020/08/16 06:08:40 DEBUG : dir: reading active writers 2020/08/16 06:08:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:40 DEBUG : dir: Looking for writers 2020/08/16 06:08:40 DEBUG : file1: reading active writers 2020/08/16 06:08:40 DEBUG : : Looking for writers 2020/08/16 06:08:40 DEBUG : dir: reading active writers 2020/08/16 06:08:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:40 DEBUG : dir: Looking for writers 2020/08/16 06:08:40 DEBUG : file1: reading active writers 2020/08/16 06:08:40 DEBUG : : Looking for writers 2020/08/16 06:08:40 DEBUG : dir: reading active writers 2020/08/16 06:08:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:40 DEBUG : dir: Looking for writers 2020/08/16 06:08:40 DEBUG : file1: reading active writers 2020/08/16 06:08:40 DEBUG : : Looking for writers 2020/08/16 06:08:40 DEBUG : dir: reading active writers 2020/08/16 06:08:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:40 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:08:40 DEBUG : dir: Looking for writers 2020/08/16 06:08:40 DEBUG : file1: reading active writers 2020/08/16 06:08:40 DEBUG : : Looking for writers 2020/08/16 06:08:40 DEBUG : dir: reading active writers 2020/08/16 06:08:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:40 DEBUG : dir: Looking for writers 2020/08/16 06:08:40 DEBUG : file1: reading active writers 2020/08/16 06:08:40 DEBUG : : Looking for writers 2020/08/16 06:08:40 DEBUG : dir: reading active writers 2020/08/16 06:08:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:40 DEBUG : dir: Looking for writers 2020/08/16 06:08:40 DEBUG : file1: reading active writers 2020/08/16 06:08:40 DEBUG : : Looking for writers 2020/08/16 06:08:40 DEBUG : dir: reading active writers 2020/08/16 06:08:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:08:41 INFO : dir/file1: Deleted 2020/08/16 06:08:41 INFO : dir/file1.rclone_chunk.001_5cvda6: Moved (server side) 2020/08/16 06:08:41 INFO : dir/file1: Copied (replaced existing) 2020/08/16 06:08:41 DEBUG : dir/file1: vfs cache: fingerprint now "20,2020-08-16 06:08:40 +0000 UTC" 2020/08/16 06:08:41 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:41 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:41 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:41 DEBUG : dir: Looking for writers 2020/08/16 06:08:41 DEBUG : file1: reading active writers 2020/08/16 06:08:41 DEBUG : : Looking for writers 2020/08/16 06:08:41 DEBUG : dir: reading active writers 2020/08/16 06:08:41 DEBUG : >WaitForWriters: 2020/08/16 06:08:41 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:538 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleSizeCreateExisting Messages: directories --- FAIL: TestRWFileHandleSizeCreateExisting (14.35s) === RUN TestRWFileHandleSizeCreateNew run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:08:53 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:08:53 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:08:53 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:08:53 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:08:53 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:08:53 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:08:53 DEBUG : file1: newRWFileHandle: 2020/08/16 06:08:53 DEBUG : file1(0xc0000901c0): openPending: 2020/08/16 06:08:53 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:08:53 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:53 DEBUG : file1(0xc0000901c0): >openPending: err= 2020/08/16 06:08:53 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:08:53 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:53 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:08:53 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:08:53 DEBUG : file1(0xc0000901c0): _writeAt: size=5, off=0 2020/08/16 06:08:53 DEBUG : file1(0xc0000901c0): >_writeAt: n=5, err= 2020/08/16 06:08:53 DEBUG : file1(0xc0000901c0): close: 2020/08/16 06:08:53 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:08:53.394188724 +0000 UTC m=+331.312667272 2020/08/16 06:08:53 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:53 DEBUG : file1(0xc0000901c0): >close: err= 2020/08/16 06:08:53 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:53 DEBUG : dir: Looking for writers 2020/08/16 06:08:53 DEBUG : : Looking for writers 2020/08/16 06:08:53 DEBUG : dir: reading active writers 2020/08/16 06:08:53 DEBUG : file1: reading active writers 2020/08/16 06:08:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:53 DEBUG : dir: Looking for writers 2020/08/16 06:08:53 DEBUG : : Looking for writers 2020/08/16 06:08:53 DEBUG : dir: reading active writers 2020/08/16 06:08:53 DEBUG : file1: reading active writers 2020/08/16 06:08:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:53 DEBUG : dir: Looking for writers 2020/08/16 06:08:53 DEBUG : : Looking for writers 2020/08/16 06:08:53 DEBUG : file1: reading active writers 2020/08/16 06:08:53 DEBUG : dir: reading active writers 2020/08/16 06:08:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:53 DEBUG : dir: Looking for writers 2020/08/16 06:08:53 DEBUG : : Looking for writers 2020/08/16 06:08:53 DEBUG : dir: reading active writers 2020/08/16 06:08:53 DEBUG : file1: reading active writers 2020/08/16 06:08:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:53 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:08:53 DEBUG : dir: Looking for writers 2020/08/16 06:08:53 DEBUG : : Looking for writers 2020/08/16 06:08:53 DEBUG : dir: reading active writers 2020/08/16 06:08:53 DEBUG : file1: reading active writers 2020/08/16 06:08:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:53 DEBUG : dir: Looking for writers 2020/08/16 06:08:53 DEBUG : : Looking for writers 2020/08/16 06:08:53 DEBUG : file1: reading active writers 2020/08/16 06:08:53 DEBUG : dir: reading active writers 2020/08/16 06:08:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:54 DEBUG : dir: Looking for writers 2020/08/16 06:08:54 DEBUG : : Looking for writers 2020/08/16 06:08:54 DEBUG : dir: reading active writers 2020/08/16 06:08:54 DEBUG : file1: reading active writers 2020/08/16 06:08:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:08:54 INFO : file1.rclone_chunk.001_5cvq62: Moved (server side) 2020/08/16 06:08:54 INFO : file1: Copied (new) 2020/08/16 06:08:54 DEBUG : file1: vfs cache: fingerprint now "5,2020-08-16 06:08:53 +0000 UTC" 2020/08/16 06:08:54 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:54 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:54 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:54 DEBUG : dir: Looking for writers 2020/08/16 06:08:54 DEBUG : : Looking for writers 2020/08/16 06:08:54 DEBUG : dir: reading active writers 2020/08/16 06:08:54 DEBUG : file1: reading active writers 2020/08/16 06:08:54 DEBUG : >WaitForWriters: 2020/08/16 06:08:54 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:563 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleSizeCreateNew Messages: directories --- FAIL: TestRWFileHandleSizeCreateNew (12.93s) === RUN TestRWFileHandleOpenTests run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:09:06 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:09:06 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:09:06 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:09:06 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:09:06 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:06 DEBUG : : Looking for writers 2020/08/16 06:09:06 DEBUG : >WaitForWriters: 2020/08/16 06:09:06 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:657 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleOpenTests Messages: directories --- FAIL: TestRWFileHandleOpenTests (11.56s) === RUN TestRWFileModTimeWithOpenWriters run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:09:17 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:09:17 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:09:17 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:09:17 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:09:17 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:09:17 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:09:17 DEBUG : file1: newRWFileHandle: 2020/08/16 06:09:17 DEBUG : file1(0xc0005bbd80): openPending: 2020/08/16 06:09:17 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:09:17 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:17 DEBUG : file1(0xc0005bbd80): >openPending: err= 2020/08/16 06:09:17 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:09:17 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:17 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:09:17 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:09:18 INFO : time_test.rclone_chunk.001_5cwenl: Moved (server side) 2020/08/16 06:09:19 DEBUG : Can set mod time: true 2020/08/16 06:09:19 DEBUG : file1(0xc0005bbd80): _writeAt: size=2, off=0 2020/08/16 06:09:19 DEBUG : file1(0xc0005bbd80): >_writeAt: n=2, err= 2020/08/16 06:09:19 DEBUG : file1(0xc0005bbd80): RWFileHandle.Flush 2020/08/16 06:09:19 DEBUG : file1(0xc0005bbd80): RWFileHandle.Release 2020/08/16 06:09:19 DEBUG : file1(0xc0005bbd80): close: 2020/08/16 06:09:19 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:09:19.180920726 +0000 UTC m=+357.099399246 2020/08/16 06:09:19 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:09:19 DEBUG : file1(0xc0005bbd80): >close: err= 2020/08/16 06:09:19 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:19 DEBUG : dir: Looking for writers 2020/08/16 06:09:19 DEBUG : : Looking for writers 2020/08/16 06:09:19 DEBUG : dir: reading active writers 2020/08/16 06:09:19 DEBUG : file1: reading active writers 2020/08/16 06:09:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:09:19 DEBUG : dir: Looking for writers 2020/08/16 06:09:19 DEBUG : : Looking for writers 2020/08/16 06:09:19 DEBUG : dir: reading active writers 2020/08/16 06:09:19 DEBUG : file1: reading active writers 2020/08/16 06:09:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:09:19 DEBUG : dir: Looking for writers 2020/08/16 06:09:19 DEBUG : : Looking for writers 2020/08/16 06:09:19 DEBUG : dir: reading active writers 2020/08/16 06:09:19 DEBUG : file1: reading active writers 2020/08/16 06:09:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:09:19 DEBUG : dir: Looking for writers 2020/08/16 06:09:19 DEBUG : : Looking for writers 2020/08/16 06:09:19 DEBUG : dir: reading active writers 2020/08/16 06:09:19 DEBUG : file1: reading active writers 2020/08/16 06:09:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:09:19 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:09:19 DEBUG : dir: Looking for writers 2020/08/16 06:09:19 DEBUG : : Looking for writers 2020/08/16 06:09:19 DEBUG : dir: reading active writers 2020/08/16 06:09:19 DEBUG : file1: reading active writers 2020/08/16 06:09:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:09:19 DEBUG : dir: Looking for writers 2020/08/16 06:09:19 DEBUG : : Looking for writers 2020/08/16 06:09:19 DEBUG : dir: reading active writers 2020/08/16 06:09:19 DEBUG : file1: reading active writers 2020/08/16 06:09:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:09:19 DEBUG : dir: Looking for writers 2020/08/16 06:09:19 DEBUG : : Looking for writers 2020/08/16 06:09:19 DEBUG : dir: reading active writers 2020/08/16 06:09:19 DEBUG : file1: reading active writers 2020/08/16 06:09:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:09:20 INFO : file1.rclone_chunk.001_5cwgkl: Moved (server side) 2020/08/16 06:09:20 INFO : file1: Copied (new) 2020/08/16 06:09:20 DEBUG : file1: vfs cache: fingerprint now "2,2020-08-16 06:09:19 +0000 UTC" 2020/08/16 06:09:20 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:09:20 DEBUG : file1: File._applyPendingModTime OK 2020/08/16 06:09:20 DEBUG : file1: vfs cache: fingerprint now "2,2012-11-18 17:32:31 +0000 UTC" 2020/08/16 06:09:20 DEBUG : file1: vfs cache: setting modification time to 2012-11-18 17:32:31 +0000 UTC 2020/08/16 06:09:20 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:20 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:09:20 DEBUG : dir: Looking for writers 2020/08/16 06:09:20 DEBUG : : Looking for writers 2020/08/16 06:09:20 DEBUG : file1: reading active writers 2020/08/16 06:09:20 DEBUG : dir: reading active writers 2020/08/16 06:09:20 DEBUG : >WaitForWriters: 2020/08/16 06:09:20 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:20 DEBUG : dir: Looking for writers 2020/08/16 06:09:20 DEBUG : : Looking for writers 2020/08/16 06:09:20 DEBUG : dir: reading active writers 2020/08/16 06:09:20 DEBUG : file1: reading active writers 2020/08/16 06:09:20 DEBUG : >WaitForWriters: 2020/08/16 06:09:20 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:694 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileModTimeWithOpenWriters Messages: directories --- FAIL: TestRWFileModTimeWithOpenWriters (14.55s) === RUN TestRWCacheRename run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:09:32 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:09:32 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:09:32 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestChunkerChunk50bMailru/rclone-test-pomaqep9gizovek9xozuler3" 2020/08/16 06:09:32 DEBUG : rename_me: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:09:32 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/08/16 06:09:32 DEBUG : rename_me: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:09:32 DEBUG : rename_me: newRWFileHandle: 2020/08/16 06:09:32 DEBUG : rename_me(0xc0003c0dc0): openPending: 2020/08/16 06:09:32 DEBUG : rename_me: vfs cache: truncate to size=0 2020/08/16 06:09:32 DEBUG : : Added virtual directory entry vAdd: "rename_me" 2020/08/16 06:09:32 DEBUG : rename_me(0xc0003c0dc0): >openPending: err= 2020/08/16 06:09:32 DEBUG : rename_me: >newRWFileHandle: err= 2020/08/16 06:09:32 DEBUG : : Added virtual directory entry vAdd: "rename_me" 2020/08/16 06:09:32 DEBUG : rename_me: >Open: fd=rename_me (rw), err= 2020/08/16 06:09:32 DEBUG : rename_me: >OpenFile: fd=rename_me (rw), err= 2020/08/16 06:09:32 DEBUG : rename_me(0xc0003c0dc0): _writeAt: size=5, off=0 2020/08/16 06:09:32 DEBUG : rename_me(0xc0003c0dc0): >_writeAt: n=5, err= 2020/08/16 06:09:32 DEBUG : rename_me(0xc0003c0dc0): close: 2020/08/16 06:09:32 DEBUG : rename_me: vfs cache: setting modification time to 2020-08-16 06:09:32.441145717 +0000 UTC m=+370.359624255 2020/08/16 06:09:32 INFO : rename_me: vfs cache: queuing for upload in 100ms 2020/08/16 06:09:32 DEBUG : rename_me(0xc0003c0dc0): >close: err= 2020/08/16 06:09:32 INFO : rename_me: vfs cache: renamed in cache to "i_was_renamed" 2020/08/16 06:09:32 DEBUG : i_was_renamed: Updating file with 0xc00019f380 2020/08/16 06:09:32 DEBUG : : Added virtual directory entry vDel: "rename_me" 2020/08/16 06:09:32 DEBUG : : Added virtual directory entry vAdd: "i_was_renamed" 2020/08/16 06:09:32 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:32 DEBUG : dir: Looking for writers 2020/08/16 06:09:32 DEBUG : : Looking for writers 2020/08/16 06:09:32 DEBUG : dir: reading active writers 2020/08/16 06:09:32 DEBUG : i_was_renamed: reading active writers 2020/08/16 06:09:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:09:32 DEBUG : dir: Looking for writers 2020/08/16 06:09:32 DEBUG : : Looking for writers 2020/08/16 06:09:32 DEBUG : dir: reading active writers 2020/08/16 06:09:32 DEBUG : i_was_renamed: reading active writers 2020/08/16 06:09:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:09:32 DEBUG : dir: Looking for writers 2020/08/16 06:09:32 DEBUG : : Looking for writers 2020/08/16 06:09:32 DEBUG : dir: reading active writers 2020/08/16 06:09:32 DEBUG : i_was_renamed: reading active writers 2020/08/16 06:09:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:09:32 DEBUG : dir: Looking for writers 2020/08/16 06:09:32 DEBUG : : Looking for writers 2020/08/16 06:09:32 DEBUG : dir: reading active writers 2020/08/16 06:09:32 DEBUG : i_was_renamed: reading active writers 2020/08/16 06:09:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:09:32 DEBUG : i_was_renamed: vfs cache: starting upload 2020/08/16 06:09:32 DEBUG : dir: Looking for writers 2020/08/16 06:09:32 DEBUG : : Looking for writers 2020/08/16 06:09:32 DEBUG : dir: reading active writers 2020/08/16 06:09:32 DEBUG : i_was_renamed: reading active writers 2020/08/16 06:09:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:09:32 DEBUG : dir: Looking for writers 2020/08/16 06:09:32 DEBUG : : Looking for writers 2020/08/16 06:09:32 DEBUG : dir: reading active writers 2020/08/16 06:09:32 DEBUG : i_was_renamed: reading active writers 2020/08/16 06:09:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:09:33 DEBUG : dir: Looking for writers 2020/08/16 06:09:33 DEBUG : : Looking for writers 2020/08/16 06:09:33 DEBUG : i_was_renamed: reading active writers 2020/08/16 06:09:33 DEBUG : dir: reading active writers 2020/08/16 06:09:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:09:33 INFO : i_was_renamed.rclone_chunk.001_5cwt3f: Moved (server side) 2020/08/16 06:09:33 INFO : i_was_renamed: Copied (new) 2020/08/16 06:09:33 DEBUG : i_was_renamed: vfs cache: fingerprint now "5,2020-08-16 06:09:32 +0000 UTC" 2020/08/16 06:09:33 DEBUG : i_was_renamed: vfs cache: writeback object to VFS layer 2020/08/16 06:09:33 DEBUG : : Added virtual directory entry vAdd: "i_was_renamed" 2020/08/16 06:09:33 INFO : i_was_renamed: vfs cache: upload succeeded try #1 2020/08/16 06:09:33 DEBUG : dir: Looking for writers 2020/08/16 06:09:33 DEBUG : : Looking for writers 2020/08/16 06:09:33 DEBUG : dir: reading active writers 2020/08/16 06:09:33 DEBUG : i_was_renamed: reading active writers 2020/08/16 06:09:33 DEBUG : >WaitForWriters: 2020/08/16 06:09:33 DEBUG : vfs cache: cleaner exiting run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 read_write_test.go:726 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWCacheRename Messages: directories --- FAIL: TestRWCacheRename (13.02s) === RUN TestCaseSensitivity run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" vfs_case_test.go:19: Can't test case sensitivity - this remote is officially not case-sensitive run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 panic.go:617 testing.go:815 testing.go:795 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 --- FAIL: TestCaseSensitivity (11.46s) === RUN TestVFSNew run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:09:56 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:09:56 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': Re-using VFS from active cache 2020/08/16 06:09:56 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:56 DEBUG : : Looking for writers 2020/08/16 06:09:56 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:161 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSNew Messages: directories --- FAIL: TestVFSNew (11.46s) === RUN TestVFSNewWithOpts run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:10:08 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:10:08 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:10:08 DEBUG : : Looking for writers 2020/08/16 06:10:08 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:177 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSNewWithOpts Messages: directories --- FAIL: TestVFSNewWithOpts (11.42s) === RUN TestVFSRoot run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:10:19 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:10:19 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:10:19 DEBUG : : Looking for writers 2020/08/16 06:10:19 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:189 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSRoot Messages: directories --- FAIL: TestVFSRoot (11.47s) === RUN TestVFSStat run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:10:31 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:10:31 INFO : file1.rclone_chunk.001_5cyg5e: Moved (server side) 2020/08/16 06:10:32 INFO : dir/file2.rclone_chunk.001_5cyg6r: Moved (server side) 2020/08/16 06:10:33 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:10:33 DEBUG : dir: Looking for writers 2020/08/16 06:10:33 DEBUG : file2: reading active writers 2020/08/16 06:10:33 DEBUG : : Looking for writers 2020/08/16 06:10:33 DEBUG : dir: reading active writers 2020/08/16 06:10:33 DEBUG : file1: reading active writers 2020/08/16 06:10:33 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:225 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSStat Messages: directories --- FAIL: TestVFSStat (14.18s) === RUN TestVFSStatParent run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:10:45 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:10:46 INFO : file1.rclone_chunk.001_5cyuhl: Moved (server side) 2020/08/16 06:10:46 INFO : dir/file2.rclone_chunk.001_5cyviw: Moved (server side) 2020/08/16 06:10:47 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:10:47 DEBUG : dir: Looking for writers 2020/08/16 06:10:47 DEBUG : : Looking for writers 2020/08/16 06:10:47 DEBUG : dir: reading active writers 2020/08/16 06:10:47 DEBUG : file1: reading active writers 2020/08/16 06:10:47 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:258 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSStatParent Messages: directories --- FAIL: TestVFSStatParent (13.82s) === RUN TestVFSOpenFile run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:10:59 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:10:59 INFO : file1.rclone_chunk.001_5cz8yq: Moved (server side) 2020/08/16 06:11:00 INFO : dir/file2.rclone_chunk.001_5cz8bs: Moved (server side) 2020/08/16 06:11:01 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:11:01 DEBUG : file1: Open: flags=O_RDONLY 2020/08/16 06:11:01 DEBUG : file1: >Open: fd=file1 (r), err= 2020/08/16 06:11:01 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/08/16 06:11:01 DEBUG : dir: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:11:01 DEBUG : dir: >OpenFile: fd=dir/ (r), err= 2020/08/16 06:11:01 DEBUG : dir/new_file.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:11:01 DEBUG : dir/new_file.txt: >OpenFile: fd=, err=file does not exist 2020/08/16 06:11:01 DEBUG : dir/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:11:01 DEBUG : dir/new_file.txt: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:11:01 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/08/16 06:11:01 DEBUG : dir/new_file.txt: >Open: fd=dir/new_file.txt (w), err= 2020/08/16 06:11:01 DEBUG : dir/new_file.txt: >OpenFile: fd=dir/new_file.txt (w), err= 2020/08/16 06:11:01 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/08/16 06:11:01 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (0 bytes), uploading instead of streaming 2020/08/16 06:11:02 INFO : dir/new_file.txt.rclone_chunk.001_5cza3x: Moved (server side) 2020/08/16 06:11:02 INFO : dir/new_file.txt: Copied (new) 2020/08/16 06:11:02 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/08/16 06:11:02 DEBUG : not found/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:11:02 DEBUG : not found/new_file.txt: >OpenFile: fd=, err=file does not exist 2020/08/16 06:11:02 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:11:02 DEBUG : dir: Looking for writers 2020/08/16 06:11:02 DEBUG : file2: reading active writers 2020/08/16 06:11:02 DEBUG : new_file.txt: reading active writers 2020/08/16 06:11:02 DEBUG : : Looking for writers 2020/08/16 06:11:02 DEBUG : dir: reading active writers 2020/08/16 06:11:02 DEBUG : file1: reading active writers 2020/08/16 06:11:02 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:293 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSOpenFile Messages: directories --- FAIL: TestVFSOpenFile (14.88s) === RUN TestVFSRename run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:11:14 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:11:14 INFO : dir/file2.rclone_chunk.001_5czn5v: Moved (server side) 2020/08/16 06:11:15 DEBUG : dir/file2: move non-chunked object... 2020/08/16 06:11:15 INFO : dir/file2: Moved (server side) 2020/08/16 06:11:15 INFO : dir/file2: Moved (server side) 2020/08/16 06:11:15 DEBUG : dir/file1: Updating file with dir/file1 0xc0002ee780 2020/08/16 06:11:15 DEBUG : dir: Added virtual directory entry vDel: "file2" 2020/08/16 06:11:15 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:16 DEBUG : dir/file1: move non-chunked object... 2020/08/16 06:11:16 INFO : dir/file1: Moved (server side) 2020/08/16 06:11:16 INFO : dir/file1: Moved (server side) 2020/08/16 06:11:16 DEBUG : file0: Updating file with file0 0xc0002ee780 2020/08/16 06:11:16 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:11:16 DEBUG : : Added virtual directory entry vAdd: "file0" 2020/08/16 06:11:16 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:11:16 DEBUG : dir: Looking for writers 2020/08/16 06:11:16 DEBUG : : Looking for writers 2020/08/16 06:11:16 DEBUG : dir: reading active writers 2020/08/16 06:11:16 DEBUG : file0: reading active writers 2020/08/16 06:11:16 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:322 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSRename Messages: directories --- FAIL: TestVFSRename (14.35s) === RUN TestVFSStatfs run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:11:28 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:11:28 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:11:28 DEBUG : : Looking for writers 2020/08/16 06:11:28 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 vfs_test.go:373 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestVFSStatfs Messages: directories --- FAIL: TestVFSStatfs (11.62s) === RUN TestWriteFileHandleMethods run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:11:39 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:11:39 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:11:40 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:11:40 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:40 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:11:40 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:11:40 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:40 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2020/08/16 06:11:40 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2020/08/16 06:11:40 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2020/08/16 06:11:40 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (5 bytes), uploading instead of streaming 2020/08/16 06:11:40 INFO : file1.rclone_chunk.001_5d0dgy: Moved (server side) 2020/08/16 06:11:40 INFO : file1: Copied (new) 2020/08/16 06:11:40 DEBUG : : Added virtual directory entry vAdd: "file1" 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 2020/08/16 06:11:48 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:11:48 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:11:48 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:48 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:11:48 DEBUG : file1: >OpenFile: fd=file1 (w), err= 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 2020/08/16 06:11:48 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:11:48 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:11:48 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:48 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:11:48 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:11:48 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes 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 2020/08/16 06:11:48 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/08/16 06:11:48 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/08/16 06:11:48 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:48 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:11:48 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:11:48 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:48 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (0 bytes), uploading instead of streaming 2020/08/16 06:11:49 INFO : file1: Deleted 2020/08/16 06:11:50 INFO : file1.rclone_chunk.001_5d0l0x: Moved (server side) 2020/08/16 06:11:50 INFO : file1: Copied (new) 2020/08/16 06:11:50 DEBUG : : Added virtual directory entry vAdd: "file1" 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 2020/08/16 06:11:50 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/08/16 06:11:50 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/08/16 06:11:50 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:50 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:11:50 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:11:50 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:11:50 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (7 bytes), uploading instead of streaming 2020/08/16 06:11:50 INFO : file1: Deleted 2020/08/16 06:11:51 INFO : file1.rclone_chunk.001_5d0nqr: Moved (server side) 2020/08/16 06:11:51 INFO : file1: Copied (new) 2020/08/16 06:11:51 DEBUG : : Added virtual directory entry vAdd: "file1" 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 2020/08/16 06:11:51 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:11:51 DEBUG : dir: Looking for writers 2020/08/16 06:11:51 DEBUG : : Looking for writers 2020/08/16 06:11:51 DEBUG : dir: reading active writers 2020/08/16 06:11:51 DEBUG : file1: reading active writers 2020/08/16 06:11:51 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:132 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleMethods Messages: directories --- FAIL: TestWriteFileHandleMethods (22.79s) === RUN TestWriteFileHandleWriteAt run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:12:02 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:12:02 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:12:02 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:12:02 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:02 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:12:02 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:12:02 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:02 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2020/08/16 06:12:03 DEBUG : file1: aborting in-sequence write wait, off=100 2020/08/16 06:12:03 DEBUG : file1: failed to wait for in-sequence write to 100 2020/08/16 06:12:03 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2020/08/16 06:12:03 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (11 bytes), uploading instead of streaming 2020/08/16 06:12:04 INFO : file1.rclone_chunk.001_5d10cv: Moved (server side) 2020/08/16 06:12:04 INFO : file1: Copied (new) 2020/08/16 06:12:04 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:04 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor 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 2020/08/16 06:12:12 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:12:12 DEBUG : dir: Looking for writers 2020/08/16 06:12:12 DEBUG : : Looking for writers 2020/08/16 06:12:12 DEBUG : dir: reading active writers 2020/08/16 06:12:12 DEBUG : file1: reading active writers 2020/08/16 06:12:12 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:177 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleWriteAt Messages: directories --- FAIL: TestWriteFileHandleWriteAt (21.38s) === RUN TestWriteFileHandleFlush run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:12:24 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:12:24 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:12:24 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:12:24 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:24 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:12:24 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:12:24 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2020/08/16 06:12:24 DEBUG : : Added virtual directory entry vAdd: "file1" 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 2020/08/16 06:12:24 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (5 bytes), uploading instead of streaming 2020/08/16 06:12:25 INFO : file1.rclone_chunk.001_5d1lk6: Moved (server side) 2020/08/16 06:12:25 INFO : file1: Copied (new) 2020/08/16 06:12:25 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:25 DEBUG : file1: WriteFileHandle.Flush nothing to do 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 2020/08/16 06:12:25 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:12:25 DEBUG : dir: Looking for writers 2020/08/16 06:12:25 DEBUG : : Looking for writers 2020/08/16 06:12:25 DEBUG : dir: reading active writers 2020/08/16 06:12:25 DEBUG : file1: reading active writers 2020/08/16 06:12:25 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:210 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleFlush Messages: directories --- FAIL: TestWriteFileHandleFlush (12.53s) === RUN TestWriteFileHandleRelease run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:12:36 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:12:36 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:12:36 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:12:36 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:36 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:12:36 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:12:36 DEBUG : file1: WriteFileHandle.Release closing 2020/08/16 06:12:36 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:36 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (0 bytes), uploading instead of streaming 2020/08/16 06:12:37 INFO : file1.rclone_chunk.001_5d1xqh: Moved (server side) 2020/08/16 06:12:37 INFO : file1: Copied (new) 2020/08/16 06:12:37 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:37 DEBUG : file1: WriteFileHandle.Release nothing to do 2020/08/16 06:12:37 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:12:37 DEBUG : dir: Looking for writers 2020/08/16 06:12:37 DEBUG : : Looking for writers 2020/08/16 06:12:37 DEBUG : dir: reading active writers 2020/08/16 06:12:37 DEBUG : file1: reading active writers 2020/08/16 06:12:37 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:229 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileHandleRelease Messages: directories --- FAIL: TestWriteFileHandleRelease (12.80s) === RUN TestWriteFileModTimeWithOpenWriters run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:12:49 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:12:49 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:12:49 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:12:49 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:49 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:12:49 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:12:49 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:49 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (2 bytes), uploading instead of streaming 2020/08/16 06:12:50 INFO : file1.rclone_chunk.001_5d2a98: Moved (server side) 2020/08/16 06:12:50 INFO : file1: Copied (new) 2020/08/16 06:12:50 DEBUG : file1: File._applyPendingModTime OK 2020/08/16 06:12:50 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:12:50 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:12:50 DEBUG : dir: Looking for writers 2020/08/16 06:12:50 DEBUG : : Looking for writers 2020/08/16 06:12:50 DEBUG : dir: reading active writers 2020/08/16 06:12:50 DEBUG : file1: reading active writers 2020/08/16 06:12:50 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:286 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestWriteFileModTimeWithOpenWriters Messages: directories --- FAIL: TestWriteFileModTimeWithOpenWriters (12.77s) === RUN TestFileReadAtZeroLength run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:13:02 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:13:02 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:13:02 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:13:02 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:13:02 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:13:02 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:13:02 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:13:02 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (0 bytes), uploading instead of streaming 2020/08/16 06:13:03 INFO : file1.rclone_chunk.001_5d2ndz: Moved (server side) 2020/08/16 06:13:03 INFO : file1: Copied (new) 2020/08/16 06:13:03 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:13:03 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/08/16 06:13:03 DEBUG : file1: Open: flags=O_RDONLY 2020/08/16 06:13:03 DEBUG : file1: >Open: fd=file1 (r), err= 2020/08/16 06:13:03 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/08/16 06:13:03 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:13:03 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Switch file server: locks 1, url https://cloclo13.datacloudmail.ru/oauth-get/, expiry "2020-08-16T06:16:03.22220694Z" 2020/08/16 06:13:03 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2020/08/16 06:13:03 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo13.datacloudmail.ru/oauth-get/ 2020/08/16 06:13:03 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:13:03 DEBUG : dir: Looking for writers 2020/08/16 06:13:03 DEBUG : : Looking for writers 2020/08/16 06:13:03 DEBUG : dir: reading active writers 2020/08/16 06:13:03 DEBUG : file1: reading active writers 2020/08/16 06:13:03 DEBUG : >WaitForWriters: run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:322 write_test.go:325 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileReadAtZeroLength Messages: directories --- FAIL: TestFileReadAtZeroLength (12.99s) === RUN TestFileReadAtNonZeroLength run.go:176: Remote "Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3'", Local "Local file system at /tmp/rclone720967012", Modify Window "1s" 2020/08/16 06:13:15 INFO : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': poll-interval is not supported by this remote 2020/08/16 06:13:15 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:13:15 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:13:15 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:13:15 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:13:15 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:13:15 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:13:15 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': File to upload is small (100 bytes), uploading instead of streaming 2020/08/16 06:13:15 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: new upload shard: https://cld-upload10.cloud.mail.ru/upload-web/ 2020/08/16 06:13:17 INFO : file1.rclone_chunk.001_5d3026: Moved (server side) 2020/08/16 06:13:17 INFO : file1.rclone_chunk.002_5d3026: Moved (server side) 2020/08/16 06:13:17 INFO : file1: Copied (new) 2020/08/16 06:13:17 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:13:17 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/08/16 06:13:17 DEBUG : file1: Open: flags=O_RDONLY 2020/08/16 06:13:17 DEBUG : file1: >Open: fd=file1 (r), err= 2020/08/16 06:13:17 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/08/16 06:13:17 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:13:17 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo13.datacloudmail.ru/oauth-get/ 2020/08/16 06:13:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo13.datacloudmail.ru/oauth-get/ 2020/08/16 06:13:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo13.datacloudmail.ru/oauth-get/ 2020/08/16 06:13:18 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2020/08/16 06:13:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo13.datacloudmail.ru/oauth-get/ 2020/08/16 06:13:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo13.datacloudmail.ru/oauth-get/ 2020/08/16 06:13:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo13.datacloudmail.ru/oauth-get/ 2020/08/16 06:13:18 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:13:18 DEBUG : dir: Looking for writers 2020/08/16 06:13:18 DEBUG : : Looking for writers 2020/08/16 06:13:18 DEBUG : dir: reading active writers 2020/08/16 06:13:18 DEBUG : file1: reading active writers 2020/08/16 06:13:18 DEBUG : >WaitForWriters: 2020/08/16 06:13:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Lock file server: locks 1, url https://cloclo13.datacloudmail.ru/oauth-get/ 2020/08/16 06:13:18 DEBUG : [rclone-test-pomaqep9gizovek9xozuler3]: Unlock file server: locks 0, url https://cloclo13.datacloudmail.ru/oauth-get/ run.go:121: removing dir "dir" failed - try 1/3: directory not empty run.go:121: removing dir "dir" failed - try 2/3: directory not empty run.go:121: removing dir "dir" failed - try 3/3: directory not empty run.go:124: removing dir "dir" failed: directory not empty fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:324: Error Trace: fstest.go:324 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:322 write_test.go:329 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestFileReadAtNonZeroLength Messages: directories --- FAIL: TestFileReadAtNonZeroLength (14.94s) FAIL 2020/08/16 06:13:30 DEBUG : Chunked 'TestChunkerChunk50bMailru:rclone-test-pomaqep9gizovek9xozuler3': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerChunk50bMailru: -verbose -size-limit 10240 -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 10m8.374978774s (try 4/5): exit status 1: Failed [TestFileRename/minimal,forceCache=true TestFileRename/writes,forceCache=false TestFileRename/writes,forceCache=true TestFileRename/full,forceCache=false TestRcGetVFS TestReadFileHandleMethods TestReadFileHandleSeek TestReadFileHandleReadAt TestReadFileHandleFlush TestReadFileHandleRelease TestRWFileHandleMethodsRead TestRWFileHandleSeek TestRWFileHandleReadAt TestRWFileHandleFlushRead TestRWFileHandleReleaseRead TestRWFileHandleMethodsWrite TestRWFileHandleWriteAt TestRWFileHandleWriteNoWrite TestRWFileHandleFlushWrite TestRWFileHandleReleaseWrite TestRWFileHandleSizeTruncateExisting TestRWFileHandleSizeCreateExisting TestRWFileHandleSizeCreateNew TestRWFileHandleOpenTests TestRWFileModTimeWithOpenWriters TestRWCacheRename TestCaseSensitivity TestVFSNew TestVFSNewWithOpts TestVFSRoot TestVFSStat TestVFSStatParent TestVFSOpenFile TestVFSRename TestVFSStatfs TestWriteFileHandleMethods TestWriteFileHandleWriteAt TestWriteFileHandleFlush TestWriteFileHandleRelease TestWriteFileModTimeWithOpenWriters TestFileReadAtZeroLength TestFileReadAtNonZeroLength]