diff --git a/changelog.d/fixes/0000-skills-timeout-status.md b/changelog.d/fixes/0000-skills-timeout-status.md new file mode 100644 index 0000000000..ad33867634 --- /dev/null +++ b/changelog.d/fixes/0000-skills-timeout-status.md @@ -0,0 +1 @@ +- **fix(skills):** a skill that outlives the executor timeout is now recorded as `timeout` instead of `error`, so execution history and analytics can tell timeouts from handler failures. The race timer is also cleared once the handler settles; it used to stay pending for the full timeout (30 s by default) after every execution. diff --git a/src/lib/skills/executor.ts b/src/lib/skills/executor.ts index 06cc96a646..e39bdfb93b 100644 --- a/src/lib/skills/executor.ts +++ b/src/lib/skills/executor.ts @@ -13,6 +13,13 @@ import { logger } from "../../../open-sse/utils/logger.ts"; const log = logger("SKILLS_EXECUTOR"); +class SkillTimeoutError extends Error { + constructor() { + super("Skill execution timed out"); + this.name = "SkillTimeoutError"; + } +} + function toSafeSkillErrorMessage(value: unknown): string { try { const raw = value instanceof Error ? value.message : value; @@ -286,12 +293,15 @@ class SkillExecutor { } private async executeWithTimeout(promise: Promise): Promise { - return Promise.race([ - promise, - new Promise((_, reject) => - setTimeout(() => reject(new Error("Skill execution timed out")), this.timeout) - ), - ]); + let timer: ReturnType | undefined; + const timeout = new Promise((_, reject) => { + timer = setTimeout(() => reject(new SkillTimeoutError()), this.timeout); + }); + try { + return await Promise.race([promise, timeout]); + } finally { + clearTimeout(timer); + } } /** @@ -343,7 +353,7 @@ class SkillExecutor { } } catch (err) { errorMessage = toSafeSkillErrorMessage(err); - status = SkillStatus.ERROR; + status = err instanceof SkillTimeoutError ? SkillStatus.TIMEOUT : SkillStatus.ERROR; } return { output, errorMessage, status }; diff --git a/tests/unit/characterization-skills.test.ts b/tests/unit/characterization-skills.test.ts index 93a22fc7b5..4d5c881447 100644 --- a/tests/unit/characterization-skills.test.ts +++ b/tests/unit/characterization-skills.test.ts @@ -31,8 +31,7 @@ function uniqueName(prefix: string) { return `${prefix}-${randomUUID().slice(0, 8)}`; } -// Short executor timeout so the timeout case runs fast. NOTE: executeWithTimeout never -// clears its timer, so every execution leaves a pending timer of this length behind. +// Short executor timeout so the timeout case runs fast. skillExecutor.setTimeout(200); skillExecutor.registerHandler("char-echo", async (input) => ({ echoed: String(input.text) })); @@ -323,7 +322,7 @@ test("execute: a failure-shaped output and a throwing handler both resolve with assert.equal(hardRun.output, null); }); -test("characterization: a timed-out skill is currently recorded as status error, never timeout", async () => { +test("a timed-out skill is recorded as status timeout", async () => { const name = uniqueName("char-slow"); await skillRegistry.register({ name, @@ -332,9 +331,8 @@ test("characterization: a timed-out skill is currently recorded as status error, apiKeyId: "char-slow", }); const run = await skillExecutor.execute(name, {}, { apiKeyId: "char-slow" }); - // SkillStatus.TIMEOUT exists and the DB CHECK allows 'timeout', but the executor maps a - // timeout to ERROR with this message. - assert.equal(run.status, SkillStatus.ERROR); + // A timeout is recorded as SkillStatus.TIMEOUT (#16187), not as a generic handler error. + assert.equal(run.status, SkillStatus.TIMEOUT); assert.equal(run.errorMessage, "Skill execution timed out"); }); diff --git a/tests/unit/skills-executor-timeout.test.ts b/tests/unit/skills-executor-timeout.test.ts new file mode 100644 index 0000000000..247fce608b --- /dev/null +++ b/tests/unit/skills-executor-timeout.test.ts @@ -0,0 +1,57 @@ +import test from "node:test"; +import assert from "node:assert/strict"; +import { randomUUID } from "node:crypto"; +import "../_setup/isolateDataDir.ts"; + +process.env.DISABLE_SQLITE_AUTO_BACKUP ||= "true"; + +const core = await import("../../src/lib/db/core.ts"); +const { skillRegistry } = await import("../../src/lib/skills/registry.ts"); +const { skillExecutor } = await import("../../src/lib/skills/executor.ts"); +const { SkillStatus } = await import("../../src/lib/skills/types.ts"); + +const SCHEMA = { input: {}, output: {} }; +const API_KEY_ID = "executor-timeout"; + +skillExecutor.registerHandler("timeout-fast", async () => ({ ok: true })); +skillExecutor.registerHandler("timeout-slow", () => new Promise(() => {})); + +test.after(() => { + core.resetDbInstance(); +}); + +function pendingTimers(): number { + return process.getActiveResourcesInfo().filter((name) => name === "Timeout").length; +} + +async function registerSkill(handler: string) { + const name = `${handler}-${randomUUID().slice(0, 8)}`; + await skillRegistry.register({ name, schema: SCHEMA, handler, apiKeyId: API_KEY_ID }); + return name; +} + +test("a skill that outlives the executor timeout is recorded as timeout and persisted that way", async () => { + skillExecutor.setTimeout(100); + const name = await registerSkill("timeout-slow"); + const run = await skillExecutor.execute(name, {}, { apiKeyId: API_KEY_ID }); + assert.equal(run.status, SkillStatus.TIMEOUT); + assert.equal(run.errorMessage, "Skill execution timed out"); + + const row = core + .getDbInstance() + .prepare("SELECT status FROM skill_executions WHERE id = ?") + .get(run.id) as { status: string }; + assert.equal(row.status, "timeout"); +}); + +test("a handler that settles in time leaves no pending timeout timer behind", async () => { + skillExecutor.setTimeout(30_000); + const name = await registerSkill("timeout-fast"); + const before = pendingTimers(); + const run = await skillExecutor.execute(name, {}, { apiKeyId: API_KEY_ID }); + assert.equal(run.status, SkillStatus.SUCCESS); + assert.ok( + pendingTimers() <= before, + "the 30s race timer must be cleared once the handler settles" + ); +}); diff --git a/tests/unit/skills-executor.test.ts b/tests/unit/skills-executor.test.ts index 7a95793745..28cb87f111 100644 --- a/tests/unit/skills-executor.test.ts +++ b/tests/unit/skills-executor.test.ts @@ -242,7 +242,7 @@ test("skillExecutor records disabled skills and missing skills as direct failure assert.equal(skillExecutor.listExecutions("key-a").length, 0); }); -test("skillExecutor turns handler errors and timeouts into error executions", async () => { +test("skillExecutor records handler errors as error and timeouts as timeout", async () => { await registerEchoSkill(); skillExecutor.registerHandler("echo-handler", async () => { @@ -289,7 +289,7 @@ test("skillExecutor turns handler errors and timeouts into error executions", as ); assert.equal(skillExecutor["maxRetries"], 7); - assert.equal(timedOut.status, "error"); + assert.equal(timedOut.status, "timeout"); assert.equal(timedOut.output, null); assert.match(timedOut.errorMessage, /timed out/i); });