"./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Starting (try 4/5) 2026/04/04 05:28:26 DEBUG : Creating backend with remote "TestChunkerOverCrypt:rclone-test-tejeviv2zibu" 2026/04/04 05:28:26 DEBUG : Using config file from "/home/rclone/.rclone.conf" 2026/04/04 05:28:26 DEBUG : Creating backend with remote "__TestChunkerOverCrypt:rclone-test-tejeviv2zibu" 2026/04/04 05:28:26 DEBUG : Creating backend with remote "/tmp/test_chunker_over_crypt/o4tffh0rvem2lrgbtjq60vtpk6fsfu8tj6p3rbho3g07gc5lutu0" 2026/04/04 05:28:26 DEBUG : Creating backend with remote "/tmp/rclone3713823627" === RUN TestRWCacheUpdate run.go:185: Remote "Chunked 'TestChunkerOverCrypt:rclone-test-tejeviv2zibu'", Local "Local file system at /tmp/rclone3713823627", Modify Window "1ns" 2026/04/04 05:28:26 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-tejeviv2zibu': poll-interval is not supported by this remote 2026/04/04 05:28:26 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-tejeviv2zibu': vfs cache: root is "/home/rclone/.cache/rclone" 2026/04/04 05:28:26 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-tejeviv2zibu': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-tejeviv2zibu" 2026/04/04 05:28:26 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-tejeviv2zibu': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-tejeviv2zibu" 2026/04/04 05:28:26 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-tejeviv2zibu" 2026/04/04 05:28:26 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/04 05:28:26 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-tejeviv2zibu" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestChunkerOverCrypt/rclone-test-tejeviv2zibu" 2026/04/04 05:28:26 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-tejeviv2zibu" 2026/04/04 05:28:26 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name 2026/04/04 05:28:26 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-tejeviv2zibu" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestChunkerOverCrypt/rclone-test-tejeviv2zibu" 2026/04/04 05:28:26 INFO : Chunked 'TestChunkerOverCrypt:rclone-test-tejeviv2zibu': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0) 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = ffe5797a9e7f25d89ff92bb038ab6426 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 7ae5ab451fb402ae78bc4d032ebf09c8 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = af68131d95056f47f1bd9a1d71e1275e OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 45b6166833e2a0ee2824ffca24b8062b OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 53eceb8baa53de6ccc67123cabbb51f1 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 4147feb47a915543234f7c71f8491d1c OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = d1dcfb9399a30f93de3f0d0f6da7cdfd OK 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.001_ykwqa4: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.002_ykwqa4: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.003_ykwqa4: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.004_ykwqa4: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.005_ykwqa4: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.006_ykwqa4: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.007_ykwqa4: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = e93635abeb5ff6b2c575774aba7b79ca OK 2026/04/04 05:28:26 DEBUG : forgetting directory cache 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aa9ae840): _readAt: size=512, off=0 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aa9ae840): openPending: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:29:26.154940883 +0000 UTC" against cached fingerprint "" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 2026/04/04 05:28:26 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aa9ae840): >openPending: err= 2026/04/04 05:28:26 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aa9ae840): >_readAt: n=20, err=EOF 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aa9ae840): close: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aa9ae840): >close: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = c3979ced7fc93ce9c5491921b0a07f6f OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 1bc5ad0f6fdf6dee0a7dd1b86dfa7647 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 511d9193116b45d4fac288b333f622bc OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 2d26c94b33b6314eca5cd9ee189d303d OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = e718be220c11f00fc6ce5d9727c15165 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 04d8f7f9a5b196a19b105269ad38efe7 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 965287a28f833b6afbdf6df1c4763701 OK 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.001_ykwqjl: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.002_ykwqjl: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.003_ykwqjl: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.004_ykwqjl: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.005_ykwqjl: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.006_ykwqjl: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.007_ykwqjl: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = d0e893060420e6948d31ebed726eda58 OK 2026/04/04 05:28:26 DEBUG : forgetting directory cache 2026/04/04 05:28:26 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aabeed00): _readAt: size=512, off=0 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aabeed00): openPending: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:30:26.154940883 +0000 UTC" against cached fingerprint "20,2026-04-04 04:29:26.154940883 +0000 UTC" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:30:26.154940883 +0000 UTC" != cached fingerprint "20,2026-04-04 04:29:26.154940883 +0000 UTC") 2026/04/04 05:28:26 INFO : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different) 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different) 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:26 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aabeed00): >openPending: err= 2026/04/04 05:28:26 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aabeed00): >_readAt: n=20, err=EOF 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aabeed00): close: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aabeed00): >close: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = bff16f377777f07f9b684b2bae6effda OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 74751698437d60625296ab73f536475b OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 96d73672bcef6b88205f65c94f4d6cfb OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 3641b7b0da6fd60fbd3f8a6c4036901b OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = b7af99c845258abb7b214960af94f9c7 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 9a67b034f30f660a1af70ea29e1bde50 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 12cd7f3df9bce88590615cc4b19db73d OK 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.001_ykwqsw: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.002_ykwqsw: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.003_ykwqsw: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.004_ykwqsw: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.005_ykwqsw: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.006_ykwqsw: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.007_ykwqsw: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = ca6a1e8f6f443f20a5bb90435b3912b5 OK 2026/04/04 05:28:26 DEBUG : forgetting directory cache 2026/04/04 05:28:26 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aab73780): _readAt: size=512, off=0 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aab73780): openPending: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:31:26.154940883 +0000 UTC" against cached fingerprint "20,2026-04-04 04:30:26.154940883 +0000 UTC" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:31:26.154940883 +0000 UTC" != cached fingerprint "20,2026-04-04 04:30:26.154940883 +0000 UTC") 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:26 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aab73780): >openPending: err= 2026/04/04 05:28:26 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aab73780): >_readAt: n=20, err=EOF 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aab73780): close: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929aab73780): >close: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = e51c37d0e988da8b94f1a507b4b16bfb OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 909633e117c4e4b530963352811556d8 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 41505aed7f0fb2a71c3ec766942c18b5 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = f9056c602ccb5c60ceb84fd30aa1545e OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 3cb18cc432fda9745ddaa91c564893f4 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 2bd507f91a69e53a4794477162de5862 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 47d159c6b0468e5362b8eb25cb10a708 OK 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.001_ykwqui: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.002_ykwqui: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.003_ykwqui: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.004_ykwqui: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.005_ykwqui: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.006_ykwqui: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.007_ykwqui: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 5caad14c8191f2884bf5583405ab31dd OK 2026/04/04 05:28:26 DEBUG : forgetting directory cache 2026/04/04 05:28:26 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929ac190240): _readAt: size=512, off=0 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929ac190240): openPending: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:32:26.154940883 +0000 UTC" against cached fingerprint "20,2026-04-04 04:31:26.154940883 +0000 UTC" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:32:26.154940883 +0000 UTC" != cached fingerprint "20,2026-04-04 04:31:26.154940883 +0000 UTC") 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:26 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929ac190240): >openPending: err= 2026/04/04 05:28:26 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929ac190240): >_readAt: n=20, err=EOF 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929ac190240): close: 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate(0x929ac190240): >close: err= 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = c51ad6339a4897fa4c12fe1122f63d74 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 61e4b73cc36294cca2b2822ab92a91dc OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 4e298d086890f9b689f0e0ae2f87ff50 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 334e76dbf08396b944693dcda7d0b558 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = c2616519ef38e09e90cfd66229c22001 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 40a87adebec4a9d6e7d81cf33e6fc190 OK 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = 60f16e0d3022a0bddb647e33ec8bfe01 OK 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.001_ykwq10: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.002_ykwq10: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.003_ykwq10: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.004_ykwq10: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.005_ykwq10: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.006_ykwq10: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:26 INFO : TestRWCacheUpdate.rcc.007_ykwq10: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:26 DEBUG : TestRWCacheUpdate: md5 = ebbaedba4f67fb5123d84234a3de890d OK 2026/04/04 05:28:27 DEBUG : forgetting directory cache 2026/04/04 05:28:27 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aab2bb40): _readAt: size=512, off=0 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aab2bb40): openPending: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:33:26.154940883 +0000 UTC" against cached fingerprint "20,2026-04-04 04:32:26.154940883 +0000 UTC" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:33:26.154940883 +0000 UTC" != cached fingerprint "20,2026-04-04 04:32:26.154940883 +0000 UTC") 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aab2bb40): >openPending: err= 2026/04/04 05:28:27 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aab2bb40): >_readAt: n=20, err=EOF 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aab2bb40): close: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aab2bb40): >close: err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 5786a636042c4468fdf7c0c09340ea6b OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = df826602a995bc43955ae27a7c6ebfab OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = f0f6dd329957210a3ad5b8aa11361016 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = b905b377cb80ee7cc49f9376c9851567 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 9bd7ab37d9a225f7850ee8a958b22e25 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = efd65ffcc93b78216ee121d59956fd94 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 26c134c2789f7590d2accd0ebf65eb46 OK 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.001_ykwri4: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.002_ykwri4: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.003_ykwri4: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.004_ykwri4: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.005_ykwri4: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.006_ykwri4: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.007_ykwri4: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = fe3b736932a0d05372d0f91fae76323f OK 2026/04/04 05:28:27 DEBUG : forgetting directory cache 2026/04/04 05:28:27 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929ac2c0c40): _readAt: size=512, off=0 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929ac2c0c40): openPending: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2026-04-04 04:34:26.154940883 +0000 UTC" against cached fingerprint "20,2026-04-04 04:33:26.154940883 +0000 UTC" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2026-04-04 04:34:26.154940883 +0000 UTC" != cached fingerprint "20,2026-04-04 04:33:26.154940883 +0000 UTC") 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929ac2c0c40): >openPending: err= 2026/04/04 05:28:27 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929ac2c0c40): >_readAt: n=20, err=EOF 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929ac2c0c40): close: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929ac2c0c40): >close: err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = c2aa56de2ab482ad6b7e9942db18e0bf OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = fff7ab3abb9940787db7f34eac9cec78 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 2bcf0d6dfd72c8cfadb1da9fa85090c0 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 8eb05e41cb32991e5ef657eab0954478 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 87155378d26f9561791e84ac16a4a628 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = e44d2bd162bd0d39b941134e20f2e4f6 OK 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = f42c841d2cdece941a8ed13e58fe67f3 OK 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.001_ykwr3z: Moved (server-side) to: TestRWCacheUpdate.rcc.001 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.002_ykwr3z: Moved (server-side) to: TestRWCacheUpdate.rcc.002 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.003_ykwr3z: Moved (server-side) to: TestRWCacheUpdate.rcc.003 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.004_ykwr3z: Moved (server-side) to: TestRWCacheUpdate.rcc.004 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.005_ykwr3z: Moved (server-side) to: TestRWCacheUpdate.rcc.005 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.006_ykwr3z: Moved (server-side) to: TestRWCacheUpdate.rcc.006 2026/04/04 05:28:27 INFO : TestRWCacheUpdate.rcc.007_ykwr3z: Moved (server-side) to: TestRWCacheUpdate.rcc.007 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: md5 = 52472c7363b96afb8269bb0ff6a80a88 OK 2026/04/04 05:28:27 DEBUG : forgetting directory cache 2026/04/04 05:28:27 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=---------- 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err= 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aabef940): _readAt: size=512, off=0 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aabef940): openPending: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2026-04-04 04:35:26.154940883 +0000 UTC" against cached fingerprint "20,2026-04-04 04:34:26.154940883 +0000 UTC" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2026-04-04 04:35:26.154940883 +0000 UTC" != cached fingerprint "20,2026-04-04 04:34:26.154940883 +0000 UTC") 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20 (not needed as size correct) 2026/04/04 05:28:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate" 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aabef940): >openPending: err= 2026/04/04 05:28:27 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: Size has changed from 20 to 21 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aabef940): >_readAt: n=21, err=EOF 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aabef940): close: 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate(0x929aabef940): >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/04 05:28:27 DEBUG : WaitForWriters: timeout=30s 2026/04/04 05:28:27 DEBUG : Looking for writers 2026/04/04 05:28:27 DEBUG : TestRWCacheUpdate: reading active writers 2026/04/04 05:28:27 DEBUG : >WaitForWriters: 2026/04/04 05:28:27 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-tejeviv2zibu': vfs cache: cleaner exiting --- FAIL: TestRWCacheUpdate (1.45s) FAIL 2026/04/04 05:28:27 DEBUG : Chunked 'TestChunkerOverCrypt:rclone-test-tejeviv2zibu': Purge dir "" "./vfs.test -test.v -test.timeout 1h0m0s -remote TestChunkerOverCrypt: -verbose -size-limit 6144 -test.run '^TestRWCacheUpdate$'" - Finished ERROR in 1.573153276s (try 4/5): exit status 1: Failed [TestRWCacheUpdate]