diff --git a/Cargo.lock b/Cargo.lock index c4af244..0aaaac0 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -988,6 +988,7 @@ checksum = "6ce2be8dc25455e1f91df71bfa12ad37d7af1092ae736f3a6cd0e37bc7810596" name = "strawcore-core" version = "0.1.0" dependencies = [ + "log", "once_cell", "parking_lot", "regex", diff --git a/Cargo.toml b/Cargo.toml index d8c0083..632bf4b 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -19,6 +19,7 @@ reqwest = { version = "0.12", default-features = false, features = ["rustls-tls- serde = { version = "1", features = ["derive"] } serde_json = "1" thiserror = "1" +log = "0.4" parking_lot = "0.12" url = "2" once_cell = "1" diff --git a/src/downloader/default_impl.rs b/src/downloader/default_impl.rs index 9dcefea..dd50291 100644 --- a/src/downloader/default_impl.rs +++ b/src/downloader/default_impl.rs @@ -9,7 +9,7 @@ // as Ok(Response) use std::io::Read; -use std::time::Duration; +use std::time::{Duration, Instant}; use reqwest::blocking::Client; use reqwest::redirect::Policy; @@ -52,6 +52,11 @@ impl ReqwestDownloader { impl Downloader for ReqwestDownloader { fn execute(&self, request: Request) -> Result { + let started = Instant::now(); + let method_str = match request.method() { + Method::Get => "GET", + Method::Post => "POST", + }; let method = match request.method() { Method::Get => reqwest::Method::GET, Method::Post => reqwest::Method::POST, @@ -79,6 +84,12 @@ impl Downloader for ReqwestDownloader { let status = resp.status(); let url_after_redirects = resp.url().to_string(); + // Query/fragment carry n/sig/pot/cpn/id — strip for every log line. + let endpoint = url_after_redirects + .split(['?', '#']) + .next() + .unwrap_or(&url_after_redirects) + .to_string(); if status.as_u16() == 429 { // Privacy: this URL ends up in error strings (and from there in @@ -91,6 +102,8 @@ impl Downloader for ReqwestDownloader { stripped.set_query(None); stripped.set_fragment(None); stripped.set_path("/"); + // Densest bot-flag signal — host only (path/query already stripped). + log::warn!("HTTP 429 reCAPTCHA / bot-wall from {stripped} — YouTube is rate-limiting"); return Err(NetworkError::Recaptcha { url: stripped.to_string() }); } @@ -107,6 +120,9 @@ impl Downloader for ReqwestDownloader { // Fail fast when a known Content-Length already exceeds the cap. if let Some(len) = resp.content_length() { if len > MAX_BODY_BYTES { + log::warn!( + "{endpoint}: Content-Length {len}B exceeds cap {MAX_BODY_BYTES}B; aborting" + ); return Err(NetworkError::Transport(format!( "response body {len} bytes exceeds cap {MAX_BODY_BYTES}" ))); @@ -123,6 +139,7 @@ impl Downloader for ReqwestDownloader { .read_to_end(&mut buf) .map_err(|e| NetworkError::Transport(format!("body read: {e}")))?; if buf.len() as u64 > MAX_BODY_BYTES { + log::warn!("{endpoint}: streamed body exceeded cap {MAX_BODY_BYTES}B; aborting"); return Err(NetworkError::Transport(format!( "response body exceeded cap {MAX_BODY_BYTES}" ))); @@ -131,11 +148,19 @@ impl Downloader for ReqwestDownloader { // common case): String::from_utf8 reinterprets the Vec in place, // whereas from_utf8_lossy always allocates + copies. Fall back to // lossy only on genuinely invalid bytes, preserving U+FFFD behavior. + let body_len = buf.len(); let body = match String::from_utf8(buf) { Ok(s) => s, Err(e) => String::from_utf8_lossy(e.as_bytes()).into_owned(), }; + // One DEBUG per request (dogfood ring). Query stripped; body length + + // status only — never the body. Gated behind the Debug-level bump. + log::debug!( + "{method_str} {endpoint} → {code} {body_len}B {}ms", + started.elapsed().as_millis() + ); + Ok(Response::new(code, message, headers, body, url_after_redirects)) } } diff --git a/src/exceptions.rs b/src/exceptions.rs index cd19946..d3796bb 100644 --- a/src/exceptions.rs +++ b/src/exceptions.rs @@ -59,6 +59,13 @@ pub enum ContentUnavailable { SoundCloudGoPlus, #[error("account terminated")] AccountTerminated, + /// The 2026 poToken/BotGuard "sign in to confirm you're not a bot" wall. + /// Its Display is kept byte-identical to the old + /// `Other("sign in to confirm you're not a bot")` so string-matching + /// callers keep working; the dedicated variant makes the wall greppable in + /// logs and distinctly classifiable in app state. + #[error("sign in to confirm you're not a bot")] + BotDetected, #[error("unavailable: {0}")] Other(String), } diff --git a/src/youtube/channel.rs b/src/youtube/channel.rs index 741f4b3..d1a33f3 100644 --- a/src/youtube/channel.rs +++ b/src/youtube/channel.rs @@ -46,7 +46,14 @@ pub fn channel_info(identifier: ChannelIdentifier) -> Result resolve_handle_to_channel_id(&format!("c/{c}"))?, ChannelIdentifier::LegacyUser(u) => resolve_handle_to_channel_id(&format!("user/{u}"))?, }; - fetch_channel_browse(&resolved) + let info = fetch_channel_browse(&resolved)?; + log::info!( + "[channel {}] channel_info ok: videos={} continuation={}", + info.channel_id, + info.recent_videos.len(), + info.videos_continuation.is_some() + ); + Ok(info) } pub fn resolve_handle_to_channel_id(url_fragment: &str) -> Result { @@ -113,10 +120,21 @@ pub fn fetch_channel_browse(channel_id: &str) -> Result { + info.recent_videos = parse_videos_tab(&videos_response, channel_id); + if let Some(token) = parse_videos_continuation(&videos_response) { + info.videos_continuation = Some(token); + } + } + Ok(Err(e)) => { + log::warn!("[channel {channel_id}] Videos-tab fetch failed ({e}); recent_videos empty (header still populated)"); + } + Err(_) => { + // The worker closure can't panic by construction → invariant breach. + log::error!( + "[channel {channel_id}] Videos-tab worker thread panicked; recent_videos empty" + ); } } Ok(info) @@ -129,7 +147,13 @@ pub fn fetch_channel_browse(channel_id: &str) -> Result Result { let body = fetch_continuation_browse(token)?; - Ok(parse_channel_continuation(&body)) + let page = parse_channel_continuation(&body); + log::info!( + "channel_videos_continuation ok: items={} more={}", + page.items.len(), + page.continuation.is_some() + ); + Ok(page) } /// POST `browse` with `{"continuation": token}` (no browseId/params). @@ -170,12 +194,24 @@ fn fetch_continuation_browse(token: &str) -> Result { /// `continuationItems` array. pub fn parse_channel_continuation(body: &Value) -> ContinuationPage { let Some(items) = continuation_items(body, "onResponseReceivedActions") else { + // A non-empty body with no continuationItems = the pagination shape + // moved; the page returns empty and pagination silently ends. + if body.as_object().map(|m| !m.is_empty()).unwrap_or(false) { + log::warn!("channel continuation: no continuationItems found (pagination shape changed?); ending pagination"); + } return ContinuationPage::default(); }; - let videos = items.iter().filter_map(parse_rich_grid_item).collect(); + let videos: Vec = items.iter().filter_map(parse_rich_grid_item).collect(); + // Aggregate renderer-migration signal: cells present but none parsed. + if !items.is_empty() && videos.is_empty() { + log::warn!( + "channel continuation: {} cell(s) but 0 parsed (renderer migration?)", + items.len() + ); + } ContinuationPage { - items: videos, continuation: token_from_items(items), + items: videos, } } @@ -289,11 +325,23 @@ pub fn parse_channel_browse(channel_id: &str, body: &Value) -> ChannelInfo { /// Handles BOTH old-style `videoRenderer` items and new-style /// `lockupViewModel` items (YT migrated channel-videos UI to /// lockupViewModel around 2024). -fn parse_videos_tab(body: &Value) -> Vec { - match selected_tab_grid_contents(body) { - Some(items) => items.iter().filter_map(parse_rich_grid_item).collect(), - None => Vec::new(), +fn parse_videos_tab(body: &Value, channel_id: &str) -> Vec { + let Some(items) = selected_tab_grid_contents(body) else { + // A real browse response (has `contents`) but no grid = layout change. + if body.get("contents").is_some() { + log::warn!("[channel {channel_id}] Videos-tab grid not found (layout change?); recent_videos empty"); + } + return Vec::new(); + }; + let parsed: Vec = items.iter().filter_map(parse_rich_grid_item).collect(); + // Aggregate renderer-migration signal: cells present but none parsed. + if !items.is_empty() && parsed.is_empty() { + log::warn!( + "[channel {channel_id}] Videos-tab grid had {} cell(s) but 0 parsed (renderer migration?)", + items.len() + ); } + parsed } /// The `contents[]` array of the selected channel tab's diff --git a/src/youtube/js/mod.rs b/src/youtube/js/mod.rs index de1641c..34b38a1 100644 --- a/src/youtube/js/mod.rs +++ b/src/youtube/js/mod.rs @@ -60,6 +60,8 @@ pub enum DeobfError { JsRuntimeFailed(String), #[error("nsig output was empty (function neutered?)")] NsigEmpty, + #[error("nsig output equalled its input (identity — deobfuscator neutered?)")] + NsigIdentity, #[error("downloader not initialized")] DownloaderMissing, } diff --git a/src/youtube/js/nsig.rs b/src/youtube/js/nsig.rs index 3853669..346e47a 100644 --- a/src/youtube/js/nsig.rs +++ b/src/youtube/js/nsig.rs @@ -177,7 +177,10 @@ fn deobfuscation_function_body( let function_base = format!("{function_name}=function"); match match_to_closing_brace(player_code, &function_base) { Ok(body) => Ok(format!("{function_base}{body};")), - Err(_) => deobfuscation_function_body_regex(player_code, function_name), + Err(_) => { + log::debug!("nsig body: lexer brace-match failed, falling back to regex extraction"); + deobfuscation_function_body_regex(player_code, function_name) + } } } @@ -220,6 +223,11 @@ pub fn fixup_function(function: &str) -> Result { .unwrap_or_default(); if first_arg.is_empty() { + // The args regex didn't capture a first argument, so the + // `if(typeof X==="undefined")return ;` guard can't be stripped — + // the deobfuscator will return its input unchanged (throttled URLs). + // Fires ~once per player.js generation (build is cached). + log::warn!("nsig fixup: could not extract the function's first argument; the early-return guard cannot be stripped → deobfuscator may return its input unchanged"); return Ok(function.to_string()); } diff --git a/src/youtube/js/player_manager.rs b/src/youtube/js/player_manager.rs index 9dc65e9..c622608 100644 --- a/src/youtube/js/player_manager.rs +++ b/src/youtube/js/player_manager.rs @@ -108,6 +108,22 @@ impl Derived { Derived::Nsig => &mut state.nsig_fail, } } + + /// Short log label for the derived artifact. + fn label(&self) -> &'static str { + match self { + Derived::SigTimestamp => "signature-timestamp", + Derived::Sig => "sig", + Derived::Nsig => "nsig", + } + } +} + +/// Strip the query/fragment off a player.js URL before logging. Player URLs are +/// static + user-independent (safe to log per the audit), but this keeps the +/// no-secrets discipline uniform with the rest of the crate. +fn strip_query(url: &str) -> &str { + url.split(['?', '#']).next().unwrap_or(url) } /// Verdict of a memo check, decided under the state lock. @@ -282,6 +298,9 @@ impl PlayerManager { ) { Ok(result) => { if result == "null" { + log::warn!( + "sig deobf returned \"null\" → empty signature (affected formats may 403)" + ); Ok(String::new()) // NPE: Objects.requireNonNullElse(..., "") } else { Ok(result) @@ -340,6 +359,21 @@ impl PlayerManager { self.on_eval_failure(Derived::Nsig, fresh, &e); return Err(e); } + if deobf == obf { + // Identity output: the deobfuscator ran but returned its input + // UNCHANGED — almost always a surviving `if(typeof X==="undefined") + // return p;` guard that `fixup_function` failed to strip. Caching it + // would permanently serve THROTTLED URLs for the whole session, so + // treat it like a neutered function: DON'T cache, invalidate + + // (fresh) memoize so the rest of the open replays cheaply, and let + // the throttled formats be counted by the aggregate nsig-fallback + // WARN in populate_streams. The memo/invalidate machinery bounds + // this WARN to ~once per player.js generation per open. + let e = DeobfError::NsigIdentity; + log::warn!("nsig deobf returned its input unchanged (identity) → NOT caching (would permanently throttle); player.js likely has an unstripped guard"); + self.on_eval_failure(Derived::Nsig, fresh, &e); + return Err(e); + } { let mut state = self.state.lock(); @@ -408,6 +442,10 @@ impl PlayerManager { // The post-cooldown probe itself failed (network). // Re-arm the cooldown so we don't probe on every // subsequent call while the network is down. + log::warn!( + "player.js {} post-cooldown probe failed ({fetch_err}); re-arming cooldown", + which.label() + ); let mut state = self.state.lock(); if let Some(m) = which.memo_mut(&mut state).as_mut() { m.at = Instant::now(); @@ -425,6 +463,11 @@ impl PlayerManager { let mut state = self.state.lock(); match which.memo_mut(&mut state).as_mut() { Some(m) => { + log::warn!( + "player.js {} still broken: YT is still serving the known-bad player.js after cooldown (player={})", + which.label(), + strip_query(&m.player_url) + ); m.at = Instant::now(); return Err(m.error.clone()); } @@ -458,6 +501,12 @@ impl PlayerManager { // the memo so every further call within the cooldown // replays instead of re-fetching ~1.7 MB per format. let player_url = state.player_url.clone().unwrap_or_default(); + log::warn!( + "player.js {} extraction failed ({e}); memoizing for {}s (player={})", + which.label(), + FAILURE_COOLDOWN.as_secs(), + strip_query(&player_url) + ); *which.memo_mut(&mut state) = Some(FailMemo { player_url, error: e.clone(), @@ -467,6 +516,12 @@ impl PlayerManager { } }; } + // Invariant breach: the 2-pass retry loop is bounded and should always + // resolve; exhausting it means an unexpected concurrent-invalidation storm. + log::error!( + "player.js {} unavailable after retry (concurrent cache-invalidation loop exhausted)", + which.label() + ); Err(DeobfError::FetchPlayerCode( "player.js unavailable after retry (concurrent cache invalidation)".into(), )) @@ -482,6 +537,16 @@ impl PlayerManager { fn on_eval_failure(&self, which: Derived, fresh: bool, error: &DeobfError) { let mut state = self.state.lock(); let player_url = state.player_url.clone().unwrap_or_default(); + log::warn!( + "player.js {} eval failed ({error}); invalidating{} (player={})", + which.label(), + if fresh { + " + memoizing (fresh download)" + } else { + " for refetch" + }, + strip_query(&player_url) + ); state.invalidate(); if fresh { *which.memo_mut(&mut state) = Some(FailMemo { @@ -550,6 +615,13 @@ impl PlayerManager { *memo = None; } } + // The one INFO that makes every sig/nsig incident diagnosable: which + // player.js generation is installed + its size. Lifecycle, ~1/rotation. + log::info!( + "player.js installed: {} ({}KB, fresh)", + strip_query(&url), + code.len() / 1024 + ); state.player_url = Some(url); state.player_code = Some(code); Ok(Ensured::Ready { fresh: true }) @@ -719,6 +791,12 @@ mod tests { // (no outer-global references), so eval succeeds for any input. const PLAYER_GOOD: &str = r#"m85=function(p){var a=p.split("");a.reverse();return a.join("");};dummy=function(q){return Q[1];};var foo={signatureTimestamp:20244};"#; + // Parses + evals fine, but the nsig function returns its INPUT unchanged + // (identity) — the neutered-deobfuscator shape (e.g. an unstripped guard). + // Name matches regex 0 via the trailing `return Q[1]`; the extracted body + // is just `m85=function(p){return p;}`. + const PLAYER_NSIG_IDENTITY: &str = r#"m85=function(p){return p;};dummy=function(q){return Q[1];};var foo={signatureTimestamp:20244};"#; + // Parses fine but throws for EVERY input at eval time. const PLAYER_EVAL_THROWS: &str = r#"m85=function(p){throw Error("boom");return Q[1];};"#; @@ -753,6 +831,29 @@ mod tests { assert_eq!(stub.count(), 2, "memo must suppress refetching"); } + #[test] + fn nsig_identity_output_is_rejected_and_not_cached() { + let _g = GLOBAL_DOWNLOADER_LOCK.lock(); + let stub = Arc::new(StubDownloader::new("aaaaaaaa", PLAYER_NSIG_IDENTITY)); + install(&stub); + let mgr = PlayerManager::new(); + + // The deobfuscator returns its input unchanged → must surface as + // NsigIdentity, NOT be treated as a successful deobfuscation. + let err = mgr + .url_with_throttling_parameter_deobfuscated("vid", "https://x/?n=abc") + .unwrap_err(); + assert!(matches!(err, DeobfError::NsigIdentity), "got {err:?}"); + + // Critically, the identity result must NOT be cached — caching it would + // serve THROTTLED URLs for the whole session (the permanent-throttle trap). + assert_eq!( + mgr.throttling_parameter_cache_size(), + 0, + "identity output must never be cached" + ); + } + #[test] fn artifact_memos_are_independent() { let _g = GLOBAL_DOWNLOADER_LOCK.lock(); diff --git a/src/youtube/js/runtime.rs b/src/youtube/js/runtime.rs index 2b7172a..da0a07e 100644 --- a/src/youtube/js/runtime.rs +++ b/src/youtube/js/runtime.rs @@ -64,10 +64,11 @@ pub fn compile_or_throw(snippet: &str) -> Result<(), DeobfError> { /// with one string argument, returns the toString of the result. /// Mirrors NPE `JavaScript.run(snippet, functionName, parameters)`. pub fn run(snippet: &str, function_name: &str, parameter: &str) -> Result { + let started = Instant::now(); let runtime = guarded_runtime().map_err(|e| DeobfError::JsRuntimeFailed(e.to_string()))?; let context = Context::full(&runtime).map_err(|e| DeobfError::JsRuntimeFailed(e.to_string()))?; - context.with(|ctx| -> Result { + let out = context.with(|ctx| -> Result { ctx.eval::<(), _>(snippet) .map_err(|e| DeobfError::JsRuntimeFailed(format!("eval: {e}")))?; let func: Function = ctx @@ -80,7 +81,18 @@ pub fn run(snippet: &str, function_name: &str, parameter: &str) -> Result= JS_DEADLINE { + log::warn!( + "JS deadline ({}s) hit during `{function_name}` — execution aborted (pathological player.js?)", + JS_DEADLINE.as_secs() + ); + } + out } #[cfg(test)] diff --git a/src/youtube/js/signature.rs b/src/youtube/js/signature.rs index 423f718..51592c5 100644 --- a/src/youtube/js/signature.rs +++ b/src/youtube/js/signature.rs @@ -101,7 +101,10 @@ pub fn deobfuscate_function_body( let function_base = format!("{function_name}=function"); match match_to_closing_brace(player_code, &function_base) { Ok(body) => Ok(format!("{function_base}{body}")), - Err(_) => deobfuscate_with_regex(player_code, function_name), + Err(_) => { + log::debug!("sig body: lexer brace-match failed, falling back to regex extraction"); + deobfuscate_with_regex(player_code, function_name) + } } } diff --git a/src/youtube/potoken/mod.rs b/src/youtube/potoken/mod.rs index 86b4630..786d157 100644 --- a/src/youtube/potoken/mod.rs +++ b/src/youtube/potoken/mod.rs @@ -113,10 +113,12 @@ static REGISTERED_PROVIDER: Lazy>>> = Lazy::new(|| RwLock::new(None)); pub fn set_po_token_provider(provider: Arc) { + log::info!("poToken provider registered"); *REGISTERED_PROVIDER.write() = Some(provider); } pub fn clear_po_token_provider() { + log::info!("poToken provider cleared"); *REGISTERED_PROVIDER.write() = None; } diff --git a/src/youtube/search_extractor.rs b/src/youtube/search_extractor.rs index 2fc5db0..955ab1e 100644 --- a/src/youtube/search_extractor.rs +++ b/src/youtube/search_extractor.rs @@ -69,7 +69,15 @@ pub fn search(query: &str, filter: SearchFilter) -> Result Result Result ContinuationPage { let Some(items) = continuation_items(body, "onResponseReceivedCommands") else { + if body.as_object().map(|m| !m.is_empty()).unwrap_or(false) { + log::warn!("search continuation: no continuationItems found (shape changed?); ending pagination"); + } return ContinuationPage::default(); }; let mut info = SearchInfo::default(); @@ -155,6 +172,16 @@ pub fn parse_search_response(query: &str, body: &Value) -> SearchInfo { .and_then(|c| c.get("sectionListRenderer")) .and_then(|c| c.get("contents")); + // A non-empty response body whose primary results path is gone = a layout + // change; we'd otherwise silently return zero results. Log query_len, never + // the query. + if primary.is_none() && body.as_object().map(|m| !m.is_empty()).unwrap_or(false) { + log::warn!( + "search: primary results path missing (layout change?); 0 results for query_len={}", + query.len() + ); + } + if let Some(sections) = primary.and_then(|v| v.as_array()) { for section in sections { if let Some(items) = section diff --git a/src/youtube/stream_extractor.rs b/src/youtube/stream_extractor.rs index ea0adcf..bc10fdd 100644 --- a/src/youtube/stream_extractor.rs +++ b/src/youtube/stream_extractor.rs @@ -35,7 +35,7 @@ use crate::youtube::itag::{lookup as itag_lookup, ItagType}; #[cfg(test)] use crate::youtube::itag::MediaFormat; use crate::youtube::js::PlayerManager; -use crate::youtube::potoken::{po_token_provider, PoTokenResult}; +use crate::youtube::potoken::{po_token_provider, PoTokenError, PoTokenResult}; use crate::youtube::stream_helper::{self, generate_content_playback_nonce}; use crate::youtube::xtags; @@ -128,9 +128,9 @@ pub fn stream_info_with( options.android_streaming_pot.as_deref(), options.android_visitor_data.as_deref(), || { - provider - .as_ref() - .and_then(|p| p.get_android_client_po_token(video_id).ok().flatten()) + provider.as_ref().and_then(|p| { + provider_token(p.get_android_client_po_token(video_id), "ANDROID", video_id) + }) }, ); @@ -157,11 +157,18 @@ pub fn stream_info_with( // the win is the warm/success path. Worst case is a rare, bounded cold-fail // delay — never a change in what's extracted. let (android_result, signature_timestamp) = std::thread::scope(|s| { - let sig_ts = s.spawn(|| { - PlayerManager::instance() - .signature_timestamp(video_id) - .unwrap_or(0) - }); + let sig_ts = s.spawn( + || match PlayerManager::instance().signature_timestamp(video_id) { + Ok(ts) => ts, + Err(e) => { + // WARN, not fatal: sig-required (WEB-family) formats may 403, + // but the android-primary formats carry direct URLs. The + // timestamp also feeds the WEB metadata playbackContext. + log::warn!("[{video_id}] signature_timestamp unavailable ({e}); using 0"); + 0 + } + }, + ); let android = fetch_android( video_id, &localization, @@ -172,8 +179,16 @@ pub fn stream_info_with( .map(|t| t.player_request_po_token.as_str()), android_token.as_ref().map(|t| t.visitor_data.as_str()), ); - // A panicked worker joins as Err → 0, same as an extraction failure. - (android, sig_ts.join().unwrap_or(0)) + // A panicked worker is an invariant breach (the spawned closure never + // panics by construction) → ERROR; still degrade to 0 like a failure. + let ts = match sig_ts.join() { + Ok(ts) => ts, + Err(_) => { + log::error!("[{video_id}] signature_timestamp worker thread panicked; using 0"); + 0 + } + }; + (android, ts) }); // ── Primary player-response selection: ANDROID → VISIONOS cascade ──────── // ANDROID was the REQUIRED primary, but the 2026 poToken/BotGuard bot-wall @@ -228,9 +243,9 @@ pub fn stream_info_with( options.ios_streaming_pot.as_deref(), options.ios_visitor_data.as_deref(), || { - provider - .as_ref() - .and_then(|p| p.get_ios_client_po_token(video_id).ok().flatten()) + provider.as_ref().and_then(|p| { + provider_token(p.get_ios_client_po_token(video_id), "IOS", video_id) + }) }, ) } else { @@ -250,7 +265,16 @@ pub fn stream_info_with( ios_token.as_ref().map(|t| t.visitor_data.as_str()), ) { Ok(r) if !is_player_response_not_valid(&r, video_id) => (Some(r), Some(ios_cpn)), - _ => (None, None), + Ok(_) => { + log::warn!( + "[{video_id}] iOS add-on response was a decoy (videoId mismatch); dropped" + ); + (None, None) + } + Err(e) => { + log::warn!("[{video_id}] iOS add-on fetch failed ({e}); dropped"); + (None, None) + } } } else { (None, None) @@ -277,7 +301,16 @@ pub fn stream_info_with( &cpn, ) { Ok(r) if !is_player_response_not_valid(&r, video_id) => (Some(r), Some(cpn)), - _ => (None, None), + Ok(_) => { + log::warn!( + "[{video_id}] visionOS add-on response was a decoy (videoId mismatch); dropped" + ); + (None, None) + } + Err(e) => { + log::warn!("[{video_id}] visionOS add-on fetch failed ({e}); dropped"); + (None, None) + } } } else { (None, None) @@ -362,6 +395,17 @@ pub fn stream_info_with( ); populate_captions(&mut info, &player_response); + log::info!( + "[{video_id}] extraction ok: primary={} audio={} video={} video_only={}", + if primary_is_visionos { + "VISIONOS" + } else { + "ANDROID" + }, + info.audio_streams.len(), + info.video_streams.len(), + info.video_only_streams.len(), + ); Ok(info) } @@ -392,9 +436,9 @@ pub fn stream_metadata(video_id: &str) -> Result { // registered (the default) this resolves to None → anonymous reel. let provider = po_token_provider(); let android_token: Option = options_or_provider(None, None, None, || { - provider - .as_ref() - .and_then(|p| p.get_android_client_po_token(video_id).ok().flatten()) + provider.as_ref().and_then(|p| { + provider_token(p.get_android_client_po_token(video_id), "ANDROID", video_id) + }) }); let android_cpn = generate_content_playback_nonce(); @@ -432,9 +476,36 @@ pub fn stream_metadata(video_id: &str) -> Result { ..StreamInfo::default() }; populate_video_details(&mut info, &player_response); + log::info!( + "[{video_id}] stream_metadata ok: title_len={} views={} duration={}s", + info.name.len(), + info.view_count, + info.duration_seconds, + ); Ok(info) } +/// Unwrap a PoTokenProvider result, logging a WARN on the Err arm the old +/// `.ok().flatten()` swallowed silently. `Ok(None)` = provider declined (go +/// anonymous, no log); `Err` = provider tried and failed (still go anonymous, +/// but it's a degradation worth a breadcrumb). Never logs the token — only the +/// error kind + client + videoId. +fn provider_token( + result: Result, PoTokenError>, + client: &str, + video_id: &str, +) -> Option { + match result { + Ok(opt) => opt, + Err(e) => { + log::warn!( + "[{video_id}] {client} poToken provider errored ({e}); continuing anonymous" + ); + None + } + } +} + fn options_or_provider( opt_player_token: Option<&str>, opt_streaming_token: Option<&str>, @@ -561,13 +632,21 @@ fn fetch_web_metadata( content_country: &ContentCountry, signature_timestamp: i32, ) -> Value { - stream_helper::get_web_metadata_player_response( + match stream_helper::get_web_metadata_player_response( video_id, localization, content_country, signature_timestamp, - ) - .unwrap_or(Value::Null) + ) { + Ok(v) => v, + Err(e) => { + // WEB metadata is best-effort; on failure we fall back to the + // primary response's videoDetails thumbnails and lose upload + // date / category / hi-res thumbnails. Also masks a WEB-client wall. + log::warn!("[{video_id}] WEB metadata fetch failed ({e}); upload date/category/hi-res thumbnails unavailable"); + Value::Null + } + } } fn check_playability_status(player_response: &Value) -> Result<(), ExtractionError> { @@ -583,7 +662,7 @@ fn check_playability_status(player_response: &Value) -> Result<(), ExtractionErr let mapped = match status_code { "LOGIN_REQUIRED" => { if reason_lc.contains("a bot") { - ContentUnavailable::Other("sign in to confirm you're not a bot".into()) + ContentUnavailable::BotDetected } else if reason_lc.contains("inappropriate") { ContentUnavailable::AgeRestricted } else if reason_lc.contains("private") { @@ -657,15 +736,28 @@ fn select_primary( // ANDROID unusable → drop the (likely poisoned) visitorData, then try // VISIONOS as the primary. On any VISIONOS failure, surface the ORIGINAL // ANDROID error rather than the visionOS one. + // `android_error`'s Display carries the playabilityStatus reason (the + // choke point in exceptions.rs strips any URL, so no stream URL leaks). + log::warn!("[{video_id}] ANDROID primary unusable ({android_error}); trying VISIONOS"); on_fallback(); match fetch_visionos() { - Ok(resp) if primary_response_usable(&resp, video_id).is_ok() => Ok((resp, true)), - _ => Err(android_error), + Ok(resp) if primary_response_usable(&resp, video_id).is_ok() => { + log::info!("[{video_id}] primary=VISIONOS (ANDROID fallback succeeded)"); + Ok((resp, true)) + } + _ => { + log::warn!("[{video_id}] extraction failed: ANDROID and VISIONOS both unusable ({android_error})"); + Err(android_error) + } } } fn populate_video_details(info: &mut StreamInfo, player_response: &Value) { let Some(vd) = player_response.get("videoDetails") else { + log::warn!( + "[{}] player response had no videoDetails; title/uploader/duration left empty", + info.video_id + ); return; }; if let Some(s) = vd.get("title").and_then(|v| v.as_str()) { @@ -759,6 +851,22 @@ fn populate_microformat(info: &mut StreamInfo, web_metadata: &Value) { } } +/// Per-EXTRACTION accumulator for per-format URL-processing outcomes, so the +/// degradations that happen inside the per-format loop are logged ONCE (in +/// `populate_streams`) as aggregate counters instead of spamming a line per +/// format. Threaded through `process_url` / `build_*`; never logged from inside +/// the loop. +#[derive(Default)] +struct UrlProcessStats { + /// Formats that shipped the THROTTLED original URL because nsig deobf was + /// unavailable (`url_with_throttling_parameter_deobfuscated` Err). + nsig_fallback: u32, + /// Formats that took the (android-primary-rare) signatureCipher path. + cipher_path: u32, + /// signatureCipher-path formats dropped because sig deobf failed. + cipher_sig_failed: u32, +} + /// One client's streamingData plus the tags every format from it carries. /// Holds borrowed `&Value`s into the (function-lived) player responses. struct FormatSource<'a> { @@ -794,9 +902,13 @@ fn populate_streams( sources: &[FormatSource], video_id: &str, ) -> Result<(), ExtractionError> { + // Per-call accumulator — every per-format degradation is counted here and + // logged ONCE below, never per iteration. + let mut stats = UrlProcessStats::default(); + // Progressive: streamingData.formats[] for (fmt, _client, cpn, pot) in merge_formats(sources, "formats") { - if let Some(stream) = build_video_progressive(fmt, video_id, cpn, pot)? { + if let Some(stream) = build_video_progressive(fmt, video_id, cpn, pot, &mut stats)? { push_video_dedup(&mut info.video_streams, stream); } } @@ -808,15 +920,58 @@ fn populate_streams( .and_then(|v| v.as_str()) .unwrap_or(""); if mime.starts_with("audio/") { - if let Some(audio) = build_audio(fmt, video_id, cpn, pot)? { + if let Some(audio) = build_audio(fmt, video_id, cpn, pot, &mut stats)? { push_audio_dedup(&mut info.audio_streams, audio); } } else if mime.starts_with("video/") { - if let Some(video) = build_video_only(fmt, video_id, cpn, pot)? { + if let Some(video) = build_video_only(fmt, video_id, cpn, pot, &mut stats)? { push_video_dedup(&mut info.video_only_streams, video); } } } + + // ── Aggregate degradation WARNs (one line each per extraction) ────────── + if stats.nsig_fallback > 0 { + log::warn!( + "[{video_id}] {} format(s) shipped THROTTLED URLs (nsig deobf unavailable)", + stats.nsig_fallback + ); + } + if stats.cipher_path > 0 { + log::warn!( + "[{video_id}] {} format(s) took the signatureCipher path ({} sig-deobf failure(s))", + stats.cipher_path, + stats.cipher_sig_failed + ); + } + let total = info.video_streams.len() + info.audio_streams.len() + info.video_only_streams.len(); + if total == 0 { + // Playability passed but nothing built — report the raw per-source + // format counts YT actually returned so a "why no streams" incident is + // diagnosable (itag-bank miss vs empty streamingData vs all-cipher). + let counts: Vec = sources + .iter() + .map(|s| { + let f = s + .streaming_data + .get("formats") + .and_then(|v| v.as_array()) + .map(|a| a.len()) + .unwrap_or(0); + let af = s + .streaming_data + .get("adaptiveFormats") + .and_then(|v| v.as_array()) + .map(|a| a.len()) + .unwrap_or(0); + format!("{}={}+{}", s.client, f, af) + }) + .collect(); + log::warn!( + "[{video_id}] playability OK but ZERO usable streams built (per-source formats+adaptive: {})", + counts.join(" ") + ); + } Ok(()) } @@ -914,12 +1069,15 @@ fn process_url( video_id: &str, cpn: &str, pot: Option<&str>, + stats: &mut UrlProcessStats, ) -> Result, ExtractionError> { let mut url = if let Some(u) = raw_format.get("url").and_then(|v| v.as_str()) { u.to_string() } else { // signatureCipher path — WEB-family only; not exercised in the // Android-primary flow but mirror NPE's behavior for completeness. + // Counted per-extraction (aggregate WARN in populate_streams). + stats.cipher_path += 1; let cipher_str = raw_format .get("signatureCipher") .or_else(|| raw_format.get("cipher")) @@ -940,7 +1098,10 @@ fn process_url( // the Android-primary flow.) let deobf = match PlayerManager::instance().deobfuscate_signature(video_id, s) { Ok(d) => d, - Err(_) => return Ok(None), + Err(_) => { + stats.cipher_sig_failed += 1; + return Ok(None); + } }; format!("{base}&{sp}={deobf}") }; @@ -956,9 +1117,19 @@ fn process_url( // zero network instead of re-downloading ~1.7 MB per format, and retries // after a cooldown / as soon as a new player.js ships. (NPE parity; straw // audits 2026-07-04 + 2026-07-28 H2.) - url = PlayerManager::instance() + url = match PlayerManager::instance() .url_with_throttling_parameter_deobfuscated(video_id, &url) - .unwrap_or(url); + { + Ok(u) => u, + Err(_e) => { + // nsig deobf unavailable (fetch/build/eval/identity failure) → ship + // the THROTTLED original URL. YouTube still serves it, rate-limited. + // Counted per-extraction; populate_streams emits ONE aggregate WARN. + // Deliberately NOT logged here (per-format = spam). + stats.nsig_fallback += 1; + url + } + }; let sep_cpn = if url.contains('?') { '&' } else { '?' }; url = format!("{url}{sep_cpn}cpn={cpn}"); @@ -987,12 +1158,13 @@ fn build_video_progressive( video_id: &str, cpn: &str, pot: Option<&str>, + stats: &mut UrlProcessStats, ) -> Result, ExtractionError> { let itag_id = fmt.get("itag").and_then(|v| v.as_u64()).unwrap_or(0) as u32; let Some(itag) = itag_lookup(itag_id) else { return Ok(None); }; - let Some(url) = process_url(fmt, video_id, cpn, pot)? else { + let Some(url) = process_url(fmt, video_id, cpn, pot, stats)? else { return Ok(None); }; Ok(Some(VideoStream { @@ -1019,6 +1191,7 @@ fn build_video_only( video_id: &str, cpn: &str, pot: Option<&str>, + stats: &mut UrlProcessStats, ) -> Result, ExtractionError> { let itag_id = fmt.get("itag").and_then(|v| v.as_u64()).unwrap_or(0) as u32; let Some(itag) = itag_lookup(itag_id) else { @@ -1027,7 +1200,7 @@ fn build_video_only( if itag.item_type != ItagType::VideoOnly { return Ok(None); } - let Some(url) = process_url(fmt, video_id, cpn, pot)? else { + let Some(url) = process_url(fmt, video_id, cpn, pot, stats)? else { return Ok(None); }; Ok(Some(VideoStream { @@ -1054,6 +1227,7 @@ fn build_audio( video_id: &str, cpn: &str, pot: Option<&str>, + stats: &mut UrlProcessStats, ) -> Result, ExtractionError> { let itag_id = fmt.get("itag").and_then(|v| v.as_u64()).unwrap_or(0) as u32; let Some(itag) = itag_lookup(itag_id) else { @@ -1062,7 +1236,7 @@ fn build_audio( if itag.item_type != ItagType::Audio { return Ok(None); } - let Some(url) = process_url(fmt, video_id, cpn, pot)? else { + let Some(url) = process_url(fmt, video_id, cpn, pot, stats)? else { return Ok(None); }; let audio_track = fmt.get("audioTrack"); @@ -1214,6 +1388,26 @@ mod tests { } } + #[test] + fn playability_bot_wall_maps_to_bot_detected() { + // The 2026 poToken/BotGuard wall on the pot-less client. It must map to + // the dedicated BotDetected variant (greppable / classifiable), and its + // Display must stay byte-identical to the old Other(...) string so + // string-matching callers keep working. + let resp = json!({ + "playabilityStatus": { + "status": "LOGIN_REQUIRED", + "reason": "Sign in to confirm you’re not a bot. This helps protect our community." + } + }); + match check_playability_status(&resp).unwrap_err() { + ExtractionError::ContentUnavailable(ref cu @ ContentUnavailable::BotDetected) => { + assert_eq!(cu.to_string(), "sign in to confirm you're not a bot"); + } + other => panic!("expected BotDetected, got {other:?}"), + } + } + #[test] fn decoy_detected() { let resp = json!({"videoDetails": {"videoId": "DIFFERENT_ID"}}); @@ -1560,7 +1754,9 @@ mod tests { #[test] fn xtags_descriptive_sets_track_type_and_is_descriptive() { let fmt = audio_fmt(Some("ChQKBWFjb250EgtkZXNjcmlwdGl2ZQ"), true); - let a = build_audio(&fmt, "vid", "cpn", None).unwrap().unwrap(); + let a = build_audio(&fmt, "vid", "cpn", None, &mut UrlProcessStats::default()) + .unwrap() + .unwrap(); assert_eq!(a.track_type, Some(AudioTrackType::Descriptive)); assert!(a.is_descriptive); } @@ -1570,7 +1766,9 @@ mod tests { // acont=dubbed → Dubbed + is_descriptive false, even though // audioIsDefault=false would make the legacy heuristic say "descriptive". let fmt = audio_fmt(Some("Cg8KBWFjb250EgZkdWJiZWQ"), false); - let a = build_audio(&fmt, "vid", "cpn", None).unwrap().unwrap(); + let a = build_audio(&fmt, "vid", "cpn", None, &mut UrlProcessStats::default()) + .unwrap() + .unwrap(); assert_eq!(a.track_type, Some(AudioTrackType::Dubbed)); assert!(!a.is_descriptive); } @@ -1578,7 +1776,9 @@ mod tests { #[test] fn xtags_original_maps_to_original() { let fmt = audio_fmt(Some("ChEKBWFjb250EghvcmlnaW5hbA"), true); - let a = build_audio(&fmt, "vid", "cpn", None).unwrap().unwrap(); + let a = build_audio(&fmt, "vid", "cpn", None, &mut UrlProcessStats::default()) + .unwrap() + .unwrap(); assert_eq!(a.track_type, Some(AudioTrackType::Original)); assert!(!a.is_descriptive); } @@ -1586,15 +1786,27 @@ mod tests { #[test] fn absent_xtags_falls_back_to_audio_is_default_heuristic() { // No xtags → track_type None → is_descriptive == !audioIsDefault. - let a = build_audio(&audio_fmt(None, false), "vid", "cpn", None) - .unwrap() - .unwrap(); + let a = build_audio( + &audio_fmt(None, false), + "vid", + "cpn", + None, + &mut UrlProcessStats::default(), + ) + .unwrap() + .unwrap(); assert_eq!(a.track_type, None); assert!(a.is_descriptive); // !false - let a = build_audio(&audio_fmt(None, true), "vid", "cpn", None) - .unwrap() - .unwrap(); + let a = build_audio( + &audio_fmt(None, true), + "vid", + "cpn", + None, + &mut UrlProcessStats::default(), + ) + .unwrap() + .unwrap(); assert_eq!(a.track_type, None); assert!(!a.is_descriptive); // !true } @@ -1602,9 +1814,15 @@ mod tests { #[test] fn unparseable_xtags_falls_back_to_heuristic() { // Garbage xtags → extract_audio_track_type None → heuristic used. - let a = build_audio(&audio_fmt(Some("!!!not-b64!!!"), false), "vid", "cpn", None) - .unwrap() - .unwrap(); + let a = build_audio( + &audio_fmt(Some("!!!not-b64!!!"), false), + "vid", + "cpn", + None, + &mut UrlProcessStats::default(), + ) + .unwrap() + .unwrap(); assert_eq!(a.track_type, None); assert!(a.is_descriptive); } diff --git a/src/youtube/stream_helper.rs b/src/youtube/stream_helper.rs index e43c1f7..fcfcfb8 100644 --- a/src/youtube/stream_helper.rs +++ b/src/youtube/stream_helper.rs @@ -142,8 +142,21 @@ fn get_visitor_data( // best-effort None (the caller then proceeds without visitorData). An // expired-but-present cache entry is deliberately NOT served on a failed // refetch: a stale visitorData is the thing we're rotating away from. - let parsed = post_youtube(&url, &body, headers).ok()?; - let visitor = visitor_data_from_response(&parsed)?; + // WARN because losing visitorData weakens attestation and kneecaps the + // visionOS bot-wall survivor. post_youtube already DEBUG-logged the + // HTTP-level detail; this is the semantic degradation. `domain` is a + // static endpoint constant (no secrets). + let parsed = match post_youtube(&url, &body, headers) { + Ok(p) => p, + Err(_e) => { + log::warn!("visitorData unavailable ({domain}visitor_id fetch failed); proceeding without it (attestation/visionOS weakened)"); + return None; + } + }; + let Some(visitor) = visitor_data_from_response(&parsed) else { + log::warn!("visitorData unavailable ({domain}visitor_id response had no visitorData); proceeding without it"); + return None; + }; *VISITOR_DATA_CACHE.write() = Some(CachedVisitorData { value: visitor.clone(), at: std::time::Instant::now(), @@ -157,6 +170,9 @@ fn get_visitor_data( /// the primary path, and since that failure aborts extraction the value would /// otherwise never self-heal. pub(crate) fn reset_visitor_data_cache() { + // Lifecycle INFO: the self-heal trigger. Covers both the primary-cascade + // path and the stream_metadata twin path. + log::info!("visitorData cache reset (primary response rejected; next fetch mints fresh)"); *VISITOR_DATA_CACHE.write() = None; } @@ -459,14 +475,32 @@ fn post_youtube( // put it in an error string (they reach Kotlin exception messages // and logs). Scheme+host+path identifies the endpoint just fine. let endpoint = url.split(['?', '#']).next().unwrap_or(url); + // body_len is the bot-wall tell (an HTML challenge page has a + // distinctive size vs a JSON error). DEBUG — per-request breadcrumb; + // the semantic WARN is emitted by the caller. + log::debug!( + "post_youtube {endpoint} → HTTP {} ({}B body)", + resp.response_code(), + resp.response_body().len() + ); return Err(ExtractionError::Network(NetworkError::Transport(format!( "HTTP {} from {endpoint}", resp.response_code() )))); } - let parsed: Value = serde_json::from_str(resp.response_body()) - .map_err(|e| ExtractionError::Parsing(ParsingError::JsonShape(e.to_string())))?; - Ok(parsed) + match serde_json::from_str(resp.response_body()) { + Ok(parsed) => Ok(parsed), + Err(e) => { + let endpoint = url.split(['?', '#']).next().unwrap_or(url); + log::debug!( + "post_youtube {endpoint} → 200 but body was not JSON ({}B): {e}", + resp.response_body().len() + ); + Err(ExtractionError::Parsing(ParsingError::JsonShape( + e.to_string(), + ))) + } + } } #[cfg(test)]