"./vfs.test -test.v -test.timeout 1h0m0s -remote TestSugarSync:Test -verbose -test.run '^TestRWFileHandleOpenTests$/^writes$/^os.O_RDONLY$'" - Starting (try 2/5)
2025/05/02 06:09:26 DEBUG : Creating backend with remote "TestSugarSync:Test/rclone-test-wosiyek4geyu"
2025/05/02 06:09:26 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/05/02 06:09:30 DEBUG : Creating backend with remote "/tmp/rclone1613109049"
=== RUN   TestRWFileHandleOpenTests
=== RUN   TestRWFileHandleOpenTests/writes
    run.go:180: Remote "sugarsync root 'Test/rclone-test-wosiyek4geyu'", Local "Local file system at /tmp/rclone1613109049", Modify Window "876000h0m0s"
2025/05/02 06:09:30 INFO  : sugarsync root 'Test/rclone-test-wosiyek4geyu': poll-interval is not supported by this remote
2025/05/02 06:09:30 DEBUG : sugarsync root 'Test/rclone-test-wosiyek4geyu': vfs cache: root is "/home/rclone/.cache/rclone"
2025/05/02 06:09:30 DEBUG : sugarsync root 'Test/rclone-test-wosiyek4geyu': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestSugarSync/Test/rclone-test-wosiyek4geyu"
2025/05/02 06:09:30 DEBUG : sugarsync root 'Test/rclone-test-wosiyek4geyu': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestSugarSync/Test/rclone-test-wosiyek4geyu"
2025/05/02 06:09:30 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestSugarSync/Test/rclone-test-wosiyek4geyu"
2025/05/02 06:09:30 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/05/02 06:09:30 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestSugarSync/Test/rclone-test-wosiyek4geyu" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestSugarSync/Test/rclone-test-wosiyek4geyu"
2025/05/02 06:09:30 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestSugarSync/Test/rclone-test-wosiyek4geyu"
2025/05/02 06:09:30 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/05/02 06:09:30 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestSugarSync/Test/rclone-test-wosiyek4geyu" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestSugarSync/Test/rclone-test-wosiyek4geyu"
=== RUN   TestRWFileHandleOpenTests/writes/os.O_RDONLY
2025/05/02 06:09:30 INFO  : sugarsync root 'Test/rclone-test-wosiyek4geyu': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/05/02 06:09:31 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=-rw-rw-rw-
2025/05/02 06:09:31 DEBUG : open-test-file: >OpenFile: fd=<nil>, err=file does not exist
2025/05/02 06:09:31 DEBUG : open-test-file: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2025/05/02 06:09:31 DEBUG : open-test-file: Open: flags=O_WRONLY|O_CREATE
2025/05/02 06:09:31 DEBUG : open-test-file: newRWFileHandle: 
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b24f40): openPending: 
2025/05/02 06:09:31 DEBUG : open-test-file: vfs cache: truncate to size=0 (not needed as size correct)
2025/05/02 06:09:31 DEBUG : : Added virtual directory entry vAddFile: "open-test-file"
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b24f40): >openPending: err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: >newRWFileHandle: err=<nil>
2025/05/02 06:09:31 DEBUG : : Added virtual directory entry vAddFile: "open-test-file"
2025/05/02 06:09:31 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b24f40): _writeAt: size=5, off=0
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b24f40): >_writeAt: n=5, err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b24f40): close: 
2025/05/02 06:09:31 DEBUG : open-test-file: vfs cache: setting modification time to 2025-05-02 06:09:31.060187344 +0000 UTC m=+4.289077941
2025/05/02 06:09:31 INFO  : open-test-file: vfs cache: queuing for upload in 100ms
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b24f40): >close: err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=-rw-rw-rw-
2025/05/02 06:09:31 DEBUG : open-test-file: Open: flags=O_RDONLY
2025/05/02 06:09:31 DEBUG : open-test-file: newRWFileHandle: 
2025/05/02 06:09:31 DEBUG : open-test-file: >newRWFileHandle: err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25000): _readAt: size=2, off=0
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25000): openPending: 
2025/05/02 06:09:31 DEBUG : open-test-file: vfs cache: truncate to size=5 (not needed as size correct)
2025/05/02 06:09:31 DEBUG : : Added virtual directory entry vAddFile: "open-test-file"
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25000): >openPending: err=<nil>
2025/05/02 06:09:31 DEBUG : vfs cache: looking for range={Pos:0 Size:2} in [{Pos:0 Size:5}] - present true
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25000): >_readAt: n=2, err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25000): _writeAt: size=3, off=2
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25000): >_writeAt: n=0, err=Bad file descriptor
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25000): close: 
2025/05/02 06:09:31 DEBUG : open-test-file: vfs cache: setting modification time to 2025-05-02 06:09:31.060187344 +0000 UTC m=+4.289077941
2025/05/02 06:09:31 INFO  : open-test-file: vfs cache: queuing for upload in 100ms
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25000): >close: err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: OpenFile: flags=O_RDONLY, perm=----------
2025/05/02 06:09:31 DEBUG : open-test-file: Open: flags=O_RDONLY
2025/05/02 06:09:31 DEBUG : open-test-file: newRWFileHandle: 
2025/05/02 06:09:31 DEBUG : open-test-file: >newRWFileHandle: err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: >Open: fd=open-test-file (rw), err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: >OpenFile: fd=open-test-file (rw), err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25040): _readAt: size=512, off=0
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25040): openPending: 
2025/05/02 06:09:31 DEBUG : open-test-file: vfs cache: truncate to size=5 (not needed as size correct)
2025/05/02 06:09:31 DEBUG : : Added virtual directory entry vAddFile: "open-test-file"
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25040): >openPending: err=<nil>
2025/05/02 06:09:31 DEBUG : vfs cache: looking for range={Pos:0 Size:5} in [{Pos:0 Size:5}] - present true
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25040): >_readAt: n=5, err=EOF
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25040): close: 
2025/05/02 06:09:31 DEBUG : open-test-file: vfs cache: setting modification time to 2025-05-02 06:09:31.060187344 +0000 UTC m=+4.289077941
2025/05/02 06:09:31 INFO  : open-test-file: vfs cache: queuing for upload in 100ms
2025/05/02 06:09:31 DEBUG : open-test-file(0xc000b25040): >close: err=<nil>
2025/05/02 06:09:31 DEBUG : open-test-file: Remove: 
2025/05/02 06:09:31 DEBUG : open-test-file: vfs cache: cancelling writeback (uploading false) 0xc000478380 item 1
2025/05/02 06:09:31 INFO  : open-test-file: vfs cache: removed cache file as file deleted
2025/05/02 06:09:31 DEBUG : open-test-file: vfs cache: removed metadata from cache as file deleted
2025/05/02 06:09:31 DEBUG : : Added virtual directory entry vDel: "open-test-file"
2025/05/02 06:09:31 DEBUG : open-test-file: >Remove: err=<nil>
2025/05/02 06:09:31 DEBUG : WaitForWriters: timeout=30s
2025/05/02 06:09:31 DEBUG : : Looking for writers
2025/05/02 06:09:31 DEBUG : >WaitForWriters: 
2025/05/02 06:09:31 DEBUG : sugarsync root 'Test/rclone-test-wosiyek4geyu': vfs cache: cleaner exiting
2025/05/02 06:09:31 ERROR : : error listing: directory not found
--- PASS: TestRWFileHandleOpenTests (1.75s)
    --- PASS: TestRWFileHandleOpenTests/writes (1.75s)
        --- PASS: TestRWFileHandleOpenTests/writes/os.O_RDONLY (0.88s)
PASS
2025/05/02 06:09:31 DEBUG : sugarsync root 'Test/rclone-test-wosiyek4geyu': Purge remote
2025/05/02 06:09:32 NOTICE: purge failed: directory not found
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestSugarSync:Test -verbose -test.run '^TestRWFileHandleOpenTests$/^writes$/^os.O_RDONLY$'" - Finished OK in 6.093046937s (try 2/5)