"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 2/5) 2026/04/06 04:56:24 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-januhur9zexo" 2026/04/06 04:56:24 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/06 04:56:24 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-januhur9zexo" 2026/04/06 04:56:24 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/8b19anvk3c1mtg39etjivoripg31s8f3p10vgsjl34f2m50p0p8g" 2026/04/06 04:56:24 DEBUG : Creating backend with remote "/tmp/rclone2432090702" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-januhur9zexo'", Local "Local file system at /tmp/rclone2432090702", Modify Window "1ns" 2026/04/06 04:56:24 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-januhur9zexo': poll-interval is not supported by this remote 2026/04/06 04:56:24 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-januhur9zexo': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/06 04:56:24 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-januhur9zexo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-januhur9zexo" 2026/04/06 04:56:24 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-januhur9zexo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-januhur9zexo" 2026/04/06 04:56:24 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-januhur9zexo" 2026/04/06 04:56:24 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/06 04:56:24 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-januhur9zexo" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-januhur9zexo" 2026/04/06 04:56:24 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-januhur9zexo" 2026/04/06 04:56:24 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/06 04:56:24 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-januhur9zexo" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-januhur9zexo" 2026/04/06 04:56:24 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-januhur9zexo': 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:24 DEBUG : TestRWCacheUpdate: md5 = a481662eacc5ba19c5d0d8144ec60d31 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = e51ed36a9ea47b35a84147640c8dc727 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = f6c811b1aaddffa33d2e00ee43e21be6 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = a079aed13da4dc9b01c69d7b330b55f3 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 8fb352551687fc12826e6a571285c7a2 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 5cda4d0fcd0c331e8eccba5e9839a038 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 4be6b58753f19143695d1ba2d2fe6244 OK 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.001_28rjqh: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.002_28rjqh: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.003_28rjqh: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.004_28rjqh: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.005_28rjqh: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.006_28rjqh: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.007_28rjqh: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = ea19a2ece12804786967a43c47523387 OK 2026/04/06 04:56:24 DEBUG : forgetting directory cache 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aa680): _readAt: size=512, off=0 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aa680): openPending: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:57:24.082806506 +0000 UTC" against cached fingerprint "" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/06 04:56:24 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aa680): >openPending: err= 2026/04/06 04:56:24 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aa680): >_readAt: n=20, err=EOF 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aa680): close: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aa680): >close: err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 915bd7c134e36d002dcd9ae72bd55102 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = b664bb031e4228266fdfe756d0b073e6 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 4f99379c59c247d685ddfb6fc92b4736 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 73674f08e6ebd51a2c766a57408088ad OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 8d8c9cedd094746a5cd613062f841895 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = e5a1803aec239be532eb47b16dab0281 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 187ca9a40586ccfa815bbda77a9aa97b OK 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.001_28rj9t: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.002_28rj9t: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.003_28rj9t: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.004_28rj9t: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.005_28rj9t: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.006_28rj9t: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.007_28rj9t: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 5317ce5702907672411f8ec4348b536d OK 2026/04/06 04:56:24 DEBUG : forgetting directory cache 2026/04/06 04:56:24 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f370ac40): _readAt: size=512, off=0 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f370ac40): openPending: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:58:24.082806506 +0000 UTC" against cached fingerprint "20,2026-04-06 03:57:24.082806506 +0000 UTC" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 03:58:24.082806506 +0000 UTC" != cached fingerprint "20,2026-04-06 03:57:24.082806506 +0000 UTC") 2026/04/06 04:56:24 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:24 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f370ac40): >openPending: err= 2026/04/06 04:56:24 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f370ac40): >_readAt: n=20, err=EOF 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f370ac40): close: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f370ac40): >close: err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 65317db3d20e1801ea716fa31d260eba OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 727e19d41c3f251bde5400cfa01765e9 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = d680865c6fb012797119bccb91fe75bb OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 9957eee46409cbd9a8d111c337ddccd2 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 0d4eaaa2e24daecfa1ae438234ef0719 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 9a9376157c886882a48c3eac63b0d5f8 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = a558dbb7b075b32a7b81a269825d400d OK 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.001_28rjjm: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.002_28rjjm: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.003_28rjjm: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.004_28rjjm: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.005_28rjjm: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.006_28rjjm: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.007_28rjjm: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = a1a10894500ae4a3a5ff302375af5bf8 OK 2026/04/06 04:56:24 DEBUG : forgetting directory cache 2026/04/06 04:56:24 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f35a3bc0): _readAt: size=512, off=0 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f35a3bc0): openPending: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:59:24.082806506 +0000 UTC" against cached fingerprint "20,2026-04-06 03:58:24.082806506 +0000 UTC" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 03:59:24.082806506 +0000 UTC" != cached fingerprint "20,2026-04-06 03:58:24.082806506 +0000 UTC") 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:24 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f35a3bc0): >openPending: err= 2026/04/06 04:56:24 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f35a3bc0): >_readAt: n=20, err=EOF 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f35a3bc0): close: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f35a3bc0): >close: err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = c6b26760c3fc807ee07707b98531e096 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 8193db7f2f71f42bd5585f964db4a70a OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 4a473c8f73fbdee36f48cfa595fd8825 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = bf53585438d8c3ba37566c4cf3d2cbc5 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = a7b7098b96abd04e1ec3775e1147218c OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 8155877166ae8a81cd34c111a9a0455b OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 7e6945a2a9a29e6c0cf1e62ab8172664 OK 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.001_28rjxy: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.002_28rjxy: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.003_28rjxy: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.004_28rjxy: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.005_28rjxy: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.006_28rjxy: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.007_28rjxy: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 78b011a2152e08a5fbc736b51404a2ca OK 2026/04/06 04:56:24 DEBUG : forgetting directory cache 2026/04/06 04:56:24 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aba80): _readAt: size=512, off=0 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aba80): openPending: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:00:24.082806506 +0000 UTC" against cached fingerprint "20,2026-04-06 03:59:24.082806506 +0000 UTC" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:00:24.082806506 +0000 UTC" != cached fingerprint "20,2026-04-06 03:59:24.082806506 +0000 UTC") 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:24 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aba80): >openPending: err= 2026/04/06 04:56:24 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aba80): >_readAt: n=20, err=EOF 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aba80): close: 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate(0x2937f31aba80): >close: err= 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 129daca890ed685fb97197af26a5f305 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 2612a745baf1236ca43c609a96e560f0 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = f2467b099ea60514d2227c09b7896494 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = cc64edc7cf6efc3e205fc97f80b76d9c OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 7e6802182056b6cd6ae077473079bed1 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 0eab400214752b6c1a1f964dde852679 OK 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = 084ec1f87d6bb27303302220be9b66a0 OK 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.001_28rjer: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.002_28rjer: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.003_28rjer: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.004_28rjer: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.005_28rjer: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.006_28rjer: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:24 INFO : TestRWCacheUpdate.rcc.007_28rjer: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:24 DEBUG : TestRWCacheUpdate: md5 = ed303a201d38fcbe8d2b1d4d3c7b9f5b OK 2026/04/06 04:56:25 DEBUG : forgetting directory cache 2026/04/06 04:56:25 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3434c40): _readAt: size=512, off=0 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3434c40): openPending: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:01:24.082806506 +0000 UTC" against cached fingerprint "20,2026-04-06 04:00:24.082806506 +0000 UTC" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:01:24.082806506 +0000 UTC" != cached fingerprint "20,2026-04-06 04:00:24.082806506 +0000 UTC") 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:25 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3434c40): >openPending: err= 2026/04/06 04:56:25 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3434c40): >_readAt: n=20, err=EOF 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3434c40): close: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3434c40): >close: err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = eabe351f673377f1dde8529ec7e7e7b8 OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 76bdfef558738b2bced56159fc6af2a6 OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 26fe5ca4ba96d7355861f159ddd77577 OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 317b8e44bd67d15174927830379228d0 OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 3d1b5d0c5bb728b8269c17c47291b451 OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 4ee7228fd23abc93b114f31c8de4151e OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = a25f59b852f54c91c97da0649e55038b OK 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.001_28rkiu: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.002_28rkiu: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.003_28rkiu: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.004_28rkiu: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.005_28rkiu: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.006_28rkiu: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.007_28rkiu: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = d30f189878e506cf95dacee2d9ad8eb2 OK 2026/04/06 04:56:25 DEBUG : forgetting directory cache 2026/04/06 04:56:25 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3435980): _readAt: size=512, off=0 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3435980): openPending: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:02:24.082806506 +0000 UTC" against cached fingerprint "20,2026-04-06 04:01:24.082806506 +0000 UTC" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:02:24.082806506 +0000 UTC" != cached fingerprint "20,2026-04-06 04:01:24.082806506 +0000 UTC") 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:25 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3435980): >openPending: err= 2026/04/06 04:56:25 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3435980): >_readAt: n=20, err=EOF 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3435980): close: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f3435980): >close: err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 682426a3cde37e2147c0d601052d3a9c OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = ea126c1596e48ef456d58d3a09121b99 OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 69f46539659de73b500d2dfb8e1c463f OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 683146d01ec7513dcab697b34ed50bd9 OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = f9c87af0b2ab81dafe7b7ac41c82948e OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 2c3f8abe76a0055d498082d4d8ae9bae OK 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 8263b1752c8dfe6af2085111e8a6a648 OK 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.001_28rkk8: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.002_28rkk8: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.003_28rkk8: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.004_28rkk8: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.005_28rkk8: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.006_28rkk8: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:25 INFO : TestRWCacheUpdate.rcc.007_28rkk8: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: md5 = 0cc07952b17ecbc039fb78dbfe76de9b OK 2026/04/06 04:56:25 DEBUG : forgetting directory cache 2026/04/06 04:56:25 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f4c6a880): _readAt: size=512, off=0 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f4c6a880): openPending: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-06 04:03:24.082806506 +0000 UTC" against cached fingerprint "20,2026-04-06 04:02:24.082806506 +0000 UTC" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-06 04:03:24.082806506 +0000 UTC" != cached fingerprint "20,2026-04-06 04:02:24.082806506 +0000 UTC") 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:25 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f4c6a880): >openPending: err= 2026/04/06 04:56:25 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f4c6a880): >_readAt: n=21, err=EOF 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f4c6a880): close: 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate(0x2937f4c6a880): >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:25 DEBUG : WaitForWriters: timeout=30s 2026/04/06 04:56:25 DEBUG : Looking for writers 2026/04/06 04:56:25 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/06 04:56:25 DEBUG : >WaitForWriters: 2026/04/06 04:56:25 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-januhur9zexo': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.44s) FAIL 2026/04/06 04:56:25 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-januhur9zexo': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.540075181s (try 2/5): exit status 1: Failed [TestRWCacheUpdate]