"./vfs.test -test.v -test.timeout 1h0m0s -remote TestB2: -list-retries 5 -verbose -test.run '^(TestCaseSensitivity|TestDirCreate|TestDirFileOpen|TestDirForgetAll|TestDirForgetPath|TestDirHandleMethods|TestDirHandleReaddir|TestDirHandleReaddirnames|TestDirMetadataExtension|TestDirMethods|TestDirMkdir|TestDirMkdirSub|TestDirOpen|TestDirReadDirAll|TestDirRemove|TestDirRemoveAll|TestDirRemoveName|TestDirRename|TestDirSetModTime|TestDirStat|TestDirWalk|TestFileMethods|TestFileOpen|TestFileOpenRead|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRemove|TestFileRemoveAll|TestRWCacheUpdate|TestRWFileHandleFlushRead|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestUnicodeNormalization|TestVFSOpenFile|TestVFSRename|TestVFSStat|TestVFSStatParent|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters|TestZipDirsInRoot|TestZipLargeFiles|TestZipManyFiles|TestZipManySubDirs)$|^TestFileRename$/^(full,forceCache=false|minimal,forceCache=false|minimal,forceCache=true|off,forceCache=false|writes,forceCache=false|writes,forceCache=true)$|^TestFileSetModTime$/^(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)$'" - Starting (try 2/5) 2025/11/28 02:36:38 DEBUG : Creating backend with remote "TestB2:rclone-test-kuhogad2fuka" 2025/11/28 02:36:38 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2025/11/28 02:36:39 DEBUG : Creating backend with remote "/tmp/rclone4140315189" === RUN TestDirHandleMethods run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:39 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:39 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:39 DEBUG : Looking for writers 2025/11/28 02:36:39 DEBUG : >WaitForWriters: --- FAIL: TestDirHandleMethods (0.56s) === RUN TestDirHandleReaddir run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:39 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:40 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:40 DEBUG : Looking for writers 2025/11/28 02:36:40 DEBUG : >WaitForWriters: --- FAIL: TestDirHandleReaddir (0.19s) === RUN TestDirHandleReaddirnames run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:40 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:40 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:40 DEBUG : Looking for writers 2025/11/28 02:36:40 DEBUG : >WaitForWriters: --- FAIL: TestDirHandleReaddirnames (0.19s) === RUN TestDirMethods run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:40 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:40 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:40 DEBUG : Looking for writers 2025/11/28 02:36:40 DEBUG : >WaitForWriters: --- FAIL: TestDirMethods (0.20s) === RUN TestDirForgetAll run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:40 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:40 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:40 DEBUG : Looking for writers 2025/11/28 02:36:40 DEBUG : >WaitForWriters: --- FAIL: TestDirForgetAll (0.20s) === RUN TestDirForgetPath run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:40 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:40 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:40 DEBUG : Looking for writers 2025/11/28 02:36:40 DEBUG : >WaitForWriters: --- FAIL: TestDirForgetPath (0.19s) === RUN TestDirWalk run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:40 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:41 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:41 DEBUG : Looking for writers 2025/11/28 02:36:41 DEBUG : >WaitForWriters: --- FAIL: TestDirWalk (0.22s) === RUN TestDirSetModTime run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:41 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:41 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:41 DEBUG : Looking for writers 2025/11/28 02:36:41 DEBUG : >WaitForWriters: --- FAIL: TestDirSetModTime (0.20s) === RUN TestDirStat run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:41 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:41 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:41 DEBUG : Looking for writers 2025/11/28 02:36:41 DEBUG : >WaitForWriters: --- FAIL: TestDirStat (0.19s) === RUN TestDirReadDirAll run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:41 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:41 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:41 DEBUG : Looking for writers 2025/11/28 02:36:41 DEBUG : >WaitForWriters: --- FAIL: TestDirReadDirAll (0.19s) === RUN TestDirOpen run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:41 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:41 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:41 DEBUG : Looking for writers 2025/11/28 02:36:41 DEBUG : >WaitForWriters: --- FAIL: TestDirOpen (0.19s) === RUN TestDirCreate run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:41 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:42 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:42 DEBUG : Looking for writers 2025/11/28 02:36:42 DEBUG : >WaitForWriters: --- FAIL: TestDirCreate (0.19s) === RUN TestDirMkdir run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:42 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:42 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:42 DEBUG : Looking for writers 2025/11/28 02:36:42 DEBUG : >WaitForWriters: --- FAIL: TestDirMkdir (0.20s) === RUN TestDirMkdirSub run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:42 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:42 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:42 DEBUG : Looking for writers 2025/11/28 02:36:42 DEBUG : >WaitForWriters: --- FAIL: TestDirMkdirSub (0.20s) === RUN TestDirRemove run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:42 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:42 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:42 DEBUG : Looking for writers 2025/11/28 02:36:42 DEBUG : >WaitForWriters: --- FAIL: TestDirRemove (0.21s) === RUN TestDirRemoveAll run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:42 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:42 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:42 DEBUG : Looking for writers 2025/11/28 02:36:42 DEBUG : >WaitForWriters: --- FAIL: TestDirRemoveAll (0.20s) === RUN TestDirRemoveName run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:42 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:43 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:43 DEBUG : Looking for writers 2025/11/28 02:36:43 DEBUG : >WaitForWriters: --- FAIL: TestDirRemoveName (0.20s) === RUN TestDirRename run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:43 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:43 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:43 DEBUG : Looking for writers 2025/11/28 02:36:43 DEBUG : >WaitForWriters: --- FAIL: TestDirRename (0.20s) === RUN TestDirFileOpen run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:43 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:43 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:43 DEBUG : Looking for writers 2025/11/28 02:36:43 DEBUG : >WaitForWriters: --- FAIL: TestDirFileOpen (0.19s) === RUN TestDirMetadataExtension run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:43 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:43 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:43 DEBUG : Looking for writers 2025/11/28 02:36:43 DEBUG : >WaitForWriters: --- FAIL: TestDirMetadataExtension (0.20s) === RUN TestFileMethods run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:43 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:43 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:43 DEBUG : Looking for writers 2025/11/28 02:36:43 DEBUG : >WaitForWriters: --- FAIL: TestFileMethods (0.19s) === RUN TestFileSetModTime === RUN TestFileSetModTime/cache=off,open=false,write=false run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:43 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:44 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:44 DEBUG : Looking for writers 2025/11/28 02:36:44 DEBUG : >WaitForWriters: === RUN TestFileSetModTime/cache=off,open=true,write=false run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:44 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:44 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:44 DEBUG : Looking for writers 2025/11/28 02:36:44 DEBUG : >WaitForWriters: === RUN TestFileSetModTime/cache=off,open=true,write=true run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:44 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:44 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:44 DEBUG : Looking for writers 2025/11/28 02:36:44 DEBUG : >WaitForWriters: === RUN TestFileSetModTime/cache=full,open=false,write=false run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:44 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:44 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:44 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:44 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:44 DEBUG : Looking for writers 2025/11/28 02:36:44 DEBUG : >WaitForWriters: 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestFileSetModTime/cache=full,open=true,write=false run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:44 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:44 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:44 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:44 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:44 DEBUG : Looking for writers 2025/11/28 02:36:44 DEBUG : >WaitForWriters: 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestFileSetModTime/cache=full,open=true,write=true run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:44 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:44 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:44 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:44 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:45 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:45 DEBUG : Looking for writers 2025/11/28 02:36:45 DEBUG : >WaitForWriters: --- FAIL: TestFileSetModTime (1.17s) --- FAIL: TestFileSetModTime/cache=off,open=false,write=false (0.19s) --- FAIL: TestFileSetModTime/cache=off,open=true,write=false (0.19s) --- FAIL: TestFileSetModTime/cache=off,open=true,write=true (0.19s) --- FAIL: TestFileSetModTime/cache=full,open=false,write=false (0.20s) --- FAIL: TestFileSetModTime/cache=full,open=true,write=false (0.19s) --- FAIL: TestFileSetModTime/cache=full,open=true,write=true (0.20s) 2025/11/28 02:36:45 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestFileOpenRead run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:45 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:45 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:45 DEBUG : Looking for writers 2025/11/28 02:36:45 DEBUG : >WaitForWriters: --- FAIL: TestFileOpenRead (0.21s) === RUN TestFileOpenWrite run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:45 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:45 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:45 DEBUG : Looking for writers 2025/11/28 02:36:45 DEBUG : >WaitForWriters: --- FAIL: TestFileOpenWrite (0.20s) === RUN TestFileRemove run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:45 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:45 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:45 DEBUG : Looking for writers 2025/11/28 02:36:45 DEBUG : >WaitForWriters: --- FAIL: TestFileRemove (0.24s) === RUN TestFileRemoveAll run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:45 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:45 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:45 DEBUG : Looking for writers 2025/11/28 02:36:45 DEBUG : >WaitForWriters: --- FAIL: TestFileRemoveAll (0.20s) === RUN TestFileOpen run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:45 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:46 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:46 DEBUG : Looking for writers 2025/11/28 02:36:46 DEBUG : >WaitForWriters: --- FAIL: TestFileOpen (0.19s) === RUN TestFileRename === RUN TestFileRename/off,forceCache=false run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:46 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:46 DEBUG : Looking for writers 2025/11/28 02:36:46 DEBUG : >WaitForWriters: === RUN TestFileRename/minimal,forceCache=false run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:46 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:46 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:46 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:46 DEBUG : Looking for writers 2025/11/28 02:36:46 DEBUG : >WaitForWriters: === RUN TestFileRename/minimal,forceCache=true run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting 2025/11/28 02:36:46 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:46 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:46 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:46 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:46 DEBUG : Looking for writers 2025/11/28 02:36:46 DEBUG : >WaitForWriters: 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=false run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:46 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:46 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:46 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:46 DEBUG : Looking for writers 2025/11/28 02:36:46 DEBUG : >WaitForWriters: 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestFileRename/writes,forceCache=true run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:46 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:46 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:46 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:47 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:47 DEBUG : Looking for writers 2025/11/28 02:36:47 DEBUG : >WaitForWriters: 2025/11/28 02:36:47 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestFileRename/full,forceCache=false run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:47 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:47 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:47 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:47 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:47 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:47 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:47 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:47 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:47 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:47 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:47 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:47 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:47 DEBUG : Looking for writers 2025/11/28 02:36:47 DEBUG : >WaitForWriters: --- FAIL: TestFileRename (1.28s) --- FAIL: TestFileRename/off,forceCache=false (0.20s) --- FAIL: TestFileRename/minimal,forceCache=false (0.20s) --- FAIL: TestFileRename/minimal,forceCache=true (0.20s) --- FAIL: TestFileRename/writes,forceCache=false (0.19s) --- FAIL: TestFileRename/writes,forceCache=true (0.28s) --- FAIL: TestFileRename/full,forceCache=false (0.20s) 2025/11/28 02:36:47 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestReadFileHandleMethods run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:47 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:47 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:47 DEBUG : Looking for writers 2025/11/28 02:36:47 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleMethods (0.19s) === RUN TestReadFileHandleSeek run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:47 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:47 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:47 DEBUG : Looking for writers 2025/11/28 02:36:47 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleSeek (0.19s) === RUN TestReadFileHandleReadAt run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:47 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:48 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:48 DEBUG : Looking for writers 2025/11/28 02:36:48 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleReadAt (0.20s) === RUN TestReadFileHandleFlush run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:48 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:48 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:48 DEBUG : Looking for writers 2025/11/28 02:36:48 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleFlush (0.21s) === RUN TestReadFileHandleRelease run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:48 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:48 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:48 DEBUG : Looking for writers 2025/11/28 02:36:48 DEBUG : >WaitForWriters: --- FAIL: TestReadFileHandleRelease (0.22s) === RUN TestRWFileHandleMethodsRead run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:48 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:48 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:48 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:48 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:48 DEBUG : Looking for writers 2025/11/28 02:36:48 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleMethodsRead (0.19s) 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestRWFileHandleSeek run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:48 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:48 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:48 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:48 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:48 DEBUG : Looking for writers 2025/11/28 02:36:48 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleSeek (0.20s) === RUN TestRWFileHandleReadAt run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:48 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:48 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting 2025/11/28 02:36:48 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:48 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:48 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:49 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleReadAt (0.19s) === RUN TestRWFileHandleFlushRead run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:49 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting 2025/11/28 02:36:49 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:49 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:49 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleFlushRead (0.19s) === RUN TestRWFileHandleReleaseRead run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:49 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting 2025/11/28 02:36:49 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:49 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:49 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : >WaitForWriters: 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting --- FAIL: TestRWFileHandleReleaseRead (0.20s) === RUN TestRWFileHandleMethodsWrite run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:36:49 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:49 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:36:49 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:36:49 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:36:49 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:36:49 DEBUG : file1: newRWFileHandle: 2025/11/28 02:36:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2025/11/28 02:36:49 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): openPending: 2025/11/28 02:36:49 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct) 2025/11/28 02:36:49 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): >openPending: err= 2025/11/28 02:36:49 DEBUG : file1: >newRWFileHandle: err= 2025/11/28 02:36:49 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:36:49 DEBUG : file1: >Open: fd=file1 (rw), err= 2025/11/28 02:36:49 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): _writeAt: size=5, off=0 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): >_writeAt: n=5, err= 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): _writeAt: size=7, off=5 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): >_writeAt: n=7, err= 2025/11/28 02:36:49 DEBUG : file1: vfs cache: truncate to size=11 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): close: 2025/11/28 02:36:49 DEBUG : file1: vfs cache: setting modification time to 2025-11-28 02:36:49.463086192 +0000 UTC m=+10.631114630 2025/11/28 02:36:49 INFO : file1: vfs cache: queuing for upload in 100ms 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): >close: err= 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): close: 2025/11/28 02:36:49 DEBUG : file1(0xc0000b19c0): >close: err=file already closed 2025/11/28 02:36:49 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : file1: reading active writers 2025/11/28 02:36:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : file1: reading active writers 2025/11/28 02:36:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : file1: reading active writers 2025/11/28 02:36:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : file1: reading active writers 2025/11/28 02:36:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2025/11/28 02:36:49 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : file1: reading active writers 2025/11/28 02:36:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2025/11/28 02:36:49 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:49 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:49 DEBUG : Looking for writers 2025/11/28 02:36:49 DEBUG : file1: reading active writers 2025/11/28 02:36:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2025/11/28 02:36:49 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:36:50 DEBUG : Looking for writers 2025/11/28 02:36:50 DEBUG : file1: reading active writers 2025/11/28 02:36:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2025/11/28 02:36:50 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:50 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:50 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:36:50 DEBUG : Looking for writers 2025/11/28 02:36:50 DEBUG : file1: reading active writers 2025/11/28 02:36:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:50 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:50 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:51 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:36:51 DEBUG : Looking for writers 2025/11/28 02:36:51 DEBUG : file1: reading active writers 2025/11/28 02:36:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:51 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:51 ERROR : file1: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:52 DEBUG : Looking for writers 2025/11/28 02:36:52 DEBUG : file1: reading active writers 2025/11/28 02:36:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:53 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:36:53 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:53 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:53 DEBUG : Looking for writers 2025/11/28 02:36:53 DEBUG : file1: reading active writers 2025/11/28 02:36:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:54 DEBUG : Looking for writers 2025/11/28 02:36:54 DEBUG : file1: reading active writers 2025/11/28 02:36:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:55 DEBUG : Looking for writers 2025/11/28 02:36:55 DEBUG : file1: reading active writers 2025/11/28 02:36:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:56 DEBUG : Looking for writers 2025/11/28 02:36:56 DEBUG : file1: reading active writers 2025/11/28 02:36:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:56 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:36:56 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:56 ERROR : file1: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:36:57 DEBUG : Looking for writers 2025/11/28 02:36:57 DEBUG : file1: reading active writers 2025/11/28 02:36:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:58 DEBUG : Looking for writers 2025/11/28 02:36:58 DEBUG : file1: reading active writers 2025/11/28 02:36:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:36:59 DEBUG : Looking for writers 2025/11/28 02:36:59 DEBUG : file1: reading active writers 2025/11/28 02:36:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:00 DEBUG : Looking for writers 2025/11/28 02:37:00 DEBUG : file1: reading active writers 2025/11/28 02:37:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:01 DEBUG : Looking for writers 2025/11/28 02:37:01 DEBUG : file1: reading active writers 2025/11/28 02:37:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:02 DEBUG : Looking for writers 2025/11/28 02:37:02 DEBUG : file1: reading active writers 2025/11/28 02:37:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:03 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:37:03 DEBUG : Looking for writers 2025/11/28 02:37:03 DEBUG : file1: reading active writers 2025/11/28 02:37:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:03 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:37:03 ERROR : file1: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:37:04 DEBUG : Looking for writers 2025/11/28 02:37:04 DEBUG : file1: reading active writers 2025/11/28 02:37:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:05 DEBUG : Looking for writers 2025/11/28 02:37:05 DEBUG : file1: reading active writers 2025/11/28 02:37:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:06 DEBUG : Looking for writers 2025/11/28 02:37:06 DEBUG : file1: reading active writers 2025/11/28 02:37:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:07 DEBUG : Looking for writers 2025/11/28 02:37:07 DEBUG : file1: reading active writers 2025/11/28 02:37:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:08 DEBUG : Looking for writers 2025/11/28 02:37:08 DEBUG : file1: reading active writers 2025/11/28 02:37:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:09 DEBUG : Looking for writers 2025/11/28 02:37:09 DEBUG : file1: reading active writers 2025/11/28 02:37:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:10 DEBUG : Looking for writers 2025/11/28 02:37:10 DEBUG : file1: reading active writers 2025/11/28 02:37:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:11 DEBUG : Looking for writers 2025/11/28 02:37:11 DEBUG : file1: reading active writers 2025/11/28 02:37:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:12 DEBUG : Looking for writers 2025/11/28 02:37:12 DEBUG : file1: reading active writers 2025/11/28 02:37:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:13 DEBUG : Looking for writers 2025/11/28 02:37:13 DEBUG : file1: reading active writers 2025/11/28 02:37:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:14 DEBUG : Looking for writers 2025/11/28 02:37:14 DEBUG : file1: reading active writers 2025/11/28 02:37:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:15 DEBUG : Looking for writers 2025/11/28 02:37:15 DEBUG : file1: reading active writers 2025/11/28 02:37:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:16 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:37:16 DEBUG : Looking for writers 2025/11/28 02:37:16 DEBUG : file1: reading active writers 2025/11/28 02:37:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:17 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:37:17 ERROR : file1: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:37:17 DEBUG : Looking for writers 2025/11/28 02:37:17 DEBUG : file1: reading active writers 2025/11/28 02:37:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:18 DEBUG : Looking for writers 2025/11/28 02:37:18 DEBUG : file1: reading active writers 2025/11/28 02:37:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:19 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc00046d590 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc00053f608 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824639223360} name:file1 opens:0 downloaders: o: fd: info:{ModTime:{wall:13997856764949308016 ext:10631114630 loc:0x42a0c60} ATime:{wall:13997856764949355726 ext:10631162341 loc:0x42a0c60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 modified:false beingReset:false}, } 2025/11/28 02:37:19 DEBUG : >WaitForWriters: fstest.go:298: Sleeping for 1s for list eventual consistency: 1/5 fstest.go:298: Sleeping for 2s for list eventual consistency: 2/5 fstest.go:298: Sleeping for 4s for list eventual consistency: 3/5 fstest.go:298: Sleeping for 8s for list eventual consistency: 4/5 fstest.go:298: Sleeping for 16s for list eventual consistency: 5/5 2025/11/28 02:37:42 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:37:43 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:37:43 ERROR : file1: vfs cache: failed to upload try #9, will retry in 51.2s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:37:49 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2025/11/28 02:37:49 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 11 (was 11) fstest.go:305: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:337 Error: Should be true Test: TestRWFileHandleMethodsWrite Messages: listing wrong, want file1 (11) got fstest.go:203: Not found "file1" fstest.go:206: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:206 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:310 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:337 Error: Not equal: expected: 0 actual : 1 Test: TestRWFileHandleMethodsWrite Messages: 1 objects not found 2025/11/28 02:37:50 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:37:50 DEBUG : Looking for writers 2025/11/28 02:37:50 DEBUG : file1: reading active writers 2025/11/28 02:37:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2025/11/28 02:37:50 DEBUG : Looking for writers 2025/11/28 02:37:50 DEBUG : file1: reading active writers 2025/11/28 02:37:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2025/11/28 02:37:50 DEBUG : Looking for writers 2025/11/28 02:37:50 DEBUG : file1: reading active writers 2025/11/28 02:37:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2025/11/28 02:37:50 DEBUG : Looking for writers 2025/11/28 02:37:50 DEBUG : file1: reading active writers 2025/11/28 02:37:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2025/11/28 02:37:50 DEBUG : Looking for writers 2025/11/28 02:37:50 DEBUG : file1: reading active writers 2025/11/28 02:37:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2025/11/28 02:37:50 DEBUG : Looking for writers 2025/11/28 02:37:50 DEBUG : file1: reading active writers 2025/11/28 02:37:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2025/11/28 02:37:51 DEBUG : Looking for writers 2025/11/28 02:37:51 DEBUG : file1: reading active writers 2025/11/28 02:37:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2025/11/28 02:37:51 DEBUG : Looking for writers 2025/11/28 02:37:51 DEBUG : file1: reading active writers 2025/11/28 02:37:51 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:52 DEBUG : Looking for writers 2025/11/28 02:37:52 DEBUG : file1: reading active writers 2025/11/28 02:37:52 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:53 DEBUG : Looking for writers 2025/11/28 02:37:53 DEBUG : file1: reading active writers 2025/11/28 02:37:53 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:54 DEBUG : Looking for writers 2025/11/28 02:37:54 DEBUG : file1: reading active writers 2025/11/28 02:37:54 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:55 DEBUG : Looking for writers 2025/11/28 02:37:55 DEBUG : file1: reading active writers 2025/11/28 02:37:55 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:56 DEBUG : Looking for writers 2025/11/28 02:37:56 DEBUG : file1: reading active writers 2025/11/28 02:37:56 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:57 DEBUG : Looking for writers 2025/11/28 02:37:57 DEBUG : file1: reading active writers 2025/11/28 02:37:57 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:58 DEBUG : Looking for writers 2025/11/28 02:37:58 DEBUG : file1: reading active writers 2025/11/28 02:37:58 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:37:59 DEBUG : Looking for writers 2025/11/28 02:37:59 DEBUG : file1: reading active writers 2025/11/28 02:37:59 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:00 DEBUG : Looking for writers 2025/11/28 02:38:00 DEBUG : file1: reading active writers 2025/11/28 02:38:00 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:01 DEBUG : Looking for writers 2025/11/28 02:38:01 DEBUG : file1: reading active writers 2025/11/28 02:38:01 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:02 DEBUG : Looking for writers 2025/11/28 02:38:02 DEBUG : file1: reading active writers 2025/11/28 02:38:02 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:03 DEBUG : Looking for writers 2025/11/28 02:38:03 DEBUG : file1: reading active writers 2025/11/28 02:38:03 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:04 DEBUG : Looking for writers 2025/11/28 02:38:04 DEBUG : file1: reading active writers 2025/11/28 02:38:04 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:05 DEBUG : Looking for writers 2025/11/28 02:38:05 DEBUG : file1: reading active writers 2025/11/28 02:38:05 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:06 DEBUG : Looking for writers 2025/11/28 02:38:06 DEBUG : file1: reading active writers 2025/11/28 02:38:06 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:07 DEBUG : Looking for writers 2025/11/28 02:38:07 DEBUG : file1: reading active writers 2025/11/28 02:38:07 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:08 DEBUG : Looking for writers 2025/11/28 02:38:08 DEBUG : file1: reading active writers 2025/11/28 02:38:08 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:09 DEBUG : Looking for writers 2025/11/28 02:38:09 DEBUG : file1: reading active writers 2025/11/28 02:38:09 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:10 DEBUG : Looking for writers 2025/11/28 02:38:10 DEBUG : file1: reading active writers 2025/11/28 02:38:10 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:11 DEBUG : Looking for writers 2025/11/28 02:38:11 DEBUG : file1: reading active writers 2025/11/28 02:38:11 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:12 DEBUG : Looking for writers 2025/11/28 02:38:12 DEBUG : file1: reading active writers 2025/11/28 02:38:12 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:13 DEBUG : Looking for writers 2025/11/28 02:38:13 DEBUG : file1: reading active writers 2025/11/28 02:38:13 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:14 DEBUG : Looking for writers 2025/11/28 02:38:14 DEBUG : file1: reading active writers 2025/11/28 02:38:14 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:15 DEBUG : Looking for writers 2025/11/28 02:38:15 DEBUG : file1: reading active writers 2025/11/28 02:38:15 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:16 DEBUG : Looking for writers 2025/11/28 02:38:16 DEBUG : file1: reading active writers 2025/11/28 02:38:16 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:17 DEBUG : Looking for writers 2025/11/28 02:38:17 DEBUG : file1: reading active writers 2025/11/28 02:38:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:18 DEBUG : Looking for writers 2025/11/28 02:38:18 DEBUG : file1: reading active writers 2025/11/28 02:38:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:19 DEBUG : Looking for writers 2025/11/28 02:38:19 DEBUG : file1: reading active writers 2025/11/28 02:38:19 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:20 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc00046d590 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc00053f608 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824639223360} name:file1 opens:0 downloaders: o: fd: info:{ModTime:{wall:13997856764949308016 ext:10631114630 loc:0x42a0c60} ATime:{wall:13997856764949355726 ext:10631162341 loc:0x42a0c60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 modified:false beingReset:false}, } 2025/11/28 02:38:20 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleMethodsWrite (91.02s) === RUN TestRWFileHandleWriteAt 2025/11/28 02:38:20 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:38:20 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:38:20 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:38:20 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:38:20 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:38:20 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:38:20 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:38:20 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:38:20 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:38:20 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:38:20 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:38:20 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:38:20 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:38:20 DEBUG : file1: newRWFileHandle: 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): openPending: 2025/11/28 02:38:20 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct) 2025/11/28 02:38:20 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2025/11/28 02:38:20 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 0 (was 0) 2025/11/28 02:38:20 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): >openPending: err= 2025/11/28 02:38:20 DEBUG : file1: >newRWFileHandle: err= 2025/11/28 02:38:20 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:38:20 DEBUG : file1: >Open: fd=file1 (rw), err= 2025/11/28 02:38:20 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): _writeAt: size=7, off=0 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): >_writeAt: n=7, err= 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): _writeAt: size=6, off=5 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): >_writeAt: n=6, err= 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): close: 2025/11/28 02:38:20 DEBUG : file1: vfs cache: setting modification time to 2025-11-28 02:38:20.483144339 +0000 UTC m=+101.651172798 2025/11/28 02:38:20 INFO : file1: vfs cache: queuing for upload in 100ms 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): >close: err= 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): _writeAt: size=5, off=0 2025/11/28 02:38:20 DEBUG : file1(0xc0006b78c0): >_writeAt: n=0, err=file already closed 2025/11/28 02:38:20 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:38:20 DEBUG : Looking for writers 2025/11/28 02:38:20 DEBUG : file1: reading active writers 2025/11/28 02:38:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2025/11/28 02:38:20 DEBUG : Looking for writers 2025/11/28 02:38:20 DEBUG : file1: reading active writers 2025/11/28 02:38:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2025/11/28 02:38:20 DEBUG : Looking for writers 2025/11/28 02:38:20 DEBUG : file1: reading active writers 2025/11/28 02:38:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2025/11/28 02:38:20 DEBUG : Looking for writers 2025/11/28 02:38:20 DEBUG : file1: reading active writers 2025/11/28 02:38:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2025/11/28 02:38:20 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:38:20 DEBUG : Looking for writers 2025/11/28 02:38:20 DEBUG : file1: reading active writers 2025/11/28 02:38:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2025/11/28 02:38:20 DEBUG : Looking for writers 2025/11/28 02:38:20 DEBUG : file1: reading active writers 2025/11/28 02:38:20 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2025/11/28 02:38:21 DEBUG : Looking for writers 2025/11/28 02:38:21 DEBUG : file1: reading active writers 2025/11/28 02:38:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2025/11/28 02:38:21 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:21 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:21 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:38:21 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:21 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:21 DEBUG : Looking for writers 2025/11/28 02:38:21 DEBUG : file1: reading active writers 2025/11/28 02:38:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:21 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:38:22 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:22 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:22 DEBUG : Looking for writers 2025/11/28 02:38:22 DEBUG : file1: reading active writers 2025/11/28 02:38:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:22 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:38:23 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38: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: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:23 DEBUG : Looking for writers 2025/11/28 02:38:23 DEBUG : file1: reading active writers 2025/11/28 02:38:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:24 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:38:24 DEBUG : Looking for writers 2025/11/28 02:38:24 DEBUG : file1: reading active writers 2025/11/28 02:38:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:24 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:24 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:25 DEBUG : Looking for writers 2025/11/28 02:38:25 DEBUG : file1: reading active writers 2025/11/28 02:38:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:26 DEBUG : Looking for writers 2025/11/28 02:38:26 DEBUG : file1: reading active writers 2025/11/28 02:38:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:27 DEBUG : Looking for writers 2025/11/28 02:38:27 DEBUG : file1: reading active writers 2025/11/28 02:38:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:28 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:38:28 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38: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: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:28 DEBUG : Looking for writers 2025/11/28 02:38:28 DEBUG : file1: reading active writers 2025/11/28 02:38:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:29 DEBUG : Looking for writers 2025/11/28 02:38:29 DEBUG : file1: reading active writers 2025/11/28 02:38:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:30 DEBUG : Looking for writers 2025/11/28 02:38:30 DEBUG : file1: reading active writers 2025/11/28 02:38:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:31 DEBUG : Looking for writers 2025/11/28 02:38:31 DEBUG : file1: reading active writers 2025/11/28 02:38:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:32 DEBUG : Looking for writers 2025/11/28 02:38:32 DEBUG : file1: reading active writers 2025/11/28 02:38:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:33 DEBUG : Looking for writers 2025/11/28 02:38:33 DEBUG : file1: reading active writers 2025/11/28 02:38:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:34 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:38:34 DEBUG : Looking for writers 2025/11/28 02:38:34 DEBUG : file1: reading active writers 2025/11/28 02:38:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:35 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38: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: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:35 DEBUG : Looking for writers 2025/11/28 02:38:35 DEBUG : file1: reading active writers 2025/11/28 02:38:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:36 DEBUG : Looking for writers 2025/11/28 02:38:36 DEBUG : file1: reading active writers 2025/11/28 02:38:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:37 DEBUG : Looking for writers 2025/11/28 02:38:37 DEBUG : file1: reading active writers 2025/11/28 02:38:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:38 DEBUG : Looking for writers 2025/11/28 02:38:38 DEBUG : file1: reading active writers 2025/11/28 02:38:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:39 DEBUG : Looking for writers 2025/11/28 02:38:39 DEBUG : file1: reading active writers 2025/11/28 02:38:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:40 DEBUG : Looking for writers 2025/11/28 02:38:40 DEBUG : file1: reading active writers 2025/11/28 02:38:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:41 DEBUG : Looking for writers 2025/11/28 02:38:41 DEBUG : file1: reading active writers 2025/11/28 02:38:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:42 DEBUG : Looking for writers 2025/11/28 02:38:42 DEBUG : file1: reading active writers 2025/11/28 02:38:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:43 DEBUG : Looking for writers 2025/11/28 02:38:43 DEBUG : file1: reading active writers 2025/11/28 02:38:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:44 DEBUG : Looking for writers 2025/11/28 02:38:44 DEBUG : file1: reading active writers 2025/11/28 02:38:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:45 DEBUG : Looking for writers 2025/11/28 02:38:45 DEBUG : file1: reading active writers 2025/11/28 02:38:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:46 DEBUG : Looking for writers 2025/11/28 02:38:46 DEBUG : file1: reading active writers 2025/11/28 02:38:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:47 DEBUG : Looking for writers 2025/11/28 02:38:47 DEBUG : file1: reading active writers 2025/11/28 02:38:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:48 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:38:48 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38: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: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:38:48 DEBUG : Looking for writers 2025/11/28 02:38:48 DEBUG : file1: reading active writers 2025/11/28 02:38:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:49 DEBUG : Looking for writers 2025/11/28 02:38:49 DEBUG : file1: reading active writers 2025/11/28 02:38:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:38:50 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc000b07860 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc00053e508 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824639219008} name:file1 opens:0 downloaders: o: fd: info:{ModTime:{wall:13997856862679872147 ext:101651172798 loc:0x42a0c60} ATime:{wall:13997856862679900591 ext:101651201241 loc:0x42a0c60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 modified:false beingReset:false}, } 2025/11/28 02:38:50 DEBUG : >WaitForWriters: fstest.go:298: Sleeping for 1s for list eventual consistency: 1/5 fstest.go:298: Sleeping for 2s for list eventual consistency: 2/5 fstest.go:298: Sleeping for 4s for list eventual consistency: 3/5 fstest.go:298: Sleeping for 8s for list eventual consistency: 4/5 fstest.go:298: Sleeping for 16s for list eventual consistency: 5/5 2025/11/28 02:39:14 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:39:14 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39: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: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:20 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2025/11/28 02:39:20 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 1, uploading 0, total size 11 (was 11) fstest.go:305: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:387 Error: Should be true Test: TestRWFileHandleWriteAt Messages: listing wrong, want file1 (11) got fstest.go:203: Not found "file1" fstest.go:206: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:206 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:310 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:387 Error: Not equal: expected: 0 actual : 1 Test: TestRWFileHandleWriteAt Messages: 1 objects not found 2025/11/28 02:39:21 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:39:21 DEBUG : Looking for writers 2025/11/28 02:39:21 DEBUG : file1: reading active writers 2025/11/28 02:39:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2025/11/28 02:39:21 DEBUG : Looking for writers 2025/11/28 02:39:21 DEBUG : file1: reading active writers 2025/11/28 02:39:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2025/11/28 02:39:21 DEBUG : Looking for writers 2025/11/28 02:39:21 DEBUG : file1: reading active writers 2025/11/28 02:39:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2025/11/28 02:39:21 DEBUG : Looking for writers 2025/11/28 02:39:21 DEBUG : file1: reading active writers 2025/11/28 02:39:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2025/11/28 02:39:21 DEBUG : Looking for writers 2025/11/28 02:39:21 DEBUG : file1: reading active writers 2025/11/28 02:39:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2025/11/28 02:39:21 DEBUG : Looking for writers 2025/11/28 02:39:21 DEBUG : file1: reading active writers 2025/11/28 02:39:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2025/11/28 02:39:22 DEBUG : Looking for writers 2025/11/28 02:39:22 DEBUG : file1: reading active writers 2025/11/28 02:39:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2025/11/28 02:39:22 DEBUG : Looking for writers 2025/11/28 02:39:22 DEBUG : file1: reading active writers 2025/11/28 02:39:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:23 DEBUG : Looking for writers 2025/11/28 02:39:23 DEBUG : file1: reading active writers 2025/11/28 02:39:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:24 DEBUG : Looking for writers 2025/11/28 02:39:24 DEBUG : file1: reading active writers 2025/11/28 02:39:24 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:25 DEBUG : Looking for writers 2025/11/28 02:39:25 DEBUG : file1: reading active writers 2025/11/28 02:39:25 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:26 DEBUG : Looking for writers 2025/11/28 02:39:26 DEBUG : file1: reading active writers 2025/11/28 02:39:26 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:27 DEBUG : Looking for writers 2025/11/28 02:39:27 DEBUG : file1: reading active writers 2025/11/28 02:39:27 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:28 DEBUG : Looking for writers 2025/11/28 02:39:28 DEBUG : file1: reading active writers 2025/11/28 02:39:28 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:29 DEBUG : Looking for writers 2025/11/28 02:39:29 DEBUG : file1: reading active writers 2025/11/28 02:39:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:30 DEBUG : Looking for writers 2025/11/28 02:39:30 DEBUG : file1: reading active writers 2025/11/28 02:39:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:31 DEBUG : Looking for writers 2025/11/28 02:39:31 DEBUG : file1: reading active writers 2025/11/28 02:39:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:32 DEBUG : Looking for writers 2025/11/28 02:39:32 DEBUG : file1: reading active writers 2025/11/28 02:39:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:33 DEBUG : Looking for writers 2025/11/28 02:39:33 DEBUG : file1: reading active writers 2025/11/28 02:39:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:34 DEBUG : Looking for writers 2025/11/28 02:39:34 DEBUG : file1: reading active writers 2025/11/28 02:39:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:35 DEBUG : Looking for writers 2025/11/28 02:39:35 DEBUG : file1: reading active writers 2025/11/28 02:39:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:36 DEBUG : Looking for writers 2025/11/28 02:39:36 DEBUG : file1: reading active writers 2025/11/28 02:39:36 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:37 DEBUG : Looking for writers 2025/11/28 02:39:37 DEBUG : file1: reading active writers 2025/11/28 02:39:37 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:38 DEBUG : Looking for writers 2025/11/28 02:39:38 DEBUG : file1: reading active writers 2025/11/28 02:39:38 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:39 DEBUG : Looking for writers 2025/11/28 02:39:39 DEBUG : file1: reading active writers 2025/11/28 02:39:39 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:40 DEBUG : Looking for writers 2025/11/28 02:39:40 DEBUG : file1: reading active writers 2025/11/28 02:39:40 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:41 DEBUG : Looking for writers 2025/11/28 02:39:41 DEBUG : file1: reading active writers 2025/11/28 02:39:41 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:42 DEBUG : Looking for writers 2025/11/28 02:39:42 DEBUG : file1: reading active writers 2025/11/28 02:39:42 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:43 DEBUG : Looking for writers 2025/11/28 02:39:43 DEBUG : file1: reading active writers 2025/11/28 02:39:43 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:44 DEBUG : Looking for writers 2025/11/28 02:39:44 DEBUG : file1: reading active writers 2025/11/28 02:39:44 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:45 DEBUG : Looking for writers 2025/11/28 02:39:45 DEBUG : file1: reading active writers 2025/11/28 02:39:45 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:46 DEBUG : Looking for writers 2025/11/28 02:39:46 DEBUG : file1: reading active writers 2025/11/28 02:39:46 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:47 DEBUG : Looking for writers 2025/11/28 02:39:47 DEBUG : file1: reading active writers 2025/11/28 02:39:47 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:48 DEBUG : Looking for writers 2025/11/28 02:39:48 DEBUG : file1: reading active writers 2025/11/28 02:39:48 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:49 DEBUG : Looking for writers 2025/11/28 02:39:49 DEBUG : file1: reading active writers 2025/11/28 02:39:49 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:50 DEBUG : Looking for writers 2025/11/28 02:39:50 DEBUG : file1: reading active writers 2025/11/28 02:39:50 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:39:51 ERROR : Exiting even though 0 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc000b07860 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc00053e508 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824639219008} name:file1 opens:0 downloaders: o: fd: info:{ModTime:{wall:13997856862679872147 ext:101651172798 loc:0x42a0c60} ATime:{wall:13997856862679900591 ext:101651201241 loc:0x42a0c60} Size:11 Rs:[{Pos:0 Size:11}] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 modified:false beingReset:false}, } 2025/11/28 02:39:51 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleWriteAt (91.02s) 2025/11/28 02:39:51 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestRWFileHandleWriteNoWrite run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:39:51 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:39:51 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:39:51 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:39:51 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:39:51 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:39:51 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:39:51 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:39:51 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:39:51 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:39:51 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:39:51 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:39:51 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:39:51 DEBUG : file1: newRWFileHandle: 2025/11/28 02:39:51 DEBUG : file1(0xc0006b1100): openPending: 2025/11/28 02:39:51 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2025/11/28 02:39:51 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct) 2025/11/28 02:39:51 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 1 (was 1) in use 1, to upload 0, uploading 0, total size 0 (was 0) 2025/11/28 02:39:51 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:39:51 DEBUG : file1(0xc0006b1100): >openPending: err= 2025/11/28 02:39:51 DEBUG : file1: >newRWFileHandle: err= 2025/11/28 02:39:51 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:39:51 DEBUG : file1: >Open: fd=file1 (rw), err= 2025/11/28 02:39:51 DEBUG : file1: >OpenFile: fd=file1 (rw), err= 2025/11/28 02:39:51 DEBUG : file1(0xc0006b1100): close: 2025/11/28 02:39:51 DEBUG : file1: vfs cache: setting modification time to 2025-11-28 02:39:51.502273161 +0000 UTC m=+192.670301620 2025/11/28 02:39:51 INFO : file1: vfs cache: queuing for upload in 100ms 2025/11/28 02:39:51 DEBUG : file1(0xc0006b1100): >close: err= 2025/11/28 02:39:51 DEBUG : file2: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx 2025/11/28 02:39:51 DEBUG : file2: Open: flags=O_WRONLY|O_CREATE|O_TRUNC 2025/11/28 02:39:51 DEBUG : file2: newRWFileHandle: 2025/11/28 02:39:51 DEBUG : file2(0xc0006b1600): openPending: 2025/11/28 02:39:51 DEBUG : file2: vfs cache: truncate to size=0 (not needed as size correct) 2025/11/28 02:39:51 DEBUG : Added virtual directory entry vAddFile: "file2" 2025/11/28 02:39:51 DEBUG : file2(0xc0006b1600): >openPending: err= 2025/11/28 02:39:51 DEBUG : file2: >newRWFileHandle: err= 2025/11/28 02:39:51 DEBUG : Added virtual directory entry vAddFile: "file2" 2025/11/28 02:39:51 DEBUG : file2: >Open: fd=file2 (rw), err= 2025/11/28 02:39:51 DEBUG : file2: >OpenFile: fd=file2 (rw), err= 2025/11/28 02:39:51 DEBUG : file2(0xc0006b1600): RWFileHandle.Flush 2025/11/28 02:39:51 DEBUG : file2(0xc0006b1600): RWFileHandle.Release 2025/11/28 02:39:51 DEBUG : file2(0xc0006b1600): close: 2025/11/28 02:39:51 DEBUG : file2: vfs cache: setting modification time to 2025-11-28 02:39:51.504269053 +0000 UTC m=+192.672297511 2025/11/28 02:39:51 INFO : file2: vfs cache: queuing for upload in 100ms 2025/11/28 02:39:51 DEBUG : file2(0xc0006b1600): >close: err= 2025/11/28 02:39:51 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:39:51 DEBUG : Looking for writers 2025/11/28 02:39:51 DEBUG : file1: reading active writers 2025/11/28 02:39:51 DEBUG : file2: reading active writers 2025/11/28 02:39:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2025/11/28 02:39:51 DEBUG : Looking for writers 2025/11/28 02:39:51 DEBUG : file1: reading active writers 2025/11/28 02:39:51 DEBUG : file2: reading active writers 2025/11/28 02:39:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2025/11/28 02:39:51 DEBUG : Looking for writers 2025/11/28 02:39:51 DEBUG : file2: reading active writers 2025/11/28 02:39:51 DEBUG : file1: reading active writers 2025/11/28 02:39:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2025/11/28 02:39:51 DEBUG : Looking for writers 2025/11/28 02:39:51 DEBUG : file1: reading active writers 2025/11/28 02:39:51 DEBUG : file2: reading active writers 2025/11/28 02:39:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2025/11/28 02:39:51 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:39:51 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:39:51 DEBUG : Looking for writers 2025/11/28 02:39:51 DEBUG : file1: reading active writers 2025/11/28 02:39:51 DEBUG : file2: reading active writers 2025/11/28 02:39:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2025/11/28 02:39:51 DEBUG : Looking for writers 2025/11/28 02:39:51 DEBUG : file1: reading active writers 2025/11/28 02:39:51 DEBUG : file2: reading active writers 2025/11/28 02:39:51 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2025/11/28 02:39:52 DEBUG : Looking for writers 2025/11/28 02:39:52 DEBUG : file1: reading active writers 2025/11/28 02:39:52 DEBUG : file2: reading active writers 2025/11/28 02:39:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2025/11/28 02:39:52 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:52 ERROR : file1: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:52 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:52 ERROR : file2: vfs cache: failed to upload try #1, will retry in 200ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:52 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:39:52 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:39:52 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:52 ERROR : file1: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:52 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:52 ERROR : file2: vfs cache: failed to upload try #2, will retry in 400ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:52 DEBUG : Looking for writers 2025/11/28 02:39:52 DEBUG : file1: reading active writers 2025/11/28 02:39:52 DEBUG : file2: reading active writers 2025/11/28 02:39:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:39:52 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:39:53 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:39:53 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:53 ERROR : file1: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:53 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:53 ERROR : file2: vfs cache: failed to upload try #3, will retry in 800ms: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:53 DEBUG : Looking for writers 2025/11/28 02:39:53 DEBUG : file1: reading active writers 2025/11/28 02:39:53 DEBUG : file2: reading active writers 2025/11/28 02:39:53 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:39:53 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:39:54 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:39:54 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:54 ERROR : file1: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:54 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:54 ERROR : file2: vfs cache: failed to upload try #4, will retry in 1.6s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:54 DEBUG : Looking for writers 2025/11/28 02:39:54 DEBUG : file1: reading active writers 2025/11/28 02:39:54 DEBUG : file2: reading active writers 2025/11/28 02:39:54 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:39:55 DEBUG : Looking for writers 2025/11/28 02:39:55 DEBUG : file1: reading active writers 2025/11/28 02:39:55 DEBUG : file2: reading active writers 2025/11/28 02:39:55 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:39:55 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:39:56 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:56 ERROR : file1: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:56 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:39:56 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:56 ERROR : file2: vfs cache: failed to upload try #5, will retry in 3.2s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:56 DEBUG : Looking for writers 2025/11/28 02:39:56 DEBUG : file1: reading active writers 2025/11/28 02:39:56 DEBUG : file2: reading active writers 2025/11/28 02:39:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:39:57 DEBUG : Looking for writers 2025/11/28 02:39:57 DEBUG : file2: reading active writers 2025/11/28 02:39:57 DEBUG : file1: reading active writers 2025/11/28 02:39:57 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:39:58 DEBUG : Looking for writers 2025/11/28 02:39:58 DEBUG : file2: reading active writers 2025/11/28 02:39:58 DEBUG : file1: reading active writers 2025/11/28 02:39:58 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:39:59 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:39:59 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:59 ERROR : file1: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:59 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:39:59 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:59 ERROR : file2: vfs cache: failed to upload try #6, will retry in 6.4s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:39:59 DEBUG : Looking for writers 2025/11/28 02:39:59 DEBUG : file2: reading active writers 2025/11/28 02:39:59 DEBUG : file1: reading active writers 2025/11/28 02:39:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:00 DEBUG : Looking for writers 2025/11/28 02:40:00 DEBUG : file1: reading active writers 2025/11/28 02:40:00 DEBUG : file2: reading active writers 2025/11/28 02:40:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:01 DEBUG : Looking for writers 2025/11/28 02:40:01 DEBUG : file2: reading active writers 2025/11/28 02:40:01 DEBUG : file1: reading active writers 2025/11/28 02:40:01 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:02 DEBUG : Looking for writers 2025/11/28 02:40:02 DEBUG : file1: reading active writers 2025/11/28 02:40:02 DEBUG : file2: reading active writers 2025/11/28 02:40:02 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:03 DEBUG : Looking for writers 2025/11/28 02:40:03 DEBUG : file1: reading active writers 2025/11/28 02:40:03 DEBUG : file2: reading active writers 2025/11/28 02:40:03 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:04 DEBUG : Looking for writers 2025/11/28 02:40:04 DEBUG : file1: reading active writers 2025/11/28 02:40:04 DEBUG : file2: reading active writers 2025/11/28 02:40:04 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:05 DEBUG : Looking for writers 2025/11/28 02:40:05 DEBUG : file1: reading active writers 2025/11/28 02:40:05 DEBUG : file2: reading active writers 2025/11/28 02:40:05 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:05 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:40:06 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:40:06 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:06 ERROR : file1: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:06 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:06 ERROR : file2: vfs cache: failed to upload try #7, will retry in 12.8s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:06 DEBUG : Looking for writers 2025/11/28 02:40:06 DEBUG : file1: reading active writers 2025/11/28 02:40:06 DEBUG : file2: reading active writers 2025/11/28 02:40:06 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:07 DEBUG : Looking for writers 2025/11/28 02:40:07 DEBUG : file1: reading active writers 2025/11/28 02:40:07 DEBUG : file2: reading active writers 2025/11/28 02:40:07 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:08 DEBUG : Looking for writers 2025/11/28 02:40:08 DEBUG : file1: reading active writers 2025/11/28 02:40:08 DEBUG : file2: reading active writers 2025/11/28 02:40:08 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:09 DEBUG : Looking for writers 2025/11/28 02:40:09 DEBUG : file1: reading active writers 2025/11/28 02:40:09 DEBUG : file2: reading active writers 2025/11/28 02:40:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:10 DEBUG : Looking for writers 2025/11/28 02:40:10 DEBUG : file1: reading active writers 2025/11/28 02:40:10 DEBUG : file2: reading active writers 2025/11/28 02:40:10 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:11 DEBUG : Looking for writers 2025/11/28 02:40:11 DEBUG : file1: reading active writers 2025/11/28 02:40:11 DEBUG : file2: reading active writers 2025/11/28 02:40:11 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:12 DEBUG : Looking for writers 2025/11/28 02:40:12 DEBUG : file1: reading active writers 2025/11/28 02:40:12 DEBUG : file2: reading active writers 2025/11/28 02:40:12 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:13 DEBUG : Looking for writers 2025/11/28 02:40:13 DEBUG : file1: reading active writers 2025/11/28 02:40:13 DEBUG : file2: reading active writers 2025/11/28 02:40:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:14 DEBUG : Looking for writers 2025/11/28 02:40:14 DEBUG : file1: reading active writers 2025/11/28 02:40:14 DEBUG : file2: reading active writers 2025/11/28 02:40:14 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:15 DEBUG : Looking for writers 2025/11/28 02:40:15 DEBUG : file1: reading active writers 2025/11/28 02:40:15 DEBUG : file2: reading active writers 2025/11/28 02:40:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:16 DEBUG : Looking for writers 2025/11/28 02:40:16 DEBUG : file2: reading active writers 2025/11/28 02:40:16 DEBUG : file1: reading active writers 2025/11/28 02:40:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:17 DEBUG : Looking for writers 2025/11/28 02:40:17 DEBUG : file1: reading active writers 2025/11/28 02:40:17 DEBUG : file2: reading active writers 2025/11/28 02:40:17 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:18 DEBUG : Looking for writers 2025/11/28 02:40:18 DEBUG : file1: reading active writers 2025/11/28 02:40:18 DEBUG : file2: reading active writers 2025/11/28 02:40:18 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:19 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:40:19 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:40:19 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:19 ERROR : file1: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:19 DEBUG : Looking for writers 2025/11/28 02:40:19 DEBUG : file1: reading active writers 2025/11/28 02:40:19 DEBUG : file2: reading active writers 2025/11/28 02:40:19 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:19 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:19 ERROR : file2: vfs cache: failed to upload try #8, will retry in 25.6s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:20 DEBUG : Looking for writers 2025/11/28 02:40:20 DEBUG : file1: reading active writers 2025/11/28 02:40:20 DEBUG : file2: reading active writers 2025/11/28 02:40:20 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:21 ERROR : Exiting even though 0 writers active and 2 cache items in use after 30s Cache{ "file1": &{c:0xc000a8e690 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc00053e908 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824639220032} name:file1 opens:0 downloaders: o: fd: info:{ModTime:{wall:13997856960409506953 ext:192670301620 loc:0x42a0c60} ATime:{wall:13997856960409935281 ext:192670729937 loc:0x42a0c60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 modified:false beingReset:false}, "file2": &{c:0xc000a8e690 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc00053ea08 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824639220288} name:file2 opens:0 downloaders: o: fd: info:{ModTime:{wall:13997856960411502845 ext:192672297511 loc:0x42a0c60} ATime:{wall:13997856960411845021 ext:192672639687 loc:0x42a0c60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 modified:false beingReset:false}, } 2025/11/28 02:40:21 DEBUG : >WaitForWriters: fstest.go:298: Sleeping for 1s for list eventual consistency: 1/5 fstest.go:298: Sleeping for 2s for list eventual consistency: 2/5 fstest.go:298: Sleeping for 4s for list eventual consistency: 3/5 fstest.go:298: Sleeping for 8s for list eventual consistency: 4/5 fstest.go:298: Sleeping for 16s for list eventual consistency: 5/5 2025/11/28 02:40:45 DEBUG : file1: vfs cache: starting upload 2025/11/28 02:40:45 DEBUG : file2: vfs cache: starting upload 2025/11/28 02:40:45 ERROR : file1: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:45 ERROR : file1: vfs cache: failed to upload try #9, will retry in 51.2s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:46 ERROR : file2: Failed to copy: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:46 ERROR : file2: vfs cache: failed to upload try #9, will retry in 51.2s: vfs cache: failed to transfer file from cache to remote: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:40:51 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file1 not removed, freed 0 bytes 2025/11/28 02:40:51 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item file2 not removed, freed 0 bytes 2025/11/28 02:40:51 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 2 (was 2) in use 2, to upload 2, uploading 0, total size 0 (was 0) fstest.go:305: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:420 Error: Should be true Test: TestRWFileHandleWriteNoWrite Messages: listing wrong, want file1 (0), file2 (0) got fstest.go:203: Not found "file2" fstest.go:203: Not found "file1" fstest.go:206: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:206 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:310 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:420 Error: Not equal: expected: 0 actual : 2 Test: TestRWFileHandleWriteNoWrite Messages: 2 objects not found 2025/11/28 02:40:52 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:40:52 DEBUG : Looking for writers 2025/11/28 02:40:52 DEBUG : file2: reading active writers 2025/11/28 02:40:52 DEBUG : file1: reading active writers 2025/11/28 02:40:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 10ms 2025/11/28 02:40:52 DEBUG : Looking for writers 2025/11/28 02:40:52 DEBUG : file1: reading active writers 2025/11/28 02:40:52 DEBUG : file2: reading active writers 2025/11/28 02:40:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 20ms 2025/11/28 02:40:52 DEBUG : Looking for writers 2025/11/28 02:40:52 DEBUG : file2: reading active writers 2025/11/28 02:40:52 DEBUG : file1: reading active writers 2025/11/28 02:40:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 40ms 2025/11/28 02:40:52 DEBUG : Looking for writers 2025/11/28 02:40:52 DEBUG : file2: reading active writers 2025/11/28 02:40:52 DEBUG : file1: reading active writers 2025/11/28 02:40:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 80ms 2025/11/28 02:40:52 DEBUG : Looking for writers 2025/11/28 02:40:52 DEBUG : file1: reading active writers 2025/11/28 02:40:52 DEBUG : file2: reading active writers 2025/11/28 02:40:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 160ms 2025/11/28 02:40:52 DEBUG : Looking for writers 2025/11/28 02:40:52 DEBUG : file2: reading active writers 2025/11/28 02:40:52 DEBUG : file1: reading active writers 2025/11/28 02:40:52 DEBUG : Still 0 writers active and 2 cache items in use, waiting 320ms 2025/11/28 02:40:53 DEBUG : Looking for writers 2025/11/28 02:40:53 DEBUG : file2: reading active writers 2025/11/28 02:40:53 DEBUG : file1: reading active writers 2025/11/28 02:40:53 DEBUG : Still 0 writers active and 2 cache items in use, waiting 640ms 2025/11/28 02:40:53 DEBUG : Looking for writers 2025/11/28 02:40:53 DEBUG : file1: reading active writers 2025/11/28 02:40:53 DEBUG : file2: reading active writers 2025/11/28 02:40:53 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:54 DEBUG : Looking for writers 2025/11/28 02:40:54 DEBUG : file1: reading active writers 2025/11/28 02:40:54 DEBUG : file2: reading active writers 2025/11/28 02:40:54 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:55 DEBUG : Looking for writers 2025/11/28 02:40:55 DEBUG : file1: reading active writers 2025/11/28 02:40:55 DEBUG : file2: reading active writers 2025/11/28 02:40:55 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:56 DEBUG : Looking for writers 2025/11/28 02:40:56 DEBUG : file1: reading active writers 2025/11/28 02:40:56 DEBUG : file2: reading active writers 2025/11/28 02:40:56 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:57 DEBUG : Looking for writers 2025/11/28 02:40:57 DEBUG : file1: reading active writers 2025/11/28 02:40:57 DEBUG : file2: reading active writers 2025/11/28 02:40:57 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:58 DEBUG : Looking for writers 2025/11/28 02:40:58 DEBUG : file1: reading active writers 2025/11/28 02:40:58 DEBUG : file2: reading active writers 2025/11/28 02:40:58 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:40:59 DEBUG : Looking for writers 2025/11/28 02:40:59 DEBUG : file1: reading active writers 2025/11/28 02:40:59 DEBUG : file2: reading active writers 2025/11/28 02:40:59 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:00 DEBUG : Looking for writers 2025/11/28 02:41:00 DEBUG : file2: reading active writers 2025/11/28 02:41:00 DEBUG : file1: reading active writers 2025/11/28 02:41:00 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:01 DEBUG : Looking for writers 2025/11/28 02:41:01 DEBUG : file1: reading active writers 2025/11/28 02:41:01 DEBUG : file2: reading active writers 2025/11/28 02:41:01 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:02 DEBUG : Looking for writers 2025/11/28 02:41:02 DEBUG : file1: reading active writers 2025/11/28 02:41:02 DEBUG : file2: reading active writers 2025/11/28 02:41:02 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:03 DEBUG : Looking for writers 2025/11/28 02:41:03 DEBUG : file1: reading active writers 2025/11/28 02:41:03 DEBUG : file2: reading active writers 2025/11/28 02:41:03 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:04 DEBUG : Looking for writers 2025/11/28 02:41:04 DEBUG : file1: reading active writers 2025/11/28 02:41:04 DEBUG : file2: reading active writers 2025/11/28 02:41:04 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:05 DEBUG : Looking for writers 2025/11/28 02:41:05 DEBUG : file1: reading active writers 2025/11/28 02:41:05 DEBUG : file2: reading active writers 2025/11/28 02:41:05 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:06 DEBUG : Looking for writers 2025/11/28 02:41:06 DEBUG : file1: reading active writers 2025/11/28 02:41:06 DEBUG : file2: reading active writers 2025/11/28 02:41:06 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:07 DEBUG : Looking for writers 2025/11/28 02:41:07 DEBUG : file1: reading active writers 2025/11/28 02:41:07 DEBUG : file2: reading active writers 2025/11/28 02:41:07 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:08 DEBUG : Looking for writers 2025/11/28 02:41:08 DEBUG : file1: reading active writers 2025/11/28 02:41:08 DEBUG : file2: reading active writers 2025/11/28 02:41:08 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:09 DEBUG : Looking for writers 2025/11/28 02:41:09 DEBUG : file1: reading active writers 2025/11/28 02:41:09 DEBUG : file2: reading active writers 2025/11/28 02:41:09 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:10 DEBUG : Looking for writers 2025/11/28 02:41:10 DEBUG : file1: reading active writers 2025/11/28 02:41:10 DEBUG : file2: reading active writers 2025/11/28 02:41:10 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:11 DEBUG : Looking for writers 2025/11/28 02:41:11 DEBUG : file1: reading active writers 2025/11/28 02:41:11 DEBUG : file2: reading active writers 2025/11/28 02:41:11 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:12 DEBUG : Looking for writers 2025/11/28 02:41:12 DEBUG : file1: reading active writers 2025/11/28 02:41:12 DEBUG : file2: reading active writers 2025/11/28 02:41:12 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:13 DEBUG : Looking for writers 2025/11/28 02:41:13 DEBUG : file1: reading active writers 2025/11/28 02:41:13 DEBUG : file2: reading active writers 2025/11/28 02:41:13 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:14 DEBUG : Looking for writers 2025/11/28 02:41:14 DEBUG : file1: reading active writers 2025/11/28 02:41:14 DEBUG : file2: reading active writers 2025/11/28 02:41:14 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:15 DEBUG : Looking for writers 2025/11/28 02:41:15 DEBUG : file1: reading active writers 2025/11/28 02:41:15 DEBUG : file2: reading active writers 2025/11/28 02:41:15 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:16 DEBUG : Looking for writers 2025/11/28 02:41:16 DEBUG : file1: reading active writers 2025/11/28 02:41:16 DEBUG : file2: reading active writers 2025/11/28 02:41:16 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:17 DEBUG : Looking for writers 2025/11/28 02:41:17 DEBUG : file1: reading active writers 2025/11/28 02:41:17 DEBUG : file2: reading active writers 2025/11/28 02:41:17 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:18 DEBUG : Looking for writers 2025/11/28 02:41:18 DEBUG : file1: reading active writers 2025/11/28 02:41:18 DEBUG : file2: reading active writers 2025/11/28 02:41:18 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:19 DEBUG : Looking for writers 2025/11/28 02:41:19 DEBUG : file1: reading active writers 2025/11/28 02:41:19 DEBUG : file2: reading active writers 2025/11/28 02:41:19 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:20 DEBUG : Looking for writers 2025/11/28 02:41:20 DEBUG : file2: reading active writers 2025/11/28 02:41:20 DEBUG : file1: reading active writers 2025/11/28 02:41:20 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:21 DEBUG : Looking for writers 2025/11/28 02:41:21 DEBUG : file1: reading active writers 2025/11/28 02:41:21 DEBUG : file2: reading active writers 2025/11/28 02:41:21 DEBUG : Still 0 writers active and 2 cache items in use, waiting 1s 2025/11/28 02:41:22 ERROR : Exiting even though 0 writers active and 2 cache items in use after 30s Cache{ "file1": &{c:0xc000a8e690 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc00053e908 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824639220032} name:file1 opens:0 downloaders: o: fd: info:{ModTime:{wall:13997856960409506953 ext:192670301620 loc:0x42a0c60} ATime:{wall:13997856960409935281 ext:192670729937 loc:0x42a0c60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:1 pendingAccesses:0 modified:false beingReset:false}, "file2": &{c:0xc000a8e690 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc00053ea08 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824639220288} name:file2 opens:0 downloaders: o: fd: info:{ModTime:{wall:13997856960411502845 ext:192672297511 loc:0x42a0c60} ATime:{wall:13997856960411845021 ext:192672639687 loc:0x42a0c60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:2 pendingAccesses:0 modified:false beingReset:false}, } 2025/11/28 02:41:22 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleWriteNoWrite (91.02s) 2025/11/28 02:41:22 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestRWFileHandleSizeTruncateExisting run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:22 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:41:22 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:41:22 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:22 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:22 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:22 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:41:22 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:22 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:22 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:41:22 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:22 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:23 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:41:23 DEBUG : Looking for writers 2025/11/28 02:41:23 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleSizeTruncateExisting (0.57s) === RUN TestRWFileHandleSizeCreateExisting 2025/11/28 02:41:23 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:23 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:41:23 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:41:23 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:41:23 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:41:23 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:23 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:41:23 DEBUG : Looking for writers 2025/11/28 02:41:23 DEBUG : >WaitForWriters: --- FAIL: TestRWFileHandleSizeCreateExisting (0.20s) 2025/11/28 02:41:23 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting === RUN TestRWFileModTimeWithOpenWriters run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:23 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:41:23 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:41:23 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:41:23 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:41:23 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:23 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:41:23 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:41:23 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/11/28 02:41:23 DEBUG : file1: newRWFileHandle: 2025/11/28 02:41:23 DEBUG : file1(0xc0006b7100): openPending: 2025/11/28 02:41:23 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct) 2025/11/28 02:41:23 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:41:23 DEBUG : file1(0xc0006b7100): >openPending: err= 2025/11/28 02:41:23 DEBUG : file1: >newRWFileHandle: err= 2025/11/28 02:41:23 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:41:23 DEBUG : file1: >Open: fd=file1 (rw), err= 2025/11/28 02:41:23 DEBUG : file1: >OpenFile: fd=file1 (rw), err= run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:23 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:41:23 DEBUG : Looking for writers 2025/11/28 02:41:23 DEBUG : file1: reading active writers 2025/11/28 02:41:23 DEBUG : file1: active writers 1 2025/11/28 02:41:23 DEBUG : Still 1 writers active and 1 cache items in use, waiting 10ms 2025/11/28 02:41:23 DEBUG : Looking for writers 2025/11/28 02:41:23 DEBUG : file1: reading active writers 2025/11/28 02:41:23 DEBUG : file1: active writers 1 2025/11/28 02:41:23 DEBUG : Still 1 writers active and 1 cache items in use, waiting 20ms 2025/11/28 02:41:23 DEBUG : Looking for writers 2025/11/28 02:41:23 DEBUG : file1: reading active writers 2025/11/28 02:41:23 DEBUG : file1: active writers 1 2025/11/28 02:41:23 DEBUG : Still 1 writers active and 1 cache items in use, waiting 40ms 2025/11/28 02:41:23 DEBUG : Looking for writers 2025/11/28 02:41:23 DEBUG : file1: reading active writers 2025/11/28 02:41:23 DEBUG : file1: active writers 1 2025/11/28 02:41:23 DEBUG : Still 1 writers active and 1 cache items in use, waiting 80ms 2025/11/28 02:41:23 DEBUG : Looking for writers 2025/11/28 02:41:23 DEBUG : file1: reading active writers 2025/11/28 02:41:23 DEBUG : file1: active writers 1 2025/11/28 02:41:23 DEBUG : Still 1 writers active and 1 cache items in use, waiting 160ms 2025/11/28 02:41:23 DEBUG : Looking for writers 2025/11/28 02:41:23 DEBUG : file1: reading active writers 2025/11/28 02:41:23 DEBUG : file1: active writers 1 2025/11/28 02:41:23 DEBUG : Still 1 writers active and 1 cache items in use, waiting 320ms 2025/11/28 02:41:24 DEBUG : Looking for writers 2025/11/28 02:41:24 DEBUG : file1: reading active writers 2025/11/28 02:41:24 DEBUG : file1: active writers 1 2025/11/28 02:41:24 DEBUG : Still 1 writers active and 1 cache items in use, waiting 640ms 2025/11/28 02:41:24 DEBUG : Looking for writers 2025/11/28 02:41:24 DEBUG : file1: reading active writers 2025/11/28 02:41:24 DEBUG : file1: active writers 1 2025/11/28 02:41:24 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:25 DEBUG : Looking for writers 2025/11/28 02:41:25 DEBUG : file1: reading active writers 2025/11/28 02:41:25 DEBUG : file1: active writers 1 2025/11/28 02:41:25 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:26 DEBUG : Looking for writers 2025/11/28 02:41:26 DEBUG : file1: reading active writers 2025/11/28 02:41:26 DEBUG : file1: active writers 1 2025/11/28 02:41:26 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:27 DEBUG : Looking for writers 2025/11/28 02:41:27 DEBUG : file1: reading active writers 2025/11/28 02:41:27 DEBUG : file1: active writers 1 2025/11/28 02:41:27 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:28 DEBUG : Looking for writers 2025/11/28 02:41:28 DEBUG : file1: reading active writers 2025/11/28 02:41:28 DEBUG : file1: active writers 1 2025/11/28 02:41:28 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:29 DEBUG : Looking for writers 2025/11/28 02:41:29 DEBUG : file1: reading active writers 2025/11/28 02:41:29 DEBUG : file1: active writers 1 2025/11/28 02:41:29 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:30 DEBUG : Looking for writers 2025/11/28 02:41:30 DEBUG : file1: reading active writers 2025/11/28 02:41:30 DEBUG : file1: active writers 1 2025/11/28 02:41:30 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:31 DEBUG : Looking for writers 2025/11/28 02:41:31 DEBUG : file1: reading active writers 2025/11/28 02:41:31 DEBUG : file1: active writers 1 2025/11/28 02:41:31 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:32 DEBUG : Looking for writers 2025/11/28 02:41:32 DEBUG : file1: reading active writers 2025/11/28 02:41:32 DEBUG : file1: active writers 1 2025/11/28 02:41:32 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:33 DEBUG : Looking for writers 2025/11/28 02:41:33 DEBUG : file1: reading active writers 2025/11/28 02:41:33 DEBUG : file1: active writers 1 2025/11/28 02:41:33 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:34 DEBUG : Looking for writers 2025/11/28 02:41:34 DEBUG : file1: reading active writers 2025/11/28 02:41:34 DEBUG : file1: active writers 1 2025/11/28 02:41:34 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:35 DEBUG : Looking for writers 2025/11/28 02:41:35 DEBUG : file1: reading active writers 2025/11/28 02:41:35 DEBUG : file1: active writers 1 2025/11/28 02:41:35 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:36 DEBUG : Looking for writers 2025/11/28 02:41:36 DEBUG : file1: reading active writers 2025/11/28 02:41:36 DEBUG : file1: active writers 1 2025/11/28 02:41:36 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:37 DEBUG : Looking for writers 2025/11/28 02:41:37 DEBUG : file1: reading active writers 2025/11/28 02:41:37 DEBUG : file1: active writers 1 2025/11/28 02:41:37 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:38 DEBUG : Looking for writers 2025/11/28 02:41:38 DEBUG : file1: reading active writers 2025/11/28 02:41:38 DEBUG : file1: active writers 1 2025/11/28 02:41:38 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:39 DEBUG : Looking for writers 2025/11/28 02:41:39 DEBUG : file1: reading active writers 2025/11/28 02:41:39 DEBUG : file1: active writers 1 2025/11/28 02:41:39 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:40 DEBUG : Looking for writers 2025/11/28 02:41:40 DEBUG : file1: reading active writers 2025/11/28 02:41:40 DEBUG : file1: active writers 1 2025/11/28 02:41:40 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:41 DEBUG : Looking for writers 2025/11/28 02:41:41 DEBUG : file1: reading active writers 2025/11/28 02:41:41 DEBUG : file1: active writers 1 2025/11/28 02:41:41 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:42 DEBUG : Looking for writers 2025/11/28 02:41:42 DEBUG : file1: reading active writers 2025/11/28 02:41:42 DEBUG : file1: active writers 1 2025/11/28 02:41:42 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:43 DEBUG : Looking for writers 2025/11/28 02:41:43 DEBUG : file1: reading active writers 2025/11/28 02:41:43 DEBUG : file1: active writers 1 2025/11/28 02:41:43 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:44 DEBUG : Looking for writers 2025/11/28 02:41:44 DEBUG : file1: reading active writers 2025/11/28 02:41:44 DEBUG : file1: active writers 1 2025/11/28 02:41:44 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:45 DEBUG : Looking for writers 2025/11/28 02:41:45 DEBUG : file1: reading active writers 2025/11/28 02:41:45 DEBUG : file1: active writers 1 2025/11/28 02:41:45 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:46 DEBUG : Looking for writers 2025/11/28 02:41:46 DEBUG : file1: reading active writers 2025/11/28 02:41:46 DEBUG : file1: active writers 1 2025/11/28 02:41:46 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:47 DEBUG : Looking for writers 2025/11/28 02:41:47 DEBUG : file1: reading active writers 2025/11/28 02:41:47 DEBUG : file1: active writers 1 2025/11/28 02:41:47 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:48 DEBUG : Looking for writers 2025/11/28 02:41:48 DEBUG : file1: reading active writers 2025/11/28 02:41:48 DEBUG : file1: active writers 1 2025/11/28 02:41:48 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:49 DEBUG : Looking for writers 2025/11/28 02:41:49 DEBUG : file1: reading active writers 2025/11/28 02:41:49 DEBUG : file1: active writers 1 2025/11/28 02:41:49 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:50 DEBUG : Looking for writers 2025/11/28 02:41:50 DEBUG : file1: reading active writers 2025/11/28 02:41:50 DEBUG : file1: active writers 1 2025/11/28 02:41:50 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:51 DEBUG : Looking for writers 2025/11/28 02:41:51 DEBUG : file1: reading active writers 2025/11/28 02:41:51 DEBUG : file1: active writers 1 2025/11/28 02:41:51 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:52 DEBUG : Looking for writers 2025/11/28 02:41:52 DEBUG : file1: reading active writers 2025/11/28 02:41:52 DEBUG : file1: active writers 1 2025/11/28 02:41:52 DEBUG : Still 1 writers active and 1 cache items in use, waiting 1s 2025/11/28 02:41:53 ERROR : Exiting even though 1 writers active and 1 cache items in use after 30s Cache{ "file1": &{c:0xc000b064b0 mu:{_:{} mu:{state:0 sema:0}} cond:{noCopy:{} L:0xc000a75508 notify:{wait:0 notify:0 lock:0 head: tail:} checker:824644687168} name:file1 opens:1 downloaders: o: fd:0xc000154150 info:{ModTime:{wall:13997857058989207483 ext:284465754342 loc:0x42a0c60} ATime:{wall:13997857058989207483 ext:284465754342 loc:0x42a0c60} Size:0 Rs:[] Fingerprint: Dirty:true} writeBackID:0 pendingAccesses:0 modified:true beingReset:false}, } 2025/11/28 02:41:53 DEBUG : >WaitForWriters: --- FAIL: TestRWFileModTimeWithOpenWriters (30.21s) === RUN TestRWCacheUpdate run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:53 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:41:53 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: root is "/home/rclone/.cache/rclone" 2025/11/28 02:41:53 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:53 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:53 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:53 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:41:53 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting 2025/11/28 02:41:53 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:53 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:53 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2025/11/28 02:41:53 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestB2/rclone-test-kuhogad2fuka" 2025/11/28 02:41:53 INFO : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2025/11/28 02:41:53 DEBUG : forgetting directory cache run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:54 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:41:54 DEBUG : Looking for writers 2025/11/28 02:41:54 DEBUG : >WaitForWriters: --- FAIL: TestRWCacheUpdate (0.56s) === RUN TestCaseSensitivity run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:54 DEBUG : B2 bucket rclone-test-kuhogad2fuka: vfs cache: cleaner exiting run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) --- FAIL: TestCaseSensitivity (0.20s) === RUN TestUnicodeNormalization run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) --- FAIL: TestUnicodeNormalization (0.29s) === RUN TestVFSStat run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:54 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:54 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:41:54 DEBUG : Looking for writers 2025/11/28 02:41:54 DEBUG : >WaitForWriters: --- FAIL: TestVFSStat (0.19s) === RUN TestVFSStatParent run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:54 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:54 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:41:54 DEBUG : Looking for writers 2025/11/28 02:41:54 DEBUG : >WaitForWriters: --- FAIL: TestVFSStatParent (0.20s) === RUN TestVFSOpenFile run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:54 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:55 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:41:55 DEBUG : Looking for writers 2025/11/28 02:41:55 DEBUG : >WaitForWriters: --- FAIL: TestVFSOpenFile (0.19s) === RUN TestVFSRename run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:55 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:55 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:41:55 DEBUG : Looking for writers 2025/11/28 02:41:55 DEBUG : >WaitForWriters: --- FAIL: TestVFSRename (0.20s) === RUN TestWriteFileHandleMethods run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:41:55 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:41:55 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:41:55 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:41:55 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:41:55 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:41:55 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:41:55 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:41:55 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal 2025/11/28 02:41:55 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal 2025/11/28 02:41:55 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes 2025/11/28 02:41:55 DEBUG : B2 bucket rclone-test-kuhogad2fuka: File to upload is small (5 bytes), uploading instead of streaming 2025/11/28 02:41:55 ERROR : file1: WriteFileHandle.New Rcat failed: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:41:55 DEBUG : file1: Remove: 2025/11/28 02:41:55 DEBUG : Added virtual directory entry vDel: "file1" 2025/11/28 02:41:55 DEBUG : file1: >Remove: err= write_test.go:144: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:144 Error: Received unexpected error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) Test: TestWriteFileHandleMethods dir_test.go:250: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:250 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:153 Error: Not equal: expected: []string{"file1,5,false"} actual : []string(nil) Diff: --- Expected +++ Actual @@ -1,4 +1,2 @@ -([]string) (len=1) { - (string) (len=13) "file1,5,false" -} +([]string) Test: TestWriteFileHandleMethods fstest.go:298: Sleeping for 1s for list eventual consistency: 1/5 fstest.go:298: Sleeping for 2s for list eventual consistency: 2/5 fstest.go:298: Sleeping for 4s for list eventual consistency: 3/5 fstest.go:298: Sleeping for 8s for list eventual consistency: 4/5 fstest.go:298: Sleeping for 16s for list eventual consistency: 5/5 fstest.go:305: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:157 Error: Should be true Test: TestWriteFileHandleMethods Messages: listing wrong, want file1 (5) got fstest.go:203: Not found "file1" fstest.go:206: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:206 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:310 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:157 Error: Not equal: expected: 0 actual : 1 Test: TestWriteFileHandleMethods Messages: 1 objects not found 2025/11/28 02:42:26 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:42:26 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:42:26 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:42:26 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:42:26 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:42:26 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:42:26 DEBUG : B2 bucket rclone-test-kuhogad2fuka: File to upload is small (0 bytes), uploading instead of streaming 2025/11/28 02:42:27 ERROR : file1: WriteFileHandle.New Rcat failed: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:42:27 DEBUG : file1: Remove: 2025/11/28 02:42:27 DEBUG : Added virtual directory entry vDel: "file1" 2025/11/28 02:42:27 DEBUG : file1: >Remove: err= write_test.go:163: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:163 Error: Received unexpected error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) Test: TestWriteFileHandleMethods dir_test.go:250: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:250 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:164 Error: Not equal: expected: []string{"file1,5,false"} actual : []string(nil) Diff: --- Expected +++ Actual @@ -1,4 +1,2 @@ -([]string) (len=1) { - (string) (len=13) "file1,5,false" -} +([]string) Test: TestWriteFileHandleMethods 2025/11/28 02:42:27 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:42:27 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:42:27 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:42:27 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:42:27 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:42:27 DEBUG : Added virtual directory entry vAddFile: "file1" write_test.go:171: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:171 Error: Not equal: expected: *errors.errorString(&errors.errorString{s:"permission denied"}) actual : () Test: TestWriteFileHandleMethods 2025/11/28 02:42:27 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:42:27 DEBUG : Looking for writers 2025/11/28 02:42:27 DEBUG : file1: reading active writers 2025/11/28 02:42:27 DEBUG : file1: active writers 1 2025/11/28 02:42:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2025/11/28 02:42:27 DEBUG : Looking for writers 2025/11/28 02:42:27 DEBUG : file1: reading active writers 2025/11/28 02:42:27 DEBUG : file1: active writers 1 2025/11/28 02:42:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2025/11/28 02:42:27 DEBUG : Looking for writers 2025/11/28 02:42:27 DEBUG : file1: reading active writers 2025/11/28 02:42:27 DEBUG : file1: active writers 1 2025/11/28 02:42:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2025/11/28 02:42:27 DEBUG : Looking for writers 2025/11/28 02:42:27 DEBUG : file1: reading active writers 2025/11/28 02:42:27 DEBUG : file1: active writers 1 2025/11/28 02:42:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2025/11/28 02:42:27 DEBUG : Looking for writers 2025/11/28 02:42:27 DEBUG : file1: reading active writers 2025/11/28 02:42:27 DEBUG : file1: active writers 1 2025/11/28 02:42:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2025/11/28 02:42:27 DEBUG : Looking for writers 2025/11/28 02:42:27 DEBUG : file1: reading active writers 2025/11/28 02:42:27 DEBUG : file1: active writers 1 2025/11/28 02:42:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2025/11/28 02:42:27 DEBUG : Looking for writers 2025/11/28 02:42:27 DEBUG : file1: reading active writers 2025/11/28 02:42:27 DEBUG : file1: active writers 1 2025/11/28 02:42:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2025/11/28 02:42:28 DEBUG : Looking for writers 2025/11/28 02:42:28 DEBUG : file1: reading active writers 2025/11/28 02:42:28 DEBUG : file1: active writers 1 2025/11/28 02:42:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:29 DEBUG : Looking for writers 2025/11/28 02:42:29 DEBUG : file1: reading active writers 2025/11/28 02:42:29 DEBUG : file1: active writers 1 2025/11/28 02:42:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:30 DEBUG : Looking for writers 2025/11/28 02:42:30 DEBUG : file1: reading active writers 2025/11/28 02:42:30 DEBUG : file1: active writers 1 2025/11/28 02:42:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:31 DEBUG : Looking for writers 2025/11/28 02:42:31 DEBUG : file1: reading active writers 2025/11/28 02:42:31 DEBUG : file1: active writers 1 2025/11/28 02:42:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:32 DEBUG : Looking for writers 2025/11/28 02:42:32 DEBUG : file1: reading active writers 2025/11/28 02:42:32 DEBUG : file1: active writers 1 2025/11/28 02:42:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:33 DEBUG : Looking for writers 2025/11/28 02:42:33 DEBUG : file1: reading active writers 2025/11/28 02:42:33 DEBUG : file1: active writers 1 2025/11/28 02:42:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:34 DEBUG : Looking for writers 2025/11/28 02:42:34 DEBUG : file1: reading active writers 2025/11/28 02:42:34 DEBUG : file1: active writers 1 2025/11/28 02:42:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:35 DEBUG : Looking for writers 2025/11/28 02:42:35 DEBUG : file1: reading active writers 2025/11/28 02:42:35 DEBUG : file1: active writers 1 2025/11/28 02:42:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:36 DEBUG : Looking for writers 2025/11/28 02:42:36 DEBUG : file1: reading active writers 2025/11/28 02:42:36 DEBUG : file1: active writers 1 2025/11/28 02:42:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:37 DEBUG : Looking for writers 2025/11/28 02:42:37 DEBUG : file1: reading active writers 2025/11/28 02:42:37 DEBUG : file1: active writers 1 2025/11/28 02:42:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:38 DEBUG : Looking for writers 2025/11/28 02:42:38 DEBUG : file1: reading active writers 2025/11/28 02:42:38 DEBUG : file1: active writers 1 2025/11/28 02:42:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:39 DEBUG : Looking for writers 2025/11/28 02:42:39 DEBUG : file1: reading active writers 2025/11/28 02:42:39 DEBUG : file1: active writers 1 2025/11/28 02:42:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:40 DEBUG : Looking for writers 2025/11/28 02:42:40 DEBUG : file1: reading active writers 2025/11/28 02:42:40 DEBUG : file1: active writers 1 2025/11/28 02:42:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:41 DEBUG : Looking for writers 2025/11/28 02:42:41 DEBUG : file1: reading active writers 2025/11/28 02:42:41 DEBUG : file1: active writers 1 2025/11/28 02:42:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:42 DEBUG : Looking for writers 2025/11/28 02:42:42 DEBUG : file1: reading active writers 2025/11/28 02:42:42 DEBUG : file1: active writers 1 2025/11/28 02:42:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:43 DEBUG : Looking for writers 2025/11/28 02:42:43 DEBUG : file1: reading active writers 2025/11/28 02:42:43 DEBUG : file1: active writers 1 2025/11/28 02:42:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:44 DEBUG : Looking for writers 2025/11/28 02:42:44 DEBUG : file1: reading active writers 2025/11/28 02:42:44 DEBUG : file1: active writers 1 2025/11/28 02:42:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:45 DEBUG : Looking for writers 2025/11/28 02:42:45 DEBUG : file1: reading active writers 2025/11/28 02:42:45 DEBUG : file1: active writers 1 2025/11/28 02:42:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:46 DEBUG : Looking for writers 2025/11/28 02:42:46 DEBUG : file1: reading active writers 2025/11/28 02:42:46 DEBUG : file1: active writers 1 2025/11/28 02:42:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:47 DEBUG : Looking for writers 2025/11/28 02:42:47 DEBUG : file1: reading active writers 2025/11/28 02:42:47 DEBUG : file1: active writers 1 2025/11/28 02:42:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:48 DEBUG : Looking for writers 2025/11/28 02:42:48 DEBUG : file1: reading active writers 2025/11/28 02:42:48 DEBUG : file1: active writers 1 2025/11/28 02:42:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:49 DEBUG : Looking for writers 2025/11/28 02:42:49 DEBUG : file1: reading active writers 2025/11/28 02:42:49 DEBUG : file1: active writers 1 2025/11/28 02:42:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:50 DEBUG : Looking for writers 2025/11/28 02:42:50 DEBUG : file1: reading active writers 2025/11/28 02:42:50 DEBUG : file1: active writers 1 2025/11/28 02:42:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:51 DEBUG : Looking for writers 2025/11/28 02:42:51 DEBUG : file1: reading active writers 2025/11/28 02:42:51 DEBUG : file1: active writers 1 2025/11/28 02:42:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:52 DEBUG : Looking for writers 2025/11/28 02:42:52 DEBUG : file1: reading active writers 2025/11/28 02:42:52 DEBUG : file1: active writers 1 2025/11/28 02:42:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:53 DEBUG : Looking for writers 2025/11/28 02:42:53 DEBUG : file1: reading active writers 2025/11/28 02:42:53 DEBUG : file1: active writers 1 2025/11/28 02:42:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:54 DEBUG : Looking for writers 2025/11/28 02:42:54 DEBUG : file1: reading active writers 2025/11/28 02:42:54 DEBUG : file1: active writers 1 2025/11/28 02:42:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:55 DEBUG : Looking for writers 2025/11/28 02:42:55 DEBUG : file1: reading active writers 2025/11/28 02:42:55 DEBUG : file1: active writers 1 2025/11/28 02:42:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:56 DEBUG : Looking for writers 2025/11/28 02:42:56 DEBUG : file1: reading active writers 2025/11/28 02:42:56 DEBUG : file1: active writers 1 2025/11/28 02:42:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2025/11/28 02:42:57 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2025/11/28 02:42:57 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleMethods (61.78s) === RUN TestWriteFileHandleWriteAt run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:42:57 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:42:57 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:42:57 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:42:57 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:42:57 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:42:57 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:42:57 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:42:57 DEBUG : file1: waiting for in-sequence write to 100 for 1s 2025/11/28 02:42:58 DEBUG : file1: aborting in-sequence write wait, off=100 2025/11/28 02:42:58 DEBUG : file1: failed to wait for in-sequence write to 100 2025/11/28 02:42:58 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes 2025/11/28 02:42:58 DEBUG : B2 bucket rclone-test-kuhogad2fuka: File to upload is small (11 bytes), uploading instead of streaming 2025/11/28 02:42:58 ERROR : file1: WriteFileHandle.New Rcat failed: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:42:58 DEBUG : file1: Remove: 2025/11/28 02:42:58 DEBUG : Added virtual directory entry vDel: "file1" 2025/11/28 02:42:58 DEBUG : file1: >Remove: err= write_test.go:221: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:221 Error: Received unexpected error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) Test: TestWriteFileHandleWriteAt 2025/11/28 02:42:58 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor dir_test.go:250: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:250 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:231 Error: Not equal: expected: []string{"file1,11,false"} actual : []string(nil) Diff: --- Expected +++ Actual @@ -1,4 +1,2 @@ -([]string) (len=1) { - (string) (len=14) "file1,11,false" -} +([]string) Test: TestWriteFileHandleWriteAt fstest.go:298: Sleeping for 1s for list eventual consistency: 1/5 fstest.go:298: Sleeping for 2s for list eventual consistency: 2/5 fstest.go:298: Sleeping for 4s for list eventual consistency: 3/5 fstest.go:298: Sleeping for 8s for list eventual consistency: 4/5 fstest.go:298: Sleeping for 16s for list eventual consistency: 5/5 fstest.go:305: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:235 Error: Should be true Test: TestWriteFileHandleWriteAt Messages: listing wrong, want file1 (11) got fstest.go:203: Not found "file1" fstest.go:206: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:206 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:310 /home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:235 Error: Not equal: expected: 0 actual : 1 Test: TestWriteFileHandleWriteAt Messages: 1 objects not found 2025/11/28 02:43:29 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:29 DEBUG : Looking for writers 2025/11/28 02:43:29 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleWriteAt (32.60s) === RUN TestWriteFileHandleFlush run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:29 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:43:29 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:43:29 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:43:29 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:29 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:43:29 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:43:29 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2025/11/28 02:43:29 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:29 DEBUG : B2 bucket rclone-test-kuhogad2fuka: File to upload is small (5 bytes), uploading instead of streaming 2025/11/28 02:43:30 ERROR : file1: WriteFileHandle.New Rcat failed: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:30 DEBUG : file1: Remove: 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vDel: "file1" 2025/11/28 02:43:30 DEBUG : file1: >Remove: err= 2025/11/28 02:43:30 ERROR : file1: WriteFileHandle.Flush error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) write_test.go:256: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:256 Error: Received unexpected error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) Test: TestWriteFileHandleFlush 2025/11/28 02:43:30 DEBUG : file1: WriteFileHandle.Flush nothing to do dir_test.go:250: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:250 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:267 Error: Not equal: expected: []string{"file1,5,false"} actual : []string(nil) Diff: --- Expected +++ Actual @@ -1,4 +1,2 @@ -([]string) (len=1) { - (string) (len=13) "file1,5,false" -} +([]string) Test: TestWriteFileHandleFlush 2025/11/28 02:43:30 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:30 DEBUG : Looking for writers 2025/11/28 02:43:30 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleFlush (0.56s) === RUN TestWriteFileHandleRelease run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:30 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:43:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:43:30 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:30 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:43:30 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:43:30 DEBUG : file1: WriteFileHandle.Release closing 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:30 DEBUG : B2 bucket rclone-test-kuhogad2fuka: File to upload is small (0 bytes), uploading instead of streaming 2025/11/28 02:43:30 ERROR : file1: WriteFileHandle.New Rcat failed: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:30 DEBUG : file1: Remove: 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vDel: "file1" 2025/11/28 02:43:30 DEBUG : file1: >Remove: err= 2025/11/28 02:43:30 ERROR : file1: WriteFileHandle.Release error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) write_test.go:279: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:279 Error: Received unexpected error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) Test: TestWriteFileHandleRelease 2025/11/28 02:43:30 DEBUG : file1: WriteFileHandle.Release nothing to do 2025/11/28 02:43:30 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:30 DEBUG : Looking for writers 2025/11/28 02:43:30 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleRelease (0.22s) === RUN TestWriteFileModTimeWithOpenWriters run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:30 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:43:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:43:30 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:30 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:43:30 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:30 DEBUG : B2 bucket rclone-test-kuhogad2fuka: File to upload is small (2 bytes), uploading instead of streaming 2025/11/28 02:43:30 ERROR : file1: WriteFileHandle.New Rcat failed: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:30 DEBUG : file1: Remove: 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vDel: "file1" 2025/11/28 02:43:30 DEBUG : file1: >Remove: err= write_test.go:333: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:333 Error: Received unexpected error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) Test: TestWriteFileModTimeWithOpenWriters 2025/11/28 02:43:30 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:30 DEBUG : Looking for writers 2025/11/28 02:43:30 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileModTimeWithOpenWriters (0.20s) === RUN TestFileReadAtZeroLength run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:30 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:43:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:43:30 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:30 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:43:30 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:30 DEBUG : B2 bucket rclone-test-kuhogad2fuka: File to upload is small (0 bytes), uploading instead of streaming 2025/11/28 02:43:30 ERROR : file1: WriteFileHandle.New Rcat failed: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:30 DEBUG : file1: Remove: 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vDel: "file1" 2025/11/28 02:43:30 DEBUG : file1: >Remove: err= write_test.go:360: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:360 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:380 Error: Received unexpected error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) Test: TestFileReadAtZeroLength 2025/11/28 02:43:30 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2025/11/28 02:43:30 DEBUG : file1: >OpenFile: fd=, err=file does not exist write_test.go:365: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:365 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:380 Error: Received unexpected error: file does not exist Test: TestFileReadAtZeroLength 2025/11/28 02:43:30 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:30 DEBUG : Looking for writers 2025/11/28 02:43:30 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtZeroLength (0.20s) === RUN TestFileReadAtNonZeroLength run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:30 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote 2025/11/28 02:43:30 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2025/11/28 02:43:30 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:30 DEBUG : file1: >Open: fd=file1 (w), err= 2025/11/28 02:43:30 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2025/11/28 02:43:30 DEBUG : Added virtual directory entry vAddFile: "file1" 2025/11/28 02:43:30 DEBUG : B2 bucket rclone-test-kuhogad2fuka: File to upload is small (100 bytes), uploading instead of streaming 2025/11/28 02:43:31 ERROR : file1: WriteFileHandle.New Rcat failed: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:31 DEBUG : file1: Remove: 2025/11/28 02:43:31 DEBUG : Added virtual directory entry vDel: "file1" 2025/11/28 02:43:31 DEBUG : file1: >Remove: err= write_test.go:360: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:360 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:384 Error: Received unexpected error: failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) Test: TestFileReadAtNonZeroLength 2025/11/28 02:43:31 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2025/11/28 02:43:31 DEBUG : file1: >OpenFile: fd=, err=file does not exist write_test.go:365: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:365 /home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:384 Error: Received unexpected error: file does not exist Test: TestFileReadAtNonZeroLength 2025/11/28 02:43:31 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:31 DEBUG : Looking for writers 2025/11/28 02:43:31 DEBUG : >WaitForWriters: --- FAIL: TestFileReadAtNonZeroLength (0.20s) === RUN TestZipManyFiles run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:31 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:31 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:31 DEBUG : Looking for writers 2025/11/28 02:43:31 DEBUG : >WaitForWriters: --- FAIL: TestZipManyFiles (0.20s) === RUN TestZipManySubDirs run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:31 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:31 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:31 DEBUG : Looking for writers 2025/11/28 02:43:31 DEBUG : >WaitForWriters: --- FAIL: TestZipManySubDirs (0.20s) === RUN TestZipLargeFiles run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:31 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:31 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:31 DEBUG : Looking for writers 2025/11/28 02:43:31 DEBUG : >WaitForWriters: --- FAIL: TestZipLargeFiles (0.25s) === RUN TestZipDirsInRoot run.go:185: Remote "B2 bucket rclone-test-kuhogad2fuka", Local "Local file system at /tmp/rclone4140315189", Modify Window "1ms" 2025/11/28 02:43:31 INFO : B2 bucket rclone-test-kuhogad2fuka: poll-interval is not supported by this remote run.go:242: Failed to mkdir "B2 bucket rclone-test-kuhogad2fuka": failed to create bucket: The account is already at the maximum bucket count (400 too_many_buckets) 2025/11/28 02:43:31 DEBUG : WaitForWriters: timeout=30s 2025/11/28 02:43:31 DEBUG : Looking for writers 2025/11/28 02:43:31 DEBUG : >WaitForWriters: --- FAIL: TestZipDirsInRoot (0.20s) FAIL 2025/11/28 02:43:31 DEBUG : B2 bucket rclone-test-kuhogad2fuka: Purge remote 2025/11/28 02:43:31 INFO : B2 bucket rclone-test-kuhogad2fuka: cleaning bucket "rclone-test-kuhogad2fuka" of all files 2025/11/28 02:43:31 NOTICE: purge failed: directory not found "./vfs.test -test.v -test.timeout 1h0m0s -remote TestB2: -list-retries 5 -verbose -test.run '^(TestCaseSensitivity|TestDirCreate|TestDirFileOpen|TestDirForgetAll|TestDirForgetPath|TestDirHandleMethods|TestDirHandleReaddir|TestDirHandleReaddirnames|TestDirMetadataExtension|TestDirMethods|TestDirMkdir|TestDirMkdirSub|TestDirOpen|TestDirReadDirAll|TestDirRemove|TestDirRemoveAll|TestDirRemoveName|TestDirRename|TestDirSetModTime|TestDirStat|TestDirWalk|TestFileMethods|TestFileOpen|TestFileOpenRead|TestFileOpenWrite|TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestFileRemove|TestFileRemoveAll|TestRWCacheUpdate|TestRWFileHandleFlushRead|TestRWFileHandleMethodsRead|TestRWFileHandleMethodsWrite|TestRWFileHandleReadAt|TestRWFileHandleReleaseRead|TestRWFileHandleSeek|TestRWFileHandleSizeCreateExisting|TestRWFileHandleSizeTruncateExisting|TestRWFileHandleWriteAt|TestRWFileHandleWriteNoWrite|TestRWFileModTimeWithOpenWriters|TestReadFileHandleFlush|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleRelease|TestReadFileHandleSeek|TestUnicodeNormalization|TestVFSOpenFile|TestVFSRename|TestVFSStat|TestVFSStatParent|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileHandleWriteAt|TestWriteFileModTimeWithOpenWriters|TestZipDirsInRoot|TestZipLargeFiles|TestZipManyFiles|TestZipManySubDirs)$|^TestFileRename$/^(full,forceCache=false|minimal,forceCache=false|minimal,forceCache=true|off,forceCache=false|writes,forceCache=false|writes,forceCache=true)$|^TestFileSetModTime$/^(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)$'" - Finished ERROR in 6m53.11800037s (try 2/5): exit status 1: Failed [TestDirHandleMethods TestDirHandleReaddir TestDirHandleReaddirnames TestDirMethods TestDirForgetAll TestDirForgetPath TestDirWalk TestDirSetModTime TestDirStat TestDirReadDirAll TestDirOpen TestDirCreate TestDirMkdir TestDirMkdirSub TestDirRemove TestDirRemoveAll TestDirRemoveName TestDirRename TestDirFileOpen TestDirMetadataExtension 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 TestReadFileHandleMethods TestReadFileHandleSeek TestReadFileHandleReadAt TestReadFileHandleFlush TestReadFileHandleRelease TestRWFileHandleMethodsRead TestRWFileHandleSeek TestRWFileHandleReadAt TestRWFileHandleFlushRead TestRWFileHandleReleaseRead TestRWFileHandleMethodsWrite TestRWFileHandleWriteAt TestRWFileHandleWriteNoWrite TestRWFileHandleSizeTruncateExisting TestRWFileHandleSizeCreateExisting TestRWFileModTimeWithOpenWriters TestRWCacheUpdate TestCaseSensitivity TestUnicodeNormalization TestVFSStat TestVFSStatParent TestVFSOpenFile TestVFSRename TestWriteFileHandleMethods TestWriteFileHandleWriteAt TestWriteFileHandleFlush TestWriteFileHandleRelease TestWriteFileModTimeWithOpenWriters TestFileReadAtZeroLength TestFileReadAtNonZeroLength TestZipManyFiles TestZipManySubDirs TestZipLargeFiles TestZipDirsInRoot]