diff --git a/crates/metadata/src/lib.rs b/crates/metadata/src/lib.rs index fc63824..46824ba 100644 --- a/crates/metadata/src/lib.rs +++ b/crates/metadata/src/lib.rs @@ -213,6 +213,13 @@ fn stage_trace(stage: &str, started: Instant, detail: &str) { const IMAGE_HOST_PROBE_TTL: Duration = Duration::from_secs(5 * 60); /// A liveness probe races the page, so it must never become the page's latency. const IMAGE_HOST_PROBE_TIMEOUT: Duration = Duration::from_secs(3); +/// The confirming probe runs after the page has already moved on, so it can +/// afford to wait out congestion the fast one could not. +const IMAGE_HOST_CONFIRM_TIMEOUT: Duration = Duration::from_secs(12); +/// Last liveness verdict per image host, shared by the fast probe and by the +/// background confirmation that is allowed to overturn it. +static IMAGE_HOST_HEALTH: std::sync::OnceLock>> = + std::sync::OnceLock::new(); /// Cached catalog responses expire after this long. const CATALOG_TTL: Duration = Duration::from_secs(15 * 60); @@ -3272,8 +3279,6 @@ impl MetadataClient { /// CDN is down" into "this provider returned nothing", which is precisely /// the state the existing fallback chain already knows how to handle. pub async fn image_host_alive(&self, url: &str) -> bool { - static HEALTH: std::sync::OnceLock>> = - std::sync::OnceLock::new(); let Some(host) = reqwest::Url::parse(url) .ok() .and_then(|parsed| parsed.host_str().map(String::from)) @@ -3281,32 +3286,132 @@ impl MetadataClient { // Not a URL this can reason about; never block art on that. return true; }; - let health = HEALTH.get_or_init(|| Mutex::new(HashMap::new())); + let health = IMAGE_HOST_HEALTH.get_or_init(|| Mutex::new(HashMap::new())); if let Some((alive, checked)) = health.lock().await.get(&host).copied() { if checked.elapsed() < IMAGE_HOST_PROBE_TTL { return alive; } } - // A one-byte ranged GET: proof the host serves image bytes without - // pulling a 4K background to find out. Any HTTP answer means the host - // is up — a 404 for one image is not an outage — so only a transport - // failure or a server error counts as dead. - let alive = tokio::time::timeout( - IMAGE_HOST_PROBE_TIMEOUT, - self.http - .get(url) - .header(reqwest::header::RANGE, "bytes=0-0") - .send(), - ) - .await - .ok() - .and_then(|sent| sent.ok()) - .is_some_and(|resp| !resp.status().is_server_error()); - if !alive { - log::warn!("image host {host} is not serving images; falling through to next provider"); + match self.probe_image_host(url, IMAGE_HOST_PROBE_TIMEOUT).await { + Ok(()) => { + health.lock().await.insert(host, (true, Instant::now())); + true + } + Err(why) => { + // Say what was measured, not what it means. "The host is down" + // is a conclusion this single 3-second sample cannot support, + // and stating it as fact sent a later reader hunting an outage + // at Fanart.tv that never happened. + log::warn!( + "image host {host} failed a liveness probe ({why}); \ + falling through to next provider" + ); + health + .lock() + .await + .insert(host.clone(), (false, Instant::now())); + self.confirm_image_host_failure(host, url); + false + } } - health.lock().await.insert(host, (alive, Instant::now())); - alive + } + + /// One liveness request, with the failure kept instead of collapsed to a + /// bool. A one-byte ranged GET is proof the host serves image bytes without + /// pulling a 4K background to find out. Any HTTP answer means the host is + /// up — a 404 for one image is not an outage — so only a transport failure + /// or a server error counts as dead. + async fn probe_image_host(&self, url: &str, budget: Duration) -> Result<(), String> { + let started = Instant::now(); + let sent = self + .http + .get(url) + .header(reqwest::header::RANGE, "bytes=0-0") + .send(); + match tokio::time::timeout(budget, sent).await { + Err(_) => Err(format!("no answer inside {}ms", budget.as_millis())), + Ok(Err(err)) => { + let mut why = format!("{err}"); + let mut source = std::error::Error::source(&err); + while let Some(inner) = source { + why.push_str(&format!(": {inner}")); + source = std::error::Error::source(inner); + } + Err(format!("{why} after {}ms", started.elapsed().as_millis())) + } + Ok(Ok(resp)) if resp.status().is_server_error() => Err(format!( + "HTTP {} after {}ms", + resp.status(), + started.elapsed().as_millis() + )), + Ok(Ok(_)) => Ok(()), + } + } + + /// Ask a second time, off the page's critical path, before a host stays + /// written off for [`IMAGE_HOST_PROBE_TTL`]. + /// + /// The probe's budget is a LATENCY rule — the page must not wait on it — + /// and losing that race is not the same fact as the CDN being down. What + /// ate the budget in the one case chased to the bottom was **name + /// resolution**, before a single byte was sent. + /// + /// Measured 2026-08-03, on the machine that reported the warning: 213 + /// `assets.fanart.tv` urls all answered in ~130ms (cache MISS included), + /// from curl and from this exact client, cold, warm and 12-way concurrent — + /// the host was never down. But the active adapter listed a dead resolver + /// first — no ping, every direct query timing out at 12s — and eight cold + /// lookups of the same name through the normal path came back **1028ms**, + /// 20ms, 30ms, 24ms, 25ms, **2029ms**, 28ms, **1035ms**: the Windows + /// resolver's 1s/2s retransmit schedule, paid before falling through to a + /// server that answers in 21ms. + /// The A record's own TTL is 300s, exactly [`IMAGE_HOST_PROBE_TTL`], so + /// every probe lands on an expired name and pays that lottery again. A + /// single unlucky draw then blacked out Fanart.tv for five minutes and gave + /// every artist a blown-up square portrait instead of a hero. + /// + /// A slow resolver is not this app's to fix, and the fast verdict still + /// stands for the page that paid for it — it falls through to the next + /// provider immediately, as before. What changes is how long one lost race + /// is believed: a background confirmation with a budget that can absorb a + /// DNS retry decides whether the verdict persists, so a blip costs one page + /// instead of five minutes. + fn confirm_image_host_failure(&self, host: String, url: &str) { + static CONFIRMING: std::sync::OnceLock>> = std::sync::OnceLock::new(); + let confirming = CONFIRMING.get_or_init(|| Mutex::new(HashSet::new())); + let http = self.http.clone(); + let url = url.to_string(); + tokio::spawn(async move { + // One confirmation per host at a time: an artist page probes + // banners and logos, twice each, and four identical retries would + // add exactly the load that is the prime suspect. + if !confirming.lock().await.insert(host.clone()) { + return; + } + let outcome = tokio::time::timeout( + IMAGE_HOST_CONFIRM_TIMEOUT, + http.get(&url) + .header(reqwest::header::RANGE, "bytes=0-0") + .send(), + ) + .await; + let recovered = matches!(outcome, Ok(Ok(ref resp)) if !resp.status().is_server_error()); + if recovered { + log::warn!( + "image host {host} answered the confirming probe; \ + the fast probe lost a race, not the host — restoring it" + ); + if let Some(health) = IMAGE_HOST_HEALTH.get() { + health + .lock() + .await + .insert(host.clone(), (true, Instant::now())); + } + } else { + log::warn!("image host {host} failed the confirming probe too; staying written off"); + } + confirming.lock().await.remove(&host); + }); } /// Can this already-chosen artwork actually be shown right now? @@ -12653,6 +12758,224 @@ fn urlencode(s: &str) -> String { #[cfg(test)] mod tests { + /// Is a provider's image host actually failing, or is this machine? + /// + /// Run this the next time a `failed a liveness probe` warning appears. It + /// reproduces [`super::MetadataClient::image_host_alive`]'s exact request + /// four ways — cold client, warm client, the concurrent burst an artist + /// page produces, and a probe interleaved with full-size hero downloads — + /// and prints the reqwest error chain the probe otherwise reduces to a + /// bool. + /// + /// 2026-08-03, the run that answered the fanart.tv report: every one of + /// these came back 206 in ~30-170ms, and 4.3MB of hero downloaded + /// alongside them in 340ms. The host was innocent; the machine's first DNS + /// server was dead and name resolution alone was spending up to 3.6s. When + /// this test is clean, look at `Resolve-DnsName` timings before suspecting + /// the provider. + /// + /// ```text + /// cargo test -p metadata fanart_probe_live -- --ignored --nocapture + /// ``` + #[tokio::test] + #[ignore = "hits assets.fanart.tv"] + async fn fanart_probe_live() { + use std::time::{Duration, Instant}; + // A real url out of this machine's own artist-art manifest. + const URL: &str = "https://assets.fanart.tv/fanart/justice-4e1c8af0c25fc.jpg"; + + fn chain(err: &reqwest::Error) -> String { + let mut out = format!( + "{err} [timeout={} connect={} request={} body={}]", + err.is_timeout(), + err.is_connect(), + err.is_request(), + err.is_body(), + ); + let mut src = std::error::Error::source(err); + while let Some(e) = src { + out.push_str(&format!("\n caused by: {e}")); + src = std::error::Error::source(e); + } + out + } + + fn client() -> reqwest::Client { + reqwest::Client::builder() + .user_agent(super::USER_AGENT) + .timeout(Duration::from_secs(15)) + .build() + .unwrap() + } + + async fn probe(http: &reqwest::Client, label: String) { + let started = Instant::now(); + let outcome = tokio::time::timeout( + super::IMAGE_HOST_PROBE_TIMEOUT, + http.get(URL) + .header(reqwest::header::RANGE, "bytes=0-0") + .send(), + ) + .await; + let ms = started.elapsed().as_millis(); + match outcome { + Err(_) => println!("{label:<18} {ms:>6}ms DEAD — probe timeout elapsed"), + Ok(Err(err)) => println!("{label:<18} {ms:>6}ms DEAD — {}", chain(&err)), + Ok(Ok(resp)) => println!( + "{label:<18} {ms:>6}ms {} {:?} (server_error={})", + resp.status(), + resp.version(), + resp.status().is_server_error(), + ), + } + } + + println!("-- cold client per request (first TLS handshake every time)"); + for i in 0..4 { + probe(&client(), format!("cold #{i}")).await; + } + + println!("-- one warm client, sequential"); + let warm = client(); + for i in 0..4 { + probe(&warm, format!("warm #{i}")).await; + } + + println!("-- 12 concurrent on one client (an artist page's shape)"); + let burst = client(); + let mut tasks = Vec::new(); + for i in 0..12 { + let http = burst.clone(); + tasks.push(tokio::spawn( + async move { probe(&http, format!("burst #{i:<2}")).await }, + )); + } + for t in tasks { + t.await.unwrap(); + } + + // The suspect: the probe does not race the CDN, it races THIS APP. A + // cold artist page has several multi-megabyte hero candidates in flight + // on this same client while the one-byte probe is queued behind them. + println!("-- probing every 250ms while 8 full-size heroes download on the same client"); + let loaded = client(); + let bulk: Vec<&str> = vec![ + "https://assets.fanart.tv/fanart/acdc-4fcad35eb2643.jpg", + "https://assets.fanart.tv/fanart/acdc-5467b70af2ff0.jpg", + "https://assets.fanart.tv/fanart/acdc-4e19b4d51609c.jpg", + "https://assets.fanart.tv/fanart/acdc-54575601f4146.jpg", + "https://assets.fanart.tv/fanart/tame-impala-515a1f8fc9345.jpg", + "https://assets.fanart.tv/fanart/tame-impala-4fd09eab05fc1.jpg", + "https://assets.fanart.tv/fanart/fleetwood-mac-4e7ec8bebeba1.jpg", + "https://assets.fanart.tv/fanart/queen-4fc9a7ea0e0f0.jpg", + ]; + let mut downloads = Vec::new(); + for url in bulk { + let http = loaded.clone(); + downloads.push(tokio::spawn(async move { + let started = Instant::now(); + match http.get(url).send().await { + Ok(resp) => { + let bytes = resp.bytes().await.map(|b| b.len()).unwrap_or(0); + (bytes, started.elapsed().as_millis()) + } + Err(_) => (0, started.elapsed().as_millis()), + } + })); + } + for i in 0..16 { + probe(&loaded, format!("under-load #{i:<2}")).await; + tokio::time::sleep(Duration::from_millis(250)).await; + } + let mut total = 0; + for d in downloads { + let (bytes, ms) = d.await.unwrap(); + total += bytes; + print!("[{bytes}B in {ms}ms] "); + } + println!("\n {total} bytes of hero pulled alongside the probes"); + } + + /// A host that stalls once must not stay written off for + /// [`super::IMAGE_HOST_PROBE_TTL`]. + /// + /// This is the fanart.tv failure reduced to its mechanism: the first + /// request gets no answer inside the probe's 3-second budget (on the real + /// machine, a dead first resolver eating 1-3.6s of name resolution), while + /// the host itself is fine and answers the very next request instantly. + /// Before the confirming probe, that single sample cost five minutes of + /// every artist page falling back to a blown-up square portrait. + /// + /// Runs against a local socket, so it asserts the policy and never the + /// weather. + #[tokio::test(flavor = "multi_thread")] + async fn one_stalled_probe_does_not_write_off_a_host() { + use std::sync::atomic::{AtomicUsize, Ordering}; + use std::sync::Arc; + use std::time::Duration; + use tokio::io::{AsyncReadExt, AsyncWriteExt}; + + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await.unwrap(); + let port = listener.local_addr().unwrap().port(); + let seen = Arc::new(AtomicUsize::new(0)); + let served = seen.clone(); + tokio::spawn(async move { + loop { + let Ok((mut socket, _)) = listener.accept().await else { + return; + }; + let nth = served.fetch_add(1, Ordering::SeqCst); + tokio::spawn(async move { + let mut scratch = [0u8; 1024]; + let _ = socket.read(&mut scratch).await; + // Only the first caller is made to wait, and for longer + // than the fast probe will ever wait for it. + if nth == 0 { + tokio::time::sleep(Duration::from_secs(5)).await; + } + let _ = socket + .write_all( + b"HTTP/1.1 206 Partial Content\r\n\ + Content-Range: bytes 0-0/511115\r\n\ + Content-Length: 1\r\n\r\nX", + ) + .await; + }); + } + }); + + let client = super::MetadataClient::new(); + let url = format!("http://127.0.0.1:{port}/fanart/justice-4e1c8af0c25fc.jpg"); + + // The page still gets its fast answer and falls through to the next + // provider — that part is deliberately unchanged. + assert!( + !client.image_host_alive(&url).await, + "a host that misses the probe budget must not hold up the page", + ); + + // ...but the verdict is confirmed off the critical path, and the host + // comes back without waiting out the five-minute TTL. + let mut restored = false; + for _ in 0..40 { + tokio::time::sleep(Duration::from_millis(100)).await; + if client.image_host_alive(&url).await { + restored = true; + break; + } + } + assert!( + restored, + "the confirming probe answered, so the host must be usable again \ + long before {:?}", + super::IMAGE_HOST_PROBE_TTL, + ); + assert!( + seen.load(Ordering::SeqCst) >= 2, + "the confirmation has to actually ask the host a second time", + ); + } + /// The search page's listener bars, end to end against the live providers. /// /// Ignored by default — it spends real Deezer, MusicBrainz and Last.fm