"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPcloud: -verbose -test.run '^(TestCaseSensitivity|TestWriteFileHandleRelease|TestWriteFileModTimeWithOpenWriters)$'" - Starting (try 2/5)
2026/05/25 01:38:59 DEBUG : Creating backend with remote "TestPcloud:rclone-test-henulat8pepe"
2026/05/25 01:38:59 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2026/05/25 01:38:59 DEBUG : Creating backend with remote "/tmp/rclone1326029488"
=== RUN   TestCaseSensitivity
    run.go:198: Remote "pcloud root 'rclone-test-henulat8pepe'", Local "Local file system at /tmp/rclone1326029488", Modify Window "1s"
2026/05/25 01:39:01 NOTICE: pcloud root 'rclone-test-henulat8pepe': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/05/25 01:39:01 NOTICE: pcloud root 'rclone-test-henulat8pepe': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/05/25 01:39:01 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:01 DEBUG : FiLeA: Open: flags=O_RDONLY
2026/05/25 01:39:01 DEBUG : FiLeA: >Open: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:01 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:01 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:01 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:01 +0000": parsing time "Mon, 25 May 2026 01:39:01 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:01 +0000" as " "
2026/05/25 01:39:01 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:01 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:01 DEBUG : FiLeA: Open: flags=O_RDONLY
2026/05/25 01:39:01 DEBUG : FiLeA: >Open: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:01 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:01 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:01 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:01 +0000": parsing time "Mon, 25 May 2026 01:39:01 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:01 +0000" as " "
2026/05/25 01:39:01 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:01 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:01 DEBUG : FiLeA: Open: flags=O_RDONLY
2026/05/25 01:39:01 DEBUG : FiLeA: >Open: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:01 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:01 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:01 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:01 +0000": parsing time "Mon, 25 May 2026 01:39:01 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:01 +0000" as " "
2026/05/25 01:39:01 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:01 DEBUG : FiLeB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:01 DEBUG : FiLeB: Open: flags=O_RDONLY
2026/05/25 01:39:01 DEBUG : FiLeB: >Open: fd=FiLeB (r), err=<nil>
2026/05/25 01:39:01 DEBUG : FiLeB: >OpenFile: fd=FiLeB (r), err=<nil>
2026/05/25 01:39:01 DEBUG : FiLeB: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:02 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:02 +0000": parsing time "Mon, 25 May 2026 01:39:02 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:02 +0000" as " "
2026/05/25 01:39:02 DEBUG : FiLeB: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:02 DEBUG : FilEb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:02 DEBUG : FilEb: Open: flags=O_RDONLY
2026/05/25 01:39:02 DEBUG : FilEb: >Open: fd=FilEb (r), err=<nil>
2026/05/25 01:39:02 DEBUG : FilEb: >OpenFile: fd=FilEb (r), err=<nil>
2026/05/25 01:39:02 DEBUG : FilEb: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:02 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:02 +0000": parsing time "Mon, 25 May 2026 01:39:02 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:02 +0000" as " "
2026/05/25 01:39:02 DEBUG : FilEb: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FiLeA: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FiLeA: >Open: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:02 +0000": parsing time "Mon, 25 May 2026 01:39:02 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:02 +0000" as " "
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : fileA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FiLeA: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FiLeA: >Open: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : fileA: >OpenFile: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:03 +0000": parsing time "Mon, 25 May 2026 01:39:03 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:03 +0000" as " "
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : filea: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FiLeA: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FiLeA: >Open: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : filea: >OpenFile: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:03 +0000": parsing time "Mon, 25 May 2026 01:39:03 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:03 +0000" as " "
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : FILEA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FiLeA: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FiLeA: >Open: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FILEA: >OpenFile: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:03 +0000": parsing time "Mon, 25 May 2026 01:39:03 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:03 +0000" as " "
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : FiLeB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FiLeB: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FiLeB: >Open: fd=FiLeB (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeB: >OpenFile: fd=FiLeB (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeB: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:03 +0000": parsing time "Mon, 25 May 2026 01:39:03 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:03 +0000" as " "
2026/05/25 01:39:03 DEBUG : FiLeB: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : FilEb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FilEb: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FilEb: >Open: fd=FilEb (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FilEb: >OpenFile: fd=FilEb (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FilEb: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:03 +0000": parsing time "Mon, 25 May 2026 01:39:03 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:03 +0000" as " "
2026/05/25 01:39:03 DEBUG : FilEb: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : fileb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 ERROR : /: Dir.Stat error: duplicate filename "fileb" detected with case/unicode normalization settings
2026/05/25 01:39:03 DEBUG : fileb: >OpenFile: fd=<nil>, err=duplicate filename "fileb" detected with case/unicode normalization settings
2026/05/25 01:39:03 DEBUG : FILEB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 ERROR : /: Dir.Stat error: duplicate filename "FILEB" detected with case/unicode normalization settings
2026/05/25 01:39:03 DEBUG : FILEB: >OpenFile: fd=<nil>, err=duplicate filename "FILEB" detected with case/unicode normalization settings
2026/05/25 01:39:03 DEBUG : FiLeA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FiLeA: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FiLeA: >Open: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeA: >OpenFile: fd=FiLeA (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:03 +0000": parsing time "Mon, 25 May 2026 01:39:03 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:03 +0000" as " "
2026/05/25 01:39:03 DEBUG : FiLeA: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : fileA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : fileA: >OpenFile: fd=<nil>, err=file does not exist
2026/05/25 01:39:03 DEBUG : filea: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : filea: >OpenFile: fd=<nil>, err=file does not exist
2026/05/25 01:39:03 DEBUG : FILEA: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FILEA: >OpenFile: fd=<nil>, err=file does not exist
2026/05/25 01:39:03 DEBUG : FiLeB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FiLeB: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FiLeB: >Open: fd=FiLeB (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeB: >OpenFile: fd=FiLeB (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FiLeB: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:03 +0000": parsing time "Mon, 25 May 2026 01:39:03 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:03 +0000" as " "
2026/05/25 01:39:03 DEBUG : FiLeB: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : FilEb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FilEb: Open: flags=O_RDONLY
2026/05/25 01:39:03 DEBUG : FilEb: >Open: fd=FilEb (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FilEb: >OpenFile: fd=FilEb (r), err=<nil>
2026/05/25 01:39:03 DEBUG : FilEb: ChunkedReader.openRange at 0 length 134217728
2026/05/25 01:39:03 DEBUG : Couldn't parse Date: from server ecph1.pcloud.com: "Mon, 25 May 2026 01:39:03 +0000": parsing time "Mon, 25 May 2026 01:39:03 +0000" as "Mon Jan _2 15:04:05 2006": cannot parse ", 25 May 2026 01:39:03 +0000" as " "
2026/05/25 01:39:03 DEBUG : FilEb: ChunkedReader.Read at 0 length 5 chunkOffset 0 chunkSize 134217728
2026/05/25 01:39:03 DEBUG : fileb: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : fileb: >OpenFile: fd=<nil>, err=file does not exist
2026/05/25 01:39:03 DEBUG : FILEB: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/05/25 01:39:03 DEBUG : FILEB: >OpenFile: fd=<nil>, err=file does not exist
2026/05/25 01:39:03 DEBUG : WaitForWriters: timeout=30s
2026/05/25 01:39:03 DEBUG : Looking for writers
2026/05/25 01:39:03 DEBUG : FiLeB: reading active writers
2026/05/25 01:39:03 DEBUG : FilEb: reading active writers
2026/05/25 01:39:03 DEBUG : FiLeA: reading active writers
2026/05/25 01:39:03 DEBUG : >WaitForWriters: 
2026/05/25 01:39:03 DEBUG : WaitForWriters: timeout=30s
2026/05/25 01:39:03 DEBUG : Looking for writers
2026/05/25 01:39:03 DEBUG : FiLeA: reading active writers
2026/05/25 01:39:03 DEBUG : FiLeB: reading active writers
2026/05/25 01:39:03 DEBUG : FilEb: reading active writers
2026/05/25 01:39:03 DEBUG : >WaitForWriters: 
    fstest.go:298: Sleeping for 1s for list eventual consistency: 1/3
    fstest.go:301: Flushing the directory cache
    fstest.go:292: Sleeping for 6s just to make sure
--- PASS: TestCaseSensitivity (12.06s)
=== RUN   TestWriteFileHandleRelease
    run.go:198: Remote "pcloud root 'rclone-test-henulat8pepe'", Local "Local file system at /tmp/rclone1326029488", Modify Window "1s"
2026/05/25 01:39:11 NOTICE: pcloud root 'rclone-test-henulat8pepe': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/05/25 01:39:11 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/05/25 01:39:11 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/05/25 01:39:11 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/05/25 01:39:11 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/05/25 01:39:11 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/05/25 01:39:11 DEBUG : file1: WriteFileHandle.Release closing
2026/05/25 01:39:11 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/05/25 01:39:11 DEBUG : pcloud root 'rclone-test-henulat8pepe': File to upload is small (0 bytes), uploading instead of streaming
2026/05/25 01:39:12 DEBUG : file1: size = 0 OK
2026/05/25 01:39:12 DEBUG : file1: sha1 = da39a3ee5e6b4b0d3255bfef95601890afd80709 OK
2026/05/25 01:39:12 DEBUG : file1: Size and sha1 of src and dst objects identical
2026/05/25 01:39:12 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/05/25 01:39:12 DEBUG : file1: WriteFileHandle.Release nothing to do
2026/05/25 01:39:12 DEBUG : WaitForWriters: timeout=30s
2026/05/25 01:39:12 DEBUG : Looking for writers
2026/05/25 01:39:12 DEBUG : file1: reading active writers
2026/05/25 01:39:12 DEBUG : >WaitForWriters: 
--- PASS: TestWriteFileHandleRelease (0.53s)
=== RUN   TestWriteFileModTimeWithOpenWriters
    run.go:198: Remote "pcloud root 'rclone-test-henulat8pepe'", Local "Local file system at /tmp/rclone1326029488", Modify Window "1s"
2026/05/25 01:39:12 NOTICE: pcloud root 'rclone-test-henulat8pepe': --vfs-cache-mode writes or full is recommended for this remote as it can't stream
2026/05/25 01:39:12 DEBUG : file1: OpenFile: flags=O_WRONLY|O_CREATE, perm=-rwxrwxrwx
2026/05/25 01:39:12 DEBUG : file1: Open: flags=O_WRONLY|O_CREATE
2026/05/25 01:39:12 DEBUG : Added virtual directory entry vAddFile: "file1"
2026/05/25 01:39:12 DEBUG : file1: >Open: fd=file1 (w), err=<nil>
2026/05/25 01:39:12 DEBUG : file1: >OpenFile: fd=file1 (w), err=<nil>
2026/05/25 01:39:12 DEBUG : pcloud root 'rclone-test-henulat8pepe': ChangeNotify: detected change in "time_test" (type: 1)
2026/05/25 01:39:12 DEBUG : changeNotify: relativePath="time_test", type=1
2026/05/25 01:39:12 DEBUG : invalidating directory cache
2026/05/25 01:39:12 DEBUG : >changeNotify: 
    write_test.go:299: 
        	Error Trace:	/home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:299
        	            				/usr/local/go/src/sync/once.go:78
        	            				/usr/local/go/src/sync/once.go:69
        	            				/home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:295
        	            				/home/rclone/go/src/github.com/rclone/rclone/vfs/write_test.go:320
        	            				/usr/local/go/src/runtime/asm_amd64.s:1771
        	Error:      	Received unexpected error:
        	            	object not found
        	Test:       	TestWriteFileModTimeWithOpenWriters
2026/05/25 01:39:12 DEBUG : WaitForWriters: timeout=30s
2026/05/25 01:39:12 DEBUG : Looking for writers
2026/05/25 01:39:12 DEBUG : file1: reading active writers
2026/05/25 01:39:12 DEBUG : file1: active writers 1
2026/05/25 01:39:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 10ms
2026/05/25 01:39:12 DEBUG : Looking for writers
2026/05/25 01:39:12 DEBUG : file1: reading active writers
2026/05/25 01:39:12 DEBUG : file1: active writers 1
2026/05/25 01:39:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 20ms
2026/05/25 01:39:12 DEBUG : Looking for writers
2026/05/25 01:39:12 DEBUG : file1: reading active writers
2026/05/25 01:39:12 DEBUG : file1: active writers 1
2026/05/25 01:39:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 40ms
2026/05/25 01:39:12 DEBUG : Looking for writers
2026/05/25 01:39:12 DEBUG : file1: reading active writers
2026/05/25 01:39:12 DEBUG : file1: active writers 1
2026/05/25 01:39:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 80ms
2026/05/25 01:39:12 DEBUG : Looking for writers
2026/05/25 01:39:12 DEBUG : file1: reading active writers
2026/05/25 01:39:12 DEBUG : file1: active writers 1
2026/05/25 01:39:12 DEBUG : Still 1 writers active and 0 cache items in use, waiting 160ms
2026/05/25 01:39:13 DEBUG : Looking for writers
2026/05/25 01:39:13 DEBUG : file1: reading active writers
2026/05/25 01:39:13 DEBUG : file1: active writers 1
2026/05/25 01:39:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 320ms
2026/05/25 01:39:13 DEBUG : Looking for writers
2026/05/25 01:39:13 DEBUG : file1: reading active writers
2026/05/25 01:39:13 DEBUG : file1: active writers 1
2026/05/25 01:39:13 DEBUG : Still 1 writers active and 0 cache items in use, waiting 640ms
2026/05/25 01:39:14 DEBUG : Looking for writers
2026/05/25 01:39:14 DEBUG : file1: reading active writers
2026/05/25 01:39:14 DEBUG : file1: active writers 1
2026/05/25 01:39:14 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:15 DEBUG : Looking for writers
2026/05/25 01:39:15 DEBUG : file1: reading active writers
2026/05/25 01:39:15 DEBUG : file1: active writers 1
2026/05/25 01:39:15 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:16 DEBUG : Looking for writers
2026/05/25 01:39:16 DEBUG : file1: reading active writers
2026/05/25 01:39:16 DEBUG : file1: active writers 1
2026/05/25 01:39:16 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:17 DEBUG : Looking for writers
2026/05/25 01:39:17 DEBUG : file1: reading active writers
2026/05/25 01:39:17 DEBUG : file1: active writers 1
2026/05/25 01:39:17 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:18 DEBUG : Looking for writers
2026/05/25 01:39:18 DEBUG : file1: reading active writers
2026/05/25 01:39:18 DEBUG : file1: active writers 1
2026/05/25 01:39:18 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:19 DEBUG : Looking for writers
2026/05/25 01:39:19 DEBUG : file1: reading active writers
2026/05/25 01:39:19 DEBUG : file1: active writers 1
2026/05/25 01:39:19 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:20 DEBUG : Looking for writers
2026/05/25 01:39:20 DEBUG : file1: reading active writers
2026/05/25 01:39:20 DEBUG : file1: active writers 1
2026/05/25 01:39:20 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:21 DEBUG : Looking for writers
2026/05/25 01:39:21 DEBUG : file1: reading active writers
2026/05/25 01:39:21 DEBUG : file1: active writers 1
2026/05/25 01:39:21 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:22 DEBUG : Looking for writers
2026/05/25 01:39:22 DEBUG : file1: reading active writers
2026/05/25 01:39:22 DEBUG : file1: active writers 1
2026/05/25 01:39:22 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:23 DEBUG : Looking for writers
2026/05/25 01:39:23 DEBUG : file1: reading active writers
2026/05/25 01:39:23 DEBUG : file1: active writers 1
2026/05/25 01:39:23 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:24 DEBUG : Looking for writers
2026/05/25 01:39:24 DEBUG : file1: reading active writers
2026/05/25 01:39:24 DEBUG : file1: active writers 1
2026/05/25 01:39:24 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:25 DEBUG : Looking for writers
2026/05/25 01:39:25 DEBUG : file1: reading active writers
2026/05/25 01:39:25 DEBUG : file1: active writers 1
2026/05/25 01:39:25 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:26 DEBUG : Looking for writers
2026/05/25 01:39:26 DEBUG : file1: reading active writers
2026/05/25 01:39:26 DEBUG : file1: active writers 1
2026/05/25 01:39:26 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:27 DEBUG : Looking for writers
2026/05/25 01:39:27 DEBUG : file1: reading active writers
2026/05/25 01:39:27 DEBUG : file1: active writers 1
2026/05/25 01:39:27 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:28 DEBUG : Looking for writers
2026/05/25 01:39:28 DEBUG : file1: reading active writers
2026/05/25 01:39:28 DEBUG : file1: active writers 1
2026/05/25 01:39:28 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:29 DEBUG : Looking for writers
2026/05/25 01:39:29 DEBUG : file1: reading active writers
2026/05/25 01:39:29 DEBUG : file1: active writers 1
2026/05/25 01:39:29 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:30 DEBUG : Looking for writers
2026/05/25 01:39:30 DEBUG : file1: reading active writers
2026/05/25 01:39:30 DEBUG : file1: active writers 1
2026/05/25 01:39:30 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:31 DEBUG : Looking for writers
2026/05/25 01:39:31 DEBUG : file1: reading active writers
2026/05/25 01:39:31 DEBUG : file1: active writers 1
2026/05/25 01:39:31 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:32 DEBUG : Looking for writers
2026/05/25 01:39:32 DEBUG : file1: reading active writers
2026/05/25 01:39:32 DEBUG : file1: active writers 1
2026/05/25 01:39:32 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:33 DEBUG : Looking for writers
2026/05/25 01:39:33 DEBUG : file1: reading active writers
2026/05/25 01:39:33 DEBUG : file1: active writers 1
2026/05/25 01:39:33 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:34 DEBUG : Looking for writers
2026/05/25 01:39:34 DEBUG : file1: reading active writers
2026/05/25 01:39:34 DEBUG : file1: active writers 1
2026/05/25 01:39:34 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:35 DEBUG : Looking for writers
2026/05/25 01:39:35 DEBUG : file1: reading active writers
2026/05/25 01:39:35 DEBUG : file1: active writers 1
2026/05/25 01:39:35 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:36 DEBUG : Looking for writers
2026/05/25 01:39:36 DEBUG : file1: reading active writers
2026/05/25 01:39:36 DEBUG : file1: active writers 1
2026/05/25 01:39:36 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:37 DEBUG : Looking for writers
2026/05/25 01:39:37 DEBUG : file1: reading active writers
2026/05/25 01:39:37 DEBUG : file1: active writers 1
2026/05/25 01:39:37 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:38 DEBUG : Looking for writers
2026/05/25 01:39:38 DEBUG : file1: reading active writers
2026/05/25 01:39:38 DEBUG : file1: active writers 1
2026/05/25 01:39:38 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:39 DEBUG : Looking for writers
2026/05/25 01:39:39 DEBUG : file1: reading active writers
2026/05/25 01:39:39 DEBUG : file1: active writers 1
2026/05/25 01:39:39 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:40 DEBUG : Looking for writers
2026/05/25 01:39:40 DEBUG : file1: reading active writers
2026/05/25 01:39:40 DEBUG : file1: active writers 1
2026/05/25 01:39:40 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:41 DEBUG : Looking for writers
2026/05/25 01:39:41 DEBUG : file1: reading active writers
2026/05/25 01:39:41 DEBUG : file1: active writers 1
2026/05/25 01:39:41 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:42 DEBUG : Looking for writers
2026/05/25 01:39:42 DEBUG : file1: reading active writers
2026/05/25 01:39:42 DEBUG : file1: active writers 1
2026/05/25 01:39:42 DEBUG : Still 1 writers active and 0 cache items in use, waiting 1s
2026/05/25 01:39:42 ERROR : Exiting even though 1 writers active and 0 cache items in use after 30s
Cache: <nil>
2026/05/25 01:39:42 DEBUG : >WaitForWriters: 
--- FAIL: TestWriteFileModTimeWithOpenWriters (30.91s)
FAIL
2026/05/25 01:39:43 DEBUG : pcloud root 'rclone-test-henulat8pepe': Purge remote
"./vfs.test -test.v -test.timeout 1h0m0s -remote TestPcloud: -verbose -test.run '^(TestCaseSensitivity|TestWriteFileHandleRelease|TestWriteFileModTimeWithOpenWriters)$'" - Finished ERROR in 44.418903741s (try 2/5): exit status 1: Failed [TestWriteFileModTimeWithOpenWriters]