diff --git a/server/lib/content-ingest.js b/server/lib/content-ingest.js index 6a23c56..6666305 100644 --- a/server/lib/content-ingest.js +++ b/server/lib/content-ingest.js @@ -60,10 +60,23 @@ async function deriveMediaMetadata(sourcePath, filepath, mime) { thumbnailPath = thumbName; } else if (mime.startsWith('video/')) { try { - const { execFileSync } = require('child_process'); - const probe = execFileSync('ffprobe', ['-v', 'quiet', '-print_format', 'json', '-show_format', '-show_streams', sourcePath], + // execFile, NOT execFileSync. These two spawns each carry a 15s timeout, and run + // synchronously they block the event loop for their whole duration — nothing else on + // the server runs, including heartbeats and socket traffic. That was survivable while + // the only caller was a human-initiated upload; it stopped being survivable the moment + // a boot-time sweep started walking a whole library of them unattended, which is the + // #240 failure mode exactly (blocked loop -> missed heartbeats -> panels marked + // offline -> reconnect churn) arriving from our own maintenance. + // + // deriveMediaMetadata is already async and both callers already await it, so awaiting + // the subprocess instead of blocking on it is invisible to them. + const { execFile } = require('child_process'); + const { promisify } = require('util'); + const execFileAsync = promisify(execFile); + const { stdout: probe } = await execFileAsync('ffprobe', + ['-v', 'quiet', '-print_format', 'json', '-show_format', '-show_streams', sourcePath], { timeout: 15000 } - ).toString(); + ); const info = JSON.parse(probe); if (info.format?.duration) durationSec = parseFloat(info.format.duration); const videoStream = info.streams?.find(s => s.codec_type === 'video'); @@ -72,11 +85,15 @@ async function deriveMediaMetadata(sourcePath, filepath, mime) { // (ffmpeg auto-rotates the thumbnail below by default, so only the dims need fixing.) ({ width, height } = videoDisplayDims(videoStream)); } - thumbnailPath = `thumb_${filepath.replace(/\.[^.]+$/, '.jpg')}`; + // Same phantom-path discipline as the image branch above: name it only once the + // file exists, so a failed encode cannot leave the row claiming a thumbnail. + const thumbName = `thumb_${filepath.replace(/\.[^.]+$/, '.jpg')}`; try { - execFileSync('ffmpeg', ['-y', '-i', sourcePath, '-ss', '2', '-vframes', '1', '-vf', `scale=${config.thumbnailWidth}:-1`, path.join(config.contentDir, thumbnailPath)], + await execFileAsync('ffmpeg', + ['-y', '-i', sourcePath, '-ss', '2', '-vframes', '1', '-vf', `scale=${config.thumbnailWidth}:-1`, path.join(config.contentDir, thumbName)], { timeout: 15000 } ); + thumbnailPath = thumbName; } catch { thumbnailPath = null; } } catch (e) { console.warn('ffprobe failed:', e.message); diff --git a/server/test/media-probe-nonblocking.test.js b/server/test/media-probe-nonblocking.test.js new file mode 100644 index 0000000..71525a8 --- /dev/null +++ b/server/test/media-probe-nonblocking.test.js @@ -0,0 +1,73 @@ +'use strict'; + +/* + * Video probing must not block the event loop. + * + * deriveMediaMetadata spawns ffprobe and ffmpeg with a 15s timeout each. Run synchronously + * (execFileSync) those two calls stop the entire server for their duration — no heartbeats, no + * socket traffic, no HTTP. That was survivable while the only caller was a human-initiated + * upload: one file, someone waiting for it, bounded. + * + * The boot-time thumbnail backfill removed every one of those mitigations. It walks a whole + * library unattended, on a server with live panels, once per boot — so a sync spawn per video + * reproduces #240's failure mode (blocked loop -> missed heartbeats -> panels marked offline -> + * reconnect churn) from our own maintenance sweep rather than from a checkpoint. + * + * These tests pin the property, not the implementation detail, so a future edit that + * reintroduces a sync spawn on this path fails here rather than in a customer's fleet. + */ +const { test } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const path = require('path'); + +const SRC = fs.readFileSync(path.join(__dirname, '..', 'lib', 'content-ingest.js'), 'utf8'); +// Comments explaining why the sync form is banned must not themselves trip the ban. +const CODE = SRC.replace(/\/\*[\s\S]*?\*\//g, '').replace(/^\s*\/\/.*$/gm, ''); + +test('#244: the media path spawns asynchronously', () => { + assert.ok(!/execFileSync|execSync|spawnSync/.test(CODE), + 'content-ingest must not spawn synchronously — it blocks the loop for the subprocess timeout'); + assert.match(SRC, /execFileAsync\('ffprobe'/, 'ffprobe must be awaited'); + assert.match(SRC, /execFileAsync\('ffmpeg'/, 'ffmpeg must be awaited'); +}); + +test('#244: every spawn keeps its timeout — async is not a licence to hang', () => { + // Async does not make a wedged binary harmless: without the timeout the promise never + // settles and the backfill stops dead on one bad file instead of moving on. + const spawns = SRC.match(/execFileAsync\(/g) || []; + const timeouts = SRC.match(/timeout: 15000/g) || []; + assert.equal(spawns.length, 2, 'expected exactly the ffprobe and ffmpeg spawns'); + assert.equal(timeouts.length, spawns.length, 'every spawn needs its own timeout'); +}); + +test('#244: the loop keeps running while a probe is in flight', async () => { + // The real property, measured rather than grepped: a slow subprocess must not stop timers. + const { promisify } = require('util'); + const execFileAsync = promisify(require('child_process').execFile); + + let ticks = 0; + const ticker = setInterval(() => { ticks++; }, 20); + try { + // Stands in for a slow ffprobe. `sleep` is on PATH everywhere the server runs. + await execFileAsync('sleep', ['0.5'], { timeout: 15000 }); + } catch { + clearInterval(ticker); + return; // no `sleep` binary — the grep assertions above still hold + } + clearInterval(ticker); + // Sync would have yielded 0 ticks across the whole call. + assert.ok(ticks >= 10, `the loop should keep ticking during a spawn, got ${ticks} ticks in 500ms`); +}); + +test('#244: neither branch names a thumbnail it has not written', () => { + // The phantom-path bug, in both media branches: assigning thumbnailPath before the write + // means a failed encode returns a name for a file that does not exist, and the dashboard + // then requests it forever as a broken image. + const videoBranch = SRC.slice(SRC.indexOf("mime.startsWith('video/')"), SRC.indexOf('return { width, height')); + assert.match(videoBranch, /const thumbName =/, 'the video branch must stage the name'); + assert.match(videoBranch, /thumbnailPath = thumbName;/, 'and assign only after the encode resolves'); + const assignIdx = videoBranch.indexOf('thumbnailPath = thumbName;'); + const spawnIdx = videoBranch.indexOf("execFileAsync('ffmpeg'"); + assert.ok(spawnIdx < assignIdx, 'the assignment must come AFTER the ffmpeg call, not before'); +});