fix(encoder): observability — silence was the bug

First real recording (2026-09-01): ffmpeg died at ~0.9s mid-session with ZERO log
lines while the pump fed a corpse for 9 more seconds. Three blind spots closed:
- OnStderrLine discarded everything non-progress: ffmpeg's actual words (startup
  config, warnings, the reason it quit) now go to AppLog prefixed 'ffmpeg:' (400-char
  cap so a \r-choked blob can't flood).
- Unexpected exit only fired ProcessFailed when code != 0 — a CLEAN exit vanished
  silently. Any exit we didn't request is now logged and fired, any code.
- ExitCode read raced StopAsync's Dispose (tonight's 'No process is associated'
  line) — guarded.
- VM output resolver logs once/5s when a webcam element resolves to a null frame
  (preview showed the cam, recording didn't — the layer skip was invisible).
FfmpegEncoderTests + FramePumpTests 21/21 against the new code, 0 warnings.
This commit is contained in:
2026-09-01 22:11:52 -07:00
parent 7f2bda8ed3
commit 8dcaee0b5b
2 changed files with 59 additions and 8 deletions
+39 -8
View File
@@ -230,14 +230,35 @@ public sealed class FfmpegEncoder : IFfmpegEncoder
OnStderrLine(process, line);
}
var code = process.ExitCode;
var stillRunning = false;
lock (_gate) stillRunning = IsRunning;
if (stillRunning && !_stopRequested && code != 0)
// Read the exit code defensively: the stop path disposes the process
// while this loop may still be waking (2026-09-01 "No process is
// associated with this object" — a cosmetic race that poisoned the log).
int exitCode;
try
{
AppLog.Write($"FFmpeg encoder: subprocess exited unexpectedly ({code})");
_health.LastError = $"FFmpeg exited with code {code}";
ProcessFailed?.Invoke(this, $"FFmpeg exited with code {code}");
exitCode = process.ExitCode;
}
catch (Exception)
{
exitCode = -1;
}
var stillRunning = false;
var stopping = false;
lock (_gate)
{
stillRunning = IsRunning;
stopping = _stopRequested;
}
if (stillRunning && !stopping)
{
// ANY exit we did not ask for is a failure — including code 0.
// The old `code != 0` gate let ffmpeg's clean early exit vanish
// without a word while the pump kept feeding a corpse
// (2026-09-01 first real recording: died at ~0.9s, zero logs).
AppLog.Write($"FFmpeg encoder: subprocess exited unexpectedly (code {exitCode})");
_health.LastError = $"FFmpeg exited with code {exitCode}";
ProcessFailed?.Invoke(this, $"FFmpeg exited with code {exitCode}");
}
}
catch (Exception ex)
@@ -250,7 +271,17 @@ public sealed class FfmpegEncoder : IFfmpegEncoder
private void OnStderrLine(IEncoderProcess process, string line)
{
var progress = FfmpegProgressParser.TryParse(line);
if (progress == null) return;
if (progress == null)
{
// THE EYES: everything ffmpeg says that isn't a progress line — startup
// config, warnings, the real reason it quit. Was silently discarded
// (2026-09-01: encoder died at ~0.9s, log silent). Truncated so a
// \r-choked stats blob can't flood; noise now beats blindness.
var text = line.Trim('\r', ' ', '\t');
if (text.Length > 0)
AppLog.Write($"ffmpeg: {(text.Length > 400 ? text[..400] + "…" : text)}");
return;
}
var dropped = Math.Max(0, (long)Math.Round(progress.Value.Fps * progress.Value.Duration.TotalSeconds) - progress.Value.Frame);
+20
View File
@@ -459,6 +459,26 @@ public partial class MainViewModel : ViewModelBase
// preview: webcam by DeviceId, live captures (the background) by CaptureKey,
// images/background by AssetId. A null frame leaves the element transparent.
private VideoFrame? ResolveOutputFrame(SceneElement element)
{
var frame = ResolveOutputFrameCore(element);
// Output-side eyes (2026-09-01): preview showed the webcam but the recording
// didn't — a null resolver frame silently DROPS the layer. Log once per 5s
// per kind so the repro run tells acquire-mismatch from compose-skip.
if (frame == null && element is WebcamSceneConfig webcam)
{
var now = DateTime.UtcNow;
if (now - _lastWebcamNullLog >= TimeSpan.FromSeconds(5))
{
_lastWebcamNullLog = now;
AppLog.Write($"Output resolver: webcam '{webcam.WebcamId}' frame is null — layer skipped in composite");
}
}
return frame;
}
private DateTime _lastWebcamNullLog = DateTime.MinValue;
private VideoFrame? ResolveOutputFrameCore(SceneElement element)
{
return element switch
{