Skip to content

Commit e384932

Browse files
steipetesteipete
committed
test: clear logging diagnostic broad matchers
1 parent b3fcdaa commit e384932

1 file changed

Lines changed: 146 additions & 76 deletions

File tree

‎src/logging/diagnostic.test.ts‎

Lines changed: 146 additions & 76 deletions
Original file line numberDiff line numberDiff line change
@@ -62,6 +62,66 @@ function countMatching<T>(items: readonly T[], predicate: (item: T) => boolean)
6262
return count;
6363
}
6464

65+
function requireRecord(value: unknown, label: string): Record<string, unknown> {
66+
expect(typeof value).toBe("object");
67+
expect(value).not.toBeNull();
68+
if (typeof value !== "object" || value === null) {
69+
throw new Error(`${label} was not an object`);
70+
}
71+
return value as Record<string, unknown>;
72+
}
73+
74+
function expectRecordFields(record: Record<string, unknown>, fields: Record<string, unknown>) {
75+
for (const [key, value] of Object.entries(fields)) {
76+
expect(record[key]).toEqual(value);
77+
}
78+
}
79+
80+
function expectNumberField(record: Record<string, unknown>, key: string) {
81+
expect(typeof record[key]).toBe("number");
82+
}
83+
84+
function requireMatchingRecord(
85+
items: readonly unknown[],
86+
fields: Record<string, unknown>,
87+
label: string,
88+
) {
89+
const found = items.find((item) => {
90+
if (typeof item !== "object" || item === null) {
91+
return false;
92+
}
93+
const record = item as Record<string, unknown>;
94+
return Object.entries(fields).every(([key, value]) => Object.is(record[key], value));
95+
});
96+
expect(found).toBeDefined();
97+
if (!found) {
98+
throw new Error(`missing ${label}`);
99+
}
100+
return requireRecord(found, label);
101+
}
102+
103+
function requireFirstMockCallArg(mock: unknown, label: string) {
104+
const calls = (mock as { mock?: { calls?: unknown[][] } }).mock?.calls;
105+
const call = calls?.[0];
106+
expect(call).toBeDefined();
107+
if (!call) {
108+
throw new Error(`missing ${label} call`);
109+
}
110+
return requireRecord(call[0], `${label} argument`);
111+
}
112+
113+
function expectRecoveryCall(
114+
recoverStuckSession: unknown,
115+
fields: Record<string, unknown>,
116+
numberFields: readonly string[],
117+
) {
118+
const params = requireFirstMockCallArg(recoverStuckSession, "recoverStuckSession");
119+
expectRecordFields(params, fields);
120+
for (const key of numberFields) {
121+
expectNumberField(params, key);
122+
}
123+
}
124+
65125
describe("diagnostic session state pruning", () => {
66126
beforeEach(() => {
67127
vi.useFakeTimers();
@@ -234,18 +294,16 @@ describe("stuck session diagnostics threshold", () => {
234294

235295
const stuckEvents = events.filter((event) => event.type === "session.stuck");
236296
expect(stuckEvents).toHaveLength(1);
237-
expect(stuckEvents[0]).toMatchObject({
297+
expectRecordFields(requireRecord(stuckEvents[0], "stuck event"), {
238298
classification: "stale_session_state",
239299
reason: "stale_session_state",
240300
queueDepth: 0,
241301
});
242-
expect(recoverStuckSession).toHaveBeenCalledWith({
243-
sessionId: "s1",
244-
sessionKey: "main",
245-
ageMs: expect.any(Number),
246-
queueDepth: 0,
247-
stateGeneration: expect.any(Number),
248-
});
302+
expectRecoveryCall(
303+
recoverStuckSession,
304+
{ sessionId: "s1", sessionKey: "main", queueDepth: 0 },
305+
["ageMs", "stateGeneration"],
306+
);
249307
});
250308

251309
it("keeps queued stale sessions eligible for lane recovery", () => {
@@ -274,18 +332,16 @@ describe("stuck session diagnostics threshold", () => {
274332
expect(events.some((event) => event.type === "session.long_running")).toBe(false);
275333
const stuckEvents = events.filter((event) => event.type === "session.stuck");
276334
expect(stuckEvents).toHaveLength(1);
277-
expect(stuckEvents[0]).toMatchObject({
335+
expectRecordFields(requireRecord(stuckEvents[0], "stuck event"), {
278336
classification: "stale_session_state",
279337
reason: "queued_work_without_active_run",
280338
queueDepth: 1,
281339
});
282-
expect(recoverStuckSession).toHaveBeenCalledWith({
283-
sessionId: "s1",
284-
sessionKey: "main",
285-
ageMs: expect.any(Number),
286-
queueDepth: 1,
287-
stateGeneration: expect.any(Number),
288-
});
340+
expectRecoveryCall(
341+
recoverStuckSession,
342+
{ sessionId: "s1", sessionKey: "main", queueDepth: 1 },
343+
["ageMs", "stateGeneration"],
344+
);
289345
});
290346

291347
it("does not warn while a processing session continues reporting progress", () => {
@@ -372,7 +428,7 @@ describe("stuck session diagnostics threshold", () => {
372428
expect(events.some((event) => event.type === "session.stuck")).toBe(false);
373429
const stalledEvents = events.filter((event) => event.type === "session.stalled");
374430
expect(stalledEvents).toHaveLength(1);
375-
expect(stalledEvents[0]).toMatchObject({
431+
expectRecordFields(requireRecord(stalledEvents[0], "stalled event"), {
376432
classification: "stalled_agent_run",
377433
reason: "active_work_without_progress",
378434
activeWorkKind: "embedded_run",
@@ -411,10 +467,16 @@ describe("stuck session diagnostics threshold", () => {
411467
}
412468

413469
expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining("terminalProgressStale=true"));
414-
expect(events.findLast((event) => event.type === "session.stalled")).toMatchObject({
415-
terminalProgressStale: true,
416-
lastProgressReason: "codex_app_server:notification:rawResponseItem/completed",
417-
});
470+
expectRecordFields(
471+
requireRecord(
472+
events.findLast((event) => event.type === "session.stalled"),
473+
"stalled event",
474+
),
475+
{
476+
terminalProgressStale: true,
477+
lastProgressReason: "codex_app_server:notification:rawResponseItem/completed",
478+
},
479+
);
418480
});
419481

420482
it("aborts and drains embedded runs after an extended no-progress stall", () => {
@@ -446,19 +508,16 @@ describe("stuck session diagnostics threshold", () => {
446508

447509
const stalledEvents = events.filter((event) => event.type === "session.stalled");
448510
expect(stalledEvents.length).toBeGreaterThan(0);
449-
expect(stalledEvents.at(-1)).toMatchObject({
511+
expectRecordFields(requireRecord(stalledEvents.at(-1), "stalled event"), {
450512
classification: "stalled_agent_run",
451513
reason: "active_work_without_progress",
452514
activeWorkKind: "embedded_run",
453515
});
454-
expect(recoverStuckSession).toHaveBeenCalledWith({
455-
sessionId: "s1",
456-
sessionKey: "main",
457-
ageMs: expect.any(Number),
458-
queueDepth: 0,
459-
allowActiveAbort: true,
460-
stateGeneration: expect.any(Number),
461-
});
516+
expectRecoveryCall(
517+
recoverStuckSession,
518+
{ sessionId: "s1", sessionKey: "main", queueDepth: 0, allowActiveAbort: true },
519+
["ageMs", "stateGeneration"],
520+
);
462521
});
463522

464523
it("uses diagnostics.stuckSessionAbortMs for stalled active-work recovery", () => {
@@ -479,14 +538,11 @@ describe("stuck session diagnostics threshold", () => {
479538

480539
vi.advanceTimersByTime(61_000);
481540

482-
expect(recoverStuckSession).toHaveBeenCalledWith({
483-
sessionId: "s1",
484-
sessionKey: "main",
485-
ageMs: expect.any(Number),
486-
queueDepth: 0,
487-
allowActiveAbort: true,
488-
stateGeneration: expect.any(Number),
489-
});
541+
expectRecoveryCall(
542+
recoverStuckSession,
543+
{ sessionId: "s1", sessionKey: "main", queueDepth: 0, allowActiveAbort: true },
544+
["ageMs", "stateGeneration"],
545+
);
490546
});
491547

492548
it("marks diagnostic session state idle only after a mutating recovery outcome", async () => {
@@ -523,12 +579,10 @@ describe("stuck session diagnostics threshold", () => {
523579
const state = getDiagnosticSessionState({ sessionId: "s1", sessionKey: "main" });
524580
expect(state.state).toBe("idle");
525581
expect(state.queueDepth).toBe(0);
526-
expect(events).toContainEqual(
527-
expect.objectContaining({
528-
type: "session.recovery.completed",
529-
status: "released",
530-
action: "release_lane",
531-
}),
582+
requireMatchingRecord(
583+
events,
584+
{ type: "session.recovery.completed", status: "released", action: "release_lane" },
585+
"released recovery event",
532586
);
533587
});
534588

@@ -569,12 +623,10 @@ describe("stuck session diagnostics threshold", () => {
569623
expect(getDiagnosticSessionState({ sessionId: "s1", sessionKey: "main" }).state).toBe(
570624
"processing",
571625
);
572-
expect(events).toContainEqual(
573-
expect.objectContaining({
574-
type: "session.recovery.completed",
575-
status: "released",
576-
stale: true,
577-
}),
626+
requireMatchingRecord(
627+
events,
628+
{ type: "session.recovery.completed", status: "released", stale: true },
629+
"stale recovery event",
578630
);
579631
});
580632

@@ -621,12 +673,14 @@ describe("stuck session diagnostics threshold", () => {
621673

622674
vi.advanceTimersByTime(60_000);
623675
expect(recoverStuckSession).toHaveBeenCalledTimes(1);
624-
expect(events).toContainEqual(
625-
expect.objectContaining({
676+
requireMatchingRecord(
677+
events,
678+
{
626679
type: "session.recovery.completed",
627680
status: "skipped",
628681
outcomeReason: "already_in_flight",
629-
}),
682+
},
683+
"skipped recovery event",
630684
);
631685

632686
resolveRecovery?.({
@@ -671,7 +725,7 @@ describe("stuck session diagnostics threshold", () => {
671725
expect(events.some((event) => event.type === "session.stalled")).toBe(false);
672726
const longRunningEvents = events.filter((event) => event.type === "session.long_running");
673727
expect(longRunningEvents).toHaveLength(1);
674-
expect(longRunningEvents[0]).toMatchObject({
728+
expectRecordFields(requireRecord(longRunningEvents[0], "long-running event"), {
675729
classification: "long_running",
676730
reason: "active_work",
677731
activeWorkKind: "embedded_run",
@@ -751,7 +805,7 @@ describe("stuck session diagnostics threshold", () => {
751805
expect(events.some((event) => event.type === "session.stalled")).toBe(false);
752806
const longRunningEvents = events.filter((event) => event.type === "session.long_running");
753807
expect(longRunningEvents).toHaveLength(1);
754-
expect(longRunningEvents[0]).toMatchObject({
808+
expectRecordFields(requireRecord(longRunningEvents[0], "long-running event"), {
755809
classification: "long_running",
756810
reason: "queued_behind_active_work",
757811
activeWorkKind: "embedded_run",
@@ -768,11 +822,10 @@ describe("stuck session diagnostics threshold", () => {
768822
});
769823
logSessionStateChange({ sessionId: "s1", sessionKey: "main", state: "processing" });
770824

771-
expect(getDiagnosticStabilitySnapshot({ limit: 10 }).events).toContainEqual(
772-
expect.objectContaining({
773-
type: "session.state",
774-
outcome: "processing",
775-
}),
825+
requireMatchingRecord(
826+
getDiagnosticStabilitySnapshot({ limit: 10 }).events,
827+
{ type: "session.state", outcome: "processing" },
828+
"session state stability event",
776829
);
777830
const [event] = getDiagnosticStabilitySnapshot({ limit: 10 }).events;
778831
expect(event).not.toHaveProperty("sessionId");
@@ -856,8 +909,9 @@ describe("stuck session diagnostics threshold", () => {
856909
expect(events).toContain("diagnostic.liveness.warning");
857910
expect(warnSpy).not.toHaveBeenCalledWith(expect.stringContaining("liveness warning:"));
858911
expect(emitMemorySample).toHaveBeenLastCalledWith({ emitSample: true });
859-
expect(getDiagnosticStabilitySnapshot({ limit: 10 }).events).toContainEqual(
860-
expect.objectContaining({
912+
requireMatchingRecord(
913+
getDiagnosticStabilitySnapshot({ limit: 10 }).events,
914+
{
861915
type: "diagnostic.liveness.warning",
862916
level: "info",
863917
reason: "cpu",
@@ -870,7 +924,8 @@ describe("stuck session diagnostics threshold", () => {
870924
active: 0,
871925
waiting: 0,
872926
queued: 0,
873-
}),
927+
},
928+
"idle liveness stability event",
874929
);
875930
});
876931

@@ -898,14 +953,16 @@ describe("stuck session diagnostics threshold", () => {
898953
vi.advanceTimersByTime(30_000);
899954

900955
expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining("liveness warning:"));
901-
expect(getDiagnosticStabilitySnapshot({ limit: 10 }).events).toContainEqual(
902-
expect.objectContaining({
956+
requireMatchingRecord(
957+
getDiagnosticStabilitySnapshot({ limit: 10 }).events,
958+
{
903959
type: "diagnostic.liveness.warning",
904960
level: "warning",
905961
active: 0,
906962
waiting: 0,
907963
queued: 1,
908-
}),
964+
},
965+
"queued liveness stability event",
909966
);
910967
});
911968

@@ -954,10 +1011,19 @@ describe("stuck session diagnostics threshold", () => {
9541011

9551012
expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining("phase=startup.plugins.load"));
9561013
expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining("work=[queued=main("));
957-
expect(events.findLast((event) => event.type === "diagnostic.liveness.warning")).toMatchObject({
958-
phase: "startup.plugins.load",
959-
queuedWorkLabels: [expect.stringContaining("main(")],
960-
});
1014+
const warning = requireRecord(
1015+
events.findLast((event) => event.type === "diagnostic.liveness.warning"),
1016+
"liveness warning event",
1017+
);
1018+
expect(warning.phase).toBe("startup.plugins.load");
1019+
const queuedWorkLabels = warning.queuedWorkLabels;
1020+
expect(Array.isArray(queuedWorkLabels)).toBe(true);
1021+
if (!Array.isArray(queuedWorkLabels)) {
1022+
throw new Error("liveness warning queuedWorkLabels was not an array");
1023+
}
1024+
expect(
1025+
queuedWorkLabels.some((label) => typeof label === "string" && label.includes("main(")),
1026+
).toBe(true);
9611027
});
9621028

9631029
it("keeps transient event-loop max spikes debug-only when only background work is active", () => {
@@ -984,14 +1050,16 @@ describe("stuck session diagnostics threshold", () => {
9841050
vi.advanceTimersByTime(30_000);
9851051

9861052
expect(warnSpy).not.toHaveBeenCalledWith(expect.stringContaining("liveness warning:"));
987-
expect(getDiagnosticStabilitySnapshot({ limit: 10 }).events).toContainEqual(
988-
expect.objectContaining({
1053+
requireMatchingRecord(
1054+
getDiagnosticStabilitySnapshot({ limit: 10 }).events,
1055+
{
9891056
type: "diagnostic.liveness.warning",
9901057
level: "warning",
9911058
active: 1,
9921059
waiting: 0,
9931060
queued: 0,
994-
}),
1061+
},
1062+
"active liveness stability event",
9951063
);
9961064
});
9971065

@@ -1132,15 +1200,17 @@ describe("diagnostic stability snapshots", () => {
11321200
});
11331201
await flushDiagnosticEvents();
11341202

1135-
expect(getDiagnosticStabilitySnapshot({ limit: 10 }).events).toContainEqual(
1136-
expect.objectContaining({
1203+
requireMatchingRecord(
1204+
getDiagnosticStabilitySnapshot({ limit: 10 }).events,
1205+
{
11371206
type: "message.delivery.error",
11381207
channel: "matrix",
11391208
deliveryKind: "text",
11401209
durationMs: 12,
11411210
outcome: "error",
11421211
reason: "TypeError",
1143-
}),
1212+
},
1213+
"bounded outbound delivery stability event",
11441214
);
11451215
const [event] = getDiagnosticStabilitySnapshot({ limit: 10 }).events;
11461216
expect(event).not.toHaveProperty("sessionKey");

0 commit comments

Comments
 (0)