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>

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

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)
 		}
 	}()
 

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)

pkg/cli/log.go

@@ -67,30 +67,30 @@ func Log() *LogService {
 	return svc
 }
 
-// LogDebug logs a debug message if log service is available.
+// LogDebug logs a debug message with optional key-value pairs if log service is available.
-func LogDebug(msg string) {
+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.
+// LogInfo logs an info message with optional key-value pairs if log service is available.
-func LogInfo(msg string) {
+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.
+// LogWarn logs a warning message with optional key-value pairs if log service is available.
-func LogWarn(msg string) {
+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.
+// LogError logs an error message with optional key-value pairs if log service is available.
-func LogError(msg string) {
+func LogError(msg string, keyvals ...any) {
 	if l := Log(); l != nil {
-		l.Error(msg)
+		l.Error(msg, keyvals...)
 	}
 }

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...))
 }

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")
 						}

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.

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)
+}

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 {

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})
 

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)
 	}
 

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())
 	}
 }