mirror of
https://github.com/rustfs/rustfs.git
synced 2026-09-07 20:46:11 +00:00
feat(observability): diagnose node-local S3 write failures (#7407)
This commit is contained in:
@@ -54,6 +54,9 @@ pub type BucketConfigPublishHook = Box<dyn Fn(&str, &str, Option<(&[u8], OffsetD
|
||||
pub static BUCKET_CONFIG_PUBLISH_HOOK: std::sync::OnceLock<BucketConfigPublishHook> = std::sync::OnceLock::new();
|
||||
|
||||
const BUCKET_METADATA_REFRESH_INTERVAL: Duration = Duration::from_secs(15 * 60);
|
||||
const LOG_COMPONENT_ECSTORE: &str = "ecstore";
|
||||
const LOG_SUBSYSTEM_BUCKET_METADATA: &str = "bucket_metadata";
|
||||
const EVENT_BUCKET_METADATA_LOAD_FAILED: &str = "bucket_metadata_load_failed";
|
||||
|
||||
#[cfg(any(test, feature = "test-util"))]
|
||||
struct ConfigWriteLockProbeState {
|
||||
@@ -1614,13 +1617,20 @@ impl BucketMetadataSys {
|
||||
|
||||
let results = join_all(futures).await;
|
||||
|
||||
for (idx, res) in results.into_iter().enumerate() {
|
||||
for (bucket, res) in buckets.iter().zip(results) {
|
||||
match res {
|
||||
Ok(()) => {}
|
||||
Err(e) => {
|
||||
error!("Unable to load bucket metadata, will be retried: {:?}", e);
|
||||
if let Some(bucket) = buckets.get(idx) {
|
||||
failed_buckets.insert(bucket.clone());
|
||||
if failed_buckets.insert(bucket.clone()) {
|
||||
error!(
|
||||
event = EVENT_BUCKET_METADATA_LOAD_FAILED,
|
||||
component = LOG_COMPONENT_ECSTORE,
|
||||
subsystem = LOG_SUBSYSTEM_BUCKET_METADATA,
|
||||
result = "retry_pending",
|
||||
bucket = %bucket,
|
||||
error_code = ?e.code(),
|
||||
"Unable to load bucket metadata; retry scheduled"
|
||||
);
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -1647,12 +1657,19 @@ impl BucketMetadataSys {
|
||||
});
|
||||
}
|
||||
let results = join_all(futures).await;
|
||||
for (idx, result) in results.into_iter().enumerate() {
|
||||
if let Err(err) = result {
|
||||
error!("Unable to load bucket metadata, will be retried: {:?}", err);
|
||||
if let Some(bucket) = buckets.get(idx) {
|
||||
failed_buckets.insert(bucket.clone());
|
||||
}
|
||||
for (bucket, result) in buckets.iter().zip(results) {
|
||||
if let Err(err) = result
|
||||
&& failed_buckets.insert(bucket.clone())
|
||||
{
|
||||
error!(
|
||||
event = EVENT_BUCKET_METADATA_LOAD_FAILED,
|
||||
component = LOG_COMPONENT_ECSTORE,
|
||||
subsystem = LOG_SUBSYSTEM_BUCKET_METADATA,
|
||||
result = "retry_pending",
|
||||
bucket = %bucket,
|
||||
error_code = ?err.code(),
|
||||
"Unable to load bucket metadata; retry scheduled"
|
||||
);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -39,6 +39,7 @@ mod capacity_dedup_tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: disks.clone(),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
let total = get_total_usable_capacity(&disks, &info);
|
||||
@@ -73,6 +74,7 @@ mod capacity_dedup_tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: disks.clone(),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
let total = get_total_usable_capacity(&disks, &info);
|
||||
@@ -150,6 +152,7 @@ mod capacity_dedup_tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: disks.clone(),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
let total = get_total_usable_capacity(&disks, &info);
|
||||
|
||||
@@ -759,7 +759,8 @@ impl Clone for StorageError {
|
||||
}
|
||||
|
||||
impl StorageError {
|
||||
fn code(&self) -> StorageErrorCode {
|
||||
/// Stable classification without error payloads or storage paths.
|
||||
pub fn code(&self) -> StorageErrorCode {
|
||||
match self {
|
||||
StorageError::Io(_) => StorageErrorCode::Io,
|
||||
StorageError::FaultyDisk => StorageErrorCode::FaultyDisk,
|
||||
|
||||
@@ -20,9 +20,10 @@ use chrono::Utc;
|
||||
use jiff::Timestamp;
|
||||
use rustfs_heal_contracts::heal_channel::DriveState;
|
||||
use rustfs_io_metrics::internode_metrics::global_internode_metrics;
|
||||
use rustfs_io_metrics::s3_http_metrics::s3_http_metrics_snapshot;
|
||||
use rustfs_madmin::metrics::{
|
||||
DiskIOStats, DiskMetric, LastMinute as MadminLastMinute, NetDevLine, NetMetrics, RPCMetrics, RealtimeMetrics,
|
||||
ScannerCheckpointReport as MadminScannerCheckpointReport,
|
||||
DiskIOStats, DiskMetric, HttpMetrics, HttpRequestMetric, LastMinute as MadminLastMinute, NetDevLine, NetMetrics, RPCMetrics,
|
||||
RealtimeMetrics, ScannerCheckpointReport as MadminScannerCheckpointReport,
|
||||
ScannerLifecycleExpirySnapshot as MadminScannerLifecycleExpirySnapshot,
|
||||
ScannerLifecycleTransitionSnapshot as MadminScannerLifecycleTransitionSnapshot,
|
||||
ScannerMaintenanceControlSnapshot as MadminScannerMaintenanceControlSnapshot,
|
||||
@@ -61,9 +62,10 @@ impl MetricType {
|
||||
pub const MEM: MetricType = MetricType(1 << 6);
|
||||
pub const CPU: MetricType = MetricType(1 << 7);
|
||||
pub const RPC: MetricType = MetricType(1 << 8);
|
||||
pub const HTTP: MetricType = MetricType(1 << 9);
|
||||
|
||||
// MetricsAll must be last.
|
||||
pub const ALL: MetricType = MetricType((1 << 9) - 1);
|
||||
pub const ALL: MetricType = MetricType((1 << 10) - 1);
|
||||
|
||||
pub fn new(t: u32) -> Self {
|
||||
Self(t)
|
||||
@@ -410,6 +412,21 @@ pub async fn collect_local_metrics(types: MetricType, opts: &CollectMetricsOpts)
|
||||
by_host_name = local_node_name;
|
||||
}
|
||||
|
||||
if types.contains(&MetricType::HTTP) {
|
||||
real_time_metrics.aggregated.http = Some(HttpMetrics {
|
||||
collected_at: Timestamp::now(),
|
||||
requests: s3_http_metrics_snapshot()
|
||||
.into_iter()
|
||||
.map(|series| HttpRequestMetric {
|
||||
method: series.method.to_string(),
|
||||
operation: series.operation.to_string(),
|
||||
outcome: series.outcome.to_string(),
|
||||
total: series.total,
|
||||
})
|
||||
.collect(),
|
||||
});
|
||||
}
|
||||
|
||||
if types.contains(&MetricType::DISK) {
|
||||
debug!("start get disk metrics");
|
||||
let mut aggr = DiskMetric {
|
||||
@@ -585,11 +602,47 @@ mod test {
|
||||
assert!(t.contains(&MetricType::MEM));
|
||||
assert!(t.contains(&MetricType::CPU));
|
||||
assert!(t.contains(&MetricType::RPC));
|
||||
assert!(t.contains(&MetricType::HTTP));
|
||||
|
||||
let disk = MetricType::new(1 << 1);
|
||||
assert!(disk.contains(&MetricType::DISK));
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn collect_local_metrics_reports_the_same_http_outcome_counters() {
|
||||
let mut request = rustfs_io_metrics::s3_http_metrics::S3HttpRequestGuard::new("PUT");
|
||||
request.response(503);
|
||||
drop(request);
|
||||
let snapshot = s3_http_metrics_snapshot();
|
||||
let realtime = collect_local_metrics(MetricType::HTTP, &CollectMetricsOpts::default()).await;
|
||||
let http = realtime.aggregated.http.as_ref().expect("HTTP selection must report support");
|
||||
assert_eq!(http.requests.len(), snapshot.len());
|
||||
for (actual, expected) in http.requests.iter().zip(&snapshot) {
|
||||
assert_eq!(actual.method, expected.method);
|
||||
assert_eq!(actual.operation, expected.operation);
|
||||
assert_eq!(actual.outcome, expected.outcome);
|
||||
assert_eq!(actual.total, expected.total);
|
||||
}
|
||||
assert_eq!(realtime.by_host.len(), 1);
|
||||
assert_eq!(
|
||||
realtime
|
||||
.by_host
|
||||
.values()
|
||||
.next()
|
||||
.expect("local host")
|
||||
.http
|
||||
.as_ref()
|
||||
.expect("host HTTP")
|
||||
.requests,
|
||||
http.requests
|
||||
);
|
||||
let encoded = rmp_serde::to_vec_named(&realtime).expect("RPC metric map");
|
||||
let decoded: RealtimeMetrics = rmp_serde::from_slice(&encoded).expect("RPC metric roundtrip");
|
||||
assert_eq!(decoded.aggregated.http.expect("HTTP field survives RPC").requests, http.requests);
|
||||
let excluded = collect_local_metrics(MetricType::NET, &CollectMetricsOpts::default()).await;
|
||||
assert!(excluded.aggregated.http.is_none());
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn collect_local_metrics_reports_internode_net_and_rpc() {
|
||||
let metrics = global_internode_metrics();
|
||||
|
||||
@@ -31,7 +31,7 @@ use lazy_static::lazy_static;
|
||||
use rustfs_madmin::health::{Cpus, MemInfo, OsInfo, Partitions, ProcInfo, SysConfig, SysErrors, SysServices};
|
||||
use rustfs_madmin::metrics::RealtimeMetrics;
|
||||
use rustfs_madmin::net::NetInfo;
|
||||
use rustfs_madmin::{ItemState, ServerProperties, StorageInfo};
|
||||
use rustfs_madmin::{ItemState, ServerProperties, StorageInfo, StorageInfoObservation, StorageInfoProbeStatus};
|
||||
use rustfs_utils::XHost;
|
||||
use sha2::{Digest, Sha256};
|
||||
use std::collections::{BTreeMap, BTreeSet, HashMap, hash_map::DefaultHasher};
|
||||
@@ -53,6 +53,7 @@ const LOG_COMPONENT_ECSTORE: &str = "ecstore";
|
||||
const LOG_SUBSYSTEM_NOTIFICATION: &str = "notification";
|
||||
const EVENT_NOTIFICATION_PEER_PROPAGATION: &str = "notification_peer_propagation";
|
||||
const EVENT_NOTIFICATION_CAPABILITY_PROBE: &str = "notification_capability_probe";
|
||||
const EVENT_STORAGE_INFO_PROBE: &str = "storage_info_probe";
|
||||
const SCANNER_ACTIVITY_PROBE_TIMEOUT: Duration = Duration::from_secs(5);
|
||||
const TIER_DAILY_STATS_PROBE_TIMEOUT: Duration = Duration::from_secs(5);
|
||||
const TIER_CONFIG_RELOAD_RETRY_BASE: Duration = Duration::from_millis(100);
|
||||
@@ -140,6 +141,8 @@ pub struct ScannerPublicationLeaseGrant {
|
||||
/// Cached result from the last successful admin call to a peer.
|
||||
struct PeerAdminCache {
|
||||
last_storage_info: Option<StorageInfo>,
|
||||
/// Wall time is for operators; the monotonic clock bounds cache reuse.
|
||||
last_storage_success: Option<(SystemTime, Instant)>,
|
||||
last_server_info: Option<ServerProperties>,
|
||||
storage_failures: u32,
|
||||
server_failures: u32,
|
||||
@@ -163,6 +166,7 @@ impl PeerAdminCache {
|
||||
fn new() -> Self {
|
||||
Self {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: None,
|
||||
storage_failures: 0,
|
||||
server_failures: 0,
|
||||
@@ -175,6 +179,9 @@ impl PeerAdminCache {
|
||||
/// failure: rather than reporting a stale `online`, the member falls through to
|
||||
/// the live unknown/degraded/offline classification (rustfs/backlog#1049 P2).
|
||||
const SERVER_INFO_CACHE_MAX_AGE: Duration = Duration::from_secs(60);
|
||||
// Diagnostic inventory may bridge a short probe interruption, but never more
|
||||
// than one minute. Failed probes are marked unknown even within this budget.
|
||||
const STORAGE_INFO_CACHE_MAX_AGE: Duration = Duration::from_secs(60);
|
||||
|
||||
lazy_static! {
|
||||
pub static ref GLOBAL_NOTIFICATION_SYS: OnceLock<Arc<NotificationSys>> = OnceLock::new();
|
||||
@@ -1906,6 +1913,7 @@ impl NotificationSys {
|
||||
for (idx, client) in self.peer_clients.iter().enumerate() {
|
||||
let endpoints = endpoints.clone();
|
||||
let cache = self.peer_admin_caches.get(idx);
|
||||
let topology_host = self.peer_topology_hosts.get(idx);
|
||||
futures.push(async move {
|
||||
if let Some(client) = client {
|
||||
let host = client.host.to_string();
|
||||
@@ -1916,32 +1924,46 @@ impl NotificationSys {
|
||||
normalize_and_cache_peer_storage_info(cache, &host, &mut info);
|
||||
Some(info)
|
||||
}
|
||||
Ok(Err(err)) => {
|
||||
warn!("peer {} storage_info failed: {}", host, err);
|
||||
handle_peer_failure(cache, &host, &endpoints)
|
||||
}
|
||||
Err(_) => {
|
||||
warn!("peer {} storage_info timed out after {:?}", host, peer_timeout);
|
||||
handle_peer_failure(cache, &host, &endpoints)
|
||||
}
|
||||
Ok(Err(err)) => handle_peer_failure(cache, &host, &endpoints, &err),
|
||||
Err(_) => handle_peer_failure(cache, &host, &endpoints, &Error::Timeout),
|
||||
}
|
||||
} else {
|
||||
None
|
||||
topology_host.and_then(|host| {
|
||||
handle_peer_failure(
|
||||
cache,
|
||||
host,
|
||||
&endpoints,
|
||||
&Error::RemoteClientUnavailable("storage inventory client is unavailable".to_string()),
|
||||
)
|
||||
})
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
let mut replies = join_all(futures).await;
|
||||
|
||||
replies.push(Some(StorageAdminApi::local_storage_info(api).await));
|
||||
let mut local = StorageAdminApi::local_storage_info(api).await;
|
||||
local.observations = vec![storage_info_observation(
|
||||
&runtime_sources::local_node_name().await,
|
||||
StorageInfoProbeStatus::Succeeded,
|
||||
false,
|
||||
Some((SystemTime::now(), Instant::now())),
|
||||
)];
|
||||
replies.push(Some(local));
|
||||
|
||||
let mut disks = Vec::new();
|
||||
let mut observations = Vec::new();
|
||||
for info in replies.into_iter().flatten() {
|
||||
disks.extend(info.disks);
|
||||
observations.extend(info.observations);
|
||||
}
|
||||
|
||||
let backend = StorageAdminApi::backend_info(api).await;
|
||||
rustfs_madmin::StorageInfo { disks, backend }
|
||||
rustfs_madmin::StorageInfo {
|
||||
disks,
|
||||
backend,
|
||||
observations,
|
||||
}
|
||||
}
|
||||
|
||||
pub async fn server_info(&self) -> Vec<ServerProperties> {
|
||||
@@ -3339,56 +3361,80 @@ where
|
||||
}
|
||||
}
|
||||
|
||||
/// Handle a peer failure for storage_info: return cached data if available,
|
||||
/// or mark offline only after consecutive failures exceed the threshold.
|
||||
fn storage_info_observation(
|
||||
host: &str,
|
||||
status: StorageInfoProbeStatus,
|
||||
cached: bool,
|
||||
last_success: Option<(SystemTime, Instant)>,
|
||||
) -> StorageInfoObservation {
|
||||
StorageInfoObservation {
|
||||
endpoint: host.to_string(),
|
||||
status,
|
||||
cached,
|
||||
last_success_unix_millis: last_success
|
||||
.and_then(|(wall, _)| wall.duration_since(SystemTime::UNIX_EPOCH).ok())
|
||||
.and_then(|age| u64::try_from(age.as_millis()).ok()),
|
||||
snapshot_age_seconds: last_success.map(|(_, monotonic)| monotonic.elapsed().as_secs()),
|
||||
error_code: None,
|
||||
}
|
||||
}
|
||||
|
||||
/// An admin RPC failure is missing evidence, not evidence of failed drives.
|
||||
/// Preserve bounded historical inventory without presenting its states as live.
|
||||
fn handle_peer_failure(
|
||||
cache: Option<&Mutex<PeerAdminCache>>,
|
||||
host: &str,
|
||||
endpoints: &EndpointServerPools,
|
||||
error: &Error,
|
||||
) -> Option<StorageInfo> {
|
||||
let cache = cache?;
|
||||
|
||||
let mut c = match cache.lock() {
|
||||
Ok(cache) => cache,
|
||||
Err(poisoned) => {
|
||||
warn!("peer {host} storage_info cache mutex poisoned");
|
||||
poisoned.into_inner()
|
||||
}
|
||||
};
|
||||
c.storage_failures += 1;
|
||||
|
||||
if let Some(ref cached) = c.last_storage_info
|
||||
&& c.storage_failures < CONSECUTIVE_FAILURE_THRESHOLD
|
||||
{
|
||||
debug!(
|
||||
event = "peer_probe_failure",
|
||||
peer = host,
|
||||
probe = "storage_info",
|
||||
consecutive_failures = c.storage_failures,
|
||||
threshold = CONSECUTIVE_FAILURE_THRESHOLD,
|
||||
"peer storage_info probe failed; returning cached state until the offline threshold is reached"
|
||||
);
|
||||
return Some(cached.clone());
|
||||
}
|
||||
|
||||
if c.storage_failures >= CONSECUTIVE_FAILURE_THRESHOLD {
|
||||
if c.storage_failures == CONSECUTIVE_FAILURE_THRESHOLD {
|
||||
let mut cache = cache.map(|cache| cache.lock().unwrap_or_else(|poisoned| poisoned.into_inner()));
|
||||
let last_success = cache.as_ref().and_then(|cache| cache.last_storage_success);
|
||||
let historical = cache
|
||||
.as_ref()
|
||||
.filter(|_| last_success.is_some_and(|(_, when)| when.elapsed() < STORAGE_INFO_CACHE_MAX_AGE))
|
||||
.and_then(|cache| cache.last_storage_info.clone());
|
||||
let cached = historical.is_some();
|
||||
let mut info = historical.unwrap_or_else(|| StorageInfo {
|
||||
disks: synthesized_disks(host, endpoints, ItemState::Unknown),
|
||||
..Default::default()
|
||||
});
|
||||
if let Some(cache) = &mut cache {
|
||||
cache.storage_failures = cache.storage_failures.saturating_add(1);
|
||||
if cache.storage_failures == 1 {
|
||||
warn!(
|
||||
event = "peer_marked_offline",
|
||||
event = EVENT_STORAGE_INFO_PROBE,
|
||||
component = LOG_COMPONENT_ECSTORE,
|
||||
subsystem = LOG_SUBSYSTEM_NOTIFICATION,
|
||||
state = "failed",
|
||||
peer = host,
|
||||
probe = "storage_info",
|
||||
consecutive_failures = c.storage_failures,
|
||||
threshold = CONSECUTIVE_FAILURE_THRESHOLD,
|
||||
"reporting peer disks offline after consecutive storage_info failures"
|
||||
error_code = ?error.code(),
|
||||
cached,
|
||||
"Storage inventory probe failed; current drive health is unknown"
|
||||
);
|
||||
}
|
||||
return Some(StorageInfo {
|
||||
disks: synthesized_disks(host, endpoints, ItemState::Offline),
|
||||
..Default::default()
|
||||
});
|
||||
}
|
||||
|
||||
None
|
||||
for disk in &mut info.disks {
|
||||
disk.state = rustfs_madmin::ITEM_UNKNOWN.to_string();
|
||||
disk.runtime_state = Some(rustfs_madmin::ITEM_UNKNOWN.to_string());
|
||||
disk.offline_duration_seconds = None;
|
||||
disk.capacity_observation_source = Some(if cached { "snapshot" } else { "missing" }.to_string());
|
||||
disk.capacity_observation_age_seconds = if cached {
|
||||
disk.capacity_observation_age_seconds
|
||||
.zip(last_success)
|
||||
.map(|(age, (_, when))| age.saturating_add(when.elapsed().as_secs()))
|
||||
} else {
|
||||
None
|
||||
};
|
||||
disk.local = false;
|
||||
}
|
||||
info.observations = vec![storage_info_observation(
|
||||
host,
|
||||
StorageInfoProbeStatus::Failed,
|
||||
cached,
|
||||
last_success,
|
||||
)];
|
||||
info.observations[0].error_code = Some(format!("{:?}", error.code()));
|
||||
Some(info)
|
||||
}
|
||||
|
||||
fn normalize_and_cache_peer_storage_info(cache: Option<&Mutex<PeerAdminCache>>, host: &str, info: &mut StorageInfo) {
|
||||
@@ -3397,6 +3443,15 @@ fn normalize_and_cache_peer_storage_info(cache: Option<&Mutex<PeerAdminCache>>,
|
||||
for disk in &mut info.disks {
|
||||
disk.local = false;
|
||||
}
|
||||
let last_success = (SystemTime::now(), Instant::now());
|
||||
// The aggregator owns probe provenance, including when an older peer
|
||||
// returns no observation or a peer sends its own observation fields.
|
||||
info.observations = vec![storage_info_observation(
|
||||
host,
|
||||
StorageInfoProbeStatus::Succeeded,
|
||||
false,
|
||||
Some(last_success),
|
||||
)];
|
||||
|
||||
let Some(cache) = cache else {
|
||||
return;
|
||||
@@ -3409,16 +3464,20 @@ fn normalize_and_cache_peer_storage_info(cache: Option<&Mutex<PeerAdminCache>>,
|
||||
poisoned.into_inner()
|
||||
}
|
||||
};
|
||||
if c.storage_failures >= CONSECUTIVE_FAILURE_THRESHOLD {
|
||||
if c.storage_failures > 0 {
|
||||
info!(
|
||||
event = "peer_recovered_online",
|
||||
event = EVENT_STORAGE_INFO_PROBE,
|
||||
component = LOG_COMPONENT_ECSTORE,
|
||||
subsystem = LOG_SUBSYSTEM_NOTIFICATION,
|
||||
state = "succeeded",
|
||||
peer = host,
|
||||
probe = "storage_info",
|
||||
consecutive_failures = c.storage_failures,
|
||||
"peer storage_info probe succeeded again; peer disks reported online"
|
||||
"Storage inventory probe recovered"
|
||||
);
|
||||
}
|
||||
c.last_storage_info = Some(info.clone());
|
||||
c.last_storage_success = Some(last_success);
|
||||
c.storage_failures = 0;
|
||||
}
|
||||
|
||||
@@ -4892,6 +4951,7 @@ mod tests {
|
||||
server_failures: 1,
|
||||
storage_failures: 0,
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
});
|
||||
let cache_b = Mutex::new(PeerAdminCache {
|
||||
last_server_info: Some(build_props("cached-b")),
|
||||
@@ -4899,6 +4959,7 @@ mod tests {
|
||||
server_failures: 1,
|
||||
storage_failures: 0,
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
});
|
||||
let caches = [cache_a, cache_b];
|
||||
let endpoints = EndpointServerPools::from(Vec::new());
|
||||
@@ -5297,13 +5358,78 @@ mod tests {
|
||||
|
||||
// --- Tests for handle_peer_failure / handle_server_info_failure caching ---
|
||||
|
||||
#[tokio::test]
|
||||
async fn storage_info_preserves_failed_members_when_no_rpc_client_exists() {
|
||||
#[derive(Debug)]
|
||||
struct LocalInventory;
|
||||
|
||||
#[async_trait::async_trait]
|
||||
impl StorageAdminApi for LocalInventory {
|
||||
type BackendInfo = rustfs_madmin::BackendInfo;
|
||||
type StorageInfo = StorageInfo;
|
||||
type Disk = ();
|
||||
type Error = Error;
|
||||
|
||||
async fn backend_info(&self) -> Self::BackendInfo {
|
||||
Self::BackendInfo::default()
|
||||
}
|
||||
|
||||
async fn storage_info(&self) -> StorageInfo {
|
||||
panic!("aggregation must query local inventory only")
|
||||
}
|
||||
|
||||
async fn local_storage_info(&self) -> StorageInfo {
|
||||
StorageInfo::default()
|
||||
}
|
||||
|
||||
async fn disk_set_inventory(
|
||||
&self,
|
||||
_: crate::storage_api_contracts::admin::DiskSetSelector,
|
||||
) -> Result<Vec<Option<Self::Disk>>> {
|
||||
panic!("admin probe must not access the data plane")
|
||||
}
|
||||
|
||||
fn set_drive_counts(&self) -> Vec<usize> {
|
||||
Vec::new()
|
||||
}
|
||||
}
|
||||
|
||||
let sys = NotificationSys {
|
||||
peer_clients: vec![None],
|
||||
all_peer_clients: vec![None, None],
|
||||
peer_topology_hosts: vec!["peer-unavailable".to_string()],
|
||||
peer_admin_caches: vec![Mutex::new(PeerAdminCache::new())],
|
||||
tier_config_reload_workers: Default::default(),
|
||||
};
|
||||
let info = sys.storage_info(&LocalInventory).await;
|
||||
let peer = info
|
||||
.observations
|
||||
.iter()
|
||||
.find(|observation| observation.endpoint == "peer-unavailable")
|
||||
.expect("failed topology member remains visible");
|
||||
assert_eq!(peer.status, StorageInfoProbeStatus::Failed);
|
||||
assert!(!peer.cached);
|
||||
assert_eq!(peer.error_code.as_deref(), Some("RemoteClientUnavailable"));
|
||||
assert!(
|
||||
info.observations
|
||||
.iter()
|
||||
.any(|observation| observation.status == StorageInfoProbeStatus::Succeeded)
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn handle_peer_failure_first_failure_returns_none_when_no_cache() {
|
||||
fn handle_peer_failure_first_failure_reports_unknown_inventory_without_cache() {
|
||||
let cache = Mutex::new(PeerAdminCache::new());
|
||||
let endpoints = EndpointServerPools::default();
|
||||
|
||||
let result = handle_peer_failure(Some(&cache), "peer-1", &endpoints);
|
||||
assert!(result.is_none());
|
||||
let result = handle_peer_failure(Some(&cache), "peer-1", &endpoints, &Error::Timeout);
|
||||
let info = result.expect("failed peer must remain visible without cached disks");
|
||||
assert!(info.disks.is_empty());
|
||||
assert_eq!(info.observations[0].status, StorageInfoProbeStatus::Failed);
|
||||
assert!(!info.observations[0].cached);
|
||||
assert_eq!(info.observations[0].last_success_unix_millis, None);
|
||||
assert_eq!(info.observations[0].snapshot_age_seconds, None);
|
||||
assert_eq!(info.observations[0].error_code.as_deref(), Some("Timeout"));
|
||||
assert_eq!(cache.lock().unwrap().storage_failures, 1);
|
||||
}
|
||||
|
||||
@@ -5320,6 +5446,7 @@ mod tests {
|
||||
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: Some(cached_info),
|
||||
last_storage_success: Some((SystemTime::now(), Instant::now())),
|
||||
last_server_info: None,
|
||||
storage_failures: 0,
|
||||
server_failures: 0,
|
||||
@@ -5327,11 +5454,17 @@ mod tests {
|
||||
});
|
||||
let endpoints = EndpointServerPools::default();
|
||||
|
||||
// First failure: should return cached data
|
||||
let result = handle_peer_failure(Some(&cache), "peer-1", &endpoints);
|
||||
// Historical inventory is available, but its health is not live.
|
||||
let result = handle_peer_failure(Some(&cache), "peer-1", &endpoints, &Error::Timeout);
|
||||
let info = result.unwrap();
|
||||
assert_eq!(info.disks.len(), 1);
|
||||
assert_eq!(info.disks[0].state, "ok");
|
||||
assert_eq!(info.disks[0].state, "unknown");
|
||||
assert_eq!(info.disks[0].runtime_state.as_deref(), Some("unknown"));
|
||||
assert_eq!(info.disks[0].capacity_observation_source.as_deref(), Some("snapshot"));
|
||||
assert_eq!(info.disks[0].capacity_observation_age_seconds, None);
|
||||
assert!(info.observations[0].cached);
|
||||
assert_eq!(info.observations[0].status, StorageInfoProbeStatus::Failed);
|
||||
assert!(info.observations[0].last_success_unix_millis.is_some());
|
||||
assert_eq!(cache.lock().unwrap().storage_failures, 1);
|
||||
}
|
||||
|
||||
@@ -5377,13 +5510,13 @@ mod tests {
|
||||
);
|
||||
drop(cached);
|
||||
|
||||
let degraded = handle_peer_failure(Some(&cache), "peer-1", &EndpointServerPools::default())
|
||||
let degraded = handle_peer_failure(Some(&cache), "peer-1", &EndpointServerPools::default(), &Error::Timeout)
|
||||
.expect("first peer failure must return the cached snapshot");
|
||||
assert!(degraded.disks.iter().all(|disk| !disk.local));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn handle_peer_failure_returns_offline_after_threshold_exceeded() {
|
||||
fn handle_peer_failure_cache_age_does_not_depend_on_poll_count() {
|
||||
let cached_info = StorageInfo {
|
||||
disks: vec![rustfs_madmin::Disk {
|
||||
endpoint: "disk-0".to_string(),
|
||||
@@ -5395,6 +5528,7 @@ mod tests {
|
||||
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: Some(cached_info),
|
||||
last_storage_success: Some((SystemTime::now(), Instant::now())),
|
||||
last_server_info: None,
|
||||
storage_failures: CONSECUTIVE_FAILURE_THRESHOLD - 1,
|
||||
server_failures: 0,
|
||||
@@ -5402,10 +5536,31 @@ mod tests {
|
||||
});
|
||||
let endpoints = EndpointServerPools::default();
|
||||
|
||||
// This failure pushes us to the threshold => offline
|
||||
let result = handle_peer_failure(Some(&cache), "peer-1", &endpoints);
|
||||
assert!(result.is_some());
|
||||
assert_eq!(cache.lock().unwrap().storage_failures, CONSECUTIVE_FAILURE_THRESHOLD);
|
||||
for _ in 0..10 {
|
||||
let info = handle_peer_failure(Some(&cache), "peer-1", &endpoints, &Error::Timeout).expect("failed probe");
|
||||
assert_eq!(info.disks.len(), 1);
|
||||
assert_eq!(info.disks[0].state, "unknown");
|
||||
assert!(info.observations[0].cached);
|
||||
}
|
||||
cache.lock().expect("age cache").last_storage_success =
|
||||
Some((SystemTime::now() - Duration::from_secs(61), Instant::now() - Duration::from_secs(61)));
|
||||
let info = handle_peer_failure(Some(&cache), "peer-1", &endpoints, &Error::Timeout).expect("expired probe");
|
||||
assert!(!info.observations[0].cached);
|
||||
assert!(info.observations[0].snapshot_age_seconds.expect("known last success") >= 61);
|
||||
assert!(info.disks.is_empty(), "expired inventory must not be reused");
|
||||
|
||||
let mut recovered = StorageInfo {
|
||||
disks: vec![rustfs_madmin::Disk {
|
||||
state: "ok".into(),
|
||||
..Default::default()
|
||||
}],
|
||||
..Default::default()
|
||||
};
|
||||
normalize_and_cache_peer_storage_info(Some(&cache), "peer-1", &mut recovered);
|
||||
assert_eq!(recovered.disks[0].state, "ok");
|
||||
assert_eq!(recovered.observations[0].status, StorageInfoProbeStatus::Succeeded);
|
||||
assert!(!recovered.observations[0].cached);
|
||||
assert_eq!(cache.lock().expect("recovered cache").storage_failures, 0);
|
||||
}
|
||||
|
||||
#[test]
|
||||
@@ -5418,6 +5573,7 @@ mod tests {
|
||||
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: Some(cached_props),
|
||||
storage_failures: 0,
|
||||
server_failures: 0,
|
||||
@@ -5448,6 +5604,7 @@ mod tests {
|
||||
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: Some(cached_props),
|
||||
storage_failures: 0,
|
||||
server_failures: 0,
|
||||
@@ -5575,6 +5732,7 @@ mod tests {
|
||||
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: Some(cached_props),
|
||||
storage_failures: 0,
|
||||
server_failures: CONSECUTIVE_FAILURE_THRESHOLD - 1,
|
||||
@@ -5594,6 +5752,7 @@ mod tests {
|
||||
// the real per-drive health), not offline (rustfs/backlog#1049 P0-B).
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: None,
|
||||
storage_failures: 0,
|
||||
server_failures: CONSECUTIVE_FAILURE_THRESHOLD - 1,
|
||||
@@ -5622,6 +5781,7 @@ mod tests {
|
||||
// this is a genuine offline, degraded must not mask it.
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: None,
|
||||
storage_failures: 0,
|
||||
server_failures: CONSECUTIVE_FAILURE_THRESHOLD - 1,
|
||||
@@ -5645,6 +5805,7 @@ mod tests {
|
||||
fn success_resets_failure_counters_independently() {
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: None,
|
||||
storage_failures: 2,
|
||||
server_failures: 2,
|
||||
@@ -5666,6 +5827,7 @@ mod tests {
|
||||
fn storage_failures_do_not_affect_server_failures() {
|
||||
let cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: Some(StorageInfo::default()),
|
||||
last_storage_success: None,
|
||||
last_server_info: Some(ServerProperties {
|
||||
endpoint: "peer-1".to_string(),
|
||||
state: "online".to_string(),
|
||||
@@ -5677,7 +5839,7 @@ mod tests {
|
||||
});
|
||||
let endpoints = EndpointServerPools::default();
|
||||
|
||||
let storage_result = handle_peer_failure(Some(&cache), "peer-1", &endpoints);
|
||||
let storage_result = handle_peer_failure(Some(&cache), "peer-1", &endpoints, &Error::Timeout);
|
||||
assert!(storage_result.is_some());
|
||||
|
||||
let server_result = handle_server_info_failure(Some(&cache), "peer-1", &endpoints, None);
|
||||
@@ -5700,8 +5862,10 @@ mod tests {
|
||||
panic!("poison server cache mutex");
|
||||
});
|
||||
|
||||
let storage_result = handle_peer_failure(Some(&storage_cache), "peer-1", &endpoints);
|
||||
assert!(storage_result.is_none());
|
||||
let storage_result = handle_peer_failure(Some(&storage_cache), "peer-1", &endpoints, &Error::Timeout);
|
||||
let storage = storage_result.expect("poisoned cache must still report the failed peer");
|
||||
assert_eq!(storage.observations[0].status, StorageInfoProbeStatus::Failed);
|
||||
assert!(!storage.observations[0].cached);
|
||||
|
||||
let server_result = handle_server_info_failure(Some(&server_cache), "peer-1", &endpoints, None);
|
||||
assert_eq!(server_result.endpoint, "peer-1");
|
||||
@@ -5712,6 +5876,7 @@ mod tests {
|
||||
fn poisoned_admin_cache_recovers_on_success_and_resets_failures() {
|
||||
let storage_cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: None,
|
||||
storage_failures: CONSECUTIVE_FAILURE_THRESHOLD - 1,
|
||||
server_failures: 0,
|
||||
@@ -5719,6 +5884,7 @@ mod tests {
|
||||
});
|
||||
let server_cache = Mutex::new(PeerAdminCache {
|
||||
last_storage_info: None,
|
||||
last_storage_success: None,
|
||||
last_server_info: None,
|
||||
storage_failures: 0,
|
||||
server_failures: CONSECUTIVE_FAILURE_THRESHOLD - 1,
|
||||
@@ -5757,9 +5923,11 @@ mod tests {
|
||||
},
|
||||
);
|
||||
|
||||
let storage_result = handle_peer_failure(Some(&storage_cache), "peer-1", &endpoints);
|
||||
let storage_result = handle_peer_failure(Some(&storage_cache), "peer-1", &endpoints, &Error::Timeout);
|
||||
assert!(storage_result.is_some());
|
||||
assert_eq!(storage_result.unwrap().disks[0].state, "ok");
|
||||
let storage = storage_result.expect("failed probe after recovery");
|
||||
assert_eq!(storage.disks[0].state, "unknown");
|
||||
assert!(storage.observations[0].cached);
|
||||
|
||||
let server_result = handle_server_info_failure(Some(&server_cache), "peer-1", &endpoints, None);
|
||||
assert_eq!(server_result.state, "online");
|
||||
|
||||
@@ -6650,6 +6650,7 @@ async fn get_storage_info(disks: &[Option<DiskStore>], eps: &[Endpoint]) -> rust
|
||||
total_sets,
|
||||
..Default::default()
|
||||
},
|
||||
..Default::default()
|
||||
}
|
||||
}
|
||||
pub async fn stat_all_dirs(disks: &[Option<DiskStore>], bucket: &str, prefix: &str) -> Vec<Option<DiskError>> {
|
||||
|
||||
@@ -1146,7 +1146,11 @@ impl ECStore {
|
||||
}
|
||||
|
||||
let backend = StorageAdminApi::backend_info(self).await;
|
||||
rustfs_madmin::StorageInfo { backend, disks }
|
||||
rustfs_madmin::StorageInfo {
|
||||
backend,
|
||||
disks,
|
||||
..Default::default()
|
||||
}
|
||||
}
|
||||
|
||||
#[instrument(skip(self))]
|
||||
|
||||
@@ -1,5 +1,7 @@
|
||||
use criterion::{Criterion, criterion_group, criterion_main};
|
||||
use rustfs_io_metrics::{MetricsCollector, PerformanceMetrics, record_get_object_request_started};
|
||||
use rustfs_io_metrics::{record_s3_op, s3_http_metrics::S3HttpRequestGuard};
|
||||
use rustfs_s3_ops::S3Operation;
|
||||
use std::hint::black_box;
|
||||
use std::sync::Arc;
|
||||
use std::time::Duration;
|
||||
@@ -8,6 +10,17 @@ fn bench_record_get_object_request_started(c: &mut Criterion) {
|
||||
c.bench_function("record_get_object_request_started", |b| b.iter(record_get_object_request_started));
|
||||
}
|
||||
|
||||
fn bench_s3_http_outcomes(c: &mut Criterion) {
|
||||
c.bench_function("s3_http_handler_counter", |b| b.iter(|| record_s3_op(black_box(S3Operation::PutObject))));
|
||||
c.bench_function("s3_http_handler_counter_with_outcome", |b| {
|
||||
b.iter(|| {
|
||||
let mut request = S3HttpRequestGuard::new(black_box("PUT"));
|
||||
request.in_scope(|| record_s3_op(black_box(S3Operation::PutObject)));
|
||||
request.response(black_box(200));
|
||||
})
|
||||
});
|
||||
}
|
||||
|
||||
fn bench_update_concurrent_requests(c: &mut Criterion) {
|
||||
let metrics = PerformanceMetrics::new();
|
||||
|
||||
@@ -37,6 +50,7 @@ fn bench_metrics_collector_record_io_operation(c: &mut Criterion) {
|
||||
criterion_group!(
|
||||
benches,
|
||||
bench_record_get_object_request_started,
|
||||
bench_s3_http_outcomes,
|
||||
bench_update_concurrent_requests,
|
||||
bench_metrics_collector_record_io_operation
|
||||
);
|
||||
|
||||
@@ -226,6 +226,7 @@ pub mod lock_metrics;
|
||||
pub mod performance;
|
||||
pub mod process_lock_metrics;
|
||||
pub mod s3_api_metrics;
|
||||
pub mod s3_http_metrics;
|
||||
pub mod sampler;
|
||||
pub mod system_path_metrics;
|
||||
pub mod timeout_metrics;
|
||||
|
||||
@@ -43,6 +43,7 @@ fn s3_op_counters() -> &'static [AtomicU64] {
|
||||
/// This mirrors MinIO, which never labels its default operation counters with
|
||||
/// bucket. The `op` dimension is bounded (<= 122 variants).
|
||||
pub fn record_s3_op(op: S3Operation) {
|
||||
crate::s3_http_metrics::observe_s3_http_operation(op);
|
||||
if let Some(counter) = s3_op_counters().get(op.metric_index()) {
|
||||
counter.fetch_add(1, Ordering::Relaxed);
|
||||
}
|
||||
|
||||
@@ -0,0 +1,254 @@
|
||||
// Copyright 2024 RustFS Team
|
||||
//
|
||||
// Licensed under the Apache License, Version 2.0 (the "License");
|
||||
// you may not use this file except in compliance with the License.
|
||||
// You may obtain a copy of the License at
|
||||
//
|
||||
// http://www.apache.org/licenses/LICENSE-2.0
|
||||
//
|
||||
// Unless required by applicable law or agreed to in writing, software
|
||||
// distributed under the License is distributed on an "AS IS" BASIS,
|
||||
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||
// See the License for the specific language governing permissions and
|
||||
// limitations under the License.
|
||||
|
||||
//! External S3 HTTP outcomes, including requests rejected before S3 dispatch.
|
||||
//! Admin snapshots and metric exporters share these counters. The older
|
||||
//! operation counter counts handler entries and is not an HTTP denominator.
|
||||
|
||||
use rustfs_s3_ops::S3Operation;
|
||||
use std::cell::Cell;
|
||||
use std::sync::atomic::{AtomicU64, Ordering};
|
||||
use std::sync::{LazyLock, OnceLock};
|
||||
|
||||
const METRIC: &str = "rustfs_s3_http_requests_total";
|
||||
const METHODS: [&str; 10] = [
|
||||
"GET", "PUT", "POST", "DELETE", "HEAD", "OPTIONS", "PATCH", "CONNECT", "TRACE", "OTHER",
|
||||
];
|
||||
const OUTCOMES: [&str; 8] = ["1xx", "2xx", "3xx", "4xx", "5xx", "unknown", "service_error", "cancelled"];
|
||||
const UNKNOWN_OPERATION: usize = S3Operation::ALL.len();
|
||||
static COUNTERS: LazyLock<HttpOutcomeCounters> = LazyLock::new(HttpOutcomeCounters::new);
|
||||
|
||||
tokio::task_local! {
|
||||
static CURRENT_OPERATION: Cell<usize>;
|
||||
}
|
||||
|
||||
#[derive(Clone, Debug, PartialEq, Eq)]
|
||||
pub struct S3HttpMetricSnapshot {
|
||||
pub method: &'static str,
|
||||
pub operation: &'static str,
|
||||
pub outcome: &'static str,
|
||||
pub total: u64,
|
||||
}
|
||||
|
||||
struct OutcomeCounter {
|
||||
total: AtomicU64,
|
||||
exported: OnceLock<metrics::Counter>,
|
||||
}
|
||||
|
||||
struct HttpOutcomeCounters(Box<[OutcomeCounter]>);
|
||||
|
||||
impl HttpOutcomeCounters {
|
||||
fn new() -> Self {
|
||||
Self(
|
||||
std::iter::repeat_with(|| OutcomeCounter {
|
||||
total: AtomicU64::new(0),
|
||||
exported: OnceLock::new(),
|
||||
})
|
||||
.take(METHODS.len() * (UNKNOWN_OPERATION + 1) * OUTCOMES.len())
|
||||
.collect(),
|
||||
)
|
||||
}
|
||||
|
||||
fn record(&self, method: usize, operation: usize, outcome: usize) {
|
||||
let counter = &self.0[(method * (UNKNOWN_OPERATION + 1) + operation) * OUTCOMES.len() + outcome];
|
||||
counter.total.fetch_add(1, Ordering::Relaxed);
|
||||
counter
|
||||
.exported
|
||||
.get_or_init(|| {
|
||||
counter!(METRIC, "method" => METHODS[method], "op" => operation_label(operation), "outcome" => OUTCOMES[outcome])
|
||||
})
|
||||
.increment(1);
|
||||
}
|
||||
|
||||
fn snapshot(&self) -> Vec<S3HttpMetricSnapshot> {
|
||||
// Individual series are monotonic; a concurrent snapshot is not a
|
||||
// transaction across series. Rates must compare consecutive samples.
|
||||
self.0
|
||||
.iter()
|
||||
.enumerate()
|
||||
.filter_map(|(index, counter)| {
|
||||
let total = counter.total.load(Ordering::Relaxed);
|
||||
(total != 0).then(|| S3HttpMetricSnapshot {
|
||||
method: METHODS[index / OUTCOMES.len() / (UNKNOWN_OPERATION + 1)],
|
||||
operation: operation_label(index / OUTCOMES.len() % (UNKNOWN_OPERATION + 1)),
|
||||
outcome: OUTCOMES[index % OUTCOMES.len()],
|
||||
total,
|
||||
})
|
||||
})
|
||||
.collect()
|
||||
}
|
||||
}
|
||||
|
||||
fn operation_label(index: usize) -> &'static str {
|
||||
S3Operation::ALL.get(index).map_or("unknown", |op| op.as_str())
|
||||
}
|
||||
|
||||
pub(crate) fn observe_s3_http_operation(op: S3Operation) {
|
||||
let _ = CURRENT_OPERATION.try_with(|current| {
|
||||
// Internal operations must not overwrite the external request's first
|
||||
// dispatched operation. No task-local scope means non-HTTP work.
|
||||
if current.get() == UNKNOWN_OPERATION {
|
||||
current.set(op.metric_index());
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
/// An external request is counted exactly once: at response headers, at a
|
||||
/// service error, or when its future is dropped before producing a response.
|
||||
/// Body-stream failures after headers use the existing streaming metrics.
|
||||
pub struct S3HttpRequestGuard {
|
||||
method: usize,
|
||||
operation: usize,
|
||||
finished: bool,
|
||||
}
|
||||
|
||||
impl S3HttpRequestGuard {
|
||||
pub fn is_active() -> bool {
|
||||
CURRENT_OPERATION.try_with(|_| ()).is_ok()
|
||||
}
|
||||
|
||||
pub fn new(method: &str) -> Self {
|
||||
Self {
|
||||
method: METHODS.iter().position(|known| *known == method).unwrap_or(METHODS.len() - 1),
|
||||
operation: UNKNOWN_OPERATION,
|
||||
finished: false,
|
||||
}
|
||||
}
|
||||
|
||||
/// Attribute existing operation instrumentation without changing S3
|
||||
/// handlers or propagating metric labels through storage/RPC contracts.
|
||||
pub fn in_scope<T>(&mut self, f: impl FnOnce() -> T) -> T {
|
||||
CURRENT_OPERATION.sync_scope(Cell::new(self.operation), || {
|
||||
let result = f();
|
||||
self.operation = CURRENT_OPERATION.with(Cell::get);
|
||||
result
|
||||
})
|
||||
}
|
||||
|
||||
pub fn response(&mut self, status: u16) {
|
||||
let outcome = match status {
|
||||
100..=599 => usize::from(status / 100 - 1),
|
||||
_ => 5,
|
||||
};
|
||||
self.finish(outcome);
|
||||
}
|
||||
|
||||
pub fn service_error(&mut self) {
|
||||
self.finish(6);
|
||||
}
|
||||
|
||||
fn finish(&mut self, outcome: usize) {
|
||||
if !self.finished {
|
||||
COUNTERS.record(self.method, self.operation, outcome);
|
||||
self.finished = true;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
impl Drop for S3HttpRequestGuard {
|
||||
fn drop(&mut self) {
|
||||
self.finish(7);
|
||||
}
|
||||
}
|
||||
|
||||
pub fn s3_http_metrics_snapshot() -> Vec<S3HttpMetricSnapshot> {
|
||||
COUNTERS.snapshot()
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
use metrics::with_local_recorder;
|
||||
use metrics_util::debugging::DebuggingRecorder;
|
||||
|
||||
#[test]
|
||||
fn outcome_counters_distinguish_partial_and_complete_write_failure() {
|
||||
let counters = HttpOutcomeCounters::new();
|
||||
let recorder = DebuggingRecorder::new();
|
||||
with_local_recorder(&recorder, || {
|
||||
for _ in 0..99 {
|
||||
counters.record(1, S3Operation::PutObject.metric_index(), 1);
|
||||
}
|
||||
counters.record(1, S3Operation::PutObject.metric_index(), 4);
|
||||
for _ in 0..100 {
|
||||
counters.record(1, UNKNOWN_OPERATION, 4);
|
||||
}
|
||||
});
|
||||
let snapshot = counters.snapshot();
|
||||
assert_eq!(snapshot.iter().map(|series| series.total).sum::<u64>(), 200);
|
||||
assert_eq!(
|
||||
snapshot
|
||||
.iter()
|
||||
.find(|s| s.operation == S3Operation::PutObject.as_str() && s.outcome == "5xx")
|
||||
.expect("write failure")
|
||||
.total,
|
||||
1
|
||||
);
|
||||
assert_eq!(
|
||||
snapshot
|
||||
.iter()
|
||||
.find(|s| s.operation == "unknown")
|
||||
.expect("pre-dispatch failures")
|
||||
.total,
|
||||
100
|
||||
);
|
||||
let exported = recorder.snapshotter().snapshot().into_vec();
|
||||
assert_eq!(exported.len(), 3);
|
||||
for (key, _, _, _) in exported {
|
||||
let labels: Vec<_> = key.key().labels().map(|label| label.key()).collect();
|
||||
assert_eq!(labels, ["method", "op", "outcome"]);
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn request_guard_preserves_operation_across_polls_and_finishes_once() {
|
||||
let totals = || {
|
||||
s3_http_metrics_snapshot()
|
||||
.into_iter()
|
||||
.filter(|series| series.method == "CONNECT")
|
||||
.map(|series| ((series.operation, series.outcome), series.total))
|
||||
.collect::<std::collections::BTreeMap<_, _>>()
|
||||
};
|
||||
let before = totals();
|
||||
let mut request = S3HttpRequestGuard::new("CONNECT");
|
||||
request.in_scope(|| observe_s3_http_operation(S3Operation::PutObject));
|
||||
request.in_scope(|| {
|
||||
assert!(S3HttpRequestGuard::is_active());
|
||||
observe_s3_http_operation(S3Operation::GetObject);
|
||||
});
|
||||
assert!(!S3HttpRequestGuard::is_active());
|
||||
request.response(204);
|
||||
request.response(503);
|
||||
request.service_error();
|
||||
drop(request);
|
||||
let after = totals();
|
||||
let key = (S3Operation::PutObject.as_str(), "2xx");
|
||||
assert_eq!(after[&key] - before.get(&key).copied().unwrap_or_default(), 1);
|
||||
assert_eq!(after.values().sum::<u64>() - before.values().sum::<u64>(), 1);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn request_operation_is_scoped_and_first_dispatch_wins() {
|
||||
let mut request = S3HttpRequestGuard::new("PUT");
|
||||
request.in_scope(|| {
|
||||
observe_s3_http_operation(S3Operation::PutObject);
|
||||
observe_s3_http_operation(S3Operation::GetObject);
|
||||
});
|
||||
assert_eq!(request.operation, S3Operation::PutObject.metric_index());
|
||||
observe_s3_http_operation(S3Operation::GetObject);
|
||||
let other = S3HttpRequestGuard::new("attacker-controlled-method");
|
||||
assert_eq!(other.method, METHODS.len() - 1);
|
||||
assert_eq!(other.operation, UNKNOWN_OPERATION);
|
||||
}
|
||||
}
|
||||
@@ -188,6 +188,30 @@ pub enum BackendByte {
|
||||
pub struct StorageInfo {
|
||||
pub disks: Vec<Disk>,
|
||||
pub backend: BackendInfo,
|
||||
/// Missing observations from older nodes are unknown, never proof of health.
|
||||
#[serde(default, skip_serializing_if = "Vec::is_empty")]
|
||||
pub observations: Vec<StorageInfoObservation>,
|
||||
}
|
||||
|
||||
#[derive(Clone, Debug, Default, Serialize, Deserialize, PartialEq, Eq)]
|
||||
#[serde(rename_all = "snake_case")]
|
||||
pub enum StorageInfoProbeStatus {
|
||||
Succeeded,
|
||||
Failed,
|
||||
#[default]
|
||||
#[serde(other)]
|
||||
Unknown,
|
||||
}
|
||||
|
||||
#[derive(Clone, Debug, Default, Serialize, Deserialize, PartialEq, Eq)]
|
||||
#[serde(default)]
|
||||
pub struct StorageInfoObservation {
|
||||
pub endpoint: String,
|
||||
pub status: StorageInfoProbeStatus,
|
||||
pub cached: bool,
|
||||
pub last_success_unix_millis: Option<u64>,
|
||||
pub snapshot_age_seconds: Option<u64>,
|
||||
pub error_code: Option<String>,
|
||||
}
|
||||
|
||||
#[derive(Clone, Debug, Default, Serialize, Deserialize)]
|
||||
@@ -879,6 +903,7 @@ mod tests {
|
||||
},
|
||||
],
|
||||
backend: BackendInfo::default(),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert_eq!(storage_info.disks.len(), 2);
|
||||
@@ -886,6 +911,40 @@ mod tests {
|
||||
assert_eq!(storage_info.disks[1].state, "offline");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn storage_info_observation_is_additive_and_unknown_for_old_peers() {
|
||||
#[derive(Serialize, Deserialize)]
|
||||
struct LegacyStorageInfo {
|
||||
disks: Vec<Disk>,
|
||||
backend: BackendInfo,
|
||||
}
|
||||
let old = LegacyStorageInfo {
|
||||
disks: Vec::new(),
|
||||
backend: BackendInfo::default(),
|
||||
};
|
||||
let encoded = rmp_serde::to_vec_named(&old).expect("legacy map");
|
||||
let decoded: StorageInfo = rmp_serde::from_slice(&encoded).expect("old peer response");
|
||||
assert!(decoded.observations.is_empty());
|
||||
let mut new = decoded;
|
||||
new.observations.push(StorageInfoObservation {
|
||||
endpoint: "node2:9000".into(),
|
||||
status: StorageInfoProbeStatus::Failed,
|
||||
cached: true,
|
||||
last_success_unix_millis: Some(1_700_000_000_000),
|
||||
snapshot_age_seconds: Some(5),
|
||||
error_code: Some("Timeout".into()),
|
||||
});
|
||||
let encoded = rmp_serde::to_vec_named(&new).expect("new map");
|
||||
let legacy: LegacyStorageInfo = rmp_serde::from_slice(&encoded).expect("old reader ignores new fields");
|
||||
assert!(legacy.disks.is_empty());
|
||||
let roundtrip: StorageInfo = rmp_serde::from_slice(&encoded).expect("new reader preserves observation");
|
||||
assert_eq!(roundtrip.observations, new.observations);
|
||||
let unknown: StorageInfoObservation =
|
||||
serde_json::from_str(r#"{"endpoint":"node2","status":"future_state"}"#).expect("future state remains unknown");
|
||||
assert_eq!(unknown.status, StorageInfoProbeStatus::Unknown);
|
||||
assert_eq!(unknown.snapshot_age_seconds, None);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn test_backend_disks_new() {
|
||||
let backend_disks = BackendDisks::new();
|
||||
@@ -1391,6 +1450,7 @@ mod tests {
|
||||
let storage_info = StorageInfo {
|
||||
disks: vec![],
|
||||
backend: BackendInfo::default(),
|
||||
..Default::default()
|
||||
};
|
||||
let backend_info = BackendInfo::default();
|
||||
let mem_stats = MemStats::default();
|
||||
|
||||
@@ -997,10 +997,56 @@ pub struct Metrics {
|
||||
pub cpu: Option<CPUMetrics>,
|
||||
#[serde(rename = "rpc", skip_serializing_if = "Option::is_none")]
|
||||
pub rpc: Option<RPCMetrics>,
|
||||
/// Absent means this node did not report HTTP outcomes, not zero traffic.
|
||||
#[serde(default, skip_serializing_if = "Option::is_none")]
|
||||
pub http: Option<HttpMetrics>,
|
||||
}
|
||||
|
||||
#[derive(Clone, Debug, Default, Serialize, Deserialize)]
|
||||
pub struct HttpMetrics {
|
||||
#[serde(rename = "collected")]
|
||||
pub collected_at: Timestamp,
|
||||
pub requests: Vec<HttpRequestMetric>,
|
||||
}
|
||||
|
||||
#[derive(Clone, Debug, Serialize, Deserialize, PartialEq, Eq)]
|
||||
pub struct HttpRequestMetric {
|
||||
pub method: String,
|
||||
pub operation: String,
|
||||
pub outcome: String,
|
||||
pub total: u64,
|
||||
}
|
||||
|
||||
impl HttpMetrics {
|
||||
fn merge(&mut self, other: &Self) {
|
||||
self.collected_at = self.collected_at.max(other.collected_at);
|
||||
let mut totals = std::collections::BTreeMap::new();
|
||||
for series in self.requests.drain(..).chain(other.requests.iter().cloned()) {
|
||||
let total = totals
|
||||
.entry((series.method, series.operation, series.outcome))
|
||||
.or_insert(0_u64);
|
||||
*total = total.saturating_add(series.total);
|
||||
}
|
||||
self.requests = totals
|
||||
.into_iter()
|
||||
.map(|((method, operation, outcome), total)| HttpRequestMetric {
|
||||
method,
|
||||
operation,
|
||||
outcome,
|
||||
total,
|
||||
})
|
||||
.collect();
|
||||
}
|
||||
}
|
||||
|
||||
impl Metrics {
|
||||
pub fn merge(&mut self, other: &Self) {
|
||||
if let Some(http) = &other.http {
|
||||
match &mut self.http {
|
||||
Some(existing) => existing.merge(http),
|
||||
None => self.http = Some(http.clone()),
|
||||
}
|
||||
}
|
||||
if let Some(scanner) = other.scanner.as_ref() {
|
||||
match self.scanner {
|
||||
Some(ref mut s_scanner) => s_scanner.merge(scanner),
|
||||
@@ -1473,6 +1519,70 @@ mod tests {
|
||||
Timestamp::constant(1_700_000_000, 123_456_000)
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn http_metrics_merge_preserves_outcomes_and_missing_node_support() {
|
||||
#[derive(Serialize, Deserialize, Default)]
|
||||
#[serde(default)]
|
||||
struct LegacyMetrics {
|
||||
rpc: Option<RPCMetrics>,
|
||||
}
|
||||
let old_map = rmp_serde::to_vec_named(&LegacyMetrics::default()).expect("legacy map");
|
||||
assert!(rmp_serde::from_slice::<Metrics>(&old_map).expect("new reader").http.is_none());
|
||||
let missing: Metrics = serde_json::from_str("{}").expect("old node metrics");
|
||||
assert!(missing.http.is_none());
|
||||
let mut combined = RealtimeMetrics::default();
|
||||
for (host, successes, failures) in [("node1", 99, 1), ("node2", 0, 100)] {
|
||||
let metrics = Metrics {
|
||||
http: Some(HttpMetrics {
|
||||
collected_at: fixed_timestamp(),
|
||||
requests: [("2xx", successes), ("5xx", failures)]
|
||||
.into_iter()
|
||||
.map(|(outcome, total)| HttpRequestMetric {
|
||||
method: "PUT".into(),
|
||||
operation: "s3:PutObject".into(),
|
||||
outcome: outcome.into(),
|
||||
total,
|
||||
})
|
||||
.collect(),
|
||||
}),
|
||||
..Default::default()
|
||||
};
|
||||
let encoded = rmp_serde::to_vec_named(&metrics).expect("peer metric map");
|
||||
let old_reader: LegacyMetrics = rmp_serde::from_slice(&encoded).expect("old reader ignores HTTP field");
|
||||
assert!(old_reader.rpc.is_none());
|
||||
let decoded: Metrics = rmp_serde::from_slice(&encoded).expect("peer metric roundtrip");
|
||||
combined.merge(RealtimeMetrics {
|
||||
aggregated: decoded,
|
||||
by_host: HashMap::from([(host.into(), metrics)]),
|
||||
hosts: vec![host.into()],
|
||||
..Default::default()
|
||||
});
|
||||
}
|
||||
let aggregate = combined.aggregated.http.as_ref().expect("HTTP support");
|
||||
assert_eq!(
|
||||
aggregate
|
||||
.requests
|
||||
.iter()
|
||||
.find(|s| s.outcome == "5xx")
|
||||
.expect("failures")
|
||||
.total,
|
||||
101
|
||||
);
|
||||
assert_eq!(aggregate.requests.iter().map(|s| s.total).sum::<u64>(), 200);
|
||||
assert_eq!(combined.by_host["node2"].http.as_ref().expect("node2").requests[1].total, 100);
|
||||
combined.aggregated.merge(&missing);
|
||||
assert_eq!(
|
||||
combined
|
||||
.aggregated
|
||||
.http
|
||||
.as_ref()
|
||||
.expect("supported peers remain")
|
||||
.requests
|
||||
.len(),
|
||||
2
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn admin_metrics_timestamps_serialize_as_rfc3339_utc() {
|
||||
let timestamp = fixed_timestamp();
|
||||
|
||||
@@ -13,6 +13,47 @@
|
||||
// limitations under the License.
|
||||
|
||||
use std::fmt;
|
||||
use std::sync::OnceLock;
|
||||
use std::sync::atomic::{AtomicU64, Ordering};
|
||||
|
||||
/// Bounds a repetitive diagnostic without changing its underlying counters.
|
||||
/// Each emitted event includes the number suppressed since the previous one.
|
||||
pub struct LogThrottle {
|
||||
interval_ms: u64,
|
||||
last_ms: AtomicU64,
|
||||
suppressed: AtomicU64,
|
||||
}
|
||||
|
||||
impl LogThrottle {
|
||||
pub const fn new(interval_ms: u64) -> Self {
|
||||
Self {
|
||||
interval_ms,
|
||||
last_ms: AtomicU64::new(u64::MAX),
|
||||
suppressed: AtomicU64::new(0),
|
||||
}
|
||||
}
|
||||
|
||||
pub fn claim(&self) -> Option<u64> {
|
||||
static ANCHOR: OnceLock<std::time::Instant> = OnceLock::new();
|
||||
let now = ANCHOR.get_or_init(std::time::Instant::now).elapsed().as_millis();
|
||||
self.claim_at(u64::try_from(now).unwrap_or(u64::MAX - 1))
|
||||
}
|
||||
|
||||
fn claim_at(&self, now: u64) -> Option<u64> {
|
||||
let last = self.last_ms.load(Ordering::Relaxed);
|
||||
if (last == u64::MAX || now.saturating_sub(last) >= self.interval_ms)
|
||||
&& self
|
||||
.last_ms
|
||||
.compare_exchange(last, now, Ordering::Relaxed, Ordering::Relaxed)
|
||||
.is_ok()
|
||||
{
|
||||
Some(self.suppressed.swap(0, Ordering::Relaxed))
|
||||
} else {
|
||||
self.suppressed.fetch_add(1, Ordering::Relaxed);
|
||||
None
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[derive(Clone, Copy)]
|
||||
pub struct MaskedAccessKey<'a>(pub &'a str);
|
||||
@@ -51,7 +92,32 @@ impl fmt::Debug for MaskedAccessKey<'_> {
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::MaskedAccessKey;
|
||||
use super::{LogThrottle, MaskedAccessKey};
|
||||
|
||||
#[test]
|
||||
fn log_throttle_emits_once_per_interval_and_reports_suppression() {
|
||||
let throttle = LogThrottle::new(5_000);
|
||||
assert_eq!(throttle.claim_at(0), Some(0));
|
||||
assert_eq!(throttle.claim_at(1), None);
|
||||
assert_eq!(throttle.claim_at(4_999), None);
|
||||
assert_eq!(throttle.claim_at(5_000), Some(2));
|
||||
assert_eq!(throttle.claim_at(5_001), None);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn log_throttle_allows_only_one_concurrent_claim() {
|
||||
let throttle = LogThrottle::new(5_000);
|
||||
let reported = std::thread::scope(|scope| {
|
||||
let threads: Vec<_> = (0..16).map(|_| scope.spawn(|| throttle.claim_at(0))).collect();
|
||||
let emitted: Vec<_> = threads
|
||||
.into_iter()
|
||||
.filter_map(|thread| thread.join().expect("claim worker"))
|
||||
.collect();
|
||||
assert_eq!(emitted.len(), 1);
|
||||
emitted[0]
|
||||
});
|
||||
assert_eq!(reported + throttle.claim_at(5_000).expect("next window"), 15);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn masks_short_values() {
|
||||
|
||||
@@ -61,3 +61,5 @@ Required headings and strings in these files are asserted by `scripts/check_arch
|
||||
| [minio-file-format-compat.md](minio-file-format-compat.md) | deciding whether a MinIO drive set, bucket-metadata blob, or SSE object can be read or imported by a given RustFS build, or before touching a listed version anchor |
|
||||
|
||||
Operations runbooks live in [../operations/](../README.md#operations) and testing references in [../testing/README.md](../testing/README.md).
|
||||
|
||||
For per-node HTTP failure ratios and cached storage probe provenance, see [S3 write failure diagnostics](../operations/s3-write-failure-diagnostics.md).
|
||||
|
||||
@@ -0,0 +1,54 @@
|
||||
# S3 write failure diagnostics
|
||||
|
||||
**Use this when:** distinguishing occasional write failures from a node-wide outage, or interpreting cached storage inventory during an internode failure.
|
||||
|
||||
## Measure the failure ratio
|
||||
|
||||
`rustfs_s3_http_requests_total` counts external S3 HTTP outcomes independently of the configured log level. Its bounded labels are `method`, `op`, and `outcome`; the exporter target identifies the node. Bucket names, object keys, request IDs, and error text are not metric labels.
|
||||
|
||||
The counter increments exactly once when response headers are produced, the service returns an error without a response (`service_error`), or its pending future is dropped (`cancelled`). Outcomes `1xx` through `5xx` classify HTTP responses; `unknown` is reserved for a response outside those classes. A successful response header is not proof that a streamed response body reached the client. Body-stream errors remain separate streaming diagnostics.
|
||||
|
||||
The `op` label uses the existing S3 operation names, such as `s3:PutObject`. A request rejected before operation dispatch has `op="unknown"`, while retaining its HTTP method. Include these requests when measuring a node outage. Do not infer `PutObject` from `PUT` alone: bucket and multipart operations also use that method. Admin, console, health, RPC, STS, and enabled non-S3 protocol routes are excluded.
|
||||
|
||||
For example, with the usual Prometheus `instance` target label, compare the per-node PUT-method HTTP 5xx ratio:
|
||||
|
||||
```promql
|
||||
sum by (instance) (rate(rustfs_s3_http_requests_total{method="PUT",outcome="5xx"}[5m]))
|
||||
/
|
||||
sum by (instance) (rate(rustfs_s3_http_requests_total{method="PUT",outcome=~"[1-5]xx"}[5m]))
|
||||
```
|
||||
|
||||
Inspect `service_error` and `cancelled` separately; neither implies a received HTTP status. A zero denominator or absent series means no observed traffic, not proof of health. Use `rate` or reset-aware deltas because counters restart with the process. The older `rustfs_s3_operations_total` counter measures handler entries and excludes pre-dispatch rejections; it is not this HTTP denominator.
|
||||
|
||||
The authenticated admin metrics endpoint exposes the same counters through the optional `http` field in `aggregated` and `by_host`. Request `/rustfs/admin/v3/metrics?types=512&by-host=true&n=1` on each node for HTTP-only data. The default type selection also includes HTTP outcomes. This endpoint remains an NDJSON stream and does not become a cluster-wide peer fanout. `http.requests` contains `method`, `operation`, `outcome`, and `total`; `http.collected` timestamps collection. Compare consecutive samples from the same host. Concurrent snapshots are not atomic across series.
|
||||
|
||||
A missing `http` field means an older or non-reporting node, not zero failures. Old map-encoded RPC readers ignore the additive field; new readers accept older snapshots. In mixed-version deployments, check reporting coverage before aggregating a fleet-wide ratio.
|
||||
|
||||
## Interpret failed storage probes
|
||||
|
||||
Storage inventory includes an `observations` entry for each probed node. The aggregator owns this provenance even when a peer runs an older version.
|
||||
|
||||
| Field | Meaning |
|
||||
| --- | --- |
|
||||
| `endpoint` | Node whose local inventory was queried. |
|
||||
| `status` | `succeeded`, `failed`, or `unknown`; this is the probe result, not physical drive health. |
|
||||
| `cached` | Historical inventory was reused for this response. |
|
||||
| `last_success_unix_millis` | Wall-clock time of the last successful observation, when known. |
|
||||
| `snapshot_age_seconds` | Monotonic elapsed age since that observation, when known. |
|
||||
| `error_code` | Bounded storage error classification for a failed probe, without raw error text. |
|
||||
|
||||
After a failed probe, inventory younger than 60 seconds may retain drive identity and capacity, but returned drive `state` and `runtime_state` become `unknown` immediately. Capacity is marked as a `snapshot`; its age advances when the original observation age was known. Expired or absent inventory is synthesized from topology, with capacity observation source `missing`. Repeated polling does not extend this age budget. A successful probe replaces the historical snapshot and clears the failure streak.
|
||||
|
||||
An admin RPC timeout or authentication error is not proof of failed physical disks. It also cannot supply fresh evidence of healthy disks. Consequently, cluster health reports can become unready on the first failed probe when remaining known-online drives cannot demonstrate the existing quorum. The quorum thresholds, S3 admission gate, drive-health tracker, and metadata recovery algorithm are unchanged. Consult independent drive and transport diagnostics before replacing a disk. Legacy snapshots without observations have unknown provenance.
|
||||
|
||||
The probe round timeout is configured independently; see [Admin peer probe timeout](admin-peer-probe-timeout.md).
|
||||
|
||||
## Correlate bounded diagnostics
|
||||
|
||||
Normal operation does not require success logs at WARN. Request counters remain available with WARN logging, while existing runtime readiness diagnostics distinguish `pool_meta_write_blocked` from insufficient storage quorum. Do not clear a metadata write fence merely to make readiness green.
|
||||
|
||||
PUT storage failures retain their typed source chain internally and emit bounded S3/storage error codes, I/O kinds, and RPC status codes alongside the existing request ID, bucket, and key. Raw nested error strings and RPC metadata are not logged by this diagnostic. A repeated PUT diagnostic is limited to one event per five seconds; HTTP server-error logs are limited per status code over the same interval for accounted S3 traffic. `suppressed_errors` reports suppressed events at the next emitted event; use the HTTP counter, not log-line counts, to measure failures. HTTP server-error URI diagnostics omit query strings, including presigned credentials.
|
||||
|
||||
Storage inventory emits a WARN event on the first failed probe and an INFO event on recovery, using `event="storage_info_probe"`. A recovery event confirms the RPC succeeded, not that every reported disk is healthy. Bucket metadata load/retry errors include the bucket and a bounded error code, so one failing bucket can be identified without dumping its metadata.
|
||||
|
||||
No new environment variable, admin authorization action, or recovery command is required.
|
||||
@@ -2285,7 +2285,7 @@ impl DefaultObjectUsecase {
|
||||
// threshold and per-request WARNs flood the log.
|
||||
rustfs_io_metrics::record_io_queue_congestion();
|
||||
|
||||
if let Some(suppressed_warns) = IO_QUEUE_CONGESTION_WARN_THROTTLE.claim(IoQueueCongestionWarnThrottle::now_ms()) {
|
||||
if let Some(suppressed_warns) = IO_QUEUE_CONGESTION_WARN_THROTTLE.claim() {
|
||||
warn!(
|
||||
bucket = %bucket,
|
||||
key = %key,
|
||||
|
||||
@@ -239,9 +239,9 @@ use std::pin::Pin;
|
||||
use std::task::{Context, Poll};
|
||||
|
||||
use std::str::FromStr;
|
||||
use std::sync::atomic::{AtomicBool, Ordering};
|
||||
#[cfg(test)]
|
||||
use std::sync::atomic::AtomicUsize;
|
||||
use std::sync::atomic::{AtomicBool, AtomicU64, Ordering};
|
||||
use std::sync::atomic::{AtomicU64, AtomicUsize};
|
||||
use std::sync::{Arc, Mutex, OnceLock};
|
||||
use std::time::{Duration, Instant};
|
||||
use time::{
|
||||
|
||||
@@ -18,6 +18,7 @@ use super::*;
|
||||
|
||||
use crate::auth::{RUSTFS_MAX_CONTENT_LENGTH_QUERY, VerifiedPresignedRequest, parse_presigned_put_max_content_length};
|
||||
use crate::error::UploadLimitExceeded;
|
||||
static PUT_FAILURE_LOGS: rustfs_utils::LogThrottle = rustfs_utils::LogThrottle::new(5_000);
|
||||
|
||||
const DEFAULT_PUT_LARGE_CONCURRENCY_TUNING_MIN_SIZE_BYTES: i64 = 32 * 1024 * 1024;
|
||||
|
||||
@@ -1976,21 +1977,29 @@ impl DefaultObjectUsecase {
|
||||
Err(err) => {
|
||||
store_put_watchdog.cancel();
|
||||
rustfs_io_metrics::record_put_object_stage_duration_from("app_store_put", store_put_stage_start);
|
||||
warn!(
|
||||
target: "rustfs::app::object_usecase",
|
||||
event = EVENT_PUT_OBJECT_STORE_RETURNED,
|
||||
component = LOG_COMPONENT_APP,
|
||||
subsystem = LOG_SUBSYSTEM_OBJECT,
|
||||
request_id = %request_id,
|
||||
bucket = %bucket,
|
||||
key = %key,
|
||||
put_path = %put_path,
|
||||
object_size = actual_size,
|
||||
duration_ms = start_time.elapsed().as_millis() as u64,
|
||||
result = "error",
|
||||
error = %err,
|
||||
"PutObject store write returned"
|
||||
);
|
||||
if let Some(suppressed_errors) = PUT_FAILURE_LOGS.claim() {
|
||||
let diagnostic = err.diagnostic();
|
||||
warn!(
|
||||
target: "rustfs::app::object_usecase",
|
||||
event = EVENT_PUT_OBJECT_STORE_RETURNED,
|
||||
component = LOG_COMPONENT_APP,
|
||||
subsystem = LOG_SUBSYSTEM_OBJECT,
|
||||
request_id = %request_id,
|
||||
bucket = %bucket,
|
||||
key = %key,
|
||||
put_path = %put_path,
|
||||
object_size = actual_size,
|
||||
duration_ms = start_time.elapsed().as_millis() as u64,
|
||||
result = "error",
|
||||
error_code = %err.code.as_str(),
|
||||
storage_error_code = ?diagnostic.storage_code,
|
||||
io_error_kind = ?diagnostic.io_kind,
|
||||
rpc_error_code = ?diagnostic.rpc_code,
|
||||
source_chain_truncated = diagnostic.truncated,
|
||||
suppressed_errors,
|
||||
"PutObject store write returned"
|
||||
);
|
||||
}
|
||||
return Err(err.into());
|
||||
}
|
||||
};
|
||||
|
||||
@@ -808,56 +808,7 @@ pub(super) async fn resolve_put_object_expiration(bucket: &str, obj_info: &Objec
|
||||
build_put_object_expiration_header(&event)
|
||||
}
|
||||
|
||||
/// Cadence for the "I/O queue congestion detected" WARN. Under sustained
|
||||
/// overload (client concurrency at or above the disk-read permit pool) every
|
||||
/// GET observes >=80% utilization, so an unthrottled WARN floods the log
|
||||
/// from the already saturated hot path; congestion metrics stay per-request.
|
||||
const IO_QUEUE_CONGESTION_WARN_INTERVAL_MS: u64 = 5_000;
|
||||
|
||||
/// At-most-one-WARN-per-interval limiter for the I/O queue congestion log.
|
||||
/// Callers supply monotonic milliseconds so tests can drive the clock.
|
||||
pub(super) struct IoQueueCongestionWarnThrottle {
|
||||
/// Timestamp of the last emitted WARN; `u64::MAX` until the first one.
|
||||
last_warn_ms: AtomicU64,
|
||||
/// Congested requests left unlogged since the last emitted WARN.
|
||||
suppressed: AtomicU64,
|
||||
}
|
||||
|
||||
impl IoQueueCongestionWarnThrottle {
|
||||
const fn new() -> Self {
|
||||
Self {
|
||||
last_warn_ms: AtomicU64::new(u64::MAX),
|
||||
suppressed: AtomicU64::new(0),
|
||||
}
|
||||
}
|
||||
|
||||
/// Claim the right to emit one WARN. Returns the number of events
|
||||
/// suppressed since the previous emission, or `None` while the interval
|
||||
/// window is still closed (the event is counted, not logged).
|
||||
pub(super) fn claim(&self, now_ms: u64) -> Option<u64> {
|
||||
let last = self.last_warn_ms.load(Ordering::Relaxed);
|
||||
let window_open = last == u64::MAX || now_ms.saturating_sub(last) >= IO_QUEUE_CONGESTION_WARN_INTERVAL_MS;
|
||||
if window_open
|
||||
&& self
|
||||
.last_warn_ms
|
||||
.compare_exchange(last, now_ms, Ordering::Relaxed, Ordering::Relaxed)
|
||||
.is_ok()
|
||||
{
|
||||
Some(self.suppressed.swap(0, Ordering::Relaxed))
|
||||
} else {
|
||||
self.suppressed.fetch_add(1, Ordering::Relaxed);
|
||||
None
|
||||
}
|
||||
}
|
||||
|
||||
/// Monotonic milliseconds since the first call, for production callers.
|
||||
pub(super) fn now_ms() -> u64 {
|
||||
static ANCHOR: OnceLock<std::time::Instant> = OnceLock::new();
|
||||
ANCHOR.get_or_init(std::time::Instant::now).elapsed().as_millis() as u64
|
||||
}
|
||||
}
|
||||
|
||||
pub(super) static IO_QUEUE_CONGESTION_WARN_THROTTLE: IoQueueCongestionWarnThrottle = IoQueueCongestionWarnThrottle::new();
|
||||
pub(super) static IO_QUEUE_CONGESTION_WARN_THROTTLE: rustfs_utils::LogThrottle = rustfs_utils::LogThrottle::new(5_000);
|
||||
|
||||
pub(super) async fn track_object_read_setup<F>(health: Option<&ObjectTrafficHealth>, future: F) -> F::Output
|
||||
where
|
||||
@@ -1063,19 +1014,6 @@ mod tests {
|
||||
};
|
||||
use std::sync::Arc;
|
||||
|
||||
#[test]
|
||||
fn io_queue_congestion_warn_throttle_emits_once_per_interval() {
|
||||
let throttle = IoQueueCongestionWarnThrottle::new();
|
||||
// The first congested request logs immediately.
|
||||
assert_eq!(throttle.claim(0), Some(0));
|
||||
// Requests inside the window are counted, not logged.
|
||||
assert_eq!(throttle.claim(1), None);
|
||||
assert_eq!(throttle.claim(IO_QUEUE_CONGESTION_WARN_INTERVAL_MS - 1), None);
|
||||
// The next emission reports how many stayed silent.
|
||||
assert_eq!(throttle.claim(IO_QUEUE_CONGESTION_WARN_INTERVAL_MS), Some(2));
|
||||
assert_eq!(throttle.claim(IO_QUEUE_CONGESTION_WARN_INTERVAL_MS + 1), None);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn parse_expires_header_accepts_http_date() {
|
||||
let expires = parse_expires_header(Some("Wed, 21 Oct 2015 07:28:00 GMT"))
|
||||
|
||||
+92
-5
@@ -12,7 +12,7 @@
|
||||
// See the License for the specific language governing permissions and
|
||||
// limitations under the License.
|
||||
|
||||
use crate::storage_api::error::contract::range::HTTPRangeError;
|
||||
use crate::storage_api::error::contract::{StorageErrorCode, range::HTTPRangeError};
|
||||
use crate::storage_api::error::{QuotaError, StorageError};
|
||||
use rustfs_kms::KmsUnavailableError;
|
||||
use s3s::{S3Error, S3ErrorCode};
|
||||
@@ -73,9 +73,47 @@ impl std::fmt::Display for ApiError {
|
||||
}
|
||||
}
|
||||
|
||||
impl std::error::Error for ApiError {}
|
||||
impl std::error::Error for ApiError {
|
||||
fn source(&self) -> Option<&(dyn std::error::Error + 'static)> {
|
||||
self.source.as_deref().map(|source| source as _)
|
||||
}
|
||||
}
|
||||
|
||||
/// Only bounded classifications are safe to include in routine diagnostics.
|
||||
#[derive(Debug, Default, PartialEq, Eq)]
|
||||
pub(crate) struct ApiErrorDiagnostic {
|
||||
pub storage_code: Option<StorageErrorCode>,
|
||||
pub io_kind: Option<std::io::ErrorKind>,
|
||||
pub rpc_code: Option<tonic::Code>,
|
||||
pub truncated: bool,
|
||||
}
|
||||
|
||||
impl ApiError {
|
||||
pub(crate) fn diagnostic(&self) -> ApiErrorDiagnostic {
|
||||
let mut diagnostic = ApiErrorDiagnostic::default();
|
||||
let mut current = std::error::Error::source(self);
|
||||
for _ in 0..16 {
|
||||
let Some(error) = current else {
|
||||
return diagnostic;
|
||||
};
|
||||
if let Some(storage) = error.downcast_ref::<StorageError>() {
|
||||
diagnostic.storage_code = Some(storage.code());
|
||||
}
|
||||
if let Some(status) = error.downcast_ref::<tonic::Status>() {
|
||||
diagnostic.rpc_code = Some(status.code());
|
||||
}
|
||||
current = if let Some(io) = error.downcast_ref::<std::io::Error>() {
|
||||
diagnostic.io_kind = Some(io.kind());
|
||||
// io::Error::source can skip the wrapped error itself.
|
||||
io.get_ref().map(|source| source as &(dyn std::error::Error + 'static))
|
||||
} else {
|
||||
error.source()
|
||||
};
|
||||
}
|
||||
diagnostic.truncated = current.is_some();
|
||||
diagnostic
|
||||
}
|
||||
|
||||
/// Access-denied error with the exact message emitted by the authorization
|
||||
/// paths in `storage::access`; callers there match on the code only.
|
||||
pub fn access_denied() -> Self {
|
||||
@@ -569,6 +607,51 @@ mod tests {
|
||||
use s3s::{S3Error, S3ErrorCode};
|
||||
use std::io::{Error as IoError, ErrorKind};
|
||||
|
||||
#[test]
|
||||
fn api_error_diagnostic_preserves_typed_cause_without_sensitive_payload() {
|
||||
let error = ApiError::from(StorageError::Io(IoError::new(ErrorKind::TimedOut, "secret=do-not-log")));
|
||||
let diagnostic = error.diagnostic();
|
||||
assert_eq!(diagnostic.storage_code, Some(StorageErrorCode::Io));
|
||||
assert_eq!(diagnostic.io_kind, Some(ErrorKind::TimedOut));
|
||||
assert!(!diagnostic.truncated);
|
||||
assert!(!format!("{diagnostic:?}").contains("do-not-log"));
|
||||
assert!(std::error::Error::source(&error).is_some());
|
||||
|
||||
let error = ApiError::from(StorageError::Io(IoError::other(StorageError::ErasureWriteQuorum)));
|
||||
assert_eq!(error.diagnostic().storage_code, Some(StorageErrorCode::ErasureWriteQuorum));
|
||||
|
||||
let mut status = tonic::Status::unavailable("secret RPC message");
|
||||
status
|
||||
.metadata_mut()
|
||||
.insert("authorization", "secret-token".parse().expect("metadata value"));
|
||||
let error = ApiError::from(StorageError::from(status));
|
||||
assert_eq!(error.diagnostic().rpc_code, Some(tonic::Code::Unavailable));
|
||||
assert!(!format!("{:?}", error.diagnostic()).contains("secret"));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn api_error_diagnostic_bounds_cyclic_error_chains() {
|
||||
#[derive(Debug)]
|
||||
struct Cycle;
|
||||
impl std::fmt::Display for Cycle {
|
||||
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
|
||||
f.write_str("secret cycle")
|
||||
}
|
||||
}
|
||||
impl std::error::Error for Cycle {
|
||||
fn source(&self) -> Option<&(dyn std::error::Error + 'static)> {
|
||||
Some(self)
|
||||
}
|
||||
}
|
||||
let error = ApiError {
|
||||
code: S3ErrorCode::InternalError,
|
||||
message: "safe".into(),
|
||||
source: Some(Box::new(Cycle)),
|
||||
};
|
||||
assert!(error.diagnostic().truncated);
|
||||
assert!(!format!("{:?}", error.diagnostic()).contains("secret"));
|
||||
}
|
||||
|
||||
#[derive(Debug)]
|
||||
enum MockUploadStreamError {
|
||||
Underlying(IoError),
|
||||
@@ -1194,8 +1277,12 @@ mod tests {
|
||||
// Test that it implements std::error::Error
|
||||
let error: &dyn std::error::Error = &api_error;
|
||||
assert_eq!(error.to_string(), "Test error");
|
||||
// ApiError doesn't implement Error::source() properly, so this would be None
|
||||
// This is expected because ApiError is not a typical Error implementation
|
||||
assert!(error.source().is_none());
|
||||
let source = error
|
||||
.source()
|
||||
.expect("typed source must remain reachable through the error trait");
|
||||
let source = source.downcast_ref::<IoError>().expect("original I/O error");
|
||||
assert_eq!(source.kind(), ErrorKind::Other);
|
||||
assert_eq!(source.to_string(), "source error");
|
||||
assert!(std::error::Error::source(&ApiError::access_denied()).is_none());
|
||||
}
|
||||
}
|
||||
|
||||
+240
-4
@@ -38,6 +38,7 @@ use hyper::body::Incoming;
|
||||
use pin_project_lite::pin_project;
|
||||
use quick_xml::events::Event;
|
||||
use rustfs_common::GlobalReadiness;
|
||||
use rustfs_io_metrics::s3_http_metrics::S3HttpRequestGuard;
|
||||
use rustfs_obs::HTTP_SERVER_LOG_TARGET;
|
||||
#[cfg(feature = "swift")]
|
||||
use rustfs_protocols::swift::SwiftRouter;
|
||||
@@ -66,6 +67,7 @@ const LOG_SUBSYSTEM_HTTP: &str = "http";
|
||||
const REDACTED_QUERY_VALUE: &str = "redacted";
|
||||
const OBJECT_ZIP_DOWNLOADS_PATH: &str = "/v3/object-zip-downloads/";
|
||||
const HTTP_REQUEST_INFLIGHT_WARN_THRESHOLD: Duration = Duration::from_secs(5);
|
||||
static HTTP_SERVER_ERROR_LOGS: [rustfs_utils::LogThrottle; 100] = [const { rustfs_utils::LogThrottle::new(5_000) }; 100];
|
||||
const STS_RESPONSE_METADATA_TAG: &str = "ResponseMetadata";
|
||||
const STS_REQUEST_ID_TAG: &str = "RequestId";
|
||||
const STS_SUCCESS_RESPONSE_TAGS: [&str; 2] = ["AssumeRoleResponse", "AssumeRoleWithWebIdentityResponse"];
|
||||
@@ -269,10 +271,18 @@ where
|
||||
};
|
||||
req.extensions_mut().insert(request_context);
|
||||
|
||||
// This outer boundary includes readiness, rate-limit and auth
|
||||
// rejections. Metric attribution never depends on an enabled span.
|
||||
let mut metrics = is_s3.then(|| S3HttpRequestGuard::new(req.method().as_str()));
|
||||
let inner = match metrics.as_mut() {
|
||||
Some(metrics) => metrics.in_scope(|| self.inner.call(req)),
|
||||
None => self.inner.call(req),
|
||||
};
|
||||
ExternalRequestContextFuture {
|
||||
inner: self.inner.call(req),
|
||||
inner,
|
||||
request_id,
|
||||
is_s3,
|
||||
metrics,
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -283,6 +293,7 @@ pin_project! {
|
||||
inner: F,
|
||||
request_id: Option<HeaderValue>,
|
||||
is_s3: bool,
|
||||
metrics: Option<S3HttpRequestGuard>,
|
||||
}
|
||||
}
|
||||
|
||||
@@ -294,12 +305,24 @@ where
|
||||
|
||||
fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
|
||||
let this = self.project();
|
||||
let mut response = match this.inner.poll(cx) {
|
||||
let result = match this.metrics.as_mut() {
|
||||
Some(metrics) => metrics.in_scope(|| this.inner.poll(cx)),
|
||||
None => this.inner.poll(cx),
|
||||
};
|
||||
let mut response = match result {
|
||||
Poll::Ready(Ok(response)) => response,
|
||||
Poll::Ready(Err(error)) => return Poll::Ready(Err(error)),
|
||||
Poll::Ready(Err(error)) => {
|
||||
if let Some(metrics) = this.metrics.as_mut() {
|
||||
metrics.service_error();
|
||||
}
|
||||
return Poll::Ready(Err(error));
|
||||
}
|
||||
Poll::Pending => return Poll::Pending,
|
||||
};
|
||||
|
||||
if let Some(metrics) = this.metrics.as_mut() {
|
||||
metrics.response(response.status().as_u16());
|
||||
}
|
||||
if let Some(request_id) = this.request_id.take() {
|
||||
if *this.is_s3 {
|
||||
response.headers_mut().insert(REQUEST_ID_HEADER, request_id.clone());
|
||||
@@ -340,6 +363,7 @@ struct RequestLogContext {
|
||||
uri: Uri,
|
||||
request_started_at: Option<RequestContext>,
|
||||
fallback_start: Instant,
|
||||
has_s3_accounting: bool,
|
||||
}
|
||||
|
||||
impl RequestLogContext {
|
||||
@@ -359,6 +383,7 @@ impl RequestLogContext {
|
||||
uri: req.uri().clone(),
|
||||
request_started_at: request_context,
|
||||
fallback_start: Instant::now(),
|
||||
has_s3_accounting: S3HttpRequestGuard::is_active(),
|
||||
}
|
||||
}
|
||||
|
||||
@@ -427,6 +452,14 @@ impl RequestLogContext {
|
||||
if !tracing::enabled!(target: HTTP_SERVER_LOG_TARGET, Level::ERROR) {
|
||||
return;
|
||||
}
|
||||
let suppressed_errors = if self.has_s3_accounting {
|
||||
let Some(suppressed) = HTTP_SERVER_ERROR_LOGS[usize::from(status_code - 500)].claim() else {
|
||||
return;
|
||||
};
|
||||
suppressed
|
||||
} else {
|
||||
0
|
||||
};
|
||||
error!(
|
||||
target: HTTP_SERVER_LOG_TARGET,
|
||||
event = HTTP_REQUEST_COMPLETED_EVENT,
|
||||
@@ -437,8 +470,9 @@ impl RequestLogContext {
|
||||
span_id = %span_id,
|
||||
peer_addr = %self.peer_addr(),
|
||||
method = %self.method.as_str(),
|
||||
uri = %self.redacted_uri(),
|
||||
uri = self.uri.path(),
|
||||
status_code,
|
||||
suppressed_errors,
|
||||
duration_ms,
|
||||
result,
|
||||
"HTTP request completed"
|
||||
@@ -2232,6 +2266,144 @@ mod tests {
|
||||
PublicHealthEndpointLayer::new(crate::runtime_sources::ServerContextSlot::new(), readiness)
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn external_s3_http_outcomes_cover_response_error_cancel_and_exclusions_at_warn() {
|
||||
use rustfs_io_metrics::{record_s3_op, s3_http_metrics::s3_http_metrics_snapshot};
|
||||
use rustfs_s3_ops::S3Operation;
|
||||
let _logs = tracing::subscriber::set_default(
|
||||
tracing_subscriber::fmt()
|
||||
.with_max_level(tracing::Level::WARN)
|
||||
.with_writer(std::io::sink)
|
||||
.finish(),
|
||||
);
|
||||
let totals = || {
|
||||
s3_http_metrics_snapshot()
|
||||
.into_iter()
|
||||
.filter(|series| series.operation == S3Operation::RestoreObject.as_str())
|
||||
.fold(std::collections::BTreeMap::<String, u64>::new(), |mut result, series| {
|
||||
*result.entry(series.outcome.to_string()).or_default() += series.total;
|
||||
result
|
||||
})
|
||||
};
|
||||
let before = totals();
|
||||
let inner = tower::service_fn(|req: Request<()>| async move {
|
||||
record_s3_op(S3Operation::RestoreObject);
|
||||
match req.uri().path() {
|
||||
"/bucket/cancel" => std::future::pending::<Result<Response<()>, io::Error>>().await,
|
||||
"/bucket/service-error" => Err(io::Error::other("test service failure")),
|
||||
path => Ok(Response::builder()
|
||||
.status(match path {
|
||||
"/bucket/denied" => StatusCode::FORBIDDEN,
|
||||
"/bucket/unavailable" => StatusCode::SERVICE_UNAVAILABLE,
|
||||
_ => StatusCode::OK,
|
||||
})
|
||||
.body(())
|
||||
.expect("response")),
|
||||
}
|
||||
});
|
||||
let mut service = ExternalRequestContextLayer::default().layer(inner);
|
||||
for path in ["/bucket/ok", "/bucket/denied", "/bucket/unavailable"] {
|
||||
let response = service
|
||||
.call(Request::builder().method(Method::PATCH).uri(path).body(()).expect("request"))
|
||||
.await
|
||||
.expect("response");
|
||||
assert!(response.headers().contains_key(AMZ_REQUEST_ID));
|
||||
}
|
||||
let error = service
|
||||
.call(
|
||||
Request::builder()
|
||||
.method(Method::PATCH)
|
||||
.uri("/bucket/service-error")
|
||||
.body(())
|
||||
.expect("request"),
|
||||
)
|
||||
.await;
|
||||
assert!(error.is_err());
|
||||
let mut cancelled = Box::pin(
|
||||
service.call(
|
||||
Request::builder()
|
||||
.method(Method::PATCH)
|
||||
.uri("/bucket/cancel")
|
||||
.body(())
|
||||
.expect("request"),
|
||||
),
|
||||
);
|
||||
assert!(futures::poll!(cancelled.as_mut()).is_pending());
|
||||
drop(cancelled);
|
||||
for path in [
|
||||
"/rustfs/admin/v3/metrics",
|
||||
"/minio/admin/v3/storageinfo",
|
||||
"/rustfs/console/",
|
||||
"/rustfs/rpc/test",
|
||||
"/health/ready",
|
||||
"/_iceberg/v1/config",
|
||||
] {
|
||||
service
|
||||
.call(Request::builder().uri(path).body(()).expect("excluded request"))
|
||||
.await
|
||||
.expect("excluded response");
|
||||
}
|
||||
let after = totals();
|
||||
for outcome in ["2xx", "4xx", "5xx", "service_error", "cancelled"] {
|
||||
assert_eq!(
|
||||
after.get(outcome).copied().unwrap_or_default() - before.get(outcome).copied().unwrap_or_default(),
|
||||
1,
|
||||
"{outcome}"
|
||||
);
|
||||
}
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn external_s3_http_outcomes_include_real_readiness_rejections() {
|
||||
use rustfs_io_metrics::s3_http_metrics::s3_http_metrics_snapshot;
|
||||
let rejected = || {
|
||||
s3_http_metrics_snapshot()
|
||||
.into_iter()
|
||||
.filter(|series| series.method == "TRACE" && series.operation == "unknown" && series.outcome == "5xx")
|
||||
.map(|series| series.total)
|
||||
.sum::<u64>()
|
||||
};
|
||||
let before = rejected();
|
||||
let listener = tokio::net::TcpListener::bind("127.0.0.1:0")
|
||||
.await
|
||||
.expect("isolated HTTP listener");
|
||||
let addr = listener.local_addr().expect("listener address");
|
||||
let server = tokio::spawn(async move {
|
||||
let (stream, _) = listener.accept().await.expect("HTTP client");
|
||||
let service = tower::ServiceBuilder::new()
|
||||
.layer(ExternalRequestContextLayer::default())
|
||||
.layer(crate::server::ReadinessGateLayer::new(Arc::new(GlobalReadiness::new())))
|
||||
.service(StatusService::new(StatusCode::OK));
|
||||
hyper::server::conn::http1::Builder::new()
|
||||
.serve_connection(
|
||||
hyper_util::rt::TokioIo::new(stream),
|
||||
hyper_util::service::TowerToHyperService::new(service),
|
||||
)
|
||||
.await
|
||||
.expect("HTTP connection");
|
||||
});
|
||||
let client = reqwest::Client::builder()
|
||||
.no_proxy()
|
||||
.http1_only()
|
||||
.timeout(Duration::from_secs(5))
|
||||
.build()
|
||||
.expect("local HTTP client");
|
||||
let response = client
|
||||
.request(Method::TRACE, format!("http://{addr}/bucket/object"))
|
||||
.header(http::header::CONNECTION, "close")
|
||||
.send()
|
||||
.await
|
||||
.expect("readiness response");
|
||||
assert_eq!(response.status(), StatusCode::SERVICE_UNAVAILABLE);
|
||||
assert!(response.headers().contains_key(AMZ_REQUEST_ID));
|
||||
let _body = response.bytes().await.expect("readiness body");
|
||||
tokio::time::timeout(Duration::from_secs(5), server)
|
||||
.await
|
||||
.expect("bounded HTTP server shutdown")
|
||||
.expect("server task");
|
||||
assert_eq!(rejected() - before, 1, "rejection is counted before the inner trace layer");
|
||||
}
|
||||
|
||||
async fn public_health_layer_with_tracker(object_traffic_health: Arc<ObjectTrafficHealth>) -> PublicHealthEndpointLayer {
|
||||
let readiness = Arc::new(GlobalReadiness::new());
|
||||
readiness.mark_stage(rustfs_common::SystemStage::FullReady);
|
||||
@@ -5135,6 +5307,70 @@ mod tests {
|
||||
assert_eq!(redact_sensitive_uri_query(&uri), "/rustfs/admin/v3/users?token=not-a-download-token");
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn request_logging_bounds_s3_failure_bursts_without_losing_counts_or_leaking_queries() {
|
||||
use rustfs_io_metrics::s3_http_metrics::s3_http_metrics_snapshot;
|
||||
let count = || {
|
||||
s3_http_metrics_snapshot()
|
||||
.iter()
|
||||
.filter(|series| series.method == "CONNECT" && series.operation == "unknown" && series.outcome == "5xx")
|
||||
.map(|series| series.total)
|
||||
.sum::<u64>()
|
||||
};
|
||||
let before = count();
|
||||
let writer = SharedWriter::default();
|
||||
let captured = writer.buffer.clone();
|
||||
let _subscriber = tracing::subscriber::set_default(
|
||||
tracing_subscriber::fmt()
|
||||
.with_max_level(tracing::Level::WARN)
|
||||
.without_time()
|
||||
.with_ansi(false)
|
||||
.with_writer(writer)
|
||||
.finish(),
|
||||
);
|
||||
// A distinct status isolates this test's process-wide log window.
|
||||
let mut service = tower::ServiceBuilder::new()
|
||||
.layer(ExternalRequestContextLayer::default())
|
||||
.layer(RequestLoggingLayer)
|
||||
.service(StatusService::new(StatusCode::from_u16(599).expect("server error")));
|
||||
for _ in 0..10 {
|
||||
service
|
||||
.call(
|
||||
Request::builder()
|
||||
.method(Method::CONNECT)
|
||||
.uri("/bucket/object?X-Amz-Signature=private-signature&X-Amz-Security-Token=private-session")
|
||||
.body(())
|
||||
.expect("request"),
|
||||
)
|
||||
.await
|
||||
.expect("response");
|
||||
}
|
||||
assert_eq!(count() - before, 10);
|
||||
let output = String::from_utf8(captured.lock().expect("logs").clone()).expect("UTF-8 logs");
|
||||
assert_eq!(output.matches("http_request_completed").count(), 1, "{output}");
|
||||
assert!(output.contains("/bucket/object"));
|
||||
assert!(!output.contains("private-"));
|
||||
assert!(!output.contains("X-Amz-"));
|
||||
for _ in 0..2 {
|
||||
service
|
||||
.call(
|
||||
Request::builder()
|
||||
.uri("/rustfs/admin/v3/info")
|
||||
.body(())
|
||||
.expect("admin request"),
|
||||
)
|
||||
.await
|
||||
.expect("admin response");
|
||||
}
|
||||
let output = String::from_utf8(captured.lock().expect("logs").clone()).expect("UTF-8 logs");
|
||||
assert_eq!(
|
||||
output.matches("http_request_completed").count(),
|
||||
3,
|
||||
"admin logging is not throttled: {output}"
|
||||
);
|
||||
assert_eq!(count() - before, 10);
|
||||
}
|
||||
|
||||
#[tokio::test]
|
||||
async fn request_logging_layer_emits_single_completion_event_with_standard_fields() {
|
||||
let writer = SharedWriter::default();
|
||||
|
||||
@@ -1381,6 +1381,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: Vec::new(),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert_eq!(pool_erasure_layout(&info, 0, 4), Some((2, 2)));
|
||||
@@ -1401,6 +1402,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: Vec::new(),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert_eq!(pool_write_quorum(&info, 0, 8), Some(6));
|
||||
@@ -1419,6 +1421,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: online_readiness_disks(0, 8),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert_eq!(pool_erasure_layout(&info, 0, 8), Some((6, 2)));
|
||||
@@ -1437,6 +1440,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: online_readiness_disks(0, 8),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert_eq!(pool_erasure_layout(&info, 0, 8), None);
|
||||
@@ -1453,6 +1457,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: Vec::new(),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert_eq!(pool_erasure_layout(&info, 0, 4), Some((3, 1)));
|
||||
@@ -1468,6 +1473,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: online_readiness_disks(0, 3),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert_eq!(pool_erasure_layout(&info, 0, 3), Some((2, 1)));
|
||||
@@ -1487,10 +1493,12 @@ mod tests {
|
||||
let three_online = StorageInfo {
|
||||
backend: backend.clone(),
|
||||
disks: online_readiness_disks(0, 3),
|
||||
..Default::default()
|
||||
};
|
||||
let two_online = StorageInfo {
|
||||
backend,
|
||||
disks: online_readiness_disks(0, 2),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(storage_read_ready_from_runtime_state(&three_online));
|
||||
@@ -1510,6 +1518,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: online_readiness_disks(0, 3),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(!storage_read_ready_from_runtime_state(&info));
|
||||
@@ -1525,6 +1534,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: online_readiness_disks(0, 3),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(!storage_read_ready_from_runtime_state(&info));
|
||||
@@ -1540,6 +1550,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: online_readiness_disks(0, 3),
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(!storage_read_ready_from_runtime_state(&info));
|
||||
@@ -1566,6 +1577,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks,
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(!storage_ready_from_runtime_state(&info));
|
||||
@@ -1588,6 +1600,7 @@ mod tests {
|
||||
runtime_state: Some("offline".to_string()),
|
||||
..Default::default()
|
||||
}],
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(!storage_ready_from_runtime_state(&info));
|
||||
@@ -1609,6 +1622,7 @@ mod tests {
|
||||
runtime_state: Some("online".to_string()),
|
||||
..Default::default()
|
||||
}],
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(storage_ready_from_runtime_state(&info));
|
||||
@@ -1637,12 +1651,47 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks,
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(storage_read_ready_from_runtime_state(&info));
|
||||
assert!(!storage_ready_from_runtime_state(&info));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn unknown_inventory_does_not_supply_quorum_evidence() {
|
||||
let mut info = StorageInfo {
|
||||
backend: BackendInfo {
|
||||
standard_sc_data: vec![2],
|
||||
total_sets: vec![1],
|
||||
drives_per_set: vec![4],
|
||||
..Default::default()
|
||||
},
|
||||
disks: (0..4)
|
||||
.map(|disk_index| Disk {
|
||||
endpoint: format!("node-{disk_index}"),
|
||||
pool_index: 0,
|
||||
set_index: 0,
|
||||
disk_index,
|
||||
state: "ok".to_string(),
|
||||
runtime_state: Some("online".to_string()),
|
||||
..Default::default()
|
||||
})
|
||||
.collect(),
|
||||
..Default::default()
|
||||
};
|
||||
assert!(storage_ready_from_runtime_state(&info));
|
||||
for disk in &mut info.disks[2..] {
|
||||
disk.state = rustfs_madmin::ITEM_UNKNOWN.to_string();
|
||||
disk.runtime_state = Some(rustfs_madmin::ITEM_UNKNOWN.to_string());
|
||||
}
|
||||
assert!(storage_read_ready_from_runtime_state(&info));
|
||||
assert!(!storage_ready_from_runtime_state(&info));
|
||||
assert_eq!(pool_read_quorum(&info, 0, 4), Some(2));
|
||||
assert_eq!(pool_write_quorum(&info, 0, 4), Some(3));
|
||||
assert!(info.disks.iter().all(|disk| disk.state != rustfs_madmin::ITEM_OFFLINE));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn storage_ready_from_runtime_state_deduplicates_duplicate_disk_rows() {
|
||||
let duplicate_disk = Disk {
|
||||
@@ -1663,6 +1712,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: vec![duplicate_disk.clone(), duplicate_disk],
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(!storage_ready_from_runtime_state(&info), "duplicate rows must not satisfy write quorum");
|
||||
@@ -1719,6 +1769,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
],
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert!(
|
||||
|
||||
@@ -360,6 +360,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks,
|
||||
..Default::default()
|
||||
}
|
||||
}
|
||||
|
||||
@@ -534,6 +535,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: vec![first, second],
|
||||
..Default::default()
|
||||
};
|
||||
let captured = CapturedLog::default();
|
||||
let subscriber = tracing_subscriber::fmt()
|
||||
@@ -593,6 +595,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: vec![pool_zero, pool_one],
|
||||
..Default::default()
|
||||
};
|
||||
assert_eq!(inventory_capacity(&incomplete_widths).expect("numeric fallback"), (300, 120));
|
||||
}
|
||||
@@ -614,6 +617,7 @@ mod tests {
|
||||
..Default::default()
|
||||
},
|
||||
disks: vec![pool_zero_set_zero, pool_zero_set_one, pool_one],
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
assert_eq!(inventory_capacity(&info).expect("configured topology"), (400, 160));
|
||||
|
||||
@@ -119,6 +119,7 @@ mod tests {
|
||||
drives_per_set: vec![4],
|
||||
..Default::default()
|
||||
},
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
let buf = encode_msgpack_map(&value).unwrap();
|
||||
|
||||
@@ -268,6 +268,7 @@ mod tests {
|
||||
drives_per_set: vec![4, 4],
|
||||
..Default::default()
|
||||
},
|
||||
..Default::default()
|
||||
};
|
||||
|
||||
let encoded = encode_msgpack_map(&info).expect("storage info should serialize");
|
||||
|
||||
@@ -76,6 +76,8 @@ pub(crate) mod config_test {
|
||||
|
||||
pub(crate) mod error {
|
||||
pub(crate) mod contract {
|
||||
pub(crate) use super::super::storage_contracts::error::StorageErrorCode;
|
||||
|
||||
pub(crate) mod range {
|
||||
pub(crate) use super::super::super::storage_contracts::HTTPRangeError;
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user