diff --git a/crates/obs/src/telemetry/guard.rs b/crates/obs/src/telemetry/guard.rs index 8b1b8bded..537abe988 100644 --- a/crates/obs/src/telemetry/guard.rs +++ b/crates/obs/src/telemetry/guard.rs @@ -47,6 +47,11 @@ pub(crate) type MemoryProfilingAgent = (); const LOG_COMPONENT_OBS: &str = "obs"; const LOG_SUBSYSTEM_GUARD: &str = "guard"; const EVENT_OBS_GUARD_SHUTDOWN: &str = "obs_guard_shutdown"; +const STDERR_ERROR_PREFIX: &str = "[ERROR]"; + +fn format_guard_shutdown_stderr_message(resource: &str, error: impl std::fmt::Display) -> String { + format!("{STDERR_ERROR_PREFIX} observability guard shutdown failed: resource={resource} error={error}") +} /// RAII guard that owns all active OpenTelemetry providers and the /// `tracing_appender` worker guard. @@ -96,43 +101,37 @@ impl Drop for OtelGuard { if let Some(provider) = self.tracer_provider.take() && let Err(err) = provider.shutdown() { - error!( - event = EVENT_OBS_GUARD_SHUTDOWN, - component = LOG_COMPONENT_OBS, - subsystem = LOG_SUBSYSTEM_GUARD, - resource = "tracer_provider", - result = "shutdown_failed", - error = ?err, - "observability guard shutdown failed" - ); + if tracing::dispatcher::has_been_set() { + error!( + event = EVENT_OBS_GUARD_SHUTDOWN, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_GUARD, + resource = "tracer_provider", + result = "shutdown_failed", + error = %err, + "observability guard shutdown failed" + ); + } else { + eprintln!("{}", format_guard_shutdown_stderr_message("tracer_provider", err)); + } } if let Some(provider) = self.meter_provider.take() && let Err(err) = provider.shutdown() { - error!( - event = EVENT_OBS_GUARD_SHUTDOWN, - component = LOG_COMPONENT_OBS, - subsystem = LOG_SUBSYSTEM_GUARD, - resource = "meter_provider", - result = "shutdown_failed", - error = ?err, - "observability guard shutdown failed" - ); - } - - if let Some(provider) = self.logger_provider.take() - && let Err(err) = provider.shutdown() - { - error!( - event = EVENT_OBS_GUARD_SHUTDOWN, - component = LOG_COMPONENT_OBS, - subsystem = LOG_SUBSYSTEM_GUARD, - resource = "logger_provider", - result = "shutdown_failed", - error = ?err, - "observability guard shutdown failed" - ); + if tracing::dispatcher::has_been_set() { + error!( + event = EVENT_OBS_GUARD_SHUTDOWN, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_GUARD, + resource = "meter_provider", + result = "shutdown_failed", + error = %err, + "observability guard shutdown failed" + ); + } else { + eprintln!("{}", format_guard_shutdown_stderr_message("meter_provider", err)); + } } #[cfg(all( @@ -141,15 +140,21 @@ impl Drop for OtelGuard { ))] if let Some(agent) = self.profiling_agent.take() { match agent.stop() { - Err(err) => error!( - event = EVENT_OBS_GUARD_SHUTDOWN, - component = LOG_COMPONENT_OBS, - subsystem = LOG_SUBSYSTEM_GUARD, - resource = "profiling_agent", - result = "shutdown_failed", - error = ?err, - "observability guard shutdown failed" - ), + Err(err) => { + if tracing::dispatcher::has_been_set() { + error!( + event = EVENT_OBS_GUARD_SHUTDOWN, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_GUARD, + resource = "profiling_agent", + result = "shutdown_failed", + error = %err, + "observability guard shutdown failed" + ); + } else { + eprintln!("{}", format_guard_shutdown_stderr_message("profiling_agent", err)); + } + } Ok(stopped) => { stopped.shutdown(); } @@ -159,15 +164,21 @@ impl Drop for OtelGuard { #[cfg(all(feature = "pyroscope", target_os = "linux", target_env = "gnu", target_arch = "x86_64"))] if let Some(agent) = self.memory_profiling_agent.take() { match agent.stop() { - Err(err) => error!( - event = EVENT_OBS_GUARD_SHUTDOWN, - component = LOG_COMPONENT_OBS, - subsystem = LOG_SUBSYSTEM_GUARD, - resource = "memory_profiling_agent", - result = "shutdown_failed", - error = ?err, - "observability guard shutdown failed" - ), + Err(err) => { + if tracing::dispatcher::has_been_set() { + error!( + event = EVENT_OBS_GUARD_SHUTDOWN, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_GUARD, + resource = "memory_profiling_agent", + result = "shutdown_failed", + error = %err, + "observability guard shutdown failed" + ); + } else { + eprintln!("{}", format_guard_shutdown_stderr_message("memory_profiling_agent", err)); + } + } Ok(stopped) => { stopped.shutdown(); } @@ -186,6 +197,15 @@ impl Drop for OtelGuard { handle.abort(); } + if let Some(provider) = self.logger_provider.take() + && let Err(err) = provider.shutdown() + { + // After logger shutdown, the OTLP log bridge is no longer a reliable + // sink for its own failure path, so fall back to stderr. + // resource = "logger_provider" + eprintln!("{}", format_guard_shutdown_stderr_message("logger_provider", err)); + } + if let Some(guard) = self.tracing_guard.take() { debug!( event = EVENT_OBS_GUARD_SHUTDOWN, @@ -211,3 +231,17 @@ impl Drop for OtelGuard { } } } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn test_guard_shutdown_stderr_message_is_actionable() { + let message = format_guard_shutdown_stderr_message("logger_provider", "flush failed"); + + assert!(message.starts_with(STDERR_ERROR_PREFIX)); + assert!(message.contains("resource=logger_provider")); + assert!(message.contains("error=flush failed")); + } +} diff --git a/crates/obs/src/telemetry/local.rs b/crates/obs/src/telemetry/local.rs index 5f0382f2e..276741e16 100644 --- a/crates/obs/src/telemetry/local.rs +++ b/crates/obs/src/telemetry/local.rs @@ -64,6 +64,7 @@ const LOG_COMPONENT_OBS: &str = "obs"; const LOG_SUBSYSTEM_LOCAL_LOGGING: &str = "local_logging"; const EVENT_LOCAL_LOGGING_STATE: &str = "local_logging_state"; const EVENT_LOG_CLEANER_STATE: &str = "log_cleaner_state"; +const STDERR_WARNING_PREFIX: &str = "[WARN]"; pub(super) fn build_json_log_layer(writer: W, enable_ansi: bool, span_events: FmtSpan) -> impl tracing_subscriber::Layer where @@ -361,19 +362,29 @@ pub(super) fn should_fallback_to_stdout(error: &TelemetryError) -> bool { } } +fn format_file_logging_fallback_warning(log_directory: &str, error: &TelemetryError) -> String { + format!( + "{STDERR_WARNING_PREFIX} local logging fallback to stdout: failed_sink=file sink=stdout log_directory={log_directory} error={error}" + ) +} + pub(super) fn emit_file_logging_fallback_warning(log_directory: &str, error: &TelemetryError) { - warn!( - event = EVENT_LOCAL_LOGGING_STATE, - component = LOG_COMPONENT_OBS, - subsystem = LOG_SUBSYSTEM_LOCAL_LOGGING, - state = "fallback_to_stdout", - backend = "local", - failed_sink = "file", - sink = "stdout", - log_directory, - error = %error, - "local logging state changed" - ); + if tracing::dispatcher::has_been_set() { + warn!( + event = EVENT_LOCAL_LOGGING_STATE, + component = LOG_COMPONENT_OBS, + subsystem = LOG_SUBSYSTEM_LOCAL_LOGGING, + state = "fallback_to_stdout", + backend = "local", + failed_sink = "file", + sink = "stdout", + log_directory, + error = %error, + "local logging state changed" + ); + } else { + eprintln!("{}", format_file_logging_fallback_warning(log_directory, error)); + } } // ─── Cleanup task ───────────────────────────────────────────────────────────── @@ -631,6 +642,19 @@ mod tests { ))); } + #[test] + fn test_file_logging_fallback_warning_message_is_actionable() { + let message = format_file_logging_fallback_warning( + "/var/log/rustfs", + &TelemetryError::Io("Permission denied (os error 13)".to_string()), + ); + + assert!(message.starts_with(STDERR_WARNING_PREFIX)); + assert!(message.contains("fallback to stdout")); + assert!(message.contains("log_directory=/var/log/rustfs")); + assert!(message.contains("Permission denied")); + } + #[test] fn test_json_log_layer_produces_parseable_json_without_ansi_escape_sequences() { let (raw, parsed) = render_json_log(true); diff --git a/rustfs/src/main.rs b/rustfs/src/main.rs index ca540037f..9bd640871 100644 --- a/rustfs/src/main.rs +++ b/rustfs/src/main.rs @@ -111,6 +111,7 @@ const EVENT_BACKGROUND_SERVICE_SHUTDOWN: &str = "background_service_shutdown"; const EVENT_EVENT_NOTIFIER_SHUTDOWN: &str = "event_notifier_shutdown"; const EVENT_PROFILING_SHUTDOWN: &str = "profiling_shutdown"; const EVENT_SERVER_SHUTDOWN_STATE: &str = "server_shutdown_state"; +const OBSERVABILITY_INIT_FATAL_ALREADY_REPORTED: &str = "observability initialization failure already reported"; #[cfg(all(target_os = "linux", target_env = "gnu", target_arch = "x86_64"))] #[global_allocator] static GLOBAL: tikv_jemallocator::Jemalloc = tikv_jemallocator::Jemalloc; @@ -132,8 +133,10 @@ fn main() { let runtime = rustfs::server::build_tokio_runtime().expect("Failed to build Tokio runtime"); let result = runtime.block_on(async_main()); if let Err(ref e) = result { - // Tracing may not be initialized when startup fails this early. - emit_fatal_stderr("Server runtime failed", e); + if e.to_string() != OBSERVABILITY_INIT_FATAL_ALREADY_REPORTED { + // Tracing may not be initialized when startup fails this early. + emit_fatal_stderr("Server runtime failed", e); + } std::process::exit(1); } } @@ -193,7 +196,7 @@ async fn async_main() -> Result<()> { Err(e) => { // Structured logging is unavailable until observability initializes. emit_fatal_stderr("Observability initialization failed", &e); - return Err(Error::other(e)); + return Err(Error::other(OBSERVABILITY_INIT_FATAL_ALREADY_REPORTED)); } };