Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion .github/workflows/daily-observability-report.lock.yml

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

7 changes: 6 additions & 1 deletion .github/workflows/daily-observability-report.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Comment on lines +213 to +215
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
Expand Down
43 changes: 35 additions & 8 deletions actions/setup/js/parse_mcp_gateway_log.cjs
Original file line number Diff line number Diff line change
Expand Up @@ -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 "";
Comment on lines +42 to +45
}
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,
Expand Down Expand Up @@ -301,10 +320,10 @@ function parseGatewayJsonlForDifcFiltered(jsonlContent) {
const lines = jsonlContent.split("\n");
for (const line of lines) {
const trimmed = line.trim();

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[/diagnosing-bugs] The early-exit regex /difc_filtered/i is case-insensitive but the final check via getRpcMessageType() produces "DIFC_FILTERED" (uppercase). This works today, but the case-insensitive fast-path may silently pass lines that getRpcMessageType cannot normalize (e.g. "DIFC_Filtered" in a future schema variant).

💡 Suggestion

Make the fast-path regex and the lookup consistent. Either:

  1. Use a case-sensitive regex matching both known spellings: /difc_filtered|DIFC_FILTERED/
  2. Or add a comment explaining the intentional loose match is just a perf guard and the inner getRpcMessageType check is the authoritative gate.
// Fast-path guard (loose): skip lines that obviously cannot be difc events.
// getRpcMessageType() below is the authoritative check.
if (!trimmed || !/difc_filtered|DIFC_FILTERED/i.test(trimmed)) continue;

@copilot please address this.

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 {
Expand Down Expand Up @@ -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") {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[/tdd] entry.type = messageType mutates the freshly-parsed JSON object. The comment explains why this is safe, but callers who re-serialize the result or pass it to multiple consumers may be surprised.

💡 Suggestion

The comment is helpful, but consider making the safety guarantee explicit at the call site:

// entry is a freshly-parsed object from JSON.parse(trimmed); safe to mutate.
if (!entry.type) entry.type = messageType;

Or avoid mutation entirely by normalizing before downstream consumers use the object:

const typedEntry = entry.type ? entry : { ...entry, type: messageType };

This makes the intent clearer and prevents subtle bugs if parseRpcMessagesJsonl is ever refactored to share parsed entries.

@copilot please address this.

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 {
Expand Down Expand Up @@ -1125,6 +1151,7 @@ if (typeof module !== "undefined" && module.exports) {
generateTokenSteeringSummary,
generateModelAliasResolutionSummary,
parseRpcMessagesJsonl,
getRpcMessageType,
getRpcRequestLabel,
generateRpcMessagesSummary,
printAllGatewayFiles,
Expand Down
70 changes: 70 additions & 0 deletions actions/setup/js/parse_mcp_gateway_log.test.cjs
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ const {
generateTokenSteeringSummary,
generateModelAliasResolutionSummary,
parseRpcMessagesJsonl,
getRpcMessageType,
getRpcRequestLabel,
generateRpcMessagesSummary,
printAllGatewayFiles,
Expand Down Expand Up @@ -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", () => {
Expand Down Expand Up @@ -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", () => {
Expand Down
Original file line number Diff line number Diff line change
@@ -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].*
12 changes: 6 additions & 6 deletions pkg/cli/gateway_logs_rpc.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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 {
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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" {
Expand Down Expand Up @@ -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
}
Expand Down
Loading
Loading