diff --git a/errors.go b/errors.go index 5064555..2494c0d 100644 --- a/errors.go +++ b/errors.go @@ -6,12 +6,23 @@ package log import ( + // AX-6 circular-dependency exception: dappco.re/go/core imports go-log to + // expose core.E, core.Is, and core.As, so go-log cannot import core without a + // dependency cycle. These stdlib imports are structural error primitives. "errors" "iter" "strings" "time" ) +type singleUnwrapper interface { + Unwrap() error +} + +type multiUnwrapper interface { + Unwrap() []error +} + // Err represents a structured error with operational context. // It implements the error interface and supports unwrapping. type Err struct { @@ -193,70 +204,87 @@ func inheritRecovery(dst *Err, err error) { if err == nil || dst == nil { return } - var source *Err - if As(err, &source) { + walkErrorTree(err, func(current error) bool { + source, ok := current.(*Err) + if !ok { + return true + } + if !source.hasRecovery() { + return true + } dst.Retryable = source.Retryable dst.RetryAfter = source.RetryAfter dst.NextAction = source.NextAction - } + return false + }) } // inheritedCode returns the first non-empty code found in an error chain. func inheritedCode(err error) string { - for err != nil { - if wrapped, ok := err.(*Err); ok && wrapped.Code != "" { - return wrapped.Code + var code string + walkErrorTree(err, func(current error) bool { + wrapped, ok := current.(*Err) + if !ok || wrapped.Code == "" { + return true } - err = errors.Unwrap(err) - } - return "" + code = wrapped.Code + return false + }) + return code } // RetryAfter returns the first retry-after hint from an error chain, if present. // // retryAfter, ok := log.RetryAfter(err) func RetryAfter(err error) (*time.Duration, bool) { - for err != nil { - if wrapped, ok := err.(*Err); ok && wrapped.RetryAfter != nil { - return wrapped.RetryAfter, true + var retryAfter *time.Duration + var ok bool + walkErrorTree(err, func(current error) bool { + wrapped, match := current.(*Err) + if !match || wrapped.RetryAfter == nil { + return true } - err = errors.Unwrap(err) - } - return nil, false + retryAfter = wrapped.RetryAfter + ok = true + return false + }) + return retryAfter, ok } // IsRetryable reports whether the error chain contains a retryable Err. // // if log.IsRetryable(err) { /* retry the operation */ } func IsRetryable(err error) bool { - var wrapped *Err - if As(err, &wrapped) { - return wrapped.Retryable - } - return false + var retryable bool + walkErrorTree(err, func(current error) bool { + wrapped, ok := current.(*Err) + if !ok || !wrapped.Retryable { + return true + } + retryable = true + return false + }) + return retryable } // RecoveryAction returns the first next action from an error chain. // // next := log.RecoveryAction(err) func RecoveryAction(err error) string { - for err != nil { - if wrapped, ok := err.(*Err); ok && wrapped.NextAction != "" { - return wrapped.NextAction + var nextAction string + walkErrorTree(err, func(current error) bool { + wrapped, ok := current.(*Err) + if !ok || wrapped.NextAction == "" { + return true } - err = errors.Unwrap(err) - } - return "" + nextAction = wrapped.NextAction + return false + }) + return nextAction } func retryableHint(err error) bool { - for err != nil { - if wrapped, ok := err.(*Err); ok && wrapped.Retryable { - return true - } - err = errors.Unwrap(err) - } - return false + return IsRetryable(err) } // --- Standard Library Wrappers --- @@ -301,11 +329,16 @@ 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 - } - return "" + var op string + walkErrorTree(err, func(current error) bool { + wrapped, ok := current.(*Err) + if !ok || wrapped.Op == "" { + return true + } + op = wrapped.Op + return false + }) + return op } // ErrCode extracts the error code from an error. @@ -313,11 +346,7 @@ 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 - } - return "" + return inheritedCode(err) } // Message extracts the message from an error. @@ -328,9 +357,17 @@ func Message(err error) string { if err == nil { return "" } - var e *Err - if As(err, &e) { - return e.Msg + var msg string + walkErrorTree(err, func(current error) bool { + wrapped, ok := current.(*Err) + if !ok || wrapped.Msg == "" { + return true + } + msg = wrapped.Msg + return false + }) + if msg != "" { + return msg } return err.Error() } @@ -343,12 +380,21 @@ func Root(err error) error { if err == nil { return nil } - for { - unwrapped := errors.Unwrap(err) + switch current := any(err).(type) { + case multiUnwrapper: + children := current.Unwrap() + if len(children) == 0 { + return err + } + return Root(children[0]) + case singleUnwrapper: + unwrapped := current.Unwrap() if unwrapped == nil { return err } - err = unwrapped + return Root(unwrapped) + default: + return err } } @@ -358,16 +404,12 @@ func Root(err error) error { // for op := range log.AllOps(err) { /* "api.Call" → "db.Query" → ... */ } func AllOps(err error) iter.Seq[string] { return func(yield func(string) bool) { - for err != nil { - if e, ok := err.(*Err); ok { - if e.Op != "" { - if !yield(e.Op) { - return - } - } + walkErrorTree(err, func(current error) bool { + if e, ok := current.(*Err); ok && e.Op != "" { + return yield(e.Op) } - err = errors.Unwrap(err) - } + return true + }) } } @@ -423,6 +465,27 @@ func LogError(err error, op, msg string) error { return wrapped } +func walkErrorTree(err error, visit func(error) bool) { + if err == nil { + return + } + if !visit(err) { + return + } + switch current := any(err).(type) { + case multiUnwrapper: + for _, child := range current.Unwrap() { + walkErrorTree(child, visit) + } + case singleUnwrapper: + walkErrorTree(current.Unwrap(), visit) + } +} + +func (e *Err) hasRecovery() bool { + return e != nil && (e.Retryable || e.RetryAfter != nil || e.NextAction != "") +} + // LogWarn logs at Warn level and returns a wrapped error. // Use for recoverable errors that should be logged but not treated as critical. // diff --git a/errors_test.go b/errors_test.go index 9dde46e..787120f 100644 --- a/errors_test.go +++ b/errors_test.go @@ -2,13 +2,15 @@ package log import ( "bytes" + // Note: intrinsic - errors.New/Is/As/Unwrap exercise stdlib error chain behavior; core.E is downstream. "errors" + // Note: intrinsic - fmt.Errorf builds wrapped test errors; core is downstream of go-log so cannot self-depend. "fmt" + "slices" + // Note: intrinsic - strings.* assertions inspect rendered errors/logs; core.* helpers are downstream of go-log. "strings" "testing" "time" - - "github.com/stretchr/testify/assert" ) // --- Err Type Tests --- @@ -16,55 +18,81 @@ import ( func TestErr_Error_Good(t *testing.T) { // With 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()) + if want, got := "db.Query: failed to query: connection refused", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } // With code err = &Err{Op: "api.Call", Msg: "request failed", Code: "TIMEOUT"} - assert.Equal(t, "api.Call: request failed [TIMEOUT]", err.Error()) + if want, got := "api.Call: request failed [TIMEOUT]", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } // 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()) + if want, got := "user.Save: save failed [DUPLICATE]: duplicate key", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } // Just op and msg err = &Err{Op: "cache.Get", Msg: "miss"} - assert.Equal(t, "cache.Get: miss", err.Error()) + if want, got := "cache.Get: miss", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestErr_Error_EmptyOp_Good(t *testing.T) { // No Op - should not have leading colon err := &Err{Msg: "just a message"} - assert.Equal(t, "just a message", err.Error()) + if want, got := "just a message", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } // No Op with code err = &Err{Msg: "error with code", Code: "ERR_CODE"} - assert.Equal(t, "error with code [ERR_CODE]", err.Error()) + if want, got := "error with code [ERR_CODE]", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } // No Op with underlying error err = &Err{Msg: "wrapped", Err: errors.New("underlying")} - assert.Equal(t, "wrapped: underlying", err.Error()) + if want, got := "wrapped: underlying", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestErr_Error_EmptyMsg_Good(t *testing.T) { err := &Err{Op: "api.Call", Code: "TIMEOUT"} - assert.Equal(t, "api.Call: [TIMEOUT]", err.Error()) + if want, got := "api.Call: [TIMEOUT]", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } err = &Err{Op: "api.Call", Err: errors.New("underlying")} - assert.Equal(t, "api.Call: underlying", err.Error()) + if want, got := "api.Call: underlying", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } err = &Err{Op: "api.Call", Code: "TIMEOUT", Err: errors.New("underlying")} - assert.Equal(t, "api.Call: [TIMEOUT]: underlying", err.Error()) + if want, got := "api.Call: [TIMEOUT]: underlying", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } err = &Err{Op: "api.Call"} - assert.Equal(t, "api.Call", err.Error()) + if want, got := "api.Call", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestErr_Unwrap_Good(t *testing.T) { underlying := errors.New("underlying error") err := &Err{Op: "test", Msg: "wrapped", Err: underlying} - assert.Equal(t, underlying, errors.Unwrap(err)) - assert.True(t, errors.Is(err, underlying)) + if want, got := underlying, errors.Unwrap(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } + if !errors.Is(err, underlying) { + t.Fatal("expected true") + } } // --- Error Creation Function Tests --- @@ -73,19 +101,33 @@ func TestE_Good(t *testing.T) { underlying := errors.New("base error") err := E("op.Name", "something failed", underlying) - assert.NotNil(t, err) + if err == nil { + t.Fatal("expected non-nil") + } 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) + if !errors.As(err, &logErr) { + t.Fatal("expected true") + } + if want, got := "op.Name", logErr.Op; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := "something failed", logErr.Msg; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := underlying, logErr.Err; want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestE_Good_NilError(t *testing.T) { // E creates an error even with nil underlying - useful for errors without causes err := E("op.Name", "message", nil) - assert.NotNil(t, err) - assert.Equal(t, "op.Name: message", err.Error()) + if err == nil { + t.Fatal("expected non-nil") + } + if want, got := "op.Name: message", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestEWithRecovery_Good(t *testing.T) { @@ -93,23 +135,42 @@ func TestEWithRecovery_Good(t *testing.T) { err := EWithRecovery("op.Name", "message", nil, true, &retryAfter, "retry once") var logErr *Err - assert.NotNil(t, err) - assert.True(t, As(err, &logErr)) - assert.True(t, logErr.Retryable) - if assert.NotNil(t, logErr.RetryAfter) { - assert.Equal(t, retryAfter, *logErr.RetryAfter) + if err == nil { + t.Fatal("expected non-nil") + } + if !As(err, &logErr) { + t.Fatal("expected true") + } + if !logErr.Retryable { + t.Fatal("expected true") + } + if logErr.RetryAfter == nil { + t.Fatal("expected non-nil") + } + if want, got := retryAfter, *logErr.RetryAfter; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := "retry once", logErr.NextAction; want != got { + t.Fatalf("want %v, got %v", want, got) } - assert.Equal(t, "retry once", logErr.NextAction) } func TestWrap_Good(t *testing.T) { underlying := errors.New("base") err := Wrap(underlying, "handler.Process", "processing failed") - assert.NotNil(t, err) - assert.Contains(t, err.Error(), "handler.Process") - assert.Contains(t, err.Error(), "processing failed") - assert.True(t, errors.Is(err, underlying)) + if err == nil { + t.Fatal("expected non-nil") + } + if !strings.Contains(err.Error(), "handler.Process") { + t.Fatalf("expected %q to contain %q", err.Error(), "handler.Process") + } + if !strings.Contains(err.Error(), "processing failed") { + t.Fatalf("expected %q to contain %q", err.Error(), "processing failed") + } + if !errors.Is(err, underlying) { + t.Fatal("expected true") + } } func TestWrap_PreservesCode_Good(t *testing.T) { @@ -119,9 +180,15 @@ func TestWrap_PreservesCode_Good(t *testing.T) { // Wrap it - should preserve the code outer := Wrap(inner, "outer.Op", "outer context") - assert.NotNil(t, outer) - assert.Equal(t, "VALIDATION_ERROR", ErrCode(outer)) - assert.Contains(t, outer.Error(), "[VALIDATION_ERROR]") + if outer == nil { + t.Fatal("expected non-nil") + } + if want, got := "VALIDATION_ERROR", ErrCode(outer); want != got { + t.Fatalf("want %v, got %v", want, got) + } + if !strings.Contains(outer.Error(), "[VALIDATION_ERROR]") { + t.Fatalf("expected %q to contain %q", outer.Error(), "[VALIDATION_ERROR]") + } } func TestWrap_PreservesCode_FromNestedErrWithEmptyOuterCode_Good(t *testing.T) { @@ -130,9 +197,15 @@ func TestWrap_PreservesCode_FromNestedErrWithEmptyOuterCode_Good(t *testing.T) { outer := Wrap(mid, "outer.Op", "outer context") - assert.NotNil(t, outer) - assert.Equal(t, "VALIDATION_ERROR", ErrCode(outer)) - assert.Contains(t, outer.Error(), "[VALIDATION_ERROR]") + if outer == nil { + t.Fatal("expected non-nil") + } + if want, got := "VALIDATION_ERROR", ErrCode(outer); want != got { + t.Fatalf("want %v, got %v", want, got) + } + if !strings.Contains(outer.Error(), "[VALIDATION_ERROR]") { + t.Fatalf("expected %q to contain %q", outer.Error(), "[VALIDATION_ERROR]") + } } func TestWrap_PreservesRecovery_Good(t *testing.T) { @@ -141,39 +214,66 @@ func TestWrap_PreservesRecovery_Good(t *testing.T) { outer := Wrap(inner, "outer.Op", "outer context") - assert.NotNil(t, outer) + if outer == nil { + t.Fatal("expected non-nil") + } var logErr *Err - assert.True(t, As(outer, &logErr)) - assert.True(t, logErr.Retryable) - if assert.NotNil(t, logErr.RetryAfter) { - assert.Equal(t, retryAfter, *logErr.RetryAfter) + if !As(outer, &logErr) { + t.Fatal("expected true") + } + if !logErr.Retryable { + t.Fatal("expected true") + } + if logErr.RetryAfter == nil { + t.Fatal("expected non-nil") + } + if want, got := retryAfter, *logErr.RetryAfter; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := "inspect input", logErr.NextAction; want != got { + t.Fatalf("want %v, got %v", want, got) } - assert.Equal(t, "inspect input", logErr.NextAction) } func TestWrap_PreservesCode_FromNestedChain_Good(t *testing.T) { root := WrapCode(errors.New("base"), "CHAIN_ERROR", "inner", "inner failed") wrapped := Wrap(fmt.Errorf("mid layer: %w", root), "outer", "outer context") - assert.Equal(t, "CHAIN_ERROR", ErrCode(wrapped)) - assert.Contains(t, wrapped.Error(), "[CHAIN_ERROR]") + if want, got := "CHAIN_ERROR", ErrCode(wrapped); want != got { + t.Fatalf("want %v, got %v", want, got) + } + if !strings.Contains(wrapped.Error(), "[CHAIN_ERROR]") { + t.Fatalf("expected %q to contain %q", wrapped.Error(), "[CHAIN_ERROR]") + } } func TestWrap_NilError_Good(t *testing.T) { err := Wrap(nil, "op", "msg") - assert.Nil(t, err) + if err != nil { + t.Fatalf("expected nil, got %v", err) + } } func TestWrapCode_Good(t *testing.T) { underlying := errors.New("validation failed") err := WrapCode(underlying, "INVALID_INPUT", "api.Validate", "bad request") - assert.NotNil(t, err) + if err == nil { + t.Fatal("expected non-nil") + } var logErr *Err - assert.True(t, errors.As(err, &logErr)) - assert.Equal(t, "INVALID_INPUT", logErr.Code) - assert.Equal(t, "api.Validate", logErr.Op) - assert.Contains(t, err.Error(), "[INVALID_INPUT]") + if !errors.As(err, &logErr) { + t.Fatal("expected true") + } + if want, got := "INVALID_INPUT", logErr.Code; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := "api.Validate", logErr.Op; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if !strings.Contains(err.Error(), "[INVALID_INPUT]") { + t.Fatalf("expected %q to contain %q", err.Error(), "[INVALID_INPUT]") + } } func TestWrapCode_Good_EmptyCodeDoesNotInherit(t *testing.T) { @@ -182,8 +282,12 @@ func TestWrapCode_Good_EmptyCodeDoesNotInherit(t *testing.T) { outer := WrapCode(inner, "", "outer.Op", "outer failed") var logErr *Err - assert.True(t, As(outer, &logErr)) - assert.Equal(t, "", logErr.Code) + if !As(outer, &logErr) { + t.Fatal("expected true") + } + if want, got := "", logErr.Code; want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestWrapCodeWithRecovery_Good(t *testing.T) { @@ -191,13 +295,27 @@ func TestWrapCodeWithRecovery_Good(t *testing.T) { err := WrapCodeWithRecovery(errors.New("validation failed"), "INVALID_INPUT", "api.Validate", "bad request", true, &retryAfter, "retry with backoff") var logErr *Err - assert.NotNil(t, err) - assert.True(t, As(err, &logErr)) - assert.True(t, logErr.Retryable) - assert.NotNil(t, logErr.RetryAfter) - assert.Equal(t, retryAfter, *logErr.RetryAfter) - assert.Equal(t, "retry with backoff", logErr.NextAction) - assert.Equal(t, "INVALID_INPUT", logErr.Code) + if err == nil { + t.Fatal("expected non-nil") + } + if !As(err, &logErr) { + t.Fatal("expected true") + } + if !logErr.Retryable { + t.Fatal("expected true") + } + if logErr.RetryAfter == nil { + t.Fatal("expected non-nil") + } + if want, got := retryAfter, *logErr.RetryAfter; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := "retry with backoff", logErr.NextAction; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := "INVALID_INPUT", logErr.Code; want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestWrapCodeWithRecovery_Good_EmptyCodeDoesNotInherit(t *testing.T) { @@ -207,29 +325,47 @@ func TestWrapCodeWithRecovery_Good_EmptyCodeDoesNotInherit(t *testing.T) { outer := WrapCodeWithRecovery(inner, "", "outer.Op", "outer failed", true, &retryAfter, "retry later") var logErr *Err - assert.True(t, As(outer, &logErr)) - assert.Equal(t, "", logErr.Code) + if !As(outer, &logErr) { + t.Fatal("expected true") + } + if want, got := "", logErr.Code; want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestWrapCode_Good_NilError(t *testing.T) { // WrapCode with 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]") + if err == nil { + t.Fatal("expected non-nil") + } + if !strings.Contains(err.Error(), "[CODE]") { + t.Fatalf("expected %q to contain %q", err.Error(), "[CODE]") + } // Only returns nil when both error and code are empty err = WrapCode(nil, "", "op", "msg") - assert.Nil(t, err) + if err != nil { + t.Fatalf("expected nil, got %v", err) + } } func TestNewCode_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) + if !errors.As(err, &logErr) { + t.Fatal("expected true") + } + if want, got := "NOT_FOUND", logErr.Code; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := "resource not found", logErr.Msg; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if logErr.Err != nil { + t.Fatalf("expected nil, got %v", logErr.Err) + } } func TestNewCodeWithRecovery_Good(t *testing.T) { @@ -237,12 +373,24 @@ func TestNewCodeWithRecovery_Good(t *testing.T) { err := NewCodeWithRecovery("NOT_FOUND", "resource not found", false, &retryAfter, "contact support") var logErr *Err - assert.NotNil(t, err) - assert.True(t, As(err, &logErr)) - assert.False(t, logErr.Retryable) - assert.NotNil(t, logErr.RetryAfter) - assert.Equal(t, retryAfter, *logErr.RetryAfter) - assert.Equal(t, "contact support", logErr.NextAction) + if err == nil { + t.Fatal("expected non-nil") + } + if !As(err, &logErr) { + t.Fatal("expected true") + } + if logErr.Retryable { + t.Fatal("expected false") + } + if logErr.RetryAfter == nil { + t.Fatal("expected non-nil") + } + if want, got := retryAfter, *logErr.RetryAfter; want != got { + t.Fatalf("want %v, got %v", want, got) + } + if want, got := "contact support", logErr.NextAction; want != got { + t.Fatalf("want %v, got %v", want, got) + } } // --- Standard Library Wrapper Tests --- @@ -251,22 +399,34 @@ func TestIs_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"))) + if !Is(wrapped, sentinel) { + t.Fatal("expected true") + } + if Is(wrapped, errors.New("other")) { + t.Fatal("expected false") + } } func TestAs_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) + if !As(err, &logErr) { + t.Fatal("expected true") + } + if want, got := "test.Op", logErr.Op; want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestNewError_Good(t *testing.T) { err := NewError("simple error") - assert.NotNil(t, err) - assert.Equal(t, "simple error", err.Error()) + if err == nil { + t.Fatal("expected non-nil") + } + if want, got := "simple error", err.Error(); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestJoin_Good(t *testing.T) { @@ -274,39 +434,55 @@ func TestJoin_Good(t *testing.T) { err2 := errors.New("error 2") joined := Join(err1, err2) - assert.True(t, errors.Is(joined, err1)) - assert.True(t, errors.Is(joined, err2)) + if !errors.Is(joined, err1) { + t.Fatal("expected true") + } + if !errors.Is(joined, err2) { + t.Fatal("expected true") + } } // --- Helper Function Tests --- func TestOp_Good(t *testing.T) { err := E("mypackage.MyFunc", "failed", errors.New("cause")) - assert.Equal(t, "mypackage.MyFunc", Op(err)) + if want, got := "mypackage.MyFunc", Op(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestOp_Good_NotLogError(t *testing.T) { err := errors.New("plain error") - assert.Equal(t, "", Op(err)) + if want, got := "", Op(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestErrCode_Good(t *testing.T) { err := WrapCode(errors.New("base"), "ERR_CODE", "op", "msg") - assert.Equal(t, "ERR_CODE", ErrCode(err)) + if want, got := "ERR_CODE", ErrCode(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestErrCode_Good_NoCode(t *testing.T) { err := E("op", "msg", errors.New("base")) - assert.Equal(t, "", ErrCode(err)) + if want, got := "", ErrCode(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestErrCode_Good_PlainError(t *testing.T) { err := errors.New("plain error") - assert.Equal(t, "", ErrCode(err)) + if want, got := "", ErrCode(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestErrCode_Good_Nil(t *testing.T) { - assert.Equal(t, "", ErrCode(nil)) + if want, got := "", ErrCode(nil); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestRetryAfter_Good(t *testing.T) { @@ -314,8 +490,12 @@ func TestRetryAfter_Good(t *testing.T) { err := &Err{Msg: "typed", RetryAfter: &retryAfter} got, ok := RetryAfter(err) - assert.True(t, ok) - assert.Equal(t, retryAfter, *got) + if !ok { + t.Fatal("expected true") + } + if want, got := retryAfter, *got; want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestRetryAfter_Good_NestedChain(t *testing.T) { @@ -324,39 +504,55 @@ func TestRetryAfter_Good_NestedChain(t *testing.T) { outer := &Err{Msg: "outer", Err: inner} got, ok := RetryAfter(outer) - assert.True(t, ok) - assert.Equal(t, retryAfter, *got) + if !ok { + t.Fatal("expected true") + } + if want, got := retryAfter, *got; want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestIsRetryable_Good(t *testing.T) { err := &Err{Msg: "typed", Retryable: true} - assert.True(t, IsRetryable(err)) + if !IsRetryable(err) { + t.Fatal("expected true") + } } func TestRecoveryAction_Good(t *testing.T) { err := &Err{Msg: "typed", NextAction: "inspect"} - assert.Equal(t, "inspect", RecoveryAction(err)) + if want, got := "inspect", RecoveryAction(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestRecoveryAction_Good_NestedChain(t *testing.T) { inner := &Err{Msg: "typed", NextAction: "inspect"} outer := &Err{Msg: "outer", Err: inner} - assert.Equal(t, "inspect", RecoveryAction(outer)) + if want, got := "inspect", RecoveryAction(outer); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestMessage_Good(t *testing.T) { err := E("op", "the message", errors.New("base")) - assert.Equal(t, "the message", Message(err)) + if want, got := "the message", Message(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestMessage_Good_PlainError(t *testing.T) { err := errors.New("plain message") - assert.Equal(t, "plain message", Message(err)) + if want, got := "plain message", Message(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestMessage_Good_Nil(t *testing.T) { - assert.Equal(t, "", Message(nil)) + if want, got := "", Message(nil); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestRoot_Good(t *testing.T) { @@ -364,16 +560,22 @@ func TestRoot_Good(t *testing.T) { level1 := Wrap(root, "level1", "wrapped once") level2 := Wrap(level1, "level2", "wrapped twice") - assert.Equal(t, root, Root(level2)) + if want, got := root, Root(level2); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestRoot_Good_SingleError(t *testing.T) { err := errors.New("single") - assert.Equal(t, err, Root(err)) + if want, got := err, Root(err); want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestRoot_Good_Nil(t *testing.T) { - assert.Nil(t, Root(nil)) + if got := Root(nil); got != nil { + t.Fatalf("expected nil, got %v", got) + } } // --- Log-and-Return Helper Tests --- @@ -389,16 +591,30 @@ func TestLogError_Good(t *testing.T) { 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)) + if err == nil { + t.Fatal("expected non-nil") + } + if !strings.Contains(err.Error(), "db.Connect") { + t.Fatalf("expected %q to contain %q", err.Error(), "db.Connect") + } + if !strings.Contains(err.Error(), "database unavailable") { + t.Fatalf("expected %q to contain %q", err.Error(), "database unavailable") + } + if !errors.Is(err, underlying) { + t.Fatal("expected true") + } // Check log output output := buf.String() - assert.Contains(t, output, "[ERR]") - assert.Contains(t, output, "database unavailable") - assert.Contains(t, output, "op=\"db.Connect\"") + if !strings.Contains(output, "[ERR]") { + t.Fatalf("expected %q to contain %q", output, "[ERR]") + } + if !strings.Contains(output, "database unavailable") { + t.Fatalf("expected %q to contain %q", output, "database unavailable") + } + if !strings.Contains(output, "op=\"db.Connect\"") { + t.Fatalf("expected %q to contain %q", output, "op=\"db.Connect\"") + } } func TestLogError_Good_LogsOriginalErrorContext(t *testing.T) { @@ -410,12 +626,20 @@ func TestLogError_Good_LogsOriginalErrorContext(t *testing.T) { underlying := E("db.Query", "query failed", errors.New("timeout")) err := LogError(underlying, "db.Connect", "database unavailable") - assert.NotNil(t, err) + if err == nil { + t.Fatal("expected non-nil") + } output := buf.String() - assert.Contains(t, output, "op=\"db.Connect\"") - assert.Contains(t, output, "stack=\"db.Query\"") - assert.NotContains(t, output, "stack=\"db.Connect -> db.Query\"") + if !strings.Contains(output, "op=\"db.Connect\"") { + t.Fatalf("expected %q to contain %q", output, "op=\"db.Connect\"") + } + if !strings.Contains(output, "stack=\"db.Query\"") { + t.Fatalf("expected %q to contain %q", output, "stack=\"db.Query\"") + } + if strings.Contains(output, "stack=\"db.Connect -> db.Query\"") { + t.Fatalf("expected %q not to contain %q", output, "stack=\"db.Connect -> db.Query\"") + } } func TestLogError_Good_NilError(t *testing.T) { @@ -425,8 +649,12 @@ func TestLogError_Good_NilError(t *testing.T) { defer SetDefault(New(Options{Level: LevelInfo})) err := LogError(nil, "op", "msg") - assert.Nil(t, err) - assert.Empty(t, buf.String()) // No log output for nil error + if err != nil { + t.Fatalf("expected nil, got %v", err) + } + if got := buf.String(); got != "" { + t.Fatalf("expected empty, got %v", got) + } } func TestLogWarn_Good(t *testing.T) { @@ -438,12 +666,20 @@ func TestLogWarn_Good(t *testing.T) { underlying := errors.New("cache miss") err := LogWarn(underlying, "cache.Get", "falling back to db") - assert.NotNil(t, err) - assert.True(t, errors.Is(err, underlying)) + if err == nil { + t.Fatal("expected non-nil") + } + if !errors.Is(err, underlying) { + t.Fatal("expected true") + } output := buf.String() - assert.Contains(t, output, "[WRN]") - assert.Contains(t, output, "falling back to db") + if !strings.Contains(output, "[WRN]") { + t.Fatalf("expected %q to contain %q", output, "[WRN]") + } + if !strings.Contains(output, "falling back to db") { + t.Fatalf("expected %q to contain %q", output, "falling back to db") + } } func TestLogWarn_Good_NilError(t *testing.T) { @@ -453,15 +689,24 @@ func TestLogWarn_Good_NilError(t *testing.T) { defer SetDefault(New(Options{Level: LevelInfo})) err := LogWarn(nil, "op", "msg") - assert.Nil(t, err) - assert.Empty(t, buf.String()) + if err != nil { + t.Fatalf("expected nil, got %v", err) + } + if got := buf.String(); got != "" { + t.Fatalf("expected empty, got %v", got) + } } func TestMust_Good_NoError(t *testing.T) { // Should not panic when error is nil - assert.NotPanics(t, func() { + func() { + defer func() { + if got := recover(); got != nil { + t.Fatalf("unexpected panic: %v", got) + } + }() Must(nil, "test", "should not panic") - }) + }() } func TestMust_Ugly_Panics(t *testing.T) { @@ -470,13 +715,24 @@ func TestMust_Ugly_Panics(t *testing.T) { SetDefault(logger) defer SetDefault(New(Options{Level: LevelInfo})) - assert.Panics(t, func() { + didPanic := false + func() { + defer func() { + if recover() != nil { + didPanic = true + } + }() Must(errors.New("fatal error"), "startup", "initialization failed") - }) + }() + if !didPanic { + t.Fatal("expected panic") + } // Verify error was logged before panic output := buf.String() - assert.True(t, strings.Contains(output, "[ERR]") || len(output) > 0) + if !(strings.Contains(output, "[ERR]") || len(output) > 0) { + t.Fatal("expected true") + } } func TestStackTrace_Good(t *testing.T) { @@ -486,28 +742,44 @@ func TestStackTrace_Good(t *testing.T) { err = Wrap(err, "op3", "msg3") stack := StackTrace(err) - assert.Equal(t, []string{"op3", "op2", "op1"}, stack) + if want, got := []string{"op3", "op2", "op1"}, stack; !slices.Equal(want, got) { + t.Fatalf("want %v, got %v", want, got) + } // Format formatted := FormatStackTrace(err) - assert.Equal(t, "op3 -> op2 -> op1", formatted) + if want, got := "op3 -> op2 -> op1", formatted; want != got { + t.Fatalf("want %v, got %v", want, got) + } } func TestStackTrace_Bad_PlainError(t *testing.T) { err := errors.New("plain error") - assert.Empty(t, StackTrace(err)) - assert.Empty(t, FormatStackTrace(err)) + if got := StackTrace(err); len(got) != 0 { + t.Fatalf("expected empty, got %v", got) + } + if got := FormatStackTrace(err); got != "" { + t.Fatalf("expected empty, got %v", got) + } } func TestStackTrace_Bad_Nil(t *testing.T) { - assert.Empty(t, StackTrace(nil)) - assert.Empty(t, FormatStackTrace(nil)) + if got := StackTrace(nil); len(got) != 0 { + t.Fatalf("expected empty, got %v", got) + } + if got := FormatStackTrace(nil); got != "" { + t.Fatalf("expected empty, got %v", got) + } } func TestStackTrace_Bad_NoOp(t *testing.T) { err := &Err{Msg: "no op"} - assert.Empty(t, StackTrace(err)) - assert.Empty(t, FormatStackTrace(err)) + if got := StackTrace(err); len(got) != 0 { + t.Fatalf("expected empty, got %v", got) + } + if got := FormatStackTrace(err); got != "" { + t.Fatalf("expected empty, got %v", got) + } } func TestStackTrace_Mixed_Good(t *testing.T) { @@ -516,5 +788,7 @@ func TestStackTrace_Mixed_Good(t *testing.T) { err = Wrap(err, "outer", "msg") stack := StackTrace(err) - assert.Equal(t, []string{"outer", "inner"}, stack) + if want, got := []string{"outer", "inner"}, stack; !slices.Equal(want, got) { + t.Fatalf("want %v, got %v", want, got) + } } diff --git a/go.mod b/go.mod index 401cf79..1dbb17f 100644 --- a/go.mod +++ b/go.mod @@ -1,14 +1,3 @@ -module dappco.re/go/core/log +module dappco.re/go/log go 1.26.0 - -require github.com/stretchr/testify v1.11.1 - -require ( - github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc // indirect - github.com/kr/pretty v0.3.1 // indirect - github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 // indirect - github.com/rogpeppe/go-internal v1.14.1 // indirect - gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c // indirect - gopkg.in/yaml.v3 v3.0.1 // indirect -) diff --git a/go.sum b/go.sum index 5a10c39..e69de29 100644 --- a/go.sum +++ b/go.sum @@ -1,23 +0,0 @@ -github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= -github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc h1:U9qPSI2PIWSS1VwoXQT9A3Wy9MM3WgvqSxFWenqJduM= -github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= -github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI= -github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= -github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= -github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= -github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= -github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= -github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= -github.com/pkg/diff v0.0.0-20210226163009-20ebb0f2a09e/go.mod h1:pJLUxLENpZxwdsKMEsNbx1VGcRFpLqf3715MtcvvzbA= -github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 h1:Jamvg5psRIccs7FGNTlIRMkT8wgtp5eCXdBlqhYGL6U= -github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= -github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs= -github.com/rogpeppe/go-internal v1.14.1 h1:UQB4HGPB6osV0SQTLymcB4TgvyWu6ZyliaW0tI/otEQ= -github.com/rogpeppe/go-internal v1.14.1/go.mod h1:MaRKkUm5W0goXpeCfT7UZI6fk/L7L7so1lCWt35ZSgc= -github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= -github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= -gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= -gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= -gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= -gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= -gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/log.go b/log.go index 78880dc..11c10b9 100644 --- a/log.go +++ b/log.go @@ -6,12 +6,15 @@ package log import ( - "fmt" + // AX-6 circular-dependency exception: dappco.re/go/core imports go-log to + // expose core logging and error primitives, so go-log cannot import core + // wrappers such as core.Mutex, core.RWMutex, core.Sprintf, or core.Process. + // These stdlib imports are limited to structural logging behaviour. goio "io" + "log/slog" "os" - "os/user" "slices" - "strings" + "strconv" "sync" "time" ) @@ -66,9 +69,10 @@ func (l Level) String() string { // Logger provides structured logging. type Logger struct { - mu sync.RWMutex - level Level - output goio.Writer + mu sync.RWMutex + writeMu sync.Mutex + level Level + output goio.Writer // RedactKeys is a list of keys whose values should be masked in logs. redactKeys []string @@ -297,7 +301,7 @@ func (l *Logger) log(level Level, prefix, msg string, keyvals ...any) { if i > 0 { kvStr += " " } - key := normaliseLogText(fmt.Sprintf("%v", keyvals[i])) + key := normaliseLogText(logValueString(keyvals[i])) var val any if i+1 < len(keyvals) { val = keyvals[i+1] @@ -310,14 +314,16 @@ func (l *Logger) log(level Level, prefix, msg string, keyvals ...any) { // Secure formatting to prevent log injection if s, ok := val.(string); ok { - kvStr += fmt.Sprintf("%s=%q", key, s) + kvStr += key + "=" + strconv.Quote(s) } else { - kvStr += fmt.Sprintf("%s=%v", key, normaliseLogText(fmt.Sprintf("%v", val))) + kvStr += key + "=" + normaliseLogText(logValueString(val)) } } } - _, _ = fmt.Fprintf(output, "%s %s %s%s\n", timestamp, prefix, normaliseLogText(msg), kvStr) + l.writeMu.Lock() + defer l.writeMu.Unlock() + _, _ = goio.WriteString(output, timestamp+" "+prefix+" "+normaliseLogText(msg)+kvStr+"\n") } // Debug logs a debug message with optional key-value pairs. @@ -382,15 +388,12 @@ 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. +// Username returns the current system username from the process environment. +// It avoids account database lookups because username discovery is not part of +// structured logging. // // user := log.Username() func Username() string { - if u, err := user.Current(); err == nil { - return u.Username - } - // Fallback for environments where user lookup might fail if u := os.Getenv("USER"); u != "" { return u } @@ -400,14 +403,33 @@ func Username() string { return "unknown" } -var logTextCleaner = strings.NewReplacer( - "\r", "\\r", - "\n", "\\n", - "\t", "\\t", -) - func normaliseLogText(text string) string { - return logTextCleaner.Replace(text) + var out []byte + for i := 0; i < len(text); i++ { + var replacement string + switch text[i] { + case '\r': + replacement = "\\r" + case '\n': + replacement = "\\n" + case '\t': + replacement = "\\t" + default: + if out != nil { + out = append(out, text[i]) + } + continue + } + if out == nil { + out = make([]byte, 0, len(text)+len(replacement)) + out = append(out, text[:i]...) + } + out = append(out, replacement...) + } + if out == nil { + return text + } + return string(out) } // --- Default logger --- @@ -487,7 +509,7 @@ func Security(msg string, keyvals ...any) { } func shouldRedact(key any, redactKeys []string) bool { - keyStr := fmt.Sprintf("%v", key) + keyStr := logValueString(key) for _, redactKey := range redactKeys { if redactKey == keyStr { return true @@ -495,3 +517,7 @@ func shouldRedact(key any, redactKeys []string) bool { } return false } + +func logValueString(value any) string { + return slog.AnyValue(value).String() +} diff --git a/log_test.go b/log_test.go index cd3b4d8..8ecc9f6 100644 --- a/log_test.go +++ b/log_test.go @@ -1,10 +1,10 @@ package log import ( + // Note: test-only stdlib (no core equivalent for io.Writer capture). "bytes" - "errors" goio "io" - "os" + // Note: test-only stdlib (no core equivalent for rendered output assertions). "strings" "testing" "time" @@ -106,7 +106,7 @@ func TestLogger_ErrorContextIncludesRecovery_Good(t *testing.T) { l := New(Options{Output: &buf, Level: LevelInfo}) retryAfter := 45 * time.Second - err := EWithRecovery("retryable.Op", "temporary failure", errors.New("temporary failure"), true, &retryAfter, "retry with backoff") + err := EWithRecovery("retryable.Op", "temporary failure", NewError("temporary failure"), true, &retryAfter, "retry with backoff") l.Error("request failed", "err", err) output := buf.String() @@ -314,14 +314,17 @@ func TestLogger_SetOutput_Good(t *testing.T) { } } -func TestLogger_SetOutput_Bad_NilFallsBackToStderr(t *testing.T) { +func TestLogger_SetOutput_Bad_NilUsesFallback(t *testing.T) { var buf bytes.Buffer l := New(Options{Level: LevelInfo, Output: &buf}) l.SetOutput(nil) - if l.output != os.Stderr { - t.Errorf("expected nil output to fallback to os.Stderr, got %T", l.output) + if l.output == nil { + t.Error("expected nil output to install a fallback writer") + } + if l.output == &buf { + t.Error("expected nil output to replace the previous writer") } } diff --git a/specs/RFC.md b/specs/RFC.md index 78aaf1d..9f44ccd 100644 --- a/specs/RFC.md +++ b/specs/RFC.md @@ -237,7 +237,7 @@ Collects `AllOps(err)` into a slice in outermost-to-innermost order. When no ope ### Username `func Username() string` -Returns the current username by trying `user.Current()` first, then the `USER` environment variable, then the `USERNAME` environment variable. +Returns the current username by trying the `USER` environment variable first, then the `USERNAME` environment variable. It does not perform account database lookups. ### Warn `func Warn(msg string, keyvals ...any)` diff --git a/tests/cli/log/Taskfile.yaml b/tests/cli/log/Taskfile.yaml new file mode 100644 index 0000000..0ff4d6d --- /dev/null +++ b/tests/cli/log/Taskfile.yaml @@ -0,0 +1,25 @@ +version: "3" + +tasks: + default: + deps: [test] + + test: + desc: Validate the go-log AX-10 CLI artifact driver. + dir: ../../.. + cmds: + - | + export GOCACHE="${GOCACHE:-/tmp/go-log-gocache}" + export GOMODCACHE="${GOMODCACHE:-/tmp/go-log-gomodcache}" + export GOWORK=off + mkdir -p "$GOCACHE" "$GOMODCACHE" + bin="$(mktemp -t core-log.XXXXXX)" + trap 'rm -f "$bin"' EXIT + go build -o "$bin" ./tests/cli/log + "$bin" + + driver: + desc: Run the go-log AX-10 driver directly. + dir: ../../.. + cmds: + - go run ./tests/cli/log diff --git a/tests/cli/log/main.go b/tests/cli/log/main.go new file mode 100644 index 0000000..37af8a8 --- /dev/null +++ b/tests/cli/log/main.go @@ -0,0 +1,198 @@ +// AX-10 CLI driver for go-log. It exercises the public logging and structured +// error helpers without depending on the repository's unit test package. +// +// task -d tests/cli/log test +// go run ./tests/cli/log +package main + +import ( + "bytes" + "errors" + "fmt" + "io" + "os" + "strings" + "time" + + corelog "dappco.re/go/log" +) + +type nopWriteCloser struct { + io.Writer +} + +func (nopWriteCloser) Close() error { + return nil +} + +func main() { + if err := run(); err != nil { + fmt.Fprintln(os.Stderr, err) + os.Exit(1) + } +} + +func run() error { + if err := verifyLoggerOutput(); err != nil { + return fmt.Errorf("logger output: %w", err) + } + if err := verifyStructuredErrors(); err != nil { + return fmt.Errorf("structured errors: %w", err) + } + if err := verifyDefaultLoggerAndRotationHooks(); err != nil { + return fmt.Errorf("default logger and rotation hooks: %w", err) + } + if username := corelog.Username(); username == "" { + return errors.New("username should not be empty") + } + return nil +} + +func verifyLoggerOutput() error { + var buf bytes.Buffer + logger := corelog.New(corelog.Options{ + Level: corelog.LevelDebug, + Output: &buf, + RedactKeys: []string{"secret"}, + }) + + retryAfter := 3 * time.Second + err := corelog.EWithRecovery("driver.inner", "temporary failure", errors.New("network"), true, &retryAfter, "retry later") + err = corelog.WrapCode(err, "AX10_TEMPORARY", "driver.outer", "outer failure") + + logger.Debug("debug event", "component", "ax-10") + logger.Info("login\nattempt", "user", "alice", "secret", "token\nvalue") + logger.Warn("slow path", "attempt", 2) + logger.Error("request failed", "err", err) + logger.Security("suspicious login", "ip", "127.0.0.1") + + output := buf.String() + for _, want := range []string{ + "[DBG] debug event", + "[INF] login\\nattempt", + "user=\"alice\"", + "secret=\"[REDACTED]\"", + "[WRN] slow path attempt=2", + "[ERR] request failed", + "err=driver.outer: outer failure [AX10_TEMPORARY]: driver.inner: temporary failure: network", + "op=\"driver.outer\"", + "stack=\"driver.outer -> driver.inner\"", + "retryable=true", + "retry_after_seconds=3", + "next_action=\"retry later\"", + "[SEC] suspicious login ip=\"127.0.0.1\"", + } { + if !strings.Contains(output, want) { + return fmt.Errorf("output missing %q in %q", want, output) + } + } + + if strings.Contains(output, "token\nvalue") { + return errors.New("log output contains an unescaped newline in a value") + } + if got := strings.Count(strings.TrimSpace(output), "\n"); got != 4 { + return fmt.Errorf("expected 5 log lines, got %d", got+1) + } + + var quiet bytes.Buffer + corelog.New(corelog.Options{Level: corelog.LevelQuiet, Output: &quiet}).Security("hidden") + if quiet.Len() != 0 { + return errors.New("quiet logger emitted security output") + } + + return nil +} + +func verifyStructuredErrors() error { + root := errors.New("root cause") + inner := corelog.WrapCode(root, "AX10_FAILURE", "driver.inner", "inner failed") + outer := corelog.Wrap(inner, "driver.outer", "outer failed") + + if !corelog.Is(outer, root) { + return errors.New("wrapped error should match root cause") + } + if got := corelog.Root(outer); got != root { + return fmt.Errorf("root = %v, want %v", got, root) + } + if got := corelog.ErrCode(outer); got != "AX10_FAILURE" { + return fmt.Errorf("error code = %q, want AX10_FAILURE", got) + } + if got := corelog.Op(outer); got != "driver.outer" { + return fmt.Errorf("op = %q, want driver.outer", got) + } + if got := corelog.Message(outer); got != "outer failed" { + return fmt.Errorf("message = %q, want outer failed", got) + } + if got := corelog.FormatStackTrace(outer); got != "driver.outer -> driver.inner" { + return fmt.Errorf("stack trace = %q", got) + } + + ops := make([]string, 0, 2) + for op := range corelog.AllOps(outer) { + ops = append(ops, op) + } + if strings.Join(ops, ",") != "driver.outer,driver.inner" { + return fmt.Errorf("ops = %v", ops) + } + + retryAfter := 5 * time.Second + retryable := corelog.WrapWithRecovery(root, "driver.retry", "retryable failure", true, &retryAfter, "retry with backoff") + if !corelog.IsRetryable(retryable) { + return errors.New("retryable error should report retryable") + } + gotRetryAfter, ok := corelog.RetryAfter(retryable) + if !ok || gotRetryAfter == nil || *gotRetryAfter != retryAfter { + return fmt.Errorf("retry after = %v, ok=%v", gotRetryAfter, ok) + } + if got := corelog.RecoveryAction(retryable); got != "retry with backoff" { + return fmt.Errorf("recovery action = %q", got) + } + + joined := corelog.Join(outer, corelog.NewCode("AX10_JOINED", "joined failure")) + var logErr *corelog.Err + if !corelog.As(joined, &logErr) { + return errors.New("joined error should expose a structured error") + } + if got := corelog.NewError("plain").Error(); got != "plain" { + return fmt.Errorf("new error = %q, want plain", got) + } + + return nil +} + +func verifyDefaultLoggerAndRotationHooks() error { + var defaultBuf bytes.Buffer + originalDefault := corelog.Default() + corelog.SetDefault(corelog.New(corelog.Options{Level: corelog.LevelInfo, Output: &defaultBuf})) + defer corelog.SetDefault(originalDefault) + + corelog.Info("default info", "ok", true) + if output := defaultBuf.String(); !strings.Contains(output, "[INF] default info ok=true") { + return fmt.Errorf("default logger output = %q", output) + } + + var rotated bytes.Buffer + originalFactory := corelog.RotationWriterFactory + corelog.RotationWriterFactory = func(opts corelog.RotationOptions) io.WriteCloser { + if opts.Filename != "ax10.log" { + return nopWriteCloser{Writer: io.Discard} + } + return nopWriteCloser{Writer: &rotated} + } + defer func() { + corelog.RotationWriterFactory = originalFactory + }() + + logger := corelog.New(corelog.Options{ + Level: corelog.LevelInfo, + Rotation: &corelog.RotationOptions{ + Filename: "ax10.log", + }, + }) + logger.Info("rotated output") + if output := rotated.String(); !strings.Contains(output, "[INF] rotated output") { + return fmt.Errorf("rotation writer output = %q", output) + } + + return nil +}