2026-01-30 22:02:40 +00:00
|
|
|
package log
|
|
|
|
|
|
|
|
|
|
import (
|
|
|
|
|
"bytes"
|
|
|
|
|
"strings"
|
|
|
|
|
"testing"
|
2026-02-05 10:26:32 +00:00
|
|
|
|
|
|
|
|
"github.com/host-uk/core/pkg/io"
|
2026-01-30 22:02:40 +00:00
|
|
|
)
|
|
|
|
|
|
|
|
|
|
func TestLogger_Levels(t *testing.T) {
|
|
|
|
|
tests := []struct {
|
|
|
|
|
name string
|
|
|
|
|
level Level
|
|
|
|
|
logFunc func(*Logger, string, ...any)
|
|
|
|
|
expected bool
|
|
|
|
|
}{
|
|
|
|
|
{"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},
|
2026-02-05 10:26:48 +00:00
|
|
|
|
|
|
|
|
{"security at info", LevelInfo, (*Logger).Security, true},
|
|
|
|
|
{"security at error", LevelError, (*Logger).Security, true},
|
2026-01-30 22:02:40 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
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)
|
|
|
|
|
}
|
|
|
|
|
})
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
func TestLogger_KeyValues(t *testing.T) {
|
|
|
|
|
var buf bytes.Buffer
|
|
|
|
|
l := New(Options{Level: LevelDebug, Output: &buf})
|
|
|
|
|
|
|
|
|
|
l.Info("test message", "key1", "value1", "key2", 42)
|
|
|
|
|
|
|
|
|
|
output := buf.String()
|
|
|
|
|
if !strings.Contains(output, "test message") {
|
|
|
|
|
t.Error("expected message in output")
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(output, "key1=value1") {
|
|
|
|
|
t.Error("expected key1=value1 in output")
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(output, "key2=42") {
|
|
|
|
|
t.Error("expected key2=42 in output")
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
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
|
|
|
func TestLogger_ErrorContext(t *testing.T) {
|
|
|
|
|
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 !strings.Contains(got, "op=outer.Op") {
|
|
|
|
|
t.Errorf("expected output to contain op=outer.Op, got %q", got)
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(got, "stack=outer.Op -> test.Op") {
|
|
|
|
|
t.Errorf("expected output to contain stack=outer.Op -> test.Op, got %q", got)
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
2026-01-30 22:02:40 +00:00
|
|
|
func TestLogger_SetLevel(t *testing.T) {
|
|
|
|
|
l := New(Options{Level: LevelInfo})
|
|
|
|
|
|
|
|
|
|
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)
|
|
|
|
|
}
|
|
|
|
|
})
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
2026-02-05 10:26:48 +00:00
|
|
|
func TestLogger_Security(t *testing.T) {
|
|
|
|
|
var buf bytes.Buffer
|
|
|
|
|
l := New(Options{Level: LevelError, Output: &buf})
|
|
|
|
|
|
|
|
|
|
l.Security("unauthorized access", "user", "admin")
|
|
|
|
|
|
|
|
|
|
output := buf.String()
|
|
|
|
|
if !strings.Contains(output, "[SEC]") {
|
|
|
|
|
t.Error("expected [SEC] prefix in security log")
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(output, "unauthorized access") {
|
|
|
|
|
t.Error("expected message in security log")
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(output, "user=admin") {
|
|
|
|
|
t.Error("expected context in security log")
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
2026-01-30 22:02:40 +00:00
|
|
|
func TestDefault(t *testing.T) {
|
|
|
|
|
// Default logger should exist
|
|
|
|
|
if Default() == nil {
|
|
|
|
|
t.Error("expected default logger to exist")
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
// Package-level functions should work
|
|
|
|
|
var buf bytes.Buffer
|
|
|
|
|
l := New(Options{Level: LevelDebug, Output: &buf})
|
|
|
|
|
SetDefault(l)
|
|
|
|
|
|
|
|
|
|
Info("test")
|
|
|
|
|
if buf.Len() == 0 {
|
|
|
|
|
t.Error("expected package-level Info to produce output")
|
|
|
|
|
}
|
|
|
|
|
}
|
2026-02-05 10:26:32 +00:00
|
|
|
|
|
|
|
|
func TestLogger_RotationIntegration(t *testing.T) {
|
|
|
|
|
m := io.NewMockMedium()
|
|
|
|
|
// Hack: override io.Local for testing
|
|
|
|
|
oldLocal := io.Local
|
|
|
|
|
io.Local = m
|
|
|
|
|
defer func() { io.Local = oldLocal }()
|
|
|
|
|
|
|
|
|
|
l := New(Options{
|
|
|
|
|
Level: LevelInfo,
|
|
|
|
|
Rotation: &RotationOptions{
|
|
|
|
|
Filename: "integration.log",
|
|
|
|
|
MaxSize: 1,
|
|
|
|
|
},
|
|
|
|
|
})
|
|
|
|
|
|
|
|
|
|
l.Info("integration test")
|
|
|
|
|
|
|
|
|
|
// RotatingWriter needs to be closed to ensure data is written to MockMedium
|
|
|
|
|
if rw, ok := l.output.(*RotatingWriter); ok {
|
|
|
|
|
rw.Close()
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
content, err := m.Read("integration.log")
|
|
|
|
|
if err != nil {
|
|
|
|
|
t.Fatalf("failed to read log: %v", err)
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(content, "integration test") {
|
|
|
|
|
t.Errorf("expected content to contain log message, got %q", content)
|
|
|
|
|
}
|
|
|
|
|
}
|