"./vfs.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^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)$|^TestWriteFileModTimeWithOpenWriters$'" - Starting (try 2/5)
2025/12/21 01:25:13 DEBUG : Creating backend with remote "TestDropbox:rclone-test-qegiker2baja"
2025/12/21 01:25:13 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/12/21 01:25:14 DEBUG : Creating backend with remote "/tmp/rclone3765138965"
=== RUN   TestFileSetModTime
=== RUN   TestFileSetModTime/cache=off,open=false,write=false
    run.go:185: Remote "Dropbox root 'rclone-test-qegiker2baja'", Local "Local file system at /tmp/rclone3765138965", Modify Window "1s"
2025/12/21 01:25:14 INFO  : Dropbox root 'rclone-test-qegiker2baja': Failed to get StartCursor: path/not_found/..
2025/12/21 01:25:15 DEBUG : dir/file1: Uploading chunk 1/1
2025/12/21 01:25:16 DEBUG : dir/file1: Uploading chunk 2/1
2025/12/21 01:25:16 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Adding "dir/file1" to batch
2025/12/21 01:25:17 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Batch idle for 500ms so committing
2025/12/21 01:25:17 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Committing sync batch length 1 starting with: dir/file1
2025/12/21 01:25:17 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Committed sync batch length 1 starting with: dir/file1
2025/12/21 01:25:19 DEBUG : time_test: Uploading chunk 1/1
2025/12/21 01:25:19 DEBUG : time_test: Uploading chunk 2/1
2025/12/21 01:25:20 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Adding "time_test" to batch
2025/12/21 01:25:21 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Batch idle for 500ms so committing
2025/12/21 01:25:21 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Committing sync batch length 1 starting with: time_test
2025/12/21 01:25:21 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Committed sync batch length 1 starting with: time_test
2025/12/21 01:25:22 DEBUG : Can set mod time: false
    file_test.go:97: can't set mod time
2025/12/21 01:25:22 DEBUG : WaitForWriters: timeout=30s
2025/12/21 01:25:22 DEBUG : dir: Looking for writers
2025/12/21 01:25:22 DEBUG : file1: reading active writers
2025/12/21 01:25:22 DEBUG : Looking for writers
2025/12/21 01:25:22 DEBUG : dir: reading active writers
2025/12/21 01:25:22 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 (10.76s)
    --- SKIP: TestFileSetModTime/cache=off,open=false,write=false (10.76s)
    --- 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   TestWriteFileModTimeWithOpenWriters
    run.go:185: Remote "Dropbox root 'rclone-test-qegiker2baja'", Local "Local file system at /tmp/rclone3765138965", Modify Window "1s"
2025/12/21 01:25:25 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2025/12/21 01:25:25 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2025/12/21 01:25:25 DEBUG : Added virtual directory entry vAddFile: "file1"
2025/12/21 01:25:25 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2025/12/21 01:25:25 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
    write_test.go:321: can't set mod time
2025/12/21 01:25:25 DEBUG : WaitForWriters: timeout=30s
2025/12/21 01:25:25 DEBUG : Looking for writers
2025/12/21 01:25:25 DEBUG : file1: reading active writers
2025/12/21 01:25:25 DEBUG : file1: active writers 1
2025/12/21 01:25:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms
2025/12/21 01:25:25 DEBUG : Looking for writers
2025/12/21 01:25:25 DEBUG : file1: reading active writers
2025/12/21 01:25:25 DEBUG : file1: active writers 1
2025/12/21 01:25:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms
2025/12/21 01:25:25 DEBUG : Looking for writers
2025/12/21 01:25:25 DEBUG : file1: reading active writers
2025/12/21 01:25:25 DEBUG : file1: active writers 1
2025/12/21 01:25:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms
2025/12/21 01:25:25 DEBUG : Looking for writers
2025/12/21 01:25:25 DEBUG : file1: reading active writers
2025/12/21 01:25:25 DEBUG : file1: active writers 1
2025/12/21 01:25:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms
2025/12/21 01:25:25 DEBUG : Looking for writers
2025/12/21 01:25:25 DEBUG : file1: reading active writers
2025/12/21 01:25:25 DEBUG : file1: active writers 1
2025/12/21 01:25:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms
2025/12/21 01:25:25 DEBUG : Looking for writers
2025/12/21 01:25:25 DEBUG : file1: reading active writers
2025/12/21 01:25:25 DEBUG : file1: active writers 1
2025/12/21 01:25:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms
2025/12/21 01:25:25 DEBUG : Looking for writers
2025/12/21 01:25:25 DEBUG : file1: reading active writers
2025/12/21 01:25:25 DEBUG : file1: active writers 1
2025/12/21 01:25:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms
2025/12/21 01:25:26 DEBUG : Looking for writers
2025/12/21 01:25:26 DEBUG : file1: reading active writers
2025/12/21 01:25:26 DEBUG : file1: active writers 1
2025/12/21 01:25:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:27 DEBUG : Looking for writers
2025/12/21 01:25:27 DEBUG : file1: reading active writers
2025/12/21 01:25:27 DEBUG : file1: active writers 1
2025/12/21 01:25:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:28 DEBUG : Looking for writers
2025/12/21 01:25:28 DEBUG : file1: reading active writers
2025/12/21 01:25:28 DEBUG : file1: active writers 1
2025/12/21 01:25:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:29 DEBUG : Looking for writers
2025/12/21 01:25:29 DEBUG : file1: reading active writers
2025/12/21 01:25:29 DEBUG : file1: active writers 1
2025/12/21 01:25:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:30 DEBUG : Looking for writers
2025/12/21 01:25:30 DEBUG : file1: reading active writers
2025/12/21 01:25:30 DEBUG : file1: active writers 1
2025/12/21 01:25:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:31 DEBUG : Looking for writers
2025/12/21 01:25:31 DEBUG : file1: reading active writers
2025/12/21 01:25:31 DEBUG : file1: active writers 1
2025/12/21 01:25:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:32 DEBUG : Looking for writers
2025/12/21 01:25:32 DEBUG : file1: reading active writers
2025/12/21 01:25:32 DEBUG : file1: active writers 1
2025/12/21 01:25:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:33 DEBUG : Looking for writers
2025/12/21 01:25:33 DEBUG : file1: reading active writers
2025/12/21 01:25:33 DEBUG : file1: active writers 1
2025/12/21 01:25:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:34 DEBUG : Looking for writers
2025/12/21 01:25:34 DEBUG : file1: reading active writers
2025/12/21 01:25:34 DEBUG : file1: active writers 1
2025/12/21 01:25:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:35 DEBUG : Looking for writers
2025/12/21 01:25:35 DEBUG : file1: reading active writers
2025/12/21 01:25:35 DEBUG : file1: active writers 1
2025/12/21 01:25:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:36 DEBUG : Looking for writers
2025/12/21 01:25:36 DEBUG : file1: reading active writers
2025/12/21 01:25:36 DEBUG : file1: active writers 1
2025/12/21 01:25:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:37 DEBUG : Looking for writers
2025/12/21 01:25:37 DEBUG : file1: reading active writers
2025/12/21 01:25:37 DEBUG : file1: active writers 1
2025/12/21 01:25:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:38 DEBUG : Looking for writers
2025/12/21 01:25:38 DEBUG : file1: reading active writers
2025/12/21 01:25:38 DEBUG : file1: active writers 1
2025/12/21 01:25:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:39 DEBUG : Looking for writers
2025/12/21 01:25:39 DEBUG : file1: reading active writers
2025/12/21 01:25:39 DEBUG : file1: active writers 1
2025/12/21 01:25:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:40 DEBUG : Looking for writers
2025/12/21 01:25:40 DEBUG : file1: reading active writers
2025/12/21 01:25:40 DEBUG : file1: active writers 1
2025/12/21 01:25:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:41 DEBUG : Looking for writers
2025/12/21 01:25:41 DEBUG : file1: reading active writers
2025/12/21 01:25:41 DEBUG : file1: active writers 1
2025/12/21 01:25:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:42 DEBUG : Looking for writers
2025/12/21 01:25:42 DEBUG : file1: reading active writers
2025/12/21 01:25:42 DEBUG : file1: active writers 1
2025/12/21 01:25:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:43 DEBUG : Looking for writers
2025/12/21 01:25:43 DEBUG : file1: reading active writers
2025/12/21 01:25:43 DEBUG : file1: active writers 1
2025/12/21 01:25:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:44 DEBUG : Looking for writers
2025/12/21 01:25:44 DEBUG : file1: reading active writers
2025/12/21 01:25:44 DEBUG : file1: active writers 1
2025/12/21 01:25:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:45 DEBUG : Looking for writers
2025/12/21 01:25:45 DEBUG : file1: reading active writers
2025/12/21 01:25:45 DEBUG : file1: active writers 1
2025/12/21 01:25:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:46 DEBUG : Looking for writers
2025/12/21 01:25:46 DEBUG : file1: reading active writers
2025/12/21 01:25:46 DEBUG : file1: active writers 1
2025/12/21 01:25:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:47 DEBUG : Looking for writers
2025/12/21 01:25:47 DEBUG : file1: reading active writers
2025/12/21 01:25:47 DEBUG : file1: active writers 1
2025/12/21 01:25:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:48 DEBUG : Looking for writers
2025/12/21 01:25:48 DEBUG : file1: reading active writers
2025/12/21 01:25:48 DEBUG : file1: active writers 1
2025/12/21 01:25:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:49 DEBUG : Looking for writers
2025/12/21 01:25:49 DEBUG : file1: reading active writers
2025/12/21 01:25:49 DEBUG : file1: active writers 1
2025/12/21 01:25:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:50 DEBUG : Looking for writers
2025/12/21 01:25:50 DEBUG : file1: reading active writers
2025/12/21 01:25:50 DEBUG : file1: active writers 1
2025/12/21 01:25:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:51 DEBUG : Looking for writers
2025/12/21 01:25:51 DEBUG : file1: reading active writers
2025/12/21 01:25:51 DEBUG : file1: active writers 1
2025/12/21 01:25:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:52 DEBUG : Looking for writers
2025/12/21 01:25:52 DEBUG : file1: reading active writers
2025/12/21 01:25:52 DEBUG : file1: active writers 1
2025/12/21 01:25:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:53 DEBUG : Looking for writers
2025/12/21 01:25:53 DEBUG : file1: reading active writers
2025/12/21 01:25:53 DEBUG : file1: active writers 1
2025/12/21 01:25:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:54 DEBUG : Looking for writers
2025/12/21 01:25:54 DEBUG : file1: reading active writers
2025/12/21 01:25:54 DEBUG : file1: active writers 1
2025/12/21 01:25:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2025/12/21 01:25:55 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s
Cache: <nil>
2025/12/21 01:25:55 DEBUG : >WaitForWriters: 
--- SKIP: TestWriteFileModTimeWithOpenWriters (31.00s)
PASS
2025/12/21 01:25:55 DEBUG : Dropbox root 'rclone-test-qegiker2baja': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestDropbox: -verbose -test.run '^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)$|^TestWriteFileModTimeWithOpenWriters$'" - Finished OK in 42.776018307s (try 2/5)