"./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestDirMetadataExtension|TestDirMkdir|TestReadFileHandleMethods)$'" - Starting (try 2/5) 2026/09/06 03:25:43 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-qubojid3fome" 2026/09/06 03:25:43 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/09/06 03:25:43 DEBUG : Linkbox root 'rclone-test-qubojid3fome': Using cached web token 2026/09/06 03:25:44 DEBUG : Creating backend with remote "/tmp/rclone1484184795" === RUN TestDirMkdir run.go:198: Remote "Linkbox root 'rclone-test-qubojid3fome'", Local "Local file system at /tmp/rclone1484184795", Modify Window "876000h0m0s" 2026/09/06 03:25:44 INFO : Linkbox root 'rclone-test-qubojid3fome': poll-interval is not supported by this remote 2026/09/06 03:25:44 NOTICE: Linkbox root 'rclone-test-qubojid3fome': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2026/09/06 03:25:52 DEBUG : dir: Added virtual directory entry vAddDir: "sub" 2026/09/06 03:25:53 DEBUG : WaitForWriters: timeout=30s 2026/09/06 03:25:53 DEBUG : dir/sub: Looking for writers 2026/09/06 03:25:53 DEBUG : dir: Looking for writers 2026/09/06 03:25:53 DEBUG : file1: reading active writers 2026/09/06 03:25:53 DEBUG : sub: reading active writers 2026/09/06 03:25:53 DEBUG : Looking for writers 2026/09/06 03:25:53 DEBUG : dir: reading active writers 2026/09/06 03:25:53 DEBUG : >WaitForWriters: --- PASS: TestDirMkdir (13.73s) === RUN TestDirMetadataExtension run.go:198: Remote "Linkbox root 'rclone-test-qubojid3fome'", Local "Local file system at /tmp/rclone1484184795", Modify Window "876000h0m0s" 2026/09/06 03:25:58 INFO : Linkbox root 'rclone-test-qubojid3fome': poll-interval is not supported by this remote 2026/09/06 03:25:58 NOTICE: Linkbox root 'rclone-test-qubojid3fome': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2026/09/06 03:25:59 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:25:59 DEBUG : pacer: Rate limited, increasing sleep to 400ms 2026/09/06 03:26:00 DEBUG : pacer: low level retry 2/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:00 DEBUG : pacer: Rate limited, increasing sleep to 800ms 2026/09/06 03:26:00 DEBUG : pacer: low level retry 3/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:00 DEBUG : pacer: Rate limited, increasing sleep to 1.6s 2026/09/06 03:26:01 DEBUG : pacer: low level retry 4/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:01 DEBUG : pacer: Rate limited, increasing sleep to 2s 2026/09/06 03:26:02 DEBUG : pacer: low level retry 5/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:04 DEBUG : pacer: low level retry 6/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:06 DEBUG : pacer: low level retry 7/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:08 DEBUG : pacer: low level retry 8/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:10 DEBUG : pacer: low level retry 9/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:12 DEBUG : pacer: low level retry 10/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:14 DEBUG : pacer: low level retry 1/10 (error invalid character '<' looking for beginning of value) 2026/09/06 03:26:17 DEBUG : pacer: Reducing sleep to 1.5s 2026/09/06 03:26:20 DEBUG : pacer: Reducing sleep to 1.125s 2026/09/06 03:26:20 DEBUG : pacer: Reducing sleep to 843.75ms 2026/09/06 03:26:21 DEBUG : pacer: Reducing sleep to 632.8125ms 2026/09/06 03:26:22 DEBUG : pacer: Reducing sleep to 474.609375ms 2026/09/06 03:26:23 DEBUG : pacer: Reducing sleep to 355.957031ms 2026/09/06 03:26:23 DEBUG : pacer: Reducing sleep to 266.967773ms 2026/09/06 03:26:23 DEBUG : dir: Added virtual directory entry vAddFile: "file1.metadata" 2026/09/06 03:26:23 DEBUG : dir/file1.metadata: Set virtual modtime to 2026-09-06 03:26:19 +0000 UTC 2026/09/06 03:26:23 DEBUG : dir/file1.metadata: OpenFile: flags=O_RDONLY, perm=---------- 2026/09/06 03:26:23 DEBUG : dir/file1.metadata: Open: flags=O_RDONLY 2026/09/06 03:26:23 DEBUG : dir/file1.metadata: >Open: fd=dir/file1.metadata (r), err= 2026/09/06 03:26:23 DEBUG : dir/file1.metadata: >OpenFile: fd=dir/file1.metadata (r), err= 2026/09/06 03:26:23 DEBUG : dir/file1.metadata: ChunkedReader.openRange at 0 length 134217728 2026/09/06 03:26:23 DEBUG : dir/file1.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728 2026/09/06 03:26:23 DEBUG : Added virtual directory entry vAddFile: "dir.metadata" 2026/09/06 03:26:23 DEBUG : dir.metadata: Set virtual modtime to 2026-09-06 03:25:58 +0000 UTC 2026/09/06 03:26:23 DEBUG : dir.metadata: OpenFile: flags=O_RDONLY, perm=---------- 2026/09/06 03:26:23 DEBUG : dir.metadata: Open: flags=O_RDONLY 2026/09/06 03:26:23 DEBUG : dir.metadata: >Open: fd=dir.metadata (r), err= 2026/09/06 03:26:23 DEBUG : dir.metadata: >OpenFile: fd=dir.metadata (r), err= 2026/09/06 03:26:23 DEBUG : dir.metadata: ChunkedReader.openRange at 0 length 134217728 2026/09/06 03:26:23 DEBUG : dir.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728 2026/09/06 03:26:23 DEBUG : WaitForWriters: timeout=30s 2026/09/06 03:26:23 DEBUG : dir: Looking for writers 2026/09/06 03:26:23 DEBUG : file1: reading active writers 2026/09/06 03:26:23 DEBUG : file1.metadata: reading active writers 2026/09/06 03:26:23 DEBUG : Looking for writers 2026/09/06 03:26:23 DEBUG : dir: reading active writers 2026/09/06 03:26:23 DEBUG : dir.metadata: reading active writers 2026/09/06 03:26:23 DEBUG : >WaitForWriters: 2026/09/06 03:26:24 DEBUG : pacer: Reducing sleep to 200.225829ms 2026/09/06 03:26:24 DEBUG : pacer: Reducing sleep to 200ms --- PASS: TestDirMetadataExtension (28.96s) === RUN TestReadFileHandleMethods run.go:198: Remote "Linkbox root 'rclone-test-qubojid3fome'", Local "Local file system at /tmp/rclone1484184795", Modify Window "876000h0m0s" 2026/09/06 03:26:27 INFO : Linkbox root 'rclone-test-qubojid3fome': poll-interval is not supported by this remote 2026/09/06 03:26:27 NOTICE: Linkbox root 'rclone-test-qubojid3fome': --vfs-cache-mode writes or full is recommended for this remote as it can't stream 2026/09/06 03:26:31 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx 2026/09/06 03:26:31 DEBUG : dir/file1: Open: flags=O_RDONLY 2026/09/06 03:26:31 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err= 2026/09/06 03:26:31 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err= 2026/09/06 03:26:31 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728 2026/09/06 03:26:31 NOTICE: Time may be set wrong - time from "aht.nuplink3.net" is 2062h46m45.853355334s different from this computer 2026/09/06 03:26:31 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728 2026/09/06 03:26:31 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728 2026/09/06 03:26:31 DEBUG : WaitForWriters: timeout=30s 2026/09/06 03:26:31 DEBUG : dir: Looking for writers 2026/09/06 03:26:31 DEBUG : file1: reading active writers 2026/09/06 03:26:31 DEBUG : Looking for writers 2026/09/06 03:26:31 DEBUG : dir: reading active writers 2026/09/06 03:26:31 DEBUG : >WaitForWriters: --- PASS: TestReadFileHandleMethods (8.05s) PASS 2026/09/06 03:26:35 DEBUG : Linkbox root 'rclone-test-qubojid3fome': Purge remote "./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestDirMetadataExtension|TestDirMkdir|TestReadFileHandleMethods)$'" - Finished OK in 53.110449693s (try 2/5)