Opening a recently closed and cached file hangs RClone

Suspected Bug
1

What is the problem you are having with rclone?

Hi,

First of all, thank you for your great work in rclone.

I've encountered a similar problem to Local Disk - openPending Hangs. When I open one test Excel file (30MB), close it, then open a second test file (5MB), close that, and reopen the first file, sometimes I get the following error:

vfs cache: failed to open item: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file

I always clear RClone cache before reattempting to trigger the issue.

The test files are available in the following links:

5MB - Example 5 MB XLSX File Download - Test File (5 MB)
30MB - Example 30 MB XLSX File Download - Test File (30 MB)

To give you some additional details, I have been unable to reproduce the issue in version 1.73.1 of rclone and the issue is harder to reproduce when the second file doesn't open as quickly (for example if using a bigger secondary test file). Furthermore, I am opening the files through Windows explorer and using Excel 2022.

Another interesting clue: setting --vfs-handle-caching 0s makes the issue unreproducible, though it increases the time needed for Excel to open the 30MB file. From what I've gathered, this was introduced in 1.74.0.

Run the command 'rclone version' and share the full output of the command.

rclone v1.74.3-DEV

  • os/version: Microsoft Windows 11 Education 24H2 24H2 (64 bit)
  • os/kernel: 10.0.26100.8655 (x86_64)
  • os/type: windows
  • os/arch: amd64
  • go/version: go1.26.4
  • go/linking: static
  • go/tags: cmount

Which cloud storage system are you using? (eg Google Drive)

Google Drive

The command you were trying to run (eg rclone copy /tmp remote:tmp)

.\rclone.exe mount GDrive: Z: --config "rclone-GDrive.conf" --vfs-refresh --links --exclude "~*" --exclude "*.tmp" --exclude ".~*" --exclude "~*" --vfs-cache-mode full --vfs-write-back 10s --vfs-read-ahead 256M --cache-dir ".\cache\"

The rclone config contents with secrets removed.

[GDrive]
type = drive
client_id = <REDACTED>
client_secret = <REDACTED>
token = {"access_token":"<REDACTED>","token_type":"Bearer","refresh_token":"<REDACTED>","expiry":"2026-06-29T17:48:07.0746628+01:00","expires_in":3599}

A log from the command with the -vv flag

2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenEx: flags=0x0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: Open: flags=O_RDONLY
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: newRWFileHandle: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >newRWFileHandle: err=<nil>
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >Open: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenFile: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenEx: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Flush: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0a200): RWFileHandle.Flush
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Flush: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Release: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0a200): RWFileHandle.Release
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0a200): close: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0a200): >close: err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Release: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenEx: flags=0x0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: Open: flags=O_RDONLY
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: newRWFileHandle: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >newRWFileHandle: err=<nil>
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >Open: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenFile: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenEx: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Flush: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0a840): RWFileHandle.Flush
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Flush: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Release: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0a840): RWFileHandle.Release
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0a840): close: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0a840): >close: err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Release: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenEx: flags=0x0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: Open: flags=O_RDONLY
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: newRWFileHandle: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >newRWFileHandle: err=<nil>
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >Open: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenFile: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenEx: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Flush: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dc740): RWFileHandle.Flush
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Flush: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Release: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dc740): RWFileHandle.Release
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dc740): close: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dc740): >close: err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Release: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenEx: flags=0x0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: Open: flags=O_RDONLY
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: newRWFileHandle: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >newRWFileHandle: err=<nil>
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >Open: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenFile: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenEx: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Flush: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dcd00): RWFileHandle.Flush
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Flush: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Release: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dcd00): RWFileHandle.Release
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dcd00): close: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dcd00): >close: err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Release: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenEx: flags=0x0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: Open: flags=O_RDONLY
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: newRWFileHandle: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >newRWFileHandle: err=<nil>
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >Open: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenFile: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenEx: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Flush: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0ae00): RWFileHandle.Flush
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Flush: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenEx: flags=0x0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: Open: flags=O_RDONLY
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Release: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0ae00): RWFileHandle.Release
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: newRWFileHandle: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0ae00): close: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0ae00): >close: err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Release: errc=0
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >newRWFileHandle: err=<nil>
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >Open: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenFile: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenEx: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Flush: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dd2c0): RWFileHandle.Flush
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Flush: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Release: fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dd2c0): RWFileHandle.Release
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dd2c0): close: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5ee9dd2c0): >close: err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Release: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Opendir: 
2026/06/29 18:43:19 DEBUG : /test_hang: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : /test_hang: >OpenFile: fd=test_hang/ (r), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang: >Opendir: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Releasedir: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: >Releasedir: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Opendir: 
2026/06/29 18:43:19 DEBUG : /test_hang: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : /test_hang: >OpenFile: fd=test_hang/ (r), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang: >Opendir: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: Releasedir: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: >Releasedir: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Opendir: 
2026/06/29 18:43:19 DEBUG : /test_hang: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : /test_hang: >OpenFile: fd=test_hang/ (r), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang: >Opendir: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: Releasedir: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: >Releasedir: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Opendir: 
2026/06/29 18:43:19 DEBUG : /test_hang: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : /test_hang: >OpenFile: fd=test_hang/ (r), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang: >Opendir: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Releasedir: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: >Releasedir: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Opendir: 
2026/06/29 18:43:19 DEBUG : /test_hang: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : /test_hang: >OpenFile: fd=test_hang/ (r), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang: >Opendir: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Releasedir: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: >Releasedir: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Opendir: 
2026/06/29 18:43:19 DEBUG : /test_hang: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : /test_hang: >OpenFile: fd=test_hang/ (r), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang: >Opendir: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: Releasedir: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: >Releasedir: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Opendir: 
2026/06/29 18:43:19 DEBUG : /test_hang: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : /test_hang: >OpenFile: fd=test_hang/ (r), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang: >Opendir: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: Releasedir: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: >Releasedir: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Opendir: 
2026/06/29 18:43:19 DEBUG : /test_hang: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : /test_hang: >OpenFile: fd=test_hang/ (r), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang: >Opendir: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Releasedir: fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang: >Releasedir: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >Getattr: errc=0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenEx: flags=0x0
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: Open: flags=O_RDONLY
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: newRWFileHandle: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >newRWFileHandle: err=<nil>
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: >Open: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenFile: fd=test_hang/30mb.xlsx (rw), err=<nil>
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: >OpenEx: errc=0, fh=0x2
2026/06/29 18:43:19 DEBUG : /test_hang/30mb.xlsx: Read: ofst=0, fh=0x2
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0be80): _readAt: size=65536, off=0
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0be80): openPending: 
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: vfs cache: checking remote fingerprint "31989470,2026-06-25 15:34:34.881 +0000 UTC,<hash-redacted>" against cached fingerprint "31989470,2026-06-25 15:34:34.881 +0000 UTC,<hash-redacted>"
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: vfs cache: truncate to size=31989470 (not needed as size correct)
2026/06/29 18:43:19 INFO  : test_hang/30mb.xlsx: vfs cache: removed cache file as item.open failed on _createFile, remove cache data/metadata files
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx: vfs cache: removed metadata from cache as item.open failed on _createFile, remove cache data/metadata files
2026/06/29 18:43:19 ERROR : test_hang/30mb.xlsx: vfs cache: failed to open item: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file
2026/06/29 18:43:19 ERROR : test_hang/30mb.xlsx: Non-out-of-space error encountered during open
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0be80): >openPending: err=open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file
2026/06/29 18:43:19 DEBUG : test_hang/30mb.xlsx(0x39d5eea0be80): >_readAt: n=0, err=open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file
2026/06/29 18:43:19 ERROR : IO error: open RW handle failed to open cache file: vfs cache item: create cache file failed: vfs cache item: internal error: didn't Close file
2

That looks worth testing against a clean 1.74.3 release build as well as the -DEV one, just to rule out a local build/debug difference. Since --vfs-handle-caching 0s makes it disappear, I’d also try a small matrix with only --vfs-cache-mode full plus handle caching at 0s/1s/default and no --vfs-refresh/read-ahead. If the minimal command still fails, that should be a pretty good repro for a VFS handle caching regression from 1.74.0.

3

The logs suggest the failure happens while recreating the cache file, so I'd focus on the VFS cache logic instead of the backend.

4

I think this is a bug in the --vfs-handle-caching code. There is a small race when closing the file which means that an open can see a half closed file which gives exactly the symptoms you have reported.

I've attempted to fix this, please try this

v1.75.0-beta.9842.bcdae6d19.fix-vfs-handle-caching-grace-close on branch fix-vfs-handle-caching-grace-close (uploaded in 15-30 mins)

5

Hi,

I am unable to reproduce the issue in that branch, it seems like your patch fixes it

6

Hi,

I was also able to reproduce in 1.74.3 release build.

With the minimal command (--vfs-cache-mode full --vfs-refresh --vfs-read-ahead 256M), I was unable to reproduce the issue after removing vfs-read-ahead. However, I believe this is because the files now take longer to open

7

Thanks for testing @Vasco_Freire

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.74.4 (in a week or so)