From 5dd581c3bfaba9b9330dd12a3feb4883df0af3e5 Mon Sep 17 00:00:00 2001 From: Snider Date: Thu, 5 Feb 2026 07:52:25 +0000 Subject: [PATCH] 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 --------- Co-authored-by: Claude Co-authored-by: Claude Opus 4.5 --- pkg/agentic/service.go | 7 +++++++ pkg/cli/daemon.go | 2 +- pkg/cli/errors.go | 12 +++++++---- pkg/cli/log.go | 24 +++++++++++----------- pkg/cli/output.go | 16 ++++++++------- pkg/cli/runtime.go | 3 +-- pkg/log/errors.go | 31 ++++++++++++++++++++++++++++ pkg/log/errors_test.go | 44 ++++++++++++++++++++++++++++++++++++++++ pkg/log/log.go | 35 ++++++++++++++++++++++++++++++++ pkg/log/log_test.go | 18 ++++++++++++++++ pkg/mcp/mcp.go | 9 ++++++++ pkg/mcp/transport_tcp.go | 4 ++-- 12 files changed, 177 insertions(+), 28 deletions(-) diff --git a/pkg/agentic/service.go b/pkg/agentic/service.go index 11364744..810abbcb 100644 --- a/pkg/agentic/service.go +++ b/pkg/agentic/service.go @@ -7,6 +7,7 @@ import ( "strings" "github.com/host-uk/core/pkg/framework" + "github.com/host-uk/core/pkg/log" ) // Tasks for AI service @@ -63,10 +64,16 @@ func (s *Service) handleTask(c *framework.Core, t framework.Task) (any, bool, er switch m := t.(type) { case TaskCommit: err := s.doCommit(m) + if err != nil { + log.Error("agentic: commit task failed", "err", err, "path", m.Path) + } return nil, true, err case TaskPrompt: err := s.doPrompt(m) + if err != nil { + log.Error("agentic: prompt task failed", "err", err) + } return nil, true, err } return nil, false, nil diff --git a/pkg/cli/daemon.go b/pkg/cli/daemon.go index 692ccd6b..ccd3678b 100644 --- a/pkg/cli/daemon.go +++ b/pkg/cli/daemon.go @@ -219,7 +219,7 @@ func (h *HealthServer) Start() error { go func() { if err := h.server.Serve(listener); err != http.ErrServerClosed { - LogError(fmt.Sprintf("health server error: %v", err)) + LogError("health server error", "err", err) } }() diff --git a/pkg/cli/errors.go b/pkg/cli/errors.go index ef39d32c..bb9e0f71 100644 --- a/pkg/cli/errors.go +++ b/pkg/cli/errors.go @@ -107,26 +107,28 @@ func Exit(code int, err error) error { // Fatal Functions (Deprecated - return error from command instead) // ───────────────────────────────────────────────────────────────────────────── -// Fatal prints an error message to stderr and exits with code 1. +// Fatal prints an error message to stderr, logs it, and exits with code 1. // // Deprecated: return an error from the command instead. func Fatal(err error) { if err != nil { + LogError("Fatal error", "err", err) fmt.Fprintln(os.Stderr, ErrorStyle.Render(Glyph(":cross:")+" "+err.Error())) os.Exit(1) } } -// Fatalf prints a formatted error message to stderr and exits with code 1. +// Fatalf prints a formatted error message to stderr, logs it, and exits with code 1. // // Deprecated: return an error from the command instead. func Fatalf(format string, args ...any) { msg := fmt.Sprintf(format, args...) + LogError("Fatal error", "msg", msg) fmt.Fprintln(os.Stderr, ErrorStyle.Render(Glyph(":cross:")+" "+msg)) os.Exit(1) } -// FatalWrap prints a wrapped error message to stderr and exits with code 1. +// FatalWrap prints a wrapped error message to stderr, logs it, and exits with code 1. // Does nothing if err is nil. // // Deprecated: return an error from the command instead. @@ -136,12 +138,13 @@ func FatalWrap(err error, msg string) { if err == nil { return } + LogError("Fatal error", "msg", msg, "err", err) fullMsg := fmt.Sprintf("%s: %v", msg, err) fmt.Fprintln(os.Stderr, ErrorStyle.Render(Glyph(":cross:")+" "+fullMsg)) os.Exit(1) } -// FatalWrapVerb prints a wrapped error using i18n grammar to stderr and exits with code 1. +// FatalWrapVerb prints a wrapped error using i18n grammar to stderr, logs it, and exits with code 1. // Does nothing if err is nil. // // Deprecated: return an error from the command instead. @@ -152,6 +155,7 @@ func FatalWrapVerb(err error, verb, subject string) { return } msg := i18n.ActionFailed(verb, subject) + LogError("Fatal error", "msg", msg, "err", err, "verb", verb, "subject", subject) fullMsg := fmt.Sprintf("%s: %v", msg, err) fmt.Fprintln(os.Stderr, ErrorStyle.Render(Glyph(":cross:")+" "+fullMsg)) os.Exit(1) diff --git a/pkg/cli/log.go b/pkg/cli/log.go index 2cc542e2..1dcd4b46 100644 --- a/pkg/cli/log.go +++ b/pkg/cli/log.go @@ -67,30 +67,30 @@ func Log() *LogService { return svc } -// LogDebug logs a debug message if log service is available. -func LogDebug(msg string) { +// LogDebug logs a debug message with optional key-value pairs if log service is available. +func LogDebug(msg string, keyvals ...any) { if l := Log(); l != nil { - l.Debug(msg) + l.Debug(msg, keyvals...) } } -// LogInfo logs an info message if log service is available. -func LogInfo(msg string) { +// LogInfo logs an info message with optional key-value pairs if log service is available. +func LogInfo(msg string, keyvals ...any) { if l := Log(); l != nil { - l.Info(msg) + l.Info(msg, keyvals...) } } -// LogWarn logs a warning message if log service is available. -func LogWarn(msg string) { +// LogWarn logs a warning message with optional key-value pairs if log service is available. +func LogWarn(msg string, keyvals ...any) { if l := Log(); l != nil { - l.Warn(msg) + l.Warn(msg, keyvals...) } } -// LogError logs an error message if log service is available. -func LogError(msg string) { +// LogError logs an error message with optional key-value pairs if log service is available. +func LogError(msg string, keyvals ...any) { if l := Log(); l != nil { - l.Error(msg) + l.Error(msg, keyvals...) } } diff --git a/pkg/cli/output.go b/pkg/cli/output.go index ccdec22b..6c4fb7fc 100644 --- a/pkg/cli/output.go +++ b/pkg/cli/output.go @@ -46,17 +46,18 @@ func Successf(format string, args ...any) { Success(fmt.Sprintf(format, args...)) } -// Error prints an error message with cross (red) to stderr. +// Error prints an error message with cross (red) to stderr and logs it. func Error(msg string) { + LogError(msg) fmt.Fprintln(os.Stderr, ErrorStyle.Render(Glyph(":cross:")+" "+msg)) } -// Errorf prints a formatted error message to stderr. +// Errorf prints a formatted error message to stderr and logs it. func Errorf(format string, args ...any) { Error(fmt.Sprintf(format, args...)) } -// ErrorWrap prints a wrapped error message to stderr. +// ErrorWrap prints a wrapped error message to stderr and logs it. func ErrorWrap(err error, msg string) { if err == nil { return @@ -64,7 +65,7 @@ func ErrorWrap(err error, msg string) { Error(fmt.Sprintf("%s: %v", msg, err)) } -// ErrorWrapVerb prints a wrapped error using i18n grammar to stderr. +// ErrorWrapVerb prints a wrapped error using i18n grammar to stderr and logs it. func ErrorWrapVerb(err error, verb, subject string) { if err == nil { return @@ -73,7 +74,7 @@ func ErrorWrapVerb(err error, verb, subject string) { Error(fmt.Sprintf("%s: %v", msg, err)) } -// ErrorWrapAction prints a wrapped error using i18n grammar to stderr. +// ErrorWrapAction prints a wrapped error using i18n grammar to stderr and logs it. func ErrorWrapAction(err error, verb string) { if err == nil { return @@ -82,12 +83,13 @@ func ErrorWrapAction(err error, verb string) { Error(fmt.Sprintf("%s: %v", msg, err)) } -// Warn prints a warning message with warning symbol (amber) to stderr. +// Warn prints a warning message with warning symbol (amber) to stderr and logs it. func Warn(msg string) { + LogWarn(msg) fmt.Fprintln(os.Stderr, WarningStyle.Render(Glyph(":warn:")+" "+msg)) } -// Warnf prints a formatted warning message to stderr. +// Warnf prints a formatted warning message to stderr and logs it. func Warnf(format string, args ...any) { Warn(fmt.Sprintf(format, args...)) } diff --git a/pkg/cli/runtime.go b/pkg/cli/runtime.go index 3291692f..9a33ccae 100644 --- a/pkg/cli/runtime.go +++ b/pkg/cli/runtime.go @@ -15,7 +15,6 @@ package cli import ( "context" - "fmt" "os" "os/signal" "sync" @@ -193,7 +192,7 @@ func (s *signalService) OnStartup(ctx context.Context) error { case syscall.SIGHUP: if s.onReload != nil { if err := s.onReload(); err != nil { - LogError(fmt.Sprintf("reload failed: %v", err)) + LogError("reload failed", "err", err) } else { LogInfo("configuration reloaded") } diff --git a/pkg/log/errors.go b/pkg/log/errors.go index c6775521..af55a429 100644 --- a/pkg/log/errors.go +++ b/pkg/log/errors.go @@ -174,6 +174,37 @@ func Root(err error) error { } } +// StackTrace returns the logical stack trace (chain of operations) from an error. +// It returns an empty slice if no operational context is found. +func StackTrace(err error) []string { + var stack []string + for err != nil { + if e, ok := err.(*Err); ok { + if e.Op != "" { + stack = append(stack, e.Op) + } + } + err = errors.Unwrap(err) + } + return stack +} + +// FormatStackTrace returns a pretty-printed logical stack trace. +func FormatStackTrace(err error) string { + stack := StackTrace(err) + if len(stack) == 0 { + return "" + } + var res string + for i, op := range stack { + if i > 0 { + res += " -> " + } + res += op + } + return res +} + // --- Combined Log-and-Return Helpers --- // LogError logs an error at Error level and returns a wrapped error. diff --git a/pkg/log/errors_test.go b/pkg/log/errors_test.go index 96cbd12f..b403cfd2 100644 --- a/pkg/log/errors_test.go +++ b/pkg/log/errors_test.go @@ -3,6 +3,7 @@ package log import ( "bytes" "errors" + "fmt" "strings" "testing" @@ -303,3 +304,46 @@ func TestMust_Ugly_Panics(t *testing.T) { 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) +} diff --git a/pkg/log/log.go b/pkg/log/log.go index 84c290de..6529fd7d 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -131,6 +131,41 @@ 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 { + if err, ok := keyvals[i+1].(error); ok { + if op := Op(err); op != "" { + // Check if op is already in keyvals + hasOp := false + for j := 0; j < len(keyvals); j += 2 { + if keyvals[j] == "op" { + hasOp = true + break + } + } + if !hasOp { + keyvals = append(keyvals, "op", op) + } + } + if stack := FormatStackTrace(err); stack != "" { + // Check if stack is already in keyvals + hasStack := false + for j := 0; j < len(keyvals); j += 2 { + if keyvals[j] == "stack" { + hasStack = true + break + } + } + if !hasStack { + keyvals = append(keyvals, "stack", stack) + } + } + } + } + } + // Format key-value pairs var kvStr string if len(keyvals) > 0 { diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go index 6721e395..ea7fc2a1 100644 --- a/pkg/log/log_test.go +++ b/pkg/log/log_test.go @@ -71,6 +71,24 @@ func TestLogger_KeyValues(t *testing.T) { } } +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) + } +} + func TestLogger_SetLevel(t *testing.T) { l := New(Options{Level: LevelInfo}) diff --git a/pkg/mcp/mcp.go b/pkg/mcp/mcp.go index 0d3dba0d..1ab3037a 100644 --- a/pkg/mcp/mcp.go +++ b/pkg/mcp/mcp.go @@ -11,6 +11,7 @@ import ( "github.com/host-uk/core/pkg/io" "github.com/host-uk/core/pkg/io/local" + "github.com/host-uk/core/pkg/log" "github.com/modelcontextprotocol/go-sdk/mcp" ) @@ -281,6 +282,7 @@ type EditDiffOutput struct { func (s *Service) readFile(ctx context.Context, req *mcp.CallToolRequest, input ReadFileInput) (*mcp.CallToolResult, ReadFileOutput, error) { content, err := s.medium.Read(input.Path) if err != nil { + log.Error("mcp: read file failed", "path", input.Path, "err", err) return nil, ReadFileOutput{}, fmt.Errorf("failed to read file: %w", err) } return nil, ReadFileOutput{ @@ -293,6 +295,7 @@ func (s *Service) readFile(ctx context.Context, req *mcp.CallToolRequest, input func (s *Service) writeFile(ctx context.Context, req *mcp.CallToolRequest, input WriteFileInput) (*mcp.CallToolResult, WriteFileOutput, error) { // Medium.Write creates parent directories automatically if err := s.medium.Write(input.Path, input.Content); err != nil { + log.Error("mcp: write file failed", "path", input.Path, "err", err) return nil, WriteFileOutput{}, fmt.Errorf("failed to write file: %w", err) } return nil, WriteFileOutput{Success: true, Path: input.Path}, nil @@ -301,6 +304,7 @@ func (s *Service) writeFile(ctx context.Context, req *mcp.CallToolRequest, input func (s *Service) listDirectory(ctx context.Context, req *mcp.CallToolRequest, input ListDirectoryInput) (*mcp.CallToolResult, ListDirectoryOutput, error) { entries, err := s.medium.List(input.Path) if err != nil { + log.Error("mcp: list directory failed", "path", input.Path, "err", err) return nil, ListDirectoryOutput{}, fmt.Errorf("failed to list directory: %w", err) } result := make([]DirectoryEntry, 0, len(entries)) @@ -322,6 +326,7 @@ func (s *Service) listDirectory(ctx context.Context, req *mcp.CallToolRequest, i func (s *Service) createDirectory(ctx context.Context, req *mcp.CallToolRequest, input CreateDirectoryInput) (*mcp.CallToolResult, CreateDirectoryOutput, error) { if err := s.medium.EnsureDir(input.Path); err != nil { + log.Error("mcp: create directory failed", "path", input.Path, "err", err) return nil, CreateDirectoryOutput{}, fmt.Errorf("failed to create directory: %w", err) } return nil, CreateDirectoryOutput{Success: true, Path: input.Path}, nil @@ -329,6 +334,7 @@ func (s *Service) createDirectory(ctx context.Context, req *mcp.CallToolRequest, func (s *Service) deleteFile(ctx context.Context, req *mcp.CallToolRequest, input DeleteFileInput) (*mcp.CallToolResult, DeleteFileOutput, error) { if err := s.medium.Delete(input.Path); err != nil { + log.Error("mcp: delete file failed", "path", input.Path, "err", err) return nil, DeleteFileOutput{}, fmt.Errorf("failed to delete file: %w", err) } return nil, DeleteFileOutput{Success: true, Path: input.Path}, nil @@ -336,6 +342,7 @@ func (s *Service) deleteFile(ctx context.Context, req *mcp.CallToolRequest, inpu func (s *Service) renameFile(ctx context.Context, req *mcp.CallToolRequest, input RenameFileInput) (*mcp.CallToolResult, RenameFileOutput, error) { if err := s.medium.Rename(input.OldPath, input.NewPath); err != nil { + log.Error("mcp: rename file failed", "oldPath", input.OldPath, "newPath", input.NewPath, "err", err) return nil, RenameFileOutput{}, fmt.Errorf("failed to rename file: %w", err) } return nil, RenameFileOutput{Success: true, OldPath: input.OldPath, NewPath: input.NewPath}, nil @@ -389,6 +396,7 @@ func (s *Service) editDiff(ctx context.Context, req *mcp.CallToolRequest, input content, err := s.medium.Read(input.Path) if err != nil { + log.Error("mcp: edit file read failed", "path", input.Path, "err", err) return nil, EditDiffOutput{}, fmt.Errorf("failed to read file: %w", err) } @@ -409,6 +417,7 @@ func (s *Service) editDiff(ctx context.Context, req *mcp.CallToolRequest, input } if err := s.medium.Write(input.Path, content); err != nil { + log.Error("mcp: edit file write failed", "path", input.Path, "err", err) return nil, EditDiffOutput{}, fmt.Errorf("failed to write file: %w", err) } diff --git a/pkg/mcp/transport_tcp.go b/pkg/mcp/transport_tcp.go index dd88b4ad..dc60b1b6 100644 --- a/pkg/mcp/transport_tcp.go +++ b/pkg/mcp/transport_tcp.go @@ -57,7 +57,7 @@ func (s *Service) ServeTCP(ctx context.Context, addr string) error { case <-ctx.Done(): return nil default: - log.Error("Accept error", "err", err) + log.Error("mcp: accept error", "err", err) continue } } @@ -83,7 +83,7 @@ func (s *Service) handleConnection(ctx context.Context, conn net.Conn) { // Run server (blocks until connection closed) // Server.Run calls Connect, then Read loop. if err := server.Run(ctx, transport); err != nil { - log.Error("Connection error", "err", err) + log.Error("mcp: connection error", "err", err, "remote", conn.RemoteAddr()) } }