fix(metadata): stop audio writes on stalled ffmpeg progress instead of a 60s timeout

A stream copy of a large audiobook onto a network share outlived the fixed 60s ffmpeg timeout
and failed the write. FFmpeg now reports progress and is stopped only once its output stops
growing for max(2 min, bytes written at 1 MiB/s), which also covers the silent flush on close.

Fixes #1769
This commit is contained in:
neon
2026-10-13 01:30:04 +00:00
parent 2cc0906ddf
commit 9c15a9a5cc
4 changed files with 379 additions and 25 deletions
@@ -7,6 +7,7 @@ const mocks = vi.hoisted(() => ({
execFile: vi.fn(),
randomUUID: vi.fn(),
replaceFileAtomically: vi.fn(),
runFfmpeg: vi.fn(),
sharpFactory: vi.fn(),
sharpJpeg: vi.fn(),
sharpToBuffer: vi.fn(),
@@ -37,6 +38,11 @@ vi.mock('../shared/atomic-file-replace', () => ({
replaceFileAtomically: mocks.replaceFileAtomically,
}));
vi.mock('./ffmpeg-runner', async (importOriginal) => ({
...(await importOriginal<typeof import('./ffmpeg-runner')>()),
runFfmpeg: mocks.runFfmpeg,
}));
vi.mock('./mp4-freeform-tags', async (importOriginal) => ({
...(await importOriginal<typeof import('./mp4-freeform-tags')>()),
writeMp4FreeformTags: mocks.writeMp4FreeformTags,
@@ -44,6 +50,7 @@ vi.mock('./mp4-freeform-tags', async (importOriginal) => ({
import { replaceFileAtomically } from '../shared/atomic-file-replace';
import { AudioMetadataEmbedder, testing } from './audio-metadata-embedder';
import { FfmpegStalledError } from './ffmpeg-runner';
const execFileMock = execFile as unknown as typeof mocks.execFile;
const randomUUIDMock = randomUUID as unknown as typeof mocks.randomUUID;
@@ -65,6 +72,7 @@ describe('AudioMetadataEmbedder', () => {
callback(null, '', '');
},
);
mocks.runFfmpeg.mockResolvedValue(undefined);
writeFileMock.mockResolvedValue(undefined);
unlinkMock.mockResolvedValue(undefined);
replaceFileAtomicallyMock.mockResolvedValue(undefined);
@@ -86,7 +94,7 @@ describe('AudioMetadataEmbedder', () => {
expect(sharpMock).toHaveBeenCalledWith(Buffer.from('raw-cover'));
expect(mocks.sharpJpeg).toHaveBeenCalledWith({ quality: 92 });
expect(writeFileMock).toHaveBeenCalledWith('/books/audio/.bookorbit-cover-fixed-id.jpg', Buffer.from('jpeg-cover'));
expect(execFileMock).toHaveBeenCalledWith(
expect(mocks.runFfmpeg).toHaveBeenCalledWith(
'/opt/bin/ffmpeg',
expect.arrayContaining([
'-v',
@@ -111,8 +119,6 @@ describe('AudioMetadataEmbedder', () => {
'composer=Scott Brick',
'/books/audio/.bookorbit-write-fixed-id.m4b',
]),
expect.objectContaining({ maxBuffer: expect.any(Number), timeout: 60_000 }),
expect.any(Function),
);
expect(replaceFileAtomicallyMock).toHaveBeenCalledWith('/books/audio/.bookorbit-write-fixed-id.m4b', '/books/audio/book.m4b');
expect(unlinkMock).toHaveBeenCalledTimes(1);
@@ -148,7 +154,7 @@ describe('AudioMetadataEmbedder', () => {
expect(sharpMock).not.toHaveBeenCalled();
expect(writeFileMock).not.toHaveBeenCalled();
const args = execFileMock.mock.calls[0]![1] as string[];
const args = mocks.runFfmpeg.mock.calls[0]![1] as string[];
expect(args).toEqual(expect.arrayContaining(['-metadata', 'album=Book', '/books/audio/.bookorbit-write-fixed-id.flac']));
// Audio, existing art, and subtitles only: a copied MP4 chapter data track fails the whole write.
expect(mapArgs(args)).toEqual(['0:a', '0:v?', '0:s?']);
@@ -162,9 +168,8 @@ describe('AudioMetadataEmbedder', () => {
it('bounds the ffprobe stream check and treats a timed-out probe as having art', async () => {
vi.stubEnv('FFPROBE_PATH', '/opt/bin/ffprobe');
execFileMock.mockImplementation((bin: string, _args: string[], _options: unknown, callback: (error: Error | null, stdout: string) => void) => {
if (bin === '/opt/bin/ffprobe') callback(Object.assign(new Error('Command failed'), { killed: true, signal: 'SIGTERM' }), '');
else callback(null, '');
execFileMock.mockImplementation((_bin: string, _args: string[], _options: unknown, callback: (error: Error | null, stdout: string) => void) => {
callback(Object.assign(new Error('Command failed'), { killed: true, signal: 'SIGTERM' }), '');
});
const embedder = new AudioMetadataEmbedder();
@@ -172,9 +177,8 @@ describe('AudioMetadataEmbedder', () => {
const probeCall = execFileMock.mock.calls.find(([bin]) => bin === '/opt/bin/ffprobe')!;
expect(probeCall[2]).toEqual({ timeout: 30_000 });
const ffmpegArgs = execFileMock.mock.calls.find(([bin]) => bin !== '/opt/bin/ffprobe')![1] as string[];
expect(ffmpegArgs).not.toContain('use_metadata_tags');
expect(ffmpegArgs).not.toContain('-f');
expect(ffmpegArgs()).not.toContain('use_metadata_tags');
expect(ffmpegArgs()).not.toContain('-f');
});
function mockProbedStreams(streams: Array<{ codec_type: string; codec_name?: string }>): void {
@@ -183,14 +187,14 @@ describe('AudioMetadataEmbedder', () => {
function mockProbeOutput(stdout: string): void {
execFileMock.mockImplementation(
(bin: string, _args: string[], _options: unknown, callback: (error: Error | null, result: { stdout: string; stderr: string }) => void) => {
callback(null, { stdout: bin === 'ffprobe' ? stdout : '', stderr: '' });
(_bin: string, _args: string[], _options: unknown, callback: (error: Error | null, result: { stdout: string; stderr: string }) => void) => {
callback(null, { stdout, stderr: '' });
},
);
}
function ffmpegArgs(): string[] {
return execFileMock.mock.calls.find(([bin]) => bin === 'ffmpeg')![1] as string[];
return mocks.runFfmpeg.mock.calls[0]![1] as string[];
}
function mapArgs(args: string[]): string[] {
@@ -413,7 +417,8 @@ describe('AudioMetadataEmbedder', () => {
await embedder.embedMetadata(`/books/audio/book.${format}`, format, { coverBytes: null, metadata: [] });
expect(execFileMock.mock.calls.map(([bin]) => bin)).toEqual(['ffmpeg']);
expect(execFileMock).not.toHaveBeenCalled();
expect(mocks.runFfmpeg).toHaveBeenCalledTimes(1);
});
});
@@ -440,12 +445,22 @@ describe('AudioMetadataEmbedder', () => {
expect(unlinkMock).toHaveBeenCalledWith('/books/audio/.bookorbit-write-fixed-id.m4b');
});
it('keeps the original file and removes the partial output when ffmpeg stalls', async () => {
mocks.runFfmpeg.mockRejectedValue(new FfmpegStalledError(120_000, 'SIGTERM'));
const embedder = new AudioMetadataEmbedder();
await expect(
embedder.embedMetadata('/books/audio/book.m4b', 'm4b', { coverBytes: Buffer.from('raw-cover'), metadata: [] }),
).rejects.toBeInstanceOf(FfmpegStalledError);
expect(mocks.writeMp4FreeformTags).not.toHaveBeenCalled();
expect(replaceFileAtomicallyMock).not.toHaveBeenCalled();
expect(unlinkMock).toHaveBeenCalledWith('/books/audio/.bookorbit-write-fixed-id.m4b');
expect(unlinkMock).toHaveBeenCalledWith('/books/audio/.bookorbit-cover-fixed-id.jpg');
});
it('preserves the ffmpeg error when cleanup also fails', async () => {
execFileMock.mockImplementation(
(_bin: string, _args: string[], _options: unknown, callback: (error: Error | null, stdout: string, stderr: string) => void) => {
callback(new Error('ffmpeg failed'), '', '');
},
);
mocks.runFfmpeg.mockRejectedValue(new Error('ffmpeg failed'));
unlinkMock.mockRejectedValue(new Error('cleanup failed'));
const embedder = new AudioMetadataEmbedder();
@@ -8,11 +8,10 @@ import { promisify } from 'util';
import { FORMAT_M4A, FORMAT_M4B, FORMAT_MP3 } from '../../file-write.constants';
import { replaceFileAtomically } from '../shared/atomic-file-replace';
import { runFfmpeg } from './ffmpeg-runner';
import { MP4_NATIVE_TAG_KEYS, writeMp4FreeformTags, type Mp4FreeformTag } from './mp4-freeform-tags';
const execFile = promisify(execFileCallback);
const FFMPEG_OUTPUT_MAX_BUFFER_BYTES = 10 * 1024 * 1024;
const FFMPEG_TIMEOUT_MS = 60_000;
const FFPROBE_TIMEOUT_MS = 30_000;
/** The only audio FFmpeg's ipod muxer accepts; an MP4 can also carry MP3, MP2, Opus, FLAC and E-AC-3. */
const IPOD_MUXER_AUDIO_CODECS = new Set(['aac', 'alac', 'ac3']);
@@ -54,10 +53,7 @@ export class AudioMetadataEmbedder {
const streams = isMp4Format(format) ? await probeStreams(filePath) : null;
const useMp4MetadataTags = shouldUseMp4MetadataTags(format, coverPath, streams);
const muxer = outputMuxer(format, streams);
await execFile(resolveFfmpegPath(), buildFfmpegArgs(filePath, coverPath, tempPath, format, input.metadata, { useMp4MetadataTags, muxer }), {
maxBuffer: FFMPEG_OUTPUT_MAX_BUFFER_BYTES,
timeout: FFMPEG_TIMEOUT_MS,
});
await runFfmpeg(resolveFfmpegPath(), buildFfmpegArgs(filePath, coverPath, tempPath, format, input.metadata, { useMp4MetadataTags, muxer }));
if (isMp4Format(format) && !useMp4MetadataTags) {
await writeMp4FreeformTags(tempPath, mp4FreeformTags(input.metadata), { carryOverFrom: filePath });
}
@@ -0,0 +1,228 @@
import { EventEmitter } from 'events';
const mocks = vi.hoisted(() => ({ spawn: vi.fn() }));
vi.mock('child_process', () => ({ spawn: mocks.spawn }));
import { describeWriteFailure } from '../../write-failure-reason';
import { FfmpegStalledError, runFfmpeg } from './ffmpeg-runner';
const MIB = 1024 * 1024;
class FakeStream extends EventEmitter {
setEncoding = vi.fn();
}
class FakeChild extends EventEmitter {
stdout = new FakeStream();
stderr = new FakeStream();
kill = vi.fn<(signal?: NodeJS.Signals) => boolean>(() => true);
/** One block of FFmpeg's `-progress` output, as FFmpeg 8 prints it for an M4B with cover art. */
report(totalSize: number): void {
this.stdout.emit('data', `frame=1\nbitrate=N/A\ntotal_size=${totalSize}\nout_time_us=N/A\nspeed=N/A\nprogress=continue\n`);
}
exit(code: number | null, signal: NodeJS.Signals | null = null): void {
this.emit('close', code, signal);
}
}
describe('runFfmpeg', () => {
let child: FakeChild;
beforeEach(() => {
vi.useFakeTimers();
child = new FakeChild();
mocks.spawn.mockReset().mockReturnValue(child);
});
afterEach(() => {
vi.useRealTimers();
});
it('asks FFmpeg for progress reports ahead of the caller arguments', async () => {
const run = runFfmpeg('/opt/bin/ffmpeg', ['-v', 'error', '-i', 'in.m4b', 'out.m4b']);
child.exit(0);
await expect(run).resolves.toBeUndefined();
expect(mocks.spawn).toHaveBeenCalledWith('/opt/bin/ffmpeg', ['-progress', 'pipe:1', '-v', 'error', '-i', 'in.m4b', 'out.m4b'], {
stdio: ['ignore', 'pipe', 'pipe'],
});
});
it('lets a slow write run far past the stall window while its output keeps growing', async () => {
const run = runFfmpeg('ffmpeg', []);
for (let report = 1; report <= 10; report++) {
vi.advanceTimersByTime(119_000);
child.report(report * 1_000_000);
}
child.exit(0);
await expect(run).resolves.toBeUndefined();
expect(child.kill).not.toHaveBeenCalled();
});
it('stops FFmpeg once its output stops growing, though it keeps printing reports', async () => {
const run = runFfmpeg('ffmpeg', []);
child.report(5_000_000);
for (let tick = 0; tick < 239; tick++) {
vi.advanceTimersByTime(500);
child.report(5_000_000);
}
expect(child.kill).not.toHaveBeenCalled();
vi.advanceTimersByTime(500);
expect(child.kill).toHaveBeenCalledWith('SIGTERM');
child.exit(null, 'SIGTERM');
const error = await run.catch((caught: unknown) => caught);
expect(error).toBeInstanceOf(FfmpegStalledError);
expect(error).toMatchObject({ killed: true, signal: 'SIGTERM', stallWindowMs: 120_000 });
});
it('waits out the silent flush of everything FFmpeg wrote into the page cache', async () => {
const run = runFfmpeg('ffmpeg', []);
child.report(900 * MIB);
child.report(1_900 * MIB);
// On NFS at 64 Mbit/s a 615 MB book was cached in 5s, then FFmpeg said nothing for 85s; 2 GB takes over 4 minutes.
vi.advanceTimersByTime(260_000);
child.stdout.emit('data', `total_size=${2_000 * MIB}\nout_time_us=N/A\nprogress=end\n`);
child.exit(0);
await expect(run).resolves.toBeUndefined();
expect(child.kill).not.toHaveBeenCalled();
});
it('stops a run silent for longer than flushing what it wrote would take at 1 MiB/s', async () => {
const run = runFfmpeg('ffmpeg', []);
child.report(600 * MIB);
vi.advanceTimersByTime(599_999);
expect(child.kill).not.toHaveBeenCalled();
vi.advanceTimersByTime(1);
expect(child.kill).toHaveBeenCalledWith('SIGTERM');
child.exit(null, 'SIGTERM');
await expect(run).rejects.toMatchObject({ name: 'FfmpegStalledError', stallWindowMs: 600_000 });
});
it('stops FFmpeg that never reports at all, such as one stuck opening its input', async () => {
const run = runFfmpeg('ffmpeg', []);
vi.advanceTimersByTime(119_999);
expect(child.kill).not.toHaveBeenCalled();
vi.advanceTimersByTime(1);
expect(child.kill).toHaveBeenCalledWith('SIGTERM');
child.exit(255);
await expect(run).rejects.toBeInstanceOf(FfmpegStalledError);
});
it('escalates to SIGKILL when FFmpeg sits out SIGTERM, and settles only once it has exited', async () => {
const run = runFfmpeg('ffmpeg', []);
let settled = false;
void run.catch(() => undefined).finally(() => (settled = true));
vi.advanceTimersByTime(120_000);
expect(child.kill).toHaveBeenCalledWith('SIGTERM');
vi.advanceTimersByTime(9_999);
expect(child.kill).toHaveBeenCalledTimes(1);
vi.advanceTimersByTime(1);
expect(child.kill).toHaveBeenLastCalledWith('SIGKILL');
await Promise.resolve();
expect(settled).toBe(false);
child.exit(null, 'SIGKILL');
await expect(run).rejects.toMatchObject({ name: 'FfmpegStalledError', signal: 'SIGKILL' });
});
it('keeps the command line, with its paths and metadata values, out of a stall failure reason', async () => {
const run = runFfmpeg('ffmpeg', ['-i', '/books/a/book.m4b', '-metadata', 'title=Secret', '/books/a/.bookorbit-write-x.m4b']);
vi.advanceTimersByTime(120_000);
child.exit(null, 'SIGTERM');
const error = await run.catch((caught: unknown) => caught);
expect(describeWriteFailure(error, '/books/a/book.m4b')).toBe('ffmpeg made no progress for 120s and was stopped');
});
it('rejects a failed run with the error execFile gives, so the failure reason is still the tool output', async () => {
const run = runFfmpeg('ffmpeg', ['-i', 'in.m4b', 'out.m4b']);
child.stderr.emit('data', '[mp4 @ 0x7f8a] Could not find tag for codec\n');
child.exit(1);
const error = await run.catch((caught: unknown) => caught);
expect(error).toBeInstanceOf(Error);
expect((error as Error).message).toBe('Command failed: ffmpeg -progress pipe:1 -i in.m4b out.m4b\n[mp4 @ 0x7f8a] Could not find tag for codec\n');
expect(error).toMatchObject({ code: 1, signal: null, killed: false, stdout: '', stderr: '[mp4 @ 0x7f8a] Could not find tag for codec\n' });
expect(describeWriteFailure(error, '/books/in.m4b')).toBe('Could not find tag for codec');
});
it('treats a signal it did not send as a failed run, not a stall', async () => {
const run = runFfmpeg('ffmpeg', []);
child.exit(null, 'SIGKILL');
const error = await run.catch((caught: unknown) => caught);
expect(error).not.toBeInstanceOf(FfmpegStalledError);
expect(error).toMatchObject({ signal: 'SIGKILL', killed: false });
expect((error as Error).message.startsWith('Command failed: ffmpeg')).toBe(true);
});
it('reads a progress value split across output chunks', async () => {
const run = runFfmpeg('ffmpeg', []);
child.report(1_000);
vi.advanceTimersByTime(119_000);
child.stdout.emit('data', 'total_si');
child.stdout.emit('data', 'ze=2000\nprogress=continue\n');
vi.advanceTimersByTime(119_000);
child.exit(0);
await expect(run).resolves.toBeUndefined();
expect(child.kill).not.toHaveBeenCalled();
});
it('counts a moving output time as progress when the byte count is not reported', async () => {
const run = runFfmpeg('ffmpeg', []);
for (let report = 1; report <= 3; report++) {
vi.advanceTimersByTime(119_000);
child.stdout.emit('data', `total_size=N/A\nout_time_us=${report * 1_000_000}\nprogress=continue\n`);
}
child.exit(0);
await expect(run).resolves.toBeUndefined();
expect(child.kill).not.toHaveBeenCalled();
});
it('rejects with the spawn error when FFmpeg cannot be started, settling once', async () => {
const run = runFfmpeg('ffmpeg', []);
const enoent = Object.assign(new Error('spawn ffmpeg ENOENT'), { code: 'ENOENT' });
child.emit('error', enoent);
child.exit(-2);
await expect(run).rejects.toBe(enoent);
expect(vi.getTimerCount()).toBe(0);
});
it('caps the stderr it keeps without stopping a chatty FFmpeg', async () => {
const run = runFfmpeg('ffmpeg', []);
for (let chunk = 0; chunk < 200; chunk++) child.stderr.emit('data', 'x'.repeat(1024));
child.exit(1);
const error = await run.catch((caught: unknown) => caught);
expect((error as { stderr: string }).stderr).toHaveLength(64 * 1024);
expect(child.kill).not.toHaveBeenCalled();
});
it('clears its timers once FFmpeg exits', async () => {
const run = runFfmpeg('ffmpeg', []);
child.report(1);
child.exit(0);
await run;
expect(vi.getTimerCount()).toBe(0);
vi.advanceTimersByTime(600_000);
expect(child.kill).not.toHaveBeenCalled();
});
});
@@ -0,0 +1,115 @@
import { spawn } from 'child_process';
const FFMPEG_STALL_MIN_MS = 120_000;
/**
* The slowest storage a write is waited out on. FFmpeg falls silent while the kernel flushes what
* it wrote, which on a network share with ample page cache can be the whole file, and its last
* report only arrives once that flush ends; NFS also holds written pages until a commit, stalling
* writes in bursts. Either quiet spell lasts as long as the data takes to reach the server.
*/
const FLUSH_FLOOR_BYTES_PER_SECOND = 1024 * 1024;
const FFMPEG_KILL_GRACE_MS = 10_000;
const FFMPEG_STDERR_MAX_CHARS = 64 * 1024;
/**
* FFmpeg 7 and later print a progress block every period even while the muxer is blocked on a
* write, so only a change in these values counts. `out_time_us` stays N/A for a file with cover
* art, which leaves the byte count as the signal that always moves.
*/
const PROGRESS_KEYS = new Set(['total_size', 'out_time_us']);
export class FfmpegStalledError extends Error {
readonly killed = true;
constructor(
readonly stallWindowMs: number,
readonly signal: NodeJS.Signals | null,
) {
super(`ffmpeg made no progress for ${Math.round(stallWindowMs / 1000)}s and was stopped`);
this.name = 'FfmpegStalledError';
}
}
/**
* Runs FFmpeg to completion, stopping it only once it stops making progress.
*
* A stream copy of a large audiobook onto a network share can run for minutes while moving
* steadily, and a wall-clock limit failed those writes. A failed run rejects with the error shape
* `execFile` gives, so callers reading `Command failed:` and `stderr` see no difference.
*/
export function runFfmpeg(binary: string, args: string[]): Promise<void> {
const fullArgs = ['-progress', 'pipe:1', ...args];
return new Promise((resolve, reject) => {
const child = spawn(binary, fullArgs, { stdio: ['ignore', 'pipe', 'pipe'] });
const lastProgress = new Map<string, string>();
let partialLine = '';
let stderr = '';
let stalled = false;
let settled = false;
let windowMs = stallWindowMs(0);
let killTimer: NodeJS.Timeout | undefined;
let stallTimer = setTimeout(stop, windowMs);
function stop(): void {
stalled = true;
child.kill('SIGTERM');
// A process blocked on a hard-mounted share can sit out SIGTERM until its write returns.
killTimer = setTimeout(() => child.kill('SIGKILL'), FFMPEG_KILL_GRACE_MS);
}
function finish(error?: Error): void {
if (settled) return;
settled = true;
clearTimeout(stallTimer);
clearTimeout(killTimer);
if (error) reject(error);
else resolve();
}
child.stdout?.setEncoding('utf8');
child.stdout?.on('data', (chunk: string) => {
const lines = (partialLine + chunk).split('\n');
partialLine = lines.pop() ?? '';
if (!advanced(lines, lastProgress) || stalled) return;
clearTimeout(stallTimer);
windowMs = stallWindowMs(Number(lastProgress.get('total_size')));
stallTimer = setTimeout(stop, windowMs);
});
child.stderr?.setEncoding('utf8');
child.stderr?.on('data', (chunk: string) => {
if (stderr.length < FFMPEG_STDERR_MAX_CHARS) stderr += chunk.slice(0, FFMPEG_STDERR_MAX_CHARS - stderr.length);
});
child.on('error', (error) => finish(error));
child.on('close', (code, signal) => {
if (stalled) finish(new FfmpegStalledError(windowMs, signal));
else if (code === 0) finish();
else finish(commandFailed([binary, ...fullArgs].join(' '), code, signal, stderr));
});
});
}
function stallWindowMs(bytesWritten: number): number {
const flushMs = Number.isFinite(bytesWritten) ? Math.ceil(bytesWritten / FLUSH_FLOOR_BYTES_PER_SECOND) * 1000 : 0;
return Math.max(FFMPEG_STALL_MIN_MS, flushMs);
}
function advanced(lines: string[], lastProgress: Map<string, string>): boolean {
let moved = false;
for (const line of lines) {
const separator = line.indexOf('=');
if (separator < 0) continue;
const key = line.slice(0, separator).trim();
if (!PROGRESS_KEYS.has(key)) continue;
const value = line.slice(separator + 1).trim();
if (lastProgress.get(key) === value) continue;
lastProgress.set(key, value);
moved = true;
}
return moved;
}
function commandFailed(cmd: string, code: number | null, signal: NodeJS.Signals | null, stderr: string): Error {
return Object.assign(new Error(`Command failed: ${cmd}\n${stderr}`), { code, signal, killed: false, cmd, stdout: '', stderr });
}