Make it so the debug logging is more useful

internal/execution/copilot.go

@@ -223,7 +223,7 @@ func (e *CopilotEngine) Execute(ctx context.Context, req *ExecutionRequest) (*Ex
 	e.usageCollectors[sessionID] = usageCollector
 	e.usageCollectorsMu.Unlock()
 
-	unsubscribe := session.On(utils.SessionToSlog)
+	unsubscribe := session.On(utils.NewSessionToSlog())
 	defer unsubscribe()
 
 	// Send prompt with updated API

internal/graders/prompt_grader.go

@@ -104,7 +104,7 @@ func (p *promptGrader) gradeIndependent(ctx context.Context, gradingContext *Con
 			return nil, fmt.Errorf("failed to start up copilot session for prompt grading: %w", err)
 		}
 
-		session.On(utils.SessionToSlog)
+		session.On(utils.NewSessionToSlog())
 
 		resp, err := session.SendAndWait(ctx, copilot.MessageOptions{
 			Prompt: p.args.Prompt,
@@ -380,7 +380,7 @@ func (p *promptGrader) runPairwiseOnce(
 		return nil, fmt.Errorf("failed to create session for pairwise grading: %w", err)
 	}
 
-	session.On(utils.SessionToSlog)
+	session.On(utils.NewSessionToSlog())
 
 	prompt := buildPairwisePrompt(p.args.Prompt, outputA, outputB, labelA, labelB)
 

internal/utils/logging.go

@@ -3,14 +3,47 @@ package utils
 import (
 	"context"
 	"log/slog"
+	"sync"
 
 	copilot "github.com/github/copilot-sdk/go"
 )
 
-// SessionToSlog tries to be a low-overhead method for dumping out any session events coming from
+// NewSessionToSlog creates a function compatible with [copilot.Session.On] that will
+// emit log entries, to slog, when the log level is set to slog.LevelDebug.
+func NewSessionToSlog() copilot.SessionEventHandler {
+	if !slog.Default().Enabled(context.Background(), slog.LevelDebug) {
+		return func(copilot.SessionEvent) {}
+	}
+
+	intentCalls := sync.Map{}
+
+	return func(event copilot.SessionEvent) {
+		switch event.Type {
+		case copilot.PendingMessagesModified, copilot.HookEnd, copilot.HookStart:
+			// we just drop these from logging, they're mostly noise, or have other events (like tool calls)
+			// that are more informative.
+			return
+		case copilot.ToolExecutionStart:
+			if event.Data.ToolName != nil && *event.Data.ToolName == "report_intent" && event.Data.ToolCallID != nil {
+				// store this off, we'll ignore the complete event when it comes in as well.
+				intentCalls.Store(*event.Data.ToolCallID, true)
+				return
+			}
+		case copilot.ToolExecutionComplete:
+			if event.Data.ToolCallID != nil &&
+				intentCalls.CompareAndDelete(*event.Data.ToolCallID, true) {
+				return
+			}
+		}
+
+		sessionToSlog(event)
+	}
+}
+
+// sessionToSlog tries to be a low-overhead method for dumping out any session events coming from
 // the copilot client to slog. It's safe to add this to your copilot session instances, in
 // their [copilot.Session.On] handler.
-func SessionToSlog(event copilot.SessionEvent) {
+func sessionToSlog(event copilot.SessionEvent) {
 	if !slog.Default().Enabled(context.Background(), slog.LevelDebug) {
 		return
 	}
@@ -19,21 +52,84 @@ func SessionToSlog(event copilot.SessionEvent) {
 		"type", event.Type,
 	}
 
-	attrs = addIf(attrs, "content", event.Data.Content)
-	attrs = addIf(attrs, "deltaContent", event.Data.DeltaContent)
-	attrs = addIf(attrs, "toolName", event.Data.ToolName)
-	attrs = addIf(attrs, "toolResult", event.Data.Result)
-	attrs = addIf(attrs, "toolCallID", event.Data.ToolCallID)
-	attrs = addIf(attrs, "reasoningText", event.Data.ReasoningText)
+	attrs = appendIf(attrs, "reasoningText", event.Data.ReasoningText)
+
+	// session starts
+	attrs = appendIf(attrs, "selectedModel", event.Data.SelectedModel)
+	attrs = appendIf(attrs, "producer", event.Data.Producer)
+	attrs = appendIf(attrs, "sessionID", event.Data.SessionID)
+
+	if event.Data.Context != nil {
+		cc := event.Data.Context.ContextClass
+		if cc != nil {
+			var ccAttrs []any
+
+			ccAttrs = appendIf(ccAttrs, "branch", cc.Branch)
+			ccAttrs = append(ccAttrs, "cwd", cc.Cwd)
+			ccAttrs = append(ccAttrs, "gitRoot", cc.GitRoot)
+			ccAttrs = append(ccAttrs, "repository", cc.Repository)
+
+			attrs = append(attrs, slog.Group("context", ccAttrs...))
+		}
+	}
+
+	// assistant.turn_start
+	attrs = appendIf(attrs, "turnID", event.Data.TurnID)
+
+	// tool calls
+	attrs = appendIf(attrs, "content", event.Data.Content)
+	attrs = appendIf(attrs, "deltaContent", event.Data.DeltaContent)
+	attrs = appendIf(attrs, "toolName", event.Data.ToolName)
+	attrs = appendIf(attrs, "toolCallID", event.Data.ToolCallID)
+
+	if event.Data.Result != nil {
+		tr := event.Data.Result
+
+		var toolResultArgs []any
+
+		toolResultArgs = appendIf(toolResultArgs, "content", tr.Content)
+		toolResultArgs = appendIf(toolResultArgs, "detailedContent", tr.DetailedContent)
+
+		attrs = append(attrs, slog.Group("toolResult", toolResultArgs...))
+	}
+
+	// tool call arguments
+	attrs = appendMapOfStringAnyIf(attrs, event.Data.Arguments, "arguments")
+
+	// hooks
+	attrs = appendIf(attrs, "hookType", event.Data.HookType)
+	attrs = appendMapOfStringAnyIf(attrs, event.Data.Input, "input")
 
 	slog.Debug("Event received", attrs...)
 }
 
-func addIf[T any](attrs []any, name string, v *T) []any {
+// appendIf appends the attribute if v is not nil
+func appendIf[T any](attrs []any, name string, v *T) []any {
 	if v != nil {
 		attrs = append(attrs, name)
 		attrs = append(attrs, *v)
 	}
 
 	return attrs
 }
+
+// appendMapOfStringAnyIf appends the contents of the map, as a slog.Group if the
+// map is both a map[string]any, and not empty.
+// NOTE: the keys are not sorted as they are added to the slog.Group.
+func appendMapOfStringAnyIf(attrs []any, mapOfStringAny any, fieldName string) []any {
+	if asMap, ok := mapOfStringAny.(map[string]any); ok {
+		if len(asMap) == 0 {
+			return attrs
+		}
+
+		var args []any
+
+		for k, v := range asMap {
+			args = append(args, k, v)
+		}
+
+		attrs = append(attrs, slog.Group(fieldName, args...))
+	}
+
+	return attrs
+}

internal/utils/logging_test.go

@@ -3,7 +3,12 @@ package utils
 import (
 	"bytes"
 	"encoding/json"
+	"errors"
+	"io"
 	"log/slog"
+	"os"
+	"path/filepath"
+	"sort"
 	"testing"
 
 	copilot "github.com/github/copilot-sdk/go"
@@ -21,7 +26,7 @@ func TestSessionToSlogDebugDisabled(t *testing.T) {
 	logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}))
 	slog.SetDefault(logger)
 
-	SessionToSlog(copilot.SessionEvent{Type: copilot.SessionEventType("message")})
+	NewSessionToSlog()(copilot.SessionEvent{Type: copilot.SessionEventType("message")})
 	assert.Equal(t, 0, buf.Len())
 }
 
@@ -41,7 +46,7 @@ func TestSessionToSlogDebugEnabled(t *testing.T) {
 	toolCallID := "call-1"
 	reasoningText := "reasoning"
 
-	SessionToSlog(copilot.SessionEvent{
+	NewSessionToSlog()(copilot.SessionEvent{
 		Type: copilot.SessionEventType("message"),
 		Data: copilot.Data{
 			Content:       &content,
@@ -63,13 +68,116 @@ func TestSessionToSlogDebugEnabled(t *testing.T) {
 	assert.Equal(t, reasoningText, logEntry["reasoningText"])
 }
 
-func TestAddIf(t *testing.T) {
+func TestAppendIf(t *testing.T) {
 	attrs := []any{"existing", "value"}
 
-	result := addIf(attrs, "missing", (*int)(nil))
+	result := appendIf(attrs, "missing", (*int)(nil))
 	assert.Equal(t, attrs, result)
 
 	v := 7
-	result = addIf(attrs, "number", &v)
+	result = appendIf(attrs, "number", &v)
 	assert.Equal(t, []any{"existing", "value", "number", 7}, result)
 }
+
+func TestSlogPrinting(t *testing.T) {
+	old := slog.Default()
+	t.Cleanup(func() {
+		slog.SetDefault(old)
+	})
+
+	actualBuffer := &bytes.Buffer{}
+	logger := slog.New(slog.NewJSONHandler(actualBuffer, &slog.HandlerOptions{Level: slog.LevelDebug}))
+	slog.SetDefault(logger)
+
+	slogger := NewSessionToSlog()
+
+	for e, err := range NewCopilotLogIterator(filepath.Join("testdata", "sample_events.jsonl")) {
+		require.NoError(t, err)
+		slogger(e)
+	}
+
+	expectedBytes, err := os.ReadFile(filepath.Join("testdata", "sample_events_slog.jsonl"))
+	require.NoError(t, err)
+
+	actual := decodeAll(t, actualBuffer.Bytes())
+	expected := decodeAll(t, expectedBytes)
+
+	require.Equal(t, len(expected), len(actual))
+
+	for i := range expected {
+		delete(expected[i], "time")
+		delete(actual[i], "time")
+
+		require.Equalf(t, expected[i], actual[i], "[%d]", i)
+	}
+}
+
+func TestSlogAppendMapOfStringAnyIf(t *testing.T) {
+	t.Run("all_empty", func(t *testing.T) {
+		values := []any{
+			nil,
+			map[string]any{},
+			map[string]bool{},
+			"really, I'm a map",
+		}
+
+		for _, v := range values {
+			var attrs []any
+
+			attrs = appendMapOfStringAnyIf(attrs, v, "myfield")
+			require.Empty(t, attrs)
+		}
+	})
+
+	t.Run("normal", func(t *testing.T) {
+		var attrs []any
+
+		attrs = appendMapOfStringAnyIf(attrs, map[string]any{
+			"astring": "world",
+			"abool":   true,
+		}, "mygroup")
+		require.NotEmpty(t, attrs)
+
+		g, ok := attrs[0].(slog.Attr)
+		require.True(t, ok)
+		require.Equal(t, "mygroup", g.Key)
+
+		actual := g.Value.Group()
+
+		sort.Slice(actual, func(i, j int) bool {
+			return actual[i].Key < actual[j].Key
+		})
+
+		require.Equal(t, []slog.Attr{
+			{
+				Key:   "abool",
+				Value: slog.BoolValue(true),
+			},
+			{
+				Key:   "astring",
+				Value: slog.StringValue("world"),
+			},
+		}, actual)
+	})
+}
+
+func decodeAll(t *testing.T, buff []byte) []map[string]any {
+	decoder := json.NewDecoder(bytes.NewReader(buff))
+
+	var all []map[string]any
+
+	for {
+		var ll map[string]any
+
+		err := decoder.Decode(&ll)
+
+		if errors.Is(err, io.EOF) {
+			break
+		}
+
+		require.NoError(t, err)
+		all = append(all, ll)
+	}
+
+	return all
+}

internal/utils/testdata/sample_events.jsonl

@@ -0,0 +1,13 @@
+{"type":"session.start","data":{"sessionId":"1038aadf-85ca-450d-b446-9feb986974e4","version":1,"producer":"copilot-agent","copilotVersion":"1.0.6","startTime":"2026-03-18T01:08:44.578Z","selectedModel":"gpt-5.1-codex-mini","context":{"cwd":"<cwd was here>"},"alreadyInUse":false},"id":"816c55c9-2aa7-4787-880b-3c3ee634181e","timestamp":"2026-03-18T01:08:44.600Z","parentId":null}
+{"type":"user.message","data":{"content":"Use azure-typespec-author to add a new preview version `2025-05-04-preview` to my service widget resource manager.","transformedContent":"<current_datetime>2026-03-18T01:08:45.999Z</current_datetime>\n\nUse azure-typespec-author to add a new preview version `2025-05-04-preview` to my service widget resource manager.\n\n<reminder>\n<sql_tables>No tables currently exist. Default tables (todos, todo_deps) will be created automatically when you first use the SQL tool.</sql_tables>\n</reminder>","attachments":[],"interactionId":"2e7dfe50-e11f-457d-b498-70a52be2aaf6"},"id":"d0412073-0974-4ed0-aa83-66b8c1d137bf","timestamp":"2026-03-18T01:08:45.999Z","parentId":"7006d08b-cd02-4da8-ac86-20e1632f5f0a"}
+{"type":"assistant.turn_start","data":{"turnId":"0","interactionId":"2e7dfe50-e11f-457d-b498-70a52be2aaf6"},"id":"32fe1400-dd39-4dbd-8c4f-ee1e93808d4b","timestamp":"2026-03-18T01:08:46.503Z","parentId":"d0412073-0974-4ed0-aa83-66b8c1d137bf"}
+{"type":"assistant.message","data":{"messageId":"6efd6208-a8b9-4ee2-bfcd-d389ef03f393","content":"","toolRequests":[{"toolCallId":"call_5HhC0BkZLOfzzcFCxXoEIxNr","name":"report_intent","arguments":{"intent":"Scanning files"},"type":"function"},{"toolCallId":"call_TEHemjFvEHVSAMo4dXKx2ySu","name":"glob","arguments":{"pattern":"**/*.tsp"},"type":"function","intentionSummary":"**/*.tsp"}],"interactionId":"2e7dfe50-e11f-457d-b498-70a52be2aaf6","reasoningOpaque":"<redacted>","reasoningText":"I’m figuring out how to start by combining a report_intent call with a file search using glob to find TypeSpec (.tsp) files. Since this is a complex task needing multiple steps, I’ll begin with a plan and gather the repo structure before diving into changes. Using multi_tool_use.parallel to do report_intent and glob together sounds like the best first move.","encryptedContent":"<redacted>","outputTokens":411},"id":"1517d2a2-684a-4d94-817b-85de4e5eacde","timestamp":"2026-03-18T01:08:52.636Z","parentId":"bd86049c-0157-4baf-b380-6d232ef391c3"}
+{"type":"tool.execution_start","data":{"toolCallId":"call_5HhC0BkZLOfzzcFCxXoEIxNr","toolName":"report_intent","arguments":{"intent":"Scanning files"}},"id":"dafce2d0-8ab8-40f7-82d9-03611bf82604","timestamp":"2026-03-18T01:08:52.637Z","parentId":"78d90291-389e-4b9c-8056-dd227015991d"}
+{"type":"tool.execution_start","data":{"toolCallId":"call_TEHemjFvEHVSAMo4dXKx2ySu","toolName":"glob","arguments":{"pattern":"**/*.tsp"}},"id":"7faf62b6-4bdc-41ac-be4c-495dacef9242","timestamp":"2026-03-18T01:08:52.637Z","parentId":"dafce2d0-8ab8-40f7-82d9-03611bf82604"}
+{"type":"hook.start","data":{"hookInvocationId":"3d6a4ef7-4acf-49a5-90d6-60bb8513ba4b","hookType":"postToolUse","input":{"sessionId":"1038aadf-85ca-450d-b446-9feb986974e4","timestamp":1773796132638,"cwd":"<cwd redacted>","toolName":"report_intent","toolArgs":{"intent":"Scanning files"},"toolResult":{"textResultForLlm":"Intent logged","resultType":"success","sessionLog":"Scanning files","toolTelemetry":{}}}},"id":"aaa3b037-2e98-4468-abe6-b8bb3b8f7706","timestamp":"2026-03-18T01:08:52.638Z","parentId":"7faf62b6-4bdc-41ac-be4c-495dacef9242"}
+{"type":"hook.end","data":{"hookInvocationId":"3d6a4ef7-4acf-49a5-90d6-60bb8513ba4b","hookType":"postToolUse","success":true},"id":"d9932ad8-f203-4e5f-ad52-de24ef015dc8","timestamp":"2026-03-18T01:08:52.639Z","parentId":"aaa3b037-2e98-4468-abe6-b8bb3b8f7706"}
+{"type":"tool.execution_complete","data":{"toolCallId":"call_5HhC0BkZLOfzzcFCxXoEIxNr","model":"gpt-5.1-codex-mini","interactionId":"2e7dfe50-e11f-457d-b498-70a52be2aaf6","success":true,"result":{"content":"Intent logged","detailedContent":"Scanning files"},"toolTelemetry":{}},"id":"ce0f4830-5c1b-4a31-b0b1-d4e044a5d32b","timestamp":"2026-03-18T01:08:52.639Z","parentId":"d9932ad8-f203-4e5f-ad52-de24ef015dc8"}
+{"type":"hook.start","data":{"hookInvocationId":"065e984f-0689-43db-b036-d03bad8fba05","hookType":"postToolUse","input":{"sessionId":"1038aadf-85ca-450d-b446-9feb986974e4","timestamp":1773796137683,"cwd":"<cwd redacted>","toolName":"glob","toolArgs":{"pattern":"**/*.tsp"},"toolResult":{"textResultForLlm":"No files matched the pattern.","resultType":"success","toolTelemetry":{"properties":{"pattern":"**/*.tsp","path":".","files_found":"false"},"metrics":{"file_count":0}}}}},"id":"c59a6fa5-147d-425c-928e-460fa4712510","timestamp":"2026-03-18T01:08:57.683Z","parentId":"19f4fa1a-3bda-4b93-9992-4f11fbc063b0"}
+{"type":"hook.end","data":{"hookInvocationId":"065e984f-0689-43db-b036-d03bad8fba05","hookType":"postToolUse","success":true},"id":"a21f71fe-2ea0-403a-8e4d-3429edb3ec64","timestamp":"2026-03-18T01:08:57.683Z","parentId":"c59a6fa5-147d-425c-928e-460fa4712510"}
+{"type":"tool.execution_complete","data":{"toolCallId":"call_TEHemjFvEHVSAMo4dXKx2ySu","model":"gpt-5.1-codex-mini","interactionId":"2e7dfe50-e11f-457d-b498-70a52be2aaf6","success":true,"result":{"content":"No files matched the pattern.","detailedContent":"No files matched the pattern."},"toolTelemetry":{"properties":{"pattern":"**/*.tsp","path":".","files_found":"false"},"metrics":{"file_count":0}}},"id":"050733ba-9976-44a9-8a53-7edc77cda998","timestamp":"2026-03-18T01:08:57.683Z","parentId":"a21f71fe-2ea0-403a-8e4d-3429edb3ec64"}
+{"type":"assistant.turn_end","data":{"turnId":"0"},"id":"7c6b98e7-8bc2-445a-b336-d81056a8c4c5","timestamp":"2026-03-18T01:08:57.684Z","parentId":"050733ba-9976-44a9-8a53-7edc77cda998"}

internal/utils/testdata/sample_events_slog.jsonl

@@ -0,0 +1,7 @@
+{"time":"2026-03-19T23:22:23.679038002Z","level":"DEBUG","msg":"Event received","type":"session.start","selectedModel":"gpt-5.1-codex-mini","producer":"copilot-agent","sessionID":"1038aadf-85ca-450d-b446-9feb986974e4","context":{"cwd":"<cwd was here>","gitRoot":null,"repository":null}}
+{"time":"2026-03-19T23:22:23.679131528Z","level":"DEBUG","msg":"Event received","type":"user.message","content":"Use azure-typespec-author to add a new preview version `2025-05-04-preview` to my service widget resource manager."}
+{"time":"2026-03-19T23:22:23.679141631Z","level":"DEBUG","msg":"Event received","type":"assistant.turn_start","turnID":"0"}
+{"time":"2026-03-19T23:22:23.679169239Z","level":"DEBUG","msg":"Event received","type":"assistant.message","reasoningText":"I’m figuring out how to start by combining a report_intent call with a file search using glob to find TypeSpec (.tsp) files. Since this is a complex task needing multiple steps, I’ll begin with a plan and gather the repo structure before diving into changes. Using multi_tool_use.parallel to do report_intent and glob together sounds like the best first move.","content":""}
+{"time":"2026-03-19T23:22:23.679202648Z","level":"DEBUG","msg":"Event received","type":"tool.execution_start","toolName":"glob","toolCallID":"call_TEHemjFvEHVSAMo4dXKx2ySu","arguments":{"pattern":"**/*.tsp"}}
+{"time":"2026-03-19T23:22:23.679291073Z","level":"DEBUG","msg":"Event received","type":"tool.execution_complete","toolCallID":"call_TEHemjFvEHVSAMo4dXKx2ySu","toolResult":{"content":"No files matched the pattern.","detailedContent":"No files matched the pattern."}}
+{"time":"2026-03-19T23:22:23.679300276Z","level":"DEBUG","msg":"Event received","type":"assistant.turn_end","turnID":"0"}