Merge pull request #2249 from code-yeongyu/fix/pr-2173-timeout-issues
fix(delegate-task): resolve timeout handling regressions from #2173
This commit is contained in:
commit
785dd529e1
@ -1,6 +1,6 @@
|
|||||||
declare const require: (name: string) => any
|
declare const require: (name: string) => any
|
||||||
const { describe, test, expect, beforeEach, afterEach } = require("bun:test")
|
const { describe, test, expect, beforeEach, afterEach } = require("bun:test")
|
||||||
import { __setTimingConfig, __resetTimingConfig, DEFAULT_SYNC_POLL_TIMEOUT_MS } from "./timing"
|
import { __setTimingConfig, __resetTimingConfig, getTimingConfig } from "./timing"
|
||||||
|
|
||||||
function createMockCtx(aborted = false) {
|
function createMockCtx(aborted = false) {
|
||||||
const controller = new AbortController()
|
const controller = new AbortController()
|
||||||
@ -78,8 +78,7 @@ describe("syncPollTimeoutMs threading", () => {
|
|||||||
test("#then default timeout constant is used", async () => {
|
test("#then default timeout constant is used", async () => {
|
||||||
const { pollSyncSession } = require("./sync-session-poller")
|
const { pollSyncSession } = require("./sync-session-poller")
|
||||||
const mockClient = createNeverCompleteClient("ses_default")
|
const mockClient = createNeverCompleteClient("ses_default")
|
||||||
|
const { MAX_POLL_TIME_MS } = getTimingConfig()
|
||||||
expect(DEFAULT_SYNC_POLL_TIMEOUT_MS).toBe(600_000)
|
|
||||||
|
|
||||||
await withMockedDateNow(300_000, async () => {
|
await withMockedDateNow(300_000, async () => {
|
||||||
const result = await pollSyncSession(createMockCtx(), mockClient, {
|
const result = await pollSyncSession(createMockCtx(), mockClient, {
|
||||||
@ -89,7 +88,25 @@ describe("syncPollTimeoutMs threading", () => {
|
|||||||
taskId: undefined,
|
taskId: undefined,
|
||||||
})
|
})
|
||||||
|
|
||||||
expect(result).toBe(`Poll timeout reached after ${DEFAULT_SYNC_POLL_TIMEOUT_MS}ms for session ses_default`)
|
expect(result).toBe(`Poll timeout reached after ${MAX_POLL_TIME_MS}ms for session ses_default`)
|
||||||
|
})
|
||||||
|
})
|
||||||
|
|
||||||
|
test("#then MAX_POLL_TIME_MS override is respected for backward compatibility", async () => {
|
||||||
|
const { pollSyncSession } = require("./sync-session-poller")
|
||||||
|
const mockClient = createNeverCompleteClient("ses_legacy")
|
||||||
|
|
||||||
|
__setTimingConfig({ MAX_POLL_TIME_MS: 120_000 })
|
||||||
|
|
||||||
|
await withMockedDateNow(60_000, async () => {
|
||||||
|
const result = await pollSyncSession(createMockCtx(), mockClient, {
|
||||||
|
sessionID: "ses_legacy",
|
||||||
|
agentToUse: "test-agent",
|
||||||
|
toastManager: null,
|
||||||
|
taskId: undefined,
|
||||||
|
})
|
||||||
|
|
||||||
|
expect(result).toBe("Poll timeout reached after 120000ms for session ses_legacy")
|
||||||
})
|
})
|
||||||
})
|
})
|
||||||
})
|
})
|
||||||
@ -169,7 +186,7 @@ describe("syncPollTimeoutMs threading", () => {
|
|||||||
)
|
)
|
||||||
|
|
||||||
expect(statusCallCount).toBe(0)
|
expect(statusCallCount).toBe(0)
|
||||||
expect(result).toContain("SUPERVISED TASK COMPLETED SUCCESSFULLY")
|
expect(result).toContain("SUPERVISED TASK TIMED OUT")
|
||||||
})
|
})
|
||||||
})
|
})
|
||||||
})
|
})
|
||||||
|
|||||||
@ -1,6 +1,6 @@
|
|||||||
import type { ToolContextWithMetadata, OpencodeClient } from "./types"
|
import type { ToolContextWithMetadata, OpencodeClient } from "./types"
|
||||||
import type { SessionMessage } from "./executor-types"
|
import type { SessionMessage } from "./executor-types"
|
||||||
import { DEFAULT_SYNC_POLL_TIMEOUT_MS, getTimingConfig } from "./timing"
|
import { getDefaultSyncPollTimeoutMs, getTimingConfig } from "./timing"
|
||||||
import { log } from "../../shared/logger"
|
import { log } from "../../shared/logger"
|
||||||
import { normalizeSDKResponse } from "../../shared"
|
import { normalizeSDKResponse } from "../../shared"
|
||||||
|
|
||||||
@ -36,7 +36,7 @@ export async function pollSyncSession(
|
|||||||
timeoutMs?: number
|
timeoutMs?: number
|
||||||
): Promise<string | null> {
|
): Promise<string | null> {
|
||||||
const syncTiming = getTimingConfig()
|
const syncTiming = getTimingConfig()
|
||||||
const maxPollTimeMs = Math.max(timeoutMs ?? DEFAULT_SYNC_POLL_TIMEOUT_MS, 50)
|
const maxPollTimeMs = Math.max(timeoutMs ?? getDefaultSyncPollTimeoutMs(), 50)
|
||||||
const pollStart = Date.now()
|
const pollStart = Date.now()
|
||||||
let pollCount = 0
|
let pollCount = 0
|
||||||
let timedOut = false
|
let timedOut = false
|
||||||
|
|||||||
18
src/tools/delegate-task/timing.test.ts
Normal file
18
src/tools/delegate-task/timing.test.ts
Normal file
@ -0,0 +1,18 @@
|
|||||||
|
declare const require: (name: string) => any
|
||||||
|
const { describe, expect, test } = require("bun:test")
|
||||||
|
import { __resetTimingConfig, __setTimingConfig, getDefaultSyncPollTimeoutMs } from "./timing"
|
||||||
|
|
||||||
|
describe("timing sync poll timeout defaults", () => {
|
||||||
|
test("default sync timeout accessor follows MAX_POLL_TIME_MS config", () => {
|
||||||
|
// #given
|
||||||
|
__resetTimingConfig()
|
||||||
|
|
||||||
|
// #when
|
||||||
|
__setTimingConfig({ MAX_POLL_TIME_MS: 123_456 })
|
||||||
|
|
||||||
|
// #then
|
||||||
|
expect(getDefaultSyncPollTimeoutMs()).toBe(123_456)
|
||||||
|
|
||||||
|
__resetTimingConfig()
|
||||||
|
})
|
||||||
|
})
|
||||||
@ -3,10 +3,15 @@ let MIN_STABILITY_TIME_MS = 10000
|
|||||||
let STABILITY_POLLS_REQUIRED = 3
|
let STABILITY_POLLS_REQUIRED = 3
|
||||||
let WAIT_FOR_SESSION_INTERVAL_MS = 100
|
let WAIT_FOR_SESSION_INTERVAL_MS = 100
|
||||||
let WAIT_FOR_SESSION_TIMEOUT_MS = 30000
|
let WAIT_FOR_SESSION_TIMEOUT_MS = 30000
|
||||||
let MAX_POLL_TIME_MS = 10 * 60 * 1000
|
const DEFAULT_POLL_TIMEOUT_MS = 10 * 60 * 1000
|
||||||
|
let MAX_POLL_TIME_MS = DEFAULT_POLL_TIMEOUT_MS
|
||||||
let SESSION_CONTINUATION_STABILITY_MS = 5000
|
let SESSION_CONTINUATION_STABILITY_MS = 5000
|
||||||
|
|
||||||
export const DEFAULT_SYNC_POLL_TIMEOUT_MS = 600_000
|
export const DEFAULT_SYNC_POLL_TIMEOUT_MS = DEFAULT_POLL_TIMEOUT_MS
|
||||||
|
|
||||||
|
export function getDefaultSyncPollTimeoutMs(): number {
|
||||||
|
return MAX_POLL_TIME_MS
|
||||||
|
}
|
||||||
|
|
||||||
export function getTimingConfig() {
|
export function getTimingConfig() {
|
||||||
return {
|
return {
|
||||||
@ -26,7 +31,7 @@ export function __resetTimingConfig(): void {
|
|||||||
STABILITY_POLLS_REQUIRED = 3
|
STABILITY_POLLS_REQUIRED = 3
|
||||||
WAIT_FOR_SESSION_INTERVAL_MS = 100
|
WAIT_FOR_SESSION_INTERVAL_MS = 100
|
||||||
WAIT_FOR_SESSION_TIMEOUT_MS = 30000
|
WAIT_FOR_SESSION_TIMEOUT_MS = 30000
|
||||||
MAX_POLL_TIME_MS = 10 * 60 * 1000
|
MAX_POLL_TIME_MS = DEFAULT_POLL_TIMEOUT_MS
|
||||||
SESSION_CONTINUATION_STABILITY_MS = 5000
|
SESSION_CONTINUATION_STABILITY_MS = 5000
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@ -79,6 +79,7 @@ export async function executeUnstableAgentTask(
|
|||||||
let lastMsgCount = 0
|
let lastMsgCount = 0
|
||||||
let stablePolls = 0
|
let stablePolls = 0
|
||||||
let terminalStatus: { status: string; error?: string } | undefined
|
let terminalStatus: { status: string; error?: string } | undefined
|
||||||
|
let completedDuringMonitoring = false
|
||||||
|
|
||||||
while (Date.now() - pollStart < (syncPollTimeoutMs ?? DEFAULT_SYNC_POLL_TIMEOUT_MS)) {
|
while (Date.now() - pollStart < (syncPollTimeoutMs ?? DEFAULT_SYNC_POLL_TIMEOUT_MS)) {
|
||||||
if (ctx.abort?.aborted) {
|
if (ctx.abort?.aborted) {
|
||||||
@ -113,7 +114,10 @@ export async function executeUnstableAgentTask(
|
|||||||
|
|
||||||
if (currentMsgCount === lastMsgCount) {
|
if (currentMsgCount === lastMsgCount) {
|
||||||
stablePolls++
|
stablePolls++
|
||||||
if (stablePolls >= timingCfg.STABILITY_POLLS_REQUIRED) break
|
if (stablePolls >= timingCfg.STABILITY_POLLS_REQUIRED) {
|
||||||
|
completedDuringMonitoring = true
|
||||||
|
break
|
||||||
|
}
|
||||||
} else {
|
} else {
|
||||||
stablePolls = 0
|
stablePolls = 0
|
||||||
lastMsgCount = currentMsgCount
|
lastMsgCount = currentMsgCount
|
||||||
@ -133,6 +137,25 @@ Model: ${actualModel}
|
|||||||
|
|
||||||
The task session may contain partial results.
|
The task session may contain partial results.
|
||||||
|
|
||||||
|
<task_metadata>
|
||||||
|
session_id: ${sessionID}
|
||||||
|
</task_metadata>`
|
||||||
|
}
|
||||||
|
|
||||||
|
if (!completedDuringMonitoring) {
|
||||||
|
const duration = formatDuration(startTime)
|
||||||
|
const timeoutBudgetMs = syncPollTimeoutMs ?? DEFAULT_SYNC_POLL_TIMEOUT_MS
|
||||||
|
return `SUPERVISED TASK TIMED OUT
|
||||||
|
|
||||||
|
Task did not reach a stable completion signal within the monitored timeout budget.
|
||||||
|
Timeout budget: ${timeoutBudgetMs}ms
|
||||||
|
|
||||||
|
Duration: ${duration}
|
||||||
|
Agent: ${agentToUse}${args.category ? ` (category: ${args.category})` : ""}
|
||||||
|
Model: ${actualModel}
|
||||||
|
|
||||||
|
The task session may still contain partial results.
|
||||||
|
|
||||||
<task_metadata>
|
<task_metadata>
|
||||||
session_id: ${sessionID}
|
session_id: ${sessionID}
|
||||||
</task_metadata>`
|
</task_metadata>`
|
||||||
|
|||||||
81
src/tools/delegate-task/unstable-agent-timeout.test.ts
Normal file
81
src/tools/delegate-task/unstable-agent-timeout.test.ts
Normal file
@ -0,0 +1,81 @@
|
|||||||
|
declare const require: (name: string) => any
|
||||||
|
const { describe, test, expect, beforeEach, afterEach } = require("bun:test")
|
||||||
|
import { __setTimingConfig, __resetTimingConfig } from "./timing"
|
||||||
|
|
||||||
|
describe("executeUnstableAgentTask timeout handling", () => {
|
||||||
|
beforeEach(() => {
|
||||||
|
__setTimingConfig({
|
||||||
|
POLL_INTERVAL_MS: 10,
|
||||||
|
MIN_STABILITY_TIME_MS: 0,
|
||||||
|
STABILITY_POLLS_REQUIRED: 1,
|
||||||
|
WAIT_FOR_SESSION_TIMEOUT_MS: 100,
|
||||||
|
WAIT_FOR_SESSION_INTERVAL_MS: 10,
|
||||||
|
})
|
||||||
|
})
|
||||||
|
|
||||||
|
afterEach(() => {
|
||||||
|
__resetTimingConfig()
|
||||||
|
})
|
||||||
|
|
||||||
|
test("returns timeout status instead of success when monitored poll budget is exhausted", async () => {
|
||||||
|
// #given
|
||||||
|
const { executeUnstableAgentTask } = require("./unstable-agent-task")
|
||||||
|
|
||||||
|
const mockManager = {
|
||||||
|
launch: async () => ({ id: "task_001", sessionID: "ses_timeout", status: "running" }),
|
||||||
|
getTask: () => ({ id: "task_001", sessionID: "ses_timeout", status: "running" }),
|
||||||
|
}
|
||||||
|
|
||||||
|
const mockClient = {
|
||||||
|
session: {
|
||||||
|
status: async () => ({ data: { ses_timeout: { type: "running" } } }),
|
||||||
|
messages: async () => ({
|
||||||
|
data: [
|
||||||
|
{
|
||||||
|
info: { id: "msg_002", role: "assistant", time: { created: 2000 } },
|
||||||
|
parts: [{ type: "text", text: "This should not be treated as success" }],
|
||||||
|
},
|
||||||
|
],
|
||||||
|
}),
|
||||||
|
},
|
||||||
|
}
|
||||||
|
|
||||||
|
const args = {
|
||||||
|
description: "timeout case",
|
||||||
|
prompt: "run",
|
||||||
|
category: "unspecified-low",
|
||||||
|
run_in_background: false,
|
||||||
|
load_skills: [],
|
||||||
|
command: undefined,
|
||||||
|
}
|
||||||
|
|
||||||
|
// #when
|
||||||
|
const result = await executeUnstableAgentTask(
|
||||||
|
args,
|
||||||
|
{
|
||||||
|
sessionID: "parent-session",
|
||||||
|
messageID: "parent-message",
|
||||||
|
metadata: () => Promise.resolve(),
|
||||||
|
},
|
||||||
|
{
|
||||||
|
manager: mockManager,
|
||||||
|
client: mockClient,
|
||||||
|
syncPollTimeoutMs: 0,
|
||||||
|
},
|
||||||
|
{
|
||||||
|
sessionID: "parent-session",
|
||||||
|
messageID: "parent-message",
|
||||||
|
model: "gpt-test",
|
||||||
|
agent: "test-agent",
|
||||||
|
},
|
||||||
|
"test-agent",
|
||||||
|
undefined,
|
||||||
|
undefined,
|
||||||
|
"gpt-test"
|
||||||
|
)
|
||||||
|
|
||||||
|
// #then
|
||||||
|
expect(result).toContain("TIMED OUT")
|
||||||
|
expect(result).not.toContain("SUPERVISED TASK COMPLETED SUCCESSFULLY")
|
||||||
|
})
|
||||||
|
})
|
||||||
Loading…
x
Reference in New Issue
Block a user