"./vfs.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestDirFileOpen|TestFileMethods|TestFileRemoveAll|TestVFSRename)$'" - Starting (try 2/5)
2025/07/20 01:50:25 DEBUG : Creating backend with remote "TestFilesCom:rclone-test-yodevil6xupo"
2025/07/20 01:50:25 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/07/20 01:50:25 DEBUG : Creating backend with remote "/tmp/rclone1315438305"
=== RUN   TestDirFileOpen
    run.go:180: Remote "files root 'rclone-test-yodevil6xupo'", Local "Local file system at /tmp/rclone1315438305", Modify Window "1s"
2025/07/20 01:50:25 INFO  : files root 'rclone-test-yodevil6xupo': poll-interval is not supported by this remote
2025/07/20 01:50:27 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2025/07/20 01:50:27 DEBUG : dir/sub/file0: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2025/07/20 01:50:28 DEBUG : dir/sub/file0: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2025/07/20 01:50:28 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2025/07/20 01:50:28 DEBUG : dir/sub/file0: >Open: fd=dir/sub/file0 (w), err=<nil>
2025/07/20 01:50:28 DEBUG : dir/sub/file0: >OpenFile: fd=dir/sub/file0 (w), err=<nil>
2025/07/20 01:50:28 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2025/07/20 01:50:28 DEBUG : dir/sub/file2: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2025/07/20 01:50:28 DEBUG : dir/sub/file2: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2025/07/20 01:50:28 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2025/07/20 01:50:28 DEBUG : dir/sub/file2: >Open: fd=dir/sub/file2 (w), err=<nil>
2025/07/20 01:50:28 DEBUG : dir/sub/file2: >OpenFile: fd=dir/sub/file2 (w), err=<nil>
2025/07/20 01:50:28 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2025/07/20 01:50:28 DEBUG : files root 'rclone-test-yodevil6xupo': File to upload is small (12 bytes), uploading instead of streaming
2025/07/20 01:50:28 DEBUG : dir/sub/file2: Dst hash empty - aborting Src hash check
2025/07/20 01:50:28 DEBUG : dir/sub/file2: Size of src and dst objects identical
2025/07/20 01:50:28 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2025/07/20 01:50:28 DEBUG : forgetting directory cache
2025/07/20 01:50:28 DEBUG : dir: forgetting directory cache
2025/07/20 01:50:28 DEBUG : dir/sub: forgetting directory cache
2025/07/20 01:50:28 DEBUG : dir/sub: Removed virtual directory entry vAddFile: "file2"
2025/07/20 01:50:28 DEBUG : dir: Removed virtual directory entry vAddDir: "sub"
2025/07/20 01:50:28 DEBUG : files root 'rclone-test-yodevil6xupo': File to upload is small (5 bytes), uploading instead of streaming
2025/07/20 01:50:29 DEBUG : dir/sub/file0: Dst hash empty - aborting Src hash check
2025/07/20 01:50:29 DEBUG : dir/sub/file0: Size of src and dst objects identical
2025/07/20 01:50:29 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2025/07/20 01:50:29 DEBUG : WaitForWriters: timeout=30s
2025/07/20 01:50:29 DEBUG : dir/sub: Looking for writers
2025/07/20 01:50:29 DEBUG : file0: reading active writers
2025/07/20 01:50:29 DEBUG : file2: reading active writers
2025/07/20 01:50:29 DEBUG : dir: Looking for writers
2025/07/20 01:50:29 DEBUG : file1: reading active writers
2025/07/20 01:50:29 DEBUG : sub: reading active writers
2025/07/20 01:50:29 DEBUG : Looking for writers
2025/07/20 01:50:29 DEBUG : dir: reading active writers
2025/07/20 01:50:29 DEBUG : >WaitForWriters: 
2025/07/20 01:50:30 DEBUG : pacer: low level retry 1/10 (error Folder Not Empty - `Folder rclone-test-yodevil6xupo/dir not empty`)
2025/07/20 01:50:30 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2025/07/20 01:50:30 DEBUG : pacer: low level retry 2/10 (error Folder Not Empty - `Folder rclone-test-yodevil6xupo/dir not empty`)
2025/07/20 01:50:30 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2025/07/20 01:50:31 DEBUG : pacer: low level retry 3/10 (error Folder Not Empty - `Folder rclone-test-yodevil6xupo/dir not empty`)
2025/07/20 01:50:31 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2025/07/20 01:50:31 DEBUG : pacer: Reducing sleep to 60ms
2025/07/20 01:50:31 DEBUG : pacer: Reducing sleep to 45ms
--- PASS: TestDirFileOpen (5.54s)
=== RUN   TestFileMethods
    run.go:180: Remote "files root 'rclone-test-yodevil6xupo'", Local "Local file system at /tmp/rclone1315438305", Modify Window "1s"
2025/07/20 01:50:31 INFO  : files root 'rclone-test-yodevil6xupo': poll-interval is not supported by this remote
2025/07/20 01:50:32 DEBUG : pacer: Reducing sleep to 33.75ms
2025/07/20 01:50:32 DEBUG : pacer: Reducing sleep to 25.3125ms
2025/07/20 01:50:32 DEBUG : pacer: Reducing sleep to 18.984375ms
2025/07/20 01:50:32 DEBUG : pacer: Reducing sleep to 14.238281ms
2025/07/20 01:50:32 DEBUG : pacer: Reducing sleep to 10.67871ms
2025/07/20 01:50:32 DEBUG : pacer: Reducing sleep to 10ms
2025/07/20 01:50:32 DEBUG : WaitForWriters: timeout=30s
2025/07/20 01:50:32 DEBUG : dir: Looking for writers
2025/07/20 01:50:32 DEBUG : file1: reading active writers
2025/07/20 01:50:32 DEBUG : Looking for writers
2025/07/20 01:50:32 DEBUG : dir: reading active writers
2025/07/20 01:50:32 DEBUG : >WaitForWriters: 
--- PASS: TestFileMethods (2.11s)
=== RUN   TestFileRemoveAll
    run.go:180: Remote "files root 'rclone-test-yodevil6xupo'", Local "Local file system at /tmp/rclone1315438305", Modify Window "1s"
2025/07/20 01:50:33 INFO  : files root 'rclone-test-yodevil6xupo': poll-interval is not supported by this remote
2025/07/20 01:50:34 DEBUG : dir/file1: Remove: 
2025/07/20 01:50:35 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/07/20 01:50:35 DEBUG : dir/file1: >Remove: err=<nil>
2025/07/20 01:50:35 DEBUG : dir/file1: Remove: 
2025/07/20 01:50:35 DEBUG : dir/file1: >Remove: err=Read only file system
2025/07/20 01:50:35 DEBUG : WaitForWriters: timeout=30s
2025/07/20 01:50:35 DEBUG : dir: Looking for writers
2025/07/20 01:50:35 DEBUG : Looking for writers
2025/07/20 01:50:35 DEBUG : dir: reading active writers
2025/07/20 01:50:35 DEBUG : >WaitForWriters: 
--- PASS: TestFileRemoveAll (2.42s)
=== RUN   TestVFSRename
    run.go:180: Remote "files root 'rclone-test-yodevil6xupo'", Local "Local file system at /tmp/rclone1315438305", Modify Window "1s"
2025/07/20 01:50:35 INFO  : files root 'rclone-test-yodevil6xupo': poll-interval is not supported by this remote
2025/07/20 01:50:38 INFO  : dir/file2: Moved (server-side) to: dir/file1
2025/07/20 01:50:38 DEBUG : dir/file1: Updating file with dir/file1 0xc0005eae40
2025/07/20 01:50:38 DEBUG : dir: Added virtual directory entry vDel: "file2"
2025/07/20 01:50:38 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2025/07/20 01:50:38 INFO  : dir/file1: Moved (server-side) to: file0
2025/07/20 01:50:38 DEBUG : file0: Updating file with file0 0xc0005eae40
2025/07/20 01:50:38 DEBUG : dir: Added virtual directory entry vDel: "file1"
2025/07/20 01:50:38 DEBUG : Added virtual directory entry vAddFile: "file0"
2025/07/20 01:50:39 DEBUG : WaitForWriters: timeout=30s
2025/07/20 01:50:39 DEBUG : dir: Looking for writers
2025/07/20 01:50:39 DEBUG : Looking for writers
2025/07/20 01:50:39 DEBUG : dir: reading active writers
2025/07/20 01:50:39 DEBUG : file0: reading active writers
2025/07/20 01:50:39 DEBUG : >WaitForWriters: 
--- PASS: TestVFSRename (4.03s)
PASS
2025/07/20 01:50:39 DEBUG : files root 'rclone-test-yodevil6xupo': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestFilesCom: -verbose -test.run '^(TestDirFileOpen|TestFileMethods|TestFileRemoveAll|TestVFSRename)$'" - Finished OK in 14.777115755s (try 2/5)