From e24e0a647340702ddabf7aef84f65826b1bb072e Mon Sep 17 00:00:00 2001 From: archipelago Date: Mon, 27 Jul 2026 20:54:35 -0400 Subject: [PATCH] =?UTF-8?q?feat(fips):=20fallback=20telemetry=20=E2=80=94?= =?UTF-8?q?=20per-reason=20counters=20in=20fips.status=20+=20last-transpor?= =?UTF-8?q?t=20recording=20on=20all=20dial=20sites?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Phase A2 of docs/FIPS-UPTIME-AND-UI-STATE-PLAN.md (RC6). Fallbacks to Tor were debug!-only and uncounted, so "FIPS uptime" was unfalsifiable and paths that were 100% Tor by construction went unnoticed for months. - fips::telemetry: process-lifetime counters for FIPS successes and the six fallback reasons (no_npub, service_inactive, dns_fail, connect_fail, http_404, http_5xx), exposed as `dial_stats` in fips.status - dial.rs: every fallback branch now counts + logs at info! with a `reason` field (resolve/connect/status branches) - PeerRequest::record_transport(data_dir): opt-in hook that writes the transport actually used to federation storage off the hot path — wired into the dial sites that never recorded (DWN sync ×3, mesh blob fetch, federation deploy notify, onion-rotation notify, node messages via a new send_to_peer data-dir param) Co-Authored-By: Claude Fable 5 --- core/archipelago/src/api/rpc/bitcoin_relay.rs | 1 + .../src/api/rpc/federation/handlers.rs | 3 +- core/archipelago/src/api/rpc/fips.rs | 9 +- .../src/api/rpc/mesh/typed_messages.rs | 1 + core/archipelago/src/api/rpc/network.rs | 2 + core/archipelago/src/api/rpc/peers.rs | 1 + core/archipelago/src/api/rpc/tor/mod.rs | 3 +- core/archipelago/src/fips/dial.rs | 97 +++++++++++- core/archipelago/src/fips/mod.rs | 1 + core/archipelago/src/fips/telemetry.rs | 144 ++++++++++++++++++ core/archipelago/src/network/dwn_sync.rs | 5 + core/archipelago/src/node_message.rs | 11 +- 12 files changed, 267 insertions(+), 11 deletions(-) create mode 100644 core/archipelago/src/fips/telemetry.rs diff --git a/core/archipelago/src/api/rpc/bitcoin_relay.rs b/core/archipelago/src/api/rpc/bitcoin_relay.rs index 57a4b1cd..cf5876c7 100644 --- a/core/archipelago/src/api/rpc/bitcoin_relay.rs +++ b/core/archipelago/src/api/rpc/bitcoin_relay.rs @@ -465,6 +465,7 @@ impl RpcHandler { signing_key.as_ref().map(|i| i.signing_key()), Some(&peer.pubkey), data.server_info.name.as_deref(), + Some(&self.config.data_dir), ) .await } diff --git a/core/archipelago/src/api/rpc/federation/handlers.rs b/core/archipelago/src/api/rpc/federation/handlers.rs index 6b8f1bec..5e4679e8 100644 --- a/core/archipelago/src/api/rpc/federation/handlers.rs +++ b/core/archipelago/src/api/rpc/federation/handlers.rs @@ -866,7 +866,8 @@ impl RpcHandler { ) .service(crate::settings::transport::PeerService::Peers) .timeout(std::time::Duration::from_secs(30)) - .fips_timeout(std::time::Duration::from_secs(6)); + .fips_timeout(std::time::Duration::from_secs(6)) + .record_transport(&self.config.data_dir); match req.send_json(&body).await { Ok((resp, transport)) if resp.status().is_success() => { diff --git a/core/archipelago/src/api/rpc/fips.rs b/core/archipelago/src/api/rpc/fips.rs index e7f0574b..391759b7 100644 --- a/core/archipelago/src/api/rpc/fips.rs +++ b/core/archipelago/src/api/rpc/fips.rs @@ -13,7 +13,14 @@ use anyhow::Result; impl RpcHandler { pub(super) async fn handle_fips_status(&self) -> Result { let status = fips::FipsStatus::query(&self.config.data_dir).await; - Ok(serde_json::to_value(status)?) + let mut v = serde_json::to_value(status)?; + // Dial outcome counters (process-lifetime): how often peer dials + // used FIPS vs fell back to Tor, broken down by reason. This is + // the observability that makes "FIPS uptime" measurable. + if let Some(obj) = v.as_object_mut() { + obj.insert("dial_stats".to_string(), fips::telemetry::snapshot()); + } + Ok(v) } /// Everything the companion app needs to join this node's mesh, embedded diff --git a/core/archipelago/src/api/rpc/mesh/typed_messages.rs b/core/archipelago/src/api/rpc/mesh/typed_messages.rs index 12e9ac78..85577b07 100644 --- a/core/archipelago/src/api/rpc/mesh/typed_messages.rs +++ b/core/archipelago/src/api/rpc/mesh/typed_messages.rs @@ -821,6 +821,7 @@ impl RpcHandler { .service(crate::settings::transport::PeerService::MeshFileSharing) .timeout(std::time::Duration::from_secs(120)) .fips_timeout(std::time::Duration::from_secs(8)) + .record_transport(&self.config.data_dir) .send_get() .await .map_err(|e| anyhow::anyhow!("Fetch failed: {}", e))?; diff --git a/core/archipelago/src/api/rpc/network.rs b/core/archipelago/src/api/rpc/network.rs index abf5ec95..9755fed6 100644 --- a/core/archipelago/src/api/rpc/network.rs +++ b/core/archipelago/src/api/rpc/network.rs @@ -137,6 +137,7 @@ impl RpcHandler { None, None, None, + Some(&self.config.data_dir), ) .await?; @@ -225,6 +226,7 @@ impl RpcHandler { signing_key.as_ref().map(|i| i.signing_key()), Some(&req.from_pubkey), data.server_info.name.as_deref(), + Some(&self.config.data_dir), ) .await { diff --git a/core/archipelago/src/api/rpc/peers.rs b/core/archipelago/src/api/rpc/peers.rs index 6e0e6812..de71f850 100644 --- a/core/archipelago/src/api/rpc/peers.rs +++ b/core/archipelago/src/api/rpc/peers.rs @@ -133,6 +133,7 @@ impl RpcHandler { Some(node_id.signing_key()), recipient_pubkey.as_deref(), node_name.as_deref(), + Some(&self.config.data_dir), ) .await?; Ok(serde_json::json!({ "ok": true, "sent_to": onion })) diff --git a/core/archipelago/src/api/rpc/tor/mod.rs b/core/archipelago/src/api/rpc/tor/mod.rs index ca0bcb2e..c0882343 100644 --- a/core/archipelago/src/api/rpc/tor/mod.rs +++ b/core/archipelago/src/api/rpc/tor/mod.rs @@ -499,7 +499,8 @@ pub(super) async fn notify_federation_peers_address_change( ) .service(crate::settings::transport::PeerService::Peers) .timeout(std::time::Duration::from_secs(30)) - .fips_timeout(std::time::Duration::from_secs(6)); + .fips_timeout(std::time::Duration::from_secs(6)) + .record_transport(data_dir); match req.send_json(&payload).await { Ok((_, transport)) => { info!(peer_did = %peer.did, transport = %transport, "Notified peer of address change") diff --git a/core/archipelago/src/fips/dial.rs b/core/archipelago/src/fips/dial.rs index fd337a9c..64c22e80 100644 --- a/core/archipelago/src/fips/dial.rs +++ b/core/archipelago/src/fips/dial.rs @@ -24,6 +24,7 @@ //! ``` #![allow(dead_code)] +use super::telemetry::{self, FallbackReason}; use anyhow::{Context, Result}; use std::net::{IpAddr, Ipv6Addr}; use std::time::Duration; @@ -317,6 +318,11 @@ pub struct PeerRequest<'a> { /// large content download needs so its long FIPS transfer isn't truncated. pub fips_timeout: Option, pub service: Option, + /// When set, the transport that actually served this request is written + /// to federation storage (`record_peer_transport`, matched by onion) so + /// the per-peer FIPS/Tor badge reflects reality. Opt-in because not + /// every caller has a data dir in scope. + pub record_data_dir: Option, } impl<'a> PeerRequest<'a> { @@ -329,6 +335,31 @@ impl<'a> PeerRequest<'a> { timeout: std::time::Duration::from_secs(30), fips_timeout: None, service: None, + record_data_dir: None, + } + } + + /// Record the transport that serves this request into federation storage + /// (matched by this request's onion host). Best-effort, off the hot path. + pub fn record_transport(mut self, data_dir: impl Into) -> Self { + self.record_data_dir = Some(data_dir.into()); + self + } + + fn spawn_record(&self, kind: crate::transport::TransportKind) { + if let Some(dir) = &self.record_data_dir { + let dir = dir.clone(); + let onion = self.onion_host.to_string(); + let transport = kind.to_string(); + tokio::spawn(async move { + let _ = crate::federation::record_peer_transport( + &dir, + None, + Some(&onion), + &transport, + ) + .await; + }); } } @@ -389,8 +420,22 @@ impl<'a> PeerRequest<'a> { // fix (404 path-not-served / 5xx) and we're allowed to // fall back. FIPS-only never falls back. if pref == TransportPref::Fips || !fips_should_fall_back(resp.status()) { + telemetry::record_fips_ok(); + self.spawn_record(crate::transport::TransportKind::Fips); return Ok((resp, crate::transport::TransportKind::Fips)); } + let reason = if resp.status() == reqwest::StatusCode::NOT_FOUND { + FallbackReason::Http404 + } else { + FallbackReason::Http5xx + }; + telemetry::record_fallback(reason); + tracing::info!( + reason = reason.key(), + status = %resp.status(), + "FIPS POST {} answered but status triggers Tor fallback", + self.path + ); } None => { if pref == TransportPref::Fips { @@ -402,6 +447,7 @@ impl<'a> PeerRequest<'a> { } } let resp = self.send_tor_post_json(body).await?; + self.spawn_record(crate::transport::TransportKind::Tor); Ok((resp, crate::transport::TransportKind::Tor)) } @@ -413,8 +459,22 @@ impl<'a> PeerRequest<'a> { match self.try_fips_get().await? { Some(resp) => { if pref == TransportPref::Fips || !fips_should_fall_back(resp.status()) { + telemetry::record_fips_ok(); + self.spawn_record(crate::transport::TransportKind::Fips); return Ok((resp, crate::transport::TransportKind::Fips)); } + let reason = if resp.status() == reqwest::StatusCode::NOT_FOUND { + FallbackReason::Http404 + } else { + FallbackReason::Http5xx + }; + telemetry::record_fallback(reason); + tracing::info!( + reason = reason.key(), + status = %resp.status(), + "FIPS GET {} answered but status triggers Tor fallback", + self.path + ); } None => { if pref == TransportPref::Fips { @@ -426,6 +486,7 @@ impl<'a> PeerRequest<'a> { } } let resp = self.send_tor_get().await?; + self.spawn_record(crate::transport::TransportKind::Tor); Ok((resp, crate::transport::TransportKind::Tor)) } @@ -434,15 +495,23 @@ impl<'a> PeerRequest<'a> { body: &B, ) -> Result> { let Some(npub) = self.fips_npub else { + telemetry::record_fallback(FallbackReason::NoNpub); return Ok(None); }; if !is_service_active().await { + telemetry::record_fallback(FallbackReason::ServiceInactive); return Ok(None); } let base = match peer_base_url(npub).await { Ok(b) => b, Err(e) => { - tracing::debug!("FIPS resolve for {} failed: {}", npub, e); + telemetry::record_fallback(FallbackReason::DnsFail); + tracing::info!( + reason = FallbackReason::DnsFail.key(), + "FIPS resolve for {} failed: {}, falling back to Tor", + npub, + e + ); return Ok(None); } }; @@ -467,7 +536,9 @@ impl<'a> PeerRequest<'a> { match tokio::time::timeout(budget, send_with_retry(rb)).await { Ok(Ok(r)) => Ok(Some(r)), Ok(Err(e)) => { - tracing::debug!( + telemetry::record_fallback(FallbackReason::ConnectFail); + tracing::info!( + reason = FallbackReason::ConnectFail.key(), "FIPS POST {} failed after retry: {}, falling back to Tor", url, e @@ -475,7 +546,9 @@ impl<'a> PeerRequest<'a> { Ok(None) } Err(_) => { - tracing::debug!( + telemetry::record_fallback(FallbackReason::ConnectFail); + tracing::info!( + reason = FallbackReason::ConnectFail.key(), "FIPS POST {} exceeded attempt budget {:?}, falling back to Tor", url, budget @@ -487,15 +560,23 @@ impl<'a> PeerRequest<'a> { async fn try_fips_get(&self) -> Result> { let Some(npub) = self.fips_npub else { + telemetry::record_fallback(FallbackReason::NoNpub); return Ok(None); }; if !is_service_active().await { + telemetry::record_fallback(FallbackReason::ServiceInactive); return Ok(None); } let base = match peer_base_url(npub).await { Ok(b) => b, Err(e) => { - tracing::debug!("FIPS resolve for {} failed: {}", npub, e); + telemetry::record_fallback(FallbackReason::DnsFail); + tracing::info!( + reason = FallbackReason::DnsFail.key(), + "FIPS resolve for {} failed: {}, falling back to Tor", + npub, + e + ); return Ok(None); } }; @@ -516,7 +597,9 @@ impl<'a> PeerRequest<'a> { match tokio::time::timeout(budget, send_with_retry(rb)).await { Ok(Ok(r)) => Ok(Some(r)), Ok(Err(e)) => { - tracing::debug!( + telemetry::record_fallback(FallbackReason::ConnectFail); + tracing::info!( + reason = FallbackReason::ConnectFail.key(), "FIPS GET {} failed after retry: {}, falling back to Tor", url, e @@ -524,7 +607,9 @@ impl<'a> PeerRequest<'a> { Ok(None) } Err(_) => { - tracing::debug!( + telemetry::record_fallback(FallbackReason::ConnectFail); + tracing::info!( + reason = FallbackReason::ConnectFail.key(), "FIPS GET {} exceeded attempt budget {:?}, falling back to Tor", url, budget diff --git a/core/archipelago/src/fips/mod.rs b/core/archipelago/src/fips/mod.rs index d7f4c8ef..a717f917 100644 --- a/core/archipelago/src/fips/mod.rs +++ b/core/archipelago/src/fips/mod.rs @@ -31,6 +31,7 @@ pub mod config; pub mod dial; pub mod iface; pub mod service; +pub mod telemetry; pub mod update; use serde::{Deserialize, Serialize}; diff --git a/core/archipelago/src/fips/telemetry.rs b/core/archipelago/src/fips/telemetry.rs new file mode 100644 index 00000000..b0ab0a53 --- /dev/null +++ b/core/archipelago/src/fips/telemetry.rs @@ -0,0 +1,144 @@ +//! In-process counters for FIPS dial outcomes. +//! +//! Every peer dial that could have used FIPS either succeeds over FIPS or +//! falls back to Tor for one of six reasons (F1–F6). Before these counters +//! existed, fallbacks were `debug!`-only and invisible in production, which +//! made "FIPS uptime" unfalsifiable — several paths were 100% Tor for months +//! (dead ports, firewalled listeners, allowlist 404s) and nothing surfaced +//! it. The counters are process-lifetime (reset on restart) and exposed via +//! `fips.status` as `dial_stats`, so a fleet-wide fallback regression shows +//! up on the dashboard instead of as vague slowness. + +use std::sync::atomic::{AtomicU64, Ordering}; + +/// Why a FIPS-capable dial fell back to Tor. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum FallbackReason { + /// F1 — no FIPS npub known for the peer (never meshed, or pre-npub + /// federation record). Expected for non-FIPS peers; high counts here + /// mean npub propagation is broken, not the transport. + NoNpub, + /// F2 — the local FIPS daemon service isn't active. + ServiceInactive, + /// F3 — the local FIPS DNS resolver couldn't resolve the peer's npub + /// (daemon up but peer not in the identity cache / mesh unreachable). + DnsFail, + /// F4 — TCP/HTTP dial to the peer's ULA failed or exceeded the FIPS + /// attempt budget (firewalled :5679, cold hole-punch, peer down). + ConnectFail, + /// F5 — peer answered over FIPS with 404: its listener doesn't serve + /// this path (older build / stricter allowlist). + Http404, + /// F6 — peer answered over FIPS with a 5xx server error. + Http5xx, +} + +impl FallbackReason { + pub fn key(self) -> &'static str { + match self { + Self::NoNpub => "no_npub", + Self::ServiceInactive => "service_inactive", + Self::DnsFail => "dns_fail", + Self::ConnectFail => "connect_fail", + Self::Http404 => "http_404", + Self::Http5xx => "http_5xx", + } + } +} + +static FIPS_OK: AtomicU64 = AtomicU64::new(0); +static NO_NPUB: AtomicU64 = AtomicU64::new(0); +static SERVICE_INACTIVE: AtomicU64 = AtomicU64::new(0); +static DNS_FAIL: AtomicU64 = AtomicU64::new(0); +static CONNECT_FAIL: AtomicU64 = AtomicU64::new(0); +static HTTP_404: AtomicU64 = AtomicU64::new(0); +static HTTP_5XX: AtomicU64 = AtomicU64::new(0); + +fn counter(reason: FallbackReason) -> &'static AtomicU64 { + match reason { + FallbackReason::NoNpub => &NO_NPUB, + FallbackReason::ServiceInactive => &SERVICE_INACTIVE, + FallbackReason::DnsFail => &DNS_FAIL, + FallbackReason::ConnectFail => &CONNECT_FAIL, + FallbackReason::Http404 => &HTTP_404, + FallbackReason::Http5xx => &HTTP_5XX, + } +} + +/// A dial completed over FIPS (any HTTP status that wasn't a fallback +/// trigger — the peer was reached on the mesh). +pub fn record_fips_ok() { + FIPS_OK.fetch_add(1, Ordering::Relaxed); +} + +/// A FIPS-capable dial fell back to Tor. +pub fn record_fallback(reason: FallbackReason) { + counter(reason).fetch_add(1, Ordering::Relaxed); +} + +/// Snapshot for `fips.status` (`dial_stats`). Process-lifetime counts. +pub fn snapshot() -> serde_json::Value { + let f1 = NO_NPUB.load(Ordering::Relaxed); + let f2 = SERVICE_INACTIVE.load(Ordering::Relaxed); + let f3 = DNS_FAIL.load(Ordering::Relaxed); + let f4 = CONNECT_FAIL.load(Ordering::Relaxed); + let f5 = HTTP_404.load(Ordering::Relaxed); + let f6 = HTTP_5XX.load(Ordering::Relaxed); + serde_json::json!({ + "fips_ok": FIPS_OK.load(Ordering::Relaxed), + "fallbacks": { + "no_npub": f1, + "service_inactive": f2, + "dns_fail": f3, + "connect_fail": f4, + "http_404": f5, + "http_5xx": f6, + "total": f1 + f2 + f3 + f4 + f5 + f6, + }, + }) +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn snapshot_counts_recorded_events() { + // Counters are global; assert deltas rather than absolutes so this + // test stays correct alongside any other test that dials. + let before = snapshot(); + record_fips_ok(); + record_fallback(FallbackReason::ConnectFail); + record_fallback(FallbackReason::Http404); + let after = snapshot(); + let d = |v: &serde_json::Value, path: &[&str]| -> u64 { + let mut cur = v; + for p in path { + cur = &cur[p]; + } + cur.as_u64().unwrap() + }; + assert_eq!(d(&after, &["fips_ok"]) - d(&before, &["fips_ok"]), 1); + assert_eq!( + d(&after, &["fallbacks", "connect_fail"]) - d(&before, &["fallbacks", "connect_fail"]), + 1 + ); + assert_eq!( + d(&after, &["fallbacks", "http_404"]) - d(&before, &["fallbacks", "http_404"]), + 1 + ); + assert!(d(&after, &["fallbacks", "total"]) >= 2); + } + + #[test] + fn reason_keys_are_stable() { + // These strings are the fips.status API surface — renaming one is a + // breaking change for the UI. + assert_eq!(FallbackReason::NoNpub.key(), "no_npub"); + assert_eq!(FallbackReason::ServiceInactive.key(), "service_inactive"); + assert_eq!(FallbackReason::DnsFail.key(), "dns_fail"); + assert_eq!(FallbackReason::ConnectFail.key(), "connect_fail"); + assert_eq!(FallbackReason::Http404.key(), "http_404"); + assert_eq!(FallbackReason::Http5xx.key(), "http_5xx"); + } +} diff --git a/core/archipelago/src/network/dwn_sync.rs b/core/archipelago/src/network/dwn_sync.rs index 5a140351..1ce68351 100644 --- a/core/archipelago/src/network/dwn_sync.rs +++ b/core/archipelago/src/network/dwn_sync.rs @@ -134,6 +134,7 @@ pub async fn sync_with_peers(data_dir: &Path, peer_onions: &[String]) -> Result< for onion in &unique_onions { let fips_npub = crate::federation::fips_npub_for_onion(data_dir, onion).await; match sync_single_peer( + data_dir, fips_npub.as_deref(), &store, onion, @@ -173,6 +174,7 @@ pub async fn sync_with_peers(data_dir: &Path, peer_onions: &[String]) -> Result< /// Sync with a single peer: pull their messages and push ours. /// Each HTTP call picks FIPS when a npub is known, otherwise Tor. async fn sync_single_peer( + data_dir: &Path, fips_npub: Option<&str>, store: &crate::network::dwn_store::DwnStore, onion: &str, @@ -187,6 +189,7 @@ async fn sync_single_peer( .service(crate::settings::transport::PeerService::Federation) .timeout(std::time::Duration::from_secs(30)) .fips_timeout(std::time::Duration::from_secs(6)) + .record_transport(data_dir) .send_get() .await .context("Peer DWN unreachable")?; @@ -213,6 +216,7 @@ async fn sync_single_peer( .service(crate::settings::transport::PeerService::Federation) .timeout(std::time::Duration::from_secs(30)) .fips_timeout(std::time::Duration::from_secs(6)) + .record_transport(data_dir) .send_json(&pull_body) .await .context("Failed to query peer DWN")?; @@ -272,6 +276,7 @@ async fn sync_single_peer( .service(crate::settings::transport::PeerService::Federation) .timeout(std::time::Duration::from_secs(30)) .fips_timeout(std::time::Duration::from_secs(6)) + .record_transport(data_dir) .send_json(&push_body) .await { diff --git a/core/archipelago/src/node_message.rs b/core/archipelago/src/node_message.rs index 2b2ed27f..d72ec3d4 100644 --- a/core/archipelago/src/node_message.rs +++ b/core/archipelago/src/node_message.rs @@ -342,6 +342,9 @@ pub async fn send_to_peer( signing_key: Option<&ed25519_dalek::SigningKey>, recipient_pubkey: Option<&str>, from_name: Option<&str>, + // Federation data dir for last-transport recording; None skips recording + // (callers without a data dir in scope). + record_data_dir: Option<&std::path::Path>, ) -> Result<()> { validate_onion(onion)?; @@ -370,11 +373,15 @@ pub async fn send_to_peer( body["from_name"] = serde_json::Value::String(name.to_string()); } - let (resp, transport) = + let mut req = crate::fips::dial::PeerRequest::new(fips_npub, onion, "/archipelago/node-message") .service(crate::settings::transport::PeerService::Messaging) .timeout(std::time::Duration::from_secs(60)) - .fips_timeout(std::time::Duration::from_secs(8)) + .fips_timeout(std::time::Duration::from_secs(8)); + if let Some(dir) = record_data_dir { + req = req.record_transport(dir); + } + let (resp, transport) = req .send_json(&body) .await .map_err(|e| {