"./vfs.test -test.v -test.timeout 1h0m0s -remote TestUptobox: -verbose -test.run '^(TestDirRemoveName|TestFileOpenRead|TestFileSetModTime|TestRWFileHandleSizeTruncateExisting|TestRcGetVFS|TestVFSNew)$/^(cache=off,open=false,write=false|cache=off,open=true,write=false)$'" - Starting (try 2/5) 2021/11/10 05:21:34 DEBUG : Creating backend with remote "TestUptobox:rclone-test-rimapip5xiluhuc8kisoxof0" 2021/11/10 05:21:34 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2021/11/10 05:21:35 DEBUG : Creating backend with remote "/tmp/rclone3720595163" === RUN TestDirRemoveName run.go:181: Remote "Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0'", Local "Local file system at /tmp/rclone3720595163", Modify Window "876000h0m0s" 2021/11/10 05:21:35 INFO : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': poll-interval is not supported by this remote 2021/11/10 05:21:35 NOTICE: Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/11/10 05:21:40 DEBUG : dir/file1: Remove: 2021/11/10 05:21:40 DEBUG : dir: Added virtual directory entry vDel: "file1" 2021/11/10 05:21:41 DEBUG : dir/file1: >Remove: err= 2021/11/10 05:21:41 DEBUG : WaitForWriters: timeout=30s 2021/11/10 05:21:41 DEBUG : dir: Looking for writers 2021/11/10 05:21:41 DEBUG : : Looking for writers 2021/11/10 05:21:41 DEBUG : dir: reading active writers 2021/11/10 05:21:41 DEBUG : >WaitForWriters: --- PASS: TestDirRemoveName (8.81s) === RUN TestFileSetModTime === RUN TestFileSetModTime/cache=off,open=false,write=false run.go:181: Remote "Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0'", Local "Local file system at /tmp/rclone3720595163", Modify Window "876000h0m0s" 2021/11/10 05:21:43 INFO : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': poll-interval is not supported by this remote 2021/11/10 05:21:43 NOTICE: Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/11/10 05:21:53 DEBUG : Can set mod time: false file_test.go:98: can't set mod time 2021/11/10 05:21:53 DEBUG : WaitForWriters: timeout=30s 2021/11/10 05:21:53 DEBUG : dir: Looking for writers 2021/11/10 05:21:53 DEBUG : file1: reading active writers 2021/11/10 05:21:53 DEBUG : : Looking for writers 2021/11/10 05:21:53 DEBUG : dir: reading active writers 2021/11/10 05:21:53 DEBUG : >WaitForWriters: === RUN TestFileSetModTime/cache=off,open=true,write=false file_test.go:93: can't set mod time --- PASS: TestFileSetModTime (11.62s) --- SKIP: TestFileSetModTime/cache=off,open=false,write=false (11.62s) --- SKIP: TestFileSetModTime/cache=off,open=true,write=false (0.00s) === RUN TestFileOpenRead run.go:181: Remote "Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0'", Local "Local file system at /tmp/rclone3720595163", Modify Window "876000h0m0s" 2021/11/10 05:21:55 INFO : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': poll-interval is not supported by this remote 2021/11/10 05:21:55 NOTICE: Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/11/10 05:22:00 DEBUG : dir/file1: Open: flags=O_RDONLY 2021/11/10 05:22:00 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2021/11/10 05:22:00 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2021/11/10 05:22:01 DEBUG : dir/file1: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728 2021/11/10 05:22:01 DEBUG : WaitForWriters: timeout=30s 2021/11/10 05:22:01 DEBUG : dir: Looking for writers 2021/11/10 05:22:01 DEBUG : file1: reading active writers 2021/11/10 05:22:01 DEBUG : : Looking for writers 2021/11/10 05:22:01 DEBUG : dir: reading active writers 2021/11/10 05:22:01 DEBUG : >WaitForWriters: run.go:126: removing dir "dir" failed - try 1/3: HTTP error 405 (405 Method Not Allowed) returned body: "\n405 Not Allowed\n\n

405 Not Allowed

\n
nginx
\n\n\n" --- PASS: TestFileOpenRead (9.86s) === RUN TestRcGetVFS run.go:181: Remote "Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0'", Local "Local file system at /tmp/rclone3720595163", Modify Window "876000h0m0s" 2021/11/10 05:22:05 INFO : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': poll-interval is not supported by this remote 2021/11/10 05:22:05 NOTICE: Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/11/10 05:22:05 INFO : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': poll-interval is not supported by this remote 2021/11/10 05:22:05 NOTICE: Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/11/10 05:22:05 DEBUG : WaitForWriters: timeout=30s 2021/11/10 05:22:05 DEBUG : : Looking for writers 2021/11/10 05:22:05 DEBUG : >WaitForWriters: 2021/11/10 05:22:05 DEBUG : pacer: low level retry 1/10 (error HTTP error 503 (503 Service Unavailable) returned body: "\n\n\n\n\n\n\n\n\n\n\n\n\nNous réalisons une maintenance et nous revenons très vite !\n

\n\nOur website is currently undergoing maintenance and will be back online shortly !\n
\n

\n

\nSuivez-nous sur Facebook / Follow us on Facebook\nSuivez-nous sur Twitch\n

\n\n\n") 2021/11/10 05:22:05 DEBUG : pacer: Rate limited, increasing sleep to 5s 2021/11/10 05:22:06 DEBUG : pacer: low level retry 2/10 (error HTTP error 503 (503 Service Unavailable) returned body: "\n\n\n\n\n\n\n\n\n\n\n\n\nNous réalisons une maintenance et nous revenons très vite !\n

\n\nOur website is currently undergoing maintenance and will be back online shortly !\n
\n

\n

\nSuivez-nous sur Facebook / Follow us on Facebook\nSuivez-nous sur Twitch\n

\n\n\n") 2021/11/10 05:22:11 DEBUG : pacer: Reducing sleep to 3.75s 2021/11/10 05:22:16 DEBUG : pacer: Reducing sleep to 2.8125s --- PASS: TestRcGetVFS (10.81s) === RUN TestRWFileHandleSizeTruncateExisting run.go:181: Remote "Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0'", Local "Local file system at /tmp/rclone3720595163", Modify Window "876000h0m0s" 2021/11/10 05:22:16 INFO : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': poll-interval is not supported by this remote 2021/11/10 05:22:16 DEBUG : vfs cache: root is "/home/rclone/.cache/rclone" 2021/11/10 05:22:16 DEBUG : vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestUptobox/rclone-test-rimapip5xiluhuc8kisoxof0" 2021/11/10 05:22:16 DEBUG : vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestUptobox/rclone-test-rimapip5xiluhuc8kisoxof0" 2021/11/10 05:22:16 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfs/TestUptobox/rclone-test-rimapip5xiluhuc8kisoxof0" 2021/11/10 05:22:16 DEBUG : Creating backend with remote "/home/rclone/.cache/rclone/vfsMeta/TestUptobox/rclone-test-rimapip5xiluhuc8kisoxof0" 2021/11/10 05:22:16 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2021/11/10 05:22:19 DEBUG : pacer: Reducing sleep to 2.109375s 2021/11/10 05:22:22 DEBUG : pacer: Reducing sleep to 1.58203125s 2021/11/10 05:22:25 DEBUG : pacer: Reducing sleep to 1.186523437s 2021/11/10 05:22:26 DEBUG : pacer: Reducing sleep to 889.892577ms 2021/11/10 05:22:27 DEBUG : pacer: Reducing sleep to 667.419432ms 2021/11/10 05:22:28 DEBUG : pacer: Reducing sleep to 500.564574ms 2021/11/10 05:22:29 DEBUG : pacer: Reducing sleep to 400ms 2021/11/10 05:22:30 DEBUG : dir/file1: OpenFile: flags=O_WRONLY|O_TRUNC, perm=-rwxrwxrwx 2021/11/10 05:22:31 DEBUG : dir/file1: Open: flags=O_WRONLY|O_TRUNC 2021/11/10 05:22:31 DEBUG : dir/file1: newRWFileHandle: 2021/11/10 05:22:31 DEBUG : dir/file1(0xc0006cacc0): openPending: 2021/11/10 05:22:31 DEBUG : dir/file1: vfs cache: checking remote fingerprint "16" against cached fingerprint "" 2021/11/10 05:22:31 DEBUG : dir/file1: vfs cache: truncate to size=16 2021/11/10 05:22:31 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/11/10 05:22:31 DEBUG : dir/file1(0xc0006cacc0): >openPending: err= 2021/11/10 05:22:31 DEBUG : dir/file1: vfs cache: truncate to size=0 2021/11/10 05:22:31 DEBUG : dir/file1: >newRWFileHandle: err= 2021/11/10 05:22:31 DEBUG : dir/file1: >Open: fd=dir/file1 (rw), err= 2021/11/10 05:22:31 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (rw), err= 2021/11/10 05:22:31 DEBUG : dir/file1(0xc0006cacc0): _writeAt: size=5, off=0 2021/11/10 05:22:31 DEBUG : dir/file1(0xc0006cacc0): >_writeAt: n=5, err= 2021/11/10 05:22:31 DEBUG : dir/file1(0xc0006cacc0): close: 2021/11/10 05:22:31 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true 2021/11/10 05:22:31 DEBUG : dir/file1: vfs cache: setting modification time to 2021-11-10 05:22:31.63843783 +0000 UTC m=+57.096927169 2021/11/10 05:22:31 INFO : dir/file1: vfs cache: queuing for upload in 100ms 2021/11/10 05:22:31 DEBUG : dir/file1(0xc0006cacc0): >close: err= 2021/11/10 05:22:31 DEBUG : WaitForWriters: timeout=30s 2021/11/10 05:22:31 DEBUG : dir: Looking for writers 2021/11/10 05:22:31 DEBUG : file1: reading active writers 2021/11/10 05:22:31 DEBUG : : Looking for writers 2021/11/10 05:22:31 DEBUG : dir: reading active writers 2021/11/10 05:22:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms 2021/11/10 05:22:31 DEBUG : dir: Looking for writers 2021/11/10 05:22:31 DEBUG : file1: reading active writers 2021/11/10 05:22:31 DEBUG : : Looking for writers 2021/11/10 05:22:31 DEBUG : dir: reading active writers 2021/11/10 05:22:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms 2021/11/10 05:22:31 DEBUG : dir: Looking for writers 2021/11/10 05:22:31 DEBUG : file1: reading active writers 2021/11/10 05:22:31 DEBUG : : Looking for writers 2021/11/10 05:22:31 DEBUG : dir: reading active writers 2021/11/10 05:22:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms 2021/11/10 05:22:31 DEBUG : dir: Looking for writers 2021/11/10 05:22:31 DEBUG : file1: reading active writers 2021/11/10 05:22:31 DEBUG : : Looking for writers 2021/11/10 05:22:31 DEBUG : dir: reading active writers 2021/11/10 05:22:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms 2021/11/10 05:22:31 DEBUG : dir/file1: vfs cache: starting upload 2021/11/10 05:22:31 DEBUG : dir: Looking for writers 2021/11/10 05:22:31 DEBUG : file1: reading active writers 2021/11/10 05:22:31 DEBUG : : Looking for writers 2021/11/10 05:22:31 DEBUG : dir: reading active writers 2021/11/10 05:22:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms 2021/11/10 05:22:31 DEBUG : dir: Looking for writers 2021/11/10 05:22:31 DEBUG : file1: reading active writers 2021/11/10 05:22:31 DEBUG : : Looking for writers 2021/11/10 05:22:31 DEBUG : dir: reading active writers 2021/11/10 05:22:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms 2021/11/10 05:22:32 DEBUG : dir: Looking for writers 2021/11/10 05:22:32 DEBUG : file1: reading active writers 2021/11/10 05:22:32 DEBUG : : Looking for writers 2021/11/10 05:22:32 DEBUG : dir: reading active writers 2021/11/10 05:22:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms 2021/11/10 05:22:32 DEBUG : dir: Looking for writers 2021/11/10 05:22:32 DEBUG : file1: reading active writers 2021/11/10 05:22:32 DEBUG : : Looking for writers 2021/11/10 05:22:32 DEBUG : dir: reading active writers 2021/11/10 05:22:32 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/11/10 05:22:33 DEBUG : dir: Looking for writers 2021/11/10 05:22:33 DEBUG : file1: reading active writers 2021/11/10 05:22:33 DEBUG : : Looking for writers 2021/11/10 05:22:33 DEBUG : dir: reading active writers 2021/11/10 05:22:33 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/11/10 05:22:34 DEBUG : dir: Looking for writers 2021/11/10 05:22:34 DEBUG : file1: reading active writers 2021/11/10 05:22:34 DEBUG : : Looking for writers 2021/11/10 05:22:34 DEBUG : dir: reading active writers 2021/11/10 05:22:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s 2021/11/10 05:22:35 INFO : dir/file1: Copied (replaced existing) 2021/11/10 05:22:35 DEBUG : dir/file1: vfs cache: fingerprint now "5" 2021/11/10 05:22:35 DEBUG : dir/file1: vfs cache: writeback object to VFS layer 2021/11/10 05:22:35 DEBUG : dir: Added virtual directory entry vAddFile: "file1" 2021/11/10 05:22:35 INFO : dir/file1: vfs cache: upload succeeded try #1 2021/11/10 05:22:35 DEBUG : dir: Looking for writers 2021/11/10 05:22:35 DEBUG : file1: reading active writers 2021/11/10 05:22:35 DEBUG : : Looking for writers 2021/11/10 05:22:35 DEBUG : dir: reading active writers 2021/11/10 05:22:35 DEBUG : >WaitForWriters: 2021/11/10 05:22:35 DEBUG : vfs cache: cleaner exiting --- PASS: TestRWFileHandleSizeTruncateExisting (21.83s) === RUN TestVFSNew run.go:181: Remote "Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0'", Local "Local file system at /tmp/rclone3720595163", Modify Window "876000h0m0s" 2021/11/10 05:22:37 INFO : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': poll-interval is not supported by this remote 2021/11/10 05:22:37 NOTICE: Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2021/11/10 05:22:37 DEBUG : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': Re-using VFS from active cache 2021/11/10 05:22:37 DEBUG : WaitForWriters: timeout=30s 2021/11/10 05:22:37 DEBUG : : Looking for writers 2021/11/10 05:22:37 DEBUG : >WaitForWriters: --- PASS: TestVFSNew (0.80s) PASS 2021/11/10 05:22:39 DEBUG : Uptobox root 'rclone-test-rimapip5xiluhuc8kisoxof0': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestUptobox: -verbose -test.run '^(TestDirRemoveName|TestFileOpenRead|TestFileSetModTime|TestRWFileHandleSizeTruncateExisting|TestRcGetVFS|TestVFSNew)$/^(cache=off,open=false,write=false|cache=off,open=true,write=false)$'" - Finished OK in 1m5.436308171s (try 2/5)