go/pkg/log/errors_test.go
Snider 2f8684061c
Log all errors at handling point with contextual information (#321)
* feat(log): log all errors at handling point with context

This change ensures all errors are logged at the point where they are
handled, including contextual information such as operations and
logical stack traces.

Key changes:
- Added `StackTrace` and `FormatStackTrace` to `pkg/log/errors.go`.
- Enhanced `Logger.log` in `pkg/log/log.go` to automatically extract
  and log `op` and `stack` keys when an error is passed in keyvals.
- Updated CLI logging and output helpers to support structured logging.
- Updated CLI fatal error handlers to log errors before exiting.
- Audited and updated error logging in MCP service (tool handlers and
  TCP transport), CLI background services (signal and health), and
  Agentic task handlers.

* feat(log): log all errors at handling point with context

This change ensures all errors are logged at the point where they are
handled, including contextual information such as operations and
logical stack traces.

Key changes:
- Added `StackTrace` and `FormatStackTrace` to `pkg/log/errors.go`.
- Enhanced `Logger.log` in `pkg/log/log.go` to automatically extract
  and log `op` and `stack` keys when an error is passed in keyvals.
- Updated CLI logging and output helpers to support structured logging.
- Updated CLI fatal error handlers to log errors before exiting.
- Audited and updated error logging in MCP service (tool handlers and
  TCP transport), CLI background services (signal and health), and
  Agentic task handlers.
- Fixed formatting in `pkg/mcp/mcp.go` and `pkg/io/local/client.go`.
- Removed unused `fmt` import in `pkg/cli/runtime.go`.

* feat(log): log all errors at handling point with context

This change ensures all errors are logged at the point where they are
handled, including contextual information such as operations and
logical stack traces.

Key changes:
- Added `StackTrace` and `FormatStackTrace` to `pkg/log/errors.go`.
- Enhanced `Logger.log` in `pkg/log/log.go` to automatically extract
  and log `op` and `stack` keys when an error is passed in keyvals.
- Updated CLI logging and output helpers to support structured logging.
- Updated CLI fatal error handlers to log errors before exiting.
- Audited and updated error logging in MCP service (tool handlers and
  TCP transport), CLI background services (signal and health), and
  Agentic task handlers.
- Fixed formatting in `pkg/mcp/mcp.go` and `pkg/io/local/client.go`.
- Removed unused `fmt` import in `pkg/cli/runtime.go`.
- Fixed CI failure in `auto-merge` workflow by providing explicit
  repository context to the GitHub CLI.

* feat(log): address PR feedback and improve error context extraction

Addressed feedback from PR review:
- Improved `Fatalf` and other fatal functions in `pkg/cli/errors.go` to
  use structured logging for the formatted message.
- Added direct unit tests for `StackTrace` and `FormatStackTrace` in
  `pkg/log/errors_test.go`, covering edge cases like plain errors,
  nil errors, and mixed error chains.
- Optimized the automatic context extraction loop in `pkg/log/log.go`
  by capturing the original length of keyvals.
- Fixed a bug in `StackTrace` where operations were duplicated when
  the error chain included non-`*log.Err` errors.
- Fixed formatting and unused imports from previous commits.

* fix: address code review comments

- Simplify Fatalf logging by removing redundant format parameter
  (the formatted message is already logged as "msg")
- Tests for StackTrace/FormatStackTrace edge cases already exist
- Loop optimization in pkg/log/log.go already implemented

Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>

---------

Co-authored-by: Claude <developers@lethean.io>
Co-authored-by: Claude Opus 4.5 <noreply@anthropic.com>
2026-02-05 07:52:25 +00:00

349 lines
9.5 KiB
Go

package log
import (
"bytes"
"errors"
"fmt"
"strings"
"testing"
"github.com/stretchr/testify/assert"
)
// --- Err Type Tests ---
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())
// 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
err := &Err{Msg: "just a message"}
assert.Equal(t, "just a message", err.Error())
// No Op with code
err = &Err{Msg: "error with code", Code: "ERR_CODE"}
assert.Equal(t, "error with code [ERR_CODE]", err.Error())
// No Op with underlying error
err = &Err{Msg: "wrapped", Err: errors.New("underlying")}
assert.Equal(t, "wrapped: underlying", err.Error())
}
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))
}
// --- Error Creation Function Tests ---
func TestE_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)
}
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())
}
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))
}
func TestWrap_PreservesCode_Good(t *testing.T) {
// Create an error with a code
inner := WrapCode(errors.New("base"), "VALIDATION_ERROR", "inner.Op", "validation failed")
// 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]")
}
func TestWrap_NilError_Good(t *testing.T) {
err := Wrap(nil, "op", "msg")
assert.Nil(t, 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)
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]")
}
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]")
// Only returns nil when both error and code are empty
err = WrapCode(nil, "", "op", "msg")
assert.Nil(t, 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)
}
// --- Standard Library Wrapper Tests ---
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")))
}
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)
}
func TestNewError_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) {
err1 := errors.New("error 1")
err2 := errors.New("error 2")
joined := Join(err1, err2)
assert.True(t, errors.Is(joined, err1))
assert.True(t, errors.Is(joined, err2))
}
// --- Helper Function Tests ---
func TestOp_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) {
err := errors.New("plain error")
assert.Equal(t, "", Op(err))
}
func TestErrCode_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) {
err := E("op", "msg", errors.New("base"))
assert.Equal(t, "", ErrCode(err))
}
func TestMessage_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) {
err := errors.New("plain message")
assert.Equal(t, "plain message", Message(err))
}
func TestMessage_Good_Nil(t *testing.T) {
assert.Equal(t, "", Message(nil))
}
func TestRoot_Good(t *testing.T) {
root := errors.New("root cause")
level1 := Wrap(root, "level1", "wrapped once")
level2 := Wrap(level1, "level2", "wrapped twice")
assert.Equal(t, root, Root(level2))
}
func TestRoot_Good_SingleError(t *testing.T) {
err := errors.New("single")
assert.Equal(t, err, Root(err))
}
func TestRoot_Good_Nil(t *testing.T) {
assert.Nil(t, Root(nil))
}
// --- Log-and-Return Helper Tests ---
func TestLogError_Good(t *testing.T) {
// Capture log output
var buf bytes.Buffer
logger := New(Options{Level: LevelDebug, Output: &buf})
SetDefault(logger)
defer SetDefault(New(Options{Level: LevelInfo}))
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) {
var buf bytes.Buffer
logger := New(Options{Level: LevelDebug, Output: &buf})
SetDefault(logger)
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
}
func TestLogWarn_Good(t *testing.T) {
var buf bytes.Buffer
logger := New(Options{Level: LevelDebug, Output: &buf})
SetDefault(logger)
defer SetDefault(New(Options{Level: LevelInfo}))
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))
output := buf.String()
assert.Contains(t, output, "[WRN]")
assert.Contains(t, output, "falling back to db")
}
func TestLogWarn_Good_NilError(t *testing.T) {
var buf bytes.Buffer
logger := New(Options{Level: LevelDebug, Output: &buf})
SetDefault(logger)
defer SetDefault(New(Options{Level: LevelInfo}))
err := LogWarn(nil, "op", "msg")
assert.Nil(t, err)
assert.Empty(t, buf.String())
}
func TestMust_Good_NoError(t *testing.T) {
// Should not panic when error is nil
assert.NotPanics(t, func() {
Must(nil, "test", "should not panic")
})
}
func TestMust_Ugly_Panics(t *testing.T) {
var buf bytes.Buffer
logger := New(Options{Level: LevelDebug, Output: &buf})
SetDefault(logger)
defer SetDefault(New(Options{Level: LevelInfo}))
assert.Panics(t, func() {
Must(errors.New("fatal error"), "startup", "initialization failed")
})
// Verify error was logged before panic
output := buf.String()
assert.True(t, strings.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")
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(t *testing.T) {
err := E("inner", "msg", nil)
err = errors.New("middle: " + err.Error()) // Breaks the chain if not handled properly, but Unwrap should work if it's a wrapped error
// Wait, errors.New doesn't wrap. fmt.Errorf("%w") does.
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)
}