v0.26.0
This commit is contained in:
1 parent
d168ee2afa
commit
ddc5c6593f
70 files changed
+2293
-594
No files matched your search
@@ -0,0 +1,276 @@
|
||||
impl IoWrite for RedactingWriter {
|
||||
fn write(&mut self, bytes: &[u8]) -> io::Result<usize> {
|
||||
self.buffer.extend_from_slice(bytes);
|
||||
Ok(bytes.len())
|
||||
}
|
||||
fn flush(&mut self) -> io::Result<()> {
|
||||
if self.buffer.is_empty() {
|
||||
return Ok(());
|
||||
}
|
||||
let text = String::from_utf8_lossy(&self.buffer);
|
||||
let redacted = redact_text(&text);
|
||||
let mut stderr = io::stderr().lock();
|
||||
stderr.write_all(redacted.as_bytes())?;
|
||||
stderr.flush()?;
|
||||
self.buffer.clear();
|
||||
Ok(())
|
||||
}
|
||||
}
|
||||
impl Drop for RedactingWriter {
|
||||
fn drop(&mut self) {
|
||||
let _ = self.flush();
|
||||
}
|
||||
}
|
||||
impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for RedactingStderr {
|
||||
type Writer = RedactingWriter;
|
||||
fn make_writer(&'a self) -> Self::Writer {
|
||||
RedactingWriter {
|
||||
buffer: Vec::with_capacity(512),
|
||||
}
|
||||
}
|
||||
}
|
||||
fn redact_regex(pattern: &'static str) -> &'static regex::Regex {
|
||||
static AUTH: OnceLock<regex::Regex> = OnceLock::new();
|
||||
static QUERY: OnceLock<regex::Regex> = OnceLock::new();
|
||||
static JSON: OnceLock<regex::Regex> = OnceLock::new();
|
||||
static KV: OnceLock<regex::Regex> = OnceLock::new();
|
||||
static PEM: OnceLock<regex::Regex> = OnceLock::new();
|
||||
match pattern {
|
||||
"auth" => AUTH.get_or_init(|| regex::Regex::new(r"(?i)(authorization\s*[:=]\s*)(?:bearer\s+)?[^\s,;]+" ).expect("redaction regex")),
|
||||
"query" => QUERY.get_or_init(|| regex::Regex::new(r"(?i)([?&](?:token|access_token|api_token|password|backup_password|secret|credential|credentials|key_secret|application_secret|consumer_key)=)[^&\s]+" ).expect("redaction regex")),
|
||||
"json" => JSON.get_or_init(|| regex::Regex::new(r#"(?i)(\"(?:authorization|proxy_authorization|api_token|access_token|application_secret|consumer_key|key_secret|backup_password|password|credential|credentials|secret|token|private_key|master_key)\"\s*:\s*\")[^\"]*(\")"#).expect("redaction regex")),
|
||||
"kv" => KV.get_or_init(|| regex::Regex::new(r#"(?i)((?:authorization|proxy[_-]?authorization|api[_-]?token|access[_-]?token|application[_-]?secret|consumer[_-]?key|key[_-]?secret|backup[_-]?password|password|credential|credentials|secret|token|private[_-]?key|master[_-]?key)\s*[=:]\s*)[^\s,;"']+"#).expect("redaction regex")),
|
||||
"pem" => PEM.get_or_init(|| regex::Regex::new(r"(?s)-----BEGIN [^-\r\n]*PRIVATE KEY-----.*?-----END [^-\r\n]*PRIVATE KEY-----" ).expect("redaction regex")),
|
||||
_ => unreachable!(),
|
||||
}
|
||||
}
|
||||
|
||||
fn is_secret_field(name: &str) -> bool {
|
||||
matches!(
|
||||
name.to_ascii_lowercase().as_str(),
|
||||
"authorization"
|
||||
| "proxy_authorization"
|
||||
| "api_token"
|
||||
| "access_token"
|
||||
| "application_secret"
|
||||
| "consumer_key"
|
||||
| "key_secret"
|
||||
| "backup_password"
|
||||
| "password"
|
||||
| "credential"
|
||||
| "credentials"
|
||||
| "secret"
|
||||
| "token"
|
||||
| "private_key"
|
||||
| "master_key"
|
||||
)
|
||||
}
|
||||
|
||||
pub fn redact_text(input: &str) -> String {
|
||||
let mut value = redact_regex("pem")
|
||||
.replace_all(input, "[REDACTED PRIVATE KEY]")
|
||||
.into_owned();
|
||||
value = redact_regex("auth")
|
||||
.replace_all(&value, "$1[REDACTED]")
|
||||
.into_owned();
|
||||
value = redact_regex("query")
|
||||
.replace_all(&value, "$1[REDACTED]")
|
||||
.into_owned();
|
||||
value = redact_regex("json")
|
||||
.replace_all(&value, "$1[REDACTED]$2")
|
||||
.into_owned();
|
||||
redact_regex("kv")
|
||||
.replace_all(&value, "$1[REDACTED]")
|
||||
.into_owned()
|
||||
}
|
||||
|
||||
fn redact_value(value: &mut Value) {
|
||||
match value {
|
||||
Value::String(text) => *text = redact_text(text),
|
||||
Value::Array(items) => {
|
||||
for item in items {
|
||||
redact_value(item);
|
||||
}
|
||||
}
|
||||
Value::Object(items) => {
|
||||
for (key, item) in items {
|
||||
if is_secret_field(key) {
|
||||
*item = Value::String("[REDACTED]".into());
|
||||
} else {
|
||||
redact_value(item);
|
||||
}
|
||||
}
|
||||
}
|
||||
_ => {}
|
||||
}
|
||||
}
|
||||
|
||||
fn rfc3339_now() -> String {
|
||||
let ms = SystemTime::now()
|
||||
.duration_since(UNIX_EPOCH)
|
||||
.unwrap_or_default()
|
||||
.as_millis() as i64;
|
||||
let seconds = ms / 1000;
|
||||
let millis = ms % 1000;
|
||||
let days = seconds.div_euclid(86_400);
|
||||
let day_seconds = seconds.rem_euclid(86_400);
|
||||
let z = days + 719_468;
|
||||
let era = if z >= 0 { z } else { z - 146_096 }.div_euclid(146_097);
|
||||
let doe = z - era * 146_097;
|
||||
let yoe = (doe - doe / 1_460 + doe / 36_524 - doe / 146_096) / 365;
|
||||
let mut year = yoe + era * 400;
|
||||
let doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
|
||||
let mp = (5 * doy + 2) / 153;
|
||||
let day = doy - (153 * mp + 2) / 5 + 1;
|
||||
let month = mp + if mp < 10 { 3 } else { -9 };
|
||||
if month <= 2 {
|
||||
year += 1;
|
||||
}
|
||||
let hour = day_seconds / 3600;
|
||||
let minute = (day_seconds % 3600) / 60;
|
||||
let second = day_seconds % 60;
|
||||
format!("{year:04}-{month:02}-{day:02}T{hour:02}:{minute:02}:{second:02}.{millis:03}Z")
|
||||
}
|
||||
|
||||
async fn open_error_file(path: PathBuf) -> Result<File> {
|
||||
let file = tokio::task::spawn_blocking(move || -> Result<std::fs::File> {
|
||||
let mut options = std::fs::OpenOptions::new();
|
||||
options.create(true).append(true).write(true);
|
||||
#[cfg(unix)]
|
||||
{
|
||||
use std::os::unix::fs::OpenOptionsExt;
|
||||
options.mode(0o600).custom_flags(libc::O_NOFOLLOW);
|
||||
}
|
||||
let file = options.open(&path)?;
|
||||
let metadata = file.metadata()?;
|
||||
ensure!(metadata.is_file(), "error log path is not a regular file");
|
||||
#[cfg(unix)]
|
||||
{
|
||||
use std::os::unix::fs::PermissionsExt;
|
||||
file.set_permissions(std::fs::Permissions::from_mode(0o600))?;
|
||||
}
|
||||
Ok(file)
|
||||
})
|
||||
.await
|
||||
.map_err(|_| anyhow::anyhow!("error log open worker failed"))??;
|
||||
Ok(File::from_std(file))
|
||||
}
|
||||
|
||||
fn format_error_event(event: &ErrorEvent, format: ErrorLogFormat) -> Vec<u8> {
|
||||
match format {
|
||||
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("target".into(), Value::String(event.target.clone()));
|
||||
object.insert("message".into(), Value::String(event.message.clone()));
|
||||
for (key, value) in &event.fields {
|
||||
if !matches!(key.as_str(), "timestamp" | "level" | "target" | "message") {
|
||||
object.insert(key.clone(), Value::String(value.clone()));
|
||||
}
|
||||
}
|
||||
let mut line = serde_json::to_vec(&Value::Object(object)).unwrap_or_default();
|
||||
line.push(b'\n');
|
||||
line
|
||||
}
|
||||
ErrorLogFormat::Raw => {
|
||||
let one_line = |value: &str| value.replace('\r', "\\r").replace('\n', "\\n");
|
||||
let mut line = format!(
|
||||
"{} ERROR {} {}",
|
||||
event.timestamp,
|
||||
event.target,
|
||||
one_line(&event.message)
|
||||
);
|
||||
for (key, value) in &event.fields {
|
||||
line.push(' ');
|
||||
line.push_str(key);
|
||||
line.push('=');
|
||||
line.push_str(&one_line(value));
|
||||
}
|
||||
line.push('\n');
|
||||
line.into_bytes()
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
async fn error_log_loop(
|
||||
mut receiver: mpsc::Receiver<ErrorEvent>,
|
||||
settings: Arc<ArcSwap<ErrorLogSettings>>,
|
||||
mut settings_changed: watch::Receiver<()>,
|
||||
written: Arc<AtomicU64>,
|
||||
errors: Arc<AtomicU64>,
|
||||
) {
|
||||
let mut open_path: Option<PathBuf> = None;
|
||||
let mut file: Option<File> = None;
|
||||
let mut retry_after: Option<Instant> = None;
|
||||
let mut last_warning: Option<Instant> = None;
|
||||
loop {
|
||||
let event = tokio::select! {
|
||||
event = receiver.recv() => match event {
|
||||
Some(event) => event,
|
||||
None => break,
|
||||
},
|
||||
changed = settings_changed.changed() => {
|
||||
if changed.is_err() && receiver.is_closed() {
|
||||
break;
|
||||
}
|
||||
let config = settings.load_full();
|
||||
let path = PathBuf::from(&config.path);
|
||||
if !config.enabled || open_path.as_ref() != Some(&path) {
|
||||
// Dropping Tokio's File closes the descriptor without blocking
|
||||
// the request path. A changed path is reopened on the next event.
|
||||
file = None;
|
||||
open_path = None;
|
||||
retry_after = None;
|
||||
}
|
||||
continue;
|
||||
}
|
||||
};
|
||||
|
||||
let config = settings.load_full();
|
||||
if !config.enabled {
|
||||
file = None;
|
||||
open_path = None;
|
||||
retry_after = None;
|
||||
continue;
|
||||
}
|
||||
let path = PathBuf::from(&config.path);
|
||||
if open_path.as_ref() != Some(&path) {
|
||||
file = None;
|
||||
open_path = Some(path.clone());
|
||||
retry_after = None;
|
||||
}
|
||||
if file.is_none() && retry_after.is_none_or(|until| Instant::now() >= until) {
|
||||
match open_error_file(path.clone()).await {
|
||||
Ok(opened) => {
|
||||
file = Some(opened);
|
||||
retry_after = None;
|
||||
}
|
||||
Err(error) => {
|
||||
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");
|
||||
last_warning = Some(Instant::now());
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
let Some(opened) = file.as_mut() else {
|
||||
continue;
|
||||
};
|
||||
let line = format_error_event(&event, config.format);
|
||||
if let Err(error) = opened.write_all(&line).await {
|
||||
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");
|
||||
last_warning = Some(Instant::now());
|
||||
}
|
||||
} else {
|
||||
written.fetch_add(1, Ordering::Relaxed);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+95
-276
@@ -1,281 +1,10 @@
|
||||
impl IoWrite for RedactingWriter {
|
||||
fn write(&mut self, bytes: &[u8]) -> io::Result<usize> {
|
||||
self.buffer.extend_from_slice(bytes);
|
||||
Ok(bytes.len())
|
||||
}
|
||||
fn flush(&mut self) -> io::Result<()> {
|
||||
if self.buffer.is_empty() {
|
||||
return Ok(());
|
||||
}
|
||||
let text = String::from_utf8_lossy(&self.buffer);
|
||||
let redacted = redact_text(&text);
|
||||
let mut stderr = io::stderr().lock();
|
||||
stderr.write_all(redacted.as_bytes())?;
|
||||
stderr.flush()?;
|
||||
self.buffer.clear();
|
||||
Ok(())
|
||||
}
|
||||
}
|
||||
impl Drop for RedactingWriter {
|
||||
fn drop(&mut self) {
|
||||
let _ = self.flush();
|
||||
}
|
||||
}
|
||||
impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for RedactingStderr {
|
||||
type Writer = RedactingWriter;
|
||||
fn make_writer(&'a self) -> Self::Writer {
|
||||
RedactingWriter {
|
||||
buffer: Vec::with_capacity(512),
|
||||
}
|
||||
}
|
||||
}
|
||||
fn redact_regex(pattern: &'static str) -> &'static regex::Regex {
|
||||
static AUTH: OnceLock<regex::Regex> = OnceLock::new();
|
||||
static QUERY: OnceLock<regex::Regex> = OnceLock::new();
|
||||
static JSON: OnceLock<regex::Regex> = OnceLock::new();
|
||||
static KV: OnceLock<regex::Regex> = OnceLock::new();
|
||||
static PEM: OnceLock<regex::Regex> = OnceLock::new();
|
||||
match pattern {
|
||||
"auth" => AUTH.get_or_init(|| regex::Regex::new(r"(?i)(authorization\s*[:=]\s*)(?:bearer\s+)?[^\s,;]+" ).expect("redaction regex")),
|
||||
"query" => QUERY.get_or_init(|| regex::Regex::new(r"(?i)([?&](?:token|access_token|api_token|password|backup_password|secret|credential|credentials|key_secret|application_secret|consumer_key)=)[^&\s]+" ).expect("redaction regex")),
|
||||
"json" => JSON.get_or_init(|| regex::Regex::new(r#"(?i)(\"(?:authorization|proxy_authorization|api_token|access_token|application_secret|consumer_key|key_secret|backup_password|password|credential|credentials|secret|token|private_key|master_key)\"\s*:\s*\")[^\"]*(\")"#).expect("redaction regex")),
|
||||
"kv" => KV.get_or_init(|| regex::Regex::new(r#"(?i)((?:authorization|proxy[_-]?authorization|api[_-]?token|access[_-]?token|application[_-]?secret|consumer[_-]?key|key[_-]?secret|backup[_-]?password|password|credential|credentials|secret|token|private[_-]?key|master[_-]?key)\s*[=:]\s*)[^\s,;"']+"#).expect("redaction regex")),
|
||||
"pem" => PEM.get_or_init(|| regex::Regex::new(r"(?s)-----BEGIN [^-\r\n]*PRIVATE KEY-----.*?-----END [^-\r\n]*PRIVATE KEY-----" ).expect("redaction regex")),
|
||||
_ => unreachable!(),
|
||||
}
|
||||
}
|
||||
|
||||
fn is_secret_field(name: &str) -> bool {
|
||||
matches!(
|
||||
name.to_ascii_lowercase().as_str(),
|
||||
"authorization"
|
||||
| "proxy_authorization"
|
||||
| "api_token"
|
||||
| "access_token"
|
||||
| "application_secret"
|
||||
| "consumer_key"
|
||||
| "key_secret"
|
||||
| "backup_password"
|
||||
| "password"
|
||||
| "credential"
|
||||
| "credentials"
|
||||
| "secret"
|
||||
| "token"
|
||||
| "private_key"
|
||||
| "master_key"
|
||||
)
|
||||
}
|
||||
|
||||
pub fn redact_text(input: &str) -> String {
|
||||
let mut value = redact_regex("pem")
|
||||
.replace_all(input, "[REDACTED PRIVATE KEY]")
|
||||
.into_owned();
|
||||
value = redact_regex("auth")
|
||||
.replace_all(&value, "$1[REDACTED]")
|
||||
.into_owned();
|
||||
value = redact_regex("query")
|
||||
.replace_all(&value, "$1[REDACTED]")
|
||||
.into_owned();
|
||||
value = redact_regex("json")
|
||||
.replace_all(&value, "$1[REDACTED]$2")
|
||||
.into_owned();
|
||||
redact_regex("kv")
|
||||
.replace_all(&value, "$1[REDACTED]")
|
||||
.into_owned()
|
||||
}
|
||||
|
||||
fn redact_value(value: &mut Value) {
|
||||
match value {
|
||||
Value::String(text) => *text = redact_text(text),
|
||||
Value::Array(items) => {
|
||||
for item in items {
|
||||
redact_value(item);
|
||||
}
|
||||
}
|
||||
Value::Object(items) => {
|
||||
for (key, item) in items {
|
||||
if is_secret_field(key) {
|
||||
*item = Value::String("[REDACTED]".into());
|
||||
} else {
|
||||
redact_value(item);
|
||||
}
|
||||
}
|
||||
}
|
||||
_ => {}
|
||||
}
|
||||
}
|
||||
|
||||
fn rfc3339_now() -> String {
|
||||
let ms = SystemTime::now()
|
||||
.duration_since(UNIX_EPOCH)
|
||||
.unwrap_or_default()
|
||||
.as_millis() as i64;
|
||||
let seconds = ms / 1000;
|
||||
let millis = ms % 1000;
|
||||
let days = seconds.div_euclid(86_400);
|
||||
let day_seconds = seconds.rem_euclid(86_400);
|
||||
let z = days + 719_468;
|
||||
let era = if z >= 0 { z } else { z - 146_096 }.div_euclid(146_097);
|
||||
let doe = z - era * 146_097;
|
||||
let yoe = (doe - doe / 1_460 + doe / 36_524 - doe / 146_096) / 365;
|
||||
let mut year = yoe + era * 400;
|
||||
let doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
|
||||
let mp = (5 * doy + 2) / 153;
|
||||
let day = doy - (153 * mp + 2) / 5 + 1;
|
||||
let month = mp + if mp < 10 { 3 } else { -9 };
|
||||
if month <= 2 {
|
||||
year += 1;
|
||||
}
|
||||
let hour = day_seconds / 3600;
|
||||
let minute = (day_seconds % 3600) / 60;
|
||||
let second = day_seconds % 60;
|
||||
format!("{year:04}-{month:02}-{day:02}T{hour:02}:{minute:02}:{second:02}.{millis:03}Z")
|
||||
}
|
||||
|
||||
async fn open_error_file(path: PathBuf) -> Result<File> {
|
||||
let file = tokio::task::spawn_blocking(move || -> Result<std::fs::File> {
|
||||
let mut options = std::fs::OpenOptions::new();
|
||||
options.create(true).append(true).write(true);
|
||||
#[cfg(unix)]
|
||||
{
|
||||
use std::os::unix::fs::OpenOptionsExt;
|
||||
options.mode(0o600).custom_flags(libc::O_NOFOLLOW);
|
||||
}
|
||||
let file = options.open(&path)?;
|
||||
let metadata = file.metadata()?;
|
||||
ensure!(metadata.is_file(), "error log path is not a regular file");
|
||||
#[cfg(unix)]
|
||||
{
|
||||
use std::os::unix::fs::PermissionsExt;
|
||||
file.set_permissions(std::fs::Permissions::from_mode(0o600))?;
|
||||
}
|
||||
Ok(file)
|
||||
})
|
||||
.await
|
||||
.map_err(|_| anyhow::anyhow!("error log open worker failed"))??;
|
||||
Ok(File::from_std(file))
|
||||
}
|
||||
|
||||
fn format_error_event(event: &ErrorEvent, format: ErrorLogFormat) -> Vec<u8> {
|
||||
match format {
|
||||
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("target".into(), Value::String(event.target.clone()));
|
||||
object.insert("message".into(), Value::String(event.message.clone()));
|
||||
for (key, value) in &event.fields {
|
||||
if !matches!(key.as_str(), "timestamp" | "level" | "target" | "message") {
|
||||
object.insert(key.clone(), Value::String(value.clone()));
|
||||
}
|
||||
}
|
||||
let mut line = serde_json::to_vec(&Value::Object(object)).unwrap_or_default();
|
||||
line.push(b'\n');
|
||||
line
|
||||
}
|
||||
ErrorLogFormat::Raw => {
|
||||
let one_line = |value: &str| value.replace('\r', "\\r").replace('\n', "\\n");
|
||||
let mut line = format!(
|
||||
"{} ERROR {} {}",
|
||||
event.timestamp,
|
||||
event.target,
|
||||
one_line(&event.message)
|
||||
);
|
||||
for (key, value) in &event.fields {
|
||||
line.push(' ');
|
||||
line.push_str(key);
|
||||
line.push('=');
|
||||
line.push_str(&one_line(value));
|
||||
}
|
||||
line.push('\n');
|
||||
line.into_bytes()
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
async fn error_log_loop(
|
||||
mut receiver: mpsc::Receiver<ErrorEvent>,
|
||||
settings: Arc<ArcSwap<ErrorLogSettings>>,
|
||||
mut settings_changed: watch::Receiver<()>,
|
||||
written: Arc<AtomicU64>,
|
||||
errors: Arc<AtomicU64>,
|
||||
) {
|
||||
let mut open_path: Option<PathBuf> = None;
|
||||
let mut file: Option<File> = None;
|
||||
let mut retry_after: Option<Instant> = None;
|
||||
let mut last_warning: Option<Instant> = None;
|
||||
loop {
|
||||
let event = tokio::select! {
|
||||
event = receiver.recv() => match event {
|
||||
Some(event) => event,
|
||||
None => break,
|
||||
},
|
||||
changed = settings_changed.changed() => {
|
||||
if changed.is_err() && receiver.is_closed() {
|
||||
break;
|
||||
}
|
||||
let config = settings.load_full();
|
||||
let path = PathBuf::from(&config.path);
|
||||
if !config.enabled || open_path.as_ref() != Some(&path) {
|
||||
// Dropping Tokio's File closes the descriptor without blocking
|
||||
// the request path. A changed path is reopened on the next event.
|
||||
file = None;
|
||||
open_path = None;
|
||||
retry_after = None;
|
||||
}
|
||||
continue;
|
||||
}
|
||||
};
|
||||
|
||||
let config = settings.load_full();
|
||||
if !config.enabled {
|
||||
file = None;
|
||||
open_path = None;
|
||||
retry_after = None;
|
||||
continue;
|
||||
}
|
||||
let path = PathBuf::from(&config.path);
|
||||
if open_path.as_ref() != Some(&path) {
|
||||
file = None;
|
||||
open_path = Some(path.clone());
|
||||
retry_after = None;
|
||||
}
|
||||
if file.is_none() && retry_after.is_none_or(|until| Instant::now() >= until) {
|
||||
match open_error_file(path.clone()).await {
|
||||
Ok(opened) => {
|
||||
file = Some(opened);
|
||||
retry_after = None;
|
||||
}
|
||||
Err(error) => {
|
||||
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");
|
||||
last_warning = Some(Instant::now());
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
let Some(opened) = file.as_mut() else {
|
||||
continue;
|
||||
};
|
||||
let line = format_error_event(&event, config.format);
|
||||
if let Err(error) = opened.write_all(&line).await {
|
||||
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");
|
||||
last_warning = Some(Instant::now());
|
||||
}
|
||||
} else {
|
||||
written.fetch_add(1, Ordering::Relaxed);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[derive(Debug, Clone, Serialize)]
|
||||
pub struct LogEntry {
|
||||
pub event: &'static str,
|
||||
pub protocol_error: Option<&'static str>,
|
||||
pub error_detail: Option<String>,
|
||||
pub local_addr: Option<String>,
|
||||
pub tls_sni: Option<String>,
|
||||
pub vhost: Option<String>,
|
||||
pub route: Option<String>,
|
||||
pub cache_effective_enabled: Option<bool>,
|
||||
@@ -342,6 +71,20 @@ impl Default for Logs {
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
fn protocol_error_detail(detail: impl std::fmt::Display) -> String {
|
||||
let mut detail = redact_text(&detail.to_string());
|
||||
if detail.len() > 512 {
|
||||
let mut end = 512;
|
||||
while !detail.is_char_boundary(end) {
|
||||
end -= 1;
|
||||
}
|
||||
detail.truncate(end);
|
||||
detail.push_str("...");
|
||||
}
|
||||
detail
|
||||
}
|
||||
|
||||
impl Logs {
|
||||
pub fn start(settings: Settings, shutdown: CancellationToken) -> Arc<Self> {
|
||||
let (tx, rx) = mpsc::channel(SINK_QUEUE);
|
||||
@@ -382,10 +125,66 @@ impl Logs {
|
||||
self.dropped.fetch_add(1, Ordering::Relaxed);
|
||||
}
|
||||
let _ = self.live.send(entry.clone());
|
||||
self.push_sink(entry);
|
||||
}
|
||||
fn push_sink(&self, entry: LogEntry) {
|
||||
if self.settings.load().enabled() && self.sink.try_send(entry).is_err() {
|
||||
self.sink_dropped.fetch_add(1, Ordering::Relaxed);
|
||||
}
|
||||
}
|
||||
/// Persist transport/protocol failures without polluting the bounded Live Logs buffer.
|
||||
pub fn push_protocol_error(
|
||||
&self,
|
||||
kind: &'static str,
|
||||
detail: impl std::fmt::Display,
|
||||
client: std::net::SocketAddr,
|
||||
local: std::net::SocketAddr,
|
||||
transport: &'static str,
|
||||
http_version: &'static str,
|
||||
status: u16,
|
||||
tls_sni: Option<String>,
|
||||
) {
|
||||
if !self.settings.load().enabled() {
|
||||
return;
|
||||
}
|
||||
let detail = protocol_error_detail(detail);
|
||||
self.push_sink(LogEntry {
|
||||
event: "protocol_error",
|
||||
protocol_error: Some(kind),
|
||||
error_detail: Some(detail),
|
||||
local_addr: Some(local.to_string()),
|
||||
tls_sni,
|
||||
vhost: None,
|
||||
route: None,
|
||||
cache_effective_enabled: None,
|
||||
transform_effective_enabled: None,
|
||||
backend: None,
|
||||
id: 0,
|
||||
request_id: String::new(),
|
||||
time_ms: now_ms(),
|
||||
method: String::new(),
|
||||
host: String::new(),
|
||||
path: String::new(),
|
||||
http_version,
|
||||
transport,
|
||||
websocket_bootstrap: None,
|
||||
websocket_phase: None,
|
||||
websocket_error: None,
|
||||
h3_reset_code: None,
|
||||
upstream_status: None,
|
||||
upstream_error: None,
|
||||
client_ip: Some(client.ip().to_string()),
|
||||
user_agent: None,
|
||||
country: None,
|
||||
status,
|
||||
duration_ms: 0,
|
||||
request_bytes: 0,
|
||||
response_bytes: 0,
|
||||
outcome: "protocol_error",
|
||||
cache: "-",
|
||||
cache_reason: "protocol_error",
|
||||
});
|
||||
}
|
||||
pub fn subscribe(&self) -> broadcast::Receiver<LogEntry> {
|
||||
self.live.subscribe()
|
||||
}
|
||||
@@ -417,6 +216,26 @@ impl Logs {
|
||||
|
||||
fn value_for(entry: &LogEntry, name: &str) -> Value {
|
||||
match name {
|
||||
"event" => json!(entry.event),
|
||||
"protocol_error" => entry
|
||||
.protocol_error
|
||||
.map(|v| Value::String(v.into()))
|
||||
.unwrap_or(Value::Null),
|
||||
"error_detail" => entry
|
||||
.error_detail
|
||||
.clone()
|
||||
.map(Value::String)
|
||||
.unwrap_or(Value::Null),
|
||||
"local_addr" => entry
|
||||
.local_addr
|
||||
.clone()
|
||||
.map(Value::String)
|
||||
.unwrap_or(Value::Null),
|
||||
"tls_sni" => entry
|
||||
.tls_sni
|
||||
.clone()
|
||||
.map(Value::String)
|
||||
.unwrap_or(Value::Null),
|
||||
"vhost" => entry
|
||||
.vhost
|
||||
.clone()
|
||||
|
||||
@@ -22,7 +22,7 @@ use std::{
|
||||
time::{Duration, Instant, SystemTime, UNIX_EPOCH},
|
||||
};
|
||||
use tokio::{
|
||||
fs::{File, OpenOptions},
|
||||
fs::File,
|
||||
io::AsyncWriteExt,
|
||||
net::TcpStream,
|
||||
sync::{broadcast, mpsc, watch},
|
||||
@@ -229,7 +229,12 @@ fn validate_json_key(key: &str) -> Result<()> {
|
||||
fn source_value_name(name: &str) -> bool {
|
||||
matches!(
|
||||
name,
|
||||
"vhost"
|
||||
"event"
|
||||
| "protocol_error"
|
||||
| "error_detail"
|
||||
| "local_addr"
|
||||
| "tls_sni"
|
||||
| "vhost"
|
||||
| "route"
|
||||
| "cache_effective_enabled"
|
||||
| "transform_effective_enabled"
|
||||
|
||||
+43
-12
@@ -15,6 +15,23 @@ fn format_entry(entry: &LogEntry, format: &JsonFormat) -> Value {
|
||||
for (key, value) in &format.static_fields {
|
||||
object.insert(key.clone(), Value::String(value.clone()));
|
||||
}
|
||||
if entry.event == "protocol_error" {
|
||||
for name in [
|
||||
"event",
|
||||
"protocol_error",
|
||||
"error_detail",
|
||||
"time_ms",
|
||||
"client_ip",
|
||||
"local_addr",
|
||||
"tls_sni",
|
||||
"transport",
|
||||
"http_version",
|
||||
"status",
|
||||
"outcome",
|
||||
] {
|
||||
object.insert(name.into(), value_for(entry, name));
|
||||
}
|
||||
}
|
||||
Value::Object(object)
|
||||
}
|
||||
|
||||
@@ -69,6 +86,30 @@ struct LogstashState {
|
||||
address: String,
|
||||
stream: TcpStream,
|
||||
}
|
||||
|
||||
async fn open_access_file(path: PathBuf) -> Result<File> {
|
||||
let file = tokio::task::spawn_blocking(move || -> Result<std::fs::File> {
|
||||
let mut options = std::fs::OpenOptions::new();
|
||||
options.create(true).append(true).write(true);
|
||||
#[cfg(unix)]
|
||||
{
|
||||
use std::os::unix::fs::OpenOptionsExt;
|
||||
options.mode(0o600).custom_flags(libc::O_NOFOLLOW);
|
||||
}
|
||||
let file = options.open(&path)?;
|
||||
let metadata = file.metadata()?;
|
||||
ensure!(metadata.is_file(), "access log path is not a regular file");
|
||||
#[cfg(unix)]
|
||||
{
|
||||
use std::os::unix::fs::PermissionsExt;
|
||||
file.set_permissions(std::fs::Permissions::from_mode(0o600))?;
|
||||
}
|
||||
Ok(file)
|
||||
})
|
||||
.await
|
||||
.map_err(|_| anyhow::anyhow!("access log open worker failed"))??;
|
||||
Ok(File::from_std(file))
|
||||
}
|
||||
async fn sink_loop(
|
||||
mut rx: mpsc::Receiver<LogEntry>,
|
||||
settings: Arc<ArcSwap<Settings>>,
|
||||
@@ -113,12 +154,7 @@ async fn sink_loop(
|
||||
vhost_files.remove(&path);
|
||||
}
|
||||
}
|
||||
match OpenOptions::new()
|
||||
.create(true)
|
||||
.append(true)
|
||||
.open(&path)
|
||||
.await
|
||||
{
|
||||
match open_access_file(path.clone()).await {
|
||||
Ok(opened) => {
|
||||
vhost_files.insert(path.clone(), opened);
|
||||
}
|
||||
@@ -142,12 +178,7 @@ async fn sink_loop(
|
||||
vhost_directory = None;
|
||||
let path = PathBuf::from(&config.file.path);
|
||||
if file.as_ref().is_none_or(|state| state.path != path) {
|
||||
file = match OpenOptions::new()
|
||||
.create(true)
|
||||
.append(true)
|
||||
.open(&path)
|
||||
.await
|
||||
{
|
||||
file = match open_access_file(path.clone()).await {
|
||||
Ok(opened) => Some(FileState {
|
||||
path: path.clone(),
|
||||
file: opened,
|
||||
|
||||
@@ -3,6 +3,11 @@ mod tests {
|
||||
|
||||
fn entry() -> LogEntry {
|
||||
LogEntry {
|
||||
event: "request",
|
||||
protocol_error: None,
|
||||
error_detail: None,
|
||||
local_addr: Some("192.0.2.1:443".into()),
|
||||
tls_sni: Some("app.example".into()),
|
||||
vhost: Some("app".into()),
|
||||
route: Some("root".into()),
|
||||
cache_effective_enabled: Some(true),
|
||||
@@ -108,11 +113,63 @@ mod tests {
|
||||
#[test]
|
||||
fn default_json_format_keeps_standard_entry() {
|
||||
let value = format_entry(&entry(), &JsonFormat::default());
|
||||
assert_eq!(value["event"], "request");
|
||||
assert_eq!(value["method"], "GET");
|
||||
assert_eq!(value["cache"], "HIT");
|
||||
assert_eq!(value["response_bytes"], 42);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn protocol_error_keeps_required_diagnostic_fields_with_custom_mapping() {
|
||||
let mut item = entry();
|
||||
item.event = "protocol_error";
|
||||
item.protocol_error = Some("tls_handshake_error");
|
||||
item.error_detail = Some("invalid handshake".into());
|
||||
item.outcome = "protocol_error";
|
||||
item.status = 0;
|
||||
item.transport = "tls";
|
||||
let mut format = JsonFormat::default();
|
||||
format.fields.insert("site".into(), "vhost".into());
|
||||
format.static_fields.insert("event".into(), "custom".into());
|
||||
let value = format_entry(&item, &format);
|
||||
assert_eq!(value["site"], "app");
|
||||
assert_eq!(value["event"], "protocol_error");
|
||||
assert_eq!(value["protocol_error"], "tls_handshake_error");
|
||||
assert_eq!(value["error_detail"], "invalid handshake");
|
||||
assert_eq!(value["client_ip"], "192.0.2.10");
|
||||
assert_eq!(value["transport"], "tls");
|
||||
assert_eq!(value["outcome"], "protocol_error");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn protocol_errors_skip_live_history_and_use_persistent_sink_only() {
|
||||
let logs = Logs::default();
|
||||
let mut settings = Settings::default();
|
||||
settings.file.enabled = true;
|
||||
logs.configure(settings);
|
||||
logs.push_protocol_error(
|
||||
"tls_handshake_error",
|
||||
"invalid token=topsecret",
|
||||
"192.0.2.10:50000".parse().unwrap(),
|
||||
"192.0.2.20:443".parse().unwrap(),
|
||||
"tls",
|
||||
"",
|
||||
0,
|
||||
Some("app.example".into()),
|
||||
);
|
||||
assert!(logs.recent().is_empty());
|
||||
assert_eq!(logs.sink_dropped.load(Ordering::Relaxed), 1);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn protocol_error_detail_is_utf8_safe_bounded_and_redacted() {
|
||||
let detail = protocol_error_detail(format!("token=topsecret {}", "€".repeat(300)));
|
||||
assert!(!detail.contains("topsecret"));
|
||||
assert!(detail.is_char_boundary(detail.len()));
|
||||
assert!(detail.len() <= 515);
|
||||
assert!(detail.ends_with("..."));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn error_log_defaults_off_and_redacts_common_secret_shapes() {
|
||||
let settings = ErrorLogSettings::default();
|
||||
|
||||
Reference in new issue
Block a user