"./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) 2022/01/09 06:12:52 DEBUG : Creating backend with remote "TestZoho:rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:12:52 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/01/09 06:12:52 DEBUG : Creating backend with remote "/tmp/rclone2351581393" === RUN TestDirHandleMethods run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:52 INFO : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': poll-interval is not supported by this remote 2022/01/09 06:12:52 NOTICE: zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': --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-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirHandleMethods (1.08s) === RUN TestDirHandleReaddir run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:54 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:12:54 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:12:54 DEBUG : : Looking for writers 2022/01/09 06:12:54 DEBUG : >WaitForWriters: --- FAIL: TestDirHandleReaddir (0.84s) === RUN TestDirHandleReaddirnames run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:54 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirHandleReaddirnames (0.50s) === RUN TestDirMethods run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:55 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirMethods (0.16s) === RUN TestDirForgetAll run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:55 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirForgetAll (0.17s) === RUN TestDirForgetPath run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:55 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirForgetPath (0.16s) === RUN TestDirWalk run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:55 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirWalk (0.17s) === RUN TestDirSetModTime run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:56 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirSetModTime (0.17s) === RUN TestDirStat run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:56 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirStat (0.16s) === RUN TestDirReadDirAll run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:56 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:12:56 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:12:56 DEBUG : : Looking for writers 2022/01/09 06:12:56 DEBUG : >WaitForWriters: --- FAIL: TestDirReadDirAll (0.84s) === RUN TestDirOpen run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:57 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirOpen (0.49s) === RUN TestDirCreate run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:57 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirCreate (0.16s) === RUN TestDirMkdir run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:57 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirMkdir (0.17s) === RUN TestDirMkdirSub run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:58 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirMkdirSub (0.17s) === RUN TestDirRemove run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:58 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirRemove (0.17s) === RUN TestDirRemoveAll run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:58 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirRemoveAll (0.16s) === RUN TestDirRemoveName run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:58 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirRemoveName (0.17s) === RUN TestDirRename run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:58 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestDirRename (0.17s) === RUN TestFileMethods run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:58 INFO : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': poll-interval is not supported by this remote 2022/01/09 06:12:58 NOTICE: zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': --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-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestFileMethods (0.16s) === RUN TestFileSetModTime === RUN TestFileSetModTime/cache=off,open=false,write=false run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:59 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileSetModTime/cache=off,open=true,write=false run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:59 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileSetModTime/cache=off,open=true,write=true run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:59 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileSetModTime/cache=full,open=false,write=false run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:59 INFO : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': poll-interval is not supported by this remote 2022/01/09 06:12:59 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2022/01/09 06:12:59 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestZoho/rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:12:59 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:12:59 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestZoho/rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:12:59 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:12:59 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-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileSetModTime/cache=full,open=true,write=false run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:59 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileSetModTime/cache=full,open=true,write=true run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:12:59 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestFileSetModTime (1.03s) --- FAIL: TestFileSetModTime/cache=off,open=false,write=false (0.17s) --- FAIL: TestFileSetModTime/cache=off,open=true,write=false (0.16s) --- FAIL: TestFileSetModTime/cache=off,open=true,write=true (0.16s) --- FAIL: TestFileSetModTime/cache=full,open=false,write=false (0.18s) --- FAIL: TestFileSetModTime/cache=full,open=true,write=false (0.16s) --- FAIL: TestFileSetModTime/cache=full,open=true,write=true (0.20s) === RUN TestFileOpenRead run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:00 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestFileOpenRead (0.17s) === RUN TestFileOpenWrite run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:00 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestFileOpenWrite (0.16s) === RUN TestFileRemove run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:00 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestFileRemove (0.16s) === RUN TestFileRemoveAll run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:00 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestFileRemoveAll (0.18s) === RUN TestFileOpen run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:00 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestFileOpen (0.16s) === RUN TestFileRename === RUN TestFileRename/off,forceCache=false run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:00 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileRename/minimal,forceCache=false run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:01 INFO : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': poll-interval is not supported by this remote 2022/01/09 06:13:01 NOTICE: zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2022/01/09 06:13:01 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2022/01/09 06:13:01 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestZoho/rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:13:01 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:13:01 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-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileRename/minimal,forceCache=true run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:01 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileRename/writes,forceCache=false run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:01 INFO : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': poll-interval is not supported by this remote 2022/01/09 06:13:01 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2022/01/09 06:13:01 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestZoho/rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:13:01 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestZoho/rclone-test-tikuguh2xarudij8kunigaf9" 2022/01/09 06:13:01 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-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileRename/writes,forceCache=true run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:01 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" === RUN TestFileRename/full,forceCache=false run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:01 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestFileRename (1.05s) --- FAIL: TestFileRename/off,forceCache=false (0.17s) --- FAIL: TestFileRename/minimal,forceCache=false (0.16s) --- FAIL: TestFileRename/minimal,forceCache=true (0.24s) --- FAIL: TestFileRename/writes,forceCache=false (0.16s) --- FAIL: TestFileRename/writes,forceCache=true (0.17s) --- FAIL: TestFileRename/full,forceCache=false (0.16s) === 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-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:01 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': 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 2022/01/09 06:13:01 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:13:01 DEBUG : : Looking for writers 2022/01/09 06:13:01 DEBUG : >WaitForWriters: --- FAIL: TestRcGetVFS (0.79s) === RUN TestReadFileHandleMethods run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:02 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestReadFileHandleMethods (0.50s) === RUN TestReadFileHandleSeek run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:03 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestReadFileHandleSeek (0.16s) === RUN TestReadFileHandleReadAt run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:03 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestReadFileHandleReadAt (0.16s) === RUN TestReadFileHandleFlush run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:03 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestReadFileHandleFlush (0.16s) === RUN TestReadFileHandleRelease run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:03 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestReadFileHandleRelease (0.16s) === RUN TestRWFileHandleMethodsRead run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:03 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestRWFileHandleMethodsRead (0.16s) === RUN TestRWFileHandleSeek run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:04 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestRWFileHandleSeek (0.17s) === RUN TestRWFileHandleReadAt run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:04 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestRWFileHandleReadAt (0.16s) === RUN TestRWFileHandleFlushRead run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:04 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestRWFileHandleFlushRead (0.17s) === RUN TestRWFileHandleReleaseRead run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:04 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestRWFileHandleReleaseRead (0.16s) === RUN TestRWFileHandleMethodsWrite run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:13:04 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:13:04 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:13:04 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:13:04 DEBUG : file1: newRWFileHandle: 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): openPending: 2022/01/09 06:13:04 DEBUG : file1: vfs cache: truncate to size=0 2022/01/09 06:13:04 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): >openPending: err= 2022/01/09 06:13:04 DEBUG : file1: >newRWFileHandle: err= 2022/01/09 06:13:04 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:13:04 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/01/09 06:13:04 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): _writeAt: size=5, off=0 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): >_writeAt: n=5, err= 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): _writeAt: size=7, off=5 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): >_writeAt: n=7, err= 2022/01/09 06:13:04 DEBUG : file1: vfs cache: truncate to size=11 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): close: 2022/01/09 06:13:04 DEBUG : file1: vfs cache: setting modification time to 2022-01-09 06:13:04.942256774 +0000 UTC m=+12.839779355 2022/01/09 06:13:04 INFO : file1: vfs cache: queuing for upload in 100ms 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): >close: err= 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): close: 2022/01/09 06:13:04 DEBUG : file1(0xc0002f4380): >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 2022/01/09 06:13:04 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:13:04 DEBUG : dir: Looking for writers 2022/01/09 06:13:04 DEBUG : : Looking for writers 2022/01/09 06:13:04 DEBUG : dir: reading active writers 2022/01/09 06:13:04 DEBUG : file1: reading active writers 2022/01/09 06:13:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/01/09 06:13:04 DEBUG : dir: Looking for writers 2022/01/09 06:13:04 DEBUG : : Looking for writers 2022/01/09 06:13:04 DEBUG : dir: reading active writers 2022/01/09 06:13:04 DEBUG : file1: reading active writers 2022/01/09 06:13:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/01/09 06:13:04 DEBUG : dir: Looking for writers 2022/01/09 06:13:04 DEBUG : : Looking for writers 2022/01/09 06:13:04 DEBUG : dir: reading active writers 2022/01/09 06:13:04 DEBUG : file1: reading active writers 2022/01/09 06:13:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/01/09 06:13:05 DEBUG : dir: Looking for writers 2022/01/09 06:13:05 DEBUG : : Looking for writers 2022/01/09 06:13:05 DEBUG : dir: reading active writers 2022/01/09 06:13:05 DEBUG : file1: reading active writers 2022/01/09 06:13:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/01/09 06:13:05 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:05 DEBUG : dir: Looking for writers 2022/01/09 06:13:05 DEBUG : : Looking for writers 2022/01/09 06:13:05 DEBUG : dir: reading active writers 2022/01/09 06:13:05 DEBUG : file1: reading active writers 2022/01/09 06:13:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2022/01/09 06:13:05 DEBUG : dir: Looking for writers 2022/01/09 06:13:05 DEBUG : : Looking for writers 2022/01/09 06:13:05 DEBUG : file1: reading active writers 2022/01/09 06:13:05 DEBUG : dir: reading active writers 2022/01/09 06:13:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2022/01/09 06:13:05 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:05 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 Payment Required) returned body: "" 2022/01/09 06:13:05 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:05 DEBUG : dir: Looking for writers 2022/01/09 06:13:05 DEBUG : : Looking for writers 2022/01/09 06:13:05 DEBUG : dir: reading active writers 2022/01/09 06:13:05 DEBUG : file1: reading active writers 2022/01/09 06:13:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2022/01/09 06:13:05 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:05 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 Payment Required) returned body: "" 2022/01/09 06:13:06 DEBUG : dir: Looking for writers 2022/01/09 06:13:06 DEBUG : : Looking for writers 2022/01/09 06:13:06 DEBUG : dir: reading active writers 2022/01/09 06:13:06 DEBUG : file1: reading active writers 2022/01/09 06:13:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:06 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:06 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:06 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 Payment Required) returned body: "" 2022/01/09 06:13:07 DEBUG : dir: Looking for writers 2022/01/09 06:13:07 DEBUG : : Looking for writers 2022/01/09 06:13:07 DEBUG : dir: reading active writers 2022/01/09 06:13:07 DEBUG : file1: reading active writers 2022/01/09 06:13:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:07 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:07 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:07 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 Payment Required) returned body: "" 2022/01/09 06:13:08 DEBUG : dir: Looking for writers 2022/01/09 06:13:08 DEBUG : : Looking for writers 2022/01/09 06:13:08 DEBUG : dir: reading active writers 2022/01/09 06:13:08 DEBUG : file1: reading active writers 2022/01/09 06:13:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:09 DEBUG : dir: Looking for writers 2022/01/09 06:13:09 DEBUG : : Looking for writers 2022/01/09 06:13:09 DEBUG : dir: reading active writers 2022/01/09 06:13:09 DEBUG : file1: reading active writers 2022/01/09 06:13:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:09 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:09 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:09 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 Payment Required) returned body: "" 2022/01/09 06:13:10 DEBUG : dir: Looking for writers 2022/01/09 06:13:10 DEBUG : : Looking for writers 2022/01/09 06:13:10 DEBUG : dir: reading active writers 2022/01/09 06:13:10 DEBUG : file1: reading active writers 2022/01/09 06:13:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:11 DEBUG : dir: Looking for writers 2022/01/09 06:13:11 DEBUG : : Looking for writers 2022/01/09 06:13:11 DEBUG : dir: reading active writers 2022/01/09 06:13:11 DEBUG : file1: reading active writers 2022/01/09 06:13:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:12 DEBUG : dir: Looking for writers 2022/01/09 06:13:12 DEBUG : : Looking for writers 2022/01/09 06:13:12 DEBUG : dir: reading active writers 2022/01/09 06:13:12 DEBUG : file1: reading active writers 2022/01/09 06:13:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:12 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:12 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:12 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 Payment Required) returned body: "" 2022/01/09 06:13:13 DEBUG : dir: Looking for writers 2022/01/09 06:13:13 DEBUG : : Looking for writers 2022/01/09 06:13:13 DEBUG : dir: reading active writers 2022/01/09 06:13:13 DEBUG : file1: reading active writers 2022/01/09 06:13:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:14 DEBUG : dir: Looking for writers 2022/01/09 06:13:14 DEBUG : : Looking for writers 2022/01/09 06:13:14 DEBUG : dir: reading active writers 2022/01/09 06:13:14 DEBUG : file1: reading active writers 2022/01/09 06:13:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:15 DEBUG : dir: Looking for writers 2022/01/09 06:13:15 DEBUG : : Looking for writers 2022/01/09 06:13:15 DEBUG : file1: reading active writers 2022/01/09 06:13:15 DEBUG : dir: reading active writers 2022/01/09 06:13:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:16 DEBUG : dir: Looking for writers 2022/01/09 06:13:16 DEBUG : : Looking for writers 2022/01/09 06:13:16 DEBUG : file1: reading active writers 2022/01/09 06:13:16 DEBUG : dir: reading active writers 2022/01/09 06:13:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:17 DEBUG : dir: Looking for writers 2022/01/09 06:13:17 DEBUG : : Looking for writers 2022/01/09 06:13:17 DEBUG : dir: reading active writers 2022/01/09 06:13:17 DEBUG : file1: reading active writers 2022/01/09 06:13:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:18 DEBUG : dir: Looking for writers 2022/01/09 06:13:18 DEBUG : : Looking for writers 2022/01/09 06:13:18 DEBUG : dir: reading active writers 2022/01/09 06:13:18 DEBUG : file1: reading active writers 2022/01/09 06:13:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:19 DEBUG : dir: Looking for writers 2022/01/09 06:13:19 DEBUG : : Looking for writers 2022/01/09 06:13:19 DEBUG : file1: reading active writers 2022/01/09 06:13:19 DEBUG : dir: reading active writers 2022/01/09 06:13:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:19 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:19 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:19 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 Payment Required) returned body: "" 2022/01/09 06:13:20 DEBUG : dir: Looking for writers 2022/01/09 06:13:20 DEBUG : : Looking for writers 2022/01/09 06:13:20 DEBUG : dir: reading active writers 2022/01/09 06:13:20 DEBUG : file1: reading active writers 2022/01/09 06:13:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:21 DEBUG : dir: Looking for writers 2022/01/09 06:13:21 DEBUG : : Looking for writers 2022/01/09 06:13:21 DEBUG : dir: reading active writers 2022/01/09 06:13:21 DEBUG : file1: reading active writers 2022/01/09 06:13:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:22 DEBUG : dir: Looking for writers 2022/01/09 06:13:22 DEBUG : : Looking for writers 2022/01/09 06:13:22 DEBUG : dir: reading active writers 2022/01/09 06:13:22 DEBUG : file1: reading active writers 2022/01/09 06:13:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:23 DEBUG : dir: Looking for writers 2022/01/09 06:13:23 DEBUG : : Looking for writers 2022/01/09 06:13:23 DEBUG : dir: reading active writers 2022/01/09 06:13:23 DEBUG : file1: reading active writers 2022/01/09 06:13:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:24 DEBUG : dir: Looking for writers 2022/01/09 06:13:24 DEBUG : : Looking for writers 2022/01/09 06:13:24 DEBUG : dir: reading active writers 2022/01/09 06:13:24 DEBUG : file1: reading active writers 2022/01/09 06:13:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:25 DEBUG : dir: Looking for writers 2022/01/09 06:13:25 DEBUG : : Looking for writers 2022/01/09 06:13:25 DEBUG : dir: reading active writers 2022/01/09 06:13:25 DEBUG : file1: reading active writers 2022/01/09 06:13:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:26 DEBUG : dir: Looking for writers 2022/01/09 06:13:26 DEBUG : : Looking for writers 2022/01/09 06:13:26 DEBUG : dir: reading active writers 2022/01/09 06:13:26 DEBUG : file1: reading active writers 2022/01/09 06:13:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:27 DEBUG : dir: Looking for writers 2022/01/09 06:13:27 DEBUG : : Looking for writers 2022/01/09 06:13:27 DEBUG : dir: reading active writers 2022/01/09 06:13:27 DEBUG : file1: reading active writers 2022/01/09 06:13:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:28 DEBUG : dir: Looking for writers 2022/01/09 06:13:28 DEBUG : : Looking for writers 2022/01/09 06:13:28 DEBUG : dir: reading active writers 2022/01/09 06:13:28 DEBUG : file1: reading active writers 2022/01/09 06:13:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:29 DEBUG : dir: Looking for writers 2022/01/09 06:13:29 DEBUG : : Looking for writers 2022/01/09 06:13:29 DEBUG : dir: reading active writers 2022/01/09 06:13:29 DEBUG : file1: reading active writers 2022/01/09 06:13:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:30 DEBUG : dir: Looking for writers 2022/01/09 06:13:30 DEBUG : : Looking for writers 2022/01/09 06:13:30 DEBUG : dir: reading active writers 2022/01/09 06:13:30 DEBUG : file1: reading active writers 2022/01/09 06:13:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:31 DEBUG : dir: Looking for writers 2022/01/09 06:13:31 DEBUG : : Looking for writers 2022/01/09 06:13:31 DEBUG : dir: reading active writers 2022/01/09 06:13:31 DEBUG : file1: reading active writers 2022/01/09 06:13:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:32 DEBUG : dir: Looking for writers 2022/01/09 06:13:32 DEBUG : : Looking for writers 2022/01/09 06:13:32 DEBUG : dir: reading active writers 2022/01/09 06:13:32 DEBUG : file1: reading active writers 2022/01/09 06:13:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:32 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:32 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:32 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 Payment Required) returned body: "" 2022/01/09 06:13:33 DEBUG : dir: Looking for writers 2022/01/09 06:13:33 DEBUG : : Looking for writers 2022/01/09 06:13:33 DEBUG : dir: reading active writers 2022/01/09 06:13:33 DEBUG : file1: reading active writers 2022/01/09 06:13:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:34 DEBUG : dir: Looking for writers 2022/01/09 06:13:34 DEBUG : : Looking for writers 2022/01/09 06:13:34 DEBUG : dir: reading active writers 2022/01/09 06:13:34 DEBUG : file1: reading active writers 2022/01/09 06:13:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:34 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc0002f4340 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228231619326598 ext:12839779355 loc:0x2a04b60} ATime:{wall:13866228231619337068 ext:12839789835 loc:0x2a04b60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2022/01/09 06:13:34 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 2022/01/09 06:13:43 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:13:43 DEBUG : dir: Looking for writers 2022/01/09 06:13:43 DEBUG : : Looking for writers 2022/01/09 06:13:43 DEBUG : dir: reading active writers 2022/01/09 06:13:43 DEBUG : file1: reading active writers 2022/01/09 06:13:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/01/09 06:13:43 DEBUG : dir: Looking for writers 2022/01/09 06:13:43 DEBUG : : Looking for writers 2022/01/09 06:13:43 DEBUG : dir: reading active writers 2022/01/09 06:13:43 DEBUG : file1: reading active writers 2022/01/09 06:13:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/01/09 06:13:43 DEBUG : dir: Looking for writers 2022/01/09 06:13:43 DEBUG : : Looking for writers 2022/01/09 06:13:43 DEBUG : dir: reading active writers 2022/01/09 06:13:43 DEBUG : file1: reading active writers 2022/01/09 06:13:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/01/09 06:13:43 DEBUG : dir: Looking for writers 2022/01/09 06:13:43 DEBUG : : Looking for writers 2022/01/09 06:13:43 DEBUG : file1: reading active writers 2022/01/09 06:13:43 DEBUG : dir: reading active writers 2022/01/09 06:13:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/01/09 06:13:43 DEBUG : dir: Looking for writers 2022/01/09 06:13:43 DEBUG : : Looking for writers 2022/01/09 06:13:43 DEBUG : dir: reading active writers 2022/01/09 06:13:43 DEBUG : file1: reading active writers 2022/01/09 06:13:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2022/01/09 06:13:43 DEBUG : dir: Looking for writers 2022/01/09 06:13:43 DEBUG : : Looking for writers 2022/01/09 06:13:43 DEBUG : dir: reading active writers 2022/01/09 06:13:43 DEBUG : file1: reading active writers 2022/01/09 06:13:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2022/01/09 06:13:43 DEBUG : dir: Looking for writers 2022/01/09 06:13:43 DEBUG : : Looking for writers 2022/01/09 06:13:43 DEBUG : dir: reading active writers 2022/01/09 06:13:43 DEBUG : file1: reading active writers 2022/01/09 06:13:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2022/01/09 06:13:44 DEBUG : dir: Looking for writers 2022/01/09 06:13:44 DEBUG : : Looking for writers 2022/01/09 06:13:44 DEBUG : dir: reading active writers 2022/01/09 06:13:44 DEBUG : file1: reading active writers 2022/01/09 06:13:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:45 DEBUG : dir: Looking for writers 2022/01/09 06:13:45 DEBUG : : Looking for writers 2022/01/09 06:13:45 DEBUG : dir: reading active writers 2022/01/09 06:13:45 DEBUG : file1: reading active writers 2022/01/09 06:13:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:46 DEBUG : dir: Looking for writers 2022/01/09 06:13:46 DEBUG : : Looking for writers 2022/01/09 06:13:46 DEBUG : dir: reading active writers 2022/01/09 06:13:46 DEBUG : file1: reading active writers 2022/01/09 06:13:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:47 DEBUG : dir: Looking for writers 2022/01/09 06:13:47 DEBUG : : Looking for writers 2022/01/09 06:13:47 DEBUG : dir: reading active writers 2022/01/09 06:13:47 DEBUG : file1: reading active writers 2022/01/09 06:13:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:48 DEBUG : dir: Looking for writers 2022/01/09 06:13:48 DEBUG : : Looking for writers 2022/01/09 06:13:48 DEBUG : dir: reading active writers 2022/01/09 06:13:48 DEBUG : file1: reading active writers 2022/01/09 06:13:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:49 DEBUG : dir: Looking for writers 2022/01/09 06:13:49 DEBUG : : Looking for writers 2022/01/09 06:13:49 DEBUG : dir: reading active writers 2022/01/09 06:13:49 DEBUG : file1: reading active writers 2022/01/09 06:13:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:50 DEBUG : dir: Looking for writers 2022/01/09 06:13:50 DEBUG : : Looking for writers 2022/01/09 06:13:50 DEBUG : dir: reading active writers 2022/01/09 06:13:50 DEBUG : file1: reading active writers 2022/01/09 06:13:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:51 DEBUG : dir: Looking for writers 2022/01/09 06:13:51 DEBUG : : Looking for writers 2022/01/09 06:13:51 DEBUG : dir: reading active writers 2022/01/09 06:13:51 DEBUG : file1: reading active writers 2022/01/09 06:13:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:52 DEBUG : dir: Looking for writers 2022/01/09 06:13:52 DEBUG : : Looking for writers 2022/01/09 06:13:52 DEBUG : dir: reading active writers 2022/01/09 06:13:52 DEBUG : file1: reading active writers 2022/01/09 06:13:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:53 DEBUG : dir: Looking for writers 2022/01/09 06:13:53 DEBUG : : Looking for writers 2022/01/09 06:13:53 DEBUG : dir: reading active writers 2022/01/09 06:13:53 DEBUG : file1: reading active writers 2022/01/09 06:13:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:54 DEBUG : dir: Looking for writers 2022/01/09 06:13:54 DEBUG : : Looking for writers 2022/01/09 06:13:54 DEBUG : file1: reading active writers 2022/01/09 06:13:54 DEBUG : dir: reading active writers 2022/01/09 06:13:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:55 DEBUG : dir: Looking for writers 2022/01/09 06:13:55 DEBUG : : Looking for writers 2022/01/09 06:13:55 DEBUG : dir: reading active writers 2022/01/09 06:13:55 DEBUG : file1: reading active writers 2022/01/09 06:13:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:56 DEBUG : dir: Looking for writers 2022/01/09 06:13:56 DEBUG : : Looking for writers 2022/01/09 06:13:56 DEBUG : dir: reading active writers 2022/01/09 06:13:56 DEBUG : file1: reading active writers 2022/01/09 06:13:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:57 DEBUG : dir: Looking for writers 2022/01/09 06:13:57 DEBUG : : Looking for writers 2022/01/09 06:13:57 DEBUG : dir: reading active writers 2022/01/09 06:13:57 DEBUG : file1: reading active writers 2022/01/09 06:13:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:58 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:13:58 DEBUG : dir: Looking for writers 2022/01/09 06:13:58 DEBUG : : Looking for writers 2022/01/09 06:13:58 DEBUG : dir: reading active writers 2022/01/09 06:13:58 DEBUG : file1: reading active writers 2022/01/09 06:13:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:58 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:13:58 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 Payment Required) returned body: "" 2022/01/09 06:13:59 DEBUG : dir: Looking for writers 2022/01/09 06:13:59 DEBUG : : Looking for writers 2022/01/09 06:13:59 DEBUG : dir: reading active writers 2022/01/09 06:13:59 DEBUG : file1: reading active writers 2022/01/09 06:13:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:13:59 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2022/01/09 06:13:59 INFO : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 11 (was 11) 2022/01/09 06:14:00 DEBUG : dir: Looking for writers 2022/01/09 06:14:00 DEBUG : : Looking for writers 2022/01/09 06:14:00 DEBUG : dir: reading active writers 2022/01/09 06:14:00 DEBUG : file1: reading active writers 2022/01/09 06:14:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:01 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2022/01/09 06:14:01 DEBUG : dir: Looking for writers 2022/01/09 06:14:01 DEBUG : : Looking for writers 2022/01/09 06:14:01 DEBUG : dir: reading active writers 2022/01/09 06:14:01 DEBUG : file1: reading active writers 2022/01/09 06:14:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:01 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2022/01/09 06:14:02 DEBUG : dir: Looking for writers 2022/01/09 06:14:02 DEBUG : : Looking for writers 2022/01/09 06:14:02 DEBUG : dir: reading active writers 2022/01/09 06:14:02 DEBUG : file1: reading active writers 2022/01/09 06:14:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:03 DEBUG : dir: Looking for writers 2022/01/09 06:14:03 DEBUG : : Looking for writers 2022/01/09 06:14:03 DEBUG : file1: reading active writers 2022/01/09 06:14:03 DEBUG : dir: reading active writers 2022/01/09 06:14:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:04 DEBUG : dir: Looking for writers 2022/01/09 06:14:04 DEBUG : : Looking for writers 2022/01/09 06:14:04 DEBUG : dir: reading active writers 2022/01/09 06:14:04 DEBUG : file1: reading active writers 2022/01/09 06:14:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:05 DEBUG : dir: Looking for writers 2022/01/09 06:14:05 DEBUG : : Looking for writers 2022/01/09 06:14:05 DEBUG : file1: reading active writers 2022/01/09 06:14:05 DEBUG : dir: reading active writers 2022/01/09 06:14:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:06 DEBUG : dir: Looking for writers 2022/01/09 06:14:06 DEBUG : : Looking for writers 2022/01/09 06:14:06 DEBUG : dir: reading active writers 2022/01/09 06:14:06 DEBUG : file1: reading active writers 2022/01/09 06:14:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:07 DEBUG : dir: Looking for writers 2022/01/09 06:14:07 DEBUG : : Looking for writers 2022/01/09 06:14:07 DEBUG : file1: reading active writers 2022/01/09 06:14:07 DEBUG : dir: reading active writers 2022/01/09 06:14:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:08 DEBUG : dir: Looking for writers 2022/01/09 06:14:08 DEBUG : : Looking for writers 2022/01/09 06:14:08 DEBUG : dir: reading active writers 2022/01/09 06:14:08 DEBUG : file1: reading active writers 2022/01/09 06:14:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:09 DEBUG : dir: Looking for writers 2022/01/09 06:14:09 DEBUG : : Looking for writers 2022/01/09 06:14:09 DEBUG : dir: reading active writers 2022/01/09 06:14:09 DEBUG : file1: reading active writers 2022/01/09 06:14:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:10 DEBUG : dir: Looking for writers 2022/01/09 06:14:10 DEBUG : : Looking for writers 2022/01/09 06:14:10 DEBUG : file1: reading active writers 2022/01/09 06:14:10 DEBUG : dir: reading active writers 2022/01/09 06:14:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:11 DEBUG : dir: Looking for writers 2022/01/09 06:14:11 DEBUG : : Looking for writers 2022/01/09 06:14:11 DEBUG : dir: reading active writers 2022/01/09 06:14:11 DEBUG : file1: reading active writers 2022/01/09 06:14:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:12 DEBUG : dir: Looking for writers 2022/01/09 06:14:12 DEBUG : : Looking for writers 2022/01/09 06:14:12 DEBUG : dir: reading active writers 2022/01/09 06:14:12 DEBUG : file1: reading active writers 2022/01/09 06:14:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:13 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc0002f4340 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228231619326598 ext:12839779355 loc:0x2a04b60} ATime:{wall:13866228231619337068 ext:12839789835 loc:0x2a04b60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2022/01/09 06:14:13 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleMethodsWrite (69.14s) === RUN TestRWFileHandleWriteAt run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:14:13 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:14:13 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:14:13 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:14:13 DEBUG : file1: newRWFileHandle: 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): openPending: 2022/01/09 06:14:13 ERROR : file1: vfs cache: detected external removal of cache file 2022/01/09 06:14:13 DEBUG : file1: vfs cache: truncate to size=0 2022/01/09 06:14:13 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): >openPending: err= 2022/01/09 06:14:13 DEBUG : file1: vfs cache: cancelling writeback (uploading false) 0xc000277f80 item 1 2022/01/09 06:14:13 DEBUG : file1: >newRWFileHandle: err= 2022/01/09 06:14:13 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:14:13 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/01/09 06:14:13 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): _writeAt: size=7, off=0 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): >_writeAt: n=7, err= 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): _writeAt: size=6, off=5 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): >_writeAt: n=6, err= 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): close: 2022/01/09 06:14:13 DEBUG : file1: vfs cache: setting modification time to 2022-01-09 06:14:13.855889799 +0000 UTC m=+81.753412380 2022/01/09 06:14:13 INFO : file1: vfs cache: queuing for upload in 100ms 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): >close: err= 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): _writeAt: size=5, off=0 2022/01/09 06:14:13 DEBUG : file1(0xc00074f640): >_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 2022/01/09 06:14:13 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:14:13 DEBUG : dir: Looking for writers 2022/01/09 06:14:13 DEBUG : : Looking for writers 2022/01/09 06:14:13 DEBUG : dir: reading active writers 2022/01/09 06:14:13 DEBUG : file1: reading active writers 2022/01/09 06:14:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/01/09 06:14:13 DEBUG : dir: Looking for writers 2022/01/09 06:14:13 DEBUG : : Looking for writers 2022/01/09 06:14:13 DEBUG : dir: reading active writers 2022/01/09 06:14:13 DEBUG : file1: reading active writers 2022/01/09 06:14:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/01/09 06:14:13 DEBUG : dir: Looking for writers 2022/01/09 06:14:13 DEBUG : : Looking for writers 2022/01/09 06:14:13 DEBUG : dir: reading active writers 2022/01/09 06:14:13 DEBUG : file1: reading active writers 2022/01/09 06:14:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/01/09 06:14:13 DEBUG : dir: Looking for writers 2022/01/09 06:14:13 DEBUG : : Looking for writers 2022/01/09 06:14:13 DEBUG : dir: reading active writers 2022/01/09 06:14:13 DEBUG : file1: reading active writers 2022/01/09 06:14:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/01/09 06:14:13 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:14:14 DEBUG : dir: Looking for writers 2022/01/09 06:14:14 DEBUG : : Looking for writers 2022/01/09 06:14:14 DEBUG : dir: reading active writers 2022/01/09 06:14:14 DEBUG : file1: reading active writers 2022/01/09 06:14:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2022/01/09 06:14:14 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:14:14 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 Payment Required) returned body: "" 2022/01/09 06:14:14 DEBUG : dir: Looking for writers 2022/01/09 06:14:14 DEBUG : : Looking for writers 2022/01/09 06:14:14 DEBUG : dir: reading active writers 2022/01/09 06:14:14 DEBUG : file1: reading active writers 2022/01/09 06:14:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2022/01/09 06:14:14 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:14:14 DEBUG : dir: Looking for writers 2022/01/09 06:14:14 DEBUG : : Looking for writers 2022/01/09 06:14:14 DEBUG : dir: reading active writers 2022/01/09 06:14:14 DEBUG : file1: reading active writers 2022/01/09 06:14:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2022/01/09 06:14:14 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:14:14 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 Payment Required) returned body: "" 2022/01/09 06:14:14 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:14:15 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:14:15 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 Payment Required) returned body: "" 2022/01/09 06:14:15 DEBUG : dir: Looking for writers 2022/01/09 06:14:15 DEBUG : : Looking for writers 2022/01/09 06:14:15 DEBUG : dir: reading active writers 2022/01/09 06:14:15 DEBUG : file1: reading active writers 2022/01/09 06:14:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:15 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:14:16 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:14:16 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 Payment Required) returned body: "" 2022/01/09 06:14:16 DEBUG : dir: Looking for writers 2022/01/09 06:14:16 DEBUG : : Looking for writers 2022/01/09 06:14:16 DEBUG : dir: reading active writers 2022/01/09 06:14:16 DEBUG : file1: reading active writers 2022/01/09 06:14:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:17 DEBUG : dir: Looking for writers 2022/01/09 06:14:17 DEBUG : : Looking for writers 2022/01/09 06:14:17 DEBUG : dir: reading active writers 2022/01/09 06:14:17 DEBUG : file1: reading active writers 2022/01/09 06:14:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:17 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:14:17 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:14:17 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 Payment Required) returned body: "" 2022/01/09 06:14:18 DEBUG : dir: Looking for writers 2022/01/09 06:14:18 DEBUG : : Looking for writers 2022/01/09 06:14:18 DEBUG : dir: reading active writers 2022/01/09 06:14:18 DEBUG : file1: reading active writers 2022/01/09 06:14:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:19 DEBUG : dir: Looking for writers 2022/01/09 06:14:19 DEBUG : : Looking for writers 2022/01/09 06:14:19 DEBUG : file1: reading active writers 2022/01/09 06:14:19 DEBUG : dir: reading active writers 2022/01/09 06:14:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:20 DEBUG : dir: Looking for writers 2022/01/09 06:14:20 DEBUG : : Looking for writers 2022/01/09 06:14:20 DEBUG : dir: reading active writers 2022/01/09 06:14:20 DEBUG : file1: reading active writers 2022/01/09 06:14:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:21 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:14:21 DEBUG : dir: Looking for writers 2022/01/09 06:14:21 DEBUG : : Looking for writers 2022/01/09 06:14:21 DEBUG : dir: reading active writers 2022/01/09 06:14:21 DEBUG : file1: reading active writers 2022/01/09 06:14:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:21 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:14:21 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 Payment Required) returned body: "" 2022/01/09 06:14:22 DEBUG : dir: Looking for writers 2022/01/09 06:14:22 DEBUG : : Looking for writers 2022/01/09 06:14:22 DEBUG : file1: reading active writers 2022/01/09 06:14:22 DEBUG : dir: reading active writers 2022/01/09 06:14:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:23 DEBUG : dir: Looking for writers 2022/01/09 06:14:23 DEBUG : : Looking for writers 2022/01/09 06:14:23 DEBUG : dir: reading active writers 2022/01/09 06:14:23 DEBUG : file1: reading active writers 2022/01/09 06:14:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:24 DEBUG : dir: Looking for writers 2022/01/09 06:14:24 DEBUG : : Looking for writers 2022/01/09 06:14:24 DEBUG : dir: reading active writers 2022/01/09 06:14:24 DEBUG : file1: reading active writers 2022/01/09 06:14:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:25 DEBUG : dir: Looking for writers 2022/01/09 06:14:25 DEBUG : : Looking for writers 2022/01/09 06:14:25 DEBUG : file1: reading active writers 2022/01/09 06:14:25 DEBUG : dir: reading active writers 2022/01/09 06:14:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:26 DEBUG : dir: Looking for writers 2022/01/09 06:14:26 DEBUG : : Looking for writers 2022/01/09 06:14:26 DEBUG : dir: reading active writers 2022/01/09 06:14:26 DEBUG : file1: reading active writers 2022/01/09 06:14:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:27 DEBUG : dir: Looking for writers 2022/01/09 06:14:27 DEBUG : : Looking for writers 2022/01/09 06:14:27 DEBUG : dir: reading active writers 2022/01/09 06:14:27 DEBUG : file1: reading active writers 2022/01/09 06:14:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:27 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:14:27 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:14:27 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 Payment Required) returned body: "" 2022/01/09 06:14:28 DEBUG : dir: Looking for writers 2022/01/09 06:14:28 DEBUG : : Looking for writers 2022/01/09 06:14:28 DEBUG : dir: reading active writers 2022/01/09 06:14:28 DEBUG : file1: reading active writers 2022/01/09 06:14:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:29 DEBUG : dir: Looking for writers 2022/01/09 06:14:29 DEBUG : : Looking for writers 2022/01/09 06:14:29 DEBUG : dir: reading active writers 2022/01/09 06:14:29 DEBUG : file1: reading active writers 2022/01/09 06:14:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:30 DEBUG : dir: Looking for writers 2022/01/09 06:14:30 DEBUG : : Looking for writers 2022/01/09 06:14:30 DEBUG : dir: reading active writers 2022/01/09 06:14:30 DEBUG : file1: reading active writers 2022/01/09 06:14:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:31 DEBUG : dir: Looking for writers 2022/01/09 06:14:31 DEBUG : : Looking for writers 2022/01/09 06:14:31 DEBUG : dir: reading active writers 2022/01/09 06:14:31 DEBUG : file1: reading active writers 2022/01/09 06:14:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:32 DEBUG : dir: Looking for writers 2022/01/09 06:14:32 DEBUG : : Looking for writers 2022/01/09 06:14:32 DEBUG : dir: reading active writers 2022/01/09 06:14:32 DEBUG : file1: reading active writers 2022/01/09 06:14:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:33 DEBUG : dir: Looking for writers 2022/01/09 06:14:33 DEBUG : : Looking for writers 2022/01/09 06:14:33 DEBUG : file1: reading active writers 2022/01/09 06:14:33 DEBUG : dir: reading active writers 2022/01/09 06:14:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:34 DEBUG : dir: Looking for writers 2022/01/09 06:14:34 DEBUG : : Looking for writers 2022/01/09 06:14:34 DEBUG : dir: reading active writers 2022/01/09 06:14:34 DEBUG : file1: reading active writers 2022/01/09 06:14:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:35 DEBUG : dir: Looking for writers 2022/01/09 06:14:35 DEBUG : : Looking for writers 2022/01/09 06:14:35 DEBUG : dir: reading active writers 2022/01/09 06:14:35 DEBUG : file1: reading active writers 2022/01/09 06:14:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:36 DEBUG : dir: Looking for writers 2022/01/09 06:14:36 DEBUG : : Looking for writers 2022/01/09 06:14:36 DEBUG : file1: reading active writers 2022/01/09 06:14:36 DEBUG : dir: reading active writers 2022/01/09 06:14:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:37 DEBUG : dir: Looking for writers 2022/01/09 06:14:37 DEBUG : : Looking for writers 2022/01/09 06:14:37 DEBUG : dir: reading active writers 2022/01/09 06:14:37 DEBUG : file1: reading active writers 2022/01/09 06:14:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:38 DEBUG : dir: Looking for writers 2022/01/09 06:14:38 DEBUG : : Looking for writers 2022/01/09 06:14:38 DEBUG : dir: reading active writers 2022/01/09 06:14:38 DEBUG : file1: reading active writers 2022/01/09 06:14:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:39 DEBUG : dir: Looking for writers 2022/01/09 06:14:39 DEBUG : : Looking for writers 2022/01/09 06:14:39 DEBUG : dir: reading active writers 2022/01/09 06:14:39 DEBUG : file1: reading active writers 2022/01/09 06:14:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:40 DEBUG : dir: Looking for writers 2022/01/09 06:14:40 DEBUG : : Looking for writers 2022/01/09 06:14:40 DEBUG : dir: reading active writers 2022/01/09 06:14:40 DEBUG : file1: reading active writers 2022/01/09 06:14:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:40 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:14:40 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:14:40 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 Payment Required) returned body: "" 2022/01/09 06:14:41 DEBUG : dir: Looking for writers 2022/01/09 06:14:41 DEBUG : : Looking for writers 2022/01/09 06:14:41 DEBUG : dir: reading active writers 2022/01/09 06:14:41 DEBUG : file1: reading active writers 2022/01/09 06:14:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:42 DEBUG : dir: Looking for writers 2022/01/09 06:14:42 DEBUG : : Looking for writers 2022/01/09 06:14:42 DEBUG : file1: reading active writers 2022/01/09 06:14:42 DEBUG : dir: reading active writers 2022/01/09 06:14:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:43 DEBUG : dir: Looking for writers 2022/01/09 06:14:43 DEBUG : : Looking for writers 2022/01/09 06:14:43 DEBUG : dir: reading active writers 2022/01/09 06:14:43 DEBUG : file1: reading active writers 2022/01/09 06:14:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:43 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc0002f4340 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228305621145479 ext:81753412380 loc:0x2a04b60} ATime:{wall:13866228305621155648 ext:81753422549 loc:0x2a04b60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2022/01/09 06:14:43 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 2022/01/09 06:14:51 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:14:51 DEBUG : dir: Looking for writers 2022/01/09 06:14:51 DEBUG : : Looking for writers 2022/01/09 06:14:51 DEBUG : dir: reading active writers 2022/01/09 06:14:51 DEBUG : file1: reading active writers 2022/01/09 06:14:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2022/01/09 06:14:51 DEBUG : dir: Looking for writers 2022/01/09 06:14:51 DEBUG : : Looking for writers 2022/01/09 06:14:51 DEBUG : dir: reading active writers 2022/01/09 06:14:51 DEBUG : file1: reading active writers 2022/01/09 06:14:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2022/01/09 06:14:51 DEBUG : dir: Looking for writers 2022/01/09 06:14:51 DEBUG : : Looking for writers 2022/01/09 06:14:51 DEBUG : dir: reading active writers 2022/01/09 06:14:51 DEBUG : file1: reading active writers 2022/01/09 06:14:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2022/01/09 06:14:51 DEBUG : dir: Looking for writers 2022/01/09 06:14:51 DEBUG : : Looking for writers 2022/01/09 06:14:51 DEBUG : dir: reading active writers 2022/01/09 06:14:51 DEBUG : file1: reading active writers 2022/01/09 06:14:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2022/01/09 06:14:51 DEBUG : dir: Looking for writers 2022/01/09 06:14:51 DEBUG : : Looking for writers 2022/01/09 06:14:51 DEBUG : file1: reading active writers 2022/01/09 06:14:51 DEBUG : dir: reading active writers 2022/01/09 06:14:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2022/01/09 06:14:51 DEBUG : dir: Looking for writers 2022/01/09 06:14:51 DEBUG : : Looking for writers 2022/01/09 06:14:51 DEBUG : dir: reading active writers 2022/01/09 06:14:51 DEBUG : file1: reading active writers 2022/01/09 06:14:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2022/01/09 06:14:52 DEBUG : dir: Looking for writers 2022/01/09 06:14:52 DEBUG : : Looking for writers 2022/01/09 06:14:52 DEBUG : dir: reading active writers 2022/01/09 06:14:52 DEBUG : file1: reading active writers 2022/01/09 06:14:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2022/01/09 06:14:52 DEBUG : dir: Looking for writers 2022/01/09 06:14:52 DEBUG : : Looking for writers 2022/01/09 06:14:52 DEBUG : dir: reading active writers 2022/01/09 06:14:52 DEBUG : file1: reading active writers 2022/01/09 06:14:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:53 DEBUG : dir: Looking for writers 2022/01/09 06:14:53 DEBUG : : Looking for writers 2022/01/09 06:14:53 DEBUG : file1: reading active writers 2022/01/09 06:14:53 DEBUG : dir: reading active writers 2022/01/09 06:14:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:54 DEBUG : dir: Looking for writers 2022/01/09 06:14:54 DEBUG : : Looking for writers 2022/01/09 06:14:54 DEBUG : dir: reading active writers 2022/01/09 06:14:54 DEBUG : file1: reading active writers 2022/01/09 06:14:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:55 DEBUG : dir: Looking for writers 2022/01/09 06:14:55 DEBUG : : Looking for writers 2022/01/09 06:14:55 DEBUG : dir: reading active writers 2022/01/09 06:14:55 DEBUG : file1: reading active writers 2022/01/09 06:14:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:56 DEBUG : dir: Looking for writers 2022/01/09 06:14:56 DEBUG : : Looking for writers 2022/01/09 06:14:56 DEBUG : dir: reading active writers 2022/01/09 06:14:56 DEBUG : file1: reading active writers 2022/01/09 06:14:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:57 DEBUG : dir: Looking for writers 2022/01/09 06:14:57 DEBUG : : Looking for writers 2022/01/09 06:14:57 DEBUG : dir: reading active writers 2022/01/09 06:14:57 DEBUG : file1: reading active writers 2022/01/09 06:14:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:58 DEBUG : dir: Looking for writers 2022/01/09 06:14:58 DEBUG : : Looking for writers 2022/01/09 06:14:58 DEBUG : dir: reading active writers 2022/01/09 06:14:58 DEBUG : file1: reading active writers 2022/01/09 06:14:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:14:59 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2022/01/09 06:14:59 INFO : vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 11 (was 11) 2022/01/09 06:14:59 DEBUG : dir: Looking for writers 2022/01/09 06:14:59 DEBUG : : Looking for writers 2022/01/09 06:14:59 DEBUG : file1: reading active writers 2022/01/09 06:14:59 DEBUG : dir: reading active writers 2022/01/09 06:14:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:00 DEBUG : dir: Looking for writers 2022/01/09 06:15:00 DEBUG : : Looking for writers 2022/01/09 06:15:00 DEBUG : dir: reading active writers 2022/01/09 06:15:00 DEBUG : file1: reading active writers 2022/01/09 06:15:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:01 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2022/01/09 06:15:01 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2022/01/09 06:15:01 DEBUG : dir: Looking for writers 2022/01/09 06:15:01 DEBUG : : Looking for writers 2022/01/09 06:15:01 DEBUG : dir: reading active writers 2022/01/09 06:15:01 DEBUG : file1: reading active writers 2022/01/09 06:15:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:02 DEBUG : dir: Looking for writers 2022/01/09 06:15:02 DEBUG : : Looking for writers 2022/01/09 06:15:02 DEBUG : dir: reading active writers 2022/01/09 06:15:02 DEBUG : file1: reading active writers 2022/01/09 06:15:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:03 DEBUG : dir: Looking for writers 2022/01/09 06:15:03 DEBUG : : Looking for writers 2022/01/09 06:15:03 DEBUG : dir: reading active writers 2022/01/09 06:15:03 DEBUG : file1: reading active writers 2022/01/09 06:15:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:04 DEBUG : dir: Looking for writers 2022/01/09 06:15:04 DEBUG : : Looking for writers 2022/01/09 06:15:04 DEBUG : dir: reading active writers 2022/01/09 06:15:04 DEBUG : file1: reading active writers 2022/01/09 06:15:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:05 DEBUG : dir: Looking for writers 2022/01/09 06:15:05 DEBUG : : Looking for writers 2022/01/09 06:15:05 DEBUG : dir: reading active writers 2022/01/09 06:15:05 DEBUG : file1: reading active writers 2022/01/09 06:15:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:06 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:06 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:06 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 Payment Required) returned body: "" 2022/01/09 06:15:06 DEBUG : dir: Looking for writers 2022/01/09 06:15:06 DEBUG : : Looking for writers 2022/01/09 06:15:06 DEBUG : dir: reading active writers 2022/01/09 06:15:06 DEBUG : file1: reading active writers 2022/01/09 06:15:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:07 DEBUG : dir: Looking for writers 2022/01/09 06:15:07 DEBUG : : Looking for writers 2022/01/09 06:15:07 DEBUG : dir: reading active writers 2022/01/09 06:15:07 DEBUG : file1: reading active writers 2022/01/09 06:15:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:08 DEBUG : dir: Looking for writers 2022/01/09 06:15:08 DEBUG : : Looking for writers 2022/01/09 06:15:08 DEBUG : file1: reading active writers 2022/01/09 06:15:08 DEBUG : dir: reading active writers 2022/01/09 06:15:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:09 DEBUG : dir: Looking for writers 2022/01/09 06:15:09 DEBUG : : Looking for writers 2022/01/09 06:15:09 DEBUG : dir: reading active writers 2022/01/09 06:15:09 DEBUG : file1: reading active writers 2022/01/09 06:15:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:10 DEBUG : dir: Looking for writers 2022/01/09 06:15:10 DEBUG : : Looking for writers 2022/01/09 06:15:10 DEBUG : dir: reading active writers 2022/01/09 06:15:10 DEBUG : file1: reading active writers 2022/01/09 06:15:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:11 DEBUG : dir: Looking for writers 2022/01/09 06:15:11 DEBUG : : Looking for writers 2022/01/09 06:15:11 DEBUG : dir: reading active writers 2022/01/09 06:15:11 DEBUG : file1: reading active writers 2022/01/09 06:15:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:12 DEBUG : dir: Looking for writers 2022/01/09 06:15:12 DEBUG : : Looking for writers 2022/01/09 06:15:12 DEBUG : dir: reading active writers 2022/01/09 06:15:12 DEBUG : file1: reading active writers 2022/01/09 06:15:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:13 DEBUG : dir: Looking for writers 2022/01/09 06:15:13 DEBUG : : Looking for writers 2022/01/09 06:15:13 DEBUG : dir: reading active writers 2022/01/09 06:15:13 DEBUG : file1: reading active writers 2022/01/09 06:15:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:14 DEBUG : dir: Looking for writers 2022/01/09 06:15:14 DEBUG : : Looking for writers 2022/01/09 06:15:14 DEBUG : dir: reading active writers 2022/01/09 06:15:14 DEBUG : file1: reading active writers 2022/01/09 06:15:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:15 DEBUG : dir: Looking for writers 2022/01/09 06:15:15 DEBUG : : Looking for writers 2022/01/09 06:15:15 DEBUG : dir: reading active writers 2022/01/09 06:15:15 DEBUG : file1: reading active writers 2022/01/09 06:15:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:16 DEBUG : dir: Looking for writers 2022/01/09 06:15:16 DEBUG : : Looking for writers 2022/01/09 06:15:16 DEBUG : dir: reading active writers 2022/01/09 06:15:16 DEBUG : file1: reading active writers 2022/01/09 06:15:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:17 DEBUG : dir: Looking for writers 2022/01/09 06:15:17 DEBUG : : Looking for writers 2022/01/09 06:15:17 DEBUG : dir: reading active writers 2022/01/09 06:15:17 DEBUG : file1: reading active writers 2022/01/09 06:15:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:18 DEBUG : dir: Looking for writers 2022/01/09 06:15:18 DEBUG : : Looking for writers 2022/01/09 06:15:18 DEBUG : dir: reading active writers 2022/01/09 06:15:18 DEBUG : file1: reading active writers 2022/01/09 06:15:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:19 DEBUG : dir: Looking for writers 2022/01/09 06:15:19 DEBUG : : Looking for writers 2022/01/09 06:15:19 DEBUG : dir: reading active writers 2022/01/09 06:15:19 DEBUG : file1: reading active writers 2022/01/09 06:15:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:20 DEBUG : dir: Looking for writers 2022/01/09 06:15:20 DEBUG : : Looking for writers 2022/01/09 06:15:20 DEBUG : dir: reading active writers 2022/01/09 06:15:20 DEBUG : file1: reading active writers 2022/01/09 06:15:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2022/01/09 06:15:21 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc0002f4340 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228305621145479 ext:81753412380 loc:0x2a04b60} ATime:{wall:13866228305621155648 ext:81753422549 loc:0x2a04b60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2022/01/09 06:15:21 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleWriteAt (67.80s) === RUN TestRWFileHandleWriteNoWrite run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:15:21 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:15:21 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:15:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:15:21 DEBUG : file1: newRWFileHandle: 2022/01/09 06:15:21 DEBUG : file1(0xc000742000): openPending: 2022/01/09 06:15:21 ERROR : file1: vfs cache: detected external removal of cache file 2022/01/09 06:15:21 DEBUG : file1: vfs cache: truncate to size=0 2022/01/09 06:15:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:15:21 DEBUG : file1(0xc000742000): >openPending: err= 2022/01/09 06:15:21 DEBUG : file1: vfs cache: cancelling writeback (uploading false) 0xc00030a4d0 item 1 2022/01/09 06:15:21 DEBUG : file1: >newRWFileHandle: err= 2022/01/09 06:15:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:15:21 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/01/09 06:15:21 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2022/01/09 06:15:21 DEBUG : file1(0xc000742000): close: 2022/01/09 06:15:21 DEBUG : file1: vfs cache: setting modification time to 2022-01-09 06:15:21.655273987 +0000 UTC m=+149.552796608 2022/01/09 06:15:21 INFO : file1: vfs cache: queuing for upload in 100ms 2022/01/09 06:15:21 DEBUG : file1(0xc000742000): >close: err= 2022/01/09 06:15:21 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2022/01/09 06:15:21 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2022/01/09 06:15:21 DEBUG : file2: newRWFileHandle: 2022/01/09 06:15:21 DEBUG : file2(0xc000742140): openPending: 2022/01/09 06:15:21 DEBUG : file2: vfs cache: truncate to size=0 2022/01/09 06:15:21 DEBUG : : Added virtual directory entry vAddFile: "file2" 2022/01/09 06:15:21 DEBUG : file2(0xc000742140): >openPending: err= 2022/01/09 06:15:21 DEBUG : file2: >newRWFileHandle: err= 2022/01/09 06:15:21 DEBUG : : Added virtual directory entry vAddFile: "file2" 2022/01/09 06:15:21 DEBUG : file2: >Open: fd=file2 (rw), err= 2022/01/09 06:15:21 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2022/01/09 06:15:21 DEBUG : file2(0xc000742140): RWFileHandle.Flush 2022/01/09 06:15:21 DEBUG : file2(0xc000742140): RWFileHandle.Release 2022/01/09 06:15:21 DEBUG : file2(0xc000742140): close: 2022/01/09 06:15:21 DEBUG : file2: vfs cache: setting modification time to 2022-01-09 06:15:21.656489752 +0000 UTC m=+149.554012334 2022/01/09 06:15:21 INFO : file2: vfs cache: queuing for upload in 100ms 2022/01/09 06:15:21 DEBUG : file2(0xc000742140): >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 2022/01/09 06:15:21 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:15:21 DEBUG : dir: Looking for writers 2022/01/09 06:15:21 DEBUG : : Looking for writers 2022/01/09 06:15:21 DEBUG : dir: reading active writers 2022/01/09 06:15:21 DEBUG : file1: reading active writers 2022/01/09 06:15:21 DEBUG : file2: reading active writers 2022/01/09 06:15:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2022/01/09 06:15:21 DEBUG : dir: Looking for writers 2022/01/09 06:15:21 DEBUG : : Looking for writers 2022/01/09 06:15:21 DEBUG : dir: reading active writers 2022/01/09 06:15:21 DEBUG : file1: reading active writers 2022/01/09 06:15:21 DEBUG : file2: reading active writers 2022/01/09 06:15:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2022/01/09 06:15:21 DEBUG : dir: Looking for writers 2022/01/09 06:15:21 DEBUG : : Looking for writers 2022/01/09 06:15:21 DEBUG : file1: reading active writers 2022/01/09 06:15:21 DEBUG : file2: reading active writers 2022/01/09 06:15:21 DEBUG : dir: reading active writers 2022/01/09 06:15:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2022/01/09 06:15:21 DEBUG : dir: Looking for writers 2022/01/09 06:15:21 DEBUG : : Looking for writers 2022/01/09 06:15:21 DEBUG : file1: reading active writers 2022/01/09 06:15:21 DEBUG : file2: reading active writers 2022/01/09 06:15:21 DEBUG : dir: reading active writers 2022/01/09 06:15:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2022/01/09 06:15:21 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:15:21 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:21 DEBUG : dir: Looking for writers 2022/01/09 06:15:21 DEBUG : : Looking for writers 2022/01/09 06:15:21 DEBUG : file1: reading active writers 2022/01/09 06:15:21 DEBUG : file2: reading active writers 2022/01/09 06:15:21 DEBUG : dir: reading active writers 2022/01/09 06:15:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2022/01/09 06:15:21 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:21 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 Payment Required) returned body: "" 2022/01/09 06:15:21 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:21 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 Payment Required) returned body: "" 2022/01/09 06:15:21 DEBUG : dir: Looking for writers 2022/01/09 06:15:21 DEBUG : : Looking for writers 2022/01/09 06:15:21 DEBUG : dir: reading active writers 2022/01/09 06:15:21 DEBUG : file1: reading active writers 2022/01/09 06:15:21 DEBUG : file2: reading active writers 2022/01/09 06:15:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2022/01/09 06:15:22 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:15:22 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:22 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:22 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 Payment Required) returned body: "" 2022/01/09 06:15:22 DEBUG : dir: Looking for writers 2022/01/09 06:15:22 DEBUG : : Looking for writers 2022/01/09 06:15:22 DEBUG : dir: reading active writers 2022/01/09 06:15:22 DEBUG : file1: reading active writers 2022/01/09 06:15:22 DEBUG : file2: reading active writers 2022/01/09 06:15:22 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2022/01/09 06:15:22 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:22 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 Payment Required) returned body: "" 2022/01/09 06:15:22 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:15:22 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:22 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:22 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 Payment Required) returned body: "" 2022/01/09 06:15:22 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:22 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 Payment Required) returned body: "" 2022/01/09 06:15:22 DEBUG : dir: Looking for writers 2022/01/09 06:15:22 DEBUG : : Looking for writers 2022/01/09 06:15:22 DEBUG : dir: reading active writers 2022/01/09 06:15:22 DEBUG : file1: reading active writers 2022/01/09 06:15:22 DEBUG : file2: reading active writers 2022/01/09 06:15:22 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:23 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:15:23 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:23 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:23 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 Payment Required) returned body: "" 2022/01/09 06:15:23 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:23 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 Payment Required) returned body: "" 2022/01/09 06:15:23 DEBUG : dir: Looking for writers 2022/01/09 06:15:23 DEBUG : : Looking for writers 2022/01/09 06:15:23 DEBUG : file2: reading active writers 2022/01/09 06:15:23 DEBUG : dir: reading active writers 2022/01/09 06:15:23 DEBUG : file1: reading active writers 2022/01/09 06:15:23 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:24 DEBUG : dir: Looking for writers 2022/01/09 06:15:24 DEBUG : : Looking for writers 2022/01/09 06:15:24 DEBUG : dir: reading active writers 2022/01/09 06:15:24 DEBUG : file1: reading active writers 2022/01/09 06:15:24 DEBUG : file2: reading active writers 2022/01/09 06:15:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:25 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:15:25 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:25 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:25 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 Payment Required) returned body: "" 2022/01/09 06:15:25 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:25 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 Payment Required) returned body: "" 2022/01/09 06:15:25 DEBUG : dir: Looking for writers 2022/01/09 06:15:25 DEBUG : : Looking for writers 2022/01/09 06:15:25 DEBUG : dir: reading active writers 2022/01/09 06:15:25 DEBUG : file1: reading active writers 2022/01/09 06:15:25 DEBUG : file2: reading active writers 2022/01/09 06:15:25 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:26 DEBUG : dir: Looking for writers 2022/01/09 06:15:26 DEBUG : : Looking for writers 2022/01/09 06:15:26 DEBUG : file1: reading active writers 2022/01/09 06:15:26 DEBUG : file2: reading active writers 2022/01/09 06:15:26 DEBUG : dir: reading active writers 2022/01/09 06:15:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:27 DEBUG : dir: Looking for writers 2022/01/09 06:15:27 DEBUG : : Looking for writers 2022/01/09 06:15:27 DEBUG : dir: reading active writers 2022/01/09 06:15:27 DEBUG : file1: reading active writers 2022/01/09 06:15:27 DEBUG : file2: reading active writers 2022/01/09 06:15:27 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:28 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:15:28 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:28 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:28 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 Payment Required) returned body: "" 2022/01/09 06:15:28 DEBUG : dir: Looking for writers 2022/01/09 06:15:28 DEBUG : : Looking for writers 2022/01/09 06:15:28 DEBUG : file2: reading active writers 2022/01/09 06:15:28 DEBUG : dir: reading active writers 2022/01/09 06:15:28 DEBUG : file1: reading active writers 2022/01/09 06:15:28 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:28 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:28 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 Payment Required) returned body: "" 2022/01/09 06:15:29 DEBUG : dir: Looking for writers 2022/01/09 06:15:29 DEBUG : : Looking for writers 2022/01/09 06:15:29 DEBUG : dir: reading active writers 2022/01/09 06:15:29 DEBUG : file1: reading active writers 2022/01/09 06:15:29 DEBUG : file2: reading active writers 2022/01/09 06:15:29 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:30 DEBUG : dir: Looking for writers 2022/01/09 06:15:30 DEBUG : : Looking for writers 2022/01/09 06:15:30 DEBUG : file1: reading active writers 2022/01/09 06:15:30 DEBUG : file2: reading active writers 2022/01/09 06:15:30 DEBUG : dir: reading active writers 2022/01/09 06:15:30 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:31 DEBUG : dir: Looking for writers 2022/01/09 06:15:31 DEBUG : : Looking for writers 2022/01/09 06:15:31 DEBUG : dir: reading active writers 2022/01/09 06:15:31 DEBUG : file1: reading active writers 2022/01/09 06:15:31 DEBUG : file2: reading active writers 2022/01/09 06:15:31 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:32 DEBUG : dir: Looking for writers 2022/01/09 06:15:32 DEBUG : : Looking for writers 2022/01/09 06:15:32 DEBUG : dir: reading active writers 2022/01/09 06:15:32 DEBUG : file1: reading active writers 2022/01/09 06:15:32 DEBUG : file2: reading active writers 2022/01/09 06:15:32 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:33 DEBUG : dir: Looking for writers 2022/01/09 06:15:33 DEBUG : : Looking for writers 2022/01/09 06:15:33 DEBUG : dir: reading active writers 2022/01/09 06:15:33 DEBUG : file1: reading active writers 2022/01/09 06:15:33 DEBUG : file2: reading active writers 2022/01/09 06:15:33 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:34 DEBUG : dir: Looking for writers 2022/01/09 06:15:34 DEBUG : : Looking for writers 2022/01/09 06:15:34 DEBUG : file1: reading active writers 2022/01/09 06:15:34 DEBUG : file2: reading active writers 2022/01/09 06:15:34 DEBUG : dir: reading active writers 2022/01/09 06:15:34 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:35 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:15:35 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:35 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:35 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 Payment Required) returned body: "" 2022/01/09 06:15:35 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:35 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 Payment Required) returned body: "" 2022/01/09 06:15:35 DEBUG : dir: Looking for writers 2022/01/09 06:15:35 DEBUG : : Looking for writers 2022/01/09 06:15:35 DEBUG : file1: reading active writers 2022/01/09 06:15:35 DEBUG : file2: reading active writers 2022/01/09 06:15:35 DEBUG : dir: reading active writers 2022/01/09 06:15:35 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:36 DEBUG : dir: Looking for writers 2022/01/09 06:15:36 DEBUG : : Looking for writers 2022/01/09 06:15:36 DEBUG : file2: reading active writers 2022/01/09 06:15:36 DEBUG : dir: reading active writers 2022/01/09 06:15:36 DEBUG : file1: reading active writers 2022/01/09 06:15:36 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:37 DEBUG : dir: Looking for writers 2022/01/09 06:15:37 DEBUG : : Looking for writers 2022/01/09 06:15:37 DEBUG : file2: reading active writers 2022/01/09 06:15:37 DEBUG : dir: reading active writers 2022/01/09 06:15:37 DEBUG : file1: reading active writers 2022/01/09 06:15:37 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:38 DEBUG : dir: Looking for writers 2022/01/09 06:15:38 DEBUG : : Looking for writers 2022/01/09 06:15:38 DEBUG : dir: reading active writers 2022/01/09 06:15:38 DEBUG : file1: reading active writers 2022/01/09 06:15:38 DEBUG : file2: reading active writers 2022/01/09 06:15:38 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:39 DEBUG : dir: Looking for writers 2022/01/09 06:15:39 DEBUG : : Looking for writers 2022/01/09 06:15:39 DEBUG : dir: reading active writers 2022/01/09 06:15:39 DEBUG : file1: reading active writers 2022/01/09 06:15:39 DEBUG : file2: reading active writers 2022/01/09 06:15:39 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:40 DEBUG : dir: Looking for writers 2022/01/09 06:15:40 DEBUG : : Looking for writers 2022/01/09 06:15:40 DEBUG : dir: reading active writers 2022/01/09 06:15:40 DEBUG : file1: reading active writers 2022/01/09 06:15:40 DEBUG : file2: reading active writers 2022/01/09 06:15:40 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:41 DEBUG : dir: Looking for writers 2022/01/09 06:15:41 DEBUG : : Looking for writers 2022/01/09 06:15:41 DEBUG : dir: reading active writers 2022/01/09 06:15:41 DEBUG : file1: reading active writers 2022/01/09 06:15:41 DEBUG : file2: reading active writers 2022/01/09 06:15:41 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:42 DEBUG : dir: Looking for writers 2022/01/09 06:15:42 DEBUG : : Looking for writers 2022/01/09 06:15:42 DEBUG : dir: reading active writers 2022/01/09 06:15:42 DEBUG : file1: reading active writers 2022/01/09 06:15:42 DEBUG : file2: reading active writers 2022/01/09 06:15:42 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:43 DEBUG : dir: Looking for writers 2022/01/09 06:15:43 DEBUG : : Looking for writers 2022/01/09 06:15:43 DEBUG : dir: reading active writers 2022/01/09 06:15:43 DEBUG : file1: reading active writers 2022/01/09 06:15:43 DEBUG : file2: reading active writers 2022/01/09 06:15:43 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:44 DEBUG : dir: Looking for writers 2022/01/09 06:15:44 DEBUG : : Looking for writers 2022/01/09 06:15:44 DEBUG : file1: reading active writers 2022/01/09 06:15:44 DEBUG : file2: reading active writers 2022/01/09 06:15:44 DEBUG : dir: reading active writers 2022/01/09 06:15:44 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:45 DEBUG : dir: Looking for writers 2022/01/09 06:15:45 DEBUG : : Looking for writers 2022/01/09 06:15:45 DEBUG : dir: reading active writers 2022/01/09 06:15:45 DEBUG : file1: reading active writers 2022/01/09 06:15:45 DEBUG : file2: reading active writers 2022/01/09 06:15:45 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:46 DEBUG : dir: Looking for writers 2022/01/09 06:15:46 DEBUG : : Looking for writers 2022/01/09 06:15:46 DEBUG : file2: reading active writers 2022/01/09 06:15:46 DEBUG : dir: reading active writers 2022/01/09 06:15:46 DEBUG : file1: reading active writers 2022/01/09 06:15:46 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:47 DEBUG : dir: Looking for writers 2022/01/09 06:15:47 DEBUG : : Looking for writers 2022/01/09 06:15:47 DEBUG : file2: reading active writers 2022/01/09 06:15:47 DEBUG : dir: reading active writers 2022/01/09 06:15:47 DEBUG : file1: reading active writers 2022/01/09 06:15:47 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:48 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:15:48 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:15:48 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:48 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 Payment Required) returned body: "" 2022/01/09 06:15:48 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:15:48 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 Payment Required) returned body: "" 2022/01/09 06:15:48 DEBUG : dir: Looking for writers 2022/01/09 06:15:48 DEBUG : : Looking for writers 2022/01/09 06:15:48 DEBUG : dir: reading active writers 2022/01/09 06:15:48 DEBUG : file1: reading active writers 2022/01/09 06:15:48 DEBUG : file2: reading active writers 2022/01/09 06:15:48 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:49 DEBUG : dir: Looking for writers 2022/01/09 06:15:49 DEBUG : : Looking for writers 2022/01/09 06:15:49 DEBUG : file2: reading active writers 2022/01/09 06:15:49 DEBUG : dir: reading active writers 2022/01/09 06:15:49 DEBUG : file1: reading active writers 2022/01/09 06:15:49 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:50 DEBUG : dir: Looking for writers 2022/01/09 06:15:50 DEBUG : : Looking for writers 2022/01/09 06:15:50 DEBUG : dir: reading active writers 2022/01/09 06:15:50 DEBUG : file1: reading active writers 2022/01/09 06:15:50 DEBUG : file2: reading active writers 2022/01/09 06:15:50 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:15:51 ERROR : Exiting even though 0 writers active and 2 cache items in use after 30s Cache{ "file1": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc0002f4340 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228378434973699 ext:149552796608 loc:0x2a04b60} ATime:{wall:13866228378435398655 ext:149553221524 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, "file2": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc000742100 name:file2 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228378436189464 ext:149554012334 loc:0x2a04b60} ATime:{wall:13866228378436595545 ext:149554418414 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 beingReset:false}, } 2022/01/09 06:15:51 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: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 2022/01/09 06:15:59 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:15:59 DEBUG : dir: Looking for writers 2022/01/09 06:15:59 DEBUG : : Looking for writers 2022/01/09 06:15:59 DEBUG : file1: reading active writers 2022/01/09 06:15:59 DEBUG : file2: reading active writers 2022/01/09 06:15:59 DEBUG : dir: reading active writers 2022/01/09 06:15:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2022/01/09 06:15:59 DEBUG : dir: Looking for writers 2022/01/09 06:15:59 DEBUG : : Looking for writers 2022/01/09 06:15:59 DEBUG : dir: reading active writers 2022/01/09 06:15:59 DEBUG : file1: reading active writers 2022/01/09 06:15:59 DEBUG : file2: reading active writers 2022/01/09 06:15:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2022/01/09 06:15:59 DEBUG : dir: Looking for writers 2022/01/09 06:15:59 DEBUG : : Looking for writers 2022/01/09 06:15:59 DEBUG : dir: reading active writers 2022/01/09 06:15:59 DEBUG : file1: reading active writers 2022/01/09 06:15:59 DEBUG : file2: reading active writers 2022/01/09 06:15:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2022/01/09 06:15:59 DEBUG : dir: Looking for writers 2022/01/09 06:15:59 DEBUG : : Looking for writers 2022/01/09 06:15:59 DEBUG : file1: reading active writers 2022/01/09 06:15:59 DEBUG : file2: reading active writers 2022/01/09 06:15:59 DEBUG : dir: reading active writers 2022/01/09 06:15:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2022/01/09 06:15:59 DEBUG : dir: Looking for writers 2022/01/09 06:15:59 DEBUG : : Looking for writers 2022/01/09 06:15:59 DEBUG : file2: reading active writers 2022/01/09 06:15:59 DEBUG : dir: reading active writers 2022/01/09 06:15:59 DEBUG : file1: reading active writers 2022/01/09 06:15:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2022/01/09 06:15:59 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2022/01/09 06:15:59 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file2 not removed, freed 0 bytes 2022/01/09 06:15:59 INFO : vfs cache: cleaned: objects 2 (was 2) in use 2, to upload 2, uploading 0, total size 0 (was 0) 2022/01/09 06:15:59 DEBUG : dir: Looking for writers 2022/01/09 06:15:59 DEBUG : : Looking for writers 2022/01/09 06:15:59 DEBUG : file2: reading active writers 2022/01/09 06:15:59 DEBUG : dir: reading active writers 2022/01/09 06:15:59 DEBUG : file1: reading active writers 2022/01/09 06:15:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2022/01/09 06:16:00 DEBUG : dir: Looking for writers 2022/01/09 06:16:00 DEBUG : : Looking for writers 2022/01/09 06:16:00 DEBUG : file1: reading active writers 2022/01/09 06:16:00 DEBUG : file2: reading active writers 2022/01/09 06:16:00 DEBUG : dir: reading active writers 2022/01/09 06:16:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2022/01/09 06:16:00 DEBUG : dir: Looking for writers 2022/01/09 06:16:00 DEBUG : : Looking for writers 2022/01/09 06:16:00 DEBUG : dir: reading active writers 2022/01/09 06:16:00 DEBUG : file1: reading active writers 2022/01/09 06:16:00 DEBUG : file2: reading active writers 2022/01/09 06:16:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:01 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2022/01/09 06:16:01 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2022/01/09 06:16:01 DEBUG : dir: Looking for writers 2022/01/09 06:16:01 DEBUG : : Looking for writers 2022/01/09 06:16:01 DEBUG : dir: reading active writers 2022/01/09 06:16:01 DEBUG : file1: reading active writers 2022/01/09 06:16:01 DEBUG : file2: reading active writers 2022/01/09 06:16:01 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:02 DEBUG : dir: Looking for writers 2022/01/09 06:16:02 DEBUG : : Looking for writers 2022/01/09 06:16:02 DEBUG : dir: reading active writers 2022/01/09 06:16:02 DEBUG : file1: reading active writers 2022/01/09 06:16:02 DEBUG : file2: reading active writers 2022/01/09 06:16:02 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:03 DEBUG : dir: Looking for writers 2022/01/09 06:16:03 DEBUG : : Looking for writers 2022/01/09 06:16:03 DEBUG : file1: reading active writers 2022/01/09 06:16:03 DEBUG : file2: reading active writers 2022/01/09 06:16:03 DEBUG : dir: reading active writers 2022/01/09 06:16:03 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:04 DEBUG : dir: Looking for writers 2022/01/09 06:16:04 DEBUG : : Looking for writers 2022/01/09 06:16:04 DEBUG : dir: reading active writers 2022/01/09 06:16:04 DEBUG : file1: reading active writers 2022/01/09 06:16:04 DEBUG : file2: reading active writers 2022/01/09 06:16:04 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:05 DEBUG : dir: Looking for writers 2022/01/09 06:16:05 DEBUG : : Looking for writers 2022/01/09 06:16:05 DEBUG : dir: reading active writers 2022/01/09 06:16:05 DEBUG : file1: reading active writers 2022/01/09 06:16:05 DEBUG : file2: reading active writers 2022/01/09 06:16:05 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:06 DEBUG : dir: Looking for writers 2022/01/09 06:16:06 DEBUG : : Looking for writers 2022/01/09 06:16:06 DEBUG : dir: reading active writers 2022/01/09 06:16:06 DEBUG : file1: reading active writers 2022/01/09 06:16:06 DEBUG : file2: reading active writers 2022/01/09 06:16:06 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:07 DEBUG : dir: Looking for writers 2022/01/09 06:16:07 DEBUG : : Looking for writers 2022/01/09 06:16:07 DEBUG : dir: reading active writers 2022/01/09 06:16:07 DEBUG : file1: reading active writers 2022/01/09 06:16:07 DEBUG : file2: reading active writers 2022/01/09 06:16:07 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:08 DEBUG : dir: Looking for writers 2022/01/09 06:16:08 DEBUG : : Looking for writers 2022/01/09 06:16:08 DEBUG : dir: reading active writers 2022/01/09 06:16:08 DEBUG : file1: reading active writers 2022/01/09 06:16:08 DEBUG : file2: reading active writers 2022/01/09 06:16:08 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:09 DEBUG : dir: Looking for writers 2022/01/09 06:16:09 DEBUG : : Looking for writers 2022/01/09 06:16:09 DEBUG : file2: reading active writers 2022/01/09 06:16:09 DEBUG : dir: reading active writers 2022/01/09 06:16:09 DEBUG : file1: reading active writers 2022/01/09 06:16:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:10 DEBUG : dir: Looking for writers 2022/01/09 06:16:10 DEBUG : : Looking for writers 2022/01/09 06:16:10 DEBUG : dir: reading active writers 2022/01/09 06:16:10 DEBUG : file1: reading active writers 2022/01/09 06:16:10 DEBUG : file2: reading active writers 2022/01/09 06:16:10 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:11 DEBUG : dir: Looking for writers 2022/01/09 06:16:11 DEBUG : : Looking for writers 2022/01/09 06:16:11 DEBUG : dir: reading active writers 2022/01/09 06:16:11 DEBUG : file1: reading active writers 2022/01/09 06:16:11 DEBUG : file2: reading active writers 2022/01/09 06:16:11 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:12 DEBUG : dir: Looking for writers 2022/01/09 06:16:12 DEBUG : : Looking for writers 2022/01/09 06:16:12 DEBUG : file2: reading active writers 2022/01/09 06:16:12 DEBUG : dir: reading active writers 2022/01/09 06:16:12 DEBUG : file1: reading active writers 2022/01/09 06:16:12 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:13 DEBUG : dir: Looking for writers 2022/01/09 06:16:13 DEBUG : : Looking for writers 2022/01/09 06:16:13 DEBUG : dir: reading active writers 2022/01/09 06:16:13 DEBUG : file1: reading active writers 2022/01/09 06:16:13 DEBUG : file2: reading active writers 2022/01/09 06:16:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:14 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:16:14 DEBUG : file1: vfs cache: starting upload 2022/01/09 06:16:14 ERROR : file2: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:16:14 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 Payment Required) returned body: "" 2022/01/09 06:16:14 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:16:14 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 Payment Required) returned body: "" 2022/01/09 06:16:14 DEBUG : dir: Looking for writers 2022/01/09 06:16:14 DEBUG : : Looking for writers 2022/01/09 06:16:14 DEBUG : file1: reading active writers 2022/01/09 06:16:14 DEBUG : file2: reading active writers 2022/01/09 06:16:14 DEBUG : dir: reading active writers 2022/01/09 06:16:14 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:15 DEBUG : dir: Looking for writers 2022/01/09 06:16:15 DEBUG : : Looking for writers 2022/01/09 06:16:15 DEBUG : dir: reading active writers 2022/01/09 06:16:15 DEBUG : file1: reading active writers 2022/01/09 06:16:15 DEBUG : file2: reading active writers 2022/01/09 06:16:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:16 DEBUG : dir: Looking for writers 2022/01/09 06:16:16 DEBUG : : Looking for writers 2022/01/09 06:16:16 DEBUG : dir: reading active writers 2022/01/09 06:16:16 DEBUG : file1: reading active writers 2022/01/09 06:16:16 DEBUG : file2: reading active writers 2022/01/09 06:16:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:17 DEBUG : dir: Looking for writers 2022/01/09 06:16:17 DEBUG : : Looking for writers 2022/01/09 06:16:17 DEBUG : dir: reading active writers 2022/01/09 06:16:17 DEBUG : file1: reading active writers 2022/01/09 06:16:17 DEBUG : file2: reading active writers 2022/01/09 06:16:17 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:18 DEBUG : dir: Looking for writers 2022/01/09 06:16:18 DEBUG : : Looking for writers 2022/01/09 06:16:18 DEBUG : dir: reading active writers 2022/01/09 06:16:18 DEBUG : file1: reading active writers 2022/01/09 06:16:18 DEBUG : file2: reading active writers 2022/01/09 06:16:18 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:19 DEBUG : dir: Looking for writers 2022/01/09 06:16:19 DEBUG : : Looking for writers 2022/01/09 06:16:19 DEBUG : dir: reading active writers 2022/01/09 06:16:19 DEBUG : file1: reading active writers 2022/01/09 06:16:19 DEBUG : file2: reading active writers 2022/01/09 06:16:19 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:20 DEBUG : dir: Looking for writers 2022/01/09 06:16:20 DEBUG : : Looking for writers 2022/01/09 06:16:20 DEBUG : file1: reading active writers 2022/01/09 06:16:20 DEBUG : file2: reading active writers 2022/01/09 06:16:20 DEBUG : dir: reading active writers 2022/01/09 06:16:20 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:21 DEBUG : dir: Looking for writers 2022/01/09 06:16:21 DEBUG : : Looking for writers 2022/01/09 06:16:21 DEBUG : dir: reading active writers 2022/01/09 06:16:21 DEBUG : file1: reading active writers 2022/01/09 06:16:21 DEBUG : file2: reading active writers 2022/01/09 06:16:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:22 DEBUG : dir: Looking for writers 2022/01/09 06:16:22 DEBUG : : Looking for writers 2022/01/09 06:16:22 DEBUG : dir: reading active writers 2022/01/09 06:16:22 DEBUG : file1: reading active writers 2022/01/09 06:16:22 DEBUG : file2: reading active writers 2022/01/09 06:16:22 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:23 DEBUG : dir: Looking for writers 2022/01/09 06:16:23 DEBUG : : Looking for writers 2022/01/09 06:16:23 DEBUG : file1: reading active writers 2022/01/09 06:16:23 DEBUG : file2: reading active writers 2022/01/09 06:16:23 DEBUG : dir: reading active writers 2022/01/09 06:16:23 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:24 DEBUG : dir: Looking for writers 2022/01/09 06:16:24 DEBUG : : Looking for writers 2022/01/09 06:16:24 DEBUG : dir: reading active writers 2022/01/09 06:16:24 DEBUG : file1: reading active writers 2022/01/09 06:16:24 DEBUG : file2: reading active writers 2022/01/09 06:16:24 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:25 DEBUG : dir: Looking for writers 2022/01/09 06:16:25 DEBUG : : Looking for writers 2022/01/09 06:16:25 DEBUG : file1: reading active writers 2022/01/09 06:16:25 DEBUG : file2: reading active writers 2022/01/09 06:16:25 DEBUG : dir: reading active writers 2022/01/09 06:16:25 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:26 DEBUG : dir: Looking for writers 2022/01/09 06:16:26 DEBUG : : Looking for writers 2022/01/09 06:16:26 DEBUG : dir: reading active writers 2022/01/09 06:16:26 DEBUG : file1: reading active writers 2022/01/09 06:16:26 DEBUG : file2: reading active writers 2022/01/09 06:16:26 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:27 DEBUG : dir: Looking for writers 2022/01/09 06:16:27 DEBUG : : Looking for writers 2022/01/09 06:16:27 DEBUG : dir: reading active writers 2022/01/09 06:16:27 DEBUG : file1: reading active writers 2022/01/09 06:16:27 DEBUG : file2: reading active writers 2022/01/09 06:16:27 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:28 DEBUG : dir: Looking for writers 2022/01/09 06:16:28 DEBUG : : Looking for writers 2022/01/09 06:16:28 DEBUG : dir: reading active writers 2022/01/09 06:16:28 DEBUG : file1: reading active writers 2022/01/09 06:16:28 DEBUG : file2: reading active writers 2022/01/09 06:16:28 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:29 ERROR : Exiting even though 0 writers active and 2 cache items in use after 30s Cache{ "file1": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc0002f4340 name:file1 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228378434973699 ext:149552796608 loc:0x2a04b60} ATime:{wall:13866228378435398655 ext:149553221524 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, "file2": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc000742100 name:file2 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228378436189464 ext:149554012334 loc:0x2a04b60} ATime:{wall:13866228378436595545 ext:149554418414 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 beingReset:false}, } 2022/01/09 06:16:29 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleWriteNoWrite (67.90s) === RUN TestRWFileHandleSizeTruncateExisting run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:16:29 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestRWFileHandleSizeTruncateExisting (0.42s) === RUN TestRWFileHandleSizeCreateExisting run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:16:29 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestRWFileHandleSizeCreateExisting (0.19s) === RUN TestRWFileModTimeWithOpenWriters run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:16:30 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:16:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:16:30 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:16:30 DEBUG : file1: newRWFileHandle: 2022/01/09 06:16:30 DEBUG : file1(0xc000151b40): openPending: 2022/01/09 06:16:30 DEBUG : file1: vfs cache: truncate to size=0 2022/01/09 06:16:30 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:16:30 DEBUG : file1(0xc000151b40): >openPending: err= 2022/01/09 06:16:30 DEBUG : file1: vfs cache: cancelling writeback (uploading false) 0xc0002761c0 item 1 2022/01/09 06:16:30 DEBUG : file1: >newRWFileHandle: err= 2022/01/09 06:16:30 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:16:30 DEBUG : file1: >Open: fd=file1 (rw), err= 2022/01/09 06:16:30 DEBUG : file1: >OpenFile: fd=file1 (rw), err= run.go:287: Failed to put "time_test" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:16:30 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:16:30 DEBUG : dir: Looking for writers 2022/01/09 06:16:30 DEBUG : : Looking for writers 2022/01/09 06:16:30 DEBUG : file1: reading active writers 2022/01/09 06:16:30 DEBUG : file1: active writers 1 2022/01/09 06:16:30 DEBUG : file2: reading active writers 2022/01/09 06:16:30 DEBUG : dir: reading active writers 2022/01/09 06:16:30 DEBUG : Still 1 writers active and 2 cache items in use, waiting 10ms 2022/01/09 06:16:30 DEBUG : dir: Looking for writers 2022/01/09 06:16:30 DEBUG : : Looking for writers 2022/01/09 06:16:30 DEBUG : dir: reading active writers 2022/01/09 06:16:30 DEBUG : file1: reading active writers 2022/01/09 06:16:30 DEBUG : file1: active writers 1 2022/01/09 06:16:30 DEBUG : file2: reading active writers 2022/01/09 06:16:30 DEBUG : Still 1 writers active and 2 cache items in use, waiting 20ms 2022/01/09 06:16:30 DEBUG : dir: Looking for writers 2022/01/09 06:16:30 DEBUG : : Looking for writers 2022/01/09 06:16:30 DEBUG : dir: reading active writers 2022/01/09 06:16:30 DEBUG : file1: reading active writers 2022/01/09 06:16:30 DEBUG : file1: active writers 1 2022/01/09 06:16:30 DEBUG : file2: reading active writers 2022/01/09 06:16:30 DEBUG : Still 1 writers active and 2 cache items in use, waiting 40ms 2022/01/09 06:16:30 DEBUG : dir: Looking for writers 2022/01/09 06:16:30 DEBUG : : Looking for writers 2022/01/09 06:16:30 DEBUG : dir: reading active writers 2022/01/09 06:16:30 DEBUG : file1: reading active writers 2022/01/09 06:16:30 DEBUG : file1: active writers 1 2022/01/09 06:16:30 DEBUG : file2: reading active writers 2022/01/09 06:16:30 DEBUG : Still 1 writers active and 2 cache items in use, waiting 80ms 2022/01/09 06:16:30 DEBUG : dir: Looking for writers 2022/01/09 06:16:30 DEBUG : : Looking for writers 2022/01/09 06:16:30 DEBUG : file2: reading active writers 2022/01/09 06:16:30 DEBUG : dir: reading active writers 2022/01/09 06:16:30 DEBUG : file1: reading active writers 2022/01/09 06:16:30 DEBUG : file1: active writers 1 2022/01/09 06:16:30 DEBUG : Still 1 writers active and 2 cache items in use, waiting 160ms 2022/01/09 06:16:30 DEBUG : dir: Looking for writers 2022/01/09 06:16:30 DEBUG : : Looking for writers 2022/01/09 06:16:30 DEBUG : dir: reading active writers 2022/01/09 06:16:30 DEBUG : file1: reading active writers 2022/01/09 06:16:30 DEBUG : file1: active writers 1 2022/01/09 06:16:30 DEBUG : file2: reading active writers 2022/01/09 06:16:30 DEBUG : Still 1 writers active and 2 cache items in use, waiting 320ms 2022/01/09 06:16:31 DEBUG : dir: Looking for writers 2022/01/09 06:16:31 DEBUG : : Looking for writers 2022/01/09 06:16:31 DEBUG : dir: reading active writers 2022/01/09 06:16:31 DEBUG : file1: reading active writers 2022/01/09 06:16:31 DEBUG : file1: active writers 1 2022/01/09 06:16:31 DEBUG : file2: reading active writers 2022/01/09 06:16:31 DEBUG : Still 1 writers active and 2 cache items in use, waiting 640ms 2022/01/09 06:16:31 DEBUG : dir: Looking for writers 2022/01/09 06:16:31 DEBUG : : Looking for writers 2022/01/09 06:16:31 DEBUG : dir: reading active writers 2022/01/09 06:16:31 DEBUG : file1: reading active writers 2022/01/09 06:16:31 DEBUG : file1: active writers 1 2022/01/09 06:16:31 DEBUG : file2: reading active writers 2022/01/09 06:16:31 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:32 DEBUG : dir: Looking for writers 2022/01/09 06:16:32 DEBUG : : Looking for writers 2022/01/09 06:16:32 DEBUG : dir: reading active writers 2022/01/09 06:16:32 DEBUG : file1: reading active writers 2022/01/09 06:16:32 DEBUG : file1: active writers 1 2022/01/09 06:16:32 DEBUG : file2: reading active writers 2022/01/09 06:16:32 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:33 DEBUG : dir: Looking for writers 2022/01/09 06:16:33 DEBUG : : Looking for writers 2022/01/09 06:16:33 DEBUG : dir: reading active writers 2022/01/09 06:16:33 DEBUG : file1: reading active writers 2022/01/09 06:16:33 DEBUG : file1: active writers 1 2022/01/09 06:16:33 DEBUG : file2: reading active writers 2022/01/09 06:16:33 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:34 DEBUG : dir: Looking for writers 2022/01/09 06:16:34 DEBUG : : Looking for writers 2022/01/09 06:16:34 DEBUG : dir: reading active writers 2022/01/09 06:16:34 DEBUG : file1: reading active writers 2022/01/09 06:16:34 DEBUG : file1: active writers 1 2022/01/09 06:16:34 DEBUG : file2: reading active writers 2022/01/09 06:16:34 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:35 DEBUG : dir: Looking for writers 2022/01/09 06:16:35 DEBUG : : Looking for writers 2022/01/09 06:16:35 DEBUG : dir: reading active writers 2022/01/09 06:16:35 DEBUG : file1: reading active writers 2022/01/09 06:16:35 DEBUG : file1: active writers 1 2022/01/09 06:16:35 DEBUG : file2: reading active writers 2022/01/09 06:16:35 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:36 DEBUG : dir: Looking for writers 2022/01/09 06:16:36 DEBUG : : Looking for writers 2022/01/09 06:16:36 DEBUG : dir: reading active writers 2022/01/09 06:16:36 DEBUG : file1: reading active writers 2022/01/09 06:16:36 DEBUG : file1: active writers 1 2022/01/09 06:16:36 DEBUG : file2: reading active writers 2022/01/09 06:16:36 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:37 DEBUG : dir: Looking for writers 2022/01/09 06:16:37 DEBUG : : Looking for writers 2022/01/09 06:16:37 DEBUG : file1: reading active writers 2022/01/09 06:16:37 DEBUG : file1: active writers 1 2022/01/09 06:16:37 DEBUG : file2: reading active writers 2022/01/09 06:16:37 DEBUG : dir: reading active writers 2022/01/09 06:16:37 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:38 DEBUG : dir: Looking for writers 2022/01/09 06:16:38 DEBUG : : Looking for writers 2022/01/09 06:16:38 DEBUG : file2: reading active writers 2022/01/09 06:16:38 DEBUG : dir: reading active writers 2022/01/09 06:16:38 DEBUG : file1: reading active writers 2022/01/09 06:16:38 DEBUG : file1: active writers 1 2022/01/09 06:16:38 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:39 DEBUG : dir: Looking for writers 2022/01/09 06:16:39 DEBUG : : Looking for writers 2022/01/09 06:16:39 DEBUG : dir: reading active writers 2022/01/09 06:16:39 DEBUG : file1: reading active writers 2022/01/09 06:16:39 DEBUG : file1: active writers 1 2022/01/09 06:16:39 DEBUG : file2: reading active writers 2022/01/09 06:16:39 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:40 DEBUG : dir: Looking for writers 2022/01/09 06:16:40 DEBUG : : Looking for writers 2022/01/09 06:16:40 DEBUG : dir: reading active writers 2022/01/09 06:16:40 DEBUG : file1: reading active writers 2022/01/09 06:16:40 DEBUG : file1: active writers 1 2022/01/09 06:16:40 DEBUG : file2: reading active writers 2022/01/09 06:16:40 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:41 DEBUG : dir: Looking for writers 2022/01/09 06:16:41 DEBUG : : Looking for writers 2022/01/09 06:16:41 DEBUG : dir: reading active writers 2022/01/09 06:16:41 DEBUG : file1: reading active writers 2022/01/09 06:16:41 DEBUG : file1: active writers 1 2022/01/09 06:16:41 DEBUG : file2: reading active writers 2022/01/09 06:16:41 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:42 DEBUG : dir: Looking for writers 2022/01/09 06:16:42 DEBUG : : Looking for writers 2022/01/09 06:16:42 DEBUG : file2: reading active writers 2022/01/09 06:16:42 DEBUG : dir: reading active writers 2022/01/09 06:16:42 DEBUG : file1: reading active writers 2022/01/09 06:16:42 DEBUG : file1: active writers 1 2022/01/09 06:16:42 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:43 DEBUG : dir: Looking for writers 2022/01/09 06:16:43 DEBUG : : Looking for writers 2022/01/09 06:16:43 DEBUG : file2: reading active writers 2022/01/09 06:16:43 DEBUG : dir: reading active writers 2022/01/09 06:16:43 DEBUG : file1: reading active writers 2022/01/09 06:16:43 DEBUG : file1: active writers 1 2022/01/09 06:16:43 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:44 DEBUG : dir: Looking for writers 2022/01/09 06:16:44 DEBUG : : Looking for writers 2022/01/09 06:16:44 DEBUG : file2: reading active writers 2022/01/09 06:16:44 DEBUG : dir: reading active writers 2022/01/09 06:16:44 DEBUG : file1: reading active writers 2022/01/09 06:16:44 DEBUG : file1: active writers 1 2022/01/09 06:16:44 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:45 DEBUG : dir: Looking for writers 2022/01/09 06:16:45 DEBUG : : Looking for writers 2022/01/09 06:16:45 DEBUG : dir: reading active writers 2022/01/09 06:16:45 DEBUG : file1: reading active writers 2022/01/09 06:16:45 DEBUG : file1: active writers 1 2022/01/09 06:16:45 DEBUG : file2: reading active writers 2022/01/09 06:16:45 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:46 DEBUG : dir: Looking for writers 2022/01/09 06:16:46 DEBUG : : Looking for writers 2022/01/09 06:16:46 DEBUG : dir: reading active writers 2022/01/09 06:16:46 DEBUG : file1: reading active writers 2022/01/09 06:16:46 DEBUG : file1: active writers 1 2022/01/09 06:16:46 DEBUG : file2: reading active writers 2022/01/09 06:16:46 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:47 DEBUG : dir: Looking for writers 2022/01/09 06:16:47 DEBUG : : Looking for writers 2022/01/09 06:16:47 DEBUG : dir: reading active writers 2022/01/09 06:16:47 DEBUG : file1: reading active writers 2022/01/09 06:16:47 DEBUG : file1: active writers 1 2022/01/09 06:16:47 DEBUG : file2: reading active writers 2022/01/09 06:16:47 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:48 DEBUG : dir: Looking for writers 2022/01/09 06:16:48 DEBUG : : Looking for writers 2022/01/09 06:16:48 DEBUG : dir: reading active writers 2022/01/09 06:16:48 DEBUG : file1: reading active writers 2022/01/09 06:16:48 DEBUG : file1: active writers 1 2022/01/09 06:16:48 DEBUG : file2: reading active writers 2022/01/09 06:16:48 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:49 DEBUG : dir: Looking for writers 2022/01/09 06:16:49 DEBUG : : Looking for writers 2022/01/09 06:16:49 DEBUG : dir: reading active writers 2022/01/09 06:16:49 DEBUG : file1: reading active writers 2022/01/09 06:16:49 DEBUG : file1: active writers 1 2022/01/09 06:16:49 DEBUG : file2: reading active writers 2022/01/09 06:16:49 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:50 DEBUG : dir: Looking for writers 2022/01/09 06:16:50 DEBUG : : Looking for writers 2022/01/09 06:16:50 DEBUG : dir: reading active writers 2022/01/09 06:16:50 DEBUG : file1: reading active writers 2022/01/09 06:16:50 DEBUG : file1: active writers 1 2022/01/09 06:16:50 DEBUG : file2: reading active writers 2022/01/09 06:16:50 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:51 DEBUG : dir: Looking for writers 2022/01/09 06:16:51 DEBUG : : Looking for writers 2022/01/09 06:16:51 DEBUG : dir: reading active writers 2022/01/09 06:16:51 DEBUG : file1: reading active writers 2022/01/09 06:16:51 DEBUG : file1: active writers 1 2022/01/09 06:16:51 DEBUG : file2: reading active writers 2022/01/09 06:16:51 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:52 DEBUG : dir: Looking for writers 2022/01/09 06:16:52 DEBUG : : Looking for writers 2022/01/09 06:16:52 DEBUG : dir: reading active writers 2022/01/09 06:16:52 DEBUG : file1: reading active writers 2022/01/09 06:16:52 DEBUG : file1: active writers 1 2022/01/09 06:16:52 DEBUG : file2: reading active writers 2022/01/09 06:16:52 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:53 DEBUG : dir: Looking for writers 2022/01/09 06:16:53 DEBUG : : Looking for writers 2022/01/09 06:16:53 DEBUG : dir: reading active writers 2022/01/09 06:16:53 DEBUG : file1: reading active writers 2022/01/09 06:16:53 DEBUG : file1: active writers 1 2022/01/09 06:16:53 DEBUG : file2: reading active writers 2022/01/09 06:16:53 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:54 DEBUG : dir: Looking for writers 2022/01/09 06:16:54 DEBUG : : Looking for writers 2022/01/09 06:16:54 DEBUG : dir: reading active writers 2022/01/09 06:16:54 DEBUG : file1: reading active writers 2022/01/09 06:16:54 DEBUG : file1: active writers 1 2022/01/09 06:16:54 DEBUG : file2: reading active writers 2022/01/09 06:16:54 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:55 DEBUG : dir: Looking for writers 2022/01/09 06:16:55 DEBUG : : Looking for writers 2022/01/09 06:16:55 DEBUG : dir: reading active writers 2022/01/09 06:16:55 DEBUG : file1: reading active writers 2022/01/09 06:16:55 DEBUG : file1: active writers 1 2022/01/09 06:16:55 DEBUG : file2: reading active writers 2022/01/09 06:16:55 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:56 DEBUG : dir: Looking for writers 2022/01/09 06:16:56 DEBUG : : Looking for writers 2022/01/09 06:16:56 DEBUG : dir: reading active writers 2022/01/09 06:16:56 DEBUG : file1: reading active writers 2022/01/09 06:16:56 DEBUG : file1: active writers 1 2022/01/09 06:16:56 DEBUG : file2: reading active writers 2022/01/09 06:16:56 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:57 DEBUG : dir: Looking for writers 2022/01/09 06:16:57 DEBUG : : Looking for writers 2022/01/09 06:16:57 DEBUG : dir: reading active writers 2022/01/09 06:16:57 DEBUG : file1: reading active writers 2022/01/09 06:16:57 DEBUG : file1: active writers 1 2022/01/09 06:16:57 DEBUG : file2: reading active writers 2022/01/09 06:16:57 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:58 DEBUG : dir: Looking for writers 2022/01/09 06:16:58 DEBUG : : Looking for writers 2022/01/09 06:16:58 DEBUG : dir: reading active writers 2022/01/09 06:16:58 DEBUG : file1: reading active writers 2022/01/09 06:16:58 DEBUG : file1: active writers 1 2022/01/09 06:16:58 DEBUG : file2: reading active writers 2022/01/09 06:16:58 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:16:59 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2022/01/09 06:16:59 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file2 not removed, freed 0 bytes 2022/01/09 06:16:59 INFO : vfs cache: cleaned: objects 2 (was 2) in use 2, to upload 1, uploading 0, total size 0 (was 0) 2022/01/09 06:16:59 DEBUG : dir: Looking for writers 2022/01/09 06:16:59 DEBUG : : Looking for writers 2022/01/09 06:16:59 DEBUG : dir: reading active writers 2022/01/09 06:16:59 DEBUG : file1: reading active writers 2022/01/09 06:16:59 DEBUG : file1: active writers 1 2022/01/09 06:16:59 DEBUG : file2: reading active writers 2022/01/09 06:16:59 DEBUG : Still 1 writers active and 2 cache items in use, waiting 1s 2022/01/09 06:17:00 ERROR : Exiting even though 1 writers active and 2 cache items in use after 30s Cache{ "file2": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc000742100 name:file2 opens:0 downloaders: o: fd: modified:false info:{ModTime:{wall:13866228378436189464 ext:149554012334 loc:0x2a04b60} ATime:{wall:13866228378436595545 ext:149554418414 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 beingReset:false}, "file1": &{c:0xc000441800 mu:{state:0 sema:0} cond:0xc0002f4340 name:file1 opens:1 downloaders: o: fd:0xc00055c4e0 modified:true info:{ModTime:{wall:13866228452032734804 ext:218062371818 loc:0x2a04b60} ATime:{wall:13866228452032734804 ext:218062371818 loc:0x2a04b60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 beingReset:false}, } 2022/01/09 06:17:00 DEBUG : >WaitForWriters: --- FAIL: TestRWFileModTimeWithOpenWriters (30.91s) === RUN TestCaseSensitivity run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" run.go:287: Failed to put "FiLeA" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" --- FAIL: TestCaseSensitivity (0.34s) === 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-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:17:01 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': 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 2022/01/09 06:17:01 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': 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 2022/01/09 06:17:01 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:17:01 DEBUG : : Looking for writers 2022/01/09 06:17:01 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-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:17:01 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:17:01 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:17:01 DEBUG : : Looking for writers 2022/01/09 06:17:01 DEBUG : >WaitForWriters: --- FAIL: TestVFSStat (0.32s) === RUN TestVFSStatParent run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:17:02 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:17:02 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:17:02 DEBUG : : Looking for writers 2022/01/09 06:17:02 DEBUG : >WaitForWriters: --- FAIL: TestVFSStatParent (0.32s) === RUN TestVFSOpenFile run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:17:02 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "file1" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:17:02 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:17:02 DEBUG : : Looking for writers 2022/01/09 06:17:02 DEBUG : >WaitForWriters: --- FAIL: TestVFSOpenFile (0.31s) === RUN TestVFSRename run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:17:02 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache run.go:287: Failed to put "dir/file2" to "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'": upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:17:03 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:17:03 DEBUG : : Looking for writers 2022/01/09 06:17:03 DEBUG : >WaitForWriters: --- FAIL: TestVFSRename (1.05s) === RUN TestWriteFileHandleMethods run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:17:03 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:17:03 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:17:03 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:17:03 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:17:03 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:17:03 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:17:03 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:17:03 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2022/01/09 06:17:03 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2022/01/09 06:17:03 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2022/01/09 06:17:03 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': File to upload is small (5 bytes), uploading instead of streaming 2022/01/09 06:17:03 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:17:03 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 Payment Required) returned body: "" write_test.go:84: Error Trace: write_test.go:84 Error: Received unexpected error: upload error: HTTP error 402 (402 Payment Required) 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 2022/01/09 06:17:05 DEBUG : file2: vfs cache: starting upload 2022/01/09 06:17:05 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-tikuguh2xarudij8kunigaf9/file2: no such file or directory 2022/01/09 06:17:05 INFO : file2: vfs cache: upload succeeded try #10 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 2022/01/09 06:17:11 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:17:11 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:17:11 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:17:11 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:17:11 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:17:11 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:17:11 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': File to upload is small (0 bytes), uploading instead of streaming 2022/01/09 06:17:11 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:17:11 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 Payment Required) returned body: "" write_test.go:103: Error Trace: write_test.go:103 Error: Received unexpected error: upload error: HTTP error 402 (402 Payment Required) 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 2022/01/09 06:17:11 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:17:11 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:17:11 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:17:11 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:17:11 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:17:11 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 2022/01/09 06:17:11 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:17:11 DEBUG : : Looking for writers 2022/01/09 06:17:11 DEBUG : file1: reading active writers 2022/01/09 06:17:11 DEBUG : file1: active writers 1 2022/01/09 06:17:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/01/09 06:17:11 DEBUG : : Looking for writers 2022/01/09 06:17:11 DEBUG : file1: reading active writers 2022/01/09 06:17:11 DEBUG : file1: active writers 1 2022/01/09 06:17:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/01/09 06:17:11 DEBUG : : Looking for writers 2022/01/09 06:17:11 DEBUG : file1: reading active writers 2022/01/09 06:17:11 DEBUG : file1: active writers 1 2022/01/09 06:17:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/01/09 06:17:11 DEBUG : : Looking for writers 2022/01/09 06:17:11 DEBUG : file1: reading active writers 2022/01/09 06:17:11 DEBUG : file1: active writers 1 2022/01/09 06:17:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/01/09 06:17:12 DEBUG : : Looking for writers 2022/01/09 06:17:12 DEBUG : file1: reading active writers 2022/01/09 06:17:12 DEBUG : file1: active writers 1 2022/01/09 06:17:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/01/09 06:17:12 DEBUG : : Looking for writers 2022/01/09 06:17:12 DEBUG : file1: reading active writers 2022/01/09 06:17:12 DEBUG : file1: active writers 1 2022/01/09 06:17:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/01/09 06:17:12 DEBUG : : Looking for writers 2022/01/09 06:17:12 DEBUG : file1: reading active writers 2022/01/09 06:17:12 DEBUG : file1: active writers 1 2022/01/09 06:17:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/01/09 06:17:13 DEBUG : : Looking for writers 2022/01/09 06:17:13 DEBUG : file1: reading active writers 2022/01/09 06:17:13 DEBUG : file1: active writers 1 2022/01/09 06:17:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:14 DEBUG : : Looking for writers 2022/01/09 06:17:14 DEBUG : file1: reading active writers 2022/01/09 06:17:14 DEBUG : file1: active writers 1 2022/01/09 06:17:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:15 DEBUG : : Looking for writers 2022/01/09 06:17:15 DEBUG : file1: reading active writers 2022/01/09 06:17:15 DEBUG : file1: active writers 1 2022/01/09 06:17:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:16 DEBUG : : Looking for writers 2022/01/09 06:17:16 DEBUG : file1: reading active writers 2022/01/09 06:17:16 DEBUG : file1: active writers 1 2022/01/09 06:17:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:17 DEBUG : : Looking for writers 2022/01/09 06:17:17 DEBUG : file1: reading active writers 2022/01/09 06:17:17 DEBUG : file1: active writers 1 2022/01/09 06:17:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:18 DEBUG : : Looking for writers 2022/01/09 06:17:18 DEBUG : file1: reading active writers 2022/01/09 06:17:18 DEBUG : file1: active writers 1 2022/01/09 06:17:18 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:19 DEBUG : : Looking for writers 2022/01/09 06:17:19 DEBUG : file1: reading active writers 2022/01/09 06:17:19 DEBUG : file1: active writers 1 2022/01/09 06:17:19 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:20 DEBUG : : Looking for writers 2022/01/09 06:17:20 DEBUG : file1: reading active writers 2022/01/09 06:17:20 DEBUG : file1: active writers 1 2022/01/09 06:17:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:21 DEBUG : : Looking for writers 2022/01/09 06:17:21 DEBUG : file1: reading active writers 2022/01/09 06:17:21 DEBUG : file1: active writers 1 2022/01/09 06:17:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:22 DEBUG : : Looking for writers 2022/01/09 06:17:22 DEBUG : file1: reading active writers 2022/01/09 06:17:22 DEBUG : file1: active writers 1 2022/01/09 06:17:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:23 DEBUG : : Looking for writers 2022/01/09 06:17:23 DEBUG : file1: reading active writers 2022/01/09 06:17:23 DEBUG : file1: active writers 1 2022/01/09 06:17:23 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:24 DEBUG : : Looking for writers 2022/01/09 06:17:24 DEBUG : file1: reading active writers 2022/01/09 06:17:24 DEBUG : file1: active writers 1 2022/01/09 06:17:24 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:25 DEBUG : : Looking for writers 2022/01/09 06:17:25 DEBUG : file1: reading active writers 2022/01/09 06:17:25 DEBUG : file1: active writers 1 2022/01/09 06:17:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:26 DEBUG : : Looking for writers 2022/01/09 06:17:26 DEBUG : file1: reading active writers 2022/01/09 06:17:26 DEBUG : file1: active writers 1 2022/01/09 06:17:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:27 DEBUG : : Looking for writers 2022/01/09 06:17:27 DEBUG : file1: reading active writers 2022/01/09 06:17:27 DEBUG : file1: active writers 1 2022/01/09 06:17:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:28 DEBUG : : Looking for writers 2022/01/09 06:17:28 DEBUG : file1: reading active writers 2022/01/09 06:17:28 DEBUG : file1: active writers 1 2022/01/09 06:17:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:29 DEBUG : : Looking for writers 2022/01/09 06:17:29 DEBUG : file1: reading active writers 2022/01/09 06:17:29 DEBUG : file1: active writers 1 2022/01/09 06:17:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:30 DEBUG : : Looking for writers 2022/01/09 06:17:30 DEBUG : file1: reading active writers 2022/01/09 06:17:30 DEBUG : file1: active writers 1 2022/01/09 06:17:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:31 DEBUG : : Looking for writers 2022/01/09 06:17:31 DEBUG : file1: reading active writers 2022/01/09 06:17:31 DEBUG : file1: active writers 1 2022/01/09 06:17:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:32 DEBUG : : Looking for writers 2022/01/09 06:17:32 DEBUG : file1: reading active writers 2022/01/09 06:17:32 DEBUG : file1: active writers 1 2022/01/09 06:17:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:33 DEBUG : : Looking for writers 2022/01/09 06:17:33 DEBUG : file1: reading active writers 2022/01/09 06:17:33 DEBUG : file1: active writers 1 2022/01/09 06:17:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:34 DEBUG : : Looking for writers 2022/01/09 06:17:34 DEBUG : file1: reading active writers 2022/01/09 06:17:34 DEBUG : file1: active writers 1 2022/01/09 06:17:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:35 DEBUG : : Looking for writers 2022/01/09 06:17:35 DEBUG : file1: reading active writers 2022/01/09 06:17:35 DEBUG : file1: active writers 1 2022/01/09 06:17:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:36 DEBUG : : Looking for writers 2022/01/09 06:17:36 DEBUG : file1: reading active writers 2022/01/09 06:17:36 DEBUG : file1: active writers 1 2022/01/09 06:17:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:37 DEBUG : : Looking for writers 2022/01/09 06:17:37 DEBUG : file1: reading active writers 2022/01/09 06:17:37 DEBUG : file1: active writers 1 2022/01/09 06:17:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:38 DEBUG : : Looking for writers 2022/01/09 06:17:38 DEBUG : file1: reading active writers 2022/01/09 06:17:38 DEBUG : file1: active writers 1 2022/01/09 06:17:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:39 DEBUG : : Looking for writers 2022/01/09 06:17:39 DEBUG : file1: reading active writers 2022/01/09 06:17:39 DEBUG : file1: active writers 1 2022/01/09 06:17:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:40 DEBUG : : Looking for writers 2022/01/09 06:17:40 DEBUG : file1: reading active writers 2022/01/09 06:17:40 DEBUG : file1: active writers 1 2022/01/09 06:17:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:41 DEBUG : : Looking for writers 2022/01/09 06:17:41 DEBUG : file1: reading active writers 2022/01/09 06:17:41 DEBUG : file1: active writers 1 2022/01/09 06:17:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:41 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2022/01/09 06:17:41 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleMethods (38.38s) === RUN TestWriteFileHandleWriteAt run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:17:42 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:17:42 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:17:42 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:17:42 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:17:42 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:17:42 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:17:42 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:17:42 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2022/01/09 06:17:43 DEBUG : file1: aborting in-sequence write wait, off=100 2022/01/09 06:17:43 DEBUG : file1: failed to wait for in-sequence write to 100 2022/01/09 06:17:43 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2022/01/09 06:17:43 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': File to upload is small (11 bytes), uploading instead of streaming 2022/01/09 06:17:43 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:17:43 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 Payment Required) returned body: "" write_test.go:162: Error Trace: write_test.go:162 Error: Received unexpected error: upload error: HTTP error 402 (402 Payment Required) returned body: "" Test: TestWriteFileHandleWriteAt 2022/01/09 06:17:43 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 2022/01/09 06:17:50 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:17:50 DEBUG : : Looking for writers 2022/01/09 06:17:50 DEBUG : file1: reading active writers 2022/01/09 06:17:50 DEBUG : file1: active writers 1 2022/01/09 06:17:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/01/09 06:17:50 DEBUG : : Looking for writers 2022/01/09 06:17:50 DEBUG : file1: reading active writers 2022/01/09 06:17:50 DEBUG : file1: active writers 1 2022/01/09 06:17:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/01/09 06:17:50 DEBUG : : Looking for writers 2022/01/09 06:17:50 DEBUG : file1: reading active writers 2022/01/09 06:17:50 DEBUG : file1: active writers 1 2022/01/09 06:17:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/01/09 06:17:50 DEBUG : : Looking for writers 2022/01/09 06:17:50 DEBUG : file1: reading active writers 2022/01/09 06:17:50 DEBUG : file1: active writers 1 2022/01/09 06:17:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/01/09 06:17:50 DEBUG : : Looking for writers 2022/01/09 06:17:50 DEBUG : file1: reading active writers 2022/01/09 06:17:50 DEBUG : file1: active writers 1 2022/01/09 06:17:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/01/09 06:17:51 DEBUG : : Looking for writers 2022/01/09 06:17:51 DEBUG : file1: reading active writers 2022/01/09 06:17:51 DEBUG : file1: active writers 1 2022/01/09 06:17:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/01/09 06:17:51 DEBUG : : Looking for writers 2022/01/09 06:17:51 DEBUG : file1: reading active writers 2022/01/09 06:17:51 DEBUG : file1: active writers 1 2022/01/09 06:17:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/01/09 06:17:52 DEBUG : : Looking for writers 2022/01/09 06:17:52 DEBUG : file1: reading active writers 2022/01/09 06:17:52 DEBUG : file1: active writers 1 2022/01/09 06:17:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:53 DEBUG : : Looking for writers 2022/01/09 06:17:53 DEBUG : file1: reading active writers 2022/01/09 06:17:53 DEBUG : file1: active writers 1 2022/01/09 06:17:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:54 DEBUG : : Looking for writers 2022/01/09 06:17:54 DEBUG : file1: reading active writers 2022/01/09 06:17:54 DEBUG : file1: active writers 1 2022/01/09 06:17:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:55 DEBUG : : Looking for writers 2022/01/09 06:17:55 DEBUG : file1: reading active writers 2022/01/09 06:17:55 DEBUG : file1: active writers 1 2022/01/09 06:17:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:56 DEBUG : : Looking for writers 2022/01/09 06:17:56 DEBUG : file1: reading active writers 2022/01/09 06:17:56 DEBUG : file1: active writers 1 2022/01/09 06:17:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:57 DEBUG : : Looking for writers 2022/01/09 06:17:57 DEBUG : file1: reading active writers 2022/01/09 06:17:57 DEBUG : file1: active writers 1 2022/01/09 06:17:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:58 DEBUG : : Looking for writers 2022/01/09 06:17:58 DEBUG : file1: reading active writers 2022/01/09 06:17:58 DEBUG : file1: active writers 1 2022/01/09 06:17:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:17:59 DEBUG : : Looking for writers 2022/01/09 06:17:59 DEBUG : file1: reading active writers 2022/01/09 06:17:59 DEBUG : file1: active writers 1 2022/01/09 06:17:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:00 DEBUG : : Looking for writers 2022/01/09 06:18:00 DEBUG : file1: reading active writers 2022/01/09 06:18:00 DEBUG : file1: active writers 1 2022/01/09 06:18:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:01 DEBUG : : Looking for writers 2022/01/09 06:18:01 DEBUG : file1: reading active writers 2022/01/09 06:18:01 DEBUG : file1: active writers 1 2022/01/09 06:18:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:02 DEBUG : : Looking for writers 2022/01/09 06:18:02 DEBUG : file1: reading active writers 2022/01/09 06:18:02 DEBUG : file1: active writers 1 2022/01/09 06:18:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:03 DEBUG : : Looking for writers 2022/01/09 06:18:03 DEBUG : file1: reading active writers 2022/01/09 06:18:03 DEBUG : file1: active writers 1 2022/01/09 06:18:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:04 DEBUG : : Looking for writers 2022/01/09 06:18:04 DEBUG : file1: reading active writers 2022/01/09 06:18:04 DEBUG : file1: active writers 1 2022/01/09 06:18:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:05 DEBUG : : Looking for writers 2022/01/09 06:18:05 DEBUG : file1: reading active writers 2022/01/09 06:18:05 DEBUG : file1: active writers 1 2022/01/09 06:18:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:06 DEBUG : : Looking for writers 2022/01/09 06:18:06 DEBUG : file1: reading active writers 2022/01/09 06:18:06 DEBUG : file1: active writers 1 2022/01/09 06:18:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:07 DEBUG : : Looking for writers 2022/01/09 06:18:07 DEBUG : file1: reading active writers 2022/01/09 06:18:07 DEBUG : file1: active writers 1 2022/01/09 06:18:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:08 DEBUG : : Looking for writers 2022/01/09 06:18:08 DEBUG : file1: reading active writers 2022/01/09 06:18:08 DEBUG : file1: active writers 1 2022/01/09 06:18:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:09 DEBUG : : Looking for writers 2022/01/09 06:18:09 DEBUG : file1: reading active writers 2022/01/09 06:18:09 DEBUG : file1: active writers 1 2022/01/09 06:18:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:10 DEBUG : : Looking for writers 2022/01/09 06:18:10 DEBUG : file1: reading active writers 2022/01/09 06:18:10 DEBUG : file1: active writers 1 2022/01/09 06:18:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:11 DEBUG : : Looking for writers 2022/01/09 06:18:11 DEBUG : file1: reading active writers 2022/01/09 06:18:11 DEBUG : file1: active writers 1 2022/01/09 06:18:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:12 DEBUG : : Looking for writers 2022/01/09 06:18:12 DEBUG : file1: reading active writers 2022/01/09 06:18:12 DEBUG : file1: active writers 1 2022/01/09 06:18:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:13 DEBUG : : Looking for writers 2022/01/09 06:18:13 DEBUG : file1: reading active writers 2022/01/09 06:18:13 DEBUG : file1: active writers 1 2022/01/09 06:18:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:14 DEBUG : : Looking for writers 2022/01/09 06:18:14 DEBUG : file1: reading active writers 2022/01/09 06:18:14 DEBUG : file1: active writers 1 2022/01/09 06:18:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:15 DEBUG : : Looking for writers 2022/01/09 06:18:15 DEBUG : file1: reading active writers 2022/01/09 06:18:15 DEBUG : file1: active writers 1 2022/01/09 06:18:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:16 DEBUG : : Looking for writers 2022/01/09 06:18:16 DEBUG : file1: reading active writers 2022/01/09 06:18:16 DEBUG : file1: active writers 1 2022/01/09 06:18:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:17 DEBUG : : Looking for writers 2022/01/09 06:18:17 DEBUG : file1: reading active writers 2022/01/09 06:18:17 DEBUG : file1: active writers 1 2022/01/09 06:18:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:18 DEBUG : : Looking for writers 2022/01/09 06:18:18 DEBUG : file1: reading active writers 2022/01/09 06:18:18 DEBUG : file1: active writers 1 2022/01/09 06:18:18 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:19 DEBUG : : Looking for writers 2022/01/09 06:18:19 DEBUG : file1: reading active writers 2022/01/09 06:18:19 DEBUG : file1: active writers 1 2022/01/09 06:18:19 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:20 DEBUG : : Looking for writers 2022/01/09 06:18:20 DEBUG : file1: reading active writers 2022/01/09 06:18:20 DEBUG : file1: active writers 1 2022/01/09 06:18:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:20 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2022/01/09 06:18:20 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleWriteAt (39.10s) === RUN TestWriteFileHandleFlush run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:18:21 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:18:21 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:18:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:18:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:18:21 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:18:21 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:18:21 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2022/01/09 06:18:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:18:21 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': File to upload is small (5 bytes), uploading instead of streaming 2022/01/09 06:18:21 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:18:21 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:18:21 ERROR : file1: WriteFileHandle.Flush error: upload error: HTTP error 402 (402 Payment Required) returned body: "" write_test.go:198: Error Trace: write_test.go:198 Error: Received unexpected error: upload error: HTTP error 402 (402 Payment Required) returned body: "" Test: TestWriteFileHandleFlush 2022/01/09 06:18:21 DEBUG : file1: WriteFileHandle.Flush nothing to do 2022/01/09 06:18:21 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:18:21 DEBUG : : Looking for writers 2022/01/09 06:18:21 DEBUG : file1: reading active writers 2022/01/09 06:18:21 DEBUG : file1: active writers 1 2022/01/09 06:18:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/01/09 06:18:21 DEBUG : : Looking for writers 2022/01/09 06:18:21 DEBUG : file1: reading active writers 2022/01/09 06:18:21 DEBUG : file1: active writers 1 2022/01/09 06:18:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/01/09 06:18:21 DEBUG : : Looking for writers 2022/01/09 06:18:21 DEBUG : file1: reading active writers 2022/01/09 06:18:21 DEBUG : file1: active writers 1 2022/01/09 06:18:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/01/09 06:18:21 DEBUG : : Looking for writers 2022/01/09 06:18:21 DEBUG : file1: reading active writers 2022/01/09 06:18:21 DEBUG : file1: active writers 1 2022/01/09 06:18:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/01/09 06:18:21 DEBUG : : Looking for writers 2022/01/09 06:18:21 DEBUG : file1: reading active writers 2022/01/09 06:18:21 DEBUG : file1: active writers 1 2022/01/09 06:18:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/01/09 06:18:21 DEBUG : : Looking for writers 2022/01/09 06:18:21 DEBUG : file1: reading active writers 2022/01/09 06:18:21 DEBUG : file1: active writers 1 2022/01/09 06:18:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/01/09 06:18:21 DEBUG : : Looking for writers 2022/01/09 06:18:21 DEBUG : file1: reading active writers 2022/01/09 06:18:21 DEBUG : file1: active writers 1 2022/01/09 06:18:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/01/09 06:18:22 DEBUG : : Looking for writers 2022/01/09 06:18:22 DEBUG : file1: reading active writers 2022/01/09 06:18:22 DEBUG : file1: active writers 1 2022/01/09 06:18:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:23 DEBUG : : Looking for writers 2022/01/09 06:18:23 DEBUG : file1: reading active writers 2022/01/09 06:18:23 DEBUG : file1: active writers 1 2022/01/09 06:18:23 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:24 DEBUG : : Looking for writers 2022/01/09 06:18:24 DEBUG : file1: reading active writers 2022/01/09 06:18:24 DEBUG : file1: active writers 1 2022/01/09 06:18:24 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:25 DEBUG : : Looking for writers 2022/01/09 06:18:25 DEBUG : file1: reading active writers 2022/01/09 06:18:25 DEBUG : file1: active writers 1 2022/01/09 06:18:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:26 DEBUG : : Looking for writers 2022/01/09 06:18:26 DEBUG : file1: reading active writers 2022/01/09 06:18:26 DEBUG : file1: active writers 1 2022/01/09 06:18:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:27 DEBUG : : Looking for writers 2022/01/09 06:18:27 DEBUG : file1: reading active writers 2022/01/09 06:18:27 DEBUG : file1: active writers 1 2022/01/09 06:18:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:28 DEBUG : : Looking for writers 2022/01/09 06:18:28 DEBUG : file1: reading active writers 2022/01/09 06:18:28 DEBUG : file1: active writers 1 2022/01/09 06:18:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:29 DEBUG : : Looking for writers 2022/01/09 06:18:29 DEBUG : file1: reading active writers 2022/01/09 06:18:29 DEBUG : file1: active writers 1 2022/01/09 06:18:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:30 DEBUG : : Looking for writers 2022/01/09 06:18:30 DEBUG : file1: reading active writers 2022/01/09 06:18:30 DEBUG : file1: active writers 1 2022/01/09 06:18:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:31 DEBUG : : Looking for writers 2022/01/09 06:18:31 DEBUG : file1: reading active writers 2022/01/09 06:18:31 DEBUG : file1: active writers 1 2022/01/09 06:18:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:32 DEBUG : : Looking for writers 2022/01/09 06:18:32 DEBUG : file1: reading active writers 2022/01/09 06:18:32 DEBUG : file1: active writers 1 2022/01/09 06:18:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:33 DEBUG : : Looking for writers 2022/01/09 06:18:33 DEBUG : file1: reading active writers 2022/01/09 06:18:33 DEBUG : file1: active writers 1 2022/01/09 06:18:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:34 DEBUG : : Looking for writers 2022/01/09 06:18:34 DEBUG : file1: reading active writers 2022/01/09 06:18:34 DEBUG : file1: active writers 1 2022/01/09 06:18:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:35 DEBUG : : Looking for writers 2022/01/09 06:18:35 DEBUG : file1: reading active writers 2022/01/09 06:18:35 DEBUG : file1: active writers 1 2022/01/09 06:18:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:36 DEBUG : : Looking for writers 2022/01/09 06:18:36 DEBUG : file1: reading active writers 2022/01/09 06:18:36 DEBUG : file1: active writers 1 2022/01/09 06:18:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:37 DEBUG : : Looking for writers 2022/01/09 06:18:37 DEBUG : file1: reading active writers 2022/01/09 06:18:37 DEBUG : file1: active writers 1 2022/01/09 06:18:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:38 DEBUG : : Looking for writers 2022/01/09 06:18:38 DEBUG : file1: reading active writers 2022/01/09 06:18:38 DEBUG : file1: active writers 1 2022/01/09 06:18:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:39 DEBUG : : Looking for writers 2022/01/09 06:18:39 DEBUG : file1: reading active writers 2022/01/09 06:18:39 DEBUG : file1: active writers 1 2022/01/09 06:18:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:40 DEBUG : : Looking for writers 2022/01/09 06:18:40 DEBUG : file1: reading active writers 2022/01/09 06:18:40 DEBUG : file1: active writers 1 2022/01/09 06:18:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:41 DEBUG : : Looking for writers 2022/01/09 06:18:41 DEBUG : file1: reading active writers 2022/01/09 06:18:41 DEBUG : file1: active writers 1 2022/01/09 06:18:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:42 DEBUG : : Looking for writers 2022/01/09 06:18:42 DEBUG : file1: reading active writers 2022/01/09 06:18:42 DEBUG : file1: active writers 1 2022/01/09 06:18:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:43 DEBUG : : Looking for writers 2022/01/09 06:18:43 DEBUG : file1: reading active writers 2022/01/09 06:18:43 DEBUG : file1: active writers 1 2022/01/09 06:18:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:44 DEBUG : : Looking for writers 2022/01/09 06:18:44 DEBUG : file1: reading active writers 2022/01/09 06:18:44 DEBUG : file1: active writers 1 2022/01/09 06:18:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:45 DEBUG : : Looking for writers 2022/01/09 06:18:45 DEBUG : file1: reading active writers 2022/01/09 06:18:45 DEBUG : file1: active writers 1 2022/01/09 06:18:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:46 DEBUG : : Looking for writers 2022/01/09 06:18:46 DEBUG : file1: reading active writers 2022/01/09 06:18:46 DEBUG : file1: active writers 1 2022/01/09 06:18:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:47 DEBUG : : Looking for writers 2022/01/09 06:18:47 DEBUG : file1: reading active writers 2022/01/09 06:18:47 DEBUG : file1: active writers 1 2022/01/09 06:18:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:48 DEBUG : : Looking for writers 2022/01/09 06:18:48 DEBUG : file1: reading active writers 2022/01/09 06:18:48 DEBUG : file1: active writers 1 2022/01/09 06:18:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:49 DEBUG : : Looking for writers 2022/01/09 06:18:49 DEBUG : file1: reading active writers 2022/01/09 06:18:49 DEBUG : file1: active writers 1 2022/01/09 06:18:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:50 DEBUG : : Looking for writers 2022/01/09 06:18:50 DEBUG : file1: reading active writers 2022/01/09 06:18:50 DEBUG : file1: active writers 1 2022/01/09 06:18:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:51 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2022/01/09 06:18:51 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleFlush (30.36s) === RUN TestWriteFileHandleRelease run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:18:51 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:18:51 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:18:51 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:18:51 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:18:51 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:18:51 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:18:51 DEBUG : file1: WriteFileHandle.Release closing 2022/01/09 06:18:51 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:18:51 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': File to upload is small (0 bytes), uploading instead of streaming 2022/01/09 06:18:51 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:18:51 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:18:51 ERROR : file1: WriteFileHandle.Release error: upload error: HTTP error 402 (402 Payment Required) returned body: "" write_test.go:222: Error Trace: write_test.go:222 Error: Received unexpected error: upload error: HTTP error 402 (402 Payment Required) returned body: "" Test: TestWriteFileHandleRelease 2022/01/09 06:18:51 DEBUG : file1: WriteFileHandle.Release nothing to do 2022/01/09 06:18:51 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:18:51 DEBUG : : Looking for writers 2022/01/09 06:18:51 DEBUG : file1: reading active writers 2022/01/09 06:18:51 DEBUG : file1: active writers 1 2022/01/09 06:18:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/01/09 06:18:51 DEBUG : : Looking for writers 2022/01/09 06:18:51 DEBUG : file1: reading active writers 2022/01/09 06:18:51 DEBUG : file1: active writers 1 2022/01/09 06:18:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/01/09 06:18:51 DEBUG : : Looking for writers 2022/01/09 06:18:51 DEBUG : file1: reading active writers 2022/01/09 06:18:51 DEBUG : file1: active writers 1 2022/01/09 06:18:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/01/09 06:18:51 DEBUG : : Looking for writers 2022/01/09 06:18:51 DEBUG : file1: reading active writers 2022/01/09 06:18:51 DEBUG : file1: active writers 1 2022/01/09 06:18:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/01/09 06:18:51 DEBUG : : Looking for writers 2022/01/09 06:18:51 DEBUG : file1: reading active writers 2022/01/09 06:18:51 DEBUG : file1: active writers 1 2022/01/09 06:18:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/01/09 06:18:51 DEBUG : : Looking for writers 2022/01/09 06:18:51 DEBUG : file1: reading active writers 2022/01/09 06:18:51 DEBUG : file1: active writers 1 2022/01/09 06:18:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/01/09 06:18:52 DEBUG : : Looking for writers 2022/01/09 06:18:52 DEBUG : file1: reading active writers 2022/01/09 06:18:52 DEBUG : file1: active writers 1 2022/01/09 06:18:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/01/09 06:18:52 DEBUG : : Looking for writers 2022/01/09 06:18:52 DEBUG : file1: reading active writers 2022/01/09 06:18:52 DEBUG : file1: active writers 1 2022/01/09 06:18:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:53 DEBUG : : Looking for writers 2022/01/09 06:18:53 DEBUG : file1: reading active writers 2022/01/09 06:18:53 DEBUG : file1: active writers 1 2022/01/09 06:18:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:54 DEBUG : : Looking for writers 2022/01/09 06:18:54 DEBUG : file1: reading active writers 2022/01/09 06:18:54 DEBUG : file1: active writers 1 2022/01/09 06:18:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:55 DEBUG : : Looking for writers 2022/01/09 06:18:55 DEBUG : file1: reading active writers 2022/01/09 06:18:55 DEBUG : file1: active writers 1 2022/01/09 06:18:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:56 DEBUG : : Looking for writers 2022/01/09 06:18:56 DEBUG : file1: reading active writers 2022/01/09 06:18:56 DEBUG : file1: active writers 1 2022/01/09 06:18:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:57 DEBUG : : Looking for writers 2022/01/09 06:18:57 DEBUG : file1: reading active writers 2022/01/09 06:18:57 DEBUG : file1: active writers 1 2022/01/09 06:18:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:58 DEBUG : : Looking for writers 2022/01/09 06:18:58 DEBUG : file1: reading active writers 2022/01/09 06:18:58 DEBUG : file1: active writers 1 2022/01/09 06:18:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:18:59 DEBUG : : Looking for writers 2022/01/09 06:18:59 DEBUG : file1: reading active writers 2022/01/09 06:18:59 DEBUG : file1: active writers 1 2022/01/09 06:18:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:00 DEBUG : : Looking for writers 2022/01/09 06:19:00 DEBUG : file1: reading active writers 2022/01/09 06:19:00 DEBUG : file1: active writers 1 2022/01/09 06:19:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:01 DEBUG : : Looking for writers 2022/01/09 06:19:01 DEBUG : file1: reading active writers 2022/01/09 06:19:01 DEBUG : file1: active writers 1 2022/01/09 06:19:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:02 DEBUG : : Looking for writers 2022/01/09 06:19:02 DEBUG : file1: reading active writers 2022/01/09 06:19:02 DEBUG : file1: active writers 1 2022/01/09 06:19:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:03 DEBUG : : Looking for writers 2022/01/09 06:19:03 DEBUG : file1: reading active writers 2022/01/09 06:19:03 DEBUG : file1: active writers 1 2022/01/09 06:19:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:04 DEBUG : : Looking for writers 2022/01/09 06:19:04 DEBUG : file1: reading active writers 2022/01/09 06:19:04 DEBUG : file1: active writers 1 2022/01/09 06:19:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:05 DEBUG : : Looking for writers 2022/01/09 06:19:05 DEBUG : file1: reading active writers 2022/01/09 06:19:05 DEBUG : file1: active writers 1 2022/01/09 06:19:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:06 DEBUG : : Looking for writers 2022/01/09 06:19:06 DEBUG : file1: reading active writers 2022/01/09 06:19:06 DEBUG : file1: active writers 1 2022/01/09 06:19:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:07 DEBUG : : Looking for writers 2022/01/09 06:19:07 DEBUG : file1: reading active writers 2022/01/09 06:19:07 DEBUG : file1: active writers 1 2022/01/09 06:19:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:08 DEBUG : : Looking for writers 2022/01/09 06:19:08 DEBUG : file1: reading active writers 2022/01/09 06:19:08 DEBUG : file1: active writers 1 2022/01/09 06:19:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:09 DEBUG : : Looking for writers 2022/01/09 06:19:09 DEBUG : file1: reading active writers 2022/01/09 06:19:09 DEBUG : file1: active writers 1 2022/01/09 06:19:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:10 DEBUG : : Looking for writers 2022/01/09 06:19:10 DEBUG : file1: reading active writers 2022/01/09 06:19:10 DEBUG : file1: active writers 1 2022/01/09 06:19:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:11 DEBUG : : Looking for writers 2022/01/09 06:19:11 DEBUG : file1: reading active writers 2022/01/09 06:19:11 DEBUG : file1: active writers 1 2022/01/09 06:19:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:12 DEBUG : : Looking for writers 2022/01/09 06:19:12 DEBUG : file1: reading active writers 2022/01/09 06:19:12 DEBUG : file1: active writers 1 2022/01/09 06:19:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:13 DEBUG : : Looking for writers 2022/01/09 06:19:13 DEBUG : file1: reading active writers 2022/01/09 06:19:13 DEBUG : file1: active writers 1 2022/01/09 06:19:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:14 DEBUG : : Looking for writers 2022/01/09 06:19:14 DEBUG : file1: reading active writers 2022/01/09 06:19:14 DEBUG : file1: active writers 1 2022/01/09 06:19:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:15 DEBUG : : Looking for writers 2022/01/09 06:19:15 DEBUG : file1: reading active writers 2022/01/09 06:19:15 DEBUG : file1: active writers 1 2022/01/09 06:19:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:16 DEBUG : : Looking for writers 2022/01/09 06:19:16 DEBUG : file1: reading active writers 2022/01/09 06:19:16 DEBUG : file1: active writers 1 2022/01/09 06:19:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:17 DEBUG : : Looking for writers 2022/01/09 06:19:17 DEBUG : file1: reading active writers 2022/01/09 06:19:17 DEBUG : file1: active writers 1 2022/01/09 06:19:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:18 DEBUG : : Looking for writers 2022/01/09 06:19:18 DEBUG : file1: reading active writers 2022/01/09 06:19:18 DEBUG : file1: active writers 1 2022/01/09 06:19:18 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:19 DEBUG : : Looking for writers 2022/01/09 06:19:19 DEBUG : file1: reading active writers 2022/01/09 06:19:19 DEBUG : file1: active writers 1 2022/01/09 06:19:19 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:20 DEBUG : : Looking for writers 2022/01/09 06:19:20 DEBUG : file1: reading active writers 2022/01/09 06:19:20 DEBUG : file1: active writers 1 2022/01/09 06:19:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:21 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2022/01/09 06:19:21 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleRelease (30.34s) === RUN TestWriteFileModTimeWithOpenWriters run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:19:21 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:19:21 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:19:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:19:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:19:21 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:19:21 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:19:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:19:21 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': File to upload is small (2 bytes), uploading instead of streaming 2022/01/09 06:19:22 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:19:22 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 Payment Required) returned body: "" write_test.go:277: Error Trace: write_test.go:277 Error: Received unexpected error: upload error: HTTP error 402 (402 Payment Required) returned body: "" Test: TestWriteFileModTimeWithOpenWriters 2022/01/09 06:19:22 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:19:22 DEBUG : : Looking for writers 2022/01/09 06:19:22 DEBUG : file1: reading active writers 2022/01/09 06:19:22 DEBUG : file1: active writers 1 2022/01/09 06:19:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/01/09 06:19:22 DEBUG : : Looking for writers 2022/01/09 06:19:22 DEBUG : file1: reading active writers 2022/01/09 06:19:22 DEBUG : file1: active writers 1 2022/01/09 06:19:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/01/09 06:19:22 DEBUG : : Looking for writers 2022/01/09 06:19:22 DEBUG : file1: reading active writers 2022/01/09 06:19:22 DEBUG : file1: active writers 1 2022/01/09 06:19:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/01/09 06:19:22 DEBUG : : Looking for writers 2022/01/09 06:19:22 DEBUG : file1: reading active writers 2022/01/09 06:19:22 DEBUG : file1: active writers 1 2022/01/09 06:19:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/01/09 06:19:22 DEBUG : : Looking for writers 2022/01/09 06:19:22 DEBUG : file1: reading active writers 2022/01/09 06:19:22 DEBUG : file1: active writers 1 2022/01/09 06:19:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/01/09 06:19:22 DEBUG : : Looking for writers 2022/01/09 06:19:22 DEBUG : file1: reading active writers 2022/01/09 06:19:22 DEBUG : file1: active writers 1 2022/01/09 06:19:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/01/09 06:19:22 DEBUG : : Looking for writers 2022/01/09 06:19:22 DEBUG : file1: reading active writers 2022/01/09 06:19:22 DEBUG : file1: active writers 1 2022/01/09 06:19:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/01/09 06:19:23 DEBUG : : Looking for writers 2022/01/09 06:19:23 DEBUG : file1: reading active writers 2022/01/09 06:19:23 DEBUG : file1: active writers 1 2022/01/09 06:19:23 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:24 DEBUG : : Looking for writers 2022/01/09 06:19:24 DEBUG : file1: reading active writers 2022/01/09 06:19:24 DEBUG : file1: active writers 1 2022/01/09 06:19:24 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:25 DEBUG : : Looking for writers 2022/01/09 06:19:25 DEBUG : file1: reading active writers 2022/01/09 06:19:25 DEBUG : file1: active writers 1 2022/01/09 06:19:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:26 DEBUG : : Looking for writers 2022/01/09 06:19:26 DEBUG : file1: reading active writers 2022/01/09 06:19:26 DEBUG : file1: active writers 1 2022/01/09 06:19:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:27 DEBUG : : Looking for writers 2022/01/09 06:19:27 DEBUG : file1: reading active writers 2022/01/09 06:19:27 DEBUG : file1: active writers 1 2022/01/09 06:19:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:28 DEBUG : : Looking for writers 2022/01/09 06:19:28 DEBUG : file1: reading active writers 2022/01/09 06:19:28 DEBUG : file1: active writers 1 2022/01/09 06:19:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:29 DEBUG : : Looking for writers 2022/01/09 06:19:29 DEBUG : file1: reading active writers 2022/01/09 06:19:29 DEBUG : file1: active writers 1 2022/01/09 06:19:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:30 DEBUG : : Looking for writers 2022/01/09 06:19:30 DEBUG : file1: reading active writers 2022/01/09 06:19:30 DEBUG : file1: active writers 1 2022/01/09 06:19:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:31 DEBUG : : Looking for writers 2022/01/09 06:19:31 DEBUG : file1: reading active writers 2022/01/09 06:19:31 DEBUG : file1: active writers 1 2022/01/09 06:19:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:32 DEBUG : : Looking for writers 2022/01/09 06:19:32 DEBUG : file1: reading active writers 2022/01/09 06:19:32 DEBUG : file1: active writers 1 2022/01/09 06:19:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:33 DEBUG : : Looking for writers 2022/01/09 06:19:33 DEBUG : file1: reading active writers 2022/01/09 06:19:33 DEBUG : file1: active writers 1 2022/01/09 06:19:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:34 DEBUG : : Looking for writers 2022/01/09 06:19:34 DEBUG : file1: reading active writers 2022/01/09 06:19:34 DEBUG : file1: active writers 1 2022/01/09 06:19:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:35 DEBUG : : Looking for writers 2022/01/09 06:19:35 DEBUG : file1: reading active writers 2022/01/09 06:19:35 DEBUG : file1: active writers 1 2022/01/09 06:19:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:36 DEBUG : : Looking for writers 2022/01/09 06:19:36 DEBUG : file1: reading active writers 2022/01/09 06:19:36 DEBUG : file1: active writers 1 2022/01/09 06:19:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:37 DEBUG : : Looking for writers 2022/01/09 06:19:37 DEBUG : file1: reading active writers 2022/01/09 06:19:37 DEBUG : file1: active writers 1 2022/01/09 06:19:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:38 DEBUG : : Looking for writers 2022/01/09 06:19:38 DEBUG : file1: reading active writers 2022/01/09 06:19:38 DEBUG : file1: active writers 1 2022/01/09 06:19:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:39 DEBUG : : Looking for writers 2022/01/09 06:19:39 DEBUG : file1: reading active writers 2022/01/09 06:19:39 DEBUG : file1: active writers 1 2022/01/09 06:19:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:40 DEBUG : : Looking for writers 2022/01/09 06:19:40 DEBUG : file1: reading active writers 2022/01/09 06:19:40 DEBUG : file1: active writers 1 2022/01/09 06:19:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:41 DEBUG : : Looking for writers 2022/01/09 06:19:41 DEBUG : file1: reading active writers 2022/01/09 06:19:41 DEBUG : file1: active writers 1 2022/01/09 06:19:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:42 DEBUG : : Looking for writers 2022/01/09 06:19:42 DEBUG : file1: reading active writers 2022/01/09 06:19:42 DEBUG : file1: active writers 1 2022/01/09 06:19:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:43 DEBUG : : Looking for writers 2022/01/09 06:19:43 DEBUG : file1: reading active writers 2022/01/09 06:19:43 DEBUG : file1: active writers 1 2022/01/09 06:19:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:44 DEBUG : : Looking for writers 2022/01/09 06:19:44 DEBUG : file1: reading active writers 2022/01/09 06:19:44 DEBUG : file1: active writers 1 2022/01/09 06:19:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:45 DEBUG : : Looking for writers 2022/01/09 06:19:45 DEBUG : file1: reading active writers 2022/01/09 06:19:45 DEBUG : file1: active writers 1 2022/01/09 06:19:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:46 DEBUG : : Looking for writers 2022/01/09 06:19:46 DEBUG : file1: reading active writers 2022/01/09 06:19:46 DEBUG : file1: active writers 1 2022/01/09 06:19:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:47 DEBUG : : Looking for writers 2022/01/09 06:19:47 DEBUG : file1: reading active writers 2022/01/09 06:19:47 DEBUG : file1: active writers 1 2022/01/09 06:19:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:48 DEBUG : : Looking for writers 2022/01/09 06:19:48 DEBUG : file1: reading active writers 2022/01/09 06:19:48 DEBUG : file1: active writers 1 2022/01/09 06:19:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:49 DEBUG : : Looking for writers 2022/01/09 06:19:49 DEBUG : file1: reading active writers 2022/01/09 06:19:49 DEBUG : file1: active writers 1 2022/01/09 06:19:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:50 DEBUG : : Looking for writers 2022/01/09 06:19:50 DEBUG : file1: reading active writers 2022/01/09 06:19:50 DEBUG : file1: active writers 1 2022/01/09 06:19:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:51 DEBUG : : Looking for writers 2022/01/09 06:19:51 DEBUG : file1: reading active writers 2022/01/09 06:19:51 DEBUG : file1: active writers 1 2022/01/09 06:19:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:52 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2022/01/09 06:19:52 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileModTimeWithOpenWriters (30.32s) === RUN TestFileReadAtZeroLength run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:19:52 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:19:52 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:19:52 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:19:52 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:19:52 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:19:52 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:19:52 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:19:52 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': File to upload is small (0 bytes), uploading instead of streaming 2022/01/09 06:19:52 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:19:52 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 Payment Required) 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 Payment Required) returned body: "" Test: TestFileReadAtZeroLength 2022/01/09 06:19:52 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2022/01/09 06:19:52 DEBUG : file1: Open: flags=O_RDONLY 2022/01/09 06:19:57 DEBUG : file1: >Open: fd=, err=file does not exist 2022/01/09 06:19:57 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 2022/01/09 06:19:57 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:19:57 DEBUG : : Looking for writers 2022/01/09 06:19:57 DEBUG : file1: reading active writers 2022/01/09 06:19:57 DEBUG : file1: active writers 1 2022/01/09 06:19:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/01/09 06:19:57 DEBUG : : Looking for writers 2022/01/09 06:19:57 DEBUG : file1: reading active writers 2022/01/09 06:19:57 DEBUG : file1: active writers 1 2022/01/09 06:19:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/01/09 06:19:57 DEBUG : : Looking for writers 2022/01/09 06:19:57 DEBUG : file1: reading active writers 2022/01/09 06:19:57 DEBUG : file1: active writers 1 2022/01/09 06:19:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/01/09 06:19:57 DEBUG : : Looking for writers 2022/01/09 06:19:57 DEBUG : file1: reading active writers 2022/01/09 06:19:57 DEBUG : file1: active writers 1 2022/01/09 06:19:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/01/09 06:19:57 DEBUG : : Looking for writers 2022/01/09 06:19:57 DEBUG : file1: reading active writers 2022/01/09 06:19:57 DEBUG : file1: active writers 1 2022/01/09 06:19:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/01/09 06:19:57 DEBUG : : Looking for writers 2022/01/09 06:19:57 DEBUG : file1: reading active writers 2022/01/09 06:19:57 DEBUG : file1: active writers 1 2022/01/09 06:19:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/01/09 06:19:57 DEBUG : : Looking for writers 2022/01/09 06:19:57 DEBUG : file1: reading active writers 2022/01/09 06:19:57 DEBUG : file1: active writers 1 2022/01/09 06:19:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/01/09 06:19:58 DEBUG : : Looking for writers 2022/01/09 06:19:58 DEBUG : file1: reading active writers 2022/01/09 06:19:58 DEBUG : file1: active writers 1 2022/01/09 06:19:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:19:59 DEBUG : : Looking for writers 2022/01/09 06:19:59 DEBUG : file1: reading active writers 2022/01/09 06:19:59 DEBUG : file1: active writers 1 2022/01/09 06:19:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:00 DEBUG : : Looking for writers 2022/01/09 06:20:00 DEBUG : file1: reading active writers 2022/01/09 06:20:00 DEBUG : file1: active writers 1 2022/01/09 06:20:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:01 DEBUG : : Looking for writers 2022/01/09 06:20:01 DEBUG : file1: reading active writers 2022/01/09 06:20:01 DEBUG : file1: active writers 1 2022/01/09 06:20:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:02 DEBUG : : Looking for writers 2022/01/09 06:20:02 DEBUG : file1: reading active writers 2022/01/09 06:20:02 DEBUG : file1: active writers 1 2022/01/09 06:20:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:03 DEBUG : : Looking for writers 2022/01/09 06:20:03 DEBUG : file1: reading active writers 2022/01/09 06:20:03 DEBUG : file1: active writers 1 2022/01/09 06:20:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:04 DEBUG : : Looking for writers 2022/01/09 06:20:04 DEBUG : file1: reading active writers 2022/01/09 06:20:04 DEBUG : file1: active writers 1 2022/01/09 06:20:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:05 DEBUG : : Looking for writers 2022/01/09 06:20:05 DEBUG : file1: reading active writers 2022/01/09 06:20:05 DEBUG : file1: active writers 1 2022/01/09 06:20:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:06 DEBUG : : Looking for writers 2022/01/09 06:20:06 DEBUG : file1: reading active writers 2022/01/09 06:20:06 DEBUG : file1: active writers 1 2022/01/09 06:20:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:07 DEBUG : : Looking for writers 2022/01/09 06:20:07 DEBUG : file1: reading active writers 2022/01/09 06:20:07 DEBUG : file1: active writers 1 2022/01/09 06:20:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:08 DEBUG : : Looking for writers 2022/01/09 06:20:08 DEBUG : file1: reading active writers 2022/01/09 06:20:08 DEBUG : file1: active writers 1 2022/01/09 06:20:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:09 DEBUG : : Looking for writers 2022/01/09 06:20:09 DEBUG : file1: reading active writers 2022/01/09 06:20:09 DEBUG : file1: active writers 1 2022/01/09 06:20:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:10 DEBUG : : Looking for writers 2022/01/09 06:20:10 DEBUG : file1: reading active writers 2022/01/09 06:20:10 DEBUG : file1: active writers 1 2022/01/09 06:20:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:11 DEBUG : : Looking for writers 2022/01/09 06:20:11 DEBUG : file1: reading active writers 2022/01/09 06:20:11 DEBUG : file1: active writers 1 2022/01/09 06:20:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:12 DEBUG : : Looking for writers 2022/01/09 06:20:12 DEBUG : file1: reading active writers 2022/01/09 06:20:12 DEBUG : file1: active writers 1 2022/01/09 06:20:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:13 DEBUG : : Looking for writers 2022/01/09 06:20:13 DEBUG : file1: reading active writers 2022/01/09 06:20:13 DEBUG : file1: active writers 1 2022/01/09 06:20:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:14 DEBUG : : Looking for writers 2022/01/09 06:20:14 DEBUG : file1: reading active writers 2022/01/09 06:20:14 DEBUG : file1: active writers 1 2022/01/09 06:20:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:15 DEBUG : : Looking for writers 2022/01/09 06:20:15 DEBUG : file1: reading active writers 2022/01/09 06:20:15 DEBUG : file1: active writers 1 2022/01/09 06:20:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:16 DEBUG : : Looking for writers 2022/01/09 06:20:16 DEBUG : file1: reading active writers 2022/01/09 06:20:16 DEBUG : file1: active writers 1 2022/01/09 06:20:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:17 DEBUG : : Looking for writers 2022/01/09 06:20:17 DEBUG : file1: reading active writers 2022/01/09 06:20:17 DEBUG : file1: active writers 1 2022/01/09 06:20:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:18 DEBUG : : Looking for writers 2022/01/09 06:20:18 DEBUG : file1: reading active writers 2022/01/09 06:20:18 DEBUG : file1: active writers 1 2022/01/09 06:20:18 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:19 DEBUG : : Looking for writers 2022/01/09 06:20:19 DEBUG : file1: reading active writers 2022/01/09 06:20:19 DEBUG : file1: active writers 1 2022/01/09 06:20:19 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:20 DEBUG : : Looking for writers 2022/01/09 06:20:20 DEBUG : file1: reading active writers 2022/01/09 06:20:20 DEBUG : file1: active writers 1 2022/01/09 06:20:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:21 DEBUG : : Looking for writers 2022/01/09 06:20:21 DEBUG : file1: reading active writers 2022/01/09 06:20:21 DEBUG : file1: active writers 1 2022/01/09 06:20:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:22 DEBUG : : Looking for writers 2022/01/09 06:20:22 DEBUG : file1: reading active writers 2022/01/09 06:20:22 DEBUG : file1: active writers 1 2022/01/09 06:20:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:23 DEBUG : : Looking for writers 2022/01/09 06:20:23 DEBUG : file1: reading active writers 2022/01/09 06:20:23 DEBUG : file1: active writers 1 2022/01/09 06:20:23 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:24 DEBUG : : Looking for writers 2022/01/09 06:20:24 DEBUG : file1: reading active writers 2022/01/09 06:20:24 DEBUG : file1: active writers 1 2022/01/09 06:20:24 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:25 DEBUG : : Looking for writers 2022/01/09 06:20:25 DEBUG : file1: reading active writers 2022/01/09 06:20:25 DEBUG : file1: active writers 1 2022/01/09 06:20:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:26 DEBUG : : Looking for writers 2022/01/09 06:20:26 DEBUG : file1: reading active writers 2022/01/09 06:20:26 DEBUG : file1: active writers 1 2022/01/09 06:20:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:27 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2022/01/09 06:20:27 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtZeroLength (35.33s) === RUN TestFileReadAtNonZeroLength run.go:181: Remote "zoho root 'rclone-test-tikuguh2xarudij8kunigaf9'", Local "Local file system at /tmp/rclone2351581393", Modify Window "876000h0m0s" 2022/01/09 06:20:27 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': Re-using VFS from active cache 2022/01/09 06:20:27 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/01/09 06:20:27 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/01/09 06:20:27 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:20:27 DEBUG : file1: >Open: fd=file1 (w), err= 2022/01/09 06:20:27 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/01/09 06:20:27 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/01/09 06:20:27 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': File to upload is small (100 bytes), uploading instead of streaming 2022/01/09 06:20:27 ERROR : file1: Failed to copy: upload error: HTTP error 402 (402 Payment Required) returned body: "" 2022/01/09 06:20:27 ERROR : file1: WriteFileHandle.New Rcat failed: upload error: HTTP error 402 (402 Payment Required) 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 Payment Required) returned body: "" Test: TestFileReadAtNonZeroLength 2022/01/09 06:20:27 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2022/01/09 06:20:27 DEBUG : file1: Open: flags=O_RDONLY 2022/01/09 06:20:32 DEBUG : file1: >Open: fd=, err=file does not exist 2022/01/09 06:20:32 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 2022/01/09 06:20:32 DEBUG : WaitForWriters: timeout=30s 2022/01/09 06:20:32 DEBUG : : Looking for writers 2022/01/09 06:20:32 DEBUG : file1: reading active writers 2022/01/09 06:20:32 DEBUG : file1: active writers 1 2022/01/09 06:20:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/01/09 06:20:32 DEBUG : : Looking for writers 2022/01/09 06:20:32 DEBUG : file1: reading active writers 2022/01/09 06:20:32 DEBUG : file1: active writers 1 2022/01/09 06:20:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/01/09 06:20:32 DEBUG : : Looking for writers 2022/01/09 06:20:32 DEBUG : file1: reading active writers 2022/01/09 06:20:32 DEBUG : file1: active writers 1 2022/01/09 06:20:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/01/09 06:20:32 DEBUG : : Looking for writers 2022/01/09 06:20:32 DEBUG : file1: reading active writers 2022/01/09 06:20:32 DEBUG : file1: active writers 1 2022/01/09 06:20:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/01/09 06:20:32 DEBUG : : Looking for writers 2022/01/09 06:20:32 DEBUG : file1: reading active writers 2022/01/09 06:20:32 DEBUG : file1: active writers 1 2022/01/09 06:20:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/01/09 06:20:33 DEBUG : : Looking for writers 2022/01/09 06:20:33 DEBUG : file1: reading active writers 2022/01/09 06:20:33 DEBUG : file1: active writers 1 2022/01/09 06:20:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/01/09 06:20:33 DEBUG : : Looking for writers 2022/01/09 06:20:33 DEBUG : file1: reading active writers 2022/01/09 06:20:33 DEBUG : file1: active writers 1 2022/01/09 06:20:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/01/09 06:20:34 DEBUG : : Looking for writers 2022/01/09 06:20:34 DEBUG : file1: reading active writers 2022/01/09 06:20:34 DEBUG : file1: active writers 1 2022/01/09 06:20:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:35 DEBUG : : Looking for writers 2022/01/09 06:20:35 DEBUG : file1: reading active writers 2022/01/09 06:20:35 DEBUG : file1: active writers 1 2022/01/09 06:20:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:36 DEBUG : : Looking for writers 2022/01/09 06:20:36 DEBUG : file1: reading active writers 2022/01/09 06:20:36 DEBUG : file1: active writers 1 2022/01/09 06:20:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:37 DEBUG : : Looking for writers 2022/01/09 06:20:37 DEBUG : file1: reading active writers 2022/01/09 06:20:37 DEBUG : file1: active writers 1 2022/01/09 06:20:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:38 DEBUG : : Looking for writers 2022/01/09 06:20:38 DEBUG : file1: reading active writers 2022/01/09 06:20:38 DEBUG : file1: active writers 1 2022/01/09 06:20:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:39 DEBUG : : Looking for writers 2022/01/09 06:20:39 DEBUG : file1: reading active writers 2022/01/09 06:20:39 DEBUG : file1: active writers 1 2022/01/09 06:20:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:40 DEBUG : : Looking for writers 2022/01/09 06:20:40 DEBUG : file1: reading active writers 2022/01/09 06:20:40 DEBUG : file1: active writers 1 2022/01/09 06:20:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:41 DEBUG : : Looking for writers 2022/01/09 06:20:41 DEBUG : file1: reading active writers 2022/01/09 06:20:41 DEBUG : file1: active writers 1 2022/01/09 06:20:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:42 DEBUG : : Looking for writers 2022/01/09 06:20:42 DEBUG : file1: reading active writers 2022/01/09 06:20:42 DEBUG : file1: active writers 1 2022/01/09 06:20:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:43 DEBUG : : Looking for writers 2022/01/09 06:20:43 DEBUG : file1: reading active writers 2022/01/09 06:20:43 DEBUG : file1: active writers 1 2022/01/09 06:20:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:44 DEBUG : : Looking for writers 2022/01/09 06:20:44 DEBUG : file1: reading active writers 2022/01/09 06:20:44 DEBUG : file1: active writers 1 2022/01/09 06:20:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:45 DEBUG : : Looking for writers 2022/01/09 06:20:45 DEBUG : file1: reading active writers 2022/01/09 06:20:45 DEBUG : file1: active writers 1 2022/01/09 06:20:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:46 DEBUG : : Looking for writers 2022/01/09 06:20:46 DEBUG : file1: reading active writers 2022/01/09 06:20:46 DEBUG : file1: active writers 1 2022/01/09 06:20:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:47 DEBUG : : Looking for writers 2022/01/09 06:20:47 DEBUG : file1: reading active writers 2022/01/09 06:20:47 DEBUG : file1: active writers 1 2022/01/09 06:20:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:48 DEBUG : : Looking for writers 2022/01/09 06:20:48 DEBUG : file1: reading active writers 2022/01/09 06:20:48 DEBUG : file1: active writers 1 2022/01/09 06:20:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:49 DEBUG : : Looking for writers 2022/01/09 06:20:49 DEBUG : file1: reading active writers 2022/01/09 06:20:49 DEBUG : file1: active writers 1 2022/01/09 06:20:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:50 DEBUG : : Looking for writers 2022/01/09 06:20:50 DEBUG : file1: reading active writers 2022/01/09 06:20:50 DEBUG : file1: active writers 1 2022/01/09 06:20:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:51 DEBUG : : Looking for writers 2022/01/09 06:20:51 DEBUG : file1: reading active writers 2022/01/09 06:20:51 DEBUG : file1: active writers 1 2022/01/09 06:20:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:52 DEBUG : : Looking for writers 2022/01/09 06:20:52 DEBUG : file1: reading active writers 2022/01/09 06:20:52 DEBUG : file1: active writers 1 2022/01/09 06:20:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:53 DEBUG : : Looking for writers 2022/01/09 06:20:53 DEBUG : file1: reading active writers 2022/01/09 06:20:53 DEBUG : file1: active writers 1 2022/01/09 06:20:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:54 DEBUG : : Looking for writers 2022/01/09 06:20:54 DEBUG : file1: reading active writers 2022/01/09 06:20:54 DEBUG : file1: active writers 1 2022/01/09 06:20:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:55 DEBUG : : Looking for writers 2022/01/09 06:20:55 DEBUG : file1: reading active writers 2022/01/09 06:20:55 DEBUG : file1: active writers 1 2022/01/09 06:20:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:56 DEBUG : : Looking for writers 2022/01/09 06:20:56 DEBUG : file1: reading active writers 2022/01/09 06:20:56 DEBUG : file1: active writers 1 2022/01/09 06:20:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:57 DEBUG : : Looking for writers 2022/01/09 06:20:57 DEBUG : file1: reading active writers 2022/01/09 06:20:57 DEBUG : file1: active writers 1 2022/01/09 06:20:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:58 DEBUG : : Looking for writers 2022/01/09 06:20:58 DEBUG : file1: reading active writers 2022/01/09 06:20:58 DEBUG : file1: active writers 1 2022/01/09 06:20:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:20:59 DEBUG : : Looking for writers 2022/01/09 06:20:59 DEBUG : file1: reading active writers 2022/01/09 06:20:59 DEBUG : file1: active writers 1 2022/01/09 06:20:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:21:00 DEBUG : : Looking for writers 2022/01/09 06:21:00 DEBUG : file1: reading active writers 2022/01/09 06:21:00 DEBUG : file1: active writers 1 2022/01/09 06:21:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:21:01 DEBUG : : Looking for writers 2022/01/09 06:21:01 DEBUG : file1: reading active writers 2022/01/09 06:21:01 DEBUG : file1: active writers 1 2022/01/09 06:21:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:21:02 DEBUG : : Looking for writers 2022/01/09 06:21:02 DEBUG : file1: reading active writers 2022/01/09 06:21:02 DEBUG : file1: active writers 1 2022/01/09 06:21:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/01/09 06:21:02 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2022/01/09 06:21:02 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtNonZeroLength (35.39s) FAIL 2022/01/09 06:21:02 DEBUG : zoho root 'rclone-test-tikuguh2xarudij8kunigaf9': 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 8m11.048766688s (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]