diff --git a/.github/workflows/daily-observability-report.lock.yml b/.github/workflows/daily-observability-report.lock.yml index 9df86022327..fc54874a897 100644 --- a/.github/workflows/daily-observability-report.lock.yml +++ b/.github/workflows/daily-observability-report.lock.yml @@ -1,4 +1,4 @@ -# gh-aw-metadata: {"schema_version":"v4","frontmatter_hash":"b49fe233da16a14f386e348484b37d23c0e7bf7692e2a1c8472be5efe71d54fa","body_hash":"2a5483de51c2aa4f8744ad69a6653242c5d155f9afac38b7c21b91647d9daf9e","strict":true,"agent_id":"codex","agent_model":"gpt-5.4","engine_versions":{"codex":"0.147.0"}} +# gh-aw-metadata: {"schema_version":"v4","frontmatter_hash":"b49fe233da16a14f386e348484b37d23c0e7bf7692e2a1c8472be5efe71d54fa","body_hash":"11b1298b5c43eecf682a9be05320dd709fcd13d451c0893995e1fe4fd4c7e328","strict":true,"agent_id":"codex","agent_model":"gpt-5.4","engine_versions":{"codex":"0.147.0"}} # gh-aw-manifest: {"version":1,"secrets":["CODEX_API_KEY","COPILOT_GITHUB_TOKEN","GH_AW_GITHUB_MCP_SERVER_TOKEN","GH_AW_GITHUB_TOKEN","GH_AW_OTEL_GRAFANA_AUTHORIZATION","GH_AW_OTEL_GRAFANA_ENDPOINT","GH_AW_OTEL_SENTRY_AUTHORIZATION","GH_AW_OTEL_SENTRY_ENDPOINT","GITHUB_TOKEN","OPENAI_API_KEY"],"actions":[{"repo":"actions/cache/restore","sha":"55cc8345863c7cc4c66a329aec7e433d2d1c52a9","version":"v6.1.0"},{"repo":"actions/cache/save","sha":"55cc8345863c7cc4c66a329aec7e433d2d1c52a9","version":"v6.1.0"},{"repo":"actions/checkout","sha":"3d3c42e5aac5ba805825da76410c181273ba90b1","version":"v7.0.1"},{"repo":"actions/download-artifact","sha":"3e5f45b2cfb9172054b4087a40e8e0b5a5461e7c","version":"v8.0.1"},{"repo":"actions/github-script","sha":"3a2844b7e9c422d3c10d287c895573f7108da1b3","version":"v9.0.0"},{"repo":"actions/setup-go","sha":"b7ad1dad31e06c5925ef5d2fc7ad053ef454303e","version":"v7.0.0"},{"repo":"actions/setup-node","sha":"820762786026740c76f36085b0efc47a31fe5020","version":"v7.0.0"},{"repo":"actions/upload-artifact","sha":"043fb46d1a93c77aae656e7c1c64a875d1fc6a0a","version":"v7.0.1"},{"repo":"docker/build-push-action","sha":"53b7df96c91f9c12dcc8a07bcb9ccacbed38856a","version":"v7.3.0"},{"repo":"docker/setup-buildx-action","sha":"bb05f3f5519dd87d3ba754cc423b652a5edd6d2c","version":"v4.2.0"}],"containers":[{"image":"ghcr.io/github/gh-aw-firewall/agent:0.28.1","digest":"sha256:5e3f6ee27eeae07195838b97ac4aa2f8aea42a7c55f1c0d3e17d8e88e294ad0d","pinned_image":"ghcr.io/github/gh-aw-firewall/agent:0.28.1@sha256:5e3f6ee27eeae07195838b97ac4aa2f8aea42a7c55f1c0d3e17d8e88e294ad0d"},{"image":"ghcr.io/github/gh-aw-firewall/api-proxy:0.28.1","digest":"sha256:288e7d2a12d5b430500d739f9c16e20bb1ed51b91f986f3f3eccde189f489f5c","pinned_image":"ghcr.io/github/gh-aw-firewall/api-proxy:0.28.1@sha256:288e7d2a12d5b430500d739f9c16e20bb1ed51b91f986f3f3eccde189f489f5c"},{"image":"ghcr.io/github/gh-aw-firewall/cli-proxy:0.28.1","digest":"sha256:f931e5e1e13f765605d03ef9511fc755d779a51b76581ea14586e9871506a610","pinned_image":"ghcr.io/github/gh-aw-firewall/cli-proxy:0.28.1@sha256:f931e5e1e13f765605d03ef9511fc755d779a51b76581ea14586e9871506a610"},{"image":"ghcr.io/github/gh-aw-firewall/squid:0.28.1","digest":"sha256:9d428af47899bf18ef2d5618075777d76ef344c91e76c1f44ec1aaa0ee347e5f","pinned_image":"ghcr.io/github/gh-aw-firewall/squid:0.28.1@sha256:9d428af47899bf18ef2d5618075777d76ef344c91e76c1f44ec1aaa0ee347e5f"},{"image":"ghcr.io/github/gh-aw-mcpg:v0.4.9","digest":"sha256:e5a1569aeaf41820fa7bdee3e94468cae448133cdbf00119ad24f5b74db1ab9f","pinned_image":"ghcr.io/github/gh-aw-mcpg:v0.4.9@sha256:e5a1569aeaf41820fa7bdee3e94468cae448133cdbf00119ad24f5b74db1ab9f"},{"image":"ghcr.io/github/gh-aw-node","digest":"sha256:0d9f1fb5fd6610c0ac1f5194a38e45a8a1e81f8a390d5142d8e4e6f26a4b3196","pinned_image":"ghcr.io/github/gh-aw-node@sha256:0d9f1fb5fd6610c0ac1f5194a38e45a8a1e81f8a390d5142d8e4e6f26a4b3196"},{"image":"ghcr.io/github/github-mcp-server:v1.9.0","digest":"sha256:881b53d6f75f69bdbc1b5b10fc2f1361717c19054143b3a8529fb5c32061a50e","pinned_image":"ghcr.io/github/github-mcp-server:v1.9.0@sha256:881b53d6f75f69bdbc1b5b10fc2f1361717c19054143b3a8529fb5c32061a50e"}]} # This file was automatically generated by gh-aw. DO NOT EDIT. To debug this workflow, load the skill at https://github.com/github/gh-aw/blob/main/debug.md # diff --git a/.github/workflows/daily-observability-report.md b/.github/workflows/daily-observability-report.md index 22652d3ff3b..50d5b1fb308 100644 --- a/.github/workflows/daily-observability-report.md +++ b/.github/workflows/daily-observability-report.md @@ -210,7 +210,12 @@ For each run that uses MCP servers, check in this order: - Do entries contain required fields: - `timestamp`: When the message was sent/received - `direction`: "IN" (from server) or "OUT" (to server) - - `type`: "REQUEST" or "RESPONSE" + - `event` or `type`: Message kind. Real-world telemetry (schema `rpc-message/v2`) uses a + top-level `event` field with values `rpc_request` / `rpc_response` (and `difc_filtered` + for blocked events); a top-level `_schema` field (e.g. `"rpc-message/v2"`) marks this + format. Older/synthetic files may instead use a top-level `type` field directly with + values `REQUEST` / `RESPONSE` / `DIFC_FILTERED`. **Do not flag a run as unhealthy solely + because entries lack a top-level `type` field** — check for `event` first. - `server_id`: MCP server identifier - `payload`: JSON-RPC payload with `method`, `params`, `result`, or `error` - Tool call count derived from outgoing `tools/call` requests diff --git a/actions/setup/js/parse_mcp_gateway_log.cjs b/actions/setup/js/parse_mcp_gateway_log.cjs index 1aa9abfb3b4..96237c677fe 100644 --- a/actions/setup/js/parse_mcp_gateway_log.cjs +++ b/actions/setup/js/parse_mcp_gateway_log.cjs @@ -24,7 +24,26 @@ const TOKEN_USAGE_PATH = "/tmp/gh-aw/sandbox/firewall/logs/api-proxy-logs/token- const MAX_RPC_SUMMARY_DETAILS_LENGTH = 120; const MAX_RPC_SUMMARY_GENERIC_LENGTH = 160; const MAX_RPC_MESSAGE_LABEL_LENGTH = 80; -const TOP_LEVEL_RPC_IGNORED_KEYS = new Set(["timestamp", "direction", "type", "server_id", "payload"]); +const TOP_LEVEL_RPC_IGNORED_KEYS = new Set(["timestamp", "direction", "type", "event", "_schema", "server_id", "payload"]); +// Maps the "event" field values used by the schema "rpc-message/v2" format (written by +// real Copilot CLI MCP gateway telemetry) to the legacy "type" values ("REQUEST", +// "RESPONSE", "DIFC_FILTERED") this file was originally written against. Real-world +// rpc-messages.jsonl files do not populate a top-level "type" field at all; they use +// "event" instead (e.g. "rpc_request"/"rpc_response"). +const RPC_EVENT_TO_TYPE = { rpc_request: "REQUEST", rpc_response: "RESPONSE", difc_filtered: "DIFC_FILTERED" }; + +/** + * Returns the normalized rpc-messages.jsonl entry type ("REQUEST", "RESPONSE", or + * "DIFC_FILTERED"), accepting either the legacy top-level "type" field or the + * "event" field used by schema "rpc-message/v2". + * @param {Object} entry + * @returns {string} + */ +function getRpcMessageType(entry) { + if (typeof entry?.type === "string" && entry.type) return entry.type; + if (typeof entry?.event === "string") return RPC_EVENT_TO_TYPE[entry.event] || entry.event; + return ""; +} const AI_CREDITS_RATE_LIMIT_PATTERNS = [ /ai[\s_-]*credits?.*(?:rate[\s-]*limit|limit exceeded|budget exceeded|exceeded)/i, /(?:rate[\s-]*limit|too many requests).*(?:ai[\s_-]*credits?)/i, @@ -301,10 +320,10 @@ function parseGatewayJsonlForDifcFiltered(jsonlContent) { const lines = jsonlContent.split("\n"); for (const line of lines) { const trimmed = line.trim(); - if (!trimmed || !trimmed.includes("DIFC_FILTERED")) continue; + if (!trimmed || !/difc_filtered/i.test(trimmed)) continue; try { const entry = JSON.parse(trimmed); - if (entry.type === "DIFC_FILTERED") { + if (getRpcMessageType(entry) === "DIFC_FILTERED") { filteredEvents.push(entry); } } catch { @@ -497,13 +516,20 @@ function parseRpcMessagesJsonl(jsonlContent) { if (!trimmed) continue; try { const entry = JSON.parse(trimmed); - if (!entry || typeof entry !== "object" || !entry.type) continue; - - if (entry.type === "REQUEST") { + if (!entry || typeof entry !== "object") continue; + const messageType = getRpcMessageType(entry); + if (!messageType) continue; + // Normalize entry.type so downstream consumers that read entry.type directly + // (e.g. grouping "other" entries by type) keep working regardless of whether + // the source used the legacy "type" field or the "event" field. Only set it + // when absent so we never overwrite an entry's own explicit "type" value. + if (!entry.type) entry.type = messageType; + + if (messageType === "REQUEST") { requests.push(entry); - } else if (entry.type === "RESPONSE") { + } else if (messageType === "RESPONSE") { responses.push(entry); - } else if (entry.type !== "DIFC_FILTERED") { + } else if (messageType !== "DIFC_FILTERED") { other.push(entry); } } catch { @@ -1125,6 +1151,7 @@ if (typeof module !== "undefined" && module.exports) { generateTokenSteeringSummary, generateModelAliasResolutionSummary, parseRpcMessagesJsonl, + getRpcMessageType, getRpcRequestLabel, generateRpcMessagesSummary, printAllGatewayFiles, diff --git a/actions/setup/js/parse_mcp_gateway_log.test.cjs b/actions/setup/js/parse_mcp_gateway_log.test.cjs index 7bcef810df4..183862e9ff3 100644 --- a/actions/setup/js/parse_mcp_gateway_log.test.cjs +++ b/actions/setup/js/parse_mcp_gateway_log.test.cjs @@ -12,6 +12,7 @@ const { generateTokenSteeringSummary, generateModelAliasResolutionSummary, parseRpcMessagesJsonl, + getRpcMessageType, getRpcRequestLabel, generateRpcMessagesSummary, printAllGatewayFiles, @@ -1301,6 +1302,21 @@ Some content here.`; const events = parseGatewayJsonlForDifcFiltered(jsonlContent); expect(events).toHaveLength(2); }); + + test("extracts events using the schema rpc-message/v2 'event' field (no top-level type)", () => { + const jsonlContent = JSON.stringify({ + timestamp: "2026-08-15T23:30:00Z", + event: "difc_filtered", + _schema: "rpc-message/v2", + server_id: "github", + tool_name: "list_issues", + reason: "Integrity check failed", + }); + + const events = parseGatewayJsonlForDifcFiltered(jsonlContent); + expect(events).toHaveLength(1); + expect(events[0].tool_name).toBe("list_issues"); + }); }); describe("parseGatewayJsonlForTokenSteering", () => { @@ -1618,6 +1634,60 @@ Some content here.`; expect(result.requests).toHaveLength(1); expect(result.other).toHaveLength(0); }); + + // Regression test for https://github.com/github/gh-aw/issues/53254: real-world + // rpc-messages.jsonl files (schema "rpc-message/v2") use a top-level "event" field + // ("rpc_request"/"rpc_response") instead of the legacy top-level "type" field. + test("categorizes entries using the schema rpc-message/v2 'event' field", () => { + const content = [ + JSON.stringify({ + timestamp: "2026-08-15T23:48:42.233Z", + event: "rpc_request", + _schema: "rpc-message/v2", + direction: "OUT", + server_id: "github", + method: "tools/call", + payload: { jsonrpc: "2.0", method: "tools/call", params: { name: "list_issues", arguments: {} } }, + }), + JSON.stringify({ + timestamp: "2026-08-15T23:48:42.400Z", + event: "rpc_response", + _schema: "rpc-message/v2", + direction: "IN", + server_id: "github", + payload: { jsonrpc: "2.0", id: 1, result: {} }, + }), + ].join("\n"); + + const result = parseRpcMessagesJsonl(content); + expect(result.requests).toHaveLength(1); + expect(result.responses).toHaveLength(1); + expect(result.other).toHaveLength(0); + expect(result.requests[0].server_id).toBe("github"); + expect(result.requests[0].type).toBe("REQUEST"); + }); + }); + + describe("getRpcMessageType", () => { + test("returns the legacy type field when present", () => { + expect(getRpcMessageType({ type: "REQUEST", event: "rpc_response" })).toBe("REQUEST"); + }); + + test("maps rpc_request to REQUEST", () => { + expect(getRpcMessageType({ event: "rpc_request" })).toBe("REQUEST"); + }); + + test("maps rpc_response to RESPONSE", () => { + expect(getRpcMessageType({ event: "rpc_response" })).toBe("RESPONSE"); + }); + + test("maps difc_filtered to DIFC_FILTERED", () => { + expect(getRpcMessageType({ event: "difc_filtered" })).toBe("DIFC_FILTERED"); + }); + + test("returns empty string when neither field is present", () => { + expect(getRpcMessageType({ server_id: "github" })).toBe(""); + }); }); describe("getRpcRequestLabel", () => { diff --git a/docs/adr/53256-normalize-rpc-messages-jsonl-schema-across-versions.md b/docs/adr/53256-normalize-rpc-messages-jsonl-schema-across-versions.md new file mode 100644 index 00000000000..9a6eb6d9dbe --- /dev/null +++ b/docs/adr/53256-normalize-rpc-messages-jsonl-schema-across-versions.md @@ -0,0 +1,44 @@ +# ADR-53256: Normalize rpc-messages.jsonl Schema Across Versions via EffectiveType + +**Date**: 2026-08-17 +**Status**: Accepted +**Deciders**: pelikhan, copilot-swe-agent + +--- + +### Context + +The `rpc-messages.jsonl` telemetry file that records MCP gateway traffic exists in two incompatible schemas. The legacy schema uses a top-level `type` field with values `REQUEST`, `RESPONSE`, and `DIFC_FILTERED`. Production telemetry written by the real Copilot CLI MCP gateway (schema `rpc-message/v2`) instead uses a top-level `event` field with values `rpc_request`, `rpc_response`, and `difc_filtered`, plus a `_schema` marker. Investigation of 20 real workflow runs confirmed that every run using the `rpc-messages.jsonl` fallback path (when `gateway.jsonl` is absent) emits schema `rpc-message/v2` exclusively — meaning 0 of 202 entries exposed the `type` field the parser expected, silently zeroing all tool-call counts and durations. + +### Decision + +We will introduce a thin normalization layer — `EffectiveType()` in Go and `getRpcMessageType()` in JavaScript — that transparently bridges the two schemas at every call site that previously compared `entry.Type` or `entry.type` directly. The legacy `type` field takes precedence when both fields are present; otherwise, `event` values are mapped to their `type` equivalents (`rpc_request` → `REQUEST`, `rpc_response` → `RESPONSE`, `difc_filtered` → `DIFC_FILTERED`). The `RPCMessageEntry` struct gains `Event` and `Schema` fields for JSON deserialization. All existing `entry.Type ==` comparisons across `gateway_logs_rpc.go`, `gateway_logs_timeline.go`, and `parse_mcp_gateway_log.cjs` are replaced with calls to the normalization helper. + +### Alternatives Considered + +#### Alternative 1: Migrate parsers to schema v2 exclusively + +Rewrite all parsers to read `event`/`_schema` only and drop the legacy `type` field entirely. This would be the cleaner long-term path if the `type` field were truly dead. Rejected because synthetic test fixtures, CI-generated artifacts, and any older production files that still emit `type` would silently break — there is no authoritative signal that the legacy schema is gone from all producers. + +#### Alternative 2: Normalize at ingestion by always mutating `entry.type` + +Overwrite `entry.type` with the normalized value on every parsed entry regardless of whether `type` was already set. Simpler call sites — downstream code never needs to call a helper. Rejected because it risks clobbering an entry's own explicit `type` value in a mixed-schema edge case, and it mutates data that may be forwarded or logged downstream. The JS parser does back-fill `entry.type` when absent (for downstream consumers that still read the field directly), but only when the field is not already present. + +### Consequences + +#### Positive +- Tool-call counts and durations are now correctly computed for all production workflow runs that emit schema `rpc-message/v2`, recovering previously silent zeroes across 20/20 sampled runs. +- Both schema versions are supported transparently without branching at every call site — adding the `rpc-message/v2` schema fields to the struct is backward-compatible with all existing tests and consumers. +- Regression test coverage added in Go and JavaScript for all three entry types (`REQUEST`/`RESPONSE`/`DIFC_FILTERED`) under both schemas. + +#### Negative +- Two parallel representations of the same concept (`type` and `event`) now coexist in the data model and codebase indefinitely, increasing conceptual overhead for future contributors. +- The precedence rule (`type` wins when both are set) is an implicit contract that future telemetry schema versions must respect; violating it would silently produce incorrect results. + +#### Neutral +- The `entry.type` back-fill in the JS parser (`if (!entry.type) entry.type = messageType`) is a shim for downstream consumers that still read `entry.type` directly; removing it in the future would require auditing those consumers. +- Documentation in `daily-observability-report.md` (Phase 3.4) is updated to reflect the dual-schema reality and explicitly instructs against flagging runs unhealthy solely for missing `type`. + +--- + +*ADR created by [adr-writer agent].* diff --git a/pkg/cli/gateway_logs_rpc.go b/pkg/cli/gateway_logs_rpc.go index c39443a3b98..72d205666c0 100644 --- a/pkg/cli/gateway_logs_rpc.go +++ b/pkg/cli/gateway_logs_rpc.go @@ -76,7 +76,7 @@ func parseRPCMessages(logPath string, verbose bool) (*GatewayMetrics, error) { } switch { - case entry.Type == "DIFC_FILTERED": + case entry.EffectiveType() == "DIFC_FILTERED": // DIFC integrity/secrecy filter event — not a REQUEST or RESPONSE metrics.TotalFiltered++ server := getOrCreateServer(metrics, entry.ServerID) @@ -95,7 +95,7 @@ func parseRPCMessages(logPath string, verbose bool) (*GatewayMetrics, error) { Number: entry.Number, }) - case entry.Direction == "OUT" && entry.Type == "REQUEST": + case entry.Direction == "OUT" && entry.EffectiveType() == "REQUEST": // Outgoing request from AI engine to MCP server var req rpcRequestPayload if err := json.Unmarshal(entry.Payload, &req); err != nil { @@ -132,7 +132,7 @@ func parseRPCMessages(logPath string, verbose bool) (*GatewayMetrics, error) { } } - case entry.Direction == "IN" && entry.Type == "RESPONSE": + case entry.Direction == "IN" && entry.EffectiveType() == "RESPONSE": // Incoming response from MCP server to AI engine var resp rpcResponsePayload if err := json.Unmarshal(entry.Payload, &resp); err != nil { @@ -292,7 +292,7 @@ func buildToolCallsFromRPCMessages(logPath string) ([]MCPToolCall, error) { // First pass: index outgoing tool-call requests by (serverID, id) for i := range entries { e := &entries[i] - if e.entry.Direction != "OUT" || e.entry.Type != "REQUEST" { + if e.entry.Direction != "OUT" || e.entry.EffectiveType() != "REQUEST" { continue } if err := json.Unmarshal(e.entry.Payload, &e.req); err != nil || e.req.Method != "tools/call" { @@ -330,10 +330,10 @@ func buildToolCallsFromRPCMessages(logPath string) ([]MCPToolCall, error) { for i := range entries { e := &entries[i] switch { - case e.entry.Direction == "OUT" && e.entry.Type == "REQUEST": + case e.entry.Direction == "OUT" && e.entry.EffectiveType() == "REQUEST": // Outgoing tool-call request – we'll emit the record when we see the response // (or after if no response found) - case e.entry.Direction == "IN" && e.entry.Type == "RESPONSE": + case e.entry.Direction == "IN" && e.entry.EffectiveType() == "RESPONSE": if err := json.Unmarshal(e.entry.Payload, &e.resp); err != nil { continue } diff --git a/pkg/cli/gateway_logs_test.go b/pkg/cli/gateway_logs_test.go index 4c67f9b4c63..c4ddaa01748 100644 --- a/pkg/cli/gateway_logs_test.go +++ b/pkg/cli/gateway_logs_test.go @@ -402,6 +402,57 @@ func TestParseRPCMessagesDifcFiltered(t *testing.T) { assert.Equal(t, 2, githubServer.FilteredCount) } +// TestParseRPCMessagesSchemaV2Format verifies that parseRPCMessages correctly parses +// real-world rpc-messages.jsonl entries that use the schema "rpc-message/v2" format: +// a top-level "event" field ("rpc_request"/"rpc_response") and "_schema" marker instead +// of the legacy top-level "type" field ("REQUEST"/"RESPONSE"). Regression test for +// https://github.com/github/gh-aw/issues/53254. +func TestParseRPCMessagesSchemaV2Format(t *testing.T) { + tmpDir := t.TempDir() + + content := `{"timestamp":"2026-08-15T23:48:42.233Z","event":"rpc_request","_schema":"rpc-message/v2","direction":"OUT","server_id":"github","method":"tools/call","payload":{"jsonrpc":"2.0","id":1,"method":"tools/call","params":{"name":"list_issues","arguments":{}}}} +{"timestamp":"2026-08-15T23:48:42.259Z","event":"rpc_response","_schema":"rpc-message/v2","direction":"IN","server_id":"github","payload":{"jsonrpc":"2.0","id":1,"result":{}}} +` + logPath := filepath.Join(tmpDir, "rpc-messages.jsonl") + require.NoError(t, os.WriteFile(logPath, []byte(content), 0644)) + + metrics, err := parseRPCMessages(logPath, false) + require.NoError(t, err) + require.NotNil(t, metrics) + + assert.Equal(t, 1, metrics.TotalRequests, "should count the REQUEST despite missing top-level 'type'") + assert.Equal(t, 1, metrics.TotalToolCalls, "should count the tools/call request as a tool call") + require.Len(t, metrics.Servers, 1) + + server := metrics.Servers["github"] + require.NotNil(t, server) + assert.Equal(t, 1, server.RequestCount) + assert.Equal(t, 1, server.ToolCallCount) +} + +// TestRPCMessageEntryEffectiveType verifies the normalization helper used to bridge +// the legacy top-level "type" field and the "event" field used by schema "rpc-message/v2". +func TestRPCMessageEntryEffectiveType(t *testing.T) { + tests := []struct { + name string + entry RPCMessageEntry + want string + }{ + {"legacy type takes precedence", RPCMessageEntry{Type: "REQUEST", Event: "rpc_response"}, "REQUEST"}, + {"rpc_request maps to REQUEST", RPCMessageEntry{Event: "rpc_request"}, "REQUEST"}, + {"rpc_response maps to RESPONSE", RPCMessageEntry{Event: "rpc_response"}, "RESPONSE"}, + {"difc_filtered maps to DIFC_FILTERED", RPCMessageEntry{Event: "difc_filtered"}, "DIFC_FILTERED"}, + {"unknown event passes through", RPCMessageEntry{Event: "something_else"}, "something_else"}, + {"empty entry returns empty string", RPCMessageEntry{}, ""}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert.Equal(t, tt.want, tt.entry.EffectiveType()) + }) + } +} + func TestGetSortedServerNames(t *testing.T) { metrics := &GatewayMetrics{ Servers: map[string]*GatewayServerMetrics{ @@ -796,6 +847,27 @@ func TestBuildToolCallsFromRPCMessagesNullID(t *testing.T) { assert.True(t, toolNames["issue_read"], "should include issue_read") } +// TestBuildToolCallsFromRPCMessagesSchemaV2Format verifies that buildToolCallsFromRPCMessages +// handles the real-world schema "rpc-message/v2" format ("event" field instead of "type"). +func TestBuildToolCallsFromRPCMessagesSchemaV2Format(t *testing.T) { + tmpDir := t.TempDir() + + rpcContent := `{"timestamp":"2026-08-15T23:48:42.233Z","event":"rpc_request","_schema":"rpc-message/v2","direction":"OUT","server_id":"github","method":"tools/call","payload":{"jsonrpc":"2.0","id":1,"method":"tools/call","params":{"name":"list_issues","arguments":{}}}} +{"timestamp":"2026-08-15T23:48:42.400Z","event":"rpc_response","_schema":"rpc-message/v2","direction":"IN","server_id":"github","payload":{"jsonrpc":"2.0","id":1,"result":{}}} +` + logPath := filepath.Join(tmpDir, "rpc-messages.jsonl") + require.NoError(t, os.WriteFile(logPath, []byte(rpcContent), 0644)) + + calls, err := buildToolCallsFromRPCMessages(logPath) + require.NoError(t, err, "should build tool calls without error") + require.Len(t, calls, 1, "should have 1 tool call") + + assert.Equal(t, "list_issues", calls[0].ToolName) + assert.Equal(t, "github", calls[0].ServerName) + assert.Equal(t, "success", calls[0].Status) + assert.NotEmpty(t, calls[0].Duration, "duration should be set for paired request/response") +} + func TestParseRPCMessagesGuardPolicyErrors(t *testing.T) { tmpDir := t.TempDir() diff --git a/pkg/cli/gateway_logs_timeline.go b/pkg/cli/gateway_logs_timeline.go index 171a30c49bf..4b2a8559796 100644 --- a/pkg/cli/gateway_logs_timeline.go +++ b/pkg/cli/gateway_logs_timeline.go @@ -214,7 +214,7 @@ func rpcEntryToTimelineEvent(entry RPCMessageEntry) (UnifiedTimelineEvent, bool) ServerName: entry.ServerID, } - switch entry.Type { + switch entry.EffectiveType() { case "DIFC_FILTERED": evt.Kind = TimelineKindDIFCFiltered evt.ToolName = entry.ToolName diff --git a/pkg/cli/gateway_logs_timeline_rpcentry_test.go b/pkg/cli/gateway_logs_timeline_rpcentry_test.go index 3ff36597dd2..8d9acd3dbf0 100644 --- a/pkg/cli/gateway_logs_timeline_rpcentry_test.go +++ b/pkg/cli/gateway_logs_timeline_rpcentry_test.go @@ -148,4 +148,35 @@ func TestRpcEntryToTimelineEvent(t *testing.T) { assert.False(t, ok) assert.Equal(t, UnifiedTimelineEvent{}, evt) }) + + t.Run("schema rpc-message/v2 REQUEST OUT with event field (no top-level type) converts", func(t *testing.T) { + payload := json.RawMessage(`{"method":"tools/call","params":{"name":"list_issues"}}`) + + entry := RPCMessageEntry{ + Timestamp: "2024-01-01T12:00:00Z", + Event: "rpc_request", + Direction: "OUT", + ServerID: "server-1", + Payload: payload, + } + evt, ok := rpcEntryToTimelineEvent(entry) + require.True(t, ok) + assert.Equal(t, TimelineKindToolCall, evt.Kind) + assert.Equal(t, "list_issues", evt.ToolName) + assert.Equal(t, "server-1", evt.ServerName) + }) + + t.Run("schema rpc-message/v2 DIFC_FILTERED entry with event field converts", func(t *testing.T) { + entry := RPCMessageEntry{ + Timestamp: "2024-01-01T12:00:00Z", + Event: "difc_filtered", + ServerID: "server-1", + ToolName: "create_issue", + Reason: "secrecy violation", + } + evt, ok := rpcEntryToTimelineEvent(entry) + require.True(t, ok) + assert.Equal(t, TimelineKindDIFCFiltered, evt.Kind) + assert.Equal(t, "create_issue", evt.ToolName) + }) } diff --git a/pkg/cli/gateway_logs_types.go b/pkg/cli/gateway_logs_types.go index 9320955986e..8ef8df63a0e 100644 --- a/pkg/cli/gateway_logs_types.go +++ b/pkg/cli/gateway_logs_types.go @@ -126,8 +126,10 @@ type GatewayMetrics struct { // exchanged between the AI engine and MCP servers, as well as DIFC_FILTERED events. type RPCMessageEntry struct { Timestamp string `json:"timestamp"` - Direction string `json:"direction"` // "IN" = received from server, "OUT" = sent to server; empty for DIFC_FILTERED - Type string `json:"type"` // "REQUEST", "RESPONSE", or "DIFC_FILTERED" + Direction string `json:"direction"` // "IN" = received from server, "OUT" = sent to server; empty for DIFC_FILTERED + Type string `json:"type"` // legacy field: "REQUEST", "RESPONSE", or "DIFC_FILTERED" + Event string `json:"event,omitempty"` // schema "rpc-message/v2" field: "rpc_request", "rpc_response", or "difc_filtered" + Schema string `json:"_schema,omitempty"` // e.g. "rpc-message/v2" ServerID string `json:"server_id"` Payload json.RawMessage `json:"payload"` // Fields populated only for DIFC_FILTERED entries @@ -142,6 +144,35 @@ type RPCMessageEntry struct { Number string `json:"number,omitempty"` } +// rpcEventToType maps the "event" field values used by the schema "rpc-message/v2" +// format (written by real Copilot CLI MCP gateway telemetry) to the legacy "type" +// values ("REQUEST", "RESPONSE", "DIFC_FILTERED") used throughout this codebase. +// Real-world rpc-messages.jsonl files do not populate a top-level "type" field at +// all; they use "event" instead (e.g. "rpc_request"/"rpc_response"). +var rpcEventToType = map[string]string{ + "rpc_request": "REQUEST", + "rpc_response": "RESPONSE", + "difc_filtered": "DIFC_FILTERED", +} + +// EffectiveType returns the logical message type for this entry ("REQUEST", +// "RESPONSE", or "DIFC_FILTERED"), normalizing across rpc-messages.jsonl schema +// versions. Older/synthetic files populate the top-level "type" field directly; +// real production files (schema "rpc-message/v2") use "event" instead. The legacy +// "type" field takes precedence when both are present, since no known schema +// version populates both fields with conflicting values; this keeps the contract +// simple while remaining forward-compatible if a future schema starts setting +// "type" explicitly again. +func (e RPCMessageEntry) EffectiveType() string { + if e.Type != "" { + return e.Type + } + if mapped, ok := rpcEventToType[e.Event]; ok { + return mapped + } + return e.Event +} + // rpcRequestPayload represents the JSON-RPC request payload fields we care about. type rpcRequestPayload struct { Method string `json:"method"`