"./vfs.test -test.v -test.timeout 1h0m0s -remote TestZoho: -verbose -test.run '^(TestCaseSensitivity|TestDirCreate|TestDirForgetAll|TestDirForgetPath|TestDirHandleMethods|TestDirHandleReaddir|TestDirHandleReaddirnames|TestDirMethods|TestDirMkdir|TestDirMkdirSub|TestDirOpen|TestDirReadDirAll|TestDirRemove|TestDirRemoveAll|TestDirRemoveName|TestDirRename|TestDirSetModTime|TestDirStat|TestDirWalk|TestFileMethods|TestFileOpen|TestFileOpenRead|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRemove|TestFileRemoveAll|TestFileRename|TestFileSetModTime|TestRWFileHandleFlushRead|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestVFSNew|TestVFSOpenFile|TestVFSRename|TestVFSStat|TestVFSStatParent|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(cache=full,open=false,write=false|cache=full,open=true,write=false|cache=full,open=true,write=true|cache=off,open=false,write=false|cache=off,open=true,write=false|cache=off,open=true,write=true|full,forceCache=false|minimal,forceCache=false|minimal,forceCache=true|off,forceCache=false|writes,forceCache=false|writes,forceCache=true)$'" - Starting (try 5/5) 2021/12/13 06:33:08 DEBUG : Creating backend with remote "TestZoho:rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:08 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/12/13 06:33:09 DEBUG : Creating backend with remote "/tmp/rclone2290915572" === RUN TestDirHandleMethods run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:09 INFO : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': poll-interval is not supported by this remote 2021/12/13 06:33:09 NOTICE: zoho root 'rclone-test-tabiruy0sigitob6joyomug2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirHandleMethods (1.57s) === RUN TestDirHandleReaddir run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:10 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:11 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:33:11 DEBUG : : Looking for writers 2021/12/13 06:33:11 DEBUG : >WaitForWriters: --- FAIL: TestDirHandleReaddir (1.43s) === RUN TestDirHandleReaddirnames run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:12 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirHandleReaddirnames (0.71s) === RUN TestDirMethods run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:12 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirMethods (0.29s) === RUN TestDirForgetAll run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:13 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirForgetAll (0.27s) === RUN TestDirForgetPath run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:13 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirForgetPath (0.29s) === RUN TestDirWalk run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:13 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirWalk (0.27s) === RUN TestDirSetModTime run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:14 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirSetModTime (0.29s) === RUN TestDirStat run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:14 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirStat (0.27s) === RUN TestDirReadDirAll run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:14 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:14 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:33:14 DEBUG : : Looking for writers 2021/12/13 06:33:14 DEBUG : >WaitForWriters: --- FAIL: TestDirReadDirAll (1.40s) === RUN TestDirOpen run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:16 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirOpen (0.73s) === RUN TestDirCreate run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:16 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirCreate (0.29s) === RUN TestDirMkdir run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:17 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirMkdir (0.28s) === RUN TestDirMkdirSub run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:17 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirMkdirSub (0.29s) === RUN TestDirRemove run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:17 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirRemove (0.28s) === RUN TestDirRemoveAll run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:17 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirRemoveAll (0.29s) === RUN TestDirRemoveName run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:18 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirRemoveName (0.27s) === RUN TestDirRename run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:18 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestDirRename (0.29s) === RUN TestFileMethods run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:18 INFO : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': poll-interval is not supported by this remote 2021/12/13 06:33:18 NOTICE: zoho root 'rclone-test-tabiruy0sigitob6joyomug2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestFileMethods (0.27s) === RUN TestFileSetModTime === RUN TestFileSetModTime/cache=off,open=false,write=false run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:19 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileSetModTime/cache=off,open=true,write=false run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:19 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileSetModTime/cache=off,open=true,write=true run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:19 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileSetModTime/cache=full,open=false,write=false run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:19 INFO : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': poll-interval is not supported by this remote 2021/12/13 06:33:19 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2021/12/13 06:33:19 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestZoho/rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:19 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:19 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestZoho/rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:19 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:19 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileSetModTime/cache=full,open=true,write=false run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:20 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileSetModTime/cache=full,open=true,write=true run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:20 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestFileSetModTime (1.72s) --- FAIL: TestFileSetModTime/cache=off,open=false,write=false (0.28s) --- FAIL: TestFileSetModTime/cache=off,open=true,write=false (0.28s) --- FAIL: TestFileSetModTime/cache=off,open=true,write=true (0.28s) --- FAIL: TestFileSetModTime/cache=full,open=false,write=false (0.31s) --- FAIL: TestFileSetModTime/cache=full,open=true,write=false (0.29s) --- FAIL: TestFileSetModTime/cache=full,open=true,write=true (0.28s) === RUN TestFileOpenRead run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:20 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestFileOpenRead (0.29s) === RUN TestFileOpenWrite run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:21 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestFileOpenWrite (0.27s) === RUN TestFileRemove run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:21 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestFileRemove (0.29s) === RUN TestFileRemoveAll run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:21 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestFileRemoveAll (0.27s) === RUN TestFileOpen run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:21 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestFileOpen (0.29s) === RUN TestFileRename === RUN TestFileRename/off,forceCache=false run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:22 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileRename/minimal,forceCache=false run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:22 INFO : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': poll-interval is not supported by this remote 2021/12/13 06:33:22 NOTICE: zoho root 'rclone-test-tabiruy0sigitob6joyomug2': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/12/13 06:33:22 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2021/12/13 06:33:22 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestZoho/rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:22 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:22 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileRename/minimal,forceCache=true run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:22 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileRename/writes,forceCache=false run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:23 INFO : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': poll-interval is not supported by this remote 2021/12/13 06:33:23 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2021/12/13 06:33:23 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestZoho/rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:23 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tabiruy0sigitob6joyomug2" 2021/12/13 06:33:23 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileRename/writes,forceCache=true run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:23 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" === RUN TestFileRename/full,forceCache=false run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:23 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestFileRename (1.71s) --- FAIL: TestFileRename/off,forceCache=false (0.28s) --- FAIL: TestFileRename/minimal,forceCache=false (0.29s) --- FAIL: TestFileRename/minimal,forceCache=true (0.28s) --- FAIL: TestFileRename/writes,forceCache=false (0.28s) --- FAIL: TestFileRename/writes,forceCache=true (0.27s) --- FAIL: TestFileRename/full,forceCache=false (0.29s) === RUN TestRcGetVFS rc_test.go:29: Error Trace: rc_test.go:29 Error: "more than one VFS active - need \"fs\" parameter" does not contain "no VFS active" Test: TestRcGetVFS run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:23 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache rc_test.go:36: Error Trace: rc_test.go:36 Error: Received unexpected error: more than one VFS active - need "fs" parameter Test: TestRcGetVFS 2021/12/13 06:33:23 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:33:23 DEBUG : : Looking for writers 2021/12/13 06:33:23 DEBUG : >WaitForWriters: --- FAIL: TestRcGetVFS (1.08s) === RUN TestReadFileHandleMethods run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:24 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestReadFileHandleMethods (0.68s) === RUN TestReadFileHandleSeek run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:25 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestReadFileHandleSeek (0.28s) === RUN TestReadFileHandleReadAt run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:25 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestReadFileHandleReadAt (0.28s) === RUN TestReadFileHandleFlush run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:26 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestReadFileHandleFlush (0.29s) === RUN TestReadFileHandleRelease run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:26 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestReadFileHandleRelease (0.29s) === RUN TestRWFileHandleMethodsRead run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:26 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestRWFileHandleMethodsRead (0.28s) === RUN TestRWFileHandleSeek run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:27 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestRWFileHandleSeek (0.28s) === RUN TestRWFileHandleReadAt run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:27 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestRWFileHandleReadAt (0.29s) === RUN TestRWFileHandleFlushRead run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:27 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestRWFileHandleFlushRead (0.28s) === RUN TestRWFileHandleReleaseRead run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:27 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestRWFileHandleReleaseRead (0.30s) === RUN TestRWFileHandleMethodsWrite run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:33:28 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:33:28 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:33:28 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:33:28 DEBUG : file1: newRWFileHandle: 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): openPending: 2021/12/13 06:33:28 DEBUG : file1: vfs cache: truncate to size=0 2021/12/13 06:33:28 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): >openPending: err= 2021/12/13 06:33:28 DEBUG : file1: >newRWFileHandle: err= 2021/12/13 06:33:28 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:33:28 DEBUG : file1: >Open: fd=file1 (rw), err= 2021/12/13 06:33:28 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): _writeAt: size=5, off=0 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): >_writeAt: n=5, err= 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): _writeAt: size=7, off=5 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): >_writeAt: n=7, err= 2021/12/13 06:33:28 DEBUG : file1: vfs cache: truncate to size=11 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): close: 2021/12/13 06:33:28 DEBUG : file1: vfs cache: setting modification time to 2021-12-13 06:33:28.533688837 +0000 UTC m=+20.273799896 2021/12/13 06:33:28 INFO : file1: vfs cache: queuing for upload in 100ms 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): >close: err= 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): close: 2021/12/13 06:33:28 DEBUG : file1(0xc00014b3c0): >close: err=file already closed dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:339 Error: Not equal: expected: []string{"file1,11,false"} actual : []string{"dir,0,true", "file1,11,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=14) "file1,11,false" Test: TestRWFileHandleMethodsWrite 2021/12/13 06:33:28 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:33:28 DEBUG : dir: Looking for writers 2021/12/13 06:33:28 DEBUG : : Looking for writers 2021/12/13 06:33:28 DEBUG : dir: reading active writers 2021/12/13 06:33:28 DEBUG : file1: reading active writers 2021/12/13 06:33:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/12/13 06:33:28 DEBUG : dir: Looking for writers 2021/12/13 06:33:28 DEBUG : : Looking for writers 2021/12/13 06:33:28 DEBUG : dir: reading active writers 2021/12/13 06:33:28 DEBUG : file1: reading active writers 2021/12/13 06:33:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/12/13 06:33:28 DEBUG : dir: Looking for writers 2021/12/13 06:33:28 DEBUG : : Looking for writers 2021/12/13 06:33:28 DEBUG : dir: reading active writers 2021/12/13 06:33:28 DEBUG : file1: reading active writers 2021/12/13 06:33:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/12/13 06:33:28 DEBUG : dir: Looking for writers 2021/12/13 06:33:28 DEBUG : : Looking for writers 2021/12/13 06:33:28 DEBUG : dir: reading active writers 2021/12/13 06:33:28 DEBUG : file1: reading active writers 2021/12/13 06:33:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/12/13 06:33:28 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:33:28 DEBUG : dir: Looking for writers 2021/12/13 06:33:28 DEBUG : : Looking for writers 2021/12/13 06:33:28 DEBUG : dir: reading active writers 2021/12/13 06:33:28 DEBUG : file1: reading active writers 2021/12/13 06:33:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/12/13 06:33:28 DEBUG : dir: Looking for writers 2021/12/13 06:33:28 DEBUG : : Looking for writers 2021/12/13 06:33:28 DEBUG : file1: reading active writers 2021/12/13 06:33:28 DEBUG : dir: reading active writers 2021/12/13 06:33:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/12/13 06:33:29 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:29 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:29 DEBUG : dir: Looking for writers 2021/12/13 06:33:29 DEBUG : : Looking for writers 2021/12/13 06:33:29 DEBUG : dir: reading active writers 2021/12/13 06:33:29 DEBUG : file1: reading active writers 2021/12/13 06:33:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/12/13 06:33:29 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:33:29 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:29 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:29 DEBUG : dir: Looking for writers 2021/12/13 06:33:29 DEBUG : : Looking for writers 2021/12/13 06:33:29 DEBUG : dir: reading active writers 2021/12/13 06:33:29 DEBUG : file1: reading active writers 2021/12/13 06:33:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:30 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:33:30 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:30 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:30 DEBUG : dir: Looking for writers 2021/12/13 06:33:30 DEBUG : : Looking for writers 2021/12/13 06:33:30 DEBUG : dir: reading active writers 2021/12/13 06:33:30 DEBUG : file1: reading active writers 2021/12/13 06:33:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:31 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:33:31 DEBUG : dir: Looking for writers 2021/12/13 06:33:31 DEBUG : : Looking for writers 2021/12/13 06:33:31 DEBUG : file1: reading active writers 2021/12/13 06:33:31 DEBUG : dir: reading active writers 2021/12/13 06:33:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:31 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:31 ERROR : file1: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:32 DEBUG : dir: Looking for writers 2021/12/13 06:33:32 DEBUG : : Looking for writers 2021/12/13 06:33:32 DEBUG : dir: reading active writers 2021/12/13 06:33:32 DEBUG : file1: reading active writers 2021/12/13 06:33:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:33 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:33:33 DEBUG : dir: Looking for writers 2021/12/13 06:33:33 DEBUG : : Looking for writers 2021/12/13 06:33:33 DEBUG : dir: reading active writers 2021/12/13 06:33:33 DEBUG : file1: reading active writers 2021/12/13 06:33:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:33 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:33 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:34 DEBUG : dir: Looking for writers 2021/12/13 06:33:34 DEBUG : : Looking for writers 2021/12/13 06:33:34 DEBUG : dir: reading active writers 2021/12/13 06:33:34 DEBUG : file1: reading active writers 2021/12/13 06:33:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:35 DEBUG : dir: Looking for writers 2021/12/13 06:33:35 DEBUG : : Looking for writers 2021/12/13 06:33:35 DEBUG : dir: reading active writers 2021/12/13 06:33:35 DEBUG : file1: reading active writers 2021/12/13 06:33:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:36 DEBUG : dir: Looking for writers 2021/12/13 06:33:36 DEBUG : : Looking for writers 2021/12/13 06:33:36 DEBUG : dir: reading active writers 2021/12/13 06:33:36 DEBUG : file1: reading active writers 2021/12/13 06:33:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:37 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:33:37 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:37 ERROR : file1: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:37 DEBUG : dir: Looking for writers 2021/12/13 06:33:37 DEBUG : : Looking for writers 2021/12/13 06:33:37 DEBUG : dir: reading active writers 2021/12/13 06:33:37 DEBUG : file1: reading active writers 2021/12/13 06:33:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:38 DEBUG : dir: Looking for writers 2021/12/13 06:33:38 DEBUG : : Looking for writers 2021/12/13 06:33:38 DEBUG : dir: reading active writers 2021/12/13 06:33:38 DEBUG : file1: reading active writers 2021/12/13 06:33:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:39 DEBUG : dir: Looking for writers 2021/12/13 06:33:39 DEBUG : : Looking for writers 2021/12/13 06:33:39 DEBUG : dir: reading active writers 2021/12/13 06:33:39 DEBUG : file1: reading active writers 2021/12/13 06:33:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:40 DEBUG : dir: Looking for writers 2021/12/13 06:33:40 DEBUG : : Looking for writers 2021/12/13 06:33:40 DEBUG : dir: reading active writers 2021/12/13 06:33:40 DEBUG : file1: reading active writers 2021/12/13 06:33:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:41 DEBUG : dir: Looking for writers 2021/12/13 06:33:41 DEBUG : : Looking for writers 2021/12/13 06:33:41 DEBUG : dir: reading active writers 2021/12/13 06:33:41 DEBUG : file1: reading active writers 2021/12/13 06:33:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:42 DEBUG : dir: Looking for writers 2021/12/13 06:33:42 DEBUG : : Looking for writers 2021/12/13 06:33:42 DEBUG : dir: reading active writers 2021/12/13 06:33:42 DEBUG : file1: reading active writers 2021/12/13 06:33:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:43 DEBUG : dir: Looking for writers 2021/12/13 06:33:43 DEBUG : : Looking for writers 2021/12/13 06:33:43 DEBUG : file1: reading active writers 2021/12/13 06:33:43 DEBUG : dir: reading active writers 2021/12/13 06:33:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:43 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:33:44 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:44 ERROR : file1: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:44 DEBUG : dir: Looking for writers 2021/12/13 06:33:44 DEBUG : : Looking for writers 2021/12/13 06:33:44 DEBUG : file1: reading active writers 2021/12/13 06:33:44 DEBUG : dir: reading active writers 2021/12/13 06:33:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:45 DEBUG : dir: Looking for writers 2021/12/13 06:33:45 DEBUG : : Looking for writers 2021/12/13 06:33:45 DEBUG : dir: reading active writers 2021/12/13 06:33:45 DEBUG : file1: reading active writers 2021/12/13 06:33:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:46 DEBUG : dir: Looking for writers 2021/12/13 06:33:46 DEBUG : : Looking for writers 2021/12/13 06:33:46 DEBUG : dir: reading active writers 2021/12/13 06:33:46 DEBUG : file1: reading active writers 2021/12/13 06:33:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:47 DEBUG : dir: Looking for writers 2021/12/13 06:33:47 DEBUG : : Looking for writers 2021/12/13 06:33:47 DEBUG : dir: reading active writers 2021/12/13 06:33:47 DEBUG : file1: reading active writers 2021/12/13 06:33:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:48 DEBUG : dir: Looking for writers 2021/12/13 06:33:48 DEBUG : : Looking for writers 2021/12/13 06:33:48 DEBUG : dir: reading active writers 2021/12/13 06:33:48 DEBUG : file1: reading active writers 2021/12/13 06:33:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:49 DEBUG : dir: Looking for writers 2021/12/13 06:33:49 DEBUG : : Looking for writers 2021/12/13 06:33:49 DEBUG : dir: reading active writers 2021/12/13 06:33:49 DEBUG : file1: reading active writers 2021/12/13 06:33:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:50 DEBUG : dir: Looking for writers 2021/12/13 06:33:50 DEBUG : : Looking for writers 2021/12/13 06:33:50 DEBUG : dir: reading active writers 2021/12/13 06:33:50 DEBUG : file1: reading active writers 2021/12/13 06:33:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:51 DEBUG : dir: Looking for writers 2021/12/13 06:33:51 DEBUG : : Looking for writers 2021/12/13 06:33:51 DEBUG : dir: reading active writers 2021/12/13 06:33:51 DEBUG : file1: reading active writers 2021/12/13 06:33:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:52 DEBUG : dir: Looking for writers 2021/12/13 06:33:52 DEBUG : : Looking for writers 2021/12/13 06:33:52 DEBUG : dir: reading active writers 2021/12/13 06:33:52 DEBUG : file1: reading active writers 2021/12/13 06:33:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:53 DEBUG : dir: Looking for writers 2021/12/13 06:33:53 DEBUG : : Looking for writers 2021/12/13 06:33:53 DEBUG : dir: reading active writers 2021/12/13 06:33:53 DEBUG : file1: reading active writers 2021/12/13 06:33:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:54 DEBUG : dir: Looking for writers 2021/12/13 06:33:54 DEBUG : : Looking for writers 2021/12/13 06:33:54 DEBUG : dir: reading active writers 2021/12/13 06:33:54 DEBUG : file1: reading active writers 2021/12/13 06:33:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:55 DEBUG : dir: Looking for writers 2021/12/13 06:33:55 DEBUG : : Looking for writers 2021/12/13 06:33:55 DEBUG : dir: reading active writers 2021/12/13 06:33:55 DEBUG : file1: reading active writers 2021/12/13 06:33:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:56 DEBUG : dir: Looking for writers 2021/12/13 06:33:56 DEBUG : : Looking for writers 2021/12/13 06:33:56 DEBUG : dir: reading active writers 2021/12/13 06:33:56 DEBUG : file1: reading active writers 2021/12/13 06:33:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:57 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:33:57 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:57 ERROR : file1: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:33:57 DEBUG : dir: Looking for writers 2021/12/13 06:33:57 DEBUG : : Looking for writers 2021/12/13 06:33:57 DEBUG : dir: reading active writers 2021/12/13 06:33:57 DEBUG : file1: reading active writers 2021/12/13 06:33:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:33:58 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc00014b380 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724720543724037 ext:20273799896 loc:0x2a04b60} ATime:{wall:13863724720543738033 ext:20273813902 loc:0x2a04b60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/12/13 06:33:58 DEBUG : >WaitForWriters: fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 read_write_test.go:344 Error: Should be true Test: TestRWFileHandleMethodsWrite Messages: listing wrong, want file1 (11) got fstest.go:204: Not found "file1" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 read_write_test.go:344 Error: Not equal: expected: 0 actual : 1 Test: TestRWFileHandleMethodsWrite Messages: 1 objects not found fstest.go:328: Error Trace: fstest.go:328 fstest.go:339 read_write_test.go:344 Error: Not equal: expected: []string{} actual : []string{"dir"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) { +([]string) (len=1) { + (string) (len=3) "dir" } Test: TestRWFileHandleMethodsWrite Messages: directories 2021/12/13 06:34:07 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:34:07 DEBUG : dir: Looking for writers 2021/12/13 06:34:07 DEBUG : : Looking for writers 2021/12/13 06:34:07 DEBUG : dir: reading active writers 2021/12/13 06:34:07 DEBUG : file1: reading active writers 2021/12/13 06:34:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/12/13 06:34:07 DEBUG : dir: Looking for writers 2021/12/13 06:34:07 DEBUG : : Looking for writers 2021/12/13 06:34:07 DEBUG : dir: reading active writers 2021/12/13 06:34:07 DEBUG : file1: reading active writers 2021/12/13 06:34:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/12/13 06:34:07 DEBUG : dir: Looking for writers 2021/12/13 06:34:07 DEBUG : : Looking for writers 2021/12/13 06:34:07 DEBUG : dir: reading active writers 2021/12/13 06:34:07 DEBUG : file1: reading active writers 2021/12/13 06:34:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/12/13 06:34:07 DEBUG : dir: Looking for writers 2021/12/13 06:34:07 DEBUG : : Looking for writers 2021/12/13 06:34:07 DEBUG : dir: reading active writers 2021/12/13 06:34:07 DEBUG : file1: reading active writers 2021/12/13 06:34:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/12/13 06:34:07 DEBUG : dir: Looking for writers 2021/12/13 06:34:07 DEBUG : : Looking for writers 2021/12/13 06:34:07 DEBUG : dir: reading active writers 2021/12/13 06:34:07 DEBUG : file1: reading active writers 2021/12/13 06:34:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/12/13 06:34:07 DEBUG : dir: Looking for writers 2021/12/13 06:34:07 DEBUG : : Looking for writers 2021/12/13 06:34:07 DEBUG : dir: reading active writers 2021/12/13 06:34:07 DEBUG : file1: reading active writers 2021/12/13 06:34:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/12/13 06:34:08 DEBUG : dir: Looking for writers 2021/12/13 06:34:08 DEBUG : : Looking for writers 2021/12/13 06:34:08 DEBUG : dir: reading active writers 2021/12/13 06:34:08 DEBUG : file1: reading active writers 2021/12/13 06:34:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/12/13 06:34:08 DEBUG : dir: Looking for writers 2021/12/13 06:34:08 DEBUG : : Looking for writers 2021/12/13 06:34:08 DEBUG : dir: reading active writers 2021/12/13 06:34:08 DEBUG : file1: reading active writers 2021/12/13 06:34:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:09 DEBUG : dir: Looking for writers 2021/12/13 06:34:09 DEBUG : : Looking for writers 2021/12/13 06:34:09 DEBUG : dir: reading active writers 2021/12/13 06:34:09 DEBUG : file1: reading active writers 2021/12/13 06:34:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:10 DEBUG : dir: Looking for writers 2021/12/13 06:34:10 DEBUG : : Looking for writers 2021/12/13 06:34:10 DEBUG : dir: reading active writers 2021/12/13 06:34:10 DEBUG : file1: reading active writers 2021/12/13 06:34:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:11 DEBUG : dir: Looking for writers 2021/12/13 06:34:11 DEBUG : : Looking for writers 2021/12/13 06:34:11 DEBUG : dir: reading active writers 2021/12/13 06:34:11 DEBUG : file1: reading active writers 2021/12/13 06:34:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:12 DEBUG : dir: Looking for writers 2021/12/13 06:34:12 DEBUG : : Looking for writers 2021/12/13 06:34:12 DEBUG : dir: reading active writers 2021/12/13 06:34:12 DEBUG : file1: reading active writers 2021/12/13 06:34:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:13 DEBUG : dir: Looking for writers 2021/12/13 06:34:13 DEBUG : : Looking for writers 2021/12/13 06:34:13 DEBUG : dir: reading active writers 2021/12/13 06:34:13 DEBUG : file1: reading active writers 2021/12/13 06:34:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:14 DEBUG : dir: Looking for writers 2021/12/13 06:34:14 DEBUG : : Looking for writers 2021/12/13 06:34:14 DEBUG : dir: reading active writers 2021/12/13 06:34:14 DEBUG : file1: reading active writers 2021/12/13 06:34:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:15 DEBUG : dir: Looking for writers 2021/12/13 06:34:15 DEBUG : : Looking for writers 2021/12/13 06:34:15 DEBUG : dir: reading active writers 2021/12/13 06:34:15 DEBUG : file1: reading active writers 2021/12/13 06:34:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:16 DEBUG : dir: Looking for writers 2021/12/13 06:34:16 DEBUG : : Looking for writers 2021/12/13 06:34:16 DEBUG : file1: reading active writers 2021/12/13 06:34:16 DEBUG : dir: reading active writers 2021/12/13 06:34:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:17 DEBUG : dir: Looking for writers 2021/12/13 06:34:17 DEBUG : : Looking for writers 2021/12/13 06:34:17 DEBUG : dir: reading active writers 2021/12/13 06:34:17 DEBUG : file1: reading active writers 2021/12/13 06:34:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:18 DEBUG : dir: Looking for writers 2021/12/13 06:34:18 DEBUG : : Looking for writers 2021/12/13 06:34:18 DEBUG : dir: reading active writers 2021/12/13 06:34:18 DEBUG : file1: reading active writers 2021/12/13 06:34:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:19 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2021/12/13 06:34:19 INFO : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 11 (was 11) 2021/12/13 06:34:19 DEBUG : dir: Looking for writers 2021/12/13 06:34:19 DEBUG : : Looking for writers 2021/12/13 06:34:19 DEBUG : dir: reading active writers 2021/12/13 06:34:19 DEBUG : file1: reading active writers 2021/12/13 06:34:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:20 DEBUG : dir: Looking for writers 2021/12/13 06:34:20 DEBUG : : Looking for writers 2021/12/13 06:34:20 DEBUG : dir: reading active writers 2021/12/13 06:34:20 DEBUG : file1: reading active writers 2021/12/13 06:34:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:21 DEBUG : dir: Looking for writers 2021/12/13 06:34:21 DEBUG : : Looking for writers 2021/12/13 06:34:21 DEBUG : dir: reading active writers 2021/12/13 06:34:21 DEBUG : file1: reading active writers 2021/12/13 06:34:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:22 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/12/13 06:34:22 DEBUG : dir: Looking for writers 2021/12/13 06:34:22 DEBUG : : Looking for writers 2021/12/13 06:34:22 DEBUG : dir: reading active writers 2021/12/13 06:34:22 DEBUG : file1: reading active writers 2021/12/13 06:34:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:23 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/12/13 06:34:23 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:34:23 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:23 ERROR : file1: vfs cache: failed to upload try #9, will retry in 51.2s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:23 DEBUG : dir: Looking for writers 2021/12/13 06:34:23 DEBUG : : Looking for writers 2021/12/13 06:34:23 DEBUG : dir: reading active writers 2021/12/13 06:34:23 DEBUG : file1: reading active writers 2021/12/13 06:34:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:24 DEBUG : dir: Looking for writers 2021/12/13 06:34:24 DEBUG : : Looking for writers 2021/12/13 06:34:24 DEBUG : dir: reading active writers 2021/12/13 06:34:24 DEBUG : file1: reading active writers 2021/12/13 06:34:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:25 DEBUG : dir: Looking for writers 2021/12/13 06:34:25 DEBUG : : Looking for writers 2021/12/13 06:34:25 DEBUG : dir: reading active writers 2021/12/13 06:34:25 DEBUG : file1: reading active writers 2021/12/13 06:34:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:26 DEBUG : dir: Looking for writers 2021/12/13 06:34:26 DEBUG : : Looking for writers 2021/12/13 06:34:26 DEBUG : dir: reading active writers 2021/12/13 06:34:26 DEBUG : file1: reading active writers 2021/12/13 06:34:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:27 DEBUG : dir: Looking for writers 2021/12/13 06:34:27 DEBUG : : Looking for writers 2021/12/13 06:34:27 DEBUG : dir: reading active writers 2021/12/13 06:34:27 DEBUG : file1: reading active writers 2021/12/13 06:34:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:28 DEBUG : dir: Looking for writers 2021/12/13 06:34:28 DEBUG : : Looking for writers 2021/12/13 06:34:28 DEBUG : dir: reading active writers 2021/12/13 06:34:28 DEBUG : file1: reading active writers 2021/12/13 06:34:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:29 DEBUG : dir: Looking for writers 2021/12/13 06:34:29 DEBUG : : Looking for writers 2021/12/13 06:34:29 DEBUG : dir: reading active writers 2021/12/13 06:34:29 DEBUG : file1: reading active writers 2021/12/13 06:34:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:30 DEBUG : dir: Looking for writers 2021/12/13 06:34:30 DEBUG : : Looking for writers 2021/12/13 06:34:30 DEBUG : dir: reading active writers 2021/12/13 06:34:30 DEBUG : file1: reading active writers 2021/12/13 06:34:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:31 DEBUG : dir: Looking for writers 2021/12/13 06:34:31 DEBUG : : Looking for writers 2021/12/13 06:34:31 DEBUG : dir: reading active writers 2021/12/13 06:34:31 DEBUG : file1: reading active writers 2021/12/13 06:34:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:32 DEBUG : dir: Looking for writers 2021/12/13 06:34:32 DEBUG : : Looking for writers 2021/12/13 06:34:32 DEBUG : dir: reading active writers 2021/12/13 06:34:32 DEBUG : file1: reading active writers 2021/12/13 06:34:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:33 DEBUG : dir: Looking for writers 2021/12/13 06:34:33 DEBUG : : Looking for writers 2021/12/13 06:34:33 DEBUG : dir: reading active writers 2021/12/13 06:34:33 DEBUG : file1: reading active writers 2021/12/13 06:34:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:34 DEBUG : dir: Looking for writers 2021/12/13 06:34:34 DEBUG : : Looking for writers 2021/12/13 06:34:34 DEBUG : dir: reading active writers 2021/12/13 06:34:34 DEBUG : file1: reading active writers 2021/12/13 06:34:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:35 DEBUG : dir: Looking for writers 2021/12/13 06:34:35 DEBUG : : Looking for writers 2021/12/13 06:34:35 DEBUG : dir: reading active writers 2021/12/13 06:34:35 DEBUG : file1: reading active writers 2021/12/13 06:34:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:36 DEBUG : dir: Looking for writers 2021/12/13 06:34:36 DEBUG : : Looking for writers 2021/12/13 06:34:36 DEBUG : dir: reading active writers 2021/12/13 06:34:36 DEBUG : file1: reading active writers 2021/12/13 06:34:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:37 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc00014b380 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724720543724037 ext:20273799896 loc:0x2a04b60} ATime:{wall:13863724720543738033 ext:20273813902 loc:0x2a04b60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/12/13 06:34:37 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleMethodsWrite (70.55s) === RUN TestRWFileHandleWriteAt run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:34:38 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:34:38 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:34:38 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:34:38 DEBUG : file1: newRWFileHandle: 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): openPending: 2021/12/13 06:34:38 ERROR : file1: vfs cache: detected external removal of cache file 2021/12/13 06:34:38 DEBUG : file1: vfs cache: truncate to size=0 2021/12/13 06:34:38 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): >openPending: err= 2021/12/13 06:34:38 DEBUG : file1: vfs cache: cancelling writeback (uploading false) 0xc00043e2a0 item 1 2021/12/13 06:34:38 DEBUG : file1: >newRWFileHandle: err= 2021/12/13 06:34:38 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:34:38 DEBUG : file1: >Open: fd=file1 (rw), err= 2021/12/13 06:34:38 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): _writeAt: size=7, off=0 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): >_writeAt: n=7, err= 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): _writeAt: size=6, off=5 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): >_writeAt: n=6, err= 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): close: 2021/12/13 06:34:38 DEBUG : file1: vfs cache: setting modification time to 2021-12-13 06:34:38.768678461 +0000 UTC m=+90.508789540 2021/12/13 06:34:38 INFO : file1: vfs cache: queuing for upload in 100ms 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): >close: err= 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): _writeAt: size=5, off=0 2021/12/13 06:34:38 DEBUG : file1(0xc000b0a000): >_writeAt: n=0, err=file already closed dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:387 Error: Not equal: expected: []string{"file1,11,false"} actual : []string{"dir,0,true", "file1,11,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=1) { +([]string) (len=2) { + (string) (len=10) "dir,0,true", (string) (len=14) "file1,11,false" Test: TestRWFileHandleWriteAt 2021/12/13 06:34:38 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:34:38 DEBUG : dir: Looking for writers 2021/12/13 06:34:38 DEBUG : : Looking for writers 2021/12/13 06:34:38 DEBUG : file1: reading active writers 2021/12/13 06:34:38 DEBUG : dir: reading active writers 2021/12/13 06:34:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/12/13 06:34:38 DEBUG : dir: Looking for writers 2021/12/13 06:34:38 DEBUG : : Looking for writers 2021/12/13 06:34:38 DEBUG : dir: reading active writers 2021/12/13 06:34:38 DEBUG : file1: reading active writers 2021/12/13 06:34:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/12/13 06:34:38 DEBUG : dir: Looking for writers 2021/12/13 06:34:38 DEBUG : : Looking for writers 2021/12/13 06:34:38 DEBUG : dir: reading active writers 2021/12/13 06:34:38 DEBUG : file1: reading active writers 2021/12/13 06:34:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/12/13 06:34:38 DEBUG : dir: Looking for writers 2021/12/13 06:34:38 DEBUG : : Looking for writers 2021/12/13 06:34:38 DEBUG : dir: reading active writers 2021/12/13 06:34:38 DEBUG : file1: reading active writers 2021/12/13 06:34:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/12/13 06:34:38 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:34:38 DEBUG : dir: Looking for writers 2021/12/13 06:34:38 DEBUG : : Looking for writers 2021/12/13 06:34:38 DEBUG : dir: reading active writers 2021/12/13 06:34:38 DEBUG : file1: reading active writers 2021/12/13 06:34:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/12/13 06:34:39 DEBUG : dir: Looking for writers 2021/12/13 06:34:39 DEBUG : : Looking for writers 2021/12/13 06:34:39 DEBUG : dir: reading active writers 2021/12/13 06:34:39 DEBUG : file1: reading active writers 2021/12/13 06:34:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/12/13 06:34:39 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:39 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:39 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:34:39 DEBUG : dir: Looking for writers 2021/12/13 06:34:39 DEBUG : : Looking for writers 2021/12/13 06:34:39 DEBUG : dir: reading active writers 2021/12/13 06:34:39 DEBUG : file1: reading active writers 2021/12/13 06:34:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/12/13 06:34:39 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:39 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:40 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:34:40 DEBUG : dir: Looking for writers 2021/12/13 06:34:40 DEBUG : : Looking for writers 2021/12/13 06:34:40 DEBUG : dir: reading active writers 2021/12/13 06:34:40 DEBUG : file1: reading active writers 2021/12/13 06:34:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:40 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:40 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:41 DEBUG : dir: Looking for writers 2021/12/13 06:34:41 DEBUG : : Looking for writers 2021/12/13 06:34:41 DEBUG : dir: reading active writers 2021/12/13 06:34:41 DEBUG : file1: reading active writers 2021/12/13 06:34:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:41 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:34:41 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:41 ERROR : file1: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:42 DEBUG : dir: Looking for writers 2021/12/13 06:34:42 DEBUG : : Looking for writers 2021/12/13 06:34:42 DEBUG : dir: reading active writers 2021/12/13 06:34:42 DEBUG : file1: reading active writers 2021/12/13 06:34:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:43 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:34:43 DEBUG : dir: Looking for writers 2021/12/13 06:34:43 DEBUG : : Looking for writers 2021/12/13 06:34:43 DEBUG : dir: reading active writers 2021/12/13 06:34:43 DEBUG : file1: reading active writers 2021/12/13 06:34:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:43 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:43 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:44 DEBUG : dir: Looking for writers 2021/12/13 06:34:44 DEBUG : : Looking for writers 2021/12/13 06:34:44 DEBUG : file1: reading active writers 2021/12/13 06:34:44 DEBUG : dir: reading active writers 2021/12/13 06:34:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:45 DEBUG : dir: Looking for writers 2021/12/13 06:34:45 DEBUG : : Looking for writers 2021/12/13 06:34:45 DEBUG : dir: reading active writers 2021/12/13 06:34:45 DEBUG : file1: reading active writers 2021/12/13 06:34:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:46 DEBUG : dir: Looking for writers 2021/12/13 06:34:46 DEBUG : : Looking for writers 2021/12/13 06:34:46 DEBUG : dir: reading active writers 2021/12/13 06:34:46 DEBUG : file1: reading active writers 2021/12/13 06:34:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:46 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:34:46 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:46 ERROR : file1: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:47 DEBUG : dir: Looking for writers 2021/12/13 06:34:47 DEBUG : : Looking for writers 2021/12/13 06:34:47 DEBUG : file1: reading active writers 2021/12/13 06:34:47 DEBUG : dir: reading active writers 2021/12/13 06:34:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:48 DEBUG : dir: Looking for writers 2021/12/13 06:34:48 DEBUG : : Looking for writers 2021/12/13 06:34:48 DEBUG : dir: reading active writers 2021/12/13 06:34:48 DEBUG : file1: reading active writers 2021/12/13 06:34:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:49 DEBUG : dir: Looking for writers 2021/12/13 06:34:49 DEBUG : : Looking for writers 2021/12/13 06:34:49 DEBUG : dir: reading active writers 2021/12/13 06:34:49 DEBUG : file1: reading active writers 2021/12/13 06:34:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:50 DEBUG : dir: Looking for writers 2021/12/13 06:34:50 DEBUG : : Looking for writers 2021/12/13 06:34:50 DEBUG : dir: reading active writers 2021/12/13 06:34:50 DEBUG : file1: reading active writers 2021/12/13 06:34:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:51 DEBUG : dir: Looking for writers 2021/12/13 06:34:51 DEBUG : : Looking for writers 2021/12/13 06:34:51 DEBUG : dir: reading active writers 2021/12/13 06:34:51 DEBUG : file1: reading active writers 2021/12/13 06:34:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:52 DEBUG : dir: Looking for writers 2021/12/13 06:34:52 DEBUG : : Looking for writers 2021/12/13 06:34:52 DEBUG : dir: reading active writers 2021/12/13 06:34:52 DEBUG : file1: reading active writers 2021/12/13 06:34:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:53 DEBUG : dir: Looking for writers 2021/12/13 06:34:53 DEBUG : : Looking for writers 2021/12/13 06:34:53 DEBUG : file1: reading active writers 2021/12/13 06:34:53 DEBUG : dir: reading active writers 2021/12/13 06:34:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:53 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:34:53 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:53 ERROR : file1: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:34:54 DEBUG : dir: Looking for writers 2021/12/13 06:34:54 DEBUG : : Looking for writers 2021/12/13 06:34:54 DEBUG : dir: reading active writers 2021/12/13 06:34:54 DEBUG : file1: reading active writers 2021/12/13 06:34:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:55 DEBUG : dir: Looking for writers 2021/12/13 06:34:55 DEBUG : : Looking for writers 2021/12/13 06:34:55 DEBUG : dir: reading active writers 2021/12/13 06:34:55 DEBUG : file1: reading active writers 2021/12/13 06:34:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:56 DEBUG : dir: Looking for writers 2021/12/13 06:34:56 DEBUG : : Looking for writers 2021/12/13 06:34:56 DEBUG : dir: reading active writers 2021/12/13 06:34:56 DEBUG : file1: reading active writers 2021/12/13 06:34:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:57 DEBUG : dir: Looking for writers 2021/12/13 06:34:57 DEBUG : : Looking for writers 2021/12/13 06:34:57 DEBUG : file1: reading active writers 2021/12/13 06:34:57 DEBUG : dir: reading active writers 2021/12/13 06:34:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:58 DEBUG : dir: Looking for writers 2021/12/13 06:34:58 DEBUG : : Looking for writers 2021/12/13 06:34:58 DEBUG : dir: reading active writers 2021/12/13 06:34:58 DEBUG : file1: reading active writers 2021/12/13 06:34:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:34:59 DEBUG : dir: Looking for writers 2021/12/13 06:34:59 DEBUG : : Looking for writers 2021/12/13 06:34:59 DEBUG : dir: reading active writers 2021/12/13 06:34:59 DEBUG : file1: reading active writers 2021/12/13 06:34:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:00 DEBUG : dir: Looking for writers 2021/12/13 06:35:00 DEBUG : : Looking for writers 2021/12/13 06:35:00 DEBUG : dir: reading active writers 2021/12/13 06:35:00 DEBUG : file1: reading active writers 2021/12/13 06:35:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:01 DEBUG : dir: Looking for writers 2021/12/13 06:35:01 DEBUG : : Looking for writers 2021/12/13 06:35:01 DEBUG : dir: reading active writers 2021/12/13 06:35:01 DEBUG : file1: reading active writers 2021/12/13 06:35:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:02 DEBUG : dir: Looking for writers 2021/12/13 06:35:02 DEBUG : : Looking for writers 2021/12/13 06:35:02 DEBUG : dir: reading active writers 2021/12/13 06:35:02 DEBUG : file1: reading active writers 2021/12/13 06:35:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:03 DEBUG : dir: Looking for writers 2021/12/13 06:35:03 DEBUG : : Looking for writers 2021/12/13 06:35:03 DEBUG : dir: reading active writers 2021/12/13 06:35:03 DEBUG : file1: reading active writers 2021/12/13 06:35:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:04 DEBUG : dir: Looking for writers 2021/12/13 06:35:04 DEBUG : : Looking for writers 2021/12/13 06:35:04 DEBUG : dir: reading active writers 2021/12/13 06:35:04 DEBUG : file1: reading active writers 2021/12/13 06:35:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:05 DEBUG : dir: Looking for writers 2021/12/13 06:35:05 DEBUG : : Looking for writers 2021/12/13 06:35:05 DEBUG : dir: reading active writers 2021/12/13 06:35:05 DEBUG : file1: reading active writers 2021/12/13 06:35:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:06 DEBUG : dir: Looking for writers 2021/12/13 06:35:06 DEBUG : : Looking for writers 2021/12/13 06:35:06 DEBUG : dir: reading active writers 2021/12/13 06:35:06 DEBUG : file1: reading active writers 2021/12/13 06:35:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:06 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:35:06 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:06 ERROR : file1: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:07 DEBUG : dir: Looking for writers 2021/12/13 06:35:07 DEBUG : : Looking for writers 2021/12/13 06:35:07 DEBUG : dir: reading active writers 2021/12/13 06:35:07 DEBUG : file1: reading active writers 2021/12/13 06:35:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:08 DEBUG : dir: Looking for writers 2021/12/13 06:35:08 DEBUG : : Looking for writers 2021/12/13 06:35:08 DEBUG : dir: reading active writers 2021/12/13 06:35:08 DEBUG : file1: reading active writers 2021/12/13 06:35:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:08 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc00014b380 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724795940641341 ext:90508789540 loc:0x2a04b60} ATime:{wall:13863724795940658242 ext:90508806421 loc:0x2a04b60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/12/13 06:35:08 DEBUG : >WaitForWriters: fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 read_write_test.go:392 Error: Should be true Test: TestRWFileHandleWriteAt Messages: listing wrong, want file1 (11) got fstest.go:204: Not found "file1" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 read_write_test.go:392 Error: Not equal: expected: 0 actual : 1 Test: TestRWFileHandleWriteAt Messages: 1 objects not found 2021/12/13 06:35:16 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:35:16 DEBUG : dir: Looking for writers 2021/12/13 06:35:16 DEBUG : : Looking for writers 2021/12/13 06:35:16 DEBUG : dir: reading active writers 2021/12/13 06:35:16 DEBUG : file1: reading active writers 2021/12/13 06:35:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/12/13 06:35:16 DEBUG : dir: Looking for writers 2021/12/13 06:35:16 DEBUG : : Looking for writers 2021/12/13 06:35:16 DEBUG : dir: reading active writers 2021/12/13 06:35:16 DEBUG : file1: reading active writers 2021/12/13 06:35:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/12/13 06:35:16 DEBUG : dir: Looking for writers 2021/12/13 06:35:16 DEBUG : : Looking for writers 2021/12/13 06:35:16 DEBUG : dir: reading active writers 2021/12/13 06:35:16 DEBUG : file1: reading active writers 2021/12/13 06:35:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/12/13 06:35:16 DEBUG : dir: Looking for writers 2021/12/13 06:35:16 DEBUG : : Looking for writers 2021/12/13 06:35:16 DEBUG : dir: reading active writers 2021/12/13 06:35:16 DEBUG : file1: reading active writers 2021/12/13 06:35:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/12/13 06:35:16 DEBUG : dir: Looking for writers 2021/12/13 06:35:16 DEBUG : : Looking for writers 2021/12/13 06:35:16 DEBUG : dir: reading active writers 2021/12/13 06:35:16 DEBUG : file1: reading active writers 2021/12/13 06:35:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/12/13 06:35:17 DEBUG : dir: Looking for writers 2021/12/13 06:35:17 DEBUG : : Looking for writers 2021/12/13 06:35:17 DEBUG : dir: reading active writers 2021/12/13 06:35:17 DEBUG : file1: reading active writers 2021/12/13 06:35:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/12/13 06:35:17 DEBUG : dir: Looking for writers 2021/12/13 06:35:17 DEBUG : : Looking for writers 2021/12/13 06:35:17 DEBUG : dir: reading active writers 2021/12/13 06:35:17 DEBUG : file1: reading active writers 2021/12/13 06:35:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/12/13 06:35:17 DEBUG : dir: Looking for writers 2021/12/13 06:35:17 DEBUG : : Looking for writers 2021/12/13 06:35:17 DEBUG : dir: reading active writers 2021/12/13 06:35:17 DEBUG : file1: reading active writers 2021/12/13 06:35:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:18 DEBUG : dir: Looking for writers 2021/12/13 06:35:18 DEBUG : : Looking for writers 2021/12/13 06:35:18 DEBUG : dir: reading active writers 2021/12/13 06:35:18 DEBUG : file1: reading active writers 2021/12/13 06:35:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:19 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2021/12/13 06:35:19 INFO : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 11 (was 11) 2021/12/13 06:35:19 DEBUG : dir: Looking for writers 2021/12/13 06:35:19 DEBUG : : Looking for writers 2021/12/13 06:35:19 DEBUG : dir: reading active writers 2021/12/13 06:35:19 DEBUG : file1: reading active writers 2021/12/13 06:35:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:20 DEBUG : dir: Looking for writers 2021/12/13 06:35:20 DEBUG : : Looking for writers 2021/12/13 06:35:20 DEBUG : dir: reading active writers 2021/12/13 06:35:20 DEBUG : file1: reading active writers 2021/12/13 06:35:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:22 DEBUG : dir: Looking for writers 2021/12/13 06:35:22 DEBUG : : Looking for writers 2021/12/13 06:35:22 DEBUG : dir: reading active writers 2021/12/13 06:35:22 DEBUG : file1: reading active writers 2021/12/13 06:35:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:22 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/12/13 06:35:23 DEBUG : dir: Looking for writers 2021/12/13 06:35:23 DEBUG : : Looking for writers 2021/12/13 06:35:23 DEBUG : dir: reading active writers 2021/12/13 06:35:23 DEBUG : file1: reading active writers 2021/12/13 06:35:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:23 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/12/13 06:35:24 DEBUG : dir: Looking for writers 2021/12/13 06:35:24 DEBUG : : Looking for writers 2021/12/13 06:35:24 DEBUG : dir: reading active writers 2021/12/13 06:35:24 DEBUG : file1: reading active writers 2021/12/13 06:35:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:25 DEBUG : dir: Looking for writers 2021/12/13 06:35:25 DEBUG : : Looking for writers 2021/12/13 06:35:25 DEBUG : dir: reading active writers 2021/12/13 06:35:25 DEBUG : file1: reading active writers 2021/12/13 06:35:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:26 DEBUG : dir: Looking for writers 2021/12/13 06:35:26 DEBUG : : Looking for writers 2021/12/13 06:35:26 DEBUG : dir: reading active writers 2021/12/13 06:35:26 DEBUG : file1: reading active writers 2021/12/13 06:35:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:27 DEBUG : dir: Looking for writers 2021/12/13 06:35:27 DEBUG : : Looking for writers 2021/12/13 06:35:27 DEBUG : dir: reading active writers 2021/12/13 06:35:27 DEBUG : file1: reading active writers 2021/12/13 06:35:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:28 DEBUG : dir: Looking for writers 2021/12/13 06:35:28 DEBUG : : Looking for writers 2021/12/13 06:35:28 DEBUG : dir: reading active writers 2021/12/13 06:35:28 DEBUG : file1: reading active writers 2021/12/13 06:35:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:29 DEBUG : dir: Looking for writers 2021/12/13 06:35:29 DEBUG : : Looking for writers 2021/12/13 06:35:29 DEBUG : dir: reading active writers 2021/12/13 06:35:29 DEBUG : file1: reading active writers 2021/12/13 06:35:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:30 DEBUG : dir: Looking for writers 2021/12/13 06:35:30 DEBUG : : Looking for writers 2021/12/13 06:35:30 DEBUG : file1: reading active writers 2021/12/13 06:35:30 DEBUG : dir: reading active writers 2021/12/13 06:35:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:31 DEBUG : dir: Looking for writers 2021/12/13 06:35:31 DEBUG : : Looking for writers 2021/12/13 06:35:31 DEBUG : file1: reading active writers 2021/12/13 06:35:31 DEBUG : dir: reading active writers 2021/12/13 06:35:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:32 DEBUG : dir: Looking for writers 2021/12/13 06:35:32 DEBUG : : Looking for writers 2021/12/13 06:35:32 DEBUG : dir: reading active writers 2021/12/13 06:35:32 DEBUG : file1: reading active writers 2021/12/13 06:35:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:32 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:35:32 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:32 ERROR : file1: vfs cache: failed to upload try #9, will retry in 51.2s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:33 DEBUG : dir: Looking for writers 2021/12/13 06:35:33 DEBUG : : Looking for writers 2021/12/13 06:35:33 DEBUG : dir: reading active writers 2021/12/13 06:35:33 DEBUG : file1: reading active writers 2021/12/13 06:35:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:34 DEBUG : dir: Looking for writers 2021/12/13 06:35:34 DEBUG : : Looking for writers 2021/12/13 06:35:34 DEBUG : dir: reading active writers 2021/12/13 06:35:34 DEBUG : file1: reading active writers 2021/12/13 06:35:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:35 DEBUG : dir: Looking for writers 2021/12/13 06:35:35 DEBUG : : Looking for writers 2021/12/13 06:35:35 DEBUG : dir: reading active writers 2021/12/13 06:35:35 DEBUG : file1: reading active writers 2021/12/13 06:35:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:36 DEBUG : dir: Looking for writers 2021/12/13 06:35:36 DEBUG : : Looking for writers 2021/12/13 06:35:36 DEBUG : dir: reading active writers 2021/12/13 06:35:36 DEBUG : file1: reading active writers 2021/12/13 06:35:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:37 DEBUG : dir: Looking for writers 2021/12/13 06:35:37 DEBUG : : Looking for writers 2021/12/13 06:35:37 DEBUG : dir: reading active writers 2021/12/13 06:35:37 DEBUG : file1: reading active writers 2021/12/13 06:35:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:38 DEBUG : dir: Looking for writers 2021/12/13 06:35:38 DEBUG : : Looking for writers 2021/12/13 06:35:38 DEBUG : dir: reading active writers 2021/12/13 06:35:38 DEBUG : file1: reading active writers 2021/12/13 06:35:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:39 DEBUG : dir: Looking for writers 2021/12/13 06:35:39 DEBUG : : Looking for writers 2021/12/13 06:35:39 DEBUG : file1: reading active writers 2021/12/13 06:35:39 DEBUG : dir: reading active writers 2021/12/13 06:35:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:40 DEBUG : dir: Looking for writers 2021/12/13 06:35:40 DEBUG : : Looking for writers 2021/12/13 06:35:40 DEBUG : dir: reading active writers 2021/12/13 06:35:40 DEBUG : file1: reading active writers 2021/12/13 06:35:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:41 DEBUG : dir: Looking for writers 2021/12/13 06:35:41 DEBUG : : Looking for writers 2021/12/13 06:35:41 DEBUG : dir: reading active writers 2021/12/13 06:35:41 DEBUG : file1: reading active writers 2021/12/13 06:35:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:42 DEBUG : dir: Looking for writers 2021/12/13 06:35:42 DEBUG : : Looking for writers 2021/12/13 06:35:42 DEBUG : dir: reading active writers 2021/12/13 06:35:42 DEBUG : file1: reading active writers 2021/12/13 06:35:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:43 DEBUG : dir: Looking for writers 2021/12/13 06:35:43 DEBUG : : Looking for writers 2021/12/13 06:35:43 DEBUG : dir: reading active writers 2021/12/13 06:35:43 DEBUG : file1: reading active writers 2021/12/13 06:35:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:44 DEBUG : dir: Looking for writers 2021/12/13 06:35:44 DEBUG : : Looking for writers 2021/12/13 06:35:44 DEBUG : dir: reading active writers 2021/12/13 06:35:44 DEBUG : file1: reading active writers 2021/12/13 06:35:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:45 DEBUG : dir: Looking for writers 2021/12/13 06:35:45 DEBUG : : Looking for writers 2021/12/13 06:35:45 DEBUG : dir: reading active writers 2021/12/13 06:35:45 DEBUG : file1: reading active writers 2021/12/13 06:35:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:46 DEBUG : dir: Looking for writers 2021/12/13 06:35:46 DEBUG : : Looking for writers 2021/12/13 06:35:46 DEBUG : dir: reading active writers 2021/12/13 06:35:46 DEBUG : file1: reading active writers 2021/12/13 06:35:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/12/13 06:35:46 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc00014b380 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724795940641341 ext:90508789540 loc:0x2a04b60} ATime:{wall:13863724795940658242 ext:90508806421 loc:0x2a04b60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/12/13 06:35:46 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleWriteAt (68.23s) === RUN TestRWFileHandleWriteNoWrite run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:35:46 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:35:46 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:35:46 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:35:46 DEBUG : file1: newRWFileHandle: 2021/12/13 06:35:46 DEBUG : file1(0xc000b0b780): openPending: 2021/12/13 06:35:46 ERROR : file1: vfs cache: detected external removal of cache file 2021/12/13 06:35:46 DEBUG : file1: vfs cache: truncate to size=0 2021/12/13 06:35:46 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:35:46 DEBUG : file1(0xc000b0b780): >openPending: err= 2021/12/13 06:35:46 DEBUG : file1: vfs cache: cancelling writeback (uploading false) 0xc00090c460 item 1 2021/12/13 06:35:46 DEBUG : file1: >newRWFileHandle: err= 2021/12/13 06:35:46 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:35:46 DEBUG : file1: >Open: fd=file1 (rw), err= 2021/12/13 06:35:46 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2021/12/13 06:35:46 DEBUG : file1(0xc000b0b780): close: 2021/12/13 06:35:46 DEBUG : file1: vfs cache: setting modification time to 2021-12-13 06:35:46.996065102 +0000 UTC m=+158.736176171 2021/12/13 06:35:46 INFO : file1: vfs cache: queuing for upload in 100ms 2021/12/13 06:35:46 DEBUG : file1(0xc000b0b780): >close: err= 2021/12/13 06:35:46 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2021/12/13 06:35:46 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2021/12/13 06:35:46 DEBUG : file2: newRWFileHandle: 2021/12/13 06:35:46 DEBUG : file2(0xc000b0b880): openPending: 2021/12/13 06:35:46 DEBUG : file2: vfs cache: truncate to size=0 2021/12/13 06:35:46 DEBUG : : Added virtual directory entry vAddFile: "file2" 2021/12/13 06:35:46 DEBUG : file2(0xc000b0b880): >openPending: err= 2021/12/13 06:35:46 DEBUG : file2: >newRWFileHandle: err= 2021/12/13 06:35:46 DEBUG : : Added virtual directory entry vAddFile: "file2" 2021/12/13 06:35:46 DEBUG : file2: >Open: fd=file2 (rw), err= 2021/12/13 06:35:46 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2021/12/13 06:35:46 DEBUG : file2(0xc000b0b880): RWFileHandle.Flush 2021/12/13 06:35:46 DEBUG : file2(0xc000b0b880): RWFileHandle.Release 2021/12/13 06:35:46 DEBUG : file2(0xc000b0b880): close: 2021/12/13 06:35:46 DEBUG : file2: vfs cache: setting modification time to 2021-12-13 06:35:46.996813559 +0000 UTC m=+158.736924618 2021/12/13 06:35:46 INFO : file2: vfs cache: queuing for upload in 100ms 2021/12/13 06:35:46 DEBUG : file2(0xc000b0b880): >close: err= dir_test.go:252: Error Trace: dir_test.go:252 read_write_test.go:420 Error: Not equal: expected: []string{"file1,0,false", "file2,0,false"} actual : []string{"dir,0,true", "file1,0,false", "file2,0,false"} Diff: --- Expected +++ Actual @@ -1,2 +1,3 @@ -([]string) (len=2) { +([]string) (len=3) { + (string) (len=10) "dir,0,true", (string) (len=13) "file1,0,false", Test: TestRWFileHandleWriteNoWrite 2021/12/13 06:35:46 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:35:46 DEBUG : dir: Looking for writers 2021/12/13 06:35:46 DEBUG : : Looking for writers 2021/12/13 06:35:46 DEBUG : dir: reading active writers 2021/12/13 06:35:46 DEBUG : file1: reading active writers 2021/12/13 06:35:46 DEBUG : file2: reading active writers 2021/12/13 06:35:46 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2021/12/13 06:35:47 DEBUG : dir: Looking for writers 2021/12/13 06:35:47 DEBUG : : Looking for writers 2021/12/13 06:35:47 DEBUG : dir: reading active writers 2021/12/13 06:35:47 DEBUG : file1: reading active writers 2021/12/13 06:35:47 DEBUG : file2: reading active writers 2021/12/13 06:35:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2021/12/13 06:35:47 DEBUG : dir: Looking for writers 2021/12/13 06:35:47 DEBUG : : Looking for writers 2021/12/13 06:35:47 DEBUG : dir: reading active writers 2021/12/13 06:35:47 DEBUG : file1: reading active writers 2021/12/13 06:35:47 DEBUG : file2: reading active writers 2021/12/13 06:35:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2021/12/13 06:35:47 DEBUG : dir: Looking for writers 2021/12/13 06:35:47 DEBUG : : Looking for writers 2021/12/13 06:35:47 DEBUG : file1: reading active writers 2021/12/13 06:35:47 DEBUG : file2: reading active writers 2021/12/13 06:35:47 DEBUG : dir: reading active writers 2021/12/13 06:35:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2021/12/13 06:35:47 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:35:47 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:35:47 DEBUG : dir: Looking for writers 2021/12/13 06:35:47 DEBUG : : Looking for writers 2021/12/13 06:35:47 DEBUG : dir: reading active writers 2021/12/13 06:35:47 DEBUG : file1: reading active writers 2021/12/13 06:35:47 DEBUG : file2: reading active writers 2021/12/13 06:35:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2021/12/13 06:35:47 DEBUG : dir: Looking for writers 2021/12/13 06:35:47 DEBUG : : Looking for writers 2021/12/13 06:35:47 DEBUG : dir: reading active writers 2021/12/13 06:35:47 DEBUG : file1: reading active writers 2021/12/13 06:35:47 DEBUG : file2: reading active writers 2021/12/13 06:35:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2021/12/13 06:35:47 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:47 ERROR : file2: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:47 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:47 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:47 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:35:47 DEBUG : dir: Looking for writers 2021/12/13 06:35:47 DEBUG : : Looking for writers 2021/12/13 06:35:47 DEBUG : dir: reading active writers 2021/12/13 06:35:47 DEBUG : file1: reading active writers 2021/12/13 06:35:47 DEBUG : file2: reading active writers 2021/12/13 06:35:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2021/12/13 06:35:47 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:35:47 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:47 ERROR : file2: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:47 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:47 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:48 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:35:48 DEBUG : dir: Looking for writers 2021/12/13 06:35:48 DEBUG : : Looking for writers 2021/12/13 06:35:48 DEBUG : dir: reading active writers 2021/12/13 06:35:48 DEBUG : file1: reading active writers 2021/12/13 06:35:48 DEBUG : file2: reading active writers 2021/12/13 06:35:48 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:48 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:35:48 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:48 ERROR : file2: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:48 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:48 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:49 DEBUG : dir: Looking for writers 2021/12/13 06:35:49 DEBUG : : Looking for writers 2021/12/13 06:35:49 DEBUG : dir: reading active writers 2021/12/13 06:35:49 DEBUG : file1: reading active writers 2021/12/13 06:35:49 DEBUG : file2: reading active writers 2021/12/13 06:35:49 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:49 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:35:49 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:35:49 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:49 ERROR : file2: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:49 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:49 ERROR : file1: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:50 DEBUG : dir: Looking for writers 2021/12/13 06:35:50 DEBUG : : Looking for writers 2021/12/13 06:35:50 DEBUG : dir: reading active writers 2021/12/13 06:35:50 DEBUG : file1: reading active writers 2021/12/13 06:35:50 DEBUG : file2: reading active writers 2021/12/13 06:35:50 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:51 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:35:51 DEBUG : dir: Looking for writers 2021/12/13 06:35:51 DEBUG : : Looking for writers 2021/12/13 06:35:51 DEBUG : dir: reading active writers 2021/12/13 06:35:51 DEBUG : file1: reading active writers 2021/12/13 06:35:51 DEBUG : file2: reading active writers 2021/12/13 06:35:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:51 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:35:51 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:51 ERROR : file2: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:51 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:51 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:52 DEBUG : dir: Looking for writers 2021/12/13 06:35:52 DEBUG : : Looking for writers 2021/12/13 06:35:52 DEBUG : dir: reading active writers 2021/12/13 06:35:52 DEBUG : file1: reading active writers 2021/12/13 06:35:52 DEBUG : file2: reading active writers 2021/12/13 06:35:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:53 DEBUG : dir: Looking for writers 2021/12/13 06:35:53 DEBUG : : Looking for writers 2021/12/13 06:35:53 DEBUG : dir: reading active writers 2021/12/13 06:35:53 DEBUG : file1: reading active writers 2021/12/13 06:35:53 DEBUG : file2: reading active writers 2021/12/13 06:35:53 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:54 DEBUG : dir: Looking for writers 2021/12/13 06:35:54 DEBUG : : Looking for writers 2021/12/13 06:35:54 DEBUG : dir: reading active writers 2021/12/13 06:35:54 DEBUG : file1: reading active writers 2021/12/13 06:35:54 DEBUG : file2: reading active writers 2021/12/13 06:35:54 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:54 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:35:54 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:35:54 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:54 ERROR : file2: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:55 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:55 ERROR : file1: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:35:55 DEBUG : dir: Looking for writers 2021/12/13 06:35:55 DEBUG : : Looking for writers 2021/12/13 06:35:55 DEBUG : dir: reading active writers 2021/12/13 06:35:55 DEBUG : file1: reading active writers 2021/12/13 06:35:55 DEBUG : file2: reading active writers 2021/12/13 06:35:55 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:56 DEBUG : dir: Looking for writers 2021/12/13 06:35:56 DEBUG : : Looking for writers 2021/12/13 06:35:56 DEBUG : dir: reading active writers 2021/12/13 06:35:56 DEBUG : file1: reading active writers 2021/12/13 06:35:56 DEBUG : file2: reading active writers 2021/12/13 06:35:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:57 DEBUG : dir: Looking for writers 2021/12/13 06:35:57 DEBUG : : Looking for writers 2021/12/13 06:35:57 DEBUG : dir: reading active writers 2021/12/13 06:35:57 DEBUG : file1: reading active writers 2021/12/13 06:35:57 DEBUG : file2: reading active writers 2021/12/13 06:35:57 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:58 DEBUG : dir: Looking for writers 2021/12/13 06:35:58 DEBUG : : Looking for writers 2021/12/13 06:35:58 DEBUG : file2: reading active writers 2021/12/13 06:35:58 DEBUG : dir: reading active writers 2021/12/13 06:35:58 DEBUG : file1: reading active writers 2021/12/13 06:35:58 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:35:59 DEBUG : dir: Looking for writers 2021/12/13 06:35:59 DEBUG : : Looking for writers 2021/12/13 06:35:59 DEBUG : dir: reading active writers 2021/12/13 06:35:59 DEBUG : file1: reading active writers 2021/12/13 06:35:59 DEBUG : file2: reading active writers 2021/12/13 06:35:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:00 DEBUG : dir: Looking for writers 2021/12/13 06:36:00 DEBUG : : Looking for writers 2021/12/13 06:36:00 DEBUG : dir: reading active writers 2021/12/13 06:36:00 DEBUG : file1: reading active writers 2021/12/13 06:36:00 DEBUG : file2: reading active writers 2021/12/13 06:36:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:01 DEBUG : dir: Looking for writers 2021/12/13 06:36:01 DEBUG : : Looking for writers 2021/12/13 06:36:01 DEBUG : dir: reading active writers 2021/12/13 06:36:01 DEBUG : file1: reading active writers 2021/12/13 06:36:01 DEBUG : file2: reading active writers 2021/12/13 06:36:01 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:01 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:36:01 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:36:01 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:01 ERROR : file2: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:01 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:01 ERROR : file1: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:02 DEBUG : dir: Looking for writers 2021/12/13 06:36:02 DEBUG : : Looking for writers 2021/12/13 06:36:02 DEBUG : dir: reading active writers 2021/12/13 06:36:02 DEBUG : file1: reading active writers 2021/12/13 06:36:02 DEBUG : file2: reading active writers 2021/12/13 06:36:02 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:03 DEBUG : dir: Looking for writers 2021/12/13 06:36:03 DEBUG : : Looking for writers 2021/12/13 06:36:03 DEBUG : file2: reading active writers 2021/12/13 06:36:03 DEBUG : dir: reading active writers 2021/12/13 06:36:03 DEBUG : file1: reading active writers 2021/12/13 06:36:03 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:04 DEBUG : dir: Looking for writers 2021/12/13 06:36:04 DEBUG : : Looking for writers 2021/12/13 06:36:04 DEBUG : dir: reading active writers 2021/12/13 06:36:04 DEBUG : file1: reading active writers 2021/12/13 06:36:04 DEBUG : file2: reading active writers 2021/12/13 06:36:04 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:05 DEBUG : dir: Looking for writers 2021/12/13 06:36:05 DEBUG : : Looking for writers 2021/12/13 06:36:05 DEBUG : dir: reading active writers 2021/12/13 06:36:05 DEBUG : file1: reading active writers 2021/12/13 06:36:05 DEBUG : file2: reading active writers 2021/12/13 06:36:05 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:06 DEBUG : dir: Looking for writers 2021/12/13 06:36:06 DEBUG : : Looking for writers 2021/12/13 06:36:06 DEBUG : dir: reading active writers 2021/12/13 06:36:06 DEBUG : file1: reading active writers 2021/12/13 06:36:06 DEBUG : file2: reading active writers 2021/12/13 06:36:06 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:07 DEBUG : dir: Looking for writers 2021/12/13 06:36:07 DEBUG : : Looking for writers 2021/12/13 06:36:07 DEBUG : dir: reading active writers 2021/12/13 06:36:07 DEBUG : file1: reading active writers 2021/12/13 06:36:07 DEBUG : file2: reading active writers 2021/12/13 06:36:07 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:08 DEBUG : dir: Looking for writers 2021/12/13 06:36:08 DEBUG : : Looking for writers 2021/12/13 06:36:08 DEBUG : dir: reading active writers 2021/12/13 06:36:08 DEBUG : file1: reading active writers 2021/12/13 06:36:08 DEBUG : file2: reading active writers 2021/12/13 06:36:08 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:09 DEBUG : dir: Looking for writers 2021/12/13 06:36:09 DEBUG : : Looking for writers 2021/12/13 06:36:09 DEBUG : dir: reading active writers 2021/12/13 06:36:09 DEBUG : file1: reading active writers 2021/12/13 06:36:09 DEBUG : file2: reading active writers 2021/12/13 06:36:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:10 DEBUG : dir: Looking for writers 2021/12/13 06:36:10 DEBUG : : Looking for writers 2021/12/13 06:36:10 DEBUG : dir: reading active writers 2021/12/13 06:36:10 DEBUG : file1: reading active writers 2021/12/13 06:36:10 DEBUG : file2: reading active writers 2021/12/13 06:36:10 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:11 DEBUG : dir: Looking for writers 2021/12/13 06:36:11 DEBUG : : Looking for writers 2021/12/13 06:36:11 DEBUG : dir: reading active writers 2021/12/13 06:36:11 DEBUG : file1: reading active writers 2021/12/13 06:36:11 DEBUG : file2: reading active writers 2021/12/13 06:36:11 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:12 DEBUG : dir: Looking for writers 2021/12/13 06:36:12 DEBUG : : Looking for writers 2021/12/13 06:36:12 DEBUG : dir: reading active writers 2021/12/13 06:36:12 DEBUG : file1: reading active writers 2021/12/13 06:36:12 DEBUG : file2: reading active writers 2021/12/13 06:36:12 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:13 DEBUG : dir: Looking for writers 2021/12/13 06:36:13 DEBUG : : Looking for writers 2021/12/13 06:36:13 DEBUG : dir: reading active writers 2021/12/13 06:36:13 DEBUG : file1: reading active writers 2021/12/13 06:36:13 DEBUG : file2: reading active writers 2021/12/13 06:36:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:14 DEBUG : dir: Looking for writers 2021/12/13 06:36:14 DEBUG : : Looking for writers 2021/12/13 06:36:14 DEBUG : dir: reading active writers 2021/12/13 06:36:14 DEBUG : file1: reading active writers 2021/12/13 06:36:14 DEBUG : file2: reading active writers 2021/12/13 06:36:14 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:14 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:36:14 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:36:14 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:14 ERROR : file2: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:14 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:14 ERROR : file1: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:15 DEBUG : dir: Looking for writers 2021/12/13 06:36:15 DEBUG : : Looking for writers 2021/12/13 06:36:15 DEBUG : dir: reading active writers 2021/12/13 06:36:15 DEBUG : file1: reading active writers 2021/12/13 06:36:15 DEBUG : file2: reading active writers 2021/12/13 06:36:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:16 DEBUG : dir: Looking for writers 2021/12/13 06:36:16 DEBUG : : Looking for writers 2021/12/13 06:36:16 DEBUG : file1: reading active writers 2021/12/13 06:36:16 DEBUG : file2: reading active writers 2021/12/13 06:36:16 DEBUG : dir: reading active writers 2021/12/13 06:36:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:16 ERROR : Exiting even though 0 writers active and 2 cache items in use after 30s Cache{ "file2": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc000b0b840 name:file2 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724869183220471 ext:158736924618 loc:0x2a04b60} ATime:{wall:13863724869183322432 ext:158737026579 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 beingReset:false}, "file1": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc00014b380 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724869182472014 ext:158736176171 loc:0x2a04b60} ATime:{wall:13863724869182656320 ext:158736360468 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/12/13 06:36:16 DEBUG : >WaitForWriters: fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 2021/12/13 06:36:19 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2021/12/13 06:36:19 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file2 not removed, freed 0 bytes 2021/12/13 06:36:19 INFO : vfs cache: cleaned: objects 2 (was 2) in use 2, to upload 2, uploading 0, total size 0 (was 0) fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 2021/12/13 06:36:22 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/12/13 06:36:23 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 read_write_test.go:426 Error: Should be true Test: TestRWFileHandleWriteNoWrite Messages: listing wrong, want file1 (0), file2 (0) got fstest.go:204: Not found "file1" fstest.go:204: Not found "file2" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 read_write_test.go:426 Error: Not equal: expected: 0 actual : 2 Test: TestRWFileHandleWriteNoWrite Messages: 2 objects not found 2021/12/13 06:36:24 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:36:24 DEBUG : dir: Looking for writers 2021/12/13 06:36:24 DEBUG : : Looking for writers 2021/12/13 06:36:24 DEBUG : file2: reading active writers 2021/12/13 06:36:24 DEBUG : dir: reading active writers 2021/12/13 06:36:24 DEBUG : file1: reading active writers 2021/12/13 06:36:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2021/12/13 06:36:24 DEBUG : dir: Looking for writers 2021/12/13 06:36:24 DEBUG : : Looking for writers 2021/12/13 06:36:24 DEBUG : dir: reading active writers 2021/12/13 06:36:24 DEBUG : file1: reading active writers 2021/12/13 06:36:24 DEBUG : file2: reading active writers 2021/12/13 06:36:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2021/12/13 06:36:24 DEBUG : dir: Looking for writers 2021/12/13 06:36:24 DEBUG : : Looking for writers 2021/12/13 06:36:24 DEBUG : dir: reading active writers 2021/12/13 06:36:24 DEBUG : file1: reading active writers 2021/12/13 06:36:24 DEBUG : file2: reading active writers 2021/12/13 06:36:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2021/12/13 06:36:24 DEBUG : dir: Looking for writers 2021/12/13 06:36:24 DEBUG : : Looking for writers 2021/12/13 06:36:24 DEBUG : file1: reading active writers 2021/12/13 06:36:24 DEBUG : file2: reading active writers 2021/12/13 06:36:24 DEBUG : dir: reading active writers 2021/12/13 06:36:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2021/12/13 06:36:25 DEBUG : dir: Looking for writers 2021/12/13 06:36:25 DEBUG : : Looking for writers 2021/12/13 06:36:25 DEBUG : dir: reading active writers 2021/12/13 06:36:25 DEBUG : file1: reading active writers 2021/12/13 06:36:25 DEBUG : file2: reading active writers 2021/12/13 06:36:25 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2021/12/13 06:36:25 DEBUG : dir: Looking for writers 2021/12/13 06:36:25 DEBUG : : Looking for writers 2021/12/13 06:36:25 DEBUG : file2: reading active writers 2021/12/13 06:36:25 DEBUG : dir: reading active writers 2021/12/13 06:36:25 DEBUG : file1: reading active writers 2021/12/13 06:36:25 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2021/12/13 06:36:25 DEBUG : dir: Looking for writers 2021/12/13 06:36:25 DEBUG : : Looking for writers 2021/12/13 06:36:25 DEBUG : file2: reading active writers 2021/12/13 06:36:25 DEBUG : dir: reading active writers 2021/12/13 06:36:25 DEBUG : file1: reading active writers 2021/12/13 06:36:25 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2021/12/13 06:36:26 DEBUG : dir: Looking for writers 2021/12/13 06:36:26 DEBUG : : Looking for writers 2021/12/13 06:36:26 DEBUG : dir: reading active writers 2021/12/13 06:36:26 DEBUG : file1: reading active writers 2021/12/13 06:36:26 DEBUG : file2: reading active writers 2021/12/13 06:36:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:27 DEBUG : dir: Looking for writers 2021/12/13 06:36:27 DEBUG : : Looking for writers 2021/12/13 06:36:27 DEBUG : dir: reading active writers 2021/12/13 06:36:27 DEBUG : file1: reading active writers 2021/12/13 06:36:27 DEBUG : file2: reading active writers 2021/12/13 06:36:27 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:28 DEBUG : dir: Looking for writers 2021/12/13 06:36:28 DEBUG : : Looking for writers 2021/12/13 06:36:28 DEBUG : dir: reading active writers 2021/12/13 06:36:28 DEBUG : file1: reading active writers 2021/12/13 06:36:28 DEBUG : file2: reading active writers 2021/12/13 06:36:28 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:29 DEBUG : dir: Looking for writers 2021/12/13 06:36:29 DEBUG : : Looking for writers 2021/12/13 06:36:29 DEBUG : dir: reading active writers 2021/12/13 06:36:29 DEBUG : file1: reading active writers 2021/12/13 06:36:29 DEBUG : file2: reading active writers 2021/12/13 06:36:29 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:30 DEBUG : dir: Looking for writers 2021/12/13 06:36:30 DEBUG : : Looking for writers 2021/12/13 06:36:30 DEBUG : file1: reading active writers 2021/12/13 06:36:30 DEBUG : file2: reading active writers 2021/12/13 06:36:30 DEBUG : dir: reading active writers 2021/12/13 06:36:30 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:31 DEBUG : dir: Looking for writers 2021/12/13 06:36:31 DEBUG : : Looking for writers 2021/12/13 06:36:31 DEBUG : dir: reading active writers 2021/12/13 06:36:31 DEBUG : file1: reading active writers 2021/12/13 06:36:31 DEBUG : file2: reading active writers 2021/12/13 06:36:31 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:32 DEBUG : dir: Looking for writers 2021/12/13 06:36:32 DEBUG : : Looking for writers 2021/12/13 06:36:32 DEBUG : dir: reading active writers 2021/12/13 06:36:32 DEBUG : file1: reading active writers 2021/12/13 06:36:32 DEBUG : file2: reading active writers 2021/12/13 06:36:32 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:33 DEBUG : dir: Looking for writers 2021/12/13 06:36:33 DEBUG : : Looking for writers 2021/12/13 06:36:33 DEBUG : dir: reading active writers 2021/12/13 06:36:33 DEBUG : file1: reading active writers 2021/12/13 06:36:33 DEBUG : file2: reading active writers 2021/12/13 06:36:33 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:34 DEBUG : dir: Looking for writers 2021/12/13 06:36:34 DEBUG : : Looking for writers 2021/12/13 06:36:34 DEBUG : dir: reading active writers 2021/12/13 06:36:34 DEBUG : file1: reading active writers 2021/12/13 06:36:34 DEBUG : file2: reading active writers 2021/12/13 06:36:34 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:35 DEBUG : dir: Looking for writers 2021/12/13 06:36:35 DEBUG : : Looking for writers 2021/12/13 06:36:35 DEBUG : dir: reading active writers 2021/12/13 06:36:35 DEBUG : file1: reading active writers 2021/12/13 06:36:35 DEBUG : file2: reading active writers 2021/12/13 06:36:35 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:36 DEBUG : dir: Looking for writers 2021/12/13 06:36:36 DEBUG : : Looking for writers 2021/12/13 06:36:36 DEBUG : dir: reading active writers 2021/12/13 06:36:36 DEBUG : file1: reading active writers 2021/12/13 06:36:36 DEBUG : file2: reading active writers 2021/12/13 06:36:36 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:37 DEBUG : dir: Looking for writers 2021/12/13 06:36:37 DEBUG : : Looking for writers 2021/12/13 06:36:37 DEBUG : dir: reading active writers 2021/12/13 06:36:37 DEBUG : file1: reading active writers 2021/12/13 06:36:37 DEBUG : file2: reading active writers 2021/12/13 06:36:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:38 DEBUG : dir: Looking for writers 2021/12/13 06:36:38 DEBUG : : Looking for writers 2021/12/13 06:36:38 DEBUG : dir: reading active writers 2021/12/13 06:36:38 DEBUG : file1: reading active writers 2021/12/13 06:36:38 DEBUG : file2: reading active writers 2021/12/13 06:36:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:39 DEBUG : dir: Looking for writers 2021/12/13 06:36:39 DEBUG : : Looking for writers 2021/12/13 06:36:39 DEBUG : dir: reading active writers 2021/12/13 06:36:39 DEBUG : file1: reading active writers 2021/12/13 06:36:39 DEBUG : file2: reading active writers 2021/12/13 06:36:39 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:40 DEBUG : dir: Looking for writers 2021/12/13 06:36:40 DEBUG : : Looking for writers 2021/12/13 06:36:40 DEBUG : dir: reading active writers 2021/12/13 06:36:40 DEBUG : file1: reading active writers 2021/12/13 06:36:40 DEBUG : file2: reading active writers 2021/12/13 06:36:40 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:40 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:36:40 DEBUG : file1: vfs cache: starting upload 2021/12/13 06:36:40 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:40 ERROR : file2: vfs cache: failed to upload try #9, will retry in 51.2s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:40 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:40 ERROR : file1: vfs cache: failed to upload try #9, will retry in 51.2s: vfs cache: failed to transfer file from cache to remote: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:41 DEBUG : dir: Looking for writers 2021/12/13 06:36:41 DEBUG : : Looking for writers 2021/12/13 06:36:41 DEBUG : file1: reading active writers 2021/12/13 06:36:41 DEBUG : file2: reading active writers 2021/12/13 06:36:41 DEBUG : dir: reading active writers 2021/12/13 06:36:41 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:42 DEBUG : dir: Looking for writers 2021/12/13 06:36:42 DEBUG : : Looking for writers 2021/12/13 06:36:42 DEBUG : dir: reading active writers 2021/12/13 06:36:42 DEBUG : file1: reading active writers 2021/12/13 06:36:42 DEBUG : file2: reading active writers 2021/12/13 06:36:42 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:43 DEBUG : dir: Looking for writers 2021/12/13 06:36:43 DEBUG : : Looking for writers 2021/12/13 06:36:43 DEBUG : dir: reading active writers 2021/12/13 06:36:43 DEBUG : file1: reading active writers 2021/12/13 06:36:43 DEBUG : file2: reading active writers 2021/12/13 06:36:43 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:44 DEBUG : dir: Looking for writers 2021/12/13 06:36:44 DEBUG : : Looking for writers 2021/12/13 06:36:44 DEBUG : file2: reading active writers 2021/12/13 06:36:44 DEBUG : dir: reading active writers 2021/12/13 06:36:44 DEBUG : file1: reading active writers 2021/12/13 06:36:44 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:45 DEBUG : dir: Looking for writers 2021/12/13 06:36:45 DEBUG : : Looking for writers 2021/12/13 06:36:45 DEBUG : file2: reading active writers 2021/12/13 06:36:45 DEBUG : dir: reading active writers 2021/12/13 06:36:45 DEBUG : file1: reading active writers 2021/12/13 06:36:45 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:46 DEBUG : dir: Looking for writers 2021/12/13 06:36:46 DEBUG : : Looking for writers 2021/12/13 06:36:46 DEBUG : dir: reading active writers 2021/12/13 06:36:46 DEBUG : file1: reading active writers 2021/12/13 06:36:46 DEBUG : file2: reading active writers 2021/12/13 06:36:46 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:47 DEBUG : dir: Looking for writers 2021/12/13 06:36:47 DEBUG : : Looking for writers 2021/12/13 06:36:47 DEBUG : dir: reading active writers 2021/12/13 06:36:47 DEBUG : file1: reading active writers 2021/12/13 06:36:47 DEBUG : file2: reading active writers 2021/12/13 06:36:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:48 DEBUG : dir: Looking for writers 2021/12/13 06:36:48 DEBUG : : Looking for writers 2021/12/13 06:36:48 DEBUG : dir: reading active writers 2021/12/13 06:36:48 DEBUG : file1: reading active writers 2021/12/13 06:36:48 DEBUG : file2: reading active writers 2021/12/13 06:36:48 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:49 DEBUG : dir: Looking for writers 2021/12/13 06:36:49 DEBUG : : Looking for writers 2021/12/13 06:36:49 DEBUG : dir: reading active writers 2021/12/13 06:36:49 DEBUG : file1: reading active writers 2021/12/13 06:36:49 DEBUG : file2: reading active writers 2021/12/13 06:36:49 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:50 DEBUG : dir: Looking for writers 2021/12/13 06:36:50 DEBUG : : Looking for writers 2021/12/13 06:36:50 DEBUG : dir: reading active writers 2021/12/13 06:36:50 DEBUG : file1: reading active writers 2021/12/13 06:36:50 DEBUG : file2: reading active writers 2021/12/13 06:36:50 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:51 DEBUG : dir: Looking for writers 2021/12/13 06:36:51 DEBUG : : Looking for writers 2021/12/13 06:36:51 DEBUG : dir: reading active writers 2021/12/13 06:36:51 DEBUG : file1: reading active writers 2021/12/13 06:36:51 DEBUG : file2: reading active writers 2021/12/13 06:36:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:52 DEBUG : dir: Looking for writers 2021/12/13 06:36:52 DEBUG : : Looking for writers 2021/12/13 06:36:52 DEBUG : dir: reading active writers 2021/12/13 06:36:52 DEBUG : file1: reading active writers 2021/12/13 06:36:52 DEBUG : file2: reading active writers 2021/12/13 06:36:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:53 DEBUG : dir: Looking for writers 2021/12/13 06:36:53 DEBUG : : Looking for writers 2021/12/13 06:36:53 DEBUG : dir: reading active writers 2021/12/13 06:36:53 DEBUG : file1: reading active writers 2021/12/13 06:36:53 DEBUG : file2: reading active writers 2021/12/13 06:36:53 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:54 DEBUG : dir: Looking for writers 2021/12/13 06:36:54 DEBUG : : Looking for writers 2021/12/13 06:36:54 DEBUG : file1: reading active writers 2021/12/13 06:36:54 DEBUG : file2: reading active writers 2021/12/13 06:36:54 DEBUG : dir: reading active writers 2021/12/13 06:36:54 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:54 ERROR : Exiting even though 0 writers active and 2 cache items in use after 30s Cache{ "file2": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc000b0b840 name:file2 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724869183220471 ext:158736924618 loc:0x2a04b60} ATime:{wall:13863724869183322432 ext:158737026579 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 beingReset:false}, "file1": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc00014b380 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724869182472014 ext:158736176171 loc:0x2a04b60} ATime:{wall:13863724869182656320 ext:158736360468 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2021/12/13 06:36:54 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleWriteNoWrite (68.21s) === RUN TestRWFileHandleSizeTruncateExisting run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:36:55 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestRWFileHandleSizeTruncateExisting (0.66s) === RUN TestRWFileHandleSizeCreateExisting run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:36:55 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestRWFileHandleSizeCreateExisting (0.29s) === RUN TestRWFileModTimeWithOpenWriters run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:36:56 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:36:56 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:36:56 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:36:56 DEBUG : file1: newRWFileHandle: 2021/12/13 06:36:56 DEBUG : file1(0xc000089bc0): openPending: 2021/12/13 06:36:56 DEBUG : file1: vfs cache: truncate to size=0 2021/12/13 06:36:56 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:36:56 DEBUG : file1(0xc000089bc0): >openPending: err= 2021/12/13 06:36:56 DEBUG : file1: vfs cache: cancelling writeback (uploading false) 0xc0004e21c0 item 1 2021/12/13 06:36:56 DEBUG : file1: >newRWFileHandle: err= 2021/12/13 06:36:56 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:36:56 DEBUG : file1: >Open: fd=file1 (rw), err= 2021/12/13 06:36:56 DEBUG : file1: >OpenFile: fd=file1 (rw), err= run.go:287: Failed to put "time_test" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:36:56 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:36:56 DEBUG : dir: Looking for writers 2021/12/13 06:36:56 DEBUG : : Looking for writers 2021/12/13 06:36:56 DEBUG : dir: reading active writers 2021/12/13 06:36:56 DEBUG : file1: reading active writers 2021/12/13 06:36:56 DEBUG : file1: active writers 1 2021/12/13 06:36:56 DEBUG : file2: reading active writers 2021/12/13 06:36:56 DEBUG : Still 1 writers active and 2 cache items in use, waiting 10ms 2021/12/13 06:36:56 DEBUG : dir: Looking for writers 2021/12/13 06:36:56 DEBUG : : Looking for writers 2021/12/13 06:36:56 DEBUG : dir: reading active writers 2021/12/13 06:36:56 DEBUG : file1: reading active writers 2021/12/13 06:36:56 DEBUG : file1: active writers 1 2021/12/13 06:36:56 DEBUG : file2: reading active writers 2021/12/13 06:36:56 DEBUG : Still 1 writers active and 2 cache items in use, waiting 20ms 2021/12/13 06:36:56 DEBUG : dir: Looking for writers 2021/12/13 06:36:56 DEBUG : : Looking for writers 2021/12/13 06:36:56 DEBUG : dir: reading active writers 2021/12/13 06:36:56 DEBUG : file1: reading active writers 2021/12/13 06:36:56 DEBUG : file1: active writers 1 2021/12/13 06:36:56 DEBUG : file2: reading active writers 2021/12/13 06:36:56 DEBUG : Still 1 writers active and 2 cache items in use, waiting 40ms 2021/12/13 06:36:56 DEBUG : dir: Looking for writers 2021/12/13 06:36:56 DEBUG : : Looking for writers 2021/12/13 06:36:56 DEBUG : dir: reading active writers 2021/12/13 06:36:56 DEBUG : file1: reading active writers 2021/12/13 06:36:56 DEBUG : file1: active writers 1 2021/12/13 06:36:56 DEBUG : file2: reading active writers 2021/12/13 06:36:56 DEBUG : Still 1 writers active and 2 cache items in use, waiting 80ms 2021/12/13 06:36:56 DEBUG : dir: Looking for writers 2021/12/13 06:36:56 DEBUG : : Looking for writers 2021/12/13 06:36:56 DEBUG : dir: reading active writers 2021/12/13 06:36:56 DEBUG : file1: reading active writers 2021/12/13 06:36:56 DEBUG : file1: active writers 1 2021/12/13 06:36:56 DEBUG : file2: reading active writers 2021/12/13 06:36:56 DEBUG : Still 1 writers active and 2 cache items in use, waiting 160ms 2021/12/13 06:36:56 DEBUG : dir: Looking for writers 2021/12/13 06:36:56 DEBUG : : Looking for writers 2021/12/13 06:36:56 DEBUG : file2: reading active writers 2021/12/13 06:36:56 DEBUG : dir: reading active writers 2021/12/13 06:36:56 DEBUG : file1: reading active writers 2021/12/13 06:36:56 DEBUG : file1: active writers 1 2021/12/13 06:36:56 DEBUG : Still 1 writers active and 2 cache items in use, waiting 320ms 2021/12/13 06:36:57 DEBUG : dir: Looking for writers 2021/12/13 06:36:57 DEBUG : : Looking for writers 2021/12/13 06:36:57 DEBUG : dir: reading active writers 2021/12/13 06:36:57 DEBUG : file1: reading active writers 2021/12/13 06:36:57 DEBUG : file1: active writers 1 2021/12/13 06:36:57 DEBUG : file2: reading active writers 2021/12/13 06:36:57 DEBUG : Still 1 writers active and 2 cache items in use, waiting 640ms 2021/12/13 06:36:57 DEBUG : dir: Looking for writers 2021/12/13 06:36:57 DEBUG : : Looking for writers 2021/12/13 06:36:57 DEBUG : dir: reading active writers 2021/12/13 06:36:57 DEBUG : file1: reading active writers 2021/12/13 06:36:57 DEBUG : file1: active writers 1 2021/12/13 06:36:57 DEBUG : file2: reading active writers 2021/12/13 06:36:57 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:58 DEBUG : dir: Looking for writers 2021/12/13 06:36:58 DEBUG : : Looking for writers 2021/12/13 06:36:58 DEBUG : file1: reading active writers 2021/12/13 06:36:58 DEBUG : file1: active writers 1 2021/12/13 06:36:58 DEBUG : file2: reading active writers 2021/12/13 06:36:58 DEBUG : dir: reading active writers 2021/12/13 06:36:58 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:36:59 DEBUG : dir: Looking for writers 2021/12/13 06:36:59 DEBUG : : Looking for writers 2021/12/13 06:36:59 DEBUG : dir: reading active writers 2021/12/13 06:36:59 DEBUG : file1: reading active writers 2021/12/13 06:36:59 DEBUG : file1: active writers 1 2021/12/13 06:36:59 DEBUG : file2: reading active writers 2021/12/13 06:36:59 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:00 DEBUG : dir: Looking for writers 2021/12/13 06:37:00 DEBUG : : Looking for writers 2021/12/13 06:37:00 DEBUG : dir: reading active writers 2021/12/13 06:37:00 DEBUG : file1: reading active writers 2021/12/13 06:37:00 DEBUG : file1: active writers 1 2021/12/13 06:37:00 DEBUG : file2: reading active writers 2021/12/13 06:37:00 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:01 DEBUG : dir: Looking for writers 2021/12/13 06:37:01 DEBUG : : Looking for writers 2021/12/13 06:37:01 DEBUG : dir: reading active writers 2021/12/13 06:37:01 DEBUG : file1: reading active writers 2021/12/13 06:37:01 DEBUG : file1: active writers 1 2021/12/13 06:37:01 DEBUG : file2: reading active writers 2021/12/13 06:37:01 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:02 DEBUG : dir: Looking for writers 2021/12/13 06:37:02 DEBUG : : Looking for writers 2021/12/13 06:37:02 DEBUG : dir: reading active writers 2021/12/13 06:37:02 DEBUG : file1: reading active writers 2021/12/13 06:37:02 DEBUG : file1: active writers 1 2021/12/13 06:37:02 DEBUG : file2: reading active writers 2021/12/13 06:37:02 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:03 DEBUG : dir: Looking for writers 2021/12/13 06:37:03 DEBUG : : Looking for writers 2021/12/13 06:37:03 DEBUG : file2: reading active writers 2021/12/13 06:37:03 DEBUG : dir: reading active writers 2021/12/13 06:37:03 DEBUG : file1: reading active writers 2021/12/13 06:37:03 DEBUG : file1: active writers 1 2021/12/13 06:37:03 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:04 DEBUG : dir: Looking for writers 2021/12/13 06:37:04 DEBUG : : Looking for writers 2021/12/13 06:37:04 DEBUG : dir: reading active writers 2021/12/13 06:37:04 DEBUG : file1: reading active writers 2021/12/13 06:37:04 DEBUG : file1: active writers 1 2021/12/13 06:37:04 DEBUG : file2: reading active writers 2021/12/13 06:37:04 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:05 DEBUG : dir: Looking for writers 2021/12/13 06:37:05 DEBUG : : Looking for writers 2021/12/13 06:37:05 DEBUG : dir: reading active writers 2021/12/13 06:37:05 DEBUG : file1: reading active writers 2021/12/13 06:37:05 DEBUG : file1: active writers 1 2021/12/13 06:37:05 DEBUG : file2: reading active writers 2021/12/13 06:37:05 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:06 DEBUG : dir: Looking for writers 2021/12/13 06:37:06 DEBUG : : Looking for writers 2021/12/13 06:37:06 DEBUG : dir: reading active writers 2021/12/13 06:37:06 DEBUG : file1: reading active writers 2021/12/13 06:37:06 DEBUG : file1: active writers 1 2021/12/13 06:37:06 DEBUG : file2: reading active writers 2021/12/13 06:37:06 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:07 DEBUG : dir: Looking for writers 2021/12/13 06:37:07 DEBUG : : Looking for writers 2021/12/13 06:37:07 DEBUG : dir: reading active writers 2021/12/13 06:37:07 DEBUG : file1: reading active writers 2021/12/13 06:37:07 DEBUG : file1: active writers 1 2021/12/13 06:37:07 DEBUG : file2: reading active writers 2021/12/13 06:37:07 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:08 DEBUG : dir: Looking for writers 2021/12/13 06:37:08 DEBUG : : Looking for writers 2021/12/13 06:37:08 DEBUG : file1: reading active writers 2021/12/13 06:37:08 DEBUG : file1: active writers 1 2021/12/13 06:37:08 DEBUG : file2: reading active writers 2021/12/13 06:37:08 DEBUG : dir: reading active writers 2021/12/13 06:37:08 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:09 DEBUG : dir: Looking for writers 2021/12/13 06:37:09 DEBUG : : Looking for writers 2021/12/13 06:37:09 DEBUG : file2: reading active writers 2021/12/13 06:37:09 DEBUG : dir: reading active writers 2021/12/13 06:37:09 DEBUG : file1: reading active writers 2021/12/13 06:37:09 DEBUG : file1: active writers 1 2021/12/13 06:37:09 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:10 DEBUG : dir: Looking for writers 2021/12/13 06:37:10 DEBUG : : Looking for writers 2021/12/13 06:37:10 DEBUG : dir: reading active writers 2021/12/13 06:37:10 DEBUG : file1: reading active writers 2021/12/13 06:37:10 DEBUG : file1: active writers 1 2021/12/13 06:37:10 DEBUG : file2: reading active writers 2021/12/13 06:37:10 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:11 DEBUG : dir: Looking for writers 2021/12/13 06:37:11 DEBUG : : Looking for writers 2021/12/13 06:37:11 DEBUG : dir: reading active writers 2021/12/13 06:37:11 DEBUG : file1: reading active writers 2021/12/13 06:37:11 DEBUG : file1: active writers 1 2021/12/13 06:37:11 DEBUG : file2: reading active writers 2021/12/13 06:37:11 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:12 DEBUG : dir: Looking for writers 2021/12/13 06:37:12 DEBUG : : Looking for writers 2021/12/13 06:37:12 DEBUG : dir: reading active writers 2021/12/13 06:37:12 DEBUG : file1: reading active writers 2021/12/13 06:37:12 DEBUG : file1: active writers 1 2021/12/13 06:37:12 DEBUG : file2: reading active writers 2021/12/13 06:37:12 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:13 DEBUG : dir: Looking for writers 2021/12/13 06:37:13 DEBUG : : Looking for writers 2021/12/13 06:37:13 DEBUG : dir: reading active writers 2021/12/13 06:37:13 DEBUG : file1: reading active writers 2021/12/13 06:37:13 DEBUG : file1: active writers 1 2021/12/13 06:37:13 DEBUG : file2: reading active writers 2021/12/13 06:37:13 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:14 DEBUG : dir: Looking for writers 2021/12/13 06:37:14 DEBUG : : Looking for writers 2021/12/13 06:37:14 DEBUG : file2: reading active writers 2021/12/13 06:37:14 DEBUG : dir: reading active writers 2021/12/13 06:37:14 DEBUG : file1: reading active writers 2021/12/13 06:37:14 DEBUG : file1: active writers 1 2021/12/13 06:37:14 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:15 DEBUG : dir: Looking for writers 2021/12/13 06:37:15 DEBUG : : Looking for writers 2021/12/13 06:37:15 DEBUG : file2: reading active writers 2021/12/13 06:37:15 DEBUG : dir: reading active writers 2021/12/13 06:37:15 DEBUG : file1: reading active writers 2021/12/13 06:37:15 DEBUG : file1: active writers 1 2021/12/13 06:37:15 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:16 DEBUG : dir: Looking for writers 2021/12/13 06:37:16 DEBUG : : Looking for writers 2021/12/13 06:37:16 DEBUG : dir: reading active writers 2021/12/13 06:37:16 DEBUG : file1: reading active writers 2021/12/13 06:37:16 DEBUG : file1: active writers 1 2021/12/13 06:37:16 DEBUG : file2: reading active writers 2021/12/13 06:37:16 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:17 DEBUG : dir: Looking for writers 2021/12/13 06:37:17 DEBUG : : Looking for writers 2021/12/13 06:37:17 DEBUG : file1: reading active writers 2021/12/13 06:37:17 DEBUG : file1: active writers 1 2021/12/13 06:37:17 DEBUG : file2: reading active writers 2021/12/13 06:37:17 DEBUG : dir: reading active writers 2021/12/13 06:37:17 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:18 DEBUG : dir: Looking for writers 2021/12/13 06:37:18 DEBUG : : Looking for writers 2021/12/13 06:37:18 DEBUG : file1: reading active writers 2021/12/13 06:37:18 DEBUG : file1: active writers 1 2021/12/13 06:37:18 DEBUG : file2: reading active writers 2021/12/13 06:37:18 DEBUG : dir: reading active writers 2021/12/13 06:37:18 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:19 DEBUG : dir: Looking for writers 2021/12/13 06:37:19 DEBUG : : Looking for writers 2021/12/13 06:37:19 DEBUG : dir: reading active writers 2021/12/13 06:37:19 DEBUG : file1: reading active writers 2021/12/13 06:37:19 DEBUG : file1: active writers 1 2021/12/13 06:37:19 DEBUG : file2: reading active writers 2021/12/13 06:37:19 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:19 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2021/12/13 06:37:19 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file2 not removed, freed 0 bytes 2021/12/13 06:37:19 INFO : vfs cache: cleaned: objects 2 (was 2) in use 2, to upload 1, uploading 0, total size 0 (was 0) 2021/12/13 06:37:20 DEBUG : dir: Looking for writers 2021/12/13 06:37:20 DEBUG : : Looking for writers 2021/12/13 06:37:20 DEBUG : dir: reading active writers 2021/12/13 06:37:20 DEBUG : file1: reading active writers 2021/12/13 06:37:20 DEBUG : file1: active writers 1 2021/12/13 06:37:20 DEBUG : file2: reading active writers 2021/12/13 06:37:20 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:21 DEBUG : dir: Looking for writers 2021/12/13 06:37:21 DEBUG : : Looking for writers 2021/12/13 06:37:21 DEBUG : dir: reading active writers 2021/12/13 06:37:21 DEBUG : file1: reading active writers 2021/12/13 06:37:21 DEBUG : file1: active writers 1 2021/12/13 06:37:21 DEBUG : file2: reading active writers 2021/12/13 06:37:21 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:22 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/12/13 06:37:22 DEBUG : dir: Looking for writers 2021/12/13 06:37:22 DEBUG : : Looking for writers 2021/12/13 06:37:22 DEBUG : dir: reading active writers 2021/12/13 06:37:22 DEBUG : file1: reading active writers 2021/12/13 06:37:22 DEBUG : file1: active writers 1 2021/12/13 06:37:22 DEBUG : file2: reading active writers 2021/12/13 06:37:22 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:23 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/12/13 06:37:23 DEBUG : dir: Looking for writers 2021/12/13 06:37:23 DEBUG : : Looking for writers 2021/12/13 06:37:23 DEBUG : dir: reading active writers 2021/12/13 06:37:23 DEBUG : file1: reading active writers 2021/12/13 06:37:23 DEBUG : file1: active writers 1 2021/12/13 06:37:23 DEBUG : file2: reading active writers 2021/12/13 06:37:23 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:24 DEBUG : dir: Looking for writers 2021/12/13 06:37:24 DEBUG : : Looking for writers 2021/12/13 06:37:24 DEBUG : dir: reading active writers 2021/12/13 06:37:24 DEBUG : file1: reading active writers 2021/12/13 06:37:24 DEBUG : file1: active writers 1 2021/12/13 06:37:24 DEBUG : file2: reading active writers 2021/12/13 06:37:24 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:25 DEBUG : dir: Looking for writers 2021/12/13 06:37:25 DEBUG : : Looking for writers 2021/12/13 06:37:25 DEBUG : file1: reading active writers 2021/12/13 06:37:25 DEBUG : file1: active writers 1 2021/12/13 06:37:25 DEBUG : file2: reading active writers 2021/12/13 06:37:25 DEBUG : dir: reading active writers 2021/12/13 06:37:25 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2021/12/13 06:37:26 ERROR : Exiting even though 1 writers active and 2 cache items in use after 30s Cache{ "file1": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc00014b380 name:file1 opens:1 downloaders: o: fd:0xc000207488 modified:true info:{ModTime:{wall:13863724943503388363 ext:227895164860 loc:0x2a04b60} ATime:{wall:13863724943503388363 ext:227895164860 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, "file2": &{c:0xc00017a600 mu:{state:0 sema:0} cond:0xc000b0b840 name:file2 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13863724869183220471 ext:158736924618 loc:0x2a04b60} ATime:{wall:13863724869183322432 ext:158737026579 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 beingReset:false}, } 2021/12/13 06:37:26 DEBUG : >WaitForWriters: --- FAIL: TestRWFileModTimeWithOpenWriters (31.63s) === RUN TestCaseSensitivity run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" run.go:287: Failed to put "FiLeA" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" --- FAIL: TestCaseSensitivity (0.54s) === RUN TestVFSNew vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:137 Error: Not equal: expected: 0 actual : 5 Test: TestVFSNew run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:37:28 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': 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 : 5 Test: TestVFSNew 2021/12/13 06:37:28 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': 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 : 5 Test: TestVFSNew vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:159 Error: Not equal: expected: 1 actual : 5 Test: TestVFSNew 2021/12/13 06:37:28 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:37:28 DEBUG : : Looking for writers 2021/12/13 06:37:28 DEBUG : >WaitForWriters: vfs_test.go:134: Error Trace: vfs_test.go:134 vfs_test.go:163 Error: Not equal: expected: 0 actual : 5 Test: TestVFSNew --- FAIL: TestVFSNew (0.27s) === RUN TestVFSStat run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:37:28 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:37:28 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:37:28 DEBUG : : Looking for writers 2021/12/13 06:37:28 DEBUG : >WaitForWriters: --- FAIL: TestVFSStat (0.56s) === RUN TestVFSStatParent run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:37:29 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:37:29 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:37:29 DEBUG : : Looking for writers 2021/12/13 06:37:29 DEBUG : >WaitForWriters: --- FAIL: TestVFSStatParent (0.54s) === RUN TestVFSOpenFile run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:37:29 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "file1" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:37:29 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:37:29 DEBUG : : Looking for writers 2021/12/13 06:37:29 DEBUG : >WaitForWriters: --- FAIL: TestVFSOpenFile (0.54s) === RUN TestVFSRename run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:37:30 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache run.go:287: Failed to put "dir/file2" to "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'": upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:37:30 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:37:30 DEBUG : : Looking for writers 2021/12/13 06:37:30 DEBUG : >WaitForWriters: 2021/12/13 06:37:32 DEBUG : file2: vfs cache: starting upload 2021/12/13 06:37:32 ERROR : file2: vfs cache: failed to write metadata file: vfs cache item: failed to write metadata: open /home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tabiruy0sigitob6joyomug2/file2: no such file or directory 2021/12/13 06:37:32 INFO : file2: vfs cache: upload succeeded try #10 --- FAIL: TestVFSRename (1.77s) === RUN TestWriteFileHandleMethods run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:37:32 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:37:32 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:37:32 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:37:32 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:37:32 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:37:32 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:37:32 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:37:32 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2021/12/13 06:37:32 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2021/12/13 06:37:32 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2021/12/13 06:37:32 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': File to upload is small (5 bytes), uploading instead of streaming 2021/12/13 06:37:32 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:37:32 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 ) returned body: "" write_test.go:84: Error Trace: write_test.go:84 Error: Received unexpected error: upload error: HTTP error 402 (402 ) returned body: "" Test: TestWriteFileHandleMethods fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 write_test.go:97 Error: Should be true Test: TestWriteFileHandleMethods Messages: listing wrong, want file1 (5) got fstest.go:204: Not found "file1" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 write_test.go:97 Error: Not equal: expected: 0 actual : 1 Test: TestWriteFileHandleMethods Messages: 1 objects not found 2021/12/13 06:37:40 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:37:40 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:37:40 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:37:40 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:37:40 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:37:40 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:37:40 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': File to upload is small (0 bytes), uploading instead of streaming 2021/12/13 06:37:40 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:37:40 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 ) returned body: "" write_test.go:103: Error Trace: write_test.go:103 Error: Received unexpected error: upload error: HTTP error 402 (402 ) returned body: "" Test: TestWriteFileHandleMethods dir_test.go:252: Error Trace: dir_test.go:252 write_test.go:104 Error: Not equal: expected: []string{"file1,5,false"} actual : []string{"file1,0,false"} Diff: --- Expected +++ Actual @@ -1,3 +1,3 @@ ([]string) (len=1) { - (string) (len=13) "file1,5,false" + (string) (len=13) "file1,0,false" } Test: TestWriteFileHandleMethods 2021/12/13 06:37:40 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:37:40 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:37:40 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:37:40 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:37:40 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:37:40 DEBUG : : Added virtual directory entry vAddFile: "file1" write_test.go:111: Error Trace: write_test.go:111 Error: Not equal: expected: *errors.errorString(&errors.errorString{s:"permission denied"}) actual : () Test: TestWriteFileHandleMethods 2021/12/13 06:37:40 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:37:40 DEBUG : : Looking for writers 2021/12/13 06:37:40 DEBUG : file1: reading active writers 2021/12/13 06:37:40 DEBUG : file1: active writers 1 2021/12/13 06:37:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2021/12/13 06:37:40 DEBUG : : Looking for writers 2021/12/13 06:37:40 DEBUG : file1: reading active writers 2021/12/13 06:37:40 DEBUG : file1: active writers 1 2021/12/13 06:37:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2021/12/13 06:37:40 DEBUG : : Looking for writers 2021/12/13 06:37:40 DEBUG : file1: reading active writers 2021/12/13 06:37:40 DEBUG : file1: active writers 1 2021/12/13 06:37:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2021/12/13 06:37:40 DEBUG : : Looking for writers 2021/12/13 06:37:40 DEBUG : file1: reading active writers 2021/12/13 06:37:40 DEBUG : file1: active writers 1 2021/12/13 06:37:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2021/12/13 06:37:41 DEBUG : : Looking for writers 2021/12/13 06:37:41 DEBUG : file1: reading active writers 2021/12/13 06:37:41 DEBUG : file1: active writers 1 2021/12/13 06:37:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2021/12/13 06:37:41 DEBUG : : Looking for writers 2021/12/13 06:37:41 DEBUG : file1: reading active writers 2021/12/13 06:37:41 DEBUG : file1: active writers 1 2021/12/13 06:37:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2021/12/13 06:37:41 DEBUG : : Looking for writers 2021/12/13 06:37:41 DEBUG : file1: reading active writers 2021/12/13 06:37:41 DEBUG : file1: active writers 1 2021/12/13 06:37:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2021/12/13 06:37:42 DEBUG : : Looking for writers 2021/12/13 06:37:42 DEBUG : file1: reading active writers 2021/12/13 06:37:42 DEBUG : file1: active writers 1 2021/12/13 06:37:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:43 DEBUG : : Looking for writers 2021/12/13 06:37:43 DEBUG : file1: reading active writers 2021/12/13 06:37:43 DEBUG : file1: active writers 1 2021/12/13 06:37:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:44 DEBUG : : Looking for writers 2021/12/13 06:37:44 DEBUG : file1: reading active writers 2021/12/13 06:37:44 DEBUG : file1: active writers 1 2021/12/13 06:37:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:45 DEBUG : : Looking for writers 2021/12/13 06:37:45 DEBUG : file1: reading active writers 2021/12/13 06:37:45 DEBUG : file1: active writers 1 2021/12/13 06:37:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:46 DEBUG : : Looking for writers 2021/12/13 06:37:46 DEBUG : file1: reading active writers 2021/12/13 06:37:46 DEBUG : file1: active writers 1 2021/12/13 06:37:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:47 DEBUG : : Looking for writers 2021/12/13 06:37:47 DEBUG : file1: reading active writers 2021/12/13 06:37:47 DEBUG : file1: active writers 1 2021/12/13 06:37:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:48 DEBUG : : Looking for writers 2021/12/13 06:37:48 DEBUG : file1: reading active writers 2021/12/13 06:37:48 DEBUG : file1: active writers 1 2021/12/13 06:37:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:49 DEBUG : : Looking for writers 2021/12/13 06:37:49 DEBUG : file1: reading active writers 2021/12/13 06:37:49 DEBUG : file1: active writers 1 2021/12/13 06:37:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:50 DEBUG : : Looking for writers 2021/12/13 06:37:50 DEBUG : file1: reading active writers 2021/12/13 06:37:50 DEBUG : file1: active writers 1 2021/12/13 06:37:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:51 DEBUG : : Looking for writers 2021/12/13 06:37:51 DEBUG : file1: reading active writers 2021/12/13 06:37:51 DEBUG : file1: active writers 1 2021/12/13 06:37:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:52 DEBUG : : Looking for writers 2021/12/13 06:37:52 DEBUG : file1: reading active writers 2021/12/13 06:37:52 DEBUG : file1: active writers 1 2021/12/13 06:37:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:53 DEBUG : : Looking for writers 2021/12/13 06:37:53 DEBUG : file1: reading active writers 2021/12/13 06:37:53 DEBUG : file1: active writers 1 2021/12/13 06:37:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:54 DEBUG : : Looking for writers 2021/12/13 06:37:54 DEBUG : file1: reading active writers 2021/12/13 06:37:54 DEBUG : file1: active writers 1 2021/12/13 06:37:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:55 DEBUG : : Looking for writers 2021/12/13 06:37:55 DEBUG : file1: reading active writers 2021/12/13 06:37:55 DEBUG : file1: active writers 1 2021/12/13 06:37:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:56 DEBUG : : Looking for writers 2021/12/13 06:37:56 DEBUG : file1: reading active writers 2021/12/13 06:37:56 DEBUG : file1: active writers 1 2021/12/13 06:37:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:57 DEBUG : : Looking for writers 2021/12/13 06:37:57 DEBUG : file1: reading active writers 2021/12/13 06:37:57 DEBUG : file1: active writers 1 2021/12/13 06:37:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:58 DEBUG : : Looking for writers 2021/12/13 06:37:58 DEBUG : file1: reading active writers 2021/12/13 06:37:58 DEBUG : file1: active writers 1 2021/12/13 06:37:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:37:59 DEBUG : : Looking for writers 2021/12/13 06:37:59 DEBUG : file1: reading active writers 2021/12/13 06:37:59 DEBUG : file1: active writers 1 2021/12/13 06:37:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:00 DEBUG : : Looking for writers 2021/12/13 06:38:00 DEBUG : file1: reading active writers 2021/12/13 06:38:00 DEBUG : file1: active writers 1 2021/12/13 06:38:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:01 DEBUG : : Looking for writers 2021/12/13 06:38:01 DEBUG : file1: reading active writers 2021/12/13 06:38:01 DEBUG : file1: active writers 1 2021/12/13 06:38:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:02 DEBUG : : Looking for writers 2021/12/13 06:38:02 DEBUG : file1: reading active writers 2021/12/13 06:38:02 DEBUG : file1: active writers 1 2021/12/13 06:38:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:03 DEBUG : : Looking for writers 2021/12/13 06:38:03 DEBUG : file1: reading active writers 2021/12/13 06:38:03 DEBUG : file1: active writers 1 2021/12/13 06:38:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:04 DEBUG : : Looking for writers 2021/12/13 06:38:04 DEBUG : file1: reading active writers 2021/12/13 06:38:04 DEBUG : file1: active writers 1 2021/12/13 06:38:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:05 DEBUG : : Looking for writers 2021/12/13 06:38:05 DEBUG : file1: reading active writers 2021/12/13 06:38:05 DEBUG : file1: active writers 1 2021/12/13 06:38:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:06 DEBUG : : Looking for writers 2021/12/13 06:38:06 DEBUG : file1: reading active writers 2021/12/13 06:38:06 DEBUG : file1: active writers 1 2021/12/13 06:38:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:07 DEBUG : : Looking for writers 2021/12/13 06:38:07 DEBUG : file1: reading active writers 2021/12/13 06:38:07 DEBUG : file1: active writers 1 2021/12/13 06:38:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:08 DEBUG : : Looking for writers 2021/12/13 06:38:08 DEBUG : file1: reading active writers 2021/12/13 06:38:08 DEBUG : file1: active writers 1 2021/12/13 06:38:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:09 DEBUG : : Looking for writers 2021/12/13 06:38:09 DEBUG : file1: reading active writers 2021/12/13 06:38:09 DEBUG : file1: active writers 1 2021/12/13 06:38:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:10 DEBUG : : Looking for writers 2021/12/13 06:38:10 DEBUG : file1: reading active writers 2021/12/13 06:38:10 DEBUG : file1: active writers 1 2021/12/13 06:38:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:10 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2021/12/13 06:38:10 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleMethods (39.12s) === RUN TestWriteFileHandleWriteAt run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:38:11 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:38:11 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:38:11 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:38:11 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:38:11 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:38:11 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:38:11 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:38:11 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2021/12/13 06:38:12 DEBUG : file1: aborting in-sequence write wait, off=100 2021/12/13 06:38:12 DEBUG : file1: failed to wait for in-sequence write to 100 2021/12/13 06:38:12 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2021/12/13 06:38:12 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': File to upload is small (11 bytes), uploading instead of streaming 2021/12/13 06:38:12 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:38:12 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 ) returned body: "" write_test.go:162: Error Trace: write_test.go:162 Error: Received unexpected error: upload error: HTTP error 402 (402 ) returned body: "" Test: TestWriteFileHandleWriteAt 2021/12/13 06:38:12 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 2s for list eventual consistency: 2/3 fstest.go:302: Flushing the directory cache fstest.go:299: Sleeping for 4s for list eventual consistency: 3/3 fstest.go:302: Flushing the directory cache fstest.go:306: Error Trace: fstest.go:306 fstest.go:339 write_test.go:176 Error: Should be true Test: TestWriteFileHandleWriteAt Messages: listing wrong, want file1 (11) got fstest.go:204: Not found "file1" fstest.go:207: Error Trace: fstest.go:207 fstest.go:311 fstest.go:339 write_test.go:176 Error: Not equal: expected: 0 actual : 1 Test: TestWriteFileHandleWriteAt Messages: 1 objects not found 2021/12/13 06:38:20 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:38:20 DEBUG : : Looking for writers 2021/12/13 06:38:20 DEBUG : file1: reading active writers 2021/12/13 06:38:20 DEBUG : file1: active writers 1 2021/12/13 06:38:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2021/12/13 06:38:20 DEBUG : : Looking for writers 2021/12/13 06:38:20 DEBUG : file1: reading active writers 2021/12/13 06:38:20 DEBUG : file1: active writers 1 2021/12/13 06:38:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2021/12/13 06:38:20 DEBUG : : Looking for writers 2021/12/13 06:38:20 DEBUG : file1: reading active writers 2021/12/13 06:38:20 DEBUG : file1: active writers 1 2021/12/13 06:38:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2021/12/13 06:38:20 DEBUG : : Looking for writers 2021/12/13 06:38:20 DEBUG : file1: reading active writers 2021/12/13 06:38:20 DEBUG : file1: active writers 1 2021/12/13 06:38:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2021/12/13 06:38:20 DEBUG : : Looking for writers 2021/12/13 06:38:20 DEBUG : file1: reading active writers 2021/12/13 06:38:20 DEBUG : file1: active writers 1 2021/12/13 06:38:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2021/12/13 06:38:20 DEBUG : : Looking for writers 2021/12/13 06:38:20 DEBUG : file1: reading active writers 2021/12/13 06:38:20 DEBUG : file1: active writers 1 2021/12/13 06:38:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2021/12/13 06:38:20 DEBUG : : Looking for writers 2021/12/13 06:38:20 DEBUG : file1: reading active writers 2021/12/13 06:38:20 DEBUG : file1: active writers 1 2021/12/13 06:38:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2021/12/13 06:38:21 DEBUG : : Looking for writers 2021/12/13 06:38:21 DEBUG : file1: reading active writers 2021/12/13 06:38:21 DEBUG : file1: active writers 1 2021/12/13 06:38:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:22 DEBUG : : Looking for writers 2021/12/13 06:38:22 DEBUG : file1: reading active writers 2021/12/13 06:38:22 DEBUG : file1: active writers 1 2021/12/13 06:38:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:23 DEBUG : : Looking for writers 2021/12/13 06:38:23 DEBUG : file1: reading active writers 2021/12/13 06:38:23 DEBUG : file1: active writers 1 2021/12/13 06:38:23 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:24 DEBUG : : Looking for writers 2021/12/13 06:38:24 DEBUG : file1: reading active writers 2021/12/13 06:38:24 DEBUG : file1: active writers 1 2021/12/13 06:38:24 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:25 DEBUG : : Looking for writers 2021/12/13 06:38:25 DEBUG : file1: reading active writers 2021/12/13 06:38:25 DEBUG : file1: active writers 1 2021/12/13 06:38:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:26 DEBUG : : Looking for writers 2021/12/13 06:38:26 DEBUG : file1: reading active writers 2021/12/13 06:38:26 DEBUG : file1: active writers 1 2021/12/13 06:38:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:27 DEBUG : : Looking for writers 2021/12/13 06:38:27 DEBUG : file1: reading active writers 2021/12/13 06:38:27 DEBUG : file1: active writers 1 2021/12/13 06:38:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:28 DEBUG : : Looking for writers 2021/12/13 06:38:28 DEBUG : file1: reading active writers 2021/12/13 06:38:28 DEBUG : file1: active writers 1 2021/12/13 06:38:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:29 DEBUG : : Looking for writers 2021/12/13 06:38:29 DEBUG : file1: reading active writers 2021/12/13 06:38:29 DEBUG : file1: active writers 1 2021/12/13 06:38:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:30 DEBUG : : Looking for writers 2021/12/13 06:38:30 DEBUG : file1: reading active writers 2021/12/13 06:38:30 DEBUG : file1: active writers 1 2021/12/13 06:38:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:31 DEBUG : : Looking for writers 2021/12/13 06:38:31 DEBUG : file1: reading active writers 2021/12/13 06:38:31 DEBUG : file1: active writers 1 2021/12/13 06:38:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:32 DEBUG : : Looking for writers 2021/12/13 06:38:32 DEBUG : file1: reading active writers 2021/12/13 06:38:32 DEBUG : file1: active writers 1 2021/12/13 06:38:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:33 DEBUG : : Looking for writers 2021/12/13 06:38:33 DEBUG : file1: reading active writers 2021/12/13 06:38:33 DEBUG : file1: active writers 1 2021/12/13 06:38:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:34 DEBUG : : Looking for writers 2021/12/13 06:38:34 DEBUG : file1: reading active writers 2021/12/13 06:38:34 DEBUG : file1: active writers 1 2021/12/13 06:38:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:35 DEBUG : : Looking for writers 2021/12/13 06:38:35 DEBUG : file1: reading active writers 2021/12/13 06:38:35 DEBUG : file1: active writers 1 2021/12/13 06:38:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:36 DEBUG : : Looking for writers 2021/12/13 06:38:36 DEBUG : file1: reading active writers 2021/12/13 06:38:36 DEBUG : file1: active writers 1 2021/12/13 06:38:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:37 DEBUG : : Looking for writers 2021/12/13 06:38:37 DEBUG : file1: reading active writers 2021/12/13 06:38:37 DEBUG : file1: active writers 1 2021/12/13 06:38:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:38 DEBUG : : Looking for writers 2021/12/13 06:38:38 DEBUG : file1: reading active writers 2021/12/13 06:38:38 DEBUG : file1: active writers 1 2021/12/13 06:38:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:39 DEBUG : : Looking for writers 2021/12/13 06:38:39 DEBUG : file1: reading active writers 2021/12/13 06:38:39 DEBUG : file1: active writers 1 2021/12/13 06:38:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:40 DEBUG : : Looking for writers 2021/12/13 06:38:40 DEBUG : file1: reading active writers 2021/12/13 06:38:40 DEBUG : file1: active writers 1 2021/12/13 06:38:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:41 DEBUG : : Looking for writers 2021/12/13 06:38:41 DEBUG : file1: reading active writers 2021/12/13 06:38:41 DEBUG : file1: active writers 1 2021/12/13 06:38:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:42 DEBUG : : Looking for writers 2021/12/13 06:38:42 DEBUG : file1: reading active writers 2021/12/13 06:38:42 DEBUG : file1: active writers 1 2021/12/13 06:38:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:43 DEBUG : : Looking for writers 2021/12/13 06:38:43 DEBUG : file1: reading active writers 2021/12/13 06:38:43 DEBUG : file1: active writers 1 2021/12/13 06:38:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:44 DEBUG : : Looking for writers 2021/12/13 06:38:44 DEBUG : file1: reading active writers 2021/12/13 06:38:44 DEBUG : file1: active writers 1 2021/12/13 06:38:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:45 DEBUG : : Looking for writers 2021/12/13 06:38:45 DEBUG : file1: reading active writers 2021/12/13 06:38:45 DEBUG : file1: active writers 1 2021/12/13 06:38:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:46 DEBUG : : Looking for writers 2021/12/13 06:38:46 DEBUG : file1: reading active writers 2021/12/13 06:38:46 DEBUG : file1: active writers 1 2021/12/13 06:38:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:47 DEBUG : : Looking for writers 2021/12/13 06:38:47 DEBUG : file1: reading active writers 2021/12/13 06:38:47 DEBUG : file1: active writers 1 2021/12/13 06:38:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:48 DEBUG : : Looking for writers 2021/12/13 06:38:48 DEBUG : file1: reading active writers 2021/12/13 06:38:48 DEBUG : file1: active writers 1 2021/12/13 06:38:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:49 DEBUG : : Looking for writers 2021/12/13 06:38:49 DEBUG : file1: reading active writers 2021/12/13 06:38:49 DEBUG : file1: active writers 1 2021/12/13 06:38:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:50 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2021/12/13 06:38:50 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleWriteAt (39.71s) === RUN TestWriteFileHandleFlush run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:38:50 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:38:50 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:38:50 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:38:50 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:38:50 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:38:50 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:38:50 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2021/12/13 06:38:50 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:38:50 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': File to upload is small (5 bytes), uploading instead of streaming 2021/12/13 06:38:51 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:38:51 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:38:51 ERROR : file1: WriteFileHandle.Flush error: upload error: HTTP error 402 (402 ) returned body: "" write_test.go:198: Error Trace: write_test.go:198 Error: Received unexpected error: upload error: HTTP error 402 (402 ) returned body: "" Test: TestWriteFileHandleFlush 2021/12/13 06:38:51 DEBUG : file1: WriteFileHandle.Flush nothing to do 2021/12/13 06:38:51 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:38:51 DEBUG : : Looking for writers 2021/12/13 06:38:51 DEBUG : file1: reading active writers 2021/12/13 06:38:51 DEBUG : file1: active writers 1 2021/12/13 06:38:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2021/12/13 06:38:51 DEBUG : : Looking for writers 2021/12/13 06:38:51 DEBUG : file1: reading active writers 2021/12/13 06:38:51 DEBUG : file1: active writers 1 2021/12/13 06:38:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2021/12/13 06:38:51 DEBUG : : Looking for writers 2021/12/13 06:38:51 DEBUG : file1: reading active writers 2021/12/13 06:38:51 DEBUG : file1: active writers 1 2021/12/13 06:38:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2021/12/13 06:38:51 DEBUG : : Looking for writers 2021/12/13 06:38:51 DEBUG : file1: reading active writers 2021/12/13 06:38:51 DEBUG : file1: active writers 1 2021/12/13 06:38:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2021/12/13 06:38:51 DEBUG : : Looking for writers 2021/12/13 06:38:51 DEBUG : file1: reading active writers 2021/12/13 06:38:51 DEBUG : file1: active writers 1 2021/12/13 06:38:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2021/12/13 06:38:51 DEBUG : : Looking for writers 2021/12/13 06:38:51 DEBUG : file1: reading active writers 2021/12/13 06:38:51 DEBUG : file1: active writers 1 2021/12/13 06:38:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2021/12/13 06:38:51 DEBUG : : Looking for writers 2021/12/13 06:38:51 DEBUG : file1: reading active writers 2021/12/13 06:38:51 DEBUG : file1: active writers 1 2021/12/13 06:38:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2021/12/13 06:38:52 DEBUG : : Looking for writers 2021/12/13 06:38:52 DEBUG : file1: reading active writers 2021/12/13 06:38:52 DEBUG : file1: active writers 1 2021/12/13 06:38:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:53 DEBUG : : Looking for writers 2021/12/13 06:38:53 DEBUG : file1: reading active writers 2021/12/13 06:38:53 DEBUG : file1: active writers 1 2021/12/13 06:38:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:54 DEBUG : : Looking for writers 2021/12/13 06:38:54 DEBUG : file1: reading active writers 2021/12/13 06:38:54 DEBUG : file1: active writers 1 2021/12/13 06:38:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:55 DEBUG : : Looking for writers 2021/12/13 06:38:55 DEBUG : file1: reading active writers 2021/12/13 06:38:55 DEBUG : file1: active writers 1 2021/12/13 06:38:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:56 DEBUG : : Looking for writers 2021/12/13 06:38:56 DEBUG : file1: reading active writers 2021/12/13 06:38:56 DEBUG : file1: active writers 1 2021/12/13 06:38:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:57 DEBUG : : Looking for writers 2021/12/13 06:38:57 DEBUG : file1: reading active writers 2021/12/13 06:38:57 DEBUG : file1: active writers 1 2021/12/13 06:38:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:58 DEBUG : : Looking for writers 2021/12/13 06:38:58 DEBUG : file1: reading active writers 2021/12/13 06:38:58 DEBUG : file1: active writers 1 2021/12/13 06:38:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:38:59 DEBUG : : Looking for writers 2021/12/13 06:38:59 DEBUG : file1: reading active writers 2021/12/13 06:38:59 DEBUG : file1: active writers 1 2021/12/13 06:38:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:00 DEBUG : : Looking for writers 2021/12/13 06:39:00 DEBUG : file1: reading active writers 2021/12/13 06:39:00 DEBUG : file1: active writers 1 2021/12/13 06:39:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:01 DEBUG : : Looking for writers 2021/12/13 06:39:01 DEBUG : file1: reading active writers 2021/12/13 06:39:01 DEBUG : file1: active writers 1 2021/12/13 06:39:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:02 DEBUG : : Looking for writers 2021/12/13 06:39:02 DEBUG : file1: reading active writers 2021/12/13 06:39:02 DEBUG : file1: active writers 1 2021/12/13 06:39:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:03 DEBUG : : Looking for writers 2021/12/13 06:39:03 DEBUG : file1: reading active writers 2021/12/13 06:39:03 DEBUG : file1: active writers 1 2021/12/13 06:39:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:04 DEBUG : : Looking for writers 2021/12/13 06:39:04 DEBUG : file1: reading active writers 2021/12/13 06:39:04 DEBUG : file1: active writers 1 2021/12/13 06:39:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:05 DEBUG : : Looking for writers 2021/12/13 06:39:05 DEBUG : file1: reading active writers 2021/12/13 06:39:05 DEBUG : file1: active writers 1 2021/12/13 06:39:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:06 DEBUG : : Looking for writers 2021/12/13 06:39:06 DEBUG : file1: reading active writers 2021/12/13 06:39:06 DEBUG : file1: active writers 1 2021/12/13 06:39:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:07 DEBUG : : Looking for writers 2021/12/13 06:39:07 DEBUG : file1: reading active writers 2021/12/13 06:39:07 DEBUG : file1: active writers 1 2021/12/13 06:39:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:08 DEBUG : : Looking for writers 2021/12/13 06:39:08 DEBUG : file1: reading active writers 2021/12/13 06:39:08 DEBUG : file1: active writers 1 2021/12/13 06:39:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:09 DEBUG : : Looking for writers 2021/12/13 06:39:09 DEBUG : file1: reading active writers 2021/12/13 06:39:09 DEBUG : file1: active writers 1 2021/12/13 06:39:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:10 DEBUG : : Looking for writers 2021/12/13 06:39:10 DEBUG : file1: reading active writers 2021/12/13 06:39:10 DEBUG : file1: active writers 1 2021/12/13 06:39:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:11 DEBUG : : Looking for writers 2021/12/13 06:39:11 DEBUG : file1: reading active writers 2021/12/13 06:39:11 DEBUG : file1: active writers 1 2021/12/13 06:39:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:12 DEBUG : : Looking for writers 2021/12/13 06:39:12 DEBUG : file1: reading active writers 2021/12/13 06:39:12 DEBUG : file1: active writers 1 2021/12/13 06:39:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:13 DEBUG : : Looking for writers 2021/12/13 06:39:13 DEBUG : file1: reading active writers 2021/12/13 06:39:13 DEBUG : file1: active writers 1 2021/12/13 06:39:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:14 DEBUG : : Looking for writers 2021/12/13 06:39:14 DEBUG : file1: reading active writers 2021/12/13 06:39:14 DEBUG : file1: active writers 1 2021/12/13 06:39:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:15 DEBUG : : Looking for writers 2021/12/13 06:39:15 DEBUG : file1: reading active writers 2021/12/13 06:39:15 DEBUG : file1: active writers 1 2021/12/13 06:39:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:16 DEBUG : : Looking for writers 2021/12/13 06:39:16 DEBUG : file1: reading active writers 2021/12/13 06:39:16 DEBUG : file1: active writers 1 2021/12/13 06:39:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:17 DEBUG : : Looking for writers 2021/12/13 06:39:17 DEBUG : file1: reading active writers 2021/12/13 06:39:17 DEBUG : file1: active writers 1 2021/12/13 06:39:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:18 DEBUG : : Looking for writers 2021/12/13 06:39:18 DEBUG : file1: reading active writers 2021/12/13 06:39:18 DEBUG : file1: active writers 1 2021/12/13 06:39:18 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:19 DEBUG : : Looking for writers 2021/12/13 06:39:19 DEBUG : file1: reading active writers 2021/12/13 06:39:19 DEBUG : file1: active writers 1 2021/12/13 06:39:19 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:20 DEBUG : : Looking for writers 2021/12/13 06:39:20 DEBUG : file1: reading active writers 2021/12/13 06:39:20 DEBUG : file1: active writers 1 2021/12/13 06:39:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:21 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2021/12/13 06:39:21 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleFlush (30.57s) === RUN TestWriteFileHandleRelease run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:39:21 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:39:21 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:39:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:39:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:39:21 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:39:21 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:39:21 DEBUG : file1: WriteFileHandle.Release closing 2021/12/13 06:39:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:39:21 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': File to upload is small (0 bytes), uploading instead of streaming 2021/12/13 06:39:21 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:39:21 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:39:21 ERROR : file1: WriteFileHandle.Release error: upload error: HTTP error 402 (402 ) returned body: "" write_test.go:222: Error Trace: write_test.go:222 Error: Received unexpected error: upload error: HTTP error 402 (402 ) returned body: "" Test: TestWriteFileHandleRelease 2021/12/13 06:39:21 DEBUG : file1: WriteFileHandle.Release nothing to do 2021/12/13 06:39:21 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:39:21 DEBUG : : Looking for writers 2021/12/13 06:39:21 DEBUG : file1: reading active writers 2021/12/13 06:39:21 DEBUG : file1: active writers 1 2021/12/13 06:39:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2021/12/13 06:39:21 DEBUG : : Looking for writers 2021/12/13 06:39:21 DEBUG : file1: reading active writers 2021/12/13 06:39:21 DEBUG : file1: active writers 1 2021/12/13 06:39:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2021/12/13 06:39:21 DEBUG : : Looking for writers 2021/12/13 06:39:21 DEBUG : file1: reading active writers 2021/12/13 06:39:21 DEBUG : file1: active writers 1 2021/12/13 06:39:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2021/12/13 06:39:21 DEBUG : : Looking for writers 2021/12/13 06:39:21 DEBUG : file1: reading active writers 2021/12/13 06:39:21 DEBUG : file1: active writers 1 2021/12/13 06:39:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2021/12/13 06:39:21 DEBUG : : Looking for writers 2021/12/13 06:39:21 DEBUG : file1: reading active writers 2021/12/13 06:39:21 DEBUG : file1: active writers 1 2021/12/13 06:39:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2021/12/13 06:39:21 DEBUG : : Looking for writers 2021/12/13 06:39:21 DEBUG : file1: reading active writers 2021/12/13 06:39:21 DEBUG : file1: active writers 1 2021/12/13 06:39:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2021/12/13 06:39:22 DEBUG : : Looking for writers 2021/12/13 06:39:22 DEBUG : file1: reading active writers 2021/12/13 06:39:22 DEBUG : file1: active writers 1 2021/12/13 06:39:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2021/12/13 06:39:22 DEBUG : : Looking for writers 2021/12/13 06:39:22 DEBUG : file1: reading active writers 2021/12/13 06:39:22 DEBUG : file1: active writers 1 2021/12/13 06:39:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:23 DEBUG : : Looking for writers 2021/12/13 06:39:23 DEBUG : file1: reading active writers 2021/12/13 06:39:23 DEBUG : file1: active writers 1 2021/12/13 06:39:23 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:24 DEBUG : : Looking for writers 2021/12/13 06:39:24 DEBUG : file1: reading active writers 2021/12/13 06:39:24 DEBUG : file1: active writers 1 2021/12/13 06:39:24 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:25 DEBUG : : Looking for writers 2021/12/13 06:39:25 DEBUG : file1: reading active writers 2021/12/13 06:39:25 DEBUG : file1: active writers 1 2021/12/13 06:39:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:26 DEBUG : : Looking for writers 2021/12/13 06:39:26 DEBUG : file1: reading active writers 2021/12/13 06:39:26 DEBUG : file1: active writers 1 2021/12/13 06:39:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:27 DEBUG : : Looking for writers 2021/12/13 06:39:27 DEBUG : file1: reading active writers 2021/12/13 06:39:27 DEBUG : file1: active writers 1 2021/12/13 06:39:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:28 DEBUG : : Looking for writers 2021/12/13 06:39:28 DEBUG : file1: reading active writers 2021/12/13 06:39:28 DEBUG : file1: active writers 1 2021/12/13 06:39:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:29 DEBUG : : Looking for writers 2021/12/13 06:39:29 DEBUG : file1: reading active writers 2021/12/13 06:39:29 DEBUG : file1: active writers 1 2021/12/13 06:39:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:30 DEBUG : : Looking for writers 2021/12/13 06:39:30 DEBUG : file1: reading active writers 2021/12/13 06:39:30 DEBUG : file1: active writers 1 2021/12/13 06:39:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:31 DEBUG : : Looking for writers 2021/12/13 06:39:31 DEBUG : file1: reading active writers 2021/12/13 06:39:31 DEBUG : file1: active writers 1 2021/12/13 06:39:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:32 DEBUG : : Looking for writers 2021/12/13 06:39:32 DEBUG : file1: reading active writers 2021/12/13 06:39:32 DEBUG : file1: active writers 1 2021/12/13 06:39:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:33 DEBUG : : Looking for writers 2021/12/13 06:39:33 DEBUG : file1: reading active writers 2021/12/13 06:39:33 DEBUG : file1: active writers 1 2021/12/13 06:39:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:34 DEBUG : : Looking for writers 2021/12/13 06:39:34 DEBUG : file1: reading active writers 2021/12/13 06:39:34 DEBUG : file1: active writers 1 2021/12/13 06:39:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:35 DEBUG : : Looking for writers 2021/12/13 06:39:35 DEBUG : file1: reading active writers 2021/12/13 06:39:35 DEBUG : file1: active writers 1 2021/12/13 06:39:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:36 DEBUG : : Looking for writers 2021/12/13 06:39:36 DEBUG : file1: reading active writers 2021/12/13 06:39:36 DEBUG : file1: active writers 1 2021/12/13 06:39:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:37 DEBUG : : Looking for writers 2021/12/13 06:39:37 DEBUG : file1: reading active writers 2021/12/13 06:39:37 DEBUG : file1: active writers 1 2021/12/13 06:39:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:38 DEBUG : : Looking for writers 2021/12/13 06:39:38 DEBUG : file1: reading active writers 2021/12/13 06:39:38 DEBUG : file1: active writers 1 2021/12/13 06:39:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:39 DEBUG : : Looking for writers 2021/12/13 06:39:39 DEBUG : file1: reading active writers 2021/12/13 06:39:39 DEBUG : file1: active writers 1 2021/12/13 06:39:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:40 DEBUG : : Looking for writers 2021/12/13 06:39:40 DEBUG : file1: reading active writers 2021/12/13 06:39:40 DEBUG : file1: active writers 1 2021/12/13 06:39:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:41 DEBUG : : Looking for writers 2021/12/13 06:39:41 DEBUG : file1: reading active writers 2021/12/13 06:39:41 DEBUG : file1: active writers 1 2021/12/13 06:39:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:42 DEBUG : : Looking for writers 2021/12/13 06:39:42 DEBUG : file1: reading active writers 2021/12/13 06:39:42 DEBUG : file1: active writers 1 2021/12/13 06:39:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:43 DEBUG : : Looking for writers 2021/12/13 06:39:43 DEBUG : file1: reading active writers 2021/12/13 06:39:43 DEBUG : file1: active writers 1 2021/12/13 06:39:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:44 DEBUG : : Looking for writers 2021/12/13 06:39:44 DEBUG : file1: reading active writers 2021/12/13 06:39:44 DEBUG : file1: active writers 1 2021/12/13 06:39:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:45 DEBUG : : Looking for writers 2021/12/13 06:39:45 DEBUG : file1: reading active writers 2021/12/13 06:39:45 DEBUG : file1: active writers 1 2021/12/13 06:39:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:46 DEBUG : : Looking for writers 2021/12/13 06:39:46 DEBUG : file1: reading active writers 2021/12/13 06:39:46 DEBUG : file1: active writers 1 2021/12/13 06:39:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:47 DEBUG : : Looking for writers 2021/12/13 06:39:47 DEBUG : file1: reading active writers 2021/12/13 06:39:47 DEBUG : file1: active writers 1 2021/12/13 06:39:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:48 DEBUG : : Looking for writers 2021/12/13 06:39:48 DEBUG : file1: reading active writers 2021/12/13 06:39:48 DEBUG : file1: active writers 1 2021/12/13 06:39:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:49 DEBUG : : Looking for writers 2021/12/13 06:39:49 DEBUG : file1: reading active writers 2021/12/13 06:39:49 DEBUG : file1: active writers 1 2021/12/13 06:39:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:50 DEBUG : : Looking for writers 2021/12/13 06:39:50 DEBUG : file1: reading active writers 2021/12/13 06:39:50 DEBUG : file1: active writers 1 2021/12/13 06:39:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:51 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2021/12/13 06:39:51 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleRelease (30.54s) === RUN TestWriteFileModTimeWithOpenWriters run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:39:51 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:39:51 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:39:51 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:39:51 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:39:51 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:39:51 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:39:51 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:39:51 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': File to upload is small (2 bytes), uploading instead of streaming 2021/12/13 06:39:52 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:39:52 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 ) returned body: "" write_test.go:277: Error Trace: write_test.go:277 Error: Received unexpected error: upload error: HTTP error 402 (402 ) returned body: "" Test: TestWriteFileModTimeWithOpenWriters 2021/12/13 06:39:52 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:39:52 DEBUG : : Looking for writers 2021/12/13 06:39:52 DEBUG : file1: reading active writers 2021/12/13 06:39:52 DEBUG : file1: active writers 1 2021/12/13 06:39:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2021/12/13 06:39:52 DEBUG : : Looking for writers 2021/12/13 06:39:52 DEBUG : file1: reading active writers 2021/12/13 06:39:52 DEBUG : file1: active writers 1 2021/12/13 06:39:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2021/12/13 06:39:52 DEBUG : : Looking for writers 2021/12/13 06:39:52 DEBUG : file1: reading active writers 2021/12/13 06:39:52 DEBUG : file1: active writers 1 2021/12/13 06:39:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2021/12/13 06:39:52 DEBUG : : Looking for writers 2021/12/13 06:39:52 DEBUG : file1: reading active writers 2021/12/13 06:39:52 DEBUG : file1: active writers 1 2021/12/13 06:39:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2021/12/13 06:39:52 DEBUG : : Looking for writers 2021/12/13 06:39:52 DEBUG : file1: reading active writers 2021/12/13 06:39:52 DEBUG : file1: active writers 1 2021/12/13 06:39:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2021/12/13 06:39:52 DEBUG : : Looking for writers 2021/12/13 06:39:52 DEBUG : file1: reading active writers 2021/12/13 06:39:52 DEBUG : file1: active writers 1 2021/12/13 06:39:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2021/12/13 06:39:52 DEBUG : : Looking for writers 2021/12/13 06:39:52 DEBUG : file1: reading active writers 2021/12/13 06:39:52 DEBUG : file1: active writers 1 2021/12/13 06:39:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2021/12/13 06:39:53 DEBUG : : Looking for writers 2021/12/13 06:39:53 DEBUG : file1: reading active writers 2021/12/13 06:39:53 DEBUG : file1: active writers 1 2021/12/13 06:39:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:54 DEBUG : : Looking for writers 2021/12/13 06:39:54 DEBUG : file1: reading active writers 2021/12/13 06:39:54 DEBUG : file1: active writers 1 2021/12/13 06:39:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:55 DEBUG : : Looking for writers 2021/12/13 06:39:55 DEBUG : file1: reading active writers 2021/12/13 06:39:55 DEBUG : file1: active writers 1 2021/12/13 06:39:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:56 DEBUG : : Looking for writers 2021/12/13 06:39:56 DEBUG : file1: reading active writers 2021/12/13 06:39:56 DEBUG : file1: active writers 1 2021/12/13 06:39:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:57 DEBUG : : Looking for writers 2021/12/13 06:39:57 DEBUG : file1: reading active writers 2021/12/13 06:39:57 DEBUG : file1: active writers 1 2021/12/13 06:39:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:58 DEBUG : : Looking for writers 2021/12/13 06:39:58 DEBUG : file1: reading active writers 2021/12/13 06:39:58 DEBUG : file1: active writers 1 2021/12/13 06:39:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:39:59 DEBUG : : Looking for writers 2021/12/13 06:39:59 DEBUG : file1: reading active writers 2021/12/13 06:39:59 DEBUG : file1: active writers 1 2021/12/13 06:39:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:00 DEBUG : : Looking for writers 2021/12/13 06:40:00 DEBUG : file1: reading active writers 2021/12/13 06:40:00 DEBUG : file1: active writers 1 2021/12/13 06:40:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:01 DEBUG : : Looking for writers 2021/12/13 06:40:01 DEBUG : file1: reading active writers 2021/12/13 06:40:01 DEBUG : file1: active writers 1 2021/12/13 06:40:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:02 DEBUG : : Looking for writers 2021/12/13 06:40:02 DEBUG : file1: reading active writers 2021/12/13 06:40:02 DEBUG : file1: active writers 1 2021/12/13 06:40:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:03 DEBUG : : Looking for writers 2021/12/13 06:40:03 DEBUG : file1: reading active writers 2021/12/13 06:40:03 DEBUG : file1: active writers 1 2021/12/13 06:40:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:04 DEBUG : : Looking for writers 2021/12/13 06:40:04 DEBUG : file1: reading active writers 2021/12/13 06:40:04 DEBUG : file1: active writers 1 2021/12/13 06:40:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:05 DEBUG : : Looking for writers 2021/12/13 06:40:05 DEBUG : file1: reading active writers 2021/12/13 06:40:05 DEBUG : file1: active writers 1 2021/12/13 06:40:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:06 DEBUG : : Looking for writers 2021/12/13 06:40:06 DEBUG : file1: reading active writers 2021/12/13 06:40:06 DEBUG : file1: active writers 1 2021/12/13 06:40:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:07 DEBUG : : Looking for writers 2021/12/13 06:40:07 DEBUG : file1: reading active writers 2021/12/13 06:40:07 DEBUG : file1: active writers 1 2021/12/13 06:40:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:08 DEBUG : : Looking for writers 2021/12/13 06:40:08 DEBUG : file1: reading active writers 2021/12/13 06:40:08 DEBUG : file1: active writers 1 2021/12/13 06:40:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:09 DEBUG : : Looking for writers 2021/12/13 06:40:09 DEBUG : file1: reading active writers 2021/12/13 06:40:09 DEBUG : file1: active writers 1 2021/12/13 06:40:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:10 DEBUG : : Looking for writers 2021/12/13 06:40:10 DEBUG : file1: reading active writers 2021/12/13 06:40:10 DEBUG : file1: active writers 1 2021/12/13 06:40:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:11 DEBUG : : Looking for writers 2021/12/13 06:40:11 DEBUG : file1: reading active writers 2021/12/13 06:40:11 DEBUG : file1: active writers 1 2021/12/13 06:40:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:12 DEBUG : : Looking for writers 2021/12/13 06:40:12 DEBUG : file1: reading active writers 2021/12/13 06:40:12 DEBUG : file1: active writers 1 2021/12/13 06:40:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:13 DEBUG : : Looking for writers 2021/12/13 06:40:13 DEBUG : file1: reading active writers 2021/12/13 06:40:13 DEBUG : file1: active writers 1 2021/12/13 06:40:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:14 DEBUG : : Looking for writers 2021/12/13 06:40:14 DEBUG : file1: reading active writers 2021/12/13 06:40:14 DEBUG : file1: active writers 1 2021/12/13 06:40:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:15 DEBUG : : Looking for writers 2021/12/13 06:40:15 DEBUG : file1: reading active writers 2021/12/13 06:40:15 DEBUG : file1: active writers 1 2021/12/13 06:40:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:16 DEBUG : : Looking for writers 2021/12/13 06:40:16 DEBUG : file1: reading active writers 2021/12/13 06:40:16 DEBUG : file1: active writers 1 2021/12/13 06:40:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:17 DEBUG : : Looking for writers 2021/12/13 06:40:17 DEBUG : file1: reading active writers 2021/12/13 06:40:17 DEBUG : file1: active writers 1 2021/12/13 06:40:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:18 DEBUG : : Looking for writers 2021/12/13 06:40:18 DEBUG : file1: reading active writers 2021/12/13 06:40:18 DEBUG : file1: active writers 1 2021/12/13 06:40:18 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:19 DEBUG : : Looking for writers 2021/12/13 06:40:19 DEBUG : file1: reading active writers 2021/12/13 06:40:19 DEBUG : file1: active writers 1 2021/12/13 06:40:19 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:20 DEBUG : : Looking for writers 2021/12/13 06:40:20 DEBUG : file1: reading active writers 2021/12/13 06:40:20 DEBUG : file1: active writers 1 2021/12/13 06:40:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:21 DEBUG : : Looking for writers 2021/12/13 06:40:21 DEBUG : file1: reading active writers 2021/12/13 06:40:21 DEBUG : file1: active writers 1 2021/12/13 06:40:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:22 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2021/12/13 06:40:22 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileModTimeWithOpenWriters (30.54s) === RUN TestFileReadAtZeroLength run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:40:22 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:40:22 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:40:22 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:40:22 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:40:22 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:40:22 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:40:22 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:40:22 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': File to upload is small (0 bytes), uploading instead of streaming 2021/12/13 06:40:22 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:40:22 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 ) returned body: "" write_test.go:305: Error Trace: write_test.go:305 write_test.go:325 Error: Received unexpected error: upload error: HTTP error 402 (402 ) returned body: "" Test: TestFileReadAtZeroLength 2021/12/13 06:40:22 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2021/12/13 06:40:22 DEBUG : file1: Open: flags=O_RDONLY 2021/12/13 06:40:27 DEBUG : file1: >Open: fd=, err=file does not exist 2021/12/13 06:40:27 DEBUG : file1: >OpenFile: fd=, err=file does not exist write_test.go:310: Error Trace: write_test.go:310 write_test.go:325 Error: Received unexpected error: file does not exist Test: TestFileReadAtZeroLength 2021/12/13 06:40:27 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:40:27 DEBUG : : Looking for writers 2021/12/13 06:40:27 DEBUG : file1: reading active writers 2021/12/13 06:40:27 DEBUG : file1: active writers 1 2021/12/13 06:40:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2021/12/13 06:40:27 DEBUG : : Looking for writers 2021/12/13 06:40:27 DEBUG : file1: reading active writers 2021/12/13 06:40:27 DEBUG : file1: active writers 1 2021/12/13 06:40:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2021/12/13 06:40:27 DEBUG : : Looking for writers 2021/12/13 06:40:27 DEBUG : file1: reading active writers 2021/12/13 06:40:27 DEBUG : file1: active writers 1 2021/12/13 06:40:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2021/12/13 06:40:27 DEBUG : : Looking for writers 2021/12/13 06:40:27 DEBUG : file1: reading active writers 2021/12/13 06:40:27 DEBUG : file1: active writers 1 2021/12/13 06:40:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2021/12/13 06:40:27 DEBUG : : Looking for writers 2021/12/13 06:40:27 DEBUG : file1: reading active writers 2021/12/13 06:40:27 DEBUG : file1: active writers 1 2021/12/13 06:40:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2021/12/13 06:40:28 DEBUG : : Looking for writers 2021/12/13 06:40:28 DEBUG : file1: reading active writers 2021/12/13 06:40:28 DEBUG : file1: active writers 1 2021/12/13 06:40:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2021/12/13 06:40:28 DEBUG : : Looking for writers 2021/12/13 06:40:28 DEBUG : file1: reading active writers 2021/12/13 06:40:28 DEBUG : file1: active writers 1 2021/12/13 06:40:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2021/12/13 06:40:29 DEBUG : : Looking for writers 2021/12/13 06:40:29 DEBUG : file1: reading active writers 2021/12/13 06:40:29 DEBUG : file1: active writers 1 2021/12/13 06:40:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:30 DEBUG : : Looking for writers 2021/12/13 06:40:30 DEBUG : file1: reading active writers 2021/12/13 06:40:30 DEBUG : file1: active writers 1 2021/12/13 06:40:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:31 DEBUG : : Looking for writers 2021/12/13 06:40:31 DEBUG : file1: reading active writers 2021/12/13 06:40:31 DEBUG : file1: active writers 1 2021/12/13 06:40:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:32 DEBUG : : Looking for writers 2021/12/13 06:40:32 DEBUG : file1: reading active writers 2021/12/13 06:40:32 DEBUG : file1: active writers 1 2021/12/13 06:40:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:33 DEBUG : : Looking for writers 2021/12/13 06:40:33 DEBUG : file1: reading active writers 2021/12/13 06:40:33 DEBUG : file1: active writers 1 2021/12/13 06:40:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:34 DEBUG : : Looking for writers 2021/12/13 06:40:34 DEBUG : file1: reading active writers 2021/12/13 06:40:34 DEBUG : file1: active writers 1 2021/12/13 06:40:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:35 DEBUG : : Looking for writers 2021/12/13 06:40:35 DEBUG : file1: reading active writers 2021/12/13 06:40:35 DEBUG : file1: active writers 1 2021/12/13 06:40:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:36 DEBUG : : Looking for writers 2021/12/13 06:40:36 DEBUG : file1: reading active writers 2021/12/13 06:40:36 DEBUG : file1: active writers 1 2021/12/13 06:40:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:37 DEBUG : : Looking for writers 2021/12/13 06:40:37 DEBUG : file1: reading active writers 2021/12/13 06:40:37 DEBUG : file1: active writers 1 2021/12/13 06:40:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:38 DEBUG : : Looking for writers 2021/12/13 06:40:38 DEBUG : file1: reading active writers 2021/12/13 06:40:38 DEBUG : file1: active writers 1 2021/12/13 06:40:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:39 DEBUG : : Looking for writers 2021/12/13 06:40:39 DEBUG : file1: reading active writers 2021/12/13 06:40:39 DEBUG : file1: active writers 1 2021/12/13 06:40:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:40 DEBUG : : Looking for writers 2021/12/13 06:40:40 DEBUG : file1: reading active writers 2021/12/13 06:40:40 DEBUG : file1: active writers 1 2021/12/13 06:40:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:41 DEBUG : : Looking for writers 2021/12/13 06:40:41 DEBUG : file1: reading active writers 2021/12/13 06:40:41 DEBUG : file1: active writers 1 2021/12/13 06:40:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:42 DEBUG : : Looking for writers 2021/12/13 06:40:42 DEBUG : file1: reading active writers 2021/12/13 06:40:42 DEBUG : file1: active writers 1 2021/12/13 06:40:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:43 DEBUG : : Looking for writers 2021/12/13 06:40:43 DEBUG : file1: reading active writers 2021/12/13 06:40:43 DEBUG : file1: active writers 1 2021/12/13 06:40:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:44 DEBUG : : Looking for writers 2021/12/13 06:40:44 DEBUG : file1: reading active writers 2021/12/13 06:40:44 DEBUG : file1: active writers 1 2021/12/13 06:40:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:45 DEBUG : : Looking for writers 2021/12/13 06:40:45 DEBUG : file1: reading active writers 2021/12/13 06:40:45 DEBUG : file1: active writers 1 2021/12/13 06:40:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:46 DEBUG : : Looking for writers 2021/12/13 06:40:46 DEBUG : file1: reading active writers 2021/12/13 06:40:46 DEBUG : file1: active writers 1 2021/12/13 06:40:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:47 DEBUG : : Looking for writers 2021/12/13 06:40:47 DEBUG : file1: reading active writers 2021/12/13 06:40:47 DEBUG : file1: active writers 1 2021/12/13 06:40:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:48 DEBUG : : Looking for writers 2021/12/13 06:40:48 DEBUG : file1: reading active writers 2021/12/13 06:40:48 DEBUG : file1: active writers 1 2021/12/13 06:40:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:49 DEBUG : : Looking for writers 2021/12/13 06:40:49 DEBUG : file1: reading active writers 2021/12/13 06:40:49 DEBUG : file1: active writers 1 2021/12/13 06:40:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:50 DEBUG : : Looking for writers 2021/12/13 06:40:50 DEBUG : file1: reading active writers 2021/12/13 06:40:50 DEBUG : file1: active writers 1 2021/12/13 06:40:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:51 DEBUG : : Looking for writers 2021/12/13 06:40:51 DEBUG : file1: reading active writers 2021/12/13 06:40:51 DEBUG : file1: active writers 1 2021/12/13 06:40:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:52 DEBUG : : Looking for writers 2021/12/13 06:40:52 DEBUG : file1: reading active writers 2021/12/13 06:40:52 DEBUG : file1: active writers 1 2021/12/13 06:40:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:53 DEBUG : : Looking for writers 2021/12/13 06:40:53 DEBUG : file1: reading active writers 2021/12/13 06:40:53 DEBUG : file1: active writers 1 2021/12/13 06:40:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:54 DEBUG : : Looking for writers 2021/12/13 06:40:54 DEBUG : file1: reading active writers 2021/12/13 06:40:54 DEBUG : file1: active writers 1 2021/12/13 06:40:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:55 DEBUG : : Looking for writers 2021/12/13 06:40:55 DEBUG : file1: reading active writers 2021/12/13 06:40:55 DEBUG : file1: active writers 1 2021/12/13 06:40:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:56 DEBUG : : Looking for writers 2021/12/13 06:40:56 DEBUG : file1: reading active writers 2021/12/13 06:40:56 DEBUG : file1: active writers 1 2021/12/13 06:40:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:57 DEBUG : : Looking for writers 2021/12/13 06:40:57 DEBUG : file1: reading active writers 2021/12/13 06:40:57 DEBUG : file1: active writers 1 2021/12/13 06:40:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:40:57 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2021/12/13 06:40:57 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtZeroLength (35.76s) === RUN TestFileReadAtNonZeroLength run.go:181: Remote "zoho root 'rclone-test-tabiruy0sigitob6joyomug2'", Local "Local file system at /tmp/rclone2290915572", Modify Window "876000h0m0s" 2021/12/13 06:40:58 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Re-using VFS from active cache 2021/12/13 06:40:58 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2021/12/13 06:40:58 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2021/12/13 06:40:58 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:40:58 DEBUG : file1: >Open: fd=file1 (w), err= 2021/12/13 06:40:58 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2021/12/13 06:40:58 DEBUG : : Added virtual directory entry vAddFile: "file1" 2021/12/13 06:40:58 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': File to upload is small (100 bytes), uploading instead of streaming 2021/12/13 06:40:58 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 ) returned body: "" 2021/12/13 06:40:58 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 ) returned body: "" write_test.go:305: Error Trace: write_test.go:305 write_test.go:329 Error: Received unexpected error: upload error: HTTP error 402 (402 ) returned body: "" Test: TestFileReadAtNonZeroLength 2021/12/13 06:40:58 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2021/12/13 06:40:58 DEBUG : file1: Open: flags=O_RDONLY 2021/12/13 06:41:03 DEBUG : file1: >Open: fd=, err=file does not exist 2021/12/13 06:41:03 DEBUG : file1: >OpenFile: fd=, err=file does not exist write_test.go:310: Error Trace: write_test.go:310 write_test.go:329 Error: Received unexpected error: file does not exist Test: TestFileReadAtNonZeroLength 2021/12/13 06:41:03 DEBUG : WaitForWriters: timeout=30s 2021/12/13 06:41:03 DEBUG : : Looking for writers 2021/12/13 06:41:03 DEBUG : file1: reading active writers 2021/12/13 06:41:03 DEBUG : file1: active writers 1 2021/12/13 06:41:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2021/12/13 06:41:03 DEBUG : : Looking for writers 2021/12/13 06:41:03 DEBUG : file1: reading active writers 2021/12/13 06:41:03 DEBUG : file1: active writers 1 2021/12/13 06:41:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2021/12/13 06:41:03 DEBUG : : Looking for writers 2021/12/13 06:41:03 DEBUG : file1: reading active writers 2021/12/13 06:41:03 DEBUG : file1: active writers 1 2021/12/13 06:41:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2021/12/13 06:41:03 DEBUG : : Looking for writers 2021/12/13 06:41:03 DEBUG : file1: reading active writers 2021/12/13 06:41:03 DEBUG : file1: active writers 1 2021/12/13 06:41:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2021/12/13 06:41:03 DEBUG : : Looking for writers 2021/12/13 06:41:03 DEBUG : file1: reading active writers 2021/12/13 06:41:03 DEBUG : file1: active writers 1 2021/12/13 06:41:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2021/12/13 06:41:03 DEBUG : : Looking for writers 2021/12/13 06:41:03 DEBUG : file1: reading active writers 2021/12/13 06:41:03 DEBUG : file1: active writers 1 2021/12/13 06:41:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2021/12/13 06:41:04 DEBUG : : Looking for writers 2021/12/13 06:41:04 DEBUG : file1: reading active writers 2021/12/13 06:41:04 DEBUG : file1: active writers 1 2021/12/13 06:41:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2021/12/13 06:41:04 DEBUG : : Looking for writers 2021/12/13 06:41:04 DEBUG : file1: reading active writers 2021/12/13 06:41:04 DEBUG : file1: active writers 1 2021/12/13 06:41:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:05 DEBUG : : Looking for writers 2021/12/13 06:41:05 DEBUG : file1: reading active writers 2021/12/13 06:41:05 DEBUG : file1: active writers 1 2021/12/13 06:41:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:06 DEBUG : : Looking for writers 2021/12/13 06:41:06 DEBUG : file1: reading active writers 2021/12/13 06:41:06 DEBUG : file1: active writers 1 2021/12/13 06:41:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:07 DEBUG : : Looking for writers 2021/12/13 06:41:07 DEBUG : file1: reading active writers 2021/12/13 06:41:07 DEBUG : file1: active writers 1 2021/12/13 06:41:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:08 DEBUG : : Looking for writers 2021/12/13 06:41:08 DEBUG : file1: reading active writers 2021/12/13 06:41:08 DEBUG : file1: active writers 1 2021/12/13 06:41:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:09 DEBUG : : Looking for writers 2021/12/13 06:41:09 DEBUG : file1: reading active writers 2021/12/13 06:41:09 DEBUG : file1: active writers 1 2021/12/13 06:41:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:10 DEBUG : : Looking for writers 2021/12/13 06:41:10 DEBUG : file1: reading active writers 2021/12/13 06:41:10 DEBUG : file1: active writers 1 2021/12/13 06:41:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:11 DEBUG : : Looking for writers 2021/12/13 06:41:11 DEBUG : file1: reading active writers 2021/12/13 06:41:11 DEBUG : file1: active writers 1 2021/12/13 06:41:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:12 DEBUG : : Looking for writers 2021/12/13 06:41:12 DEBUG : file1: reading active writers 2021/12/13 06:41:12 DEBUG : file1: active writers 1 2021/12/13 06:41:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:13 DEBUG : : Looking for writers 2021/12/13 06:41:13 DEBUG : file1: reading active writers 2021/12/13 06:41:13 DEBUG : file1: active writers 1 2021/12/13 06:41:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:14 DEBUG : : Looking for writers 2021/12/13 06:41:14 DEBUG : file1: reading active writers 2021/12/13 06:41:14 DEBUG : file1: active writers 1 2021/12/13 06:41:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:15 DEBUG : : Looking for writers 2021/12/13 06:41:15 DEBUG : file1: reading active writers 2021/12/13 06:41:15 DEBUG : file1: active writers 1 2021/12/13 06:41:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:16 DEBUG : : Looking for writers 2021/12/13 06:41:16 DEBUG : file1: reading active writers 2021/12/13 06:41:16 DEBUG : file1: active writers 1 2021/12/13 06:41:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:17 DEBUG : : Looking for writers 2021/12/13 06:41:17 DEBUG : file1: reading active writers 2021/12/13 06:41:17 DEBUG : file1: active writers 1 2021/12/13 06:41:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:18 DEBUG : : Looking for writers 2021/12/13 06:41:18 DEBUG : file1: reading active writers 2021/12/13 06:41:18 DEBUG : file1: active writers 1 2021/12/13 06:41:18 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:19 DEBUG : : Looking for writers 2021/12/13 06:41:19 DEBUG : file1: reading active writers 2021/12/13 06:41:19 DEBUG : file1: active writers 1 2021/12/13 06:41:19 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:20 DEBUG : : Looking for writers 2021/12/13 06:41:20 DEBUG : file1: reading active writers 2021/12/13 06:41:20 DEBUG : file1: active writers 1 2021/12/13 06:41:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:21 DEBUG : : Looking for writers 2021/12/13 06:41:21 DEBUG : file1: reading active writers 2021/12/13 06:41:21 DEBUG : file1: active writers 1 2021/12/13 06:41:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:22 DEBUG : : Looking for writers 2021/12/13 06:41:22 DEBUG : file1: reading active writers 2021/12/13 06:41:22 DEBUG : file1: active writers 1 2021/12/13 06:41:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:23 DEBUG : : Looking for writers 2021/12/13 06:41:23 DEBUG : file1: reading active writers 2021/12/13 06:41:23 DEBUG : file1: active writers 1 2021/12/13 06:41:23 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:24 DEBUG : : Looking for writers 2021/12/13 06:41:24 DEBUG : file1: reading active writers 2021/12/13 06:41:24 DEBUG : file1: active writers 1 2021/12/13 06:41:24 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:25 DEBUG : : Looking for writers 2021/12/13 06:41:25 DEBUG : file1: reading active writers 2021/12/13 06:41:25 DEBUG : file1: active writers 1 2021/12/13 06:41:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:26 DEBUG : : Looking for writers 2021/12/13 06:41:26 DEBUG : file1: reading active writers 2021/12/13 06:41:26 DEBUG : file1: active writers 1 2021/12/13 06:41:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:27 DEBUG : : Looking for writers 2021/12/13 06:41:27 DEBUG : file1: reading active writers 2021/12/13 06:41:27 DEBUG : file1: active writers 1 2021/12/13 06:41:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:28 DEBUG : : Looking for writers 2021/12/13 06:41:28 DEBUG : file1: reading active writers 2021/12/13 06:41:28 DEBUG : file1: active writers 1 2021/12/13 06:41:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:29 DEBUG : : Looking for writers 2021/12/13 06:41:29 DEBUG : file1: reading active writers 2021/12/13 06:41:29 DEBUG : file1: active writers 1 2021/12/13 06:41:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:30 DEBUG : : Looking for writers 2021/12/13 06:41:30 DEBUG : file1: reading active writers 2021/12/13 06:41:30 DEBUG : file1: active writers 1 2021/12/13 06:41:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:31 DEBUG : : Looking for writers 2021/12/13 06:41:31 DEBUG : file1: reading active writers 2021/12/13 06:41:31 DEBUG : file1: active writers 1 2021/12/13 06:41:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:32 DEBUG : : Looking for writers 2021/12/13 06:41:32 DEBUG : file1: reading active writers 2021/12/13 06:41:32 DEBUG : file1: active writers 1 2021/12/13 06:41:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2021/12/13 06:41:33 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2021/12/13 06:41:33 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtNonZeroLength (35.70s) FAIL 2021/12/13 06:41:33 DEBUG : zoho root 'rclone-test-tabiruy0sigitob6joyomug2': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestZoho: -verbose -test.run '^(TestCaseSensitivity|TestDirCreate|TestDirForgetAll|TestDirForgetPath|TestDirHandleMethods|TestDirHandleReaddir|TestDirHandleReaddirnames|TestDirMethods|TestDirMkdir|TestDirMkdirSub|TestDirOpen|TestDirReadDirAll|TestDirRemove|TestDirRemoveAll|TestDirRemoveName|TestDirRename|TestDirSetModTime|TestDirStat|TestDirWalk|TestFileMethods|TestFileOpen|TestFileOpenRead|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRemove|TestFileRemoveAll|TestFileRename|TestFileSetModTime|TestRWFileHandleFlushRead|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestRcGetVFS|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestVFSNew|TestVFSOpenFile|TestVFSRename|TestVFSStat|TestVFSStatParent|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters)$/^(cache=full,open=false,write=false|cache=full,open=true,write=false|cache=full,open=true,write=true|cache=off,open=false,write=false|cache=off,open=true,write=false|cache=off,open=true,write=true|full,forceCache=false|minimal,forceCache=false|minimal,forceCache=true|off,forceCache=false|writes,forceCache=false|writes,forceCache=true)$'" - Finished ERROR in 8m26.086188846s (try 5/5): exit status 1: Failed [TestDirHandleMethods TestDirHandleReaddir TestDirHandleReaddirnames TestDirMethods TestDirForgetAll TestDirForgetPath TestDirWalk TestDirSetModTime TestDirStat TestDirReadDirAll TestDirOpen TestDirCreate TestDirMkdir TestDirMkdirSub TestDirRemove TestDirRemoveAll TestDirRemoveName TestDirRename TestFileMethods TestFileSetModTime/cache=off,open=false,write=false TestFileSetModTime/cache=off,open=true,write=false TestFileSetModTime/cache=off,open=true,write=true TestFileSetModTime/cache=full,open=false,write=false TestFileSetModTime/cache=full,open=true,write=false TestFileSetModTime/cache=full,open=true,write=true TestFileOpenRead TestFileOpenWrite TestFileRemove TestFileRemoveAll TestFileOpen TestFileRename/off,forceCache=false TestFileRename/minimal,forceCache=false TestFileRename/minimal,forceCache=true TestFileRename/writes,forceCache=false TestFileRename/writes,forceCache=true TestFileRename/full,forceCache=false TestRcGetVFS TestReadFileHandleMethods TestReadFileHandleSeek TestReadFileHandleReadAt TestReadFileHandleFlush TestReadFileHandleRelease TestRWFileHandleMethodsRead TestRWFileHandleSeek TestRWFileHandleReadAt TestRWFileHandleFlushRead TestRWFileHandleReleaseRead TestRWFileHandleMethodsWrite TestRWFileHandleWriteAt TestRWFileHandleWriteNoWrite TestRWFileHandleSizeTruncateExisting TestRWFileHandleSizeCreateExisting TestRWFileModTimeWithOpenWriters TestCaseSensitivity TestVFSNew TestVFSStat TestVFSStatParent TestVFSOpenFile TestVFSRename TestWriteFileHandleMethods TestWriteFileHandleWriteAt TestWriteFileHandleFlush TestWriteFileHandleRelease TestWriteFileModTimeWithOpenWriters TestFileReadAtZeroLength TestFileReadAtNonZeroLength]