"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 4/5) 2026/04/07 05:36:13 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-paqadir4suce" 2026/04/07 05:36:13 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/07 05:36:13 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-paqadir4suce" 2026/04/07 05:36:13 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/vsvlqsstus84odadfjcu13ausj6trd52tekp0v898a4umkqmqgpg" 2026/04/07 05:36:13 DEBUG : Creating backend with remote "/tmp/rclone2216473437" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-paqadir4suce'", Local "Local file system at /tmp/rclone2216473437", Modify Window "1ns" 2026/04/07 05:36:13 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-paqadir4suce': poll-interval is not supported by this remote 2026/04/07 05:36:13 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-paqadir4suce': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/07 05:36:13 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-paqadir4suce': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-paqadir4suce" 2026/04/07 05:36:13 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-paqadir4suce': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-paqadir4suce" 2026/04/07 05:36:13 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-paqadir4suce" 2026/04/07 05:36:13 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/07 05:36:13 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-paqadir4suce" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-paqadir4suce" 2026/04/07 05:36:13 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-paqadir4suce" 2026/04/07 05:36:13 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/07 05:36:13 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-paqadir4suce" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-paqadir4suce" 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 2c1eac2e96745b5e17dd94fd5bed80d8 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 3a9ad3441006e2a1f8e1654e8842e52a OK 2026/04/07 05:36:13 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-paqadir4suce': 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:13 DEBUG : TestRWCacheUpdate: md5 = 0e1973f9873a6e30cd28689ca642d12c OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 01c7aec5c9926d3a57a08b4007f2a6a8 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = d9d60bc33b2ae5ea04b2c415b3e7534d OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 3ed49f0def9aca087b1aa23154ef2612 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = c4806268b7d99d8cb5651d3c5d2f2d6c OK 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.001_459wej: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.002_459wej: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.003_459wej: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.004_459wej: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.005_459wej: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.006_459wej: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.007_459wej: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 0238b21571efa3a30a4345d2ee6332d8 OK 2026/04/07 05:36:13 DEBUG : forgetting directory cache 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(0x23f93305f140): _readAt: size=512, off=0 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f93305f140): openPending: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:37:13.260592711 +0000 UTC" against cached fingerprint "" 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/07 05:36:13 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f93305f140): >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(0x23f93305f140): >_readAt: n=20, err=EOF 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f93305f140): close: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f93305f140): >close: err= 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = add1b4bd9f302d4d326afe54c387af21 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = f74455867fa7ff4347fc07715795e248 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = ec2b01b12b9861e68aaa51a498ff85fc OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = b56cc8ad042e9bb0d1fe56ac96b2c454 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 1a754cde07c7f96f6e094ee15a63f2ae OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = a773fd999ea43c7ab9abd16e7f16167e OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = a9856f6a2a5ebe9647f289ce114ad318 OK 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.001_459w6q: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.002_459w6q: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.003_459w6q: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.004_459w6q: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.005_459w6q: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.006_459w6q: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.007_459w6q: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 0e1529e31fccb5b70bc62bcea2a5082b 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(0x23f933337680): _readAt: size=512, off=0 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f933337680): openPending: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:38:13.260592711 +0000 UTC" against cached fingerprint "20,2026-04-07 04:37:13.260592711 +0000 UTC" 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:38:13.260592711 +0000 UTC" != cached fingerprint "20,2026-04-07 04:37:13.260592711 +0000 UTC") 2026/04/07 05:36:13 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 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(0x23f933337680): >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(0x23f933337680): >_readAt: n=20, err=EOF 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f933337680): close: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f933337680): >close: err= 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 1fa8ad3d809440245924eaff81824d48 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = e4d81aa1b7c5ac1016c6e9347ec35a36 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 0ab64c1c3e7f7ed6405261c21fea7d7c OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 9fdd8464978f735dd67970a7e0c810f0 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 8b1ce793942f8e96771e6305c0995522 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = c2cfdf6f1204b0a655953d75e7661ffd OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 23b80c7432494a7471302536a7f12f6d OK 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.001_459wqf: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.002_459wqf: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.003_459wqf: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.004_459wqf: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.005_459wqf: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.006_459wqf: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.007_459wqf: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 3bb813a5bbf64ed3ad7c242e454e4392 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(0x23f93305f700): _readAt: size=512, off=0 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f93305f700): openPending: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:39:13.260592711 +0000 UTC" against cached fingerprint "20,2026-04-07 04:38:13.260592711 +0000 UTC" 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:39:13.260592711 +0000 UTC" != cached fingerprint "20,2026-04-07 04:38:13.260592711 +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(0x23f93305f700): >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(0x23f93305f700): >_readAt: n=20, err=EOF 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f93305f700): close: 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate(0x23f93305f700): >close: err= 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = fe9ea163b92510f475a2975435255cce OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 19799142842d9b50fe7d5db8d7f1e0b6 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = fb860eb96c6566854c731b9579c62ab6 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = c543424ee9c64442634c9a270b053e4e OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 3c66db731fc196ffe8a69a108ba395cc OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 5fb896a3fc815e7ec098164b551a6f52 OK 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = 32d7c16468a07295ac7c92ac426c8e82 OK 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.001_459wgx: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.002_459wgx: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.003_459wgx: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.004_459wgx: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.005_459wgx: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.006_459wgx: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:13 INFO : TestRWCacheUpdate.rcc.007_459wgx: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:13 DEBUG : TestRWCacheUpdate: md5 = b2e7b5b22cfab82f5495365efbe8d6bd OK 2026/04/07 05:36:14 DEBUG : forgetting directory cache 2026/04/07 05:36:14 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f93305fc40): _readAt: size=512, off=0 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f93305fc40): openPending: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:40:13.260592711 +0000 UTC" against cached fingerprint "20,2026-04-07 04:39:13.260592711 +0000 UTC" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:40:13.260592711 +0000 UTC" != cached fingerprint "20,2026-04-07 04:39:13.260592711 +0000 UTC") 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:14 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f93305fc40): >openPending: err= 2026/04/07 05:36:14 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f93305fc40): >_readAt: n=20, err=EOF 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f93305fc40): close: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f93305fc40): >close: err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 2af4740cf51d708a3b50f9c7b4238036 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = b230f477ae1841d84c4dad398f2ea331 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 0c1e7434945abd41e9dc6c89064375cd OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 4c2e312ef1c8eff74c1da1f3c91213e7 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 31954ef91052bf36ad2db9a3cb898eec OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 2c1885100231323fa73097282fa9bda4 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = c49cfbbb77483e6a8df1b3544657e0c0 OK 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.001_459xy7: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.002_459xy7: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.003_459xy7: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.004_459xy7: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.005_459xy7: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.006_459xy7: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.007_459xy7: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 360977f634ab1d23a8f2273653d5911b OK 2026/04/07 05:36:14 DEBUG : forgetting directory cache 2026/04/07 05:36:14 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933375c40): _readAt: size=512, off=0 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933375c40): openPending: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:41:13.260592711 +0000 UTC" against cached fingerprint "20,2026-04-07 04:40:13.260592711 +0000 UTC" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:41:13.260592711 +0000 UTC" != cached fingerprint "20,2026-04-07 04:40:13.260592711 +0000 UTC") 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:14 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933375c40): >openPending: err= 2026/04/07 05:36:14 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933375c40): >_readAt: n=20, err=EOF 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933375c40): close: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933375c40): >close: err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 8e1f881def98faef00e3d57ee3efc730 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 71b3f9abb8e6b57f7e8c2fa8464463d5 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 869a226981ceb1816d2c4d59f8897f3f OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = d0d561d91d0e405106638a7306ddee97 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 4f6aba11c71695720c1384ed947e3ce8 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 6131f73f7ba5f7f07f9b3c08d1b056bf OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = f20d9cdf9019da3ddfe9f4978f11a778 OK 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.001_459xfo: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.002_459xfo: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.003_459xfo: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.004_459xfo: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.005_459xfo: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.006_459xfo: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.007_459xfo: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 99e7efdbdb95d4c5af4469172551b16d OK 2026/04/07 05:36:14 DEBUG : forgetting directory cache 2026/04/07 05:36:14 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f9331d7800): _readAt: size=512, off=0 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f9331d7800): openPending: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-07 04:42:13.260592711 +0000 UTC" against cached fingerprint "20,2026-04-07 04:41:13.260592711 +0000 UTC" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-07 04:42:13.260592711 +0000 UTC" != cached fingerprint "20,2026-04-07 04:41:13.260592711 +0000 UTC") 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:14 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f9331d7800): >openPending: err= 2026/04/07 05:36:14 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f9331d7800): >_readAt: n=20, err=EOF 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f9331d7800): close: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f9331d7800): >close: err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 02735c3ec1a18a39f6ef156071ced595 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 0b280988b090dc2f6228128a2cfd14d9 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = a69c4563baa2b6497e02b06e07ce880e OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = c0221a3a4495a75cb7b2226ecc4a25c3 OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = cff5d08516bfbd39892e1dbf3278bb8b OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = ed65292ab469b83476a174ad30955fda OK 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 549ea820803bbeadcf363eea17a20610 OK 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.001_459xv1: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.002_459xv1: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.003_459xv1: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.004_459xv1: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.005_459xv1: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.006_459xv1: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/07 05:36:14 INFO : TestRWCacheUpdate.rcc.007_459xv1: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: md5 = 2b667e723b47fe6f69d2265233830ab2 OK 2026/04/07 05:36:14 DEBUG : forgetting directory cache 2026/04/07 05:36:14 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933337cc0): _readAt: size=512, off=0 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933337cc0): openPending: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-07 04:43:13.260592711 +0000 UTC" against cached fingerprint "20,2026-04-07 04:42:13.260592711 +0000 UTC" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-07 04:43:13.260592711 +0000 UTC" != cached fingerprint "20,2026-04-07 04:42:13.260592711 +0000 UTC") 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/07 05:36:14 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933337cc0): >openPending: err= 2026/04/07 05:36:14 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933337cc0): >_readAt: n=21, err=EOF 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933337cc0): close: 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate(0x23f933337cc0): >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:14 DEBUG : WaitForWriters: timeout=30s 2026/04/07 05:36:14 DEBUG : Looking for writers 2026/04/07 05:36:14 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/07 05:36:14 DEBUG : >WaitForWriters: 2026/04/07 05:36:14 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-paqadir4suce': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.45s) FAIL 2026/04/07 05:36:14 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-paqadir4suce': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.598405379s (try 4/5): exit status 1: Failed [TestRWCacheUpdate]