"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 2/5) 2026/04/05 03:28:34 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi" 2026/04/05 03:28:34 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/05 03:28:34 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi" 2026/04/05 03:28:34 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/lndfse4p9nlt6co6t92ibtfngbt120ilb3svleentgi789em8cpg" 2026/04/05 03:28:34 DEBUG : Creating backend with remote "/tmp/rclone2738469282" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi'", Local "Local file system at /tmp/rclone2738469282", Modify Window "1ns" 2026/04/05 03:28:34 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi': poll-interval is not supported by this remote 2026/04/05 03:28:34 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/05 03:28:34 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-duxuqeh5ziqi" 2026/04/05 03:28:34 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-duxuqeh5ziqi" 2026/04/05 03:28:34 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-duxuqeh5ziqi" 2026/04/05 03:28:34 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/05 03:28:34 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-duxuqeh5ziqi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-duxuqeh5ziqi" 2026/04/05 03:28:34 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-duxuqeh5ziqi" 2026/04/05 03:28:34 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/05 03:28:34 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-duxuqeh5ziqi" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-duxuqeh5ziqi" 2026/04/05 03:28:34 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 859c819c6cec0024262c246040b5b2b0 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 2a1af2b109c54143049f9ed15133aee8 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 54fbe4e7a55504e130dadaefaf0bb675 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 99c57fae4ad83da2864182f8f534ee7c OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = dfb51527700eda4ee676b404e7fc300d OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 02295f0a77e335dd821cff0cdf2a6c49 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 970781302a8e5be556df213f0ae55023 OK 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.001_0a15jl: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.002_0a15jl: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.003_0a15jl: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.004_0a15jl: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.005_0a15jl: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.006_0a15jl: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.007_0a15jl: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 207299dbe3998b8d596b55f895535837 OK 2026/04/05 03:28:34 DEBUG : forgetting directory cache 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90de83b80): _readAt: size=512, off=0 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90de83b80): openPending: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:29:34.179176406 +0000 UTC" against cached fingerprint "" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/05 03:28:34 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90de83b80): >openPending: err= 2026/04/05 03:28:34 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90de83b80): >_readAt: n=20, err=EOF 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90de83b80): close: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90de83b80): >close: err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 8e87fb10793d4c965f930dac3f1cac38 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 363c06ae01b1d664ddc0e4611cff10c6 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 4bd444ec9b4abeb0e9369742370d4e0f OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 4e3b50f3b56deca05e4821145bf1a325 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 6913f2e32d329602fbe9f6d331dde76e OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = a1bd83151f0828878b3b6c97fe9e26f3 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 074b181ab5dd6a8d92a0c1a9d190fbbf OK 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.001_0a15tt: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.002_0a15tt: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.003_0a15tt: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.004_0a15tt: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.005_0a15tt: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.006_0a15tt: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.007_0a15tt: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 2da3f6e0d00b93e5abf80ec03e537802 OK 2026/04/05 03:28:34 DEBUG : forgetting directory cache 2026/04/05 03:28:34 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90d97eb00): _readAt: size=512, off=0 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90d97eb00): openPending: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:30:34.179176406 +0000 UTC" against cached fingerprint "20,2026-04-05 02:29:34.179176406 +0000 UTC" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:30:34.179176406 +0000 UTC" != cached fingerprint "20,2026-04-05 02:29:34.179176406 +0000 UTC") 2026/04/05 03:28:34 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:34 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90d97eb00): >openPending: err= 2026/04/05 03:28:34 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90d97eb00): >_readAt: n=20, err=EOF 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90d97eb00): close: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90d97eb00): >close: err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 80a3f0fa51c270e690d507c925a8f88b OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = d6c83200472ad45a80a6ccdc4915cc81 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 2101aa63e4f3cc004da419228babf8b9 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = f49c7032ac809c5388b0d72cb8946dac OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 6b7f0ebd5808bac298d62de73f6dcdb5 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 51ad479db1d8b56c1eb410d90213f287 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = dc54ab0fab2611f2bfe32869476dc0fe OK 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.001_0a15sx: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.002_0a15sx: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.003_0a15sx: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.004_0a15sx: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.005_0a15sx: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.006_0a15sx: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.007_0a15sx: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = ae55bb755b2edeab9592a6ab2894976a OK 2026/04/05 03:28:34 DEBUG : forgetting directory cache 2026/04/05 03:28:34 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbacc00): _readAt: size=512, off=0 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbacc00): openPending: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:31:34.179176406 +0000 UTC" against cached fingerprint "20,2026-04-05 02:30:34.179176406 +0000 UTC" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:31:34.179176406 +0000 UTC" != cached fingerprint "20,2026-04-05 02:30:34.179176406 +0000 UTC") 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:34 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbacc00): >openPending: err= 2026/04/05 03:28:34 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbacc00): >_readAt: n=20, err=EOF 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbacc00): close: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbacc00): >close: err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = dbd732078a60dd4e9d503a6a60ff426d OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = a6a4e18ce6e8e6efb0aa9282fee327b5 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = e56ece380aa2e117fbe1231c407eb927 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 6e8d6fc93a0b19928b934f6e5369a760 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 467b3b2dc31838345816c26905bf74a5 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 2529541390a3768250b5378adeb32daa OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = ed3efc590b85dd0f98af982627b6ba9d OK 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.001_0a15dc: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.002_0a15dc: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.003_0a15dc: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.004_0a15dc: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.005_0a15dc: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.006_0a15dc: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:34 INFO : TestRWCacheUpdate.rcc.007_0a15dc: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 3a1fe770394d0b124af04bd601a54708 OK 2026/04/05 03:28:34 DEBUG : forgetting directory cache 2026/04/05 03:28:34 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbadc80): _readAt: size=512, off=0 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbadc80): openPending: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:32:34.179176406 +0000 UTC" against cached fingerprint "20,2026-04-05 02:31:34.179176406 +0000 UTC" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:32:34.179176406 +0000 UTC" != cached fingerprint "20,2026-04-05 02:31:34.179176406 +0000 UTC") 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:34 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbadc80): >openPending: err= 2026/04/05 03:28:34 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbadc80): >_readAt: n=20, err=EOF 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbadc80): close: 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate(0x3ad90dbadc80): >close: err= 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = d616df459175f762ba8a866b73260084 OK 2026/04/05 03:28:34 DEBUG : TestRWCacheUpdate: md5 = 43c6dbca5ea55c8524b019af7f6ec814 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 30d3ceaf65068568258a2ddbcb3c4f9d OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 379171c2d4477db52c32d9a9e2885e56 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 2a957902b591510c6f3504ca5048a1fc OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = afbf9db6c0e5c109cbbe2091fcc34976 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = baa652f0c2e9be6e66243b350fc2cace OK 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.001_0a153s: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.002_0a153s: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.003_0a153s: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.004_0a153s: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.005_0a153s: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.006_0a153s: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.007_0a153s: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 68706fcc534028f64b3efd77a29dbe34 OK 2026/04/05 03:28:35 DEBUG : forgetting directory cache 2026/04/05 03:28:35 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90daa3d00): _readAt: size=512, off=0 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90daa3d00): openPending: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:33:34.179176406 +0000 UTC" against cached fingerprint "20,2026-04-05 02:32:34.179176406 +0000 UTC" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:33:34.179176406 +0000 UTC" != cached fingerprint "20,2026-04-05 02:32:34.179176406 +0000 UTC") 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:35 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90daa3d00): >openPending: err= 2026/04/05 03:28:35 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90daa3d00): >_readAt: n=20, err=EOF 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90daa3d00): close: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90daa3d00): >close: err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = e40744b5d9a48e7299d8513b314140a4 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = e69909fc3a22cab1d597dba945b1c39c OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = c1c30e37d728d8238d81334b6a78e7fe OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 1f7454ded7798da579af51d155c84402 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 194ad6f869965efb677565bf9c83462b OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = fc968730322131feeac21b78afe39192 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 89206590eaeb2af08a21fd6dccd14222 OK 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.001_0a16y5: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.002_0a16y5: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.003_0a16y5: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.004_0a16y5: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.005_0a16y5: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.006_0a16y5: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.007_0a16y5: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 08abf73a9117f51fd6dd458fd8f62703 OK 2026/04/05 03:28:35 DEBUG : forgetting directory cache 2026/04/05 03:28:35 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22ab40): _readAt: size=512, off=0 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22ab40): openPending: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-05 02:34:34.179176406 +0000 UTC" against cached fingerprint "20,2026-04-05 02:33:34.179176406 +0000 UTC" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-05 02:34:34.179176406 +0000 UTC" != cached fingerprint "20,2026-04-05 02:33:34.179176406 +0000 UTC") 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:35 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22ab40): >openPending: err= 2026/04/05 03:28:35 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22ab40): >_readAt: n=20, err=EOF 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22ab40): close: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22ab40): >close: err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 8238716d0f2500abce29880907710cc0 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 32962d1fcff337197071ade58bef01b9 OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 3473be9818a7c26626dd018b257cb40c OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = c9ddd0794570a47ee3c797f989e9e00d OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = a36d077f5bcc58a9165f5eb163a5f4bf OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 5c935ebb13bde8c905206773c917deba OK 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 0e336c9dee6bb41e8ab6a53f56e9c122 OK 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.001_0a16o4: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.002_0a16o4: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.003_0a16o4: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.004_0a16o4: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.005_0a16o4: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.006_0a16o4: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/05 03:28:35 INFO : TestRWCacheUpdate.rcc.007_0a16o4: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: md5 = 3f2056c01e9548d462ee3ee19e04aafb OK 2026/04/05 03:28:35 DEBUG : forgetting directory cache 2026/04/05 03:28:35 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22b880): _readAt: size=512, off=0 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22b880): openPending: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-05 02:35:34.179176406 +0000 UTC" against cached fingerprint "20,2026-04-05 02:34:34.179176406 +0000 UTC" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-05 02:35:34.179176406 +0000 UTC" != cached fingerprint "20,2026-04-05 02:34:34.179176406 +0000 UTC") 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/05 03:28:35 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22b880): >openPending: err= 2026/04/05 03:28:35 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22b880): >_readAt: n=21, err=EOF 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22b880): close: 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate(0x3ad90f22b880): >close: err= read_write_test.go:752: Error Trace: /home/rclone/go/src/github.com/rclone/rclone/vfs/read_write_test.go:752 Error: Not equal: expected: "TestRWCacheUpdate006*" actual : "TestRWCacheUpdate006\x00" Diff: --- Expected +++ Actual @@ -1 +1 @@ -TestRWCacheUpdate006* +TestRWCacheUpdate006 Test: TestRWCacheUpdate 2026/04/05 03:28:35 DEBUG : WaitForWriters: timeout=30s 2026/04/05 03:28:35 DEBUG : Looking for writers 2026/04/05 03:28:35 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/05 03:28:35 DEBUG : >WaitForWriters: 2026/04/05 03:28:35 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.44s) FAIL 2026/04/05 03:28:35 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-duxuqeh5ziqi': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.551633018s (try 2/5): exit status 1: Failed [TestRWCacheUpdate]