libfreemkv/src/diag.rs

//! Structured scan diagnostics — the `--log-level 3` self-diagnosing dump.
//!
//! Emits one terse line per row (title, cell, stream, decision) under the `tracing` target
//! `freemkv::diag`, routed to `log.txt` at `--log-level 3`. Every line is prefixed `tag=`
//! (`disc`, `title`, `bd.clip`, `extent`, `stream`, `decision`, `decision.demoted`, `aacs`,
//! `dvd.cell`, `dvd.pgc`, `dvd.chap`, `dvd.vobs`, `dvd.vattr`, `dvd.aattr`, `dvd.sattr`,
//! `dvd.astctl`, `dvd.spstctl`, `dvd.substream`, `dvd.aroute`, `mkv.track`, `mkv.opening.*`,
//! `mp2.channels`) so a log scraper can filter. Raw bytes are shown as `0xNN` beside their
//! decode. This module only reads already-parsed scan state.

use crate::disc::{ColorSpace, Disc, DiscTitle, FrameRate, HdrFormat, Resolution, Stream};
use crate::ifo::{CellCategory, DvdTitle};

const DIAG: &str = "freemkv::diag";

// ── small format helpers (pure, unit-testable) ──────────────────────────────

/// Compact name for a [`Resolution`] with the interlace marker preserved.
pub fn res_str(r: Resolution) -> &'static str {
    match r {
        Resolution::R480i => "480i",
        Resolution::R480p => "480p",
        Resolution::R576i => "576i",
        Resolution::R576p => "576p",
        Resolution::R720p => "720p",
        Resolution::R1080i => "1080i",
        Resolution::R1080p => "1080p",
        Resolution::R2160p => "2160p",
        Resolution::R4320p => "4320p",
        Resolution::Unknown => "res?",
    }
}

/// Frames-per-second string for a [`FrameRate`].
pub fn fps_str(f: FrameRate) -> &'static str {
    match f {
        FrameRate::F23_976 => "23.976",
        FrameRate::F24 => "24",
        FrameRate::F25 => "25",
        FrameRate::F29_97 => "29.97",
        FrameRate::F30 => "30",
        FrameRate::F50 => "50",
        FrameRate::F59_94 => "59.94",
        FrameRate::F60 => "60",
        FrameRate::Unknown => "fps?",
    }
}

/// PAL/NTSC field-rate family inferred from the frame rate (DVD has no
/// explicit field, so this is the colour/standard the muxer stamps).
pub fn tv_system_str(f: FrameRate) -> &'static str {
    match f {
        FrameRate::F25 | FrameRate::F50 => "PAL",
        FrameRate::F23_976 | FrameRate::F29_97 | FrameRate::F59_94 => "NTSC",
        _ => "—",
    }
}

/// CICP-ish short name for a [`ColorSpace`].
pub fn color_str(c: ColorSpace) -> &'static str {
    match c {
        ColorSpace::Bt709 => "BT.709",
        ColorSpace::Bt2020 => "BT.2020",
        ColorSpace::Bt470bg => "BT.470BG",
        ColorSpace::Smpte170m => "SMPTE-170M",
        ColorSpace::Unknown => "color?",
    }
}

/// HDR format short name.
pub fn hdr_str(h: HdrFormat) -> &'static str {
    match h {
        HdrFormat::Sdr => "SDR",
        HdrFormat::Hdr10 => "HDR10",
        HdrFormat::Hdr10Plus => "HDR10+",
        HdrFormat::DolbyVision => "DoVi",
        HdrFormat::Hlg => "HLG",
    }
}

// `channel_count`/`sample_rate_hz` used to live here as a HONEST duplicate of
// the AudioChannels/SampleRate mappings; deleted now canonical accessors are honest.

// ── DVD cell-category dump (from the IFO scan, pre-lowering) ─────────────────

/// One formatted cell row for the DVD per-PGC cell table. Returned as a
/// string so it can be unit-tested without a logger.
///
/// Columns: `idx`, raw category (`cat=0xNN`) + decoded fields, first/last
/// sector, duration, and the keep/drop verdict from the bug-4 leading-cell
/// filter.
pub fn dvd_cell_row(idx: usize, cell: &crate::ifo::DvdCell, dropped: bool) -> String {
    let c = CellCategory::decode(cell.category);
    // Per-cell keep/skip REASON (self-sufficient bug log): a dropped cell is a
    // leading secondary angle/interleave piece; a kept cell is the first feature
    // cell or genuine content. Makes the leading-cell-filter decision auditable.
    let verdict = if dropped {
        "DROP(leading-secondary-block-piece)"
    } else if c.is_secondary_block_piece() {
        // Kept despite being a secondary piece — only happens past the leading
        // run (the filter stops at the first plain feature cell).
        "keep(feature-body)"
    } else {
        "keep(plain-feature)"
    };
    format!(
        "tag=dvd.cell idx={idx} cat=0x{:02X} block_mode={} block_type={} \
seamless={} ilv={} stc={} angle={} plain={} first={} last={} dur={:.1}s {}",
        cell.category,
        c.block_mode,
        c.block_type,
        c.seamless_play as u8,
        c.interleaved as u8,
        c.stc_discontinuity as u8,
        c.seamless_angle as u8,
        c.is_plain_feature() as u8,
        cell.first_sector,
        cell.last_sector,
        cell.duration_secs,
        verdict,
    )
}

/// Emit the per-PGC cell table for one DVD title during the IFO scan.
///
/// `vts`/`title` identify the row group; `title` is the `DvdTitle` whose
/// cells (and bug-4 leading-cell verdict) are dumped. Called from
/// `scan_dvd_titles` while the `DvdTitle` is still in scope (the per-cell
/// category byte is lowered away before the `Disc` exists).
pub fn dump_dvd_cells(vts: u8, title_num: u16, title: &DvdTitle) {
    if !tracing::enabled!(target: DIAG, tracing::Level::DEBUG) {
        return;
    }
    let feature_start = title.feature_start_cell();
    tracing::debug!(
        target: DIAG,
        "tag=dvd.pgc vts={vts} title={title_num} cells={} chapters={} \
    dur={:.1}s feature_start_cell={feature_start}",
        title.cells.len(),
        title.chapters,
        title.duration_secs,
    );
    for (i, cell) in title.cells.iter().enumerate() {
        tracing::debug!(target: DIAG, "{}", dvd_cell_row(i, cell, i < feature_start));
    }
    // Chapter/PTT map (program → cumulative start time).
    for (i, &t) in title.chapter_times.iter().enumerate() {
        tracing::debug!(
            target: DIAG,
            "tag=dvd.chap vts={vts} title={title_num} ch={} time={:.1}s",
            i + 1,
            t,
        );
    }
}

/// Emit the IFO `video_attr` / `audio_attr` decode for one DVD title set,
/// showing the raw bytes next to their decoded meaning. Called from the IFO
/// scan with the still-parsed `ifo::DvdTitleSet` view.
pub fn dump_dvd_attrs(ts: &crate::ifo::DvdTitleSet) {
    if !tracing::enabled!(target: DIAG, tracing::Level::DEBUG) {
        return;
    }
    tracing::debug!(
        target: DIAG,
        "tag=dvd.vobs vts={} vob_start_sector={}",
        ts.vts_number,
        ts.vob_start_sector,
    );
    let v = &ts.video;
    tracing::debug!(
        target: DIAG,
        "tag=dvd.vattr vts={} codec={:?} res={} aspect={:?} std={:?}",
        ts.vts_number,
        v.codec,
        res_str(v.resolution),
        v.aspect,
        v.standard,
    );
    for (i, a) in ts.audio_streams.iter().enumerate() {
        tracing::debug!(
            target: DIAG,
            "tag=dvd.aattr vts={} idx={i} codec={:?} ch={} sr={}Hz lang={:?} mpeg_ext={}",
            ts.vts_number,
            a.codec,
            a.channels,
            a.sample_rate,
            a.language,
            a.mpeg_ext,
        );
    }
    for (i, s) in ts.subtitle_streams.iter().enumerate() {
        tracing::debug!(
            target: DIAG,
            "tag=dvd.sattr vts={} idx={i} lang={:?}",
            ts.vts_number,
            s.language,
        );
    }
}

/// A title whose PGC control table (`ast`/`spst`) marks none of its `declared` streams present,
/// so a disc that loses every audio or subtitle track to sloppy authoring is traceable.
pub fn dvd_ctl_none_present(kind: &str, vts: u8, title: u16, declared: usize, outcome: &str) {
    tracing::debug!(
        target: DIAG,
        "tag=dvd.{kind}ctl vts={vts} title={title} declared={declared} present=0 -> {outcome}",
    );
}

/// A logical stream dropped because an earlier one already routes to the same physical id
/// (`id`: the VobSub sub-id, or the audio routing PID).
pub fn dvd_ctl_duplicate(kind: &str, vts: u8, title: u16, id: u16, kept: &str, dropped: &str) {
    tracing::debug!(
        target: DIAG,
        "tag=dvd.{kind}ctl vts={vts} title={title} id=0x{id:02X} kept={kept:?} dropped={dropped:?} (duplicate physical id)",
    );
}

/// Where one title routes a declared audio stream: its raw AST_CTL entry and the PID it
/// muxes from, or `absent` when the PGC does not play it.
pub fn dvd_audio_route(
    vts: u8,
    title: u16,
    idx: usize,
    a: &crate::ifo::DvdAudioAttr,
    ctl: u16,
    pid: Option<u16>,
) {
    let route = pid.map_or("absent".to_string(), |p| format!("pid=0x{p:04X}"));
    tracing::debug!(
        target: DIAG,
        "tag=dvd.aroute vts={vts} title={title} idx={idx} codec={:?} lang={:?} ast=0x{ctl:04X} {route}",
        a.codec,
        a.language,
    );
}

/// Emit the ACTUAL per-physical-sub-stream AC-3 channel counts read off the VOB during the
/// mux-time sub-stream probe. This is the ground truth the IFO nibble is compared against: each
/// row is `sub_id=0x8x channels=N` for a physical `private_stream_1` AC-3 sub-stream whose
/// first frame was decoded. An empty probe (scrambled / unreadable / short VOB) logs a single
/// `probed=0` line so the absence is explicit in a bug log.
pub fn dump_dvd_substream_probe(title_id: u16, probed: &std::collections::BTreeMap<u8, u8>) {
    if !tracing::enabled!(target: DIAG, tracing::Level::DEBUG) {
        return;
    }
    if probed.is_empty() {
        tracing::debug!(
            target: DIAG,
            "tag=dvd.substream title={title_id} probed=0 (no AC-3 sync in feature head — scrambled/unreadable/none)",
        );
        return;
    }
    for (sub, ch) in probed {
        tracing::debug!(
            target: DIAG,
            "tag=dvd.substream title={title_id} sub_id=0x{sub:02X} channels={ch} (physical acmod read from VOB)",
        );
    }
}

// ── MKV TrackEntry dump (the ACTUAL container elements written) ──────────────

/// `true` when the `--log-level 3` diagnostic target is enabled. Hot-path
/// callers (the opening-frame capture) check this once and skip all work when
/// off, so a normal run pays nothing.
pub fn diag_enabled() -> bool {
    tracing::enabled!(target: DIAG, tracing::Level::DEBUG)
}

// Cap on codecPrivate bytes rendered to hex in `tag=mkv.track`. The seq
// header / avcC / hvcC prefix that matters for diagnosis is at the front;
// a multi-KB blob past this is summarised as `..(+NB)`.
const CODEC_PRIVATE_HEX_CAP: usize = 64;

/// Render a track's codecPrivate as an uppercase-hex string for the diagnostic
/// line, capped at [`CODEC_PRIVATE_HEX_CAP`] bytes (`..(+NB)` suffix beyond).
/// `None` / empty → `"none"`. Pure (no logging) so it is directly unit-testable.
fn codec_private_hex(cp: Option<&[u8]>) -> String {
    match cp {
        Some(b) if !b.is_empty() => {
            use std::fmt::Write;
            let shown = b.len().min(CODEC_PRIVATE_HEX_CAP);
            let mut s = String::with_capacity(shown * 2 + 8);
            for byte in &b[..shown] {
                let _ = write!(s, "{byte:02X}");
            }
            if b.len() > CODEC_PRIVATE_HEX_CAP {
                let _ = write!(s, "..(+{}B)", b.len() - CODEC_PRIVATE_HEX_CAP);
            }
            s
        }
        _ => "none".to_string(),
    }
}

// Frame one captured opening frame for the `.opening.bin` side file:
// `[track:u8][keyframe:u8][pts_ns:i64 LE][len:u32 LE][raw bytes]`. Pure
// (no I/O); `record` appends the returned bytes to the side file.
fn frame_record(track_idx: usize, pts_ns: i64, keyframe: bool, data: &[u8]) -> Vec<u8> {
    let mut rec = Vec::with_capacity(14 + data.len());
    rec.push(u8::try_from(track_idx).unwrap_or(u8::MAX));
    rec.push(keyframe as u8);
    rec.extend_from_slice(&pts_ns.to_le_bytes());
    rec.extend_from_slice(&(data.len() as u32).to_le_bytes());
    rec.extend_from_slice(data);
    rec
}

// Emits the MKV `TrackEntry` elements the muxer is about to write for one track
// (FlagInterlaced, FieldOrder, DefaultDuration, Display dims, codecPrivate hex).
pub(crate) fn dump_mkv_track(track_number: u64, track: &crate::mux::mkv::MkvTrack) {
    if !diag_enabled() {
        return;
    }
    // codecPrivate as hex (capped so a multi-KB hvcC doesn't flood the log; the
    // sequence header / avcC prefix that matters for diagnosis is at the front).
    let cp = codec_private_hex(track.codec_private.as_deref());
    let field_order = match track.field_order {
        crate::mux::ebml::FIELD_ORDER_TFF => "TFF",
        crate::mux::ebml::FIELD_ORDER_BFF => "BFF",
        _ => "—",
    };
    // FlagInterlaced is only written for video tracks (1=interlaced/2=progressive);
    // report what the muxer will emit, or "—" for non-video tracks where the
    // element is omitted entirely.
    let interlaced = if track.track_type == crate::mux::ebml::TRACK_TYPE_VIDEO {
        if track.interlaced {
            "1(interlaced)"
        } else {
            "2(progressive)"
        }
    } else {
        "—"
    };
    tracing::debug!(
        target: DIAG,
        "tag=mkv.track num={track_number} type={} codec={} flag_interlaced={interlaced} \
    field_order={field_order} default_duration_ns={} field_duration_ns={} \
    pixel={}x{} display={}x{} cp_len={} cp_hex={cp}",
        track.track_type,
        track.codec_id,
        track.default_duration_ns,
        track.field_duration_ns,
        track.pixel_width,
        track.pixel_height,
        track.display_width,
        track.display_height,
        track.codec_private.as_ref().map_or(0, |b| b.len()),
    );
}

// ── Opening-frame capture (first ~N coded frames per track → side file) ──────

// Frames captured PER TRACK before capture goes dormant. ~100 covers a DVD's
// first few seconds per track while bounding the side file to a few MB.
const OPENING_FRAMES_PER_TRACK: usize = 100;

/// Captures the first [`OPENING_FRAMES_PER_TRACK`] coded frames of EACH track to
/// a side file (`<output>.opening.bin`) and logs a per-frame summary line, so an
/// opening-GOP / menu / mid-GOP-open issue is diagnosable from a future log +
/// side file WITHOUT the disc. Gated to `--log-level 3`: constructed only when
/// the diag target is on, so a normal run never opens the file or records a byte.
///
/// Side-file record framing (so a reader can split it back into frames):
/// `[track:u8][keyframe:u8][pts_ns:i64 LE][len:u32 LE][raw frame bytes]`.
pub struct OpeningCapture {
    file: std::fs::File,
    /// Frames captured so far, per track index. Capture for a track stops once
    /// its counter reaches [`OPENING_FRAMES_PER_TRACK`].
    counts: Vec<usize>,
}

impl OpeningCapture {
    /// Open `<output>.opening.bin` next to the MKV output. Returns `None` (no
    /// capture) when the diag target is off OR the side file can't be created —
    /// a diagnostic must never fail the rip. `track_count` sizes the per-track
    /// counters.
    pub fn new(output_path: &std::path::Path, track_count: usize) -> Option<Self> {
        if !diag_enabled() {
            return None;
        }
        let mut name = output_path.as_os_str().to_os_string();
        name.push(".opening.bin");
        match std::fs::File::create(&name) {
            Ok(file) => {
                tracing::debug!(
                    target: DIAG,
                    "tag=mkv.opening.open path={:?} per_track_cap={OPENING_FRAMES_PER_TRACK}",
                    std::path::Path::new(&name),
                );
                Some(Self {
                    file,
                    counts: vec![0; track_count],
                })
            }
            Err(e) => {
                tracing::debug!(
                    target: DIAG,
                    "tag=mkv.opening.open path={:?} failed={e} (capture disabled, rip unaffected)",
                    std::path::Path::new(&name),
                );
                None
            }
        }
    }

    /// Record one coded frame for `track_idx` if that track is still under its
    /// per-track cap. Writes the framed raw bytes to the side file and logs a
    /// one-line summary. A write error disables further capture for all tracks
    /// (counters pinned to the cap) but never propagates — the rip is unaffected.
    pub fn record(&mut self, track_idx: usize, pts_ns: i64, keyframe: bool, data: &[u8]) {
        let Some(count) = self.counts.get_mut(track_idx) else {
            return;
        };
        // The record's track field is a u8; skip higher indices rather than alias them.
        if *count >= OPENING_FRAMES_PER_TRACK || track_idx > usize::from(u8::MAX) {
            return;
        }
        use std::io::Write;
        let rec = frame_record(track_idx, pts_ns, keyframe, data);
        if let Err(e) = self.file.write_all(&rec) {
            // A torn record desyncs a len-framed reader: stop capture on every track.
            self.counts
                .iter_mut()
                .for_each(|c| *c = OPENING_FRAMES_PER_TRACK);
            tracing::debug!(
                target: DIAG,
                "tag=mkv.opening.frame track={track_idx} write_failed={e} (capture stopped)",
            );
            return;
        }
        *count += 1;
        tracing::debug!(
            target: DIAG,
            "tag=mkv.opening.frame track={track_idx} n={count} type={} size={} pts_ns={pts_ns}",
            if keyframe { "key" } else { "delta" },
            data.len(),
        );
    }
}

// ── Disc-level dump (post-lowering: titles, streams, decisions, AACS) ────────

/// Emit the full scan diagnostic block for a built [`Disc`]. Terse, one line
/// per row, under target `freemkv::diag` at DEBUG. No-op unless that target
/// is enabled, so it costs nothing when `--log-level 3` is off.
pub fn dump_disc(disc: &Disc) {
    if !tracing::enabled!(target: DIAG, tracing::Level::DEBUG) {
        return;
    }

    tracing::debug!(
        target: DIAG,
        "tag=disc vol={:?} format={:?} content={:?} cap_sectors={} layers={} titles={} encrypted={}",
        disc.volume_id,
        disc.format,
        disc.content_format,
        disc.capacity_sectors,
        disc.layers,
        disc.titles.len(),
        disc.encrypted,
    );

    dump_aacs(disc);

    for (ti, title) in disc.titles.iter().enumerate() {
        dump_title(ti, title);
    }

    // freemkv's top-level DECISION: which title is the main feature.
    if let Some(main) = disc.titles.first() {
        tracing::debug!(
            target: DIAG,
            "tag=decision pick=main_feature title_idx=0 playlist={:?} dur={:.1}s \
        size={}B clips={} video={} reason={}",
            main.playlist,
            main.duration_secs,
            main.size_bytes,
            main.clips.len(),
            main.video_streams().count(),
            main_feature_reason(),
        );
    }

    // Titles disqualified from main-feature candidacy for carrying no video — the
    // streamless obfuscation decoys the `has-video` gate demotes. Logged so a field
    // bug report shows WHY a playlist wasn't picked (the gap behind E6008 on `00245`).
    for (ti, t) in disc.titles.iter().enumerate() {
        // Match the ACTUAL has-video gate used by `main_feature_order`
        // (`has_probable_video`, deliberately more permissive than `has_video`),
        // so the diagnostic doesn't report a title as demoted that was in fact kept.
        if !t.has_probable_video() {
            tracing::debug!(
                target: DIAG,
                "tag=decision.demoted title_idx={} playlist={:?} dur={:.1}s size={}B reason=no-video",
                ti,
                t.playlist,
                t.duration_secs,
                t.size_bytes,
            );
        }
    }
}

// The `reason=` token on the main-feature decision row. DERIVED from the Disc key lists.
fn main_feature_reason() -> String {
    let keys: Vec<&str> = Disc::MAIN_FEATURE_ORDER_KEYS
        .iter()
        .chain(Disc::CANONICAL_TITLE_ORDER_KEYS.iter())
        .copied()
        .collect();
    format!("main_feature_order({})", keys.join(", "))
}

fn dump_aacs(disc: &Disc) {
    let Some(a) = disc.aacs.as_ref() else {
        if disc.css.is_some() {
            tracing::debug!(target: DIAG, "tag=aacs none crypto=CSS(DVD)");
        } else if disc.encrypted {
            tracing::debug!(target: DIAG, "tag=aacs none crypto=encrypted-no-keys");
        } else {
            tracing::debug!(target: DIAG, "tag=aacs none crypto=clear");
        }
        return;
    };
    // Key material is never on the disc (KU §2.2); report the raw AACS inputs' sizes.
    tracing::debug!(
        target: DIAG,
        "tag=aacs version={} bus_enc={} mkb_version={} disc_hash={} uk_ro_bytes={} mkb_bytes={}",
        a.version,
        a.bus_encryption,
        a.mkb_version
            .map(|v| v.to_string())
            .unwrap_or_else(|| "unknown".to_string()),
        a.disc_hash,
        a.uk_ro.len(),
        a.mkb.len(),
    );
}

fn dump_title(ti: usize, title: &DiscTitle) {
    let (mut nv, mut na, mut ns) = (0u32, 0u32, 0u32);
    for s in &title.streams {
        match s {
            Stream::Video(_) => nv += 1,
            Stream::Audio(_) => na += 1,
            Stream::Subtitle(_) => ns += 1,
        }
    }
    tracing::debug!(
        target: DIAG,
        "tag=title idx={ti} playlist={:?} id={} dur={:.1}s size={}B clips={} \
    extents={} chapters={} v={nv} a={na} s={ns} fmt={:?}",
        title.playlist,
        title.playlist_id,
        title.duration_secs,
        title.size_bytes,
        title.clips.len(),
        title.extents.len(),
        title.chapters.len(),
        title.content_format,
    );

    // Per-clip rows (BD: PlayItem/CLPI; DVD has none).
    for (ci, c) in title.clips.iter().enumerate() {
        tracing::debug!(
            target: DIAG,
            "tag=bd.clip title={ti} idx={ci} id={:?} in={} out={} dur={:.1}s src_packets={}",
            c.clip_id,
            c.in_time,
            c.out_time,
            c.duration_secs,
            c.source_packets,
        );
    }

    // Per-extent rows (the sectors freemkv will actually rip — the bug-4
    // decision is visible here: leading non-feature cells are already gone).
    for (ei, e) in title.extents.iter().enumerate() {
        tracing::debug!(
            target: DIAG,
            "tag=extent title={ti} idx={ei} start_lba={} sectors={}",
            e.start_lba,
            e.sector_count,
        );
    }

    // freemkv's per-stream DECISIONS (what the muxer will write).
    for (si, s) in title.streams.iter().enumerate() {
        match s {
            Stream::Video(v) => tracing::debug!(
                target: DIAG,
                "tag=stream title={ti} idx={si} kind=video pid=0x{:04X} codec={:?} \
            res={} interlaced={} fps={} std={} color={} hdr={} aspect={:?} secondary={}",
                v.pid,
                v.codec,
                res_str(v.resolution),
                v.resolution.is_interlaced(),
                fps_str(v.frame_rate),
                tv_system_str(v.frame_rate),
                color_str(v.color_space),
                hdr_str(v.hdr),
                v.display_aspect,
                v.secondary,
            ),
            Stream::Audio(a) => tracing::debug!(
                target: DIAG,
                "tag=stream title={ti} idx={si} kind=audio pid=0x{:04X} codec={:?} \
            channels={}({}) sr={}Hz lang={:?} secondary={}",
                a.pid,
                a.codec,
                a.channels,
                a.channels.count(),
                a.sample_rate.hz(),
                a.language,
                a.secondary,
            ),
            Stream::Subtitle(sub) => tracing::debug!(
                target: DIAG,
                "tag=stream title={ti} idx={si} kind=subtitle pid=0x{:04X} codec={:?} \
            lang={:?} forced={}",
                sub.pid,
                sub.codec,
                sub.language,
                sub.forced,
            ),
        }
    }
}

#[cfg(test)]
#[path = "diag_tests.rs"]
mod tests;