"./vfs.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestReadFileHandleReadAt|TestVFSMkdirAll)$'" - Starting (try 2/5)
2025/09/20 03:21:02 DEBUG : Creating backend with remote "TestOpenDrive:rclone-test-cawuhom8fabi"
2025/09/20 03:21:02 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/09/20 03:21:02 DEBUG : Starting OpenDrive session with ID: dcf8b45690f06efa37e4f38c0f70edd81aacbfc2105e044713521b0de45876da
2025/09/20 03:21:03 DEBUG : Creating backend with remote "/tmp/rclone869788906"
=== RUN   TestReadFileHandleReadAt
    run.go:180: Remote "OpenDrive root 'rclone-test-cawuhom8fabi'", Local "Local file system at /tmp/rclone869788906", Modify Window "1s"
2025/09/20 03:21:03 INFO  : OpenDrive root 'rclone-test-cawuhom8fabi': poll-interval is not supported by this remote
2025/09/20 03:21:03 NOTICE: OpenDrive root 'rclone-test-cawuhom8fabi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2025/09/20 03:21:04 DEBUG : dir/file1: Uploading chunk 0, size=16, remain=0
2025/09/20 03:21:06 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2025/09/20 03:21:06 DEBUG : dir/file1: Open: flags=O_RDONLY
2025/09/20 03:21:06 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2025/09/20 03:21:06 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2025/09/20 03:21:06 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2025/09/20 03:21:07 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2025/09/20 03:21:07 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms
2025/09/20 03:21:07 DEBUG : dir/file1: aborting in-sequence read wait, off=5
2025/09/20 03:21:07 DEBUG : dir/file1: failed to wait for in-sequence read to 5
2025/09/20 03:21:07 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker)
2025/09/20 03:21:07 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1
2025/09/20 03:21:07 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728
2025/09/20 03:21:07 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2025/09/20 03:21:07 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker)
2025/09/20 03:21:07 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1
2025/09/20 03:21:07 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728
2025/09/20 03:21:07 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728
2025/09/20 03:21:08 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms
2025/09/20 03:21:08 DEBUG : dir/file1: aborting in-sequence read wait, off=10
2025/09/20 03:21:08 DEBUG : dir/file1: failed to wait for in-sequence read to 10
2025/09/20 03:21:08 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker)
2025/09/20 03:21:08 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1
2025/09/20 03:21:08 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728
2025/09/20 03:21:08 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728
2025/09/20 03:21:08 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker)
2025/09/20 03:21:08 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1
2025/09/20 03:21:08 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728
2025/09/20 03:21:08 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728
2025/09/20 03:21:09 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms
2025/09/20 03:21:09 DEBUG : dir/file1: aborting in-sequence read wait, off=100
2025/09/20 03:21:09 DEBUG : dir/file1: failed to wait for in-sequence read to 100
2025/09/20 03:21:09 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16
2025/09/20 03:21:09 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms
2025/09/20 03:21:09 DEBUG : dir/file1: aborting in-sequence read wait, off=100
2025/09/20 03:21:09 DEBUG : dir/file1: failed to wait for in-sequence read to 100
2025/09/20 03:21:09 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor
2025/09/20 03:21:09 DEBUG : WaitForWriters: timeout=30s
2025/09/20 03:21:09 DEBUG : dir: Looking for writers
2025/09/20 03:21:09 DEBUG : file1: reading active writers
2025/09/20 03:21:09 DEBUG : Looking for writers
2025/09/20 03:21:09 DEBUG : dir: reading active writers
2025/09/20 03:21:09 DEBUG : >WaitForWriters: 
--- PASS: TestReadFileHandleReadAt (7.39s)
=== RUN   TestVFSMkdirAll
    run.go:180: Remote "OpenDrive root 'rclone-test-cawuhom8fabi'", Local "Local file system at /tmp/rclone869788906", Modify Window "1s"
2025/09/20 03:21:10 INFO  : OpenDrive root 'rclone-test-cawuhom8fabi': poll-interval is not supported by this remote
2025/09/20 03:21:10 NOTICE: OpenDrive root 'rclone-test-cawuhom8fabi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2025/09/20 03:21:11 DEBUG : Added virtual directory entry vAddDir: "a"
2025/09/20 03:21:12 DEBUG : a: Added virtual directory entry vAddDir: "b"
2025/09/20 03:21:12 DEBUG : a/b: Added virtual directory entry vAddDir: "c"
2025/09/20 03:21:13 DEBUG : a/b/c: Added virtual directory entry vAddDir: "d"
2025/09/20 03:21:16 DEBUG : WaitForWriters: timeout=30s
2025/09/20 03:21:16 DEBUG : a/b/c/d: Looking for writers
2025/09/20 03:21:16 DEBUG : a/b/c: Looking for writers
2025/09/20 03:21:16 DEBUG : d: reading active writers
2025/09/20 03:21:16 DEBUG : a/b: Looking for writers
2025/09/20 03:21:16 DEBUG : c: reading active writers
2025/09/20 03:21:16 DEBUG : a: Looking for writers
2025/09/20 03:21:16 DEBUG : b: reading active writers
2025/09/20 03:21:16 DEBUG : Looking for writers
2025/09/20 03:21:16 DEBUG : a: reading active writers
2025/09/20 03:21:16 DEBUG : >WaitForWriters: 
--- PASS: TestVFSMkdirAll (8.67s)
PASS
2025/09/20 03:21:19 DEBUG : OpenDrive root 'rclone-test-cawuhom8fabi': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestOpenDrive: -verbose -test.run '^(TestReadFileHandleReadAt|TestVFSMkdirAll)$'" - Finished OK in 17.574075012s (try 2/5)