chore(mount,fuse-test): diagnostics for FUSE ConcurrentReadWrite ENOENT flake

PR #9230 attempt 1 hit an intermittent
TestConcurrentFileOperations/ConcurrentReadWrite failure where stat
returned ENOENT for a path all writers had just succeeded against, and
the captured mount.log carried no signal about which layer dropped the
entry because the relevant lookup logged at V(4).

Two diagnostic-only changes (no behavior change on the happy path):

- weed/mount/weedfs.go: in lookupEntry, when filer GetEntry returns
  ErrNotFound for a path whose inode is still tracked locally with no
  in-flight create or flush, log Warningf with inode + dirtyHandle +
  pendingFlush + localCache + dirCached. This surfaces layer-by-layer
  state at the moment of the suspicious ENOENT.

- test/fuse_integration/framework_test.go: on AssertFileExists failure,
  dump five 100ms-spaced stat retries, a parent ReadDir, and a direct
  O_RDONLY open before failing. Triangulates kernel dentry caching vs
  mount lookup vs filer state.
This commit is contained in:
Chris Lu
2026-04-26 16:57:37 -07:00
parent c934b5dab6
commit 6cbcdf488c
2 changed files with 88 additions and 6 deletions
+68 -2
View File
@@ -370,11 +370,77 @@ func findWeedBinary() string {
// Helper functions for test assertions
// AssertFileExists checks if a file exists in the mount point
// AssertFileExists checks if a file exists in the mount point. On failure,
// it gathers diagnostic state (retry stat, parent listing, direct open) so
// transient FUSE flakes leave enough information to identify the layer that
// dropped the entry. The diagnostic block runs only on the failure path.
func (f *FuseTestFramework) AssertFileExists(relativePath string) {
fullPath := filepath.Join(f.mountPoint, relativePath)
_, err := os.Stat(fullPath)
require.NoError(f.t, err, "file should exist: %s", relativePath)
if err == nil {
return
}
f.dumpExistenceDiagnostics(relativePath, fullPath, err)
require.NoError(f.t, err, "file should exist: %s (see diagnostic logs above)", relativePath)
}
// dumpExistenceDiagnostics is invoked when AssertFileExists fails. It probes
// whether the missing entry is transient (retries appear), missing from the
// parent directory listing, or missing via a direct open syscall — three
// signals that triangulate where the entry was lost (kernel dentry cache vs
// mount lookup vs filer).
func (f *FuseTestFramework) dumpExistenceDiagnostics(relativePath, fullPath string, initialErr error) {
f.t.Logf("AssertFileExists diagnostic dump for %s", relativePath)
f.t.Logf(" initial stat: err=%v isNotExist=%v", initialErr, os.IsNotExist(initialErr))
// Retry stat to detect transient invisibility — if it becomes visible
// the issue is a short-lived dentry/cache window; if it stays missing
// the entry is genuinely gone from the filer or the local cache.
for attempt := 1; attempt <= 5; attempt++ {
time.Sleep(100 * time.Millisecond)
_, err := os.Stat(fullPath)
f.t.Logf(" retry #%d after %dms: err=%v", attempt, attempt*100, err)
if err == nil {
break
}
}
// List the parent directory: if the file appears here but stat fails,
// the failure is in the kernel's per-name dentry cache; if not, the
// mount-side LOOKUP itself is dropping the entry.
parentDir := filepath.Dir(fullPath)
target := filepath.Base(fullPath)
if entries, listErr := os.ReadDir(parentDir); listErr != nil {
f.t.Logf(" ReadDir(%s) failed: %v", parentDir, listErr)
} else {
found := false
names := make([]string, 0, len(entries))
for _, e := range entries {
names = append(names, e.Name())
if e.Name() == target {
found = true
}
}
f.t.Logf(" ReadDir(%s): %d entries, target %q present=%v", parentDir, len(entries), target, found)
if len(names) <= 32 {
f.t.Logf(" ReadDir entries: %v", names)
}
}
// Direct O_RDONLY open — exercises the same FUSE Lookup+Open path
// userspace would, but separately from stat, in case stat-only caching
// is interfering.
if fd, openErr := os.OpenFile(fullPath, os.O_RDONLY, 0); openErr != nil {
f.t.Logf(" Open(%s, O_RDONLY): %v", fullPath, openErr)
} else {
st, statErr := fd.Stat()
fd.Close()
size := int64(-1)
if statErr == nil && st != nil {
size = st.Size()
}
f.t.Logf(" Open(%s, O_RDONLY): success size=%d statErr=%v", fullPath, size, statErr)
}
}
// AssertFileNotExists checks if a file does not exist in the mount point
+20 -4
View File
@@ -606,13 +606,15 @@ func (wfs *WFS) lookupEntry(fullpath util.FullPath) (*filer.Entry, fuse.Status)
// the local store when an open file handle or pending async flush
// confirms the entry is genuinely local-only; otherwise a stale
// cache hit could resurrect a deleted/renamed entry.
if inode, inodeFound := wfs.inodeToPath.GetInode(fullpath); inodeFound {
hasDirtyHandle := false
inode, inodeFound := wfs.inodeToPath.GetInode(fullpath)
hasDirtyHandle := false
hasPendingFlush := false
if inodeFound {
if fh, fhFound := wfs.fhMap.FindFileHandle(inode); fhFound && fh.dirtyMetadata {
hasDirtyHandle = true
}
wfs.pendingAsyncFlushMu.Lock()
_, hasPendingFlush := wfs.pendingAsyncFlush[inode]
_, hasPendingFlush = wfs.pendingAsyncFlush[inode]
wfs.pendingAsyncFlushMu.Unlock()
if hasDirtyHandle || hasPendingFlush {
@@ -622,7 +624,21 @@ func (wfs *WFS) lookupEntry(fullpath util.FullPath) (*filer.Entry, fuse.Status)
}
}
}
glog.V(4).Infof("lookupEntry not found %s", fullpath)
if inodeFound {
// Filer reports ErrNotFound for a path the kernel/local map
// still tracks, with no in-flight create or flush to excuse
// it. Log loudly (Warningf, not V(4)) so flake captures show
// up without -v=4 — and include layer-by-layer state so the
// next failed run pinpoints which layer dropped the entry.
localPresent := false
if localEntry, localErr := wfs.metaCache.FindEntry(context.Background(), fullpath); localErr == nil && localEntry != nil {
localPresent = true
}
glog.Warningf("lookupEntry: filer ErrNotFound for tracked path %s (inode=%d dirtyHandle=%v pendingFlush=%v localCache=%v dirCached=%v) — possible coherence bug",
fullpath, inode, hasDirtyHandle, hasPendingFlush, localPresent, wfs.metaCache.IsDirectoryCached(dirPath))
} else {
glog.V(4).Infof("lookupEntry not found %s", fullpath)
}
return nil, fuse.ENOENT
}
glog.Warningf("lookupEntry GetEntry %s: %v", fullpath, err)