diff --git a/crates/verify/expectations.toml b/crates/verify/expectations.toml index ea47214b2e..94233df4a7 100644 --- a/crates/verify/expectations.toml +++ b/crates/verify/expectations.toml @@ -361,23 +361,3 @@ hosts = ["github-hosted", "local"] bound = { count = 1, screen-pictures = 1 } reason = "NEW (ScreenCaptureKit idle resume, see above): the first 15 fps picture after the 3 s hold is missing when the resume takes longer than its 67 ms; runners 5 of 6 runs (flaky because the 70 to 82 ms resume straddles the 67 ms picture). Bound: the one hold's picture" link = "https://github.com/CapSoftware/Cap/actions/runs/38745219281" -# Crash safety (crates/verify/tests/crash.rs). Measured on Blacksmith runners -# (run 38850661948: macos-15 libx264, ubuntu-2404, windows-2025) with the suite -# merged into main 3ec0c9497; each fix has its own proof branch -# ci/fixproof-crash- (runs 38850662667, 38850661576, 38850663436, -# 38850662102), which removes exactly its entries. Fixes: #2640 (bug A), -# #2641 (bug B1), #2643 (bug C), #2644 (bug E). - -[[xfail]] -case = "crash/recorder-kill/inproc/static-screen" -class = "loss-time" -bound = { count = 1, secs = [2.5, 20.5] } -reason = "NEW (bug B1): fragments are cut only at keyframes and every recording encoder's keyframe interval is a frame count (g = 2 s x nominal fps; libx264 keyint 60 here, VideoToolbox 12), so when the screen delivers 3 frames per second a fragment spans 20 s of capture and a crash after 11 s loses all of it (3 of 3 platforms; macOS runners use libx264). Bound: at most one 20 s fragment of capture" -link = "https://github.com/CapSoftware/Cap/pull/2641" - -[[xfail]] -case = "crash/recorder-kill/inproc/static-screen" -class = "missing" -bound = { count = 1 } -reason = "NEW (bug B1, see loss-time): no fragment of the static recording is complete when the recorder dies, so recovery has nothing (no frames)" -link = "https://github.com/CapSoftware/Cap/pull/2641" diff --git a/crates/verify/tests/crash.rs b/crates/verify/tests/crash.rs index 33c3b8c206..68e5340732 100644 --- a/crates/verify/tests/crash.rs +++ b/crates/verify/tests/crash.rs @@ -18,7 +18,7 @@ //! time. Frames lost to a failure must be the newest ones and fit in the //! fragment being written: one GOP (`GOP_SECS` x fps frames, the encoder's //! keyframe interval, so the longest a segment can be when frames arrive at -//! the nominal rate) plus `IN_FLIGHT` frames still inside the pipeline. +//! the nominal rate) plus the writer's frames still inside the pipeline. mod common; @@ -42,6 +42,7 @@ use cap_verify::{ report::{self, Case, Tier}, video_code::{self, FrameMarker, StreamKind}, }; +use tracing_subscriber::fmt::writer::MakeWriterExt; const FPS: u32 = 30; const WIDTH: u32 = 640; @@ -57,6 +58,34 @@ const GOP: u32 = (GOP_SECS as u32) * FPS; /// The emitter runs at the nominal rate on an idle encoder, so the channel /// holds at most one frame at a time. const IN_FLIGHT: u32 = 3; + +fn recorder_in_flight(arm: Arm, encoder: &str) -> u32 { + // VideoToolbox can retain four frames before emitting their packets, + // in addition to the duration holder, active encode and channel slots. + // The OOP writer drains its received packets after recorder EOF. + IN_FLIGHT + u32::from(encoder == "h264_videotoolbox" && arm == Arm::InProcess) * 4 +} +fn selected_encoder(log: &str) -> Option<&str> { + log.lines().find_map(|line| { + if line.contains("Selected hardware H264 encoder with zero-copy VideoToolbox input") { + Some("h264_videotoolbox") + } else { + [ + "Selected hardware H264 encoder ", + "Using SOFTWARE H264 encoder (high CPU usage expected) ", + "Using SOFTWARE encoder for high throughput (hardware cannot keep up at this resolution/fps) ", + ] + .into_iter() + .find_map(|message| line.split_once(message)) + .and_then(|(_, fields)| { + fields + .split_whitespace() + .find_map(|field| field.strip_prefix("encoder=")) + }) + } + }) +} + /// Recorded length of every case. const SECONDS: f64 = 8.0; /// Truth timestamps vs presentation times: the encoder time base and the @@ -182,7 +211,10 @@ mod source { Arm::InProcess => { builder .build::>( - MacOSFragmentedM4SMuxerConfig::default(), + MacOSFragmentedM4SMuxerConfig { + timed_fragments: true, + ..Default::default() + }, ) .await } @@ -245,6 +277,7 @@ mod source { // The Studio display config (capture_pipeline.rs, X11Capture): // 2 s segments. .build::>(SegmentedVideoMuxerConfig { + timed_fragments: true, segment_duration: Duration::from_secs(2), ..Default::default() }) @@ -472,7 +505,6 @@ fn crash_child_recorder() { let Ok(spec) = std::env::var(CHILD_ENV) else { return; }; - common::init(); let fields: BTreeMap<&str, &str> = spec .split(';') .filter_map(|kv| kv.split_once('=')) @@ -482,6 +514,25 @@ fn crash_child_recorder() { let truth = PathBuf::from(fields["truth"]); let seconds: f64 = fields["seconds"].parse().expect("seconds"); let step: u32 = fields["step"].parse().expect("step"); + let encoder_log = std::fs::File::create(truth.with_extension("encoder.log")) + .expect("create recorder encoder log"); + tracing_subscriber::fmt() + .with_env_filter( + tracing_subscriber::EnvFilter::new(std::env::var("CAP_VERIFY_LOG").unwrap_or_default()) + .add_directive( + "cap_enc_ffmpeg::video::h264=info" + .parse() + .expect("encoder filter"), + ), + ) + .without_time() + .with_level(false) + .with_target(false) + .with_ansi(false) + .with_writer(encoder_log.and(std::io::stderr)) + .try_init() + .expect("capture recorder encoder selection"); + common::init(); if arm == Arm::OutOfProcess { cap_recording::oop_muxer::resolve_muxer_binary().expect("child recorder: cap-muxer binary"); } @@ -670,6 +721,49 @@ fn fragment_complete(path: &Path) -> bool { at == data.len() && moof && mdat } +// A segment can contain several moof/mdat fragments and end mid-write. +// This oracle deliberately does not use the recovery parser being tested. +fn complete_fragment_ends(data: &[u8]) -> Vec { + let mut ends = Vec::new(); + let mut at = 0usize; + let mut pending_moof = false; + while let Some(header) = data.get(at..).and_then(|tail| tail.get(..8)) { + let size32 = u32::from_be_bytes(header[..4].try_into().unwrap()); + let (size, header_len) = match size32 { + 0 => break, + 1 => { + let Some(extended) = data.get(at..).and_then(|tail| tail.get(8..16)) else { + break; + }; + let Ok(size) = usize::try_from(u64::from_be_bytes(extended.try_into().unwrap())) + else { + break; + }; + (size, 16) + } + size => (size as usize, 8), + }; + let Some(end) = at.checked_add(size).filter(|end| *end <= data.len()) else { + break; + }; + if size < header_len { + break; + } + match &header[4..8] { + b"moof" if pending_moof => break, + b"moof" => pending_moof = true, + b"mdat" if pending_moof => { + ends.push(end); + pending_moof = false; + } + b"mdat" => break, + _ => {} + } + at = end; + } + ends +} + fn segment_index(name: &str) -> Option { name.strip_prefix("segment_")? .trim_end_matches(".tmp") @@ -678,9 +772,8 @@ fn segment_index(name: &str) -> Option { .ok() } -/// Physically complete fragments of one writer directory (finished -/// `segment_NNN.m4s`, or a finished `.m4s.tmp` the writer had not renamed -/// yet), in index order. +/// Segments with at least one complete on-disk fragment, including a +/// complete prefix of an interrupted `.m4s.tmp`, in index order. fn complete_fragments(dir: &Path) -> Vec { let Ok(entries) = std::fs::read_dir(dir) else { return Vec::new(); @@ -694,7 +787,10 @@ fn complete_fragments(dir: &Path) -> Vec { let Some(index) = segment_index(name) else { continue; }; - if !fragment_complete(&path) { + if std::fs::read(&path) + .map(|data| complete_fragment_ends(&data).is_empty()) + .unwrap_or(true) + { continue; } // Prefer the renamed file when both exist. @@ -737,7 +833,10 @@ fn decode_fragments( } let mut joined = std::fs::read(dir.join("init.mp4")).context("init.mp4")?; for fragment in fragments { - joined.extend(std::fs::read(fragment)?); + let data = std::fs::read(fragment)?; + if let Some(&end) = complete_fragment_ends(&data).last() { + joined.extend_from_slice(&data[..end]); + } } let path = scratch.join(format!( "joined-{}.mp4", @@ -772,11 +871,21 @@ fn fragments_on_disk(display: &Path, scratch: &Path) -> anyhow::Result anyhow::Result> { Ok(fragments_on_disk(display, scratch)?.concat()) } -/// A fragment covers the capture time from its first frame to the first -/// frame of the next one, and the encoders must start a new one once +/// A timed fragment covers capture time from its first frame to the first +/// frame of the next one, and the writer must flush a new one once /// `GOP_SECS` have passed: the span may exceed `GOP_SECS` only by the /// interval before the frame that closed it. fn check_fragment_spans(case: &mut Case, fragments: &[Vec<(u32, f64)>], handed: &[Handed]) { @@ -976,6 +1085,7 @@ fn check_timeline(case: &mut Case, label: &str, frames: &[(u32, f64)], handed: & /// fragment being written plus the frames in flight, all at the end. fn check_recovery( case: &mut Case, + in_flight: u32, recovered: &[(u32, f64)], physical: &[(u32, f64)], handed: &[Handed], @@ -1044,7 +1154,7 @@ fn check_recovery( ), ); } - let bound = GOP + IN_FLIGHT; + let bound = GOP + in_flight; // In time: one fragment of capture time, plus the in-flight frames and // the frame that closes the fragment at the delivered interval (a static // screen delivers far fewer frames than the nominal rate). @@ -1052,7 +1162,7 @@ fn check_recovery( .windows(2) .map(|w| w[1].secs - w[0].secs) .fold(1.0 / f64::from(FPS), f64::max); - let bound_secs = GOP_SECS + f64::from(IN_FLIGHT + 1) * interval; + let bound_secs = GOP_SECS + f64::from(in_flight + 1) * interval; case.note(format!( "handed {} frames, complete on disk up to {:?}, lost tail {lost_tail} frames / {lost_secs:.2}s (bound {bound} frames / {bound_secs:.2}s)", handed.len(), @@ -1063,7 +1173,7 @@ fn check_recovery( case.problem( "loss", format!( - "the crash lost the last {lost_tail} handed frames, more than one fragment ({GOP}) plus {IN_FLIGHT} in flight" + "the crash lost the last {lost_tail} handed frames, more than one fragment ({GOP}) plus {in_flight} in flight" ), ); } @@ -1072,7 +1182,7 @@ fn check_recovery( case.problem( "loss-time", format!( - "the crash lost {lost_secs:.2}s of capture, more than one {GOP_SECS}s fragment plus {} frames in flight ({bound_secs:.2}s at the delivered interval)", IN_FLIGHT + 1 + "the crash lost {lost_secs:.2}s of capture, more than one {GOP_SECS}s fragment plus {} frames in flight ({bound_secs:.2}s at the delivered interval)", in_flight + 1 ), ); } @@ -1263,7 +1373,11 @@ fn recorder_kill( check_open_fragment(case, &display); } let fragments = fragments_on_disk(&display, &scratch)?; - check_fragment_spans(case, &fragments, &handed); + // Studio flushes timed fragments; the OOP writer instead drains its + // keyframe-delimited segment after the recorder exits (#2646, #2644). + if arm == Arm::InProcess { + check_fragment_spans(case, &fragments, &handed); + } let physical = fragments.concat(); let pending = pending_fragment_frames(&display, &scratch)?; let recovered = match finalize(&display, &scratch.join("recovered.mp4")) { @@ -1274,7 +1388,16 @@ fn recorder_kill( } Err(e) => return Err(e), }; - check_recovery(case, &recovered, &physical, &handed, &pending); + let in_flight = if arm == Arm::InProcess { + let log = std::fs::read_to_string(truth.with_extension("encoder.log"))?; + let encoder = + selected_encoder(&log).context("recorder did not report its selected encoder")?; + case.note(format!("recorder encoder: {encoder}")); + recorder_in_flight(arm, encoder) + } else { + IN_FLIGHT + }; + check_recovery(case, in_flight, &recovered, &physical, &handed, &pending); if std::env::var_os("CAP_VERIFY_KEEP").is_none() { let _ = std::fs::remove_dir_all(&scratch); } @@ -1575,8 +1698,7 @@ fn crash_safety() { } settle(case); } - // A mostly static screen: one frame every STATIC_STEP slots. A - // fragment must still close every GOP_SECS of capture time. + // A mostly static screen still has the same crash-loss budget. let id = format!("crash/recorder-kill/{}/static-screen", arm.label()); if report::selected(&id) { let mut case = Case::new(&id); @@ -1722,6 +1844,7 @@ fn pending_fragment_bound_rejects_other_complete_frame_loss() { let mut case = Case::new("pending-fragment-test"); check_recovery( &mut case, + IN_FLIGHT, &physical[..1], &physical, &handed, @@ -1730,3 +1853,134 @@ fn pending_fragment_bound_rejects_other_complete_frame_loss() { assert!(case.classes.contains("dropped-complete")); assert!(!case.classes.contains("loss")); } + +#[test] +fn recorder_encoder_selection_ignores_failed_candidates() { + let failed = "Hardware H264 encoder failed pre-flight self-test, trying next candidate encoder=h264_videotoolbox"; + assert_eq!(selected_encoder(failed), None); + for (selection, expected) in [ + ( + "Selected hardware H264 encoder with zero-copy VideoToolbox input width=640", + "h264_videotoolbox", + ), + ( + "Selected hardware H264 encoder encoder=h264_videotoolbox width=640", + "h264_videotoolbox", + ), + ( + "Using SOFTWARE H264 encoder (high CPU usage expected) encoder=libx264 width=640", + "libx264", + ), + ( + "Using SOFTWARE encoder for high throughput (hardware cannot keep up at this resolution/fps) encoder=libx264 width=640", + "libx264", + ), + ] { + assert_eq!( + selected_encoder(&format!("{failed}\nrecording: {selection}\n")), + Some(expected) + ); + } +} + +#[test] +fn recorder_loss_budget_accounts_for_codec_buffering_without_hiding_excess_loss() { + let physical: Vec<_> = (0..120).map(|i| (i, f64::from(i) / 30.0)).collect(); + for arm in [Arm::InProcess, Arm::OutOfProcess] { + for encoder in ["libx264", "h264_videotoolbox"] { + for lost in [63, 64, 65, 67, 68, 69] { + let handed: Vec<_> = (0..120 + lost) + .map(|index| Handed { + index, + secs: f64::from(index) / 30.0, + }) + .collect(); + let mut case = Case::new("recorder-loss-budget"); + check_recovery( + &mut case, + recorder_in_flight(arm, encoder), + &physical, + &physical, + &handed, + &Default::default(), + ); + let videotoolbox = encoder == "h264_videotoolbox" && arm == Arm::InProcess; + assert_eq!( + case.classes.contains("loss"), + if videotoolbox { lost >= 68 } else { lost >= 64 }, + "{arm:?}, {encoder}, {lost} lost frames" + ); + assert_eq!( + case.classes.contains("loss-time"), + if videotoolbox { lost >= 69 } else { lost >= 65 }, + "{arm:?}, {encoder}, {lost} lost frames" + ); + assert!(!case.classes.contains("dropped-complete")); + } + } + } +} + +#[test] +fn complete_prefix_keeps_whole_fragments_before_every_truncated_tail() { + let atom = |kind: &[u8; 4], payload: &[u8]| { + let mut bytes = ((payload.len() + 8) as u32).to_be_bytes().to_vec(); + bytes.extend_from_slice(kind); + bytes.extend_from_slice(payload); + bytes + }; + let first = [atom(b"moof", &[1, 2]), atom(b"mdat", &[3, 4, 5])].concat(); + let second = [atom(b"moof", &[6]), atom(b"mdat", &[7, 8, 9])].concat(); + for cut in 0..first.len() { + assert!(complete_fragment_ends(&first[..cut]).is_empty(), "{cut}"); + } + for cut in 0..second.len() { + let bytes = [&first[..], &second[..cut]].concat(); + assert_eq!(complete_fragment_ends(&bytes), vec![first.len()], "{cut}"); + } + let joined = [first.clone(), second].concat(); + assert_eq!( + complete_fragment_ends(&joined), + vec![first.len(), joined.len()] + ); + for tail in [ + vec![0; 8], + [4u32.to_be_bytes().as_slice(), b"moof"].concat(), + [u32::MAX.to_be_bytes().as_slice(), b"moof"].concat(), + [atom(b"moof", &[]), atom(b"moof", &[]), atom(b"mdat", &[])].concat(), + ] { + assert_eq!( + complete_fragment_ends(&[first.clone(), tail].concat()), + vec![first.len()] + ); + } + let extended = [ + atom(b"moof", &[]), + [ + 1u32.to_be_bytes().as_slice(), + b"mdat", + 19u64.to_be_bytes().as_slice(), + &[1, 2, 3], + ] + .concat(), + ] + .concat(); + assert_eq!(complete_fragment_ends(&extended), vec![extended.len()]); +} + +#[test] +fn timed_fragment_span_still_rejects_a_delayed_flush() { + let handed: Vec<_> = (0..=120) + .step_by(10) + .map(|index| Handed { + index, + secs: f64::from(index) / f64::from(FPS), + }) + .collect(); + for (count, fails) in [(6, false), (12, true)] { + let fragment = handed[..count].iter().map(|h| (h.index, h.secs)).collect(); + let mut case = Case::new("timed-fragment-test"); + check_fragment_spans(&mut case, &[fragment], &handed); + assert_eq!(case.classes.contains("fragment-span"), fails); + } +}