Skip to content

Commit 8a31757

Browse files
authored
fix(execution): treat an undetermined lease as a fallback, not a denial (#7228)
* fix(execution): treat an undetermined lease as a fallback, not a denial The distributed owner lease is a cross-process fairness check, not a correctness lock. A round trip that did not answer before its deadline was reported as a hard failure and rejected the execution, even though the per-process pool and the per-owner active/queued limits still bound the work. - Fall back to the local limits when the lease is undetermined. Only `limit_exceeded` denies an execution, since it is an actual answer. - Rename that outcome from `unavailable` to `undetermined` so the absence of an answer is not read as a negative one, and log it at warn. - Make the round-trip deadline configurable and raise its default. This deadline and the client's `commandTimeout` are both plain timers, so a value near normal event-loop latency misreads a scheduling pause as an unreachable dependency. - Skip the release round trip when no lease was ever registered. * fix(execution): reclaim a lease Redis registers after the local deadline Addresses review findings on the fallback path. - Always release the lease. The deadline abandons the local wait but cannot cancel the script, so a late completion still registers the lease id; leaving it unreleased kept it counted against the owner for the whole TTL and denied later executions that did have capacity. The id is unique per execution, so removing one that was never registered is a no-op. - Treat a non-positive configured deadline as unconfigured. A timer of zero or less fires immediately, which would leave every acquisition undetermined and silently drop cross-replica enforcement. - Cover both with tests: a lease that completes after the deadline is still released, and a non-positive deadline still lets a real answer land. * test(execution): stop the lease deadline override leaking between tests - Add `IVM_LEASE_REDIS_DEADLINE_MS` to the harness env reset. It was absent, so a test that overrode it left the value in the module-scoped mock env for every later test in the file, quietly changing their fallback timing. - Drop the duplicate over-limit test and fold its extra assertion into the existing one; the two had identical setup and covered the same path.
1 parent 34a5300 commit 8a31757

3 files changed

Lines changed: 152 additions & 32 deletions

File tree

apps/sim/lib/core/config/env.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -432,6 +432,7 @@ export const env = createEnv({
432432
IVM_MAX_OWNER_WEIGHT: z.string().optional().default('5'), // Max accepted weight for weighted owner scheduling
433433
IVM_DISTRIBUTED_MAX_INFLIGHT_PER_OWNER:z.string().optional().default('2200'), // Max owner in-flight leases across replicas
434434
IVM_DISTRIBUTED_LEASE_MIN_TTL_MS: z.string().optional().default('120000'), // Min TTL for distributed in-flight leases (ms)
435+
IVM_LEASE_REDIS_DEADLINE_MS: z.string().optional().default('1000'), // Deadline for one distributed lease round trip (ms)
435436
IVM_QUEUE_TIMEOUT_MS: z.string().optional().default('300000'), // Max queue wait before rejection (ms)
436437
IVM_MAX_EXECUTIONS_PER_WORKER: z.string().optional().default('200'), // Max lifetime executions before worker is recycled
437438
IVM_MAX_BROKER_ARGS_JSON_CHARS: z.string().optional().default('262144'), // Max JSON payload size for sandbox task broker args (isolate→host)

apps/sim/lib/execution/isolated-vm.test.ts

Lines changed: 110 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ import {
88
loggerMock,
99
redisConfigMockFns,
1010
} from '@sim/testing'
11+
import { sleep } from '@sim/utils/helpers'
1112
import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'
1213

1314
type MockProc = EventEmitter & {
@@ -184,6 +185,7 @@ const { mockSpawn, mockExecSync, mockEnv } = vi.hoisted(() => ({
184185
IVM_MAX_OWNER_WEIGHT: '5',
185186
IVM_DISTRIBUTED_MAX_INFLIGHT_PER_OWNER: '100',
186187
IVM_DISTRIBUTED_LEASE_MIN_TTL_MS: '1000',
188+
IVM_LEASE_REDIS_DEADLINE_MS: '1000',
187189
IVM_QUEUE_TIMEOUT_MS: '1000',
188190
IVM_MAX_FETCH_RESPONSE_BYTES: '',
189191
IVM_MAX_FETCH_RESPONSE_CHARS: '',
@@ -245,6 +247,7 @@ async function loadExecutionModule(options: {
245247
IVM_MAX_OWNER_WEIGHT: '5',
246248
IVM_DISTRIBUTED_MAX_INFLIGHT_PER_OWNER: '100',
247249
IVM_DISTRIBUTED_LEASE_MIN_TTL_MS: '1000',
250+
IVM_LEASE_REDIS_DEADLINE_MS: '1000',
248251
IVM_QUEUE_TIMEOUT_MS: '1000',
249252
IVM_MAX_FETCH_RESPONSE_BYTES: '',
250253
IVM_MAX_FETCH_RESPONSE_CHARS: '',
@@ -496,9 +499,10 @@ describe('isolated-vm scheduler', () => {
496499
})
497500

498501
expect(result.error?.message).toContain('Too many concurrent')
502+
expect(result.result).toBeNull()
499503
})
500504

501-
it('fails closed when Redis is configured but unavailable', async () => {
505+
it('falls back to local limits when no Redis client is available', async () => {
502506
const { executeInIsolatedVM } = await loadExecutionModule({
503507
envOverrides: {
504508
REDIS_URL: 'redis://localhost:6379',
@@ -516,14 +520,11 @@ describe('isolated-vm scheduler', () => {
516520
ownerKey: 'user:redis-down',
517521
})
518522

519-
expect(result.error).toMatchObject({
520-
isSystemError: true,
521-
message: 'Code execution coordination is temporarily unavailable. Please try again later.',
522-
})
523-
expect(result.result).toBeNull()
523+
expect(result.error).toBeUndefined()
524+
expect(result.result).toBe('ok')
524525
})
525526

526-
it('fails closed when Redis lease evaluation errors', async () => {
527+
it('falls back to local limits when the lease evaluation errors', async () => {
527528
const { executeInIsolatedVM } = await loadExecutionModule({
528529
envOverrides: {
529530
REDIS_URL: 'redis://localhost:6379',
@@ -548,11 +549,109 @@ describe('isolated-vm scheduler', () => {
548549
ownerKey: 'user:redis-error',
549550
})
550551

551-
expect(result.error).toMatchObject({
552-
isSystemError: true,
553-
message: 'Code execution coordination is temporarily unavailable. Please try again later.',
552+
expect(result.error).toBeUndefined()
553+
expect(result.result).toBe('ok')
554+
})
555+
556+
it('falls back to local limits when the lease round trip exceeds its deadline', async () => {
557+
const { executeInIsolatedVM } = await loadExecutionModule({
558+
envOverrides: {
559+
REDIS_URL: 'redis://localhost:6379',
560+
IVM_LEASE_REDIS_DEADLINE_MS: '5',
561+
},
562+
spawns: [() => createReadyProc('ok')],
563+
redisEvalImpl: (...args: unknown[]) => {
564+
const script = String(args[0] ?? '')
565+
// Never settles, so only the deadline can decide the outcome.
566+
if (script.includes('ZREMRANGEBYSCORE')) {
567+
return new Promise<number>(() => {})
568+
}
569+
return 1
570+
},
571+
})
572+
573+
const result = await executeInIsolatedVM({
574+
code: 'return "ok"',
575+
params: {},
576+
envVars: {},
577+
contextVariables: {},
578+
timeoutMs: 100,
579+
requestId: 'req-9',
580+
ownerKey: 'user:redis-slow',
554581
})
555-
expect(result.result).toBeNull()
582+
583+
expect(result.error).toBeUndefined()
584+
expect(result.result).toBe('ok')
585+
})
586+
587+
it('releases a lease that Redis registers after the local deadline', async () => {
588+
const scripts: string[] = []
589+
let completeAcquire!: (value: number) => void
590+
const lateAcquire = new Promise<number>((resolve) => {
591+
completeAcquire = resolve
592+
})
593+
const { executeInIsolatedVM } = await loadExecutionModule({
594+
envOverrides: {
595+
REDIS_URL: 'redis://localhost:6379',
596+
IVM_LEASE_REDIS_DEADLINE_MS: '5',
597+
},
598+
spawns: [() => createReadyProc('ok')],
599+
redisEvalImpl: (...args: unknown[]) => {
600+
const script = String(args[0] ?? '')
601+
scripts.push(script)
602+
// Settles only once the test says so, standing in for a script the
603+
// deadline abandoned locally but that Redis still runs to completion.
604+
if (script.includes('ZREMRANGEBYSCORE')) return lateAcquire
605+
return 1
606+
},
607+
})
608+
609+
const result = await executeInIsolatedVM({
610+
code: 'return "ok"',
611+
params: {},
612+
envVars: {},
613+
contextVariables: {},
614+
timeoutMs: 100,
615+
requestId: 'req-11',
616+
ownerKey: 'user:redis-late',
617+
})
618+
completeAcquire(1)
619+
620+
expect(result.error).toBeUndefined()
621+
expect(scripts.some((script) => script.includes("'ZREM'"))).toBe(true)
622+
})
623+
624+
it('ignores a non-positive configured deadline instead of abandoning every lease', async () => {
625+
const { executeInIsolatedVM } = await loadExecutionModule({
626+
envOverrides: {
627+
IVM_DISTRIBUTED_MAX_INFLIGHT_PER_OWNER: '1',
628+
IVM_LEASE_REDIS_DEADLINE_MS: '-1',
629+
REDIS_URL: 'redis://localhost:6379',
630+
},
631+
spawns: [() => createReadyProc('ok')],
632+
redisEvalImpl: async (...args: unknown[]) => {
633+
const script = String(args[0] ?? '')
634+
if (script.includes('ZREMRANGEBYSCORE')) {
635+
// Arrives after a non-positive timer would already have fired, so the
636+
// answer only lands in time when the default deadline is restored.
637+
await sleep(25)
638+
return 0
639+
}
640+
return 1
641+
},
642+
})
643+
644+
const result = await executeInIsolatedVM({
645+
code: 'return "ok"',
646+
params: {},
647+
envVars: {},
648+
contextVariables: {},
649+
timeoutMs: 100,
650+
requestId: 'req-12',
651+
ownerKey: 'user:negative-deadline',
652+
})
653+
654+
expect(result.error?.message).toContain('Too many concurrent')
556655
})
557656

558657
it('reports cancellation when abort races a rejected distributed lease', async () => {

apps/sim/lib/execution/isolated-vm.ts

Lines changed: 41 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -140,7 +140,22 @@ const MAX_EXECUTIONS_PER_WORKER = Number.parseInt(env.IVM_MAX_EXECUTIONS_PER_WOR
140140
const MAX_BROKER_ARGS_JSON_CHARS = Number.parseInt(env.IVM_MAX_BROKER_ARGS_JSON_CHARS) || 262_144
141141
const MAX_BROKERS_PER_EXECUTION = Number.parseInt(env.IVM_MAX_BROKERS_PER_EXECUTION) || 1000
142142
const DISTRIBUTED_KEY_PREFIX = 'ivm:fair:v1:owner'
143-
const LEASE_REDIS_DEADLINE_MS = 200
143+
/**
144+
* Deadline for a single lease round trip, kept below the shared Redis client's
145+
* `commandTimeout` so this race still resolves first.
146+
*
147+
* Both this deadline and `commandTimeout` are plain `setTimeout`s, so what they
148+
* actually measure is event-loop scheduling, not Redis. A value near normal loop
149+
* latency therefore reports a healthy Redis as unreachable whenever a garbage
150+
* collection pause lands on the call. Keep it well clear of that floor.
151+
*
152+
* A non-positive configured value is treated as unconfigured rather than
153+
* honored: a timer of zero or less fires immediately, which would leave every
154+
* acquisition undetermined and silently drop cross-replica enforcement.
155+
*/
156+
const CONFIGURED_LEASE_REDIS_DEADLINE_MS = Number.parseInt(env.IVM_LEASE_REDIS_DEADLINE_MS)
157+
const LEASE_REDIS_DEADLINE_MS =
158+
CONFIGURED_LEASE_REDIS_DEADLINE_MS > 0 ? CONFIGURED_LEASE_REDIS_DEADLINE_MS : 1000
144159
const QUEUE_RETRY_DELAY_MS = 1000
145160
const DISTRIBUTED_LEASE_GRACE_MS = 30000
146161

@@ -347,7 +362,16 @@ function ownerRedisKey(ownerKey: string): string {
347362
return `${DISTRIBUTED_KEY_PREFIX}:${ownerKey}`
348363
}
349364

350-
type LeaseAcquireResult = 'acquired' | 'limit_exceeded' | 'unavailable'
365+
/**
366+
* Outcome of one distributed lease acquisition.
367+
*
368+
* `limit_exceeded` is an answer from Redis — the owner is genuinely over its
369+
* share — and is the only outcome that denies an execution. `undetermined`
370+
* means no answer arrived before the deadline, which is not a denial and must
371+
* never be projected as one: the local admission limits below still bound the
372+
* work, so the caller falls back to them.
373+
*/
374+
type LeaseAcquireResult = 'acquired' | 'limit_exceeded' | 'undetermined'
351375

352376
async function tryAcquireDistributedLease(
353377
ownerKey: string,
@@ -358,10 +382,10 @@ async function tryAcquireDistributedLease(
358382

359383
const redis = getRedisClient()
360384
if (!redis) {
361-
logger.error('Redis is configured but unavailable for distributed lease acquisition', {
385+
logger.warn('No Redis client for distributed lease acquisition; using local limits', {
362386
ownerKey,
363387
})
364-
return 'unavailable'
388+
return 'undetermined'
365389
}
366390

367391
const now = Date.now()
@@ -407,11 +431,12 @@ async function tryAcquireDistributedLease(
407431
])
408432
return Number(result) === 1 ? 'acquired' : 'limit_exceeded'
409433
} catch (error) {
410-
logger.error('Failed to acquire distributed owner lease; execution will be rejected', {
434+
logger.warn('Distributed owner lease undetermined; using local limits', {
411435
ownerKey,
436+
deadlineMs: LEASE_REDIS_DEADLINE_MS,
412437
error,
413438
})
414-
return 'unavailable'
439+
return 'undetermined'
415440
} finally {
416441
clearTimeout(deadlineTimer)
417442
}
@@ -1416,23 +1441,18 @@ export async function executeInIsolatedVM(
14161441
},
14171442
}
14181443
}
1419-
if (leaseAcquireResult === 'unavailable') {
1420-
logger.error('Isolated-vm execution rejected because its distributed lease is unavailable', {
1421-
ownerKey,
1422-
})
1423-
maybeCleanupOwner(ownerKey)
1424-
return {
1425-
result: null,
1426-
stdout: '',
1427-
error: {
1428-
message: 'Code execution coordination is temporarily unavailable. Please try again later.',
1429-
name: 'Error',
1430-
isSystemError: true,
1431-
},
1432-
}
1433-
}
1444+
// An undetermined lease cannot reject the execution: the per-process pool and
1445+
// the per-owner active/queued limits above still bound this work.
14341446

14351447
let settled = false
1448+
/**
1449+
* Released even when the acquisition was undetermined. The deadline abandons
1450+
* the local wait but cannot cancel the script, so a late completion still
1451+
* registers this lease id — and unreleased it would count against the owner
1452+
* for the whole TTL, denying later executions that do have capacity. The
1453+
* lease id is unique to this execution, so removing one that was never
1454+
* registered is a no-op.
1455+
*/
14361456
const releaseLease = () => {
14371457
if (settled) return
14381458
settled = true

0 commit comments

Comments
 (0)