"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPcloud: -verbose -test.run '^(TestDirMetadataExtension|TestDirSetModTime|TestDirWalk|TestFileMethods|TestZipManySubDirs)$'" - Starting (try 2/5)
2026/09/29 01:26:39 DEBUG : Creating backend with remote "TestPcloud:rclone-test-yokeneh9mezu"
2026/09/29 01:26:39 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/09/29 01:26:40 DEBUG : Creating backend with remote "/tmp/rclone3592005750"
=== RUN   TestDirWalk
    run.go:198: Remote "pcloud root 'rclone-test-yokeneh9mezu'", Local "Local file system at /tmp/rclone3592005750", Modify Window "1s"
2026/09/29 01:26:40 NOTICE: pcloud root 'rclone-test-yokeneh9mezu': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/09/29 01:26:40 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "dir" (type: 0)
2026/09/29 01:26:40 DEBUG : changeNotify: relativePath="dir", type=0
2026/09/29 01:26:40 DEBUG : >changeNotify: 
2026/09/29 01:26:40 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "dir/file1" (type: 1)
2026/09/29 01:26:40 DEBUG : changeNotify: relativePath="dir/file1", type=1
2026/09/29 01:26:40 DEBUG : >changeNotify: 
2026/09/29 01:26:41 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "fil" (type: 0)
2026/09/29 01:26:41 DEBUG : changeNotify: relativePath="fil", type=0
2026/09/29 01:26:41 DEBUG : invalidating directory cache
2026/09/29 01:26:41 DEBUG : >changeNotify: 
2026/09/29 01:26:41 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "fil/a" (type: 0)
2026/09/29 01:26:41 DEBUG : changeNotify: relativePath="fil/a", type=0
2026/09/29 01:26:41 DEBUG : >changeNotify: 
2026/09/29 01:26:41 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "fil/a/b" (type: 0)
2026/09/29 01:26:41 DEBUG : changeNotify: relativePath="fil/a/b", type=0
2026/09/29 01:26:41 DEBUG : >changeNotify: 
2026/09/29 01:26:41 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "fil/a/b/c" (type: 1)
2026/09/29 01:26:41 DEBUG : changeNotify: relativePath="fil/a/b/c", type=1
2026/09/29 01:26:41 DEBUG : >changeNotify: 
2026/09/29 01:26:42 DEBUG : forgetting directory cache
2026/09/29 01:26:42 DEBUG : dir: forgetting directory cache
2026/09/29 01:26:42 DEBUG : WaitForWriters: timeout=30s
2026/09/29 01:26:42 DEBUG : dir: Looking for writers
2026/09/29 01:26:42 DEBUG : fil/a/b: Looking for writers
2026/09/29 01:26:42 DEBUG : fil/a: Looking for writers
2026/09/29 01:26:42 DEBUG : b: reading active writers
2026/09/29 01:26:42 DEBUG : fil: Looking for writers
2026/09/29 01:26:42 DEBUG : a: reading active writers
2026/09/29 01:26:42 DEBUG : Looking for writers
2026/09/29 01:26:42 DEBUG : dir: reading active writers
2026/09/29 01:26:42 DEBUG : fil: reading active writers
2026/09/29 01:26:42 DEBUG : >WaitForWriters: 
--- PASS: TestDirWalk (3.99s)
=== RUN   TestDirSetModTime
    run.go:198: Remote "pcloud root 'rclone-test-yokeneh9mezu'", Local "Local file system at /tmp/rclone3592005750", Modify Window "1s"
2026/09/29 01:26:44 NOTICE: pcloud root 'rclone-test-yokeneh9mezu': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/09/29 01:26:44 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "dir" (type: 0)
2026/09/29 01:26:44 DEBUG : changeNotify: relativePath="dir", type=0
2026/09/29 01:26:44 DEBUG : >changeNotify: 
2026/09/29 01:26:44 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "dir/file1" (type: 1)
2026/09/29 01:26:44 DEBUG : changeNotify: relativePath="dir/file1", type=1
2026/09/29 01:26:44 DEBUG : >changeNotify: 
2026/09/29 01:26:44 DEBUG : WaitForWriters: timeout=30s
2026/09/29 01:26:44 DEBUG : dir: Looking for writers
2026/09/29 01:26:44 DEBUG : Looking for writers
2026/09/29 01:26:44 DEBUG : dir: reading active writers
2026/09/29 01:26:44 DEBUG : >WaitForWriters: 
--- PASS: TestDirSetModTime (1.33s)
=== RUN   TestDirMetadataExtension
    run.go:198: Remote "pcloud root 'rclone-test-yokeneh9mezu'", Local "Local file system at /tmp/rclone3592005750", Modify Window "1s"
2026/09/29 01:26:45 NOTICE: pcloud root 'rclone-test-yokeneh9mezu': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/09/29 01:26:46 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "dir/file1" (type: 1)
2026/09/29 01:26:46 DEBUG : changeNotify: relativePath="dir/file1", type=1
2026/09/29 01:26:46 DEBUG : >changeNotify: 
2026/09/29 01:26:46 DEBUG : dir: Added virtual directory entry vAddFile: "file1.metadata"
2026/09/29 01:26:46 DEBUG : dir/file1.metadata: OpenFile: flags=O_RDONLY, perm=----------
2026/09/29 01:26:46 DEBUG : dir/file1.metadata: Open: flags=O_RDONLY
2026/09/29 01:26:46 DEBUG : dir/file1.metadata: >Open: fd=dir/file1.metadata (r), err=<nil>
2026/09/29 01:26:46 DEBUG : dir/file1.metadata: >OpenFile: fd=dir/file1.metadata (r), err=<nil>
2026/09/29 01:26:46 DEBUG : dir/file1.metadata: ChunkedReader.openRange at 0 length 134217728
2026/09/29 01:26:46 DEBUG : dir/file1.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2026/09/29 01:26:46 DEBUG : Added virtual directory entry vAddFile: "dir.metadata"
2026/09/29 01:26:46 DEBUG : dir.metadata: OpenFile: flags=O_RDONLY, perm=----------
2026/09/29 01:26:46 DEBUG : dir.metadata: Open: flags=O_RDONLY
2026/09/29 01:26:46 DEBUG : dir.metadata: >Open: fd=dir.metadata (r), err=<nil>
2026/09/29 01:26:46 DEBUG : dir.metadata: >OpenFile: fd=dir.metadata (r), err=<nil>
2026/09/29 01:26:46 DEBUG : dir.metadata: ChunkedReader.openRange at 0 length 134217728
2026/09/29 01:26:46 DEBUG : dir.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2026/09/29 01:26:46 DEBUG : dir/newfile: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rw-rw-rw-
2026/09/29 01:26:46 DEBUG : dir/newfile: Open: flags=O_WRONLY|O_CREATE
2026/09/29 01:26:46 DEBUG : dir: Added virtual directory entry vAddFile: "newfile"
2026/09/29 01:26:46 DEBUG : dir/newfile: >Open: fd=dir/newfile (w), err=<nil>
2026/09/29 01:26:46 DEBUG : dir/newfile: >OpenFile: fd=dir/newfile (w), err=<nil>
2026/09/29 01:26:46 DEBUG : dir: Added virtual directory entry vAddFile: "newfile.metadata"
2026/09/29 01:26:46 DEBUG : dir/newfile.metadata: OpenFile: flags=O_RDONLY, perm=----------
2026/09/29 01:26:46 DEBUG : dir/newfile.metadata: Open: flags=O_RDONLY
2026/09/29 01:26:46 DEBUG : dir/newfile.metadata: >Open: fd=dir/newfile.metadata (r), err=<nil>
2026/09/29 01:26:46 DEBUG : dir/newfile.metadata: >OpenFile: fd=dir/newfile.metadata (r), err=<nil>
2026/09/29 01:26:46 DEBUG : dir/newfile.metadata: ChunkedReader.openRange at 0 length 134217728
2026/09/29 01:26:46 DEBUG : dir/newfile.metadata: ChunkedReader.Read at 0 length 512 chunkOffset 0 chunkSize 134217728
2026/09/29 01:26:46 DEBUG : dir: Added virtual directory entry vAddFile: "newfile"
2026/09/29 01:26:46 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': File to upload is small (0 bytes), uploading instead of streaming
2026/09/29 01:26:46 DEBUG : dir/newfile: size = 0 OK
2026/09/29 01:26:46 DEBUG : dir/newfile: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK
2026/09/29 01:26:46 DEBUG : dir/newfile: Size and sha1 of src and dst objects identical
2026/09/29 01:26:46 DEBUG : dir: Added virtual directory entry vAddFile: "newfile"
2026/09/29 01:26:46 DEBUG : WaitForWriters: timeout=30s
2026/09/29 01:26:46 DEBUG : dir: Looking for writers
2026/09/29 01:26:46 DEBUG : file1: reading active writers
2026/09/29 01:26:46 DEBUG : file1.metadata: reading active writers
2026/09/29 01:26:46 DEBUG : newfile: reading active writers
2026/09/29 01:26:46 DEBUG : newfile.metadata: reading active writers
2026/09/29 01:26:46 DEBUG : Looking for writers
2026/09/29 01:26:46 DEBUG : dir: reading active writers
2026/09/29 01:26:46 DEBUG : dir.metadata: reading active writers
2026/09/29 01:26:46 DEBUG : >WaitForWriters: 
--- PASS: TestDirMetadataExtension (1.44s)
=== RUN   TestFileMethods
    run.go:198: Remote "pcloud root 'rclone-test-yokeneh9mezu'", Local "Local file system at /tmp/rclone3592005750", Modify Window "1s"
2026/09/29 01:26:46 NOTICE: pcloud root 'rclone-test-yokeneh9mezu': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/09/29 01:26:46 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "dir" (type: 0)
2026/09/29 01:26:46 DEBUG : changeNotify: relativePath="dir", type=0
2026/09/29 01:26:46 DEBUG : >changeNotify: 
2026/09/29 01:26:47 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "dir/file1" (type: 1)
2026/09/29 01:26:47 DEBUG : changeNotify: relativePath="dir/file1", type=1
2026/09/29 01:26:47 DEBUG : >changeNotify: 
2026/09/29 01:26:47 DEBUG : WaitForWriters: timeout=30s
2026/09/29 01:26:47 DEBUG : dir: Looking for writers
2026/09/29 01:26:47 DEBUG : file1: reading active writers
2026/09/29 01:26:47 DEBUG : Looking for writers
2026/09/29 01:26:47 DEBUG : dir: reading active writers
2026/09/29 01:26:47 DEBUG : >WaitForWriters: 
    fstest.go:299: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:302: Flushing the directory cache
    fstest.go:293: Sleeping for 6s just to make sure
--- PASS: TestFileMethods (8.88s)
=== RUN   TestZipManySubDirs
    run.go:198: Remote "pcloud root 'rclone-test-yokeneh9mezu'", Local "Local file system at /tmp/rclone3592005750", Modify Window "1s"
2026/09/29 01:26:55 NOTICE: pcloud root 'rclone-test-yokeneh9mezu': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/09/29 01:26:56 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "a" (type: 0)
2026/09/29 01:26:56 DEBUG : changeNotify: relativePath="a", type=0
2026/09/29 01:26:56 DEBUG : >changeNotify: 
2026/09/29 01:26:56 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "a/top.txt" (type: 1)
2026/09/29 01:26:56 DEBUG : changeNotify: relativePath="a/top.txt", type=1
2026/09/29 01:26:56 DEBUG : >changeNotify: 
2026/09/29 01:26:56 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "a/b" (type: 0)
2026/09/29 01:26:56 DEBUG : changeNotify: relativePath="a/b", type=0
2026/09/29 01:26:56 DEBUG : >changeNotify: 
2026/09/29 01:26:56 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "a/b/mid.txt" (type: 1)
2026/09/29 01:26:56 DEBUG : changeNotify: relativePath="a/b/mid.txt", type=1
2026/09/29 01:26:56 DEBUG : >changeNotify: 
2026/09/29 01:26:57 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "a/b/c" (type: 0)
2026/09/29 01:26:57 DEBUG : changeNotify: relativePath="a/b/c", type=0
2026/09/29 01:26:57 DEBUG : a/b: invalidating directory cache
2026/09/29 01:26:57 DEBUG : a/b/c/deep.txt: Open: flags=O_RDONLY
2026/09/29 01:26:57 DEBUG : a/b/c/deep.txt: >Open: fd=a/b/c/deep.txt (r), err=<nil>
2026/09/29 01:26:57 DEBUG : a/b/c: invalidating directory cache
2026/09/29 01:26:57 DEBUG : >changeNotify: 
2026/09/29 01:26:57 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': ChangeNotify: detected change in "a/b/c/deep.txt" (type: 1)
2026/09/29 01:26:57 DEBUG : changeNotify: relativePath="a/b/c/deep.txt", type=1
2026/09/29 01:26:57 DEBUG : >changeNotify: 
2026/09/29 01:26:57 DEBUG : a/b/c/deep.txt: ChunkedReader.openRange at 0 length 134217728
2026/09/29 01:26:57 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Tue, 29 Sep 2026 01:26:57 +0000": parsing time "Tue, 29 Sep 2026 01:26:57 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 29 Sep 2026 01:26:57 +0000" as " "
2026/09/29 01:26:57 DEBUG : a/b/c/deep.txt: ChunkedReader.Read at 0 length 32768 chunkOffset 0 chunkSize 134217728
2026/09/29 01:26:58 DEBUG : a/b/mid.txt: Open: flags=O_RDONLY
2026/09/29 01:26:58 DEBUG : a/b/mid.txt: >Open: fd=a/b/mid.txt (r), err=<nil>
2026/09/29 01:26:58 DEBUG : a/b/mid.txt: ChunkedReader.openRange at 0 length 134217728
2026/09/29 01:26:58 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Tue, 29 Sep 2026 01:26:58 +0000": parsing time "Tue, 29 Sep 2026 01:26:58 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 29 Sep 2026 01:26:58 +0000" as " "
2026/09/29 01:26:58 DEBUG : a/b/mid.txt: ChunkedReader.Read at 0 length 32768 chunkOffset 0 chunkSize 134217728
2026/09/29 01:26:58 DEBUG : a/top.txt: Open: flags=O_RDONLY
2026/09/29 01:26:58 DEBUG : a/top.txt: >Open: fd=a/top.txt (r), err=<nil>
2026/09/29 01:26:58 DEBUG : a/top.txt: ChunkedReader.openRange at 0 length 134217728
2026/09/29 01:26:58 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Tue, 29 Sep 2026 01:26:58 +0000": parsing time "Tue, 29 Sep 2026 01:26:58 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 29 Sep 2026 01:26:58 +0000" as " "
2026/09/29 01:26:58 DEBUG : a/top.txt: ChunkedReader.Read at 0 length 32768 chunkOffset 0 chunkSize 134217728
2026/09/29 01:26:58 DEBUG : WaitForWriters: timeout=30s
2026/09/29 01:26:58 DEBUG : a/b/c: Looking for writers
2026/09/29 01:26:58 DEBUG : deep.txt: reading active writers
2026/09/29 01:26:58 DEBUG : a/b: Looking for writers
2026/09/29 01:26:58 DEBUG : c: reading active writers
2026/09/29 01:26:58 DEBUG : mid.txt: reading active writers
2026/09/29 01:26:58 DEBUG : a: Looking for writers
2026/09/29 01:26:58 DEBUG : b: reading active writers
2026/09/29 01:26:58 DEBUG : top.txt: reading active writers
2026/09/29 01:26:58 DEBUG : Looking for writers
2026/09/29 01:26:58 DEBUG : a: reading active writers
2026/09/29 01:26:58 DEBUG : >WaitForWriters: 
--- PASS: TestZipManySubDirs (3.55s)
PASS
2026/09/29 01:26:59 DEBUG : pcloud root 'rclone-test-yokeneh9mezu': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPcloud: -verbose -test.run '^(TestDirMetadataExtension|TestDirSetModTime|TestDirWalk|TestFileMethods|TestZipManySubDirs)$'" - Finished OK in 20.322960809s (try 2/5)