"./vfs.test -test.v -test.timeout 2h0m0s -remote TestDrime: -verbose" - Starting (try 2/5)
2026/04/06 06:46:04 DEBUG : Creating backend with remote "TestDrime:rclone-test-ridasul9gome"
2026/04/06 06:46:04 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/04/06 06:46:14 DEBUG : Creating backend with remote "/tmp/rclone3590281827"
=== RUN   TestDirHandleMethods
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:46:14 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:47:01 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:47:01 DEBUG : dir: Looking for writers
2026/04/06 06:47:01 DEBUG : Looking for writers
2026/04/06 06:47:01 DEBUG : dir: reading active writers
2026/04/06 06:47:01 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleMethods (79.38s)
=== RUN   TestDirHandleReaddir
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:47:34 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:49:07 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:49:07 DEBUG : dir/subdir: Looking for writers
2026/04/06 06:49:07 DEBUG : dir: Looking for writers
2026/04/06 06:49:07 DEBUG : file1: reading active writers
2026/04/06 06:49:07 DEBUG : file2: reading active writers
2026/04/06 06:49:07 DEBUG : subdir: reading active writers
2026/04/06 06:49:07 DEBUG : Looking for writers
2026/04/06 06:49:07 DEBUG : dir: reading active writers
2026/04/06 06:49:07 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddir (145.22s)
=== RUN   TestDirHandleReaddirnames
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:49:59 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:50:55 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:50:55 DEBUG : dir: Looking for writers
2026/04/06 06:50:55 DEBUG : file1: reading active writers
2026/04/06 06:50:55 DEBUG : Looking for writers
2026/04/06 06:50:55 DEBUG : dir: reading active writers
2026/04/06 06:50:55 DEBUG : >WaitForWriters: 
--- PASS: TestDirHandleReaddirnames (82.27s)
=== RUN   TestDirMethods
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:51:21 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:51:59 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:51:59 DEBUG : dir: Looking for writers
2026/04/06 06:51:59 DEBUG : Looking for writers
2026/04/06 06:51:59 DEBUG : dir: reading active writers
2026/04/06 06:51:59 DEBUG : >WaitForWriters: 
--- PASS: TestDirMethods (64.18s)
=== RUN   TestDirForgetAll
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:52:25 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:53:06 DEBUG : dir: forgetting directory cache
2026/04/06 06:53:06 DEBUG : forgetting directory cache
2026/04/06 06:53:06 DEBUG : dir: forgetting directory cache
2026/04/06 06:53:06 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:53:06 DEBUG : Looking for writers
2026/04/06 06:53:06 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetAll (56.27s)
=== RUN   TestDirForgetPath
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:53:22 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:54:05 DEBUG : ForgetPath: relativePath="dir/notfound", type=1
2026/04/06 06:54:05 DEBUG : dir: invalidating directory cache
2026/04/06 06:54:05 DEBUG : >ForgetPath: 
2026/04/06 06:54:05 DEBUG : ForgetPath: relativePath="dir", type=0
2026/04/06 06:54:05 DEBUG : invalidating directory cache
2026/04/06 06:54:05 DEBUG : dir: forgetting directory cache
2026/04/06 06:54:05 DEBUG : >ForgetPath: 
2026/04/06 06:54:05 DEBUG : ForgetPath: relativePath="not/in/cache", type=0
2026/04/06 06:54:05 DEBUG : >ForgetPath: 
2026/04/06 06:54:05 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:54:05 DEBUG : dir: Looking for writers
2026/04/06 06:54:05 DEBUG : Looking for writers
2026/04/06 06:54:05 DEBUG : dir: reading active writers
2026/04/06 06:54:05 DEBUG : >WaitForWriters: 
--- PASS: TestDirForgetPath (75.47s)
=== RUN   TestDirWalk
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:54:37 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:56:18 DEBUG : forgetting directory cache
2026/04/06 06:56:18 DEBUG : dir: forgetting directory cache
2026/04/06 06:56:29 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:56:29 DEBUG : dir: Looking for writers
2026/04/06 06:56:29 DEBUG : fil/a/b: Looking for writers
2026/04/06 06:56:29 DEBUG : fil/a: Looking for writers
2026/04/06 06:56:29 DEBUG : b: reading active writers
2026/04/06 06:56:29 DEBUG : fil: Looking for writers
2026/04/06 06:56:29 DEBUG : a: reading active writers
2026/04/06 06:56:29 DEBUG : Looking for writers
2026/04/06 06:56:29 DEBUG : dir: reading active writers
2026/04/06 06:56:29 DEBUG : fil: reading active writers
2026/04/06 06:56:29 DEBUG : >WaitForWriters: 
2026/04/06 06:57:01 DEBUG : forgetting directory cache
2026/04/06 06:57:01 DEBUG : dir: forgetting directory cache
2026/04/06 06:57:01 DEBUG : dir: forgetting directory cache
--- PASS: TestDirWalk (173.50s)
=== RUN   TestDirSetModTime
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:57:31 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:58:11 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:58:11 DEBUG : dir: Looking for writers
2026/04/06 06:58:11 DEBUG : Looking for writers
2026/04/06 06:58:11 DEBUG : dir: reading active writers
2026/04/06 06:58:11 DEBUG : >WaitForWriters: 
--- PASS: TestDirSetModTime (71.58s)
=== RUN   TestDirStat
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:58:42 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 06:59:04 DEBUG : forgetting directory cache
2026/04/06 06:59:04 DEBUG : dir: forgetting directory cache
2026/04/06 06:59:04 DEBUG : dir/subdir: forgetting directory cache
2026/04/06 06:59:16 DEBUG : WaitForWriters: timeout=30s
2026/04/06 06:59:16 DEBUG : dir: Looking for writers
2026/04/06 06:59:16 DEBUG : file1: reading active writers
2026/04/06 06:59:16 DEBUG : Looking for writers
2026/04/06 06:59:16 DEBUG : dir: reading active writers
2026/04/06 06:59:16 DEBUG : >WaitForWriters: 
--- PASS: TestDirStat (62.05s)
=== RUN   TestDirReadDirAll
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 06:59:44 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:00:48 DEBUG : forgetting directory cache
2026/04/06 07:00:48 DEBUG : dir: forgetting directory cache
2026/04/06 07:01:59 DEBUG : forgetting directory cache
2026/04/06 07:01:59 DEBUG : dir: forgetting directory cache
2026/04/06 07:01:59 DEBUG : dir: forgetting directory cache
=== RUN   TestDirReadDirAll/Virtual
2026/04/06 07:02:09 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2026/04/06 07:02:09 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2026/04/06 07:02:09 DEBUG : dir: Added virtual directory entry vDel: "file2"
2026/04/06 07:02:09 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2026/04/06 07:03:50 DEBUG : dir: invalidating directory cache
2026/04/06 07:03:57 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir"
2026/04/06 07:03:57 DEBUG : dir: Removed virtual directory entry vDel: "file2"
2026/04/06 07:03:57 DEBUG : dir: Removed virtual directory entry vDel: "subdir"
2026/04/06 07:03:57 DEBUG : dir/file1: Reset virtual modtime
2026/04/06 07:03:57 DEBUG : dir: Removed virtual directory entry vAddFile: "virtualFile"
2026/04/06 07:03:57 DEBUG : dir/virtualFile: Reset virtual modtime
2026/04/06 07:03:57 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile2"
2026/04/06 07:03:57 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir2"
2026/04/06 07:03:57 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/06 07:03:57 DEBUG : dir: invalidating directory cache
2026/04/06 07:04:00 DEBUG : forgetting directory cache
2026/04/06 07:04:00 DEBUG : dir: forgetting directory cache
2026/04/06 07:04:05 DEBUG : dir: Removed virtual directory entry vAddDir: "virtualDir2"
2026/04/06 07:04:05 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/06 07:04:05 DEBUG : dir/virtualFile: Reset virtual modtime
2026/04/06 07:04:05 DEBUG : forgetting directory cache
2026/04/06 07:04:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:04:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:04:05 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:04:05 DEBUG : dir/virtualDir: Looking for writers
2026/04/06 07:04:05 DEBUG : dir: Looking for writers
2026/04/06 07:04:05 DEBUG : virtualFile: reading active writers
2026/04/06 07:04:05 DEBUG : virtualDir: reading active writers
2026/04/06 07:04:05 DEBUG : file1: reading active writers
2026/04/06 07:04:05 DEBUG : virtualFile2: reading active writers
2026/04/06 07:04:05 DEBUG : Looking for writers
2026/04/06 07:04:05 DEBUG : dir: reading active writers
2026/04/06 07:04:05 DEBUG : >WaitForWriters: 
--- PASS: TestDirReadDirAll (302.84s)
    --- PASS: TestDirReadDirAll/Virtual (116.46s)
=== RUN   TestDirOpen
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:04:47 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:05:26 ERROR : dir/: Can only open directories read only
2026/04/06 07:05:26 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:05:26 DEBUG : dir: Looking for writers
2026/04/06 07:05:26 DEBUG : Looking for writers
2026/04/06 07:05:26 DEBUG : dir: reading active writers
2026/04/06 07:05:26 DEBUG : >WaitForWriters: 
--- PASS: TestDirOpen (67.67s)
=== RUN   TestDirCreate
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:05:55 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:06:22 DEBUG : forgetting directory cache
2026/04/06 07:06:22 DEBUG : dir: forgetting directory cache
2026/04/06 07:06:22 DEBUG : dir: forgetting directory cache
2026/04/06 07:06:22 DEBUG : fil: forgetting directory cache
2026/04/06 07:06:22 DEBUG : fil/a: forgetting directory cache
2026/04/06 07:06:22 DEBUG : fil/a/b: forgetting directory cache
2026/04/06 07:06:30 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2026/04/06 07:06:30 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/04/06 07:06:30 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2026/04/06 07:06:30 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/04/06 07:06:30 DEBUG : drime root 'rclone-test-ridasul9gome': File to upload is small (5 bytes), uploading instead of streaming
2026/04/06 07:06:40 DEBUG : dir/potato: size = 5 OK
2026/04/06 07:06:40 NOTICE: drime root 'rclone-test-ridasul9gome': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2026/04/06 07:06:40 DEBUG : dir/potato: Size of src and dst objects identical
2026/04/06 07:06:40 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/04/06 07:06:40 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:06:40 DEBUG : dir: Looking for writers
2026/04/06 07:06:40 DEBUG : potato: reading active writers
2026/04/06 07:06:40 DEBUG : file1: reading active writers
2026/04/06 07:06:40 DEBUG : Looking for writers
2026/04/06 07:06:40 DEBUG : dir: reading active writers
2026/04/06 07:06:40 DEBUG : >WaitForWriters: 
--- PASS: TestDirCreate (71.39s)
=== RUN   TestDirMkdir
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:07:06 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:08:04 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2026/04/06 07:08:11 DEBUG : dir: forgetting directory cache
2026/04/06 07:08:11 DEBUG : forgetting directory cache
2026/04/06 07:08:11 DEBUG : dir: forgetting directory cache
2026/04/06 07:08:13 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:08:13 DEBUG : dir/sub: Looking for writers
2026/04/06 07:08:13 DEBUG : dir: Looking for writers
2026/04/06 07:08:13 DEBUG : file1: reading active writers
2026/04/06 07:08:13 DEBUG : sub: reading active writers
2026/04/06 07:08:13 DEBUG : Looking for writers
2026/04/06 07:08:13 DEBUG : dir: reading active writers
2026/04/06 07:08:13 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdir (97.83s)
=== RUN   TestDirMkdirSub
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:08:44 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:09:12 DEBUG : forgetting directory cache
2026/04/06 07:09:12 DEBUG : dir: forgetting directory cache
2026/04/06 07:09:26 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2026/04/06 07:09:39 DEBUG : dir/sub: Added virtual directory entry vAddDir: "subsub"
2026/04/06 07:09:57 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:09:57 DEBUG : dir/sub/subsub: Looking for writers
2026/04/06 07:09:57 DEBUG : dir/sub: Looking for writers
2026/04/06 07:09:57 DEBUG : subsub: reading active writers
2026/04/06 07:09:57 DEBUG : dir: Looking for writers
2026/04/06 07:09:57 DEBUG : file1: reading active writers
2026/04/06 07:09:57 DEBUG : sub: reading active writers
2026/04/06 07:09:57 DEBUG : Looking for writers
2026/04/06 07:09:57 DEBUG : dir: reading active writers
2026/04/06 07:09:57 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdirSub (132.60s)
=== RUN   TestDirRemove
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:10:57 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:12:07 ERROR : dir/: Dir.Remove not empty
2026/04/06 07:12:07 DEBUG : dir/file1: Remove: 
2026/04/06 07:12:09 DEBUG : dir/subdir: forgetting directory cache
2026/04/06 07:12:14 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/06 07:12:14 DEBUG : dir/file1: >Remove: err=<nil>
2026/04/06 07:12:24 DEBUG : Added virtual directory entry vDel: "dir"
2026/04/06 07:12:27 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:12:27 DEBUG : Looking for writers
2026/04/06 07:12:27 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemove (99.10s)
=== RUN   TestDirRemoveAll
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:12:36 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:13:14 DEBUG : dir/file1: Remove: 
2026/04/06 07:13:17 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/06 07:13:17 DEBUG : dir/file1: >Remove: err=<nil>
2026/04/06 07:13:25 DEBUG : Added virtual directory entry vDel: "dir"
2026/04/06 07:13:31 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:13:31 DEBUG : Looking for writers
2026/04/06 07:13:31 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveAll (67.27s)
=== RUN   TestDirRemoveName
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:13:43 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:13:57 DEBUG : dir/virtualDir2: forgetting directory cache
2026/04/06 07:14:05 DEBUG : forgetting directory cache
2026/04/06 07:14:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:14:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:14:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:14:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:14:20 DEBUG : dir/file1: Remove: 
2026/04/06 07:14:24 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/06 07:14:24 DEBUG : dir/file1: >Remove: err=<nil>
2026/04/06 07:14:33 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:14:33 DEBUG : dir: Looking for writers
2026/04/06 07:14:33 DEBUG : Looking for writers
2026/04/06 07:14:33 DEBUG : dir: reading active writers
2026/04/06 07:14:33 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemoveName (73.60s)
=== RUN   TestDirRename
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:14:56 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:15:26 DEBUG : dir: forgetting directory cache
2026/04/06 07:15:26 DEBUG : forgetting directory cache
2026/04/06 07:15:26 DEBUG : dir: forgetting directory cache
2026/04/06 07:16:26 DEBUG : forgetting directory cache
2026/04/06 07:16:26 DEBUG : dir: forgetting directory cache
2026/04/06 07:16:26 DEBUG : dir: Removed virtual directory entry vAddFile: "potato"
2026/04/06 07:16:32 DEBUG : Couldn't decode error response: invalid character '<' looking for beginning of value
2026/04/06 07:16:32 DEBUG : pacer: low level retry 1/1 (error Error "504 Gateway Timeout (504): <html>\r\n<head><title>504 Gateway Time-out</title></head>\r\n<body>\r\n<center><h1>504 Gateway Time-out</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n")
2026/04/06 07:16:32 DEBUG : pacer: Rate limited, increasing sleep to 20ms
    run.go:286: Retry Put of "dir/file3" to drime root 'rclone-test-ridasul9gome': 1/10 (failed to upload file: Error "504 Gateway Timeout (504): <html>\r\n<head><title>504 Gateway Time-out</title></head>\r\n<body>\r\n<center><h1>504 Gateway Time-out</h1></center>\r\n<hr><center>nginx</center>\r\n</body>\r\n</html>\r\n")
2026/04/06 07:16:41 DEBUG : pacer: Reducing sleep to 10ms
2026/04/06 07:16:53 DEBUG : pacer: low level retry 1/1 (error Error "Server Error")
2026/04/06 07:16:53 DEBUG : pacer: Rate limited, increasing sleep to 20ms
    run.go:286: Retry Put of "dir/file3" to drime root 'rclone-test-ridasul9gome': 2/10 (failed to upload file: Error "Server Error")
2026/04/06 07:17:01 DEBUG : pacer: Reducing sleep to 10ms
2026/04/06 07:17:07 DEBUG : dir/file3: Removing old object on successful upload
    run.go:290: Failed to put "dir/file3" to "drime root 'rclone-test-ridasul9gome'": failed to delete existing object: failed to delete item: Error "The selected entry ids is invalid."
2026/04/06 07:17:14 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:17:14 DEBUG : dir: Looking for writers
2026/04/06 07:17:14 DEBUG : Looking for writers
2026/04/06 07:17:14 DEBUG : dir: reading active writers
2026/04/06 07:17:14 DEBUG : >WaitForWriters: 
--- FAIL: TestDirRename (172.44s)
=== RUN   TestDirStructSize
    dir_test.go:611: Dir struct has size 200 bytes
--- PASS: TestDirStructSize (0.00s)
=== RUN   TestDirFileOpen
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:17:49 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:17:51 DEBUG : forgetting directory cache
2026/04/06 07:17:51 DEBUG : dir: forgetting directory cache
2026/04/06 07:17:51 DEBUG : dir/sub: forgetting directory cache
2026/04/06 07:17:51 DEBUG : dir: Removed virtual directory entry vAddDir: "sub"
2026/04/06 07:18:56 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2026/04/06 07:18:56 DEBUG : dir/sub/file0: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2026/04/06 07:19:03 DEBUG : dir/sub/file0: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2026/04/06 07:19:03 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2026/04/06 07:19:03 DEBUG : dir/sub/file0: >Open: fd=dir/sub/file0 (w), err=<nil>
2026/04/06 07:19:03 DEBUG : dir/sub/file0: >OpenFile: fd=dir/sub/file0 (w), err=<nil>
2026/04/06 07:19:03 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2026/04/06 07:19:03 DEBUG : dir/sub/file2: OpenFile: flags=O_RDWR|O_CREATE|O_TRUNC, perm=-rw-rw-rw-
2026/04/06 07:19:03 DEBUG : dir/sub/file2: Open: flags=O_RDWR|O_CREATE|O_TRUNC
2026/04/06 07:19:03 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2026/04/06 07:19:03 DEBUG : dir/sub/file2: >Open: fd=dir/sub/file2 (w), err=<nil>
2026/04/06 07:19:03 DEBUG : dir/sub/file2: >OpenFile: fd=dir/sub/file2 (w), err=<nil>
2026/04/06 07:19:03 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2026/04/06 07:19:03 DEBUG : drime root 'rclone-test-ridasul9gome': File to upload is small (12 bytes), uploading instead of streaming
2026/04/06 07:19:12 DEBUG : forgetting directory cache
2026/04/06 07:19:12 DEBUG : dir: forgetting directory cache
2026/04/06 07:19:12 DEBUG : dir/sub: forgetting directory cache
2026/04/06 07:19:12 DEBUG : dir/sub/subsub: forgetting directory cache
2026/04/06 07:19:12 DEBUG : dir/sub: Removed virtual directory entry vAddDir: "subsub"
2026/04/06 07:19:12 DEBUG : dir: Removed virtual directory entry vAddDir: "sub"
2026/04/06 07:19:24 DEBUG : dir/sub/file2: size = 12 OK
2026/04/06 07:19:24 DEBUG : dir/sub/file2: Size of src and dst objects identical
2026/04/06 07:19:24 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file2"
2026/04/06 07:19:24 DEBUG : forgetting directory cache
2026/04/06 07:19:24 DEBUG : dir: forgetting directory cache
2026/04/06 07:19:24 DEBUG : dir/sub: forgetting directory cache
2026/04/06 07:19:24 DEBUG : dir/sub: Removed virtual directory entry vAddFile: "file2"
2026/04/06 07:19:24 DEBUG : dir: Removed virtual directory entry vAddDir: "sub"
2026/04/06 07:19:24 DEBUG : drime root 'rclone-test-ridasul9gome': File to upload is small (5 bytes), uploading instead of streaming
2026/04/06 07:19:39 DEBUG : dir/sub/file0: size = 5 OK
2026/04/06 07:19:39 DEBUG : dir/sub/file0: Size of src and dst objects identical
2026/04/06 07:19:39 DEBUG : dir/sub: Added virtual directory entry vAddFile: "file0"
2026/04/06 07:19:39 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:19:39 DEBUG : dir/sub: Looking for writers
2026/04/06 07:19:39 DEBUG : file2: reading active writers
2026/04/06 07:19:39 DEBUG : file0: reading active writers
2026/04/06 07:19:39 DEBUG : dir: Looking for writers
2026/04/06 07:19:39 DEBUG : sub: reading active writers
2026/04/06 07:19:39 DEBUG : file1: reading active writers
2026/04/06 07:19:39 DEBUG : Looking for writers
2026/04/06 07:19:39 DEBUG : dir: reading active writers
2026/04/06 07:19:39 DEBUG : >WaitForWriters: 
--- PASS: TestDirFileOpen (190.37s)
=== RUN   TestDirEntryModTimeInvalidation
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:20:59 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
    dir_test.go:666: Need DirModTimeUpdatesOnWrite
2026/04/06 07:20:59 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:20:59 DEBUG : Looking for writers
2026/04/06 07:20:59 DEBUG : >WaitForWriters: 
--- SKIP: TestDirEntryModTimeInvalidation (14.56s)
=== RUN   TestDirMetadataExtension
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:21:14 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:22:02 DEBUG : forgetting directory cache
2026/04/06 07:22:02 DEBUG : Removed virtual directory entry vDel: "dir"
2026/04/06 07:22:07 DEBUG : dir: forgetting directory cache
2026/04/06 07:22:07 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/06 07:22:48 DEBUG : dir: Added virtual directory entry vAddFile: "file1.metadata"
2026/04/06 07:22:48 DEBUG : dir/file1.metadata: Set virtual modtime to 2026-04-06 07:21:45 +0000 UTC
2026/04/06 07:22:48 DEBUG : dir/file1.metadata: OpenFile: flags=O_RDONLY, perm=----------
2026/04/06 07:22:48 DEBUG : dir/file1.metadata: Open: flags=O_RDONLY
2026/04/06 07:22:48 DEBUG : dir/file1.metadata: >Open: fd=dir/file1.metadata (r), err=<nil>
2026/04/06 07:22:48 DEBUG : dir/file1.metadata: >OpenFile: fd=dir/file1.metadata (r), err=<nil>
2026/04/06 07:22:48 DEBUG : dir/file1.metadata: ChunkedReader.openRange at 0 length 134217728
2026/04/06 07:22:48 DEBUG : dir/file1.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2026/04/06 07:22:48 DEBUG : Added virtual directory entry vAddFile: "dir.metadata"
2026/04/06 07:22:48 DEBUG : dir.metadata: Set virtual modtime to 2026-04-06 07:21:56 +0000 UTC
2026/04/06 07:22:48 DEBUG : dir.metadata: OpenFile: flags=O_RDONLY, perm=----------
2026/04/06 07:22:48 DEBUG : dir.metadata: Open: flags=O_RDONLY
2026/04/06 07:22:48 DEBUG : dir.metadata: >Open: fd=dir.metadata (r), err=<nil>
2026/04/06 07:22:48 DEBUG : dir.metadata: >OpenFile: fd=dir.metadata (r), err=<nil>
2026/04/06 07:22:48 DEBUG : dir.metadata: ChunkedReader.openRange at 0 length 134217728
2026/04/06 07:22:48 DEBUG : dir.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2026/04/06 07:22:48 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:22:48 DEBUG : dir: Looking for writers
2026/04/06 07:22:48 DEBUG : file1: reading active writers
2026/04/06 07:22:48 DEBUG : file1.metadata: reading active writers
2026/04/06 07:22:48 DEBUG : Looking for writers
2026/04/06 07:22:48 DEBUG : dir: reading active writers
2026/04/06 07:22:48 DEBUG : dir.metadata: reading active writers
2026/04/06 07:22:48 DEBUG : >WaitForWriters: 
2026/04/06 07:23:11 DEBUG : forgetting directory cache
2026/04/06 07:23:11 DEBUG : Removed virtual directory entry vDel: "dir"
2026/04/06 07:23:14 DEBUG : dir: forgetting directory cache
2026/04/06 07:23:14 DEBUG : dir: Removed virtual directory entry vDel: "file1"
--- PASS: TestDirMetadataExtension (128.93s)
=== RUN   TestErrorError
--- PASS: TestErrorError (0.00s)
=== RUN   TestFileMethods
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:23:23 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:24:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:24:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:24:05 DEBUG : forgetting directory cache
2026/04/06 07:24:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:24:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:24:15 DEBUG : forgetting directory cache
2026/04/06 07:24:15 DEBUG : dir: forgetting directory cache
2026/04/06 07:24:15 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/06 07:24:19 DEBUG : dir/file1: Set virtual modtime to 2026-04-06 07:24:01 +0000 UTC
2026/04/06 07:24:19 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:24:19 DEBUG : dir: Looking for writers
2026/04/06 07:24:19 DEBUG : file1: reading active writers
2026/04/06 07:24:19 DEBUG : Looking for writers
2026/04/06 07:24:19 DEBUG : dir: reading active writers
2026/04/06 07:24:19 DEBUG : >WaitForWriters: 
--- PASS: TestFileMethods (96.10s)
=== RUN   TestFileSetModTime
=== RUN   TestFileSetModTime/cache=off,open=false,write=false
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:24:59 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:25:24 DEBUG : dir: forgetting directory cache
2026/04/06 07:25:24 DEBUG : forgetting directory cache
2026/04/06 07:25:24 DEBUG : dir: forgetting directory cache
2026/04/06 07:26:12 DEBUG : Can set mod time: false
    file_test.go:97: can't set mod time
2026/04/06 07:26:12 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:26:12 DEBUG : dir: Looking for writers
2026/04/06 07:26:12 DEBUG : file1: reading active writers
2026/04/06 07:26:12 DEBUG : Looking for writers
2026/04/06 07:26:12 DEBUG : dir: reading active writers
2026/04/06 07:26:12 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
=== RUN   TestFileSetModTime/cache=full,open=true,write=true
    file_test.go:93: can't set mod time
--- PASS: TestFileSetModTime (127.99s)
    --- SKIP: TestFileSetModTime/cache=off,open=false,write=false (127.99s)
    --- 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)
    --- SKIP: TestFileSetModTime/cache=full,open=true,write=true (0.00s)
=== RUN   TestFileOpenRead
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:27:07 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:28:10 DEBUG : dir/file1: Open: flags=O_RDONLY
2026/04/06 07:28:10 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2026/04/06 07:28:10 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2026/04/06 07:28:19 DEBUG : dir/file1: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2026/04/06 07:28:19 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:28:19 DEBUG : dir: Looking for writers
2026/04/06 07:28:19 DEBUG : file1: reading active writers
2026/04/06 07:28:19 DEBUG : Looking for writers
2026/04/06 07:28:19 DEBUG : dir: reading active writers
2026/04/06 07:28:19 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpenRead (99.53s)
=== RUN   TestFileOpenReadUnknownSize
2026/04/06 07:28:46 INFO  : Mock file system at root: poll-interval is not supported by this remote
2026/04/06 07:28:46 NOTICE: Mock file system at root: --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/04/06 07:28:46 DEBUG : file.txt: ChunkedReader.openRange at 0 length 134217728
2026/04/06 07:28:46 DEBUG : file.txt: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
    file_test.go:223: gotContents = "file contents"
2026/04/06 07:28:46 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:28:46 DEBUG : Looking for writers
2026/04/06 07:28:46 DEBUG : file.txt: reading active writers
2026/04/06 07:28:46 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpenReadUnknownSize (0.00s)
=== RUN   TestFileOpenWrite
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:28:46 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:29:24 DEBUG : dir/sub: forgetting directory cache
2026/04/06 07:29:24 DEBUG : dir/sub: Removed virtual directory entry vAddFile: "file0"
2026/04/06 07:29:24 DEBUG : forgetting directory cache
2026/04/06 07:29:24 DEBUG : dir: forgetting directory cache
2026/04/06 07:29:24 DEBUG : dir/sub: forgetting directory cache
2026/04/06 07:29:24 DEBUG : dir: forgetting directory cache
2026/04/06 07:29:24 DEBUG : dir/sub: forgetting directory cache
2026/04/06 07:30:16 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2026/04/06 07:30:16 DEBUG : drime root 'rclone-test-ridasul9gome': File to upload is small (25 bytes), uploading instead of streaming
2026/04/06 07:30:45 DEBUG : dir/file1: Removing old object on successful upload
2026/04/06 07:30:53 ERROR : dir/file1: WriteFileHandle.New Rcat failed: failed to delete existing object: failed to delete item: Error "The selected entry ids is invalid."
    file_test.go:241: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:241
        	Error:      	Received unexpected error:
        	            	failed to delete existing object: failed to delete item: Error "The selected entry ids is invalid."
        	Test:       	TestFileOpenWrite
2026/04/06 07:30:53 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:30:53 DEBUG : dir: Looking for writers
2026/04/06 07:30:53 DEBUG : file1: reading active writers
2026/04/06 07:30:53 DEBUG : Looking for writers
2026/04/06 07:30:53 DEBUG : dir: reading active writers
2026/04/06 07:30:53 DEBUG : >WaitForWriters: 
2026/04/06 07:30:59 DEBUG : forgetting directory cache
--- FAIL: TestFileOpenWrite (161.04s)
=== RUN   TestFileRemove
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:31:27 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:32:02 DEBUG : forgetting directory cache
2026/04/06 07:32:21 DEBUG : dir/file1: Remove: 
2026/04/06 07:32:27 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/06 07:32:27 DEBUG : dir/file1: >Remove: err=<nil>
2026/04/06 07:32:39 DEBUG : forgetting directory cache
2026/04/06 07:32:39 DEBUG : dir: forgetting directory cache
2026/04/06 07:32:39 DEBUG : dir: Removed virtual directory entry vAddFile: "file1.metadata"
2026/04/06 07:32:39 DEBUG : Removed virtual directory entry vAddFile: "dir.metadata"
2026/04/06 07:32:41 DEBUG : dir/file1: Remove: 
2026/04/06 07:32:41 DEBUG : dir/file1: >Remove: err=Read only file system
2026/04/06 07:32:41 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:32:41 DEBUG : dir: Looking for writers
2026/04/06 07:32:41 DEBUG : Looking for writers
2026/04/06 07:32:41 DEBUG : dir: reading active writers
2026/04/06 07:32:41 DEBUG : >WaitForWriters: 
--- PASS: TestFileRemove (101.58s)
=== RUN   TestFileRemoveAll
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:33:09 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:33:11 DEBUG : forgetting directory cache
2026/04/06 07:34:05 DEBUG : forgetting directory cache
2026/04/06 07:34:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:34:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:34:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:34:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:34:10 DEBUG : dir/file1: Remove: 
2026/04/06 07:34:13 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/04/06 07:34:13 DEBUG : dir/file1: >Remove: err=<nil>
2026/04/06 07:34:16 DEBUG : forgetting directory cache
2026/04/06 07:34:16 DEBUG : dir: forgetting directory cache
2026/04/06 07:34:22 DEBUG : dir/file1: Remove: 
2026/04/06 07:34:22 DEBUG : dir/file1: >Remove: err=Read only file system
2026/04/06 07:34:22 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:34:22 DEBUG : dir: Looking for writers
2026/04/06 07:34:22 DEBUG : Looking for writers
2026/04/06 07:34:22 DEBUG : dir: reading active writers
2026/04/06 07:34:22 DEBUG : >WaitForWriters: 
--- PASS: TestFileRemoveAll (101.48s)
=== RUN   TestFileOpen
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:34:50 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:35:44 DEBUG : forgetting directory cache
2026/04/06 07:35:44 DEBUG : dir: forgetting directory cache
2026/04/06 07:35:44 DEBUG : dir/file1: Open: flags=O_RDONLY
2026/04/06 07:35:44 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2026/04/06 07:35:44 DEBUG : dir/file1: Open: flags=O_WRONLY
2026/04/06 07:35:44 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2026/04/06 07:35:44 DEBUG : dir/file1: Open: flags=O_RDWR
2026/04/06 07:35:44 DEBUG : dir/file1: >Open: fd=dir/file1 (w), err=<nil>
2026/04/06 07:35:44 DEBUG : dir/file1: Open: flags=0x3
2026/04/06 07:35:44 DEBUG : dir/file1: Can't figure out how to open with flags: 0x3
2026/04/06 07:35:44 DEBUG : dir/file1: >Open: fd=<nil>, err=permission denied
2026/04/06 07:35:44 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:35:44 DEBUG : dir: Looking for writers
2026/04/06 07:35:44 DEBUG : file1: reading active writers
2026/04/06 07:35:44 DEBUG : Looking for writers
2026/04/06 07:35:44 DEBUG : dir: reading active writers
2026/04/06 07:35:44 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpen (82.87s)
=== RUN   TestFileRename
=== RUN   TestFileRename/off,forceCache=false
    run.go:185: Remote "drime root 'rclone-test-ridasul9gome'", Local "Local file system at /tmp/rclone3590281827", Modify Window "876000h0m0s"
2026/04/06 07:36:13 INFO  : drime root 'rclone-test-ridasul9gome': poll-interval is not supported by this remote
2026/04/06 07:37:13 DEBUG : WaitForWriters: timeout=30s
2026/04/06 07:37:13 DEBUG : dir: Looking for writers
2026/04/06 07:37:13 DEBUG : file1: reading active writers
2026/04/06 07:37:13 DEBUG : Looking for writers
2026/04/06 07:37:13 DEBUG : dir: reading active writers
2026/04/06 07:37:13 DEBUG : >WaitForWriters: 
2026/04/06 07:38:03 DEBUG : forgetting directory cache
2026/04/06 07:38:03 DEBUG : dir: forgetting directory cache
2026/04/06 07:38:46 DEBUG : forgetting directory cache
2026/04/06 07:40:00 DEBUG : forgetting directory cache
2026/04/06 07:40:00 DEBUG : dir: forgetting directory cache
2026/04/06 07:40:00 DEBUG : dir: Removed virtual directory entry vAddFile: "file1"
2026/04/06 07:42:14 DEBUG : forgetting directory cache
2026/04/06 07:42:14 DEBUG : dir: forgetting directory cache
2026/04/06 07:42:14 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/06 07:44:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:44:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:44:05 DEBUG : forgetting directory cache
2026/04/06 07:44:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:44:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:44:06 DEBUG : forgetting directory cache
2026/04/06 07:44:06 DEBUG : dir: forgetting directory cache
2026/04/06 07:44:06 DEBUG : dir: Removed virtual directory entry vDel: "file1"
2026/04/06 07:45:38 DEBUG : forgetting directory cache
2026/04/06 07:45:38 DEBUG : dir: forgetting directory cache
2026/04/06 07:47:08 DEBUG : forgetting directory cache
2026/04/06 07:47:08 DEBUG : dir: forgetting directory cache
2026/04/06 07:54:05 DEBUG : forgetting directory cache
2026/04/06 07:54:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:54:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:54:05 DEBUG : dir: forgetting directory cache
2026/04/06 07:54:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 07:57:03 DEBUG : pacer: low level retry 1/10 (error Put "https://app.drime.cloud/api/v1/file-entries/677789699": read tcp 65.108.87.141:42008->57.130.54.115:443: read: connection reset by peer)
2026/04/06 07:57:03 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2026/04/06 08:04:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:04:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:04:05 DEBUG : forgetting directory cache
2026/04/06 08:04:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:04:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:14:05 DEBUG : forgetting directory cache
2026/04/06 08:14:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:14:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:14:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:14:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:24:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:24:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:24:05 DEBUG : forgetting directory cache
2026/04/06 08:24:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:24:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:34:05 DEBUG : forgetting directory cache
2026/04/06 08:34:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:34:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:34:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:34:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:44:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:44:05 DEBUG : dir/virtualDir: forgetting directory cache
2026/04/06 08:44:05 DEBUG : forgetting directory cache
2026/04/06 08:44:05 DEBUG : dir: forgetting directory cache
2026/04/06 08:44:05 DEBUG : dir/virtualDir: forgetting directory cache
panic: test timed out after 2h0m0s
	running tests:
		TestFileRename (1h10m1s)
		TestFileRename/off,forceCache=false (1h10m1s)

goroutine 379772 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:2802 +0x34b
created by time.goFunc
	/usr/local/go/src/time/sleep.go:215 +0x2d

goroutine 1 [chan receive, 71 minutes]:
testing.(*T).Run(0xf67893cfc8, {0x2a21575?, 0xf67880fae8?}, 0x2ba0538)
	/usr/local/go/src/testing/testing.go:2109 +0x4e5
testing.runTests.func1(0xf67893cfc8)
	/usr/local/go/src/testing/testing.go:2585 +0x37
testing.tRunner(0xf67893cfc8, 0xf67880fc10)
	/usr/local/go/src/testing/testing.go:2036 +0xea
testing.runTests({0x2a44c9c, 0x18}, {0x2a548fa, 0x1c}, 0xf678b52108, {0x464aca0, 0x59, 0x59}, {0xc26cfa95ad514921, 0x68ec11ca09b, ...})
	/usr/local/go/src/testing/testing.go:2583 +0x505
testing.(*M).Run(0xf678ad4b40)
	/usr/local/go/src/testing/testing.go:2443 +0x6ac
github.com/rclone/rclone/fstest.TestMain(0xf678ad4b40)
	/home/rclone/go/src/github.com/rclone/rclone/fstest/run.go:74 +0xa6
github.com/rclone/rclone/vfs.TestMain(...)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs_test.go:36
main.main()
	_testmain.go:226 +0xa6

goroutine 2104 [chan receive, 71 minutes]:
testing.(*T).Run(0xf6785dc008, {0xf6782ec510?, 0xf678718f30?}, 0xf67881a7d0)
	/usr/local/go/src/testing/testing.go:2109 +0x4e5
github.com/rclone/rclone/vfs.TestFileRename(0xf6785dc008)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:412 +0x119
testing.tRunner(0xf6785dc008, 0x2ba0538)
	/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

goroutine 28 [syscall, 120 minutes]:
os/signal.signal_recv()
	/usr/local/go/src/runtime/sigqueue.go:152 +0x98
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:23 +0x13
created by os/signal.Notify.func1.1 in goroutine 1
	/usr/local/go/src/os/signal/signal.go:152 +0x1f

goroutine 29 [chan receive, 120 minutes]:
github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler.func1()
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:24 +0x27
created by github.com/rclone/rclone/fs/accounting.(*tokenBucket).startSignalHandler in goroutine 1
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting_unix.go:21 +0xa7

goroutine 2186 [select]:
github.com/rclone/rclone/fs/accounting.(*Account).averageLoop(0xf678930c00)
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:222 +0xec
created by github.com/rclone/rclone/fs/accounting.newAccountSizeName in goroutine 2105
	/home/rclone/go/src/github.com/rclone/rclone/fs/accounting/accounting.go:120 +0x43f

goroutine 379771 [select]:
net/http.(*http2clientStream).writeRequest(0xf678858000, 0xf67861c780, 0x0)
	/usr/local/go/src/net/http/h2_bundle.go:8857 +0xc68
net/http.(*http2clientStream).doRequest(0xf678858000, 0xe16d07f85885e9ff?, 0x0?)
	/usr/local/go/src/net/http/h2_bundle.go:8718 +0x18
created by net/http.(*http2ClientConn).roundTrip in goroutine 2105
	/usr/local/go/src/net/http/h2_bundle.go:8624 +0x470

goroutine 2106 [select, 71 minutes]:
github.com/rclone/rclone/vfs.(*VFS).signalHandler(0xf678513900, {0x2be6b08, 0xf67890e2d0})
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs.go:290 +0xc5
created by github.com/rclone/rclone/vfs.New in goroutine 2105
	/home/rclone/go/src/github.com/rclone/rclone/vfs/vfs.go:266 +0x852

goroutine 2105 [select]:
net/http.(*http2ClientConn).roundTrip(0xf6783fa540, 0xf67861c780, 0x0)
	/usr/local/go/src/net/http/h2_bundle.go:8688 +0x525
net/http.(*http2ClientConn).RoundTrip(...)
	/usr/local/go/src/net/http/h2_bundle.go:8603
net/http.(*http2Transport).RoundTripOpt(0xf678342140, 0xf67861c780, {0x48?, 0x43?})
	/usr/local/go/src/net/http/h2_bundle.go:7901 +0x1ed
net/http.(*http2Transport).RoundTrip(0xf6786fe1a0?, 0xf67890ecd0?)
	/usr/local/go/src/net/http/h2_bundle.go:7852 +0x17
net/http.(*Transport).roundTrip(0xf6786fe1a0, 0xf67856d540)
	/usr/local/go/src/net/http/transport.go:702 +0xaab
net/http.(*Transport).RoundTrip(...)
	/usr/local/go/src/net/http/roundtrip.go:33
github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip(0xf6783da540, 0xf67856d540)
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/http.go:496 +0x34a
net/http.send(0xf67856d540, {0x2bbc760, 0xf6783da540}, {0xf6781b49e0?, 0x4936a6?, 0x0?})
	/usr/local/go/src/net/http/client.go:264 +0x64b
net/http.(*Client).send(0xf6784d5e60, 0xf67856d540, {0xf678adca01?, 0xf6781b4a68?, 0x0?})
	/usr/local/go/src/net/http/client.go:185 +0x258
net/http.(*Client).do(0xf6784d5e60, 0xf67856d540)
	/usr/local/go/src/net/http/client.go:733 +0x9d7
net/http.(*Client).Do(...)
	/usr/local/go/src/net/http/client.go:592
github.com/rclone/rclone/lib/rest.(*Client).Call(0xf6785ba000, {0x2be6a28, 0x468d040}, 0xf6781b50d0)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:371 +0xd85
github.com/rclone/rclone/lib/rest.(*Client).callCodec(0xf6785ba000, {0x2be6a28, 0x468d040}, 0xf678992580?, {0x233d280?, 0xf67862c500?}, {0x233d2c0, 0xf67883f800}, 0xf6781b5200?, 0x2ba1ef8, ...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:579 +0x447
github.com/rclone/rclone/lib/rest.(*Client).CallJSON(...)
	/home/rclone/go/src/github.com/rclone/rclone/lib/rest/rest.go:522
github.com/rclone/rclone/backend/drime.(*Fs).patch.func1()
	/home/rclone/go/src/github.com/rclone/rclone/backend/drime/drime.go:794 +0x8d
github.com/rclone/rclone/fs.pacerInvoker(0x2, 0xa, 0x2bbb3a0?)
	/home/rclone/go/src/github.com/rclone/rclone/fs/pacer.go:86 +0x32
github.com/rclone/rclone/lib/pacer.(*Pacer).call(0xf6783da5a0, 0xf67853c9b0, 0xa)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:228 +0xd2
github.com/rclone/rclone/lib/pacer.(*Pacer).Call(0xf6783da5a0, 0xf67853c9b0)
	/home/rclone/go/src/github.com/rclone/rclone/lib/pacer/pacer.go:247 +0x92
github.com/rclone/rclone/backend/drime.(*Fs).patch(0xf678342000, {0x2be6a28, 0x468d040}, {0xf67862a250, 0x9}, {0x2a029e7, 0x4}, {0xf67862a780, 0x10})
	/home/rclone/go/src/github.com/rclone/rclone/backend/drime/drime.go:793 +0x3ae
github.com/rclone/rclone/backend/drime.(*Fs).rename(0xf678342000, {0x2be6a28, 0x468d040}, {0xf67862a250, 0x9}, {0xf67862a780, 0x10})
	/home/rclone/go/src/github.com/rclone/rclone/backend/drime/drime.go:805 +0x96
github.com/rclone/rclone/backend/drime.(*Fs).moveTo(0xf678342000, {0x2be6a28, 0x468d040}, {0xf67862a250, 0x9}, {0xf67862a2b4, 0x5}, {0xf6788b2369, 0x7}, {0xf67881a180, ...}, ...)
	/home/rclone/go/src/github.com/rclone/rclone/backend/drime/drime.go:848 +0x1c5
github.com/rclone/rclone/backend/drime.(*Fs).Move(0xf678342000, {0x2be6a28, 0x468d040}, {0x2c03000?, 0xf6783d8180?}, {0xf6788b2369, 0x7})
	/home/rclone/go/src/github.com/rclone/rclone/backend/drime/drime.go:910 +0x1c9
github.com/rclone/rclone/fs/operations.move({0x2be6a28, 0x468d040}, {0x2c02f90, 0xf678342000}, {0x0, 0x0}, {0xf6788b2369, 0x7}, {0x2c03000, 0xf6783d8180}, ...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:487 +0x810
github.com/rclone/rclone/fs/operations.Move(...)
	/home/rclone/go/src/github.com/rclone/rclone/fs/operations/operations.go:421
github.com/rclone/rclone/vfs.(*File).rename.func1({0x2be6a28, 0x468d040})
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file.go:270 +0x265
github.com/rclone/rclone/vfs.(*File).rename(0xf6784c60c0, {0x2be6a28, 0x468d040}, 0xf6788848f0, {0x2a0de60, 0x7})
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file.go:324 +0x4a3
github.com/rclone/rclone/vfs.(*Dir).Rename(0xf67834c1a0, {0x2a040a4, 0x5}, {0x2a0de60, 0x7}, 0xf6788848f0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir.go:1205 +0x618
github.com/rclone/rclone/vfs.testFileRename(0xf6785dc908, 0xb3?, 0x0, 0x0)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:341 +0x448
github.com/rclone/rclone/vfs.TestFileRename.func1(0xf6785dc908?)
	/home/rclone/go/src/github.com/rclone/rclone/vfs/file_test.go:413 +0x1f
testing.tRunner(0xf6785dc908, 0xf67881a7d0)
	/usr/local/go/src/testing/testing.go:2036 +0xea
created by testing.(*T).Run in goroutine 2104
	/usr/local/go/src/testing/testing.go:2101 +0x4c5

goroutine 379770 [IO wait]:
internal/poll.runtime_pollWait(0x74a1f3a27800, 0x72)
	/usr/local/go/src/runtime/netpoll.go:351 +0x85
internal/poll.(*pollDesc).wait(0xf6783d8400?, 0xf67886a000?, 0x0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xf6783d8400, {0xf67886a000, 0x1300, 0x1300})
	/usr/local/go/src/internal/poll/fd_unix.go:165 +0x2ae
net.(*netFD).Read(0xf6783d8400, {0xf67886a000?, 0x0?, 0x0?})
	/usr/local/go/src/net/fd_posix.go:68 +0x25
net.(*conn).Read(0xf67814a430, {0xf67886a000?, 0x1001c?, 0x0?})
	/usr/local/go/src/net/net.go:196 +0x45
github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read(0xf6789081b0, {0xf67886a000?, 0x74a1ac2fc760?, 0x74a1f3aec2f8?})
	/home/rclone/go/src/github.com/rclone/rclone/fs/fshttp/dialer.go:111 +0x29
crypto/tls.(*atLeastReader).Read(0xf6788c50b0, {0xf67886a000?, 0xf6786fc1e0?, 0xf6788eaa48?})
	/usr/local/go/src/crypto/tls/conn.go:815 +0x3b
bytes.(*Buffer).ReadFrom(0xf6786609a8, {0x2bbe1a0, 0xf6788c50b0})
	/usr/local/go/src/bytes/buffer.go:229 +0x98
crypto/tls.(*Conn).readFromUntil(0xf678660708, {0x74a1ac43f860, 0xf6789081b0}, 0xf6788eac08?)
	/usr/local/go/src/crypto/tls/conn.go:837 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xf678660708, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:626 +0x3db
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:588
crypto/tls.(*Conn).Read(0xf678660708, {0xf67887f000, 0x1000, 0x0?})
	/usr/local/go/src/crypto/tls/conn.go:1393 +0x145
bufio.(*Reader).Read(0xf67887c0c0, {0xf678b6e044, 0x9, 0x1000065?})
	/usr/local/go/src/bufio/bufio.go:245 +0x197
io.ReadAtLeast({0x2bbaf60, 0xf67887c0c0}, {0xf678b6e044, 0x9, 0x9}, 0x9)
	/usr/local/go/src/io/io.go:335 +0x8e
io.ReadFull(...)
	/usr/local/go/src/io/io.go:354
net/http.http2readFrameHeader({0xf678b6e044, 0x9, 0x0?}, {0x2bbaf60?, 0xf67887c0c0?})
	/usr/local/go/src/net/http/h2_bundle.go:1805 +0x65
net/http.(*http2Framer).ReadFrameHeader(0xf678b6e000)
	/usr/local/go/src/net/http/h2_bundle.go:2071 +0x6b
net/http.(*http2Framer).ReadFrame(0xf678b6e000)
	/usr/local/go/src/net/http/h2_bundle.go:2130 +0x18
net/http.(*http2clientConnReadLoop).run(0xf6788eafa8)
	/usr/local/go/src/net/http/h2_bundle.go:9550 +0xca
net/http.(*http2ClientConn).readLoop(0xf6783fa540)
	/usr/local/go/src/net/http/h2_bundle.go:9419 +0x52
created by net/http.(*http2Transport).newClientConn in goroutine 379769
	/usr/local/go/src/net/http/h2_bundle.go:8171 +0xda5
"./vfs.test -test.v -test.timeout 2h0m0s -remote TestDrime: -verbose" - Finished ERROR in 2h0m10.214835756s (try 2/5): exit status 2: Failed [TestDirRename TestFileOpenWrite]