Skip to content

Commit 9108ae0

Browse files
TurboTheTurtleTurboTheTurtle
authored
Include delivery errors in subagent announce give-up logs (#84281)
* Include delivery error in subagent announce give-up logs * test(agents): type announce delivery error response
1 parent 2ab3a4e commit 9108ae0

4 files changed

Lines changed: 96 additions & 7 deletions

File tree

‎src/agents/subagent-announce.test.ts‎

Lines changed: 45 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -3,8 +3,14 @@ import type { EmbeddedPiQueueMessageOutcome } from "./pi-embedded-runner/runs.js
33
import { createSubagentAnnounceDeliveryRuntimeMock } from "./subagent-announce.test-support.js";
44

55
type AgentCallRequest = { method?: string; params?: Record<string, unknown> };
6+
type AgentCallResponse = { runId?: string; status: string; error?: string };
67

7-
const agentSpy = vi.fn(async (_req: AgentCallRequest) => ({ runId: "run-main", status: "ok" }));
8+
const agentSpy = vi.fn(
9+
async (_req: AgentCallRequest): Promise<AgentCallResponse> => ({
10+
runId: "run-main",
11+
status: "ok",
12+
}),
13+
);
814
const sessionsDeleteSpy = vi.fn((_req: AgentCallRequest) => undefined);
915
const callGatewayMock = vi.fn(async (_request: unknown) => ({}));
1016
const loadSessionStoreMock = vi.fn((_storePath: string) => ({}));
@@ -120,7 +126,7 @@ vi.mock("./subagent-announce-delivery.js", () => ({
120126
const effectiveOrigin =
121127
params.completionDirectOrigin ?? params.requesterOrigin ?? params.directOrigin;
122128

123-
await callGatewayMock({
129+
const response = (await callGatewayMock({
124130
method: "agent",
125131
params: {
126132
sessionKey: params.targetRequesterSessionKey,
@@ -139,7 +145,11 @@ vi.mock("./subagent-announce-delivery.js", () => ({
139145
threadId: effectiveOrigin?.threadId,
140146
}),
141147
},
142-
});
148+
})) as { status?: string; error?: string };
149+
150+
if (response.status === "error") {
151+
return { delivered: false, path: "direct", error: response.error ?? "agent delivery failed" };
152+
}
143153

144154
return { delivered: true, path: "direct" };
145155
},
@@ -180,6 +190,7 @@ vi.mock("./subagent-announce-delivery.js", () => ({
180190
}));
181191

182192
vi.mock("./subagent-announce.registry.runtime.js", () => subagentRegistryRuntimeMock);
193+
import { defaultRuntime } from "../runtime.js";
183194
import { applySubagentWaitOutcome } from "./subagent-announce-output.js";
184195
import { runSubagentAnnounceFlow } from "./subagent-announce.js";
185196

@@ -502,4 +513,35 @@ describe("subagent announce seam flow", () => {
502513
expect(agentCall.params?.accountId).toBe("bot-123");
503514
expect(agentCall.params?.to).toBe("-1001234567890");
504515
});
516+
517+
it("logs direct completion announce delivery failures through the gateway log path", async () => {
518+
const logSpy = vi.spyOn(defaultRuntime, "log").mockImplementation(() => {});
519+
agentSpy.mockResolvedValueOnce({ status: "error", error: "Outbound not configured for slack" });
520+
521+
const didAnnounce = await runSubagentAnnounceFlow({
522+
childSessionKey: "agent:main:subagent:slack",
523+
childRunId: "run-direct-failure-log",
524+
requesterSessionKey: "agent:main:main",
525+
requesterDisplayKey: "main",
526+
requesterOrigin: {
527+
channel: "slack",
528+
to: "C123",
529+
},
530+
task: "deliver completion",
531+
timeoutMs: 10,
532+
cleanup: "keep",
533+
waitForCompletion: false,
534+
startedAt: 10,
535+
endedAt: 20,
536+
outcome: { status: "ok" },
537+
roundOneReply: "done",
538+
expectsCompletionMessage: true,
539+
});
540+
541+
expect(didAnnounce).toBe(false);
542+
expect(logSpy).toHaveBeenCalledWith(
543+
"[warn] Subagent completion direct announce failed for run run-direct-failure-log: Outbound not configured for slack",
544+
);
545+
logSpy.mockRestore();
546+
});
505547
});

‎src/agents/subagent-announce.ts‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -573,8 +573,8 @@ export async function runSubagentAnnounceFlow(params: {
573573
params.onDeliveryResult?.(delivery);
574574
didAnnounce = delivery.delivered;
575575
if (!delivery.delivered && delivery.path === "direct" && delivery.error) {
576-
defaultRuntime.error?.(
577-
`Subagent completion direct announce failed for run ${params.childRunId}: ${delivery.error}`,
576+
defaultRuntime.log(
577+
`[warn] Subagent completion direct announce failed for run ${params.childRunId}: ${delivery.error}`,
578578
);
579579
}
580580
} catch (err) {

‎src/agents/subagent-registry-helpers.test.ts‎

Lines changed: 40 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import { afterEach, describe, expect, it, vi } from "vitest";
2-
import { reconcileOrphanedRun } from "./subagent-registry-helpers.js";
2+
import { defaultRuntime } from "../runtime.js";
3+
import { logAnnounceGiveUp, reconcileOrphanedRun } from "./subagent-registry-helpers.js";
34
import type { SubagentRunRecord } from "./subagent-registry.types.js";
45

56
function createRunEntry(overrides: Partial<SubagentRunRecord> = {}): SubagentRunRecord {
@@ -52,3 +53,41 @@ describe("reconcileOrphanedRun", () => {
5253
expect(resumedRuns.has(entry.runId)).toBe(false);
5354
});
5455
});
56+
57+
describe("logAnnounceGiveUp", () => {
58+
afterEach(() => {
59+
vi.useRealTimers();
60+
});
61+
62+
it("includes the last delivery error in retry-limit warnings", () => {
63+
vi.useFakeTimers();
64+
vi.setSystemTime(9_000);
65+
const logSpy = vi.spyOn(defaultRuntime, "log").mockImplementation(() => {});
66+
const entry = createRunEntry({
67+
endedAt: 4_000,
68+
announceRetryCount: 3,
69+
lastAnnounceDeliveryError: "direct-primary: routed-dispatch-did-not-queue-final",
70+
});
71+
72+
logAnnounceGiveUp(entry, "retry-limit");
73+
74+
expect(logSpy).toHaveBeenCalledWith(
75+
'[warn] Subagent announce give up (retry-limit) run=run-1 child=agent:main:subagent:child requester=agent:main:main retries=3 endedAgo=5s deliveryError="direct-primary: routed-dispatch-did-not-queue-final"',
76+
);
77+
logSpy.mockRestore();
78+
});
79+
80+
it("normalizes multiline delivery errors onto one gateway log line", () => {
81+
const logSpy = vi.spyOn(defaultRuntime, "log").mockImplementation(() => {});
82+
const entry = createRunEntry({
83+
lastAnnounceDeliveryError: "gateway timeout\nphase: routed dispatch failed",
84+
});
85+
86+
logAnnounceGiveUp(entry, "expiry");
87+
88+
expect(logSpy).toHaveBeenCalledWith(
89+
expect.stringContaining('deliveryError="gateway timeout phase: routed dispatch failed"'),
90+
);
91+
logSpy.mockRestore();
92+
});
93+
});

‎src/agents/subagent-registry-helpers.ts‎

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -65,13 +65,21 @@ export function resolveAnnounceRetryDelayMs(retryCount: number) {
6565
return Math.min(baseDelay, MAX_ANNOUNCE_RETRY_DELAY_MS);
6666
}
6767

68+
function formatAnnounceGiveUpLogField(value: string): string {
69+
const normalized = value.replace(/\s+/g, " ").trim();
70+
return JSON.stringify(normalized.length > 2_000 ? `${normalized.slice(0, 2_000)}…` : normalized);
71+
}
72+
6873
export function logAnnounceGiveUp(entry: SubagentRunRecord, reason: "retry-limit" | "expiry") {
6974
const retryCount = entry.announceRetryCount ?? 0;
7075
const endedAgoMs =
7176
typeof entry.endedAt === "number" ? Math.max(0, Date.now() - entry.endedAt) : undefined;
7277
const endedAgoLabel = endedAgoMs != null ? `${Math.round(endedAgoMs / 1000)}s` : "n/a";
78+
const deliveryError = entry.lastAnnounceDeliveryError?.trim()
79+
? ` deliveryError=${formatAnnounceGiveUpLogField(entry.lastAnnounceDeliveryError)}`
80+
: "";
7381
defaultRuntime.log(
74-
`[warn] Subagent announce give up (${reason}) run=${entry.runId} child=${entry.childSessionKey} requester=${entry.requesterSessionKey} retries=${retryCount} endedAgo=${endedAgoLabel}`,
82+
`[warn] Subagent announce give up (${reason}) run=${entry.runId} child=${entry.childSessionKey} requester=${entry.requesterSessionKey} retries=${retryCount} endedAgo=${endedAgoLabel}${deliveryError}`,
7583
);
7684
}
7785

0 commit comments

Comments
 (0)