From 6cbcdf488ceba13a4450e20843445d0999b0d3ab Mon Sep 17 00:00:00 2001 From: Chris Lu Date: Sun, 26 Apr 2026 16:57:37 -0700 Subject: [PATCH] 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. --- test/fuse_integration/framework_test.go | 70 ++++++++++++++++++++++++- weed/mount/weedfs.go | 24 +++++++-- 2 files changed, 88 insertions(+), 6 deletions(-) diff --git a/test/fuse_integration/framework_test.go b/test/fuse_integration/framework_test.go index b7f61e0aa..91497aad3 100644 --- a/test/fuse_integration/framework_test.go +++ b/test/fuse_integration/framework_test.go @@ -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 diff --git a/weed/mount/weedfs.go b/weed/mount/weedfs.go index eb8f2308a..9b4953e48 100644 --- a/weed/mount/weedfs.go +++ b/weed/mount/weedfs.go @@ -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)