"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPikPak: -verbose -test.run '^(TestReadFileHandleFlush|TestReadFileHandleRelease)$'" - Starting (try 2/5)
2025/08/23 02:36:45 DEBUG : Creating backend with remote "TestPikPak:rclone-test-gidajuz3cawa"
2025/08/23 02:36:45 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/08/23 02:36:47 DEBUG : Creating backend with remote "/tmp/rclone1544210936"
=== RUN   TestReadFileHandleFlush
    run.go:180: Remote "PikPak root 'rclone-test-gidajuz3cawa'", Local "Local file system at /tmp/rclone1544210936", Modify Window "876000h0m0s"
2025/08/23 02:36:47 INFO  : PikPak root 'rclone-test-gidajuz3cawa': poll-interval is not supported by this remote
2025/08/23 02:36:47 NOTICE: PikPak root 'rclone-test-gidajuz3cawa': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2025/08/23 02:36:48 DEBUG : dir/file1: calculating gcid: failed to unwrap object from src: dir/file1
2025/08/23 02:36:48 DEBUG : dir/file1: gcid = 75291f3a188a427f873fb88fbc37ce5ce150d01c
2025/08/23 02:36:50 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2025/08/23 02:36:51 DEBUG : dir/file1: Open: flags=O_RDONLY
2025/08/23 02:36:51 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2025/08/23 02:36:51 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2025/08/23 02:36:51 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2025/08/23 02:36:57 DEBUG : pacer: low level retry 1/10 (error no link)
2025/08/23 02:36:57 DEBUG : pacer: Rate limited, increasing sleep to 200ms
2025/08/23 02:37:03 DEBUG : pacer: low level retry 2/10 (error no link)
2025/08/23 02:37:03 DEBUG : pacer: Rate limited, increasing sleep to 400ms
2025/08/23 02:37:09 DEBUG : pacer: low level retry 3/10 (error no link)
2025/08/23 02:37:09 DEBUG : pacer: Rate limited, increasing sleep to 800ms
2025/08/23 02:37:16 DEBUG : pacer: low level retry 4/10 (error no link)
2025/08/23 02:37:16 DEBUG : pacer: Rate limited, increasing sleep to 1.6s
2025/08/23 02:37:16 DEBUG : pacer: Reducing sleep to 1.2s
2025/08/23 02:37:18 DEBUG : pacer: Reducing sleep to 900ms
2025/08/23 02:37:18 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728
2025/08/23 02:37:18 DEBUG : WaitForWriters: timeout=30s
2025/08/23 02:37:18 DEBUG : dir: Looking for writers
2025/08/23 02:37:18 DEBUG : file1: reading active writers
2025/08/23 02:37:18 DEBUG : Looking for writers
2025/08/23 02:37:18 DEBUG : dir: reading active writers
2025/08/23 02:37:18 DEBUG : >WaitForWriters: 
2025/08/23 02:37:19 DEBUG : pacer: Reducing sleep to 675ms
2025/08/23 02:37:20 DEBUG : pacer: Reducing sleep to 506.25ms
2025/08/23 02:37:20 DEBUG : pacer: Reducing sleep to 379.6875ms
2025/08/23 02:37:21 DEBUG : pacer: Reducing sleep to 284.765625ms
2025/08/23 02:37:22 DEBUG : pacer: Reducing sleep to 213.574218ms
2025/08/23 02:37:22 DEBUG : dir: Rmdir: contains trashed file: "file1"
2025/08/23 02:37:22 DEBUG : pacer: Reducing sleep to 160.180663ms
2025/08/23 02:37:23 DEBUG : pacer: Reducing sleep to 120.135497ms
2025/08/23 02:37:23 DEBUG : pacer: Reducing sleep to 100ms
--- PASS: TestReadFileHandleFlush (36.07s)
=== RUN   TestReadFileHandleRelease
    run.go:180: Remote "PikPak root 'rclone-test-gidajuz3cawa'", Local "Local file system at /tmp/rclone1544210936", Modify Window "876000h0m0s"
2025/08/23 02:37:23 INFO  : PikPak root 'rclone-test-gidajuz3cawa': poll-interval is not supported by this remote
2025/08/23 02:37:23 NOTICE: PikPak root 'rclone-test-gidajuz3cawa': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2025/08/23 02:37:24 DEBUG : dir/file1: calculating gcid: failed to unwrap object from src: dir/file1
2025/08/23 02:37:24 DEBUG : dir/file1: gcid = 75291f3a188a427f873fb88fbc37ce5ce150d01c
2025/08/23 02:37:26 DEBUG : dir/file1: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2025/08/23 02:37:26 DEBUG : dir/file1: Open: flags=O_RDONLY
2025/08/23 02:37:26 DEBUG : dir/file1: >Open: fd=dir/file1 (r), err=<nil>
2025/08/23 02:37:26 DEBUG : dir/file1: >OpenFile: fd=dir/file1 (r), err=<nil>
2025/08/23 02:37:26 DEBUG : dir/file1: ChunkedReader.openRange at 0 length 134217728
2025/08/23 02:37:32 DEBUG : pacer: low level retry 1/10 (error no link)
2025/08/23 02:37:32 DEBUG : pacer: Rate limited, increasing sleep to 200ms
2025/08/23 02:37:33 DEBUG : pacer: Reducing sleep to 150ms
2025/08/23 02:37:34 DEBUG : pacer: Reducing sleep to 112.5ms
2025/08/23 02:37:34 DEBUG : dir/file1: ChunkedReader.Read at 0 length 256 chunkOffset 0 chunkSize 134217728
2025/08/23 02:37:34 DEBUG : dir/file1: ReadFileHandle.Release closing
2025/08/23 02:37:34 DEBUG : dir/file1: ReadFileHandle.Release nothing to do
2025/08/23 02:37:34 DEBUG : WaitForWriters: timeout=30s
2025/08/23 02:37:34 DEBUG : dir: Looking for writers
2025/08/23 02:37:34 DEBUG : file1: reading active writers
2025/08/23 02:37:34 DEBUG : Looking for writers
2025/08/23 02:37:34 DEBUG : dir: reading active writers
2025/08/23 02:37:34 DEBUG : >WaitForWriters: 
2025/08/23 02:37:34 DEBUG : pacer: Reducing sleep to 100ms
2025/08/23 02:37:36 DEBUG : dir: Rmdir: contains trashed file: "file1"
--- PASS: TestReadFileHandleRelease (14.39s)
PASS
2025/08/23 02:37:37 DEBUG : PikPak root 'rclone-test-gidajuz3cawa': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPikPak: -verbose -test.run '^(TestReadFileHandleFlush|TestReadFileHandleRelease)$'" - Finished OK in 52.909027851s (try 2/5)