"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 5/5) 2026/04/07 05:36:14 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-pilovif0nota" 2026/04/07 05:36:14 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/07 05:36:14 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-pilovif0nota" 2026/04/07 05:36:14 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/v30bt6pqt6a9530c4s0aalcd3maghiuetskms510lnmoph2c7t5g" 2026/04/07 05:36:14 DEBUG : Creating backend with remote "/tmp/rclone187726154" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-pilovif0nota'", Local "Local file system at /tmp/rclone187726154", Modify Window "1ns" 2026/04/07 05:36:14 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-pilovif0nota': poll-interval is not supported by this remote 2026/04/07 05:36:14 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pilovif0nota': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/07 05:36:14 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pilovif0nota': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-pilovif0nota" 2026/04/07 05:36:14 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pilovif0nota': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-pilovif0nota" 2026/04/07 05:36:14 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-pilovif0nota" 2026/04/07 05:36:14 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/07 05:36:14 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-pilovif0nota" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-pilovif0nota" 2026/04/07 05:36:14 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-pilovif0nota" 2026/04/07 05:36:14 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/07 05:36:14 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-pilovif0nota" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-pilovif0nota" 2026/04/07 05:36:14 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-pilovif0nota': 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:14 DEBUG : TestRWCacheUpdate: md5 = 0f15741e5c51e66a7c790a440a9fae67 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 217a9dc86d3feab14b37e17c1bc43160 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = e5f577f52732e674f46a2e570470ad2a OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 0bae9f09b1c31b81d35440506c7c9c20 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 9b4209c4fafd7c5388c3e8253aad1794 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 197e961706a6a7727f6158f3c61092d7 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = d475be58b239bd5a4e1c136543c8ac77 OK 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.001_459xuo: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.002_459xuo: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.003_459xuo: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.004_459xuo: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.005_459xuo: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.006_459xuo: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.007_459xuo: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = a46535258f0bdd158bf95c8a6a112770 OK 2026/04/07 05:36:15 DEBUG : forgetting directory cache 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d174ac0): _readAt: size=512, off=0 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d174ac0): openPending: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:37:14.860819529 +0000 UTC" against cached fingerprint "" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/07 05:36:15 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d174ac0): >openPending: err= 2026/04/07 05:36:15 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d174ac0): >_readAt: n=20, err=EOF 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d174ac0): close: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d174ac0): >close: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = b3919a7e37bce67cdcd66b1cbe4707f1 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 2a179c0de2b3c1998fd8de95b7049bac OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = b7928523a9c93f85f1d36cfc51416575 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = af80a6ef914b509d21cd2638ddf15a58 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 55f7e97d5f89f66f0e307ad6c8546bb0 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = f7b838f6db6127335c0c8bab82a23d9e OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 7fff0961c7c62769fc91e7fc3baae52d OK 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.001_459ylc: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.002_459ylc: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.003_459ylc: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.004_459ylc: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.005_459ylc: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.006_459ylc: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.007_459ylc: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = dc9718a90eecf604f561de45b5d0699e OK 2026/04/07 05:36:15 DEBUG : forgetting directory cache 2026/04/07 05:36:15 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1be400): _readAt: size=512, off=0 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1be400): openPending: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:38:14.860819529 +0000 UTC" against cached fingerprint "20,2026-04-07 04:37:14.860819529 +0000 UTC" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:38:14.860819529 +0000 UTC" != cached fingerprint "20,2026-04-07 04:37:14.860819529 +0000 UTC") 2026/04/07 05:36:15 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:15 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1be400): >openPending: err= 2026/04/07 05:36:15 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1be400): >_readAt: n=20, err=EOF 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1be400): close: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1be400): >close: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 66b00429c1af5c1c13f1e2974f18039a OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 8aad000c2a0be01da53d0929fa7c230b OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 0ad886ef0f278fcd6341affadfaa3745 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 440fb78a7365d690c90715a67e26b63b OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 8366ceb74a33e03a64cf7e2f27b956c8 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = bd979afae34490904bf070ac84e011b3 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 9dcb222a1bbe506b90898d9294315738 OK 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.001_459ytv: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.002_459ytv: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.003_459ytv: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.004_459ytv: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.005_459ytv: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.006_459ytv: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.007_459ytv: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = d568606ed39e76ebc7c183973839ba89 OK 2026/04/07 05:36:15 DEBUG : forgetting directory cache 2026/04/07 05:36:15 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1bfb40): _readAt: size=512, off=0 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1bfb40): openPending: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:39:14.860819529 +0000 UTC" against cached fingerprint "20,2026-04-07 04:38:14.860819529 +0000 UTC" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:39:14.860819529 +0000 UTC" != cached fingerprint "20,2026-04-07 04:38:14.860819529 +0000 UTC") 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:15 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1bfb40): >openPending: err= 2026/04/07 05:36:15 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1bfb40): >_readAt: n=20, err=EOF 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1bfb40): close: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d1bfb40): >close: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 74e7982fb63cd2706ba0928108eb065a OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = ce0f138a8cc2ff3a25349201b482c091 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = fdf474f7d7a4e7aee707fe69e4f2157f OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 8c365d1be90d57e202280d2526e5b681 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = e958cd416d86de712b57d650b89a71b1 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 5f5fcf03993fa7c085739402a7ce5755 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = aa8b9860572c0a6a3c100d012438921b OK 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.001_459y2g: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.002_459y2g: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.003_459y2g: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.004_459y2g: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.005_459y2g: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.006_459y2g: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.007_459y2g: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 5c4755be9be6d91763775fc786510cab OK 2026/04/07 05:36:15 DEBUG : forgetting directory cache 2026/04/07 05:36:15 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d693140): _readAt: size=512, off=0 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d693140): openPending: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:40:14.860819529 +0000 UTC" against cached fingerprint "20,2026-04-07 04:39:14.860819529 +0000 UTC" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:40:14.860819529 +0000 UTC" != cached fingerprint "20,2026-04-07 04:39:14.860819529 +0000 UTC") 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:15 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d693140): >openPending: err= 2026/04/07 05:36:15 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d693140): >_readAt: n=20, err=EOF 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d693140): close: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65d693140): >close: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = f3c4776d3d03fae3ea83c114ba4a2531 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 08e4a924089c556bb838bbbedc9ade35 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 0d0f689e225d983c9f5cb4b7c6fb52e4 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 841c62477e75a9d2e55841dcf0b819dc OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 13a8c2926910b02723cd83a6380e4f3e OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 5aed46afdb6ebd29e22e15ae26caacec OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 9a2766b7e0588ca69df16466ec199619 OK 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.001_459ydl: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.002_459ydl: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.003_459ydl: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.004_459ydl: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.005_459ydl: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.006_459ydl: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.007_459ydl: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 467a4a137c7ffb15fef0caebada5e645 OK 2026/04/07 05:36:15 DEBUG : forgetting directory cache 2026/04/07 05:36:15 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65cf31480): _readAt: size=512, off=0 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65cf31480): openPending: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:41:14.860819529 +0000 UTC" against cached fingerprint "20,2026-04-07 04:40:14.860819529 +0000 UTC" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:41:14.860819529 +0000 UTC" != cached fingerprint "20,2026-04-07 04:40:14.860819529 +0000 UTC") 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:15 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65cf31480): >openPending: err= 2026/04/07 05:36:15 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65cf31480): >_readAt: n=20, err=EOF 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65cf31480): close: 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate(0x9f65cf31480): >close: err= 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 59d2ed0198a941b8d77207734d495791 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 16646eefd8c833e79284ffe3a74a71dc OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 8ec61c48eb3559c53bc1fc137e9fff87 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = f6bad11ae79a07908b3a4e8ae6237c63 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 8ac10cbbdd1024095b3be2052efbc676 OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 0e29dd722cb0025121a145f8b339cf6f OK 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 818fed2b9362a513e3d90f88041021ac OK 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.001_459yxj: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.002_459yxj: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.003_459yxj: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.004_459yxj: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.005_459yxj: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.006_459yxj: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:15 INFO : TestRWCacheUpdate.rcc.007_459yxj: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:15 DEBUG : TestRWCacheUpdate: md5 = 107c1a58ac86e9383cda20ee6543ac3c OK 2026/04/07 05:36:16 DEBUG : forgetting directory cache 2026/04/07 05:36:16 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65ea62b00): _readAt: size=512, off=0 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65ea62b00): openPending: 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:42:14.860819529 +0000 UTC" against cached fingerprint "20,2026-04-07 04:41:14.860819529 +0000 UTC" 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:42:14.860819529 +0000 UTC" != cached fingerprint "20,2026-04-07 04:41:14.860819529 +0000 UTC") 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:16 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65ea62b00): >openPending: err= 2026/04/07 05:36:16 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65ea62b00): >_readAt: n=20, err=EOF 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65ea62b00): close: 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65ea62b00): >close: err= 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: md5 = 94bbd89948d317e70a5388bb0d9579d1 OK 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: md5 = f2e66a0571f420972298fd284f535d3b OK 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: md5 = df1a936146905cb0872cae9467f823aa OK 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: md5 = f5eb513804dc1c3e98f6b1b78ec43210 OK 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: md5 = ea36b4e7028be1b26faa8863af4a330e OK 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: md5 = 780a7d0fceb1914033b5d9953f14c6f0 OK 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: md5 = 39059aff08f061de0f1cee48b09377ab OK 2026/04/07 05:36:16 INFO : TestRWCacheUpdate.rcc.001_459zd2: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:16 INFO : TestRWCacheUpdate.rcc.002_459zd2: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:16 INFO : TestRWCacheUpdate.rcc.003_459zd2: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:16 INFO : TestRWCacheUpdate.rcc.004_459zd2: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:16 INFO : TestRWCacheUpdate.rcc.005_459zd2: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:16 INFO : TestRWCacheUpdate.rcc.006_459zd2: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:16 INFO : TestRWCacheUpdate.rcc.007_459zd2: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: md5 = a815963bb227ee9c37ac4825bcacb957 OK 2026/04/07 05:36:16 DEBUG : forgetting directory cache 2026/04/07 05:36:16 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65e936400): _readAt: size=512, off=0 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65e936400): openPending: 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-07 04:43:14.860819529 +0000 UTC" against cached fingerprint "20,2026-04-07 04:42:14.860819529 +0000 UTC" 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-07 04:43:14.860819529 +0000 UTC" != cached fingerprint "20,2026-04-07 04:42:14.860819529 +0000 UTC") 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:16 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65e936400): >openPending: err= 2026/04/07 05:36:16 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65e936400): >_readAt: n=21, err=EOF 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65e936400): close: 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate(0x9f65e936400): >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:16 DEBUG : WaitForWriters: timeout=30s 2026/04/07 05:36:16 DEBUG : Looking for writers 2026/04/07 05:36:16 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/07 05:36:16 DEBUG : >WaitForWriters: 2026/04/07 05:36:16 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pilovif0nota': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.45s) FAIL 2026/04/07 05:36:16 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-pilovif0nota': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.60132377s (try 5/5): exit status 1: Failed [TestRWCacheUpdate]