"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 3/5) 2026/04/04 05:28:24 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-heponoz4nisu" 2026/04/04 05:28:24 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/04 05:28:24 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-heponoz4nisu" 2026/04/04 05:28:24 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/j7ni01eo277jb8hmb82enimsgrnhvmcls5ckv1506kdfaeujvitg" 2026/04/04 05:28:24 DEBUG : Creating backend with remote "/tmp/rclone474438049" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-heponoz4nisu'", Local "Local file system at /tmp/rclone474438049", Modify Window "1ns" 2026/04/04 05:28:24 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-heponoz4nisu': poll-interval is not supported by this remote 2026/04/04 05:28:24 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-heponoz4nisu': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/04 05:28:24 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-heponoz4nisu': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-heponoz4nisu" 2026/04/04 05:28:24 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-heponoz4nisu': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-heponoz4nisu" 2026/04/04 05:28:24 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-heponoz4nisu" 2026/04/04 05:28:24 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/04 05:28:24 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-heponoz4nisu" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-heponoz4nisu" 2026/04/04 05:28:24 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-heponoz4nisu" 2026/04/04 05:28:24 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/04 05:28:24 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-heponoz4nisu" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-heponoz4nisu" 2026/04/04 05:28:24 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-heponoz4nisu': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = b524b3d7ffc98c171d78ffba7dc1968c OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 8768cd565dfdebb0c8b1d40133ab79da OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 75d67533e2871d2e2ff90801ca273231 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 77958c4ec0106cd1e62c594f22e6a756 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 2b254d4bfaffa56bde4528c0ad9e2ca7 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = ede0870894dd343beb177c972f514be9 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = f0985459b9b54412e5e1ff2c76e0910a OK 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.001_ykwouv: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.002_ykwouv: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.003_ykwouv: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.004_ykwouv: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.005_ykwouv: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.006_ykwouv: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.007_ykwouv: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 2d686f528e10083bb1a2b2d017a51725 OK 2026/04/04 05:28:24 DEBUG : forgetting directory cache 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x748d2c39d80): _readAt: size=512, off=0 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x748d2c39d80): openPending: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:29:24.597594215 +0000 UTC" against cached fingerprint "" 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/04 05:28:24 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x748d2c39d80): >openPending: err= 2026/04/04 05:28:24 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x748d2c39d80): >_readAt: n=20, err=EOF 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x748d2c39d80): close: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x748d2c39d80): >close: err= 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 099fe3401d38b03d637b0ed1f29a65bc OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 56dbc74b274678cb0bf676217d59653d OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = ca3a0307aa19e82abbe69d2452e9ae4d OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = a237b46f20d2d1deb6162d48b6442da6 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 0d00d53b316094c64ed5d9617626d870 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = d101ea673095d5ac619d4fac755c72d3 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 6fb808cd336a3d8a470d2c89aae97c0f OK 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.001_ykwotl: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.002_ykwotl: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.003_ykwotl: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.004_ykwotl: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.005_ykwotl: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.006_ykwotl: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.007_ykwotl: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 03d279776c558aa754452f506bfd2de3 OK 2026/04/04 05:28:25 DEBUG : forgetting directory cache 2026/04/04 05:28:25 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2bc9700): _readAt: size=512, off=0 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2bc9700): openPending: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:30:24.597594215 +0000 UTC" against cached fingerprint "20,2026-04-04 04:29:24.597594215 +0000 UTC" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:30:24.597594215 +0000 UTC" != cached fingerprint "20,2026-04-04 04:29:24.597594215 +0000 UTC") 2026/04/04 05:28:25 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:25 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2bc9700): >openPending: err= 2026/04/04 05:28:25 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2bc9700): >_readAt: n=20, err=EOF 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2bc9700): close: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2bc9700): >close: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 3471b361459becd1a5886d0f4ec7fae5 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = e2a9d61171c47225e8c81c5b83e61eec OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = cb9b322de8410735a4bb1c33bfcbf0d7 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = b80d735ca954e7e5b476ed2c750ba47f OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = c3b1809f1f20cc1a12edae1f77427158 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 44e32219ba01692eafdb9dc04b8b8192 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 26e5dd05ab8609812a212f56f88c3071 OK 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.001_ykwp3g: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.002_ykwp3g: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.003_ykwp3g: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.004_ykwp3g: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.005_ykwp3g: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.006_ykwp3g: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.007_ykwp3g: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 1ddb06468a771f7f3ce6154cbc9a013f OK 2026/04/04 05:28:25 DEBUG : forgetting directory cache 2026/04/04 05:28:25 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8ea40): _readAt: size=512, off=0 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8ea40): openPending: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:31:24.597594215 +0000 UTC" against cached fingerprint "20,2026-04-04 04:30:24.597594215 +0000 UTC" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:31:24.597594215 +0000 UTC" != cached fingerprint "20,2026-04-04 04:30:24.597594215 +0000 UTC") 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:25 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8ea40): >openPending: err= 2026/04/04 05:28:25 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8ea40): >_readAt: n=20, err=EOF 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8ea40): close: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8ea40): >close: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = fb9465ae494bbf4c4cd7cbc32b1f4f75 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 4af6f1e2008b16937ae1cb2fbbcafbcf OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 991039e33bc804f1037518b90e6d195c OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = f483c0afeefbfb3462ea300af0d33dcd OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = c51f823e43dba6a3e3845f64b6ee3cad OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 64395592299cd9fe5ac870ff303c68e8 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = e492385fc433af3fe365515ec73aa53b OK 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.001_ykwp2s: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.002_ykwp2s: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.003_ykwp2s: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.004_ykwp2s: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.005_ykwp2s: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.006_ykwp2s: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.007_ykwp2s: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 9673b058e17f88573e1a87d1c3a7ece6 OK 2026/04/04 05:28:25 DEBUG : forgetting directory cache 2026/04/04 05:28:25 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8f780): _readAt: size=512, off=0 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8f780): openPending: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:32:24.597594215 +0000 UTC" against cached fingerprint "20,2026-04-04 04:31:24.597594215 +0000 UTC" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:32:24.597594215 +0000 UTC" != cached fingerprint "20,2026-04-04 04:31:24.597594215 +0000 UTC") 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:25 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8f780): >openPending: err= 2026/04/04 05:28:25 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8f780): >_readAt: n=20, err=EOF 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8f780): close: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2c8f780): >close: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = a930cb33513bc41c91691ff497077d66 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 9a2ab84ccaded1017331acdfdd45bab8 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = a2e8e841a923771249855d641e0ffc5e OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 85406654573e40c0cd9ae3d53437fdb5 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 248b52d7a6ab0bfae4baa6f028cca6af OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 87d503cfd874bdcaa55f2f3bdb6ea3a2 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 5fbe7f48df64dfb2d3892333be3cf95b OK 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.001_ykwplh: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.002_ykwplh: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.003_ykwplh: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.004_ykwplh: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.005_ykwplh: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.006_ykwplh: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.007_ykwplh: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 0170394f617c58ba82de7fb45dd52ffb OK 2026/04/04 05:28:25 DEBUG : forgetting directory cache 2026/04/04 05:28:25 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2b531c0): _readAt: size=512, off=0 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2b531c0): openPending: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:33:24.597594215 +0000 UTC" against cached fingerprint "20,2026-04-04 04:32:24.597594215 +0000 UTC" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:33:24.597594215 +0000 UTC" != cached fingerprint "20,2026-04-04 04:32:24.597594215 +0000 UTC") 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:25 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2b531c0): >openPending: err= 2026/04/04 05:28:25 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2b531c0): >_readAt: n=20, err=EOF 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2b531c0): close: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2b531c0): >close: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 055eedc8349888b982e6bc56b6d71428 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = e9c383c7a55e3af03c3bb091b3c4fe26 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = c4775fa80ba075c3124e8c2b5b54c392 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = f16836308ff4e590ec91f6b22117d64b OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 6b4c7c2f98c226e436bf5180cd9fb9b2 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 47fc75a13bd383031f14151d3e145012 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 63cd2737737f1560de8204dfb225ca2f OK 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.001_ykwp7z: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.002_ykwp7z: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.003_ykwp7z: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.004_ykwp7z: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.005_ykwp7z: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.006_ykwp7z: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.007_ykwp7z: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 04911bf0e24a261f09c4fae5478c7303 OK 2026/04/04 05:28:25 DEBUG : forgetting directory cache 2026/04/04 05:28:25 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2e20a00): _readAt: size=512, off=0 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2e20a00): openPending: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:34:24.597594215 +0000 UTC" against cached fingerprint "20,2026-04-04 04:33:24.597594215 +0000 UTC" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:34:24.597594215 +0000 UTC" != cached fingerprint "20,2026-04-04 04:33:24.597594215 +0000 UTC") 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:25 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2e20a00): >openPending: err= 2026/04/04 05:28:25 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2e20a00): >_readAt: n=20, err=EOF 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2e20a00): close: 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate(0x748d2e20a00): >close: err= 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 65da7ca627590180730ba64ab3489816 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = a8ed566d90647a6c39d4d80b32bdd8cf OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = ee859ce096ab8b3ced5810d5add30d71 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 8e6bfcec31969447fcb132447c68bc56 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 53edcace1e7505db4278a542aa8c8c81 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 1675d3c4b183efde0534478c44f2bae2 OK 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 802fcf363d90650c1162f23effa4f78c OK 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.001_ykwp4r: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.002_ykwp4r: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.003_ykwp4r: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.004_ykwp4r: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.005_ykwp4r: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.006_ykwp4r: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:25 INFO : TestRWCacheUpdate.rcc.007_ykwp4r: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:25 DEBUG : TestRWCacheUpdate: md5 = 5dc300b2a8e705ba285c71853d82ba7f OK 2026/04/04 05:28:26 DEBUG : forgetting directory cache 2026/04/04 05:28:26 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x748d2e21780): _readAt: size=512, off=0 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x748d2e21780): openPending: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-04 04:35:24.597594215 +0000 UTC" against cached fingerprint "20,2026-04-04 04:34:24.597594215 +0000 UTC" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-04 04:35:24.597594215 +0000 UTC" != cached fingerprint "20,2026-04-04 04:34:24.597594215 +0000 UTC") 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:26 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x748d2e21780): >openPending: err= 2026/04/04 05:28:26 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x748d2e21780): >_readAt: n=21, err=EOF 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x748d2e21780): close: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x748d2e21780): >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/04 05:28:26 DEBUG : WaitForWriters: timeout=30s 2026/04/04 05:28:26 DEBUG : Looking for writers 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/04 05:28:26 DEBUG : >WaitForWriters: 2026/04/04 05:28:26 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-heponoz4nisu': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.44s) FAIL 2026/04/04 05:28:26 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-heponoz4nisu': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.540107297s (try 3/5): exit status 1: Failed [TestRWCacheUpdate]