refactor(logging): normalize admin telemetry and error messages (#3430)

This commit is contained in:
houseme
2026-06-14 13:27:10 +08:00
committed by GitHub
parent dc82efbab4
commit e8012bd1ba
70 changed files with 4807 additions and 1445 deletions
@@ -77,7 +77,7 @@ use tokio::sync::mpsc::{Receiver, Sender};
use tokio::sync::{RwLock, mpsc};
use tokio::task::JoinHandle;
use tokio_util::sync::CancellationToken;
use tracing::{debug, error, info, warn};
use tracing::{debug, error, warn};
use uuid::Uuid;
use xxhash_rust::xxh64;
@@ -762,13 +762,13 @@ impl TransitionState {
"Transition compensation backfill failed"
);
} else {
info!(
debug!(
event = EVENT_LIFECYCLE_TRANSITION_COMPENSATION,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_LIFECYCLE,
bucket = %bucket,
state = "completed",
"Completed transition compensation backfill"
"Transition compensation completed"
);
}
@@ -958,7 +958,7 @@ impl TransitionState {
pub async fn init(api: Arc<ECStore>) {
let (configured, absolute_max, n) = resolve_transition_worker_count();
info!(
debug!(
event = EVENT_LIFECYCLE_WORKER_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_LIFECYCLE,
@@ -968,7 +968,7 @@ impl TransitionState {
transition_queue_capacity = GLOBAL_TransitionState.transition_queue_capacity,
transition_queue_send_timeout_ms = GLOBAL_TransitionState.transition_queue_send_timeout.as_millis() as u64,
state = "configured",
"Lifecycle worker state resolved"
"Lifecycle worker configuration resolved"
);
//let mut transition_state = GLOBAL_TransitionState.write().await;
@@ -1158,7 +1158,7 @@ impl TransitionState {
GLOBAL_TransitionState.num_workers.store(current_workers, Ordering::SeqCst);
GLOBAL_TransitionState.record_scanner_transition_state();
info!(
debug!(
event = EVENT_LIFECYCLE_WORKER_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_LIFECYCLE,
@@ -1169,7 +1169,7 @@ impl TransitionState {
current_transition_workers = current_workers,
pruned_finished_transition_workers = pruned_finished_workers,
state = "resized",
"Lifecycle worker state updated"
"Lifecycle worker pool resized"
);
}
}
@@ -2008,14 +2008,14 @@ pub fn audit_tier_actions(_tier: &str, bytes: i64) -> TimeFn {
Arc::new(move || {
let tier = tier.clone();
Box::pin(async move {
info!(
debug!(
event = EVENT_LIFECYCLE_TIER_AUDIT,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_LIFECYCLE,
tier = %tier,
bytes = bytes,
state = "transition_completed",
"Lifecycle tier transition audit completed"
"Lifecycle tier transition recorded"
);
})
})
+87 -11
View File
@@ -29,7 +29,11 @@ use tokio::io::AsyncRead;
use tokio::spawn;
use tokio::time::timeout;
use tokio_util::sync::CancellationToken;
use tracing::{error, info, warn};
use tracing::{error, warn};
const LOG_COMPONENT_ECSTORE: &str = "ecstore";
const LOG_SUBSYSTEM_METACACHE: &str = "metacache";
const EVENT_METACACHE_LISTING: &str = "metacache_listing";
pub type AgreedFn = Box<dyn Fn(MetaCacheEntry) -> Pin<Box<dyn Future<Output = ()> + Send>> + Send + 'static>;
pub type PartialFn =
@@ -114,6 +118,9 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
return Err(DiskError::ErasureReadQuorum);
}
let log_bucket = opts.bucket.clone();
let log_path = opts.path.clone();
let mut jobs: Vec<tokio::task::JoinHandle<std::result::Result<(), DiskError>>> = Vec::new();
let mut readers = Vec::with_capacity(opts.disks.len());
let fds = opts.fallback_disks.iter().flatten().cloned().collect::<VecDeque<_>>();
@@ -180,7 +187,17 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
match disk.walk_dir(wakl_opts, &mut wr).await {
Ok(_res) => {}
Err(err) => {
info!("walk dir err {:?}", &err);
warn!(
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
bucket = %opts_clone.bucket,
path = %opts_clone.path,
disk_index = disk_idx,
state = "walk_dir_failed",
error = ?err,
"Metacache walk_dir failed"
);
last_err = Some(err);
need_fallback = true;
}
@@ -205,7 +222,16 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
}
let Some(disk) = disk_op else {
warn!("list_path_raw: fallback disk is none");
warn!(
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
bucket = %opts_clone.bucket,
path = %opts_clone.path,
disk_index = disk_idx,
state = "fallback_disk_missing",
"Metacache fallback disk missing"
);
let err = last_err.unwrap_or(DiskError::DiskNotFound);
record_producer_error(&producer_errs_clone, disk_idx, &err);
return Err(err);
@@ -234,7 +260,17 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
last_err = None;
}
Err(err) => {
error!("walk dir2 err {:?}", &err);
error!(
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
bucket = %opts_clone.bucket,
path = %opts_clone.path,
disk_index = disk_idx,
state = "fallback_walk_dir_failed",
error = ?err,
"Metacache fallback walk_dir failed"
);
last_err = Some(err);
}
}
@@ -355,11 +391,15 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
)
.increment(1);
warn!(
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
drive = %endpoint,
bucket = %opts.bucket,
path = %opts.path,
timeout_ms = peek_timeout.as_millis(),
"list_path_raw reader peek timed out; excluding drive from current merge"
state = "peek_timed_out",
"Metacache reader peek timed out"
);
let (detached_rd, write_half) = tokio::io::duplex(1);
drop(write_half);
@@ -439,8 +479,14 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
});
error!(
"list_path_raw: has_err > 0 && has_err > opts.disks.len() - opts.min_disks break, err: {:?}",
&combined_err.join(", ")
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
bucket = %opts.bucket,
path = %opts.path,
state = "quorum_failed",
error = %combined_err.join(", "),
"Metacache listing quorum failed"
);
return Err(DiskError::other(combined_err.join(", ")));
}
@@ -493,7 +539,16 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
});
if let Err(err) = revjob.await.map_err(std::io::Error::other)? {
error!("list_path_raw: revjob err {:?}", err);
error!(
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
bucket = %log_bucket,
path = %log_path,
state = "merge_job_failed",
error = ?err,
"Metacache merge job failed"
);
cancel_rx.cancel();
for job in jobs {
job.abort();
@@ -521,9 +576,23 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
Ok(Ok(())) => {}
Ok(Err(err)) => {
if matches!(err, DiskError::FileNotFound | DiskError::VolumeNotFound) {
warn!("list_path_raw producer missing path {:?}", err);
warn!(
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
state = "producer_missing_path",
error = ?err,
"Metacache producer missing path"
);
} else {
error!("list_path_raw producer err {:?}", err);
error!(
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
state = "producer_failed",
error = ?err,
"Metacache producer failed"
);
}
job_errs.push(err);
}
@@ -531,7 +600,14 @@ pub async fn list_path_raw(rx: CancellationToken, opts: ListPathRawOptions) -> d
if err.is_cancelled() {
continue;
}
error!("list_path_raw join err {:?}", err);
error!(
event = EVENT_METACACHE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_METACACHE,
state = "producer_join_failed",
error = ?err,
"Metacache producer join failed"
);
job_errs.push(err.into());
}
}
+28 -4
View File
@@ -472,7 +472,15 @@ fn resolve_local_disk_root(ep_path: &str) -> Result<PathBuf> {
impl LocalDisk {
pub async fn new(ep: &Endpoint, cleanup: bool) -> Result<Self> {
debug!("Creating local disk");
debug!(
event = EVENT_DISK_LOCAL_STARTUP_CLEANUP,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_DISK_LOCAL,
endpoint = %ep,
state = "create_started",
cleanup,
"Local disk creation started"
);
let endpoint_path = ep.get_file_path();
let root = resolve_local_disk_root(&endpoint_path).inspect_err(|err| {
log_startup_disk_error("resolve_local_disk_root", Path::new(&endpoint_path), err);
@@ -501,13 +509,21 @@ impl LocalDisk {
root = ?root,
state = "failed",
error = ?err,
"Disk local startup cleanup failed"
"Local disk startup cleanup failed"
);
}
// Use optimized path resolution instead of absolutize_virtually
let format_path = root.join(RUSTFS_META_BUCKET).join(super::FORMAT_CONFIG_FILE);
debug!("format_path: {:?}", format_path);
debug!(
event = EVENT_DISK_LOCAL_STARTUP_CLEANUP,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_DISK_LOCAL,
root = ?root,
format_path = ?format_path,
state = "format_path_resolved",
"Local disk format path resolved"
);
let (format_data, format_meta) = read_file_exists(&format_path).await.inspect_err(|err| {
log_startup_disk_error("read_format_json", &format_path, err);
})?;
@@ -639,7 +655,15 @@ impl LocalDisk {
let root = disk.root.clone();
tokio::spawn(Self::cleanup_deleted_objects_loop(root, exit_rx));
debug!("LocalDisk created: {:?}", disk);
debug!(
event = EVENT_DISK_LOCAL_STARTUP_CLEANUP,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_DISK_LOCAL,
endpoint = %disk.endpoint,
root = ?disk.root,
state = "created",
"Local disk created"
);
Ok(disk)
}
+323 -43
View File
@@ -71,6 +71,12 @@ use time::{Duration, OffsetDateTime};
use tokio_util::sync::CancellationToken;
use tracing::{debug, error, info, warn};
const LOG_COMPONENT_ECSTORE: &str = "ecstore";
const LOG_SUBSYSTEM_POOLS: &str = "pools";
const EVENT_DECOMMISSION_STATE: &str = "decommission_state";
const EVENT_DECOMMISSION_BUCKET: &str = "decommission_bucket";
const EVENT_DECOMMISSION_ENTRY: &str = "decommission_entry";
pub const POOL_META_NAME: &str = "pool.bin";
pub const POOL_META_FORMAT: u16 = 1;
pub const POOL_META_VERSION: u16 = 1;
@@ -1280,7 +1286,15 @@ impl ECStore {
take_decommission_canceler(cancelers.as_mut_slice(), idx)
};
if !cancel_decommission_canceler(canceler) {
warn!("decommission_cancel: no active canceler found for pool {}", idx);
warn!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
state = "cancel_skipped",
reason = "no_active_canceler",
"Decommission cancel skipped"
);
}
if should_reload_pool_meta && let Some(notification_sys) = get_global_notification_sys() {
@@ -1338,7 +1352,15 @@ impl ECStore {
let store = store.clone();
tokio::spawn(async move {
if let Err(err) = store.do_decommission_in_routine(canceler, idx).await {
error!("decommission: routine failed for idx {}: {err}", idx);
error!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
state = "routine_failed",
error = %err,
"Decommission routine failed"
);
}
});
}
@@ -1350,7 +1372,14 @@ impl ECStore {
pub async fn decommission(&self, rx: CancellationToken, indices: Vec<usize>) -> Result<()> {
let indices = dedup_indices(&indices);
warn!("decommission: {:?}", indices);
info!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_indices = ?indices,
state = "requested",
"Decommission requested"
);
validate_start_decommission_request(&indices, self.single_pool())?;
ensure_decommission_not_rebalancing(self.is_rebalance_conflicting_with_decommission().await)?;
@@ -1363,8 +1392,13 @@ impl ECStore {
for idx in indices {
if let Err(cancel_err) = self.decommission_cancel(idx).await {
error!(
"decommission: failed to rollback decommission state for idx {} after spawn error: {:?}",
idx, cancel_err
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
state = "rollback_failed",
error = ?cancel_err,
"Decommission rollback failed after spawn error"
);
if rollback_err.is_none() {
rollback_err = Some(Error::other(format!("decommission rollback failed for idx {idx}: {cancel_err}")));
@@ -1390,10 +1424,28 @@ impl ECStore {
lock_retention: Option<DefaultRetention>,
replication_config: Option<(ReplicationConfiguration, OffsetDateTime)>,
) -> Result<()> {
warn!("decommission_entry: {} {}", &bucket, &entry.name);
debug!(
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %entry.name,
state = "started",
"Decommission entry started"
);
wk.give().await;
if entry.is_dir() {
warn!("decommission_entry: skip dir {}", &entry.name);
debug!(
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %entry.name,
state = "skipped_directory",
"Decommission entry skipped directory"
);
return Ok(());
}
@@ -1426,7 +1478,16 @@ impl ECStore {
if should_skip_decommission_delete_marker(version, remaining_versions, replication_config.is_some()) {
//
decommissioned += 1;
info!("decommission_pool: DELETE marked object with no other non-current versions will be skipped");
debug!(
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %version.name,
state = "skipped_delete_marker",
"Decommission delete marker skipped"
);
continue;
}
@@ -1447,8 +1508,16 @@ impl ECStore {
{
if is_err_object_not_found(&err) || is_err_version_not_found(&err) || is_err_data_movement_overwrite(&err) {
warn!(
"decommission_pool: ignore delete-marker copy for {}/{} version {:?}: {:?}",
&bucket, &version.name, &version_id, &err
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %version.name,
version_id = ?version_id,
state = "ignored_delete_marker_copy",
error = ?err,
"Decommission delete marker copy ignored"
);
ignore = true;
cleanup_ignored = true;
@@ -1463,7 +1532,16 @@ impl ECStore {
if should_count_decommission_version_complete(ignore, cleanup_ignored, failure) {
decommissioned += 1;
}
info!("decommission_pool: ignore {}", &version.name);
debug!(
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %version.name,
state = "ignored",
"Decommission entry ignored"
);
continue;
}
@@ -1483,9 +1561,17 @@ impl ECStore {
decommissioned += 1;
}
info!(
"decommission_pool: DecomCopyDeleteMarker {} {} {:?} {:?}",
&bucket, &version.name, &version_id, error
debug!(
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %version.name,
version_id = ?version_id,
result = ?error,
state = "delete_marker_copied",
"Decommission delete marker copied"
);
continue;
}
@@ -1571,8 +1657,15 @@ impl ECStore {
}
warn!(
"decommission_pool: decommission_object done {}/{} {}",
&bucket_name, &object_name, &version.name
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket_name,
object = %object_name,
version = %version.name,
state = "object_migrated",
"Decommission object migrated"
);
failure = false;
@@ -1583,7 +1676,16 @@ impl ECStore {
if should_count_decommission_version_complete(ignore, cleanup_ignored, failure) {
decommissioned += 1;
}
info!("decommission_pool: ignore {}", &version.name);
debug!(
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %version.name,
state = "ignored",
"Decommission entry ignored"
);
continue;
}
@@ -1624,12 +1726,17 @@ impl ECStore {
resolve_decommission_entry_cleanup_delete_result(cleanup_result, bucket.as_str(), entry.name.as_str())?
} else if decommissioned != fivs.versions.len() || expired > 0 {
warn!(
"decommission_pool: source object retained for {}/{} because only {}/{} versions were decommissioned and {} expired by lifecycle",
&bucket,
&entry.name,
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %entry.name,
decommissioned,
fivs.versions.len(),
expired
total_versions = fivs.versions.len(),
expired,
state = "source_retained",
"Decommission source object retained"
);
}
@@ -1667,7 +1774,16 @@ impl ECStore {
}
}
warn!("decommission_pool: decommission_entry done {} {}", &bucket, &entry.name);
debug!(
event = EVENT_DECOMMISSION_ENTRY,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bucket,
object = %entry.name,
state = "completed",
"Decommission entry completed"
);
Ok(())
}
@@ -1705,7 +1821,16 @@ impl ECStore {
for (set_idx, set) in pool.disk_set.iter().enumerate() {
wk.clone().take().await;
warn!("decommission_pool: decommission_pool {} {}", set_idx, &bi.name);
debug!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
set_index = set_idx,
bucket = %bi.name,
state = "listing_worker_started",
"Decommission listing worker started"
);
let decommission_entry: ListCallback = Arc::new({
let this = Arc::clone(self);
@@ -1753,23 +1878,69 @@ impl ECStore {
let worker = tokio::spawn(async move {
loop {
if rx_clone.is_cancelled() {
warn!("decommission_pool: cancel {}", set_id);
debug!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
set_index = set_id,
bucket = %bi.name,
state = "listing_worker_cancelled",
"Decommission listing worker cancelled"
);
break;
}
warn!("decommission_pool: list_objects_to_decommission {} {}", set_id, &bi.name);
debug!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
set_index = set_id,
bucket = %bi.name,
state = "listing_started",
"Decommission listing started"
);
match set
.list_objects_to_decommission(rx_clone.clone(), bi.clone(), decommission_entry.clone())
.await
{
Ok(_) => {
warn!("decommission_pool: list_objects_to_decommission {} done", set_id);
debug!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
set_index = set_id,
bucket = %bi.name,
state = "listing_completed",
"Decommission listing completed"
);
break;
}
Err(err) => {
error!("decommission_pool: list_objects_to_decommission {} err {:?}", set_id, &err);
error!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
set_index = set_id,
bucket = %bi.name,
state = "listing_failed",
error = ?err,
"Decommission listing failed"
);
if is_err_bucket_not_found(&err) {
warn!("decommission_pool: list_objects_to_decommission {} volume not found", set_id);
warn!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
set_index = set_id,
bucket = %bi.name,
state = "listing_bucket_missing",
"Decommission listing bucket missing"
);
break;
}
@@ -1783,7 +1954,15 @@ impl ECStore {
listing_workers.push((set_id, worker));
}
warn!("decommission_pool: decommission_pool wait {} {}", idx, &bi.name);
debug!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bi.name,
state = "waiting_for_workers",
"Decommission waiting for workers"
);
let mut listing_worker_error = None;
for (set_id, worker) in listing_workers {
@@ -1807,11 +1986,28 @@ impl ECStore {
}
if let Err(err) = decommission_cancel_signal_result(rx.is_cancelled()) {
warn!("decommission_pool: canceled after wait {} {}", idx, &bi.name);
warn!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bi.name,
state = "cancelled_after_wait",
error = %err,
"Decommission bucket cancelled after wait"
);
return Err(err);
}
warn!("decommission_pool: decommission_pool done {} {}", idx, &bi.name);
debug!(
event = EVENT_DECOMMISSION_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
bucket = %bi.name,
state = "completed",
"Decommission bucket completed"
);
Ok(())
}
@@ -1821,7 +2017,14 @@ impl ECStore {
defer!(|| async {
let mut cancelers = self.decommission_cancelers.write().await;
if take_decommission_canceler(cancelers.as_mut_slice(), idx).is_none() {
warn!("decommission: canceler already cleared for pool {}", idx);
warn!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
state = "canceler_already_cleared",
"Decommission canceler already cleared"
);
}
});
@@ -1830,7 +2033,14 @@ impl ECStore {
let (final_state, canceled, cmd_line) = {
let pool_meta = self.pool_meta.read().await;
let Some(pool) = pool_meta.pools.get(idx) else {
error!("decommission: pool metadata missing for idx {}", idx);
error!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
state = "pool_metadata_missing",
"Decommission pool metadata missing"
);
return Err(Error::other(format!(
"failed to resolve decommission final state: pool metadata missing for idx {idx}"
)));
@@ -1849,29 +2059,75 @@ impl ECStore {
};
if let Err(err) = result {
error!("decom err {:?}", &err);
error!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
state = "background_failed",
error = ?err,
"Decommission background routine failed"
);
if is_err_operation_canceled(&err) || should_preserve_decommission_canceled_state(canceled, rx.is_cancelled()) {
warn!("decommission: canceled for pool {}, preserving canceled state", cmd_line);
warn!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
cmd_line = %cmd_line,
state = "cancelled_preserved",
"Decommission cancelled; preserving canceled state"
);
return Ok(());
}
resolve_decommission_terminal_mark_after_error_result(self.decommission_failed(idx).await, idx, &err)?;
warn!("decommission: decommission_failed {}", idx);
warn!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
state = "marked_failed",
"Decommission marked failed"
);
return Ok(());
}
warn!("decommission: decommission_in_background complete {}", idx);
debug!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
state = "background_complete",
"Decommission background routine completed"
);
if should_preserve_decommission_canceled_state(canceled, rx.is_cancelled()) {
warn!("decommission: canceled for pool {}, skipping terminal state overwrite", cmd_line);
warn!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
cmd_line = %cmd_line,
state = "terminal_state_preserved",
"Decommission terminal state preserved after cancellation"
);
return Ok(());
}
match final_state {
DecommissionFinalState::Complete => {
warn!("Decommissioning complete for pool {}, verifying for any pending objects", cmd_line);
debug!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
cmd_line = %cmd_line,
state = "verifying_completion",
"Decommission completion verification started"
);
if let Err(err) = self.check_after_decommission(idx).await {
resolve_decommission_terminal_mark_result(self.decommission_failed(idx).await, "failed", &cmd_line)?;
return Err(Error::other(format!(
@@ -1879,16 +2135,40 @@ impl ECStore {
)));
}
warn!("Decommissioning complete for pool {}, marking completed state", cmd_line);
info!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
cmd_line = %cmd_line,
state = "marking_completed",
"Decommission marking completed state"
);
resolve_decommission_terminal_mark_result(self.complete_decommission(idx).await, "completed", &cmd_line)?;
}
DecommissionFinalState::Failed => {
warn!("Decommissioning finished with failed items for pool {}, marking failed state", cmd_line);
warn!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
cmd_line = %cmd_line,
state = "marking_failed",
"Decommission marking failed state"
);
resolve_decommission_terminal_mark_result(self.decommission_failed(idx).await, "failed", &cmd_line)?;
}
}
warn!("Decommissioning complete for pool {}", cmd_line);
info!(
event = EVENT_DECOMMISSION_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_POOLS,
pool_index = idx,
cmd_line = %cmd_line,
state = "completed",
"Decommission completed"
);
Ok(())
}
+176 -30
View File
@@ -858,7 +858,14 @@ impl ECStore {
"init_rebalance_meta",
)?;
info!("init_rebalance_meta: rebalance meta saved");
info!(
event = EVENT_REBALANCE_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
state = "metadata_initialized",
bucket_count = bucktes.len(),
"Rebalance metadata initialized"
);
let id = meta.id.clone();
@@ -898,9 +905,16 @@ impl ECStore {
#[tracing::instrument(skip(self))]
pub async fn next_rebal_bucket(&self, pool_index: usize) -> Result<Option<String>> {
info!("next_rebal_bucket: pool_index: {}", pool_index);
let rebalance_meta = self.rebalance_meta.read().await;
info!("next_rebal_bucket: rebalance_meta: {:?}", rebalance_meta);
debug!(
event = EVENT_REBALANCE_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
has_meta = rebalance_meta.is_some(),
state = "next_bucket_lookup",
"Rebalance next bucket lookup"
);
resolve_next_rebalance_bucket(rebalance_meta.as_ref(), pool_index)
}
@@ -931,20 +945,38 @@ impl ECStore {
let rebalance_meta = self.rebalance_meta.read().await;
if let Some(meta) = rebalance_meta.as_ref() {
meta.pool_stats.iter().enumerate().for_each(|(i, v)| {
info!(
"is_rebalance_started: pool_index: {}, participating: {:?}, status: {:?}",
i, v.participating, v.info.status
debug!(
event = EVENT_REBALANCE_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index = i,
participating = v.participating,
status = ?v.info.status,
state = "status_inspected",
"Rebalance status inspected"
);
});
let started = is_rebalance_conflicting_with_decommission(meta);
if started {
info!("is_rebalance_started: rebalance started");
debug!(
event = EVENT_REBALANCE_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
state = "running",
"Rebalance is running"
);
return true;
}
}
info!("is_rebalance_started: rebalance not started");
debug!(
event = EVENT_REBALANCE_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
state = "not_running",
"Rebalance is not running"
);
false
}
@@ -1108,15 +1140,23 @@ impl ECStore {
workers_started += 1;
tokio::spawn(async move {
if let Err(err) = store.rebalance_buckets(rx_clone, pool_idx).await {
error!("Rebalance failed for pool {}: {}", pool_idx, err);
error!(
event = EVENT_REBALANCE_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index = pool_idx,
state = "pool_failed",
error = %err,
"Rebalance pool failed"
);
} else {
info!(
debug!(
event = EVENT_REBALANCE_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index = pool_idx,
state = "completed",
"Completed rebalance pool"
"Rebalance pool completed"
);
}
});
@@ -1139,7 +1179,8 @@ impl ECStore {
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
state = "started",
"Started rebalance"
worker_count = workers_started,
"Rebalance started"
);
Ok(())
}
@@ -1240,7 +1281,7 @@ impl ECStore {
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
state = "pool_started",
"Started rebalance worker"
"Rebalance worker started"
);
let mut final_result: Result<()> = Ok(());
let mut deferred_buckets = HashSet::new();
@@ -1267,7 +1308,15 @@ impl ECStore {
let next_bucket = match self.next_rebal_bucket(pool_index).await {
Ok(bucket) => bucket,
Err(err) => {
error!("next_rebal_bucket failed for pool {}: {:?}", pool_index, err);
error!(
event = EVENT_REBALANCE_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
state = "next_bucket_failed",
error = ?err,
"Rebalance next bucket lookup failed"
);
final_result = Err(resolve_rebalance_terminal_error(
err.clone(),
send_rebalance_done_signal(&done_tx, Err(err.clone()), pool_index).await,
@@ -1294,7 +1343,16 @@ impl ECStore {
) {
Ok(outcome) => outcome,
Err(err) => {
error!("Error rebalancing bucket {}: {:?}", bucket, err);
error!(
event = EVENT_REBALANCE_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
bucket = %bucket,
state = "bucket_failed",
error = ?err,
"Rebalance bucket failed"
);
final_result = Err(resolve_rebalance_terminal_error(
err.clone(),
send_rebalance_done_signal(&done_tx, Err(err.clone()), pool_index).await,
@@ -1308,7 +1366,16 @@ impl ECStore {
let err = Error::other(format!(
"rebalance bucket {bucket} deferred repeatedly due to transient object failures: {last_error}"
));
error!("Error rebalancing bucket {}: {:?}", bucket, err);
error!(
event = EVENT_REBALANCE_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
bucket = %bucket,
state = "bucket_deferred_repeatedly",
error = ?err,
"Rebalance bucket failed after repeated deferral"
);
final_result = Err(resolve_rebalance_terminal_error(
err.clone(),
send_rebalance_done_signal(&done_tx, Err(err.clone()), pool_index).await,
@@ -1327,7 +1394,16 @@ impl ECStore {
"Deferred rebalance bucket after transient object failures"
);
if let Err(err) = self.defer_rebalance_bucket(pool_index, bucket.clone(), last_error).await {
error!("defer_rebalance_bucket failed for pool {}: {:?}", pool_index, err);
error!(
event = EVENT_REBALANCE_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
bucket = %bucket,
state = "defer_failed",
error = ?err,
"Rebalance bucket defer failed"
);
final_result = Err(resolve_rebalance_terminal_error(
err.clone(),
send_rebalance_done_signal(&done_tx, Err(err.clone()), pool_index).await,
@@ -1347,7 +1423,15 @@ impl ECStore {
"Completed rebalance bucket"
);
if let Err(err) = self.bucket_rebalance_done(pool_index, bucket).await {
error!("bucket_rebalance_done failed for pool {}: {:?}", pool_index, err);
error!(
event = EVENT_REBALANCE_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
state = "bucket_done_mark_failed",
error = ?err,
"Rebalance bucket completion mark failed"
);
final_result = Err(resolve_rebalance_terminal_error(
err.clone(),
send_rebalance_done_signal(&done_tx, Err(err.clone()), pool_index).await,
@@ -1374,7 +1458,7 @@ impl ECStore {
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
state = "pool_done",
"Finished rebalance worker"
"Rebalance worker finished"
);
if final_result.is_ok()
@@ -1388,7 +1472,14 @@ impl ECStore {
{
final_result = Err(err);
}
info!("Pool {} rebalancing is done2", pool_index);
debug!(
event = EVENT_REBALANCE_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
state = "pool_result_returned",
"Rebalance worker result returned"
);
final_result
}
@@ -2591,7 +2682,15 @@ impl ECStore {
ensure_valid_rebalance_pool_index(self.pools.len(), pool_index)?;
// Placeholder for actual bucket rebalance logic
info!("Rebalancing bucket {} in pool {}", bucket, pool_index);
debug!(
event = EVENT_REBALANCE_BUCKET,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index,
bucket = %bucket,
state = "entry_scan_started",
"Rebalance bucket entry scan started"
);
// TODO: other config
// if bucket != RUSTFS_META_BUCKET{
@@ -2765,9 +2864,14 @@ impl ECStore {
let pool = clone_first_arc(&self.pools, "save_rebalance_stats: no pools available")?;
info!(
"save_rebalance_stats: save rebalance meta, pool_idx: {}, opt: {:?}, meta: {:?}",
pool_idx, opt, meta_to_save
debug!(
event = EVENT_REBALANCE_STATE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
pool_index = pool_idx,
save_opt = ?opt,
state = "metadata_save_requested",
"Rebalance metadata save requested"
);
let stage = format!("save_rebalance_stats for pool {pool_idx} opt {opt:?}");
resolve_rebalance_meta_save_result(
@@ -2838,12 +2942,27 @@ impl SetDisks {
bucket: String,
cb: ListCallback,
) -> Result<()> {
info!("list_objects_to_rebalance: start list_objects_to_rebalance");
debug!(
event = EVENT_REBALANCE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
bucket = %bucket,
state = "started",
"Rebalance listing started"
);
// Placeholder for actual object listing logic
let (disks, _) = self.get_online_disks_with_healing(false).await;
ensure_rebalance_listing_disks_available(!disks.is_empty(), &bucket)?;
info!("list_objects_to_rebalance: get online disks with healing");
debug!(
event = EVENT_REBALANCE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
bucket = %bucket,
disk_count = disks.len(),
state = "disks_resolved",
"Rebalance listing disks resolved"
);
let listing_quorum = self.set_drive_count.div_ceil(2);
let resolver = MetadataResolutionParams {
@@ -2863,7 +2982,14 @@ impl SetDisks {
min_disks: listing_quorum,
skip_walkdir_total_timeout: true,
agreed: Some(Box::new(move |entry: MetaCacheEntry| {
info!("list_objects_to_rebalance: agreed: {:?}", &entry.name);
debug!(
event = EVENT_REBALANCE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
entry = %entry.name,
state = "agreed_entry",
"Rebalance listing agreed entry"
);
Box::pin(cb1(entry))
})),
partial: Some(Box::new(move |entries: MetaCacheEntries, _: &[Option<DiskError>]| {
@@ -2873,11 +2999,24 @@ impl SetDisks {
match entries.resolve(resolver) {
Some(entry) => {
info!("list_objects_to_rebalance: list_objects_to_decommission get {}", &entry.name);
debug!(
event = EVENT_REBALANCE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
entry = %entry.name,
state = "resolved_partial_entry",
"Rebalance listing resolved partial entry"
);
Box::pin(async move { cb(entry).await })
}
None => {
info!("list_objects_to_rebalance: list_objects_to_decommission get none");
debug!(
event = EVENT_REBALANCE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
state = "partial_entry_missing",
"Rebalance listing partial entry missing"
);
Box::pin(async {})
}
}
@@ -2887,7 +3026,14 @@ impl SetDisks {
)
.await?;
info!("list_objects_to_rebalance: list_objects_to_rebalance done");
debug!(
event = EVENT_REBALANCE_LISTING,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REBALANCE,
bucket = %bucket,
state = "completed",
"Rebalance listing completed"
);
Ok(())
}
}
+363 -37
View File
@@ -65,7 +65,7 @@ use tokio::{
};
use tokio_util::sync::CancellationToken;
use tonic::{Request, service::interceptor::InterceptedService, transport::Channel};
use tracing::{debug, info, warn};
use tracing::{debug, warn};
use uuid::Uuid;
#[derive(Clone, Copy, Debug, Eq, PartialEq)]
@@ -76,6 +76,10 @@ enum FailureHealthAction {
const REMOTE_DISK_OPEN_WRITE_MAX_ATTEMPTS: usize = 2;
const REMOTE_DISK_OPEN_WRITE_RETRY_BACKOFF: Duration = Duration::from_millis(20);
const LOG_COMPONENT_ECSTORE: &str = "ecstore";
const LOG_SUBSYSTEM_REMOTE_DISK: &str = "remote_disk";
const EVENT_REMOTE_DISK_HEALTH: &str = "remote_disk_health";
const EVENT_REMOTE_DISK_RPC: &str = "remote_disk_rpc";
async fn copy_stream_with_buffer<R, W>(reader: &mut R, writer: &mut W, buffer_size: usize) -> io::Result<u64>
where
@@ -275,7 +279,16 @@ impl RemoteDisk {
if initial_probe_ok {
health.record_operation_success(&endpoint, "connectivity_probe_success");
} else if health.mark_failure(&endpoint, "connectivity_probe_failed") {
warn!("Remote disk health check failed for {}: marking as faulty", addr);
warn!(
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %endpoint,
addr,
state = "initial_probe_failed",
result = "mark_faulty",
"Remote disk initial health probe failed"
);
// Start recovery monitoring
let health_clone = Arc::clone(&health);
@@ -291,7 +304,15 @@ impl RemoteDisk {
loop {
tokio::select! {
_ = cancel_token.cancelled() => {
debug!("Health monitoring cancelled for remote disk: {}", addr);
debug!(
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %endpoint,
addr,
state = "monitor_cancelled",
"Remote disk health monitor cancelled"
);
return;
}
_ = interval.tick() => {
@@ -320,7 +341,16 @@ impl RemoteDisk {
if Self::perform_connectivity_check(&addr).await.is_ok() {
health.record_operation_success(&endpoint, "connectivity_probe_success");
} else if health.mark_failure(&endpoint, "connectivity_probe_failed") {
warn!("Remote disk health check failed for {}: marking as faulty", addr);
warn!(
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %endpoint,
addr,
state = "probe_failed",
result = "mark_faulty",
"Remote disk health probe failed"
);
// Start recovery monitoring
let health_clone = Arc::clone(&health);
@@ -354,9 +384,25 @@ impl RemoteDisk {
_ = interval.tick() => {
if Self::perform_recovery_probe(&addr, &endpoint).await.is_ok() {
let became_online = health.mark_recovery_success(&endpoint, "disk_info_probe_success");
info!("Remote disk recovery probe succeeded: {}", addr);
debug!(
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %endpoint,
addr,
state = "recovery_probe_succeeded",
"Remote disk recovery probe succeeded"
);
if became_online {
info!("Remote disk recovered: {}", addr);
debug!(
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %endpoint,
addr,
state = "recovered",
"Remote disk recovered"
);
return;
}
} else {
@@ -469,7 +515,16 @@ impl RemoteDisk {
{
// Check if disk is faulty
if self.health.is_faulty() {
warn!("remote disk {} health is faulty, returning error", self.to_string());
warn!(
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
addr = %self.addr,
op,
state = "faulty_short_circuit",
"Remote disk operation short-circuited by faulty state"
);
return Err(DiskError::FaultyDisk);
}
@@ -519,10 +574,14 @@ impl RemoteDisk {
self.mark_faulty_and_evict("operation_timeout").await;
}
warn!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
addr = %self.addr,
op,
timeout_ms = timeout_duration.as_millis(),
state = "timeout",
"Remote disk operation timed out"
);
Err(DiskError::Timeout)
@@ -547,11 +606,15 @@ impl RemoteDisk {
)
.increment(1);
warn!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
addr = %self.addr,
op,
timeout_ms = timeout_duration.as_millis(),
"Remote disk operation returned a network-like error"
state = "network_like_error",
"Remote disk operation returned network-like error"
);
if failure_health_action == FailureHealthAction::MarkFailure {
self.mark_faulty_and_evict("operation_network_error").await;
@@ -574,13 +637,26 @@ impl RemoteDisk {
.increment(1);
if transitioned_to_offline {
warn!(
"Remote disk marked faulty after timeout: endpoint={}, addr={}, reason={}",
self.endpoint, self.addr, reason
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
addr = %self.addr,
reason,
state = "marked_faulty",
"Remote disk marked faulty"
);
} else {
warn!(
"Remote disk marked suspect after timeout: endpoint={}, addr={}, reason={}, state={:?}",
self.endpoint, self.addr, reason, state
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
addr = %self.addr,
reason,
runtime_state = ?state,
state = "marked_suspect",
"Remote disk marked suspect"
);
}
counter!(
@@ -589,11 +665,15 @@ impl RemoteDisk {
"reason" => reason.to_string()
)
.increment(1);
info!(
debug!(
event = EVENT_REMOTE_DISK_HEALTH,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
addr = %self.addr,
reason,
"Evicting cached remote disk connection after fault transition"
state = "evict_cached_connection",
"Remote disk cached connection evicted"
);
evict_failed_connection(&self.addr).await;
}
@@ -705,7 +785,16 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn make_volume(&self, volume: &str) -> Result<()> {
info!("make_volume");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
op = "make_volume",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -733,7 +822,16 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn make_volumes(&self, volumes: Vec<&str>) -> Result<()> {
info!("make_volumes");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume_count = volumes.len(),
op = "make_volumes",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -761,7 +859,15 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn list_volumes(&self) -> Result<Vec<VolumeInfo>> {
info!("list_volumes");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
op = "list_volumes",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -794,7 +900,16 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn stat_volume(&self, volume: &str) -> Result<VolumeInfo> {
info!("stat_volume");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
op = "stat_volume",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -824,7 +939,16 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn delete_volume(&self, volume: &str) -> Result<()> {
info!("delete_volume {}/{}", self.endpoint.to_string(), volume);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
op = "delete_volume",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -909,7 +1033,17 @@ impl DiskAPI for RemoteDisk {
force_del_marker: bool,
opts: DeleteOptions,
) -> Result<()> {
info!("delete_version");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
op = "delete_version",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -946,7 +1080,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn delete_versions(&self, volume: &str, versions: Vec<FileInfoVersions>, opts: DeleteOptions) -> Vec<Option<Error>> {
info!("delete_versions");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
version_count = versions.len(),
op = "delete_versions",
state = "started",
"Remote disk RPC started"
);
if self.health.is_faulty() {
return vec![Some(DiskError::FaultyDisk); versions.len()];
@@ -1041,7 +1185,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn delete_paths(&self, volume: &str, paths: &[String]) -> Result<()> {
info!("delete_paths");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path_count = paths.len(),
op = "delete_paths",
state = "started",
"Remote disk RPC started"
);
let paths = paths.to_owned();
self.execute_with_timeout(
@@ -1071,7 +1225,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn write_metadata(&self, _org_volume: &str, volume: &str, path: &str, fi: FileInfo) -> Result<()> {
info!("write_metadata {}/{}", volume, path);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
op = "write_metadata",
state = "started",
"Remote disk RPC started"
);
let file_info = serde_json::to_string(&fi)?;
let file_info_bin = encode_msgpack(&fi)?;
@@ -1134,7 +1298,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn update_metadata(&self, volume: &str, path: &str, fi: FileInfo, opts: &UpdateMetadataOpts) -> Result<()> {
info!("update_metadata");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
op = "update_metadata",
state = "started",
"Remote disk RPC started"
);
let file_info = serde_json::to_string(&fi)?;
let opts_str = serde_json::to_string(&opts)?;
let file_info_bin = encode_msgpack(&fi)?;
@@ -1180,7 +1354,18 @@ impl DiskAPI for RemoteDisk {
version_id: &str,
opts: &ReadOptions,
) -> Result<FileInfo> {
info!("read_version");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
version_id,
op = "read_version",
state = "started",
"Remote disk RPC started"
);
let opts_str = serde_json::to_string(opts)?;
let opts_bin = encode_msgpack(opts)?;
@@ -1217,7 +1402,18 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(level = "debug", skip(self))]
async fn read_xl(&self, volume: &str, path: &str, read_data: bool) -> Result<RawFileInfo> {
info!("read_xl {}/{}/{}", self.endpoint.to_string(), volume, path);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
read_data,
op = "read_xl",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -1257,7 +1453,19 @@ impl DiskAPI for RemoteDisk {
dst_volume: &str,
dst_path: &str,
) -> Result<RenameDataResp> {
info!("rename_data {}/{}/{}/{}", self.addr, self.endpoint.to_string(), dst_volume, dst_path);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
src_volume,
src_path,
dst_volume,
dst_path,
op = "rename_data",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout_for_op(
"rename_data",
@@ -1325,7 +1533,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self, wr))]
async fn walk_dir<W: AsyncWrite + Unpin + Send>(&self, opts: WalkDirOptions, wr: &mut W) -> Result<()> {
info!("walk_dir {}", self.endpoint.to_string());
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
bucket = %opts.bucket,
base_dir = %opts.base_dir,
op = "walk_dir",
state = "started",
"Remote disk RPC started"
);
let disk = self.disk_ref().await;
let body = serde_json::to_vec(&opts)?;
@@ -1443,7 +1661,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(level = "debug", skip(self))]
async fn append_file(&self, volume: &str, path: &str) -> Result<FileWriter> {
info!("append_file {}/{}", volume, path);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
op = "append_file",
state = "started",
"Remote disk RPC started"
);
if self.health.is_faulty() {
return Err(DiskError::FaultyDisk);
@@ -1487,7 +1715,19 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(level = "debug", skip(self))]
async fn rename_file(&self, src_volume: &str, src_path: &str, dst_volume: &str, dst_path: &str) -> Result<()> {
info!("rename_file");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
src_volume,
src_path,
dst_volume,
dst_path,
op = "rename_file",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -1518,7 +1758,19 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn rename_part(&self, src_volume: &str, src_path: &str, dst_volume: &str, dst_path: &str, meta: Bytes) -> Result<()> {
info!("rename_part {}/{}", src_volume, src_path);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
src_volume,
src_path,
dst_volume,
dst_path,
op = "rename_part",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -1550,7 +1802,19 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn delete(&self, volume: &str, path: &str, opt: DeleteOptions) -> Result<()> {
info!("delete {}/{}/{}", self.endpoint.to_string(), volume, path);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
recursive = opt.recursive,
immediate = opt.immediate,
op = "delete",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -1581,7 +1845,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn verify_file(&self, volume: &str, path: &str, fi: &FileInfo) -> Result<CheckPartsResp> {
info!("verify_file");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
op = "verify_file",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -1614,6 +1888,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn read_parts(&self, bucket: &str, paths: &[String]) -> Result<Vec<ObjectPartInfo>> {
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
bucket,
path_count = paths.len(),
op = "read_parts",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
let mut client = self
@@ -1642,7 +1927,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn check_parts(&self, volume: &str, path: &str, fi: &FileInfo) -> Result<CheckPartsResp> {
info!("check_parts");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
op = "check_parts",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -1675,7 +1970,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn read_multiple(&self, req: ReadMultipleReq) -> Result<Vec<ReadMultipleResp>> {
info!("read_multiple {}/{}/{}", self.endpoint.to_string(), req.bucket, req.prefix);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
bucket = %req.bucket,
prefix = %req.prefix,
op = "read_multiple",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -1721,7 +2026,18 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn write_all(&self, volume: &str, path: &str, data: Bytes) -> Result<()> {
info!("write_all");
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
bytes = data.len(),
op = "write_all",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
@@ -1779,7 +2095,17 @@ impl DiskAPI for RemoteDisk {
#[tracing::instrument(skip(self))]
async fn read_all(&self, volume: &str, path: &str) -> Result<Bytes> {
info!("read_all {}/{}", volume, path);
debug!(
event = EVENT_REMOTE_DISK_RPC,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_REMOTE_DISK,
endpoint = %self.endpoint,
volume,
path,
op = "read_all",
state = "started",
"Remote disk RPC started"
);
self.execute_with_timeout(
|| async {
+110 -10
View File
@@ -130,6 +130,12 @@ use tracing::error;
use tracing::{debug, info, warn};
use uuid::Uuid;
const LOG_COMPONENT_ECSTORE: &str = "ecstore";
const LOG_SUBSYSTEM_SET_DISK: &str = "set_disk";
const EVENT_SET_DISK_MULTIPART: &str = "set_disk_multipart";
const EVENT_SET_DISK_WRITE: &str = "set_disk_write";
const EVENT_SET_DISK_HEAL: &str = "set_disk_heal";
use crate::rio::{EtagResolvable, HashReader, HashReaderMut, TryGetIndex as _};
pub const DEFAULT_READ_BUFFER_SIZE: usize = MI_B; // 1 MiB = 1024 * 1024;
@@ -948,7 +954,16 @@ impl ObjectIO for SetDisks {
)
.await
{
error!("get_object_with_fileinfo {bucket}/{object} err {:?}", e);
error!(
event = EVENT_SET_DISK_WRITE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
bucket,
object,
state = "read_pipeline_failed",
error = ?e,
"Set disk object read pipeline failed"
);
};
});
@@ -1065,7 +1080,15 @@ impl ObjectIO for SetDisks {
{
Ok(writer) => (Some(writer), None),
Err(err) => {
warn!("create_bitrot_writer disk {}, err {:?}, skipping operation", disk.to_string(), err);
warn!(
event = EVENT_SET_DISK_WRITE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
disk = ?disk,
state = "bitrot_writer_skipped",
error = ?err,
"Set disk bitrot writer skipped"
);
(None, Some(err))
}
}
@@ -1085,7 +1108,18 @@ impl ObjectIO for SetDisks {
let nil_count = errors.iter().filter(|&e| e.is_none()).count();
if nil_count < write_quorum {
error!("not enough disks to write: {:?}", errors);
error!(
event = EVENT_SET_DISK_WRITE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
bucket,
object,
write_quorum,
available_writers = nil_count,
state = "write_quorum_unavailable",
error = ?errors,
"Set disk write quorum unavailable"
);
if let Some(write_err) = reduce_write_quorum_errs(&errors, OBJECT_OP_IGNORED_ERRS, write_quorum) {
return Err(to_object_err(write_err.into(), vec![bucket, object]));
}
@@ -1136,7 +1170,17 @@ impl ObjectIO for SetDisks {
// }
if (w_size as i64) < data.size() {
warn!("put_object write size < data.size(), w_size={}, data.size={}", w_size, data.size());
warn!(
event = EVENT_SET_DISK_WRITE,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
bucket,
object,
written_size = w_size,
expected_size = data.size(),
state = "short_write",
"Set disk write produced fewer bytes than expected"
);
return Err(Error::other(format!(
"put_object write size < data.size(), w_size={}, data.size={}",
w_size,
@@ -2976,7 +3020,15 @@ impl MultipartOperations for SetDisks {
{
Ok(writer) => writer,
Err(err) => {
warn!("create_bitrot_writer disk {}, err {:?}, skipping operation", disk.to_string(), err);
warn!(
event = EVENT_SET_DISK_MULTIPART,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
disk = ?disk,
state = "bitrot_writer_skipped",
error = ?err,
"Set disk multipart bitrot writer skipped"
);
errors.push(Some(err));
writers.push(None);
continue;
@@ -3021,7 +3073,18 @@ impl MultipartOperations for SetDisks {
let _ = mem::replace(&mut data.stream, reader);
if (w_size as i64) < data.size() {
warn!("put_object_part write size < data.size(), w_size={}, data.size={}", w_size, data.size());
warn!(
event = EVENT_SET_DISK_MULTIPART,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
bucket,
object,
part_number = part_id,
written_size = w_size,
expected_size = data.size(),
state = "short_write",
"Set disk multipart write produced fewer bytes than expected"
);
return Err(Error::other(format!(
"put_object_part write size < data.size(), w_size={}, data.size={}",
w_size,
@@ -3657,7 +3720,17 @@ impl MultipartOperations for SetDisks {
);
return Err(Error::InvalidPart(p.part_num, "".to_owned(), p.etag.clone().unwrap_or_default()));
};
info!(target:"rustfs_ecstore::set_disk", part_number = p.part_num, part_size = ext_part.size, part_actual_size = ext_part.actual_size, "Completing multipart part");
debug!(
target:"rustfs_ecstore::set_disk",
event = EVENT_SET_DISK_MULTIPART,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
part_number = p.part_num,
part_size = ext_part.size,
part_actual_size = ext_part.actual_size,
state = "part_validated",
"Set disk multipart part validated"
);
// Normalize ETags by removing quotes before comparison (PR #592 compatibility)
let client_etag = p.etag.as_ref().map(|e| rustfs_utils::path::trim_etag(e));
@@ -3988,7 +4061,16 @@ impl HealOperations for SetDisks {
let disks = disks.clone();
let (_, errs) = Self::read_all_fileinfo(&disks, "", bucket, object, version_id, false, false, false).await?;
if DiskError::is_all_not_found(&errs) {
debug!(bucket, object, version_id, "heal_object skipped missing object");
debug!(
event = EVENT_SET_DISK_HEAL,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
bucket,
object,
version_id,
state = "missing_object_skipped",
"Set disk heal skipped missing object"
);
let err = if !version_id.is_empty() {
Error::FileVersionNotFound
} else {
@@ -4356,7 +4438,16 @@ async fn disks_with_all_parts(
verify_resp = v;
}
Err(err) => {
info!("verify_file failed: {err:?}, object_name={}, index: {index}", object_name);
debug!(
event = EVENT_SET_DISK_HEAL,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
object = %object_name,
disk_index = index,
state = "verify_failed",
error = ?err,
"Set disk verify_file failed"
);
verify_err = Some(err);
}
}
@@ -4366,7 +4457,16 @@ async fn disks_with_all_parts(
verify_resp = v;
}
Err(err) => {
info!("check_parts failed: {err:?}, object_name={}, index: {index}", object_name);
debug!(
event = EVENT_SET_DISK_HEAL,
component = LOG_COMPONENT_ECSTORE,
subsystem = LOG_SUBSYSTEM_SET_DISK,
object = %object_name,
disk_index = index,
state = "check_parts_failed",
error = ?err,
"Set disk check_parts failed"
);
verify_err = Some(err);
}
}