diff --git a/src/disc/bluray.rs b/src/disc/bluray.rs index 4b850f9..b049622 100644 --- a/src/disc/bluray.rs +++ b/src/disc/bluray.rs @@ -285,18 +285,57 @@ impl Disc { // feed is silently missing this clip's runtime while its // durations, spans and size still count it — data loss // wearing the shape of a normal rip. - if let (None, Some(code)) = (&file_exts, unresolved) { - // The REAL code, not a fixed one. A scratched sector - // (E6000) and an over-long AD chain (E6016) logged as - // E6017 would send anyone triaging them after authoring - // holes and hide the population that actually exists. - tracing::warn!( - target: "freemkv::disc", - playlist = ?filename, - clip = ?play_item.clip_id, - "E{}", code - ); - return Ok(None); + match (&file_exts, unresolved) { + (None, Some(code)) => { + // The REAL code, not a fixed one. A scratched sector + // (E6000) and an over-long AD chain (E6016) logged as + // E6017 would send anyone triaging them after authoring + // holes and hide the population that actually exists. + tracing::warn!( + target: "freemkv::disc", + playlist = ?filename, + clip = ?play_item.clip_id, + "E{}", code + ); + return Ok(None); + } + // A non-absence failure that the FALLBACK then papered + // over. `unresolved` was recorded and then thrown away: + // the `if let (None, Some(code))` above is the only reader + // of it, so when `/BDMV/STREAM/SSIF/.ssif` failed + // with `DiscRead` / `UdfAdChainTooLong` / `UdfEmbeddedData` + // but the `.m2ts` beside it resolved, the code was dropped + // on the floor. The title then shipped BASE-VIEW 2D off a + // disc that carries 3D, at rc=0, with not one log line — + // the operator gets a rip that looks complete and is + // missing the dependent view, and there is nothing in the + // journal to explain it or to distinguish it from a disc + // that was only ever 2D. + // + // This site's own doctrine, three paragraphs up, is + // "ABSENCE is the only benign failure" — `note()` already + // filters `UdfNotFound` out, so anything left in + // `unresolved` is by construction NOT benign. Reaching + // here means it was silently tolerated anyway. + // + // It is LOGGED, not refused. The fallback genuinely + // produced a truthful read plan for the base view, so the + // title is complete as 2D; dropping it would trade a + // degraded rip for no rip, which is the worse of the two + // and is not what the refusal above is for. The line + // carries the error's OWN code for the same reason as + // every other site in this file. + (Some(_), Some(code)) => { + tracing::warn!( + target: "freemkv::disc", + playlist = ?filename, + clip = ?play_item.clip_id, + fell_back = true, + code = code, + "E{}", code + ); + } + _ => {} } // KNOWN GAP, deliberately left open: `file_extents` can also // return `Ok(vec![])`, or a vector every entry of which the @@ -312,6 +351,18 @@ impl Disc { // healthy titles is a worse failure than the residual gap. // Recorded here so the next audit finds the decision instead // of re-deriving it. + // + // ASYMMETRY, DELIBERATE: `disc::hddvd` CLOSES this same hole. + // Two things differ there. It already keeps an `unusable` set, + // so refusing costs nothing new (here it would mean inventing + // a post-loop "every clip_id must appear in `spans`" + // invariant). And the consequence is worse: an HD-DVD feature + // is COMPOSED from parts, so a missing part is spliced out of + // a title that keeps claiming the full runtime, whereas here + // the clip is one PlayItem of an otherwise whole title. Same + // hole, different price — see the long note at the + // `extents.is_empty()` branch in `hddvd.rs`. If BD ever grows + // an equivalent set, revisit this together with that one. if let Some(file_exts) = file_exts { let span_start = feed_pos; for (lba, sectors) in file_exts { @@ -1174,6 +1225,15 @@ mod tests { /// The correct behaviour is the same as for a clip whose extents cannot be /// resolved (see `parse_playlist_unreadable_clip_icb_yields_no_title`): /// drop the title and log the read's OWN error code. + /// + /// That last clause is now ASSERTED, not merely asked for. The site's + /// comment insists on `e.code()` because a missing `.clpi` (E6003), a + /// scratched one (E6000) and a malformed one (E6002) are different + /// populations, but nothing checked it: putting a literal back compiled + /// and passed. Mutation: `"E6017"` (or any fixed code) in place of + /// `"E{}", e.code()` fails here, and so does dropping the warn entirely — + /// a silent drop is the same invisible title loss this test was written + /// for, one step later. #[test] fn parse_playlist_missing_clpi_yields_no_title() { let mut disc = MemDisc::new(); @@ -1227,7 +1287,9 @@ mod tests { &[], &[], ); - let t = Disc::parse_playlist(&mut disc, &udf, "00009.mpls", &mpls).expect("scan"); + let (t, events) = crate::testlog::capture(|| { + Disc::parse_playlist(&mut disc, &udf, "00009.mpls", &mpls).expect("scan") + }); assert!( t.is_none(), "a clip with no .clpi cannot be sized or resolved, so offering the \ @@ -1235,6 +1297,18 @@ mod tests { clip's bytes behind it; got {:?}", t.map(|t| (t.size_bytes, t.extents)) ); + let line = events + .iter() + .find(|e| e.target == "freemkv::disc") + .unwrap_or_else(|| panic!("a dropped title must be accounted; got {events:?}")); + assert_eq!(line.field("clip"), Some("\"00009\"")); + assert_eq!( + line.message(), + format!("E{}", crate::error::E_UDF_NOT_FOUND), + "the read's OWN code — an absent .clpi is not a scratched or \ + malformed one, and triaging them together hides the population \ + that actually exists: {line:?}" + ); } /// A clip stream whose ICB declares an UNRECORDED (ECMA-167 4/14.14.1.1 @@ -1420,7 +1494,9 @@ mod tests { &[], &[], ); - let t = Disc::parse_playlist(&mut disc, &udf, "00001.mpls", &mpls).expect("scan"); + let (t, events) = crate::testlog::capture(|| { + Disc::parse_playlist(&mut disc, &udf, "00001.mpls", &mpls).expect("scan") + }); assert!( t.is_none(), "a clip whose extents could not be resolved must drop the title, \ @@ -1428,6 +1504,133 @@ mod tests { its bytes; got {:?}", t.map(|t| (t.size_bytes, t.extents)) ); + // ...and the refusal is accounted with the SCRATCH's own code. + // Mutation: a fixed `"E6017"` here files a scratched sector as an + // authoring hole and fails this assertion. + let line = events + .iter() + .find(|e| e.target == "freemkv::disc") + .unwrap_or_else(|| panic!("a dropped title must be accounted; got {events:?}")); + assert_eq!( + line.message(), + format!("E{}", crate::error::E_DISC_READ), + "the error's OWN code: {line:?}" + ); + } + + /// A non-absence SSIF failure that the `.m2ts` fallback then papers over + /// must be LOGGED, with its own code. + /// + /// `unresolved` had exactly one reader — `if let (None, Some(code))` — so + /// a code recorded for `/BDMV/STREAM/SSIF/.ssif` was thrown away + /// whenever the fallback succeeded. The disc here IS a 3D disc: the SSIF + /// is present and carries both eyes, and only its ICB is unreadable (a + /// scratched sector, the ordinary way this happens). The title shipped + /// base-view 2D at rc=0 with `is_3d` false and NOT ONE LOG LINE, so the + /// operator's rip is silently missing the dependent view and the journal + /// cannot tell this disc apart from one that was only ever 2D. + /// + /// The title is deliberately still RETURNED — the base view resolved, so + /// refusing would trade a degraded rip for no rip. The defect being fixed + /// is the silence, not the fallback. + /// + /// Mutations this catches: deleting the new `(Some(_), Some(code))` arm, + /// or restoring the `if let (None, Some(code))` shape, leaves no event to + /// find; logging a fixed code instead of `e.code()` fails the code + /// assertion; making the arm `return Ok(None)` fails the title assertion. + #[test] + fn parse_playlist_logs_a_non_absence_ssif_failure_the_m2ts_fallback_hid() { + let mut disc = MemDisc::new(); + let bdmv = DirSpec { + name: "BDMV".to_string(), + icb_lba: 20, + dir_data_lba: 21, + files: Vec::new(), + subdirs: vec![ + DirSpec { + name: "STREAM".to_string(), + icb_lba: 22, + dir_data_lba: 23, + // The base view is healthy and resolves normally. + files: vec![file("00001.m2ts", 100, 5000, 1000 * 2048, true)], + subdirs: vec![DirSpec { + name: "SSIF".to_string(), + icb_lba: 26, + dir_data_lba: 27, + files: vec![file("00001.ssif", 104, 6000, 4096, false)], + subdirs: vec![], + }], + }, + DirSpec { + name: "CLIPINF".to_string(), + icb_lba: 24, + dir_data_lba: 25, + files: vec![file_with("00001.clpi", 102, 8000, build_clpi(4000), false)], + subdirs: vec![], + }, + ], + }; + let root = DirSpec { + name: String::new(), + icb_lba: 10, + dir_data_lba: 11, + files: Vec::new(), + subdirs: vec![bdmv], + }; + build_udf_skeleton(&mut disc, 10); + lay_dir(&mut disc, &root); + // Corrupt ONLY the SSIF's descriptor tag: structurally valid ICB + // behind a tag the parser rejects, i.e. what a garbled sector looks + // like. Not an absence — the directory entry is still there. + let mut icb = build_file_icb(4096, 6000, false); + icb[0..2].copy_from_slice(&999u16.to_le_bytes()); + disc.put_bytes(PART_START + 104, &icb); + let udf = udf::read_filesystem(&mut disc).expect("fs"); + + // The fixture must really produce a NON-ABSENCE error on the SSIF and + // a clean resolve on the .m2ts, or the behaviour under test is never + // reached and the test would pass for the wrong reason. + assert!( + matches!( + udf.file_extents(&mut disc, "/BDMV/STREAM/SSIF/00001.ssif"), + Err(Error::DiscRead { .. }) + ), + "fixture must fail the SSIF with DiscRead, not UdfNotFound" + ); + assert!( + udf.file_extents(&mut disc, "/BDMV/STREAM/00001.m2ts") + .is_ok() + ); + + let mpls = build_mpls( + &[PiSpec { + clip_id: *b"00001", + in_time: 0, + out_time: 60 * 45000, + }], + (0, 0, 0, 0, 0, 0, 0, 0), + &[], + &[], + ); + let (t, events) = crate::testlog::capture(|| { + Disc::parse_playlist(&mut disc, &udf, "00001.mpls", &mpls).expect("scan") + }); + let t = t.expect("the base view resolved, so the 2D title still ships"); + assert_eq!(t.extents.len(), 1, "base-view extents present"); + + let line = events + .iter() + .find(|e| e.target == "freemkv::disc") + .unwrap_or_else(|| { + panic!("silently shipping 2D off a 3D disc must be logged; got {events:?}") + }); + assert_eq!(line.level, tracing::Level::WARN); + assert_eq!(line.field("clip"), Some("\"00001\"")); + assert_eq!( + line.message(), + format!("E{}", crate::error::E_DISC_READ), + "the SSIF failure's OWN code, not a fixed one: {line:?}" + ); } // --------------------------------------------------------------- diff --git a/src/disc/hddvd.rs b/src/disc/hddvd.rs index c83c088..f10a0f0 100644 --- a/src/disc/hddvd.rs +++ b/src/disc/hddvd.rs @@ -947,11 +947,16 @@ impl Disc { // // The Blu-ray half of this same fix already warns; this // file had no diagnostics at all. Logging is exempt from - // the crate's no-English rule (errors stay numeric: E6017). + // the crate's no-English rule (errors stay numeric). + // + // Named constant, not the literal 6017 this used to carry: + // a hardcoded code in the very file whose sibling arm was + // changed to stop doing that is the next drift waiting to + // happen, and the literal cannot follow a renumbering. tracing::warn!( target: "freemkv::disc", clip = ?name, - code = 6017, + code = crate::error::E_UDF_UNRECORDED_EXTENT, "clip carries an unrecorded extent; dropping every title that names it" ); unusable.insert(name.to_ascii_lowercase()); @@ -983,7 +988,55 @@ impl Disc { unusable.insert(name.to_ascii_lowercase()); } } - if !extents.is_empty() { + // A clip that resolved with NO usable extent is unusable too, and + // for exactly the same reason as the `Err` arms above. + // + // Round 1 accounted for every `Err` from `file_extents` and left + // this route open: `Ok` can still yield an empty AD list, or a list + // every entry of which the `sectors > 0 && lba > 0` filter above + // discards (a zero-length placeholder AD, or one pointing at LBA + // 0 — see `UdfFs::file_extents`). The clip then entered NEITHER + // `clip_extents` NOR `unusable`, and nothing was logged. The + // composer's `any(|n| unusable.contains(..))` guard below therefore + // missed it and the `filter(|n| clip_extents.contains_key(..))` + // beside it quietly deleted the part: a `FEATURE_2.EVO` of size 0 + // next to a healthy `FEATURE_1.EVO` composed a FEATURE title out of + // part one alone, still advertising the whole runtime, at rc=0, + // silently. That is strictly WORSE than the `Err` case this guard + // was built for — half a movie presented as a whole one — and it is + // reachable from an ordinary zero-byte file, no crafting needed. + // + // WHY THE BLU-RAY HALF DELIBERATELY DIFFERS. `bluray.rs` documents + // this same `Ok`-but-empty hole as a KNOWN GAP and leaves it open, + // and that decision still stands there — not here. Two things are + // different. (1) Cost: BD has no `unusable` set, so closing it + // there means a post-loop "every clip_id must appear in `spans`" + // invariant that DROPS the title, and it is not settled that an + // empty-but-Ok resolve is always a defect rather than a legitimate + // healthy-disc state; dropping healthy titles is worse than the + // gap. Here the set already exists, so refusing costs nothing new. + // (2) Consequence: on BD the clip is one PlayItem of a title that + // is otherwise whole; on HD-DVD the authored feature is COMPOSED + // from parts, so the missing one is silently spliced out of a title + // that keeps claiming the full runtime. Same hole, different price. + // The asymmetry is deliberate; it is written down here so the next + // audit reads a decision instead of finding an oversight. + // + // `insert` returning false means an `Err` arm above already logged + // this clip — no second line for one clip. + if extents.is_empty() { + if unusable.insert(name.to_ascii_lowercase()) { + // Not the neighbouring 6017: an empty AD list is not an + // unrecorded extent, and flattening the two would account a + // zero-byte file as an authoring hole. + tracing::warn!( + target: "freemkv::disc", + clip = ?name, + code = crate::error::E_UDF_NO_USABLE_EXTENT, + "clip resolved to no usable extent; dropping every title that names it" + ); + } + } else { clip_extents.insert(name.to_ascii_lowercase(), (name.clone(), *size, extents)); } } @@ -1463,6 +1516,161 @@ mod tests { ); } + /// The refusal above must also be ACCOUNTED, with the unrecorded extent's + /// own code. + /// + /// This warn site carried a hardcoded `code = 6017` literal — in the very + /// file whose sibling arm was changed to stop doing exactly that — and + /// nothing tested it, so neither the literal nor its absence broke + /// anything. Refusing a feature and saying nothing leaves the operator + /// with a disc that scanned "fine" and is quietly missing its main title. + /// + /// Mutations: deleting the `tracing::warn!` (no event to find); restoring + /// the literal `6017` still passes here BY VALUE, which is the point — + /// what is pinned is `E_UDF_UNRECORDED_EXTENT`'s value reaching the log, + /// so a renumbering that the literal could not follow goes red; logging a + /// neighbouring code (e.g. `E_UDF_NO_USABLE_EXTENT`) goes red immediately. + #[test] + fn scan_hddvd_logs_an_unrecorded_feature_part_with_its_own_code() { + let mut disc = MemDisc::new(); + let vti = synthetic_vti(&["FEATURE_1.EVO", "FEATURE_2.EVO"]); + let files = vec![ + file("FEATURE_1.EVO", 100, 5000, 10 * 2048, true), + file("FEATURE_2.EVO", 101, 8000, 6 * 2048, true), + file_with("HVA00001.VTI", 103, 15000, vti, true), + ]; + let root = DirSpec { + name: String::new(), + icb_lba: 10, + dir_data_lba: 11, + files: Vec::new(), + subdirs: vec![DirSpec { + name: "HVDVD_TS".to_string(), + icb_lba: 20, + dir_data_lba: 21, + files, + subdirs: vec![], + }], + }; + build_udf_skeleton(&mut disc, 10); + lay_dir(&mut disc, &root); + // Same crafted ICB as the test above: an unrecorded (type 1) extent + // ahead of FEATURE_2's real content. + let mut icb = build_file_icb(6 * 2048, 8000, false); + icb[212..216].copy_from_slice(&16u32.to_le_bytes()); + icb[216..220].copy_from_slice(&0x4000_0800u32.to_le_bytes()); + icb[220..224].copy_from_slice(&7999u32.to_le_bytes()); + icb[224..228].copy_from_slice(&(6u32 * 2048).to_le_bytes()); + icb[228..232].copy_from_slice(&8000u32.to_le_bytes()); + disc.put_bytes(PART_START + 101, &icb); + let udf = crate::udf::read_filesystem(&mut disc).expect("fs"); + + let (_titles, events) = crate::testlog::capture(|| { + Disc::scan_hddvd_titles(&mut disc, &udf, None).expect("scan") + }); + let line = events + .iter() + .find(|e| e.field("clip") == Some("\"FEATURE_2.EVO\"")) + .unwrap_or_else(|| panic!("the refused clip must be logged; got {events:?}")); + assert_eq!(line.target, "freemkv::disc"); + assert_eq!(line.level, tracing::Level::WARN); + assert_eq!( + line.field("code"), + Some(crate::error::E_UDF_UNRECORDED_EXTENT.to_string().as_str()), + "{line:?}" + ); + } + + /// The `Ok`-but-empty twin of the test above, and the one that actually + /// bites on an ordinary disc: a feature part whose `file_extents` call + /// SUCCEEDS and yields nothing usable — here a zero-byte `FEATURE_2.EVO`, + /// no crafted ICB required — must refuse the composition too, and must say + /// so in the log. + /// + /// Before this, the empty-`Ok` clip entered neither `clip_extents` nor + /// `unusable`, so the `any(|n| unusable.contains(..))` guard missed it and + /// the `filter(|n| clip_extents.contains_key(..))` beside it quietly + /// DELETED the part: the scan composed a `FEATURE` title out of part one + /// alone, still advertising itself as the feature, at rc=0, with no + /// diagnostic anywhere. Half a movie presented as a whole one — strictly + /// worse than the `Err` case the guard was built for, and reachable + /// without a hostile disc. + /// + /// Mutations this catches, all of which the pre-fix code exhibited: + /// * dropping the `extents.is_empty()` branch entirely -> a `FEATURE` + /// title appears with one extent; + /// * inserting into `clip_extents` anyway -> same; + /// * marking the clip unusable but NOT logging -> the log assertion + /// fails (absence of a log is itself the defect: nothing else in the + /// system records that a part of the feature went missing); + /// * logging the neighbouring `E_UDF_UNRECORDED_EXTENT` instead of + /// `E_UDF_NO_USABLE_EXTENT` -> the code assertion fails, because a + /// zero-length file is not an authoring hole and triaging the two + /// together sends whoever reads it at the wrong population. + #[test] + fn scan_hddvd_does_not_compose_a_feature_over_a_part_with_no_usable_extent() { + let mut disc = MemDisc::new(); + let vti = synthetic_vti(&["FEATURE_1.EVO", "FEATURE_2.EVO", "TRAILER.EVO"]); + let files = vec![ + file("FEATURE_1.EVO", 100, 5000, 10 * 2048, true), + // Size 0 -> `file_extents` returns Ok with a zero-sector AD, which + // the `sectors > 0 && lba > 0` filter discards. No error is ever + // returned; the clip simply resolves to nothing. + file("FEATURE_2.EVO", 101, 8000, 0, true), + file("TRAILER.EVO", 102, 12000, 2 * 2048, true), + file_with("HVA00001.VTI", 103, 15000, vti, true), + ]; + let root = DirSpec { + name: String::new(), + icb_lba: 10, + dir_data_lba: 11, + files: Vec::new(), + subdirs: vec![DirSpec { + name: "HVDVD_TS".to_string(), + icb_lba: 20, + dir_data_lba: 21, + files, + subdirs: vec![], + }], + }; + build_udf_skeleton(&mut disc, 10); + lay_dir(&mut disc, &root); + let udf = crate::udf::read_filesystem(&mut disc).expect("fs"); + + let (titles, events) = crate::testlog::capture(|| { + Disc::scan_hddvd_titles(&mut disc, &udf, None).expect("scan") + }); + + assert!( + !titles.iter().any(|t| t.playlist == "FEATURE"), + "a feature part that resolved to no usable extent must not be \ + composed into a title that silently omits it while claiming the \ + whole feature; got {:?}", + titles + .iter() + .map(|t| (&t.playlist, t.extents.len(), t.size_bytes)) + .collect::>() + ); + // Refusing the composition is not refusing the disc. + assert!( + titles.iter().any(|t| t.playlist == "FEATURE_1.EVO"), + "the part that DID resolve is still offered standalone" + ); + assert!(titles.iter().any(|t| t.playlist == "TRAILER.EVO")); + + // ...and it is accounted, with its own code, naming the clip. + let line = events + .iter() + .find(|e| e.target == "freemkv::disc" && e.field("clip") == Some("\"FEATURE_2.EVO\"")) + .unwrap_or_else(|| panic!("the dropped clip must be logged; got {events:?}")); + assert_eq!(line.level, tracing::Level::WARN); + assert_eq!( + line.field("code"), + Some(crate::error::E_UDF_NO_USABLE_EXTENT.to_string().as_str()), + "the condition's OWN code, not a neighbouring one: {line:?}" + ); + } + // ── codec sniffing ──────────────────────────────────────────────────── #[test] diff --git a/src/disc/mod.rs b/src/disc/mod.rs index 3888a4e..a610da5 100644 --- a/src/disc/mod.rs +++ b/src/disc/mod.rs @@ -3716,6 +3716,115 @@ mod tests { ); } + /// `scan_with` must hand `ScanOptions::halt` to the BLU-RAY enumerator. + /// + /// Every BD and DVD cancellation test in this crate calls + /// `scan_bluray_titles` / `scan_dvd_titles` DIRECTLY, so the three-line + /// wiring in `scan_with` that connects the operator's Stop to them was + /// covered by nothing at all: replacing `opts.halt.as_ref()` with `None` + /// on either branch left the whole suite green while a Stop during a BD + /// or DVD scan silently did nothing. Only the HD-DVD branch was pinned. + /// + /// The fixture is deliberately the smallest disc that takes the BD branch + /// — a bare `/BDMV` with no PLAYLIST — because the point under test is the + /// ARGUMENT, not the enumerator's own (separately tested) halt polling. + /// Nothing between `scan_with`'s entry and the enumerator reads the flag + /// (the disc is unencrypted, so the AACS path is skipped), so a green here + /// can only mean the flag arrived. + /// + /// Mutation: `Self::scan_bluray_titles(reader, &udf_fs, None)?` fails here. + #[test] + fn scan_with_passes_the_halt_flag_to_the_bluray_enumerator() { + use crate::udf::fixture::*; + let mut disc = MemDisc::new(); + let root = DirSpec { + name: String::new(), + icb_lba: 10, + dir_data_lba: 11, + files: Vec::new(), + subdirs: vec![DirSpec { + name: "BDMV".into(), + icb_lba: 12, + dir_data_lba: 13, + files: Vec::new(), + subdirs: vec![], + }], + }; + build_udf_skeleton(&mut disc, 10); + lay_dir(&mut disc, &root); + let udf = crate::udf::read_filesystem(&mut disc).expect("fs"); + + // Sanity: the same disc scans clean when nothing is cancelled, so a + // pass below cannot be some unrelated failure wearing Halted. + assert!( + Disc::scan_with(&mut disc, 500_000, None, None, &ScanOptions::default(), udf).is_ok(), + "fixture must scan successfully when not cancelled" + ); + + let udf = crate::udf::read_filesystem(&mut disc).expect("fs"); + let halt = crate::halt::Halt::new(); + halt.cancel(); + let opts = ScanOptions { + halt: Some(halt), + ..Default::default() + }; + let res = Disc::scan_with(&mut disc, 500_000, None, None, &opts, udf); + assert!( + matches!(res, Err(Error::Halted)), + "a cancelled BD scan must say so; returning a title list built \ + after Stop reports a truncated enumeration as a completed one. \ + Got {:?}", + res.map(|d| d.titles.len()) + ); + } + + /// The DVD half of the same wiring, and the same reasoning. + /// + /// Mutation: `Self::scan_dvd_titles(reader, &udf_fs, None)?` fails here. + #[test] + fn scan_with_passes_the_halt_flag_to_the_dvd_enumerator() { + use crate::udf::fixture::*; + let mut disc = MemDisc::new(); + let root = DirSpec { + name: String::new(), + icb_lba: 10, + dir_data_lba: 11, + files: Vec::new(), + subdirs: vec![DirSpec { + name: "VIDEO_TS".into(), + icb_lba: 50, + dir_data_lba: 51, + files: vec![ + file_with("VIDEO_TS.IFO", 60, 5000, dvd_vmg_bytes(), true), + file_with("VTS_01_0.IFO", 62, 6000, dvd_vts_bytes(1000, 10, 10), true), + ], + subdirs: vec![], + }], + }; + build_udf_skeleton(&mut disc, 10); + lay_dir(&mut disc, &root); + let udf = crate::udf::read_filesystem(&mut disc).expect("fs"); + assert!( + Disc::scan_with(&mut disc, 500_000, None, None, &ScanOptions::default(), udf).is_ok(), + "fixture must scan successfully when not cancelled" + ); + + let udf = crate::udf::read_filesystem(&mut disc).expect("fs"); + let halt = crate::halt::Halt::new(); + halt.cancel(); + let opts = ScanOptions { + halt: Some(halt), + ..Default::default() + }; + let res = Disc::scan_with(&mut disc, 500_000, None, None, &opts, udf); + assert!( + matches!(res, Err(Error::Halted)), + "a cancelled DVD scan must say so, not hand back whatever it had \ + enumerated so far as a finished scan. Got {:?}", + res.map(|d| d.titles.len()) + ); + } + /// A Stop on a LIVE DRIVE never touches `ScanOptions::halt`: `Drive` has /// its own flag and `checked_exec` fails every SCSI command with /// [`Error::Halted`] once it is set. The HD-DVD enumerator must not diff --git a/src/drive/mod.rs b/src/drive/mod.rs index 15edab0..727f86a 100644 --- a/src/drive/mod.rs +++ b/src/drive/mod.rs @@ -290,22 +290,33 @@ impl Drive { for attempt in 0..60u64 { hb.tick(attempt, 60); let mut buf = [0u8; 0]; - if self - .scsi - .as_mut() - .execute(&tur, crate::scsi::DataDirection::None, &mut buf, 5_000) - .is_ok() - { - tracing::info!( - target: "freemkv::drive", - phase = "wait_ready", - attempts = attempt + 1, - elapsed_ms = t0.elapsed().as_millis() as u64, - "end" - ); - return Ok(()); + // `checked_exec`, not a bare `execute`. This poll was the ONE + // drive path that talked to the transport directly, and it is the + // longest-running one: 60 x 500 ms = ~30 s. It never read + // `self.halt`, so an operator Stop pressed while a cold drive spun + // up was ignored for up to half a minute while every other path in + // this file returned `Halted` at its next command boundary. A Stop + // that does nothing for 30 s is indistinguishable from a hung app. + // + // A TUR that FAILS is the ordinary not-ready-yet answer and must + // keep the loop going — only `Halted` aborts it. + match self.checked_exec(&tur, crate::scsi::DataDirection::None, &mut buf, 5_000) { + Ok(_) => { + tracing::info!( + target: "freemkv::drive", + phase = "wait_ready", + attempts = attempt + 1, + elapsed_ms = t0.elapsed().as_millis() as u64, + "end" + ); + return Ok(()); + } + Err(Error::Halted) => return Err(Error::Halted), + Err(_) => {} } - std::thread::sleep(std::time::Duration::from_millis(500)); + // Halt-aware backoff: the flag can also flip DURING the 500 ms + // gap, which is where most of the 30 s is actually spent. + sleep_until_halted(&self.halt, std::time::Duration::from_millis(500))?; } tracing::warn!( target: "freemkv::drive", @@ -937,11 +948,34 @@ impl Drive { // range NonTrimmed and retries (a loud miss, never a silent commit). // The sector/file path enforces the same invariant in // sector/prefetched.rs; this is the live-drive counterpart. - Ok(_) => Err(Error::DiscRead { - sector: lba as u64, - status: None, - sense: None, - }), + // + // SAY SO. The refusal was correct and completely silent: the + // sibling `Err(e)` arm below warns with lba/count/status, this one + // logged nothing at all, so a drive that residual-underruns on + // GOOD status was indistinguishable in the logs from a scratched + // disc — two different populations (replace the drive vs. clean + // the disc) collapsed into one. Absence of a log is itself the + // defect here; the read still fails either way. + // + // `scsi_status`/`sense` are deliberately absent from the line + // rather than faked: the command SUCCEEDED, so there is no sense + // data to report. `transferred` vs `expected` is the whole signal. + Ok(result) => { + tracing::warn!( + target: "freemkv::drive", + lba, + count, + transferred = result.bytes_transferred, + expected = count as usize * 2048, + code = crate::error::E_DISC_READ, + "READ(10) returned GOOD status with a residual underrun; refusing the short transfer" + ); + Err(Error::DiscRead { + sector: lba as u64, + status: None, + sense: None, + }) + } Err(Error::Halted) => Err(Error::Halted), Err(e) => { let (status, sense) = extract_scsi_context(&e); @@ -1097,14 +1131,25 @@ impl Drive { let stop = [SCSI_START_STOP_UNIT, 0, 0, 0, 0x00, 0]; // START=0, LOEJ=0 → spin down let start = [SCSI_START_STOP_UNIT, 0, 0, 0, 0x01, 0]; // START=1, LOEJ=0 → spin up let mut buf = [0u8; 0]; - self.scsi - .as_mut() - .execute(&stop, crate::scsi::DataDirection::None, &mut buf, 30_000)?; - std::thread::sleep(std::time::Duration::from_secs(SPIN_DOWN_IDLE_SECS)); - self.scsi - .as_mut() - .execute(&start, crate::scsi::DataDirection::None, &mut buf, 30_000)?; - std::thread::sleep(std::time::Duration::from_secs(SPIN_UP_SETTLE_SECS)); + // `checked_exec` + `sleep_until_halted`, not `execute` + a blind + // `thread::sleep`. This routine is ~15 s of deliberate waiting + // (`SPIN_DOWN_IDLE_SECS` + `SPIN_UP_SETTLE_SECS`) issued from the + // recovery path, i.e. exactly when a run is going badly and the + // operator is most likely to press Stop. Both commands bypassed the + // halt flag and both sleeps were unconditional, so the whole cycle was + // deaf: Stop appeared to hang. Nothing here is un-interruptible — a + // half-finished spin cycle leaves the drive spun down, which the next + // command spins back up. + self.checked_exec(&stop, crate::scsi::DataDirection::None, &mut buf, 30_000)?; + sleep_until_halted( + &self.halt, + std::time::Duration::from_secs(SPIN_DOWN_IDLE_SECS), + )?; + self.checked_exec(&start, crate::scsi::DataDirection::None, &mut buf, 30_000)?; + sleep_until_halted( + &self.halt, + std::time::Duration::from_secs(SPIN_UP_SETTLE_SECS), + )?; Ok(()) } @@ -1310,11 +1355,18 @@ pub(crate) fn decode_read_capacity(buf: &[u8; 8], bytes_transferred: usize) -> R last_lba.checked_add(1).ok_or(Error::DiscCapacityOverflow) } -/// Halt-aware sleep primitive — wakes within ~100 ms of `halt` flipping -/// to true. Kept for the unit tests that cover the slicing behaviour; -/// production code paths no longer sleep on the recovery hot path -/// (recovery loop removed in 0.13.6). -#[cfg(test)] +/// Halt-aware sleep primitive — wakes within ~100 ms of `halt` flipping to +/// true, returning [`Error::Halted`]. +/// +/// This was `#[cfg(test)]` for two releases, kept alive only by the four unit +/// tests below, while the two production paths that actually sleep — the +/// `wait_ready` poll backoff (60 x 500 ms) and `spin_cycle`'s spin-down/settle +/// pauses (`SPIN_DOWN_IDLE_SECS` + `SPIN_UP_SETTLE_SECS`) — used a plain +/// `std::thread::sleep` and so were DEAF to the operator's Stop for ~30 s and +/// ~15 s respectively. Every other drive path returns `Halted` at the next +/// `checked_exec` boundary; a Stop pressed during spin-up simply did nothing +/// visible until the poll ran out. The primitive existed; the sleeping code +/// just did not call it. It is production code again. fn sleep_until_halted(halt: &AtomicBool, total: std::time::Duration) -> Result<()> { const SLICE: std::time::Duration = std::time::Duration::from_millis(100); let deadline = std::time::Instant::now() + total; @@ -2684,6 +2736,231 @@ mod command_tests { ); } + /// A Stop pressed before the poll starts must be answered at once. + /// + /// `wait_ready` was the ONE drive path that called + /// `self.scsi.as_mut().execute(..)` instead of `checked_exec`, and its + /// 60 x 500 ms loop never read `self.halt`. A cancel during spin-up was + /// therefore ignored for ~30 s — the test above measures exactly how long + /// — while every other drive path returns `Halted` at its next command + /// boundary. Thirty seconds of a dead Stop button is indistinguishable + /// from a hung application. + /// + /// Mutation: restoring the bare `execute` makes this run the full poll and + /// return `DeviceNotReady`, failing both assertions. + #[test] + fn wait_ready_returns_halted_when_stopped_before_the_poll() { + struct NeverReady; + impl ScsiTransport for NeverReady { + fn execute( + &mut self, + cdb: &[u8], + _dir: DataDirection, + _data: &mut [u8], + _timeout_ms: u32, + ) -> Result { + Err(Error::ScsiError { + opcode: cdb[0], + status: 2, + sense: None, + }) + } + } + let mut d = Drive::from_transport_for_test(Box::new(NeverReady)); + d.halt(); + let t0 = std::time::Instant::now(); + let r = d.wait_ready(); + assert!( + matches!(r, Err(Error::Halted)), + "a Stop is the operator, not a drive that failed to spin up: {r:?}" + ); + assert!( + t0.elapsed() < std::time::Duration::from_secs(5), + "the poll must abandon immediately, not run its ~30 s course" + ); + } + + /// ...and a Stop pressed PART WAY THROUGH the poll must be answered at the + /// next command boundary, not at the end of the 30 s. + /// + /// The flag is flipped by the transport itself on its third TEST UNIT + /// READY, which is deterministic (no wall-clock race): `checked_exec` + /// re-reads the flag after the command completes, so the loop must exit on + /// attempt three of sixty. + #[test] + fn wait_ready_returns_halted_when_stopped_during_the_poll() { + struct StopsOnThirdPoll { + halt: Arc, + seen: usize, + } + impl ScsiTransport for StopsOnThirdPoll { + fn execute( + &mut self, + cdb: &[u8], + _dir: DataDirection, + _data: &mut [u8], + _timeout_ms: u32, + ) -> Result { + self.seen += 1; + if self.seen == 3 { + self.halt.store(true, Ordering::Relaxed); + } + Err(Error::ScsiError { + opcode: cdb[0], + status: 2, + sense: None, + }) + } + } + let mut d = Drive::from_transport_for_test(Box::new(StopsOnThirdPoll { + halt: Arc::new(AtomicBool::new(false)), + seen: 0, + })); + // Hand the transport the drive's OWN flag, so setting it is exactly + // what an operator's Stop does. + let flag = d.halt_flag(); + d.scsi = Box::new(StopsOnThirdPoll { + halt: flag, + seen: 0, + }); + let t0 = std::time::Instant::now(); + let r = d.wait_ready(); + assert!( + matches!(r, Err(Error::Halted)), + "a mid-poll Stop must surface as Halted, not as DeviceNotReady \ + after the full 30 s: {r:?}" + ); + assert!( + t0.elapsed() < std::time::Duration::from_secs(5), + "must exit on the third poll, not the sixtieth" + ); + } + + /// `spin_cycle` must not be deaf to Stop for its ~15 s of deliberate + /// waiting. + /// + /// Both START STOP UNIT commands went out through a bare `execute` and + /// both pauses (`SPIN_DOWN_IDLE_SECS` + `SPIN_UP_SETTLE_SECS`) were plain + /// `std::thread::sleep`, so the whole routine ignored the halt flag. It + /// runs from the RECOVERY path — precisely when a run is going badly and + /// the operator is most likely to press Stop. + /// + /// The flag is set BEFORE the call, so this is deterministic: the very + /// first `checked_exec` must refuse. + /// + /// Mutation: restoring either bare `execute` lets the first command + /// through and the test then waits out a real 5 s sleep, failing the + /// elapsed bound. + #[test] + fn spin_cycle_returns_halted_when_stopped_before_it_starts() { + let RecordingHarness { + drive: mut d, + cdb, + timeouts: _to, + } = recording(TransportOutcome::Ok(0)); + d.halt(); + let t0 = std::time::Instant::now(); + let r = d.spin_cycle(); + assert!( + matches!(r, Err(Error::Halted)), + "a Stop must abort the spin cycle: {r:?}" + ); + assert!( + t0.elapsed() < std::time::Duration::from_secs(2), + "no sleep may run after the flag is set" + ); + assert!( + cdb.lock().unwrap().is_empty(), + "not one START STOP UNIT may be issued after Stop" + ); + } + + /// ...and a Stop that lands DURING the spin-down pause must wake it. + /// + /// This is the half a `checked_exec` alone cannot fix: the flag flips + /// while the thread is parked inside the 5 s `SPIN_DOWN_IDLE_SECS` sleep, + /// so only a halt-aware sleep can observe it. `sleep_until_halted` — which + /// already lived in this file with four tests, marked `#[cfg(test)]` and + /// called from nowhere — wakes within ~100 ms. + /// + /// The margin is deliberately enormous (≈0.3 s against 5 s) so the bound + /// is not a wall-clock race: a plain `thread::sleep` cannot come in under + /// two seconds, and the halt-aware one cannot take that long. + #[test] + fn spin_cycle_wakes_from_its_spin_down_pause_when_stopped() { + let RecordingHarness { + drive: mut d, + cdb: _cdb, + timeouts: _to, + } = recording(TransportOutcome::Ok(0)); + let flag = d.halt_flag(); + let stopper = std::thread::spawn(move || { + std::thread::sleep(std::time::Duration::from_millis(200)); + flag.store(true, Ordering::Relaxed); + }); + let t0 = std::time::Instant::now(); + let r = d.spin_cycle(); + stopper.join().expect("stopper thread"); + assert!( + matches!(r, Err(Error::Halted)), + "a Stop during the spin-down pause must surface as Halted: {r:?}" + ); + assert!( + t0.elapsed() < std::time::Duration::from_secs(2), + "the pause must be halt-aware, not a blind {SPIN_DOWN_IDLE_SECS}s \ + thread::sleep; took {:?}", + t0.elapsed() + ); + } + + /// A READ(10) that completes with GOOD status but a residual underrun is + /// correctly refused — and must SAY SO. + /// + /// The refusal itself already existed and is right: the tail of the buffer + /// still holds stale bytes, so committing them would be silent + /// corruption. What was missing is any trace of it. The sibling `Err(e)` + /// arm warns with lba/count/status; this arm logged NOTHING, so a drive + /// that residual-underruns on GOOD status produced exactly the same + /// journal as a scratched disc — two populations with opposite remedies + /// (replace the drive vs. clean the disc) collapsed into one, with the + /// operator sent after the wrong one. + /// + /// Mutation: deleting the `tracing::warn!` leaves no event; logging a + /// different code, or dropping the transferred/expected pair that is the + /// entire signal, fails the field assertions. + #[test] + fn read_logs_a_good_status_short_transfer() { + let RecordingHarness { + drive: mut d, + cdb: _cdb, + timeouts: _to, + } = recording(TransportOutcome::Ok(1024)); // half of one sector + let mut buf = vec![0u8; 2048]; + let (r, events) = crate::testlog::capture(|| d.read(7, 1, &mut buf, false)); + assert!( + matches!(r, Err(Error::DiscRead { sector: 7, .. })), + "a short transfer stays a failed read: {r:?}" + ); + let line = events + .iter() + .find(|e| e.target == "freemkv::drive" && e.field("transferred").is_some()) + .unwrap_or_else(|| { + panic!("a silently refused short transfer is the defect; got {events:?}") + }); + assert_eq!(line.level, tracing::Level::WARN); + assert_eq!(line.field("lba"), Some("7")); + assert_eq!(line.field("transferred"), Some("1024")); + assert_eq!( + line.field("expected"), + Some("2048"), + "the underrun is only legible as transferred-vs-expected" + ); + assert_eq!( + line.field("code"), + Some(crate::error::E_DISC_READ.to_string().as_str()) + ); + } + // ── report_key / mode_sense / read_buffer empty-vs-some ───────── #[test] diff --git a/src/error.rs b/src/error.rs index 84c829e..14ca4aa 100644 --- a/src/error.rs +++ b/src/error.rs @@ -67,6 +67,19 @@ pub const E_IMAGE_TRUNCATED: u16 = 6015; pub const E_UDF_AD_CHAIN_TOO_LONG: u16 = 6016; pub const E_UDF_UNRECORDED_EXTENT: u16 = 6017; pub const E_UDF_EMBEDDED_DATA: u16 = 6018; +/// A file that EXISTS and whose allocation descriptors resolved without error, +/// yet yields not one usable extent: an empty AD list, or a list every entry of +/// which is zero-length or points at LBA 0. Reported by the HD-DVD clip +/// resolver (`disc::hddvd`). +/// +/// It has no [`Error`] variant on purpose. `UdfFs::file_extents` returns +/// `Ok(vec![])` here rather than failing — the emptiness is only a defect in +/// the eye of a caller that needs bytes — so the condition is DETECTED by the +/// caller, not returned to it. The code exists so that detection can be +/// accounted in the log with something other than a neighbouring error's code: +/// logging it as E6017 would file a zero-length AD list as an authoring hole +/// and send whoever triages it at the wrong population. +pub const E_UDF_NO_USABLE_EXTENT: u16 = 6019; // AACS (7xxx) pub const E_AACS_NO_KEYS: u16 = 7000; @@ -1900,133 +1913,129 @@ mod tests { // ── New comprehensive tests ──────────────────────────────────────────────── + /// Every `pub const E_*` code declared in this file, as + /// `(name, value)`, PARSED OUT OF THE SOURCE at compile time. + /// + /// WHY THIS IS PARSED AND NOT LISTED. The uniqueness test below used to + /// carry a hand-maintained `vec![]` of the constants, with a doc comment + /// claiming it "pins all code assignments". It did not. At the time this + /// was written the file declared **127** `pub const E_*` and the vector + /// named **109** of them: eighteen codes — `E_DIR_IMAGE_FANOUT`, + /// `E_DIR_INSUFFICIENT_SPACE`, `E_DIR_MULTIPASS_REJECTED`, + /// `E_DIR_NAME_COLLISION`, `E_DIR_NAME_TOO_LONG`, `E_DIR_NOT_EMPTY`, + /// `E_DIR_RAW_REJECTED`, `E_DIR_SOURCE_UNSUPPORTED`, `E_DIR_WRITE_FAILED`, + /// `E_DRIVE_INQUIRY_SHORT`, `E_EMPTY_IMAGE`, `E_MP4_UNKNOWN_RESOLUTION`, + /// `E_SEAM_PLAN_DROPPED_MOST`, `E_SHORT_IMAGE_READ`, `E_SINK_WROTE_NOTHING`, + /// `E_SOURCE_TERMINATED`, `E_SYNC_TIMEOUT`, `E_SYNC_WORKER_LOST` — were + /// outside the guarantee entirely, so a new variant colliding with any of + /// them passed green. Worse, an earlier audit READ that doc comment and + /// trusted it while assigning new codes. + /// + /// The defect is not the eighteen omissions, it is that the list is + /// hand-maintained at all: adding a constant and forgetting the vector is + /// a silent no-op, which is the definition of a guarantee that decays. + /// Deriving the list from the declarations makes forgetting impossible — + /// the only way to escape the check is to stop declaring the constant. + /// + /// `include_str!` of this very file is the cheapest seam that does that: + /// no `build.rs`, no proc macro, no dependency, and — being `#[cfg(test)]` + /// — not one byte of the source embedded in a release build. + fn declared_error_codes() -> Vec<(&'static str, u16)> { + const SRC: &str = include_str!("error.rs"); + SRC.lines() + .filter_map(|line| { + // Only real declarations at column 0. A retired code is + // recorded as `// 2001: burned/retired`, which carries no `pub + // const` and is therefore correctly invisible here. + let decl = line.strip_prefix("pub const ")?; + let (name, value) = decl.split_once(": u16 = ")?; + if !name.starts_with("E_") { + return None; + } + let value = value.strip_suffix(';')?; + Some(( + name, + value + .parse::() + .unwrap_or_else(|_| panic!("non-literal error code for `{name}`")), + )) + }) + .collect() + } + + /// The parser above must actually FIND the declarations, and read their + /// values correctly. Without this, a `declared_error_codes` that returned + /// an empty vector would make the uniqueness test below pass vacuously — + /// exactly the failure mode (a guarantee that is really a no-op) this + /// whole change exists to remove. + /// + /// Mutation: a `strip_prefix` typo, an off-by-one in the name slice, or a + /// parser that drops the last line fails here. + #[test] + fn declared_error_codes_parses_the_declarations_it_claims_to() { + let declared = declared_error_codes(); + // Independent count of the declarations, computed a different way + // from the parser under test. + let expected = include_str!("error.rs") + .lines() + .filter(|l| l.starts_with("pub const E_")) + .count(); + assert_eq!( + declared.len(), + expected, + "the parser must see every `pub const E_*` line" + ); + assert!( + expected >= 120, + "sanity floor: this file declares well over a hundred codes, got {expected}" + ); + // Names and values must match the compiled constants, so a parser that + // mis-slices the name or mis-reads the digits cannot pass. + for (name, value) in [ + ("E_DEVICE_NOT_FOUND", E_DEVICE_NOT_FOUND), + ("E_UDF_UNRECORDED_EXTENT", E_UDF_UNRECORDED_EXTENT), + ("E_KEYDB_PARSE", E_KEYDB_PARSE), + ] { + assert!( + declared.contains(&(name, value)), + "`{name}` = {value} not parsed out of the source; got {:?}", + declared + .iter() + .filter(|(n, _)| *n == name) + .collect::>() + ); + } + // A comment-only retired code must NOT be picked up as a constant. + assert!( + !declared.iter().any(|(n, _)| n.is_empty()), + "no empty names" + ); + } + /// Every published error code constant must be unique. - /// This pins all code assignments: a new variant that accidentally reuses - /// an existing code will make this test fail. - /// Mutation: changing E_KEYDB_PARSE from 8004 to 8000 (duplicating E_KEYDB_CONNECT) fails here. + /// + /// The set is derived from the declarations by + /// [`declared_error_codes`], so — unlike the hand-kept vector this + /// replaced — a newly added constant is covered the moment it is + /// written, with no second edit to remember. + /// + /// Mutation: changing E_KEYDB_PARSE from 8004 to 8000 (duplicating + /// E_KEYDB_CONNECT) fails here, and so now does the same collision on any + /// of the eighteen codes the old hand-kept list had never heard of. #[test] fn all_error_code_constants_are_unique() { - let mut codes = vec![ - E_DEVICE_NOT_FOUND, - E_DEVICE_PERMISSION, - E_DEVICE_NOT_READY, - E_DEVICE_RESET_FAILED, - E_SCSI_INTERFACE_UNAVAILABLE, - E_DEVICE_LOCKED, - E_IOKIT_PLUGIN_FAILED, - E_UNSUPPORTED_DRIVE, - E_PROFILE_PARSE, - E_UNSUPPORTED_PLATFORM, - E_PLATFORM_NOT_IMPLEMENTED, - E_UNLOCK_FAILED, - E_SIGNATURE_MISMATCH, - E_SCSI_ERROR, - E_INVALID_CDB_LENGTH, - E_IO_ERROR, - E_DISC_READ, - E_MPLS_PARSE, - E_CLPI_PARSE, - E_UDF_NOT_FOUND, - E_DISC_TITLE_RANGE, - E_IFO_PARSE, - E_MKV_INVALID, - E_NO_STREAMS, - E_HALTED, - E_MAPFILE_INVALID, - E_IMAGE_TRUNCATED, - E_UDF_BUFFER_TOO_SMALL, - E_UDF_NOT_FILESYSTEM, - // These four were absent, so the "every published code is unique" - // claim above did not actually cover them: a new variant reusing - // 6014, 6016 or 6017 would have passed this test. - E_SELECTION_PID_UNKNOWN, - E_UDF_AD_CHAIN_TOO_LONG, - E_UDF_UNRECORDED_EXTENT, - E_UDF_EMBEDDED_DATA, - E_AACS_NO_KEYS, - E_AACS_CERT_SHORT, - E_AACS_AGID_ALLOC, - E_AACS_CERT_REJECTED, - E_AACS_CERT_READ, - E_AACS_CERT_VERIFY, - E_AACS_KEY_READ, - E_AACS_KEY_REJECTED, - E_AACS_KEY_VERIFY, - E_AACS_VID_READ, - E_AACS_VID_MAC, - E_AACS_DATA_KEY, - E_DECRYPT_FAILED, - E_CSS_AUTH_FAILED, - E_AACS_HOST_CERT_REJECTED, - E_AACS_RAW_READ_UNSUPPORTED, - E_AACS_VID_UNAVAILABLE, - E_AACS_MK_UNAVAILABLE, - E_AACS_VUK_NOT_IN_KEYDB, - E_DRIVE_PROFILE_MISSING, - E_VID_CDB_UNAVAILABLE, - E_NO_DISC_KEY, - E_CSS_KEY_MISSING, - E_CSS_NO_DISC_KEY, - E_KEY_SERVICE_UNAVAILABLE, - E_KEY_SERVICE_UNAUTHORIZED, - E_KEY_SERVICE_RATE_LIMITED, - E_AACS_NO_HOST_CERT, - E_AACS_BUS_KEY_UNAVAILABLE, - E_FMTS_KEY_MISSING, - E_KEYDB_CONNECT, - E_KEYDB_HTTP, - E_KEYDB_INVALID, - E_KEYDB_WRITE, - E_KEYDB_PARSE, - E_KEYDB_LOAD, - E_KEYDB_UNSUPPORTED_SCHEME, - E_KEYDB_TOO_MANY_REDIRECTS, - E_STREAM_READ_ONLY, - E_STREAM_WRITE_ONLY, - E_STREAM_URL_INVALID, - E_STREAM_URL_MISSING_PATH, - E_STREAM_URL_MISSING_PORT, - E_NETWORK_ADDR_BLOCKED, - E_MUX_EMPTY, - E_MUX_HEADER_BUFFER_EXCEEDED, - E_MKV_LACING_INVALID, - E_MKV_SOURCE_INVALID, - E_MKV_UNENCODABLE, - E_MP4_NO_VIDEO_TRACK, - E_MP4_INVALID, - E_MP4_MISSING_CODEC_PRIVATE, - E_PES_FRAME_TOO_LARGE, - E_PES_INVALID_MAGIC, - E_PES_TRACK_TOO_LARGE, - E_ISO_TOO_LARGE, - E_NO_METADATA, - E_DISC_URL_NOT_DIRECT, - E_HEVC_PARAM_PARSE, - E_MUX_TRACK_RANGE, - E_FMP4_UNIMPLEMENTED, - E_DEMUX_THREAD_PANICKED, - E_PIPELINE_JOIN_TIMEOUT, - E_PIPELINE_CONSUMER_PANICKED, - E_SWEEP_CONSUMER_GONE, - E_PIPELINE_CONSUMER_GONE, - E_DISC_CAPACITY_OVERFLOW, - E_M2TS_PACKET_MALFORMED, - E_EXTENT_NOT_UNIT_ALIGNED, - E_DISC_CAPACITY_MALFORMED, - E_DIR_IMAGE_SSIF_UNSUPPORTED, - E_DIR_IMAGE_PLACEMENT, - E_DIR_IMAGE_ENCRYPTED, - E_DIR_IMAGE_UNSUPPORTED_TREE, - E_DIR_IMAGE_FILE_CHANGED, - E_DIR_IMAGE_TOO_LARGE, - ]; - let original_len = codes.len(); - codes.sort(); - codes.dedup(); - assert_eq!( - codes.len(), - original_len, - "duplicate error code constants detected — check error.rs" + let mut by_code: std::collections::BTreeMap> = + std::collections::BTreeMap::new(); + for (name, value) in declared_error_codes() { + by_code.entry(value).or_default().push(name); + } + let dupes: Vec<_> = by_code + .iter() + .filter(|(_, names)| names.len() > 1) + .collect(); + assert!( + dupes.is_empty(), + "duplicate error code constants detected — check error.rs: {dupes:?}" ); } diff --git a/src/lib.rs b/src/lib.rs index 0ae1d5a..054b76f 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -129,6 +129,8 @@ pub mod progress; pub mod scsi; pub mod sector; pub mod session; +#[cfg(test)] +pub(crate) mod testlog; pub(crate) mod udf; pub(crate) mod unlock_bridge; diff --git a/src/mux/network.rs b/src/mux/network.rs index c537466..af4a8f3 100644 --- a/src/mux/network.rs +++ b/src/mux/network.rs @@ -627,16 +627,36 @@ mod tests { /// accept_from() must reject a connection whose first bytes are NOT the /// FMKV magic — there is no metadata to drive muxing, so it surfaces /// NoMetadata rather than proceeding with an empty/garbage title. + /// + /// FLAKE FIXED, not the behaviour under test: this used to + /// `shutdown(Shutdown::Both)` the instant the bytes were written. Closing + /// the READ half while the server had not yet read makes the kernel answer + /// the server's in-flight data with an RST, so `accept_from` came back + /// `ConnectionReset` instead of the `InvalidInput` this asserts — rarely + /// when run alone, reproducibly under the loaded concurrent suite, where + /// the server thread is descheduled long enough for the race to open. A + /// logging/protocol assertion that fails at random teaches the next person + /// to re-run until green, which is how a real regression gets waved + /// through. + /// + /// Half-closing (`Shutdown::Write`) delivers the same EOF the test needs + /// while leaving the read half open, and blocking on a read until the + /// server drops its end keeps the socket alive for as long as the server + /// is looking at it. The port was already ephemeral (`:0`), so it was + /// never a port collision. #[test] fn accept_from_rejects_stream_without_fmkv_header() { + use std::io::Read as _; use std::io::Write as _; let listener = TcpListener::bind("127.0.0.1:0").unwrap(); let addr = listener.local_addr().unwrap(); let handle = std::thread::spawn(move || { - // Raw non-FMKV bytes (not starting with 'F') then close. + // Raw non-FMKV bytes (not starting with 'F') then EOF. let mut s = TcpStream::connect(addr).unwrap(); s.write_all(&[0x47u8; 64]).unwrap(); // TS sync bytes, no FMKV magic - s.shutdown(std::net::Shutdown::Both).unwrap(); + s.shutdown(std::net::Shutdown::Write).unwrap(); + // Park until the server closes, so no RST can overtake the data. + let _ = s.read(&mut [0u8; 1]); }); let err = match NetworkStream::accept_from(listener) { Ok(_) => panic!("missing FMKV header must error, not silently accept"), diff --git a/src/testlog.rs b/src/testlog.rs new file mode 100644 index 0000000..8b91920 --- /dev/null +++ b/src/testlog.rs @@ -0,0 +1,194 @@ +//! Test-only capture of `tracing` events, so the crate's logging contract is +//! ENFORCED rather than merely commented. +//! +//! # Why this exists +//! +//! The error contract is "Account / Log / Classify", and the round-2 audit +//! found the third leg unverifiable: three separate sites carry long comments +//! insisting they log **the error's OWN code, not a fixed one** — because +//! flattening a scratched sector (E6000) or an over-long allocation-descriptor +//! chain (E6016) into E6017 sends whoever triages them after authoring holes +//! and hides the population that actually exists. Nothing tested that. Putting +//! a literal back at `bluray.rs`'s or `hddvd.rs`'s warn sites broke no test, so +//! the guarantee was a convention one careless edit away from being false. Two +//! of those very sites were changed in round 1, and a third still carried a +//! hardcoded `code = 6017`. +//! +//! Likewise "absence of a log is itself a bug": a refusal that returns the +//! right error but says nothing produces the wrong population downstream (a +//! residual-underrunning drive is indistinguishable from a scratched disc). +//! That is only checkable by looking at what was emitted. +//! +//! # Why a hand-rolled subscriber and not `tracing-subscriber` +//! +//! Same posture as [`crate::harness`]: this crate has exactly one +//! dev-dependency on purpose. `tracing-subscriber` would pull a tree of them to +//! do what forty lines of [`tracing::Subscriber`] does here. The capture is +//! installed with [`tracing::subscriber::with_default`], which is +//! THREAD-LOCAL — so it composes with `cargo test`'s parallel harness and two +//! capturing tests cannot see each other's events. +//! +//! Field values are stringified through [`std::fmt::Debug`]/`Display` because +//! that is all the visitor API offers without a typed schema; tests compare +//! against the string form of the expected constant, which is exactly the +//! comparison that catches a hardcoded code. + +#![cfg(test)] + +use std::sync::{Arc, Mutex}; + +/// One captured `tracing` event: its target, level, message and fields. +#[derive(Debug, Clone)] +pub(crate) struct CapturedEvent { + pub target: String, + pub level: tracing::Level, + /// Every field, in emission order, stringified. The implicit `message` + /// field (the format string) is included under the name `message`. + pub fields: Vec<(String, String)>, +} + +impl CapturedEvent { + /// The stringified value of `name`, or `None` if the event has no such + /// field. + pub fn field(&self, name: &str) -> Option<&str> { + self.fields + .iter() + .find(|(k, _)| k == name) + .map(|(_, v)| v.as_str()) + } + + /// The event's message (the `tracing` format string), or `""`. + pub fn message(&self) -> &str { + self.field("message").unwrap_or("") + } +} + +#[derive(Default)] +struct Visitor(Vec<(String, String)>); + +impl tracing::field::Visit for Visitor { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + self.0 + .push((field.name().to_string(), format!("{value:?}"))); + } + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + self.0.push((field.name().to_string(), value.to_string())); + } + fn record_u64(&mut self, field: &tracing::field::Field, value: u64) { + self.0.push((field.name().to_string(), value.to_string())); + } + fn record_i64(&mut self, field: &tracing::field::Field, value: i64) { + self.0.push((field.name().to_string(), value.to_string())); + } + fn record_bool(&mut self, field: &tracing::field::Field, value: bool) { + self.0.push((field.name().to_string(), value.to_string())); + } +} + +struct Capture(Arc>>); + +impl tracing::Subscriber for Capture { + fn enabled(&self, _metadata: &tracing::Metadata<'_>) -> bool { + true + } + // Spans are irrelevant here — nothing in this crate asserts on span + // structure, only on events — so they get a constant id and no storage. + fn new_span(&self, _span: &tracing::span::Attributes<'_>) -> tracing::span::Id { + tracing::span::Id::from_u64(1) + } + fn record(&self, _span: &tracing::span::Id, _values: &tracing::span::Record<'_>) {} + fn record_follows_from(&self, _span: &tracing::span::Id, _follows: &tracing::span::Id) {} + fn event(&self, event: &tracing::Event<'_>) { + let mut v = Visitor::default(); + event.record(&mut v); + let meta = event.metadata(); + self.0.lock().expect("capture mutex").push(CapturedEvent { + target: meta.target().to_string(), + level: *meta.level(), + fields: v.0, + }); + } + fn enter(&self, _span: &tracing::span::Id) {} + fn exit(&self, _span: &tracing::span::Id) {} +} + +/// Process-wide lock serialising captures. See [`capture`]. +static CAPTURE_LOCK: Mutex<()> = Mutex::new(()); + +/// Run `f` with every `tracing` event emitted on THIS thread captured. +/// +/// Returns `f`'s value alongside the events, in emission order. +/// +/// # Why captures are serialised across the whole test binary +/// +/// `tracing`'s per-callsite INTEREST CACHE is global, while +/// `with_default` is thread-local, and the two race under `cargo test`'s +/// parallel harness. `tracing_core` rebuilds that cache only on the 0 -> 1 and +/// 1 -> 0 transitions of its scoped-dispatcher count: entering the first +/// capture flips every callsite to "ask the subscriber", leaving the last one +/// flips them back to "never" (there being no global subscriber in tests). +/// With two capturing tests on two threads, the exiting one's rebuild can land +/// AFTER the entering one's, leaving the cache at "never" while a capture is +/// live — so the callsite is short-circuited and the capture observes NOTHING. +/// +/// That was not theoretical: `parse_playlist_unreadable_clip_icb_yields_no_title` +/// passed alone and failed in the full suite, with an empty event list, the +/// first time two capturing tests existed in one module. A logging assertion +/// that fails at random is worse than none — it teaches the next person to +/// re-run until green, which is how a real regression gets waved through. +/// +/// Holding this lock across the whole of `with_default` — including the +/// guard's drop, which is where the exiting rebuild happens — orders the +/// transitions strictly. Captures are few and short, so the serialisation +/// costs nothing measurable. +/// +/// The lock is deliberately taken through the poison, not `expect`ed: a +/// capturing test that panics (i.e. a genuine assertion failure) must not +/// convert every other capturing test into a confusing secondary failure. +pub(crate) fn capture(f: impl FnOnce() -> T) -> (T, Vec) { + let _guard = CAPTURE_LOCK.lock().unwrap_or_else(|e| e.into_inner()); + let sink: Arc>> = Arc::default(); + let out = tracing::subscriber::with_default(Capture(sink.clone()), f); + let events = std::mem::take(&mut *sink.lock().expect("capture mutex")); + (out, events) +} + +#[cfg(test)] +mod tests { + use super::*; + + /// The capture must actually see events and their field VALUES — if it + /// silently recorded nothing, every logging assertion built on it would + /// pass vacuously, which is worse than having no harness at all. + /// + /// Mutation: an `enabled()` returning `false`, or an `event()` that drops + /// the visitor's fields, fails here. + #[test] + fn capture_records_target_level_and_fields() { + let ((), events) = capture(|| { + tracing::warn!(target: "freemkv::testlog", code = 6017u16, clip = ?"A.EVO", "E6017"); + }); + assert_eq!(events.len(), 1, "exactly one event: {events:?}"); + assert_eq!(events[0].target, "freemkv::testlog"); + assert_eq!(events[0].level, tracing::Level::WARN); + assert_eq!(events[0].field("code"), Some("6017")); + assert_eq!(events[0].field("clip"), Some("\"A.EVO\"")); + assert_eq!(events[0].message(), "E6017"); + } + + /// A field that is absent must read as `None`, not as an empty string — an + /// assertion of the shape `field("code") == Some(..)` has to be able to + /// fail when the site stops logging the code at all. + #[test] + fn missing_field_is_none_and_capture_is_scoped() { + let ((), events) = capture(|| tracing::warn!(target: "freemkv::testlog", "no fields")); + assert_eq!(events[0].field("code"), None); + // Emitted outside `capture`, so it must not appear in a later capture. + tracing::warn!(target: "freemkv::testlog", code = 1u16, "outside"); + let ((), later) = capture(|| {}); + assert!( + later.is_empty(), + "capture is scoped to its closure: {later:?}" + ); + } +}