fix(logging): enforce single-writer sinks and bound tracing (#4765)

* fix(obs): prevent rolling log stdout aliasing

* fix(ecstore): bound hot-path tracing payloads

* test(logging): guard service and disk log invariants

* fix(obs): silence useless_conversion on st_dev for Linux clippy

rustix's Stat.st_dev is u64 on Linux/glibc, making u64::try_from a no-op
that trips clippy::useless_conversion under -D warnings. The conversion is
still needed on macOS/BSD where st_dev is a signed dev_t, so suppress the
lint on that line rather than dropping the portable fallible conversion.

* fix(logging): keep stdout sink validation portable (#4769)

* fix(obs): keep stdout device conversion portable

* docs(logging): update single-writer plan status

---------

Co-authored-by: overtrue <anzhengchao@gmail.com>
Co-authored-by: houseme <housemecn@gmail.com>
This commit is contained in:
cxymds
2026-07-12 16:03:01 +08:00
committed by GitHub
parent 2ddafb4ed9
commit d8e69a3adf
14 changed files with 539 additions and 153 deletions
+1
View File
@@ -74,6 +74,7 @@ rustfs-notify = { workspace = true }
rustfs-security-governance = { workspace = true }
rustfs-storage-api = { workspace = true }
rustfs-utils = { workspace = true, features = ["ip"] }
rustix = { workspace = true, features = ["fs", "stdio"] }
chrono = { workspace = true }
flate2 = { workspace = true }
glob = { workspace = true }
+20 -6
View File
@@ -44,13 +44,12 @@ use rustfs_config::observability::{
};
use rustfs_config::{
APP_NAME, DEFAULT_LOG_KEEP_FILES, DEFAULT_LOG_LEVEL, DEFAULT_LOG_ROTATION_TIME, DEFAULT_OBS_LOG_FILENAME,
DEFAULT_OBS_LOG_STDOUT_ENABLED, DEFAULT_OBS_LOGS_EXPORT_ENABLED, DEFAULT_OBS_METRICS_EXPORT_ENABLED,
DEFAULT_OBS_PROFILING_EXPORT_ENABLED, DEFAULT_OBS_TRACES_EXPORT_ENABLED, ENVIRONMENT, METER_INTERVAL, SAMPLE_RATIO,
SERVICE_VERSION, USE_STDOUT,
DEFAULT_OBS_LOGS_EXPORT_ENABLED, DEFAULT_OBS_METRICS_EXPORT_ENABLED, DEFAULT_OBS_PROFILING_EXPORT_ENABLED,
DEFAULT_OBS_TRACES_EXPORT_ENABLED, ENVIRONMENT, METER_INTERVAL, SAMPLE_RATIO, SERVICE_VERSION, USE_STDOUT,
};
use rustfs_utils::{
get_env_bool, get_env_bool_with_aliases, get_env_f64, get_env_opt_str, get_env_opt_u64, get_env_str, get_env_u64,
get_env_usize,
get_env_bool, get_env_bool_with_aliases, get_env_f64, get_env_opt_bool, get_env_opt_str, get_env_opt_u64, get_env_str,
get_env_u64, get_env_usize,
};
use serde::{Deserialize, Serialize};
use std::env;
@@ -310,7 +309,7 @@ impl OtelConfig {
environment: Some(get_env_str(ENV_OBS_ENVIRONMENT, ENVIRONMENT)),
// Local logging
logger_level: Some(get_env_str(ENV_OBS_LOGGER_LEVEL, DEFAULT_LOG_LEVEL)),
log_stdout_enabled: Some(get_env_bool(ENV_OBS_LOG_STDOUT_ENABLED, DEFAULT_OBS_LOG_STDOUT_ENABLED)),
log_stdout_enabled: get_env_opt_bool(ENV_OBS_LOG_STDOUT_ENABLED),
log_directory,
log_filename: Some(get_env_nonempty_str(ENV_OBS_LOG_FILENAME, DEFAULT_OBS_LOG_FILENAME)),
log_rotation_time,
@@ -495,4 +494,19 @@ mod tests {
});
});
}
#[test]
fn stdout_mirror_environment_preserves_unset_true_and_false() {
with_profiling_env_lock(|| {
temp_env::with_var_unset(ENV_OBS_LOG_STDOUT_ENABLED, || {
assert_eq!(OtelConfig::extract_otel_config_from_env(None).log_stdout_enabled, None);
});
temp_env::with_var(ENV_OBS_LOG_STDOUT_ENABLED, Some("true"), || {
assert_eq!(OtelConfig::extract_otel_config_from_env(None).log_stdout_enabled, Some(true));
});
temp_env::with_var(ENV_OBS_LOG_STDOUT_ENABLED, Some("false"), || {
assert_eq!(OtelConfig::extract_otel_config_from_env(None).log_stdout_enabled, Some(false));
});
});
}
}
+2
View File
@@ -68,6 +68,8 @@ pub enum TelemetryError {
Io(String),
#[error("Set permissions failed: {0}")]
SetPermissions(String),
#[error("Log sink conflict: {0}")]
LogSinkConflict(String),
}
impl From<std::io::Error> for TelemetryError {
+177 -2
View File
@@ -47,7 +47,7 @@ use rustfs_config::observability::{
DEFAULT_OBS_LOG_PARALLEL_WORKERS, DEFAULT_OBS_LOG_ZSTD_COMPRESSION_LEVEL, DEFAULT_OBS_LOG_ZSTD_FALLBACK_TO_GZIP,
DEFAULT_OBS_LOG_ZSTD_WORKERS,
};
use rustfs_config::{APP_NAME, DEFAULT_LOG_KEEP_FILES, DEFAULT_LOG_ROTATION_TIME, DEFAULT_OBS_LOG_STDOUT_ENABLED};
use rustfs_config::{APP_NAME, DEFAULT_LOG_KEEP_FILES, DEFAULT_LOG_ROTATION_TIME};
use serde_json::Value as JsonValue;
use std::sync::Arc;
use std::{collections::BTreeMap, fmt};
@@ -74,6 +74,59 @@ const STDERR_WARNING_PREFIX: &str = "[WARN]";
const REQUEST_ID_CANONICAL: &str = "request_id";
const REQUEST_ID_COMPAT: &str = "request-id";
pub(super) fn resolve_file_stdout_mirror(configured: Option<bool>, is_production: bool) -> bool {
configured.unwrap_or(!is_production)
}
#[cfg(unix)]
pub(super) fn validate_stdout_sink(file_appender: &RollingAppender) -> Result<(), TelemetryError> {
use std::os::fd::AsFd;
let stdout_stat = rustix::fs::fstat(std::io::stdout().as_fd())
.map_err(|error| TelemetryError::LogSinkConflict(format!("failed to inspect stdout file descriptor: {error}")))?;
if !rustix::fs::FileType::from_raw_mode(stdout_stat.st_mode).is_file() {
return Ok(());
}
let stdout_device = {
#[cfg(any(target_os = "linux", target_os = "android"))]
{
stdout_stat.st_dev
}
#[cfg(not(any(target_os = "linux", target_os = "android")))]
{
u64::try_from(stdout_stat.st_dev).map_err(|error| {
TelemetryError::LogSinkConflict(format!("stdout file descriptor returned an invalid device identifier: {error}"))
})?
}
};
let active_identity = file_appender
.active_file_identity()
.map_err(|error| TelemetryError::Io(error.to_string()))?;
validate_distinct_file_identities((stdout_device, stdout_stat.st_ino), active_identity, &file_appender.active_file_path())
}
#[cfg(not(unix))]
pub(super) fn validate_stdout_sink(_file_appender: &RollingAppender) -> Result<(), TelemetryError> {
Ok(())
}
#[cfg(unix)]
fn validate_distinct_file_identities(
stdout_identity: (u64, u64),
active_identity: (u64, u64),
active_log_path: &std::path::Path,
) -> Result<(), TelemetryError> {
if stdout_identity == active_identity {
return Err(TelemetryError::LogSinkConflict(format!(
"stdout and rolling log resolve to the same file {}; route stdout to journald or choose a different log file",
active_log_path.display()
)));
}
Ok(())
}
fn resolve_log_cleanup_interval_seconds(config: &OtelConfig) -> u64 {
match config.log_cleanup_interval_seconds {
Some(0) => {
@@ -353,6 +406,7 @@ fn init_file_logging_internal(
let file_appender =
RollingAppender::new(log_directory, log_filename.to_string(), rotation, max_single_file_size, match_mode)?;
validate_stdout_sink(&file_appender)?;
let (non_blocking, guard) = tracing_appender::non_blocking(file_appender);
@@ -367,7 +421,7 @@ fn init_file_logging_internal(
// Optional stdout mirror: enabled explicitly via `log_stdout_enabled`, or
// unconditionally in non-production environments so developers still see
// immediate terminal output while file rotation remains enabled.
let (stdout_layer, stdout_guard) = if config.log_stdout_enabled.unwrap_or(DEFAULT_OBS_LOG_STDOUT_ENABLED) || !is_production {
let (stdout_layer, stdout_guard) = if resolve_file_stdout_mirror(config.log_stdout_enabled, is_production) {
let (stdout_nb, stdout_guard) = tracing_appender::non_blocking(std::io::stdout());
let enable_color = std::io::stdout().is_terminal();
(Some(build_json_log_layer(stdout_nb, enable_color, span_events)), Some(stdout_guard))
@@ -802,6 +856,127 @@ mod tests {
)));
}
#[test]
fn stdout_mirror_configuration_overrides_environment_default() {
assert!(!resolve_file_stdout_mirror(None, true));
assert!(resolve_file_stdout_mirror(None, false));
assert!(resolve_file_stdout_mirror(Some(true), true));
assert!(resolve_file_stdout_mirror(Some(true), false));
assert!(!resolve_file_stdout_mirror(Some(false), true));
assert!(!resolve_file_stdout_mirror(Some(false), false));
}
#[cfg(unix)]
#[test]
fn stdout_sink_validation_rejects_file_aliases() {
use std::fs::{self, File};
use std::os::unix::fs::MetadataExt;
let temp_dir = tempdir().expect("create temp dir");
let active_path = temp_dir.path().join("rustfs.log");
let hardlink_path = temp_dir.path().join("stdout-hardlink.log");
let symlink_path = temp_dir.path().join("stdout-symlink.log");
File::create(&active_path).expect("create active log");
fs::hard_link(&active_path, &hardlink_path).expect("create hardlink");
std::os::unix::fs::symlink(&active_path, &symlink_path).expect("create symlink");
let active_metadata = fs::metadata(&active_path).expect("stat active log");
for alias in [&active_path, &hardlink_path, &symlink_path] {
let alias_metadata = fs::metadata(alias).expect("stat stdout alias");
assert!(matches!(
validate_distinct_file_identities(
(alias_metadata.dev(), alias_metadata.ino()),
(active_metadata.dev(), active_metadata.ino()),
&active_path,
),
Err(TelemetryError::LogSinkConflict(_))
));
}
}
#[cfg(unix)]
#[test]
fn stdout_sink_validation_allows_distinct_files() {
use std::fs::{self, File};
use std::os::unix::fs::MetadataExt;
let temp_dir = tempdir().expect("create temp dir");
let stdout_path = temp_dir.path().join("stdout.log");
let active_path = temp_dir.path().join("rustfs.log");
File::create(&stdout_path).expect("create stdout log");
File::create(&active_path).expect("create active log");
let stdout_metadata = fs::metadata(&stdout_path).expect("stat stdout log");
let active_metadata = fs::metadata(&active_path).expect("stat active log");
assert!(
validate_distinct_file_identities(
(stdout_metadata.dev(), stdout_metadata.ino()),
(active_metadata.dev(), active_metadata.ino()),
&active_path,
)
.is_ok()
);
}
#[cfg(unix)]
#[test]
fn file_logging_initialization_rejects_stdout_alias() {
const CHILD_ENV: &str = "RUSTFS_TEST_STDOUT_LOG_ALIAS_CHILD";
const PATH_ENV: &str = "RUSTFS_TEST_STDOUT_LOG_ALIAS_PATH";
if std::env::var_os(CHILD_ENV).is_some() {
use std::fs::OpenOptions;
let active_path = std::path::PathBuf::from(std::env::var_os(PATH_ENV).expect("child log path must be set"));
let stdout_file = OpenOptions::new()
.create(true)
.append(true)
.open(&active_path)
.expect("open child stdout log");
rustix::stdio::dup2_stdout(&stdout_file).expect("redirect child stdout");
let config = OtelConfig {
log_filename: active_path.file_name().map(|name| name.to_string_lossy().into_owned()),
log_stdout_enabled: Some(false),
..OtelConfig::default()
};
let log_directory = active_path.parent().expect("active log must have parent");
let runtime = tokio::runtime::Runtime::new().expect("create Tokio runtime");
runtime.block_on(async {
assert!(matches!(
init_file_logging_internal(
&config,
log_directory.to_str().expect("log directory must be UTF-8"),
"info",
true,
),
Err(TelemetryError::LogSinkConflict(_))
));
});
return;
}
let temp_dir = tempdir().expect("create parent temp dir");
let active_path = temp_dir.path().join("rustfs.log");
let output = std::process::Command::new(std::env::current_exe().expect("resolve current test executable"))
.args([
"--exact",
"telemetry::local::tests::file_logging_initialization_rejects_stdout_alias",
"--nocapture",
])
.env(CHILD_ENV, "1")
.env(PATH_ENV, &active_path)
.output()
.expect("run isolated stdout alias child test");
assert!(
output.status.success(),
"stdout alias child failed: stdout={} stderr={}",
String::from_utf8_lossy(&output.stdout),
String::from_utf8_lossy(&output.stderr)
);
}
#[test]
fn test_file_logging_fallback_warning_message_is_actionable() {
let message = format_file_logging_fallback_warning(
+7 -4
View File
@@ -60,7 +60,7 @@ use opentelemetry_sdk::{
use percent_encoding::percent_decode_str;
use rustfs_config::observability::{DEFAULT_OBS_LOG_MATCH_MODE, DEFAULT_OBS_LOG_MAX_SINGLE_FILE_SIZE_BYTES};
use rustfs_config::{
APP_NAME, DEFAULT_LOG_KEEP_FILES, DEFAULT_LOG_ROTATION_TIME, DEFAULT_OBS_LOG_STDOUT_ENABLED, DEFAULT_OBS_LOGS_EXPORT_ENABLED,
APP_NAME, DEFAULT_LOG_KEEP_FILES, DEFAULT_LOG_ROTATION_TIME, DEFAULT_OBS_LOGS_EXPORT_ENABLED,
DEFAULT_OBS_METRICS_EXPORT_ENABLED, DEFAULT_OBS_TRACES_EXPORT_ENABLED, METER_INTERVAL, SAMPLE_RATIO,
};
use std::collections::HashMap;
@@ -200,6 +200,7 @@ pub(super) fn init_observability_http(
let file_appender =
RollingAppender::new(log_directory, log_filename.to_string(), rotation, max_single_file_size, match_mode)?;
crate::telemetry::local::validate_stdout_sink(&file_appender)?;
let (non_blocking, guard) = tracing_appender::non_blocking(file_appender);
let file_layer = build_json_log_layer(non_blocking, false, span_events.clone());
@@ -220,8 +221,10 @@ pub(super) fn init_observability_http(
log_directory,
rotation = %rotation_str,
keep_files,
stdout_mirror_enabled = config.log_stdout_enabled.unwrap_or(DEFAULT_OBS_LOG_STDOUT_ENABLED)
|| !is_production,
stdout_mirror_enabled = crate::telemetry::local::resolve_file_stdout_mirror(
config.log_stdout_enabled,
is_production,
),
logger_level,
is_production,
"Initialized local logging fallback for observability"
@@ -243,7 +246,7 @@ pub(super) fn init_observability_http(
// Optional stdout mirror (matching init_file_logging_internal logic)
// This is separate from OTLP stdout logic. If file logging is enabled, we honor its stdout rules.
if force_stdout_logging || config.log_stdout_enabled.unwrap_or(DEFAULT_OBS_LOG_STDOUT_ENABLED) || !is_production {
if force_stdout_logging || crate::telemetry::local::resolve_file_stdout_mirror(config.log_stdout_enabled, is_production) {
let (stdout_nb, stdout_g) = tracing_appender::non_blocking(std::io::stdout());
stdout_guard = Some(stdout_g);
stdout_layer_opt = Some(build_json_log_layer(stdout_nb, std::io::stdout().is_terminal(), span_events));
+13 -1
View File
@@ -133,10 +133,22 @@ impl RollingAppender {
Ok(appender)
}
fn active_file_path(&self) -> PathBuf {
pub(crate) fn active_file_path(&self) -> PathBuf {
self.dir.join(&self.filename)
}
#[cfg(unix)]
pub(crate) fn active_file_identity(&self) -> io::Result<(u64, u64)> {
use std::os::unix::fs::MetadataExt;
let metadata = self
.file
.as_ref()
.ok_or_else(|| io::Error::other("rolling log file is not open"))?
.metadata()?;
Ok((metadata.dev(), metadata.ino()))
}
fn open_file(&mut self) -> io::Result<()> {
if self.file.is_some() {
return Ok(());