"./vfs.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestReadFileHandleSeek|TestWriteFileModTimeWithOpenWriters)$|^TestFileSetModTime$/^(cache=full,open=false,write=false|cache=full,open=true,write=false|cache=off,open=false,write=false|cache=off,open=true,write=false|cache=off,open=true,write=true)$'" - Starting (try 2/5)
2026/04/12 01:57:07 DEBUG : Creating backend with remote "TestDropbox:rclone-test-yeqaqem1basu"
2026/04/12 01:57:07 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/04/12 01:57:07 DEBUG : Creating backend with remote "/tmp/rclone763572564"
=== RUN   TestFileSetModTime
=== RUN   TestFileSetModTime/cache=off,open=false,write=false
    run.go:185: Remote "Dropbox root 'rclone-test-yeqaqem1basu'", Local "Local file system at /tmp/rclone763572564", Modify Window "1s"
2026/04/12 01:57:08 INFO  : Dropbox root 'rclone-test-yeqaqem1basu': Failed to get StartCursor: path/not_found/.
2026/04/12 01:57:08 DEBUG : pacer: low level retry 1/10 (error too_many_write_operations/..)
2026/04/12 01:57:08 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2026/04/12 01:57:09 DEBUG : pacer: low level retry 2/10 (error too_many_write_operations/)
2026/04/12 01:57:09 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2026/04/12 01:57:09 DEBUG : pacer: Reducing sleep to 30ms
2026/04/12 01:57:10 DEBUG : pacer: Reducing sleep to 22.5ms
2026/04/12 01:57:10 DEBUG : dir/file1: Uploading chunk 1/1
2026/04/12 01:57:10 DEBUG : pacer: Reducing sleep to 16.875ms
2026/04/12 01:57:10 DEBUG : dir/file1: Uploading chunk 2/1
2026/04/12 01:57:11 DEBUG : pacer: Reducing sleep to 12.65625ms
2026/04/12 01:57:11 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Adding "dir/file1" to batch
2026/04/12 01:57:11 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Batch idle for 500ms so committing
2026/04/12 01:57:11 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Committing sync batch length 1 starting with: dir/file1
2026/04/12 01:57:13 DEBUG : pacer: Reducing sleep to 10ms
2026/04/12 01:57:13 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Committed sync batch length 1 starting with: dir/file1
2026/04/12 01:57:14 DEBUG : time_test: Uploading chunk 1/1
2026/04/12 01:57:15 DEBUG : time_test: Uploading chunk 2/1
2026/04/12 01:57:15 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Adding "time_test" to batch
2026/04/12 01:57:16 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Batch idle for 500ms so committing
2026/04/12 01:57:16 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Committing sync batch length 1 starting with: time_test
2026/04/12 01:57:16 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Committed sync batch length 1 starting with: time_test
2026/04/12 01:57:17 DEBUG : Can set mod time: false
    file_test.go:97: can't set mod time
2026/04/12 01:57:17 DEBUG : WaitForWriters: timeout=30s
2026/04/12 01:57:17 DEBUG : dir: Looking for writers
2026/04/12 01:57:17 DEBUG : file1: reading active writers
2026/04/12 01:57:17 DEBUG : Looking for writers
2026/04/12 01:57:17 DEBUG : dir: reading active writers
2026/04/12 01:57:17 DEBUG : >WaitForWriters: 
=== RUN   TestFileSetModTime/cache=off,open=true,write=false
    file_test.go:93: can't set mod time
=== RUN   TestFileSetModTime/cache=off,open=true,write=true
    file_test.go:93: can't set mod time
=== RUN   TestFileSetModTime/cache=full,open=false,write=false
    file_test.go:93: can't set mod time
=== RUN   TestFileSetModTime/cache=full,open=true,write=false
    file_test.go:93: can't set mod time
--- PASS: TestFileSetModTime (12.11s)
    --- SKIP: TestFileSetModTime/cache=off,open=false,write=false (12.10s)
    --- SKIP: TestFileSetModTime/cache=off,open=true,write=false (0.00s)
    --- SKIP: TestFileSetModTime/cache=off,open=true,write=true (0.00s)
    --- SKIP: TestFileSetModTime/cache=full,open=false,write=false (0.00s)
    --- SKIP: TestFileSetModTime/cache=full,open=true,write=false (0.00s)
=== RUN   TestReadFileHandleSeek
    run.go:185: Remote "Dropbox root 'rclone-test-yeqaqem1basu'", Local "Local file system at /tmp/rclone763572564", Modify Window "1s"
2026/04/12 01:57:20 DEBUG : dir/file1: Uploading chunk 1/1
2026/04/12 01:57:21 DEBUG : dir/file1: Uploading chunk 2/1
2026/04/12 01:57:21 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Adding "dir/file1" to batch
2026/04/12 01:57:22 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Batch idle for 500ms so committing
2026/04/12 01:57:22 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Committing sync batch length 1 starting with: dir/file1
2026/04/12 01:57:22 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Committed sync batch length 1 starting with: dir/file1
2026/04/12 01:57:23 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/04/12 01:57:23 DEBUG : dir/file1: Open: flags=O_RDONLY
2026/04/12 01:57:23 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2026/04/12 01:57:23 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2026/04/12 01:57:23 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2026/04/12 01:57:24 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2026/04/12 01:57:24 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms
2026/04/12 01:57:24 DEBUG : dir/file1: aborting in-sequence read wait, off=5
2026/04/12 01:57:24 DEBUG : dir/file1: failed to wait for in-sequence read to 5
2026/04/12 01:57:24 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker)
2026/04/12 01:57:24 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1
2026/04/12 01:57:24 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728
2026/04/12 01:57:24 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2026/04/12 01:57:25 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker)
2026/04/12 01:57:25 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1
2026/04/12 01:57:25 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728
2026/04/12 01:57:25 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728
2026/04/12 01:57:25 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker)
2026/04/12 01:57:25 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1
2026/04/12 01:57:25 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728
2026/04/12 01:57:25 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728
2026/04/12 01:57:26 DEBUG : WaitForWriters: timeout=30s
2026/04/12 01:57:26 DEBUG : dir: Looking for writers
2026/04/12 01:57:26 DEBUG : file1: reading active writers
2026/04/12 01:57:26 DEBUG : Looking for writers
2026/04/12 01:57:26 DEBUG : dir: reading active writers
2026/04/12 01:57:26 DEBUG : >WaitForWriters: 
--- PASS: TestReadFileHandleSeek (9.08s)
=== RUN   TestWriteFileModTimeWithOpenWriters
    run.go:185: Remote "Dropbox root 'rclone-test-yeqaqem1basu'", Local "Local file system at /tmp/rclone763572564", Modify Window "1s"
2026/04/12 01:57:29 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/04/12 01:57:29 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/04/12 01:57:29 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/04/12 01:57:29 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/04/12 01:57:29 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
    write_test.go:321: can't set mod time
2026/04/12 01:57:29 DEBUG : WaitForWriters: timeout=30s
2026/04/12 01:57:29 DEBUG : Looking for writers
2026/04/12 01:57:29 DEBUG : file1: reading active writers
2026/04/12 01:57:29 DEBUG : file1: active writers 1
2026/04/12 01:57:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms
2026/04/12 01:57:29 DEBUG : Looking for writers
2026/04/12 01:57:29 DEBUG : file1: reading active writers
2026/04/12 01:57:29 DEBUG : file1: active writers 1
2026/04/12 01:57:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms
2026/04/12 01:57:29 DEBUG : Looking for writers
2026/04/12 01:57:29 DEBUG : file1: reading active writers
2026/04/12 01:57:29 DEBUG : file1: active writers 1
2026/04/12 01:57:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms
2026/04/12 01:57:29 DEBUG : Looking for writers
2026/04/12 01:57:29 DEBUG : file1: reading active writers
2026/04/12 01:57:29 DEBUG : file1: active writers 1
2026/04/12 01:57:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms
2026/04/12 01:57:29 DEBUG : Looking for writers
2026/04/12 01:57:29 DEBUG : file1: reading active writers
2026/04/12 01:57:29 DEBUG : file1: active writers 1
2026/04/12 01:57:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms
2026/04/12 01:57:29 DEBUG : Looking for writers
2026/04/12 01:57:29 DEBUG : file1: reading active writers
2026/04/12 01:57:29 DEBUG : file1: active writers 1
2026/04/12 01:57:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms
2026/04/12 01:57:30 DEBUG : Looking for writers
2026/04/12 01:57:30 DEBUG : file1: reading active writers
2026/04/12 01:57:30 DEBUG : file1: active writers 1
2026/04/12 01:57:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms
2026/04/12 01:57:30 DEBUG : Looking for writers
2026/04/12 01:57:30 DEBUG : file1: reading active writers
2026/04/12 01:57:30 DEBUG : file1: active writers 1
2026/04/12 01:57:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:31 DEBUG : Looking for writers
2026/04/12 01:57:31 DEBUG : file1: reading active writers
2026/04/12 01:57:31 DEBUG : file1: active writers 1
2026/04/12 01:57:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:32 DEBUG : Looking for writers
2026/04/12 01:57:32 DEBUG : file1: reading active writers
2026/04/12 01:57:32 DEBUG : file1: active writers 1
2026/04/12 01:57:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:33 DEBUG : Looking for writers
2026/04/12 01:57:33 DEBUG : file1: reading active writers
2026/04/12 01:57:33 DEBUG : file1: active writers 1
2026/04/12 01:57:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:34 DEBUG : Looking for writers
2026/04/12 01:57:34 DEBUG : file1: reading active writers
2026/04/12 01:57:34 DEBUG : file1: active writers 1
2026/04/12 01:57:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:35 DEBUG : Looking for writers
2026/04/12 01:57:35 DEBUG : file1: reading active writers
2026/04/12 01:57:35 DEBUG : file1: active writers 1
2026/04/12 01:57:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:36 DEBUG : Looking for writers
2026/04/12 01:57:36 DEBUG : file1: reading active writers
2026/04/12 01:57:36 DEBUG : file1: active writers 1
2026/04/12 01:57:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:37 DEBUG : Looking for writers
2026/04/12 01:57:37 DEBUG : file1: reading active writers
2026/04/12 01:57:37 DEBUG : file1: active writers 1
2026/04/12 01:57:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:38 DEBUG : Looking for writers
2026/04/12 01:57:38 DEBUG : file1: reading active writers
2026/04/12 01:57:38 DEBUG : file1: active writers 1
2026/04/12 01:57:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:39 DEBUG : Looking for writers
2026/04/12 01:57:39 DEBUG : file1: reading active writers
2026/04/12 01:57:39 DEBUG : file1: active writers 1
2026/04/12 01:57:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:40 DEBUG : Looking for writers
2026/04/12 01:57:40 DEBUG : file1: reading active writers
2026/04/12 01:57:40 DEBUG : file1: active writers 1
2026/04/12 01:57:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:41 DEBUG : Looking for writers
2026/04/12 01:57:41 DEBUG : file1: reading active writers
2026/04/12 01:57:41 DEBUG : file1: active writers 1
2026/04/12 01:57:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:42 DEBUG : Looking for writers
2026/04/12 01:57:42 DEBUG : file1: reading active writers
2026/04/12 01:57:42 DEBUG : file1: active writers 1
2026/04/12 01:57:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:43 DEBUG : Looking for writers
2026/04/12 01:57:43 DEBUG : file1: reading active writers
2026/04/12 01:57:43 DEBUG : file1: active writers 1
2026/04/12 01:57:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:44 DEBUG : Looking for writers
2026/04/12 01:57:44 DEBUG : file1: reading active writers
2026/04/12 01:57:44 DEBUG : file1: active writers 1
2026/04/12 01:57:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:45 DEBUG : Looking for writers
2026/04/12 01:57:45 DEBUG : file1: reading active writers
2026/04/12 01:57:45 DEBUG : file1: active writers 1
2026/04/12 01:57:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:46 DEBUG : Looking for writers
2026/04/12 01:57:46 DEBUG : file1: reading active writers
2026/04/12 01:57:46 DEBUG : file1: active writers 1
2026/04/12 01:57:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:47 DEBUG : Looking for writers
2026/04/12 01:57:47 DEBUG : file1: reading active writers
2026/04/12 01:57:47 DEBUG : file1: active writers 1
2026/04/12 01:57:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:48 DEBUG : Looking for writers
2026/04/12 01:57:48 DEBUG : file1: reading active writers
2026/04/12 01:57:48 DEBUG : file1: active writers 1
2026/04/12 01:57:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:49 DEBUG : Looking for writers
2026/04/12 01:57:49 DEBUG : file1: reading active writers
2026/04/12 01:57:49 DEBUG : file1: active writers 1
2026/04/12 01:57:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:50 DEBUG : Looking for writers
2026/04/12 01:57:50 DEBUG : file1: reading active writers
2026/04/12 01:57:50 DEBUG : file1: active writers 1
2026/04/12 01:57:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:51 DEBUG : Looking for writers
2026/04/12 01:57:51 DEBUG : file1: reading active writers
2026/04/12 01:57:51 DEBUG : file1: active writers 1
2026/04/12 01:57:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:52 DEBUG : Looking for writers
2026/04/12 01:57:52 DEBUG : file1: reading active writers
2026/04/12 01:57:52 DEBUG : file1: active writers 1
2026/04/12 01:57:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:53 DEBUG : Looking for writers
2026/04/12 01:57:53 DEBUG : file1: reading active writers
2026/04/12 01:57:53 DEBUG : file1: active writers 1
2026/04/12 01:57:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:54 DEBUG : Looking for writers
2026/04/12 01:57:54 DEBUG : file1: reading active writers
2026/04/12 01:57:54 DEBUG : file1: active writers 1
2026/04/12 01:57:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:55 DEBUG : Looking for writers
2026/04/12 01:57:55 DEBUG : file1: reading active writers
2026/04/12 01:57:55 DEBUG : file1: active writers 1
2026/04/12 01:57:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:56 DEBUG : Looking for writers
2026/04/12 01:57:56 DEBUG : file1: reading active writers
2026/04/12 01:57:56 DEBUG : file1: active writers 1
2026/04/12 01:57:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:57 DEBUG : Looking for writers
2026/04/12 01:57:57 DEBUG : file1: reading active writers
2026/04/12 01:57:57 DEBUG : file1: active writers 1
2026/04/12 01:57:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:58 DEBUG : Looking for writers
2026/04/12 01:57:58 DEBUG : file1: reading active writers
2026/04/12 01:57:58 DEBUG : file1: active writers 1
2026/04/12 01:57:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/04/12 01:57:59 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s
Cache: <nil>
2026/04/12 01:57:59 DEBUG : >WaitForWriters: 
--- SKIP: TestWriteFileModTimeWithOpenWriters (31.01s)
PASS
2026/04/12 01:58:00 DEBUG : Dropbox root 'rclone-test-yeqaqem1basu': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^(TestReadFileHandleSeek|TestWriteFileModTimeWithOpenWriters)$|^TestFileSetModTime$/^(cache=full,open=false,write=false|cache=full,open=true,write=false|cache=off,open=false,write=false|cache=off,open=true,write=false|cache=off,open=true,write=true)$'" - Finished OK in 53.112139464s (try 2/5)