forked from Keelrleek/SoulStream
metadata: a lost probe race no longer writes an image host off for five minutes
The image-host liveness probe has a 3-second budget so a page never waits on it — but losing that race was recorded as "the host is down" and cached for the full five-minute TTL, turning one bad sample into square portraits on every artist page in the window. Measured on the machine that reported it: all 213 cached assets.fanart.tv urls answered in ~130ms while the machine's own first DNS resolver ate 1-3.6s of the budget before a byte was sent — and the A record's TTL is 300s, exactly the probe TTL, so every probe replayed that lottery on an expired name. The fast verdict still stands for the page that paid for it — it falls through to the next provider immediately, as before — but a background confirmation with a 12-second budget now decides whether the verdict persists, and the warning reports what was measured (timeout, transport error chain, or 5xx) instead of asserting an outage it cannot see. A regression test stalls a local socket exactly once and proves the host comes back without waiting out the TTL; the fanart_probe_live harness prints the reqwest error chain four ways for the next time a provider is suspected on this machine.
This commit is contained in:
KeelrLeek committed
1 parent
9aeb6c39c7
commit
3aaec30dc6
1 file changed
+340
-17
+340
-17
@@ -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<Mutex<HashMap<String, (bool, Instant)>>> =
|
||||
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<Mutex<HashMap<String, (bool, Instant)>>> =
|
||||
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
|
||||
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
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// 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<Mutex<HashSet<String>>> = 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
|
||||
.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");
|
||||
.insert(host.clone(), (true, Instant::now()));
|
||||
}
|
||||
health.lock().await.insert(host, (alive, Instant::now()));
|
||||
alive
|
||||
} 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
|
||||
|
||||
Reference in new issue
Block a user