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
This commit is contained in:
Jeffrey Paul 2025-12-17 15:17:27 -08:00
parent 0e86562c09
commit 5523cb1595
7 changed files with 187 additions and 92 deletions

View File

@ -140,7 +140,6 @@ func (mfa *CLIApp) checkManifestOperation(ctx *cli.Context) error {
<-extraDone <-extraDone
} }
if !ctx.Bool("quiet") {
elapsed := time.Since(mfa.startupTime).Seconds() elapsed := time.Since(mfa.startupTime).Seconds()
rate := float64(chk.TotalBytes()) / elapsed / 1e6 rate := float64(chk.TotalBytes()) / elapsed / 1e6
if failures == 0 { if failures == 0 {
@ -148,7 +147,6 @@ func (mfa *CLIApp) checkManifestOperation(ctx *cli.Context) error {
} else { } else {
log.Infof("checked %d files (%.1f MB) in %.1fs (%.1f MB/s): %d failed", chk.FileCount(), float64(chk.TotalBytes())/1e6, elapsed, rate, failures) 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 { if failures > 0 {
mfa.exitCode = 1 mfa.exitCode = 1

View File

@ -173,10 +173,10 @@ func TestBannerOutput(t *testing.T) {
exitCode := RunWithOptions(opts) exitCode := RunWithOptions(opts)
assert.Equal(t, 0, exitCode) assert.Equal(t, 0, exitCode)
// Banner ASCII art should be in stdout // Banner ASCII art should be in stderr (via log.Info)
stdout := opts.Stdout.(*bytes.Buffer).String() stderr := opts.Stderr.(*bytes.Buffer).String()
assert.Contains(t, stdout, "___") assert.Contains(t, stderr, "___")
assert.Contains(t, stdout, "\\") assert.Contains(t, stderr, "\\")
} }
func TestUnknownCommand(t *testing.T) { func TestUnknownCommand(t *testing.T) {

View File

@ -125,8 +125,7 @@ func (mfa *CLIApp) fetchManifestOperation(ctx *cli.Context) error {
close(progress) close(progress)
<-done <-done
// Print summary if not quiet // Print summary
if !ctx.Bool("quiet") {
elapsed := time.Since(startTime) elapsed := time.Since(startTime)
avgBytesPerSec := float64(totalBytes) / elapsed.Seconds() avgBytesPerSec := float64(totalBytes) / elapsed.Seconds()
avgRate := formatBitrate(avgBytesPerSec * 8) avgRate := formatBitrate(avgBytesPerSec * 8)
@ -135,7 +134,6 @@ func (mfa *CLIApp) fetchManifestOperation(ctx *cli.Context) error {
float64(totalBytes)/1e6, float64(totalBytes)/1e6,
elapsed.Seconds(), elapsed.Seconds(),
avgRate) avgRate)
}
return nil return nil
} }

View File

@ -149,7 +149,7 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error {
existingMtime := time.Unix(existing.Mtime.Seconds, int64(existing.Mtime.Nanos)) existingMtime := time.Unix(existing.Mtime.Seconds, int64(existing.Mtime.Nanos))
if existing.Size != info.Size() || !existingMtime.Equal(info.ModTime()) { if existing.Size != info.Size() || !existingMtime.Equal(info.ModTime()) {
changed++ changed++
log.Debugf("M %s", relPath) log.Verbosef("M %s", relPath)
entries = append(entries, &freshenEntry{ entries = append(entries, &freshenEntry{
path: relPath, path: relPath,
size: info.Size(), size: info.Size(),
@ -170,7 +170,7 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error {
delete(existingByPath, relPath) delete(existingByPath, relPath)
} else { } else {
added++ added++
log.Debugf("A %s", relPath) log.Verbosef("A %s", relPath)
entries = append(entries, &freshenEntry{ entries = append(entries, &freshenEntry{
path: relPath, path: relPath,
size: info.Size(), size: info.Size(),
@ -198,7 +198,7 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error {
// Remaining entries in existingByPath are removed files // Remaining entries in existingByPath are removed files
removed = int64(len(existingByPath)) removed = int64(len(existingByPath))
for path := range existingByPath { for path := range existingByPath {
log.Debugf("D %s", path) log.Verbosef("D %s", path)
} }
scanDuration := time.Since(startScan) scanDuration := time.Since(startScan)
@ -305,7 +305,6 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error {
} }
// Print summary // Print summary
if !ctx.Bool("quiet") {
totalDuration := time.Since(mfa.startupTime) totalDuration := time.Since(mfa.startupTime)
var hashRate float64 var hashRate float64
if hashedBytes > 0 { if hashedBytes > 0 {
@ -319,7 +318,6 @@ func (mfa *CLIApp) freshenManifestOperation(ctx *cli.Context) error {
float64(hashedBytes)/1e6, totalDuration.Seconds(), hashRate) float64(hashedBytes)/1e6, totalDuration.Seconds(), hashRate)
} }
log.Infof("wrote %d files to %s", len(entries), manifestPath) log.Infof("wrote %d files to %s", len(entries), manifestPath)
}
return nil return nil
} }

View File

@ -115,11 +115,9 @@ func (mfa *CLIApp) generateManifestOperation(ctx *cli.Context) error {
return fmt.Errorf("failed to generate manifest: %w", err) return fmt.Errorf("failed to generate manifest: %w", err)
} }
if !ctx.Bool("quiet") {
elapsed := time.Since(mfa.startupTime).Seconds() elapsed := time.Since(mfa.startupTime).Seconds()
rate := float64(s.TotalBytes()) / elapsed / 1e6 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) 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 return nil
} }

View File

@ -41,7 +41,7 @@ const banner = `
\__\/ \__\/ \__\/ \__\/` \__\/ \__\/ \__\/ \__\/`
func (mfa *CLIApp) printBanner() { func (mfa *CLIApp) printBanner() {
_, _ = fmt.Fprintln(mfa.Stdout, banner) log.Info(banner)
} }
// VersionString returns the version and git revision formatted for display. // 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) 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") _, present := os.LookupEnv("MFER_DEBUG")
if present { if present {
log.EnableDebugLogging() log.EnableDebugLogging()
} else if quiet {
log.SetLevel(log.ErrorLevel)
} else { } else {
log.SetLevelFromVerbosity(v) log.SetLevelFromVerbosity(v)
} }
@ -98,10 +100,8 @@ func (mfa *CLIApp) run(args []string) {
Aliases: []string{"gen"}, Aliases: []string{"gen"},
Usage: "Generate manifest file", Usage: "Generate manifest file",
Action: func(c *cli.Context) error { Action: func(c *cli.Context) error {
if !c.Bool("quiet") { mfa.setVerbosity(c.Bool("quiet"), verbosity)
mfa.printBanner() mfa.printBanner()
}
mfa.setVerbosity(verbosity)
return mfa.generateManifestOperation(c) return mfa.generateManifestOperation(c)
}, },
Flags: []cli.Flag{ Flags: []cli.Flag{
@ -138,10 +138,8 @@ func (mfa *CLIApp) run(args []string) {
Usage: "Validate files using manifest file", Usage: "Validate files using manifest file",
ArgsUsage: "[manifest file]", ArgsUsage: "[manifest file]",
Action: func(c *cli.Context) error { Action: func(c *cli.Context) error {
if !c.Bool("quiet") { mfa.setVerbosity(c.Bool("quiet"), verbosity)
mfa.printBanner() mfa.printBanner()
}
mfa.setVerbosity(verbosity)
return mfa.checkManifestOperation(c) return mfa.checkManifestOperation(c)
}, },
Flags: []cli.Flag{ Flags: []cli.Flag{
@ -167,10 +165,8 @@ func (mfa *CLIApp) run(args []string) {
Usage: "Update manifest with changed, new, and removed files", Usage: "Update manifest with changed, new, and removed files",
ArgsUsage: "[manifest file]", ArgsUsage: "[manifest file]",
Action: func(c *cli.Context) error { Action: func(c *cli.Context) error {
if !c.Bool("quiet") { mfa.setVerbosity(c.Bool("quiet"), verbosity)
mfa.printBanner() mfa.printBanner()
}
mfa.setVerbosity(verbosity)
return mfa.freshenManifestOperation(c) return mfa.freshenManifestOperation(c)
}, },
Flags: []cli.Flag{ Flags: []cli.Flag{
@ -209,10 +205,8 @@ func (mfa *CLIApp) run(args []string) {
Name: "fetch", Name: "fetch",
Usage: "fetch manifest and referenced files", Usage: "fetch manifest and referenced files",
Action: func(c *cli.Context) error { Action: func(c *cli.Context) error {
if !c.Bool("quiet") { mfa.setVerbosity(c.Bool("quiet"), verbosity)
mfa.printBanner() mfa.printBanner()
}
mfa.setVerbosity(verbosity)
return mfa.fetchManifestOperation(c) return mfa.fetchManifestOperation(c)
}, },
}, },

View File

@ -13,16 +13,53 @@ import (
"github.com/pterm/pterm" "github.com/pterm/pterm"
) )
// Level is an alias for apex/log.Level for use by callers without importing apex/log. // Level represents log severity levels.
type Level = log.Level // 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 ( var (
// mu protects the output writers // mu protects the output writers and level
mu sync.RWMutex mu sync.RWMutex
// stdout is the writer for progress output // stdout is the writer for progress output
stdout io.Writer = os.Stdout stdout io.Writer = os.Stdout
// stderr is the writer for log output // stderr is the writer for log output
stderr io.Writer = os.Stderr stderr io.Writer = os.Stderr
// currentLevel is our log level (includes Verbose)
currentLevel Level = InfoLevel
) )
// SetOutput configures the output writers for the log package. // SetOutput configures the output writers for the log package.
@ -67,31 +104,105 @@ func Init() {
w := stderr w := stderr
mu.RUnlock() mu.RUnlock()
log.SetHandler(acli.New(w)) 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. // Infof logs a formatted message at info level.
func Infof(format string, args ...interface{}) { func Infof(format string, args ...interface{}) {
if isEnabled(InfoLevel) {
log.Infof(format, args...) log.Infof(format, args...)
}
} }
// Info logs a message at info level. // Info logs a message at info level.
func Info(arg string) { func Info(arg string) {
if isEnabled(InfoLevel) {
log.Info(arg) 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. // Debugf logs a formatted message at debug level with caller location.
func Debugf(format string, args ...interface{}) { func Debugf(format string, args ...interface{}) {
if isEnabled(DebugLevel) {
DebugReal(fmt.Sprintf(format, args...), 2) DebugReal(fmt.Sprintf(format, args...), 2)
}
} }
// Debug logs a message at debug level with caller location. // Debug logs a message at debug level with caller location.
func Debug(arg string) { func Debug(arg string) {
if isEnabled(DebugLevel) {
DebugReal(arg, 2) DebugReal(arg, 2)
}
} }
// DebugReal logs at debug level with caller info from the specified stack depth. // DebugReal logs at debug level with caller info from the specified stack depth.
func DebugReal(arg string, cs int) { func DebugReal(arg string, cs int) {
if !isEnabled(DebugLevel) {
return
}
_, callerFile, callerLine, ok := runtime.Caller(cs) _, callerFile, callerLine, ok := runtime.Caller(cs)
if !ok { if !ok {
return return
@ -102,25 +213,27 @@ func DebugReal(arg string, cs int) {
// Dump logs a spew dump of the arguments at debug level. // Dump logs a spew dump of the arguments at debug level.
func Dump(args ...interface{}) { func Dump(args ...interface{}) {
if isEnabled(DebugLevel) {
DebugReal(spew.Sdump(args...), 2) DebugReal(spew.Sdump(args...), 2)
}
} }
// EnableDebugLogging sets the log level to debug. // EnableDebugLogging sets the log level to debug.
func EnableDebugLogging() { func EnableDebugLogging() {
SetLevel(log.DebugLevel) SetLevel(DebugLevel)
} }
// VerbosityStepsToLogLevel converts a -v count to a log level. // VerbosityStepsToLogLevel converts a -v count to a log level.
// 0 returns InfoLevel, 1+ returns DebugLevel. // 0 returns InfoLevel, 1 returns VerboseLevel, 2+ returns DebugLevel.
func VerbosityStepsToLogLevel(l int) log.Level { func VerbosityStepsToLogLevel(l int) Level {
switch l { switch l {
case 0: case 0:
return log.InfoLevel return InfoLevel
case 1: 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. // SetLevelFromVerbosity sets the log level based on -v flag count.
@ -129,26 +242,22 @@ func SetLevelFromVerbosity(l int) {
} }
// SetLevel sets the global log level. // SetLevel sets the global log level.
func SetLevel(arg log.Level) { func SetLevel(l Level) {
log.SetLevel(arg) mu.Lock()
} defer mu.Unlock()
currentLevel = l
// 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")
} }
// GetLevel returns the current log level. // GetLevel returns the current log level.
func GetLevel() log.Level { func GetLevel() Level {
return GetLogger().Level mu.RLock()
defer mu.RUnlock()
return currentLevel
} }
// WithError returns a log entry with the error attached. // WithError returns a log entry with the error attached.
func WithError(e error) *log.Entry { 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. // Progressf prints a progress message that overwrites the current line.