"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 4/5) 2026/04/05 03:28:37 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-guzuyeb7duwo" 2026/04/05 03:28:37 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/05 03:28:37 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-guzuyeb7duwo" 2026/04/05 03:28:37 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/g1ih8r3ptgta7bfqdade1g2umuabg04s8p38sria0jcno2off1ug" 2026/04/05 03:28:37 DEBUG : Creating backend with remote "/tmp/rclone853636466" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-guzuyeb7duwo'", Local "Local file system at /tmp/rclone853636466", Modify Window "1ns" 2026/04/05 03:28:37 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-guzuyeb7duwo': poll-interval is not supported by this remote 2026/04/05 03:28:37 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-guzuyeb7duwo': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/05 03:28:37 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-guzuyeb7duwo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-guzuyeb7duwo" 2026/04/05 03:28:37 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-guzuyeb7duwo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-guzuyeb7duwo" 2026/04/05 03:28:37 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-guzuyeb7duwo" 2026/04/05 03:28:37 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/05 03:28:37 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-guzuyeb7duwo" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-guzuyeb7duwo" 2026/04/05 03:28:37 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-guzuyeb7duwo" 2026/04/05 03:28:37 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/05 03:28:37 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-guzuyeb7duwo" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-guzuyeb7duwo" 2026/04/05 03:28:37 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-guzuyeb7duwo': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 51c9fd28563b6944cbc7f1633174363f OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = d7b6a5dd309cbc751666ea2b72e0a311 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 6207ca13cf0f589642f6d08e81bf0c54 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 317da6fef17fcdcbfc8298051fcc2793 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 42cf81db1c2dbf563c1a0f4d64f300e5 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = e96beb14be405050bbe37abb95147f8c OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = b7f3ba065d5b747f0f6e48f7eb77e57d OK 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.001_0a18f0: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.002_0a18f0: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.003_0a18f0: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.004_0a18f0: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.005_0a18f0: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.006_0a18f0: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.007_0a18f0: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 8b99af10b3d1633510baadb366fadaf1 OK 2026/04/05 03:28:37 DEBUG : forgetting directory cache 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8423b80): _readAt: size=512, off=0 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8423b80): openPending: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:29:37.337245087 +0000 UTC" against cached fingerprint "" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/05 03:28:37 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8423b80): >openPending: err= 2026/04/05 03:28:37 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8423b80): >_readAt: n=20, err=EOF 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8423b80): close: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8423b80): >close: err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 1b077cc6bff5858c61cbe49d07b0e8cb OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = a5236507e99659d0e2f780284c6699a6 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 451507bd022e5a4314f7f007c3447ea3 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 0182e3b7ca9381bcf1948434e450e6ab OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = ee9f207e778aa0b5720d594f4735d3e1 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 1041a4b34f3d4681a37c9d564b695d29 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = caca8470f9788b3c5bc699135288a962 OK 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.001_0a18b7: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.002_0a18b7: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.003_0a18b7: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.004_0a18b7: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.005_0a18b7: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.006_0a18b7: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.007_0a18b7: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 5d48cf78562333c1af7c30c78ca4ae5f OK 2026/04/05 03:28:37 DEBUG : forgetting directory cache 2026/04/05 03:28:37 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8118d40): _readAt: size=512, off=0 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8118d40): openPending: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:30:37.337245087 +0000 UTC" against cached fingerprint "20,2026-04-05 02:29:37.337245087 +0000 UTC" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:30:37.337245087 +0000 UTC" != cached fingerprint "20,2026-04-05 02:29:37.337245087 +0000 UTC") 2026/04/05 03:28:37 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:37 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8118d40): >openPending: err= 2026/04/05 03:28:37 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8118d40): >_readAt: n=20, err=EOF 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8118d40): close: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8118d40): >close: err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 5213c414f93d05f37bb57fd9e6511a3c OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 2be6f0aa3721551f2bdc315897801e6f OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = e7f965c7c0fe343b87630dab04b1f938 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = cd83bbd2a0916937e60ab47274fff77d OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 0444dabccb2af9527ec95bad582714ac OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 7d453cabe0f3fd4acfa0c310eb775a0a OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 62c93f630abcc50a2d376bc6dc4a4c41 OK 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.001_0a182u: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.002_0a182u: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.003_0a182u: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.004_0a182u: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.005_0a182u: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.006_0a182u: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.007_0a182u: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = ebd9932aafb385cd7a556fabf9b04650 OK 2026/04/05 03:28:37 DEBUG : forgetting directory cache 2026/04/05 03:28:37 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8119dc0): _readAt: size=512, off=0 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8119dc0): openPending: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:31:37.337245087 +0000 UTC" against cached fingerprint "20,2026-04-05 02:30:37.337245087 +0000 UTC" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:31:37.337245087 +0000 UTC" != cached fingerprint "20,2026-04-05 02:30:37.337245087 +0000 UTC") 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:37 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8119dc0): >openPending: err= 2026/04/05 03:28:37 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8119dc0): >_readAt: n=20, err=EOF 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8119dc0): close: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x19a1e8119dc0): >close: err= 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = bf9d59c003f9d6521760e843498074e3 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 76394667cb99552253a684687508cd3f OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 771186735244f11a51573682136271d0 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = c8736f20c5e4b1fbdf20a931c9d38f1e OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 920a9bc5a10ec8bd804c49355834ae96 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 5ece3bf5b00f6257b9b25a7e451d41a1 OK 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = 88c7c0288faaad93508bea4298e77103 OK 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.001_0a18f3: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.002_0a18f3: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.003_0a18f3: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.004_0a18f3: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.005_0a18f3: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.006_0a18f3: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.007_0a18f3: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = b321b5315b9bc261d01a29e7c38260c3 OK 2026/04/05 03:28:38 DEBUG : forgetting directory cache 2026/04/05 03:28:38 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e7f2f0c0): _readAt: size=512, off=0 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e7f2f0c0): openPending: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:32:37.337245087 +0000 UTC" against cached fingerprint "20,2026-04-05 02:31:37.337245087 +0000 UTC" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:32:37.337245087 +0000 UTC" != cached fingerprint "20,2026-04-05 02:31:37.337245087 +0000 UTC") 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:38 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e7f2f0c0): >openPending: err= 2026/04/05 03:28:38 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e7f2f0c0): >_readAt: n=20, err=EOF 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e7f2f0c0): close: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e7f2f0c0): >close: err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 4d55136daa11905348a0a87c931ddb69 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 1303623acd4a5e067e4b9704ceba492d OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 46236b86ea209d8cdb49cd40f075511f OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 741262a5cd5e0e204dd07839967cd1f2 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = f2d18cf24326356b16721f2034a45a03 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = dd87806a4f96bbc0da35a7c1a3942e17 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = f257a995cd198de1b7f3442e3c56cfca OK 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.001_0a196i: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.002_0a196i: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.003_0a196i: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.004_0a196i: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.005_0a196i: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.006_0a196i: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.007_0a196i: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 20a9fe5c20fd167c998d18c01a397541 OK 2026/04/05 03:28:38 DEBUG : forgetting directory cache 2026/04/05 03:28:38 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cc5c0): _readAt: size=512, off=0 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cc5c0): openPending: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:33:37.337245087 +0000 UTC" against cached fingerprint "20,2026-04-05 02:32:37.337245087 +0000 UTC" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:33:37.337245087 +0000 UTC" != cached fingerprint "20,2026-04-05 02:32:37.337245087 +0000 UTC") 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:38 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cc5c0): >openPending: err= 2026/04/05 03:28:38 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cc5c0): >_readAt: n=20, err=EOF 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cc5c0): close: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cc5c0): >close: err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 095189ac21cca1a1d300ce98fecda8cc OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 3eebc9a63308e7a469c4c81a6d1c11f7 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 0c8c1273dca81c42534adbfb5e2f484c OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = cdd804576fbca03a3bf66a8c64e37c4d OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 226a393f1504cb1eb32ae366bfd953be OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = b69d0e3f729cb94b7b0ea74a027df935 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 6695957f2cf7262aceaea9aad7751f4d OK 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.001_0a19be: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.002_0a19be: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.003_0a19be: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.004_0a19be: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.005_0a19be: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.006_0a19be: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.007_0a19be: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 83448c7cba4184ca7f9908e940c2daed OK 2026/04/05 03:28:38 DEBUG : forgetting directory cache 2026/04/05 03:28:38 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cd300): _readAt: size=512, off=0 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cd300): openPending: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:34:37.337245087 +0000 UTC" against cached fingerprint "20,2026-04-05 02:33:37.337245087 +0000 UTC" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:34:37.337245087 +0000 UTC" != cached fingerprint "20,2026-04-05 02:33:37.337245087 +0000 UTC") 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:38 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cd300): >openPending: err= 2026/04/05 03:28:38 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cd300): >_readAt: n=20, err=EOF 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cd300): close: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e97cd300): >close: err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = e5be556bb0b8ddd7e4cbb59a8ed784dc OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 4e8c6937206a62577361b17543f262a8 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = a6af872b69122a6eb85e36710666099a OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = ea1078e18def974b79e653cf079c57a6 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 9f5b965be62f8f9f51d622eae6fbb208 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 492835fa49d344d89a75c82489152bd3 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 37c120ea0a5ab749660aff68af25752a OK 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.001_0a198e: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.002_0a198e: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.003_0a198e: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.004_0a198e: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.005_0a198e: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.006_0a198e: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.007_0a198e: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 3d02b7ede30538943207ee807eb811e2 OK 2026/04/05 03:28:38 DEBUG : forgetting directory cache 2026/04/05 03:28:38 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e99ac140): _readAt: size=512, off=0 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e99ac140): openPending: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-05 02:35:37.337245087 +0000 UTC" against cached fingerprint "20,2026-04-05 02:34:37.337245087 +0000 UTC" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-05 02:35:37.337245087 +0000 UTC" != cached fingerprint "20,2026-04-05 02:34:37.337245087 +0000 UTC") 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:38 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e99ac140): >openPending: err= 2026/04/05 03:28:38 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e99ac140): >_readAt: n=21, err=EOF 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e99ac140): close: 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate(0x19a1e99ac140): >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/05 03:28:38 DEBUG : WaitForWriters: timeout=30s 2026/04/05 03:28:38 DEBUG : Looking for writers 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/05 03:28:38 DEBUG : >WaitForWriters: 2026/04/05 03:28:38 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-guzuyeb7duwo': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.45s) FAIL 2026/04/05 03:28:38 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-guzuyeb7duwo': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.583325691s (try 4/5): exit status 1: Failed [TestRWCacheUpdate]