"./vfs.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -test.run '^(TestCaseSensitivity|TestDirCreate|TestDirMkdir|TestDirMkdirSub|TestDirRemove|TestDirRemoveAll|TestDirRemoveName|TestDirRename|TestFileOpen|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRemove|TestFileRemoveAll|TestFileRename|TestRWFileHandleFlushRead|TestRWFileHandleFlushWrite|TestRWFileHandleMethodsWrite|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeCreateNew|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestVFSNew|TestVFSOpenFile|TestVFSRename|TestVFSStat|TestVFSStatParent|TestWriteFileHandleFlush|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(minimal,forceCache=true|off,forceCache=false)$'" - Starting (try 2/5) === RUN TestDirCreate run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:06:46 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:06:49 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:06:49 DEBUG : dir: Added virtual directory entry vAdd: "potato" 2020/08/16 06:06:49 DEBUG : dir/potato: >Open: fd=dir/potato (w), err= 2020/08/16 06:06:49 DEBUG : dir: Added virtual directory entry vAdd: "potato" 2020/08/16 06:06:49 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: File to upload is small (5 bytes), uploading instead of streaming 2020/08/16 06:06:49 DEBUG : dir/potato: SHA-1 = aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d OK 2020/08/16 06:06:49 INFO : dir/potato: Copied (new) 2020/08/16 06:06:49 DEBUG : dir: Added virtual directory entry vAdd: "potato" 2020/08/16 06:06:49 DEBUG : dir: Removed virtual directory entry vAdd: "potato" 2020/08/16 06:06:49 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:49 DEBUG : dir: Looking for writers 2020/08/16 06:06:49 DEBUG : potato: reading active writers 2020/08/16 06:06:49 DEBUG : file1: reading active writers 2020/08/16 06:06:49 DEBUG : : Looking for writers 2020/08/16 06:06:49 DEBUG : dir: reading active writers 2020/08/16 06:06:49 DEBUG : >WaitForWriters: --- PASS: TestDirCreate (5.08s) === RUN TestDirMkdir run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:06:52 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:06:52 DEBUG : dir: Added virtual directory entry vAdd: "sub" fstest.go:247: Filtering empty directory "dir/sub" 2020/08/16 06:06:53 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:53 DEBUG : dir/sub: Looking for writers 2020/08/16 06:06:53 DEBUG : dir: Looking for writers 2020/08/16 06:06:53 DEBUG : sub: reading active writers 2020/08/16 06:06:53 DEBUG : file1: reading active writers 2020/08/16 06:06:53 DEBUG : : Looking for writers 2020/08/16 06:06:53 DEBUG : dir: reading active writers 2020/08/16 06:06:53 DEBUG : >WaitForWriters: --- PASS: TestDirMkdir (1.59s) === RUN TestDirMkdirSub run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:06:53 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:06:54 DEBUG : dir: Added virtual directory entry vAdd: "sub" 2020/08/16 06:06:54 DEBUG : dir/sub: Added virtual directory entry vAdd: "subsub" fstest.go:247: Filtering empty directory "dir/sub" fstest.go:247: Filtering empty directory "dir/sub/subsub" 2020/08/16 06:06:54 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:54 DEBUG : dir/sub/subsub: Looking for writers 2020/08/16 06:06:54 DEBUG : dir/sub: Looking for writers 2020/08/16 06:06:54 DEBUG : subsub: reading active writers 2020/08/16 06:06:54 DEBUG : dir: Looking for writers 2020/08/16 06:06:54 DEBUG : file1: reading active writers 2020/08/16 06:06:54 DEBUG : sub: reading active writers 2020/08/16 06:06:54 DEBUG : : Looking for writers 2020/08/16 06:06:54 DEBUG : dir: reading active writers 2020/08/16 06:06:54 DEBUG : >WaitForWriters: --- PASS: TestDirMkdirSub (2.08s) === RUN TestDirRemove run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:06:55 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:06:56 ERROR : dir/: Dir.Remove not empty 2020/08/16 06:06:56 DEBUG : dir/file1: Remove: 2020/08/16 06:06:56 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:06:56 DEBUG : dir/file1: >Remove: err= 2020/08/16 06:06:56 DEBUG : : Added virtual directory entry vDel: "dir" 2020/08/16 06:06:57 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:57 DEBUG : : Looking for writers 2020/08/16 06:06:57 DEBUG : >WaitForWriters: --- PASS: TestDirRemove (1.67s) === RUN TestDirRemoveAll run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:06:57 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:06:58 DEBUG : dir/file1: Remove: 2020/08/16 06:06:58 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:06:58 DEBUG : dir/file1: >Remove: err= 2020/08/16 06:06:58 DEBUG : : Added virtual directory entry vDel: "dir" 2020/08/16 06:06:58 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:06:58 DEBUG : : Looking for writers 2020/08/16 06:06:58 DEBUG : >WaitForWriters: --- PASS: TestDirRemoveAll (1.43s) === RUN TestDirRemoveName run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:06:58 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:06:59 DEBUG : dir/file1: Remove: 2020/08/16 06:06:59 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:07:00 DEBUG : dir/file1: >Remove: err= fstest.go:247: Filtering empty directory "dir" 2020/08/16 06:07:00 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:00 DEBUG : dir: Looking for writers 2020/08/16 06:07:00 DEBUG : : Looking for writers 2020/08/16 06:07:00 DEBUG : dir: reading active writers 2020/08/16 06:07:00 DEBUG : >WaitForWriters: --- PASS: TestDirRemoveName (1.71s) === RUN TestDirRename run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:00 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:07:01 ERROR : dir/not found: Dir.Rename error: file does not exist 2020/08/16 06:07:02 DEBUG : dir/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/08/16 06:07:02 INFO : dir/file1: Copied (server side copy) 2020/08/16 06:07:02 DEBUG : dir/file3: SHA-1 = 5360d62d7372ae902378af794a02722679d4c87f OK 2020/08/16 06:07:02 INFO : dir/file3: Copied (server side copy) 2020/08/16 06:07:03 INFO : dir/file3: Deleted 2020/08/16 06:07:04 INFO : dir/file1: Deleted 2020/08/16 06:07:04 DEBUG : dir: Updating dir with dir2 0xc00064e600 2020/08/16 06:07:04 DEBUG : dir: forgetting directory cache 2020/08/16 06:07:04 DEBUG : : Added virtual directory entry vDel: "dir" 2020/08/16 06:07:04 DEBUG : : Added virtual directory entry vAdd: "dir2" 2020/08/16 06:07:06 DEBUG : dir2/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/08/16 06:07:06 INFO : dir2/file1: Copied (server side copy) 2020/08/16 06:07:12 INFO : dir2/file1: Deleted 2020/08/16 06:07:12 DEBUG : file2: Updating file with file2 0xc00064e840 2020/08/16 06:07:12 DEBUG : dir2: Added virtual directory entry vDel: "file1" 2020/08/16 06:07:12 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/08/16 06:07:15 DEBUG : file2: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/08/16 06:07:15 INFO : file2: Copied (server side copy) 2020/08/16 06:07:17 INFO : file2: Deleted 2020/08/16 06:07:17 DEBUG : dir2/file3: Updating file with dir2/file3 0xc00064e840 2020/08/16 06:07:17 DEBUG : : Added virtual directory entry vDel: "file2" 2020/08/16 06:07:17 DEBUG : dir2: Added virtual directory entry vAdd: "file3" 2020/08/16 06:07:17 DEBUG : : Added virtual directory entry vAdd: "empty directory" 2020/08/16 06:07:17 DEBUG : empty directory: Updating dir with renamed empty directory 0xc000870600 2020/08/16 06:07:17 DEBUG : empty directory: forgetting directory cache 2020/08/16 06:07:17 DEBUG : : Added virtual directory entry vDel: "empty directory" 2020/08/16 06:07:17 DEBUG : : Added virtual directory entry vAdd: "renamed empty directory" 2020/08/16 06:07:17 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:17 DEBUG : dir2: Looking for writers 2020/08/16 06:07:17 DEBUG : file3: reading active writers 2020/08/16 06:07:17 DEBUG : renamed empty directory: Looking for writers 2020/08/16 06:07:17 DEBUG : : Looking for writers 2020/08/16 06:07:17 DEBUG : dir2: reading active writers 2020/08/16 06:07:17 DEBUG : renamed empty directory: reading active writers 2020/08/16 06:07:17 DEBUG : >WaitForWriters: --- PASS: TestDirRename (27.48s) === RUN TestFileOpenWrite run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:28 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:07:29 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:29 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: File to upload is small (25 bytes), uploading instead of streaming 2020/08/16 06:07:31 DEBUG : dir/file1: SHA-1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK 2020/08/16 06:07:31 INFO : dir/file1: Copied (new) 2020/08/16 06:07:31 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:31 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:31 DEBUG : dir: Looking for writers 2020/08/16 06:07:31 DEBUG : file1: reading active writers 2020/08/16 06:07:31 DEBUG : : Looking for writers 2020/08/16 06:07:31 DEBUG : dir: reading active writers 2020/08/16 06:07:31 DEBUG : >WaitForWriters: --- PASS: TestFileOpenWrite (4.77s) === RUN TestFileRemove run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:32 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 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:302: Error Trace: fstest.go:302 fstest.go:335 fstest.go:347 file_test.go:27 file_test.go:194 Error: Should be true Test: TestFileRemove Messages: listing wrong, want dir/file1 (14) got fstest.go:200: Not found "dir/file1" fstest.go:203: Error Trace: fstest.go:203 fstest.go:307 fstest.go:335 fstest.go:347 file_test.go:27 file_test.go:194 Error: Not equal: expected: 0 actual : 1 Test: TestFileRemove Messages: 1 objects not found file_test.go:30: Error Trace: file_test.go:30 file_test.go:194 Error: Received unexpected error: file does not exist Test: TestFileRemove --- FAIL: TestFileRemove (7.90s) === RUN TestFileRemoveAll run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:40 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache file_test.go:30: Error Trace: file_test.go:30 file_test.go:208 Error: Received unexpected error: file does not exist Test: TestFileRemoveAll --- FAIL: TestFileRemoveAll (0.87s) === RUN TestFileOpen run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:41 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache file_test.go:30: Error Trace: file_test.go:30 file_test.go:222 Error: Received unexpected error: file does not exist Test: TestFileOpen --- FAIL: TestFileOpen (3.23s) === RUN TestFileRename === RUN TestFileRename/off,forceCache=false run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:44 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache file_test.go:30: Error Trace: file_test.go:30 file_test.go:248 file_test.go:357 Error: Received unexpected error: file does not exist Test: TestFileRename/off,forceCache=false === RUN TestFileRename/minimal,forceCache=true run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:45 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:07:45 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:07:45 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:07:45 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:49 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/08/16 06:07:49 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e240): openPending: 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "" 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:07:49 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e240): >openPending: err= 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:07:49 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:07:49 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:49 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e240): _writeAt: size=14, off=0 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e240): >_writeAt: n=14, err= 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e240): close: 2020/08/16 06:07:49 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:07:49.251714866 +0000 UTC m=+63.015572506 2020/08/16 06:07:49 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e240): >close: err= 2020/08/16 06:07:49 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:07:49 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:07:49 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:07:49 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e340): _readAt: size=512, off=0 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e340): openPending: 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "14,2001-02-03 04:05:06.499 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:07:49 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e340): >openPending: err= 2020/08/16 06:07:49 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e340): >_readAt: n=14, err=EOF 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e340): close: 2020/08/16 06:07:49 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:07:49.251714866 +0000 UTC m=+63.015572506 2020/08/16 06:07:49 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:07:49 DEBUG : dir/file1(0xc00073e340): >close: err= 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:07:49 DEBUG : dir/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/08/16 06:07:49 INFO : dir/file1: Copied (replaced existing) 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: fingerprint now "14,2020-08-16 06:07:49.251 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" 2020/08/16 06:07:49 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/08/16 06:07:49 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:07:49 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/08/16 06:07:50 DEBUG : dir/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/08/16 06:07:50 INFO : dir/file1: Copied (server side copy) 2020/08/16 06:07:51 INFO : dir/file1: Deleted 2020/08/16 06:07:51 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:07:51 DEBUG : newLeaf: Updating file with newLeaf 0xc00034a540 2020/08/16 06:07:51 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:07:51 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:07:52 DEBUG : newLeaf: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/08/16 06:07:52 INFO : newLeaf: Copied (server side copy) 2020/08/16 06:07:52 INFO : newLeaf: Deleted 2020/08/16 06:07:52 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/08/16 06:07:52 DEBUG : dir/file1: Updating file with dir/file1 0xc00034a540 2020/08/16 06:07:52 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/08/16 06:07:52 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:53 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/08/16 06:07:53 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:07:53 DEBUG : dir/file1(0xc00073e6c0): openPending: 2020/08/16 06:07:53 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "14,2020-08-16 06:07:49.251 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" 2020/08/16 06:07:53 DEBUG : dir/file1: vfs cache: removing cached entry as stale (remote fingerprint "14,2001-02-03 04:05:06.499 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" != cached fingerprint "14,2020-08-16 06:07:49.251 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6") 2020/08/16 06:07:53 INFO : dir/file1: vfs cache: removed cache file as stale (remote is different) 2020/08/16 06:07:53 DEBUG : dir/file1: vfs cache: removed metadata from cache as stale (remote is different) 2020/08/16 06:07:53 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/08/16 06:07:53 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:07:53 DEBUG : dir/file1(0xc00073e6c0): >openPending: err= 2020/08/16 06:07:53 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:07:53 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:07:53 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:07:53 DEBUG : dir/file1(0xc00073e6c0): _writeAt: size=25, off=0 2020/08/16 06:07:53 DEBUG : dir/file1(0xc00073e6c0): >_writeAt: n=25, err= 2020/08/16 06:07:53 DEBUG : dir/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/08/16 06:07:53 INFO : dir/file1: Copied (server side copy) 2020/08/16 06:07:54 INFO : dir/file1: Deleted 2020/08/16 06:07:54 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/08/16 06:07:54 DEBUG : newLeaf: Updating file with newLeaf 0xc00034a540 2020/08/16 06:07:54 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/08/16 06:07:54 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:07:54 DEBUG : newLeaf(0xc00073e6c0): close: 2020/08/16 06:07:54 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/08/16 06:07:54 DEBUG : newLeaf: vfs cache: setting modification time to 2020-08-16 06:07:53.03251148 +0000 UTC m=+66.796369111 2020/08/16 06:07:54 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/08/16 06:07:54 DEBUG : newLeaf(0xc00073e6c0): >close: err= 2020/08/16 06:07:54 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:54 DEBUG : dir: Looking for writers 2020/08/16 06:07:54 DEBUG : : Looking for writers 2020/08/16 06:07:54 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:54 DEBUG : dir: reading active writers 2020/08/16 06:07:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:07:54 DEBUG : dir: Looking for writers 2020/08/16 06:07:54 DEBUG : : Looking for writers 2020/08/16 06:07:54 DEBUG : dir: reading active writers 2020/08/16 06:07:54 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:07:54 DEBUG : dir: Looking for writers 2020/08/16 06:07:54 DEBUG : : Looking for writers 2020/08/16 06:07:54 DEBUG : dir: reading active writers 2020/08/16 06:07:54 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:07:54 DEBUG : dir: Looking for writers 2020/08/16 06:07:54 DEBUG : : Looking for writers 2020/08/16 06:07:54 DEBUG : dir: reading active writers 2020/08/16 06:07:54 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:07:54 DEBUG : newLeaf: vfs cache: starting upload 2020/08/16 06:07:54 DEBUG : dir: Looking for writers 2020/08/16 06:07:54 DEBUG : : Looking for writers 2020/08/16 06:07:54 DEBUG : dir: reading active writers 2020/08/16 06:07:54 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:07:54 DEBUG : dir: Looking for writers 2020/08/16 06:07:54 DEBUG : : Looking for writers 2020/08/16 06:07:54 DEBUG : dir: reading active writers 2020/08/16 06:07:54 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:07:54 DEBUG : dir: Looking for writers 2020/08/16 06:07:54 DEBUG : : Looking for writers 2020/08/16 06:07:54 DEBUG : dir: reading active writers 2020/08/16 06:07:54 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:07:55 DEBUG : newLeaf: SHA-1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK 2020/08/16 06:07:55 INFO : newLeaf: Copied (replaced existing) 2020/08/16 06:07:55 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-08-16 06:07:53.032 +0000 UTC,f1f3d7db56f36d9a5a912b01803c2176a972b9b0" 2020/08/16 06:07:55 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/08/16 06:07:55 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/08/16 06:07:55 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/08/16 06:07:55 DEBUG : dir: Looking for writers 2020/08/16 06:07:55 DEBUG : : Looking for writers 2020/08/16 06:07:55 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:55 DEBUG : dir: reading active writers 2020/08/16 06:07:55 DEBUG : >WaitForWriters: 2020/08/16 06:07:55 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:55 DEBUG : dir: Looking for writers 2020/08/16 06:07:55 DEBUG : : Looking for writers 2020/08/16 06:07:55 DEBUG : dir: reading active writers 2020/08/16 06:07:55 DEBUG : newLeaf: reading active writers 2020/08/16 06:07:55 DEBUG : >WaitForWriters: 2020/08/16 06:07:55 DEBUG : vfs cache: cleaner exiting --- FAIL: TestFileRename (11.51s) --- FAIL: TestFileRename/off,forceCache=false (0.85s) --- PASS: TestFileRename/minimal,forceCache=true (10.66s) === RUN TestRcGetVFS rc_test.go:28: Error Trace: rc_test.go:28 Error: An error is expected but got nil. Test: TestRcGetVFS --- FAIL: TestRcGetVFS (0.00s) === RUN TestReadFileHandleMethods run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:56 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:07:56 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:07:57 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:07:57 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/08/16 06:07:57 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/08/16 06:07:57 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:07:57 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/08/16 06:07:57 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728 2020/08/16 06:07:57 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:07:57 DEBUG : dir: Looking for writers 2020/08/16 06:07:57 DEBUG : file1: reading active writers 2020/08/16 06:07:57 DEBUG : : Looking for writers 2020/08/16 06:07:57 DEBUG : dir: reading active writers 2020/08/16 06:07:57 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleMethods (3.35s) === RUN TestReadFileHandleSeek run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:07:59 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:00 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:08:00 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:08:00 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/08/16 06:08:00 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/08/16 06:08:00 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:08:00 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/08/16 06:08:00 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/08/16 06:08:00 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/08/16 06:08:00 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/08/16 06:08:00 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/08/16 06:08:00 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/08/16 06:08:00 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/08/16 06:08:00 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/08/16 06:08:01 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker) 2020/08/16 06:08:01 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1 2020/08/16 06:08:01 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728 2020/08/16 06:08:01 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728 2020/08/16 06:08:01 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker) 2020/08/16 06:08:01 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1 2020/08/16 06:08:01 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728 2020/08/16 06:08:01 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728 2020/08/16 06:08:02 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:02 DEBUG : dir: Looking for writers 2020/08/16 06:08:02 DEBUG : file1: reading active writers 2020/08/16 06:08:02 DEBUG : : Looking for writers 2020/08/16 06:08:02 DEBUG : dir: reading active writers 2020/08/16 06:08:02 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleSeek (8.83s) === RUN TestReadFileHandleReadAt run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:08 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:10 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:08:11 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:08:11 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/08/16 06:08:11 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/08/16 06:08:11 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:08:11 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/08/16 06:08:11 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/08/16 06:08:11 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/08/16 06:08:11 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/08/16 06:08:11 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/08/16 06:08:11 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/08/16 06:08:11 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/08/16 06:08:11 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/08/16 06:08:12 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker) 2020/08/16 06:08:12 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1 2020/08/16 06:08:12 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728 2020/08/16 06:08:12 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728 2020/08/16 06:08:12 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms 2020/08/16 06:08:12 DEBUG : dir/file1: aborting in-sequence read wait, off=10 2020/08/16 06:08:12 DEBUG : dir/file1: failed to wait for in-sequence read to 10 2020/08/16 06:08:12 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker) 2020/08/16 06:08:12 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1 2020/08/16 06:08:12 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728 2020/08/16 06:08:12 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:08:13 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker) 2020/08/16 06:08:13 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1 2020/08/16 06:08:13 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728 2020/08/16 06:08:13 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/08/16 06:08:13 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/08/16 06:08:13 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/08/16 06:08:13 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/08/16 06:08:13 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16 2020/08/16 06:08:13 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/08/16 06:08:13 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/08/16 06:08:13 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/08/16 06:08:13 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor 2020/08/16 06:08:13 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:13 DEBUG : dir: Looking for writers 2020/08/16 06:08:13 DEBUG : file1: reading active writers 2020/08/16 06:08:13 DEBUG : : Looking for writers 2020/08/16 06:08:13 DEBUG : dir: reading active writers 2020/08/16 06:08:13 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleReadAt (5.99s) === RUN TestReadFileHandleFlush run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:14 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 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:302: Error Trace: fstest.go:302 fstest.go:335 fstest.go:347 read_test.go:19 read_test.go:182 Error: Should be true Test: TestReadFileHandleFlush Messages: listing wrong, want dir/file1 (16) got fstest.go:200: Not found "dir/file1" fstest.go:203: Error Trace: fstest.go:203 fstest.go:307 fstest.go:335 fstest.go:347 read_test.go:19 read_test.go:182 Error: Not equal: expected: 0 actual : 1 Test: TestReadFileHandleFlush Messages: 1 objects not found 2020/08/16 06:08:22 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:08:22 DEBUG : dir/file1: >OpenFile: fd=, err=file does not exist read_test.go:22: Error Trace: read_test.go:22 read_test.go:182 Error: Received unexpected error: file does not exist Test: TestReadFileHandleFlush --- FAIL: TestReadFileHandleFlush (7.82s) === RUN TestReadFileHandleRelease run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:22 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache 2020/08/16 06:08:23 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:08:23 DEBUG : dir/file1: >OpenFile: fd=, err=file does not exist read_test.go:22: Error Trace: read_test.go:22 read_test.go:211 Error: Received unexpected error: file does not exist Test: TestReadFileHandleRelease --- FAIL: TestReadFileHandleRelease (0.85s) === RUN TestRWFileHandleSeek run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:23 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:23 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:23 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:23 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:23 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:08:23 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:08:23 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:08:23 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:08:23 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:08:23 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:08:23 DEBUG : dir/file1(0xc00082e0c0): _readAt: size=1, off=0 2020/08/16 06:08:23 DEBUG : dir/file1(0xc00082e0c0): openPending: 2020/08/16 06:08:23 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06.499 +0000 UTC,fe5567e8d769550852182cdf69d74bb16dff8e29" against cached fingerprint "" 2020/08/16 06:08:23 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:08:23 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:23 DEBUG : dir/file1(0xc00082e0c0): >openPending: err= 2020/08/16 06:08:23 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/08/16 06:08:23 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:08:23 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:08:23 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): >_readAt: n=1, err= 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): _readAt: size=1, off=5 2020/08/16 06:08:24 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): >_readAt: n=1, err= 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): _readAt: size=1, off=3 2020/08/16 06:08:24 DEBUG : vfs cache: looking for range={Pos:3 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): >_readAt: n=1, err= 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): _readAt: size=1, off=13 2020/08/16 06:08:24 DEBUG : vfs cache: looking for range={Pos:13 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): >_readAt: n=1, err= 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): _readAt: size=16, off=100 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): >_readAt: n=0, err=EOF 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): close: 2020/08/16 06:08:24 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499 +0000 UTC 2020/08/16 06:08:24 DEBUG : dir/file1(0xc00082e0c0): >close: err= 2020/08/16 06:08:24 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:24 DEBUG : dir: Looking for writers 2020/08/16 06:08:24 DEBUG : file1: reading active writers 2020/08/16 06:08:24 DEBUG : : Looking for writers 2020/08/16 06:08:24 DEBUG : dir: reading active writers 2020/08/16 06:08:24 DEBUG : >WaitForWriters: 2020/08/16 06:08:24 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleSeek (2.23s) === RUN TestRWFileHandleReadAt run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:25 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:25 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:25 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:25 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 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:08:26 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:08:26 DEBUG : dir/file1: newRWFileHandle: 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(0xc000a80680): _readAt: size=1, off=0 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): openPending: 2020/08/16 06:08:26 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06.499 +0000 UTC,fe5567e8d769550852182cdf69d74bb16dff8e29" 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(0xc000a80680): >openPending: err= 2020/08/16 06:08:26 DEBUG : vfs cache: looking for range={Pos:0 Size:1} in [] - present false 2020/08/16 06:08:26 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:08:26 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:08:26 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): >_readAt: n=1, err= 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): _readAt: size=1, off=5 2020/08/16 06:08:26 DEBUG : vfs cache: looking for range={Pos:5 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): >_readAt: n=1, err= 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): _readAt: size=1, off=1 2020/08/16 06:08:26 DEBUG : vfs cache: looking for range={Pos:1 Size:1} in [{Pos:0 Size:16}] - present true 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): >_readAt: n=1, err= 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): _readAt: size=6, off=10 2020/08/16 06:08:26 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): >_readAt: n=6, err= 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): _readAt: size=256, off=10 2020/08/16 06:08:26 DEBUG : vfs cache: looking for range={Pos:10 Size:6} in [{Pos:0 Size:16}] - present true 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): >_readAt: n=6, err=EOF 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): _readAt: size=256, off=100 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): >_readAt: n=0, err=EOF 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): close: 2020/08/16 06:08:26 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499 +0000 UTC 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): >close: err= 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): _readAt: size=256, off=100 2020/08/16 06:08:26 DEBUG : dir/file1(0xc000a80680): >_readAt: n=0, err=file already closed 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 : >WaitForWriters: 2020/08/16 06:08:26 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleReadAt (1.62s) === RUN TestRWFileHandleFlushRead run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:26 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:26 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:26 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:26 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:27 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:08:28 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:08:28 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:08:28 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:08:28 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:08:28 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): RWFileHandle.Flush 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): _readAt: size=256, off=0 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): openPending: 2020/08/16 06:08:28 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06.499 +0000 UTC,fe5567e8d769550852182cdf69d74bb16dff8e29" against cached fingerprint "" 2020/08/16 06:08:28 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:08:28 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): >openPending: err= 2020/08/16 06:08:28 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2020/08/16 06:08:28 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:08:28 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:08:28 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): >_readAt: n=16, err=EOF 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): RWFileHandle.Flush 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): RWFileHandle.Flush 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): close: 2020/08/16 06:08:28 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499 +0000 UTC 2020/08/16 06:08:28 DEBUG : dir/file1(0xc000091680): >close: err= 2020/08/16 06:08:28 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:28 DEBUG : dir: Looking for writers 2020/08/16 06:08:28 DEBUG : file1: reading active writers 2020/08/16 06:08:28 DEBUG : : Looking for writers 2020/08/16 06:08:28 DEBUG : dir: reading active writers 2020/08/16 06:08:28 DEBUG : >WaitForWriters: 2020/08/16 06:08:28 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleFlushRead (4.55s) === RUN TestRWFileHandleReleaseRead run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:31 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:31 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:31 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:31 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:31 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:08:32 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/08/16 06:08:32 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:08:32 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:08:32 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:08:32 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:08:32 DEBUG : dir/file1(0xc00073e140): _readAt: size=256, off=0 2020/08/16 06:08:32 DEBUG : dir/file1(0xc00073e140): openPending: 2020/08/16 06:08:32 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06.499 +0000 UTC,fe5567e8d769550852182cdf69d74bb16dff8e29" against cached fingerprint "" 2020/08/16 06:08:32 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:08:32 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:32 DEBUG : dir/file1(0xc00073e140): >openPending: err= 2020/08/16 06:08:32 DEBUG : vfs cache: looking for range={Pos:0 Size:16} in [] - present false 2020/08/16 06:08:32 DEBUG : dir/file1: ChunkedReader.RangeSeek from -1 to 0 length -1 2020/08/16 06:08:32 DEBUG : dir/file1: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2020/08/16 06:08:32 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:08:32 DEBUG : dir/file1(0xc00073e140): >_readAt: n=16, err=EOF 2020/08/16 06:08:32 DEBUG : dir/file1(0xc00073e140): RWFileHandle.Release 2020/08/16 06:08:32 DEBUG : dir/file1(0xc00073e140): close: 2020/08/16 06:08:32 DEBUG : dir/file1: vfs cache: setting modification time to 2001-02-03 04:05:06.499 +0000 UTC 2020/08/16 06:08:32 DEBUG : dir/file1(0xc00073e140): >close: err= 2020/08/16 06:08:32 DEBUG : dir/file1(0xc00073e140): RWFileHandle.Release 2020/08/16 06:08:32 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:32 DEBUG : dir: Looking for writers 2020/08/16 06:08:32 DEBUG : file1: reading active writers 2020/08/16 06:08:32 DEBUG : : Looking for writers 2020/08/16 06:08:32 DEBUG : dir: reading active writers 2020/08/16 06:08:32 DEBUG : >WaitForWriters: 2020/08/16 06:08:32 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleReleaseRead (1.46s) === RUN TestRWFileHandleMethodsWrite run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:32 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:32 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:32 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:32 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:08: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:08:33 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:08:33 DEBUG : file1: newRWFileHandle: 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): openPending: 2020/08/16 06:08:33 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:08:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): >openPending: err= 2020/08/16 06:08:33 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:08:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:33 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:08:33 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): _writeAt: size=5, off=0 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): >_writeAt: n=5, err= 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): _writeAt: size=7, off=5 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): >_writeAt: n=7, err= 2020/08/16 06:08:33 DEBUG : file1: vfs cache: truncate to size=11 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): close: 2020/08/16 06:08:33 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:08:33.23420005 +0000 UTC m=+106.998057689 2020/08/16 06:08:33 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): >close: err= 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): close: 2020/08/16 06:08:33 DEBUG : file1(0xc000a81280): >close: err=file already closed 2020/08/16 06:08:33 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:33 DEBUG : : Looking for writers 2020/08/16 06:08:33 DEBUG : file1: reading active writers 2020/08/16 06:08:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:33 DEBUG : : Looking for writers 2020/08/16 06:08:33 DEBUG : file1: reading active writers 2020/08/16 06:08:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:33 DEBUG : : Looking for writers 2020/08/16 06:08:33 DEBUG : file1: reading active writers 2020/08/16 06:08:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:33 DEBUG : : Looking for writers 2020/08/16 06:08:33 DEBUG : file1: reading active writers 2020/08/16 06:08:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:33 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:08:33 DEBUG : : Looking for writers 2020/08/16 06:08:33 DEBUG : file1: reading active writers 2020/08/16 06:08:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:33 DEBUG : : Looking for writers 2020/08/16 06:08:33 DEBUG : file1: reading active writers 2020/08/16 06:08:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:33 DEBUG : file1: SHA-1 = 2aae6c35c94fcfb415dbe95f408b9ce91ee846ed OK 2020/08/16 06:08:33 INFO : file1: Copied (new) 2020/08/16 06:08:33 DEBUG : file1: vfs cache: fingerprint now "11,2020-08-16 06:08:33.234 +0000 UTC,2aae6c35c94fcfb415dbe95f408b9ce91ee846ed" 2020/08/16 06:08:33 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:33 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:33 DEBUG : : Looking for writers 2020/08/16 06:08:33 DEBUG : file1: reading active writers 2020/08/16 06:08:33 DEBUG : >WaitForWriters: 2020/08/16 06:08:34 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:34 DEBUG : : Looking for writers 2020/08/16 06:08:34 DEBUG : file1: reading active writers 2020/08/16 06:08:34 DEBUG : >WaitForWriters: 2020/08/16 06:08:34 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleMethodsWrite (1.67s) === RUN TestRWFileHandleWriteAt run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:34 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:34 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:34 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:34 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:08:34 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:34 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:08:34 DEBUG : file1: newRWFileHandle: 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): openPending: 2020/08/16 06:08:34 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:08:34 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): >openPending: err= 2020/08/16 06:08:34 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:08:34 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:34 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:08:34 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): _writeAt: size=7, off=0 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): >_writeAt: n=7, err= 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): _writeAt: size=6, off=5 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): >_writeAt: n=6, err= 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): close: 2020/08/16 06:08:34 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:08:34.805179026 +0000 UTC m=+108.569036668 2020/08/16 06:08:34 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): >close: err= 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): _writeAt: size=5, off=0 2020/08/16 06:08:34 DEBUG : file1(0xc000a800c0): >_writeAt: n=0, err=file already closed 2020/08/16 06:08:34 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:34 DEBUG : : Looking for writers 2020/08/16 06:08:34 DEBUG : file1: reading active writers 2020/08/16 06:08:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:34 DEBUG : : Looking for writers 2020/08/16 06:08:34 DEBUG : file1: reading active writers 2020/08/16 06:08:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:34 DEBUG : : Looking for writers 2020/08/16 06:08:34 DEBUG : file1: reading active writers 2020/08/16 06:08:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:34 DEBUG : : Looking for writers 2020/08/16 06:08:34 DEBUG : file1: reading active writers 2020/08/16 06:08:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:34 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:08:34 DEBUG : : Looking for writers 2020/08/16 06:08:34 DEBUG : file1: reading active writers 2020/08/16 06:08:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:35 DEBUG : : Looking for writers 2020/08/16 06:08:35 DEBUG : file1: reading active writers 2020/08/16 06:08:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:35 DEBUG : file1: SHA-1 = 2aae6c35c94fcfb415dbe95f408b9ce91ee846ed OK 2020/08/16 06:08:35 INFO : file1: Copied (new) 2020/08/16 06:08:35 DEBUG : file1: vfs cache: fingerprint now "11,2020-08-16 06:08:34.805 +0000 UTC,2aae6c35c94fcfb415dbe95f408b9ce91ee846ed" 2020/08/16 06:08:35 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:35 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:35 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:35 DEBUG : : Looking for writers 2020/08/16 06:08:35 DEBUG : file1: reading active writers 2020/08/16 06:08:35 DEBUG : >WaitForWriters: 2020/08/16 06:08:35 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:35 DEBUG : : Looking for writers 2020/08/16 06:08:35 DEBUG : file1: reading active writers 2020/08/16 06:08:35 DEBUG : >WaitForWriters: 2020/08/16 06:08:35 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleWriteAt (3.19s) === RUN TestRWFileHandleWriteNoWrite run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:37 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:37 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:37 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:37 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:08: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:08:37 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:08:37 DEBUG : file1: newRWFileHandle: 2020/08/16 06:08:37 DEBUG : file1(0xc00082e340): openPending: 2020/08/16 06:08:37 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:08:37 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:37 DEBUG : file1(0xc00082e340): >openPending: err= 2020/08/16 06:08:37 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:08:37 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:37 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:08:37 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:08:37 DEBUG : file1(0xc00082e340): close: 2020/08/16 06:08:37 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:08:37.989857062 +0000 UTC m=+111.753714689 2020/08/16 06:08:37 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:37 DEBUG : file1(0xc00082e340): >close: err= 2020/08/16 06:08:37 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/08/16 06:08:37 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/08/16 06:08:37 DEBUG : file2: newRWFileHandle: 2020/08/16 06:08:37 DEBUG : file2(0xc00082e400): openPending: 2020/08/16 06:08:37 DEBUG : file2: vfs cache: truncate to size=0 2020/08/16 06:08:37 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/08/16 06:08:37 DEBUG : file2(0xc00082e400): >openPending: err= 2020/08/16 06:08:37 DEBUG : file2: >newRWFileHandle: err= 2020/08/16 06:08:37 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/08/16 06:08:37 DEBUG : file2: >Open: fd=file2 (rw), err= 2020/08/16 06:08:37 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2020/08/16 06:08:37 DEBUG : file2(0xc00082e400): RWFileHandle.Flush 2020/08/16 06:08:37 DEBUG : file2(0xc00082e400): RWFileHandle.Release 2020/08/16 06:08:37 DEBUG : file2(0xc00082e400): close: 2020/08/16 06:08:37 DEBUG : file2: vfs cache: setting modification time to 2020-08-16 06:08:37.990834441 +0000 UTC m=+111.754692059 2020/08/16 06:08:37 INFO : file2: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:37 DEBUG : file2(0xc00082e400): >close: err= 2020/08/16 06:08:37 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:37 DEBUG : : Looking for writers 2020/08/16 06:08:37 DEBUG : file2: reading active writers 2020/08/16 06:08:37 DEBUG : file1: reading active writers 2020/08/16 06:08:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2020/08/16 06:08:38 DEBUG : : Looking for writers 2020/08/16 06:08:38 DEBUG : file2: reading active writers 2020/08/16 06:08:38 DEBUG : file1: reading active writers 2020/08/16 06:08:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2020/08/16 06:08:38 DEBUG : : Looking for writers 2020/08/16 06:08:38 DEBUG : file2: reading active writers 2020/08/16 06:08:38 DEBUG : file1: reading active writers 2020/08/16 06:08:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2020/08/16 06:08:38 DEBUG : : Looking for writers 2020/08/16 06:08:38 DEBUG : file1: reading active writers 2020/08/16 06:08:38 DEBUG : file2: reading active writers 2020/08/16 06:08:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2020/08/16 06:08:38 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:08:38 DEBUG : file2: vfs cache: starting upload 2020/08/16 06:08:38 DEBUG : : Looking for writers 2020/08/16 06:08:38 DEBUG : file1: reading active writers 2020/08/16 06:08:38 DEBUG : file2: reading active writers 2020/08/16 06:08:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2020/08/16 06:08:38 DEBUG : : Looking for writers 2020/08/16 06:08:38 DEBUG : file1: reading active writers 2020/08/16 06:08:38 DEBUG : file2: reading active writers 2020/08/16 06:08:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2020/08/16 06:08:38 DEBUG : : Looking for writers 2020/08/16 06:08:38 DEBUG : file1: reading active writers 2020/08/16 06:08:38 DEBUG : file2: reading active writers 2020/08/16 06:08:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2020/08/16 06:08:39 DEBUG : file2: SHA-1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2020/08/16 06:08:39 INFO : file2: Copied (new) 2020/08/16 06:08:39 DEBUG : file2: vfs cache: fingerprint now "0,2020-08-16 06:08:37.99 +0000 UTC,da39a3ee5e6b4b0d3255bfef95601890afd80709" 2020/08/16 06:08:39 DEBUG : file2: vfs cache: writeback object to VFS layer 2020/08/16 06:08:39 DEBUG : : Added virtual directory entry vAdd: "file2" 2020/08/16 06:08:39 INFO : file2: vfs cache: upload succeeded try #1 2020/08/16 06:08:39 DEBUG : : Looking for writers 2020/08/16 06:08:39 DEBUG : file1: reading active writers 2020/08/16 06:08:39 DEBUG : file2: reading active writers 2020/08/16 06:08:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:40 DEBUG : : Looking for writers 2020/08/16 06:08:40 DEBUG : file1: reading active writers 2020/08/16 06:08:40 DEBUG : file2: reading active writers 2020/08/16 06:08:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:41 DEBUG : : Looking for writers 2020/08/16 06:08:41 DEBUG : file1: reading active writers 2020/08/16 06:08:41 DEBUG : file2: reading active writers 2020/08/16 06:08:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:41 DEBUG : file1: SHA-1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2020/08/16 06:08:41 INFO : file1: Copied (new) 2020/08/16 06:08:41 DEBUG : file1: vfs cache: fingerprint now "0,2020-08-16 06:08:37.989 +0000 UTC,da39a3ee5e6b4b0d3255bfef95601890afd80709" 2020/08/16 06:08:41 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:41 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:41 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:42 DEBUG : : Looking for writers 2020/08/16 06:08:42 DEBUG : file1: reading active writers 2020/08/16 06:08:42 DEBUG : file2: reading active writers 2020/08/16 06:08:42 DEBUG : >WaitForWriters: 2020/08/16 06:08:42 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:42 DEBUG : : Looking for writers 2020/08/16 06:08:42 DEBUG : file1: reading active writers 2020/08/16 06:08:42 DEBUG : file2: reading active writers 2020/08/16 06:08:42 DEBUG : >WaitForWriters: 2020/08/16 06:08:42 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleWriteNoWrite (7.94s) === RUN TestRWFileHandleFlushWrite run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:45 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:45 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:45 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:45 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:08:45 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:45 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:08:45 DEBUG : file1: newRWFileHandle: 2020/08/16 06:08:45 DEBUG : file1(0xc00082ef00): openPending: 2020/08/16 06:08:45 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:08:45 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:45 DEBUG : file1(0xc00082ef00): >openPending: err= 2020/08/16 06:08:45 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:08:45 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:45 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:08:45 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:08:45 DEBUG : file1(0xc00082ef00): _writeAt: size=5, off=0 2020/08/16 06:08:45 DEBUG : file1(0xc00082ef00): >_writeAt: n=5, err= 2020/08/16 06:08:45 DEBUG : file1(0xc00082ef00): RWFileHandle.Flush 2020/08/16 06:08:45 DEBUG : file1(0xc00082ef00): RWFileHandle.Flush 2020/08/16 06:08:45 DEBUG : file1(0xc00082ef00): close: 2020/08/16 06:08:45 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:08:45.93559247 +0000 UTC m=+119.699450109 2020/08/16 06:08:45 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:45 DEBUG : file1(0xc00082ef00): >close: err= 2020/08/16 06:08:45 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:45 DEBUG : : Looking for writers 2020/08/16 06:08:45 DEBUG : file1: reading active writers 2020/08/16 06:08:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:45 DEBUG : : Looking for writers 2020/08/16 06:08:45 DEBUG : file1: reading active writers 2020/08/16 06:08:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:45 DEBUG : : Looking for writers 2020/08/16 06:08:45 DEBUG : file1: reading active writers 2020/08/16 06:08:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:46 DEBUG : : Looking for writers 2020/08/16 06:08:46 DEBUG : file1: reading active writers 2020/08/16 06:08:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:46 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:08:46 DEBUG : : Looking for writers 2020/08/16 06:08:46 DEBUG : file1: reading active writers 2020/08/16 06:08:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:46 DEBUG : : Looking for writers 2020/08/16 06:08:46 DEBUG : file1: reading active writers 2020/08/16 06:08:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:46 DEBUG : : Looking for writers 2020/08/16 06:08:46 DEBUG : file1: reading active writers 2020/08/16 06:08:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:08:47 DEBUG : : Looking for writers 2020/08/16 06:08:47 DEBUG : file1: reading active writers 2020/08/16 06:08:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:48 DEBUG : file1: SHA-1 = aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d OK 2020/08/16 06:08:48 INFO : file1: Copied (new) 2020/08/16 06:08:48 DEBUG : file1: vfs cache: fingerprint now "5,2020-08-16 06:08:45.935 +0000 UTC,aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d" 2020/08/16 06:08:48 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:48 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:48 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:48 DEBUG : : Looking for writers 2020/08/16 06:08:48 DEBUG : file1: reading active writers 2020/08/16 06:08:48 DEBUG : >WaitForWriters: 2020/08/16 06:08:48 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleFlushWrite (3.37s) === RUN TestRWFileHandleSizeTruncateExisting run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:49 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:49 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:49 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08: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:08:50 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rwxrwxrwx 2020/08/16 06:08:50 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/08/16 06:08:50 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:08:50 DEBUG : dir/file1(0xc00082f000): openPending: 2020/08/16 06:08:50 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06.499 +0000 UTC,fe5567e8d769550852182cdf69d74bb16dff8e29" against cached fingerprint "" 2020/08/16 06:08:50 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:08:50 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:50 DEBUG : dir/file1(0xc00082f000): >openPending: err= 2020/08/16 06:08:50 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/08/16 06:08:50 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:08:50 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:08:50 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:08:50 DEBUG : dir/file1(0xc00082f000): _writeAt: size=5, off=0 2020/08/16 06:08:50 DEBUG : dir/file1(0xc00082f000): >_writeAt: n=5, err= 2020/08/16 06:08:50 DEBUG : dir/file1(0xc00082f000): close: 2020/08/16 06:08:50 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true 2020/08/16 06:08:50 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:08:50.395658828 +0000 UTC m=+124.159516450 2020/08/16 06:08:50 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:50 DEBUG : dir/file1(0xc00082f000): >close: err= 2020/08/16 06:08:50 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:50 DEBUG : dir: Looking for writers 2020/08/16 06:08:50 DEBUG : file1: reading active writers 2020/08/16 06:08:50 DEBUG : : Looking for writers 2020/08/16 06:08:50 DEBUG : dir: reading active writers 2020/08/16 06:08:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:50 DEBUG : dir: Looking for writers 2020/08/16 06:08:50 DEBUG : file1: reading active writers 2020/08/16 06:08:50 DEBUG : : Looking for writers 2020/08/16 06:08:50 DEBUG : dir: reading active writers 2020/08/16 06:08:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:50 DEBUG : dir: Looking for writers 2020/08/16 06:08:50 DEBUG : file1: reading active writers 2020/08/16 06:08:50 DEBUG : : Looking for writers 2020/08/16 06:08:50 DEBUG : dir: reading active writers 2020/08/16 06:08:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:50 DEBUG : dir: Looking for writers 2020/08/16 06:08:50 DEBUG : file1: reading active writers 2020/08/16 06:08:50 DEBUG : : Looking for writers 2020/08/16 06:08:50 DEBUG : dir: reading active writers 2020/08/16 06:08:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:50 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:08:50 DEBUG : dir: Looking for writers 2020/08/16 06:08:50 DEBUG : file1: reading active writers 2020/08/16 06:08:50 DEBUG : : Looking for writers 2020/08/16 06:08:50 DEBUG : dir: reading active writers 2020/08/16 06:08:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:50 DEBUG : dir: Looking for writers 2020/08/16 06:08:50 DEBUG : file1: reading active writers 2020/08/16 06:08:50 DEBUG : : Looking for writers 2020/08/16 06:08:50 DEBUG : dir: reading active writers 2020/08/16 06:08:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:51 DEBUG : dir: Looking for writers 2020/08/16 06:08:51 DEBUG : file1: reading active writers 2020/08/16 06:08:51 DEBUG : : Looking for writers 2020/08/16 06:08:51 DEBUG : dir: reading active writers 2020/08/16 06:08:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:08:51 DEBUG : dir: Looking for writers 2020/08/16 06:08:51 DEBUG : file1: reading active writers 2020/08/16 06:08:51 DEBUG : : Looking for writers 2020/08/16 06:08:51 DEBUG : dir: reading active writers 2020/08/16 06:08:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:52 DEBUG : dir: Looking for writers 2020/08/16 06:08:52 DEBUG : file1: reading active writers 2020/08/16 06:08:52 DEBUG : : Looking for writers 2020/08/16 06:08:52 DEBUG : dir: reading active writers 2020/08/16 06:08:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:53 DEBUG : dir: Looking for writers 2020/08/16 06:08:53 DEBUG : file1: reading active 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 : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:54 DEBUG : dir: Looking for writers 2020/08/16 06:08:54 DEBUG : file1: reading active 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 : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:55 DEBUG : dir: Looking for writers 2020/08/16 06:08:55 DEBUG : file1: reading active writers 2020/08/16 06:08:55 DEBUG : : Looking for writers 2020/08/16 06:08:55 DEBUG : dir: reading active writers 2020/08/16 06:08:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2020/08/16 06:08:55 DEBUG : dir/file1: SHA-1 = aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d OK 2020/08/16 06:08:55 INFO : dir/file1: Copied (replaced existing) 2020/08/16 06:08:55 DEBUG : dir/file1: vfs cache: fingerprint now "5,2020-08-16 06:08:50.395 +0000 UTC,aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d" 2020/08/16 06:08:55 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:55 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:55 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/08/16 06:08:56 DEBUG : dir: Looking for writers 2020/08/16 06:08:56 DEBUG : file1: reading active writers 2020/08/16 06:08:56 DEBUG : : Looking for writers 2020/08/16 06:08:56 DEBUG : dir: reading active writers 2020/08/16 06:08:56 DEBUG : >WaitForWriters: 2020/08/16 06:08:56 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleSizeTruncateExisting (8.67s) === RUN TestRWFileHandleSizeCreateExisting run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:08:57 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:08:57 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:57 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:08:57 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:58 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:08:59 DEBUG : dir/file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:08:59 DEBUG : dir/file1: newRWFileHandle: 2020/08/16 06:08:59 DEBUG : dir/file1: >newRWFileHandle: err= 2020/08/16 06:08:59 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:59 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/08/16 06:08:59 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/08/16 06:08:59 DEBUG : dir/file1(0xc00020d780): _writeAt: size=5, off=0 2020/08/16 06:08:59 DEBUG : dir/file1(0xc00020d780): openPending: 2020/08/16 06:08:59 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06.499 +0000 UTC,fe5567e8d769550852182cdf69d74bb16dff8e29" against cached fingerprint "" 2020/08/16 06:08:59 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/08/16 06:08:59 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:59 DEBUG : dir/file1(0xc00020d780): >openPending: err= 2020/08/16 06:08:59 DEBUG : dir/file1(0xc00020d780): >_writeAt: n=5, err= 2020/08/16 06:08:59 DEBUG : dir/file1(0xc00020d780): _writeAt: size=15, off=5 2020/08/16 06:08:59 DEBUG : dir/file1(0xc00020d780): >_writeAt: n=15, err= 2020/08/16 06:08:59 DEBUG : dir/file1(0xc00020d780): close: 2020/08/16 06:08:59 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [{Pos:0 Size:20}] - present true 2020/08/16 06:08:59 DEBUG : dir/file1: vfs cache: setting modification time to 2020-08-16 06:08:59.042865845 +0000 UTC m=+132.806723482 2020/08/16 06:08:59 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:08:59 DEBUG : dir/file1(0xc00020d780): >close: err= 2020/08/16 06:08:59 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:08:59 DEBUG : dir: Looking for writers 2020/08/16 06:08:59 DEBUG : file1: reading active writers 2020/08/16 06:08:59 DEBUG : : Looking for writers 2020/08/16 06:08:59 DEBUG : dir: reading active writers 2020/08/16 06:08:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:08:59 DEBUG : dir: Looking for writers 2020/08/16 06:08:59 DEBUG : file1: reading active writers 2020/08/16 06:08:59 DEBUG : : Looking for writers 2020/08/16 06:08:59 DEBUG : dir: reading active writers 2020/08/16 06:08:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:08:59 DEBUG : dir: Looking for writers 2020/08/16 06:08:59 DEBUG : file1: reading active writers 2020/08/16 06:08:59 DEBUG : : Looking for writers 2020/08/16 06:08:59 DEBUG : dir: reading active writers 2020/08/16 06:08:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:08:59 DEBUG : dir: Looking for writers 2020/08/16 06:08:59 DEBUG : file1: reading active writers 2020/08/16 06:08:59 DEBUG : : Looking for writers 2020/08/16 06:08:59 DEBUG : dir: reading active writers 2020/08/16 06:08:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:08:59 DEBUG : dir/file1: vfs cache: starting upload 2020/08/16 06:08:59 DEBUG : dir: Looking for writers 2020/08/16 06:08:59 DEBUG : file1: reading active writers 2020/08/16 06:08:59 DEBUG : : Looking for writers 2020/08/16 06:08:59 DEBUG : dir: reading active writers 2020/08/16 06:08:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:08:59 DEBUG : dir: Looking for writers 2020/08/16 06:08:59 DEBUG : file1: reading active writers 2020/08/16 06:08:59 DEBUG : : Looking for writers 2020/08/16 06:08:59 DEBUG : dir: reading active writers 2020/08/16 06:08:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:08:59 DEBUG : dir: Looking for writers 2020/08/16 06:08:59 DEBUG : file1: reading active writers 2020/08/16 06:08:59 DEBUG : : Looking for writers 2020/08/16 06:08:59 DEBUG : dir: reading active writers 2020/08/16 06:08:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2020/08/16 06:08:59 DEBUG : dir/file1: SHA-1 = 57d2323f11c653458352529c8319b3f4cc13c661 OK 2020/08/16 06:08:59 INFO : dir/file1: Copied (replaced existing) 2020/08/16 06:08:59 DEBUG : dir/file1: vfs cache: fingerprint now "20,2020-08-16 06:08:59.042 +0000 UTC,57d2323f11c653458352529c8319b3f4cc13c661" 2020/08/16 06:08:59 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/08/16 06:08:59 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/08/16 06:08:59 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/08/16 06:09:00 DEBUG : dir: Looking for writers 2020/08/16 06:09:00 DEBUG : file1: reading active writers 2020/08/16 06:09:00 DEBUG : : Looking for writers 2020/08/16 06:09:00 DEBUG : dir: reading active writers 2020/08/16 06:09:00 DEBUG : >WaitForWriters: 2020/08/16 06:09:00 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleSizeCreateExisting (3.37s) === RUN TestRWFileHandleSizeCreateNew run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:01 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:09:01 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:09:01 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:09:01 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:09:01 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:01 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:09:01 DEBUG : file1: newRWFileHandle: 2020/08/16 06:09:01 DEBUG : file1(0xc00082f880): openPending: 2020/08/16 06:09:01 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:09:01 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:01 DEBUG : file1(0xc00082f880): >openPending: err= 2020/08/16 06:09:01 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:09:01 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:01 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:09:01 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:09:01 DEBUG : file1(0xc00082f880): _writeAt: size=5, off=0 2020/08/16 06:09:01 DEBUG : file1(0xc00082f880): >_writeAt: n=5, err= 2020/08/16 06:09:01 DEBUG : file1(0xc00082f880): close: 2020/08/16 06:09:01 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:09:01.339865539 +0000 UTC m=+135.103723165 2020/08/16 06:09:01 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:09:01 DEBUG : file1(0xc00082f880): >close: err= 2020/08/16 06:09:01 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:01 DEBUG : : Looking for writers 2020/08/16 06:09:01 DEBUG : file1: reading active writers 2020/08/16 06:09:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:09:01 DEBUG : : Looking for writers 2020/08/16 06:09:01 DEBUG : file1: reading active writers 2020/08/16 06:09:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:09:01 DEBUG : : Looking for writers 2020/08/16 06:09:01 DEBUG : file1: reading active writers 2020/08/16 06:09:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:09:01 DEBUG : : Looking for writers 2020/08/16 06:09:01 DEBUG : file1: reading active writers 2020/08/16 06:09:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:09:01 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:09:01 DEBUG : : Looking for writers 2020/08/16 06:09:01 DEBUG : file1: reading active writers 2020/08/16 06:09:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:09:01 DEBUG : : Looking for writers 2020/08/16 06:09:01 DEBUG : file1: reading active writers 2020/08/16 06:09:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:09:01 DEBUG : file1: SHA-1 = aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d OK 2020/08/16 06:09:01 INFO : file1: Copied (new) 2020/08/16 06:09:01 DEBUG : file1: vfs cache: fingerprint now "5,2020-08-16 06:09:01.339 +0000 UTC,aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d" 2020/08/16 06:09:01 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:09:01 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:01 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:09:01 DEBUG : : Looking for writers 2020/08/16 06:09:01 DEBUG : file1: reading active writers 2020/08/16 06:09:01 DEBUG : >WaitForWriters: 2020/08/16 06:09:01 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleSizeCreateNew (2.27s) === RUN TestRWFileModTimeWithOpenWriters run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:03 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:09:03 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:09:03 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1" 2020/08/16 06:09:03 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:09: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:09:03 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:09:03 DEBUG : file1: newRWFileHandle: 2020/08/16 06:09:03 DEBUG : file1(0xc0002c95c0): openPending: 2020/08/16 06:09:03 DEBUG : file1: vfs cache: truncate to size=0 2020/08/16 06:09:03 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:03 DEBUG : file1(0xc0002c95c0): >openPending: err= 2020/08/16 06:09:03 DEBUG : file1: >newRWFileHandle: err= 2020/08/16 06:09:03 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:03 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/08/16 06:09:03 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/08/16 06:09:06 DEBUG : Can set mod time: true 2020/08/16 06:09:06 DEBUG : file1(0xc0002c95c0): _writeAt: size=2, off=0 2020/08/16 06:09:06 DEBUG : file1(0xc0002c95c0): >_writeAt: n=2, err= 2020/08/16 06:09:06 DEBUG : file1(0xc0002c95c0): RWFileHandle.Flush 2020/08/16 06:09:06 DEBUG : file1(0xc0002c95c0): RWFileHandle.Release 2020/08/16 06:09:06 DEBUG : file1(0xc0002c95c0): close: 2020/08/16 06:09:06 DEBUG : file1: vfs cache: setting modification time to 2020-08-16 06:09:06.03978548 +0000 UTC m=+139.803643119 2020/08/16 06:09:06 INFO : file1: vfs cache: queuing for upload in 100ms 2020/08/16 06:09:06 DEBUG : file1(0xc0002c95c0): >close: err= 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 : file1: reading active writers 2020/08/16 06:09:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/08/16 06:09:06 DEBUG : : Looking for writers 2020/08/16 06:09:06 DEBUG : file1: reading active writers 2020/08/16 06:09:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/08/16 06:09:06 DEBUG : : Looking for writers 2020/08/16 06:09:06 DEBUG : file1: reading active writers 2020/08/16 06:09:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/08/16 06:09:06 DEBUG : : Looking for writers 2020/08/16 06:09:06 DEBUG : file1: reading active writers 2020/08/16 06:09:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/08/16 06:09:06 DEBUG : file1: vfs cache: starting upload 2020/08/16 06:09:06 DEBUG : : Looking for writers 2020/08/16 06:09:06 DEBUG : file1: reading active writers 2020/08/16 06:09:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/08/16 06:09:06 DEBUG : : Looking for writers 2020/08/16 06:09:06 DEBUG : file1: reading active writers 2020/08/16 06:09:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/08/16 06:09:06 DEBUG : file1: SHA-1 = c22b5f9178342609428d6f51b2c5af4c0bde6a42 OK 2020/08/16 06:09:06 INFO : file1: Copied (new) 2020/08/16 06:09:06 DEBUG : file1: vfs cache: fingerprint now "2,2020-08-16 06:09:06.039 +0000 UTC,c22b5f9178342609428d6f51b2c5af4c0bde6a42" 2020/08/16 06:09:06 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/08/16 06:09:06 DEBUG : : Looking for writers 2020/08/16 06:09:06 DEBUG : file1: reading active writers 2020/08/16 06:09:06 DEBUG : >WaitForWriters: fstest.go:124: Error Trace: fstest.go:124 fstest.go:129 fstest.go:148 fstest.go:192 fstest.go:305 fstest.go:335 fstest.go:347 read_write_test.go:693 Error: Should be true Test: TestRWFileModTimeWithOpenWriters Messages: file1: Modification time difference too big |-67860h36m35.039s| > 1ms (want 2012-11-18 17:32:31 +0000 UTC vs got 2020-08-16 06:09:06.039 +0000 UTC) (precision 1ms) 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 : file1: reading active writers 2020/08/16 06:09:06 DEBUG : >WaitForWriters: 2020/08/16 06:09:06 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileModTimeWithOpenWriters (4.76s) === RUN TestCaseSensitivity run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:08 DEBUG : file1: File._applyPendingModTime OK 2020/08/16 06:09:08 DEBUG : file1: vfs cache: fingerprint now "2,2012-11-18 17:32:31 +0000 UTC,c22b5f9178342609428d6f51b2c5af4c0bde6a42" 2020/08/16 06:09:08 DEBUG : file1: vfs cache: setting modification time to 2012-11-18 17:32:31 +0000 UTC 2020/08/16 06:09:08 ERROR : file1: vfs cache: failed to set modification time of cached file: chtimes /home/rclone/.cache/rclone/vfs/TestB2/rclone-test-povijor0yamakin5netineq1/file1: no such file or directory 2020/08/16 06:09:08 ERROR : file1: vfs cache: setModTime: failed to save item info: vfs cache item: failed to write metadata: open /home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-povijor0yamakin5netineq1/file1: no such file or directory 2020/08/16 06:09:08 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:08 INFO : file1: vfs cache: upload succeeded try #1 2020/08/16 06:09:09 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache 2020/08/16 06:09:09 INFO : B2 bucket rclone-test-povijor0yamakin5netineq1: poll-interval is not supported by this remote 2020/08/16 06:09:09 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:09:09 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/08/16 06:09:09 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/08/16 06:09:09 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err= 2020/08/16 06:09:09 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:09:10 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/08/16 06:09:10 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:09:10 DEBUG : FiLeA: >OpenFile: fd=, err=file does not exist vfs_case_test.go:130: Error Trace: vfs_case_test.go:130 vfs_case_test.go:48 Error: Expected value not to be nil. Test: TestCaseSensitivity vfs_case_test.go:131: Error Trace: vfs_case_test.go:131 vfs_case_test.go:48 Error: Received unexpected error: file does not exist Test: TestCaseSensitivity vfs_case_test.go:141: Error Trace: vfs_case_test.go:141 vfs_case_test.go:48 Error: Should be true Test: TestCaseSensitivity 2020/08/16 06:09:10 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:10 DEBUG : : Looking for writers 2020/08/16 06:09:10 DEBUG : FiLeB: reading active writers 2020/08/16 06:09:10 DEBUG : FilEb: reading active writers 2020/08/16 06:09:10 DEBUG : FiLeA: reading active writers 2020/08/16 06:09:10 DEBUG : >WaitForWriters: 2020/08/16 06:09:10 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:10 DEBUG : : Looking for writers 2020/08/16 06:09:10 DEBUG : >WaitForWriters: --- FAIL: TestCaseSensitivity (9.64s) === RUN TestVFSNew vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:137 Error: Not equal: expected: 0 actual : 2 Test: TestVFSNew run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:17 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:147 Error: Not equal: expected: 1 actual : 2 Test: TestVFSNew 2020/08/16 06:09:17 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:154 Error: Not equal: expected: 1 actual : 2 Test: TestVFSNew vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:159 Error: Not equal: expected: 1 actual : 2 Test: TestVFSNew 2020/08/16 06:09:17 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:17 DEBUG : : Looking for writers 2020/08/16 06:09:17 DEBUG : >WaitForWriters: vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:163 Error: Not equal: expected: 0 actual : 2 Test: TestVFSNew --- FAIL: TestVFSNew (0.30s) === RUN TestVFSStat run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:18 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache vfs_test.go:200: Error Trace: vfs_test.go:200 Error: Received unexpected error: file does not exist Test: TestVFSStat 2020/08/16 06:09:20 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:20 DEBUG : : Looking for writers 2020/08/16 06:09:20 DEBUG : >WaitForWriters: --- FAIL: TestVFSStat (3.49s) === RUN TestVFSStatParent run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:21 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache vfs_test.go:242: Error Trace: vfs_test.go:242 Error: Received unexpected error: file does not exist Test: TestVFSStatParent 2020/08/16 06:09:24 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:24 DEBUG : : Looking for writers 2020/08/16 06:09:24 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:302: Error Trace: fstest.go:302 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 panic.go:617 testing.go:715 vfs_test.go:242 Error: Should be true Test: TestVFSStatParent Messages: listing wrong, want got dir/file2 (14) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 panic.go:617 testing.go:715 vfs_test.go:242 Error: Should be true Test: TestVFSStatParent Messages: Unexpected file "dir/file2" --- FAIL: TestVFSStatParent (13.23s) === RUN TestVFSOpenFile run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:34 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache 2020/08/16 06:09:37 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/08/16 06:09:37 DEBUG : file1: >OpenFile: fd=, err=file does not exist vfs_test.go:269: Error Trace: vfs_test.go:269 Error: Received unexpected error: file does not exist Test: TestVFSOpenFile 2020/08/16 06:09:37 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:37 DEBUG : : Looking for writers 2020/08/16 06:09:37 DEBUG : >WaitForWriters: --- FAIL: TestVFSOpenFile (7.39s) === RUN TestVFSRename run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:42 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache vfs_test.go:308: Error Trace: vfs_test.go:308 Error: Received unexpected error: file does not exist Test: TestVFSRename 2020/08/16 06:09:43 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:43 DEBUG : : Looking for writers 2020/08/16 06:09:43 DEBUG : >WaitForWriters: --- FAIL: TestVFSRename (1.54s) === RUN TestWriteFileHandleWriteAt run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:43 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache 2020/08/16 06:09:43 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:09:43 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:09:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:43 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:09:43 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:09:43 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:43 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2020/08/16 06:09:44 DEBUG : file1: aborting in-sequence write wait, off=100 2020/08/16 06:09:44 DEBUG : file1: failed to wait for in-sequence write to 100 2020/08/16 06:09:44 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2020/08/16 06:09:44 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: File to upload is small (11 bytes), uploading instead of streaming 2020/08/16 06:09:45 DEBUG : file1: SHA-1 = 2aae6c35c94fcfb415dbe95f408b9ce91ee846ed OK 2020/08/16 06:09:45 INFO : file1: Copied (new) 2020/08/16 06:09:45 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:45 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor 2020/08/16 06:09:45 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:45 DEBUG : : Looking for writers 2020/08/16 06:09:45 DEBUG : file1: reading active writers 2020/08/16 06:09:45 DEBUG : >WaitForWriters: --- PASS: TestWriteFileHandleWriteAt (3.82s) === RUN TestWriteFileHandleFlush run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:47 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache 2020/08/16 06:09:47 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:09:47 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:09:47 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:47 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:09:47 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:09:47 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2020/08/16 06:09:47 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes write_test.go:185: Error Trace: write_test.go:185 Error: Received unexpected error: permission denied Test: TestWriteFileHandleFlush dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:189 Error: Not equal: expected: []string{"file1,0,false"} actual : []string{"file1,11,false"} Diff: --- Expected +++ Actual @@ -1,3 +1,3 @@ ([]string) (len=1) { - (string) (len=13) "file1,0,false" + (string) (len=14) "file1,11,false" } Test: TestWriteFileHandleFlush 2020/08/16 06:09:47 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes write_test.go:193: Error Trace: write_test.go:193 Error: Received unexpected error: permission denied Test: TestWriteFileHandleFlush write_test.go:194: Error Trace: write_test.go:194 Error: Not equal: expected: 5 actual : 0 Test: TestWriteFileHandleFlush 2020/08/16 06:09:47 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2020/08/16 06:09:47 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes write_test.go:198: Error Trace: write_test.go:198 Error: Received unexpected error: permission denied Test: TestWriteFileHandleFlush write_test.go:199: Error Trace: write_test.go:199 Error: Should be true Test: TestWriteFileHandleFlush 2020/08/16 06:09:47 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2020/08/16 06:09:47 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes write_test.go:203: Error Trace: write_test.go:203 Error: Received unexpected error: permission denied Test: TestWriteFileHandleFlush write_test.go:204: Error Trace: write_test.go:204 Error: Should be true Test: TestWriteFileHandleFlush dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:209 Error: Not equal: expected: []string{"file1,5,false"} actual : []string{"file1,11,false"} Diff: --- Expected +++ Actual @@ -1,3 +1,3 @@ ([]string) (len=1) { - (string) (len=13) "file1,5,false" + (string) (len=14) "file1,11,false" } Test: TestWriteFileHandleFlush 2020/08/16 06:09:47 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:47 DEBUG : : Looking for writers 2020/08/16 06:09:47 DEBUG : file1: reading active writers 2020/08/16 06:09:47 DEBUG : file1: active writers 1 2020/08/16 06:09:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2020/08/16 06:09:47 DEBUG : : Looking for writers 2020/08/16 06:09:47 DEBUG : file1: reading active writers 2020/08/16 06:09:47 DEBUG : file1: active writers 1 2020/08/16 06:09:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2020/08/16 06:09:47 DEBUG : : Looking for writers 2020/08/16 06:09:47 DEBUG : file1: reading active writers 2020/08/16 06:09:47 DEBUG : file1: active writers 1 2020/08/16 06:09:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2020/08/16 06:09:47 DEBUG : : Looking for writers 2020/08/16 06:09:47 DEBUG : file1: reading active writers 2020/08/16 06:09:47 DEBUG : file1: active writers 1 2020/08/16 06:09:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2020/08/16 06:09:47 DEBUG : : Looking for writers 2020/08/16 06:09:47 DEBUG : file1: reading active writers 2020/08/16 06:09:47 DEBUG : file1: active writers 1 2020/08/16 06:09:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2020/08/16 06:09:47 DEBUG : : Looking for writers 2020/08/16 06:09:47 DEBUG : file1: reading active writers 2020/08/16 06:09:47 DEBUG : file1: active writers 1 2020/08/16 06:09:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2020/08/16 06:09:48 DEBUG : : Looking for writers 2020/08/16 06:09:48 DEBUG : file1: reading active writers 2020/08/16 06:09:48 DEBUG : file1: active writers 1 2020/08/16 06:09:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2020/08/16 06:09:48 DEBUG : : Looking for writers 2020/08/16 06:09:48 DEBUG : file1: reading active writers 2020/08/16 06:09:48 DEBUG : file1: active writers 1 2020/08/16 06:09:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:49 DEBUG : : Looking for writers 2020/08/16 06:09:49 DEBUG : file1: reading active writers 2020/08/16 06:09:49 DEBUG : file1: active writers 1 2020/08/16 06:09:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:50 DEBUG : : Looking for writers 2020/08/16 06:09:50 DEBUG : file1: reading active writers 2020/08/16 06:09:50 DEBUG : file1: active writers 1 2020/08/16 06:09:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:51 DEBUG : : Looking for writers 2020/08/16 06:09:51 DEBUG : file1: reading active writers 2020/08/16 06:09:51 DEBUG : file1: active writers 1 2020/08/16 06:09:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:52 DEBUG : : Looking for writers 2020/08/16 06:09:52 DEBUG : file1: reading active writers 2020/08/16 06:09:52 DEBUG : file1: active writers 1 2020/08/16 06:09:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:53 DEBUG : : Looking for writers 2020/08/16 06:09:53 DEBUG : file1: reading active writers 2020/08/16 06:09:53 DEBUG : file1: active writers 1 2020/08/16 06:09:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:54 DEBUG : : Looking for writers 2020/08/16 06:09:54 DEBUG : file1: reading active writers 2020/08/16 06:09:54 DEBUG : file1: active writers 1 2020/08/16 06:09:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:55 DEBUG : : Looking for writers 2020/08/16 06:09:55 DEBUG : file1: reading active writers 2020/08/16 06:09:55 DEBUG : file1: active writers 1 2020/08/16 06:09:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:56 DEBUG : : Looking for writers 2020/08/16 06:09:56 DEBUG : file1: reading active writers 2020/08/16 06:09:56 DEBUG : file1: active writers 1 2020/08/16 06:09:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:09:57 ERROR : Exiting even though 1 writers active and 0 cache items in use after 10s Cache: 2020/08/16 06:09:57 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleFlush (10.74s) === RUN TestWriteFileModTimeWithOpenWriters run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:09:58 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache 2020/08/16 06:09:58 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:09:58 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:09:58 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:09:58 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:09:58 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:09:58 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes write_test.go:271: Error Trace: write_test.go:271 Error: Received unexpected error: permission denied Test: TestWriteFileModTimeWithOpenWriters 2020/08/16 06:09:58 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:09:58 DEBUG : : Looking for writers 2020/08/16 06:09:58 DEBUG : file1: reading active writers 2020/08/16 06:09:58 DEBUG : file1: active writers 2 2020/08/16 06:09:58 DEBUG : Still 2 writers active and 0 cache items in use, waiting 10ms 2020/08/16 06:09:58 DEBUG : : Looking for writers 2020/08/16 06:09:58 DEBUG : file1: reading active writers 2020/08/16 06:09:58 DEBUG : file1: active writers 2 2020/08/16 06:09:58 DEBUG : Still 2 writers active and 0 cache items in use, waiting 20ms 2020/08/16 06:09:58 DEBUG : : Looking for writers 2020/08/16 06:09:58 DEBUG : file1: reading active writers 2020/08/16 06:09:58 DEBUG : file1: active writers 2 2020/08/16 06:09:58 DEBUG : Still 2 writers active and 0 cache items in use, waiting 40ms 2020/08/16 06:09:58 DEBUG : : Looking for writers 2020/08/16 06:09:58 DEBUG : file1: reading active writers 2020/08/16 06:09:58 DEBUG : file1: active writers 2 2020/08/16 06:09:58 DEBUG : Still 2 writers active and 0 cache items in use, waiting 80ms 2020/08/16 06:09:58 DEBUG : : Looking for writers 2020/08/16 06:09:58 DEBUG : file1: reading active writers 2020/08/16 06:09:58 DEBUG : file1: active writers 2 2020/08/16 06:09:58 DEBUG : Still 2 writers active and 0 cache items in use, waiting 160ms 2020/08/16 06:09:58 DEBUG : : Looking for writers 2020/08/16 06:09:58 DEBUG : file1: reading active writers 2020/08/16 06:09:58 DEBUG : file1: active writers 2 2020/08/16 06:09:58 DEBUG : Still 2 writers active and 0 cache items in use, waiting 320ms 2020/08/16 06:09:59 DEBUG : : Looking for writers 2020/08/16 06:09:59 DEBUG : file1: reading active writers 2020/08/16 06:09:59 DEBUG : file1: active writers 2 2020/08/16 06:09:59 DEBUG : Still 2 writers active and 0 cache items in use, waiting 640ms 2020/08/16 06:09:59 DEBUG : : Looking for writers 2020/08/16 06:09:59 DEBUG : file1: reading active writers 2020/08/16 06:09:59 DEBUG : file1: active writers 2 2020/08/16 06:09:59 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:00 DEBUG : : Looking for writers 2020/08/16 06:10:00 DEBUG : file1: reading active writers 2020/08/16 06:10:00 DEBUG : file1: active writers 2 2020/08/16 06:10:00 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:01 DEBUG : : Looking for writers 2020/08/16 06:10:01 DEBUG : file1: reading active writers 2020/08/16 06:10:01 DEBUG : file1: active writers 2 2020/08/16 06:10:01 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:02 DEBUG : : Looking for writers 2020/08/16 06:10:02 DEBUG : file1: reading active writers 2020/08/16 06:10:02 DEBUG : file1: active writers 2 2020/08/16 06:10:02 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:03 DEBUG : : Looking for writers 2020/08/16 06:10:03 DEBUG : file1: reading active writers 2020/08/16 06:10:03 DEBUG : file1: active writers 2 2020/08/16 06:10:03 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:04 DEBUG : : Looking for writers 2020/08/16 06:10:04 DEBUG : file1: reading active writers 2020/08/16 06:10:04 DEBUG : file1: active writers 2 2020/08/16 06:10:04 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:05 DEBUG : : Looking for writers 2020/08/16 06:10:05 DEBUG : file1: reading active writers 2020/08/16 06:10:05 DEBUG : file1: active writers 2 2020/08/16 06:10:05 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:06 DEBUG : : Looking for writers 2020/08/16 06:10:06 DEBUG : file1: reading active writers 2020/08/16 06:10:06 DEBUG : file1: active writers 2 2020/08/16 06:10:06 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:07 DEBUG : : Looking for writers 2020/08/16 06:10:07 DEBUG : file1: reading active writers 2020/08/16 06:10:07 DEBUG : file1: active writers 2 2020/08/16 06:10:07 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:08 ERROR : Exiting even though 2 writers active and 0 cache items in use after 10s Cache: 2020/08/16 06:10:08 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileModTimeWithOpenWriters (10.75s) === RUN TestFileReadAtZeroLength run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:10:09 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache 2020/08/16 06:10:09 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:10:09 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:10:09 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:10:09 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:10:09 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:10:09 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/08/16 06:10:09 DEBUG : file1: Open: flags=O_RDONLY 2020/08/16 06:10:09 DEBUG : file1: >Open: fd=file1 (r), err= 2020/08/16 06:10:09 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/08/16 06:10:09 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/08/16 06:10:09 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 write_test.go:317: Error Trace: write_test.go:317 write_test.go:325 Error: Not equal: expected: 11 actual : 0 Test: TestFileReadAtZeroLength write_test.go:318: Error Trace: write_test.go:318 write_test.go:325 Error: Not equal: expected: []byte{} actual : []byte{0x68, 0x65, 0x6c, 0x6c, 0x6f, 0x20, 0x77, 0x6f, 0x72, 0x6c, 0x64} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]uint8) { +([]uint8) (len=11) { + 00000000 68 65 6c 6c 6f 20 77 6f 72 6c 64 |hello world| } Test: TestFileReadAtZeroLength 2020/08/16 06:10:09 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:10:09 DEBUG : : Looking for writers 2020/08/16 06:10:09 DEBUG : file1: reading active writers 2020/08/16 06:10:09 DEBUG : file1: active writers 2 2020/08/16 06:10:09 DEBUG : Still 2 writers active and 0 cache items in use, waiting 10ms 2020/08/16 06:10:09 DEBUG : : Looking for writers 2020/08/16 06:10:09 DEBUG : file1: reading active writers 2020/08/16 06:10:09 DEBUG : file1: active writers 2 2020/08/16 06:10:09 DEBUG : Still 2 writers active and 0 cache items in use, waiting 20ms 2020/08/16 06:10:09 DEBUG : : Looking for writers 2020/08/16 06:10:09 DEBUG : file1: reading active writers 2020/08/16 06:10:09 DEBUG : file1: active writers 2 2020/08/16 06:10:09 DEBUG : Still 2 writers active and 0 cache items in use, waiting 40ms 2020/08/16 06:10:09 DEBUG : : Looking for writers 2020/08/16 06:10:09 DEBUG : file1: reading active writers 2020/08/16 06:10:09 DEBUG : file1: active writers 2 2020/08/16 06:10:09 DEBUG : Still 2 writers active and 0 cache items in use, waiting 80ms 2020/08/16 06:10:09 DEBUG : : Looking for writers 2020/08/16 06:10:09 DEBUG : file1: reading active writers 2020/08/16 06:10:09 DEBUG : file1: active writers 2 2020/08/16 06:10:09 DEBUG : Still 2 writers active and 0 cache items in use, waiting 160ms 2020/08/16 06:10:10 DEBUG : : Looking for writers 2020/08/16 06:10:10 DEBUG : file1: reading active writers 2020/08/16 06:10:10 DEBUG : file1: active writers 2 2020/08/16 06:10:10 DEBUG : Still 2 writers active and 0 cache items in use, waiting 320ms 2020/08/16 06:10:10 DEBUG : : Looking for writers 2020/08/16 06:10:10 DEBUG : file1: reading active writers 2020/08/16 06:10:10 DEBUG : file1: active writers 2 2020/08/16 06:10:10 DEBUG : Still 2 writers active and 0 cache items in use, waiting 640ms 2020/08/16 06:10:11 DEBUG : : Looking for writers 2020/08/16 06:10:11 DEBUG : file1: reading active writers 2020/08/16 06:10:11 DEBUG : file1: active writers 2 2020/08/16 06:10:11 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:12 DEBUG : : Looking for writers 2020/08/16 06:10:12 DEBUG : file1: reading active writers 2020/08/16 06:10:12 DEBUG : file1: active writers 2 2020/08/16 06:10:12 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:13 DEBUG : : Looking for writers 2020/08/16 06:10:13 DEBUG : file1: reading active writers 2020/08/16 06:10:13 DEBUG : file1: active writers 2 2020/08/16 06:10:13 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:14 DEBUG : : Looking for writers 2020/08/16 06:10:14 DEBUG : file1: reading active writers 2020/08/16 06:10:14 DEBUG : file1: active writers 2 2020/08/16 06:10:14 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:15 DEBUG : : Looking for writers 2020/08/16 06:10:15 DEBUG : file1: reading active writers 2020/08/16 06:10:15 DEBUG : file1: active writers 2 2020/08/16 06:10:15 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:16 DEBUG : : Looking for writers 2020/08/16 06:10:16 DEBUG : file1: reading active writers 2020/08/16 06:10:16 DEBUG : file1: active writers 2 2020/08/16 06:10:16 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:17 DEBUG : : Looking for writers 2020/08/16 06:10:17 DEBUG : file1: reading active writers 2020/08/16 06:10:17 DEBUG : file1: active writers 2 2020/08/16 06:10:17 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:18 DEBUG : : Looking for writers 2020/08/16 06:10:18 DEBUG : file1: reading active writers 2020/08/16 06:10:18 DEBUG : file1: active writers 2 2020/08/16 06:10:18 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:19 DEBUG : : Looking for writers 2020/08/16 06:10:19 DEBUG : file1: reading active writers 2020/08/16 06:10:19 DEBUG : file1: active writers 2 2020/08/16 06:10:19 DEBUG : Still 2 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:19 ERROR : Exiting even though 2 writers active and 0 cache items in use after 10s Cache: 2020/08/16 06:10:19 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtZeroLength (11.39s) === RUN TestFileReadAtNonZeroLength run.go:176: Remote "B2 bucket rclone-test-povijor0yamakin5netineq1", Local "Local file system at /tmp/rclone063728248", Modify Window "1ms" 2020/08/16 06:10:20 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Re-using VFS from active cache 2020/08/16 06:10:20 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/08/16 06:10:20 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/08/16 06:10:20 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/08/16 06:10:20 DEBUG : file1: >Open: fd=file1 (w), err= 2020/08/16 06:10:20 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/08/16 06:10:20 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes write_test.go:295: Error Trace: write_test.go:295 write_test.go:329 Error: Received unexpected error: permission denied Test: TestFileReadAtNonZeroLength 2020/08/16 06:10:20 DEBUG : WaitForWriters: timeout=10s 2020/08/16 06:10:20 DEBUG : : Looking for writers 2020/08/16 06:10:20 DEBUG : file1: reading active writers 2020/08/16 06:10:20 DEBUG : file1: active writers 3 2020/08/16 06:10:20 DEBUG : Still 3 writers active and 0 cache items in use, waiting 10ms 2020/08/16 06:10:20 DEBUG : : Looking for writers 2020/08/16 06:10:20 DEBUG : file1: reading active writers 2020/08/16 06:10:20 DEBUG : file1: active writers 3 2020/08/16 06:10:20 DEBUG : Still 3 writers active and 0 cache items in use, waiting 20ms 2020/08/16 06:10:20 DEBUG : : Looking for writers 2020/08/16 06:10:20 DEBUG : file1: reading active writers 2020/08/16 06:10:20 DEBUG : file1: active writers 3 2020/08/16 06:10:20 DEBUG : Still 3 writers active and 0 cache items in use, waiting 40ms 2020/08/16 06:10:20 DEBUG : : Looking for writers 2020/08/16 06:10:20 DEBUG : file1: reading active writers 2020/08/16 06:10:20 DEBUG : file1: active writers 3 2020/08/16 06:10:20 DEBUG : Still 3 writers active and 0 cache items in use, waiting 80ms 2020/08/16 06:10:20 DEBUG : : Looking for writers 2020/08/16 06:10:20 DEBUG : file1: reading active writers 2020/08/16 06:10:20 DEBUG : file1: active writers 3 2020/08/16 06:10:20 DEBUG : Still 3 writers active and 0 cache items in use, waiting 160ms 2020/08/16 06:10:20 DEBUG : : Looking for writers 2020/08/16 06:10:20 DEBUG : file1: reading active writers 2020/08/16 06:10:20 DEBUG : file1: active writers 3 2020/08/16 06:10:20 DEBUG : Still 3 writers active and 0 cache items in use, waiting 320ms 2020/08/16 06:10:21 DEBUG : : Looking for writers 2020/08/16 06:10:21 DEBUG : file1: reading active writers 2020/08/16 06:10:21 DEBUG : file1: active writers 3 2020/08/16 06:10:21 DEBUG : Still 3 writers active and 0 cache items in use, waiting 640ms 2020/08/16 06:10:21 DEBUG : : Looking for writers 2020/08/16 06:10:21 DEBUG : file1: reading active writers 2020/08/16 06:10:21 DEBUG : file1: active writers 3 2020/08/16 06:10:21 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:22 DEBUG : : Looking for writers 2020/08/16 06:10:22 DEBUG : file1: reading active writers 2020/08/16 06:10:22 DEBUG : file1: active writers 3 2020/08/16 06:10:22 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:23 DEBUG : : Looking for writers 2020/08/16 06:10:23 DEBUG : file1: reading active writers 2020/08/16 06:10:23 DEBUG : file1: active writers 3 2020/08/16 06:10:23 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:24 DEBUG : : Looking for writers 2020/08/16 06:10:24 DEBUG : file1: reading active writers 2020/08/16 06:10:24 DEBUG : file1: active writers 3 2020/08/16 06:10:24 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:25 DEBUG : : Looking for writers 2020/08/16 06:10:25 DEBUG : file1: reading active writers 2020/08/16 06:10:25 DEBUG : file1: active writers 3 2020/08/16 06:10:25 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:26 DEBUG : : Looking for writers 2020/08/16 06:10:26 DEBUG : file1: reading active writers 2020/08/16 06:10:26 DEBUG : file1: active writers 3 2020/08/16 06:10:26 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:27 DEBUG : : Looking for writers 2020/08/16 06:10:27 DEBUG : file1: reading active writers 2020/08/16 06:10:27 DEBUG : file1: active writers 3 2020/08/16 06:10:27 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:28 DEBUG : : Looking for writers 2020/08/16 06:10:28 DEBUG : file1: reading active writers 2020/08/16 06:10:28 DEBUG : file1: active writers 3 2020/08/16 06:10:28 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:29 DEBUG : : Looking for writers 2020/08/16 06:10:29 DEBUG : file1: reading active writers 2020/08/16 06:10:29 DEBUG : file1: active writers 3 2020/08/16 06:10:29 DEBUG : Still 3 writers active and 0 cache items in use, waiting 1s 2020/08/16 06:10:30 ERROR : Exiting even though 3 writers active and 0 cache items in use after 10s Cache: 2020/08/16 06:10:30 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtNonZeroLength (10.75s) FAIL 2020/08/16 06:10:31 DEBUG : B2 bucket rclone-test-povijor0yamakin5netineq1: Purge remote 2020/08/16 06:10:31 DEBUG : FiLeA: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1172611ccea3f1ee_d20200816_m060910_c001_v0001136_t0011") 2020/08/16 06:10:31 DEBUG : FiLeA: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c9851a3_d20200816_m060908_c001_v0001041_t0000") 2020/08/16 06:10:31 DEBUG : FiLeB: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1058d713e8fe3689_d20200816_m060911_c001_v0001041_t0036") 2020/08/16 06:10:31 DEBUG : FiLeB: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a67f_d20200816_m060908_c001_v0001041_t0017") 2020/08/16 06:10:31 DEBUG : FilEb: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f11483db35d5e6fc5_d20200816_m060916_c001_v0001120_t0049") 2020/08/16 06:10:31 DEBUG : FilEb: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c9851a6_d20200816_m060909_c001_v0001041_t0000") 2020/08/16 06:10:31 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f10985d38acb09df5_d20200816_m060900_c001_v0001131_t0057") 2020/08/16 06:10:31 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c985192_d20200816_m060859_c001_v0001041_t0000") 2020/08/16 06:10:31 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a677_d20200816_m060858_c001_v0001041_t0017") 2020/08/16 06:10:31 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1006890fb90e6328_d20200816_m060857_c001_v0001136_t0058") 2020/08/16 06:10:31 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c98517d_d20200816_m060850_c001_v0001041_t0000") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a672_d20200816_m060849_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f112b34b125fb1f95_d20200816_m060832_c001_v0001093_t0025") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a661_d20200816_m060831_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f10864437d8fdf1e6_d20200816_m060828_c001_v0001144_t0054") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a659_d20200816_m060827_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f100a95ab6470ddaa_d20200816_m060826_c001_v0001137_t0040") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a656_d20200816_m060825_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f103cb5f1128ac9cf_d20200816_m060824_c001_v0001120_t0029") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a654_d20200816_m060823_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a652_d20200816_m060822_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f11367bb744726848_d20200816_m060814_c001_v0001032_t0018") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a64b_d20200816_m060814_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a642_d20200816_m060808_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1032f9800a80be70_d20200816_m060802_c001_v0001144_t0007") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a635_d20200816_m060759_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1071de928a10dec1_d20200816_m060757_c001_v0001036_t0049") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a62d_d20200816_m060756_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1137ab1eb91589ae_d20200816_m060753_c001_v0001120_t0010") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1099da060b1b3fba_d20200816_m060752_c001_v0001134_t0051") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f11867654cce77d65_d20200816_m060751_c001_v0001026_t0039") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a625_d20200816_m060749_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a620_d20200816_m060745_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a61e_d20200816_m060744_c001_v0001041_t0017") 2020/08/16 06:10:32 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a618_d20200816_m060741_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a61a_d20200816_m060741_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1183b256525f9423_d20200816_m060732_c001_v0001031_t0014") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a614_d20200816_m060732_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a60e_d20200816_m060729_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a609_d20200816_m060728_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f10194ff43464e55a_d20200816_m060702_c001_v0001042_t0029") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5f3_d20200816_m060700_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f101319da96ceb660_d20200816_m060659_c001_v0001041_t0043") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5f0_d20200816_m060658_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f10792d73a1aa3e92_d20200816_m060658_c001_v0001131_t0039") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5ee_d20200816_m060657_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f11532c88ee65bc6e_d20200816_m060656_c001_v0001136_t0000") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5ec_d20200816_m060655_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1087df3fca080637_d20200816_m060655_c001_v0001136_t0051") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5e9_d20200816_m060653_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1167795d37501cde_d20200816_m060653_c001_v0001137_t0055") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5e7_d20200816_m060652_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104e1ffa1c5d67f6_d20200816_m060649_c001_v0001036_t0010") 2020/08/16 06:10:33 DEBUG : dir/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5dc_d20200816_m060648_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f11858a214d2b5df7_d20200816_m060943_c001_v0001033_t0006") 2020/08/16 06:10:33 DEBUG : dir/file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a6a8_d20200816_m060942_c001_v0001041_t0017") 2020/08/16 06:10:33 DEBUG : dir/file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f108d8e4111558376_d20200816_m060937_c001_v0001005_t0036") 2020/08/16 06:10:33 DEBUG : dir/file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c9851e2_d20200816_m060936_c001_v0001041_t0000") 2020/08/16 06:10:33 DEBUG : dir/file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c9851cf_d20200816_m060924_c001_v0001041_t0000") 2020/08/16 06:10:34 DEBUG : dir/file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f108c465775a537e0_d20200816_m060924_c001_v0001093_t0035") 2020/08/16 06:10:34 DEBUG : dir/file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1036e1780c7384c1_d20200816_m060920_c001_v0001134_t0043") 2020/08/16 06:10:34 DEBUG : dir/file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c9851be_d20200816_m060919_c001_v0001041_t0000") 2020/08/16 06:10:34 DEBUG : dir/file3: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f103a1337285c2c61_d20200816_m060702_c001_v0001128_t0051") 2020/08/16 06:10:34 DEBUG : dir/file3: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5f5_d20200816_m060701_c001_v0001041_t0017") 2020/08/16 06:10:34 DEBUG : dir/potato: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f11176bc4ce59f70a_d20200816_m060651_c001_v0001136_t0043") 2020/08/16 06:10:34 DEBUG : dir/potato: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a5e0_d20200816_m060649_c001_v0001041_t0017") 2020/08/16 06:10:34 DEBUG : dir2/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f113654f1b3c3c07e_d20200816_m060707_c001_v0001144_t0025") 2020/08/16 06:10:34 DEBUG : dir2/file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f115ffd7ab275dc03_d20200816_m060702_c001_v0001130_t0059") 2020/08/16 06:10:34 DEBUG : dir2/file3: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1157339a8baf3f1b_d20200816_m060718_c001_v0001029_t0044") 2020/08/16 06:10:34 DEBUG : dir2/file3: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f10864437d8fdecff_d20200816_m060712_c001_v0001144_t0001") 2020/08/16 06:10:34 DEBUG : dir2/file3: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f11162206560a0e3c_d20200816_m060702_c001_v0001134_t0007") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1071de928a10df73_d20200816_m060945_c001_v0001036_t0056") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c9851f3_d20200816_m060945_c001_v0001041_t0000") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f100d8ca176fda57c_d20200816_m060937_c001_v0001131_t0041") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a6a1_d20200816_m060935_c001_v0001041_t0017") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1019e99e39411885_d20200816_m060926_c001_v0001136_t0002") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a694_d20200816_m060921_c001_v0001041_t0017") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f109606c10a76cc1d_d20200816_m060921_c001_v0001136_t0057") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a690_d20200816_m060918_c001_v0001041_t0017") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f103490730a3db166_d20200816_m060907_c001_v0001039_t0007") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a67b_d20200816_m060906_c001_v0001041_t0017") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1194de80708a293f_d20200816_m060906_c001_v0001144_t0056") 2020/08/16 06:10:34 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f105affbf398011aa_d20200816_m060902_c001_v0001144_t0059") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a679_d20200816_m060901_c001_v0001041_t0017") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f114ec8732dd4b8d5_d20200816_m060848_c001_v0001134_t0046") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c98516b_d20200816_m060846_c001_v0001041_t0000") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1039b92c3f471725_d20200816_m060842_c001_v0001092_t0051") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a66b_d20200816_m060838_c001_v0001041_t0017") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f109b76d7b9ee7c4f_d20200816_m060835_c001_v0001144_t0021") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a668_d20200816_m060834_c001_v0001041_t0017") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f10985d38acb09dd3_d20200816_m060834_c001_v0001131_t0059") 2020/08/16 06:10:35 DEBUG : file1: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a665_d20200816_m060833_c001_v0001041_t0017") 2020/08/16 06:10:35 DEBUG : file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f102c79dc22bb312c_d20200816_m060843_c001_v0001144_t0000") 2020/08/16 06:10:35 DEBUG : file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c985160_d20200816_m060838_c001_v0001041_t0000") 2020/08/16 06:10:35 DEBUG : file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106f43af8b54f79e_d20200816_m060715_c001_v0001033_t0046") 2020/08/16 06:10:35 DEBUG : file2: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f10864437d8fdec7a_d20200816_m060704_c001_v0001144_t0033") 2020/08/16 06:10:35 DEBUG : newLeaf: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f103519c1d1f3221f_d20200816_m060755_c001_v0001137_t0035") 2020/08/16 06:10:35 DEBUG : newLeaf: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f104ec6aff8c4a629_d20200816_m060754_c001_v0001041_t0017") 2020/08/16 06:10:35 DEBUG : newLeaf: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1166dbf3bb981b25_d20200816_m060753_c001_v0001026_t0002") 2020/08/16 06:10:35 DEBUG : newLeaf: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1041b4029caeb13b_d20200816_m060752_c001_v0001005_t0019") 2020/08/16 06:10:35 DEBUG : newLeaf: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f11863160720d5140_d20200816_m060749_c001_v0001144_t0047") 2020/08/16 06:10:35 DEBUG : time_test: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f119421a7c837dad0_d20200816_m060904_c001_v0001040_t0022") 2020/08/16 06:10:35 DEBUG : time_test: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f1054907b2c4f74c1_d20200816_m060904_c001_v0001137_t0043") 2020/08/16 06:10:35 DEBUG : time_test: Deleting (id "4_zdfb2ad63e00dfb5b7f380e1b_f106dc1590c985198_d20200816_m060903_c001_v0001041_t0000") "./vfs.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -test.run '^(TestCaseSensitivity|TestDirCreate|TestDirMkdir|TestDirMkdirSub|TestDirRemove|TestDirRemoveAll|TestDirRemoveName|TestDirRename|TestFileOpen|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRemove|TestFileRemoveAll|TestFileRename|TestRWFileHandleFlushRead|TestRWFileHandleFlushWrite|TestRWFileHandleMethodsWrite|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeCreateNew|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestVFSNew|TestVFSOpenFile|TestVFSRename|TestVFSStat|TestVFSStatParent|TestWriteFileHandleFlush|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(minimal,forceCache=true|off,forceCache=false)$'" - Finished ERROR in 3m50.310495664s (try 2/5): exit status 1: Failed [TestFileRemove TestFileRemoveAll TestFileOpen TestFileRename/off,forceCache=false TestRcGetVFS TestReadFileHandleFlush TestReadFileHandleRelease TestRWFileModTimeWithOpenWriters TestCaseSensitivity TestVFSNew TestVFSStat TestVFSStatParent TestVFSOpenFile TestVFSRename TestWriteFileHandleFlush TestWriteFileModTimeWithOpenWriters TestFileReadAtZeroLength TestFileReadAtNonZeroLength]