fix(logging) add failover log source and target (#65955)

* clarify failover log source and target

* fix embedded runner final assistant raw text helper
This commit is contained in:
Tak Hoffman
2026-04-13 08:56:10 -05:00
committed by GitHub
parent c15b295a85
commit dc5ed7edea
6 changed files with 139 additions and 6 deletions

View File

@@ -878,6 +878,8 @@ describe("runEmbeddedPiAgent auth profile rotation", () => {
decision: "rotate_profile",
failoverReason: "overloaded",
profileId: safeProfileId,
sourceProvider: "openai",
sourceModel: "gpt-5.4-mini",
providerErrorType: "overloaded_error",
rawErrorPreview: expect.stringContaining('"request_id":"sha256:'),
});

View File

@@ -82,10 +82,11 @@ import { createFailoverDecisionLogger } from "./run/failover-observation.js";
import { mergeRetryFailoverReason, resolveRunFailoverDecision } from "./run/failover-policy.js";
import {
buildErrorAgentMeta,
resolveFinalAssistantVisibleText,
buildUsageAgentMetaFields,
createCompactionDiagId,
resolveActiveErrorContext,
resolveFinalAssistantRawText,
resolveFinalAssistantVisibleText,
resolveMaxRunRetryIterations,
resolveOverloadFailoverBackoffMs,
resolveOverloadProfileRotationLimit,
@@ -1267,6 +1268,8 @@ export async function runEmbeddedPiAgent(
profileFailureReason: promptProfileFailureReason,
provider,
model: modelId,
sourceProvider: provider,
sourceModel: modelId,
profileId: failedPromptProfileId,
fallbackConfigured,
aborted,
@@ -1385,6 +1388,8 @@ export async function runEmbeddedPiAgent(
profileFailureReason: assistantProfileFailureReason,
provider: activeErrorContext.provider,
model: activeErrorContext.model,
sourceProvider: assistantForFailover?.provider ?? provider,
sourceModel: assistantForFailover?.model ?? modelId,
profileId: failedAssistantProfileId,
fallbackConfigured,
timedOut,
@@ -1498,6 +1503,7 @@ export async function runEmbeddedPiAgent(
compactionCount: autoCompactionCount > 0 ? autoCompactionCount : undefined,
};
const finalAssistantVisibleText = resolveFinalAssistantVisibleText(sessionLastAssistant);
const finalAssistantRawText = resolveFinalAssistantRawText(sessionLastAssistant);
const payloads = buildEmbeddedRunPayloads({
assistantTexts: attempt.assistantTexts,
@@ -1557,6 +1563,7 @@ export async function runEmbeddedPiAgent(
aborted,
systemPromptReport: attempt.systemPromptReport,
finalAssistantVisibleText,
finalAssistantRawText,
replayInvalid,
livenessState,
},
@@ -1659,6 +1666,7 @@ export async function runEmbeddedPiAgent(
aborted,
systemPromptReport: attempt.systemPromptReport,
finalAssistantVisibleText,
finalAssistantRawText,
replayInvalid,
livenessState,
},
@@ -1711,6 +1719,7 @@ export async function runEmbeddedPiAgent(
aborted,
systemPromptReport: attempt.systemPromptReport,
finalAssistantVisibleText,
finalAssistantRawText,
replayInvalid,
livenessState,
},
@@ -1759,6 +1768,7 @@ export async function runEmbeddedPiAgent(
aborted,
systemPromptReport: attempt.systemPromptReport,
finalAssistantVisibleText,
finalAssistantRawText,
replayInvalid,
livenessState,
// Handle client tool calls (OpenResponses hosted tools)

View File

@@ -1,5 +1,9 @@
import { describe, expect, it } from "vitest";
import { normalizeFailoverDecisionObservationBase } from "./failover-observation.js";
import { afterEach, describe, expect, it, vi } from "vitest";
import { log } from "../logger.js";
import {
createFailoverDecisionLogger,
normalizeFailoverDecisionObservationBase,
} from "./failover-observation.js";
function normalizeObservation(
overrides: Partial<Parameters<typeof normalizeFailoverDecisionObservationBase>[0]>,
@@ -51,3 +55,72 @@ describe("normalizeFailoverDecisionObservationBase", () => {
});
});
});
describe("createFailoverDecisionLogger", () => {
afterEach(() => {
vi.restoreAllMocks();
});
it("includes from and to model refs when the source differs from the selected target", () => {
const warnSpy = vi.spyOn(log, "warn").mockImplementation(() => {});
const logDecision = createFailoverDecisionLogger({
stage: "assistant",
runId: "run:failover",
rawError: "timeout",
failoverReason: "timeout",
profileFailureReason: "timeout",
provider: "openai",
model: "gpt-5.4",
sourceProvider: "github-copilot",
sourceModel: "gpt-5.4-mini",
profileId: "openai:p1",
fallbackConfigured: true,
timedOut: true,
aborted: false,
});
logDecision("fallback_model");
expect(warnSpy).toHaveBeenCalledWith(
"embedded run failover decision",
expect.objectContaining({
sourceProvider: "github-copilot",
sourceModel: "gpt-5.4-mini",
provider: "openai",
model: "gpt-5.4",
consoleMessage: expect.stringContaining("from=github-copilot/gpt-5.4-mini"),
}),
);
expect(
(warnSpy.mock.calls[0]?.[1] as { consoleMessage?: string } | undefined)?.consoleMessage,
).toContain("to=openai/gpt-5.4");
});
it("omits to model refs when the source matches the selected target", () => {
const warnSpy = vi.spyOn(log, "warn").mockImplementation(() => {});
const logDecision = createFailoverDecisionLogger({
stage: "assistant",
runId: "run:same-model",
rawError: "timeout",
failoverReason: "timeout",
profileFailureReason: "timeout",
provider: "openai",
model: "gpt-5.4",
sourceProvider: "openai",
sourceModel: "gpt-5.4",
profileId: "openai:p1",
fallbackConfigured: true,
timedOut: true,
aborted: false,
});
logDecision("surface_error");
expect(
(warnSpy.mock.calls[0]?.[1] as { consoleMessage?: string } | undefined)?.consoleMessage,
).toContain("from=openai/gpt-5.4");
expect(
(warnSpy.mock.calls[0]?.[1] as { consoleMessage?: string } | undefined)?.consoleMessage,
).not.toContain("to=openai/gpt-5.4");
});
});

View File

@@ -16,6 +16,8 @@ export type FailoverDecisionLoggerInput = {
profileFailureReason?: AuthProfileFailureReason | null;
provider: string;
model: string;
sourceProvider?: string;
sourceModel?: string;
profileId?: string;
fallbackConfigured: boolean;
timedOut?: boolean;
@@ -48,8 +50,11 @@ export function createFailoverDecisionLogger(
const safeRunId = sanitizeForConsole(normalizedBase.runId) ?? "-";
const safeProvider = sanitizeForConsole(normalizedBase.provider) ?? "-";
const safeModel = sanitizeForConsole(normalizedBase.model) ?? "-";
const safeSourceProvider = sanitizeForConsole(normalizedBase.sourceProvider) ?? safeProvider;
const safeSourceModel = sanitizeForConsole(normalizedBase.sourceModel) ?? safeModel;
const profileText = safeProfileId ?? "-";
const reasonText = normalizedBase.failoverReason ?? "none";
const sourceChanged = safeSourceProvider !== safeProvider || safeSourceModel !== safeModel;
return (decision, extra) => {
const observedError = buildApiErrorObservationFields(normalizedBase.rawError);
log.warn("embedded run failover decision", {
@@ -62,6 +67,8 @@ export function createFailoverDecisionLogger(
profileFailureReason: normalizedBase.profileFailureReason,
provider: normalizedBase.provider,
model: normalizedBase.model,
sourceProvider: normalizedBase.sourceProvider ?? normalizedBase.provider,
sourceModel: normalizedBase.sourceModel ?? normalizedBase.model,
profileId: safeProfileId,
fallbackConfigured: normalizedBase.fallbackConfigured,
timedOut: normalizedBase.timedOut,
@@ -70,7 +77,8 @@ export function createFailoverDecisionLogger(
...observedError,
consoleMessage:
`embedded run failover decision: runId=${safeRunId} stage=${normalizedBase.stage} decision=${decision} ` +
`reason=${reasonText} provider=${safeProvider}/${safeModel} profile=${profileText}`,
`reason=${reasonText} from=${safeSourceProvider}/${safeSourceModel}` +
`${sourceChanged ? ` to=${safeProvider}/${safeModel}` : ""} profile=${profileText}`,
});
};
}

View File

@@ -1,6 +1,6 @@
import type { AssistantMessage } from "@mariozechner/pi-ai";
import { describe, expect, it } from "vitest";
import { resolveFinalAssistantVisibleText } from "./helpers.js";
import { resolveFinalAssistantRawText, resolveFinalAssistantVisibleText } from "./helpers.js";
function makeAssistantMessage(
content: AssistantMessage["content"],
@@ -61,3 +61,33 @@ describe("resolveFinalAssistantVisibleText", () => {
expect(resolveFinalAssistantVisibleText(lastAssistant)).toBeUndefined();
});
});
describe("resolveFinalAssistantRawText", () => {
it("preserves commentary and final answer text", () => {
const lastAssistant = makeAssistantMessage([
{
type: "text",
text: "Working...",
textSignature: JSON.stringify({ v: 1, id: "item_commentary", phase: "commentary" }),
},
{
type: "text",
text: "Section 1\nSection 2",
textSignature: JSON.stringify({ v: 1, id: "item_final", phase: "final_answer" }),
},
]);
expect(resolveFinalAssistantRawText(lastAssistant)).toBe("Working...\nSection 1\nSection 2");
});
it("returns undefined when the final raw text is empty", () => {
const lastAssistant = makeAssistantMessage([
{
type: "text",
text: " ",
},
]);
expect(resolveFinalAssistantRawText(lastAssistant)).toBeUndefined();
});
});

View File

@@ -1,7 +1,7 @@
import type { AssistantMessage } from "@mariozechner/pi-ai";
import type { OpenClawConfig } from "../../../config/types.openclaw.js";
import { generateSecureToken } from "../../../infra/secure-random.js";
import { extractAssistantVisibleText } from "../../pi-embedded-utils.js";
import { extractAssistantText, extractAssistantVisibleText } from "../../pi-embedded-utils.js";
import { derivePromptTokens, normalizeUsage } from "../../usage.js";
import type { EmbeddedPiAgentMeta } from "../types.js";
import { toLastCallUsage, toNormalizedUsage, type UsageAccumulator } from "../usage-accumulator.js";
@@ -153,3 +153,13 @@ export function resolveFinalAssistantVisibleText(
const visibleText = extractAssistantVisibleText(lastAssistant).trim();
return visibleText || undefined;
}
export function resolveFinalAssistantRawText(
lastAssistant: AssistantMessage | undefined,
): string | undefined {
if (!lastAssistant) {
return undefined;
}
const rawText = extractAssistantText(lastAssistant).trim();
return rawText || undefined;
}