"./vfs.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -test.run '^(TestCaseSensitivity|TestDirRemoveName|TestFileOpen|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRemove|TestFileRemoveAll|TestFileRename|TestRWFileHandleSizeTruncateExisting|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestVFSNew|TestVFSOpenFile|TestVFSRename|TestVFSStat|TestVFSStatParent|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(off,forceCache=false|writes,forceCache=true)$'" - Starting (try 2/5) === RUN TestDirRemoveName 2020/07/24 10:27:20 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:27:22 DEBUG : dir/file1: Remove: 2020/07/24 10:27:22 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:27:23 DEBUG : dir/file1: >Remove: err= 2020/07/24 10:27:30 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:30 DEBUG : dir: Looking for writers 2020/07/24 10:27:30 DEBUG : : Looking for writers 2020/07/24 10:27:30 DEBUG : dir: reading active writers 2020/07/24 10:27:30 DEBUG : >WaitForWriters: --- FAIL: TestDirRemoveName (10.59s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" fstest.go:247: Filtering empty directory "dir" 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 dir_test.go:492 Error: Should be true Test: TestDirRemoveName Messages: listing wrong, want got dir/file1 (14) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 dir_test.go:492 Error: Should be true Test: TestDirRemoveName Messages: Unexpected file "dir/file1" === RUN TestFileOpenWrite 2020/07/24 10:27:31 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:27:32 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:32 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (25 bytes), uploading instead of streaming 2020/07/24 10:27:35 DEBUG : dir/file1: SHA-1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK 2020/07/24 10:27:35 INFO : dir/file1: Copied (new) 2020/07/24 10:27:35 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:27:35 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:35 DEBUG : dir: Looking for writers 2020/07/24 10:27:35 DEBUG : file1: reading active writers 2020/07/24 10:27:35 DEBUG : : Looking for writers 2020/07/24 10:27:35 DEBUG : dir: reading active writers 2020/07/24 10:27:35 DEBUG : >WaitForWriters: --- PASS: TestFileOpenWrite (5.12s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestFileRemove 2020/07/24 10:27:36 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:27:37 DEBUG : dir/file1: Remove: 2020/07/24 10:27:37 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:27:37 DEBUG : dir/file1: >Remove: err= 2020/07/24 10:27:37 DEBUG : dir/file1: Remove: 2020/07/24 10:27:37 DEBUG : dir/file1: >Remove: err=Read only file system 2020/07/24 10:27:37 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:37 DEBUG : dir: Looking for writers 2020/07/24 10:27:37 DEBUG : : Looking for writers 2020/07/24 10:27:37 DEBUG : dir: reading active writers 2020/07/24 10:27:37 DEBUG : >WaitForWriters: --- PASS: TestFileRemove (1.59s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestFileRemoveAll 2020/07/24 10:27:37 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:27:38 DEBUG : dir/file1: Remove: 2020/07/24 10:27:38 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:27:39 DEBUG : dir/file1: >Remove: err= 2020/07/24 10:27:46 DEBUG : dir/file1: Remove: 2020/07/24 10:27:46 DEBUG : dir/file1: >Remove: err=Read only file system 2020/07/24 10:27:46 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:46 DEBUG : dir: Looking for writers 2020/07/24 10:27:46 DEBUG : : Looking for writers 2020/07/24 10:27:46 DEBUG : dir: reading active writers 2020/07/24 10:27:46 DEBUG : >WaitForWriters: --- FAIL: TestFileRemoveAll (9.22s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" 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:214 Error: Should be true Test: TestFileRemoveAll Messages: listing wrong, want got dir/file1 (14) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 fstest.go:347 file_test.go:214 Error: Should be true Test: TestFileRemoveAll Messages: Unexpected file "dir/file1" === RUN TestFileOpen 2020/07/24 10:27:47 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:27:48 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:27:48 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:27:48 DEBUG : dir/file1: Open: flags=O_WRONLY 2020/07/24 10:27:48 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2020/07/24 10:27:48 DEBUG : dir/file1: Open: flags=O_RDWR 2020/07/24 10:27:48 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2020/07/24 10:27:48 DEBUG : dir/file1: Open: flags=0x3 2020/07/24 10:27:48 DEBUG : dir/file1: Can't figure out how to open with flags: 0x3 2020/07/24 10:27:48 DEBUG : dir/file1: >Open: fd=, err=permission denied 2020/07/24 10:27:48 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:27:48 DEBUG : dir: Looking for writers 2020/07/24 10:27:48 DEBUG : file1: reading active writers 2020/07/24 10:27:48 DEBUG : : Looking for writers 2020/07/24 10:27:48 DEBUG : dir: reading active writers 2020/07/24 10:27:48 DEBUG : >WaitForWriters: --- PASS: TestFileOpen (1.96s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestFileRename === RUN TestFileRename/off,forceCache=false 2020/07/24 10:27:49 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:27:50 DEBUG : dir/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/07/24 10:27:50 INFO : dir/file1: Copied (server side copy) 2020/07/24 10:28:03 INFO : dir/file1: Deleted 2020/07/24 10:28:03 DEBUG : newLeaf: Updating file with newLeaf 0xc000278480 2020/07/24 10:28:03 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:28:03 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:28:03 DEBUG : newLeaf: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/07/24 10:28:03 INFO : newLeaf: Copied (server side copy) 2020/07/24 10:28:04 INFO : newLeaf: Deleted 2020/07/24 10:28:04 DEBUG : dir/file1: Updating file with dir/file1 0xc000278480 2020/07/24 10:28:04 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:28:04 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:04 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:28:04 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err= 2020/07/24 10:28:04 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:04 DEBUG : dir/file1: File is currently open, delaying rename 0xc000278480 2020/07/24 10:28:04 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:28:04 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:28:04 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (25 bytes), uploading instead of streaming 2020/07/24 10:28:07 DEBUG : dir/file1: SHA-1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK 2020/07/24 10:28:07 INFO : dir/file1: Copied (new) 2020/07/24 10:28:07 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:28:07 DEBUG : newLeaf: Running delayed rename now 2020/07/24 10:28:08 DEBUG : dir/file1: SHA-1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK 2020/07/24 10:28:08 INFO : dir/file1: Copied (server side copy) 2020/07/24 10:28:12 INFO : dir/file1: Deleted 2020/07/24 10:28:12 DEBUG : newLeaf: Updating file with newLeaf 0xc000278480 2020/07/24 10:28:12 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:12 DEBUG : dir: Looking for writers 2020/07/24 10:28:12 DEBUG : : Looking for writers 2020/07/24 10:28:12 DEBUG : dir: reading active writers 2020/07/24 10:28:12 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:12 DEBUG : >WaitForWriters: 2020/07/24 10:28:12 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:12 DEBUG : dir: Looking for writers 2020/07/24 10:28:12 DEBUG : : Looking for writers 2020/07/24 10:28:12 DEBUG : dir: reading active writers 2020/07/24 10:28:12 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:12 DEBUG : >WaitForWriters: === RUN TestFileRename/writes,forceCache=true 2020/07/24 10:28:13 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:13 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-hebecom2wanikot5sureciw2" 2020/07/24 10:28:13 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-hebecom2wanikot5sureciw2" 2020/07/24 10:28:13 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:28:14 DEBUG : dir/file1: Open: flags=O_RDWR|O_CREATE|O_TRUNC 2020/07/24 10:28:14 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad2c0): openPending: 2020/07/24 10:28:14 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "" 2020/07/24 10:28:14 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:28:14 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad2c0): >openPending: err= 2020/07/24 10:28:14 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:28:14 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:28:14 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:14 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad2c0): _writeAt: size=14, off=0 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad2c0): >_writeAt: n=14, err= 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad2c0): close: 2020/07/24 10:28:14 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:28:14 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:28:14.587615303 +0000 UTC m=+54.662227561 2020/07/24 10:28:14 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad2c0): >close: err= 2020/07/24 10:28:14 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:28:14 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:28:14 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:28:14 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad5c0): _readAt: size=512, off=0 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad5c0): openPending: 2020/07/24 10:28:14 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/07/24 10:28:14 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:28:14 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad5c0): >openPending: err= 2020/07/24 10:28:14 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad5c0): >_readAt: n=14, err=EOF 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad5c0): close: 2020/07/24 10:28:14 DEBUG : vfs cache: looking for range={Pos:0 Size:14} in [{Pos:0 Size:14}] - present true 2020/07/24 10:28:14 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:28:14.587615303 +0000 UTC m=+54.662227561 2020/07/24 10:28:14 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:28:14 DEBUG : dir/file1(0xc0000ad5c0): >close: err= 2020/07/24 10:28:14 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:28:14 DEBUG : dir/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/07/24 10:28:14 INFO : dir/file1: Copied (replaced existing) 2020/07/24 10:28:14 DEBUG : dir/file1: vfs cache: fingerprint now "14,2020-07-24 10:28:14.587 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" 2020/07/24 10:28:14 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/07/24 10:28:14 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:28:14 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/07/24 10:28:15 DEBUG : dir/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/07/24 10:28:15 INFO : dir/file1: Copied (server side copy) 2020/07/24 10:28:15 INFO : dir/file1: Deleted 2020/07/24 10:28:15 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:28:15 DEBUG : newLeaf: Updating file with newLeaf 0xc00030e0c0 2020/07/24 10:28:15 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:28:15 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:28:16 DEBUG : newLeaf: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/07/24 10:28:16 INFO : newLeaf: Copied (server side copy) 2020/07/24 10:28:16 INFO : newLeaf: Deleted 2020/07/24 10:28:16 INFO : newLeaf: vfs cache: renamed in cache to "dir/file1" 2020/07/24 10:28:16 DEBUG : dir/file1: Updating file with dir/file1 0xc00030e0c0 2020/07/24 10:28:16 DEBUG : : Added virtual directory entry vDel: "newLeaf" 2020/07/24 10:28:16 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:17 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:28:17 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:28:17 DEBUG : dir/file1(0xc000156000): openPending: 2020/07/24 10:28:17 DEBUG : dir/file1: vfs cache: checking remote fingerprint "14,2001-02-03 04:05:06.499 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" against cached fingerprint "14,2020-07-24 10:28:14.587 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6" 2020/07/24 10:28:17 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-07-24 10:28:14.587 +0000 UTC,a379624177abc4679cafafa8eae1d73e1478aaa6") 2020/07/24 10:28:17 INFO : dir/file1: vfs cache: removed cache file as stale (remote is different) 2020/07/24 10:28:17 DEBUG : dir/file1: vfs cache: removed metadata from cache as stale (remote is different) 2020/07/24 10:28:17 DEBUG : dir/file1: vfs cache: truncate to size=14 2020/07/24 10:28:17 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:17 DEBUG : dir/file1(0xc000156000): >openPending: err= 2020/07/24 10:28:17 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:28:17 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:28:17 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:28:17 DEBUG : dir/file1(0xc000156000): _writeAt: size=25, off=0 2020/07/24 10:28:17 DEBUG : dir/file1(0xc000156000): >_writeAt: n=25, err= 2020/07/24 10:28:17 DEBUG : dir/file1: SHA-1 = a379624177abc4679cafafa8eae1d73e1478aaa6 OK 2020/07/24 10:28:17 INFO : dir/file1: Copied (server side copy) 2020/07/24 10:28:17 INFO : dir/file1: Deleted 2020/07/24 10:28:17 INFO : dir/file1: vfs cache: renamed in cache to "newLeaf" 2020/07/24 10:28:17 DEBUG : newLeaf: Updating file with newLeaf 0xc00030e0c0 2020/07/24 10:28:17 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:28:17 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:28:17 DEBUG : newLeaf(0xc000156000): close: 2020/07/24 10:28:17 DEBUG : vfs cache: looking for range={Pos:0 Size:25} in [{Pos:0 Size:25}] - present true 2020/07/24 10:28:17 DEBUG : newLeaf: vfs cache: setting modification time to 2020-07-24 10:28:17.100499531 +0000 UTC m=+57.175111797 2020/07/24 10:28:17 INFO : newLeaf: vfs cache: queuing for upload in 100ms 2020/07/24 10:28:17 DEBUG : newLeaf(0xc000156000): >close: err= 2020/07/24 10:28:17 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:17 DEBUG : dir: Looking for writers 2020/07/24 10:28:17 DEBUG : : Looking for writers 2020/07/24 10:28:17 DEBUG : dir: reading active writers 2020/07/24 10:28:17 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:28:17 DEBUG : dir: Looking for writers 2020/07/24 10:28:17 DEBUG : : Looking for writers 2020/07/24 10:28:17 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:17 DEBUG : dir: reading active writers 2020/07/24 10:28:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:28:17 DEBUG : dir: Looking for writers 2020/07/24 10:28:17 DEBUG : : Looking for writers 2020/07/24 10:28:17 DEBUG : dir: reading active writers 2020/07/24 10:28:17 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:28:18 DEBUG : dir: Looking for writers 2020/07/24 10:28:18 DEBUG : : Looking for writers 2020/07/24 10:28:18 DEBUG : dir: reading active writers 2020/07/24 10:28:18 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:28:18 DEBUG : newLeaf: vfs cache: starting upload 2020/07/24 10:28:18 DEBUG : dir: Looking for writers 2020/07/24 10:28:18 DEBUG : : Looking for writers 2020/07/24 10:28:18 DEBUG : dir: reading active writers 2020/07/24 10:28:18 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:28:18 DEBUG : dir: Looking for writers 2020/07/24 10:28:18 DEBUG : : Looking for writers 2020/07/24 10:28:18 DEBUG : dir: reading active writers 2020/07/24 10:28:18 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:28:18 DEBUG : newLeaf: SHA-1 = f1f3d7db56f36d9a5a912b01803c2176a972b9b0 OK 2020/07/24 10:28:18 INFO : newLeaf: Copied (replaced existing) 2020/07/24 10:28:18 DEBUG : newLeaf: vfs cache: fingerprint now "25,2020-07-24 10:28:17.1 +0000 UTC,f1f3d7db56f36d9a5a912b01803c2176a972b9b0" 2020/07/24 10:28:18 DEBUG : newLeaf: vfs cache: writeback object to VFS layer 2020/07/24 10:28:18 DEBUG : : Added virtual directory entry vAdd: "newLeaf" 2020/07/24 10:28:18 INFO : newLeaf: vfs cache: upload succeeded try #1 2020/07/24 10:28:18 DEBUG : dir: Looking for writers 2020/07/24 10:28:18 DEBUG : : Looking for writers 2020/07/24 10:28:18 DEBUG : dir: reading active writers 2020/07/24 10:28:18 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:18 DEBUG : >WaitForWriters: 2020/07/24 10:28:18 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:18 DEBUG : dir: Looking for writers 2020/07/24 10:28:18 DEBUG : : Looking for writers 2020/07/24 10:28:18 DEBUG : dir: reading active writers 2020/07/24 10:28:18 DEBUG : newLeaf: reading active writers 2020/07/24 10:28:18 DEBUG : >WaitForWriters: 2020/07/24 10:28:18 DEBUG : vfs cache: cleaner exiting --- PASS: TestFileRename (30.22s) --- PASS: TestFileRename/off,forceCache=false (24.06s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" --- PASS: TestFileRename/writes,forceCache=true (6.15s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestRcGetVFS 2020/07/24 10:28:19 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:19 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:19 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:19 DEBUG : : Looking for writers 2020/07/24 10:28:19 DEBUG : >WaitForWriters: --- PASS: TestRcGetVFS (0.29s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestReadFileHandleReadAt 2020/07/24 10:28:19 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:20 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:20 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:28:20 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:28:20 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:28:20 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:21 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:21 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2020/07/24 10:28:21 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2020/07/24 10:28:21 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2020/07/24 10:28:21 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2020/07/24 10:28:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2020/07/24 10:28:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2020/07/24 10:28:21 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2020/07/24 10:28:21 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker) 2020/07/24 10:28:21 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1 2020/07/24 10:28:21 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728 2020/07/24 10:28:21 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728 2020/07/24 10:28:22 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms 2020/07/24 10:28:22 DEBUG : dir/file1: aborting in-sequence read wait, off=10 2020/07/24 10:28:22 DEBUG : dir/file1: failed to wait for in-sequence read to 10 2020/07/24 10:28:22 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker) 2020/07/24 10:28:22 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1 2020/07/24 10:28:22 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728 2020/07/24 10:28:22 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:28:23 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker) 2020/07/24 10:28:23 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1 2020/07/24 10:28:23 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728 2020/07/24 10:28:23 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2020/07/24 10:28:23 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/07/24 10:28:23 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/07/24 10:28:23 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/07/24 10:28:23 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16 2020/07/24 10:28:23 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2020/07/24 10:28:23 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2020/07/24 10:28:23 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2020/07/24 10:28:23 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor 2020/07/24 10:28:23 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:23 DEBUG : dir: Looking for writers 2020/07/24 10:28:23 DEBUG : file1: reading active writers 2020/07/24 10:28:23 DEBUG : : Looking for writers 2020/07/24 10:28:23 DEBUG : dir: reading active writers 2020/07/24 10:28:23 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleReadAt (5.46s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestReadFileHandleFlush 2020/07/24 10:28:25 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:26 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:26 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:28:26 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:28:26 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:28:26 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:26 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:26 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:26 DEBUG : dir: Looking for writers 2020/07/24 10:28:26 DEBUG : file1: reading active writers 2020/07/24 10:28:26 DEBUG : : Looking for writers 2020/07/24 10:28:26 DEBUG : dir: reading active writers 2020/07/24 10:28:26 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleFlush (2.02s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestReadFileHandleRelease 2020/07/24 10:28:27 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:27 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:27 DEBUG : dir/file1: Open: flags=O_RDONLY 2020/07/24 10:28:27 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2020/07/24 10:28:27 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2020/07/24 10:28:27 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:28 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:28 DEBUG : dir/file1: ReadFileHandle.Release closing 2020/07/24 10:28:28 DEBUG : dir/file1: ReadFileHandle.Release nothing to do 2020/07/24 10:28:28 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:28 DEBUG : dir: Looking for writers 2020/07/24 10:28:28 DEBUG : file1: reading active writers 2020/07/24 10:28:28 DEBUG : : Looking for writers 2020/07/24 10:28:28 DEBUG : dir: reading active writers 2020/07/24 10:28:28 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleRelease (1.54s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestRWFileHandleSizeTruncateExisting 2020/07/24 10:28:28 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:28 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-hebecom2wanikot5sureciw2" 2020/07/24 10:28:28 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-hebecom2wanikot5sureciw2" 2020/07/24 10:28:28 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:28:29 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:28:29 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2020/07/24 10:28:29 DEBUG : dir/file1: newRWFileHandle: 2020/07/24 10:28:29 DEBUG : dir/file1(0xc0003d9580): openPending: 2020/07/24 10:28:29 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16,2001-02-03 04:05:06.499 +0000 UTC,fe5567e8d769550852182cdf69d74bb16dff8e29" against cached fingerprint "" 2020/07/24 10:28:29 DEBUG : dir/file1: vfs cache: truncate to size=16 2020/07/24 10:28:29 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:29 DEBUG : dir/file1(0xc0003d9580): >openPending: err= 2020/07/24 10:28:29 DEBUG : dir/file1: vfs cache: truncate to size=0 2020/07/24 10:28:29 DEBUG : dir/file1: >newRWFileHandle: err= 2020/07/24 10:28:29 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2020/07/24 10:28:29 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2020/07/24 10:28:29 DEBUG : dir/file1(0xc0003d9580): _writeAt: size=5, off=0 2020/07/24 10:28:29 DEBUG : dir/file1(0xc0003d9580): >_writeAt: n=5, err= 2020/07/24 10:28:29 DEBUG : dir/file1(0xc0003d9580): close: 2020/07/24 10:28:29 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true 2020/07/24 10:28:29 DEBUG : dir/file1: vfs cache: setting modification time to 2020-07-24 10:28:29.662431838 +0000 UTC m=+69.737044107 2020/07/24 10:28:29 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:28:29 DEBUG : dir/file1(0xc0003d9580): >close: err= 2020/07/24 10:28:29 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:29 DEBUG : dir: Looking for writers 2020/07/24 10:28:29 DEBUG : file1: reading active writers 2020/07/24 10:28:29 DEBUG : : Looking for writers 2020/07/24 10:28:29 DEBUG : dir: reading active writers 2020/07/24 10:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:28:29 DEBUG : dir: Looking for writers 2020/07/24 10:28:29 DEBUG : file1: reading active writers 2020/07/24 10:28:29 DEBUG : : Looking for writers 2020/07/24 10:28:29 DEBUG : dir: reading active writers 2020/07/24 10:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:28:29 DEBUG : dir: Looking for writers 2020/07/24 10:28:29 DEBUG : file1: reading active writers 2020/07/24 10:28:29 DEBUG : : Looking for writers 2020/07/24 10:28:29 DEBUG : dir: reading active writers 2020/07/24 10:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:28:29 DEBUG : dir: Looking for writers 2020/07/24 10:28:29 DEBUG : file1: reading active writers 2020/07/24 10:28:29 DEBUG : : Looking for writers 2020/07/24 10:28:29 DEBUG : dir: reading active writers 2020/07/24 10:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:28:29 DEBUG : dir/file1: vfs cache: starting upload 2020/07/24 10:28:29 DEBUG : dir: Looking for writers 2020/07/24 10:28:29 DEBUG : file1: reading active writers 2020/07/24 10:28:29 DEBUG : : Looking for writers 2020/07/24 10:28:29 DEBUG : dir: reading active writers 2020/07/24 10:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:28:29 DEBUG : dir: Looking for writers 2020/07/24 10:28:29 DEBUG : file1: reading active writers 2020/07/24 10:28:29 DEBUG : : Looking for writers 2020/07/24 10:28:29 DEBUG : dir: reading active writers 2020/07/24 10:28:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:28:30 DEBUG : dir/file1: SHA-1 = aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d OK 2020/07/24 10:28:30 INFO : dir/file1: Copied (replaced existing) 2020/07/24 10:28:30 DEBUG : dir/file1: vfs cache: fingerprint now "5,2020-07-24 10:28:29.662 +0000 UTC,aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d" 2020/07/24 10:28:30 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2020/07/24 10:28:30 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:30 INFO : dir/file1: vfs cache: upload succeeded try #1 2020/07/24 10:28:30 DEBUG : dir: Looking for writers 2020/07/24 10:28:30 DEBUG : file1: reading active writers 2020/07/24 10:28:30 DEBUG : : Looking for writers 2020/07/24 10:28:30 DEBUG : dir: reading active writers 2020/07/24 10:28:30 DEBUG : >WaitForWriters: 2020/07/24 10:28:30 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleSizeTruncateExisting (2.28s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestRWFileModTimeWithOpenWriters 2020/07/24 10:28:30 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:30 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-hebecom2wanikot5sureciw2" 2020/07/24 10:28:30 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-hebecom2wanikot5sureciw2" 2020/07/24 10:28:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:28:30 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2020/07/24 10:28:31 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:28:31 DEBUG : file1: newRWFileHandle: 2020/07/24 10:28:31 DEBUG : file1(0xc0007be080): openPending: 2020/07/24 10:28:31 DEBUG : file1: vfs cache: truncate to size=0 2020/07/24 10:28:31 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:31 DEBUG : file1(0xc0007be080): >openPending: err= 2020/07/24 10:28:31 DEBUG : file1: >newRWFileHandle: err= 2020/07/24 10:28:31 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:31 DEBUG : file1: >Open: fd=file1 (rw), err= 2020/07/24 10:28:31 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2020/07/24 10:28:32 DEBUG : Can set mod time: true 2020/07/24 10:28:32 DEBUG : file1(0xc0007be080): _writeAt: size=2, off=0 2020/07/24 10:28:32 DEBUG : file1(0xc0007be080): >_writeAt: n=2, err= 2020/07/24 10:28:32 DEBUG : file1(0xc0007be080): RWFileHandle.Flush 2020/07/24 10:28:32 DEBUG : file1(0xc0007be080): RWFileHandle.Release 2020/07/24 10:28:32 DEBUG : file1(0xc0007be080): close: 2020/07/24 10:28:32 DEBUG : file1: vfs cache: setting modification time to 2020-07-24 10:28:32.478712184 +0000 UTC m=+72.553324458 2020/07/24 10:28:32 INFO : file1: vfs cache: queuing for upload in 100ms 2020/07/24 10:28:32 DEBUG : file1(0xc0007be080): >close: err= 2020/07/24 10:28:32 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:32 DEBUG : : Looking for writers 2020/07/24 10:28:32 DEBUG : file1: reading active writers 2020/07/24 10:28:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2020/07/24 10:28:32 DEBUG : : Looking for writers 2020/07/24 10:28:32 DEBUG : file1: reading active writers 2020/07/24 10:28:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2020/07/24 10:28:32 DEBUG : : Looking for writers 2020/07/24 10:28:32 DEBUG : file1: reading active writers 2020/07/24 10:28:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2020/07/24 10:28:32 DEBUG : : Looking for writers 2020/07/24 10:28:32 DEBUG : file1: reading active writers 2020/07/24 10:28:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2020/07/24 10:28:32 DEBUG : file1: vfs cache: starting upload 2020/07/24 10:28:32 DEBUG : : Looking for writers 2020/07/24 10:28:32 DEBUG : file1: reading active writers 2020/07/24 10:28:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2020/07/24 10:28:32 DEBUG : : Looking for writers 2020/07/24 10:28:32 DEBUG : file1: reading active writers 2020/07/24 10:28:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2020/07/24 10:28:32 DEBUG : file1: SHA-1 = c22b5f9178342609428d6f51b2c5af4c0bde6a42 OK 2020/07/24 10:28:32 INFO : file1: Copied (new) 2020/07/24 10:28:32 DEBUG : file1: vfs cache: fingerprint now "2,2020-07-24 10:28:32.478 +0000 UTC,c22b5f9178342609428d6f51b2c5af4c0bde6a42" 2020/07/24 10:28:32 DEBUG : file1: vfs cache: writeback object to VFS layer 2020/07/24 10:28:33 DEBUG : : Looking for writers 2020/07/24 10:28:33 DEBUG : file1: reading active writers 2020/07/24 10:28:33 DEBUG : >WaitForWriters: 2020/07/24 10:28:33 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:33 DEBUG : : Looking for writers 2020/07/24 10:28:33 DEBUG : file1: reading active writers 2020/07/24 10:28:33 DEBUG : >WaitForWriters: 2020/07/24 10:28:33 DEBUG : vfs cache: cleaner exiting --- FAIL: TestRWFileModTimeWithOpenWriters (3.34s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" 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 |-67312h56m1.478s| > 1ms (want 2012-11-18 17:32:31 +0000 UTC vs got 2020-07-24 10:28:32.478 +0000 UTC) (precision 1ms) === RUN TestCaseSensitivity 2020/07/24 10:28:34 DEBUG : file1: File._applyPendingModTime OK 2020/07/24 10:28:34 DEBUG : file1: vfs cache: fingerprint now "2,2012-11-18 17:32:31 +0000 UTC,c22b5f9178342609428d6f51b2c5af4c0bde6a42" 2020/07/24 10:28:34 DEBUG : file1: vfs cache: setting modification time to 2012-11-18 17:32:31 +0000 UTC 2020/07/24 10:28:34 ERROR : file1: vfs cache: failed to set modification time of cached file: chtimes /home/rclone/.cache/rclone/vfs/TestB2/rclone-test-hebecom2wanikot5sureciw2/file1: no such file or directory 2020/07/24 10:28:34 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-hebecom2wanikot5sureciw2/file1: no such file or directory 2020/07/24 10:28:34 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:28:34 INFO : file1: vfs cache: upload succeeded try #1 2020/07/24 10:28:35 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:35 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:28:35 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:35 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/07/24 10:28:35 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/07/24 10:28:35 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err= 2020/07/24 10:28:35 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:36 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:36 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:36 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/07/24 10:28:36 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/07/24 10:28:36 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err= 2020/07/24 10:28:36 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:36 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:36 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:36 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/07/24 10:28:36 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/07/24 10:28:36 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err= 2020/07/24 10:28:36 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:36 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:36 DEBUG : FiLeB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:36 DEBUG : FiLeB: Open: flags=O_RDONLY 2020/07/24 10:28:36 DEBUG : FiLeB: >Open: fd=FiLeB (r), err= 2020/07/24 10:28:36 DEBUG : FiLeB: >OpenFile: fd=FiLeB (r), err= 2020/07/24 10:28:36 DEBUG : FiLeB: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:36 DEBUG : FiLeB: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:36 DEBUG : FilEb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:36 DEBUG : FilEb: Open: flags=O_RDONLY 2020/07/24 10:28:36 DEBUG : FilEb: >Open: fd=FilEb (r), err= 2020/07/24 10:28:36 DEBUG : FilEb: >OpenFile: fd=FilEb (r), err= 2020/07/24 10:28:36 DEBUG : FilEb: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:36 DEBUG : FilEb: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:37 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/07/24 10:28:37 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:37 DEBUG : fileA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/07/24 10:28:37 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : fileA: >OpenFile: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:37 DEBUG : filea: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/07/24 10:28:37 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : filea: >OpenFile: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:37 DEBUG : FILEA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/07/24 10:28:37 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : FILEA: >OpenFile: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:37 DEBUG : FiLeB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 DEBUG : FiLeB: Open: flags=O_RDONLY 2020/07/24 10:28:37 DEBUG : FiLeB: >Open: fd=FiLeB (r), err= 2020/07/24 10:28:37 DEBUG : FiLeB: >OpenFile: fd=FiLeB (r), err= 2020/07/24 10:28:37 DEBUG : FiLeB: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:37 DEBUG : FiLeB: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:37 DEBUG : FilEb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 DEBUG : FilEb: Open: flags=O_RDONLY 2020/07/24 10:28:37 DEBUG : FilEb: >Open: fd=FilEb (r), err= 2020/07/24 10:28:37 DEBUG : FilEb: >OpenFile: fd=FilEb (r), err= 2020/07/24 10:28:37 DEBUG : FilEb: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:37 DEBUG : FilEb: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:37 DEBUG : fileb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 ERROR : /: Dir.Stat error: duplicate filename "fileb" detected with --vfs-case-insensitive set 2020/07/24 10:28:37 DEBUG : fileb: >OpenFile: fd=, err=duplicate filename "fileb" detected with --vfs-case-insensitive set 2020/07/24 10:28:37 DEBUG : FILEB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 ERROR : /: Dir.Stat error: duplicate filename "FILEB" detected with --vfs-case-insensitive set 2020/07/24 10:28:37 DEBUG : FILEB: >OpenFile: fd=, err=duplicate filename "FILEB" detected with --vfs-case-insensitive set 2020/07/24 10:28:37 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:37 DEBUG : FiLeA: Open: flags=O_RDONLY 2020/07/24 10:28:37 DEBUG : FiLeA: >Open: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err= 2020/07/24 10:28:37 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:38 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:38 DEBUG : fileA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:38 DEBUG : fileA: >OpenFile: fd=, err=file does not exist 2020/07/24 10:28:38 DEBUG : filea: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:38 DEBUG : filea: >OpenFile: fd=, err=file does not exist 2020/07/24 10:28:38 DEBUG : FILEA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:38 DEBUG : FILEA: >OpenFile: fd=, err=file does not exist 2020/07/24 10:28:38 DEBUG : FiLeB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:38 DEBUG : FiLeB: Open: flags=O_RDONLY 2020/07/24 10:28:38 DEBUG : FiLeB: >Open: fd=FiLeB (r), err= 2020/07/24 10:28:38 DEBUG : FiLeB: >OpenFile: fd=FiLeB (r), err= 2020/07/24 10:28:38 DEBUG : FiLeB: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:38 DEBUG : FiLeB: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:38 DEBUG : FilEb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:38 DEBUG : FilEb: Open: flags=O_RDONLY 2020/07/24 10:28:38 DEBUG : FilEb: >Open: fd=FilEb (r), err= 2020/07/24 10:28:38 DEBUG : FilEb: >OpenFile: fd=FilEb (r), err= 2020/07/24 10:28:38 DEBUG : FilEb: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:28:38 DEBUG : FilEb: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728 2020/07/24 10:28:38 DEBUG : fileb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:38 DEBUG : fileb: >OpenFile: fd=, err=file does not exist 2020/07/24 10:28:38 DEBUG : FILEB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:28:38 DEBUG : FILEB: >OpenFile: fd=, err=file does not exist 2020/07/24 10:28:38 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:38 DEBUG : : Looking for writers 2020/07/24 10:28:38 DEBUG : FiLeA: reading active writers 2020/07/24 10:28:38 DEBUG : FiLeB: reading active writers 2020/07/24 10:28:38 DEBUG : FilEb: reading active writers 2020/07/24 10:28:38 DEBUG : >WaitForWriters: 2020/07/24 10:28:38 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:28:38 DEBUG : : Looking for writers 2020/07/24 10:28:38 DEBUG : FiLeA: reading active writers 2020/07/24 10:28:38 DEBUG : FiLeB: reading active writers 2020/07/24 10:28:38 DEBUG : FilEb: reading active writers 2020/07/24 10:28:38 DEBUG : >WaitForWriters: --- PASS: TestCaseSensitivity (35.27s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestVFSNew 2020/07/24 10:29:09 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:29:09 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: Re-using VFS from active cache 2020/07/24 10:29:09 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:29:09 DEBUG : : Looking for writers 2020/07/24 10:29:09 DEBUG : >WaitForWriters: --- PASS: TestVFSNew (0.29s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestVFSStat 2020/07/24 10:29:09 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:29:11 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:29:11 DEBUG : dir: Looking for writers 2020/07/24 10:29:11 DEBUG : file2: reading active writers 2020/07/24 10:29:11 DEBUG : : Looking for writers 2020/07/24 10:29:11 DEBUG : file1: reading active writers 2020/07/24 10:29:11 DEBUG : dir: reading active writers 2020/07/24 10:29:11 DEBUG : >WaitForWriters: --- PASS: TestVFSStat (2.94s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestVFSStatParent 2020/07/24 10:29:12 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:29:23 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:29:23 DEBUG : dir: Looking for writers 2020/07/24 10:29:23 DEBUG : : Looking for writers 2020/07/24 10:29:23 DEBUG : dir: reading active writers 2020/07/24 10:29:23 DEBUG : >WaitForWriters: --- FAIL: TestVFSStatParent (12.35s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" 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 vfs_test.go:233 Error: Should be true Test: TestVFSStatParent Messages: listing wrong, want dir/file2 (14), file1 (14) got dir/file2 (14) fstest.go:200: Not found "file1" fstest.go:203: Error Trace: fstest.go:203 fstest.go:307 fstest.go:335 fstest.go:347 vfs_test.go:233 Error: Not equal: expected: 0 actual : 1 Test: TestVFSStatParent Messages: 1 objects not found vfs_test.go:257: Error Trace: vfs_test.go:257 Error: Not equal: expected: &errors.errorString{s:"file already exists"} actual : &errors.errorString{s:"file does not exist"} Diff: --- Expected +++ Actual @@ -1,3 +1,3 @@ (*errors.errorString)({ - s: (string) (len=19) "file already exists" + s: (string) (len=19) "file does not exist" }) Test: TestVFSStatParent === RUN TestVFSOpenFile 2020/07/24 10:29:25 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:29:26 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:29:26 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:29:26 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:29:26 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:29:26 DEBUG : dir: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:29:26 DEBUG : dir: >OpenFile: fd=dir/ (r), err= 2020/07/24 10:29:26 DEBUG : dir/new_file.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2020/07/24 10:29:26 DEBUG : dir/new_file.txt: >OpenFile: fd=, err=file does not exist 2020/07/24 10:29:26 DEBUG : dir/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:29:26 DEBUG : dir/new_file.txt: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:29:26 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:29:26 DEBUG : dir/new_file.txt: >Open: fd=dir/new_file.txt (w), err= 2020/07/24 10:29:26 DEBUG : dir/new_file.txt: >OpenFile: fd=dir/new_file.txt (w), err= 2020/07/24 10:29:26 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:29:26 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:29:27 DEBUG : dir/new_file.txt: SHA-1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2020/07/24 10:29:27 INFO : dir/new_file.txt: Copied (new) 2020/07/24 10:29:27 DEBUG : dir: Added virtual directory entry vAdd: "new_file.txt" 2020/07/24 10:29:27 DEBUG : not found/new_file.txt: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:29:27 DEBUG : not found/new_file.txt: >OpenFile: fd=, err=file does not exist 2020/07/24 10:29:27 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:29:27 DEBUG : dir: Looking for writers 2020/07/24 10:29:27 DEBUG : file2: reading active writers 2020/07/24 10:29:27 DEBUG : new_file.txt: reading active writers 2020/07/24 10:29:27 DEBUG : : Looking for writers 2020/07/24 10:29:27 DEBUG : dir: reading active writers 2020/07/24 10:29:27 DEBUG : file1: reading active writers 2020/07/24 10:29:27 DEBUG : >WaitForWriters: --- PASS: TestVFSOpenFile (3.18s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestVFSRename 2020/07/24 10:29:28 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:29:30 DEBUG : dir/file2: SHA-1 = 693a1c717811546a82e06145f0d12f4e35710bb9 OK 2020/07/24 10:29:30 INFO : dir/file2: Copied (server side copy) 2020/07/24 10:29:30 INFO : dir/file2: Deleted 2020/07/24 10:29:30 DEBUG : dir/file1: Updating file with dir/file1 0xc0002ac480 2020/07/24 10:29:30 DEBUG : dir: Added virtual directory entry vDel: "file2" 2020/07/24 10:29:30 DEBUG : dir: Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:31 DEBUG : dir/file1: SHA-1 = 693a1c717811546a82e06145f0d12f4e35710bb9 OK 2020/07/24 10:29:31 INFO : dir/file1: Copied (server side copy) 2020/07/24 10:29:31 INFO : dir/file1: Deleted 2020/07/24 10:29:31 DEBUG : file0: Updating file with file0 0xc0002ac480 2020/07/24 10:29:31 DEBUG : dir: Added virtual directory entry vDel: "file1" 2020/07/24 10:29:31 DEBUG : : Added virtual directory entry vAdd: "file0" 2020/07/24 10:29:31 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:29:31 DEBUG : dir: Looking for writers 2020/07/24 10:29:31 DEBUG : : Looking for writers 2020/07/24 10:29:31 DEBUG : dir: reading active writers 2020/07/24 10:29:31 DEBUG : file0: reading active writers 2020/07/24 10:29:31 DEBUG : >WaitForWriters: --- PASS: TestVFSRename (3.98s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestWriteFileHandleMethods 2020/07/24 10:29:32 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:29:32 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:29:32 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:29:32 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:32 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:29:32 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:29:32 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:32 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2020/07/24 10:29:32 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2020/07/24 10:29:32 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2020/07/24 10:29:32 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (5 bytes), uploading instead of streaming 2020/07/24 10:29:32 DEBUG : file1: SHA-1 = aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d OK 2020/07/24 10:29:32 INFO : file1: Copied (new) 2020/07/24 10:29:32 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:32 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:29:32 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:29:32 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:32 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:29:32 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:29:32 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:29:32 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:29:32 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:32 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:29:32 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:29:32 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes 2020/07/24 10:29:32 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:29:32 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/07/24 10:29:32 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:32 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:29:32 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:29:32 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:32 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:29:33 DEBUG : file1: SHA-1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2020/07/24 10:29:33 INFO : file1: Copied (new) 2020/07/24 10:29:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:33 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2020/07/24 10:29:33 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2020/07/24 10:29:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:33 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:29:33 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:29:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:33 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (7 bytes), uploading instead of streaming 2020/07/24 10:29:33 DEBUG : file1: SHA-1 = 189d2b4d61d6c47f31a89ef5d008c201199ef899 OK 2020/07/24 10:29:33 INFO : file1: Copied (new) 2020/07/24 10:29:33 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:33 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:29:33 DEBUG : : Looking for writers 2020/07/24 10:29:33 DEBUG : file1: reading active writers 2020/07/24 10:29:33 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleMethods (9.24s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" 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 write_test.go:132 Error: Should be true Test: TestWriteFileHandleMethods Messages: listing wrong, want got file1 (7) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:132 Error: Should be true Test: TestWriteFileHandleMethods Messages: Unexpected file "file1" === RUN TestWriteFileHandleWriteAt 2020/07/24 10:29:41 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:29:41 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:29:41 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:29:41 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:41 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:29:41 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:29:41 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes 2020/07/24 10:29:41 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2020/07/24 10:29:42 DEBUG : file1: aborting in-sequence write wait, off=100 2020/07/24 10:29:42 DEBUG : file1: failed to wait for in-sequence write to 100 2020/07/24 10:29:42 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2020/07/24 10:29:42 DEBUG : file1: waiting for in-sequence write to 5 for 1s 2020/07/24 10:29:43 DEBUG : file1: aborting in-sequence write wait, off=5 2020/07/24 10:29:43 DEBUG : file1: failed to wait for in-sequence write to 5 2020/07/24 10:29:43 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2020/07/24 10:29:43 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor 2020/07/24 10:29:51 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:29:51 DEBUG : : Looking for writers 2020/07/24 10:29:51 DEBUG : file1: reading active writers 2020/07/24 10:29:51 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleWriteAt (10.26s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" write_test.go:144: Error Trace: write_test.go:144 Error: Received unexpected error: permission denied Test: TestWriteFileHandleWriteAt write_test.go:145: Error Trace: write_test.go:145 Error: Not equal: expected: 5 actual : 0 Test: TestWriteFileHandleWriteAt write_test.go:148: Error Trace: write_test.go:148 Error: Not equal: expected: 5 actual : 0 Test: TestWriteFileHandleWriteAt write_test.go:149: Error Trace: write_test.go:149 Error: Should be true Test: TestWriteFileHandleWriteAt write_test.go:158: Error Trace: write_test.go:158 Error: Received unexpected error: Illegal seek Test: TestWriteFileHandleWriteAt write_test.go:159: Error Trace: write_test.go:159 Error: Not equal: expected: 6 actual : 0 Test: TestWriteFileHandleWriteAt dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:172 Error: Not equal: expected: []string{"file1,11,false"} actual : []string{"file1,7,false"} Diff: --- Expected +++ Actual @@ -1,3 +1,3 @@ ([]string) (len=1) { - (string) (len=14) "file1,11,false" + (string) (len=13) "file1,7,false" } Test: TestWriteFileHandleWriteAt fstest.go:295: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:295: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:295: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Error Trace: fstest.go:302 fstest.go:335 write_test.go:176 Error: Should be true Test: TestWriteFileHandleWriteAt Messages: listing wrong, want file1 (11) got file1 (7) fstest.go:140: Error Trace: fstest.go:140 fstest.go:146 fstest.go:192 fstest.go:305 fstest.go:335 write_test.go:176 Error: Should be true Test: TestWriteFileHandleWriteAt Messages: B2 bucket rclone-test-hebecom2wanikot5sureciw2/file1: SHA-1 hash incorrect - expecting "2aae6c35c94fcfb415dbe95f408b9ce91ee846ed" got "189d2b4d61d6c47f31a89ef5d008c201199ef899" fstest.go:147: Error Trace: fstest.go:147 fstest.go:192 fstest.go:305 fstest.go:335 write_test.go:176 Error: Not equal: expected: 11 actual : 7 Test: TestWriteFileHandleWriteAt Messages: file1: size incorrect file=11 vs obj=7 === RUN TestWriteFileHandleFlush 2020/07/24 10:29:51 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:29:51 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:29:51 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:29:51 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:51 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:29:51 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:29:51 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2020/07/24 10:29:51 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:51 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (5 bytes), uploading instead of streaming 2020/07/24 10:29:52 DEBUG : file1: SHA-1 = aaf4c61ddcc5e8a2dabede0f3b482cd9aea9434d OK 2020/07/24 10:29:52 INFO : file1: Copied (new) 2020/07/24 10:29:52 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:29:52 DEBUG : file1: WriteFileHandle.Flush nothing to do 2020/07/24 10:29:52 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:29:52 DEBUG : : Looking for writers 2020/07/24 10:29:52 DEBUG : file1: reading active writers 2020/07/24 10:29:52 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleFlush (9.41s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" 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 write_test.go:210 Error: Should be true Test: TestWriteFileHandleFlush Messages: listing wrong, want got file1 (5) fstest.go:188: Error Trace: fstest.go:188 fstest.go:305 fstest.go:335 run.go:169 run.go:339 vfs_test.go:54 write_test.go:210 Error: Should be true Test: TestWriteFileHandleFlush Messages: Unexpected file "file1" === RUN TestWriteFileModTimeWithOpenWriters 2020/07/24 10:30:01 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:30:01 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:30:01 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:30:01 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:30:01 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:30:01 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:30:01 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes 2020/07/24 10:30:01 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:30:01 DEBUG : : Looking for writers 2020/07/24 10:30:01 DEBUG : file1: reading active writers 2020/07/24 10:30:01 DEBUG : file1: active writers 1 2020/07/24 10:30:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2020/07/24 10:30:01 DEBUG : : Looking for writers 2020/07/24 10:30:01 DEBUG : file1: reading active writers 2020/07/24 10:30:01 DEBUG : file1: active writers 1 2020/07/24 10:30:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2020/07/24 10:30:01 DEBUG : : Looking for writers 2020/07/24 10:30:01 DEBUG : file1: reading active writers 2020/07/24 10:30:01 DEBUG : file1: active writers 1 2020/07/24 10:30:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2020/07/24 10:30:01 DEBUG : : Looking for writers 2020/07/24 10:30:01 DEBUG : file1: reading active writers 2020/07/24 10:30:01 DEBUG : file1: active writers 1 2020/07/24 10:30:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2020/07/24 10:30:01 DEBUG : : Looking for writers 2020/07/24 10:30:01 DEBUG : file1: reading active writers 2020/07/24 10:30:01 DEBUG : file1: active writers 1 2020/07/24 10:30:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2020/07/24 10:30:01 DEBUG : : Looking for writers 2020/07/24 10:30:01 DEBUG : file1: reading active writers 2020/07/24 10:30:01 DEBUG : file1: active writers 1 2020/07/24 10:30:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2020/07/24 10:30:02 DEBUG : : Looking for writers 2020/07/24 10:30:02 DEBUG : file1: reading active writers 2020/07/24 10:30:02 DEBUG : file1: active writers 1 2020/07/24 10:30:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2020/07/24 10:30:02 DEBUG : : Looking for writers 2020/07/24 10:30:02 DEBUG : file1: reading active writers 2020/07/24 10:30:02 DEBUG : file1: active writers 1 2020/07/24 10:30:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:03 DEBUG : : Looking for writers 2020/07/24 10:30:03 DEBUG : file1: reading active writers 2020/07/24 10:30:03 DEBUG : file1: active writers 1 2020/07/24 10:30:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:04 DEBUG : : Looking for writers 2020/07/24 10:30:04 DEBUG : file1: reading active writers 2020/07/24 10:30:04 DEBUG : file1: active writers 1 2020/07/24 10:30:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:05 DEBUG : : Looking for writers 2020/07/24 10:30:05 DEBUG : file1: reading active writers 2020/07/24 10:30:05 DEBUG : file1: active writers 1 2020/07/24 10:30:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:06 DEBUG : : Looking for writers 2020/07/24 10:30:06 DEBUG : file1: reading active writers 2020/07/24 10:30:06 DEBUG : file1: active writers 1 2020/07/24 10:30:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:07 DEBUG : : Looking for writers 2020/07/24 10:30:07 DEBUG : file1: reading active writers 2020/07/24 10:30:07 DEBUG : file1: active writers 1 2020/07/24 10:30:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:08 DEBUG : : Looking for writers 2020/07/24 10:30:08 DEBUG : file1: reading active writers 2020/07/24 10:30:08 DEBUG : file1: active writers 1 2020/07/24 10:30:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:09 DEBUG : : Looking for writers 2020/07/24 10:30:09 DEBUG : file1: reading active writers 2020/07/24 10:30:09 DEBUG : file1: active writers 1 2020/07/24 10:30:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:10 DEBUG : : Looking for writers 2020/07/24 10:30:10 DEBUG : file1: reading active writers 2020/07/24 10:30:10 DEBUG : file1: active writers 1 2020/07/24 10:30:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2020/07/24 10:30:11 ERROR : Exiting even though 1 writers active and 0 cache items in use after 10s Cache: 2020/07/24 10:30:11 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileModTimeWithOpenWriters (11.15s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" write_test.go:271: Error Trace: write_test.go:271 Error: Received unexpected error: permission denied Test: TestWriteFileModTimeWithOpenWriters === RUN TestFileReadAtZeroLength 2020/07/24 10:30:12 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:30:12 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:30:12 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:30:12 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:30:12 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:30:12 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:30:12 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:30:12 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (0 bytes), uploading instead of streaming 2020/07/24 10:30:13 DEBUG : file1: SHA-1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK 2020/07/24 10:30:13 INFO : file1: Copied (new) 2020/07/24 10:30:13 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:30:13 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/07/24 10:30:13 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:30:13 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:30:13 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:30:13 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:30:14 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2020/07/24 10:30:14 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:30:14 DEBUG : : Looking for writers 2020/07/24 10:30:14 DEBUG : file1: reading active writers 2020/07/24 10:30:14 DEBUG : >WaitForWriters: --- PASS: TestFileReadAtZeroLength (2.22s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" === RUN TestFileReadAtNonZeroLength 2020/07/24 10:30:14 INFO : B2 bucket rclone-test-hebecom2wanikot5sureciw2: poll-interval is not supported by this remote 2020/07/24 10:30:14 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2020/07/24 10:30:14 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2020/07/24 10:30:14 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:30:14 DEBUG : file1: >Open: fd=file1 (w), err= 2020/07/24 10:30:14 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2020/07/24 10:30:14 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:30:14 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: File to upload is small (100 bytes), uploading instead of streaming 2020/07/24 10:30:15 DEBUG : file1: SHA-1 = b43025f66ae093e2a4845ee7033334f30036ab34 OK 2020/07/24 10:30:15 INFO : file1: Copied (new) 2020/07/24 10:30:15 DEBUG : : Added virtual directory entry vAdd: "file1" 2020/07/24 10:30:15 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2020/07/24 10:30:15 DEBUG : file1: Open: flags=O_RDONLY 2020/07/24 10:30:15 DEBUG : file1: >Open: fd=file1 (r), err= 2020/07/24 10:30:15 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2020/07/24 10:30:15 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2020/07/24 10:30:15 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2020/07/24 10:30:15 DEBUG : WaitForWriters: timeout=10s 2020/07/24 10:30:15 DEBUG : : Looking for writers 2020/07/24 10:30:15 DEBUG : file1: reading active writers 2020/07/24 10:30:15 DEBUG : >WaitForWriters: --- PASS: TestFileReadAtNonZeroLength (1.20s) run.go:176: Remote "B2 bucket rclone-test-hebecom2wanikot5sureciw2", Local "Local file system at /tmp/rclone105909553", Modify Window "1ms" FAIL 2020/07/24 10:30:15 DEBUG : B2 bucket rclone-test-hebecom2wanikot5sureciw2: Purge remote 2020/07/24 10:30:16 DEBUG : FiLeA: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f111b8ad805f4afeb_d20200724_m102838_c001_v0001137_t0003") 2020/07/24 10:30:16 DEBUG : FiLeA: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151029_d20200724_m102834_c001_v0001037_t0019") 2020/07/24 10:30:16 DEBUG : FiLeB: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f11675582e6048765_d20200724_m102838_c001_v0001131_t0001") 2020/07/24 10:30:16 DEBUG : FiLeB: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad15102b_d20200724_m102834_c001_v0001037_t0019") 2020/07/24 10:30:16 DEBUG : FilEb: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10278d76fc5f080e_d20200724_m102909_c001_v0001040_t0033") 2020/07/24 10:30:16 DEBUG : FilEb: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad15102f_d20200724_m102835_c001_v0001037_t0019") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f106271d1a1302750_d20200724_m102931_c001_v0001136_t0050") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f11537e6ce9c039ff_d20200724_m102929_c001_v0001090_t0025") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f106c69e6c439840c_d20200724_m102830_c001_v0001093_t0010") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151017_d20200724_m102829_c001_v0001037_t0019") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151015_d20200724_m102828_c001_v0001037_t0019") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f102aa39793760836_d20200724_m102828_c001_v0001128_t0042") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151011_d20200724_m102827_c001_v0001037_t0019") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f106038d87f0c071a_d20200724_m102826_c001_v0001040_t0015") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad15100d_d20200724_m102825_c001_v0001037_t0019") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f100c92aedae937fc_d20200724_m102823_c001_v0001036_t0034") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151001_d20200724_m102819_c001_v0001037_t0019") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10818954e50d49e9_d20200724_m102817_c001_v0001093_t0002") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f105c8d69dbc7e06c_d20200724_m102816_c001_v0001137_t0050") 2020/07/24 10:30:16 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1098fc8f7f24c2bb_d20200724_m102815_c001_v0001001_t0020") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150ff7_d20200724_m102814_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150ff3_d20200724_m102813_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f116c08e0cb4215b3_d20200724_m102808_c001_v0001092_t0034") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150fec_d20200724_m102805_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f106eb2190f495682_d20200724_m102803_c001_v0001130_t0048") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f110cf617b1158508_d20200724_m102750_c001_v0001041_t0046") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150fcf_d20200724_m102749_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f101052749ff36672_d20200724_m102748_c001_v0001137_t0048") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150fcd_d20200724_m102747_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10223856cfb1ea58_d20200724_m102746_c001_v0001136_t0036") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150fc1_d20200724_m102738_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f113f4980c67a9aa5_d20200724_m102738_c001_v0001113_t0049") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1090525c84fc7d12_d20200724_m102737_c001_v0001093_t0023") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150fbf_d20200724_m102736_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10771969f376a5fd_d20200724_m102735_c001_v0001023_t0023") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150fbb_d20200724_m102733_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150fb9_d20200724_m102731_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f108b18eee005b02a_d20200724_m102730_c001_v0001128_t0026") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150fb0_d20200724_m102722_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f114e5b35075a3b92_d20200724_m102722_c001_v0001134_t0038") 2020/07/24 10:30:17 DEBUG : dir/file2: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10542644d9b874e1_d20200724_m102930_c001_v0001037_t0047") 2020/07/24 10:30:17 DEBUG : dir/file2: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151099_d20200724_m102928_c001_v0001037_t0019") 2020/07/24 10:30:17 DEBUG : dir/file2: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f105df6ccced1da4b_d20200724_m102927_c001_v0001090_t0017") 2020/07/24 10:30:18 DEBUG : dir/file2: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad15108f_d20200724_m102926_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : dir/file2: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f114f113baff6fa69_d20200724_m102923_c001_v0001044_t0019") 2020/07/24 10:30:18 DEBUG : dir/file2: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151070_d20200724_m102915_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : dir/file2: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f117b48a9efcab70c_d20200724_m102911_c001_v0001136_t0031") 2020/07/24 10:30:18 DEBUG : dir/file2: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151069_d20200724_m102910_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : dir/new_file.txt: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f110321146c8797a2_d20200724_m102927_c001_v0001038_t0020") 2020/07/24 10:30:18 DEBUG : dir/new_file.txt: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151093_d20200724_m102926_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : file0: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10989ceeff2c3e3e_d20200724_m102932_c001_v0001136_t0023") 2020/07/24 10:30:18 DEBUG : file0: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f113883dffa139ee8_d20200724_m102931_c001_v0001130_t0020") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1170a56f1ed936d3_d20200724_m103015_c001_v0001018_t0016") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad1510f8_d20200724_m103014_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f11249d35734eda84_d20200724_m103014_c001_v0001128_t0053") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad1510f4_d20200724_m103013_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f106eb2190f49582a_d20200724_m103012_c001_v0001130_t0034") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad1510d4_d20200724_m102952_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10979c30f221c559_d20200724_m102952_c001_v0001120_t0057") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f111b8ad805f4b438_d20200724_m102951_c001_v0001137_t0048") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad1510a7_d20200724_m102933_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f103450f34dfe0543_d20200724_m102933_c001_v0001134_t0035") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad15109f_d20200724_m102932_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad1510a3_d20200724_m102932_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f11803c81445d072b_d20200724_m102927_c001_v0001134_t0035") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad15108d_d20200724_m102925_c001_v0001037_t0019") 2020/07/24 10:30:18 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1179c2a3639d4801_d20200724_m102912_c001_v0001029_t0023") 2020/07/24 10:30:19 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad15106d_d20200724_m102912_c001_v0001037_t0019") 2020/07/24 10:30:19 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151067_d20200724_m102910_c001_v0001037_t0019") 2020/07/24 10:30:19 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f11210573ca88339a_d20200724_m102833_c001_v0001037_t0021") 2020/07/24 10:30:19 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1116792af2a5a84b_d20200724_m102833_c001_v0001136_t0049") 2020/07/24 10:30:19 DEBUG : file1: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad151025_d20200724_m102832_c001_v0001037_t0019") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f11403c970f17fbb3_d20200724_m102818_c001_v0001030_t0019") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad150ffd_d20200724_m102818_c001_v0001037_t0019") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1185541eec3fb311_d20200724_m102817_c001_v0001026_t0035") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10572cba0f01eaf4_d20200724_m102816_c001_v0001134_t0006") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f114e9373019918b3_d20200724_m102815_c001_v0001137_t0030") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1099fcbbaa23984f_d20200724_m102812_c001_v0001026_t0005") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f10023c8007fd2d0a_d20200724_m102807_c001_v0001038_t0014") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f104b7b9d793b3e21_d20200724_m102803_c001_v0001113_t0035") 2020/07/24 10:30:19 DEBUG : newLeaf: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f112d2c48a98dc07f_d20200724_m102750_c001_v0001134_t0058") 2020/07/24 10:30:19 DEBUG : time_test: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f114d9b048bb88784_d20200724_m102832_c001_v0001093_t0034") 2020/07/24 10:30:19 DEBUG : time_test: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1153ec0fad15101d_d20200724_m102831_c001_v0001037_t0019") 2020/07/24 10:30:19 DEBUG : time_test: Deleting (id "4_zffa2edf350cd8b0b7f380e1b_f1066534e47221627_d20200724_m102831_c001_v0001134_t0020") "./vfs.test -test.v -test.timeout 1h0m0s -remote TestB2: -verbose -test.run '^(TestCaseSensitivity|TestDirRemoveName|TestFileOpen|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRemove|TestFileRemoveAll|TestFileRename|TestRWFileHandleSizeTruncateExisting|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestVFSNew|TestVFSOpenFile|TestVFSRename|TestVFSStat|TestVFSStatParent|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(off,forceCache=false|writes,forceCache=true)$'" - Finished ERROR in 3m0.546425971s (try 2/5): exit status 1: Failed [TestDirRemoveName TestFileRemoveAll TestRWFileModTimeWithOpenWriters TestVFSStatParent TestWriteFileHandleMethods TestWriteFileHandleWriteAt TestWriteFileHandleFlush TestWriteFileModTimeWithOpenWriters]