fix(voice-call): summarize restored call verification logs

This commit is contained in:
Peter Steinberger
2026-05-02 11:02:23 +01:00
parent ab0f8a79ca
commit 4e82cacc84
3 changed files with 182 additions and 16 deletions

View File

@@ -290,6 +290,7 @@ Docs: https://docs.openclaw.ai
- QA Lab: stop gateway children when the suite parent disappears, so interrupted local QA runs cannot leave hot orphaned gateways behind.
- Codex/app-server: tolerate a second connection close during startup recovery and include retry counts plus stringified errors in the restart warning, so concurrent lanes do not fail after one shared-client race.
- Plugins/CLI: cache plugin CLI registration entries per command program so completion state generation does not repeat the full plugin sweep in one invocation. Thanks @ScientificProgrammer.
- Voice Call: summarize restored-call verification logs during startup while preserving expired-call cleanup, reducing duplicate per-call skip messages. Thanks @jckm14.
- Plugins: reuse gateway-bindable plugin loader cache entries for later default-mode loads without serving default-built registries to gateway-bound requests, reducing repeated plugin registration during dispatch. Refs #61756. Thanks @DmitryPogodaev.
- Gateway/secrets: include the caught error message in `secrets.reload` and `secrets.resolve` warning logs while keeping RPC errors generic, so operators can diagnose reload and permission failures. Thanks @davidangularme.
- Providers/OpenRouter: fill DeepSeek V4 `reasoning_content` replay placeholders for `openrouter/deepseek/deepseek-v4-flash` and `openrouter/deepseek/deepseek-v4-pro`, so thinking/tool follow-up turns do not fail with DeepSeek's replay-shape error. Fixes #76018. Thanks @cloph-dsp.

View File

@@ -22,6 +22,7 @@ function requireSingleActiveCall(manager: CallManager) {
describe("CallManager verification on restore", () => {
afterEach(() => {
vi.useRealTimers();
vi.restoreAllMocks();
});
async function initializeManager(params?: {
@@ -121,6 +122,129 @@ describe("CallManager verification on restore", () => {
expect(activeCall.state).toBe(call.state);
});
it("summarizes repeated restored-call verification outcomes", async () => {
const now = Date.now();
const storePath = createTestStorePath();
const calls = [
makePersistedCall({
callId: "missing-provider-a",
providerCallId: undefined,
state: "initiated",
startedAt: now - 10_000,
answeredAt: undefined,
}),
makePersistedCall({
callId: "missing-provider-b",
providerCallId: undefined,
state: "initiated",
startedAt: now - 10_000,
answeredAt: undefined,
}),
makePersistedCall({
callId: "expired-a",
providerCallId: "expired-provider-a",
state: "initiated",
startedAt: now - 600_000,
answeredAt: undefined,
}),
makePersistedCall({
callId: "terminal-a",
providerCallId: "terminal-provider-a",
state: "initiated",
startedAt: now - 20_000,
answeredAt: undefined,
}),
makePersistedCall({
callId: "terminal-b",
providerCallId: "terminal-provider-b",
state: "initiated",
startedAt: now - 20_000,
answeredAt: undefined,
}),
makePersistedCall({
callId: "unknown-a",
providerCallId: "unknown-provider-a",
state: "initiated",
startedAt: now - 20_000,
answeredAt: undefined,
}),
makePersistedCall({
callId: "active-a",
providerCallId: "active-provider-a",
state: "initiated",
startedAt: now - 20_000,
answeredAt: undefined,
}),
makePersistedCall({
callId: "failure-a",
providerCallId: "failure-provider-a",
state: "initiated",
startedAt: now - 20_000,
answeredAt: undefined,
}),
];
writeCallsToStore(storePath, calls);
const provider = new FakeProvider();
provider.getCallStatus = async ({ providerCallId }) => {
if (providerCallId.startsWith("terminal-provider")) {
return { status: "completed", isTerminal: true };
}
if (providerCallId.startsWith("unknown-provider")) {
return { status: "unknown", isTerminal: false, isUnknown: true };
}
if (providerCallId.startsWith("active-provider")) {
return { status: "in-progress", isTerminal: false };
}
throw new Error("network failure");
};
const config = VoiceCallConfigSchema.parse({
enabled: true,
provider: "plivo",
fromNumber: "+15550000000",
maxDurationSeconds: 300,
});
const logSpy = vi.spyOn(console, "log").mockImplementation(() => {});
const manager = new CallManager(config, storePath);
await manager.initialize(provider, "https://example.com/voice/webhook");
expect(
manager
.getActiveCalls()
.map((call) => call.callId)
.toSorted(),
).toEqual(["active-a", "failure-a", "unknown-a"]);
expect(provider.hangupCalls).toEqual([
expect.objectContaining({
callId: "expired-a",
providerCallId: "expired-provider-a",
reason: "timeout",
}),
]);
expect(logSpy).toHaveBeenCalledWith(
"[voice-call] Skipped 2 restored call(s) with no providerCallId",
);
expect(logSpy).toHaveBeenCalledWith(
"[voice-call] Skipped 1 restored call(s) older than maxDurationSeconds",
);
expect(logSpy).toHaveBeenCalledWith(
"[voice-call] Skipped 2 restored call(s) with provider status: completed",
);
expect(logSpy).toHaveBeenCalledWith(
"[voice-call] Kept 1 restored call(s) confirmed active by provider",
);
expect(logSpy).toHaveBeenCalledWith(
"[voice-call] Kept 1 restored call(s) with unknown provider status (relying on timer)",
);
expect(logSpy).toHaveBeenCalledWith(
"[voice-call] Kept 1 restored call(s) after verification failure (relying on timer)",
);
expect(logSpy.mock.calls.map((call) => String(call[0])).join("\n")).not.toContain("terminal-a");
logSpy.mockRestore();
});
it("uses only remaining max duration for restored answered calls", async () => {
vi.useFakeTimers();
const now = new Date("2026-03-17T03:07:00Z");

View File

@@ -37,6 +37,14 @@ function markRestoredCallSkipped(call: CallRecord, endReason: "completed" | "tim
call.state = endReason;
}
function incrementRestoreStatusCount(
counts: Map<string, number>,
status: string | undefined,
): void {
const key = normalizeOptionalString(status) ?? "terminal";
counts.set(key, (counts.get(key) ?? 0) + 1);
}
function resolveDefaultStoreBase(config: VoiceCallConfig, storePath?: string): string {
const rawOverride = storePath?.trim() || config.store?.trim();
if (rawOverride) {
@@ -110,6 +118,7 @@ export class CallManager {
}
// Restart max-duration timers for restored calls that are past the answered state
let skippedAlreadyElapsedTimers = 0;
for (const [callId, call] of verified) {
if (call.answeredAt && !TerminalStates.has(call.state)) {
const elapsed = Date.now() - call.answeredAt;
@@ -120,9 +129,7 @@ export class CallManager {
if (call.providerCallId) {
this.providerCallIdMap.delete(call.providerCallId);
}
console.log(
`[voice-call] Skipping restored call ${callId} (max duration already elapsed)`,
);
skippedAlreadyElapsedTimers += 1;
continue;
}
startMaxDurationTimer({
@@ -136,6 +143,11 @@ export class CallManager {
console.log(`[voice-call] Restarted max-duration timer for restored call ${callId}`);
}
}
if (skippedAlreadyElapsedTimers > 0) {
console.log(
`[voice-call] Skipped ${skippedAlreadyElapsedTimers} restored call(s) whose max-duration timer already elapsed`,
);
}
if (verified.size > 0) {
console.log(`[voice-call] Restored ${verified.size} active call(s) from store`);
@@ -159,19 +171,23 @@ export class CallManager {
const now = Date.now();
const verified = new Map<CallId, CallRecord>();
const verifyTasks: Array<{ callId: CallId; call: CallRecord; promise: Promise<void> }> = [];
let skippedNoProviderCallId = 0;
let skippedOlderThanMaxDuration = 0;
const skippedTerminalStatuses = new Map<string, number>();
let keptVerifiedActive = 0;
let keptUnknownProviderStatus = 0;
let keptVerificationFailures = 0;
for (const [callId, call] of candidates) {
// Skip calls without a provider ID — can't verify
if (!call.providerCallId) {
console.log(`[voice-call] Skipping restored call ${callId} (no providerCallId)`);
skippedNoProviderCallId += 1;
continue;
}
// Skip calls older than maxDurationSeconds (time-based fallback)
if (now - call.startedAt > maxAgeMs) {
console.log(
`[voice-call] Skipping restored call ${callId} (older than maxDurationSeconds)`,
);
skippedOlderThanMaxDuration += 1;
markRestoredCallSkipped(call, "timeout");
persistCallRecord(this.storePath, call);
await provider
@@ -196,25 +212,20 @@ export class CallManager {
.getCallStatus({ providerCallId: call.providerCallId })
.then((result) => {
if (result.isTerminal) {
console.log(
`[voice-call] Skipping restored call ${callId} (provider status: ${result.status})`,
);
incrementRestoreStatusCount(skippedTerminalStatuses, result.status);
markRestoredCallSkipped(call, "completed");
persistCallRecord(this.storePath, call);
} else if (result.isUnknown) {
console.log(
`[voice-call] Keeping restored call ${callId} (provider status unknown, relying on timer)`,
);
keptUnknownProviderStatus += 1;
verified.set(callId, call);
} else {
keptVerifiedActive += 1;
verified.set(callId, call);
}
})
.catch(() => {
// Verification failed entirely — keep the call, rely on timer
console.log(
`[voice-call] Keeping restored call ${callId} (verification failed, relying on timer)`,
);
keptVerificationFailures += 1;
verified.set(callId, call);
}),
};
@@ -222,6 +233,36 @@ export class CallManager {
}
await Promise.allSettled(verifyTasks.map((t) => t.promise));
if (skippedNoProviderCallId > 0) {
console.log(
`[voice-call] Skipped ${skippedNoProviderCallId} restored call(s) with no providerCallId`,
);
}
if (skippedOlderThanMaxDuration > 0) {
console.log(
`[voice-call] Skipped ${skippedOlderThanMaxDuration} restored call(s) older than maxDurationSeconds`,
);
}
for (const [status, count] of [...skippedTerminalStatuses].toSorted(([a], [b]) =>
a.localeCompare(b),
)) {
console.log(`[voice-call] Skipped ${count} restored call(s) with provider status: ${status}`);
}
if (keptVerifiedActive > 0) {
console.log(
`[voice-call] Kept ${keptVerifiedActive} restored call(s) confirmed active by provider`,
);
}
if (keptUnknownProviderStatus > 0) {
console.log(
`[voice-call] Kept ${keptUnknownProviderStatus} restored call(s) with unknown provider status (relying on timer)`,
);
}
if (keptVerificationFailures > 0) {
console.log(
`[voice-call] Kept ${keptVerificationFailures} restored call(s) after verification failure (relying on timer)`,
);
}
return verified;
}