"./vfs.test -test.v -test.timeout 2h0m0s -remote TestPutio: -verbose -test.run '^TestRWCacheUpdate$'" - Starting (try 2/5)
2025/08/09 01:32:10 DEBUG : Creating backend with remote "TestPutio:rclone-test-qilujal4yuwe"
2025/08/09 01:32:10 DEBUG : Using config file from "/home/rclone/.rclone.conf"
2025/08/09 01:32:10 DEBUG : Creating backend with remote "/tmp/rclone1382898388"
=== RUN   TestRWCacheUpdate
    run.go:180: Remote "Putio root 'rclone-test-qilujal4yuwe'", Local "Local file system at /tmp/rclone1382898388", Modify Window "1s"
2025/08/09 01:32:10 INFO  : Putio root 'rclone-test-qilujal4yuwe': poll-interval is not supported by this remote
2025/08/09 01:32:10 DEBUG : Putio root 'rclone-test-qilujal4yuwe': vfs cache: root is "/home/rclone/.cache/rclone"
2025/08/09 01:32:10 DEBUG : Putio root 'rclone-test-qilujal4yuwe': vfs cache: data root is "/home/rclone/.cache/rclone/vfs/TestPutio/rclone-test-qilujal4yuwe"
2025/08/09 01:32:10 DEBUG : Putio root 'rclone-test-qilujal4yuwe': vfs cache: metadata root is "/home/rclone/.cache/rclone/vfsMeta/TestPutio/rclone-test-qilujal4yuwe"
2025/08/09 01:32:10 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestPutio/rclone-test-qilujal4yuwe"
2025/08/09 01:32:10 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/09 01:32:10 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfs/TestPutio/rclone-test-qilujal4yuwe" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfs/TestPutio/rclone-test-qilujal4yuwe"
2025/08/09 01:32:10 DEBUG : Creating backend with remote ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestPutio/rclone-test-qilujal4yuwe"
2025/08/09 01:32:10 DEBUG : :local: detected overridden config - adding "{8un-i}" suffix to name
2025/08/09 01:32:10 DEBUG : fs cache: renaming cache item ":local,encoding='Slash,Dot',links=false:/home/rclone/.cache/rclone/vfsMeta/TestPutio/rclone-test-qilujal4yuwe" to be canonical ":local{8un-i}:/home/rclone/.cache/rclone/vfsMeta/TestPutio/rclone-test-qilujal4yuwe"
2025/08/09 01:32:10 INFO  : Putio root 'rclone-test-qilujal4yuwe': vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2025/08/09 01:32:10 DEBUG : forgetting directory cache
2025/08/09 01:32:11 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 20
2025/08/09 01:32:11 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 20
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate(0xc0002d6840): _readAt: size=512, off=0
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate(0xc0002d6840): openPending: 
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-08-09 00:33:10 +0000 UTC,36019ec9" against cached fingerprint ""
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20
2025/08/09 01:32:12 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate(0xc0002d6840): >openPending: err=<nil>
2025/08/09 01:32:12 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:12 DEBUG : forgetting directory cache
2025/08/09 01:32:12 DEBUG : forgetting directory cache
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate(0xc0002d6840): >_readAt: n=20, err=EOF
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate(0xc0002d6840): close: 
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:33:10 +0000 UTC
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate(0xc0002d6840): >close: err=<nil>
2025/08/09 01:32:12 DEBUG : Re-reading directory (457.753823ms old)
2025/08/09 01:32:12 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:12 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:12 DEBUG : forgetting directory cache
2025/08/09 01:32:13 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 20
2025/08/09 01:32:13 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 20
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate(0xc000396440): _readAt: size=512, off=0
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate(0xc000396440): openPending: 
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-08-09 00:34:10 +0000 UTC,4106ae5f" against cached fingerprint "20,2025-08-09 00:33:10 +0000 UTC,36019ec9"
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-08-09 00:34:10 +0000 UTC,4106ae5f" != cached fingerprint "20,2025-08-09 00:33:10 +0000 UTC,36019ec9")
2025/08/09 01:32:13 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20
2025/08/09 01:32:13 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate(0xc000396440): >openPending: err=<nil>
2025/08/09 01:32:13 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:13 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:14 DEBUG : forgetting directory cache
2025/08/09 01:32:14 DEBUG : forgetting directory cache
2025/08/09 01:32:14 DEBUG : TestRWCacheUpdate(0xc000396440): >_readAt: n=20, err=EOF
2025/08/09 01:32:14 DEBUG : TestRWCacheUpdate(0xc000396440): close: 
2025/08/09 01:32:14 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:34:10 +0000 UTC
2025/08/09 01:32:14 DEBUG : TestRWCacheUpdate(0xc000396440): >close: err=<nil>
2025/08/09 01:32:14 DEBUG : Re-reading directory (460.567291ms old)
2025/08/09 01:32:14 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:14 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:14 DEBUG : forgetting directory cache
2025/08/09 01:32:14 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 20
2025/08/09 01:32:14 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 20
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate(0xc000140b80): _readAt: size=512, off=0
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate(0xc000140b80): openPending: 
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-08-09 00:35:10 +0000 UTC,d80fffe5" against cached fingerprint "20,2025-08-09 00:34:10 +0000 UTC,4106ae5f"
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-08-09 00:35:10 +0000 UTC,d80fffe5" != cached fingerprint "20,2025-08-09 00:34:10 +0000 UTC,4106ae5f")
2025/08/09 01:32:15 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20
2025/08/09 01:32:15 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate(0xc000140b80): >openPending: err=<nil>
2025/08/09 01:32:15 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:15 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:15 DEBUG : forgetting directory cache
2025/08/09 01:32:16 DEBUG : forgetting directory cache
2025/08/09 01:32:16 DEBUG : forgetting directory cache
2025/08/09 01:32:16 DEBUG : TestRWCacheUpdate(0xc000140b80): >_readAt: n=20, err=EOF
2025/08/09 01:32:16 DEBUG : TestRWCacheUpdate(0xc000140b80): close: 
2025/08/09 01:32:16 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:35:10 +0000 UTC
2025/08/09 01:32:16 DEBUG : TestRWCacheUpdate(0xc000140b80): >close: err=<nil>
2025/08/09 01:32:16 DEBUG : Re-reading directory (705.926883ms old)
2025/08/09 01:32:16 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:16 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:16 DEBUG : forgetting directory cache
2025/08/09 01:32:16 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 20
2025/08/09 01:32:16 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 20
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate(0xc0002d7580): _readAt: size=512, off=0
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate(0xc0002d7580): openPending: 
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-08-09 00:36:10 +0000 UTC,af08cf73" against cached fingerprint "20,2025-08-09 00:35:10 +0000 UTC,d80fffe5"
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-08-09 00:36:10 +0000 UTC,af08cf73" != cached fingerprint "20,2025-08-09 00:35:10 +0000 UTC,d80fffe5")
2025/08/09 01:32:17 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20
2025/08/09 01:32:17 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate(0xc0002d7580): >openPending: err=<nil>
2025/08/09 01:32:17 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:17 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:18 DEBUG : forgetting directory cache
2025/08/09 01:32:18 DEBUG : TestRWCacheUpdate(0xc0002d7580): >_readAt: n=20, err=EOF
2025/08/09 01:32:18 DEBUG : TestRWCacheUpdate(0xc0002d7580): close: 
2025/08/09 01:32:18 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:36:10 +0000 UTC
2025/08/09 01:32:18 DEBUG : TestRWCacheUpdate(0xc0002d7580): >close: err=<nil>
2025/08/09 01:32:18 DEBUG : Re-reading directory (378.38991ms old)
2025/08/09 01:32:18 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:18 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:18 DEBUG : forgetting directory cache
2025/08/09 01:32:18 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 20
2025/08/09 01:32:18 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 20
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate(0xc0002d6800): _readAt: size=512, off=0
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate(0xc0002d6800): openPending: 
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-08-09 00:37:10 +0000 UTC,316c5ad0" against cached fingerprint "20,2025-08-09 00:36:10 +0000 UTC,af08cf73"
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-08-09 00:37:10 +0000 UTC,316c5ad0" != cached fingerprint "20,2025-08-09 00:36:10 +0000 UTC,af08cf73")
2025/08/09 01:32:19 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20
2025/08/09 01:32:19 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate(0xc0002d6800): >openPending: err=<nil>
2025/08/09 01:32:19 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:19 DEBUG : forgetting directory cache
2025/08/09 01:32:19 DEBUG : forgetting directory cache
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate(0xc0002d6800): >_readAt: n=20, err=EOF
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate(0xc0002d6800): close: 
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:37:10 +0000 UTC
2025/08/09 01:32:19 DEBUG : TestRWCacheUpdate(0xc0002d6800): >close: err=<nil>
2025/08/09 01:32:19 DEBUG : Re-reading directory (413.733711ms old)
2025/08/09 01:32:20 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:20 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:20 DEBUG : forgetting directory cache
2025/08/09 01:32:20 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 20
2025/08/09 01:32:20 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 20
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate(0xc000396f00): _readAt: size=512, off=0
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate(0xc000396f00): openPending: 
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "20,2025-08-09 00:38:10 +0000 UTC,466b6a46" against cached fingerprint "20,2025-08-09 00:37:10 +0000 UTC,316c5ad0"
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "20,2025-08-09 00:38:10 +0000 UTC,466b6a46" != cached fingerprint "20,2025-08-09 00:37:10 +0000 UTC,316c5ad0")
2025/08/09 01:32:21 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=20
2025/08/09 01:32:21 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate(0xc000396f00): >openPending: err=<nil>
2025/08/09 01:32:21 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [] - present false
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:21 DEBUG : forgetting directory cache
2025/08/09 01:32:21 DEBUG : forgetting directory cache
2025/08/09 01:32:21 DEBUG : forgetting directory cache
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate(0xc000396f00): >_readAt: n=20, err=EOF
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate(0xc000396f00): close: 
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:38:10 +0000 UTC
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate(0xc000396f00): >close: err=<nil>
2025/08/09 01:32:21 DEBUG : Re-reading directory (715.133269ms old)
2025/08/09 01:32:21 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:21 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:22 DEBUG : forgetting directory cache
2025/08/09 01:32:26 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 21
2025/08/09 01:32:26 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 21
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate(0xc0002d6a40): _readAt: size=512, off=0
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate(0xc0002d6a40): openPending: 
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "21,2025-08-09 00:39:10 +0000 UTC,bd6dfa57" against cached fingerprint "20,2025-08-09 00:38:10 +0000 UTC,466b6a46"
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "21,2025-08-09 00:39:10 +0000 UTC,bd6dfa57" != cached fingerprint "20,2025-08-09 00:38:10 +0000 UTC,466b6a46")
2025/08/09 01:32:27 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=21
2025/08/09 01:32:27 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate(0xc0002d6a40): >openPending: err=<nil>
2025/08/09 01:32:27 DEBUG : vfs cache: looking for range={Pos:0 Size:21} in [] - present false
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:27 DEBUG : forgetting directory cache
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate(0xc0002d6a40): >_readAt: n=21, err=EOF
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate(0xc0002d6a40): close: 
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:39:10 +0000 UTC
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate(0xc0002d6a40): >close: err=<nil>
2025/08/09 01:32:27 DEBUG : Re-reading directory (395.904569ms old)
2025/08/09 01:32:27 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:27 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:27 DEBUG : forgetting directory cache
2025/08/09 01:32:28 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 22
2025/08/09 01:32:28 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 22
2025/08/09 01:32:28 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate(0xc0009ded80): _readAt: size=512, off=0
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate(0xc0009ded80): openPending: 
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "22,2025-08-09 00:40:10 +0000 UTC,fdc9e5c1" against cached fingerprint "21,2025-08-09 00:39:10 +0000 UTC,bd6dfa57"
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "22,2025-08-09 00:40:10 +0000 UTC,fdc9e5c1" != cached fingerprint "21,2025-08-09 00:39:10 +0000 UTC,bd6dfa57")
2025/08/09 01:32:29 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=22
2025/08/09 01:32:29 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate(0xc0009ded80): >openPending: err=<nil>
2025/08/09 01:32:29 DEBUG : vfs cache: looking for range={Pos:0 Size:22} in [] - present false
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:29 DEBUG : forgetting directory cache
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate(0xc0009ded80): >_readAt: n=22, err=EOF
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate(0xc0009ded80): close: 
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:40:10 +0000 UTC
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate(0xc0009ded80): >close: err=<nil>
2025/08/09 01:32:29 DEBUG : Re-reading directory (334.57943ms old)
2025/08/09 01:32:29 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:29 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:29 DEBUG : forgetting directory cache
2025/08/09 01:32:29 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 23
2025/08/09 01:32:29 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 23
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate(0xc000a00400): _readAt: size=512, off=0
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate(0xc000a00400): openPending: 
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "23,2025-08-09 00:41:10 +0000 UTC,bd440dce" against cached fingerprint "22,2025-08-09 00:40:10 +0000 UTC,fdc9e5c1"
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "23,2025-08-09 00:41:10 +0000 UTC,bd440dce" != cached fingerprint "22,2025-08-09 00:40:10 +0000 UTC,fdc9e5c1")
2025/08/09 01:32:30 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=23
2025/08/09 01:32:30 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate(0xc000a00400): >openPending: err=<nil>
2025/08/09 01:32:30 DEBUG : vfs cache: looking for range={Pos:0 Size:23} in [] - present false
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:30 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:30 DEBUG : forgetting directory cache
2025/08/09 01:32:31 DEBUG : TestRWCacheUpdate(0xc000a00400): >_readAt: n=23, err=EOF
2025/08/09 01:32:31 DEBUG : TestRWCacheUpdate(0xc000a00400): close: 
2025/08/09 01:32:31 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:41:10 +0000 UTC
2025/08/09 01:32:31 DEBUG : TestRWCacheUpdate(0xc000a00400): >close: err=<nil>
2025/08/09 01:32:31 DEBUG : Re-reading directory (321.975687ms old)
2025/08/09 01:32:31 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:31 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:31 DEBUG : forgetting directory cache
2025/08/09 01:32:31 DEBUG : Putio root 'rclone-test-qilujal4yuwe': chunkStart: 0, reqSize: 24
2025/08/09 01:32:31 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Sending chunk. transferOffset: 0 length: 24
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: OpenFile: flags=O_RDONLY, perm=----------
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: Open: flags=O_RDONLY
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: newRWFileHandle: 
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: >newRWFileHandle: err=<nil>
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: >Open: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: >OpenFile: fd=TestRWCacheUpdate (rw), err=<nil>
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate(0xc000486940): _readAt: size=512, off=0
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate(0xc000486940): openPending: 
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: vfs cache: checking remote fingerprint "24,2025-08-09 00:42:10 +0000 UTC,48b8a451" against cached fingerprint "23,2025-08-09 00:41:10 +0000 UTC,bd440dce"
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: vfs cache: removing cached entry as stale (remote fingerprint "24,2025-08-09 00:42:10 +0000 UTC,48b8a451" != cached fingerprint "23,2025-08-09 00:41:10 +0000 UTC,bd440dce")
2025/08/09 01:32:32 INFO  : TestRWCacheUpdate: vfs cache: removed cache file as stale (remote is different)
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: vfs cache: removed metadata from cache as stale (remote is different)
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: vfs cache: truncate to size=24
2025/08/09 01:32:32 DEBUG : Added virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate(0xc000486940): >openPending: err=<nil>
2025/08/09 01:32:32 DEBUG : vfs cache: looking for range={Pos:0 Size:24} in [] - present false
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: ChunkedReader.RangeSeek from -1 to 0 length -1
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: ChunkedReader.openRange at 0 length 134217728
2025/08/09 01:32:32 DEBUG : forgetting directory cache
2025/08/09 01:32:32 DEBUG : forgetting directory cache
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate(0xc000486940): >_readAt: n=24, err=EOF
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate(0xc000486940): close: 
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: vfs cache: setting modification time to 2025-08-09 00:42:10 +0000 UTC
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate(0xc000486940): >close: err=<nil>
2025/08/09 01:32:32 DEBUG : Re-reading directory (403.846087ms old)
2025/08/09 01:32:32 DEBUG : Removed virtual directory entry vAddFile: "TestRWCacheUpdate"
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: Reset virtual modtime
2025/08/09 01:32:32 DEBUG : WaitForWriters: timeout=30s
2025/08/09 01:32:32 DEBUG : Looking for writers
2025/08/09 01:32:32 DEBUG : TestRWCacheUpdate: reading active writers
2025/08/09 01:32:32 DEBUG : >WaitForWriters: 
2025/08/09 01:32:32 DEBUG : Putio root 'rclone-test-qilujal4yuwe': vfs cache: cleaner exiting
2025/08/09 01:32:32 DEBUG : forgetting directory cache
--- PASS: TestRWCacheUpdate (22.47s)
PASS
2025/08/09 01:32:33 DEBUG : Putio root 'rclone-test-qilujal4yuwe': Purge remote
"./vfs.test -test.v -test.timeout 2h0m0s -remote TestPutio: -verbose -test.run '^TestRWCacheUpdate$'" - Finished OK in 23.111655918s (try 2/5)