"./vfs.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^TestDirReadDirAll$/^Virtual$|^TestReadFileHandleReadAt$'" - Starting (try 3/5) 2026/06/25 02:41:52 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-raxozek2xase" 2026/06/25 02:41:52 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/06/25 02:41:53 DEBUG : Creating backend with remote "/tmp/rclone652186660" === RUN TestDirReadDirAll run.go:198: Remote "files root 'rclone-test-raxozek2xase'", Local "Local file system at /tmp/rclone652186660", Modify Window "1s" 2026/06/25 02:41:53 INFO : files root 'rclone-test-raxozek2xase': poll-interval is not supported by this remote === RUN TestDirReadDirAll/Virtual 2026/06/25 02:41:58 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile" 2026/06/25 02:41:58 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir" 2026/06/25 02:41:58 DEBUG : dir: Added virtual directory entry vDel: "file2" 2026/06/25 02:41:58 DEBUG : dir: Added virtual directory entry vDel: "subdir" 2026/06/25 02:42:00 DEBUG : dir: invalidating directory cache 2026/06/25 02:42:00 DEBUG : dir: Removed virtual directory entry vDel: "subdir" 2026/06/25 02:42:00 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir" 2026/06/25 02:42:00 DEBUG : dir: Removed virtual directory entry vDel: "file2" 2026/06/25 02:42:00 DEBUG : dir/file1: Reset virtual modtime 2026/06/25 02:42:00 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile" 2026/06/25 02:42:00 DEBUG : dir/virtualFile: Reset virtual modtime 2026/06/25 02:42:00 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2" 2026/06/25 02:42:00 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2" 2026/06/25 02:42:00 DEBUG : dir: Added virtual directory entry vDel: "file1" 2026/06/25 02:42:00 DEBUG : dir: invalidating directory cache 2026/06/25 02:42:00 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2" 2026/06/25 02:42:00 DEBUG : dir: Removed virtual directory entry vDel: "file1" 2026/06/25 02:42:00 DEBUG : dir/virtualFile: Reset virtual modtime 2026/06/25 02:42:00 DEBUG : forgetting directory cache 2026/06/25 02:42:00 DEBUG : dir: forgetting directory cache 2026/06/25 02:42:00 DEBUG : dir/virtualDir: forgetting directory cache 2026/06/25 02:42:00 DEBUG : WaitForWriters: timeout=30s 2026/06/25 02:42:00 DEBUG : dir/virtualDir: Looking for writers 2026/06/25 02:42:00 DEBUG : dir: Looking for writers 2026/06/25 02:42:00 DEBUG : virtualDir: reading active writers 2026/06/25 02:42:00 DEBUG : file1: reading active writers 2026/06/25 02:42:00 DEBUG : virtualFile2: reading active writers 2026/06/25 02:42:00 DEBUG : virtualFile: reading active writers 2026/06/25 02:42:00 DEBUG : Looking for writers 2026/06/25 02:42:00 DEBUG : dir: reading active writers 2026/06/25 02:42:00 DEBUG : >WaitForWriters: 2026/06/25 02:42:01 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-raxozek2xase/dir not empty`) 2026/06/25 02:42:01 DEBUG : pacer: Rate limited, increasing sleep to 20ms 2026/06/25 02:42:01 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-raxozek2xase/dir not empty`) 2026/06/25 02:42:01 DEBUG : pacer: Rate limited, increasing sleep to 40ms 2026/06/25 02:42:01 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-raxozek2xase/dir not empty`) 2026/06/25 02:42:01 DEBUG : pacer: Rate limited, increasing sleep to 80ms 2026/06/25 02:42:02 DEBUG : pacer: Reducing sleep to 60ms 2026/06/25 02:42:02 DEBUG : pacer: Reducing sleep to 45ms --- PASS: TestDirReadDirAll (8.67s) --- PASS: TestDirReadDirAll/Virtual (2.47s) === RUN TestReadFileHandleReadAt run.go:198: Remote "files root 'rclone-test-raxozek2xase'", Local "Local file system at /tmp/rclone652186660", Modify Window "1s" 2026/06/25 02:42:02 INFO : files root 'rclone-test-raxozek2xase': poll-interval is not supported by this remote 2026/06/25 02:42:02 DEBUG : pacer: Reducing sleep to 33.75ms 2026/06/25 02:42:03 DEBUG : pacer: Reducing sleep to 25.3125ms 2026/06/25 02:42:03 DEBUG : pacer: Reducing sleep to 18.984375ms 2026/06/25 02:42:03 DEBUG : pacer: Reducing sleep to 14.238281ms 2026/06/25 02:42:03 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2026/06/25 02:42:03 DEBUG : pacer: Reducing sleep to 10.67871ms 2026/06/25 02:42:03 DEBUG : pacer: Reducing sleep to 10ms 2026/06/25 02:42:03 DEBUG : dir/file1: Open: flags=O_RDONLY 2026/06/25 02:42:03 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2026/06/25 02:42:03 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2026/06/25 02:42:03 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2026/06/25 02:42:03 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2026/06/25 02:42:03 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms 2026/06/25 02:42:03 DEBUG : dir/file1: aborting in-sequence read wait, off=5 2026/06/25 02:42:03 DEBUG : dir/file1: failed to wait for in-sequence read to 5 2026/06/25 02:42:03 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker) 2026/06/25 02:42:03 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1 2026/06/25 02:42:03 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728 2026/06/25 02:42:03 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728 2026/06/25 02:42:04 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker) 2026/06/25 02:42:04 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1 2026/06/25 02:42:04 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728 2026/06/25 02:42:04 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728 2026/06/25 02:42:04 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms 2026/06/25 02:42:04 DEBUG : dir/file1: aborting in-sequence read wait, off=10 2026/06/25 02:42:04 DEBUG : dir/file1: failed to wait for in-sequence read to 10 2026/06/25 02:42:04 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker) 2026/06/25 02:42:04 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1 2026/06/25 02:42:04 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728 2026/06/25 02:42:04 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2026/06/25 02:42:05 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker) 2026/06/25 02:42:05 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1 2026/06/25 02:42:05 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728 2026/06/25 02:42:05 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728 2026/06/25 02:42:05 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2026/06/25 02:42:05 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2026/06/25 02:42:05 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2026/06/25 02:42:05 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16 2026/06/25 02:42:05 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms 2026/06/25 02:42:05 DEBUG : dir/file1: aborting in-sequence read wait, off=100 2026/06/25 02:42:05 DEBUG : dir/file1: failed to wait for in-sequence read to 100 2026/06/25 02:42:05 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor 2026/06/25 02:42:05 DEBUG : WaitForWriters: timeout=30s 2026/06/25 02:42:05 DEBUG : dir: Looking for writers 2026/06/25 02:42:05 DEBUG : file1: reading active writers 2026/06/25 02:42:05 DEBUG : Looking for writers 2026/06/25 02:42:05 DEBUG : dir: reading active writers 2026/06/25 02:42:05 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleReadAt (4.23s) PASS 2026/06/25 02:42:06 DEBUG : files root 'rclone-test-raxozek2xase': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^TestDirReadDirAll$/^Virtual$|^TestReadFileHandleReadAt$'" - Finished OK in 13.85847043s (try 3/5)