This commit is contained in:
Mateusz Gruszczyński committed 2026-10-09 17:09:41 +02:00
1 parent 3e33982cd3
commit ad95bfb050
27 files changed
+309 -80

No files matched your search

+33 -5
View File
@@ -161,7 +161,7 @@ fn format_error_event(event: &ErrorEvent, format: ErrorLogFormat) -> Vec<u8> {
ErrorLogFormat::Json => {
let mut object = Map::new();
object.insert("timestamp".into(), Value::String(event.timestamp.clone()));
object.insert("level".into(), Value::String("ERROR".into()));
object.insert("level".into(), Value::String(event.level.clone()));
object.insert("target".into(), Value::String(event.target.clone()));
object.insert("message".into(), Value::String(event.message.clone()));
for (key, value) in &event.fields {
@@ -176,8 +176,9 @@ fn format_error_event(event: &ErrorEvent, format: ErrorLogFormat) -> Vec<u8> {
ErrorLogFormat::Raw => {
let one_line = |value: &str| value.replace('\r', "\\r").replace('\n', "\\n");
let mut line = format!(
"{} ERROR {} {}",
"{} {} {} {}",
event.timestamp,
event.level,
event.target,
one_line(&event.message)
);
@@ -193,6 +194,21 @@ fn format_error_event(event: &ErrorEvent, format: ErrorLogFormat) -> Vec<u8> {
}
}
fn write_error_fallback(event: &ErrorEvent, format: ErrorLogFormat) {
// File unavailable or the bounded queue is full: preserve the redacted
// diagnostic on stderr rather than dropping it into a black hole.
let line = format_error_event(event, format);
let mut stderr = io::stderr().lock();
let _ = stderr.write_all(&line);
}
fn warn_error_sink_failure(path: &std::path::Path, error: &dyn std::fmt::Display, action: &str) {
let path = redact_text(&path.display().to_string());
let error = redact_text(&error.to_string());
let mut stderr = io::stderr().lock();
let _ = writeln!(stderr, "RustProxy error log {action} ({path}): {error}; using stderr fallback");
}
async fn error_log_loop(
mut receiver: mpsc::Receiver<ErrorEvent>,
settings: Arc<ArcSwap<ErrorLogSettings>>,
@@ -232,6 +248,9 @@ async fn error_log_loop(
file = None;
open_path = None;
retry_after = None;
// A queued event may outlive a live settings change. It was
// suppressed on the console when queued; do not lose it now.
write_error_fallback(&event, config.format);
continue;
}
let path = PathBuf::from(&config.path);
@@ -250,24 +269,33 @@ async fn error_log_loop(
errors.fetch_add(1, Ordering::Relaxed);
retry_after = Some(Instant::now() + ERROR_LOG_RETRY);
if last_warning.is_none_or(|time| time.elapsed() >= ERROR_LOG_RETRY) {
tracing::warn!(path=%path.display(), %error, "optional error log file is unavailable");
warn_error_sink_failure(&path, &error, "open failed");
last_warning = Some(Instant::now());
}
}
}
}
let Some(opened) = file.as_mut() else {
write_error_fallback(&event, config.format);
continue;
};
let line = format_error_event(&event, config.format);
if let Err(error) = opened.write_all(&line).await {
// Tokio's File buffers writes; flush so diagnostics are visible to
// log readers promptly and a later shutdown cannot strand a record.
let write = async {
opened.write_all(&line).await?;
opened.flush().await
}
.await;
if let Err(error) = write {
errors.fetch_add(1, Ordering::Relaxed);
file = None;
retry_after = Some(Instant::now() + ERROR_LOG_RETRY);
if last_warning.is_none_or(|time| time.elapsed() >= ERROR_LOG_RETRY) {
tracing::warn!(path=%path.display(), %error, "optional error log write failed");
warn_error_sink_failure(&path, &error, "write failed");
last_warning = Some(Instant::now());
}
write_error_fallback(&event, config.format);
} else {
written.fetch_add(1, Ordering::Relaxed);
}
+18 -2
View File
@@ -328,6 +328,7 @@ pub struct ErrorLogStats {
#[derive(Debug)]
struct ErrorEvent {
timestamp: String,
level: String,
target: String,
message: String,
fields: BTreeMap<String, String>,
@@ -369,9 +370,23 @@ impl ErrorLogController {
self.settings.store(Arc::new(settings));
self.settings_changed.send_replace(());
}
/// All diagnostics go to stderr when file logging is disabled. With a file
/// configured, warnings/errors go only to that file (unless the sink fails).
/// Informational startup messages remain on the console.
pub fn console_enabled_for(&self, level: &Level) -> bool {
!matches!(*level, Level::WARN | Level::ERROR) || !self.settings.load().enabled
}
fn push(&self, event: ErrorEvent) {
if self.settings.load().enabled && self.sender.try_send(event).is_err() {
let config = self.settings.load();
if !config.enabled {
return;
}
if let Err(error) = self.sender.try_send(event) {
self.dropped.fetch_add(1, Ordering::Relaxed);
// An overloaded/closed sink must not silently swallow a diagnostic
// suppressed by the console filter. This emergency path is bounded
// to one event and only runs on a failed non-blocking enqueue.
write_error_fallback(&error.into_inner(), config.format);
}
}
pub fn stats(&self) -> ErrorLogStats {
@@ -451,7 +466,7 @@ impl tracing::field::Visit for EventVisitor {
}
impl<S: Subscriber> Layer<S> for ErrorLogLayer {
fn on_event(&self, event: &Event<'_>, _ctx: LayerContext<'_, S>) {
if *event.metadata().level() != Level::ERROR {
if !matches!(*event.metadata().level(), Level::ERROR | Level::WARN) {
return;
}
let mut visitor = EventVisitor::default();
@@ -466,6 +481,7 @@ impl<S: Subscriber> Layer<S> for ErrorLogLayer {
}
self.controller.push(ErrorEvent {
timestamp: rfc3339_now(),
level: event.metadata().level().as_str().to_owned(),
target: event.metadata().target().to_owned(),
message: redact_text(visitor.message.as_deref().unwrap_or("error")),
fields,
+50
View File
@@ -1,5 +1,6 @@
mod tests {
use super::*;
use tracing_subscriber::prelude::*;
fn entry() -> LogEntry {
LogEntry {
@@ -212,6 +213,7 @@ mod tests {
fn error_json_is_one_record_and_reserved_fields_cannot_be_overwritten() {
let event = ErrorEvent {
timestamp: "2026-10-03T12:34:56.123Z".into(),
level: "ERROR".into(),
target: "rust_proxy::http".into(),
message: "upstream failed\nsecond line".into(),
fields: BTreeMap::from([
@@ -224,6 +226,54 @@ mod tests {
let value: Value = serde_json::from_slice(&line).unwrap();
assert_eq!(value["message"], "upstream failed\nsecond line");
assert_eq!(value["request_id"], "abc");
assert_eq!(value["level"], "ERROR");
}
#[tokio::test]
async fn diagnostics_switch_between_console_and_file_without_restart() {
let tmp = tempfile::tempdir().unwrap();
let path = tmp.path().join("error.log");
let controller = ErrorLogController::start();
assert!(controller.console_enabled_for(&Level::WARN));
assert!(controller.console_enabled_for(&Level::ERROR));
controller.configure(ErrorLogSettings {
enabled: true,
path: path.to_string_lossy().into_owned(),
format: ErrorLogFormat::Json,
});
assert!(!controller.console_enabled_for(&Level::WARN));
assert!(!controller.console_enabled_for(&Level::ERROR));
assert!(controller.console_enabled_for(&Level::INFO));
let subscriber = tracing_subscriber::registry().with(ErrorLogLayer::new(controller.clone()));
tracing::subscriber::with_default(subscriber, || {
tracing::warn!(target: "rust_proxy::tests", "PHP-FPM FastCGI stderr");
tracing::error!(target: "rust_proxy::tests", "RustProxy worker panicked");
});
let content = tokio::time::timeout(Duration::from_secs(5), async {
loop {
if let Ok(content) = tokio::fs::read_to_string(&path).await {
if content.lines().count() == 2 {
break content;
}
}
tokio::time::sleep(Duration::from_millis(20)).await;
}
})
.await
.expect("diagnostics were not written to the configured error file");
let entries: Vec<Value> = content
.lines()
.map(|line| serde_json::from_str(line).unwrap())
.collect();
assert_eq!(entries[0]["level"], "WARN");
assert_eq!(entries[1]["level"], "ERROR");
controller.configure(ErrorLogSettings::default());
assert!(controller.console_enabled_for(&Level::WARN));
assert!(controller.console_enabled_for(&Level::ERROR));
}
#[test]