fix: harden concurrency limits and high-RPM runtime paths

Bound request, stream, queue, and shutdown resource lifetimes. Reduce scheduler and Redis hot-path work and isolate database maintenance. Include regression coverage, load probes, and concurrency audit results.
This commit is contained in:
elky
2026-09-10 08:14:58 +08:00
parent 361952ada9
commit ecc16673eb
149 changed files with 27963 additions and 1926 deletions
+2 -1
View File
@@ -34,5 +34,6 @@ pub use queue::{
pub use redaction::{summarize_text_payload, TextPayloadSummary};
pub use shutdown::wait_for_shutdown_signal;
pub use tracing::{
init_reloadable_service_tracing, init_reloadable_tracing, LogFormat, LogReloader,
init_reloadable_service_tracing, init_reloadable_tracing, logging_metric_samples,
shutdown_logging, LogFormat, LogReloader, LogShutdownGuard,
};
+216 -60
View File
@@ -21,6 +21,11 @@ use crate::config::ServiceRuntimeConfig;
use crate::error::RuntimeBootstrapError;
use crate::observability::{FileLoggingConfig, LogDestination, LogRotation};
mod writer;
pub use writer::{logging_metric_samples, shutdown_logging, LogShutdownGuard};
use writer::{register_log_workers, LogWorker, NonBlockingLogWriter};
static TRACING_INIT: OnceLock<Result<(), String>> = OnceLock::new();
pub type LogReloader = Box<dyn Fn(&str) + Send + Sync>;
@@ -385,17 +390,12 @@ pub(crate) fn init_tracing(config: ServiceRuntimeConfig) -> Result<(), RuntimeBo
.unwrap_or_else(|_| config.default_log_filter.into());
let identity = RuntimeLogIdentity::from_config(&config);
let (file_writer, startup_cleanup_warning) =
if config.observability.log_destination.needs_file_sink() {
let Some(file_logging) = config.observability.file_logging.clone() else {
return Err("file logging requires a configured log directory".to_string());
};
let (writer, startup_cleanup_warning) =
RollingFileMakeWriter::new(config.service_name, file_logging)?;
(Some(writer), startup_cleanup_warning)
} else {
(None, None)
};
let RuntimeLogWriters {
stdout_writer,
file_writer,
workers,
startup_cleanup_warning,
} = RuntimeLogWriters::new(&config)?;
let init_result = match (
config.observability.log_format,
@@ -403,16 +403,26 @@ pub(crate) fn init_tracing(config: ServiceRuntimeConfig) -> Result<(), RuntimeBo
) {
(LogFormat::Pretty, LogDestination::Stdout) => tracing_subscriber::registry()
.with(filter)
.with(tracing_subscriber::fmt::layer().event_format(
PrettyRuntimeEventFormatter::new(identity.clone(), stdout_supports_ansi()),
))
.with(
tracing_subscriber::fmt::layer()
.event_format(PrettyRuntimeEventFormatter::new(
identity.clone(),
stdout_supports_ansi(),
))
.with_writer(
stdout_writer.clone().expect("stdout writer should exist"),
),
)
.try_init(),
(LogFormat::Json, LogDestination::Stdout) => tracing_subscriber::registry()
.with(filter)
.with(
tracing_subscriber::fmt::layer()
.json()
.event_format(JsonRuntimeEventFormatter::new(identity.clone())),
.event_format(JsonRuntimeEventFormatter::new(identity.clone()))
.with_writer(
stdout_writer.clone().expect("stdout writer should exist"),
),
)
.try_init(),
(LogFormat::Pretty, LogDestination::File) => tracing_subscriber::registry()
@@ -435,9 +445,16 @@ pub(crate) fn init_tracing(config: ServiceRuntimeConfig) -> Result<(), RuntimeBo
.try_init(),
(LogFormat::Pretty, LogDestination::Both) => tracing_subscriber::registry()
.with(filter)
.with(tracing_subscriber::fmt::layer().event_format(
PrettyRuntimeEventFormatter::new(identity.clone(), stdout_supports_ansi()),
))
.with(
tracing_subscriber::fmt::layer()
.event_format(PrettyRuntimeEventFormatter::new(
identity.clone(),
stdout_supports_ansi(),
))
.with_writer(
stdout_writer.clone().expect("stdout writer should exist"),
),
)
.with(
tracing_subscriber::fmt::layer()
.with_ansi(false)
@@ -450,7 +467,10 @@ pub(crate) fn init_tracing(config: ServiceRuntimeConfig) -> Result<(), RuntimeBo
.with(
tracing_subscriber::fmt::layer()
.json()
.event_format(JsonRuntimeEventFormatter::new(identity.clone())),
.event_format(JsonRuntimeEventFormatter::new(identity.clone()))
.with_writer(
stdout_writer.clone().expect("stdout writer should exist"),
),
)
.with(
tracing_subscriber::fmt::layer()
@@ -463,6 +483,7 @@ pub(crate) fn init_tracing(config: ServiceRuntimeConfig) -> Result<(), RuntimeBo
.map_err(|err| err.to_string());
if init_result.is_ok() {
register_log_workers(workers);
if let Some(warning) = startup_cleanup_warning.as_ref() {
emit_log_cleanup_warning("startup", warning.log_dir.as_path(), &warning.error);
}
@@ -497,39 +518,35 @@ pub fn init_reloadable_service_tracing(
let (filter_layer, reload_handle) = reload::Layer::new(filter);
let identity = RuntimeLogIdentity::from_config(&config);
let (file_writer, startup_cleanup_warning) =
if config.observability.log_destination.needs_file_sink() {
let Some(file_logging) = config.observability.file_logging.clone() else {
return Err(RuntimeBootstrapError::Tracing(
"file logging requires a configured log directory".to_string(),
));
};
let (writer, startup_cleanup_warning) =
RollingFileMakeWriter::new(config.service_name, file_logging)
.map_err(RuntimeBootstrapError::Tracing)?;
(Some(writer), startup_cleanup_warning)
} else {
(None, None)
};
let RuntimeLogWriters {
stdout_writer,
file_writer,
workers,
startup_cleanup_warning,
} = RuntimeLogWriters::new(&config).map_err(RuntimeBootstrapError::Tracing)?;
match (
config.observability.log_format,
config.observability.log_destination,
) {
(LogFormat::Pretty, LogDestination::Stdout) => {
tracing_subscriber::registry()
.with(filter_layer)
.with(tracing_subscriber::fmt::layer().event_format(
PrettyRuntimeEventFormatter::new(identity.clone(), stdout_supports_ansi()),
))
.try_init()
}
(LogFormat::Pretty, LogDestination::Stdout) => tracing_subscriber::registry()
.with(filter_layer)
.with(
tracing_subscriber::fmt::layer()
.event_format(PrettyRuntimeEventFormatter::new(
identity.clone(),
stdout_supports_ansi(),
))
.with_writer(stdout_writer.clone().expect("stdout writer should exist")),
)
.try_init(),
(LogFormat::Json, LogDestination::Stdout) => tracing_subscriber::registry()
.with(filter_layer)
.with(
tracing_subscriber::fmt::layer()
.json()
.event_format(JsonRuntimeEventFormatter::new(identity.clone())),
.event_format(JsonRuntimeEventFormatter::new(identity.clone()))
.with_writer(stdout_writer.clone().expect("stdout writer should exist")),
)
.try_init(),
(LogFormat::Pretty, LogDestination::File) => tracing_subscriber::registry()
@@ -550,26 +567,30 @@ pub fn init_reloadable_service_tracing(
.with_writer(file_writer.clone().expect("file writer should exist")),
)
.try_init(),
(LogFormat::Pretty, LogDestination::Both) => {
tracing_subscriber::registry()
.with(filter_layer)
.with(tracing_subscriber::fmt::layer().event_format(
PrettyRuntimeEventFormatter::new(identity.clone(), stdout_supports_ansi()),
))
.with(
tracing_subscriber::fmt::layer()
.with_ansi(false)
.event_format(PrettyRuntimeEventFormatter::new(identity.clone(), false))
.with_writer(file_writer.clone().expect("file writer should exist")),
)
.try_init()
}
(LogFormat::Pretty, LogDestination::Both) => tracing_subscriber::registry()
.with(filter_layer)
.with(
tracing_subscriber::fmt::layer()
.event_format(PrettyRuntimeEventFormatter::new(
identity.clone(),
stdout_supports_ansi(),
))
.with_writer(stdout_writer.clone().expect("stdout writer should exist")),
)
.with(
tracing_subscriber::fmt::layer()
.with_ansi(false)
.event_format(PrettyRuntimeEventFormatter::new(identity.clone(), false))
.with_writer(file_writer.clone().expect("file writer should exist")),
)
.try_init(),
(LogFormat::Json, LogDestination::Both) => tracing_subscriber::registry()
.with(filter_layer)
.with(
tracing_subscriber::fmt::layer()
.json()
.event_format(JsonRuntimeEventFormatter::new(identity.clone())),
.event_format(JsonRuntimeEventFormatter::new(identity.clone()))
.with_writer(stdout_writer.clone().expect("stdout writer should exist")),
)
.with(
tracing_subscriber::fmt::layer()
@@ -581,6 +602,7 @@ pub fn init_reloadable_service_tracing(
}
.map_err(|err| RuntimeBootstrapError::Tracing(err.to_string()))?;
register_log_workers(workers);
if let Some(warning) = startup_cleanup_warning.as_ref() {
emit_log_cleanup_warning("startup", warning.log_dir.as_path(), &warning.error);
}
@@ -595,6 +617,54 @@ pub fn init_reloadable_service_tracing(
}))
}
struct RuntimeLogWriters {
stdout_writer: Option<NonBlockingLogWriter>,
file_writer: Option<NonBlockingLogWriter>,
workers: Vec<LogWorker>,
startup_cleanup_warning: Option<StartupCleanupWarning>,
}
impl RuntimeLogWriters {
fn new(config: &ServiceRuntimeConfig) -> Result<Self, String> {
let (file_sink, startup_cleanup_warning) =
if config.observability.log_destination.needs_file_sink() {
let file_logging = config
.observability
.file_logging
.clone()
.ok_or("file logging requires a configured log directory")?;
let (sink, warning) =
RollingFileMakeWriter::new(config.service_name, file_logging)?;
(Some(sink), warning)
} else {
(None, None)
};
let mut workers = Vec::with_capacity(2);
let stdout_writer = if config.observability.log_destination != LogDestination::File {
let (writer, worker) = NonBlockingLogWriter::new("stdout", io::stdout())
.map_err(|err| format!("failed to start stdout log writer: {err}"))?;
workers.push(worker);
Some(writer)
} else {
None
};
let file_writer = if let Some(sink) = file_sink {
let (writer, worker) = NonBlockingLogWriter::new("file", sink.make_writer())
.map_err(|err| format!("failed to start file log writer: {err}"))?;
workers.push(worker);
Some(writer)
} else {
None
};
Ok(Self {
stdout_writer,
file_writer,
workers,
startup_cleanup_warning,
})
}
}
#[derive(Debug, Clone)]
struct RollingFileMakeWriter {
sink: Arc<RollingFileSink>,
@@ -692,7 +762,10 @@ impl RollingFileSink {
}
fn write(&self, buf: &[u8]) -> io::Result<usize> {
let now = Local::now();
self.write_at(buf, Local::now())
}
fn write_at(&self, buf: &[u8], now: DateTime<Local>) -> io::Result<usize> {
let mut state = self
.state
.lock()
@@ -833,8 +906,19 @@ fn spawn_log_cleanup_task(service_name: &'static str, config: FileLoggingConfig)
let interval = Duration::from_secs(6 * 60 * 60);
loop {
tokio::time::sleep(interval).await;
if let Err(err) = cleanup_log_files(service_name, &config) {
emit_log_cleanup_warning("background", config.dir.as_path(), &err);
let cleanup_config = config.clone();
match tokio::task::spawn_blocking(move || {
cleanup_log_files(service_name, &cleanup_config)
})
.await
{
Ok(Ok(_)) => {}
Ok(Err(err)) => {
emit_log_cleanup_warning("background", config.dir.as_path(), &err);
}
Err(err) => {
emit_log_cleanup_warning("background", config.dir.as_path(), &err);
}
}
}
});
@@ -1028,6 +1112,78 @@ mod tests {
);
}
#[test]
fn rolling_file_sink_rotates_without_mixing_bucket_contents() {
for rotation in [LogRotation::Hourly, LogRotation::Daily] {
let dir = std::env::temp_dir().join(format!("aether-runtime-logs-{}", Uuid::new_v4()));
let config = FileLoggingConfig::new(&dir, rotation, 7, 30);
let (sink, _) = RollingFileSink::new("runtime-test", config).expect("sink should open");
let before = Local
.with_ymd_and_hms(2026, 4, 4, 23, 59, 59)
.single()
.expect("timestamp should build");
let after = before + chrono::Duration::seconds(2);
assert_eq!(sink.write_at(b"before\n", before).unwrap(), 7);
assert_eq!(sink.write_at(b"after\n", after).unwrap(), 6);
sink.flush().unwrap();
for (instant, expected) in [(before, "before\n"), (after, "after\n")] {
let path =
bucketed_log_path(&dir, "runtime-test", &log_bucket_key(rotation, instant));
assert_eq!(fs::read_to_string(&path).unwrap(), expected);
#[cfg(unix)]
{
use std::os::unix::fs::PermissionsExt as _;
assert_eq!(
fs::metadata(path).unwrap().permissions().mode() & 0o777,
0o600
);
}
}
drop(sink);
fs::remove_dir_all(&dir).unwrap();
}
}
#[cfg(unix)]
#[test]
fn failed_rotation_preserves_old_file_and_can_retry_safely() {
use std::os::unix::fs::symlink;
let dir = std::env::temp_dir().join(format!("aether-runtime-logs-{}", Uuid::new_v4()));
let config = FileLoggingConfig::new(&dir, LogRotation::Daily, 7, 30);
let (sink, _) = RollingFileSink::new("runtime-test", config).unwrap();
let before = Local
.with_ymd_and_hms(2026, 4, 4, 12, 0, 0)
.single()
.unwrap();
let after = before + chrono::Duration::days(1);
let old_bucket = log_bucket_key(LogRotation::Daily, before);
let old_path = bucketed_log_path(&dir, "runtime-test", &old_bucket);
let new_path = bucketed_log_path(
&dir,
"runtime-test",
&log_bucket_key(LogRotation::Daily, after),
);
let victim = dir.join("victim.txt");
fs::write(&victim, b"unchanged").unwrap();
sink.write_at(b"before\n", before).unwrap();
symlink(&victim, &new_path).unwrap();
assert!(sink.write_at(b"rejected\n", after).is_err());
assert_eq!(sink.state.lock().unwrap().current_bucket, old_bucket);
assert_eq!(fs::read(&victim).unwrap(), b"unchanged");
assert_eq!(fs::read(&old_path).unwrap(), b"before\n");
fs::remove_file(&new_path).unwrap();
sink.write_at(b"after\n", after).unwrap();
sink.flush().unwrap();
assert_eq!(fs::read(&new_path).unwrap(), b"after\n");
assert_eq!(fs::read(&old_path).unwrap(), b"before\n");
drop(sink);
fs::remove_dir_all(&dir).unwrap();
}
#[test]
fn cleanup_log_files_removes_matching_files_on_disk() {
let dir = std::env::temp_dir().join(format!("aether-runtime-logs-{}", Uuid::new_v4()));
File diff suppressed because it is too large Load Diff
@@ -0,0 +1,253 @@
use std::fs;
use std::io::{self, Read};
use std::path::{Path, PathBuf};
use std::process::{Child, Command, ExitStatus, Stdio};
use std::thread::JoinHandle;
use std::time::{Duration, Instant};
use aether_runtime::{
init_service_runtime, logging_metric_samples, FileLoggingConfig, LogDestination, LogFormat,
LogRotation, LogShutdownGuard, ServiceRuntimeConfig,
};
const CHILD_ENV: &str = "AETHER_TEST_BLOCKED_STDOUT_CHILD";
const DIRECTORY_ENV: &str = "AETHER_TEST_BLOCKED_STDOUT_DIR";
const SERVICE_NAME: &str = "blocked-stdout-test";
const EVENT_NAME: &str = "blocked_stdout_probe";
const TEST_NAME: &str = "blocked_stdout_does_not_block_file_logs_or_process_exit";
#[test]
fn blocked_stdout_does_not_block_file_logs_or_process_exit() {
if std::env::var_os(CHILD_ENV).is_some() {
run_child_scenario();
eprintln!("blocked stdout guard returned");
// The scenario returns normally and drops its guard. Skip libtest's own
// stdout report, while still exercising Rust's standard exit cleanup.
std::process::exit(0);
}
let directory = TestDirectory::new();
let mut command = Command::new(std::env::current_exe().expect("test executable"));
command
.args(["--exact", TEST_NAME, "--nocapture", "--quiet"])
.env(CHILD_ENV, "1")
.env(DIRECTORY_ENV, &directory.0)
.env_remove("RUST_LOG")
.env_remove("NO_COLOR")
.env_remove("FORCE_COLOR");
let mut child = BlockedStdoutChild::spawn(&mut command).expect("logging child should start");
let (status, timed_out, stderr) = child
.wait(Duration::from_secs(8))
.expect("logging child should be reaped");
let stderr = String::from_utf8_lossy(&stderr);
assert!(
!timed_out,
"blocked stdout prevented process exit within 8 seconds: {stderr}"
);
assert!(status.success(), "logging child failed: {status}: {stderr}");
assert!(
stderr.contains("blocked stdout saturated")
&& stderr.contains("blocked stdout guard returned"),
"child did not reach saturation and return from its guard: {stderr}"
);
let records = read_file_records(&directory.0);
assert!(
!records.is_empty(),
"healthy file destination received no logs"
);
let final_markers: Vec<_> = records
.iter()
.filter(|record| record["fields"]["phase"] == "final")
.collect();
assert_eq!(
final_markers.len(),
1,
"file lost or duplicated final marker"
);
let final_marker = final_markers[0];
assert_eq!(final_marker["fields"]["event_name"], EVENT_NAME);
assert!(
final_marker["fields"]["stdout_dropped_full"]
.as_u64()
.expect("stdout queue drop counter")
+ final_marker["fields"]["stdout_dropped_bytes"]
.as_u64()
.expect("stdout byte drop counter")
> 0,
"file marker must prove stdout saturation"
);
assert_eq!(records.last().unwrap()["fields"]["phase"], "final");
}
fn run_child_scenario() {
let _shutdown = LogShutdownGuard::new();
let directory = PathBuf::from(std::env::var_os(DIRECTORY_ENV).expect("child log directory"));
init_service_runtime(
ServiceRuntimeConfig::new(SERVICE_NAME, "info")
.with_log_destination(LogDestination::Both)
.with_log_format(LogFormat::Json)
.with_file_logging(FileLoggingConfig::new(directory, LogRotation::Daily, 7, 30)),
)
.expect("both log destinations should initialize");
let payload = "x".repeat(384);
let flood_deadline = Instant::now() + Duration::from_secs(3);
let mut emitted = 0;
while emitted < 20_000 && Instant::now() < flood_deadline {
tracing::info!(
event_name = EVENT_NAME,
phase = "flood",
sequence = emitted,
payload = %payload,
"fill unread stdout"
);
emitted += 1;
if emitted % 64 == 0 && stdout_dropped_events() > 0 {
break;
}
}
assert!(stdout_dropped_events() > 0, "stdout queue did not saturate");
let file_deadline = Instant::now() + Duration::from_secs(1);
while metric("logging_file_retained_bytes") > 0 && Instant::now() < file_deadline {
std::thread::sleep(Duration::from_millis(5));
}
assert_eq!(
metric("logging_file_retained_bytes"),
0,
"file writer stalled"
);
assert_eq!(metric("logging_file_write_errors_total"), 0);
let dropped_full = metric("logging_stdout_dropped_full_total");
let dropped_bytes = metric("logging_stdout_dropped_bytes_total");
eprintln!(
"blocked stdout saturated: full={dropped_full} bytes={dropped_bytes} emitted={emitted}"
);
tracing::info!(
event_name = EVENT_NAME,
phase = "final",
stdout_dropped_full = dropped_full,
stdout_dropped_bytes = dropped_bytes,
"healthy file final marker"
);
}
fn metric(name: &str) -> u64 {
logging_metric_samples()
.into_iter()
.find(|sample| sample.name == name)
.unwrap_or_else(|| panic!("missing logging metric: {name}"))
.value
}
fn stdout_dropped_events() -> u64 {
metric("logging_stdout_dropped_full_total") + metric("logging_stdout_dropped_bytes_total")
}
fn read_file_records(directory: &Path) -> Vec<serde_json::Value> {
let mut paths: Vec<_> = fs::read_dir(directory)
.expect("log directory")
.map(|entry| entry.expect("log entry").path())
.filter(|path| {
path.file_name()
.and_then(|name| name.to_str())
.is_some_and(|name| name.starts_with(SERVICE_NAME) && name.ends_with(".log"))
})
.collect();
paths.sort();
let mut records = Vec::new();
for path in paths {
let contents = fs::read_to_string(path).expect("UTF-8 file logs");
assert!(contents.ends_with('\n'), "partial final file record");
for line in contents.lines() {
assert!(line.len() < 1024, "test event exceeded 1 KiB");
records.push(serde_json::from_str(line).expect("complete JSON file record"));
}
}
records
}
struct BlockedStdoutChild {
child: Child,
stderr_reader: Option<JoinHandle<io::Result<Vec<u8>>>>,
}
impl BlockedStdoutChild {
fn spawn(command: &mut Command) -> io::Result<Self> {
let child = command
.stdout(Stdio::piped())
.stderr(Stdio::piped())
.spawn()?;
let mut guarded = Self {
child,
stderr_reader: None,
};
let mut stderr = guarded.child.stderr.take().expect("child stderr pipe");
guarded.stderr_reader = Some(std::thread::Builder::new().spawn(move || {
let mut captured = Vec::new();
let mut chunk = [0u8; 1024];
loop {
let count = stderr.read(&mut chunk)?;
if count == 0 {
return Ok(captured);
}
let retained = count.min((16 * 1024usize).saturating_sub(captured.len()));
captured.extend_from_slice(&chunk[..retained]);
}
})?);
Ok(guarded)
}
fn wait(&mut self, timeout: Duration) -> io::Result<(ExitStatus, bool, Vec<u8>)> {
let deadline = Instant::now() + timeout;
let (status, timed_out) = loop {
if let Some(status) = self.child.try_wait()? {
break (status, false);
}
if Instant::now() >= deadline {
let _ = self.child.kill();
break (self.child.wait()?, true);
}
std::thread::sleep(Duration::from_millis(10));
};
// Keep the stdout read end open and completely unread until the child
// has exited or been killed. Closing it earlier would unblock writes.
drop(self.child.stdout.take());
let stderr = self
.stderr_reader
.take()
.expect("stderr reader")
.join()
.map_err(|_| io::Error::other("stderr reader panicked"))??;
Ok((status, timed_out, stderr))
}
}
impl Drop for BlockedStdoutChild {
fn drop(&mut self) {
let _ = self.child.kill();
let _ = self.child.wait();
drop(self.child.stdout.take());
if let Some(reader) = self.stderr_reader.take() {
let _ = reader.join();
}
}
}
struct TestDirectory(PathBuf);
impl TestDirectory {
fn new() -> Self {
let path =
std::env::temp_dir().join(format!("aether-blocked-stdout-{}", uuid::Uuid::new_v4()));
fs::create_dir(&path).expect("test directory");
Self(path)
}
}
impl Drop for TestDirectory {
fn drop(&mut self) {
let _ = fs::remove_dir_all(&self.0);
}
}
@@ -0,0 +1,354 @@
use std::fs;
use std::io::Read;
use std::path::{Path, PathBuf};
use std::process::{Command, Output, Stdio};
use std::time::{Duration, Instant};
use aether_runtime::{
init_reloadable_service_tracing, init_service_runtime, FileLoggingConfig, LogDestination,
LogFormat, LogRotation, LogShutdownGuard, ServiceRuntimeConfig,
};
const CASE_ENV: &str = "AETHER_TEST_NONBLOCKING_LOGGING_CASE";
const DIRECTORY_ENV: &str = "AETHER_TEST_NONBLOCKING_LOGGING_DIR";
const EVENT_NAME: &str = "nonblocking_logging_probe";
const SERVICE_NAME: &str = "nonblocking-logging-test";
const RECORD_COUNT: usize = 32;
const FIELD_VALUE: &str = "quote\" newline\n backslash\\ \u{4e2d}\u{6587}";
#[test]
fn nonblocking_logging_entrypoints_reload_and_guard_drain() {
if let Ok(scenario) = std::env::var(CASE_ENV) {
run_scenario(&scenario);
return;
}
let root = TestDirectory::new();
for entrypoint in ["standard", "reloadable"] {
for destination in ["stdout", "file", "both"] {
for format in ["pretty", "json"] {
let scenario = format!("{entrypoint}-{destination}-{format}");
let directory = root.0.join(&scenario);
fs::create_dir(&directory).expect("scenario directory");
let mut command = Command::new(std::env::current_exe().expect("test executable"));
command
.args([
"--exact",
"nonblocking_logging_entrypoints_reload_and_guard_drain",
"--nocapture",
"--quiet",
])
.env(CASE_ENV, &scenario)
.env(DIRECTORY_ENV, &directory)
.env_remove("RUST_LOG")
.env_remove("NO_COLOR")
.env_remove("FORCE_COLOR");
let output = run_subprocess(&mut command);
let stdout = String::from_utf8(output.stdout).expect("UTF-8 stdout");
let stderr = String::from_utf8(output.stderr).expect("UTF-8 stderr");
assert!(output.status.success(), "{scenario}: {stdout}\n{stderr}");
let file_output = read_log_files(&directory);
verify_output(
&stdout,
entrypoint,
format,
destination != "file",
&scenario,
);
verify_output(
&file_output,
entrypoint,
format,
destination != "stdout",
&scenario,
);
}
}
}
}
fn run_scenario(scenario: &str) {
let parts: Vec<_> = scenario.split('-').collect();
let [entrypoint, destination, format] = parts.as_slice() else {
panic!("invalid logging scenario: {scenario}");
};
let _shutdown = LogShutdownGuard::new();
let destination = match *destination {
"stdout" => LogDestination::Stdout,
"file" => LogDestination::File,
"both" => LogDestination::Both,
other => panic!("unknown destination: {other}"),
};
let mut config = ServiceRuntimeConfig::new(SERVICE_NAME, "info")
.with_node_role("integration")
.with_instance_id("logging-child")
.with_log_destination(destination)
.with_log_format(match *format {
"pretty" => LogFormat::Pretty,
"json" => LogFormat::Json,
other => panic!("unknown format: {other}"),
});
if matches!(destination, LogDestination::File | LogDestination::Both) {
config = config.with_file_logging(FileLoggingConfig::new(
PathBuf::from(std::env::var_os(DIRECTORY_ENV).expect("scenario log directory")),
LogRotation::Daily,
7,
30,
));
}
let reload = match *entrypoint {
"standard" => {
init_service_runtime(config).expect("standard logging initializes");
None
}
"reloadable" => Some(
init_reloadable_service_tracing("info", config)
.expect("reloadable logging initializes"),
),
other => panic!("unknown entrypoint: {other}"),
};
tracing::debug!(
event_name = EVENT_NAME,
phase = "initial_hidden",
"filtered debug"
);
tracing::info!(event_name = EVENT_NAME, phase = "initial", "initial event");
if let Some(reload) = reload {
reload("debug");
tracing::debug!(
event_name = EVENT_NAME,
phase = "reloaded_debug",
"visible debug"
);
let invalid_filter = "nonblocking_logging=not-a-level";
assert!(tracing_subscriber::EnvFilter::try_new(invalid_filter).is_err());
reload(invalid_filter);
tracing::debug!(
event_name = EVENT_NAME,
phase = "invalid_reload_unchanged",
"still debug"
);
reload("error");
tracing::info!(
event_name = EVENT_NAME,
phase = "error_filter_hidden",
"filtered info"
);
tracing::error!(
event_name = EVENT_NAME,
phase = "reloaded_error",
"visible error"
);
reload("info");
}
for sequence in 0..RECORD_COUNT {
tracing::info!(
event_name = EVENT_NAME,
phase = "record",
sequence = sequence as u64,
value = FIELD_VALUE,
"complete record"
);
}
tracing::info!(
event_name = EVENT_NAME,
phase = "tail",
"final event before guard drop"
);
// Returning drops the guard. The parent verifies the tail after process exit.
}
fn verify_output(output: &str, entrypoint: &str, format: &str, enabled: bool, scenario: &str) {
let lines: Vec<_> = output
.lines()
.filter(|line| line.contains(EVENT_NAME))
.collect();
if !enabled {
assert!(
lines.is_empty(),
"unexpected destination output in {scenario}: {output}"
);
return;
}
let expected_count = RECORD_COUNT + 2 + usize::from(entrypoint == "reloadable") * 3;
assert_eq!(
lines.len(),
expected_count,
"missing or duplicate records in {scenario}: {output}"
);
assert!(
!output.contains('\u{1b}'),
"redirected/file output must not contain ANSI: {scenario}"
);
assert!(
!output.contains("initial_hidden"),
"initial filter failed: {scenario}"
);
assert!(
!output.contains("error_filter_hidden"),
"reloaded filter failed: {scenario}"
);
let mut phases = Vec::new();
let mut sequences = Vec::new();
for line in lines {
if format == "json" {
let record: serde_json::Value = serde_json::from_str(line)
.unwrap_or_else(|error| panic!("incomplete JSON in {scenario}: {error}: {line}"));
assert_eq!(record["service"], SERVICE_NAME);
assert_eq!(record["node_role"], "integration");
assert_eq!(record["instance_id"], "logging-child");
let phase = record["fields"]["phase"].as_str().expect("event phase");
phases.push(phase.to_string());
if phase == "record" {
assert_eq!(record["fields"]["value"], FIELD_VALUE);
sequences.push(
record["fields"]["sequence"]
.as_u64()
.expect("record sequence"),
);
}
} else {
assert!(
line.contains(" | INFO") || line.contains(" | DEBUG") || line.contains(" | ERROR"),
"incomplete Pretty record in {scenario}: {line}"
);
let phase = [
"initial",
"reloaded_debug",
"invalid_reload_unchanged",
"reloaded_error",
"record",
"tail",
]
.into_iter()
.find(|phase| line.contains(&format!("phase=\"{phase}\"")))
.expect("complete Pretty phase field");
phases.push(phase.to_string());
if phase == "record" {
let expected_value = format!("value={FIELD_VALUE:?}");
assert!(
line.contains(&expected_value),
"incomplete Pretty value in {scenario}: {line}"
);
let sequence = line
.split_whitespace()
.find_map(|field| field.strip_prefix("sequence="))
.expect("complete Pretty sequence field")
.parse::<u64>()
.expect("sequence number");
sequences.push(sequence);
}
}
}
assert_eq!(phases.first().map(String::as_str), Some("initial"));
assert_eq!(
phases.last().map(String::as_str),
Some("tail"),
"guard lost tail event: {scenario}"
);
for phase in [
"reloaded_debug",
"invalid_reload_unchanged",
"reloaded_error",
] {
assert_eq!(
phases
.iter()
.filter(|value| value.as_str() == phase)
.count(),
usize::from(entrypoint == "reloadable"),
"reload phase {phase} in {scenario}"
);
}
assert_eq!(
sequences,
(0..RECORD_COUNT as u64).collect::<Vec<_>>(),
"records must remain complete and ordered in {scenario}"
);
}
fn read_log_files(directory: &Path) -> String {
let mut paths: Vec<_> = fs::read_dir(directory)
.expect("log directory")
.map(|entry| entry.expect("log directory entry").path())
.filter(|path| {
path.file_name()
.and_then(|name| name.to_str())
.is_some_and(|name| name.starts_with(SERVICE_NAME) && name.ends_with(".log"))
})
.collect();
paths.sort();
paths
.into_iter()
.map(|path| fs::read_to_string(path).expect("UTF-8 file log"))
.collect()
}
fn run_subprocess(command: &mut Command) -> Output {
let mut child = command
.stdout(Stdio::piped())
.stderr(Stdio::piped())
.spawn()
.expect("logging subprocess");
let stdout = child.stdout.take().expect("stdout pipe");
let stderr = child.stderr.take().expect("stderr pipe");
let stdout_reader = std::thread::spawn(move || read_pipe(stdout));
let stderr_reader = std::thread::spawn(move || read_pipe(stderr));
let deadline = Instant::now() + Duration::from_secs(10);
let mut timed_out = false;
let status = loop {
if let Some(status) = child.try_wait().expect("child status") {
break status;
}
if Instant::now() >= deadline {
timed_out = true;
let _ = child.kill();
break child.wait().expect("reap timed out child");
}
std::thread::sleep(Duration::from_millis(10));
};
let output = Output {
status,
stdout: stdout_reader.join().expect("stdout reader"),
stderr: stderr_reader.join().expect("stderr reader"),
};
assert!(
!timed_out,
"logging subprocess timed out: {}\n{}",
String::from_utf8_lossy(&output.stdout),
String::from_utf8_lossy(&output.stderr)
);
output
}
fn read_pipe(mut pipe: impl Read) -> Vec<u8> {
const MAX_CAPTURE_BYTES: usize = 4 * 1024 * 1024;
let mut captured = Vec::new();
let mut chunk = [0u8; 8192];
loop {
let count = pipe.read(&mut chunk).expect("drain child pipe");
if count == 0 {
return captured;
}
let retained = count.min(MAX_CAPTURE_BYTES.saturating_sub(captured.len()));
captured.extend_from_slice(&chunk[..retained]);
}
}
struct TestDirectory(PathBuf);
impl TestDirectory {
fn new() -> Self {
let path =
std::env::temp_dir().join(format!("aether-nonblocking-logs-{}", uuid::Uuid::new_v4()));
fs::create_dir(&path).expect("test directory");
Self(path)
}
}
impl Drop for TestDirectory {
fn drop(&mut self) {
let _ = fs::remove_dir_all(&self.0);
}
}
@@ -1,13 +1,15 @@
#![cfg(target_os = "linux")]
use std::fs;
use std::io::Read;
use std::os::unix::fs::{MetadataExt as _, PermissionsExt as _};
use std::path::PathBuf;
use std::process::Command;
use std::process::{Command, Output, Stdio};
use std::time::{Duration, Instant};
use aether_runtime::{
init_reloadable_service_tracing, init_service_runtime, FileLoggingConfig, LogDestination,
LogFormat, LogRotation, ServiceRuntimeConfig,
init_reloadable_service_tracing, init_service_runtime, shutdown_logging, FileLoggingConfig,
LogDestination, LogFormat, LogRotation, ServiceRuntimeConfig,
};
#[test]
@@ -23,7 +25,9 @@ fn root_appends_to_existing_logs_without_changing_ownership() {
for format in ["pretty", "json"] {
for owner in ["0", "1000", "65532", "new"] {
let scenario = format!("{entrypoint}-{destination}-{format}-{owner}");
let output = Command::new(std::env::current_exe().expect("test executable"))
let mut command =
Command::new(std::env::current_exe().expect("test executable"));
command
.args([
"--ignored",
"--exact",
@@ -31,9 +35,8 @@ fn root_appends_to_existing_logs_without_changing_ownership() {
"--nocapture",
])
.env("AETHER_TEST_ROOT_LOGGING_CASE", &scenario)
.env_remove("RUST_LOG")
.output()
.expect("root logging subprocess");
.env_remove("RUST_LOG");
let output = run_subprocess(&mut command);
let stdout = String::from_utf8_lossy(&output.stdout);
let stderr = String::from_utf8_lossy(&output.stderr);
assert!(output.status.success(), "{scenario}: {stdout}\n{stderr}");
@@ -49,6 +52,51 @@ fn root_appends_to_existing_logs_without_changing_ownership() {
}
}
fn run_subprocess(command: &mut Command) -> Output {
let mut child = command
.stdout(Stdio::piped())
.stderr(Stdio::piped())
.spawn()
.expect("root logging subprocess");
let mut stdout = child.stdout.take().expect("stdout pipe");
let mut stderr = child.stderr.take().expect("stderr pipe");
let stdout_reader = std::thread::spawn(move || {
let mut bytes = Vec::new();
stdout.read_to_end(&mut bytes).expect("read child stdout");
bytes
});
let stderr_reader = std::thread::spawn(move || {
let mut bytes = Vec::new();
stderr.read_to_end(&mut bytes).expect("read child stderr");
bytes
});
let deadline = Instant::now() + Duration::from_secs(10);
let mut timed_out = false;
let status = loop {
if let Some(status) = child.try_wait().expect("child status") {
break status;
}
if Instant::now() >= deadline {
timed_out = true;
let _ = child.kill();
break child.wait().expect("reap timed out child");
}
std::thread::sleep(Duration::from_millis(10));
};
let output = Output {
status,
stdout: stdout_reader.join().expect("stdout reader"),
stderr: stderr_reader.join().expect("stderr reader"),
};
assert!(
!timed_out,
"root logging subprocess timed out: {}\n{}",
String::from_utf8_lossy(&output.stdout),
String::from_utf8_lossy(&output.stderr)
);
output
}
fn run_scenario(scenario: &str) {
assert_eq!(unsafe { libc::geteuid() }, 0);
assert_eq!(unsafe { libc::getegid() }, 0);
@@ -117,6 +165,10 @@ fn run_scenario(scenario: &str) {
other => panic!("unknown entrypoint: {other}"),
};
tracing::info!("root logging ready");
assert!(
shutdown_logging(Duration::from_secs(2)),
"root file logging should drain"
);
let metadata = fs::metadata(&log_file).expect("written log file");
assert_eq!(metadata.uid(), expected_owner);