"./vfs.test -test.v -test.timeout 2h0m0s -remote TestPutio: -verbose -test.run '^(TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestWriteFileHandleFlush|TestWriteFileModTimeWithOpenWriters)$'" - Starting (try 4/5) 2022/03/23 05:38:46 DEBUG : Creating backend with remote "TestPutio:rclone-test-rimojiw7fatumeg5koceban6" 2022/03/23 05:38:46 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2022/03/23 05:38:47 DEBUG : Creating backend with remote "/tmp/rclone924494356" === RUN TestWriteFileHandleFlush run.go:181: Remote "Putio root 'rclone-test-rimojiw7fatumeg5koceban6'", Local "Local file system at /tmp/rclone924494356", Modify Window "1s" 2022/03/23 05:38:47 INFO : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': poll-interval is not supported by this remote 2022/03/23 05:38:47 NOTICE: Putio root 'rclone-test-rimojiw7fatumeg5koceban6': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2022/03/23 05:38:47 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/03/23 05:38:47 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/03/23 05:38:47 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:38:47 DEBUG : file1: >Open: fd=file1 (w), err= 2022/03/23 05:38:47 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/03/23 05:38:47 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions 2022/03/23 05:38:47 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:38:47 DEBUG : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': File to upload is small (5 bytes), uploading instead of streaming 2022/03/23 05:38:47 ERROR : file1: Failed to copy: unexpected status code from upload create: 429 2022/03/23 05:38:47 ERROR : file1: WriteFileHandle.New Rcat failed: unexpected status code from upload create: 429 2022/03/23 05:38:47 ERROR : file1: WriteFileHandle.Flush error: unexpected status code from upload create: 429 write_test.go:198: Error Trace: write_test.go:198 Error: Received unexpected error: unexpected status code from upload create: 429 Test: TestWriteFileHandleFlush 2022/03/23 05:38:47 DEBUG : file1: WriteFileHandle.Flush nothing to do 2022/03/23 05:38:47 DEBUG : WaitForWriters: timeout=30s 2022/03/23 05:38:47 DEBUG : : Looking for writers 2022/03/23 05:38:47 DEBUG : file1: reading active writers 2022/03/23 05:38:47 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileHandleFlush (0.60s) === RUN TestWriteFileModTimeWithOpenWriters run.go:181: Remote "Putio root 'rclone-test-rimojiw7fatumeg5koceban6'", Local "Local file system at /tmp/rclone924494356", Modify Window "1s" 2022/03/23 05:38:47 INFO : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': poll-interval is not supported by this remote 2022/03/23 05:38:47 NOTICE: Putio root 'rclone-test-rimojiw7fatumeg5koceban6': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2022/03/23 05:38:47 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/03/23 05:38:47 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/03/23 05:38:47 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:38:47 DEBUG : file1: >Open: fd=file1 (w), err= 2022/03/23 05:38:47 DEBUG : file1: >OpenFile: fd=file1 (w), err= run.go:287: Failed to put "time_test" to "Putio root 'rclone-test-rimojiw7fatumeg5koceban6'": unexpected status code from upload create: 429 2022/03/23 05:38:48 DEBUG : WaitForWriters: timeout=30s 2022/03/23 05:38:48 DEBUG : : Looking for writers 2022/03/23 05:38:48 DEBUG : file1: reading active writers 2022/03/23 05:38:48 DEBUG : file1: active writers 1 2022/03/23 05:38:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms 2022/03/23 05:38:48 DEBUG : : Looking for writers 2022/03/23 05:38:48 DEBUG : file1: reading active writers 2022/03/23 05:38:48 DEBUG : file1: active writers 1 2022/03/23 05:38:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms 2022/03/23 05:38:48 DEBUG : : Looking for writers 2022/03/23 05:38:48 DEBUG : file1: reading active writers 2022/03/23 05:38:48 DEBUG : file1: active writers 1 2022/03/23 05:38:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms 2022/03/23 05:38:48 DEBUG : : Looking for writers 2022/03/23 05:38:48 DEBUG : file1: reading active writers 2022/03/23 05:38:48 DEBUG : file1: active writers 1 2022/03/23 05:38:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms 2022/03/23 05:38:48 DEBUG : : Looking for writers 2022/03/23 05:38:48 DEBUG : file1: reading active writers 2022/03/23 05:38:48 DEBUG : file1: active writers 1 2022/03/23 05:38:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms 2022/03/23 05:38:48 DEBUG : : Looking for writers 2022/03/23 05:38:48 DEBUG : file1: reading active writers 2022/03/23 05:38:48 DEBUG : file1: active writers 1 2022/03/23 05:38:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms 2022/03/23 05:38:48 DEBUG : : Looking for writers 2022/03/23 05:38:48 DEBUG : file1: reading active writers 2022/03/23 05:38:48 DEBUG : file1: active writers 1 2022/03/23 05:38:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms 2022/03/23 05:38:49 DEBUG : : Looking for writers 2022/03/23 05:38:49 DEBUG : file1: reading active writers 2022/03/23 05:38:49 DEBUG : file1: active writers 1 2022/03/23 05:38:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:50 DEBUG : : Looking for writers 2022/03/23 05:38:50 DEBUG : file1: reading active writers 2022/03/23 05:38:50 DEBUG : file1: active writers 1 2022/03/23 05:38:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:51 DEBUG : : Looking for writers 2022/03/23 05:38:51 DEBUG : file1: reading active writers 2022/03/23 05:38:51 DEBUG : file1: active writers 1 2022/03/23 05:38:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:52 DEBUG : : Looking for writers 2022/03/23 05:38:52 DEBUG : file1: reading active writers 2022/03/23 05:38:52 DEBUG : file1: active writers 1 2022/03/23 05:38:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:53 DEBUG : : Looking for writers 2022/03/23 05:38:53 DEBUG : file1: reading active writers 2022/03/23 05:38:53 DEBUG : file1: active writers 1 2022/03/23 05:38:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:54 DEBUG : : Looking for writers 2022/03/23 05:38:54 DEBUG : file1: reading active writers 2022/03/23 05:38:54 DEBUG : file1: active writers 1 2022/03/23 05:38:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:55 DEBUG : : Looking for writers 2022/03/23 05:38:55 DEBUG : file1: reading active writers 2022/03/23 05:38:55 DEBUG : file1: active writers 1 2022/03/23 05:38:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:56 DEBUG : : Looking for writers 2022/03/23 05:38:56 DEBUG : file1: reading active writers 2022/03/23 05:38:56 DEBUG : file1: active writers 1 2022/03/23 05:38:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:57 DEBUG : : Looking for writers 2022/03/23 05:38:57 DEBUG : file1: reading active writers 2022/03/23 05:38:57 DEBUG : file1: active writers 1 2022/03/23 05:38:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:58 DEBUG : : Looking for writers 2022/03/23 05:38:58 DEBUG : file1: reading active writers 2022/03/23 05:38:58 DEBUG : file1: active writers 1 2022/03/23 05:38:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:38:59 DEBUG : : Looking for writers 2022/03/23 05:38:59 DEBUG : file1: reading active writers 2022/03/23 05:38:59 DEBUG : file1: active writers 1 2022/03/23 05:38:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:00 DEBUG : : Looking for writers 2022/03/23 05:39:00 DEBUG : file1: reading active writers 2022/03/23 05:39:00 DEBUG : file1: active writers 1 2022/03/23 05:39:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:01 DEBUG : : Looking for writers 2022/03/23 05:39:01 DEBUG : file1: reading active writers 2022/03/23 05:39:01 DEBUG : file1: active writers 1 2022/03/23 05:39:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:02 DEBUG : : Looking for writers 2022/03/23 05:39:02 DEBUG : file1: reading active writers 2022/03/23 05:39:02 DEBUG : file1: active writers 1 2022/03/23 05:39:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:03 DEBUG : : Looking for writers 2022/03/23 05:39:03 DEBUG : file1: reading active writers 2022/03/23 05:39:03 DEBUG : file1: active writers 1 2022/03/23 05:39:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:04 DEBUG : : Looking for writers 2022/03/23 05:39:04 DEBUG : file1: reading active writers 2022/03/23 05:39:04 DEBUG : file1: active writers 1 2022/03/23 05:39:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:05 DEBUG : : Looking for writers 2022/03/23 05:39:05 DEBUG : file1: reading active writers 2022/03/23 05:39:05 DEBUG : file1: active writers 1 2022/03/23 05:39:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:06 DEBUG : : Looking for writers 2022/03/23 05:39:06 DEBUG : file1: reading active writers 2022/03/23 05:39:06 DEBUG : file1: active writers 1 2022/03/23 05:39:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:07 DEBUG : : Looking for writers 2022/03/23 05:39:07 DEBUG : file1: reading active writers 2022/03/23 05:39:07 DEBUG : file1: active writers 1 2022/03/23 05:39:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:08 DEBUG : : Looking for writers 2022/03/23 05:39:08 DEBUG : file1: reading active writers 2022/03/23 05:39:08 DEBUG : file1: active writers 1 2022/03/23 05:39:08 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:09 DEBUG : : Looking for writers 2022/03/23 05:39:09 DEBUG : file1: reading active writers 2022/03/23 05:39:09 DEBUG : file1: active writers 1 2022/03/23 05:39:09 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:10 DEBUG : : Looking for writers 2022/03/23 05:39:10 DEBUG : file1: reading active writers 2022/03/23 05:39:10 DEBUG : file1: active writers 1 2022/03/23 05:39:10 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:11 DEBUG : : Looking for writers 2022/03/23 05:39:11 DEBUG : file1: reading active writers 2022/03/23 05:39:11 DEBUG : file1: active writers 1 2022/03/23 05:39:11 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:12 DEBUG : : Looking for writers 2022/03/23 05:39:12 DEBUG : file1: reading active writers 2022/03/23 05:39:12 DEBUG : file1: active writers 1 2022/03/23 05:39:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:13 DEBUG : : Looking for writers 2022/03/23 05:39:13 DEBUG : file1: reading active writers 2022/03/23 05:39:13 DEBUG : file1: active writers 1 2022/03/23 05:39:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:14 DEBUG : : Looking for writers 2022/03/23 05:39:14 DEBUG : file1: reading active writers 2022/03/23 05:39:14 DEBUG : file1: active writers 1 2022/03/23 05:39:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:15 DEBUG : : Looking for writers 2022/03/23 05:39:15 DEBUG : file1: reading active writers 2022/03/23 05:39:15 DEBUG : file1: active writers 1 2022/03/23 05:39:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:16 DEBUG : : Looking for writers 2022/03/23 05:39:16 DEBUG : file1: reading active writers 2022/03/23 05:39:16 DEBUG : file1: active writers 1 2022/03/23 05:39:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:17 DEBUG : : Looking for writers 2022/03/23 05:39:17 DEBUG : file1: reading active writers 2022/03/23 05:39:17 DEBUG : file1: active writers 1 2022/03/23 05:39:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s 2022/03/23 05:39:18 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s Cache: 2022/03/23 05:39:18 DEBUG : >WaitForWriters: --- FAIL: TestWriteFileModTimeWithOpenWriters (30.43s) === RUN TestFileReadAtZeroLength run.go:181: Remote "Putio root 'rclone-test-rimojiw7fatumeg5koceban6'", Local "Local file system at /tmp/rclone924494356", Modify Window "1s" 2022/03/23 05:39:18 INFO : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': poll-interval is not supported by this remote 2022/03/23 05:39:18 NOTICE: Putio root 'rclone-test-rimojiw7fatumeg5koceban6': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2022/03/23 05:39:18 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/03/23 05:39:18 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/03/23 05:39:18 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:39:18 DEBUG : file1: >Open: fd=file1 (w), err= 2022/03/23 05:39:18 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/03/23 05:39:18 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:39:18 DEBUG : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': File to upload is small (0 bytes), uploading instead of streaming 2022/03/23 05:39:19 DEBUG : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': Sending zero length chunk 2022/03/23 05:39:19 DEBUG : file1: crc32 = 00000000 OK 2022/03/23 05:39:19 INFO : file1: Copied (new) 2022/03/23 05:39:19 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:39:19 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2022/03/23 05:39:19 DEBUG : file1: Open: flags=O_RDONLY 2022/03/23 05:39:19 DEBUG : file1: >Open: fd=file1 (r), err= 2022/03/23 05:39:19 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2022/03/23 05:39:19 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2022/03/23 05:39:19 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2022/03/23 05:39:19 DEBUG : WaitForWriters: timeout=30s 2022/03/23 05:39:19 DEBUG : : Looking for writers 2022/03/23 05:39:19 DEBUG : file1: reading active writers 2022/03/23 05:39:19 DEBUG : >WaitForWriters: --- PASS: TestFileReadAtZeroLength (1.87s) === RUN TestFileReadAtNonZeroLength run.go:181: Remote "Putio root 'rclone-test-rimojiw7fatumeg5koceban6'", Local "Local file system at /tmp/rclone924494356", Modify Window "1s" 2022/03/23 05:39:20 INFO : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': poll-interval is not supported by this remote 2022/03/23 05:39:20 NOTICE: Putio root 'rclone-test-rimojiw7fatumeg5koceban6': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2022/03/23 05:39:20 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx 2022/03/23 05:39:20 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE 2022/03/23 05:39:20 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:39:20 DEBUG : file1: >Open: fd=file1 (w), err= 2022/03/23 05:39:20 DEBUG : file1: >OpenFile: fd=file1 (w), err= 2022/03/23 05:39:20 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:39:20 DEBUG : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': File to upload is small (100 bytes), uploading instead of streaming 2022/03/23 05:39:20 DEBUG : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': chunkStart: 0, reqSize: 100 2022/03/23 05:39:20 DEBUG : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': Sending chunk. transferOffset: 0 length: 100 2022/03/23 05:39:21 DEBUG : file1: crc32 = f6f5a48b OK 2022/03/23 05:39:21 INFO : file1: Copied (new) 2022/03/23 05:39:21 DEBUG : : Added virtual directory entry vAddFile: "file1" 2022/03/23 05:39:21 DEBUG : file1: OpenFile: flags=O_RDONLY, perm=---------- 2022/03/23 05:39:21 DEBUG : file1: Open: flags=O_RDONLY 2022/03/23 05:39:21 DEBUG : file1: >Open: fd=file1 (r), err= 2022/03/23 05:39:21 DEBUG : file1: >OpenFile: fd=file1 (r), err= 2022/03/23 05:39:21 DEBUG : file1: ChunkedReader.openRange at 0 length 134217728 2022/03/23 05:39:21 DEBUG : file1: ChunkedReader.Read at 0 length 1024 chunkOffset 0 chunkSize 134217728 2022/03/23 05:39:21 DEBUG : WaitForWriters: timeout=30s 2022/03/23 05:39:21 DEBUG : : Looking for writers 2022/03/23 05:39:21 DEBUG : file1: reading active writers 2022/03/23 05:39:21 DEBUG : >WaitForWriters: --- PASS: TestFileReadAtNonZeroLength (2.09s) FAIL 2022/03/23 05:39:22 DEBUG : Putio root 'rclone-test-rimojiw7fatumeg5koceban6': Purge remote "./vfs.test -test.v -test.timeout 2h0m0s -remote TestPutio: -verbose -test.run '^(TestFileReadAtNonZeroLength|TestFileReadAtZeroLength|TestWriteFileHandleFlush|TestWriteFileModTimeWithOpenWriters)$'" - Finished ERROR in 35.409635765s (try 4/5): exit status 1: Failed [TestWriteFileHandleFlush TestWriteFileModTimeWithOpenWriters]