"./vfs.test -test.v -test.timeout 2h0m0s -remote TestDrime: -verbose" - Starting (try 2/5)
2026/04/03 06:38:58 DEBUG : Creating backend with remote "TestDrime:rclone-test-sinoyas2ragi"
2026/04/03 06:38:58 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/04/03 06:39:04 DEBUG : Creating backend with remote "/tmp/rclone710118343"
=== RUN   TestDirHandleMethods
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:39:04 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:39:33 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:39:33 DEBUG : dir: Looking for writers
2026/04/03 06:39:33 DEBUG : Looking for writers
2026/04/03 06:39:33 DEBUG : dir: reading active writers
2026/04/03 06:39:33 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleMethods (50.22s)
=== RUN   TestDirHandleReaddir
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:39:54 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:40:43 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:40:43 DEBUG : dir/subdir: Looking for writers
2026/04/03 06:40:43 DEBUG : dir: Looking for writers
2026/04/03 06:40:43 DEBUG : subdir: reading active writers
2026/04/03 06:40:43 DEBUG : file1: reading active writers
2026/04/03 06:40:43 DEBUG : file2: reading active writers
2026/04/03 06:40:43 DEBUG : Looking for writers
2026/04/03 06:40:43 DEBUG : dir: reading active writers
2026/04/03 06:40:43 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddir (75.17s)
=== RUN   TestDirHandleReaddirnames
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:41:09 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:41:33 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:41:33 DEBUG : dir: Looking for writers
2026/04/03 06:41:33 DEBUG : file1: reading active writers
2026/04/03 06:41:33 DEBUG : Looking for writers
2026/04/03 06:41:33 DEBUG : dir: reading active writers
2026/04/03 06:41:33 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddirnames (33.96s)
=== RUN   TestDirMethods
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:41:43 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:42:08 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:42:08 DEBUG : dir: Looking for writers
2026/04/03 06:42:08 DEBUG : Looking for writers
2026/04/03 06:42:08 DEBUG : dir: reading active writers
2026/04/03 06:42:08 DEBUG : >WaitForWriters: 
--- PASS: TestDirMethods (43.51s)
=== RUN   TestDirForgetAll
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:42:27 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:42:54 DEBUG : dir: forgetting directory cache
2026/04/03 06:42:54 DEBUG : forgetting directory cache
2026/04/03 06:42:54 DEBUG : dir: forgetting directory cache
2026/04/03 06:42:54 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:42:54 DEBUG : Looking for writers
2026/04/03 06:42:54 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetAll (39.80s)
=== RUN   TestDirForgetPath
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:43:07 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:43:27 DEBUG : ForgetPath: relativePath="dir/notfound", type=1
2026/04/03 06:43:27 DEBUG : dir: invalidating directory cache
2026/04/03 06:43:27 DEBUG : >ForgetPath: 
2026/04/03 06:43:27 DEBUG : ForgetPath: relativePath="dir", type=0
2026/04/03 06:43:27 DEBUG : invalidating directory cache
2026/04/03 06:43:27 DEBUG : dir: forgetting directory cache
2026/04/03 06:43:27 DEBUG : >ForgetPath: 
2026/04/03 06:43:27 DEBUG : ForgetPath: relativePath="not/in/cache", type=0
2026/04/03 06:43:27 DEBUG : >ForgetPath: 
2026/04/03 06:43:27 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:43:27 DEBUG : dir: Looking for writers
2026/04/03 06:43:27 DEBUG : Looking for writers
2026/04/03 06:43:27 DEBUG : dir: reading active writers
2026/04/03 06:43:27 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetPath (31.44s)
=== RUN   TestDirWalk
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:43:38 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:44:36 DEBUG : forgetting directory cache
2026/04/03 06:44:36 DEBUG : dir: forgetting directory cache
2026/04/03 06:44:44 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:44:44 DEBUG : dir: Looking for writers
2026/04/03 06:44:44 DEBUG : fil/a/b: Looking for writers
2026/04/03 06:44:44 DEBUG : fil/a: Looking for writers
2026/04/03 06:44:44 DEBUG : b: reading active writers
2026/04/03 06:44:44 DEBUG : fil: Looking for writers
2026/04/03 06:44:44 DEBUG : a: reading active writers
2026/04/03 06:44:44 DEBUG : Looking for writers
2026/04/03 06:44:44 DEBUG : fil: reading active writers
2026/04/03 06:44:44 DEBUG : dir: reading active writers
2026/04/03 06:44:44 DEBUG : >WaitForWriters: 
--- PASS: TestDirWalk (98.32s)
=== RUN   TestDirSetModTime
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:45:16 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:45:46 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:45:46 DEBUG : dir: Looking for writers
2026/04/03 06:45:46 DEBUG : Looking for writers
2026/04/03 06:45:46 DEBUG : dir: reading active writers
2026/04/03 06:45:46 DEBUG : >WaitForWriters: 
--- PASS: TestDirSetModTime (52.87s)
=== RUN   TestDirStat
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:46:09 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:46:41 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:46:41 DEBUG : dir: Looking for writers
2026/04/03 06:46:41 DEBUG : file1: reading active writers
2026/04/03 06:46:41 DEBUG : Looking for writers
2026/04/03 06:46:41 DEBUG : dir: reading active writers
2026/04/03 06:46:41 DEBUG : >WaitForWriters: 
--- PASS: TestDirStat (48.56s)
=== RUN   TestDirReadDirAll
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:46:58 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
=== RUN   TestDirReadDirAll/Virtual
2026/04/03 06:48:07 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2026/04/03 06:48:07 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2026/04/03 06:48:07 DEBUG : dir: Added virtual directory entry vDel: "file2"
2026/04/03 06:48:07 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2026/04/03 06:48:41 DEBUG : dir: invalidating directory cache
2026/04/03 06:48:44 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2026/04/03 06:48:44 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2026/04/03 06:48:44 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2026/04/03 06:48:44 DEBUG : dir/file1: Reset virtual modtime
2026/04/03 06:48:44 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
2026/04/03 06:48:44 DEBUG : dir/virtualFile: Reset virtual modtime
2026/04/03 06:48:44 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2026/04/03 06:48:44 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2026/04/03 06:48:44 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/03 06:48:44 DEBUG : dir: invalidating directory cache
2026/04/03 06:48:46 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2"
2026/04/03 06:48:46 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/03 06:48:46 DEBUG : dir/virtualFile: Reset virtual modtime
2026/04/03 06:48:46 DEBUG : forgetting directory cache
2026/04/03 06:48:46 DEBUG : dir: forgetting directory cache
2026/04/03 06:48:46 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 06:48:46 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:48:46 DEBUG : dir/virtualDir: Looking for writers
2026/04/03 06:48:46 DEBUG : dir: Looking for writers
2026/04/03 06:48:46 DEBUG : virtualDir: reading active writers
2026/04/03 06:48:46 DEBUG : file1: reading active writers
2026/04/03 06:48:46 DEBUG : virtualFile2: reading active writers
2026/04/03 06:48:46 DEBUG : virtualFile: reading active writers
2026/04/03 06:48:46 DEBUG : Looking for writers
2026/04/03 06:48:46 DEBUG : dir: reading active writers
2026/04/03 06:48:46 DEBUG : >WaitForWriters: 
--- PASS: TestDirReadDirAll (144.64s)
    --- PASS: TestDirReadDirAll/Virtual (39.72s)
=== RUN   TestDirOpen
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:49:23 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:49:33 DEBUG : dir: forgetting directory cache
2026/04/03 06:49:33 DEBUG : forgetting directory cache
2026/04/03 06:49:33 DEBUG : dir: forgetting directory cache
2026/04/03 06:49:53 ERROR : dir/: Can only open directories read only
2026/04/03 06:49:53 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:49:53 DEBUG : dir: Looking for writers
2026/04/03 06:49:53 DEBUG : Looking for writers
2026/04/03 06:49:53 DEBUG : dir: reading active writers
2026/04/03 06:49:53 DEBUG : >WaitForWriters: 
--- PASS: TestDirOpen (49.59s)
=== RUN   TestDirCreate
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:50:12 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:50:41 DEBUG : forgetting directory cache
2026/04/03 06:50:41 DEBUG : dir: forgetting directory cache
2026/04/03 06:50:41 DEBUG : dir/subdir: forgetting directory cache
2026/04/03 06:50:49 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2026/04/03 06:50:49 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/04/03 06:50:49 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2026/04/03 06:50:49 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/04/03 06:50:49 DEBUG : drime root 'rclone-test-sinoyas2ragi': File to upload is small (5 bytes), uploading instead of streaming
2026/04/03 06:50:59 DEBUG : dir/potato: size = 5 OK
2026/04/03 06:50:59 NOTICE: drime root 'rclone-test-sinoyas2ragi': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2026/04/03 06:50:59 DEBUG : dir/potato: Size of src and dst objects identical
2026/04/03 06:50:59 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/04/03 06:50:59 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:50:59 DEBUG : dir: Looking for writers
2026/04/03 06:50:59 DEBUG : file1: reading active writers
2026/04/03 06:50:59 DEBUG : potato: reading active writers
2026/04/03 06:50:59 DEBUG : Looking for writers
2026/04/03 06:50:59 DEBUG : dir: reading active writers
2026/04/03 06:50:59 DEBUG : >WaitForWriters: 
--- PASS: TestDirCreate (72.73s)
=== RUN   TestDirMkdir
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:51:25 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:51:30 DEBUG : forgetting directory cache
2026/04/03 06:51:30 DEBUG : dir: forgetting directory cache
2026/04/03 06:51:59 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2026/04/03 06:52:08 DEBUG : forgetting directory cache
2026/04/03 06:52:08 DEBUG : dir: forgetting directory cache
2026/04/03 06:52:08 DEBUG : dir: forgetting directory cache
2026/04/03 06:52:12 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:52:12 DEBUG : dir/sub: Looking for writers
2026/04/03 06:52:12 DEBUG : dir: Looking for writers
2026/04/03 06:52:12 DEBUG : file1: reading active writers
2026/04/03 06:52:12 DEBUG : sub: reading active writers
2026/04/03 06:52:12 DEBUG : Looking for writers
2026/04/03 06:52:12 DEBUG : dir: reading active writers
2026/04/03 06:52:12 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdir (69.82s)
=== RUN   TestDirMkdirSub
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:52:35 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:53:16 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2026/04/03 06:53:24 DEBUG : forgetting directory cache
2026/04/03 06:53:24 DEBUG : dir: forgetting directory cache
2026/04/03 06:53:28 DEBUG : dir/sub: Added virtual directory entry vAddDir: "subsub"
2026/04/03 06:53:45 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:53:45 DEBUG : dir/sub/subsub: Looking for writers
2026/04/03 06:53:45 DEBUG : dir/sub: Looking for writers
2026/04/03 06:53:45 DEBUG : subsub: reading active writers
2026/04/03 06:53:45 DEBUG : dir: Looking for writers
2026/04/03 06:53:45 DEBUG : file1: reading active writers
2026/04/03 06:53:45 DEBUG : sub: reading active writers
2026/04/03 06:53:45 DEBUG : Looking for writers
2026/04/03 06:53:45 DEBUG : dir: reading active writers
2026/04/03 06:53:45 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdirSub (119.41s)
=== RUN   TestDirRemove
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:54:34 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:54:39 DEBUG : forgetting directory cache
2026/04/03 06:54:39 DEBUG : dir: forgetting directory cache
2026/04/03 06:54:39 DEBUG : dir: forgetting directory cache
2026/04/03 06:54:39 DEBUG : fil: forgetting directory cache
2026/04/03 06:54:39 DEBUG : fil/a: forgetting directory cache
2026/04/03 06:54:39 DEBUG : fil/a/b: forgetting directory cache
2026/04/03 06:55:12 ERROR : dir/: Dir.Remove not empty
2026/04/03 06:55:12 DEBUG : dir/file1: Remove: 
2026/04/03 06:55:18 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/03 06:55:18 DEBUG : dir/file1: >Remove: err=<nil>
2026/04/03 06:55:26 DEBUG : Added virtual directory entry vDel: "dir"
2026/04/03 06:55:30 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:55:30 DEBUG : Looking for writers
2026/04/03 06:55:30 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemove (61.88s)
=== RUN   TestDirRemoveAll
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:55:36 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:55:46 DEBUG : forgetting directory cache
2026/04/03 06:55:46 DEBUG : dir: forgetting directory cache
2026/04/03 06:55:46 DEBUG : dir: forgetting directory cache
2026/04/03 06:56:14 DEBUG : dir/file1: Remove: 
2026/04/03 06:56:16 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/03 06:56:16 DEBUG : dir/file1: >Remove: err=<nil>
2026/04/03 06:56:24 DEBUG : Added virtual directory entry vDel: "dir"
2026/04/03 06:56:28 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:56:28 DEBUG : Looking for writers
2026/04/03 06:56:28 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveAll (57.95s)
=== RUN   TestDirRemoveName
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:56:34 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:56:37 DEBUG : forgetting directory cache
2026/04/03 06:56:37 DEBUG : dir: forgetting directory cache
2026/04/03 06:57:08 DEBUG : dir/file1: Remove: 
2026/04/03 06:57:10 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/03 06:57:10 DEBUG : dir/file1: >Remove: err=<nil>
2026/04/03 06:57:18 DEBUG : WaitForWriters: timeout=30s
2026/04/03 06:57:18 DEBUG : dir: Looking for writers
2026/04/03 06:57:18 DEBUG : Looking for writers
2026/04/03 06:57:18 DEBUG : dir: reading active writers
2026/04/03 06:57:18 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveName (61.77s)
=== RUN   TestDirRename
    run.go:185: Remote "drime root 'rclone-test-sinoyas2ragi'", Local "Local file system at /tmp/rclone710118343", Modify Window "876000h0m0s"
2026/04/03 06:57:36 INFO  : drime root 'rclone-test-sinoyas2ragi': poll-interval is not supported by this remote
2026/04/03 06:58:07 DEBUG : dir/subdir: forgetting directory cache
2026/04/03 06:58:29 ERROR : dir/not found: Dir.Rename error: file does not exist
2026/04/03 06:58:44 DEBUG : dir/virtualDir2: forgetting directory cache
2026/04/03 06:58:46 DEBUG : dir: forgetting directory cache
2026/04/03 06:58:46 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 06:58:46 DEBUG : forgetting directory cache
2026/04/03 06:58:46 DEBUG : dir: forgetting directory cache
2026/04/03 06:58:46 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 06:59:53 DEBUG : dir: forgetting directory cache
2026/04/03 06:59:53 DEBUG : forgetting directory cache
2026/04/03 06:59:53 DEBUG : dir: forgetting directory cache
2026/04/03 07:00:46 DEBUG : forgetting directory cache
2026/04/03 07:00:46 DEBUG : dir: forgetting directory cache
2026/04/03 07:00:46 DEBUG : dir: Removed virtual directory entry vAddFile: "potato"
2026/04/03 07:01:51 DEBUG : forgetting directory cache
2026/04/03 07:01:51 DEBUG : dir: forgetting directory cache
2026/04/03 07:01:51 DEBUG : dir/sub: forgetting directory cache
2026/04/03 07:01:51 DEBUG : dir: Removed virtual directory entry vAddDir: "sub"
2026/04/03 07:03:09 DEBUG : forgetting directory cache
2026/04/03 07:03:09 DEBUG : dir: forgetting directory cache
2026/04/03 07:03:09 DEBUG : dir/sub: forgetting directory cache
2026/04/03 07:03:09 DEBUG : dir/sub/subsub: forgetting directory cache
2026/04/03 07:03:09 DEBUG : dir/sub: Removed virtual directory entry vAddDir: "subsub"
2026/04/03 07:03:09 DEBUG : dir: Removed virtual directory entry vAddDir: "sub"
2026/04/03 07:05:08 DEBUG : forgetting directory cache
2026/04/03 07:05:08 DEBUG : Removed virtual directory entry vDel: "dir"
2026/04/03 07:05:12 DEBUG : dir: forgetting directory cache
2026/04/03 07:05:12 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/03 07:06:09 DEBUG : forgetting directory cache
2026/04/03 07:06:09 DEBUG : Removed virtual directory entry vDel: "dir"
2026/04/03 07:06:14 DEBUG : dir: forgetting directory cache
2026/04/03 07:06:14 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/03 07:07:05 DEBUG : forgetting directory cache
2026/04/03 07:07:05 DEBUG : dir: forgetting directory cache
2026/04/03 07:07:05 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/03 07:08:07 DEBUG : forgetting directory cache
2026/04/03 07:08:07 DEBUG : dir: forgetting directory cache
2026/04/03 07:08:46 DEBUG : forgetting directory cache
2026/04/03 07:08:46 DEBUG : dir: forgetting directory cache
2026/04/03 07:08:46 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 07:08:46 DEBUG : dir: forgetting directory cache
2026/04/03 07:08:46 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 07:15:08 DEBUG : forgetting directory cache
2026/04/03 07:16:09 DEBUG : forgetting directory cache
2026/04/03 07:16:58 DEBUG : pacer: low level retry 1/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": read tcp 65.108.87.141:45328->57.130.54.115:443: read: connection reset by peer)
2026/04/03 07:16:58 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2026/04/03 07:17:25 DEBUG : pacer: low level retry 2/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": read tcp 65.108.87.141:56746->57.130.54.115:443: read: connection reset by peer)
2026/04/03 07:17:25 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2026/04/03 07:17:27 DEBUG : pacer: low level retry 3/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": read tcp 65.108.87.141:56788->57.130.54.115:443: read: connection reset by peer)
2026/04/03 07:17:27 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2026/04/03 07:18:47 DEBUG : dir: forgetting directory cache
2026/04/03 07:18:47 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 07:18:47 DEBUG : forgetting directory cache
2026/04/03 07:18:47 DEBUG : dir: forgetting directory cache
2026/04/03 07:18:47 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 07:28:47 DEBUG : forgetting directory cache
2026/04/03 07:28:47 DEBUG : dir: forgetting directory cache
2026/04/03 07:28:47 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 07:28:47 DEBUG : dir: forgetting directory cache
2026/04/03 07:28:47 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/03 07:36:02 DEBUG : pacer: low level retry 4/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": read tcp 65.108.87.141:38570->57.130.54.115:443: read: connection reset by peer)
2026/04/03 07:36:02 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2026/04/03 07:36:05 DEBUG : pacer: low level retry 5/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": EOF)
2026/04/03 07:36:05 DEBUG : pacer: Rate limited, increasing sleep to 320ms
2026/04/03 07:36:06 DEBUG : pacer: low level retry 6/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": read tcp 65.108.87.141:38682->57.130.54.115:443: read: connection reset by peer)
2026/04/03 07:36:06 DEBUG : pacer: Rate limited, increasing sleep to 640ms
2026/04/03 07:36:06 DEBUG : pacer: low level retry 7/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": EOF)
2026/04/03 07:36:06 DEBUG : pacer: Rate limited, increasing sleep to 1.28s
2026/04/03 07:36:09 DEBUG : pacer: low level retry 8/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": read tcp 65.108.87.141:39182->57.130.54.115:443: read: connection reset by peer)
2026/04/03 07:36:09 DEBUG : pacer: Rate limited, increasing sleep to 2.56s
2026/04/03 07:36:32 DEBUG : pacer: low level retry 9/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": read tcp 65.108.87.141:45992->57.130.54.115:443: read: connection reset by peer)
2026/04/03 07:36:32 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2026/04/03 07:36:33 DEBUG : pacer: low level retry 10/10 (error Put "https://app.drime.cloud/api/v1/file-entries/676829498": EOF)
2026/04/03 07:36:33 DEBUG : pacer: Rate limited, increasing sleep to 10.24s
2026/04/03 07:36:33 ERROR : dir: Dir.Rename error: Move rename leaf: failed to patch item "name" to dir2: Put "https://app.drime.cloud/api/v1/file-entries/676829498": EOF
    dir_test.go:538: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:538
        	Error:      	Received unexpected error:
        	            	Move rename leaf: failed to patch item "name" to dir2: Put "https://app.drime.cloud/api/v1/file-entries/676829498": EOF
        	Test:       	TestDirRename
2026/04/03 07:36:39 DEBUG : pacer: Reducing sleep to 5.12s
    dir_test.go:250: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:250
        	            				/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:539
        	Error:      	Not equal: 
        	            	expected: []string{"dir2,0,true"}
        	            	actual  : []string{"dir,0,true"}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,3 +1,3 @@
        	            	 ([]string) (len=1) {
        	            	- (string) (len=11) "dir2,0,true"
        	            	+ (string) (len=10) "dir,0,true"
        	            	 }
        	Test:       	TestDirRename
2026/04/03 07:36:50 DEBUG : pacer: Reducing sleep to 2.56s
2026/04/03 07:36:52 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2026/04/03 07:36:52 DEBUG : pacer: low level retry 1/10 (error Error "500 Internal Server Error (500): <html>\r\n<head><title>500 Internal Server Error</title></head>\r\n<body>\r\n<center><h1>500 Internal Server Error</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n")
2026/04/03 07:36:52 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2026/04/03 07:36:58 DEBUG : pacer: Reducing sleep to 2.56s
2026/04/03 07:37:00 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2026/04/03 07:37:00 DEBUG : pacer: low level retry 1/10 (error Error "500 Internal Server Error (500): <html>\r\n<head><title>500 Internal Server Error</title></head>\r\n<body>\r\n<center><h1>500 Internal Server Error</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n")
2026/04/03 07:37:00 DEBUG : pacer: Rate limited, increasing sleep to 5.12s
2026/04/03 07:37:06 DEBUG : pacer: Reducing sleep to 2.56s
    fstest.go:298: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:301: Flushing the directory cache
2026/04/03 07:37:11 DEBUG : pacer: Reducing sleep to 1.28s
2026/04/03 07:37:14 DEBUG : pacer: Reducing sleep to 640ms
2026/04/03 07:37:16 DEBUG : pacer: Reducing sleep to 320ms
    fstest.go:298: Sleeping for 2s for list eventual consistency: 2/3
    fstest.go:301: Flushing the directory cache
2026/04/03 07:37:19 DEBUG : pacer: Reducing sleep to 160ms
2026/04/03 07:37:21 DEBUG : pacer: Reducing sleep to 80ms
2026/04/03 07:37:22 DEBUG : pacer: low level retry 1/10 (error Get "https://app.drime.cloud/api/v1/drive/file-entries?page=1&parentIds=676829498&perPage=1000": read tcp 65.108.87.141:60790->57.130.54.115:443: read: connection reset by peer)
2026/04/03 07:37:22 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2026/04/03 07:37:25 DEBUG : pacer: Reducing sleep to 80ms
    fstest.go:298: Sleeping for 4s for list eventual consistency: 3/3
    fstest.go:301: Flushing the directory cache
    fstest.go:305: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:305
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338
        	            				/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:545
        	Error:      	Should be true
        	Test:       	TestDirRename
        	Messages:   	listing wrong, want
        	            	  dir2/file1 (14), dir2/file3 (15) got
        	            	  dir/file1 (14), dir/file3 (15)
    fstest.go:191: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:191
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:308
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338
        	            				/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:545
        	Error:      	Should be true
        	Test:       	TestDirRename
        	Messages:   	Unexpected file "dir/file1"
    fstest.go:191: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:191
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:308
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338
        	            				/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:545
        	Error:      	Should be true
        	Test:       	TestDirRename
        	Messages:   	Unexpected file "dir/file3"
    fstest.go:203: Not found "dir2/file1"
    fstest.go:203: Not found "dir2/file3"
    fstest.go:206: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:206
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:310
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338
        	            				/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:545
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 2
        	Test:       	TestDirRename
        	Messages:   	2 objects not found
    fstest.go:327: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:327
        	            				/home/rclone/go/src/github.com/rclone/rclone/fstest/fstest.go:338
        	            				/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:545
        	Error:      	Not equal: 
        	            	expected: []string{"dir2"}
        	            	actual  : []string{"dir"}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,3 +1,3 @@
        	            	 ([]string) (len=1) {
        	            	- (string) (len=4) "dir2"
        	            	+ (string) (len=3) "dir"
        	            	 }
        	Test:       	TestDirRename
        	Messages:   	directories
    dir_test.go:549: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:549
        	Error:      	Received unexpected error:
        	            	file does not exist
        	Test:       	TestDirRename
2026/04/03 07:37:29 DEBUG : WaitForWriters: timeout=30s
2026/04/03 07:37:29 DEBUG : dir: Looking for writers
2026/04/03 07:37:29 DEBUG : Looking for writers
2026/04/03 07:37:29 DEBUG : dir: reading active writers
2026/04/03 07:37:29 DEBUG : >WaitForWriters: 
2026/04/03 07:37:30 DEBUG : pacer: Reducing sleep to 40ms
2026/04/03 07:37:31 DEBUG : pacer: Reducing sleep to 20ms
2026/04/03 07:37:31 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2026/04/03 07:37:31 DEBUG : pacer: low level retry 1/10 (error Error "500 Internal Server Error (500): <html>\r\n<head><title>500 Internal Server Error</title></head>\r\n<body>\r\n<center><h1>500 Internal Server Error</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n")
2026/04/03 07:37:31 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2026/04/03 07:37:31 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2026/04/03 07:37:31 DEBUG : pacer: low level retry 2/10 (error Error "500 Internal Server Error (500): <html>\r\n<head><title>500 Internal Server Error</title></head>\r\n<body>\r\n<center><h1>500 Internal Server Error</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n")
2026/04/03 07:37:31 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2026/04/03 07:37:31 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2026/04/03 07:37:31 DEBUG : pacer: low level retry 3/10 (error Error "500 Internal Server Error (500): <html>\r\n<head><title>500 Internal Server Error</title></head>\r\n<body>\r\n<center><h1>500 Internal Server Error</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n")
2026/04/03 07:37:31 DEBUG : pacer: Rate limited, increasing sleep to 160ms
2026/04/03 07:37:33 DEBUG : pacer: Reducing sleep to 80ms
2026/04/03 07:37:34 DEBUG : pacer: Reducing sleep to 40ms
2026/04/03 07:37:35 DEBUG : pacer: Reducing sleep to 20ms
2026/04/03 07:37:36 DEBUG : pacer: Reducing sleep to 10ms
2026/04/03 07:37:36 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2026/04/03 07:37:36 DEBUG : pacer: low level retry 1/10 (error Error "500 Internal Server Error (500): <html>\r\n<head><title>500 Internal Server Error</title></head>\r\n<body>\r\n<center><h1>500 Internal Server Error</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n")
2026/04/03 07:37:36 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2026/04/03 07:37:37 DEBUG : pacer: Reducing sleep to 10ms
--- FAIL: TestDirRename (2402.13s)
panic: interface conversion: vfs.Node is nil, not *vfs.Dir [recovered, repanicked]

goroutine 1345 [running]:
testing.tRunner.func1.2({0x253abe0, 0x1a59c90af680})
	/usr/local/go/src/testing/testing.go:1974 +0x232
testing.tRunner.func1()
	/usr/local/go/src/testing/testing.go:1977 +0x349
panic({0x253abe0?, 0x1a59c90af680?})
	/usr/local/go/src/runtime/panic.go:860 +0x13a
github.com/rclone/rclone/vfs.TestDirRename(0x1a59c8e7afc8)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:550 +0x10a6
testing.tRunner(0x1a59c8e7afc8, 0x2ba02c0)
	/usr/local/go/src/testing/testing.go:2036 +0xea
created by testing.(*T).Run in goroutine 1
	/usr/local/go/src/testing/testing.go:2101 +0x4c5
"./vfs.test -test.v -test.timeout 2h0m0s -remote TestDrime: -verbose" - Finished ERROR in 58m39.673308216s (try 2/5): exit status 2: Failed [TestDirRename]