"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 2/5) 2026/04/04 05:28:22 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-royiham5puyo" 2026/04/04 05:28:22 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/04 05:28:22 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-royiham5puyo" 2026/04/04 05:28:23 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/do8tv18qag4l2dvsmb9k7645gfb9h111f2f0m35a5s4t6psi9u8g" 2026/04/04 05:28:23 DEBUG : Creating backend with remote "/tmp/rclone2796563361" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-royiham5puyo'", Local "Local file system at /tmp/rclone2796563361", Modify Window "1ns" 2026/04/04 05:28:23 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-royiham5puyo': poll-interval is not supported by this remote 2026/04/04 05:28:23 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-royiham5puyo': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/04 05:28:23 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-royiham5puyo': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-royiham5puyo" 2026/04/04 05:28:23 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-royiham5puyo': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-royiham5puyo" 2026/04/04 05:28:23 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-royiham5puyo" 2026/04/04 05:28:23 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/04 05:28:23 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-royiham5puyo" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-royiham5puyo" 2026/04/04 05:28:23 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-royiham5puyo" 2026/04/04 05:28:23 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/04 05:28:23 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-royiham5puyo" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-royiham5puyo" 2026/04/04 05:28:23 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-royiham5puyo': 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:23 DEBUG : TestRWCacheUpdate: md5 = 706466bd9dfb1ebbd51144915d679e57 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = c8b5711f20f54b5f86d0a89ff34b30ab OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = ab99167b69b49f17d80ce8435efe9197 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = f58e0261f362f0d76a9244877272d2f6 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 06d104cf1061b24eee2b72ae6289b5cf OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 93907c67ceee56e71cc1533c48ea111c OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = a365cef7909c986c3dd9fc97525057cb OK 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.001_ykwn7n: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.002_ykwn7n: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.003_ykwn7n: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.004_ykwn7n: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.005_ykwn7n: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.006_ykwn7n: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.007_ykwn7n: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 9f500fc04d9f6d83abafc0c6897e069e OK 2026/04/04 05:28:23 DEBUG : forgetting directory cache 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c943cc380): _readAt: size=512, off=0 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c943cc380): openPending: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:29:23.057677274 +0000 UTC" against cached fingerprint "" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/04 05:28:23 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c943cc380): >openPending: err= 2026/04/04 05:28:23 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c943cc380): >_readAt: n=20, err=EOF 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c943cc380): close: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c943cc380): >close: err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 200e0324d7bde26de9bffd87d13f84bb OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = f051bd7e2d82590973ae7297392573e5 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 7718babe5cf1d7edccdd5db1fa258e9b OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 0154940bb50f2bfbb735b728a035db93 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = ba69545531737c2dbf574b691b098143 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = a2fe2d1b8ab64339c02b769264f87f93 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = b3ae53246e3f417cc790107eda406766 OK 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.001_ykwngu: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.002_ykwngu: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.003_ykwngu: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.004_ykwngu: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.005_ykwngu: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.006_ykwngu: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.007_ykwngu: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 8392b3e72a5218801845d7df1365f817 OK 2026/04/04 05:28:23 DEBUG : forgetting directory cache 2026/04/04 05:28:23 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c94182c80): _readAt: size=512, off=0 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c94182c80): openPending: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:30:23.057677274 +0000 UTC" against cached fingerprint "20,2026-04-04 04:29:23.057677274 +0000 UTC" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:30:23.057677274 +0000 UTC" != cached fingerprint "20,2026-04-04 04:29:23.057677274 +0000 UTC") 2026/04/04 05:28:23 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:23 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c94182c80): >openPending: err= 2026/04/04 05:28:23 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c94182c80): >_readAt: n=20, err=EOF 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c94182c80): close: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c94182c80): >close: err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 47ad82d8d9f821e72b7f77ebc03685f5 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 543040e75a87d7d26733b97e6a89df12 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 45727a4aa4852cf18a844494c0d07f74 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 927f6e60ba5d6d8befcc4d20bdc8c898 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = d18a992a7e1859033526049faa707363 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 85d966a1dabf7ea9a863924dd7210724 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 7c1e672d502dd33fbaa9d0f01ea54ec0 OK 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.001_ykwnlo: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.002_ykwnlo: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.003_ykwnlo: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.004_ykwnlo: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.005_ykwnlo: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.006_ykwnlo: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.007_ykwnlo: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = ba7690c1c3cd9319c01fec8e145667ac OK 2026/04/04 05:28:23 DEBUG : forgetting directory cache 2026/04/04 05:28:23 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c946d88c0): _readAt: size=512, off=0 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c946d88c0): openPending: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:31:23.057677274 +0000 UTC" against cached fingerprint "20,2026-04-04 04:30:23.057677274 +0000 UTC" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:31:23.057677274 +0000 UTC" != cached fingerprint "20,2026-04-04 04:30:23.057677274 +0000 UTC") 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:23 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c946d88c0): >openPending: err= 2026/04/04 05:28:23 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c946d88c0): >_readAt: n=20, err=EOF 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c946d88c0): close: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c946d88c0): >close: err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = ec116d8380cde2d33fcf13c41babafe4 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 1d501e29ce41f60624eb48face3881c5 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 2e5ef59fc18d2cadfe32ca7ebcfc74de OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 06e52253436254f6d23d89f87cbd6ce0 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = d29d50c5070ee19cfc4aa16bd4896f28 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = c57221cf410df9d3c8c902b1a0801152 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 84142809ac759906efeca407c0900d9c OK 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.001_ykwnhb: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.002_ykwnhb: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.003_ykwnhb: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.004_ykwnhb: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.005_ykwnhb: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.006_ykwnhb: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.007_ykwnhb: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 05bbbaf0363bd036a035f2eec7d47004 OK 2026/04/04 05:28:23 DEBUG : forgetting directory cache 2026/04/04 05:28:23 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c942ae740): _readAt: size=512, off=0 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c942ae740): openPending: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:32:23.057677274 +0000 UTC" against cached fingerprint "20,2026-04-04 04:31:23.057677274 +0000 UTC" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:32:23.057677274 +0000 UTC" != cached fingerprint "20,2026-04-04 04:31:23.057677274 +0000 UTC") 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:23 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c942ae740): >openPending: err= 2026/04/04 05:28:23 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c942ae740): >_readAt: n=20, err=EOF 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c942ae740): close: 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate(0x220c942ae740): >close: err= 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 5d2013bf78a26c75ba4cb69dd81e4cb5 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 9360910a1c265ac0ca98dab61e98e4ae OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 59d1673ce22521713244066730214c78 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = b5f1de30ab80089e98465058e976a955 OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 4580106f3771af6b09da04993d6145ae OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = a13e4b20987417805e2aff08badab7ea OK 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = 894267c2cee41bf201589791a9e05b7e OK 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.001_ykwn6h: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.002_ykwn6h: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.003_ykwn6h: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.004_ykwn6h: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.005_ykwn6h: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.006_ykwn6h: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:23 INFO : TestRWCacheUpdate.rcc.007_ykwn6h: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:23 DEBUG : TestRWCacheUpdate: md5 = e63d5adb0eea03d1bdc088bd229edc57 OK 2026/04/04 05:28:24 DEBUG : forgetting directory cache 2026/04/04 05:28:24 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 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(0x220c9461e340): _readAt: size=512, off=0 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c9461e340): openPending: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:33:23.057677274 +0000 UTC" against cached fingerprint "20,2026-04-04 04:32:23.057677274 +0000 UTC" 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:33:23.057677274 +0000 UTC" != cached fingerprint "20,2026-04-04 04:32:23.057677274 +0000 UTC") 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:24 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c9461e340): >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(0x220c9461e340): >_readAt: n=20, err=EOF 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c9461e340): close: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c9461e340): >close: err= 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 15bd9824d6a86401b289bf3bbbe12376 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = a11172c38d68f92b4b8a9d8003edbc9f OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = e4f356ec26938410699f5ff5d1e62fe9 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = ba4e941c984771dc984cffe3862667c5 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = e4bc30f0c759285950136619c26d1bd9 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 638f3cb5ce2857721f7dc07989e4e134 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 63486e331a6a5b417354b44573ce7b02 OK 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.001_ykwof5: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.002_ykwof5: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.003_ykwof5: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.004_ykwof5: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.005_ykwof5: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.006_ykwof5: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.007_ykwof5: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = f0707e89e16fe0d6fab5c47e5e353802 OK 2026/04/04 05:28:24 DEBUG : forgetting directory cache 2026/04/04 05:28:24 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 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(0x220c9461f100): _readAt: size=512, off=0 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c9461f100): openPending: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:34:23.057677274 +0000 UTC" against cached fingerprint "20,2026-04-04 04:33:23.057677274 +0000 UTC" 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:34:23.057677274 +0000 UTC" != cached fingerprint "20,2026-04-04 04:33:23.057677274 +0000 UTC") 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:24 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c9461f100): >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(0x220c9461f100): >_readAt: n=20, err=EOF 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c9461f100): close: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c9461f100): >close: err= 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 0c005dff725fe43ff10a20a7ce243b5b OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 81956f67e9e5c968a404d63697362308 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 841d2a637f0a571c294cc98b5e8cd560 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = ad2e74607fa615a46735b1cdac4135bc OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 809cb7af95a3e478422f06c657947ae9 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 3ffef699887bd8c195cc40f2e9865479 OK 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 463ae4f9721f970cc0b5fdf843d0ec09 OK 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.001_ykwobv: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.002_ykwobv: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.003_ykwobv: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.004_ykwobv: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.005_ykwobv: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.006_ykwobv: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:24 INFO : TestRWCacheUpdate.rcc.007_ykwobv: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: md5 = 505bf710b472728e55b26714b4e6dc01 OK 2026/04/04 05:28:24 DEBUG : forgetting directory cache 2026/04/04 05:28:24 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 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(0x220c946d9d80): _readAt: size=512, off=0 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c946d9d80): openPending: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-04 04:35:23.057677274 +0000 UTC" against cached fingerprint "20,2026-04-04 04:34:23.057677274 +0000 UTC" 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-04 04:35:23.057677274 +0000 UTC" != cached fingerprint "20,2026-04-04 04:34:23.057677274 +0000 UTC") 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:24 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c946d9d80): >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: Size has changed from 20 to 21 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c946d9d80): >_readAt: n=21, err=EOF 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c946d9d80): close: 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate(0x220c946d9d80): >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:24 DEBUG : WaitForWriters: timeout=30s 2026/04/04 05:28:24 DEBUG : Looking for writers 2026/04/04 05:28:24 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/04 05:28:24 DEBUG : >WaitForWriters: 2026/04/04 05:28:24 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-royiham5puyo': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.44s) FAIL 2026/04/04 05:28:24 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-royiham5puyo': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.56227664s (try 2/5): exit status 1: Failed [TestRWCacheUpdate]