From 5523cb1595731c76305963e30287cb0f53128409 Mon Sep 17 00:00:00 2001 From: sneak Date: Wed, 17 Dec 2025 15:17:27 -0800 Subject: [PATCH] Add Verbose log level between Info and Debug Implemented full log level hierarchy: Fatal, Error, Warn, Info, Verbose, Debug. - Verbose level (-v) shows detailed operations like file changes (M/A/D) - Debug level (-vv) shows low-level tracing with caller info - Quiet mode (-q) sets level to Error, suppressing Info messages - Banner and summary output now use log levels for filtering --- internal/cli/check.go | 14 ++-- internal/cli/entry_test.go | 8 +- internal/cli/fetch.go | 20 ++--- internal/cli/freshen.go | 32 ++++--- internal/cli/gen.go | 8 +- internal/cli/mfer.go | 30 +++---- internal/log/log.go | 167 ++++++++++++++++++++++++++++++------- 7 files changed, 187 insertions(+), 92 deletions(-) diff --git a/internal/cli/check.go b/internal/cli/check.go index 6d3554c..592869e 100644 --- a/internal/cli/check.go +++ b/internal/cli/check.go @@ -140,14 +140,12 @@ func (mfa *CLIApp) checkManifestOperation(ctx *cli.Context) error { <-extraDone } - if !ctx.Bool("quiet") { - elapsed := time.Since(mfa.startupTime).Seconds() - rate := float64(chk.TotalBytes()) / elapsed / 1e6 - if failures == 0 { - log.Infof("checked %d files (%.1f MB) in %.1fs (%.1f MB/s): all OK", chk.FileCount(), float64(chk.TotalBytes())/1e6, elapsed, rate) - } else { - log.Infof("checked %d files (%.1f MB) in %.1fs (%.1f MB/s): %d failed", chk.FileCount(), float64(chk.TotalBytes())/1e6, elapsed, rate, failures) - } + elapsed := time.Since(mfa.startupTime).Seconds() + rate := float64(chk.TotalBytes()) / elapsed / 1e6 + if failures == 0 { + log.Infof("checked %d files (%.1f MB) in %.1fs (%.1f MB/s): all OK", chk.FileCount(), float64(chk.TotalBytes())/1e6, elapsed, rate) + } else { + log.Infof("checked %d files (%.1f MB) in %.1fs (%.1f MB/s): %d failed", chk.FileCount(), float64(chk.TotalBytes())/1e6, elapsed, rate, failures) } if failures > 0 { diff --git a/internal/cli/entry_test.go b/internal/cli/entry_test.go index 98d19df..52c08ca 100644 --- a/internal/cli/entry_test.go +++ b/internal/cli/entry_test.go @@ -173,10 +173,10 @@ func TestBannerOutput(t *testing.T) { exitCode := RunWithOptions(opts) assert.Equal(t, 0, exitCode) - // Banner ASCII art should be in stdout - stdout := opts.Stdout.(*bytes.Buffer).String() - assert.Contains(t, stdout, "___") - assert.Contains(t, stdout, "\\") + // Banner ASCII art should be in stderr (via log.Info) + stderr := opts.Stderr.(*bytes.Buffer).String() + assert.Contains(t, stderr, "___") + assert.Contains(t, stderr, "\\") } func TestUnknownCommand(t *testing.T) { diff --git a/internal/cli/fetch.go b/internal/cli/fetch.go index a38e12f..894c60a 100644 --- a/internal/cli/fetch.go +++ b/internal/cli/fetch.go @@ -125,17 +125,15 @@ func (mfa *CLIApp) fetchManifestOperation(ctx *cli.Context) error { close(progress) <-done - // Print summary if not quiet - if !ctx.Bool("quiet") { - elapsed := time.Since(startTime) - avgBytesPerSec := float64(totalBytes) / elapsed.Seconds() - avgRate := formatBitrate(avgBytesPerSec * 8) - log.Infof("downloaded %d files (%.1f MB) in %.1fs (%s avg)", - len(files), - float64(totalBytes)/1e6, - elapsed.Seconds(), - avgRate) - } + // Print summary + elapsed := time.Since(startTime) + avgBytesPerSec := float64(totalBytes) / elapsed.Seconds() + avgRate := formatBitrate(avgBytesPerSec * 8) + log.Infof("downloaded %d files (%.1f MB) in %.1fs (%s avg)", + len(files), + float64(totalBytes)/1e6, + elapsed.Seconds(), + avgRate) return nil } diff --git a/internal/cli/freshen.go b/internal/cli/freshen.go index 164f857..5ef4f75 100644 --- a/internal/cli/freshen.go +++ b/internal/cli/freshen.go @@ -149,7 +149,7 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error { existingMtime := time.Unix(existing.Mtime.Seconds, int64(existing.Mtime.Nanos)) if existing.Size != info.Size() || !existingMtime.Equal(info.ModTime()) { changed++ - log.Debugf("M %s", relPath) + log.Verbosef("M %s", relPath) entries = append(entries, &freshenEntry{ path: relPath, size: info.Size(), @@ -170,7 +170,7 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error { delete(existingByPath, relPath) } else { added++ - log.Debugf("A %s", relPath) + log.Verbosef("A %s", relPath) entries = append(entries, &freshenEntry{ path: relPath, size: info.Size(), @@ -198,7 +198,7 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error { // Remaining entries in existingByPath are removed files removed = int64(len(existingByPath)) for path := range existingByPath { - log.Debugf("D %s", path) + log.Verbosef("D %s", path) } scanDuration := time.Since(startScan) @@ -305,21 +305,19 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error { } // Print summary - if !ctx.Bool("quiet") { - totalDuration := time.Since(mfa.startupTime) - var hashRate float64 - if hashedBytes > 0 { - hashDuration := time.Since(startHash) - hashRate = float64(hashedBytes) / hashDuration.Seconds() / 1e6 - } - log.Infof("freshen complete: %d unchanged, %d changed, %d added, %d removed", - unchanged, changed, added, removed) - if filesToHash > 0 { - log.Infof("hashed %.1f MB in %.1fs (%.1f MB/s)", - float64(hashedBytes)/1e6, totalDuration.Seconds(), hashRate) - } - log.Infof("wrote %d files to %s", len(entries), manifestPath) + totalDuration := time.Since(mfa.startupTime) + var hashRate float64 + if hashedBytes > 0 { + hashDuration := time.Since(startHash) + hashRate = float64(hashedBytes) / hashDuration.Seconds() / 1e6 } + log.Infof("freshen complete: %d unchanged, %d changed, %d added, %d removed", + unchanged, changed, added, removed) + if filesToHash > 0 { + log.Infof("hashed %.1f MB in %.1fs (%.1f MB/s)", + float64(hashedBytes)/1e6, totalDuration.Seconds(), hashRate) + } + log.Infof("wrote %d files to %s", len(entries), manifestPath) return nil } diff --git a/internal/cli/gen.go b/internal/cli/gen.go index 2a6d394..67cdf87 100644 --- a/internal/cli/gen.go +++ b/internal/cli/gen.go @@ -115,11 +115,9 @@ func (mfa *CLIApp) generateManifestOperation(ctx *cli.Context) error { return fmt.Errorf("failed to generate manifest: %w", err) } - if !ctx.Bool("quiet") { - elapsed := time.Since(mfa.startupTime).Seconds() - rate := float64(s.TotalBytes()) / elapsed / 1e6 - log.Infof("wrote %d files (%.1f MB) to %s in %.1fs (%.1f MB/s)", s.FileCount(), float64(s.TotalBytes())/1e6, outputPath, elapsed, rate) - } + elapsed := time.Since(mfa.startupTime).Seconds() + rate := float64(s.TotalBytes()) / elapsed / 1e6 + log.Infof("wrote %d files (%.1f MB) to %s in %.1fs (%.1f MB/s)", s.FileCount(), float64(s.TotalBytes())/1e6, outputPath, elapsed, rate) return nil } diff --git a/internal/cli/mfer.go b/internal/cli/mfer.go index 921d6b3..657bab5 100644 --- a/internal/cli/mfer.go +++ b/internal/cli/mfer.go @@ -41,7 +41,7 @@ const banner = ` \__\/ \__\/ \__\/ \__\/` func (mfa *CLIApp) printBanner() { - _, _ = fmt.Fprintln(mfa.Stdout, banner) + log.Info(banner) } // VersionString returns the version and git revision formatted for display. @@ -49,10 +49,12 @@ func (mfa *CLIApp) VersionString() string { return fmt.Sprintf("%s (%s)", mfa.version, mfa.gitrev) } -func (mfa *CLIApp) setVerbosity(v int) { +func (mfa *CLIApp) setVerbosity(quiet bool, v int) { _, present := os.LookupEnv("MFER_DEBUG") if present { log.EnableDebugLogging() + } else if quiet { + log.SetLevel(log.ErrorLevel) } else { log.SetLevelFromVerbosity(v) } @@ -98,10 +100,8 @@ func (mfa *CLIApp) run(args []string) { Aliases: []string{"gen"}, Usage: "Generate manifest file", Action: func(c *cli.Context) error { - if !c.Bool("quiet") { - mfa.printBanner() - } - mfa.setVerbosity(verbosity) + mfa.setVerbosity(c.Bool("quiet"), verbosity) + mfa.printBanner() return mfa.generateManifestOperation(c) }, Flags: []cli.Flag{ @@ -138,10 +138,8 @@ func (mfa *CLIApp) run(args []string) { Usage: "Validate files using manifest file", ArgsUsage: "[manifest file]", Action: func(c *cli.Context) error { - if !c.Bool("quiet") { - mfa.printBanner() - } - mfa.setVerbosity(verbosity) + mfa.setVerbosity(c.Bool("quiet"), verbosity) + mfa.printBanner() return mfa.checkManifestOperation(c) }, Flags: []cli.Flag{ @@ -167,10 +165,8 @@ func (mfa *CLIApp) run(args []string) { Usage: "Update manifest with changed, new, and removed files", ArgsUsage: "[manifest file]", Action: func(c *cli.Context) error { - if !c.Bool("quiet") { - mfa.printBanner() - } - mfa.setVerbosity(verbosity) + mfa.setVerbosity(c.Bool("quiet"), verbosity) + mfa.printBanner() return mfa.freshenManifestOperation(c) }, Flags: []cli.Flag{ @@ -209,10 +205,8 @@ func (mfa *CLIApp) run(args []string) { Name: "fetch", Usage: "fetch manifest and referenced files", Action: func(c *cli.Context) error { - if !c.Bool("quiet") { - mfa.printBanner() - } - mfa.setVerbosity(verbosity) + mfa.setVerbosity(c.Bool("quiet"), verbosity) + mfa.printBanner() return mfa.fetchManifestOperation(c) }, }, diff --git a/internal/log/log.go b/internal/log/log.go index 5e56c4f..74bb9b6 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -13,16 +13,53 @@ import ( "github.com/pterm/pterm" ) -// Level is an alias for apex/log.Level for use by callers without importing apex/log. -type Level = log.Level +// Level represents log severity levels. +// Lower values are more verbose. +type Level int + +const ( + // DebugLevel is for low-level tracing and structure inspection + DebugLevel Level = iota + // VerboseLevel is for detailed operational info (file listings, etc) + VerboseLevel + // InfoLevel is for operational summaries (default) + InfoLevel + // WarnLevel is for warnings + WarnLevel + // ErrorLevel is for errors + ErrorLevel + // FatalLevel is for fatal errors + FatalLevel +) + +func (l Level) String() string { + switch l { + case DebugLevel: + return "debug" + case VerboseLevel: + return "verbose" + case InfoLevel: + return "info" + case WarnLevel: + return "warn" + case ErrorLevel: + return "error" + case FatalLevel: + return "fatal" + default: + return "unknown" + } +} var ( - // mu protects the output writers + // mu protects the output writers and level mu sync.RWMutex // stdout is the writer for progress output stdout io.Writer = os.Stdout // stderr is the writer for log output stderr io.Writer = os.Stderr + // currentLevel is our log level (includes Verbose) + currentLevel Level = InfoLevel ) // SetOutput configures the output writers for the log package. @@ -67,31 +104,105 @@ func Init() { w := stderr mu.RUnlock() log.SetHandler(acli.New(w)) - log.SetLevel(log.InfoLevel) + log.SetLevel(log.DebugLevel) // Let apex/log pass everything; we filter ourselves +} + +// isEnabled returns true if messages at the given level should be logged. +func isEnabled(l Level) bool { + mu.RLock() + defer mu.RUnlock() + return l >= currentLevel +} + +// Fatalf logs a formatted message at fatal level. +func Fatalf(format string, args ...interface{}) { + if isEnabled(FatalLevel) { + log.Fatalf(format, args...) + } +} + +// Fatal logs a message at fatal level. +func Fatal(arg string) { + if isEnabled(FatalLevel) { + log.Fatal(arg) + } +} + +// Errorf logs a formatted message at error level. +func Errorf(format string, args ...interface{}) { + if isEnabled(ErrorLevel) { + log.Errorf(format, args...) + } +} + +// Error logs a message at error level. +func Error(arg string) { + if isEnabled(ErrorLevel) { + log.Error(arg) + } +} + +// Warnf logs a formatted message at warn level. +func Warnf(format string, args ...interface{}) { + if isEnabled(WarnLevel) { + log.Warnf(format, args...) + } +} + +// Warn logs a message at warn level. +func Warn(arg string) { + if isEnabled(WarnLevel) { + log.Warn(arg) + } } // Infof logs a formatted message at info level. func Infof(format string, args ...interface{}) { - log.Infof(format, args...) + if isEnabled(InfoLevel) { + log.Infof(format, args...) + } } // Info logs a message at info level. func Info(arg string) { - log.Info(arg) + if isEnabled(InfoLevel) { + log.Info(arg) + } +} + +// Verbosef logs a formatted message at verbose level. +func Verbosef(format string, args ...interface{}) { + if isEnabled(VerboseLevel) { + log.Infof(format, args...) + } +} + +// Verbose logs a message at verbose level. +func Verbose(arg string) { + if isEnabled(VerboseLevel) { + log.Info(arg) + } } // Debugf logs a formatted message at debug level with caller location. func Debugf(format string, args ...interface{}) { - DebugReal(fmt.Sprintf(format, args...), 2) + if isEnabled(DebugLevel) { + DebugReal(fmt.Sprintf(format, args...), 2) + } } // Debug logs a message at debug level with caller location. func Debug(arg string) { - DebugReal(arg, 2) + if isEnabled(DebugLevel) { + DebugReal(arg, 2) + } } // DebugReal logs at debug level with caller info from the specified stack depth. func DebugReal(arg string, cs int) { + if !isEnabled(DebugLevel) { + return + } _, callerFile, callerLine, ok := runtime.Caller(cs) if !ok { return @@ -102,25 +213,27 @@ func DebugReal(arg string, cs int) { // Dump logs a spew dump of the arguments at debug level. func Dump(args ...interface{}) { - DebugReal(spew.Sdump(args...), 2) + if isEnabled(DebugLevel) { + DebugReal(spew.Sdump(args...), 2) + } } // EnableDebugLogging sets the log level to debug. func EnableDebugLogging() { - SetLevel(log.DebugLevel) + SetLevel(DebugLevel) } // VerbosityStepsToLogLevel converts a -v count to a log level. -// 0 returns InfoLevel, 1+ returns DebugLevel. -func VerbosityStepsToLogLevel(l int) log.Level { +// 0 returns InfoLevel, 1 returns VerboseLevel, 2+ returns DebugLevel. +func VerbosityStepsToLogLevel(l int) Level { switch l { case 0: - return log.InfoLevel + return InfoLevel case 1: - return log.DebugLevel + return VerboseLevel + default: + return DebugLevel } - // -vv or more - return log.DebugLevel } // SetLevelFromVerbosity sets the log level based on -v flag count. @@ -129,26 +242,22 @@ func SetLevelFromVerbosity(l int) { } // SetLevel sets the global log level. -func SetLevel(arg log.Level) { - log.SetLevel(arg) -} - -// GetLogger returns the underlying apex/log Logger. -func GetLogger() *log.Logger { - if logger, ok := log.Log.(*log.Logger); ok { - return logger - } - panic("unable to get logger") +func SetLevel(l Level) { + mu.Lock() + defer mu.Unlock() + currentLevel = l } // GetLevel returns the current log level. -func GetLevel() log.Level { - return GetLogger().Level +func GetLevel() Level { + mu.RLock() + defer mu.RUnlock() + return currentLevel } // WithError returns a log entry with the error attached. func WithError(e error) *log.Entry { - return GetLogger().WithError(e) + return log.Log.WithError(e) } // Progressf prints a progress message that overwrites the current line.