"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 2/5) 2026/04/07 05:36:10 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-volufil6deme" 2026/04/07 05:36:10 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/07 05:36:10 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-volufil6deme" 2026/04/07 05:36:10 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/38e8n6j409s52jghj2e20tcitmr6qir4er2drof6etp7btr8vbqg" 2026/04/07 05:36:10 DEBUG : Creating backend with remote "/tmp/rclone709278343" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-volufil6deme'", Local "Local file system at /tmp/rclone709278343", Modify Window "1ns" 2026/04/07 05:36:10 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-volufil6deme': poll-interval is not supported by this remote 2026/04/07 05:36:10 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-volufil6deme': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/07 05:36:10 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-volufil6deme': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-volufil6deme" 2026/04/07 05:36:10 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-volufil6deme': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-volufil6deme" 2026/04/07 05:36:10 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-volufil6deme" 2026/04/07 05:36:10 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/07 05:36:10 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-volufil6deme" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-volufil6deme" 2026/04/07 05:36:10 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-volufil6deme" 2026/04/07 05:36:10 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/07 05:36:10 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-volufil6deme" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-volufil6deme" 2026/04/07 05:36:10 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-volufil6deme': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 0caf359056189044b0d8e5361dc01644 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = f2d56431f0f200798b729c11b2b5024c OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 59b06935e473b95cde3ff392cba191ec OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 7bf58ddb601760b328b0a96dd4926e64 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 68cf5eec83b8c4ec249e3e5844b07a80 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 49ca466c18d8b427983e9a4b2a01a1f8 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = bb925569c58021bde1739f2720f892fe OK 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.001_459t5y: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.002_459t5y: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.003_459t5y: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.004_459t5y: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.005_459t5y: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.006_459t5y: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.007_459t5y: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 564249f26a501557e18c57482a16b488 OK 2026/04/07 05:36:10 DEBUG : forgetting directory cache 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb2bde00): _readAt: size=512, off=0 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb2bde00): openPending: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:37:10.123377729 +0000 UTC" against cached fingerprint "" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/07 05:36:10 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb2bde00): >openPending: err= 2026/04/07 05:36:10 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb2bde00): >_readAt: n=20, err=EOF 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb2bde00): close: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb2bde00): >close: err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 0625ce1a7432ec7d4cdac583b0a0d9b5 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = c4fae5de55d1e8a7e7ae0efd50a50440 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 481d62c4e1d0bfe565831966307becc7 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 4af7aaf749af03a2655901a1776dee6b OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 89d731af4b1cc496ad3ca2cc6f7bd3b9 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 2aa4723a3127f5e117bdb912b707a70c OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = e2d74fb4460a765b93f9a056ea473e79 OK 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.001_459tfn: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.002_459tfn: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.003_459tfn: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.004_459tfn: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.005_459tfn: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.006_459tfn: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.007_459tfn: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = d95f44773e27cb07640efc4098b9dff5 OK 2026/04/07 05:36:10 DEBUG : forgetting directory cache 2026/04/07 05:36:10 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb453140): _readAt: size=512, off=0 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb453140): openPending: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:38:10.123377729 +0000 UTC" against cached fingerprint "20,2026-04-07 04:37:10.123377729 +0000 UTC" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:38:10.123377729 +0000 UTC" != cached fingerprint "20,2026-04-07 04:37:10.123377729 +0000 UTC") 2026/04/07 05:36:10 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:10 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb453140): >openPending: err= 2026/04/07 05:36:10 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb453140): >_readAt: n=20, err=EOF 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb453140): close: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb453140): >close: err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = eaa61f77134f2126bb81b09d43ecd32b OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 19f7c94a0cac0aece59f0a03313a9a3e OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 3826ba2eb7642d941ba597992624d35d OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 0dd037c7789b620f4aa03b9cc254f7fc OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 489cb4c4eb8dcab98064c7a6b8ee0d9e OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = d38ffc70a99c40637c504f91dd861ecc OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 5840d3330d37a4c7f42197141cb2c6fc OK 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.001_459tm4: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.002_459tm4: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.003_459tm4: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.004_459tm4: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.005_459tm4: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.006_459tm4: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.007_459tm4: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = ad670a8f695b04ccd1312ba58572e916 OK 2026/04/07 05:36:10 DEBUG : forgetting directory cache 2026/04/07 05:36:10 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb4de540): _readAt: size=512, off=0 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb4de540): openPending: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:39:10.123377729 +0000 UTC" against cached fingerprint "20,2026-04-07 04:38:10.123377729 +0000 UTC" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:39:10.123377729 +0000 UTC" != cached fingerprint "20,2026-04-07 04:38:10.123377729 +0000 UTC") 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:10 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb4de540): >openPending: err= 2026/04/07 05:36:10 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb4de540): >_readAt: n=20, err=EOF 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb4de540): close: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb4de540): >close: err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = c4ac489c8e0500cdbc8e0a0412cb8bd8 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 0c810565cf8c405fbc5dc5a66e12d144 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = c9fd7108da89119e4b81eff08234c3e2 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 156d1f431252b6fbe56c38f6972c1e00 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 91dec8a7a27673684d93fce6ff542c7c OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = c2e640491bdb9aa85a3730751d3828be OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 57ae8ec7cb3d1b696eb062a5f567501f OK 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.001_459tin: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.002_459tin: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.003_459tin: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.004_459tin: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.005_459tin: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.006_459tin: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.007_459tin: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = e5245bb2d36f06a4f447a19e71e70f96 OK 2026/04/07 05:36:10 DEBUG : forgetting directory cache 2026/04/07 05:36:10 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb3f8240): _readAt: size=512, off=0 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb3f8240): openPending: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:40:10.123377729 +0000 UTC" against cached fingerprint "20,2026-04-07 04:39:10.123377729 +0000 UTC" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:40:10.123377729 +0000 UTC" != cached fingerprint "20,2026-04-07 04:39:10.123377729 +0000 UTC") 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:10 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb3f8240): >openPending: err= 2026/04/07 05:36:10 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb3f8240): >_readAt: n=20, err=EOF 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb3f8240): close: 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate(0x12a2fb3f8240): >close: err= 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = f4bc2182ecae4f54e52805f6073c7322 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 5d39fbbe00f5e80d2f5400080de13162 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = bb04363f29c20a8f19bf961bdd0ec94d OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 2e8607ca8835ea9e2e6b244c88322f38 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 9081613890de011a2d5ffcddfa5e955b OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 02478490eed9560a654ef8fe6de15567 OK 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 349eff24a176586c9b950a864c7f19df OK 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.001_459tyr: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.002_459tyr: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.003_459tyr: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.004_459tyr: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.005_459tyr: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.006_459tyr: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:10 INFO : TestRWCacheUpdate.rcc.007_459tyr: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:10 DEBUG : TestRWCacheUpdate: md5 = 678d3ae6470b09984a0480302f21d189 OK 2026/04/07 05:36:11 DEBUG : forgetting directory cache 2026/04/07 05:36:11 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9000): _readAt: size=512, off=0 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9000): openPending: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:41:10.123377729 +0000 UTC" against cached fingerprint "20,2026-04-07 04:40:10.123377729 +0000 UTC" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:41:10.123377729 +0000 UTC" != cached fingerprint "20,2026-04-07 04:40:10.123377729 +0000 UTC") 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:11 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9000): >openPending: err= 2026/04/07 05:36:11 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9000): >_readAt: n=20, err=EOF 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9000): close: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9000): >close: err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 4051975f1e91bd865ef49639413ddcd4 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = b5b6dcece778177bd2970501c4888ef1 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 57f2dc069255b20546240c238a0fde43 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 09115a0f5d2f6df0e865033e91f459e1 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = bce89cad9beea9c3348825264fb06c2c OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 0f0ad52f6f9e479fc2f1165cba0ca5af OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 5ea9640aa361afd3918d166824bfb107 OK 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.001_459uj9: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.002_459uj9: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.003_459uj9: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.004_459uj9: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.005_459uj9: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.006_459uj9: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.007_459uj9: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 1ed635a7f5ea22f64ed71370eeb8dc97 OK 2026/04/07 05:36:11 DEBUG : forgetting directory cache 2026/04/07 05:36:11 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9d40): _readAt: size=512, off=0 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9d40): openPending: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:42:10.123377729 +0000 UTC" against cached fingerprint "20,2026-04-07 04:41:10.123377729 +0000 UTC" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:42:10.123377729 +0000 UTC" != cached fingerprint "20,2026-04-07 04:41:10.123377729 +0000 UTC") 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:11 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9d40): >openPending: err= 2026/04/07 05:36:11 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9d40): >_readAt: n=20, err=EOF 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9d40): close: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb3f9d40): >close: err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 996b5f885fe168f7de0300d999d1d7be OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 620d29ee5a5cb0a095ab51b38301a74d OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = c94b6dcda49fe060123cf2b47f7183fd OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 61c7ec7ccd23a656d7dda2a080edd11d OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 44493fcbc1f9f65e30e6b62ae52b86a4 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 82109932ac997faa83edc6e735cbba5e OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 92e026a1ecca5a111f3455f7a5742d28 OK 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.001_459uzu: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.002_459uzu: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.003_459uzu: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.004_459uzu: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.005_459uzu: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.006_459uzu: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.007_459uzu: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 239d8917a175f0f1f1377050820daa9d OK 2026/04/07 05:36:11 DEBUG : forgetting directory cache 2026/04/07 05:36:11 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb4deb00): _readAt: size=512, off=0 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb4deb00): openPending: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-07 04:43:10.123377729 +0000 UTC" against cached fingerprint "20,2026-04-07 04:42:10.123377729 +0000 UTC" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-07 04:43:10.123377729 +0000 UTC" != cached fingerprint "20,2026-04-07 04:42:10.123377729 +0000 UTC") 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:11 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb4deb00): >openPending: err= 2026/04/07 05:36:11 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb4deb00): >_readAt: n=21, err=EOF 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb4deb00): close: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x12a2fb4deb00): >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/07 05:36:11 DEBUG : WaitForWriters: timeout=30s 2026/04/07 05:36:11 DEBUG : Looking for writers 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/07 05:36:11 DEBUG : >WaitForWriters: 2026/04/07 05:36:11 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-volufil6deme': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.45s) FAIL 2026/04/07 05:36:11 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-volufil6deme': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.601292585s (try 2/5): exit status 1: Failed [TestRWCacheUpdate]