"./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestDirCreate|TestDirMkdir|TestDirMkdirSub|TestDirRemove|TestDirWalk|TestFileOpenWrite|TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestVFSMkdir|TestVFSStat|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileModTimeWithOpenWriters)$|^TestDirReadDirAll$/^Virtual$|^TestFileRename$/^full,forceCache=false$'" - Starting (try 2/5)
2026/08/31 04:37:36 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-koposul0noru"
2026/08/31 04:37:36 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/08/31 04:37:36 DEBUG : Linkbox root 'rclone-test-koposul0noru': Using cached web token
2026/08/31 04:37:37 DEBUG : Creating backend with remote "/tmp/rclone1982117180"
=== RUN   TestDirWalk
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:37:37 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:37:37 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:37:46 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:46 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2026/08/31 04:37:46 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:46 DEBUG : pacer: Rate limited, increasing sleep to 800ms
2026/08/31 04:37:46 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:46 DEBUG : pacer: Rate limited, increasing sleep to 1.6s
2026/08/31 04:37:47 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:47 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/08/31 04:37:49 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:51 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:53 DEBUG : pacer: low level retry 7/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:55 DEBUG : pacer: low level retry 8/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:57 DEBUG : pacer: low level retry 9/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:37:59 DEBUG : pacer: low level retry 10/10 (error invalid character '<' looking for beginning of value)
    run.go:299: Retry Put of "fil/a/b/c" to Linkbox root 'rclone-test-koposul0noru': 1/10 (failed to make directory: CreateDir failed: invalid character '<' looking for beginning of value)
2026/08/31 04:38:01 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:03 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:05 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:07 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:09 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:11 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:13 DEBUG : pacer: low level retry 7/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:15 DEBUG : pacer: low level retry 8/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:17 DEBUG : pacer: Reducing sleep to 1.5s
2026/08/31 04:38:20 DEBUG : pacer: Reducing sleep to 1.125s
2026/08/31 04:38:20 DEBUG : pacer: Reducing sleep to 843.75ms
2026/08/31 04:38:22 DEBUG : pacer: Reducing sleep to 632.8125ms
2026/08/31 04:38:24 DEBUG : pacer: Reducing sleep to 474.609375ms
2026/08/31 04:38:24 DEBUG : pacer: Reducing sleep to 355.957031ms
2026/08/31 04:38:25 DEBUG : pacer: Reducing sleep to 266.967773ms
2026/08/31 04:38:25 DEBUG : pacer: Reducing sleep to 200.225829ms
2026/08/31 04:38:25 DEBUG : pacer: Reducing sleep to 200ms
2026/08/31 04:38:26 DEBUG : forgetting directory cache
2026/08/31 04:38:26 DEBUG : dir: forgetting directory cache
2026/08/31 04:38:26 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:38:26 DEBUG : dir: Looking for writers
2026/08/31 04:38:26 DEBUG : fil/a/b: Looking for writers
2026/08/31 04:38:26 DEBUG : fil/a: Looking for writers
2026/08/31 04:38:26 DEBUG : b: reading active writers
2026/08/31 04:38:26 DEBUG : fil: Looking for writers
2026/08/31 04:38:26 DEBUG : a: reading active writers
2026/08/31 04:38:26 DEBUG : Looking for writers
2026/08/31 04:38:26 DEBUG : dir: reading active writers
2026/08/31 04:38:26 DEBUG : fil: reading active writers
2026/08/31 04:38:26 DEBUG : >WaitForWriters: 
--- PASS: TestDirWalk (59.65s)
=== RUN   TestDirReadDirAll
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:38:36 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:38:36 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
=== RUN   TestDirReadDirAll/Virtual
2026/08/31 04:38:47 DEBUG : dir: Added virtual directory entry vAddFile: "virtualFile"
2026/08/31 04:38:47 DEBUG : dir: Added virtual directory entry vAddDir: "virtualDir"
2026/08/31 04:38:47 DEBUG : dir: Added virtual directory entry vDel: "file2"
2026/08/31 04:38:47 DEBUG : dir: Added virtual directory entry vDel: "subdir"
2026/08/31 04:38:54 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:54 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2026/08/31 04:38:54 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:54 DEBUG : pacer: Rate limited, increasing sleep to 800ms
2026/08/31 04:38:54 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:54 DEBUG : pacer: Rate limited, increasing sleep to 1.6s
2026/08/31 04:38:55 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:55 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/08/31 04:38:57 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:38:59 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:01 DEBUG : pacer: low level retry 7/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:03 DEBUG : pacer: low level retry 8/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:05 DEBUG : pacer: low level retry 9/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:07 DEBUG : pacer: low level retry 10/10 (error invalid character '<' looking for beginning of value)
    dir_test.go:295: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/vfs/dir_test.go:295
        	Error:      	Received unexpected error:
        	            	purge error: invalid character '<' looking for beginning of value
        	Test:       	TestDirReadDirAll/Virtual
2026/08/31 04:39:07 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:39:07 DEBUG : dir/virtualDir: Looking for writers
2026/08/31 04:39:07 DEBUG : dir: Looking for writers
2026/08/31 04:39:07 DEBUG : file1: reading active writers
2026/08/31 04:39:07 DEBUG : virtualFile: reading active writers
2026/08/31 04:39:07 DEBUG : virtualDir: reading active writers
2026/08/31 04:39:07 DEBUG : Looking for writers
2026/08/31 04:39:07 DEBUG : dir: reading active writers
2026/08/31 04:39:07 DEBUG : >WaitForWriters: 
2026/08/31 04:39:09 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:11 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:13 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:15 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:17 DEBUG : pacer: Reducing sleep to 1.5s
2026/08/31 04:39:19 DEBUG : pacer: Reducing sleep to 1.125s
2026/08/31 04:39:22 DEBUG : pacer: Reducing sleep to 843.75ms
2026/08/31 04:39:23 DEBUG : pacer: Reducing sleep to 632.8125ms
2026/08/31 04:39:23 DEBUG : pacer: Reducing sleep to 474.609375ms
2026/08/31 04:39:24 DEBUG : pacer: Reducing sleep to 355.957031ms
2026/08/31 04:39:25 DEBUG : pacer: Reducing sleep to 266.967773ms
2026/08/31 04:39:27 DEBUG : pacer: Reducing sleep to 200.225829ms
2026/08/31 04:39:27 DEBUG : pacer: Reducing sleep to 200ms
--- FAIL: TestDirReadDirAll (55.19s)
    --- FAIL: TestDirReadDirAll/Virtual (20.07s)
=== RUN   TestDirCreate
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:39:31 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:39:31 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:39:36 DEBUG : dir/potato: Open: flags=O_WRONLY|O_CREATE
2026/08/31 04:39:36 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/08/31 04:39:36 DEBUG : dir/potato: >Open: fd=dir/potato (w), err=<nil>
2026/08/31 04:39:36 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/08/31 04:39:36 DEBUG : Linkbox root 'rclone-test-koposul0noru': File to upload is small (5 bytes), uploading instead of streaming
2026/08/31 04:39:38 DEBUG : dir/potato: size = 5 OK
2026/08/31 04:39:38 NOTICE: Linkbox root 'rclone-test-koposul0noru': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2026/08/31 04:39:38 DEBUG : dir/potato: Size of src and dst objects identical
2026/08/31 04:39:38 DEBUG : dir: Added virtual directory entry vAddFile: "potato"
2026/08/31 04:39:38 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:39:38 DEBUG : dir: Looking for writers
2026/08/31 04:39:38 DEBUG : file1: reading active writers
2026/08/31 04:39:38 DEBUG : potato: reading active writers
2026/08/31 04:39:38 DEBUG : Looking for writers
2026/08/31 04:39:38 DEBUG : dir: reading active writers
2026/08/31 04:39:38 DEBUG : >WaitForWriters: 
--- PASS: TestDirCreate (11.18s)
=== RUN   TestDirMkdir
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:39:43 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:39:43 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:39:49 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2026/08/31 04:39:49 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:39:49 DEBUG : dir/sub: Looking for writers
2026/08/31 04:39:49 DEBUG : dir: Looking for writers
2026/08/31 04:39:49 DEBUG : file1: reading active writers
2026/08/31 04:39:49 DEBUG : sub: reading active writers
2026/08/31 04:39:49 DEBUG : Looking for writers
2026/08/31 04:39:49 DEBUG : dir: reading active writers
2026/08/31 04:39:49 DEBUG : >WaitForWriters: 
2026/08/31 04:39:53 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:53 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2026/08/31 04:39:53 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:53 DEBUG : pacer: Rate limited, increasing sleep to 800ms
2026/08/31 04:39:54 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:54 DEBUG : pacer: Rate limited, increasing sleep to 1.6s
2026/08/31 04:39:54 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:54 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/08/31 04:39:56 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:39:58 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:00 DEBUG : pacer: low level retry 7/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:02 DEBUG : pacer: low level retry 8/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:04 DEBUG : pacer: low level retry 9/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:06 DEBUG : pacer: low level retry 10/10 (error invalid character '<' looking for beginning of value)
    run.go:186: removing dir "dir" failed - try 1/3: sleeping 1s: getting files failed: invalid character '<' looking for beginning of value
2026/08/31 04:40:08 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:10 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:12 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:14 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:16 DEBUG : pacer: Reducing sleep to 1.5s
2026/08/31 04:40:19 DEBUG : pacer: Reducing sleep to 1.125s
2026/08/31 04:40:20 DEBUG : pacer: Reducing sleep to 843.75ms
--- PASS: TestDirMkdir (37.01s)
=== RUN   TestDirMkdirSub
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:40:20 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:40:20 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:40:21 DEBUG : pacer: Reducing sleep to 632.8125ms
2026/08/31 04:40:23 DEBUG : pacer: Reducing sleep to 474.609375ms
2026/08/31 04:40:23 DEBUG : pacer: Reducing sleep to 355.957031ms
2026/08/31 04:40:23 DEBUG : pacer: Reducing sleep to 266.967773ms
2026/08/31 04:40:25 DEBUG : pacer: Reducing sleep to 200.225829ms
2026/08/31 04:40:25 DEBUG : pacer: Reducing sleep to 200ms
2026/08/31 04:40:27 DEBUG : dir: Added virtual directory entry vAddDir: "sub"
2026/08/31 04:40:29 DEBUG : dir/sub: Added virtual directory entry vAddDir: "subsub"
2026/08/31 04:40:30 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:40:30 DEBUG : dir/sub/subsub: Looking for writers
2026/08/31 04:40:30 DEBUG : dir/sub: Looking for writers
2026/08/31 04:40:30 DEBUG : subsub: reading active writers
2026/08/31 04:40:30 DEBUG : dir: Looking for writers
2026/08/31 04:40:30 DEBUG : file1: reading active writers
2026/08/31 04:40:30 DEBUG : sub: reading active writers
2026/08/31 04:40:30 DEBUG : Looking for writers
2026/08/31 04:40:30 DEBUG : dir: reading active writers
2026/08/31 04:40:30 DEBUG : >WaitForWriters: 
--- PASS: TestDirMkdirSub (17.64s)
=== RUN   TestDirRemove
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:40:37 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:40:37 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:40:42 ERROR : dir/: Dir.Remove not empty
2026/08/31 04:40:42 DEBUG : dir/file1: Remove: 
2026/08/31 04:40:43 DEBUG : dir: Added virtual directory entry vDel: "file1"
2026/08/31 04:40:43 DEBUG : dir/file1: >Remove: err=<nil>
2026/08/31 04:40:44 DEBUG : Added virtual directory entry vDel: "dir"
2026/08/31 04:40:45 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:40:45 DEBUG : Looking for writers
2026/08/31 04:40:45 DEBUG : >WaitForWriters: 
--- PASS: TestDirRemove (7.80s)
=== RUN   TestFileOpenWrite
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:40:45 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:40:45 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:40:49 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2026/08/31 04:40:49 DEBUG : Linkbox root 'rclone-test-koposul0noru': File to upload is small (25 bytes), uploading instead of streaming
2026/08/31 04:40:50 DEBUG : dir/file1: Update: removing old file
2026/08/31 04:40:53 DEBUG : dir/file1: size = 25 OK
2026/08/31 04:40:53 DEBUG : dir/file1: Size of src and dst objects identical
2026/08/31 04:40:53 DEBUG : dir: Added virtual directory entry vAddFile: "file1"
2026/08/31 04:40:53 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:40:53 DEBUG : dir: Looking for writers
2026/08/31 04:40:53 DEBUG : file1: reading active writers
2026/08/31 04:40:53 DEBUG : Looking for writers
2026/08/31 04:40:53 DEBUG : dir: reading active writers
2026/08/31 04:40:53 DEBUG : >WaitForWriters: 
--- PASS: TestFileOpenWrite (11.18s)
=== RUN   TestFileRename
=== RUN   TestFileRename/full,forceCache=false
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:40:56 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:40:56 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: root is "/home/rclone/.cache/rclone"
2026/08/31 04:40:56 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:40:56 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:40:56 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:40:56 DEBUG : Config file has changed externally - reloading
2026/08/31 04:40:56 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/08/31 04:40:56 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:40:56 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:40:56 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/08/31 04:40:56 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:40:56 INFO  : Linkbox root 'rclone-test-koposul0noru': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2026/08/31 04:40:56 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:56 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2026/08/31 04:40:56 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:56 DEBUG : pacer: Rate limited, increasing sleep to 800ms
2026/08/31 04:40:57 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:57 DEBUG : pacer: Rate limited, increasing sleep to 1.6s
2026/08/31 04:40:58 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:40:58 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/08/31 04:40:59 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:01 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:03 DEBUG : pacer: low level retry 7/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:05 DEBUG : pacer: low level retry 8/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:07 DEBUG : pacer: low level retry 9/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:09 DEBUG : pacer: low level retry 10/10 (error invalid character '<' looking for beginning of value)
    run.go:299: Retry Put of "dir/file1" to Linkbox root 'rclone-test-koposul0noru': 1/10 (getting files failed: invalid character '<' looking for beginning of value)
2026/08/31 04:41:11 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:13 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:15 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:17 DEBUG : pacer: Reducing sleep to 1.5s
2026/08/31 04:41:21 DEBUG : pacer: Reducing sleep to 1.125s
2026/08/31 04:41:21 DEBUG : pacer: Reducing sleep to 843.75ms
2026/08/31 04:41:22 DEBUG : pacer: Reducing sleep to 632.8125ms
2026/08/31 04:41:24 DEBUG : pacer: Reducing sleep to 474.609375ms
2026/08/31 04:41:24 DEBUG : pacer: Reducing sleep to 355.957031ms
2026/08/31 04:41:25 DEBUG : pacer: Reducing sleep to 266.967773ms
2026/08/31 04:41:25 DEBUG : pacer: Reducing sleep to 200.225829ms
2026/08/31 04:41:25 DEBUG : pacer: Reducing sleep to 200ms
    file_test.go:305: skip as can't rename files
2026/08/31 04:41:26 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:41:26 DEBUG : dir: Looking for writers
2026/08/31 04:41:26 DEBUG : file1: reading active writers
2026/08/31 04:41:26 DEBUG : Looking for writers
2026/08/31 04:41:26 DEBUG : dir: reading active writers
2026/08/31 04:41:26 DEBUG : >WaitForWriters: 
2026/08/31 04:41:26 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: cleaner exiting
--- PASS: TestFileRename (32.88s)
    --- SKIP: TestFileRename/full,forceCache=false (32.88s)
=== RUN   TestRWFileHandleMethodsWrite
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:41:29 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:41:29 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: root is "/home/rclone/.cache/rclone"
2026/08/31 04:41:29 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:29 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:29 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:29 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/08/31 04:41:29 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:29 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:29 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/08/31 04:41:29 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:29 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/08/31 04:41:29 INFO  : Linkbox root 'rclone-test-koposul0noru': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2026/08/31 04:41:29 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/08/31 04:41:29 DEBUG : file1: newRWFileHandle: 
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): openPending: 
2026/08/31 04:41:29 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct)
2026/08/31 04:41:29 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): >openPending: err=<nil>
2026/08/31 04:41:29 DEBUG : file1: >newRWFileHandle: err=<nil>
2026/08/31 04:41:29 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:41:29 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2026/08/31 04:41:29 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): _writeAt: size=5, off=0
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): >_writeAt: n=5, err=<nil>
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): _writeAt: size=7, off=5
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): >_writeAt: n=7, err=<nil>
2026/08/31 04:41:29 DEBUG : file1: vfs cache: truncate to size=11
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): close: 
2026/08/31 04:41:29 DEBUG : file1: vfs cache: setting modification time to 2026-08-31 04:41:29.801110241 +0000 UTC m=+233.766716003
2026/08/31 04:41:29 INFO  : file1: vfs cache: queuing for upload in 100ms
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): >close: err=<nil>
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): close: 
2026/08/31 04:41:29 DEBUG : file1(0x258a5bd8ae00): >close: err=file already closed
2026/08/31 04:41:29 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:41:29 DEBUG : Looking for writers
2026/08/31 04:41:29 DEBUG : file1: reading active writers
2026/08/31 04:41:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2026/08/31 04:41:29 DEBUG : Looking for writers
2026/08/31 04:41:29 DEBUG : file1: reading active writers
2026/08/31 04:41:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2026/08/31 04:41:29 DEBUG : Looking for writers
2026/08/31 04:41:29 DEBUG : file1: reading active writers
2026/08/31 04:41:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2026/08/31 04:41:29 DEBUG : Looking for writers
2026/08/31 04:41:29 DEBUG : file1: reading active writers
2026/08/31 04:41:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2026/08/31 04:41:29 DEBUG : file1: vfs cache: starting upload
2026/08/31 04:41:29 DEBUG : Looking for writers
2026/08/31 04:41:29 DEBUG : file1: reading active writers
2026/08/31 04:41:29 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2026/08/31 04:41:30 DEBUG : Looking for writers
2026/08/31 04:41:30 DEBUG : file1: reading active writers
2026/08/31 04:41:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2026/08/31 04:41:30 DEBUG : Looking for writers
2026/08/31 04:41:30 DEBUG : file1: reading active writers
2026/08/31 04:41:30 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2026/08/31 04:41:31 DEBUG : Looking for writers
2026/08/31 04:41:31 DEBUG : file1: reading active writers
2026/08/31 04:41:31 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2026/08/31 04:41:31 DEBUG : file1: size = 11 OK
2026/08/31 04:41:31 INFO  : file1: Copied (new)
2026/08/31 04:41:31 DEBUG : file1: vfs cache: fingerprint now "11"
2026/08/31 04:41:31 DEBUG : file1: vfs cache: writeback object to VFS layer
2026/08/31 04:41:31 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:41:31 INFO  : file1: vfs cache: upload succeeded try #1
2026/08/31 04:41:32 DEBUG : Looking for writers
2026/08/31 04:41:32 DEBUG : file1: reading active writers
2026/08/31 04:41:32 DEBUG : >WaitForWriters: 
2026/08/31 04:41:32 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:41:32 DEBUG : Looking for writers
2026/08/31 04:41:32 DEBUG : file1: reading active writers
2026/08/31 04:41:32 DEBUG : >WaitForWriters: 
2026/08/31 04:41:32 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: cleaner exiting
--- PASS: TestRWFileHandleMethodsWrite (4.41s)
=== RUN   TestRWFileHandleWriteAt
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:41:34 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:41:34 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: root is "/home/rclone/.cache/rclone"
2026/08/31 04:41:34 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:34 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:34 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:34 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/08/31 04:41:34 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:34 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:34 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/08/31 04:41:34 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-koposul0noru"
2026/08/31 04:41:34 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/08/31 04:41:34 INFO  : Linkbox root 'rclone-test-koposul0noru': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2026/08/31 04:41:34 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/08/31 04:41:34 DEBUG : file1: newRWFileHandle: 
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): openPending: 
2026/08/31 04:41:34 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct)
2026/08/31 04:41:34 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): >openPending: err=<nil>
2026/08/31 04:41:34 DEBUG : file1: >newRWFileHandle: err=<nil>
2026/08/31 04:41:34 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:41:34 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2026/08/31 04:41:34 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): _writeAt: size=7, off=0
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): >_writeAt: n=7, err=<nil>
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): _writeAt: size=6, off=5
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): >_writeAt: n=6, err=<nil>
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): close: 
2026/08/31 04:41:34 DEBUG : file1: vfs cache: setting modification time to 2026-08-31 04:41:34.208787811 +0000 UTC m=+238.174393573
2026/08/31 04:41:34 INFO  : file1: vfs cache: queuing for upload in 100ms
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): >close: err=<nil>
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): _writeAt: size=5, off=0
2026/08/31 04:41:34 DEBUG : file1(0x258a5bd8bb00): >_writeAt: n=0, err=file already closed
2026/08/31 04:41:34 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:41:34 DEBUG : Looking for writers
2026/08/31 04:41:34 DEBUG : file1: reading active writers
2026/08/31 04:41:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2026/08/31 04:41:34 DEBUG : Looking for writers
2026/08/31 04:41:34 DEBUG : file1: reading active writers
2026/08/31 04:41:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2026/08/31 04:41:34 DEBUG : Looking for writers
2026/08/31 04:41:34 DEBUG : file1: reading active writers
2026/08/31 04:41:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2026/08/31 04:41:34 DEBUG : Looking for writers
2026/08/31 04:41:34 DEBUG : file1: reading active writers
2026/08/31 04:41:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2026/08/31 04:41:34 DEBUG : file1: vfs cache: starting upload
2026/08/31 04:41:34 DEBUG : Looking for writers
2026/08/31 04:41:34 DEBUG : file1: reading active writers
2026/08/31 04:41:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2026/08/31 04:41:34 DEBUG : Looking for writers
2026/08/31 04:41:34 DEBUG : file1: reading active writers
2026/08/31 04:41:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2026/08/31 04:41:34 DEBUG : Looking for writers
2026/08/31 04:41:34 DEBUG : file1: reading active writers
2026/08/31 04:41:34 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2026/08/31 04:41:35 DEBUG : Looking for writers
2026/08/31 04:41:35 DEBUG : file1: reading active writers
2026/08/31 04:41:35 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2026/08/31 04:41:36 DEBUG : file1: size = 11 OK
2026/08/31 04:41:36 INFO  : file1: Copied (new)
2026/08/31 04:41:36 DEBUG : file1: vfs cache: fingerprint now "11"
2026/08/31 04:41:36 DEBUG : file1: vfs cache: writeback object to VFS layer
2026/08/31 04:41:36 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:41:36 INFO  : file1: vfs cache: upload succeeded try #1
2026/08/31 04:41:36 DEBUG : Looking for writers
2026/08/31 04:41:36 DEBUG : file1: reading active writers
2026/08/31 04:41:36 DEBUG : >WaitForWriters: 
2026/08/31 04:41:36 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:41:36 DEBUG : Looking for writers
2026/08/31 04:41:36 DEBUG : file1: reading active writers
2026/08/31 04:41:36 DEBUG : >WaitForWriters: 
2026/08/31 04:41:36 DEBUG : Linkbox root 'rclone-test-koposul0noru': vfs cache: cleaner exiting
--- PASS: TestRWFileHandleWriteAt (4.40s)
=== RUN   TestVFSStat
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:41:38 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:41:38 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:41:44 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:41:44 DEBUG : dir: Looking for writers
2026/08/31 04:41:44 DEBUG : file2: reading active writers
2026/08/31 04:41:44 DEBUG : Looking for writers
2026/08/31 04:41:44 DEBUG : dir: reading active writers
2026/08/31 04:41:44 DEBUG : file1: reading active writers
2026/08/31 04:41:44 DEBUG : >WaitForWriters: 
--- PASS: TestVFSStat (11.22s)
=== RUN   TestVFSMkdir
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:41:49 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:41:49 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:41:50 DEBUG : Added virtual directory entry vAddDir: "/"
2026/08/31 04:41:51 DEBUG : Added virtual directory entry vAddDir: "a"
2026/08/31 04:41:52 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:52 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2026/08/31 04:41:52 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:52 DEBUG : pacer: Rate limited, increasing sleep to 800ms
2026/08/31 04:41:52 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:52 DEBUG : pacer: Rate limited, increasing sleep to 1.6s
2026/08/31 04:41:53 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:53 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/08/31 04:41:55 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:57 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:41:59 DEBUG : pacer: low level retry 7/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:01 DEBUG : pacer: low level retry 8/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:03 DEBUG : pacer: low level retry 9/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:05 DEBUG : pacer: low level retry 10/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:05 ERROR : a: error listing: getting files failed: invalid character '<' looking for beginning of value
    fstest.go:283: Error listing: getting files failed: invalid character '<' looking for beginning of value
2026/08/31 04:42:05 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:42:05 DEBUG : Looking for writers
2026/08/31 04:42:05 DEBUG : a: Looking for writers
2026/08/31 04:42:05 DEBUG : Looking for writers
2026/08/31 04:42:05 DEBUG : /: reading active writers
2026/08/31 04:42:05 DEBUG : a: reading active writers
2026/08/31 04:42:05 DEBUG : >WaitForWriters: 
2026/08/31 04:42:07 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:09 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:11 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:13 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:15 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:17 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:42:19 DEBUG : pacer: Reducing sleep to 1.5s
2026/08/31 04:42:21 DEBUG : pacer: Reducing sleep to 1.125s
2026/08/31 04:42:22 DEBUG : pacer: Reducing sleep to 843.75ms
2026/08/31 04:42:24 DEBUG : pacer: Reducing sleep to 632.8125ms
2026/08/31 04:42:25 DEBUG : pacer: Reducing sleep to 474.609375ms
--- FAIL: TestVFSMkdir (35.56s)
=== RUN   TestWriteFileHandleMethods
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:42:25 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:42:25 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:42:25 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/08/31 04:42:25 DEBUG : pacer: Reducing sleep to 355.957031ms
2026/08/31 04:42:25 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/08/31 04:42:25 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:25 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/08/31 04:42:25 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/08/31 04:42:25 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:25 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal
2026/08/31 04:42:25 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal
2026/08/31 04:42:25 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes
2026/08/31 04:42:25 DEBUG : Linkbox root 'rclone-test-koposul0noru': File to upload is small (5 bytes), uploading instead of streaming
2026/08/31 04:42:26 DEBUG : pacer: Reducing sleep to 266.967773ms
2026/08/31 04:42:26 DEBUG : pacer: Reducing sleep to 200.225829ms
2026/08/31 04:42:28 DEBUG : pacer: Reducing sleep to 200ms
2026/08/31 04:42:28 DEBUG : file1: size = 5 OK
2026/08/31 04:42:28 DEBUG : file1: Size of src and dst objects identical
2026/08/31 04:42:28 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:28 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/08/31 04:42:28 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/08/31 04:42:28 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:28 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/08/31 04:42:28 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/08/31 04:42:28 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/08/31 04:42:28 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/08/31 04:42:28 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:28 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/08/31 04:42:28 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/08/31 04:42:28 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes
2026/08/31 04:42:28 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2026/08/31 04:42:28 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2026/08/31 04:42:28 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:28 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/08/31 04:42:28 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/08/31 04:42:28 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:28 DEBUG : Linkbox root 'rclone-test-koposul0noru': File to upload is small (0 bytes), uploading instead of streaming
2026/08/31 04:42:28 ERROR : file1: WriteFileHandle.New Rcat failed: can't upload empty files to this remote
2026/08/31 04:42:28 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2026/08/31 04:42:28 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2026/08/31 04:42:28 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:28 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/08/31 04:42:28 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/08/31 04:42:28 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:28 DEBUG : Linkbox root 'rclone-test-koposul0noru': File to upload is small (7 bytes), uploading instead of streaming
2026/08/31 04:42:28 DEBUG : file1: Update: removing old file
2026/08/31 04:42:31 DEBUG : file1: size = 7 OK
2026/08/31 04:42:31 DEBUG : file1: Size of src and dst objects identical
2026/08/31 04:42:31 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:31 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:42:31 DEBUG : Looking for writers
2026/08/31 04:42:31 DEBUG : file1: reading active writers
2026/08/31 04:42:31 DEBUG : >WaitForWriters: 
--- PASS: TestWriteFileHandleMethods (8.31s)
=== RUN   TestWriteFileHandleRelease
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:42:33 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:42:33 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:42:33 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/08/31 04:42:33 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/08/31 04:42:33 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:33 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/08/31 04:42:33 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/08/31 04:42:33 DEBUG : file1: WriteFileHandle.Release closing
2026/08/31 04:42:33 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:33 DEBUG : Linkbox root 'rclone-test-koposul0noru': File to upload is small (0 bytes), uploading instead of streaming
2026/08/31 04:42:33 ERROR : file1: WriteFileHandle.New Rcat failed: can't upload empty files to this remote
2026/08/31 04:42:33 DEBUG : file1: Remove: 
2026/08/31 04:42:33 DEBUG : Added virtual directory entry vDel: "file1"
2026/08/31 04:42:33 DEBUG : file1: >Remove: err=<nil>
2026/08/31 04:42:33 ERROR : file1: WriteFileHandle.Release error: can't upload empty files to this remote
    write_test.go:318: skipping test: can't upload empty files to this remote
2026/08/31 04:42:33 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:42:33 DEBUG : Looking for writers
2026/08/31 04:42:33 DEBUG : >WaitForWriters: 
--- PASS: TestWriteFileHandleRelease (0.61s)
=== RUN   TestWriteFileModTimeWithOpenWriters
    run.go:198: Remote "Linkbox root 'rclone-test-koposul0noru'", Local "Local file system at /tmp/rclone1982117180", Modify Window "876000h0m0s"
2026/08/31 04:42:34 INFO  : Linkbox root 'rclone-test-koposul0noru': poll-interval is not supported by this remote
2026/08/31 04:42:34 NOTICE: Linkbox root 'rclone-test-koposul0noru': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/08/31 04:42:34 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/08/31 04:42:34 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/08/31 04:42:34 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/08/31 04:42:34 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/08/31 04:42:34 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/08/31 04:42:37 DEBUG : Can set mod time: false
    write_test.go:363: can't set mod time
2026/08/31 04:42:37 DEBUG : WaitForWriters: timeout=30s
2026/08/31 04:42:37 DEBUG : Looking for writers
2026/08/31 04:42:37 DEBUG : file1: reading active writers
2026/08/31 04:42:37 DEBUG : file1: active writers 1
2026/08/31 04:42:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms
2026/08/31 04:42:37 DEBUG : Looking for writers
2026/08/31 04:42:37 DEBUG : file1: reading active writers
2026/08/31 04:42:37 DEBUG : file1: active writers 1
2026/08/31 04:42:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms
2026/08/31 04:42:37 DEBUG : Looking for writers
2026/08/31 04:42:37 DEBUG : file1: reading active writers
2026/08/31 04:42:37 DEBUG : file1: active writers 1
2026/08/31 04:42:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms
2026/08/31 04:42:38 DEBUG : Looking for writers
2026/08/31 04:42:38 DEBUG : file1: reading active writers
2026/08/31 04:42:38 DEBUG : file1: active writers 1
2026/08/31 04:42:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms
2026/08/31 04:42:38 DEBUG : Looking for writers
2026/08/31 04:42:38 DEBUG : file1: reading active writers
2026/08/31 04:42:38 DEBUG : file1: active writers 1
2026/08/31 04:42:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms
2026/08/31 04:42:38 DEBUG : Looking for writers
2026/08/31 04:42:38 DEBUG : file1: reading active writers
2026/08/31 04:42:38 DEBUG : file1: active writers 1
2026/08/31 04:42:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms
2026/08/31 04:42:38 DEBUG : Looking for writers
2026/08/31 04:42:38 DEBUG : file1: reading active writers
2026/08/31 04:42:38 DEBUG : file1: active writers 1
2026/08/31 04:42:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms
2026/08/31 04:42:39 DEBUG : Looking for writers
2026/08/31 04:42:39 DEBUG : file1: reading active writers
2026/08/31 04:42:39 DEBUG : file1: active writers 1
2026/08/31 04:42:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:40 DEBUG : Looking for writers
2026/08/31 04:42:40 DEBUG : file1: reading active writers
2026/08/31 04:42:40 DEBUG : file1: active writers 1
2026/08/31 04:42:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:41 DEBUG : Looking for writers
2026/08/31 04:42:41 DEBUG : file1: reading active writers
2026/08/31 04:42:41 DEBUG : file1: active writers 1
2026/08/31 04:42:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:42 DEBUG : Looking for writers
2026/08/31 04:42:42 DEBUG : file1: reading active writers
2026/08/31 04:42:42 DEBUG : file1: active writers 1
2026/08/31 04:42:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:43 DEBUG : Looking for writers
2026/08/31 04:42:43 DEBUG : file1: reading active writers
2026/08/31 04:42:43 DEBUG : file1: active writers 1
2026/08/31 04:42:43 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:44 DEBUG : Looking for writers
2026/08/31 04:42:44 DEBUG : file1: reading active writers
2026/08/31 04:42:44 DEBUG : file1: active writers 1
2026/08/31 04:42:44 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:45 DEBUG : Looking for writers
2026/08/31 04:42:45 DEBUG : file1: reading active writers
2026/08/31 04:42:45 DEBUG : file1: active writers 1
2026/08/31 04:42:45 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:46 DEBUG : Looking for writers
2026/08/31 04:42:46 DEBUG : file1: reading active writers
2026/08/31 04:42:46 DEBUG : file1: active writers 1
2026/08/31 04:42:46 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:47 DEBUG : Looking for writers
2026/08/31 04:42:47 DEBUG : file1: reading active writers
2026/08/31 04:42:47 DEBUG : file1: active writers 1
2026/08/31 04:42:47 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:48 DEBUG : Looking for writers
2026/08/31 04:42:48 DEBUG : file1: reading active writers
2026/08/31 04:42:48 DEBUG : file1: active writers 1
2026/08/31 04:42:48 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:49 DEBUG : Looking for writers
2026/08/31 04:42:49 DEBUG : file1: reading active writers
2026/08/31 04:42:49 DEBUG : file1: active writers 1
2026/08/31 04:42:49 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:50 DEBUG : Looking for writers
2026/08/31 04:42:50 DEBUG : file1: reading active writers
2026/08/31 04:42:50 DEBUG : file1: active writers 1
2026/08/31 04:42:50 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:51 DEBUG : Looking for writers
2026/08/31 04:42:51 DEBUG : file1: reading active writers
2026/08/31 04:42:51 DEBUG : file1: active writers 1
2026/08/31 04:42:51 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:52 DEBUG : Looking for writers
2026/08/31 04:42:52 DEBUG : file1: reading active writers
2026/08/31 04:42:52 DEBUG : file1: active writers 1
2026/08/31 04:42:52 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:53 DEBUG : Looking for writers
2026/08/31 04:42:53 DEBUG : file1: reading active writers
2026/08/31 04:42:53 DEBUG : file1: active writers 1
2026/08/31 04:42:53 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:54 DEBUG : Looking for writers
2026/08/31 04:42:54 DEBUG : file1: reading active writers
2026/08/31 04:42:54 DEBUG : file1: active writers 1
2026/08/31 04:42:54 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:55 DEBUG : Looking for writers
2026/08/31 04:42:55 DEBUG : file1: reading active writers
2026/08/31 04:42:55 DEBUG : file1: active writers 1
2026/08/31 04:42:55 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:56 DEBUG : Looking for writers
2026/08/31 04:42:56 DEBUG : file1: reading active writers
2026/08/31 04:42:56 DEBUG : file1: active writers 1
2026/08/31 04:42:56 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:57 DEBUG : Looking for writers
2026/08/31 04:42:57 DEBUG : file1: reading active writers
2026/08/31 04:42:57 DEBUG : file1: active writers 1
2026/08/31 04:42:57 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:58 DEBUG : Looking for writers
2026/08/31 04:42:58 DEBUG : file1: reading active writers
2026/08/31 04:42:58 DEBUG : file1: active writers 1
2026/08/31 04:42:58 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:42:59 DEBUG : Looking for writers
2026/08/31 04:42:59 DEBUG : file1: reading active writers
2026/08/31 04:42:59 DEBUG : file1: active writers 1
2026/08/31 04:42:59 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:00 DEBUG : Looking for writers
2026/08/31 04:43:00 DEBUG : file1: reading active writers
2026/08/31 04:43:00 DEBUG : file1: active writers 1
2026/08/31 04:43:00 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:01 DEBUG : Looking for writers
2026/08/31 04:43:01 DEBUG : file1: reading active writers
2026/08/31 04:43:01 DEBUG : file1: active writers 1
2026/08/31 04:43:01 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:02 DEBUG : Looking for writers
2026/08/31 04:43:02 DEBUG : file1: reading active writers
2026/08/31 04:43:02 DEBUG : file1: active writers 1
2026/08/31 04:43:02 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:03 DEBUG : Looking for writers
2026/08/31 04:43:03 DEBUG : file1: reading active writers
2026/08/31 04:43:03 DEBUG : file1: active writers 1
2026/08/31 04:43:03 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:04 DEBUG : Looking for writers
2026/08/31 04:43:04 DEBUG : file1: reading active writers
2026/08/31 04:43:04 DEBUG : file1: active writers 1
2026/08/31 04:43:04 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:05 DEBUG : Looking for writers
2026/08/31 04:43:05 DEBUG : file1: reading active writers
2026/08/31 04:43:05 DEBUG : file1: active writers 1
2026/08/31 04:43:05 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:06 DEBUG : Looking for writers
2026/08/31 04:43:06 DEBUG : file1: reading active writers
2026/08/31 04:43:06 DEBUG : file1: active writers 1
2026/08/31 04:43:06 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:07 DEBUG : Looking for writers
2026/08/31 04:43:07 DEBUG : file1: reading active writers
2026/08/31 04:43:07 DEBUG : file1: active writers 1
2026/08/31 04:43:07 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/08/31 04:43:07 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s
Cache: <nil>
2026/08/31 04:43:07 DEBUG : >WaitForWriters: 
2026/08/31 04:43:07 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:43:07 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2026/08/31 04:43:08 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:43:08 DEBUG : pacer: Rate limited, increasing sleep to 800ms
2026/08/31 04:43:08 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:43:08 DEBUG : pacer: Rate limited, increasing sleep to 1.6s
2026/08/31 04:43:09 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:43:09 DEBUG : pacer: Rate limited, increasing sleep to 2s
2026/08/31 04:43:10 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:43:12 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:43:14 DEBUG : pacer: low level retry 7/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:43:16 DEBUG : pacer: low level retry 8/10 (error invalid character '<' looking for beginning of value)
2026/08/31 04:43:19 DEBUG : pacer: Reducing sleep to 1.5s
2026/08/31 04:43:21 DEBUG : pacer: Reducing sleep to 1.125s
--- SKIP: TestWriteFileModTimeWithOpenWriters (47.05s)
FAIL
2026/08/31 04:43:21 DEBUG : Linkbox root 'rclone-test-koposul0noru': Purge remote
2026/08/31 04:43:23 DEBUG : pacer: Reducing sleep to 843.75ms
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestDirCreate|TestDirMkdir|TestDirMkdirSub|TestDirRemove|TestDirWalk|TestFileOpenWrite|TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestVFSMkdir|TestVFSStat|TestWriteFileHandleMethods|TestWriteFileHandleRelease|TestWriteFileModTimeWithOpenWriters)$|^TestDirReadDirAll$/^Virtual$|^TestFileRename$/^full,forceCache=false$'" - Finished ERROR in 5m47.74637015s (try 2/5): exit status 1: Failed [TestDirReadDirAll/Virtual TestVFSMkdir]