From 5f42d4fe5f1d6868093ec2b2cf8c5cb408f68bdf Mon Sep 17 00:00:00 2001 From: Roger Date: Tue, 7 Apr 2026 16:50:01 +0800 Subject: [PATCH] refactor: redesign logging system for CLI-friendly output (#561) * refactor: redesign logging system for CLI-friendly output * refactor: remove ANSI color support from logger * fix: address PR review feedback --- CLAUDE.md | 2 +- browser/chromium/chromium.go | 1 - browser/chromium/extract_cookie.go | 8 +- browser/chromium/extract_creditcard.go | 14 +- browser/chromium/extract_password.go | 8 +- browser/firefox/extract_password.go | 11 +- browser/firefox/firefox.go | 1 - cmd/hack-browser-data/dump.go | 3 +- log/{level => }/level.go | 19 ++- log/log.go | 32 ++-- log/logger.go | 220 +++++++++++-------------- log/logger_test.go | 155 +++++++++++------ output/output.go | 12 +- 13 files changed, 287 insertions(+), 199 deletions(-) rename log/{level => }/level.go (71%) diff --git a/CLAUDE.md b/CLAUDE.md index 9387991..51f40c8 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -46,7 +46,7 @@ go mod verify - **Platform code**: use build tags (`_darwin.go`, `_windows.go`, `_linux.go`) - **Error handling**: `fmt.Errorf("context: %w", err)` for wrapping, never `_ =` to ignore errors -- **Logging**: `log.Debugf` for record-level issues, `log.Warnf` for user-visible warnings. Extract methods should return errors, not log them. +- **Logging**: `log.Debugf` for record-level diagnostics, `log.Infof` for user-facing progress/status, `log.Warnf` for unexpected conditions. Extract methods should return errors, not log them. - **Naming**: follow Go conventions — `Config` not `BrowserConfig`, `Extract` not `BrowsingData` - **Tests**: use `t.TempDir()` for filesystem tests, `go-sqlmock` for database tests - **Architecture**: see `rfcs/` for design documents diff --git a/browser/chromium/chromium.go b/browser/chromium/chromium.go index bcf236a..fe21048 100644 --- a/browser/chromium/chromium.go +++ b/browser/chromium/chromium.go @@ -187,7 +187,6 @@ func (b *Browser) extractCategory(data *types.BrowserData, cat types.Category, m func discoverProfiles(userDataDir string, sources map[types.Category][]sourcePath) []string { entries, err := os.ReadDir(userDataDir) if err != nil { - log.Debugf("read user data dir %s: %v", userDataDir, err) return nil } diff --git a/browser/chromium/extract_cookie.go b/browser/chromium/extract_cookie.go index a7a34f1..8e7f40b 100644 --- a/browser/chromium/extract_cookie.go +++ b/browser/chromium/extract_cookie.go @@ -16,6 +16,8 @@ const defaultCookieQuery = `SELECT name, encrypted_value, host_key, path, has_expires, is_persistent FROM cookies` func extractCookies(masterKey []byte, path string) ([]types.CookieEntry, error) { + var decryptFails int + var lastErr error cookies, err := sqliteutil.QueryRows(path, false, defaultCookieQuery, func(rows *sql.Rows) (types.CookieEntry, error) { var ( @@ -33,7 +35,8 @@ func extractCookies(masterKey []byte, path string) ([]types.CookieEntry, error) value, err := decryptValue(masterKey, encryptedValue) if err != nil { - log.Debugf("decrypt cookie %s on %s: %v", name, host, err) + decryptFails++ + lastErr = err } value = stripCookieHash(value, host) return types.CookieEntry{ @@ -52,6 +55,9 @@ func extractCookies(masterKey []byte, path string) ([]types.CookieEntry, error) if err != nil { return nil, err } + if decryptFails > 0 { + log.Debugf("decrypt cookies: %d failed: %v", decryptFails, lastErr) + } sort.Slice(cookies, func(i, j int) bool { return cookies[i].CreatedAt.After(cookies[j].CreatedAt) diff --git a/browser/chromium/extract_creditcard.go b/browser/chromium/extract_creditcard.go index fe4c80b..6babbcd 100644 --- a/browser/chromium/extract_creditcard.go +++ b/browser/chromium/extract_creditcard.go @@ -12,7 +12,9 @@ const defaultCreditCardQuery = `SELECT COALESCE(guid, ''), name_on_card, expirat card_number_encrypted, COALESCE(nickname, ''), COALESCE(billing_address_id, '') FROM credit_cards` func extractCreditCards(masterKey []byte, path string) ([]types.CreditCardEntry, error) { - return sqliteutil.QueryRows(path, false, defaultCreditCardQuery, + var decryptFails int + var lastErr error + cards, err := sqliteutil.QueryRows(path, false, defaultCreditCardQuery, func(rows *sql.Rows) (types.CreditCardEntry, error) { var guid, name, month, year, nickname, address string var encNumber []byte @@ -21,7 +23,8 @@ func extractCreditCards(masterKey []byte, path string) ([]types.CreditCardEntry, } number, err := decryptValue(masterKey, encNumber) if err != nil { - log.Debugf("decrypt credit card for %s: %v", name, err) + decryptFails++ + lastErr = err } return types.CreditCardEntry{ GUID: guid, @@ -33,4 +36,11 @@ func extractCreditCards(masterKey []byte, path string) ([]types.CreditCardEntry, Address: address, }, nil }) + if err != nil { + return nil, err + } + if decryptFails > 0 { + log.Debugf("decrypt credit cards: %d failed: %v", decryptFails, lastErr) + } + return cards, nil } diff --git a/browser/chromium/extract_password.go b/browser/chromium/extract_password.go index 45e762a..d90c77d 100644 --- a/browser/chromium/extract_password.go +++ b/browser/chromium/extract_password.go @@ -16,6 +16,8 @@ func extractPasswords(masterKey []byte, path string) ([]types.LoginEntry, error) } func extractPasswordsWithQuery(masterKey []byte, path, query string) ([]types.LoginEntry, error) { + var decryptFails int + var lastErr error logins, err := sqliteutil.QueryRows(path, false, query, func(rows *sql.Rows) (types.LoginEntry, error) { var url, username string @@ -26,7 +28,8 @@ func extractPasswordsWithQuery(masterKey []byte, path, query string) ([]types.Lo } password, err := decryptValue(masterKey, pwd) if err != nil { - log.Debugf("decrypt password for %s: %v", url, err) + decryptFails++ + lastErr = err } return types.LoginEntry{ URL: url, @@ -38,6 +41,9 @@ func extractPasswordsWithQuery(masterKey []byte, path, query string) ([]types.Lo if err != nil { return nil, err } + if decryptFails > 0 { + log.Debugf("decrypt passwords: %d failed: %v", decryptFails, lastErr) + } sort.Slice(logins, func(i, j int) bool { return logins[i].CreatedAt.After(logins[j].CreatedAt) diff --git a/browser/firefox/extract_password.go b/browser/firefox/extract_password.go index cb67f19..cab09a7 100644 --- a/browser/firefox/extract_password.go +++ b/browser/firefox/extract_password.go @@ -37,6 +37,8 @@ func extractPasswords(masterKey []byte, path string) ([]types.LoginEntry, error) } var logins []types.LoginEntry + var decryptFails int + var lastErr error for _, v := range gjson.GetBytes(data, "logins").Array() { url := v.Get("formSubmitURL").String() if url == "" { @@ -45,11 +47,13 @@ func extractPasswords(masterKey []byte, path string) ([]types.LoginEntry, error) user, err := decryptPBE(v.Get("encryptedUsername").String(), masterKey) if err != nil { - log.Debugf("decrypt firefox username for %s: %v", url, err) + decryptFails++ + lastErr = err } pwd, err := decryptPBE(v.Get("encryptedPassword").String(), masterKey) if err != nil { - log.Debugf("decrypt firefox password for %s: %v", url, err) + decryptFails++ + lastErr = err } logins = append(logins, types.LoginEntry{ @@ -59,6 +63,9 @@ func extractPasswords(masterKey []byte, path string) ([]types.LoginEntry, error) CreatedAt: timestamp(v.Get("timeCreated").Int() / 1000), }) } + if decryptFails > 0 { + log.Debugf("decrypt firefox login fields: %d failed: %v", decryptFails, lastErr) + } sort.Slice(logins, func(i, j int) bool { return logins[i].CreatedAt.After(logins[j].CreatedAt) diff --git a/browser/firefox/firefox.go b/browser/firefox/firefox.go index 9b62bfa..cae0726 100644 --- a/browser/firefox/firefox.go +++ b/browser/firefox/firefox.go @@ -188,7 +188,6 @@ type resolvedPath struct { func discoverProfiles(userDataDir string, sources map[types.Category][]sourcePath) []string { entries, err := os.ReadDir(userDataDir) if err != nil { - log.Debugf("read user data dir %s: %v", userDataDir, err) return nil } diff --git a/cmd/hack-browser-data/dump.go b/cmd/hack-browser-data/dump.go index 280477a..15abd1a 100644 --- a/cmd/hack-browser-data/dump.go +++ b/cmd/hack-browser-data/dump.go @@ -58,6 +58,7 @@ func dumpCmd() *cobra.Command { } for _, b := range browsers { + log.Infof("Extracting %s/%s...", b.BrowserName(), b.ProfileName()) data, extractErr := b.Extract(categories) if extractErr != nil { log.Errorf("extract %s/%s: %v", b.BrowserName(), b.ProfileName(), extractErr) @@ -73,7 +74,7 @@ func dumpCmd() *cobra.Command { if err := fileutil.CompressDir(outputDir); err != nil { return fmt.Errorf("compress: %w", err) } - log.Warnf("compressed: %s/%s.zip", outputDir, filepath.Base(outputDir)) + log.Infof("Compressed: %s/%s.zip", outputDir, filepath.Base(outputDir)) } return nil }, diff --git a/log/level/level.go b/log/level.go similarity index 71% rename from log/level/level.go rename to log/level.go index 3b0ee5e..8843d31 100644 --- a/log/level/level.go +++ b/log/level.go @@ -1,6 +1,6 @@ -package level +package log -// Level defines all the available levels we can log at +// Level defines all the available levels we can log at. type Level int32 const ( @@ -8,6 +8,9 @@ const ( // Debug logs are intended for debugging and development purposes. DebugLevel Level = iota + 1 + // InfoLevel is used for user-facing progress and status messages. + InfoLevel + // WarnLevel is used for undesired but relatively expected events, // which may indicate a problem. WarnLevel @@ -24,14 +27,16 @@ const ( func (l Level) String() string { switch l { case DebugLevel: - return "DEBUG" + return "DBG" + case InfoLevel: + return "INF" case WarnLevel: - return "WARN" + return "WRN" case ErrorLevel: - return "ERROR" + return "ERR" case FatalLevel: - return "FATAL" + return "FTL" default: - return "UNKNOWN" + return "???" } } diff --git a/log/log.go b/log/log.go index 14f522c..38d6d4d 100644 --- a/log/log.go +++ b/log/log.go @@ -1,44 +1,52 @@ package log -import ( - "github.com/moond4rk/hackbrowserdata/log/level" -) +import "fmt" // defaultLogger is the default logger used by the package-level functions. var defaultLogger = NewLogger(nil) func SetVerbose() { - defaultLogger.SetLevel(level.DebugLevel) + defaultLogger.SetLevel(DebugLevel) } func Debug(args ...any) { - defaultLogger.Debug(args...) + defaultLogger.logMsg(DebugLevel, fmt.Sprint(args...)) } func Debugf(format string, args ...any) { - defaultLogger.Debugf(format, args...) + defaultLogger.logMsg(DebugLevel, fmt.Sprintf(format, args...)) +} + +func Info(args ...any) { + defaultLogger.logMsg(InfoLevel, fmt.Sprint(args...)) +} + +func Infof(format string, args ...any) { + defaultLogger.logMsg(InfoLevel, fmt.Sprintf(format, args...)) } func Warn(args ...any) { - defaultLogger.Warn(args...) + defaultLogger.logMsg(WarnLevel, fmt.Sprint(args...)) } func Warnf(format string, args ...any) { - defaultLogger.Warnf(format, args...) + defaultLogger.logMsg(WarnLevel, fmt.Sprintf(format, args...)) } func Error(args ...any) { - defaultLogger.Error(args...) + defaultLogger.logMsg(ErrorLevel, fmt.Sprint(args...)) } func Errorf(format string, args ...any) { - defaultLogger.Errorf(format, args...) + defaultLogger.logMsg(ErrorLevel, fmt.Sprintf(format, args...)) } func Fatal(args ...any) { - defaultLogger.Fatal(args...) + defaultLogger.logMsg(FatalLevel, fmt.Sprint(args...)) + osExit(1) } func Fatalf(format string, args ...any) { - defaultLogger.Fatalf(format, args...) + defaultLogger.logMsg(FatalLevel, fmt.Sprintf(format, args...)) + osExit(1) } diff --git a/log/logger.go b/log/logger.go index a006208..5a2ca44 100644 --- a/log/logger.go +++ b/log/logger.go @@ -3,180 +3,158 @@ package log import ( "fmt" "io" - stdlog "log" "os" + "path/filepath" "runtime" "strings" + "sync" "sync/atomic" - - "github.com/moond4rk/hackbrowserdata/log/level" ) // NewLogger creates and returns a new instance of Logger. -// Log level is set to DebugLevel by default. +// Default level is InfoLevel (Debug messages are suppressed unless SetVerbose is called). func NewLogger(base Base) *Logger { if base == nil { base = newBase(os.Stderr) } - return &Logger{base: base, minLevel: level.WarnLevel} + return &Logger{base: base, minLevel: InfoLevel} } -// Logger logs message to io.Writer at various log levels. +// Logger logs messages to io.Writer at various log levels. type Logger struct { base Base // Minimum log level for this logger. - // Message with level lower than this level won't be outputted. - minLevel level.Level + // Messages with level lower than this won't be outputted. + minLevel Level } // canLogAt reports whether logger can log at level v. -func (l *Logger) canLogAt(v level.Level) bool { - return v >= level.Level(atomic.LoadInt32((*int32)(&l.minLevel))) +func (l *Logger) canLogAt(v Level) bool { + return v >= Level(atomic.LoadInt32((*int32)(&l.minLevel))) } // SetLevel sets the logger level. // It panics if v is less than DebugLevel or greater than FatalLevel. -func (l *Logger) SetLevel(v level.Level) { - if v < level.DebugLevel || v > level.FatalLevel { +func (l *Logger) SetLevel(v Level) { + if v < DebugLevel || v > FatalLevel { panic("log: invalid log level") } atomic.StoreInt32((*int32)(&l.minLevel), int32(v)) } +// baseCallerSkip is the number of frames to skip in runtime.Caller to reach +// the actual call site. Both package-level functions (log.Xxx -> logMsg -> base.Log) +// and Logger methods (Logger.Xxx -> logMsg -> base.Log) add exactly one frame +// above logMsg, so the skip is the same: base.Log(0) -> logMsg(1) -> caller_wrapper(2) -> caller(3). +const baseCallerSkip = 3 + +// logMsg is the internal method all public methods delegate to. +func (l *Logger) logMsg(lvl Level, msg string) { + if !l.canLogAt(lvl) { + return + } + l.base.Log(baseCallerSkip, lvl, msg) +} + func (l *Logger) Debug(args ...any) { - if !l.canLogAt(level.DebugLevel) { - return - } - l.base.Debug(args...) -} - -func (l *Logger) Warn(args ...any) { - if !l.canLogAt(level.WarnLevel) { - return - } - l.base.Warn(args...) -} - -func (l *Logger) Error(args ...any) { - if !l.canLogAt(level.ErrorLevel) { - return - } - l.base.Error(args...) -} - -func (l *Logger) Fatal(args ...any) { - if !l.canLogAt(level.FatalLevel) { - return - } - l.base.Fatal(args...) + l.logMsg(DebugLevel, fmt.Sprint(args...)) } func (l *Logger) Debugf(format string, args ...any) { - if !l.canLogAt(level.DebugLevel) { - return - } - l.base.Debug(fmt.Sprintf(format, args...)) + l.logMsg(DebugLevel, fmt.Sprintf(format, args...)) +} + +func (l *Logger) Info(args ...any) { + l.logMsg(InfoLevel, fmt.Sprint(args...)) +} + +func (l *Logger) Infof(format string, args ...any) { + l.logMsg(InfoLevel, fmt.Sprintf(format, args...)) +} + +func (l *Logger) Warn(args ...any) { + l.logMsg(WarnLevel, fmt.Sprint(args...)) } func (l *Logger) Warnf(format string, args ...any) { - if !l.canLogAt(level.WarnLevel) { - return - } - l.base.Warn(fmt.Sprintf(format, args...)) + l.logMsg(WarnLevel, fmt.Sprintf(format, args...)) +} + +func (l *Logger) Error(args ...any) { + l.logMsg(ErrorLevel, fmt.Sprint(args...)) } func (l *Logger) Errorf(format string, args ...any) { - if !l.canLogAt(level.ErrorLevel) { - return - } - l.base.Error(fmt.Sprintf(format, args...)) + l.logMsg(ErrorLevel, fmt.Sprintf(format, args...)) +} + +func (l *Logger) Fatal(args ...any) { + l.logMsg(FatalLevel, fmt.Sprint(args...)) + osExit(1) } func (l *Logger) Fatalf(format string, args ...any) { - if !l.canLogAt(level.FatalLevel) { - return - } - l.base.Fatal(fmt.Sprintf(format, args...)) + l.logMsg(FatalLevel, fmt.Sprintf(format, args...)) + osExit(1) } +// Base is the interface that underlies the Logger. It receives the caller +// skip count, log level, and formatted message. type Base interface { - Debug(args ...any) - Warn(args ...any) - Error(args ...any) - Fatal(args ...any) + Log(callerSkip int, lvl Level, msg string) } -// baseLogger is a wrapper object around log.Logger from the standard library. -// It supports logging at various log levels. +// baseLogger writes formatted log messages to an io.Writer. +// Output format: +// +// [DBG] file.go:42: message +// [INF] message +// [WRN] message +// [ERR] message +// [FTL] message type baseLogger struct { - *stdlog.Logger - callDepth int + out io.Writer + mu sync.Mutex } func newBase(out io.Writer) *baseLogger { - prefix := "[hack-browser-data] " - base := &baseLogger{ - Logger: stdlog.New(out, prefix, stdlog.Lshortfile), - } - base.callDepth = base.calculateCallDepth() - return base -} - -// calculateCallDepth returns the call depth for the logger. -func (l *baseLogger) calculateCallDepth() int { - return l.getCallDepth() -} - -func (l *baseLogger) prefixPrint(prefix string, args ...any) { - args = append([]any{prefix}, args...) - if err := l.Output(l.callDepth, fmt.Sprint(args...)); err != nil { - _, _ = fmt.Fprintf(os.Stderr, "log output error: %v\n", err) - } -} - -func (l *baseLogger) getCallDepth() int { - defaultCallDepth := 2 - pcs := make([]uintptr, 10) - n := runtime.Callers(defaultCallDepth, pcs) - frames := runtime.CallersFrames(pcs[:n]) - for i := 0; i < n; i++ { - frame, more := frames.Next() - if !l.isLoggerPackage(frame.Function) { - return i + 1 - } - if !more { - break - } - } - return defaultCallDepth -} - -func (l *baseLogger) isLoggerPackage(funcName string) bool { - const loggerFuncName = "hackbrowserdata/log" - return strings.Contains(funcName, loggerFuncName) -} - -// Debug logs a message at Debug level. -func (l *baseLogger) Debug(args ...any) { - l.prefixPrint("DEBUG: ", args...) -} - -// Warn logs a message at Warning level. -func (l *baseLogger) Warn(args ...any) { - l.prefixPrint("WARN: ", args...) -} - -// Error logs a message at Error level. -func (l *baseLogger) Error(args ...any) { - l.prefixPrint("ERROR: ", args...) + return &baseLogger{out: out} } var osExit = os.Exit -// Fatal logs a message at Fatal level -// and process will exit with status set to 1. -func (l *baseLogger) Fatal(args ...any) { - l.prefixPrint("FATAL: ", args...) - osExit(1) +// continuation is the indent for multi-line messages. +// Width matches "[DBG] " (6 chars). +const continuation = " " + +func (l *baseLogger) Log(callerSkip int, lvl Level, msg string) { + msg = strings.TrimRight(msg, "\n") + if strings.Contains(msg, "\n") { + msg = strings.ReplaceAll(msg, "\n", "\n"+continuation) + } + + label := l.formatLabel(lvl) + var line string + if lvl == DebugLevel { + _, file, num, ok := runtime.Caller(callerSkip) + if ok { + file = filepath.Base(file) + } else { + file = "???" + num = 0 + } + line = fmt.Sprintf("%s %s:%d: %s\n", label, file, num, msg) + } else { + line = fmt.Sprintf("%s %s\n", label, msg) + } + + l.mu.Lock() + _, _ = io.WriteString(l.out, line) + l.mu.Unlock() +} + +// formatLabel returns the bracketed level label, e.g. "[DBG]". +func (l *baseLogger) formatLabel(lvl Level) string { + return "[" + lvl.String() + "]" } diff --git a/log/logger_test.go b/log/logger_test.go index 9fa8a85..4d52094 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -6,19 +6,13 @@ import ( "testing" "github.com/stretchr/testify/assert" - - level2 "github.com/moond4rk/hackbrowserdata/log/level" -) - -const ( - pattern = `^\[hack\-browser\-data] \w+\.go:\d+:` ) type baseTestCase struct { description string message string suffix string - level level2.Level + level Level wantedPattern string } @@ -38,13 +32,13 @@ var baseTestCases = []baseTestCase{ func TestLoggerDebug(t *testing.T) { for _, tc := range baseTestCases { tc := tc - tc.level = level2.DebugLevel + tc.level = DebugLevel message := tc.message + tc.suffix - tc.wantedPattern = fmt.Sprintf("%s %s: %s\n$", pattern, tc.level, tc.message) + tc.wantedPattern = fmt.Sprintf(`^\[DBG\] \w+\.go:\d+: %s\n$`, tc.message) t.Run(tc.description, func(t *testing.T) { var buf bytes.Buffer logger := NewLogger(newBase(&buf)) - logger.SetLevel(level2.DebugLevel) + logger.SetLevel(DebugLevel) logger.Debug(message) got := buf.String() assert.Regexp(t, tc.wantedPattern, got) @@ -52,12 +46,28 @@ func TestLoggerDebug(t *testing.T) { } } +func TestLoggerInfo(t *testing.T) { + for _, tc := range baseTestCases { + tc := tc + tc.level = InfoLevel + message := tc.message + tc.suffix + tc.wantedPattern = fmt.Sprintf(`^\[INF\] %s\n$`, tc.message) + t.Run(tc.description, func(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger(newBase(&buf)) + logger.Info(message) + got := buf.String() + assert.Regexp(t, tc.wantedPattern, got) + }) + } +} + func TestLoggerWarn(t *testing.T) { for _, tc := range baseTestCases { tc := tc - tc.level = level2.WarnLevel + tc.level = WarnLevel message := tc.message + tc.suffix - tc.wantedPattern = fmt.Sprintf("%s %s: %s\n$", pattern, tc.level, tc.message) + tc.wantedPattern = fmt.Sprintf(`^\[WRN\] %s\n$`, tc.message) t.Run(tc.description, func(t *testing.T) { var buf bytes.Buffer logger := NewLogger(newBase(&buf)) @@ -71,9 +81,9 @@ func TestLoggerWarn(t *testing.T) { func TestLoggerError(t *testing.T) { for _, tc := range baseTestCases { tc := tc - tc.level = level2.ErrorLevel + tc.level = ErrorLevel message := tc.message + tc.suffix - tc.wantedPattern = fmt.Sprintf("%s %s: %s\n$", pattern, tc.level, tc.message) + tc.wantedPattern = fmt.Sprintf(`^\[ERR\] %s\n$`, tc.message) t.Run(tc.description, func(t *testing.T) { var buf bytes.Buffer logger := NewLogger(newBase(&buf)) @@ -90,9 +100,9 @@ func TestLoggerFatal(t *testing.T) { for _, tc := range baseTestCases { tc := tc - tc.level = level2.FatalLevel + tc.level = FatalLevel message := tc.message + tc.suffix - tc.wantedPattern = fmt.Sprintf("%s %s: %s\n$", pattern, tc.level, tc.message) + tc.wantedPattern = fmt.Sprintf(`^\[FTL\] %s\n$`, tc.message) t.Run(tc.description, func(t *testing.T) { var buf bytes.Buffer exitCalled := false @@ -115,23 +125,23 @@ type formatTestCase struct { description string format string args []interface{} - level level2.Level + level Level wantedPattern string } var formatTestCases = []formatTestCase{ { - description: "message with format prefix", + description: "message with string format", format: "hello, %s!", args: []any{"Hacker"}, }, { - description: "message with format prefix", + description: "message with int format", format: "hello, %d,%d,%d!", args: []any{1, 2, 3}, }, { - description: "message with format prefix", + description: "message with mixed format", format: "hello, %s,%d,%d!", args: []any{"Hacker", 2, 3}, }, @@ -140,13 +150,13 @@ var formatTestCases = []formatTestCase{ func TestLoggerDebugf(t *testing.T) { for _, tc := range formatTestCases { tc := tc - tc.level = level2.DebugLevel + tc.level = DebugLevel message := fmt.Sprintf(tc.format, tc.args...) - tc.wantedPattern = fmt.Sprintf("%s %s: %s\n$", pattern, tc.level, message) + tc.wantedPattern = fmt.Sprintf(`^\[DBG\] \w+\.go:\d+: %s\n$`, message) t.Run(tc.description, func(t *testing.T) { var buf bytes.Buffer logger := NewLogger(newBase(&buf)) - logger.SetLevel(level2.DebugLevel) + logger.SetLevel(DebugLevel) logger.Debugf(tc.format, tc.args...) got := buf.String() assert.Regexp(t, tc.wantedPattern, got) @@ -154,12 +164,28 @@ func TestLoggerDebugf(t *testing.T) { } } +func TestLoggerInfof(t *testing.T) { + for _, tc := range formatTestCases { + tc := tc + tc.level = InfoLevel + message := fmt.Sprintf(tc.format, tc.args...) + tc.wantedPattern = fmt.Sprintf(`^\[INF\] %s\n$`, message) + t.Run(tc.description, func(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger(newBase(&buf)) + logger.Infof(tc.format, tc.args...) + got := buf.String() + assert.Regexp(t, tc.wantedPattern, got) + }) + } +} + func TestLoggerWarnf(t *testing.T) { for _, tc := range formatTestCases { tc := tc - tc.level = level2.WarnLevel + tc.level = WarnLevel message := fmt.Sprintf(tc.format, tc.args...) - tc.wantedPattern = fmt.Sprintf("%s %s: %s\n$", pattern, tc.level, message) + tc.wantedPattern = fmt.Sprintf(`^\[WRN\] %s\n$`, message) t.Run(tc.description, func(t *testing.T) { var buf bytes.Buffer logger := NewLogger(newBase(&buf)) @@ -173,9 +199,9 @@ func TestLoggerWarnf(t *testing.T) { func TestLoggerErrorf(t *testing.T) { for _, tc := range formatTestCases { tc := tc - tc.level = level2.ErrorLevel + tc.level = ErrorLevel message := fmt.Sprintf(tc.format, tc.args...) - tc.wantedPattern = fmt.Sprintf("%s %s: %s\n$", pattern, tc.level, message) + tc.wantedPattern = fmt.Sprintf(`^\[ERR\] %s\n$`, message) t.Run(tc.description, func(t *testing.T) { var buf bytes.Buffer logger := NewLogger(newBase(&buf)) @@ -191,9 +217,9 @@ func TestLoggerFatalf(t *testing.T) { defer func() { osExit = originalOsExit }() for _, tc := range formatTestCases { tc := tc - tc.level = level2.FatalLevel + tc.level = FatalLevel message := fmt.Sprintf(tc.format, tc.args...) - tc.wantedPattern = fmt.Sprintf("%s %s: %s\n$", pattern, tc.level, message) + tc.wantedPattern = fmt.Sprintf(`^\[FTL\] %s\n$`, message) t.Run(tc.description, func(t *testing.T) { var buf bytes.Buffer exitCalled := false @@ -213,19 +239,20 @@ func TestLoggerFatalf(t *testing.T) { } func TestLoggerWithLowerLevels(t *testing.T) { - // Logger should not log messages at a level - // lower than the specified level. - levels := []level2.Level{level2.DebugLevel, level2.WarnLevel, level2.ErrorLevel, level2.FatalLevel} + originalOsExit := osExit + defer func() { osExit = originalOsExit }() + + levels := []Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, FatalLevel} ops := []struct { - op string - level level2.Level - logFunc func(*Logger) - expected bool + op string + level Level + logFunc func(*Logger) }{ - {"Debug", level2.DebugLevel, func(l *Logger) { l.Debug("hello") }, false}, - {"Warn", level2.WarnLevel, func(l *Logger) { l.Warn("hello") }, false}, - {"Error", level2.ErrorLevel, func(l *Logger) { l.Error("hello") }, false}, - {"Fatal", level2.FatalLevel, func(l *Logger) { l.Fatal("hello") }, false}, + {"Debug", DebugLevel, func(l *Logger) { l.Debug("hello") }}, + {"Info", InfoLevel, func(l *Logger) { l.Info("hello") }}, + {"Warn", WarnLevel, func(l *Logger) { l.Warn("hello") }}, + {"Error", ErrorLevel, func(l *Logger) { l.Error("hello") }}, + {"Fatal", FatalLevel, func(l *Logger) { l.Fatal("hello") }}, } for _, setLevel := range levels { @@ -236,23 +263,57 @@ func TestLoggerWithLowerLevels(t *testing.T) { expectedOutput := op.level >= setLevel exitCalled := false - exitCode := 0 osExit = func(code int) { exitCalled = true - exitCode = code } op.logFunc(logger) output := buf.String() if expectedOutput { - assert.NotEmpty(t, output) + assert.NotEmpty(t, output, "setLevel=%s op=%s should produce output", setLevel, op.op) } else { - assert.Empty(t, output) + assert.Empty(t, output, "setLevel=%s op=%s should be suppressed", setLevel, op.op) } - if op.op == "Fatal" { - assert.True(t, exitCalled) - assert.Equal(t, 1, exitCode) + if op.op == "Fatal" && expectedOutput { + assert.True(t, exitCalled, "Fatal should call osExit") } } } } + +func TestDefaultLevelIsInfo(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger(newBase(&buf)) + + // Debug should be suppressed at default level (InfoLevel). + logger.Debug("debug msg") + assert.Empty(t, buf.String(), "Debug should be suppressed at default InfoLevel") + + // Info should be visible at default level. + logger.Info("info msg") + assert.Contains(t, buf.String(), "info msg") +} + +func TestDebugIncludesFileLine(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger(newBase(&buf)) + logger.SetLevel(DebugLevel) + logger.Debug("test location") + got := buf.String() + assert.Regexp(t, `^\[DBG\] logger_test\.go:\d+: test location\n$`, got) +} + +func TestInfoHasLabel(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger(newBase(&buf)) + logger.Info("clean message") + assert.Equal(t, "[INF] clean message\n", buf.String()) +} + +func TestMultilineMessageIndented(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger(newBase(&buf)) + logger.Warn("line1\nline2\nline3") + got := buf.String() + assert.Equal(t, "[WRN] line1\n line2\n line3\n", got) +} diff --git a/output/output.go b/output/output.go index c272479..d962118 100644 --- a/output/output.go +++ b/output/output.go @@ -60,11 +60,20 @@ func (o *Writer) Write() error { if err := os.MkdirAll(o.dir, 0o750); err != nil { return fmt.Errorf("create output dir: %w", err) } - for _, cs := range o.aggregate() { + agg := o.aggregate() + for _, cs := range agg { if err := o.writeFile(cs.name, cs.rows); err != nil { return err } } + if len(agg) > 0 { + fmt.Fprintln(os.Stderr) + log.Infof("Exported to %s/", o.dir) + for _, cs := range agg { + filename := fmt.Sprintf("%s.%s", cs.name, o.formatter.ext()) + log.Infof(" %-24s %d entries", filename, len(cs.rows)) + } + } return nil } @@ -155,6 +164,5 @@ func (o *Writer) writeFile(category string, rows []row) (err error) { if _, err := f.Write(buf.Bytes()); err != nil { return fmt.Errorf("write %s: %w", filename, err) } - log.Warnf("export: %s", path) return nil }