"./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleSeek|TestVFSIsMetadataFile|TestVFSMkdir|TestVFSMkdirAll|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleWriteAt)$'" - Starting (try 2/5)
2026/06/27 04:29:49 DEBUG : Creating backend with remote "TestLinkbox:rclone-test-sovodiz6bogi"
2026/06/27 04:29:49 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/06/27 04:29:49 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': Using cached web token
2026/06/27 04:29:49 DEBUG : Creating backend with remote "/tmp/rclone632655635"
=== RUN   TestReadFileHandleMethods
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:29:49 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:29:49 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:29:55 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/27 04:29:55 DEBUG : dir/file1: Open: flags=O_RDONLY
2026/06/27 04:29:55 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2026/06/27 04:29:55 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2026/06/27 04:29:55 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2026/06/27 04:29:56 NOTICE: Time may be set wrong - time from "aht.nuplink3.net" is 359h50m10.119881576s different from this computer
2026/06/27 04:29:56 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2026/06/27 04:29:56 DEBUG : dir/file1: ChunkedReader.Read at 1 length 256 chunkOffset 0 chunkSize 134217728
2026/06/27 04:29:56 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:29:56 DEBUG : dir: Looking for writers
2026/06/27 04:29:56 DEBUG : file1: reading active writers
2026/06/27 04:29:56 DEBUG : Looking for writers
2026/06/27 04:29:56 DEBUG : dir: reading active writers
2026/06/27 04:29:56 DEBUG : >WaitForWriters: 
--- PASS: TestReadFileHandleMethods (9.70s)
=== RUN   TestReadFileHandleSeek
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:29:59 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:29:59 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:30:03 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/27 04:30:04 DEBUG : dir/file1: Open: flags=O_RDONLY
2026/06/27 04:30:04 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2026/06/27 04:30:04 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2026/06/27 04:30:04 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms
2026/06/27 04:30:04 DEBUG : dir/file1: aborting in-sequence read wait, off=5
2026/06/27 04:30:04 DEBUG : dir/file1: failed to wait for in-sequence read to 5
2026/06/27 04:30:04 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker)
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2026/06/27 04:30:04 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 3 (fs.RangeSeeker)
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 3 length -1
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 3 chunkSize 134217728
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.openRange at 3 length 134217728
2026/06/27 04:30:04 DEBUG : dir/file1: ReadFileHandle.seek from 4 to 13 (fs.RangeSeeker)
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.RangeSeek from 4 to 13 length -1
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 13 chunkSize 134217728
2026/06/27 04:30:04 DEBUG : dir/file1: ChunkedReader.openRange at 13 length 134217728
2026/06/27 04:30:04 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:30:04 DEBUG : dir: Looking for writers
2026/06/27 04:30:04 DEBUG : file1: reading active writers
2026/06/27 04:30:04 DEBUG : Looking for writers
2026/06/27 04:30:04 DEBUG : dir: reading active writers
2026/06/27 04:30:04 DEBUG : >WaitForWriters: 
--- PASS: TestReadFileHandleSeek (8.63s)
=== RUN   TestReadFileHandleReadAt
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:30:08 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:30:08 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:30:12 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/27 04:30:12 DEBUG : dir/file1: Open: flags=O_RDONLY
2026/06/27 04:30:12 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2026/06/27 04:30:12 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2026/06/27 04:30:12 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2026/06/27 04:30:12 DEBUG : dir/file1: ChunkedReader.Read at 0 length 1 chunkOffset 0 chunkSize 134217728
2026/06/27 04:30:12 DEBUG : dir/file1: waiting for in-sequence read to 5 for 20ms
2026/06/27 04:30:12 DEBUG : dir/file1: aborting in-sequence read wait, off=5
2026/06/27 04:30:12 DEBUG : dir/file1: failed to wait for in-sequence read to 5
2026/06/27 04:30:12 DEBUG : dir/file1: ReadFileHandle.seek from 1 to 5 (fs.RangeSeeker)
2026/06/27 04:30:12 DEBUG : dir/file1: ChunkedReader.RangeSeek from 1 to 5 length -1
2026/06/27 04:30:12 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 5 chunkSize 134217728
2026/06/27 04:30:12 DEBUG : dir/file1: ChunkedReader.openRange at 5 length 134217728
2026/06/27 04:30:13 DEBUG : dir/file1: ReadFileHandle.seek from 6 to 1 (fs.RangeSeeker)
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.RangeSeek from 6 to 1 length -1
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.Read at -1 length 1 chunkOffset 1 chunkSize 134217728
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.openRange at 1 length 134217728
2026/06/27 04:30:13 DEBUG : dir/file1: waiting for in-sequence read to 10 for 20ms
2026/06/27 04:30:13 DEBUG : dir/file1: aborting in-sequence read wait, off=10
2026/06/27 04:30:13 DEBUG : dir/file1: failed to wait for in-sequence read to 10
2026/06/27 04:30:13 DEBUG : dir/file1: ReadFileHandle.seek from 2 to 10 (fs.RangeSeeker)
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.RangeSeek from 2 to 10 length -1
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.Read at -1 length 6 chunkOffset 10 chunkSize 134217728
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728
2026/06/27 04:30:13 DEBUG : dir/file1: ReadFileHandle.seek from 16 to 10 (fs.RangeSeeker)
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.RangeSeek from 16 to 10 length -1
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.Read at -1 length 256 chunkOffset 10 chunkSize 134217728
2026/06/27 04:30:13 DEBUG : dir/file1: ChunkedReader.openRange at 10 length 134217728
2026/06/27 04:30:13 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms
2026/06/27 04:30:13 DEBUG : dir/file1: aborting in-sequence read wait, off=100
2026/06/27 04:30:13 DEBUG : dir/file1: failed to wait for in-sequence read to 100
2026/06/27 04:30:13 DEBUG : dir/file1: ReadFileHandle.Read attempt to read beyond end of file: 100 > 16
2026/06/27 04:30:13 DEBUG : dir/file1: waiting for in-sequence read to 100 for 20ms
2026/06/27 04:30:13 DEBUG : dir/file1: aborting in-sequence read wait, off=100
2026/06/27 04:30:13 DEBUG : dir/file1: failed to wait for in-sequence read to 100
2026/06/27 04:30:13 ERROR : dir/file1: ReadFileHandle.Read error: Bad file descriptor
2026/06/27 04:30:13 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:30:13 DEBUG : dir: Looking for writers
2026/06/27 04:30:13 DEBUG : file1: reading active writers
2026/06/27 04:30:13 DEBUG : Looking for writers
2026/06/27 04:30:13 DEBUG : dir: reading active writers
2026/06/27 04:30:13 DEBUG : >WaitForWriters: 
--- PASS: TestReadFileHandleReadAt (8.95s)
=== RUN   TestRWFileHandleMethodsWrite
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:30:17 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:30:17 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: root is "/home/rclone/.cache/rclone"
2026/06/27 04:30:17 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:17 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:17 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:17 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/06/27 04:30:17 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-sovodiz6bogi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:17 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:17 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/06/27 04:30:17 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-sovodiz6bogi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:17 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/06/27 04:30:17 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2026/06/27 04:30:17 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/06/27 04:30:17 DEBUG : file1: newRWFileHandle: 
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): openPending: 
2026/06/27 04:30:17 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct)
2026/06/27 04:30:17 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): >openPending: err=<nil>
2026/06/27 04:30:17 DEBUG : file1: >newRWFileHandle: err=<nil>
2026/06/27 04:30:17 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:30:17 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2026/06/27 04:30:17 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): _writeAt: size=5, off=0
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): >_writeAt: n=5, err=<nil>
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): _writeAt: size=7, off=5
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): >_writeAt: n=7, err=<nil>
2026/06/27 04:30:17 DEBUG : file1: vfs cache: truncate to size=11
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): close: 
2026/06/27 04:30:17 DEBUG : file1: vfs cache: setting modification time to 2026-06-27 04:30:17.47567599 +0000 UTC m=+28.251865504
2026/06/27 04:30:17 INFO  : file1: vfs cache: queuing for upload in 100ms
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): >close: err=<nil>
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): close: 
2026/06/27 04:30:17 DEBUG : file1(0xdd766972c00): >close: err=file already closed
2026/06/27 04:30:17 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:30:17 DEBUG : Looking for writers
2026/06/27 04:30:17 DEBUG : file1: reading active writers
2026/06/27 04:30:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2026/06/27 04:30:17 DEBUG : Looking for writers
2026/06/27 04:30:17 DEBUG : file1: reading active writers
2026/06/27 04:30:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2026/06/27 04:30:17 DEBUG : Looking for writers
2026/06/27 04:30:17 DEBUG : file1: reading active writers
2026/06/27 04:30:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2026/06/27 04:30:17 DEBUG : Looking for writers
2026/06/27 04:30:17 DEBUG : file1: reading active writers
2026/06/27 04:30:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2026/06/27 04:30:17 DEBUG : file1: vfs cache: starting upload
2026/06/27 04:30:17 DEBUG : Looking for writers
2026/06/27 04:30:17 DEBUG : file1: reading active writers
2026/06/27 04:30:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2026/06/27 04:30:17 DEBUG : Looking for writers
2026/06/27 04:30:17 DEBUG : file1: reading active writers
2026/06/27 04:30:17 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2026/06/27 04:30:18 DEBUG : Looking for writers
2026/06/27 04:30:18 DEBUG : file1: reading active writers
2026/06/27 04:30:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2026/06/27 04:30:18 DEBUG : Looking for writers
2026/06/27 04:30:18 DEBUG : file1: reading active writers
2026/06/27 04:30:18 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2026/06/27 04:30:19 DEBUG : file1: size = 11 OK
2026/06/27 04:30:19 INFO  : file1: Copied (new)
2026/06/27 04:30:19 DEBUG : file1: vfs cache: fingerprint now "11"
2026/06/27 04:30:19 DEBUG : file1: vfs cache: writeback object to VFS layer
2026/06/27 04:30:19 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:30:19 INFO  : file1: vfs cache: upload succeeded try #1
2026/06/27 04:30:19 DEBUG : Looking for writers
2026/06/27 04:30:19 DEBUG : file1: reading active writers
2026/06/27 04:30:19 DEBUG : >WaitForWriters: 
2026/06/27 04:30:19 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:30:19 DEBUG : Looking for writers
2026/06/27 04:30:19 DEBUG : file1: reading active writers
2026/06/27 04:30:19 DEBUG : >WaitForWriters: 
2026/06/27 04:30:19 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: cleaner exiting
--- PASS: TestRWFileHandleMethodsWrite (4.42s)
=== RUN   TestRWFileHandleWriteAt
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:30:21 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:30:21 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: root is "/home/rclone/.cache/rclone"
2026/06/27 04:30:21 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:21 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:21 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:21 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/06/27 04:30:21 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-sovodiz6bogi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:21 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:21 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2026/06/27 04:30:21 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-sovodiz6bogi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestLinkbox/rclone-test-sovodiz6bogi"
2026/06/27 04:30:21 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/06/27 04:30:21 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2026/06/27 04:30:21 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/06/27 04:30:21 DEBUG : file1: newRWFileHandle: 
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): openPending: 
2026/06/27 04:30:21 DEBUG : file1: vfs cache: truncate to size=0 (not needed as size correct)
2026/06/27 04:30:21 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): >openPending: err=<nil>
2026/06/27 04:30:21 DEBUG : file1: >newRWFileHandle: err=<nil>
2026/06/27 04:30:21 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:30:21 DEBUG : file1: >Open: fd=file1 (rw), err=<nil>
2026/06/27 04:30:21 DEBUG : file1: >OpenFile: fd=file1 (rw), err=<nil>
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): _writeAt: size=7, off=0
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): >_writeAt: n=7, err=<nil>
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): _writeAt: size=6, off=5
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): >_writeAt: n=6, err=<nil>
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): close: 
2026/06/27 04:30:21 DEBUG : file1: vfs cache: setting modification time to 2026-06-27 04:30:21.883234452 +0000 UTC m=+32.659423947
2026/06/27 04:30:21 INFO  : file1: vfs cache: queuing for upload in 100ms
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): >close: err=<nil>
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): _writeAt: size=5, off=0
2026/06/27 04:30:21 DEBUG : file1(0xdd7669d78c0): >_writeAt: n=0, err=file already closed
2026/06/27 04:30:21 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:30:21 DEBUG : Looking for writers
2026/06/27 04:30:21 DEBUG : file1: reading active writers
2026/06/27 04:30:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 10ms
2026/06/27 04:30:21 DEBUG : Looking for writers
2026/06/27 04:30:21 DEBUG : file1: reading active writers
2026/06/27 04:30:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 20ms
2026/06/27 04:30:21 DEBUG : Looking for writers
2026/06/27 04:30:21 DEBUG : file1: reading active writers
2026/06/27 04:30:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 40ms
2026/06/27 04:30:21 DEBUG : Looking for writers
2026/06/27 04:30:21 DEBUG : file1: reading active writers
2026/06/27 04:30:21 DEBUG : Still 0 writers active and 1 cache items in use, waiting 80ms
2026/06/27 04:30:21 DEBUG : file1: vfs cache: starting upload
2026/06/27 04:30:22 DEBUG : Looking for writers
2026/06/27 04:30:22 DEBUG : file1: reading active writers
2026/06/27 04:30:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 160ms
2026/06/27 04:30:22 DEBUG : Looking for writers
2026/06/27 04:30:22 DEBUG : file1: reading active writers
2026/06/27 04:30:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 320ms
2026/06/27 04:30:22 DEBUG : Looking for writers
2026/06/27 04:30:22 DEBUG : file1: reading active writers
2026/06/27 04:30:22 DEBUG : Still 0 writers active and 1 cache items in use, waiting 640ms
2026/06/27 04:30:23 DEBUG : Looking for writers
2026/06/27 04:30:23 DEBUG : file1: reading active writers
2026/06/27 04:30:23 DEBUG : Still 0 writers active and 1 cache items in use, waiting 1s
2026/06/27 04:30:23 DEBUG : file1: size = 11 OK
2026/06/27 04:30:23 INFO  : file1: Copied (new)
2026/06/27 04:30:23 DEBUG : file1: vfs cache: fingerprint now "11"
2026/06/27 04:30:23 DEBUG : file1: vfs cache: writeback object to VFS layer
2026/06/27 04:30:23 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:30:23 INFO  : file1: vfs cache: upload succeeded try #1
2026/06/27 04:30:24 DEBUG : Looking for writers
2026/06/27 04:30:24 DEBUG : file1: reading active writers
2026/06/27 04:30:24 DEBUG : >WaitForWriters: 
2026/06/27 04:30:24 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:30:24 DEBUG : Looking for writers
2026/06/27 04:30:24 DEBUG : file1: reading active writers
2026/06/27 04:30:24 DEBUG : >WaitForWriters: 
2026/06/27 04:30:24 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': vfs cache: cleaner exiting
--- PASS: TestRWFileHandleWriteAt (4.39s)
=== RUN   TestVFSMkdir
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:30:26 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:30:26 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:30:26 DEBUG : Added virtual directory entry vAddDir: "/"
2026/06/27 04:30:28 DEBUG : Added virtual directory entry vAddDir: "a"
2026/06/27 04:30:30 DEBUG : Added virtual directory entry vAddDir: "b"
2026/06/27 04:30:32 DEBUG : Added virtual directory entry vAddDir: "c"
2026/06/27 04:30:35 DEBUG : Added virtual directory entry vAddDir: "d"
2026/06/27 04:30:36 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:30:36 DEBUG : d: Looking for writers
2026/06/27 04:30:36 DEBUG : Looking for writers
2026/06/27 04:30:36 DEBUG : a: Looking for writers
2026/06/27 04:30:36 DEBUG : b: Looking for writers
2026/06/27 04:30:36 DEBUG : c: Looking for writers
2026/06/27 04:30:36 DEBUG : Looking for writers
2026/06/27 04:30:36 DEBUG : /: reading active writers
2026/06/27 04:30:36 DEBUG : a: reading active writers
2026/06/27 04:30:36 DEBUG : b: reading active writers
2026/06/27 04:30:36 DEBUG : c: reading active writers
2026/06/27 04:30:36 DEBUG : d: reading active writers
2026/06/27 04:30:36 DEBUG : >WaitForWriters: 
--- PASS: TestVFSMkdir (17.34s)
=== RUN   TestVFSMkdirAll
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:30:43 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:30:43 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:30:45 DEBUG : Added virtual directory entry vAddDir: "a"
2026/06/27 04:30:47 DEBUG : a: Added virtual directory entry vAddDir: "b"
2026/06/27 04:30:48 DEBUG : a/b: Added virtual directory entry vAddDir: "c"
2026/06/27 04:30:50 DEBUG : a/b/c: Added virtual directory entry vAddDir: "d"
2026/06/27 04:30:53 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:30:53 DEBUG : a/b/c/d: Looking for writers
2026/06/27 04:30:53 DEBUG : a/b/c: Looking for writers
2026/06/27 04:30:53 DEBUG : d: reading active writers
2026/06/27 04:30:53 DEBUG : a/b: Looking for writers
2026/06/27 04:30:53 DEBUG : c: reading active writers
2026/06/27 04:30:53 DEBUG : a: Looking for writers
2026/06/27 04:30:53 DEBUG : b: reading active writers
2026/06/27 04:30:53 DEBUG : Looking for writers
2026/06/27 04:30:53 DEBUG : a: reading active writers
2026/06/27 04:30:53 DEBUG : >WaitForWriters: 
--- PASS: TestVFSMkdirAll (17.75s)
=== RUN   TestVFSIsMetadataFile
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:31:01 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:31:01 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:31:01 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:31:01 DEBUG : Looking for writers
2026/06/27 04:31:01 DEBUG : >WaitForWriters: 
--- PASS: TestVFSIsMetadataFile (0.45s)
=== RUN   TestWriteFileHandleMethods
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:31:01 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:31:01 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:31:01 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/06/27 04:31:01 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/06/27 04:31:01 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:01 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/06/27 04:31:01 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/06/27 04:31:01 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:01 ERROR : file1: WriteFileHandle: Read: Can't read and write to file without --vfs-cache-mode >= minimal
2026/06/27 04:31:01 ERROR : file1: WriteFileHandle: ReadAt: Can't read and write to file without --vfs-cache-mode >= minimal
2026/06/27 04:31:01 ERROR : file1: WriteFileHandle: Truncate: Can't change size without --vfs-cache-mode >= writes
2026/06/27 04:31:01 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': File to upload is small (5 bytes), uploading instead of streaming
2026/06/27 04:31:04 DEBUG : file1: size = 5 OK
2026/06/27 04:31:04 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --checksum is in use but the source and destination have no hashes in common; falling back to --size-only
2026/06/27 04:31:04 DEBUG : file1: Size of src and dst objects identical
2026/06/27 04:31:04 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:04 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/06/27 04:31:04 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/06/27 04:31:04 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:04 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/06/27 04:31:04 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/06/27 04:31:04 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/06/27 04:31:04 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/06/27 04:31:04 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:04 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/06/27 04:31:04 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/06/27 04:31:04 ERROR : file1: WriteFileHandle: Can't open for write without O_TRUNC on existing file without --vfs-cache-mode >= writes
2026/06/27 04:31:04 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2026/06/27 04:31:04 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2026/06/27 04:31:04 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:04 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/06/27 04:31:04 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/06/27 04:31:04 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:04 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': File to upload is small (0 bytes), uploading instead of streaming
2026/06/27 04:31:04 ERROR : file1: WriteFileHandle.New Rcat failed: can't upload empty files to this remote
2026/06/27 04:31:04 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE|O_TRUNC, perm=-rwxrwxrwx
2026/06/27 04:31:04 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE|O_TRUNC
2026/06/27 04:31:04 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:04 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/06/27 04:31:04 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/06/27 04:31:04 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:04 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': File to upload is small (7 bytes), uploading instead of streaming
2026/06/27 04:31:04 DEBUG : file1: Update: removing old file
2026/06/27 04:31:07 DEBUG : file1: size = 7 OK
2026/06/27 04:31:07 DEBUG : file1: Size of src and dst objects identical
2026/06/27 04:31:07 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:07 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:31:07 DEBUG : Looking for writers
2026/06/27 04:31:07 DEBUG : file1: reading active writers
2026/06/27 04:31:07 DEBUG : >WaitForWriters: 
--- PASS: TestWriteFileHandleMethods (7.65s)
=== RUN   TestWriteFileHandleWriteAt
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:31:09 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:31:09 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:31:09 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/06/27 04:31:09 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/06/27 04:31:09 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:09 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/06/27 04:31:09 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/06/27 04:31:09 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:09 DEBUG : file1: waiting for in-sequence write to 100 for 1s
2026/06/27 04:31:10 DEBUG : file1: aborting in-sequence write wait, off=100
2026/06/27 04:31:10 DEBUG : file1: failed to wait for in-sequence write to 100
2026/06/27 04:31:10 ERROR : file1: WriteFileHandle.Write: can't seek in file without --vfs-cache-mode >= writes
2026/06/27 04:31:10 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': File to upload is small (11 bytes), uploading instead of streaming
2026/06/27 04:31:12 DEBUG : file1: size = 11 OK
2026/06/27 04:31:12 DEBUG : file1: Size of src and dst objects identical
2026/06/27 04:31:12 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:12 ERROR : file1: WriteFileHandle.Write: error: Bad file descriptor
2026/06/27 04:31:12 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:31:12 DEBUG : Looking for writers
2026/06/27 04:31:12 DEBUG : file1: reading active writers
2026/06/27 04:31:12 DEBUG : >WaitForWriters: 
--- PASS: TestWriteFileHandleWriteAt (5.16s)
=== RUN   TestWriteFileHandleFlush
    run.go:198: Remote "Linkbox root 'rclone-test-sovodiz6bogi'", Local "Local file system at /tmp/rclone632655635", Modify Window "876000h0m0s"
2026/06/27 04:31:14 INFO  : Linkbox root 'rclone-test-sovodiz6bogi': poll-interval is not supported by this remote
2026/06/27 04:31:14 NOTICE: Linkbox root 'rclone-test-sovodiz6bogi': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/06/27 04:31:14 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/06/27 04:31:14 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/06/27 04:31:14 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:14 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/06/27 04:31:14 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/06/27 04:31:14 DEBUG : file1: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2026/06/27 04:31:14 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:14 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': File to upload is small (5 bytes), uploading instead of streaming
2026/06/27 04:31:16 DEBUG : file1: size = 5 OK
2026/06/27 04:31:16 DEBUG : file1: Size of src and dst objects identical
2026/06/27 04:31:16 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/06/27 04:31:16 DEBUG : file1: WriteFileHandle.Flush nothing to do
2026/06/27 04:31:16 DEBUG : WaitForWriters: timeout=30s
2026/06/27 04:31:16 DEBUG : Looking for writers
2026/06/27 04:31:16 DEBUG : file1: reading active writers
2026/06/27 04:31:16 DEBUG : >WaitForWriters: 
--- PASS: TestWriteFileHandleFlush (3.92s)
PASS
2026/06/27 04:31:18 DEBUG : Linkbox root 'rclone-test-sovodiz6bogi': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestLinkbox: -verbose -test.run '^(TestRWFileHandleMethodsWrite|TestRWFileHandleWriteAt|TestReadFileHandleMethods|TestReadFileHandleReadAt|TestReadFileHandleSeek|TestVFSIsMetadataFile|TestVFSMkdir|TestVFSMkdirAll|TestWriteFileHandleFlush|TestWriteFileHandleMethods|TestWriteFileHandleWriteAt)$'" - Finished OK in 1m30.459687871s (try 2/5)