"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 3/5) 2026/04/05 03:28:35 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-pihomaf0xove" 2026/04/05 03:28:35 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/05 03:28:35 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-pihomaf0xove" 2026/04/05 03:28:35 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/tlk8do7poal98otsa585ul6u1avam0viphgvbgkb4b89vajp8rlg" 2026/04/05 03:28:35 DEBUG : Creating backend with remote "/tmp/rclone1333697891" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-pihomaf0xove'", Local "Local file system at /tmp/rclone1333697891", Modify Window "1ns" 2026/04/05 03:28:35 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-pihomaf0xove': poll-interval is not supported by this remote 2026/04/05 03:28:35 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pihomaf0xove': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/05 03:28:35 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pihomaf0xove': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-pihomaf0xove" 2026/04/05 03:28:35 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pihomaf0xove': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-pihomaf0xove" 2026/04/05 03:28:35 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-pihomaf0xove" 2026/04/05 03:28:35 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/05 03:28:35 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-pihomaf0xove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-pihomaf0xove" 2026/04/05 03:28:35 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-pihomaf0xove" 2026/04/05 03:28:35 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/05 03:28:35 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-pihomaf0xove" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-pihomaf0xove" 2026/04/05 03:28:35 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-pihomaf0xove': 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:35 DEBUG : TestRWCacheUpdate: md5 = 7bc6826d580e7318de408367d6114955 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 6da2ff59e1a7c255f07ed0fd5f9edf25 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 9232849c1bbe3d140e9126f190fc16cd OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 5eb0881051c71af38a8af2880a82c310 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = f8518722979b30ee6611cef0a27ced59 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 1aefe9bccc6f323453a2393aadf8c9c0 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 9a8e670788129622b8f9c4e23ba547f6 OK 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.001_0a16v0: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.002_0a16v0: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.003_0a16v0: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.004_0a16v0: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.005_0a16v0: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.006_0a16v0: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.007_0a16v0: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 4db8ba669be7bfc8a63361c94061af93 OK 2026/04/05 03:28:35 DEBUG : forgetting directory cache 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x299b7c940dc0): _readAt: size=512, off=0 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x299b7c940dc0): openPending: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:29:35.764541935 +0000 UTC" against cached fingerprint "" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/05 03:28:35 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x299b7c940dc0): >openPending: err= 2026/04/05 03:28:35 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x299b7c940dc0): >_readAt: n=20, err=EOF 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x299b7c940dc0): close: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x299b7c940dc0): >close: err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 5a479c12a50903c3aae0ca819182d4af OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 4d5bf4f1546f658fb43b92b0204b9790 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = dda17cee24a4170f0ea8faffaf7dac35 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 5cedcc1e5f2e9f0bc4afeb5d6d231ba9 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 8d13e636940714f2e0aebad10bfd699e OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 3281a7c8fdd08cc4aa5be1b8a59b8501 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 70886a56de2042005929fa65724f1925 OK 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.001_0a166p: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.002_0a166p: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.003_0a166p: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.004_0a166p: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.005_0a166p: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.006_0a166p: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.007_0a166p: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 0be0aab6c61519b2d140c075ee314366 OK 2026/04/05 03:28:36 DEBUG : forgetting directory cache 2026/04/05 03:28:36 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c941b40): _readAt: size=512, off=0 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c941b40): openPending: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:30:35.764541935 +0000 UTC" against cached fingerprint "20,2026-04-05 02:29:35.764541935 +0000 UTC" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:30:35.764541935 +0000 UTC" != cached fingerprint "20,2026-04-05 02:29:35.764541935 +0000 UTC") 2026/04/05 03:28:36 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:36 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c941b40): >openPending: err= 2026/04/05 03:28:36 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c941b40): >_readAt: n=20, err=EOF 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c941b40): close: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c941b40): >close: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 3a274348555cdabd94975ea42879e8bc OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = ee5abc3a969317914162990773fe734a OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 9d17346ad935d23048da68ae8adaec9a OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = c9d92638ca13b6b3454c3f3224e3216c OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 9a1c82ab2ad470434c7b94b6845bfb16 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 9c2d674c55f95162ad9ce5daec7798cc OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 6ecaad26c4451a3a2a2e6381cc8bbdb8 OK 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.001_0a175b: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.002_0a175b: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.003_0a175b: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.004_0a175b: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.005_0a175b: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.006_0a175b: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.007_0a175b: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = e6de6fbd998dffc8fb8dbd3572cccb69 OK 2026/04/05 03:28:36 DEBUG : forgetting directory cache 2026/04/05 03:28:36 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c477c40): _readAt: size=512, off=0 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c477c40): openPending: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:31:35.764541935 +0000 UTC" against cached fingerprint "20,2026-04-05 02:30:35.764541935 +0000 UTC" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:31:35.764541935 +0000 UTC" != cached fingerprint "20,2026-04-05 02:30:35.764541935 +0000 UTC") 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:36 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c477c40): >openPending: err= 2026/04/05 03:28:36 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c477c40): >_readAt: n=20, err=EOF 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c477c40): close: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c477c40): >close: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = c071a5e7d7dda89ab75549de8ab07d47 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = e8c278fb8bfc5a123bcae62f0ef7735e OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = a49ea9d1989e9d0bbb19b7201cad96ac OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = a112b50709738b84a06e2e8821e3c4e0 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 569c81f7a6aff2ddcd31000586dc3e4c OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 0e9825e0e9bcad70bf63443214439b35 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 5866b0d8ee5558c4707236e041057efe OK 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.001_0a178g: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.002_0a178g: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.003_0a178g: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.004_0a178g: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.005_0a178g: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.006_0a178g: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.007_0a178g: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 85fb64d0f554a5d4d5b73353fe8f9cf4 OK 2026/04/05 03:28:36 DEBUG : forgetting directory cache 2026/04/05 03:28:36 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c1dfe00): _readAt: size=512, off=0 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c1dfe00): openPending: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:32:35.764541935 +0000 UTC" against cached fingerprint "20,2026-04-05 02:31:35.764541935 +0000 UTC" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:32:35.764541935 +0000 UTC" != cached fingerprint "20,2026-04-05 02:31:35.764541935 +0000 UTC") 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:36 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c1dfe00): >openPending: err= 2026/04/05 03:28:36 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c1dfe00): >_readAt: n=20, err=EOF 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c1dfe00): close: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7c1dfe00): >close: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = d7872ddc2ee9dca900c013855de5474f OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = f32bcd1d76b086a76c9a7d63bfb61769 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 38d287d378e535765209f6e1ba5cb7a5 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 658ae97ad3bff6e001352fe8563a0303 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = fe1a9afe50f036cc391e9c26f0c3b569 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 14e714f186bd88b0bb0e65763a3d974d OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 24570d65a7bb645cc2b6071fec29cec8 OK 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.001_0a17ma: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.002_0a17ma: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.003_0a17ma: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.004_0a17ma: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.005_0a17ma: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.006_0a17ma: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.007_0a17ma: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 0c3f6278c29fcadb996394fd21dd0918 OK 2026/04/05 03:28:36 DEBUG : forgetting directory cache 2026/04/05 03:28:36 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0ec80): _readAt: size=512, off=0 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0ec80): openPending: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:33:35.764541935 +0000 UTC" against cached fingerprint "20,2026-04-05 02:32:35.764541935 +0000 UTC" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:33:35.764541935 +0000 UTC" != cached fingerprint "20,2026-04-05 02:32:35.764541935 +0000 UTC") 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:36 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0ec80): >openPending: err= 2026/04/05 03:28:36 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0ec80): >_readAt: n=20, err=EOF 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0ec80): close: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0ec80): >close: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = a8c4339d046beec9321e97b27afabf8b OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 006b346f6bb64cb4528a1e56e1d6063c OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 3eb20ea4bbab047ae981b108084b073a OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 8baadd696d9ad58fde4873c898d356dc OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = b103ab0b1ecc4b62d4e09402fa3630da OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = a32b549b4d4a9c34a6bdfc4dfc6c6e4c OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 0f4e797486891e3066edf44ebd557894 OK 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.001_0a17xx: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.002_0a17xx: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.003_0a17xx: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.004_0a17xx: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.005_0a17xx: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.006_0a17xx: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:36 INFO : TestRWCacheUpdate.rcc.007_0a17xx: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 9f0756ae8fb3f5ac9ba71ce148decc29 OK 2026/04/05 03:28:36 DEBUG : forgetting directory cache 2026/04/05 03:28:36 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0f9c0): _readAt: size=512, off=0 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0f9c0): openPending: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:34:35.764541935 +0000 UTC" against cached fingerprint "20,2026-04-05 02:33:35.764541935 +0000 UTC" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:34:35.764541935 +0000 UTC" != cached fingerprint "20,2026-04-05 02:33:35.764541935 +0000 UTC") 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:36 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0f9c0): >openPending: err= 2026/04/05 03:28:36 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0f9c0): >_readAt: n=20, err=EOF 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0f9c0): close: 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate(0x299b7dc0f9c0): >close: err= 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = d2e8891465cb0c9a753141331a48ce96 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 2d334a974c0337260fed949d1b951df6 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = ba28ebcebc32d609ef50c60d128c9e83 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 16539d20c47ab54cefcfc55bbbffd03b OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 5529aa81df5de6d4a7d471a2af62ba97 OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = ec92c14cf4b4418624a371ffb666139c OK 2026/04/05 03:28:36 DEBUG : TestRWCacheUpdate: md5 = 0620b19bf64166eb61083835f8474d88 OK 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.001_0a179x: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.002_0a179x: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.003_0a179x: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.004_0a179x: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.005_0a179x: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.006_0a179x: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:37 INFO : TestRWCacheUpdate.rcc.007_0a179x: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: md5 = ca48e4ccc377a919eb76d22e0632f6c9 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(0x299b7ddd2800): _readAt: size=512, off=0 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x299b7ddd2800): openPending: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-05 02:35:35.764541935 +0000 UTC" against cached fingerprint "20,2026-04-05 02:34:35.764541935 +0000 UTC" 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-05 02:35:35.764541935 +0000 UTC" != cached fingerprint "20,2026-04-05 02:34:35.764541935 +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(0x299b7ddd2800): >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: Size has changed from 20 to 21 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x299b7ddd2800): >_readAt: n=21, err=EOF 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x299b7ddd2800): close: 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate(0x299b7ddd2800): >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:37 DEBUG : WaitForWriters: timeout=30s 2026/04/05 03:28:37 DEBUG : Looking for writers 2026/04/05 03:28:37 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/05 03:28:37 DEBUG : >WaitForWriters: 2026/04/05 03:28:37 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pihomaf0xove': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.44s) FAIL 2026/04/05 03:28:37 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pihomaf0xove': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.578716537s (try 3/5): exit status 1: Failed [TestRWCacheUpdate]