add debug logging for MKB processing

src/aacs/keys.rs

@@ -247,6 +247,7 @@ fn validate_processing_key(
 /// Find Verify Media Key Record (type 0x10) in MKB.
 fn mkb_find_mk_dv(mkb: &[u8]) -> Option<[u8; 16]> {
     let mut pos = 0;
+    let mut type10_seen: Vec<(usize, usize)> = Vec::new();
     while pos + 4 <= mkb.len() {
         let rec_type = mkb[pos];
         let rec_len = u32::from_be_bytes([0, mkb[pos + 1], mkb[pos + 2], mkb[pos + 3]]) as usize;
@@ -254,14 +255,32 @@ fn mkb_find_mk_dv(mkb: &[u8]) -> Option<[u8; 16]> {
             break;
         }
 
+        if rec_type == 0x10 {
+            type10_seen.push((pos, rec_len));
+        }
+
         if rec_type == 0x10 && rec_len >= 20 {
             // mk_dv is at offset 4 (after record header)
             let mut dv = [0u8; 16];
             dv.copy_from_slice(&mkb[pos + 4..pos + 20]);
+            tracing::warn!(
+                target: "freemkv::disc",
+                phase = "mkb_mk_dv_found",
+                pos,
+                rec_len,
+                "mk_dv extracted from MKB"
+            );
             return Some(dv);
         }
         pos += rec_len;
     }
+    tracing::warn!(
+        target: "freemkv::disc",
+        phase = "mkb_mk_dv_not_found",
+        type10_seen = ?type10_seen,
+        scanned_bytes = pos,
+        "no 0x10 record with rec_len>=20 found"
+    );
     None
 }
 
@@ -628,32 +647,70 @@ pub fn resolve_keys(
         }
     };
 
+    tracing::warn!(
+        target: "freemkv::disc",
+        phase = "resolve_keys_start",
+        aacs2,
+        bus_encryption,
+        disc_hash = %hash_hex,
+        mkb_present = mkb_data.is_some(),
+        "resolve_keys: starting"
+    );
+
     // Path 1: Look up VUK by disc hash in KEYDB
     if let Some(entry) = keydb.find_disc(&hash_hex) {
+        tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path1_hit_entry", "disc hash found in keydb");
         if let Some(vuk) = entry.vuk {
             return Some(build(vuk, 1));
         }
+        tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path1_no_vuk", "disc hash entry has no VUK");
+    } else {
+        tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path1_miss", "disc hash NOT in keydb");
     }
 
     // Path 2: Find entry with matching VID → derive VUK from MK + VID
+    let mut path2_mk_did_count = 0usize;
     for entry in keydb.disc_entries.values() {
         if let (Some(mk), Some(did)) = (entry.media_key, entry.disc_id) {
+            path2_mk_did_count += 1;
             if did == *volume_id {
+                tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path2_hit", "MK+VID entry matched volume_id");
                 return Some(build(derive_vuk(&mk, volume_id), 2));
             }
         }
     }
+    tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path2_miss", mk_did_entries = path2_mk_did_count, "no MK+VID entry matched volume_id");
 
     // Path 3: MKB + processing keys → media key → VUK
     if let Some(mkb) = mkb_data {
+        let mk_dv = mkb_find_mk_dv(mkb);
+        let subdiff = mkb_find_subdiff_records(mkb);
+        let cvalues = mkb_find_cvalues(mkb);
+        tracing::warn!(
+            target: "freemkv::disc",
+            phase = "resolve_keys_mkb_records",
+            mk_dv_found = mk_dv.is_some(),
+            subdiff_found = subdiff.is_some(),
+            subdiff_len = subdiff.as_ref().map(|s| s.len()).unwrap_or(0),
+            cvalues_found = cvalues.is_some(),
+            cvalues_len = cvalues.as_ref().map(|c| c.len()).unwrap_or(0),
+            "MKB record scan results"
+        );
+
         if let Some(mk) = derive_media_key_from_pk(mkb, &keydb.processing_keys) {
+            tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path3_hit", "media key derived from processing key");
             return Some(build(derive_vuk(&mk, volume_id), 3));
         }
+        tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path3_miss", pk_count = keydb.processing_keys.len(), "PK derivation failed");
 
         // Path 4: MKB + device keys → processing key → media key → VUK
         if let Some(mk) = derive_media_key_from_dk(mkb, &keydb.device_keys) {
+            tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path4_hit", "media key derived from device key");
             return Some(build(derive_vuk(&mk, volume_id), 4));
         }
+        tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_path4_miss", dk_count = keydb.device_keys.len(), "DK derivation failed");
+    } else {
+        tracing::warn!(target: "freemkv::disc", phase = "resolve_keys_no_mkb", "no MKB data available; paths 3/4 skipped");
     }
 
     None

src/disc/encrypt.rs

@@ -22,12 +22,27 @@ impl Disc {
     ) -> Option<HandshakeResult> {
         use crate::aacs::{self, KeyDb};
 
-        let keydb_path = opts.resolve_keydb()?;
+        tracing::warn!(
+            target: "freemkv::disc",
+            phase = "handshake_entry",
+            "do_handshake entered"
+        );
+        let keydb_path = match opts.resolve_keydb() {
+            Some(p) => p,
+            None => {
+                tracing::warn!(
+                    target: "freemkv::disc",
+                    phase = "handshake_no_keydb",
+                    "no KEYDB found in search paths; handshake skipped"
+                );
+                return None;
+            }
+        };
         let keydb = match KeyDb::load(&keydb_path) {
             Ok(db) => db,
             Err(e) => {
                 tracing::warn!(
-                    target: "freemkv::aacs",
+                    target: "freemkv::disc",
                     phase = "handshake_keydb_load_failed",
                     io_error_kind = ?e.kind(),
                     keydb = %keydb_path.display(),
@@ -38,11 +53,12 @@ impl Disc {
         };
 
         let host_cert_count = keydb.host_certs.len();
-        tracing::debug!(
-            target: "freemkv::aacs",
+        tracing::warn!(
+            target: "freemkv::disc",
             phase = "handshake_start",
             host_cert_count,
             keydb = %keydb_path.display(),
+            "handshake starting"
         );
 
         const MAX_CERT_ATTEMPTS: usize = 16;
@@ -54,7 +70,7 @@ impl Disc {
                         Ok(vid) => vid,
                         Err(e) => {
                             tracing::warn!(
-                                target: "freemkv::aacs",
+                                target: "freemkv::disc",
                                 phase = "handshake_vid_read_failed",
                                 cert_index = idx,
                                 error_code = e.code(),
@@ -67,7 +83,7 @@ impl Disc {
                         .ok()
                         .map(|(rdk, _)| rdk);
                     tracing::debug!(
-                        target: "freemkv::aacs",
+                        target: "freemkv::disc",
                         phase = "handshake_ok",
                         cert_index = idx,
                         has_read_data_key = read_data_key.is_some(),
@@ -84,7 +100,7 @@ impl Disc {
             }
         }
         tracing::warn!(
-            target: "freemkv::aacs",
+            target: "freemkv::disc",
             phase = "handshake_all_certs_failed",
             host_cert_count,
             tried = host_cert_count.min(MAX_CERT_ATTEMPTS),
@@ -118,6 +134,19 @@ impl Disc {
             .or_else(|_| udf_fs.read_file(reader, "/AACS/DUPLICATE/Unit_Key_RO.inf"))
             .map_err(|_| Error::AacsNoKeys)?;
 
+        // Log the disc hash so we can confirm whether it's present in KEYDB
+        // when key resolution fails. The disc hash is SHA-1 of the full
+        // Unit_Key_RO.inf file bytes — same value KEYDB.cfg keys VUK entries by.
+        let dh = crate::aacs::disc_hash(&uk_ro_data);
+        let dh_hex = crate::aacs::disc_hash_hex(&dh);
+        tracing::warn!(
+            target: "freemkv::disc",
+            phase = "scan_aacs_disc_hash",
+            disc_hash = %dh_hex,
+            uk_ro_len = uk_ro_data.len(),
+            "disc hash computed (compare with keydb.cfg entries)"
+        );
+
         let cc_data = udf_fs
             .read_file(reader, "/AACS/Content000.cer")
             .or_else(|_| udf_fs.read_file(reader, "/AACS/Content001.cer"))
@@ -129,6 +158,28 @@ impl Disc {
             .ok();
         let mkb_ver = mkb_data.as_deref().and_then(aacs::mkb_version);
 
+        let mkb_first_64_hex = mkb_data
+            .as_deref()
+            .map(|m| {
+                m.iter()
+                    .take(64)
+                    .map(|b| format!("{b:02x}"))
+                    .collect::<String>()
+            })
+            .unwrap_or_default();
+        tracing::warn!(
+            target: "freemkv::disc",
+            phase = "scan_aacs_mkb_info",
+            mkb_present = mkb_data.is_some(),
+            mkb_len = mkb_data.as_deref().map(|m| m.len()).unwrap_or(0),
+            mkb_version = ?mkb_ver,
+            mkb_first_64 = %mkb_first_64_hex,
+            keydb_disc_count = keydb.disc_entries.len(),
+            keydb_dk_count = keydb.device_keys.len(),
+            keydb_pk_count = keydb.processing_keys.len(),
+            "AACS resolution inputs"
+        );
+
         // Use handshake volume ID if available, otherwise zeros
         // (KEYDB VUK lookup by disc hash works without volume ID)
         let volume_id = handshake.map(|h| h.volume_id).unwrap_or([0u8; 16]);

src/mux/resolve.rs

@@ -204,7 +204,10 @@ pub fn input(url: &str, opts: &InputOptions) -> io::Result<Box<dyn crate::pes::S
             let title = disc.titles[idx].clone();
             let keys = disc.decrypt_keys();
             let format = disc.content_format;
-            let mut stream = DiscStream::new(Box::new(reader), title, keys, 64, format);
+            // ISO file: use large batch size (16 MB) — sequential read from fast storage, no bad sectors.
+            // Physical drives need small batches for adaptive error handling and retry logic.
+            const ISO_MUX_BATCH_SECTORS: u16 = 8192;
+            let mut stream = DiscStream::new(Box::new(reader), title, keys, ISO_MUX_BATCH_SECTORS, format);
             if opts.raw {
                 stream.set_raw();
             }