"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 5/5) 2026/04/04 05:28:27 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-xejibum0cuga" 2026/04/04 05:28:27 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/04 05:28:27 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-xejibum0cuga" 2026/04/04 05:28:27 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/a6fh0i2l1j6bs8uvruoksp286upmqv2fq955fm49s9ir7bj3adc0" 2026/04/04 05:28:27 DEBUG : Creating backend with remote "/tmp/rclone2344569621" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-xejibum0cuga'", Local "Local file system at /tmp/rclone2344569621", Modify Window "1ns" 2026/04/04 05:28:27 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-xejibum0cuga': poll-interval is not supported by this remote 2026/04/04 05:28:27 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-xejibum0cuga': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/04 05:28:27 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-xejibum0cuga': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-xejibum0cuga" 2026/04/04 05:28:27 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-xejibum0cuga': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-xejibum0cuga" 2026/04/04 05:28:27 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-xejibum0cuga" 2026/04/04 05:28:27 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/04 05:28:27 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-xejibum0cuga" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-xejibum0cuga" 2026/04/04 05:28:27 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-xejibum0cuga" 2026/04/04 05:28:27 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/04 05:28:27 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-xejibum0cuga" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-xejibum0cuga" 2026/04/04 05:28:27 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-xejibum0cuga': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = ab3b4aec377089e68b546c0f79ee7490 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 90abc6cbef9a5220c4742af3a92b8321 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = aa2ebb0a9ae181f6dec6583fc7da7e7e OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = ad0ffebbde2e8807b8da7dee0f6e1591 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 17fb91ebb57c4481e772bacccfc19cb1 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 0d5876d4e515f9218c8a6b6cd7043216 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = c633febc6f2eef8543c8d2f865191563 OK 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.001_ykwryq: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.002_ykwryq: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.003_ykwryq: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.004_ykwryq: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.005_ykwryq: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.006_ykwryq: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.007_ykwryq: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = e4d00722bc5fdbddedf4380bedbb8936 OK 2026/04/04 05:28:27 DEBUG : forgetting directory cache 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x28fad06b19c0): _readAt: size=512, off=0 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x28fad06b19c0): openPending: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:29:27.744691095 +0000 UTC" against cached fingerprint "" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/04 05:28:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x28fad06b19c0): >openPending: err= 2026/04/04 05:28:27 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x28fad06b19c0): >_readAt: n=20, err=EOF 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x28fad06b19c0): close: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x28fad06b19c0): >close: err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = e11a7f8b9c1359713c1ebaef9fca441e OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 6ae9812db06874f63f56c386d8974744 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = a6a4205e4ed63428f56feecc27aef5dc OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = db604334c0288a6b7756fa8ac735c3f1 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 0cd7b567857a052e0a5646ffd3ae0209 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 83369006a40c4e171b6421195300a364 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = b9c17d91d88cc5695e1112dbbad27c2a OK 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.001_ykwrxi: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.002_ykwrxi: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.003_ykwrxi: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.004_ykwrxi: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.005_ykwrxi: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.006_ykwrxi: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.007_ykwrxi: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = a0a1df97c9e2427c9387e7f8dfdc10b4 OK 2026/04/04 05:28:28 DEBUG : forgetting directory cache 2026/04/04 05:28:28 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad0a0a780): _readAt: size=512, off=0 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad0a0a780): openPending: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:30:27.744691095 +0000 UTC" against cached fingerprint "20,2026-04-04 04:29:27.744691095 +0000 UTC" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:30:27.744691095 +0000 UTC" != cached fingerprint "20,2026-04-04 04:29:27.744691095 +0000 UTC") 2026/04/04 05:28:28 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad0a0a780): >openPending: err= 2026/04/04 05:28:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad0a0a780): >_readAt: n=20, err=EOF 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad0a0a780): close: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad0a0a780): >close: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 5b7f076af95eca158e3d4eddf5f14c7b OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 391b21693678221e00e1efee5a3c013d OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = d57b722a6419166ee5e12d6be60f0129 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = ff0397db109c0679ac02c678b915f5f9 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 785b9c1941add065ea2019123ad81dba OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 72c1a5eb2dea246a20d88cb801a12f87 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 69d2fd82d3f04f5fb27359102b5357a8 OK 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.001_ykws8m: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.002_ykws8m: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.003_ykws8m: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.004_ykws8m: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.005_ykws8m: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.006_ykws8m: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.007_ykws8m: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 90611cdec86eb9886ad70c20eb380a88 OK 2026/04/04 05:28:28 DEBUG : forgetting directory cache 2026/04/04 05:28:28 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad07b21c0): _readAt: size=512, off=0 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad07b21c0): openPending: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:31:27.744691095 +0000 UTC" against cached fingerprint "20,2026-04-04 04:30:27.744691095 +0000 UTC" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:31:27.744691095 +0000 UTC" != cached fingerprint "20,2026-04-04 04:30:27.744691095 +0000 UTC") 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad07b21c0): >openPending: err= 2026/04/04 05:28:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad07b21c0): >_readAt: n=20, err=EOF 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad07b21c0): close: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad07b21c0): >close: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = d381a93b36ad36d73eb4dd5c55ed2654 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 200ec87af86b92c2937f026151e309eb OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 9263e06e84a7a20ca8eef7f1541ec411 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = de64d5017391d0875a85d936093e7067 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 8a662250cee62e499140d87a83b51e97 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 85dd8277f53558577183cb74f6ac7b1a OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 84160efde31bcdd0f2dc0de61a4558c1 OK 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.001_ykws5x: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.002_ykws5x: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.003_ykws5x: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.004_ykws5x: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.005_ykws5x: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.006_ykws5x: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.007_ykws5x: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = f763566958043182c1e236f6b3935137 OK 2026/04/04 05:28:28 DEBUG : forgetting directory cache 2026/04/04 05:28:28 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e100c0): _readAt: size=512, off=0 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e100c0): openPending: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:32:27.744691095 +0000 UTC" against cached fingerprint "20,2026-04-04 04:31:27.744691095 +0000 UTC" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:32:27.744691095 +0000 UTC" != cached fingerprint "20,2026-04-04 04:31:27.744691095 +0000 UTC") 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e100c0): >openPending: err= 2026/04/04 05:28:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e100c0): >_readAt: n=20, err=EOF 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e100c0): close: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e100c0): >close: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 9576ed849359fdf811c814f7d51176fc OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 0792f395eeab933e64bf4493e2eebab5 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = e1cb0c12679b81eff2678a92a14266c8 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 2cbf03664fab9c7bacccebaee47d3589 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 0fa0eaeddeadedbb9da67480bbbc93f2 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 71b5a3090be99bd9d7bdfc673dcebde3 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = a0ff59aa04e51fd543edb5cc8df5e5a4 OK 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.001_ykwsqi: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.002_ykwsqi: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.003_ykwsqi: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.004_ykwsqi: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.005_ykwsqi: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.006_ykwsqi: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.007_ykwsqi: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = ef6886fba228dc469937e856bfc2ae40 OK 2026/04/04 05:28:28 DEBUG : forgetting directory cache 2026/04/04 05:28:28 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e10e00): _readAt: size=512, off=0 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e10e00): openPending: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:33:27.744691095 +0000 UTC" against cached fingerprint "20,2026-04-04 04:32:27.744691095 +0000 UTC" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:33:27.744691095 +0000 UTC" != cached fingerprint "20,2026-04-04 04:32:27.744691095 +0000 UTC") 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e10e00): >openPending: err= 2026/04/04 05:28:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e10e00): >_readAt: n=20, err=EOF 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e10e00): close: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e10e00): >close: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = ca1702cd95b643dfbfae4872813fb26a OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = d2187a8dbd9c62cf9e1e6cafbe8ddaa4 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 232cca4d0e1400a6fb4964ff007c9c9d OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 26ee07303630d2a8e0762196aedb94e4 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 300a139e08fbfef9c8cbbe124588586c OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 5ad2b6ad2a8237d0e3e071f12456207d OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 2a4825df06887f1ed6d4b12569033a13 OK 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.001_ykwshg: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.002_ykwshg: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.003_ykwshg: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.004_ykwshg: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.005_ykwshg: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.006_ykwshg: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.007_ykwshg: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 09eab19a8676ec3ee2b06dea4887b17f OK 2026/04/04 05:28:28 DEBUG : forgetting directory cache 2026/04/04 05:28:28 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e11b40): _readAt: size=512, off=0 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e11b40): openPending: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:34:27.744691095 +0000 UTC" against cached fingerprint "20,2026-04-04 04:33:27.744691095 +0000 UTC" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:34:27.744691095 +0000 UTC" != cached fingerprint "20,2026-04-04 04:33:27.744691095 +0000 UTC") 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e11b40): >openPending: err= 2026/04/04 05:28:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e11b40): >_readAt: n=20, err=EOF 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e11b40): close: 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate(0x28fad1e11b40): >close: err= 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 450f571314f4737cb8f15c3767258a17 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 93c9a58621216303e6f263318827b001 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 4a238853d9133e9e1038a2b062525863 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = 21e1087fdb7b35756dfe2466aba6398c OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = c16d252cacff703c8ffbe3ce2a7497c4 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = db167ec8f9fb9c9fc01da09e0286c8a9 OK 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = a70399eae81ec3c0e1d0081dfe8d0822 OK 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.001_ykwssl: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.002_ykwssl: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.003_ykwssl: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.004_ykwssl: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.005_ykwssl: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.006_ykwssl: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:28 INFO : TestRWCacheUpdate.rcc.007_ykwssl: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:28 DEBUG : TestRWCacheUpdate: md5 = ff9e6e56b50cfc17758c49aae8ba1d74 OK 2026/04/04 05:28:29 DEBUG : forgetting directory cache 2026/04/04 05:28:29 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate(0x28fad1fbc980): _readAt: size=512, off=0 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate(0x28fad1fbc980): openPending: 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-04 04:35:27.744691095 +0000 UTC" against cached fingerprint "20,2026-04-04 04:34:27.744691095 +0000 UTC" 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-04 04:35:27.744691095 +0000 UTC" != cached fingerprint "20,2026-04-04 04:34:27.744691095 +0000 UTC") 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:29 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate(0x28fad1fbc980): >openPending: err= 2026/04/04 05:28:29 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate(0x28fad1fbc980): >_readAt: n=21, err=EOF 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate(0x28fad1fbc980): close: 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate(0x28fad1fbc980): >close: err= read_write_test.go:752: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:752 Error: Not equal: expected: "TestRWCacheUpdate006*" actual : "TestRWCacheUpdate006\x00" Diff: --- Expected +++ Actual @@ -1 +1 @@ -TestRWCacheUpdate006* +TestRWCacheUpdate006 Test: TestRWCacheUpdate 2026/04/04 05:28:29 DEBUG : WaitForWriters: timeout=30s 2026/04/04 05:28:29 DEBUG : Looking for writers 2026/04/04 05:28:29 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/04 05:28:29 DEBUG : >WaitForWriters: 2026/04/04 05:28:29 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-xejibum0cuga': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.44s) FAIL 2026/04/04 05:28:29 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-xejibum0cuga': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.568696436s (try 5/5): exit status 1: Failed [TestRWCacheUpdate]