Repository navigation
fix(engine,producer): retry a spawn that hits a locked ffmpeg/ffprobe executable - #5698
chiarorosa wants to merge 6 commits into
Conversation
|
This is my first PR here, so the workflows are waiting on maintainer approval ( |
bd49c4b to
e4b0284
Compare
|
Rebased on main ( |
miguel-heygen
left a comment
There was a problem hiding this comment.
Welcome, and thank you for this. The research behind it is the best part: measuring that the errno is EBUSY rather than EPERM, and establishing that Node throws it synchronously from spawn() instead of routing it through the 'error' event, is exactly why the earlier attempt could not have worked. I checked the execFile sites too, since those are the ones where it is easy to be wrong. Node's promisify(execFile) calls execFile inside a Promise executor, so the synchronous throw becomes a rejection and your retry does see it. Your test fakes match that real behaviour.
One change needed before merge. In packages/engine/src/utils/spawnLockRetry.ts:38-41, the exhausted-attempts error copies code, errno and syscall from the original, which means it still satisfies isLockedExecutableSpawn. Two of the wrapped helpers nest, so an outer wrapper retries a sequence the inner one already gave up on. The concrete path is spawnStreamingEncoder at packages/engine/src/services/streamingEncoder.ts:472, which awaits getCachedGpuEncoder() at line 494, which calls the wrapped detectGpuEncoder at packages/engine/src/utils/gpuEncoder.ts:65. The -encoders spawn at gpuEncoder.ts:70 is not inside any catch; the .catch at line 85 covers only the probe stage. So if antivirus holds the executable for about 4 seconds while a GPU render starts, the inner wrapper tries 3 times over 750 ms, throws, and the outer wrapper treats that as a fresh locked spawn and restarts the whole encoder start twice more. Nine spawns, roughly 3.75 seconds, and the message the user finally reads still says "after 3 attempts". Not copying syscall onto the enriched error, or tagging it so the classifier declines a tagged error, fixes it in one place.
A smaller accuracy point on the same file. The description lists the GPU probe's cached "no usable GPU encoder" as one of the two cached-lock bugs this fixes, but only the -encoders stage is actually protected. A lock that outlasts the retries during the per-encoder probe is still swallowed by the catch at gpuEncoder.ts:51, returns null, and cachedGpuEncoder at gpuEncoder.ts:88 keeps that for the life of the process. The window is much smaller now, which is a real improvement, but it belongs in your "Known limit" note next to the psnr one, or the cache could decline to store a lock-caused null.
Two minor ones you can take or leave. In packages/engine/src/utils/runFfmpeg.ts, deadlineAtMs is recomputed per attempt, so a caller passing timeout: 30_000 can now wait up to 30.75 seconds; worth a line in the description since the timeout is a public option. And both spawnLockRetry.callSites.test.ts files use real timers, so each retrying case genuinely sleeps 250 ms and the eight of them add about two seconds to every suite run; spawnLockRetry.test.ts already shows the fake-timer pattern.
Separately, and not something you can act on: at this head only the Graphite mergeability check and the WIP check have run, so none of the Windows lanes has ever executed on this branch. For a change about a Windows spawn path that is the evidence that matters most, so a maintainer approving the workflow run is the other thing blocking merge. The branch is also 170 commits behind main and will need a rebase.
jrusso1020
left a comment
There was a problem hiding this comment.
Reviewed at e4b02843. I agree with Miguel's request for changes, and I have one small addition.
The nested retry he found is real. At this head the exhausted error in spawnLockRetry.ts copies syscall: "spawn" and the EBUSY code back onto itself, so isLockedExecutableSpawn still matches it. And because spawnStreamingEncoder awaits the wrapped detectGpuEncoder, the outer wrapper restarts a sequence the inner one already gave up on. If you tag the enriched error so the classifier skips it, every nesting is fixed in one place. A test that nests two wrappers and asserts three spawns, not nine, would pin it.
The rest looks right to me. The first attempt runs synchronously, so healthy spawns keep their timing. The abort recheck in runFfmpeg keeps the "an aborted run starts no process" contract. EPERM is correctly left alone. The security pass is clean: no workflow, dependency or network changes.
Need: yes, #4058 is still open and main has no retry · Size: ok · Reuse: nothing to reuse, since engine has no spawn-retry helper today · Simpler: one helper is the right size
— Rames
e4b0284 to
86ae93d
Compare
|
Thanks @miguel-heygen and @jrusso1020, both reviews were useful. Pushed Nested retries (the required change). An error that has exhausted its attempts is now tagged in a module-level Description. I narrowed the claim: only the GPU probe's
Not taken. The two The rebase also touched |
miguel-heygen
left a comment
There was a problem hiding this comment.
Re-checked at 86ae93d. The earlier blocker is fixed: an error this module has already given up on is tagged (exhaustedErrors), so an outer retrySpawnWhileLocked passes it through instead of starting three more attempts, and the exhausted error keeps code, errno and syscall with the original as its cause.
One change before this merges: the comment at the top of packages/engine/src/utils/spawnLockRetry.ts is 8 lines, and the repository merges comments of at most 3 to 4 lines. Something like this keeps what the code cannot say:
// Windows throws EBUSY (POSIX: ETXTBSY) from spawn() itself while another process holds the
// executable open, e.g. antivirus; nothing has started, so running the caller again is safe.The Node source link and the list of codes Node routes through 'error' read well in the PR description. Optional while you are there: the call-site tests wait the real 250 ms and 500 ms delays; fake timers would keep them fast. I have approved the waiting CI runs so the Windows lanes run on this head.
|
@miguel-heygen Pushed |
On Windows, starting an executable that another process holds open for writing or without sharing (antivirus scanning it, an installer still writing it) fails, and Node throws `spawn EBUSY` synchronously from spawn(), before any ChildProcess exists. ManagedChildProcess never sees it, so the whole render failed with a bare `spawn EBUSY`. retrySpawnWhileLocked reruns the caller after 250 ms and 500 ms when the failure is a spawn EBUSY/ETXTBSY, and otherwise rethrows unchanged. Once the attempts run out, the error names the binary and keeps the errno. Every engine call site that starts the managed binary uses it, including the GPU probe and the psnr filter listing, which cached a lock as "no GPU" and "no filters" for the life of the process. Refs heygen-com#4058
The producer starts the managed binary itself in two places, and a transient Windows `spawn EBUSY` hurt each one differently: the pad/trim video probe failed the audio step, and readFfmpegVersion failed the distributed plan. Both now go through the engine's retrySpawnWhileLocked, which the engine exports for this. Refs heygen-com#4058
An exhausted retry error still matched the locked-spawn check, so an outer retry wrapper (detectGpuEncoder inside spawnStreamingEncoder) restarted the whole sequence. Tag exhausted errors so the classifier declines them.
…the helper comment The call-site tests waited the real 250/500 ms retry delays and timed out in the flake gate; they now step a fake clock. The header comment of spawnLockRetry.ts is cut to two lines to satisfy the comment ratchet.
…xecutable Two spawns that arrived with the rebase were not wrapped: the setts duration check before an AAC encode and the ffprobe version read for probe facts. Both cache a promise, so an EBUSY thrown from spawn() was kept as a rejection for the life of the process and every later AAC encode or probe fact failed. Both now retry, and a lock that outlasts the retries is not cached.
…ed the retries getCachedGpuEncoder now caches the detection promise, so a `-encoders` spawn still locked after every attempt was kept as a rejection and every later GPU render failed. The next call now detects again.
233e40a to
633cf65
Compare
|
@miguel-heygen Rebased onto
Each new call-site test fails without its fix. Touched engine suites, the producer call-site tests, typecheck, oxlint, oxfmt, fallow and both comment checks pass locally on Windows. The workflow runs will need approval again for this head. |
|
@miguel-heygen @jrusso1020 Both requested changes are in (the exhausted-error tag in |
What
A transient lock on the ffmpeg/ffprobe executable no longer fails a render with a bare
spawn EBUSY.retrySpawnWhileLocked(engine) reruns the call after 250 ms and 500 ms whenspawn()fails withEBUSY/ETXTBSY. Once the attempts run out, the error names the binary and keepscode/errno/syscall:It is used at all 11 non-test call sites that start
getFfmpegBinary()/getFfprobeBinary().Why
On Windows, an executable can't be started while another process holds it open for writing or without sharing (antivirus scanning it, an installer still writing it). The measurements are in the issue comment. In short:
EBUSY.EPERMis what an ACL that denies execute produces, which is permanent, so it is not retried.EBUSYis thrown synchronously fromspawn(). Node only deliversEACCES/EAGAIN/EMFILE/ENFILE/ENOENTthrough the'error'event (ChildProcess.prototype.spawn). SoManagedChildProcess'sspawn_erroroutcome never sees it, and a retry keyed on that outcome would not fire for this bug.Besides failing outright, two call sites cached the lock for the life of the process: the GPU probe's
-encoderslisting reported "no usable GPU encoder" (silently falling back to CPU), and the psnr filter listing reported "no filters". This PR protects the-encodersstage of the GPU probe; see the known limits below for what is left.Three call sites cache a promise, so on
maina synchronousEBUSYis kept as a rejection for the life of the process:getCachedGpuEncoder(every later GPU render fails), the setts duration check inaacEncode.ts(every later AAC encode fails) andffprobeMajorfor probe facts. Each now retries, and a lock that outlasts the retries is not cached, so the next call asks again.Related work
Fixes #4058. #4059 attempted this and was closed as stale; this PR addresses its review: the real errno measured on Windows hardware, every managed-binary call site covered, and the enriched error on the
runFfmpegpath as well.How
retrySpawnWhileLocked(binary, run)wraps the async function that already does the spawn, rather thanspawn()itself. The first attempt runs synchronously, so a healthy spawn keeps its exact timing; existing fakes that emitcloseon the next tick are unaffected. Retrying is safe because the error is thrown before any process exists.…Once, keeping the diff small:runFfprobe,spawnStreamingEncoder,ffmpegStdout(the GPU-encodersand NVENC preset listings),canUseGpuEncoder,runFfprobeJson,ffprobeMajor. TheexecFilesites (psnrDb, psnr filter listing,readFfmpegVersion, setts duration check) wrap the call itself.runFfmpegrechecks its abort signal at every attempt, so aborting during the wait starts no process. That keeps its existing "an aborted run starts no process" contract. Itstimeoutis an inactivity window that starts when the process spawns, so a retry does not shorten it; the only extra wait is the retry delays (at most ~750 ms).spawnStreamingEncoderawaits the GPU detection, which runs the wrappedffmpegStdout). An error that has exhausted its attempts is tagged, and the classifier declines a tagged error, so an outer wrapper does not restart a sequence the inner one already gave up on: a lock that outlasts the window costs 3 spawns, not 9, and the message says "after 3 attempts".ffmpeg.exemay take longer; this is the singleRETRY_DELAYS_MSconstant.-encoderslisting is protected).Test plan
spawnLockRetry.test.tscovers classification, backoff, the exhausted error, and no retry forEPERM/ENOENT/non-spawnEBUSY/non-errno errors.engine/src/utils/spawnLockRetry.callSites.test.ts,producer/src/services/spawnLockRetry.callSites.test.ts, and a case instreamingEncoder.test.ts. Each fails onmainwith the barespawn EBUSY(or, for the psnr listing, with the silent wrong result) and passes with the fix.syscallcheck,ETXTBSY, one retry delay, or the exhausted-error tag each fails at least one test. The nested-wrapper case asserts 3 spawns, not 9.341fdd353: the engine suites for the touched modules pass on Windows (345 tests), and the producer call-site tests pass. The new tests foraacEncode,ffprobeMajorandgetCachedGpuEncodereach fail without their fix. The Linux container runs above predate the rebase and were not repeated.runFfmpegagainst a copy offfmpeg.exeheld withFileShare.None. Lock released after 400 ms → succeeds on attempt 3. Lock held 3 s → throws the error above after 757 ms withcode=EBUSY. Script below.oven/bun:1.4.3container): the new tests,ffprobeArgvContract.test.tsandshared.ffmpegVersion.test.tspass.ffprobe.test.tsHDR PNG fixtures,browserManager,audioFxRender,audioMixer.grouping), identical onmain(4e6fcdb) and this branch in the same container (8 failed / 250 passed / 21 skipped both times), so they're environmental.test:classificationcallsnode --test, and theoven/bunimage has no Node, so the lane stops before any test onmaintoo. On Windows the lane's failures (4 tests in 5 files) are identical onmain.typecheck, oxlint, oxfmt, fallow,check-comment-citations.mjsandcomment-ratchet.mjspass.On Windows, some unrelated tests fail identically on
main(path separators, symlinks, ffmpeg 9 dropping-vsync); I left those alone.@hyperframes/inspector's build also fails on Windows onmain(C:\C:\...path), and I can file it separately.Windows repro (Node, no repo needed)