feat(logging): enhance logging for metadata extraction and MCP tool handling

internal/ai/compat/client.go

@@ -208,6 +208,33 @@ func (c *Client) ExtractMetadata(ctx context.Context, input string) (thoughttype
 		return thoughttypes.ThoughtMetadata{}, fmt.Errorf("%s extract metadata: input must not be empty", c.name)
 	}
 
+	start := time.Now()
+	if c.log != nil {
+		c.log.Info("metadata client started",
+			slog.String("provider", c.name),
+			slog.String("model", c.metadataModel),
+		)
+	}
+
+	logCompletion := func(model string, err error) {
+		if c.log == nil {
+			return
+		}
+
+		attrs := []any{
+			slog.String("provider", c.name),
+			slog.String("model", model),
+			slog.Duration("duration", time.Since(start)),
+		}
+		if err != nil {
+			attrs = append(attrs, slog.String("error", err.Error()))
+			c.log.Error("metadata client completed", attrs...)
+			return
+		}
+
+		c.log.Info("metadata client completed", attrs...)
+	}
+
 	result, err := c.extractMetadataWithModel(ctx, input, c.metadataModel)
 	if errors.Is(err, errMetadataEmptyResponse) {
 		c.noteEmptyResponse(c.metadataModel)
@@ -217,6 +244,7 @@ func (c *Client) ExtractMetadata(ctx context.Context, input string) (thoughttype
 	}
 	if err == nil {
 		c.noteModelSuccess(c.metadataModel)
+		logCompletion(c.metadataModel, nil)
 		return result, nil
 	}
 
@@ -247,13 +275,16 @@ func (c *Client) ExtractMetadata(ctx context.Context, input string) (thoughttype
 		}
 		if fallbackErr == nil {
 			c.noteModelSuccess(fallbackModel)
+			logCompletion(fallbackModel, nil)
 			return fallbackResult, nil
 		}
 		err = fallbackErr
 	}
 
 	if ctx.Err() != nil {
-		return thoughttypes.ThoughtMetadata{}, fmt.Errorf("%s metadata: %w", c.name, ctx.Err())
+		err = fmt.Errorf("%s metadata: %w", c.name, ctx.Err())
+		logCompletion(c.metadataModel, err)
+		return thoughttypes.ThoughtMetadata{}, err
 	}
 
 	heuristic := heuristicMetadataFromInput(input)
@@ -263,6 +294,7 @@ func (c *Client) ExtractMetadata(ctx context.Context, input string) (thoughttype
 			slog.String("error", err.Error()),
 		)
 	}
+	logCompletion(c.metadataModel, nil)
 	return heuristic, nil
 }
 

internal/app/app.go

@@ -176,7 +176,7 @@ func routes(logger *slog.Logger, cfg *config.Config, db *store.DB, provider ai.P
 		Skills:        tools.NewSkillsTool(db, activeProjects),
 	}
 
-	mcpHandler := mcpserver.New(cfg.MCP, toolSet)
+	mcpHandler := mcpserver.New(cfg.MCP, logger, toolSet)
 	mux.Handle(cfg.MCP.Path, authMiddleware(mcpHandler))
 	mux.Handle("/files", authMiddleware(fileHandler(filesTool)))
 	mux.Handle("/files/{id}", authMiddleware(fileHandler(filesTool)))

internal/mcpserver/schema.go

@@ -3,7 +3,9 @@ package mcpserver
 import (
 	"context"
 	"fmt"
+	"log/slog"
 	"reflect"
+	"time"
 
 	"github.com/google/jsonschema-go/jsonschema"
 	"github.com/google/uuid"
@@ -19,11 +21,39 @@ var toolSchemaOptions = &jsonschema.ForOptions{
 	},
 }
 
-func addTool[In any, Out any](server *mcp.Server, tool *mcp.Tool, handler func(context.Context, *mcp.CallToolRequest, In) (*mcp.CallToolResult, Out, error)) {
+func addTool[In any, Out any](server *mcp.Server, logger *slog.Logger, tool *mcp.Tool, handler func(context.Context, *mcp.CallToolRequest, In) (*mcp.CallToolResult, Out, error)) {
 	if err := setToolSchemas[In, Out](tool); err != nil {
 		panic(fmt.Sprintf("configure MCP tool %q schemas: %v", tool.Name, err))
 	}
-	mcp.AddTool(server, tool, handler)
+	mcp.AddTool(server, tool, logToolCall(logger, tool.Name, handler))
+}
+
+func logToolCall[In any, Out any](logger *slog.Logger, toolName string, handler func(context.Context, *mcp.CallToolRequest, In) (*mcp.CallToolResult, Out, error)) func(context.Context, *mcp.CallToolRequest, In) (*mcp.CallToolResult, Out, error) {
+	if logger == nil {
+		return handler
+	}
+
+	return func(ctx context.Context, req *mcp.CallToolRequest, in In) (*mcp.CallToolResult, Out, error) {
+		start := time.Now()
+		attrs := []any{slog.String("tool", toolName)}
+		if req != nil && req.Params != nil {
+			attrs = append(attrs, slog.Any("arguments", req.Params.Arguments))
+		}
+
+		logger.Info("mcp tool started", attrs...)
+		result, out, err := handler(ctx, req, in)
+
+		completionAttrs := append([]any{}, attrs...)
+		completionAttrs = append(completionAttrs, slog.Duration("duration", time.Since(start)))
+		if err != nil {
+			completionAttrs = append(completionAttrs, slog.String("error", err.Error()))
+			logger.Error("mcp tool completed", completionAttrs...)
+			return result, out, err
+		}
+
+		logger.Info("mcp tool completed", completionAttrs...)
+		return result, out, nil
+	}
 }
 
 func setToolSchemas[In any, Out any](tool *mcp.Tool) error {

internal/mcpserver/server.go

@@ -1,6 +1,7 @@
 package mcpserver
 
 import (
+	"log/slog"
 	"net/http"
 	"time"
 
@@ -36,93 +37,93 @@ type ToolSet struct {
 	Skills        *tools.SkillsTool
 }
 
-func New(cfg config.MCPConfig, toolSet ToolSet) http.Handler {
+func New(cfg config.MCPConfig, logger *slog.Logger, toolSet ToolSet) http.Handler {
 	server := mcp.NewServer(&mcp.Implementation{
 		Name:    cfg.ServerName,
 		Version: cfg.Version,
 	}, nil)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "capture_thought",
 		Description: "Store a thought with generated embeddings and extracted metadata.",
 	}, toolSet.Capture.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "search_thoughts",
 		Description: "Search stored thoughts by semantic similarity.",
 	}, toolSet.Search.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_thoughts",
 		Description: "List recent thoughts with optional metadata filters.",
 	}, toolSet.List.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "thought_stats",
 		Description: "Get counts and top metadata buckets across stored thoughts.",
 	}, toolSet.Stats.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_thought",
 		Description: "Retrieve a full thought by id.",
 	}, toolSet.Get.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "update_thought",
 		Description: "Update thought content or merge metadata.",
 	}, toolSet.Update.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "delete_thought",
 		Description: "Hard-delete a thought by id.",
 	}, toolSet.Delete.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "archive_thought",
 		Description: "Archive a thought so it is hidden from default search and listing.",
 	}, toolSet.Archive.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "create_project",
 		Description: "Create a named project container for thoughts.",
 	}, toolSet.Projects.Create)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_projects",
 		Description: "List projects and their current thought counts.",
 	}, toolSet.Projects.List)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "set_active_project",
 		Description: "Set the active project for the current MCP session.",
 	}, toolSet.Projects.SetActive)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_active_project",
 		Description: "Return the active project for the current MCP session.",
 	}, toolSet.Projects.GetActive)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_project_context",
 		Description: "Get recent and semantic context for a project.",
 	}, toolSet.Context.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "recall_context",
 		Description: "Recall semantically relevant and recent context.",
 	}, toolSet.Recall.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "summarize_thoughts",
 		Description: "Summarize a filtered or searched set of thoughts.",
 	}, toolSet.Summarize.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "link_thoughts",
 		Description: "Create a typed relationship between two thoughts.",
 	}, toolSet.Links.Link)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "related_thoughts",
 		Description: "Retrieve explicit links and semantic neighbors for a thought.",
 	}, toolSet.Links.Related)
@@ -133,245 +134,245 @@ func New(cfg config.MCPConfig, toolSet ToolSet) http.Handler {
 		Description: "A stored file. Read a file's raw binary content by its id. Use load_file for metadata.",
 	}, toolSet.Files.ReadResource)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "save_file",
 		Description: "Store a base64-encoded file such as an image, document, or audio clip, optionally linking it to a thought.",
 	}, toolSet.Files.Save)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "load_file",
 		Description: "Load a previously stored file by id and return its metadata and base64 content.",
 	}, toolSet.Files.Load)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_files",
 		Description: "List stored files, optionally filtered by thought, project, or kind.",
 	}, toolSet.Files.List)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "backfill_embeddings",
 		Description: "Generate missing embeddings for stored thoughts using the active embedding model.",
 	}, toolSet.Backfill.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "reparse_thought_metadata",
 		Description: "Re-extract and normalize metadata for stored thoughts from their content.",
 	}, toolSet.Reparse.Handle)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "retry_failed_metadata",
 		Description: "Retry metadata extraction for thoughts still marked pending or failed.",
 	}, toolSet.RetryMetadata.Handle)
 
 	// Household Knowledge
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_household_item",
 		Description: "Store a household fact (paint color, appliance details, measurement, document, etc.).",
 	}, toolSet.Household.AddItem)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "search_household_items",
 		Description: "Search household items by name, category, or location.",
 	}, toolSet.Household.SearchItems)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_household_item",
 		Description: "Retrieve a household item by id.",
 	}, toolSet.Household.GetItem)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_vendor",
 		Description: "Add a service provider (plumber, electrician, landscaper, etc.).",
 	}, toolSet.Household.AddVendor)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_vendors",
 		Description: "List household service vendors, optionally filtered by service type.",
 	}, toolSet.Household.ListVendors)
 
 	// Home Maintenance
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_maintenance_task",
 		Description: "Create a recurring or one-time home maintenance task.",
 	}, toolSet.Maintenance.AddTask)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "log_maintenance",
 		Description: "Log completed maintenance work; automatically updates the task's next due date.",
 	}, toolSet.Maintenance.LogWork)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_upcoming_maintenance",
 		Description: "List maintenance tasks due within the next N days.",
 	}, toolSet.Maintenance.GetUpcoming)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "search_maintenance_history",
 		Description: "Search the maintenance log by task name, category, or date range.",
 	}, toolSet.Maintenance.SearchHistory)
 
 	// Family Calendar
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_family_member",
 		Description: "Add a family member to the household.",
 	}, toolSet.Calendar.AddMember)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_family_members",
 		Description: "List all family members.",
 	}, toolSet.Calendar.ListMembers)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_activity",
 		Description: "Schedule a one-time or recurring family activity.",
 	}, toolSet.Calendar.AddActivity)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_week_schedule",
 		Description: "Get all activities scheduled for a given week.",
 	}, toolSet.Calendar.GetWeekSchedule)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "search_activities",
 		Description: "Search activities by title, type, or family member.",
 	}, toolSet.Calendar.SearchActivities)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_important_date",
 		Description: "Track a birthday, anniversary, deadline, or other important date.",
 	}, toolSet.Calendar.AddImportantDate)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_upcoming_dates",
 		Description: "Get important dates coming up in the next N days.",
 	}, toolSet.Calendar.GetUpcomingDates)
 
 	// Meal Planning
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_recipe",
 		Description: "Save a recipe with ingredients and instructions.",
 	}, toolSet.Meals.AddRecipe)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "search_recipes",
 		Description: "Search recipes by name, cuisine, tags, or ingredient.",
 	}, toolSet.Meals.SearchRecipes)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "update_recipe",
 		Description: "Update an existing recipe.",
 	}, toolSet.Meals.UpdateRecipe)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "create_meal_plan",
 		Description: "Set the meal plan for a week; replaces any existing plan for that week.",
 	}, toolSet.Meals.CreateMealPlan)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_meal_plan",
 		Description: "Get the meal plan for a given week.",
 	}, toolSet.Meals.GetMealPlan)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "generate_shopping_list",
 		Description: "Auto-generate a shopping list from the meal plan for a given week.",
 	}, toolSet.Meals.GenerateShoppingList)
 
 	// Professional CRM
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_professional_contact",
 		Description: "Add a professional contact to the CRM.",
 	}, toolSet.CRM.AddContact)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "search_contacts",
 		Description: "Search professional contacts by name, company, title, notes, or tags.",
 	}, toolSet.CRM.SearchContacts)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "log_interaction",
 		Description: "Log an interaction with a professional contact.",
 	}, toolSet.CRM.LogInteraction)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_contact_history",
 		Description: "Get full history (interactions and opportunities) for a contact.",
 	}, toolSet.CRM.GetHistory)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "create_opportunity",
 		Description: "Create a deal, project, or opportunity linked to a contact.",
 	}, toolSet.CRM.CreateOpportunity)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "get_follow_ups_due",
 		Description: "List contacts with a follow-up date due within the next N days.",
 	}, toolSet.CRM.GetFollowUpsDue)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "link_thought_to_contact",
 		Description: "Append a stored thought to a contact's notes.",
 	}, toolSet.CRM.LinkThought)
 
 	// Agent Skills
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_skill",
 		Description: "Store a reusable agent skill (behavioural instruction or capability prompt).",
 	}, toolSet.Skills.AddSkill)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "remove_skill",
 		Description: "Delete an agent skill by id.",
 	}, toolSet.Skills.RemoveSkill)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_skills",
 		Description: "List all agent skills, optionally filtered by tag.",
 	}, toolSet.Skills.ListSkills)
 
 	// Agent Guardrails
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_guardrail",
 		Description: "Store a reusable agent guardrail (constraint or safety rule).",
 	}, toolSet.Skills.AddGuardrail)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "remove_guardrail",
 		Description: "Delete an agent guardrail by id.",
 	}, toolSet.Skills.RemoveGuardrail)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_guardrails",
 		Description: "List all agent guardrails, optionally filtered by tag or severity.",
 	}, toolSet.Skills.ListGuardrails)
 
 	// Project Skills & Guardrails
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_project_skill",
 		Description: "Link an agent skill to a project.",
 	}, toolSet.Skills.AddProjectSkill)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "remove_project_skill",
 		Description: "Unlink an agent skill from a project.",
 	}, toolSet.Skills.RemoveProjectSkill)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_project_skills",
 		Description: "List all skills linked to a project. Call this at the start of a project session to load existing agent behaviour instructions before generating new ones.",
 	}, toolSet.Skills.ListProjectSkills)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "add_project_guardrail",
 		Description: "Link an agent guardrail to a project.",
 	}, toolSet.Skills.AddProjectGuardrail)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "remove_project_guardrail",
 		Description: "Unlink an agent guardrail from a project.",
 	}, toolSet.Skills.RemoveProjectGuardrail)
 
-	addTool(server, &mcp.Tool{
+	addTool(server, logger, &mcp.Tool{
 		Name:        "list_project_guardrails",
 		Description: "List all guardrails linked to a project. Call this at the start of a project session to load existing agent constraints before generating new ones.",
 	}, toolSet.Skills.ListProjectGuardrails)