Add structured logging infrastructure (#59)

Implement comprehensive structured logging using slog across agent runtime,
task reconciliation, and model providers with:

• New logging layer: agent/logger.go with standardized log key constants
• Context propagation: agent/context.go for task/agent/model tracking
• Model providers: OpenAI, Anthropic, Gemini with operation telemetry
• Task reconciliation: Detailed logging of reconciliation phases and tool execution
• Filesystem tools: Logging for file operations and search results
• Code interpreter: Execution timing and output tracking
• Runtime lifecycle: Component initialization and shutdown logging

Key features:
- Centralized log key constants for consistency (KeyTaskID, KeyModel, etc.)
- Operation timing with LogOperationStart/End helpers
- Token usage logging with cache hit ratio calculations
- Retryable error logging with retry-after timing

This enables better observability into task execution, model invocations,
and tool operations for debugging and performance monitoring.

Co-authored-by: construct-agent <noreply@construct.sh>

Author: Furisto

backend/agent/client.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
+	"log/slog"
 
 	"github.com/furisto/construct/backend/memory"
 	"github.com/furisto/construct/backend/memory/schema/types"
@@ -27,55 +28,61 @@ func NewModelProviderFactory(encryption *secret.Encryption, memory *memory.Clien
 func (f *ModelProviderFactory) CreateClient(
 	ctx context.Context,
 	modelProviderID uuid.UUID,
-) (model.ModelProvider, error) {
+) (providerClient model.ModelProvider, err error) {
+	logger := slog.With(
+		KeyComponent, "model_provider_factory",
+		KeyModelProvider, modelProviderID,
+	)
+
 	provider, err := f.memory.ModelProvider.Get(ctx, modelProviderID)
 	if err != nil {
+		LogError(logger, "fetch model provider", err)
 		return nil, fmt.Errorf("failed to fetch model provider: %w", err)
 	}
+	logger = logger.With(KeyProvider, string(provider.ProviderType))
 
 	providerAuth, err := f.encryption.Decrypt(provider.Secret, []byte(secret.ModelProviderAssociated(provider.ID)))
 	if err != nil {
+		LogError(logger, "decrypt model provider secret", err)
 		return nil, fmt.Errorf("failed to decrypt model provider secret: %w", err)
 	}
+	logger.Debug("model provider secret decrypted")
 
 	var auth struct {
 		APIKey string `json:"apiKey"`
 	}
+
 	err = json.Unmarshal(providerAuth, &auth)
 	if err != nil {
+		LogError(logger, "unmarshal model provider auth", err)
 		return nil, fmt.Errorf("failed to unmarshal model provider auth: %w", err)
 	}
 
+	logger.Debug("creating model provider client")
 	switch provider.ProviderType {
 	case types.ModelProviderTypeAnthropic:
-		apiProvider, err := model.NewAnthropicProvider(auth.APIKey)
-		if err != nil {
-			return nil, fmt.Errorf("failed to create Anthropic provider: %w", err)
-		}
-		return apiProvider, nil
+		providerClient, err = model.NewAnthropicProvider(auth.APIKey)
 
 	case types.ModelProviderTypeOpenAI:
-		apiProvider, err := model.NewOpenAICompletionProvider(auth.APIKey)
-		if err != nil {
-			return nil, fmt.Errorf("failed to create OpenAI provider: %w", err)
-		}
-		return apiProvider, nil
+		providerClient, err = model.NewOpenAICompletionProvider(auth.APIKey)
 
 	case types.ModelProviderTypeGemini:
-		apiProvider, err := model.NewGeminiProvider(auth.APIKey)
-		if err != nil {
-			return nil, fmt.Errorf("failed to create Gemini provider: %w", err)
-		}
-		return apiProvider, nil
+		providerClient, err = model.NewGeminiProvider(auth.APIKey)
 
 	case types.ModelProviderTypeXAI:
-		apiProvider, err := model.NewOpenAICompletionProvider(auth.APIKey, model.WithURL("https://api.xai.com/v1"))
-		if err != nil {
-			return nil, fmt.Errorf("failed to create XAI provider: %w", err)
-		}
-		return apiProvider, nil
+		providerClient, err = model.NewOpenAICompletionProvider(auth.APIKey, model.WithURL("https://api.xai.com/v1"))
 
 	default:
+		logger.Error("unknown model provider type",
+			KeyProvider, string(provider.ProviderType),
+		)
 		return nil, fmt.Errorf("unknown model provider type: %s", provider.ProviderType)
 	}
+
+	if err != nil {
+		LogError(logger, "create provider", err)
+		return nil, fmt.Errorf("failed to create Anthropic provider: %w", err)
+	}
+
+	return providerClient, nil
 }

backend/agent/logger.go

@@ -0,0 +1,180 @@
+package agent
+
+import (
+	"fmt"
+	"log/slog"
+	"time"
+)
+
+// Log key constants for consistency across the codebase
+const (
+	// Task and agent identifiers
+	KeyTaskID    = "task_id"
+	KeyAgentID   = "agent_id"
+	KeyMessageID = "message_id"
+
+	// Model and provider information
+	KeyModel         = "model"
+	KeyProvider      = "provider"
+	KeyModelProvider = "model_provider"
+
+	// Timing and performance
+	KeyDuration   = "duration_ms"
+	KeyStartTime  = "start_time"
+	KeyEndTime    = "end_time"
+	KeyLatency    = "latency_ms"
+	KeyThroughput = "throughput"
+
+	// Token and cost tracking
+	KeyInputTokens      = "input_tokens"
+	KeyOutputTokens     = "output_tokens"
+	KeyTotalTokens      = "total_tokens"
+	KeyCacheWriteTokens = "cache_write_tokens"
+	KeyCacheReadTokens  = "cache_read_tokens"
+	KeyCost             = "cost"
+	KeyTokensPerSecond  = "tokens_per_second"
+	KeyCacheHitRatio    = "cache_hit_ratio"
+
+	// Tool and execution information
+	KeyTool         = "tool"
+	KeyToolCount    = "tool_count"
+	KeyToolName     = "tool_name"
+	KeyToolDuration = "tool_duration_ms"
+	KeyToolResult   = "tool_result"
+	KeyToolStats    = "tool_stats"
+
+	// Message and queue information
+	KeyMessageCount     = "message_count"
+	KeyProcessedCount   = "processed_count"
+	KeyUnprocessedCount = "unprocessed_count"
+	KeyQueueDepth       = "queue_depth"
+	KeyActiveTaskCount  = "active_task_count"
+	KeyPhase            = "phase"
+	KeyNextPhase        = "next_phase"
+
+	// Configuration and environment
+	KeyConcurrency     = "concurrency"
+	KeyToolsRegistered = "tools_registered"
+	KeyListenerAddress = "listener_address"
+	KeyListenerType    = "listener_type"
+
+	// Error and retry information
+	KeyRetryable  = "retryable"
+	KeyRetryAfter = "retry_after_ms"
+	KeyRetryCount = "retry_count"
+	KeyErrorType  = "error_type"
+	KeyError      = "error"
+
+	// Operations and components
+	KeyOperation = "operation"
+	KeyComponent = "component"
+)
+
+// LoggerConfig holds logging configuration
+type LoggerConfig struct {
+	Level         slog.Level
+	VerboseTools  bool
+	VerboseModels bool
+}
+
+// DefaultLoggerConfig returns default logging configuration
+func DefaultLoggerConfig() *LoggerConfig {
+	return &LoggerConfig{
+		Level:         slog.LevelInfo,
+		VerboseTools:  false,
+		VerboseModels: false,
+	}
+}
+
+// LogOperationStart logs the start of a significant operation
+func LogOperationStart(logger *slog.Logger, operation string, keyValues ...any) {
+	args := append([]any{KeyOperation, operation}, keyValues...)
+	logger.Debug(fmt.Sprintf("%s started", operation), args...)
+}
+
+// LogOperationEnd logs the end of a significant operation
+func LogOperationEnd(logger *slog.Logger, operation string, start time.Time, keyValues ...any) {
+	args := append(
+		[]any{
+			KeyOperation, operation,
+			KeyDuration, time.Since(start).Milliseconds(),
+		},
+		keyValues...,
+	)
+	logger.Debug(fmt.Sprintf("%s completed", operation), args...)
+}
+
+// LogTokenUsage logs token usage from an API call
+func LogTokenUsage(logger *slog.Logger, level slog.Level, inputTokens, outputTokens, cacheWrite, cacheRead int64, cost float64, duration time.Duration, keyValues ...any) {
+	totalTokens := inputTokens + outputTokens + cacheWrite + cacheRead
+	tokensPerSec := 0.0
+	if duration.Seconds() > 0 {
+		tokensPerSec = float64(outputTokens) / duration.Seconds()
+	}
+	cacheHitRatio := 0.0
+	if inputTokens+cacheRead > 0 {
+		cacheHitRatio = float64(cacheRead) / float64(inputTokens+cacheRead)
+	}
+
+	args := append(
+		[]any{
+			KeyInputTokens, inputTokens,
+			KeyOutputTokens, outputTokens,
+			KeyTotalTokens, totalTokens,
+			KeyCacheWriteTokens, cacheWrite,
+			KeyCacheReadTokens, cacheRead,
+			KeyCost, fmt.Sprintf("$%.6f", cost),
+			KeyTokensPerSecond, fmt.Sprintf("%.2f", tokensPerSec),
+			KeyCacheHitRatio, fmt.Sprintf("%.1f%%", cacheHitRatio*100),
+			KeyDuration, duration.Milliseconds(),
+		},
+		keyValues...,
+	)
+	logger.Log(nil, level, "token usage", args...)
+}
+
+// LogPhaseTransition logs task phase transitions
+func LogPhaseTransition(logger *slog.Logger, taskID string, from, to string, keyValues ...any) {
+	args := append(
+		[]any{
+			KeyTaskID, taskID,
+			"from_phase", from,
+			"to_phase", to,
+		},
+		keyValues...,
+	)
+	logger.Debug("task phase transition", args...)
+}
+
+// LogComponentStartup logs component initialization
+func LogComponentStartup(logger *slog.Logger, component string, keyValues ...any) {
+	args := append(
+		[]any{KeyComponent, component},
+		keyValues...,
+	)
+	logger.Info(fmt.Sprintf("%s initializing", component), args...)
+}
+
+// LogComponentShutdown logs component shutdown
+func LogComponentShutdown(logger *slog.Logger, component string, shutdownStart time.Time, keyValues ...any) {
+	args := append(
+		[]any{
+			KeyComponent, component,
+			KeyDuration, time.Since(shutdownStart).Milliseconds(),
+		},
+		keyValues...,
+	)
+	logger.Info(fmt.Sprintf("%s shutdown complete", component), args...)
+}
+
+// LogError logs an error with structured context
+func LogError(logger *slog.Logger, operation string, err error, keyValues ...any) {
+	args := append(
+		[]any{
+			KeyOperation, operation,
+			KeyError, err.Error(),
+		},
+		keyValues...,
+	)
+	logger.Error(fmt.Sprintf("failed: %s", operation), args...)
+}