"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 5/5) 2026/04/05 03:28:38 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-jaqutim0davi" 2026/04/05 03:28:38 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/05 03:28:38 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-jaqutim0davi" 2026/04/05 03:28:38 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/k4kcbvget1t600qtetmnfivsr46us9a1769nqjcaoe318im0ue4g" 2026/04/05 03:28:38 DEBUG : Creating backend with remote "/tmp/rclone1647464282" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-jaqutim0davi'", Local "Local file system at /tmp/rclone1647464282", Modify Window "1ns" 2026/04/05 03:28:38 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-jaqutim0davi': poll-interval is not supported by this remote 2026/04/05 03:28:38 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-jaqutim0davi': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/05 03:28:38 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-jaqutim0davi': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-jaqutim0davi" 2026/04/05 03:28:38 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-jaqutim0davi': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-jaqutim0davi" 2026/04/05 03:28:38 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-jaqutim0davi" 2026/04/05 03:28:38 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/05 03:28:38 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-jaqutim0davi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-jaqutim0davi" 2026/04/05 03:28:38 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-jaqutim0davi" 2026/04/05 03:28:38 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/05 03:28:38 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-jaqutim0davi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-jaqutim0davi" 2026/04/05 03:28:38 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-jaqutim0davi': 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:38 DEBUG : TestRWCacheUpdate: md5 = 2bda893e9b9150cfeb140447834a519e OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 1897dfdc5e3fe0ef43b405e89066e602 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 113934d69ce1a97bb16bbe0b4e318889 OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 05f5b488c999b2e7a61e61ce1fadf97f OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = eb5f49700bc7c5342bef8f268f37ceda OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 8072ccb98f0b9d4a53a5db614caad7da OK 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = 22253207a8ad8242f3061f6de7a95f0b OK 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.001_0a19i2: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.002_0a19i2: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.003_0a19i2: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.004_0a19i2: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.005_0a19i2: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.006_0a19i2: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:38 INFO : TestRWCacheUpdate.rcc.007_0a19i2: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:38 DEBUG : TestRWCacheUpdate: md5 = bc03bff5e12336fdef183a73c707a967 OK 2026/04/05 03:28:39 DEBUG : forgetting directory cache 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3aa8400): _readAt: size=512, off=0 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3aa8400): openPending: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:29:38.924827819 +0000 UTC" against cached fingerprint "" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/05 03:28:39 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3aa8400): >openPending: err= 2026/04/05 03:28:39 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3aa8400): >_readAt: n=20, err=EOF 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3aa8400): close: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3aa8400): >close: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 82a8231092b4bfc18a0869223258f3d0 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 273662e4b576647584b6f61aa2ea8387 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 49abec8eff5c12d2c65f193e6fe3dc8d OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 0fa325fe7c742c2ab2876f9e76cbd9fc OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = f7f08a78d4f95dc4e35aab10878b57fe OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 3e62fe54941a7734dabf9f109aefbcfb OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 6059fd03b68119008b20340b50a04f68 OK 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.001_0a1a2a: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.002_0a1a2a: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.003_0a1a2a: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.004_0a1a2a: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.005_0a1a2a: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.006_0a1a2a: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.007_0a1a2a: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 7a7101d81e04bdf89bbe694b517daefb OK 2026/04/05 03:28:39 DEBUG : forgetting directory cache 2026/04/05 03:28:39 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3baa600): _readAt: size=512, off=0 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3baa600): openPending: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:30:38.924827819 +0000 UTC" against cached fingerprint "20,2026-04-05 02:29:38.924827819 +0000 UTC" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:30:38.924827819 +0000 UTC" != cached fingerprint "20,2026-04-05 02:29:38.924827819 +0000 UTC") 2026/04/05 03:28:39 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:39 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3baa600): >openPending: err= 2026/04/05 03:28:39 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3baa600): >_readAt: n=20, err=EOF 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3baa600): close: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3baa600): >close: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 1e51a27a6a64decee9c0dd7a08caf541 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 96ac1ea0db28f08945c040876acd5552 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = c73b9c8c46af6335364b78217add4876 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = dd7d6e59af4d332f0f0eba82cc1374ad OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = c8071519e36ff646aa89dbcc75b9b9b7 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 5833ca8dd31ef40304d8ce10b5688dcb OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 5fb5e34e5cc0e1e84a89980d39d0d21f OK 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.001_0a1a99: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.002_0a1a99: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.003_0a1a99: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.004_0a1a99: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.005_0a1a99: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.006_0a1a99: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.007_0a1a99: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 05903da8c252a1a4f37a7c20a01dfe5e OK 2026/04/05 03:28:39 DEBUG : forgetting directory cache 2026/04/05 03:28:39 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3873640): _readAt: size=512, off=0 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3873640): openPending: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:31:38.924827819 +0000 UTC" against cached fingerprint "20,2026-04-05 02:30:38.924827819 +0000 UTC" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:31:38.924827819 +0000 UTC" != cached fingerprint "20,2026-04-05 02:30:38.924827819 +0000 UTC") 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:39 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3873640): >openPending: err= 2026/04/05 03:28:39 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3873640): >_readAt: n=20, err=EOF 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3873640): close: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3873640): >close: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = f4482d4ee732125daf39dacb121f6af9 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 0d668a6b3ecb7552681ba4c3232924a4 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 1077b5b2a302de47745521e305e8725b OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 21777e699d157dd85951ca0bcc192845 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = c2549ea424fe9aca593a8c25348349c9 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 7a4d1117d40f8c174fa0a969360619e3 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = cacc279dc9fedf66333df5b5e224ea5f OK 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.001_0a1a6e: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.002_0a1a6e: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.003_0a1a6e: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.004_0a1a6e: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.005_0a1a6e: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.006_0a1a6e: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.007_0a1a6e: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 5719341780dd4f8bf3cbab3d781d036d OK 2026/04/05 03:28:39 DEBUG : forgetting directory cache 2026/04/05 03:28:39 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3bab440): _readAt: size=512, off=0 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3bab440): openPending: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:32:38.924827819 +0000 UTC" against cached fingerprint "20,2026-04-05 02:31:38.924827819 +0000 UTC" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:32:38.924827819 +0000 UTC" != cached fingerprint "20,2026-04-05 02:31:38.924827819 +0000 UTC") 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:39 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3bab440): >openPending: err= 2026/04/05 03:28:39 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3bab440): >_readAt: n=20, err=EOF 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3bab440): close: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d3bab440): >close: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = b27ce8a1acaeffde918649e2d7202ec6 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 4738ac0007dfd24073f7be9259c60639 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 16c4affc72cd653f304f24a7c13f4607 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 1e8fe3f16b4bdcfa4c11ad3aeed686e2 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 371760afa176e3401645cfaa32118f73 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = be624481bba9c6cd5f05a74212de1e01 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 973003553b55641a4ecdf53947ff8b53 OK 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.001_0a1afh: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.002_0a1afh: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.003_0a1afh: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.004_0a1afh: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.005_0a1afh: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.006_0a1afh: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.007_0a1afh: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 9c67419722b2af7dfcfa3b3adae47428 OK 2026/04/05 03:28:39 DEBUG : forgetting directory cache 2026/04/05 03:28:39 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d511a280): _readAt: size=512, off=0 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d511a280): openPending: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:33:38.924827819 +0000 UTC" against cached fingerprint "20,2026-04-05 02:32:38.924827819 +0000 UTC" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:33:38.924827819 +0000 UTC" != cached fingerprint "20,2026-04-05 02:32:38.924827819 +0000 UTC") 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:39 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d511a280): >openPending: err= 2026/04/05 03:28:39 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d511a280): >_readAt: n=20, err=EOF 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d511a280): close: 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate(0xcc6d511a280): >close: err= 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = cb9c25bcba0e874a56b611854bdd09a3 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = f6f0ca1d249cae0238709efecc5fd3d7 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 59f09e40c6172751bfe3cd93ba226e77 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = 4f2712851d7d03f21007b465b14853ff OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = abec43c92f26ee6cd81e1410ffb8292f OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = ab1eda513dc36f0fb3258eee91ed5387 OK 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = d3164dfacea418a0e106e87248bbcfec OK 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.001_0a1am6: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.002_0a1am6: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.003_0a1am6: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.004_0a1am6: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.005_0a1am6: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.006_0a1am6: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:39 INFO : TestRWCacheUpdate.rcc.007_0a1am6: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:39 DEBUG : TestRWCacheUpdate: md5 = a96aae17b293aaae90f5e64267aad247 OK 2026/04/05 03:28:40 DEBUG : forgetting directory cache 2026/04/05 03:28:40 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d511afc0): _readAt: size=512, off=0 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d511afc0): openPending: 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:34:38.924827819 +0000 UTC" against cached fingerprint "20,2026-04-05 02:33:38.924827819 +0000 UTC" 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:34:38.924827819 +0000 UTC" != cached fingerprint "20,2026-04-05 02:33:38.924827819 +0000 UTC") 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:40 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d511afc0): >openPending: err= 2026/04/05 03:28:40 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d511afc0): >_readAt: n=20, err=EOF 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d511afc0): close: 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d511afc0): >close: err= 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: md5 = b88cace41b92850c4728ee5da69dcff3 OK 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: md5 = dbc84d7fa931aba64284845fab4c58dd OK 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: md5 = eefb47f1b3103ef3b137f88a954367d2 OK 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: md5 = 02fce281280e1fde2522e9d2da3d7fcb OK 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: md5 = df7f9cc217eceb6c785f8e55655fb734 OK 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: md5 = 8819d93e60796ca6a5f6ef4bbf3141a7 OK 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: md5 = 1d99beb8e5e4840d8bcbf58263204752 OK 2026/04/05 03:28:40 INFO : TestRWCacheUpdate.rcc.001_0a1btw: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:40 INFO : TestRWCacheUpdate.rcc.002_0a1btw: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:40 INFO : TestRWCacheUpdate.rcc.003_0a1btw: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:40 INFO : TestRWCacheUpdate.rcc.004_0a1btw: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:40 INFO : TestRWCacheUpdate.rcc.005_0a1btw: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:40 INFO : TestRWCacheUpdate.rcc.006_0a1btw: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:40 INFO : TestRWCacheUpdate.rcc.007_0a1btw: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: md5 = dcd37ce7ea548e64845f7adec5843da8 OK 2026/04/05 03:28:40 DEBUG : forgetting directory cache 2026/04/05 03:28:40 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d3873c40): _readAt: size=512, off=0 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d3873c40): openPending: 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-05 02:35:38.924827819 +0000 UTC" against cached fingerprint "20,2026-04-05 02:34:38.924827819 +0000 UTC" 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-05 02:35:38.924827819 +0000 UTC" != cached fingerprint "20,2026-04-05 02:34:38.924827819 +0000 UTC") 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:40 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d3873c40): >openPending: err= 2026/04/05 03:28:40 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d3873c40): >_readAt: n=21, err=EOF 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d3873c40): close: 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate(0xcc6d3873c40): >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:40 DEBUG : WaitForWriters: timeout=30s 2026/04/05 03:28:40 DEBUG : Looking for writers 2026/04/05 03:28:40 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/05 03:28:40 DEBUG : >WaitForWriters: 2026/04/05 03:28:40 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-jaqutim0davi': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.45s) FAIL 2026/04/05 03:28:40 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-jaqutim0davi': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.582000268s (try 5/5): exit status 1: Failed [TestRWCacheUpdate]