diff --git a/errors.go b/errors.go index d06cd5a..41a22f8 100644 --- a/errors.go +++ b/errors.go @@ -68,9 +68,9 @@ func Wrap(err error, op, msg string) error { return nil } // Preserve Code from wrapped *Err - var logErr *Err - if As(err, &logErr) && logErr.Code != "" { - return &Err{Op: op, Msg: msg, Err: err, Code: logErr.Code} + var typedError *Err + if As(err, &typedError) && typedError.Code != "" { + return &Err{Op: op, Msg: msg, Err: err, Code: typedError.Code} } return &Err{Op: op, Msg: msg, Err: err} } @@ -102,25 +102,30 @@ func NewCode(code, msg string) error { // --- Standard Library Wrappers --- // Is reports whether any error in err's tree matches target. -// Wrapper around errors.Is for convenience. +// +// if log.Is(err, ErrNotFound) { /* handle */ } func Is(err, target error) bool { return errors.Is(err, target) } // As finds the first error in err's tree that matches target. -// Wrapper around errors.As for convenience. +// +// var typedError *log.Err +// if log.As(err, &typedError) { code := typedError.Code } func As(err error, target any) bool { return errors.As(err, target) } // NewError creates a simple error with the given text. -// Wrapper around errors.New for convenience. +// +// var ErrNotFound = log.NewError("not found") func NewError(text string) error { return errors.New(text) } // Join combines multiple errors into one. -// Wrapper around errors.Join for convenience. +// +// return log.Join(validationErr, permissionErr) func Join(errs ...error) error { return errors.Join(errs...) } @@ -132,9 +137,9 @@ func Join(errs ...error) error { // // op := log.Op(err) // e.g. "user.Save" func Op(err error) string { - var e *Err - if As(err, &e) { - return e.Op + var typedError *Err + if As(err, &typedError) { + return typedError.Op } return "" } @@ -144,22 +149,24 @@ func Op(err error) string { // // code := log.ErrCode(err) // e.g. "VALIDATION_FAILED" func ErrCode(err error) string { - var e *Err - if As(err, &e) { - return e.Code + var typedError *Err + if As(err, &typedError) { + return typedError.Code } return "" } // Message extracts the message from an error. // Returns the error's Error() string if not an *Err. +// +// msg := log.Message(err) // "rate limited" (not the full "api.Call: rate limited: ...") func Message(err error) string { if err == nil { return "" } - var e *Err - if As(err, &e) { - return e.Msg + var typedError *Err + if As(err, &typedError) { + return typedError.Msg } return err.Error() } diff --git a/errors_test.go b/errors_test.go index 10b99ca..9194144 100644 --- a/errors_test.go +++ b/errors_test.go @@ -10,28 +10,26 @@ import ( "github.com/stretchr/testify/assert" ) -// --- Err Type Tests --- +// --- Err type --- -func TestErr_Error_Good(t *testing.T) { - // With underlying error +func TestErrors_ErrError_Good(t *testing.T) { + // Op + Msg + underlying error err := &Err{Op: "db.Query", Msg: "failed to query", Err: errors.New("connection refused")} assert.Equal(t, "db.Query: failed to query: connection refused", err.Error()) - - // With code - err = &Err{Op: "api.Call", Msg: "request failed", Code: "TIMEOUT"} - assert.Equal(t, "api.Call: request failed [TIMEOUT]", err.Error()) - - // With both underlying error and code - err = &Err{Op: "user.Save", Msg: "save failed", Err: errors.New("duplicate key"), Code: "DUPLICATE"} - assert.Equal(t, "user.Save: save failed [DUPLICATE]: duplicate key", err.Error()) - - // Just op and msg - err = &Err{Op: "cache.Get", Msg: "miss"} - assert.Equal(t, "cache.Get: miss", err.Error()) } -func TestErr_Error_EmptyOp_Good(t *testing.T) { - // No Op - should not have leading colon +func TestErrors_ErrError_Bad(t *testing.T) { + // Code included in message + err := &Err{Op: "api.Call", Msg: "request failed", Code: "TIMEOUT"} + assert.Equal(t, "api.Call: request failed [TIMEOUT]", err.Error()) + + // All three: Op, Msg, Code, and underlying error + err = &Err{Op: "user.Save", Msg: "save failed", Err: errors.New("duplicate key"), Code: "DUPLICATE"} + assert.Equal(t, "user.Save: save failed [DUPLICATE]: duplicate key", err.Error()) +} + +func TestErrors_ErrError_Ugly(t *testing.T) { + // No Op — no leading colon err := &Err{Msg: "just a message"} assert.Equal(t, "just a message", err.Error()) @@ -39,12 +37,18 @@ func TestErr_Error_EmptyOp_Good(t *testing.T) { err = &Err{Msg: "error with code", Code: "ERR_CODE"} assert.Equal(t, "error with code [ERR_CODE]", err.Error()) - // No Op with underlying error + // No Op with underlying error only err = &Err{Msg: "wrapped", Err: errors.New("underlying")} assert.Equal(t, "wrapped: underlying", err.Error()) + + // Just op and msg, no error and no code + err = &Err{Op: "cache.Get", Msg: "miss"} + assert.Equal(t, "cache.Get: miss", err.Error()) } -func TestErr_Unwrap_Good(t *testing.T) { +// --- Err.Unwrap --- + +func TestErrors_ErrUnwrap_Good(t *testing.T) { underlying := errors.New("underlying error") err := &Err{Op: "test", Msg: "wrapped", Err: underlying} @@ -52,28 +56,50 @@ func TestErr_Unwrap_Good(t *testing.T) { assert.True(t, errors.Is(err, underlying)) } -// --- Error Creation Function Tests --- +func TestErrors_ErrUnwrap_Bad(t *testing.T) { + // No underlying error — Unwrap returns nil + err := &Err{Op: "op", Msg: "no cause"} + assert.Nil(t, errors.Unwrap(err)) +} -func TestE_Good(t *testing.T) { +func TestErrors_ErrUnwrap_Ugly(t *testing.T) { + // Deeply nested — errors.Is still traverses the chain + root := errors.New("root") + level1 := &Err{Op: "l1", Msg: "level1", Err: root} + level2 := &Err{Op: "l2", Msg: "level2", Err: level1} + assert.True(t, errors.Is(level2, root)) +} + +// --- E --- + +func TestErrors_E_Good(t *testing.T) { underlying := errors.New("base error") err := E("op.Name", "something failed", underlying) assert.NotNil(t, err) - var logErr *Err - assert.True(t, errors.As(err, &logErr)) - assert.Equal(t, "op.Name", logErr.Op) - assert.Equal(t, "something failed", logErr.Msg) - assert.Equal(t, underlying, logErr.Err) + var typedError *Err + assert.True(t, errors.As(err, &typedError)) + assert.Equal(t, "op.Name", typedError.Op) + assert.Equal(t, "something failed", typedError.Msg) + assert.Equal(t, underlying, typedError.Err) } -func TestE_Good_NilError(t *testing.T) { - // E creates an error even with nil underlying - useful for errors without causes +func TestErrors_E_Bad(t *testing.T) { + // E with nil underlying error still creates an error err := E("op.Name", "message", nil) assert.NotNil(t, err) assert.Equal(t, "op.Name: message", err.Error()) } -func TestWrap_Good(t *testing.T) { +func TestErrors_E_Ugly(t *testing.T) { + // E with empty op produces no leading colon + err := E("", "bare message", nil) + assert.Equal(t, "bare message", err.Error()) +} + +// --- Wrap --- + +func TestErrors_Wrap_Good(t *testing.T) { underlying := errors.New("base") err := Wrap(underlying, "handler.Process", "processing failed") @@ -83,11 +109,15 @@ func TestWrap_Good(t *testing.T) { assert.True(t, errors.Is(err, underlying)) } -func TestWrap_PreservesCode_Good(t *testing.T) { - // Create an error with a code - inner := WrapCode(errors.New("base"), "VALIDATION_ERROR", "inner.Op", "validation failed") +func TestErrors_Wrap_Bad(t *testing.T) { + // Wrap nil returns nil + err := Wrap(nil, "op", "msg") + assert.Nil(t, err) +} - // Wrap it - should preserve the code +func TestErrors_Wrap_Ugly(t *testing.T) { + // Wrap preserves Code from the inner *Err + inner := WrapCode(errors.New("base"), "VALIDATION_ERROR", "inner.Op", "validation failed") outer := Wrap(inner, "outer.Op", "outer context") assert.NotNil(t, outer) @@ -95,69 +125,135 @@ func TestWrap_PreservesCode_Good(t *testing.T) { assert.Contains(t, outer.Error(), "[VALIDATION_ERROR]") } -func TestWrap_NilError_Good(t *testing.T) { - err := Wrap(nil, "op", "msg") - assert.Nil(t, err) -} +// --- WrapCode --- -func TestWrapCode_Good(t *testing.T) { +func TestErrors_WrapCode_Good(t *testing.T) { underlying := errors.New("validation failed") err := WrapCode(underlying, "INVALID_INPUT", "api.Validate", "bad request") assert.NotNil(t, err) - var logErr *Err - assert.True(t, errors.As(err, &logErr)) - assert.Equal(t, "INVALID_INPUT", logErr.Code) - assert.Equal(t, "api.Validate", logErr.Op) + var typedError *Err + assert.True(t, errors.As(err, &typedError)) + assert.Equal(t, "INVALID_INPUT", typedError.Code) + assert.Equal(t, "api.Validate", typedError.Op) assert.Contains(t, err.Error(), "[INVALID_INPUT]") } -func TestWrapCode_Good_NilError(t *testing.T) { - // WrapCode with nil error but with code still creates an error +func TestErrors_WrapCode_Bad(t *testing.T) { + // nil error but with code still creates an error err := WrapCode(nil, "CODE", "op", "msg") assert.NotNil(t, err) assert.Contains(t, err.Error(), "[CODE]") +} - // Only returns nil when both error and code are empty - err = WrapCode(nil, "", "op", "msg") +func TestErrors_WrapCode_Ugly(t *testing.T) { + // nil error AND empty code — only then returns nil + err := WrapCode(nil, "", "op", "msg") assert.Nil(t, err) } -func TestNewCode_Good(t *testing.T) { +// --- NewCode --- + +func TestErrors_NewCode_Good(t *testing.T) { err := NewCode("NOT_FOUND", "resource not found") - var logErr *Err - assert.True(t, errors.As(err, &logErr)) - assert.Equal(t, "NOT_FOUND", logErr.Code) - assert.Equal(t, "resource not found", logErr.Msg) - assert.Nil(t, logErr.Err) + var typedError *Err + assert.True(t, errors.As(err, &typedError)) + assert.Equal(t, "NOT_FOUND", typedError.Code) + assert.Equal(t, "resource not found", typedError.Msg) + assert.Nil(t, typedError.Err) } -// --- Standard Library Wrapper Tests --- +func TestErrors_NewCode_Bad(t *testing.T) { + // Empty code is preserved as-is + err := NewCode("", "no code error") + assert.NotNil(t, err) + assert.Equal(t, "no code error", err.Error()) +} -func TestIs_Good(t *testing.T) { +func TestErrors_NewCode_Ugly(t *testing.T) { + // NewCode result can be used as a sentinel value + sentinel := NewCode("SENTINEL", "sentinel error") + wrapped := Wrap(sentinel, "caller.Op", "something went wrong") + assert.True(t, Is(wrapped, sentinel)) +} + +// --- Is --- + +func TestErrors_Is_Good(t *testing.T) { sentinel := errors.New("sentinel") wrapped := Wrap(sentinel, "test", "wrapped") assert.True(t, Is(wrapped, sentinel)) - assert.False(t, Is(wrapped, errors.New("other"))) } -func TestAs_Good(t *testing.T) { +func TestErrors_Is_Bad(t *testing.T) { + // Different errors are not equal + assert.False(t, Is(errors.New("a"), errors.New("b"))) +} + +func TestErrors_Is_Ugly(t *testing.T) { + // nil target + assert.False(t, Is(errors.New("something"), nil)) + // nil err + assert.False(t, Is(nil, errors.New("something"))) + // both nil + assert.True(t, Is(nil, nil)) +} + +// --- As --- + +func TestErrors_As_Good(t *testing.T) { err := E("test.Op", "message", errors.New("base")) - var logErr *Err - assert.True(t, As(err, &logErr)) - assert.Equal(t, "test.Op", logErr.Op) + var typedError *Err + assert.True(t, As(err, &typedError)) + assert.Equal(t, "test.Op", typedError.Op) } -func TestNewError_Good(t *testing.T) { +func TestErrors_As_Bad(t *testing.T) { + // As returns false for non-matching types + err := errors.New("plain") + var typedError *Err + assert.False(t, As(err, &typedError)) +} + +func TestErrors_As_Ugly(t *testing.T) { + // As traverses the chain to find *Err + plain := errors.New("base") + wrapped := Wrap(plain, "op", "msg") + doubleWrapped := fmt.Errorf("fmt wrapper: %w", wrapped) + + var typedError *Err + assert.True(t, As(doubleWrapped, &typedError)) + assert.Equal(t, "op", typedError.Op) +} + +// --- NewError --- + +func TestErrors_NewError_Good(t *testing.T) { err := NewError("simple error") assert.NotNil(t, err) assert.Equal(t, "simple error", err.Error()) } -func TestJoin_Good(t *testing.T) { +func TestErrors_NewError_Bad(t *testing.T) { + // Two NewError calls with same text are distinct values + a := NewError("same text") + b := NewError("same text") + assert.False(t, Is(a, b), "two NewError values with same text must not match via Is") +} + +func TestErrors_NewError_Ugly(t *testing.T) { + // Empty text produces an error with empty message + err := NewError("") + assert.NotNil(t, err) + assert.Equal(t, "", err.Error()) +} + +// --- Join --- + +func TestErrors_Join_Good(t *testing.T) { err1 := errors.New("error 1") err2 := errors.New("error 2") joined := Join(err1, err2) @@ -166,52 +262,78 @@ func TestJoin_Good(t *testing.T) { assert.True(t, errors.Is(joined, err2)) } -// --- Helper Function Tests --- +func TestErrors_Join_Bad(t *testing.T) { + // All nil — returns nil + assert.Nil(t, Join(nil, nil)) +} -func TestOp_Good(t *testing.T) { +func TestErrors_Join_Ugly(t *testing.T) { + // Mix of nil and non-nil — non-nil are preserved + err := errors.New("only error") + joined := Join(nil, err, nil) + assert.True(t, errors.Is(joined, err)) +} + +// --- Op --- + +func TestErrors_Op_Good(t *testing.T) { err := E("mypackage.MyFunc", "failed", errors.New("cause")) assert.Equal(t, "mypackage.MyFunc", Op(err)) } -func TestOp_Good_NotLogError(t *testing.T) { +func TestErrors_Op_Bad(t *testing.T) { + // Plain error has no op err := errors.New("plain error") assert.Equal(t, "", Op(err)) } -func TestErrCode_Good(t *testing.T) { +func TestErrors_Op_Ugly(t *testing.T) { + // Outer op is returned, not inner + inner := E("inner.Op", "inner", nil) + outer := Wrap(inner, "outer.Op", "outer") + assert.Equal(t, "outer.Op", Op(outer)) +} + +// --- ErrCode --- + +func TestErrors_ErrCode_Good(t *testing.T) { err := WrapCode(errors.New("base"), "ERR_CODE", "op", "msg") assert.Equal(t, "ERR_CODE", ErrCode(err)) } -func TestErrCode_Good_NoCode(t *testing.T) { +func TestErrors_ErrCode_Bad(t *testing.T) { + // No code on a plain *Err err := E("op", "msg", errors.New("base")) assert.Equal(t, "", ErrCode(err)) } -func TestErrCode_Good_PlainError(t *testing.T) { - err := errors.New("plain error") - assert.Equal(t, "", ErrCode(err)) -} - -func TestErrCode_Good_Nil(t *testing.T) { +func TestErrors_ErrCode_Ugly(t *testing.T) { + // Nil and plain errors both return empty string assert.Equal(t, "", ErrCode(nil)) + assert.Equal(t, "", ErrCode(errors.New("plain"))) } -func TestMessage_Good(t *testing.T) { +// --- Message --- + +func TestErrors_Message_Good(t *testing.T) { err := E("op", "the message", errors.New("base")) assert.Equal(t, "the message", Message(err)) } -func TestMessage_Good_PlainError(t *testing.T) { +func TestErrors_Message_Bad(t *testing.T) { + // Plain error — falls back to Error() string err := errors.New("plain message") assert.Equal(t, "plain message", Message(err)) } -func TestMessage_Good_Nil(t *testing.T) { +func TestErrors_Message_Ugly(t *testing.T) { + // Nil returns empty string assert.Equal(t, "", Message(nil)) } -func TestRoot_Good(t *testing.T) { +// --- Root --- + +func TestErrors_Root_Good(t *testing.T) { root := errors.New("root cause") level1 := Wrap(root, "level1", "wrapped once") level2 := Wrap(level1, "level2", "wrapped twice") @@ -219,19 +341,88 @@ func TestRoot_Good(t *testing.T) { assert.Equal(t, root, Root(level2)) } -func TestRoot_Good_SingleError(t *testing.T) { +func TestErrors_Root_Bad(t *testing.T) { + // Single unwrapped error returns itself err := errors.New("single") assert.Equal(t, err, Root(err)) } -func TestRoot_Good_Nil(t *testing.T) { +func TestErrors_Root_Ugly(t *testing.T) { + // Nil returns nil assert.Nil(t, Root(nil)) } -// --- Log-and-Return Helper Tests --- +// --- StackTrace / FormatStackTrace --- -func TestLogError_Good(t *testing.T) { - // Capture log output +func TestErrors_StackTrace_Good(t *testing.T) { + err := E("op1", "msg1", nil) + err = Wrap(err, "op2", "msg2") + err = Wrap(err, "op3", "msg3") + + stack := StackTrace(err) + assert.Equal(t, []string{"op3", "op2", "op1"}, stack) + + formatted := FormatStackTrace(err) + assert.Equal(t, "op3 -> op2 -> op1", formatted) +} + +func TestErrors_StackTrace_Bad(t *testing.T) { + // Plain error has no ops in the stack + err := errors.New("plain error") + assert.Empty(t, StackTrace(err)) + assert.Empty(t, FormatStackTrace(err)) +} + +func TestErrors_StackTrace_Ugly(t *testing.T) { + // Nil and *Err with no Op both yield empty stack + assert.Empty(t, StackTrace(nil)) + assert.Empty(t, FormatStackTrace(nil)) + assert.Empty(t, StackTrace(&Err{Msg: "no op"})) + + // Mixed chain: fmt.Errorf wrapper in the middle — ops on both sides still appear + inner := E("inner", "msg", nil) + wrapped := fmt.Errorf("fmt wrapper: %w", inner) + outer := Wrap(wrapped, "outer", "msg") + + stack := StackTrace(outer) + assert.Equal(t, []string{"outer", "inner"}, stack) +} + +// --- AllOps --- + +func TestErrors_AllOps_Good(t *testing.T) { + err := E("op1", "msg1", nil) + err = Wrap(err, "op2", "msg2") + + var ops []string + for op := range AllOps(err) { + ops = append(ops, op) + } + assert.Equal(t, []string{"op2", "op1"}, ops) +} + +func TestErrors_AllOps_Bad(t *testing.T) { + // Plain error yields no ops + err := errors.New("plain") + var ops []string + for op := range AllOps(err) { + ops = append(ops, op) + } + assert.Empty(t, ops) +} + +func TestErrors_AllOps_Ugly(t *testing.T) { + // Nil error — iterator yields nothing, no panic + var ops []string + for op := range AllOps(nil) { + ops = append(ops, op) + } + assert.Empty(t, ops) +} + +// --- LogError --- + +func TestErrors_LogError_Good(t *testing.T) { var buf bytes.Buffer logger := New(Options{Level: LevelDebug, Output: &buf}) SetDefault(logger) @@ -240,20 +431,19 @@ func TestLogError_Good(t *testing.T) { underlying := errors.New("connection failed") err := LogError(underlying, "db.Connect", "database unavailable") - // Check returned error assert.NotNil(t, err) assert.Contains(t, err.Error(), "db.Connect") assert.Contains(t, err.Error(), "database unavailable") assert.True(t, errors.Is(err, underlying)) - // Check log output output := buf.String() assert.Contains(t, output, "[ERR]") assert.Contains(t, output, "database unavailable") assert.Contains(t, output, "op=\"db.Connect\"") } -func TestLogError_Good_NilError(t *testing.T) { +func TestErrors_LogError_Bad(t *testing.T) { + // nil error — returns nil, no log output var buf bytes.Buffer logger := New(Options{Level: LevelDebug, Output: &buf}) SetDefault(logger) @@ -261,10 +451,27 @@ func TestLogError_Good_NilError(t *testing.T) { err := LogError(nil, "op", "msg") assert.Nil(t, err) - assert.Empty(t, buf.String()) // No log output for nil error + assert.Empty(t, buf.String()) } -func TestLogWarn_Good(t *testing.T) { +func TestErrors_LogError_Ugly(t *testing.T) { + // LogError on an already-wrapped *Err — error chain preserved + var buf bytes.Buffer + logger := New(Options{Level: LevelDebug, Output: &buf}) + SetDefault(logger) + defer SetDefault(New(Options{Level: LevelInfo})) + + root := errors.New("root") + inner := E("inner.Op", "inner failed", root) + err := LogError(inner, "outer.Op", "outer context") + + assert.True(t, errors.Is(err, root)) + assert.Contains(t, buf.String(), "[ERR]") +} + +// --- LogWarn --- + +func TestErrors_LogWarn_Good(t *testing.T) { var buf bytes.Buffer logger := New(Options{Level: LevelDebug, Output: &buf}) SetDefault(logger) @@ -275,13 +482,12 @@ func TestLogWarn_Good(t *testing.T) { assert.NotNil(t, err) assert.True(t, errors.Is(err, underlying)) - - output := buf.String() - assert.Contains(t, output, "[WRN]") - assert.Contains(t, output, "falling back to db") + assert.Contains(t, buf.String(), "[WRN]") + assert.Contains(t, buf.String(), "falling back to db") } -func TestLogWarn_Good_NilError(t *testing.T) { +func TestErrors_LogWarn_Bad(t *testing.T) { + // nil error — returns nil, no log output var buf bytes.Buffer logger := New(Options{Level: LevelDebug, Output: &buf}) SetDefault(logger) @@ -292,14 +498,28 @@ func TestLogWarn_Good_NilError(t *testing.T) { assert.Empty(t, buf.String()) } -func TestMust_Good_NoError(t *testing.T) { - // Should not panic when error is nil +func TestErrors_LogWarn_Ugly(t *testing.T) { + // LogWarn at LevelError — [WRN] is suppressed since Warn < Error threshold + var buf bytes.Buffer + logger := New(Options{Level: LevelError, Output: &buf}) + SetDefault(logger) + defer SetDefault(New(Options{Level: LevelInfo})) + + LogWarn(errors.New("warn level"), "op", "msg") + assert.Empty(t, buf.String(), "expected warn suppressed at LevelError") +} + +// --- Must --- + +func TestErrors_Must_Good(t *testing.T) { + // nil error — no panic assert.NotPanics(t, func() { Must(nil, "test", "should not panic") }) } -func TestMust_Ugly_Panics(t *testing.T) { +func TestErrors_Must_Bad(t *testing.T) { + // Non-nil error — panics with wrapped error var buf bytes.Buffer logger := New(Options{Level: LevelDebug, Output: &buf}) SetDefault(logger) @@ -309,47 +529,21 @@ func TestMust_Ugly_Panics(t *testing.T) { Must(errors.New("fatal error"), "startup", "initialization failed") }) - // Verify error was logged before panic output := buf.String() assert.True(t, core.Contains(output, "[ERR]") || len(output) > 0) } -func TestStackTrace_Good(t *testing.T) { - // Nested operations - err := E("op1", "msg1", nil) - err = Wrap(err, "op2", "msg2") - err = Wrap(err, "op3", "msg3") +func TestErrors_Must_Ugly(t *testing.T) { + // Panic value is a wrapped *Err, not the raw error + var panicValue any + func() { + defer func() { panicValue = recover() }() + Must(errors.New("root cause"), "init.Op", "startup failed") + }() - stack := StackTrace(err) - assert.Equal(t, []string{"op3", "op2", "op1"}, stack) - - // Format - formatted := FormatStackTrace(err) - assert.Equal(t, "op3 -> op2 -> op1", formatted) -} - -func TestStackTrace_PlainError(t *testing.T) { - err := errors.New("plain error") - assert.Empty(t, StackTrace(err)) - assert.Empty(t, FormatStackTrace(err)) -} - -func TestStackTrace_Nil(t *testing.T) { - assert.Empty(t, StackTrace(nil)) - assert.Empty(t, FormatStackTrace(nil)) -} - -func TestStackTrace_NoOp(t *testing.T) { - err := &Err{Msg: "no op"} - assert.Empty(t, StackTrace(err)) - assert.Empty(t, FormatStackTrace(err)) -} - -func TestStackTrace_Mixed_Good(t *testing.T) { - err := E("inner", "msg", nil) - err = fmt.Errorf("wrapper: %w", err) - err = Wrap(err, "outer", "msg") - - stack := StackTrace(err) - assert.Equal(t, []string{"outer", "inner"}, stack) + assert.NotNil(t, panicValue) + panicErr, ok := panicValue.(error) + assert.True(t, ok, "panic value must be an error") + assert.Contains(t, panicErr.Error(), "init.Op") + assert.Contains(t, panicErr.Error(), "startup failed") } diff --git a/log.go b/log.go index e2a1392..152b303 100644 --- a/log.go +++ b/log.go @@ -109,6 +109,9 @@ type Options struct { var RotationWriterFactory func(RotationOptions) goio.WriteCloser // New creates a new Logger with the given options. +// +// logger := log.New(log.Options{Level: log.LevelInfo, Output: os.Stderr}) +// logger := log.New(log.Options{Level: log.LevelDebug, RedactKeys: []string{"password"}}) func New(opts Options) *Logger { output := opts.Output if opts.Rotation != nil && opts.Rotation.Filename != "" && RotationWriterFactory != nil { @@ -185,33 +188,33 @@ func (l *Logger) log(level Level, prefix, msg string, keyvals ...any) { timestamp := styleTimestamp(time.Now().Format("15:04:05")) // Automatically extract context from error if present in keyvals - origLen := len(keyvals) - for i := 0; i < origLen; i += 2 { - if i+1 < origLen { + originalLength := len(keyvals) + for i := 0; i < originalLength; i += 2 { + if i+1 < originalLength { if err, ok := keyvals[i+1].(error); ok { if op := Op(err); op != "" { // Check if op is already in keyvals - hasOp := false + hasOperationKey := false for j := 0; j < len(keyvals); j += 2 { if k, ok := keyvals[j].(string); ok && k == "op" { - hasOp = true + hasOperationKey = true break } } - if !hasOp { + if !hasOperationKey { keyvals = append(keyvals, "op", op) } } if stack := FormatStackTrace(err); stack != "" { // Check if stack is already in keyvals - hasStack := false + hasStackKey := false for j := 0; j < len(keyvals); j += 2 { if k, ok := keyvals[j].(string); ok && k == "stack" { - hasStack = true + hasStackKey = true break } } - if !hasStack { + if !hasStackKey { keyvals = append(keyvals, "stack", stack) } } @@ -220,12 +223,12 @@ func (l *Logger) log(level Level, prefix, msg string, keyvals ...any) { } // Format key-value pairs - var kvStr string + var keyValueString string if len(keyvals) > 0 { - kvStr = " " + keyValueString = " " for i := 0; i < len(keyvals); i += 2 { if i > 0 { - kvStr += " " + keyValueString += " " } key := keyvals[i] var val any @@ -241,14 +244,14 @@ func (l *Logger) log(level Level, prefix, msg string, keyvals ...any) { // Secure formatting to prevent log injection if s, ok := val.(string); ok { - kvStr += core.Sprintf("%v=%q", key, s) + keyValueString += core.Sprintf("%v=%q", key, s) } else { - kvStr += core.Sprintf("%v=%v", key, val) + keyValueString += core.Sprintf("%v=%v", key, val) } } } - _, _ = fmt.Fprintf(output, "%s %s %s%s\n", timestamp, prefix, msg, kvStr) + _, _ = fmt.Fprintf(output, "%s %s %s%s\n", timestamp, prefix, msg, keyValueString) } // Debug logs a debug message with optional key-value pairs. @@ -299,7 +302,8 @@ func (l *Logger) Security(msg string, keyvals ...any) { } // Username returns the current system username. -// It uses os/user for reliability and falls back to environment variables. +// +// owner := log.Username() // e.g. "deploy", "www-data" func Username() string { if u, err := user.Current(); err == nil { return u.Username @@ -330,36 +334,50 @@ func SetDefault(l *Logger) { } // SetLevel sets the default logger's level. +// +// log.SetLevel(log.LevelDebug) func SetLevel(level Level) { defaultLogger.SetLevel(level) } // SetRedactKeys sets the default logger's redaction keys. +// +// log.SetRedactKeys("password", "token", "api_key") func SetRedactKeys(keys ...string) { defaultLogger.SetRedactKeys(keys...) } -// Debug logs to the default logger. +// Debug logs a debug message to the default logger. +// +// log.Debug("cache lookup", "key", "user:42", "hit", false) func Debug(msg string, keyvals ...any) { defaultLogger.Debug(msg, keyvals...) } -// Info logs to the default logger. +// Info logs an informational message to the default logger. +// +// log.Info("server started", "port", 8080) func Info(msg string, keyvals ...any) { defaultLogger.Info(msg, keyvals...) } -// Warn logs to the default logger. +// Warn logs a warning message to the default logger. +// +// log.Warn("retrying", "attempt", 2, "max", 3) func Warn(msg string, keyvals ...any) { defaultLogger.Warn(msg, keyvals...) } -// Error logs to the default logger. +// Error logs an error message to the default logger. +// +// log.Error("request failed", "err", err, "path", r.URL.Path) func Error(msg string, keyvals ...any) { defaultLogger.Error(msg, keyvals...) } -// Security logs to the default logger. +// Security logs a security event to the default logger. +// +// log.Security("login failed", "ip", remoteAddr, "user", username) func Security(msg string, keyvals ...any) { defaultLogger.Security(msg, keyvals...) } diff --git a/log_test.go b/log_test.go index a127dd7..313bbc9 100644 --- a/log_test.go +++ b/log_test.go @@ -16,61 +16,348 @@ func substringCount(s, substr string) int { return len(core.Split(s, substr)) - 1 } -func TestLogger_Levels(t *testing.T) { - tests := []struct { - name string +// --- Level.String --- + +func TestLog_LevelString_Good(t *testing.T) { + cases := []struct { level Level - logFunc func(*Logger, string, ...any) - expected bool + expected string }{ - {"debug at debug", LevelDebug, (*Logger).Debug, true}, - {"info at debug", LevelDebug, (*Logger).Info, true}, - {"warn at debug", LevelDebug, (*Logger).Warn, true}, - {"error at debug", LevelDebug, (*Logger).Error, true}, - - {"debug at info", LevelInfo, (*Logger).Debug, false}, - {"info at info", LevelInfo, (*Logger).Info, true}, - {"warn at info", LevelInfo, (*Logger).Warn, true}, - {"error at info", LevelInfo, (*Logger).Error, true}, - - {"debug at warn", LevelWarn, (*Logger).Debug, false}, - {"info at warn", LevelWarn, (*Logger).Info, false}, - {"warn at warn", LevelWarn, (*Logger).Warn, true}, - {"error at warn", LevelWarn, (*Logger).Error, true}, - - {"debug at error", LevelError, (*Logger).Debug, false}, - {"info at error", LevelError, (*Logger).Info, false}, - {"warn at error", LevelError, (*Logger).Warn, false}, - {"error at error", LevelError, (*Logger).Error, true}, - - {"debug at quiet", LevelQuiet, (*Logger).Debug, false}, - {"info at quiet", LevelQuiet, (*Logger).Info, false}, - {"warn at quiet", LevelQuiet, (*Logger).Warn, false}, - {"error at quiet", LevelQuiet, (*Logger).Error, false}, - - {"security at info", LevelInfo, (*Logger).Security, true}, - {"security at error", LevelError, (*Logger).Security, true}, + {LevelQuiet, "quiet"}, + {LevelError, "error"}, + {LevelWarn, "warn"}, + {LevelInfo, "info"}, + {LevelDebug, "debug"}, } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - var buf bytes.Buffer - l := New(Options{Level: tt.level, Output: &buf}) - tt.logFunc(l, "test message") - - hasOutput := buf.Len() > 0 - if hasOutput != tt.expected { - t.Errorf("expected output=%v, got output=%v", tt.expected, hasOutput) + for _, tc := range cases { + t.Run(tc.expected, func(t *testing.T) { + if got := tc.level.String(); got != tc.expected { + t.Errorf("expected %q, got %q", tc.expected, got) } }) } } -func TestLogger_KeyValues(t *testing.T) { - var buf bytes.Buffer - l := New(Options{Level: LevelDebug, Output: &buf}) +func TestLog_LevelString_Bad(t *testing.T) { + // Invalid level value returns "unknown" + if got := Level(99).String(); got != "unknown" { + t.Errorf("expected \"unknown\" for out-of-range level, got %q", got) + } +} - l.Info("test message", "key1", "value1", "key2", 42) +func TestLog_LevelString_Ugly(t *testing.T) { + // Negative level value also returns "unknown" + if got := Level(-1).String(); got != "unknown" { + t.Errorf("expected \"unknown\" for negative level, got %q", got) + } +} + +// --- New --- + +func TestLog_New_Good(t *testing.T) { + var buf bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf}) + if logger == nil { + t.Fatal("expected non-nil logger") + } + if logger.Level() != LevelInfo { + t.Errorf("expected LevelInfo, got %v", logger.Level()) + } +} + +func TestLog_New_Bad(t *testing.T) { + // No output specified — should default to stderr (not nil or panic) + logger := New(Options{Level: LevelInfo}) + if logger.output == nil { + t.Error("expected non-nil output when no Output specified") + } +} + +func TestLog_New_Ugly(t *testing.T) { + // Rotation factory set but no filename — should fall back to Output + var buf bytes.Buffer + original := RotationWriterFactory + defer func() { RotationWriterFactory = original }() + + called := false + RotationWriterFactory = func(opts RotationOptions) goio.WriteCloser { + called = true + return nopWriteCloser{&buf} + } + + // Rotation with empty Filename — factory must NOT be called + logger := New(Options{ + Level: LevelInfo, + Output: &buf, + Rotation: &RotationOptions{Filename: ""}, + }) + if called { + t.Error("expected rotation factory NOT called when Filename is empty") + } + if logger.output == nil { + t.Error("expected non-nil output") + } +} + +// --- New with RotationWriterFactory --- + +func TestLog_NewRotationFactory_Good(t *testing.T) { + var buf bytes.Buffer + original := RotationWriterFactory + defer func() { RotationWriterFactory = original }() + + RotationWriterFactory = func(opts RotationOptions) goio.WriteCloser { + return nopWriteCloser{&buf} + } + + logger := New(Options{ + Level: LevelInfo, + Rotation: &RotationOptions{Filename: "test.log"}, + }) + + logger.Info("rotated message") + if buf.Len() == 0 { + t.Error("expected output via rotation writer") + } +} + +func TestLog_NewRotationFactory_Bad(t *testing.T) { + // Rotation requested but RotationWriterFactory is nil — should fall back to Output + var buf bytes.Buffer + original := RotationWriterFactory + defer func() { RotationWriterFactory = original }() + RotationWriterFactory = nil + + logger := New(Options{ + Level: LevelInfo, + Output: &buf, + Rotation: &RotationOptions{Filename: "test.log"}, + }) + + logger.Info("fallback message") + if buf.Len() == 0 { + t.Error("expected fallback to Output when RotationWriterFactory is nil") + } +} + +func TestLog_NewRotationFactory_Ugly(t *testing.T) { + // Both Output and Rotation provided — Rotation wins when factory is set + var rotationBuf, outputBuf bytes.Buffer + original := RotationWriterFactory + defer func() { RotationWriterFactory = original }() + + RotationWriterFactory = func(opts RotationOptions) goio.WriteCloser { + return nopWriteCloser{&rotationBuf} + } + + logger := New(Options{ + Level: LevelInfo, + Output: &outputBuf, + Rotation: &RotationOptions{Filename: "test.log"}, + }) + + logger.Info("which writer?") + if rotationBuf.Len() == 0 { + t.Error("expected rotation writer to be used") + } + if outputBuf.Len() != 0 { + t.Error("expected Output to be ignored when Rotation is set") + } +} + +// --- SetLevel / Level --- + +func TestLog_SetLevel_Good(t *testing.T) { + logger := New(Options{Level: LevelInfo}) + if logger.Level() != LevelInfo { + t.Error("expected initial level to be Info") + } + logger.SetLevel(LevelDebug) + if logger.Level() != LevelDebug { + t.Error("expected level to be Debug after SetLevel") + } +} + +func TestLog_SetLevel_Bad(t *testing.T) { + // SetLevel to Quiet suppresses all output + var buf bytes.Buffer + logger := New(Options{Level: LevelDebug, Output: &buf}) + logger.SetLevel(LevelQuiet) + logger.Error("should be suppressed") + if buf.Len() != 0 { + t.Error("expected no output at LevelQuiet") + } +} + +func TestLog_SetLevel_Ugly(t *testing.T) { + // SetLevel with an out-of-range value — should not panic, level stored as-is + logger := New(Options{Level: LevelInfo}) + logger.SetLevel(Level(99)) + if logger.Level() != Level(99) { + t.Errorf("expected level 99, got %v", logger.Level()) + } +} + +// --- SetOutput --- + +func TestLog_SetOutput_Good(t *testing.T) { + var buf1, buf2 bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf1}) + + logger.Info("first") + if buf1.Len() == 0 { + t.Error("expected output in first buffer") + } + + logger.SetOutput(&buf2) + logger.Info("second") + if buf2.Len() == 0 { + t.Error("expected output in second buffer after SetOutput") + } +} + +func TestLog_SetOutput_Bad(t *testing.T) { + // Output switched mid-stream — first buffer must not receive later messages + var buf1, buf2 bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf1}) + logger.Info("first") + first1Len := buf1.Len() + + logger.SetOutput(&buf2) + logger.Info("second") + + if buf1.Len() != first1Len { + t.Error("first buffer must not receive messages after SetOutput") + } +} + +func TestLog_SetOutput_Ugly(t *testing.T) { + // SetOutput to goio.Discard — no panic, just silently discarded + logger := New(Options{Level: LevelInfo}) + logger.SetOutput(goio.Discard) + logger.Info("discarded message") // must not panic +} + +// --- SetRedactKeys --- + +func TestLog_SetRedactKeys_Good(t *testing.T) { + var buf bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf}) + + // No redaction initially + logger.Info("msg", "secret", "visible") + if !core.Contains(buf.String(), "secret=\"visible\"") { + t.Errorf("expected visible value, got %q", buf.String()) + } + + buf.Reset() + logger.SetRedactKeys("secret") + logger.Info("msg", "secret", "hidden") + if !core.Contains(buf.String(), "secret=\"[REDACTED]\"") { + t.Errorf("expected redacted value, got %q", buf.String()) + } +} + +func TestLog_SetRedactKeys_Bad(t *testing.T) { + // Calling SetRedactKeys with empty list clears all redaction + var buf bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf, RedactKeys: []string{"token"}}) + logger.SetRedactKeys() // clear all + logger.Info("msg", "token", "visible-now") + if !core.Contains(buf.String(), "token=\"visible-now\"") { + t.Errorf("expected token to be visible after clearing redact keys, got %q", buf.String()) + } +} + +func TestLog_SetRedactKeys_Ugly(t *testing.T) { + // Redact key that doesn't appear in log — no effect, no panic + var buf bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf}) + logger.SetRedactKeys("nonexistent_key") + logger.Info("msg", "other", "value") + output := buf.String() + if !core.Contains(output, "other=\"value\"") { + t.Errorf("expected other to appear normally, got %q", output) + } +} + +// --- Debug / Info / Warn / Error / Security --- + +func TestLog_Levels_Good(t *testing.T) { + cases := []struct { + name string + level Level + logFunc func(*Logger, string, ...any) + expect bool + }{ + {"debug at debug", LevelDebug, (*Logger).Debug, true}, + {"info at info", LevelInfo, (*Logger).Info, true}, + {"warn at warn", LevelWarn, (*Logger).Warn, true}, + {"error at error", LevelError, (*Logger).Error, true}, + {"security at error", LevelError, (*Logger).Security, true}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + logger := New(Options{Level: tc.level, Output: &buf}) + tc.logFunc(logger, "test message") + if buf.Len() == 0 { + t.Errorf("expected output for %s", tc.name) + } + }) + } +} + +func TestLog_Levels_Bad(t *testing.T) { + // Messages below the active level are suppressed + cases := []struct { + name string + level Level + logFunc func(*Logger, string, ...any) + }{ + {"debug at info", LevelInfo, (*Logger).Debug}, + {"debug at warn", LevelWarn, (*Logger).Debug}, + {"info at warn", LevelWarn, (*Logger).Info}, + {"debug at error", LevelError, (*Logger).Debug}, + {"info at error", LevelError, (*Logger).Info}, + {"warn at error", LevelError, (*Logger).Warn}, + {"debug at quiet", LevelQuiet, (*Logger).Debug}, + {"info at quiet", LevelQuiet, (*Logger).Info}, + {"warn at quiet", LevelQuiet, (*Logger).Warn}, + {"error at quiet", LevelQuiet, (*Logger).Error}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + logger := New(Options{Level: tc.level, Output: &buf}) + tc.logFunc(logger, "test message") + if buf.Len() != 0 { + t.Errorf("expected no output for %s, got %q", tc.name, buf.String()) + } + }) + } +} + +func TestLog_Levels_Ugly(t *testing.T) { + // Security always uses LevelError threshold — even at LevelWarn it should appear + var buf bytes.Buffer + logger := New(Options{Level: LevelWarn, Output: &buf}) + logger.Security("intrusion attempt", "ip", "10.0.0.1") + if buf.Len() == 0 { + t.Error("expected security log output at LevelWarn (security uses LevelError threshold)") + } + if !core.Contains(buf.String(), "[SEC]") { + t.Errorf("expected [SEC] prefix, got %q", buf.String()) + } +} + +// --- Key-value formatting --- + +func TestLog_KeyValues_Good(t *testing.T) { + var buf bytes.Buffer + logger := New(Options{Level: LevelDebug, Output: &buf}) + + logger.Info("test message", "key1", "value1", "key2", 42) output := buf.String() if !core.Contains(output, "test message") { @@ -84,33 +371,76 @@ func TestLogger_KeyValues(t *testing.T) { } } -func TestLogger_ErrorContext(t *testing.T) { +func TestLog_KeyValues_Bad(t *testing.T) { + // Odd number of keyvals — last key has no value, rendered as var buf bytes.Buffer - l := New(Options{Output: &buf, Level: LevelInfo}) - - err := E("test.Op", "failed", NewError("root cause")) - err = Wrap(err, "outer.Op", "outer failed") - - l.Error("something failed", "err", err) - - got := buf.String() - if !core.Contains(got, "op=\"outer.Op\"") { - t.Errorf("expected output to contain op=\"outer.Op\", got %q", got) - } - if !core.Contains(got, "stack=\"outer.Op -> test.Op\"") { - t.Errorf("expected output to contain stack=\"outer.Op -> test.Op\", got %q", got) + logger := New(Options{Level: LevelInfo, Output: &buf}) + logger.Info("msg", "lonely_key") + output := buf.String() + if !core.Contains(output, "lonely_key=") { + t.Errorf("expected lonely_key=, got %q", output) } } -func TestLogger_Redaction(t *testing.T) { +func TestLog_KeyValues_Ugly(t *testing.T) { + // No keyvals at all — message alone, no trailing space var buf bytes.Buffer - l := New(Options{ + logger := New(Options{Level: LevelInfo, Output: &buf}) + logger.Info("just a message") + output := buf.String() + if !core.Contains(output, "just a message") { + t.Errorf("expected message in output, got %q", output) + } +} + +// --- Log injection prevention --- + +func TestLog_InjectionPrevention_Good(t *testing.T) { + var buf bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf}) + + logger.Info("message", "key", "value\n[SEC] injected message") + + output := buf.String() + if !core.Contains(output, "key=\"value\\n[SEC] injected message\"") { + t.Errorf("expected escaped newline, got %q", output) + } +} + +func TestLog_InjectionPrevention_Bad(t *testing.T) { + // Embedded carriage return also escaped + var buf bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf}) + logger.Info("message", "key", "value\r\ninjected") + output := buf.String() + // The value must be quoted (escaped), so it remains one log line + lines := core.Split(core.Trim(output), "\n") + if len(lines) != 1 { + t.Errorf("expected 1 line after injection attempt, got %d: %q", len(lines), output) + } +} + +func TestLog_InjectionPrevention_Ugly(t *testing.T) { + // Tab and null bytes in value — must be quoted, no panic + var buf bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf}) + logger.Info("message", "key", "val\t\x00ue") + if buf.Len() == 0 { + t.Error("expected output even with unusual characters in value") + } +} + +// --- Redaction --- + +func TestLog_Redaction_Good(t *testing.T) { + var buf bytes.Buffer + logger := New(Options{ Level: LevelInfo, Output: &buf, RedactKeys: []string{"password", "token"}, }) - l.Info("login", "user", "admin", "password", "secret123", "token", "abc-123") + logger.Info("login", "user", "admin", "password", "secret123", "token", "abc-123") output := buf.String() if !core.Contains(output, "user=\"admin\"") { @@ -124,63 +454,92 @@ func TestLogger_Redaction(t *testing.T) { } } -func TestLogger_InjectionPrevention(t *testing.T) { +func TestLog_Redaction_Bad(t *testing.T) { + // Non-string value under a redacted key is also masked var buf bytes.Buffer - l := New(Options{Level: LevelInfo, Output: &buf}) - - l.Info("message", "key", "value\n[SEC] injected message") + logger := New(Options{ + Level: LevelInfo, + Output: &buf, + RedactKeys: []string{"pin"}, + }) + logger.Info("auth", "pin", 1234) + if !core.Contains(buf.String(), "pin=\"[REDACTED]\"") { + t.Errorf("expected numeric pin to be redacted, got %q", buf.String()) + } +} +func TestLog_Redaction_Ugly(t *testing.T) { + // Redact key that appears multiple times — all occurrences masked + var buf bytes.Buffer + logger := New(Options{ + Level: LevelInfo, + Output: &buf, + RedactKeys: []string{"x"}, + }) + logger.Info("msg", "x", "first", "y", "plain", "x", "second") output := buf.String() - if !core.Contains(output, "key=\"value\\n[SEC] injected message\"") { - t.Errorf("expected escaped newline, got %q", output) - } - // Ensure it's still a single line (excluding trailing newline) - lines := core.Split(core.Trim(output), "\n") - if len(lines) != 1 { - t.Errorf("expected 1 line, got %d", len(lines)) + count := substringCount(output, "[REDACTED]") + if count != 2 { + t.Errorf("expected 2 redactions, got %d in %q", count, output) } } -func TestLogger_SetLevel(t *testing.T) { - l := New(Options{Level: LevelInfo}) +// --- Error context auto-extraction --- - if l.Level() != LevelInfo { - t.Error("expected initial level to be Info") - } - - l.SetLevel(LevelDebug) - if l.Level() != LevelDebug { - t.Error("expected level to be Debug after SetLevel") - } -} - -func TestLevel_String(t *testing.T) { - tests := []struct { - level Level - expected string - }{ - {LevelQuiet, "quiet"}, - {LevelError, "error"}, - {LevelWarn, "warn"}, - {LevelInfo, "info"}, - {LevelDebug, "debug"}, - {Level(99), "unknown"}, - } - - for _, tt := range tests { - t.Run(tt.expected, func(t *testing.T) { - if got := tt.level.String(); got != tt.expected { - t.Errorf("expected %q, got %q", tt.expected, got) - } - }) - } -} - -func TestLogger_Security(t *testing.T) { +func TestLog_ErrorContext_Good(t *testing.T) { var buf bytes.Buffer - l := New(Options{Level: LevelError, Output: &buf}) + logger := New(Options{Output: &buf, Level: LevelInfo}) - l.Security("unauthorized access", "user", "admin") + err := E("test.Op", "failed", NewError("root cause")) + err = Wrap(err, "outer.Op", "outer failed") + + logger.Error("something failed", "err", err) + + got := buf.String() + if !core.Contains(got, "op=\"outer.Op\"") { + t.Errorf("expected output to contain op=\"outer.Op\", got %q", got) + } + if !core.Contains(got, "stack=\"outer.Op -> test.Op\"") { + t.Errorf("expected output to contain stack=\"outer.Op -> test.Op\", got %q", got) + } +} + +func TestLog_ErrorContext_Bad(t *testing.T) { + // Plain error (not *Err) — no op or stack injected + var buf bytes.Buffer + logger := New(Options{Output: &buf, Level: LevelInfo}) + logger.Error("plain error", "err", NewError("plain")) + output := buf.String() + if core.Contains(output, "op=") { + t.Errorf("expected no op= for plain error, got %q", output) + } + if core.Contains(output, "stack=") { + t.Errorf("expected no stack= for plain error, got %q", output) + } +} + +func TestLog_ErrorContext_Ugly(t *testing.T) { + // Caller provides op explicitly — must not duplicate + var buf bytes.Buffer + logger := New(Options{Level: LevelInfo, Output: &buf}) + err := E("inner.Op", "failed", NewError("cause")) + logger.Error("failed", "op", "explicit.Op", "err", err) + output := buf.String() + if substringCount(output, "op=") != 1 { + t.Errorf("expected exactly one op= in output, got %q", output) + } + if !core.Contains(output, "op=\"explicit.Op\"") { + t.Errorf("expected explicit op, got %q", output) + } +} + +// --- Security --- + +func TestLog_Security_Good(t *testing.T) { + var buf bytes.Buffer + logger := New(Options{Level: LevelError, Output: &buf}) + + logger.Security("unauthorized access", "user", "admin") output := buf.String() if !core.Contains(output, "[SEC]") { @@ -194,135 +553,66 @@ func TestLogger_Security(t *testing.T) { } } -func TestLogger_SetOutput_Good(t *testing.T) { - var buf1, buf2 bytes.Buffer - l := New(Options{Level: LevelInfo, Output: &buf1}) - - l.Info("first") - if buf1.Len() == 0 { - t.Error("expected output in first buffer") - } - - l.SetOutput(&buf2) - l.Info("second") - if buf2.Len() == 0 { - t.Error("expected output in second buffer after SetOutput") - } -} - -func TestLogger_SetRedactKeys_Good(t *testing.T) { +func TestLog_Security_Bad(t *testing.T) { + // Security is suppressed at LevelQuiet var buf bytes.Buffer - l := New(Options{Level: LevelInfo, Output: &buf}) - - // No redaction initially - l.Info("msg", "secret", "visible") - if !core.Contains(buf.String(), "secret=\"visible\"") { - t.Errorf("expected visible value, got %q", buf.String()) - } - - buf.Reset() - l.SetRedactKeys("secret") - l.Info("msg", "secret", "hidden") - if !core.Contains(buf.String(), "secret=\"[REDACTED]\"") { - t.Errorf("expected redacted value, got %q", buf.String()) + logger := New(Options{Level: LevelQuiet, Output: &buf}) + logger.Security("suppressed", "ip", "1.2.3.4") + if buf.Len() != 0 { + t.Error("expected security log suppressed at LevelQuiet") } } -func TestLogger_OddKeyvals_Good(t *testing.T) { +func TestLog_Security_Ugly(t *testing.T) { + // Security message with no key-value pairs — no panic, correct prefix var buf bytes.Buffer - l := New(Options{Level: LevelInfo, Output: &buf}) - - // Odd number of keyvals — last key should have no value - l.Info("msg", "lonely_key") - output := buf.String() - if !core.Contains(output, "lonely_key=") { - t.Errorf("expected lonely_key=, got %q", output) + logger := New(Options{Level: LevelInfo, Output: &buf}) + logger.Security("bare security event") + if !core.Contains(buf.String(), "[SEC]") { + t.Errorf("expected [SEC] prefix even with no kvs, got %q", buf.String()) } } -func TestLogger_ExistingOpNotDuplicated_Good(t *testing.T) { - var buf bytes.Buffer - l := New(Options{Level: LevelInfo, Output: &buf}) +// --- Username --- - err := E("inner.Op", "failed", NewError("cause")) - // Pass op explicitly — should not duplicate - l.Error("failed", "op", "explicit.Op", "err", err) - - output := buf.String() - if substringCount(output, "op=") != 1 { - t.Errorf("expected exactly one op= in output, got %q", output) - } - if !core.Contains(output, "op=\"explicit.Op\"") { - t.Errorf("expected explicit op, got %q", output) - } -} - -func TestLogger_ExistingStackNotDuplicated_Good(t *testing.T) { - var buf bytes.Buffer - l := New(Options{Level: LevelInfo, Output: &buf}) - - err := E("inner.Op", "failed", NewError("cause")) - // Pass stack explicitly — should not duplicate - l.Error("failed", "stack", "custom.Stack", "err", err) - - output := buf.String() - if substringCount(output, "stack=") != 1 { - t.Errorf("expected exactly one stack= in output, got %q", output) - } - if !core.Contains(output, "stack=\"custom.Stack\"") { - t.Errorf("expected custom stack, got %q", output) - } -} - -func TestNew_RotationFactory_Good(t *testing.T) { - var buf bytes.Buffer - // Set up a mock rotation writer factory - original := RotationWriterFactory - defer func() { RotationWriterFactory = original }() - - RotationWriterFactory = func(opts RotationOptions) goio.WriteCloser { - return nopWriteCloser{&buf} - } - - l := New(Options{ - Level: LevelInfo, - Rotation: &RotationOptions{Filename: "test.log"}, - }) - - l.Info("rotated message") - if buf.Len() == 0 { - t.Error("expected output via rotation writer") - } -} - -func TestNew_DefaultOutput_Good(t *testing.T) { - // No output or rotation — should default to stderr (not nil) - l := New(Options{Level: LevelInfo}) - if l.output == nil { - t.Error("expected non-nil output when no Output specified") - } -} - -func TestUsername_Good(t *testing.T) { +func TestLog_Username_Good(t *testing.T) { name := Username() if name == "" { t.Error("expected Username to return a non-empty string") } } -func TestDefault_Good(t *testing.T) { +func TestLog_Username_Bad(t *testing.T) { + // Username must not contain a newline (common mistake from raw /etc/passwd reads) + name := Username() + if core.Contains(name, "\n") { + t.Errorf("Username must not contain newline, got %q", name) + } +} + +func TestLog_Username_Ugly(t *testing.T) { + // Username is idempotent — two calls return the same value + first := Username() + second := Username() + if first != second { + t.Errorf("Username not idempotent: %q vs %q", first, second) + } +} + +// --- Default logger and package-level proxies --- + +func TestLog_Default_Good(t *testing.T) { if Default() == nil { t.Error("expected default logger to exist") } - // All package-level proxy functions var buf bytes.Buffer - l := New(Options{Level: LevelDebug, Output: &buf}) - SetDefault(l) + logger := New(Options{Level: LevelDebug, Output: &buf}) + SetDefault(logger) defer SetDefault(New(Options{Level: LevelInfo})) SetLevel(LevelDebug) - if l.Level() != LevelDebug { + if logger.Level() != LevelDebug { t.Error("expected package-level SetLevel to work") } @@ -341,3 +631,35 @@ func TestDefault_Good(t *testing.T) { } } } + +func TestLog_Default_Bad(t *testing.T) { + // SetDefault(nil) must not panic immediately — panics only on use + // Test that Default() returns the newly set logger + var buf bytes.Buffer + custom := New(Options{Level: LevelWarn, Output: &buf}) + SetDefault(custom) + defer SetDefault(New(Options{Level: LevelInfo})) + + if Default() != custom { + t.Error("expected Default() to return the custom logger after SetDefault") + } +} + +func TestLog_Default_Ugly(t *testing.T) { + // Stack de-duplication via package-level proxy + var buf bytes.Buffer + logger := New(Options{Level: LevelDebug, Output: &buf}) + SetDefault(logger) + defer SetDefault(New(Options{Level: LevelInfo})) + + err := E("inner.Op", "failed", NewError("cause")) + Error("failed", "stack", "custom.Stack", "err", err) + + output := buf.String() + if substringCount(output, "stack=") != 1 { + t.Errorf("expected exactly one stack= in output, got %q", output) + } + if !core.Contains(output, "stack=\"custom.Stack\"") { + t.Errorf("expected custom stack, got %q", output) + } +}