"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 3/5) 2026/04/07 05:36:11 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-yehijic6daro" 2026/04/07 05:36:11 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/07 05:36:11 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-yehijic6daro" 2026/04/07 05:36:11 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/7kup3celb583u0k6qpsvrliq0kevlt7nbqennlfmiq7kss117o3g" 2026/04/07 05:36:11 DEBUG : Creating backend with remote "/tmp/rclone3464601481" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-yehijic6daro'", Local "Local file system at /tmp/rclone3464601481", Modify Window "1ns" 2026/04/07 05:36:11 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-yehijic6daro': poll-interval is not supported by this remote 2026/04/07 05:36:11 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-yehijic6daro': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/07 05:36:11 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-yehijic6daro': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-yehijic6daro" 2026/04/07 05:36:11 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-yehijic6daro': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-yehijic6daro" 2026/04/07 05:36:11 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-yehijic6daro" 2026/04/07 05:36:11 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/07 05:36:11 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-yehijic6daro" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-yehijic6daro" 2026/04/07 05:36:11 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-yehijic6daro" 2026/04/07 05:36:11 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/07 05:36:11 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-yehijic6daro" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-yehijic6daro" 2026/04/07 05:36:11 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-yehijic6daro': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = d0499f3867e8694870033445471e11f6 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 4284d26fdf73face809c1235e75c95e2 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = ab85ebe2ccce7bc2f54d3f4390eb0e9e OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 57dd42c643d52095a1b41d54be278b4e OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 7d91df0dcfa490a65bcdaad6c2892a55 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 301526e3dfdba72587cf809c87602b39 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 2a57b88db0b912aff57e0c8948a9f3be OK 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.001_459uur: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.002_459uur: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.003_459uur: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.004_459uur: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.005_459uur: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.006_459uur: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.007_459uur: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 6d7336b513f87cc1478cfbbf6b12d60d OK 2026/04/07 05:36:11 DEBUG : forgetting directory cache 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x212f6668b6c0): _readAt: size=512, off=0 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x212f6668b6c0): openPending: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:37:11.66840728 +0000 UTC" against cached fingerprint "" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/07 05:36:11 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x212f6668b6c0): >openPending: err= 2026/04/07 05:36:11 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x212f6668b6c0): >_readAt: n=20, err=EOF 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x212f6668b6c0): close: 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate(0x212f6668b6c0): >close: err= 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 5ae90d608f4b2dde75c86719f8ed8a82 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 9af665fef69ec815ba834e769e58d328 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = c1cd6e29149f88a33a0fcce0e54bf4e6 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 5931eec0afb86759b96e1865d0e0c2de OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = f184eb681a3f33d845fb089df8b6a0a7 OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 348514998a6ecca46f6253bc506c62fd OK 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 4a54a26ee1335967ea7dca45f1912be7 OK 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.001_459ubm: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.002_459ubm: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.003_459ubm: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.004_459ubm: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.005_459ubm: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.006_459ubm: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:11 INFO : TestRWCacheUpdate.rcc.007_459ubm: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:11 DEBUG : TestRWCacheUpdate: md5 = 652e00d62ff2ecfc135facb338d5cb4e OK 2026/04/07 05:36:12 DEBUG : forgetting directory cache 2026/04/07 05:36:12 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f66252000): _readAt: size=512, off=0 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f66252000): openPending: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:38:11.66840728 +0000 UTC" against cached fingerprint "20,2026-04-07 04:37:11.66840728 +0000 UTC" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:38:11.66840728 +0000 UTC" != cached fingerprint "20,2026-04-07 04:37:11.66840728 +0000 UTC") 2026/04/07 05:36:12 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:12 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f66252000): >openPending: err= 2026/04/07 05:36:12 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f66252000): >_readAt: n=20, err=EOF 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f66252000): close: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f66252000): >close: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = bda7997f55c42ef4a314678341a56e45 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 25849696bc57b088cbf20b446596b1ab OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 8695dbe41b56b1a751385c2fac1b1eec OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = af93536b4cf0cfe376f3623dc2c5d8d4 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = ee0a9e57bcce949faa6839297b7b9869 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 00f9a882f0f29305d78339a95cf1ea9e OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = d7453acf7a1dde30a27b4446f42099a7 OK 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.001_459vx8: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.002_459vx8: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.003_459vx8: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.004_459vx8: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.005_459vx8: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.006_459vx8: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.007_459vx8: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 2be6d91e1b2d8e71ba878eca5f5bae81 OK 2026/04/07 05:36:12 DEBUG : forgetting directory cache 2026/04/07 05:36:12 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675edc0): _readAt: size=512, off=0 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675edc0): openPending: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:39:11.66840728 +0000 UTC" against cached fingerprint "20,2026-04-07 04:38:11.66840728 +0000 UTC" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:39:11.66840728 +0000 UTC" != cached fingerprint "20,2026-04-07 04:38:11.66840728 +0000 UTC") 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:12 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675edc0): >openPending: err= 2026/04/07 05:36:12 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675edc0): >_readAt: n=20, err=EOF 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675edc0): close: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675edc0): >close: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 2ccce4b0e99deb3cc94eee2f318a6a49 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = cc877b5ce7db3966ae2ca468885fe5c9 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 49a857c0e1a30cd288e23e38801cce97 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = bc1b1318281930f4ae7ab01a011bb494 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 68a2ec2f8ac3b7299af588e0097407d8 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = dd0aa6f393721898f03b460ad2ece4ab OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = e0333d20aa3d945bce8fb0145be4a7a6 OK 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.001_459vrw: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.002_459vrw: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.003_459vrw: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.004_459vrw: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.005_459vrw: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.006_459vrw: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.007_459vrw: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 92f1c771d2d8c4078b69d6e6f2c0634b OK 2026/04/07 05:36:12 DEBUG : forgetting directory cache 2026/04/07 05:36:12 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f669501c0): _readAt: size=512, off=0 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f669501c0): openPending: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:40:11.66840728 +0000 UTC" against cached fingerprint "20,2026-04-07 04:39:11.66840728 +0000 UTC" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:40:11.66840728 +0000 UTC" != cached fingerprint "20,2026-04-07 04:39:11.66840728 +0000 UTC") 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:12 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f669501c0): >openPending: err= 2026/04/07 05:36:12 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f669501c0): >_readAt: n=20, err=EOF 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f669501c0): close: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f669501c0): >close: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 2525748b6b9fd68f024089138516874c OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = ec491d839f004f9ca85910ae6fdb813c OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 55db1cfc76a78f804cfc206952007227 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = a1f897cb007a0f372b864e5bd089fb71 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 99128c4309aef69c4d9aff589f1d75bb OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 6f3a96dfe10a22d75713ef2f2336b4f3 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 4fcecd379e1922d0431a150faa5d8544 OK 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.001_459vob: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.002_459vob: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.003_459vob: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.004_459vob: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.005_459vob: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.006_459vob: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.007_459vob: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 68fad468d3ce77406afeb11cf023e875 OK 2026/04/07 05:36:12 DEBUG : forgetting directory cache 2026/04/07 05:36:12 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675f640): _readAt: size=512, off=0 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675f640): openPending: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:41:11.66840728 +0000 UTC" against cached fingerprint "20,2026-04-07 04:40:11.66840728 +0000 UTC" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:41:11.66840728 +0000 UTC" != cached fingerprint "20,2026-04-07 04:40:11.66840728 +0000 UTC") 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:12 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675f640): >openPending: err= 2026/04/07 05:36:12 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675f640): >_readAt: n=20, err=EOF 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675f640): close: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675f640): >close: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = c27d1e948a0f53d12bc0ea7655f18249 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 64794974c5f1e2a754b4af54a1f17bad OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = ce23a79750a9e486b9024c368ea3896a OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 858096a107401ecd5c14c81cee3cd5c7 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = fb55bc638aff161110bb94b28d7a2138 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 2aa42773c1f8841260db7aea21f8b18e OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = b5c1f68697e71d5fc46febb44b27272a OK 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.001_459v7g: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.002_459v7g: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.003_459v7g: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.004_459v7g: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.005_459v7g: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.006_459v7g: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.007_459v7g: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = c09a774d831ad3a68dcd007f0e0e0fc1 OK 2026/04/07 05:36:12 DEBUG : forgetting directory cache 2026/04/07 05:36:12 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675fc00): _readAt: size=512, off=0 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675fc00): openPending: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:42:11.66840728 +0000 UTC" against cached fingerprint "20,2026-04-07 04:41:11.66840728 +0000 UTC" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:42:11.66840728 +0000 UTC" != cached fingerprint "20,2026-04-07 04:41:11.66840728 +0000 UTC") 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:12 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675fc00): >openPending: err= 2026/04/07 05:36:12 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675fc00): >_readAt: n=20, err=EOF 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675fc00): close: 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate(0x212f6675fc00): >close: err= 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 54c008f67c37dbbcc5c1ade9089b9a5a OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = e235941df3fcb6cffc54f15eb748c01d OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = a35074a87c4fe3c06ab2a016797853ef OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 339be97686148632e1a90bb892180d64 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 1089bfa5835e0062f464c9ab85656aaf OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = 5db34e476bf155a708e053dca01eb406 OK 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = fba7e3f23f9ab7379c7f88c6e5be506c OK 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.001_459vuf: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.002_459vuf: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.003_459vuf: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.004_459vuf: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.005_459vuf: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.006_459vuf: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:12 INFO : TestRWCacheUpdate.rcc.007_459vuf: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:12 DEBUG : TestRWCacheUpdate: md5 = d9a4b84f6121b7c3ba0cd40dc2972329 OK 2026/04/07 05:36:13 DEBUG : forgetting directory cache 2026/04/07 05:36:13 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x212f662f8280): _readAt: size=512, off=0 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x212f662f8280): openPending: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-07 04:43:11.66840728 +0000 UTC" against cached fingerprint "20,2026-04-07 04:42:11.66840728 +0000 UTC" 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-07 04:43:11.66840728 +0000 UTC" != cached fingerprint "20,2026-04-07 04:42:11.66840728 +0000 UTC") 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:13 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x212f662f8280): >openPending: err= 2026/04/07 05:36:13 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x212f662f8280): >_readAt: n=21, err=EOF 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x212f662f8280): close: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x212f662f8280): >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/07 05:36:13 DEBUG : WaitForWriters: timeout=30s 2026/04/07 05:36:13 DEBUG : Looking for writers 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/07 05:36:13 DEBUG : >WaitForWriters: 2026/04/07 05:36:13 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-yehijic6daro': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.44s) FAIL 2026/04/07 05:36:13 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-yehijic6daro': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.529477278s (try 3/5): exit status 1: Failed [TestRWCacheUpdate]