v0.25.1

src/logging/format.rs

@@ -0,0 +1,425 @@
+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 vhost: Option<String>,
+    pub route: Option<String>,
+    pub cache_effective_enabled: Option<bool>,
+    pub transform_effective_enabled: Option<bool>,
+    pub backend: Option<String>,
+    pub id: u64,
+    pub time_ms: u64,
+    pub method: String,
+    pub host: String,
+    pub path: String,
+    pub http_version: &'static str,
+    pub transport: &'static str,
+    pub websocket_bootstrap: Option<&'static str>,
+    pub websocket_phase: Option<&'static str>,
+    pub websocket_error: Option<&'static str>,
+    pub h3_reset_code: Option<&'static str>,
+    pub upstream_status: Option<u16>,
+    pub upstream_error: Option<String>,
+    pub client_ip: Option<String>,
+    pub user_agent: Option<String>,
+    pub country: Option<String>,
+    pub status: u16,
+    pub duration_ms: u64,
+    pub request_bytes: u64,
+    pub response_bytes: u64,
+    pub outcome: &'static str,
+    pub cache: &'static str,
+    pub cache_reason: &'static str,
+}
+
+#[derive(Debug, Clone, Serialize)]
+pub struct SinkStats {
+    pub queue_capacity: usize,
+    pub queue_dropped: u64,
+    pub sent: u64,
+    pub errors: u64,
+}
+
+pub struct Logs {
+    entries: Mutex<VecDeque<LogEntry>>,
+    pub dropped: AtomicU64,
+    settings: Arc<ArcSwap<Settings>>,
+    live: broadcast::Sender<LogEntry>,
+    sink: mpsc::Sender<LogEntry>,
+    sink_dropped: Arc<AtomicU64>,
+    sink_sent: Arc<AtomicU64>,
+    sink_errors: Arc<AtomicU64>,
+}
+impl Default for Logs {
+    fn default() -> Self {
+        let (sink, receiver) = mpsc::channel(SINK_QUEUE);
+        drop(receiver);
+        let (live, _) = broadcast::channel(LIVE_STREAM_CAPACITY);
+        Self {
+            entries: Mutex::new(VecDeque::new()),
+            dropped: AtomicU64::new(0),
+            settings: Arc::new(ArcSwap::from_pointee(Settings::default())),
+            live,
+            sink,
+            sink_dropped: Arc::new(AtomicU64::new(0)),
+            sink_sent: Arc::new(AtomicU64::new(0)),
+            sink_errors: Arc::new(AtomicU64::new(0)),
+        }
+    }
+}
+impl Logs {
+    pub fn start(settings: Settings, shutdown: CancellationToken) -> Arc<Self> {
+        let (tx, rx) = mpsc::channel(SINK_QUEUE);
+        let (live, _) = broadcast::channel(LIVE_STREAM_CAPACITY);
+        let settings = Arc::new(ArcSwap::from_pointee(settings));
+        let sink_dropped = Arc::new(AtomicU64::new(0));
+        let sink_sent = Arc::new(AtomicU64::new(0));
+        let sink_errors = Arc::new(AtomicU64::new(0));
+        let logs = Arc::new(Self {
+            entries: Mutex::new(VecDeque::new()),
+            dropped: AtomicU64::new(0),
+            settings: settings.clone(),
+            live,
+            sink: tx,
+            sink_dropped: sink_dropped.clone(),
+            sink_sent: sink_sent.clone(),
+            sink_errors: sink_errors.clone(),
+        });
+        tokio::spawn(sink_loop(rx, settings, sink_sent, sink_errors, shutdown));
+        logs
+    }
+    pub fn configure(&self, settings: Settings) {
+        self.settings.store(Arc::new(settings));
+    }
+    pub fn capture_user_agent(&self) -> bool {
+        self.settings.load().capture_user_agent
+    }
+    pub fn capture_country(&self) -> bool {
+        self.settings.load().capture_country
+    }
+    pub fn push(&self, entry: LogEntry) {
+        if let Ok(mut entries) = self.entries.try_lock() {
+            if entries.len() == HISTORY_CAPACITY {
+                entries.pop_front();
+            }
+            entries.push_back(entry.clone());
+        } else {
+            self.dropped.fetch_add(1, Ordering::Relaxed);
+        }
+        let _ = self.live.send(entry.clone());
+        if self.settings.load().enabled() && self.sink.try_send(entry).is_err() {
+            self.sink_dropped.fetch_add(1, Ordering::Relaxed);
+        }
+    }
+    pub fn subscribe(&self) -> broadcast::Receiver<LogEntry> {
+        self.live.subscribe()
+    }
+    pub fn recent(&self) -> Vec<LogEntry> {
+        self.recent_limit(HISTORY_CAPACITY)
+    }
+    pub fn recent_limit(&self, limit: usize) -> Vec<LogEntry> {
+        self.entries
+            .lock()
+            .map(|entries| entries.iter().rev().take(limit.min(HISTORY_CAPACITY)).cloned().collect())
+            .unwrap_or_default()
+    }
+    pub fn stats(&self) -> SinkStats {
+        SinkStats {
+            queue_capacity: SINK_QUEUE,
+            queue_dropped: self.sink_dropped.load(Ordering::Relaxed),
+            sent: self.sink_sent.load(Ordering::Relaxed),
+            errors: self.sink_errors.load(Ordering::Relaxed),
+        }
+    }
+}
+
+fn value_for(entry: &LogEntry, name: &str) -> Value {
+    match name {
+        "vhost" => entry
+            .vhost
+            .clone()
+            .map(Value::String)
+            .unwrap_or(Value::Null),
+        "route" => entry
+            .route
+            .clone()
+            .map(Value::String)
+            .unwrap_or(Value::Null),
+        "cache_effective_enabled" => entry
+            .cache_effective_enabled
+            .map(Value::Bool)
+            .unwrap_or(Value::Null),
+        "transform_effective_enabled" => entry
+            .transform_effective_enabled
+            .map(Value::Bool)
+            .unwrap_or(Value::Null),
+        "backend" => entry
+            .backend
+            .clone()
+            .map(Value::String)
+            .unwrap_or(Value::Null),
+        "id" => json!(entry.id),
+        "time_ms" => json!(entry.time_ms),
+        "method" => json!(&entry.method),
+        "host" => json!(&entry.host),
+        "path" => json!(&entry.path),
+        "http_version" => json!(entry.http_version),
+        "transport" => json!(entry.transport),
+        "websocket_bootstrap" => entry.websocket_bootstrap.map(|v| Value::String(v.into())).unwrap_or(Value::Null),
+        "websocket_phase" => entry.websocket_phase.map(|v| Value::String(v.into())).unwrap_or(Value::Null),
+        "websocket_error" => entry.websocket_error.map(|v| Value::String(v.into())).unwrap_or(Value::Null),
+        "h3_reset_code" => entry.h3_reset_code.map(|v| Value::String(v.into())).unwrap_or(Value::Null),
+        "upstream_status" => entry.upstream_status.map(|v| json!(v)).unwrap_or(Value::Null),
+        "upstream_error" => entry.upstream_error.clone().map(Value::String).unwrap_or(Value::Null),
+        "client_ip" => entry.client_ip.clone().map(Value::String).unwrap_or(Value::Null),
+        "user_agent" => entry.user_agent.clone().map(Value::String).unwrap_or(Value::Null),
+        "country" => entry.country.clone().map(Value::String).unwrap_or(Value::Null),
+        "status" => json!(entry.status),
+        "duration_ms" => json!(entry.duration_ms),
+        "request_bytes" => json!(entry.request_bytes),
+        "response_bytes" => json!(entry.response_bytes),
+        "outcome" => json!(entry.outcome),
+        "cache" => json!(entry.cache),
+        "cache_reason" => json!(entry.cache_reason),
+        _ => Value::Null,
+    }
+}