"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 5/5) 2026/04/06 04:56:28 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-zadubir1dula" 2026/04/06 04:56:28 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/06 04:56:28 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-zadubir1dula" 2026/04/06 04:56:28 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/u7qg8v3raas1vgm85scpbnvdo1qahqkcfomhsrkgpchcn85peu8g" 2026/04/06 04:56:28 DEBUG : Creating backend with remote "/tmp/rclone647080771" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-zadubir1dula'", Local "Local file system at /tmp/rclone647080771", Modify Window "1ns" 2026/04/06 04:56:28 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-zadubir1dula': poll-interval is not supported by this remote 2026/04/06 04:56:28 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-zadubir1dula': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/06 04:56:28 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-zadubir1dula': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-zadubir1dula" 2026/04/06 04:56:28 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-zadubir1dula': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-zadubir1dula" 2026/04/06 04:56:28 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-zadubir1dula" 2026/04/06 04:56:28 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/06 04:56:28 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-zadubir1dula" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-zadubir1dula" 2026/04/06 04:56:28 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-zadubir1dula" 2026/04/06 04:56:28 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/06 04:56:28 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-zadubir1dula" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-zadubir1dula" 2026/04/06 04:56:28 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-zadubir1dula': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = cf03ac3c22b783beb3765cfe3aaffc09 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = a8d52d605827ce99162a9b30f6ae189f OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = fd64ac16828eaaa2a5e4f5a4e8ad2139 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = bafaccc6a7cefc9a7df38c4dfe227403 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 25f9e78b2d0abf4365546d5a8eb2a0da OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = eb58cc49793ea971f7d319d53847b7a5 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 5def164a15e04da2760e3af9eccf88ba OK 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.001_28rnwe: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.002_28rnwe: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.003_28rnwe: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.004_28rnwe: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.005_28rnwe: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.006_28rnwe: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.007_28rnwe: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 19e8d2ea0bcd5b6ee85b328324b53302 OK 2026/04/06 04:56:28 DEBUG : forgetting directory cache 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x3fa18a577a00): _readAt: size=512, off=0 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x3fa18a577a00): openPending: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:57:28.705899517 +0000 UTC" against cached fingerprint "" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/06 04:56:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x3fa18a577a00): >openPending: err= 2026/04/06 04:56:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x3fa18a577a00): >_readAt: n=20, err=EOF 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x3fa18a577a00): close: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x3fa18a577a00): >close: err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 9c0390130b3cf87e082e3aac872997cb OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = ce1e92a61a3753bbeb4212f72e3af1a0 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 03ee8e28690a26b890a960c0382a1254 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = c677a692ae86fbd42ba5912f0d63da38 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = a305185fd9500c39ab3d1d60d5e539d7 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = cc4d174b4fb76c43adda0b4078d16100 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 5d0a0c2a2d9bcc21e07c9ad2da7f4c2b OK 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.001_28rnq5: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.002_28rnq5: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.003_28rnq5: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.004_28rnq5: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.005_28rnq5: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.006_28rnq5: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.007_28rnq5: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = feeb59d84f8ae0894ac2a3c7cfb27e10 OK 2026/04/06 04:56:29 DEBUG : forgetting directory cache 2026/04/06 04:56:29 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa600c0): _readAt: size=512, off=0 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa600c0): openPending: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:58:28.705899517 +0000 UTC" against cached fingerprint "20,2026-04-06 03:57:28.705899517 +0000 UTC" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 03:58:28.705899517 +0000 UTC" != cached fingerprint "20,2026-04-06 03:57:28.705899517 +0000 UTC") 2026/04/06 04:56:29 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:29 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa600c0): >openPending: err= 2026/04/06 04:56:29 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa600c0): >_readAt: n=20, err=EOF 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa600c0): close: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa600c0): >close: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 5fe5510210213b44ab056d2f3ea0a335 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 2ee831fd9ceb0f608e8576a3d50a066a OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 6b7437f827026e064bb210641bb9fd9e OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = ba1eaf7f8d17fff177826f60d0dc1b35 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = c597821ae9a801097f92ae1152bed193 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = dc9f15176a6ec22b24086cae8ca60a07 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 2a2bf0716e97537ba401bc299d74fabe OK 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.001_28roah: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.002_28roah: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.003_28roah: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.004_28roah: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.005_28roah: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.006_28roah: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.007_28roah: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = fd7ab9dac4305b1683fbcb5d0124f401 OK 2026/04/06 04:56:29 DEBUG : forgetting directory cache 2026/04/06 04:56:29 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa618c0): _readAt: size=512, off=0 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa618c0): openPending: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:59:28.705899517 +0000 UTC" against cached fingerprint "20,2026-04-06 03:58:28.705899517 +0000 UTC" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 03:59:28.705899517 +0000 UTC" != cached fingerprint "20,2026-04-06 03:58:28.705899517 +0000 UTC") 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:29 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa618c0): >openPending: err= 2026/04/06 04:56:29 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa618c0): >_readAt: n=20, err=EOF 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa618c0): close: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18aa618c0): >close: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 3f3acd9d65c6811f5597ba8e91438ad8 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = f5297bf8a032c03451b5011ae0af4aeb OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = cb9bb60b6d40cc2827302698d34b9b5f OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 10fdbf4860d3aae21dc06a0690380ca1 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 8ec9cf125462c66e2284d5b8ea825602 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 6e6f49952800dc39c00901bcb00ba5aa OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = f2b57940e20971a90ced95ceac54b9ae OK 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.001_28ron0: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.002_28ron0: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.003_28ron0: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.004_28ron0: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.005_28ron0: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.006_28ron0: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.007_28ron0: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = f18d7b824d4b0dd26e22e16fbc2bf8d0 OK 2026/04/06 04:56:29 DEBUG : forgetting directory cache 2026/04/06 04:56:29 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8180): _readAt: size=512, off=0 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8180): openPending: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:00:28.705899517 +0000 UTC" against cached fingerprint "20,2026-04-06 03:59:28.705899517 +0000 UTC" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:00:28.705899517 +0000 UTC" != cached fingerprint "20,2026-04-06 03:59:28.705899517 +0000 UTC") 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:29 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8180): >openPending: err= 2026/04/06 04:56:29 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8180): >_readAt: n=20, err=EOF 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8180): close: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8180): >close: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 6abc2f79d33c04669663c35f4143cd97 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 74c17d3e0f81bdf09b9efbde8e5df3ea OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 26d7cbdd7080d1c728fbd899c408b1b5 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = f3ecce4e7279a22299a128f78a585b97 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 76717fc675c3c4959183da2d5a9304a9 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = d4a288c38dca175cf7d806c97fd0e9d8 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 00951292b2ab00517f6ea1c0cd045c7e OK 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.001_28rovj: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.002_28rovj: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.003_28rovj: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.004_28rovj: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.005_28rovj: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.006_28rovj: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.007_28rovj: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = a405a9b26dcd4640cb69810392696752 OK 2026/04/06 04:56:29 DEBUG : forgetting directory cache 2026/04/06 04:56:29 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8ec0): _readAt: size=512, off=0 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8ec0): openPending: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:01:28.705899517 +0000 UTC" against cached fingerprint "20,2026-04-06 04:00:28.705899517 +0000 UTC" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:01:28.705899517 +0000 UTC" != cached fingerprint "20,2026-04-06 04:00:28.705899517 +0000 UTC") 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:29 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8ec0): >openPending: err= 2026/04/06 04:56:29 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8ec0): >_readAt: n=20, err=EOF 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8ec0): close: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef8ec0): >close: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 0d6d986711371f855287eb66315d222b OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 2b668bacb5bf568f3e5742c6a3ba385d OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 2e2820246b1f124fb942ebcf0f78a2e9 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = dc8b89f469bf346327ea38ec3571c49d OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 3fec7c7e1565fca0665fff6d18cb851e OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 44e44ada85caa150725175ff0a22800f OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 97d995d705612f2a3b30f4a17a07285e OK 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.001_28rogn: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.002_28rogn: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.003_28rogn: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.004_28rogn: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.005_28rogn: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.006_28rogn: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.007_28rogn: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 0f64b3bd2e370b8dcfe3ac8e6106845f OK 2026/04/06 04:56:29 DEBUG : forgetting directory cache 2026/04/06 04:56:29 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef9c00): _readAt: size=512, off=0 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef9c00): openPending: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:02:28.705899517 +0000 UTC" against cached fingerprint "20,2026-04-06 04:01:28.705899517 +0000 UTC" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:02:28.705899517 +0000 UTC" != cached fingerprint "20,2026-04-06 04:01:28.705899517 +0000 UTC") 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:29 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef9c00): >openPending: err= 2026/04/06 04:56:29 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef9c00): >_readAt: n=20, err=EOF 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef9c00): close: 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate(0x3fa18bef9c00): >close: err= 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 8bd66ad6f4082605e62ecb1c727786ce OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 01ec2faa5999270ce3c5b2b85093c630 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 167b7d1fbf899bbda8a82005ed65620e OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = d34e330bfd94599ff94cc9937f031a3e OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = 8db3898556f89960962643a16302d119 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = c4e2e81257cf47dcdef213b8638c18c4 OK 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = ac4f51fcb6215b44747ec08235126422 OK 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.001_28ro46: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.002_28ro46: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.003_28ro46: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.004_28ro46: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.005_28ro46: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.006_28ro46: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:29 INFO : TestRWCacheUpdate.rcc.007_28ro46: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:29 DEBUG : TestRWCacheUpdate: md5 = e0e3f80d2a5810befd142589977197f3 OK 2026/04/06 04:56:30 DEBUG : forgetting directory cache 2026/04/06 04:56:30 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate(0x3fa18c0b0a40): _readAt: size=512, off=0 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate(0x3fa18c0b0a40): openPending: 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-06 04:03:28.705899517 +0000 UTC" against cached fingerprint "20,2026-04-06 04:02:28.705899517 +0000 UTC" 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-06 04:03:28.705899517 +0000 UTC" != cached fingerprint "20,2026-04-06 04:02:28.705899517 +0000 UTC") 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:30 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate(0x3fa18c0b0a40): >openPending: err= 2026/04/06 04:56:30 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate(0x3fa18c0b0a40): >_readAt: n=21, err=EOF 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate(0x3fa18c0b0a40): close: 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate(0x3fa18c0b0a40): >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/06 04:56:30 DEBUG : WaitForWriters: timeout=30s 2026/04/06 04:56:30 DEBUG : Looking for writers 2026/04/06 04:56:30 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/06 04:56:30 DEBUG : >WaitForWriters: 2026/04/06 04:56:30 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-zadubir1dula': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.44s) FAIL 2026/04/06 04:56:30 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-zadubir1dula': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.537823899s (try 5/5): exit status 1: Failed [TestRWCacheUpdate]