From d1e92fb3583a982dd3ad5d344578ea36b8bf8e59 Mon Sep 17 00:00:00 2001 From: Dan Fuhry Date: Sat, 14 Mar 2026 19:39:19 -0400 Subject: [PATCH] [mtls/fsnotify] hush fsnotify debug log messages --- mtls/fsnotify/fsnotify.go | 105 ++++++++++++++++++++------------------ 1 file changed, 55 insertions(+), 50 deletions(-) diff --git a/mtls/fsnotify/fsnotify.go b/mtls/fsnotify/fsnotify.go index 0fd985a..23f8fef 100644 --- a/mtls/fsnotify/fsnotify.go +++ b/mtls/fsnotify/fsnotify.go @@ -29,23 +29,26 @@ import ( "sync" "go.fuhry.dev/fsnotify" + "go.fuhry.dev/runtime/utils/hashset" "go.fuhry.dev/runtime/utils/log" ) -type NotifyFunc = func(string, fsnotify.Op) -type notifyRule struct { - // absPath is the real path of the file after resolving all symlinks both in the filename - // itself, and in any of the directories in the path components of the file's absolute path. - absPath string - // inum is the inode number of the underlying file after resolving - // all symlinks. - inum int64 - // upstreams is a HashSet of the original filename, target filename, and all intermediates - // in between - upstreams *hashset.HashSet[string] - callbacks []NotifyFunc -} +type ( + NotifyFunc = func(string, fsnotify.Op) + notifyRule struct { + // absPath is the real path of the file after resolving all symlinks both in the filename + // itself, and in any of the directories in the path components of the file's absolute path. + absPath string + // inum is the inode number of the underlying file after resolving + // all symlinks. + inum int64 + // upstreams is a HashSet of the original filename, target filename, and all intermediates + // in between + upstreams *hashset.HashSet[string] + callbacks []NotifyFunc + } +) type Op = fsnotify.Op @@ -58,9 +61,11 @@ var ( Close = fsnotify.Close ) -var startWatcherMu sync.Mutex -var gWatcher *fsnotify.Watcher -var logger log.Logger +var ( + startWatcherMu sync.Mutex + gWatcher *fsnotify.Watcher + logger log.Logger +) // Map of original path => notifyRule. // This tracks paths we were asked to watch. More paths may be watched than the entries here, if @@ -86,7 +91,7 @@ func startWatcher() error { return nil } - logger = log.Default().WithPrefix("mtls/fsnotify") + logger = log.Default().WithPrefix("mtls/fsnotify").V(4) initState() // inodes = make(map[string]int64) watcher, err := fsnotify.NewWatcher() @@ -111,17 +116,17 @@ func subscribeInternal(filePath string) error { defer startWatcherMu.Unlock() if n, ok := watched[filePath]; ok { - logger.V(2).Debugf("subscribe(%s): refCount=%d", filePath, n+1) + logger.Debugf("subscribe(%s): refCount=%d", filePath, n+1) watched[filePath]++ return nil } err := gWatcher.Add(filePath) if err != nil { - logger.V(2).Errorf("subscribe(%s): ERR=%v", filePath, err) + logger.Errorf("subscribe(%s): ERR=%v", filePath, err) return err } - logger.V(2).Debugf("subscribe(%s): refCount=1", filePath) + logger.Debugf("subscribe(%s): refCount=1", filePath) watched[filePath] = 1 return nil } @@ -141,12 +146,12 @@ func unsubscribeInternal(filePath string) error { defer startWatcherMu.Unlock() if _, ok := watched[filePath]; !ok { - logger.V(2).Debugf("unsubscribe(%s): refCount=!NF", filePath) + logger.Debugf("unsubscribe(%s): refCount=!NF", filePath) return nil } watched[filePath]-- - logger.V(2).Debugf("unsubscribe(%s): refCount=%d", filePath, watched[filePath]) + logger.Debugf("unsubscribe(%s): refCount=%d", filePath, watched[filePath]) if watched[filePath] > 0 { return nil } @@ -155,10 +160,10 @@ func unsubscribeInternal(filePath string) error { err := gWatcher.Remove(filePath) if err != nil { if errors.Is(err, fsnotify.ErrNonExistentWatch) { - logger.V(2).Debugf("unsubscribe(%s): refCount=!0", filePath) + logger.Debugf("unsubscribe(%s): refCount=!0", filePath) return nil } - logger.V(2).Errorf("unsubscribe(%s): failed to remove a watch: %T(%+v)", filePath, err, err) + logger.Errorf("unsubscribe(%s): failed to remove a watch: %T(%+v)", filePath, err, err) // log error but don't block dir refcount from being decremented return nil } @@ -225,7 +230,7 @@ func handleEvent(event fsnotify.Event) { // Event occurred on the underlying file (recursively-resolved absolute path) of a watched // path for _, child := range children.AsSortedSlice() { - logger.V(2).Debugf("propagating %v event on %s to underlying path %s", + logger.Debugf("propagating %v event on %s to underlying path %s", event.Op, event.Name, child) handleEventForPath(event, child) } @@ -260,11 +265,11 @@ func handleEvent(event fsnotify.Event) { for _, link := range links { for _, ruleName := range symlinkPropagationMap[link].AsSlice() { if _, ok := watchHandlers[ruleName]; ok { - logger.V(2).Debugf("propagating %v event on %s to origin %s", + logger.Debugf("propagating %v event on %s to origin %s", event.Op, link, ruleName) handleEventForPath(event, ruleName) } else { - logger.V(2).Errorf("symlinkPropagationMap target without corresponding rule: %s", ruleName) + logger.Errorf("symlinkPropagationMap target without corresponding rule: %s", ruleName) } } } @@ -278,7 +283,7 @@ func handleEvent(event fsnotify.Event) { return } } - logger.V(4).Warningf("dangling watcher on path %s: not known within normal rules or symlink map: %v", event.Name, event.Op) + logger.Warningf("dangling watcher on path %s: not known within normal rules or symlink map: %v", event.Name, event.Op) } // handleEventForPath is the second stage of event handling which calls the actual handlers. @@ -290,15 +295,15 @@ func handleEvent(event fsnotify.Event) { func handleEventForPath(event fsnotify.Event, ruleName string) { rule, ok := watchHandlers[ruleName] if !ok { - logger.V(1).Errorf("handleEventForPath called for file without rule: %s: %+v", ruleName, event) + logger.Errorf("handleEventForPath called for file without rule: %s: %+v", ruleName, event) return } op := event.Op - logger.V(2).Debugf("inotify event on %s: %v", event.Name, event.Op) - logger.V(2).Debugf("ruleName: %s", ruleName) - logger.V(2).Debugf("upstreams: %+v", rule.upstreams.AsSlice()) + logger.Debugf("inotify event on %s: %v", event.Name, event.Op) + logger.Debugf("ruleName: %s", ruleName) + logger.Debugf("upstreams: %+v", rule.upstreams.AsSlice()) newRealpath := resolveSymlinkAndDereferenceParents(ruleName) newInum := inum(newRealpath) @@ -306,7 +311,7 @@ func handleEventForPath(event fsnotify.Event, ruleName string) { handlerPath := event.Name if fileSwapped { - logger.V(1).Noticef( + logger.Noticef( "watched file %s: detected absolute path or inum change, pruning watchers:\n %s->%s\n %d->%d", ruleName, rule.absPath, newRealpath, @@ -321,7 +326,7 @@ func handleEventForPath(event fsnotify.Event, ruleName string) { untrackSymlinks(ruleName) Unsubscribe(ruleName) if len(watchHandlers) == 1 { - logger.V(2).Noticef("all watchers should now be cleaned up:") + logger.Noticef("all watchers should now be cleaned up:") Debug() } subscribe(ruleName) @@ -368,7 +373,7 @@ func untrackSymlinks(ruleName string) { var toDelete []string for link, targets := range symlinkPropagationMap { if targets.Contains(ruleName) { - logger.V(2).Debugf("cleaning up watcher on %s for fsnotify watch rule %s", link, ruleName) + logger.Debugf("cleaning up watcher on %s for fsnotify watch rule %s", link, ruleName) Unsubscribe(link) targets.Del(ruleName) } @@ -384,7 +389,7 @@ func untrackSymlinks(ruleName string) { func symlinkPropagationChildren(link string) []string { var targets []string - for path, _ := range symlinkPropagationMap { + for path := range symlinkPropagationMap { if path == link || strings.HasPrefix(path, link+"/") { targets = append(targets, path) } @@ -406,7 +411,7 @@ func scanSymlinks(filePath string) error { break } - logger.V(1).Debugf("symlink resolution step yields abspath: %s", target) + logger.Debugf("symlink resolution step yields abspath: %s", target) rule.upstreams.Add(target) subscribe(target) @@ -418,10 +423,10 @@ func scanSymlinks(filePath string) error { // replaced, we can fire a change event on the original file. for _, link := range symlinksInFullpath(target) { target = link.target + strings.TrimPrefix(target, link.link) - logger.V(1).Debugf("while adding watcher on file %s: rewrote abspath to %s based on symlink %s->%s", + logger.Debugf("while adding watcher on file %s: rewrote abspath to %s based on symlink %s->%s", filePath, target, link.link, link.target) if _, err := os.Lstat(link.target); err != nil { - logger.V(1).Warningf("failed to stat resolved parent directory %s: %v", link.target, err) + logger.Warningf("failed to stat resolved parent directory %s: %v", link.target, err) continue } rule.upstreams.Add(target) @@ -438,28 +443,28 @@ func scanSymlinks(filePath string) error { } func Debug() { - logger.V(1).Debugf("symlinkPropagationMap:") + logger.Debugf("symlinkPropagationMap:") if len(symlinkPropagationMap) == 0 { - logger.V(1).Debugf(" ") + logger.Debugf(" ") } for filePath, members := range symlinkPropagationMap { - logger.V(1).Debugf(" %s: %+v", filePath, members.AsSortedSlice()) + logger.Debugf(" %s: %+v", filePath, members.AsSortedSlice()) } - logger.V(1).Debugf("watchHandlers:") + logger.Debugf("watchHandlers:") if len(watchHandlers) == 0 { - logger.V(1).Debugf(" ") + logger.Debugf(" ") } for filePath, rule := range watchHandlers { - logger.V(1).Debugf(" %s: upstreams=%+v, %+v", filePath, rule.upstreams.AsSortedSlice(), rule.callbacks) + logger.Debugf(" %s: upstreams=%+v, %+v", filePath, rule.upstreams.AsSortedSlice(), rule.callbacks) } - logger.V(1).Debugf("fsnotify ref counts:") + logger.Debugf("fsnotify ref counts:") if len(watched) == 0 { - logger.V(1).Debugf(" ") + logger.Debugf(" ") } for filePath, n := range watched { - logger.V(1).Debugf(" %s: %d", filePath, n) + logger.Debugf(" %s: %d", filePath, n) } } @@ -474,7 +479,7 @@ func NotifyPath(filePath string, callback NotifyFunc) error { return fmt.Errorf("unable to watch %s: error calling lstat: %v", filePath, err) } - logger.V(1).Debugf("adding watcher on file %s", filePath) + logger.Debugf("adding watcher on file %s", filePath) err = subscribe(filePath) if err != nil { return err @@ -504,7 +509,7 @@ func Stop() { } startWatcherMu.Unlock() - for path, _ := range watched { + for path := range watched { unsubscribeInternal(path) } -- 2.52.0