From 5e55f45223558d797df0187de5144af98cd08ba5 Mon Sep 17 00:00:00 2001 From: Richard Park Date: Thu, 19 Mar 2026 23:12:17 +0000 Subject: [PATCH 1/3] Make it so the debug logging is more useful. - Omits some entries, like report_intent, that just add noise to the debugging process. Had to have some state to do this since only the tool.execution_start indicates that it's a report_intent event. - Dive into the arguments, input and context parameters, which usually contain important information. - Output the selected model, and the producer (ie: the agent) --- internal/execution/copilot.go | 2 +- internal/graders/prompt_grader.go | 4 +- internal/utils/logging.go | 117 +++++++++++++++-- internal/utils/logging_test.go | 118 +++++++++++++++++- internal/utils/testdata/sample_events.jsonl | 13 ++ .../utils/testdata/sample_events_slog.jsonl | 7 ++ 6 files changed, 244 insertions(+), 17 deletions(-) create mode 100644 internal/utils/testdata/sample_events.jsonl create mode 100644 internal/utils/testdata/sample_events_slog.jsonl diff --git a/internal/execution/copilot.go b/internal/execution/copilot.go index 18f7e26b..837fbc6e 100644 --- a/internal/execution/copilot.go +++ b/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 diff --git a/internal/graders/prompt_grader.go b/internal/graders/prompt_grader.go index 7308ac39..53742092 100644 --- a/internal/graders/prompt_grader.go +++ b/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) diff --git a/internal/utils/logging.go b/internal/utils/logging.go index 1f51d4db..249d7622 100644 --- a/internal/utils/logging.go +++ b/internal/utils/logging.go @@ -7,10 +7,45 @@ import ( 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 := map[string]bool{} + + return func(event copilot.SessionEvent) { + if event.Type == copilot.PendingMessagesModified { + return + } + + if event.Data.ToolName != nil && *event.Data.ToolName == "report_intent" { + if event.Data.ToolCallID != nil { + intentCalls[*event.Data.ToolCallID] = true + } + + return + } + + if event.Data.ToolCallID != nil && intentCalls[*event.Data.ToolCallID] { + delete(intentCalls, *event.Data.ToolCallID) + return + } + + if event.Type == copilot.HookEnd || event.Type == copilot.HookStart { + 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,17 +54,59 @@ 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) @@ -37,3 +114,25 @@ func addIf[T any](attrs []any, name string, v *T) []any { 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 + + // NOTE: keys are unsorted here + for k, v := range asMap { + args = append(args, k, v) + } + + attrs = append(attrs, slog.Group(fieldName, args...)) + } + + return attrs +} diff --git a/internal/utils/logging_test.go b/internal/utils/logging_test.go index ecf40de0..58e58429 100644 --- a/internal/utils/logging_test.go +++ b/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 +} diff --git a/internal/utils/testdata/sample_events.jsonl b/internal/utils/testdata/sample_events.jsonl new file mode 100644 index 00000000..0f7022aa --- /dev/null +++ b/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":""},"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":"2026-03-18T01:08:45.999Z\n\nUse azure-typespec-author to add a new preview version `2025-05-04-preview` to my service widget resource manager.\n\n\nNo tables currently exist. Default tables (todos, todo_deps) will be created automatically when you first use the SQL tool.\n","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":"","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":"","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":"","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":"","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"} diff --git a/internal/utils/testdata/sample_events_slog.jsonl b/internal/utils/testdata/sample_events_slog.jsonl new file mode 100644 index 00000000..a781913b --- /dev/null +++ b/internal/utils/testdata/sample_events_slog.jsonl @@ -0,0 +1,7 @@ +{"time":"2026-03-19T23:22:23.679038002Z","level":"INFO","msg":"Event received","type":"session.start","selectedModel":"gpt-5.1-codex-mini","producer":"copilot-agent","sessionID":"1038aadf-85ca-450d-b446-9feb986974e4","context":{"cwd":"","gitRoot":null,"repository":null}} +{"time":"2026-03-19T23:22:23.679131528Z","level":"INFO","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":"INFO","msg":"Event received","type":"assistant.turn_start","turnID":"0"} +{"time":"2026-03-19T23:22:23.679169239Z","level":"INFO","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":"INFO","msg":"Event received","type":"tool.execution_start","toolName":"glob","toolCallID":"call_TEHemjFvEHVSAMo4dXKx2ySu","arguments":{"pattern":"**/*.tsp"}} +{"time":"2026-03-19T23:22:23.679291073Z","level":"INFO","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":"INFO","msg":"Event received","type":"assistant.turn_end","turnID":"0"} From a1b57eae7df9556a22fb4ff3543f25367b150987 Mon Sep 17 00:00:00 2001 From: Richard Park Date: Fri, 20 Mar 2026 00:13:28 +0000 Subject: [PATCH 2/3] Whoops, they're debug now --- internal/utils/testdata/sample_events_slog.jsonl | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/internal/utils/testdata/sample_events_slog.jsonl b/internal/utils/testdata/sample_events_slog.jsonl index a781913b..2fd0d92a 100644 --- a/internal/utils/testdata/sample_events_slog.jsonl +++ b/internal/utils/testdata/sample_events_slog.jsonl @@ -1,7 +1,7 @@ -{"time":"2026-03-19T23:22:23.679038002Z","level":"INFO","msg":"Event received","type":"session.start","selectedModel":"gpt-5.1-codex-mini","producer":"copilot-agent","sessionID":"1038aadf-85ca-450d-b446-9feb986974e4","context":{"cwd":"","gitRoot":null,"repository":null}} -{"time":"2026-03-19T23:22:23.679131528Z","level":"INFO","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":"INFO","msg":"Event received","type":"assistant.turn_start","turnID":"0"} -{"time":"2026-03-19T23:22:23.679169239Z","level":"INFO","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":"INFO","msg":"Event received","type":"tool.execution_start","toolName":"glob","toolCallID":"call_TEHemjFvEHVSAMo4dXKx2ySu","arguments":{"pattern":"**/*.tsp"}} -{"time":"2026-03-19T23:22:23.679291073Z","level":"INFO","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":"INFO","msg":"Event received","type":"assistant.turn_end","turnID":"0"} +{"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":"","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"} From f8603fd86c5c4b7713a8da174e8a4d555ca64dc7 Mon Sep 17 00:00:00 2001 From: Richard Park Date: Sat, 21 Mar 2026 01:11:20 +0000 Subject: [PATCH 3/3] Addressing all the copilot feedback, and restructuring the code that does the event testing a bit to make it more readable. --- internal/utils/logging.go | 35 ++++++++++++++++------------------- 1 file changed, 16 insertions(+), 19 deletions(-) diff --git a/internal/utils/logging.go b/internal/utils/logging.go index 249d7622..cace231f 100644 --- a/internal/utils/logging.go +++ b/internal/utils/logging.go @@ -3,6 +3,7 @@ package utils import ( "context" "log/slog" + "sync" copilot "github.com/github/copilot-sdk/go" ) @@ -14,28 +15,25 @@ func NewSessionToSlog() copilot.SessionEventHandler { return func(copilot.SessionEvent) {} } - intentCalls := map[string]bool{} + intentCalls := sync.Map{} return func(event copilot.SessionEvent) { - if event.Type == copilot.PendingMessagesModified { + 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 - } - - if event.Data.ToolName != nil && *event.Data.ToolName == "report_intent" { - if event.Data.ToolCallID != nil { - intentCalls[*event.Data.ToolCallID] = true + 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 } - - return - } - - if event.Data.ToolCallID != nil && intentCalls[*event.Data.ToolCallID] { - delete(intentCalls, *event.Data.ToolCallID) - return - } - - if event.Type == copilot.HookEnd || event.Type == copilot.HookStart { - return } sessionToSlog(event) @@ -126,7 +124,6 @@ func appendMapOfStringAnyIf(attrs []any, mapOfStringAny any, fieldName string) [ var args []any - // NOTE: keys are unsorted here for k, v := range asMap { args = append(args, k, v) }