"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 4/5) 2026/04/06 04:56:27 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-sosexun0daka" 2026/04/06 04:56:27 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/06 04:56:27 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-sosexun0daka" 2026/04/06 04:56:27 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/3dp3b7l8ocht4frjitvi3upnftroc2cohtn0aqm9gcfa7ecta9d0" 2026/04/06 04:56:27 DEBUG : Creating backend with remote "/tmp/rclone4239472965" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-sosexun0daka'", Local "Local file system at /tmp/rclone4239472965", Modify Window "1ns" 2026/04/06 04:56:27 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-sosexun0daka': poll-interval is not supported by this remote 2026/04/06 04:56:27 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-sosexun0daka': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/06 04:56:27 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-sosexun0daka': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-sosexun0daka" 2026/04/06 04:56:27 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-sosexun0daka': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-sosexun0daka" 2026/04/06 04:56:27 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-sosexun0daka" 2026/04/06 04:56:27 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/06 04:56:27 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-sosexun0daka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-sosexun0daka" 2026/04/06 04:56:27 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-sosexun0daka" 2026/04/06 04:56:27 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/06 04:56:27 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-sosexun0daka" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-sosexun0daka" 2026/04/06 04:56:27 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-sosexun0daka': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 3fc04d462c8fba709cfed5913f182916 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 263447cfab78e3074b73dc52dd095491 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 67151838a4c57d575ea8bff4ecf5e66a OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = af69945a6846a93bf17b8488519f02e6 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 90d0727fd107d53bf0cf43a996bc4825 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = a3ac7cf184acef84ce440dc914b2d51a OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = e770150f3b1ab93bbd931bacca0464b3 OK 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.001_28rmf5: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.002_28rmf5: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.003_28rmf5: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.004_28rmf5: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.005_28rmf5: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.006_28rmf5: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.007_28rmf5: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 88d8d1fe6345152fbc10eb5089a7de1c OK 2026/04/06 04:56:27 DEBUG : forgetting directory cache 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277180): _readAt: size=512, off=0 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277180): openPending: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:57:27.164759218 +0000 UTC" against cached fingerprint "" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/06 04:56:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277180): >openPending: err= 2026/04/06 04:56:27 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277180): >_readAt: n=20, err=EOF 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277180): close: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277180): >close: err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 8af4e097843465d3e33b94476ff108ac OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 9a6fa1f8d4568134d02f364ce123c977 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = eebd30bf0a791941649aa086d11f60e2 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = c90f4598a04431f51af11666057045d6 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 950227f53cb4c6b0adffdbec1b27623d OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 76da46580e3349c33cdc2d978a1ae47a OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 78c20bafe58b1116318f507a8fefd250 OK 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.001_28rm5h: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.002_28rm5h: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.003_28rm5h: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.004_28rm5h: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.005_28rm5h: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.006_28rm5h: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.007_28rm5h: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = cd35cc10c8582f9189fc918371f5bafb OK 2026/04/06 04:56:27 DEBUG : forgetting directory cache 2026/04/06 04:56:27 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277ec0): _readAt: size=512, off=0 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277ec0): openPending: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:58:27.164759218 +0000 UTC" against cached fingerprint "20,2026-04-06 03:57:27.164759218 +0000 UTC" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 03:58:27.164759218 +0000 UTC" != cached fingerprint "20,2026-04-06 03:57:27.164759218 +0000 UTC") 2026/04/06 04:56:27 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277ec0): >openPending: err= 2026/04/06 04:56:27 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277ec0): >_readAt: n=20, err=EOF 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277ec0): close: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b5277ec0): >close: err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = d989c561762b42ee804c967c3f85fb6f OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 096bf0227ec2dbf1a6f0026ef647d87b OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 5514f110b74e277cefc3577de9bbb7d4 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 2febc6e71637eb50c06864fc5e3b4c3d OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = d89132cb0908586a8fadf1b5649a7d32 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 84e3ecfc7d669ed0417fd8c0f73a583a OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = cb7c43b49eab65e93e2640cff98111e0 OK 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.001_28rmn5: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.002_28rmn5: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.003_28rmn5: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.004_28rmn5: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.005_28rmn5: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.006_28rmn5: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.007_28rmn5: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = e79941f7bfc1169f32fcf4117feec3ab OK 2026/04/06 04:56:27 DEBUG : forgetting directory cache 2026/04/06 04:56:27 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b506fa40): _readAt: size=512, off=0 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b506fa40): openPending: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 03:59:27.164759218 +0000 UTC" against cached fingerprint "20,2026-04-06 03:58:27.164759218 +0000 UTC" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 03:59:27.164759218 +0000 UTC" != cached fingerprint "20,2026-04-06 03:58:27.164759218 +0000 UTC") 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b506fa40): >openPending: err= 2026/04/06 04:56:27 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b506fa40): >_readAt: n=20, err=EOF 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b506fa40): close: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b506fa40): >close: err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 2af6485df08143a278e7bbd5597c72ad OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = f4f5cb5359ff7205c98ccf9d111df8ca OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 90c3d18bfa532931e5baf8bd8ea21921 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = d2f694d442fa3972af242e9cc22d5473 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = b6a109c28839fb4d9e911151a0c083f5 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 9c99184dff6a534f64262cda431032e4 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 0b872c241ea25f3a2e9bf5d0d6e9ca5e OK 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.001_28rmtb: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.002_28rmtb: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.003_28rmtb: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.004_28rmtb: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.005_28rmtb: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.006_28rmtb: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.007_28rmtb: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 12134e2680b3a081737bd3f30cd7d26e OK 2026/04/06 04:56:27 DEBUG : forgetting directory cache 2026/04/06 04:56:27 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b516e840): _readAt: size=512, off=0 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b516e840): openPending: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:00:27.164759218 +0000 UTC" against cached fingerprint "20,2026-04-06 03:59:27.164759218 +0000 UTC" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:00:27.164759218 +0000 UTC" != cached fingerprint "20,2026-04-06 03:59:27.164759218 +0000 UTC") 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b516e840): >openPending: err= 2026/04/06 04:56:27 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b516e840): >_readAt: n=20, err=EOF 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b516e840): close: 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate(0x27a2b516e840): >close: err= 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 9296203ff5ce02f24acff5077d4fd971 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 2ef7f923861d2314fa505c2fec3b980a OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = fb7dd751da8c9838103140b6f8a169fd OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = bf01b5e4a06d511850c53adeab31bba0 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 95db616c9229750497c32356f860455b OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = ddfcb77e3f75ebb180b61859bc4f8280 OK 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 2b6aa3927a9d982e9753aa3527436baa OK 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.001_28rmnw: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.002_28rmnw: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.003_28rmnw: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.004_28rmnw: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.005_28rmnw: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.006_28rmnw: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:27 INFO : TestRWCacheUpdate.rcc.007_28rmnw: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:27 DEBUG : TestRWCacheUpdate: md5 = 1a9def91afa94c9e913e74e68a1c16b4 OK 2026/04/06 04:56:28 DEBUG : forgetting directory cache 2026/04/06 04:56:28 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c02c0): _readAt: size=512, off=0 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c02c0): openPending: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:01:27.164759218 +0000 UTC" against cached fingerprint "20,2026-04-06 04:00:27.164759218 +0000 UTC" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:01:27.164759218 +0000 UTC" != cached fingerprint "20,2026-04-06 04:00:27.164759218 +0000 UTC") 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c02c0): >openPending: err= 2026/04/06 04:56:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c02c0): >_readAt: n=20, err=EOF 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c02c0): close: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c02c0): >close: err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = b87f951bb4f8e107223160d80418cd2b OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 0f1e2e6afe96d557ebf5767a3caed544 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 4ed431e1b759a94a4a4f09a9fcad4ee3 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 3619a8b5baa1cdc41e69870375ab1137 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 8ac0a43f25ead090fa38bbabd7005398 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = dd3902e2dbef2127d7528f2ae8f04058 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = e78d43be40e206aed6210cc7bcfc335b OK 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.001_28rnp9: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.002_28rnp9: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.003_28rnp9: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.004_28rnp9: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.005_28rnp9: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.006_28rnp9: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.007_28rnp9: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 6f645102380a4c41f71aaf0e49118d90 OK 2026/04/06 04:56:28 DEBUG : forgetting directory cache 2026/04/06 04:56:28 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c0940): _readAt: size=512, off=0 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c0940): openPending: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-06 04:02:27.164759218 +0000 UTC" against cached fingerprint "20,2026-04-06 04:01:27.164759218 +0000 UTC" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-06 04:02:27.164759218 +0000 UTC" != cached fingerprint "20,2026-04-06 04:01:27.164759218 +0000 UTC") 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c0940): >openPending: err= 2026/04/06 04:56:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c0940): >_readAt: n=20, err=EOF 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c0940): close: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c0940): >close: err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 81660680d20489d6119db82985d03b53 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = e4326dd59bb8d626542b8949b24ecf54 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = a0148ac631251b5aa2f0f759519692c3 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 79d2acea24576fc18457e346cf8061ea OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 567cbdcd43e3f752d14eafee91ca1043 OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 41f89c43659c0800cc1f357e259fa3cc OK 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 8c75a46f98655452138a5b043c4bba73 OK 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.001_28rnj0: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.002_28rnj0: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.003_28rnj0: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.004_28rnj0: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.005_28rnj0: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.006_28rnj0: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/06 04:56:28 INFO : TestRWCacheUpdate.rcc.007_28rnj0: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: md5 = 9fef5c75895318211ee0793624f9b4df OK 2026/04/06 04:56:28 DEBUG : forgetting directory cache 2026/04/06 04:56:28 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c1a40): _readAt: size=512, off=0 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c1a40): openPending: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-06 04:03:27.164759218 +0000 UTC" against cached fingerprint "20,2026-04-06 04:02:27.164759218 +0000 UTC" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-06 04:03:27.164759218 +0000 UTC" != cached fingerprint "20,2026-04-06 04:02:27.164759218 +0000 UTC") 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/06 04:56:28 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c1a40): >openPending: err= 2026/04/06 04:56:28 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c1a40): >_readAt: n=21, err=EOF 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c1a40): close: 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate(0x27a2b53c1a40): >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/06 04:56:28 DEBUG : WaitForWriters: timeout=30s 2026/04/06 04:56:28 DEBUG : Looking for writers 2026/04/06 04:56:28 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/06 04:56:28 DEBUG : >WaitForWriters: 2026/04/06 04:56:28 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-sosexun0daka': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.45s) FAIL 2026/04/06 04:56:28 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-sosexun0daka': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.549755777s (try 4/5): exit status 1: Failed [TestRWCacheUpdate]