Files
RustProxy/src/logging.rs
T
2026-10-04 09:29:10 +02:00

1393 lines
48 KiB
Rust

//! Bounded live access ring plus optional asynchronous structured-log sinks.
//! Request handling only performs a try-lock/try-send; file/network I/O lives on
//! the background worker and is bounded by a fixed queue.
use anyhow::{ensure, Context, Result};
use arc_swap::ArcSwap;
use axum::body::Body;
use http::{Request, Uri};
use http_body_util::{BodyExt, Limited};
use hyper_rustls::HttpsConnectorBuilder;
use hyper_util::{
client::legacy::{connect::HttpConnector, Client},
rt::TokioExecutor,
};
use rustls::{ClientConfig, RootCertStore};
use serde::{Deserialize, Serialize};
use serde_json::{json, Map, Value};
use std::{
collections::{BTreeMap, VecDeque},
io::{self, Write as IoWrite},
path::PathBuf,
sync::{
atomic::{AtomicU64, Ordering},
Arc, Mutex, OnceLock,
},
time::{Duration, Instant, SystemTime, UNIX_EPOCH},
};
use tokio::{
fs::{File, OpenOptions},
io::AsyncWriteExt,
net::TcpStream,
sync::{broadcast, mpsc, watch},
};
use tokio_util::sync::CancellationToken;
use tracing::{Event, Level, Subscriber};
use tracing_subscriber::{layer::Context as LayerContext, Layer};
pub const LIVE_WINDOW: usize = 256;
pub const HISTORY_CAPACITY: usize = 4096;
pub const LIVE_STREAM_CAPACITY: usize = 4096;
const SINK_QUEUE: usize = 512;
const SINK_TIMEOUT: Duration = Duration::from_secs(5);
#[derive(Debug, Clone, Serialize, Deserialize)]
#[serde(default, deny_unknown_fields)]
pub struct FileSink {
pub enabled: bool,
pub path: String,
/// Write one JSONL file per resolved vhost instead of one combined file.
#[serde(default)]
pub per_vhost: bool,
/// Directory used by per-vhost mode. Files are named `<vhost>.jsonl`;
/// unmatched requests are written to `_unmatched.jsonl`.
#[serde(default = "default_vhost_log_directory")]
pub directory: String,
}
fn default_vhost_log_directory() -> String {
"/var/log/rustproxy/vhosts".into()
}
impl Default for FileSink {
fn default() -> Self {
Self {
enabled: false,
path: "/var/log/rustproxy/access.jsonl".into(),
per_vhost: false,
directory: default_vhost_log_directory(),
}
}
}
#[derive(Debug, Clone, Serialize, Deserialize)]
#[serde(default, deny_unknown_fields)]
pub struct LogstashSink {
pub enabled: bool,
pub address: String,
}
impl Default for LogstashSink {
fn default() -> Self {
Self {
enabled: false,
address: "127.0.0.1:5044".into(),
}
}
}
#[derive(Debug, Clone, Serialize, Deserialize)]
#[serde(default, deny_unknown_fields)]
pub struct LokiSink {
pub enabled: bool,
pub url: String,
pub bearer_token_env: Option<String>,
pub labels: BTreeMap<String, String>,
}
impl Default for LokiSink {
fn default() -> Self {
Self {
enabled: false,
url: "http://127.0.0.1:3100/loki/api/v1/push".into(),
bearer_token_env: None,
labels: BTreeMap::from([("job".into(), "rustproxy".into())]),
}
}
}
#[derive(Debug, Clone, Default, Serialize, Deserialize)]
#[serde(default, deny_unknown_fields)]
pub struct JsonFormat {
/// output field -> LogEntry field. Empty means the complete standard entry.
pub fields: BTreeMap<String, String>,
pub static_fields: BTreeMap<String, String>,
}
#[derive(Debug, Clone, Serialize, Deserialize)]
#[serde(default, deny_unknown_fields)]
pub struct Settings {
/// Capture a bounded User-Agent value in access logs and traffic analytics.
pub capture_user_agent: bool,
/// Resolve the effective client IP through the loaded GeoIP database.
/// Disabled by default because this adds per-request lookup work.
pub capture_country: bool,
pub file: FileSink,
pub logstash: LogstashSink,
pub loki: LokiSink,
pub format: JsonFormat,
}
impl Default for Settings {
fn default() -> Self {
Self {
capture_user_agent: true,
capture_country: false,
file: FileSink::default(),
logstash: LogstashSink::default(),
loki: LokiSink::default(),
format: JsonFormat::default(),
}
}
}
impl Settings {
pub fn enabled(&self) -> bool {
self.file.enabled || self.logstash.enabled || self.loki.enabled
}
pub fn validate(&self) -> Result<()> {
if self.file.enabled {
if self.file.per_vhost {
ensure!(
!self.file.directory.trim().is_empty() && self.file.directory.len() <= 1024,
"logging.file.directory must be 1..1024 bytes in per-vhost mode"
);
} else {
ensure!(
!self.file.path.trim().is_empty() && self.file.path.len() <= 1024,
"logging.file.path must be 1..1024 bytes"
);
}
}
if self.logstash.enabled {
let authority = self
.logstash
.address
.parse::<http::uri::Authority>()
.context("logging.logstash.address must be host:port")?;
ensure!(
!authority.host().is_empty()
&& authority.port_u16().is_some()
&& !authority.as_str().contains('@'),
"logging.logstash.address must be host:port"
);
}
if self.loki.enabled {
ensure!(self.loki.url.len() <= 2048, "logging.loki.url is too long");
let url = url::Url::parse(&self.loki.url).context("invalid logging.loki.url")?;
ensure!(
matches!(url.scheme(), "http" | "https") && url.host().is_some(),
"logging.loki.url must be HTTP(S)"
);
ensure!(
url.username().is_empty() && url.password().is_none(),
"credentials in logging.loki.url are forbidden; use bearer_token_env"
);
}
if let Some(name) = &self.loki.bearer_token_env {
ensure!(
!name.is_empty()
&& name.len() <= 128
&& name.bytes().all(|b| b.is_ascii_alphanumeric() || b == b'_'),
"logging.loki.bearer_token_env must be a simple environment variable name"
);
}
ensure!(
self.loki.labels.len() <= 32,
"at most 32 Loki labels are allowed"
);
for (key, value) in &self.loki.labels {
ensure!(
!key.is_empty()
&& key.len() <= 64
&& key.bytes().all(|b| b.is_ascii_alphanumeric() || b == b'_'),
"Loki label names must be 1..64 letters, numbers or underscores"
);
ensure!(
value.len() <= 256,
"Loki label values must be at most 256 bytes"
);
}
ensure!(
self.format.fields.len() <= 32 && self.format.static_fields.len() <= 32,
"structured log format allows at most 32 mapped and 32 static fields"
);
for (output, source) in &self.format.fields {
validate_json_key(output)?;
ensure!(
source_value_name(source),
"unknown structured log source field: {source}"
);
}
for (key, value) in &self.format.static_fields {
validate_json_key(key)?;
ensure!(
value.len() <= 1024,
"structured log static value is too long"
);
}
Ok(())
}
}
fn validate_json_key(key: &str) -> Result<()> {
ensure!(
!key.is_empty() && key.len() <= 128 && !key.chars().any(char::is_control),
"structured log output field names must be 1..128 bytes without controls"
);
Ok(())
}
fn source_value_name(name: &str) -> bool {
matches!(
name,
"vhost"
| "route"
| "cache_effective_enabled"
| "transform_effective_enabled"
| "backend"
| "id"
| "time_ms"
| "method"
| "host"
| "path"
| "http_version"
| "transport"
| "websocket_bootstrap"
| "websocket_phase"
| "websocket_error"
| "h3_reset_code"
| "upstream_status"
| "upstream_error"
| "client_ip"
| "user_agent"
| "country"
| "status"
| "duration_ms"
| "request_bytes"
| "response_bytes"
| "outcome"
| "cache"
| "cache_reason"
)
}
#[derive(Debug, Clone, Copy, Serialize, Deserialize, PartialEq, Eq)]
pub enum ErrorLogFormat {
#[serde(rename = "JSON")]
Json,
#[serde(rename = "RAW")]
Raw,
}
impl Default for ErrorLogFormat {
fn default() -> Self {
Self::Json
}
}
#[derive(Debug, Clone, Serialize, Deserialize)]
#[serde(default, deny_unknown_fields)]
pub struct ErrorLogSettings {
pub enabled: bool,
pub path: String,
pub format: ErrorLogFormat,
}
impl Default for ErrorLogSettings {
fn default() -> Self {
Self {
enabled: false,
path: "/var/log/rustproxy/error.log".into(),
format: ErrorLogFormat::Json,
}
}
}
impl ErrorLogSettings {
pub fn validate(&self) -> Result<()> {
if self.enabled {
ensure!(
!self.path.trim().is_empty()
&& self.path.len() <= 1024
&& !self.path.chars().any(char::is_control),
"error_log.path must be 1..1024 bytes without controls"
);
}
Ok(())
}
}
const ERROR_LOG_QUEUE: usize = 512;
const ERROR_LOG_RETRY: Duration = Duration::from_secs(30);
#[derive(Debug, Clone, Serialize)]
pub struct ErrorLogStats {
pub queue_capacity: usize,
pub queue_dropped: u64,
pub written: u64,
pub errors: u64,
}
#[derive(Debug)]
struct ErrorEvent {
timestamp: String,
target: String,
message: String,
fields: BTreeMap<String, String>,
}
pub struct ErrorLogController {
settings: Arc<ArcSwap<ErrorLogSettings>>,
settings_changed: watch::Sender<()>,
sender: mpsc::Sender<ErrorEvent>,
dropped: Arc<AtomicU64>,
written: Arc<AtomicU64>,
errors: Arc<AtomicU64>,
}
impl ErrorLogController {
pub fn start() -> Arc<Self> {
let (sender, receiver) = mpsc::channel(ERROR_LOG_QUEUE);
let (settings_changed, settings_watch) = watch::channel(());
let settings = Arc::new(ArcSwap::from_pointee(ErrorLogSettings::default()));
let dropped = Arc::new(AtomicU64::new(0));
let written = Arc::new(AtomicU64::new(0));
let errors = Arc::new(AtomicU64::new(0));
tokio::spawn(error_log_loop(
receiver,
settings.clone(),
settings_watch,
written.clone(),
errors.clone(),
));
Arc::new(Self {
settings,
settings_changed,
sender,
dropped,
written,
errors,
})
}
pub fn configure(&self, settings: ErrorLogSettings) {
self.settings.store(Arc::new(settings));
self.settings_changed.send_replace(());
}
fn push(&self, event: ErrorEvent) {
if self.settings.load().enabled && self.sender.try_send(event).is_err() {
self.dropped.fetch_add(1, Ordering::Relaxed);
}
}
pub fn stats(&self) -> ErrorLogStats {
ErrorLogStats {
queue_capacity: ERROR_LOG_QUEUE,
queue_dropped: self.dropped.load(Ordering::Relaxed),
written: self.written.load(Ordering::Relaxed),
errors: self.errors.load(Ordering::Relaxed),
}
}
}
static ERROR_LOG: OnceLock<Arc<ErrorLogController>> = OnceLock::new();
pub fn install_error_log_controller(controller: Arc<ErrorLogController>) -> Result<()> {
ERROR_LOG
.set(controller)
.map_err(|_| anyhow::anyhow!("error logger already initialized"))
}
pub fn configure_error_log(settings: ErrorLogSettings) {
if let Some(controller) = ERROR_LOG.get() {
controller.configure(settings);
}
}
pub fn error_log_stats() -> Option<ErrorLogStats> {
ERROR_LOG.get().map(|controller| controller.stats())
}
#[derive(Clone)]
pub struct ErrorLogLayer {
controller: Arc<ErrorLogController>,
}
impl ErrorLogLayer {
pub fn new(controller: Arc<ErrorLogController>) -> Self {
Self { controller }
}
}
#[derive(Default)]
struct EventVisitor {
message: Option<String>,
fields: BTreeMap<String, String>,
}
impl tracing::field::Visit for EventVisitor {
fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
let value = format!("{value:?}");
if field.name() == "message" {
self.message = Some(value);
} else {
self.fields.insert(field.name().to_owned(), value);
}
}
fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
if field.name() == "message" {
self.message = Some(value.to_owned());
} else {
self.fields
.insert(field.name().to_owned(), value.to_owned());
}
}
fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
self.fields
.insert(field.name().to_owned(), value.to_string());
}
fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
self.fields
.insert(field.name().to_owned(), value.to_string());
}
fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
self.fields
.insert(field.name().to_owned(), value.to_string());
}
fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
self.fields
.insert(field.name().to_owned(), value.to_string());
}
}
impl<S: Subscriber> Layer<S> for ErrorLogLayer {
fn on_event(&self, event: &Event<'_>, _ctx: LayerContext<'_, S>) {
if *event.metadata().level() != Level::ERROR {
return;
}
let mut visitor = EventVisitor::default();
event.record(&mut visitor);
let mut fields = visitor.fields;
for (key, value) in &mut fields {
*value = if is_secret_field(key) {
"[REDACTED]".into()
} else {
redact_text(value)
};
}
self.controller.push(ErrorEvent {
timestamp: rfc3339_now(),
target: event.metadata().target().to_owned(),
message: redact_text(visitor.message.as_deref().unwrap_or("error")),
fields,
});
}
}
#[derive(Clone, Copy, Default)]
pub struct RedactingStderr;
pub struct RedactingWriter {
buffer: Vec<u8>,
}
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,
}
}
fn format_entry(entry: &LogEntry, format: &JsonFormat) -> Value {
if format.fields.is_empty() && format.static_fields.is_empty() {
return serde_json::to_value(entry).unwrap_or(Value::Null);
}
let mut object = Map::new();
if format.fields.is_empty() {
if let Value::Object(defaults) = serde_json::to_value(entry).unwrap_or(Value::Null) {
object.extend(defaults);
}
} else {
for (output, source) in &format.fields {
object.insert(output.clone(), value_for(entry, source));
}
}
for (key, value) in &format.static_fields {
object.insert(key.clone(), Value::String(value.clone()));
}
Value::Object(object)
}
type LokiClient = Client<hyper_rustls::HttpsConnector<HttpConnector>, Body>;
fn loki_client() -> Result<LokiClient> {
let mut roots = RootCertStore::empty();
roots.extend(webpki_roots::TLS_SERVER_ROOTS.iter().cloned());
let config =
ClientConfig::builder_with_provider(Arc::new(rustls::crypto::ring::default_provider()))
.with_safe_default_protocol_versions()?
.with_root_certificates(roots)
.with_no_client_auth();
let mut http = HttpConnector::new();
http.enforce_http(false);
http.set_connect_timeout(Some(SINK_TIMEOUT));
http.set_nodelay(true);
let connector = HttpsConnectorBuilder::new()
.with_tls_config(config)
.https_or_http()
.enable_http1()
.wrap_connector(http);
Ok(Client::builder(TokioExecutor::new()).build(connector))
}
struct FileState {
path: PathBuf,
file: File,
}
const PER_VHOST_OPEN_FILES: usize = 64;
fn vhost_log_name(vhost: Option<&str>) -> String {
let raw = vhost
.filter(|value| !value.is_empty())
.unwrap_or("_unmatched");
let mut safe = String::with_capacity(raw.len().min(96));
for ch in raw.chars().take(96) {
safe.push(
if ch.is_ascii_alphanumeric() || matches!(ch, '-' | '_' | '.') {
ch
} else {
'_'
},
);
}
if safe.is_empty() {
"_unmatched".into()
} else {
safe
}
}
struct LogstashState {
address: String,
stream: TcpStream,
}
async fn sink_loop(
mut rx: mpsc::Receiver<LogEntry>,
settings: Arc<ArcSwap<Settings>>,
sent: Arc<AtomicU64>,
errors: Arc<AtomicU64>,
shutdown: CancellationToken,
) {
let client = loki_client().ok();
let mut file: Option<FileState> = None;
let mut vhost_files: BTreeMap<PathBuf, File> = BTreeMap::new();
let mut vhost_directory: Option<PathBuf> = None;
let mut logstash: Option<LogstashState> = None;
loop {
let entry = tokio::select! {
_ = shutdown.cancelled() => break,
entry = rx.recv() => match entry { Some(entry) => entry, None => break },
};
let config = settings.load_full();
let mut payload = format_entry(&entry, &config.format);
redact_value(&mut payload);
let mut attempted = false;
let mut failed = false;
if config.file.enabled {
attempted = true;
let mut line = serde_json::to_vec(&payload).unwrap_or_default();
line.push(b'\n');
if config.file.per_vhost {
file = None;
let directory = PathBuf::from(&config.file.directory);
if vhost_directory.as_ref() != Some(&directory) {
vhost_files.clear();
vhost_directory = Some(directory.clone());
}
if tokio::fs::create_dir_all(&directory).await.is_err() {
failed = true;
} else {
let path =
directory.join(format!("{}.jsonl", vhost_log_name(entry.vhost.as_deref())));
if !vhost_files.contains_key(&path) {
if vhost_files.len() >= PER_VHOST_OPEN_FILES {
if let Some(path) = vhost_files.keys().next().cloned() {
vhost_files.remove(&path);
}
}
match OpenOptions::new()
.create(true)
.append(true)
.open(&path)
.await
{
Ok(opened) => {
vhost_files.insert(path.clone(), opened);
}
Err(error) => {
tracing::warn!(%error, path=%path.display(), "per-vhost access log file unavailable");
failed = true;
}
}
}
let write_failed = match vhost_files.get_mut(&path) {
Some(opened) => opened.write_all(&line).await.is_err(),
None => true,
};
if write_failed {
failed = true;
vhost_files.remove(&path);
}
}
} else {
vhost_files.clear();
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
{
Ok(opened) => Some(FileState {
path: path.clone(),
file: opened,
}),
Err(error) => {
tracing::warn!(%error, path=%path.display(), "access log file unavailable");
None
}
};
}
if let Some(state) = file.as_mut() {
if state.file.write_all(&line).await.is_err() {
failed = true;
file = None;
}
} else {
failed = true;
}
}
} else {
file = None;
vhost_files.clear();
vhost_directory = None;
}
if config.logstash.enabled {
attempted = true;
let address = config.logstash.address.clone();
if logstash
.as_ref()
.is_none_or(|state| state.address != address)
{
logstash =
match tokio::time::timeout(SINK_TIMEOUT, TcpStream::connect(&address)).await {
Ok(Ok(stream)) => Some(LogstashState {
address: address.clone(),
stream,
}),
_ => None,
};
}
let mut line = serde_json::to_vec(&payload).unwrap_or_default();
line.push(b'\n');
if let Some(state) = logstash.as_mut() {
if !matches!(
tokio::time::timeout(SINK_TIMEOUT, state.stream.write_all(&line)).await,
Ok(Ok(()))
) {
failed = true;
logstash = None;
}
} else {
failed = true;
}
} else {
logstash = None;
}
if config.loki.enabled {
attempted = true;
let labels = if config.loki.labels.is_empty() {
BTreeMap::from([("job".to_owned(), "rustproxy".to_owned())])
} else {
config.loki.labels.clone()
};
let body = json!({"streams":[{"stream":labels,"values":[[(entry.time_ms as u128 * 1_000_000).to_string(), payload.to_string()]]}]});
let result = async {
let uri: Uri = config.loki.url.parse()?;
let mut request = Request::post(uri)
.header("content-type", "application/json")
.body(Body::from(serde_json::to_vec(&body)?))?;
if let Some(env) = &config.loki.bearer_token_env {
if let Ok(token) = std::env::var(env) {
if !token.is_empty() {
request
.headers_mut()
.insert("authorization", format!("Bearer {token}").parse()?);
}
}
}
let client = client.as_ref().context("Loki HTTP client unavailable")?;
let response = client.request(request).await?;
let status = response.status();
let _ = Limited::new(response.into_body(), 64 * 1024)
.collect()
.await;
ensure!(status.is_success(), "Loki returned {status}");
Ok::<(), anyhow::Error>(())
};
if !matches!(tokio::time::timeout(SINK_TIMEOUT, result).await, Ok(Ok(()))) {
failed = true;
}
}
if attempted {
if failed {
errors.fetch_add(1, Ordering::Relaxed);
} else {
sent.fetch_add(1, Ordering::Relaxed);
}
}
}
}
pub fn now_ms() -> u64 {
SystemTime::now()
.duration_since(UNIX_EPOCH)
.unwrap_or_default()
.as_millis() as u64
}
#[cfg(test)]
mod tests {
use super::*;
fn entry() -> LogEntry {
LogEntry {
vhost: Some("app".into()),
route: Some("root".into()),
cache_effective_enabled: Some(true),
transform_effective_enabled: Some(false),
backend: Some("origin".into()),
id: 7,
time_ms: 1_700_000_000_000,
method: "GET".into(),
host: "app.example".into(),
path: "/health".into(),
http_version: "3",
transport: "h3",
websocket_bootstrap: Some("h3_extended_connect"),
websocket_phase: Some("tunnel_closed"),
websocket_error: None,
h3_reset_code: None,
upstream_status: Some(101),
upstream_error: None,
client_ip: Some("192.0.2.10".into()),
user_agent: Some("RustProxy-Test/1.0".into()),
country: Some("PL".into()),
status: 200,
duration_ms: 12,
request_bytes: 10,
response_bytes: 42,
outcome: "ok",
cache: "HIT",
cache_reason: "cache_hit",
}
}
#[test]
fn json_format_can_map_and_add_static_fields() {
let mut format = JsonFormat::default();
format.fields.insert("http_status".into(), "status".into());
format.fields.insert("site".into(), "vhost".into());
format.fields.insert("route".into(), "route".into());
format.fields.insert("ua".into(), "user_agent".into());
format.fields.insert("geo_country".into(), "country".into());
format
.fields
.insert("cache_enabled".into(), "cache_effective_enabled".into());
format.fields.insert(
"transform_enabled".into(),
"transform_effective_enabled".into(),
);
format.static_fields.insert("service".into(), "edge".into());
let mut settings = Settings::default();
settings.format = format.clone();
settings.validate().unwrap();
let value = format_entry(&entry(), &format);
assert_eq!(value["http_status"], 200);
assert_eq!(value["site"], "app");
assert_eq!(value["route"], "root");
assert_eq!(value["ua"], "RustProxy-Test/1.0");
assert_eq!(value["geo_country"], "PL");
assert_eq!(value["cache_enabled"], true);
assert_eq!(value["transform_enabled"], false);
assert_eq!(value["service"], "edge");
assert!(value.get("method").is_none());
}
#[test]
fn logging_validation_rejects_credentials_unknown_fields_and_bad_endpoints() {
let mut settings = Settings::default();
settings.loki.enabled = true;
settings.loki.url = "https://user:secret@example.invalid/loki/api/v1/push".into();
assert!(settings.validate().is_err());
let mut settings = Settings::default();
settings.logstash.enabled = true;
settings.logstash.address = "missing-port.example".into();
assert!(settings.validate().is_err());
let mut settings = Settings::default();
settings
.format
.fields
.insert("status".into(), "does_not_exist".into());
assert!(settings.validate().is_err());
}
#[test]
fn per_vhost_file_mode_has_safe_names_and_requires_directory() {
assert_eq!(vhost_log_name(Some("app-1")), "app-1");
assert_eq!(vhost_log_name(None), "_unmatched");
assert_eq!(vhost_log_name(Some("bad/name")), "bad_name");
let mut settings = Settings::default();
settings.file.enabled = true;
settings.file.per_vhost = true;
settings.file.directory.clear();
assert!(settings.validate().is_err());
}
#[test]
fn capture_defaults_keep_geoip_off_request_path() {
let settings = Settings::default();
assert!(settings.capture_user_agent);
assert!(!settings.capture_country);
}
#[test]
fn default_json_format_keeps_standard_entry() {
let value = format_entry(&entry(), &JsonFormat::default());
assert_eq!(value["method"], "GET");
assert_eq!(value["cache"], "HIT");
assert_eq!(value["response_bytes"], 42);
}
#[test]
fn error_log_defaults_off_and_redacts_common_secret_shapes() {
let settings = ErrorLogSettings::default();
assert!(!settings.enabled);
assert_eq!(settings.format, ErrorLogFormat::Json);
let text = redact_text(
r#"Authorization: Bearer topsecret url=https://x.invalid/?api_token=abc password=hunter2 {\"private_key\":\"pem-data\"}"#,
);
assert!(!text.contains("topsecret"));
assert!(!text.contains("api_token=abc"));
assert!(!text.contains("hunter2"));
assert!(!text.contains("pem-data"));
}
#[test]
fn error_json_is_one_record_and_reserved_fields_cannot_be_overwritten() {
let event = ErrorEvent {
timestamp: "2026-10-03T12:34:56.123Z".into(),
target: "rust_proxy::http".into(),
message: "upstream failed\nsecond line".into(),
fields: BTreeMap::from([
("message".into(), "attacker override".into()),
("request_id".into(), "abc".into()),
]),
};
let line = format_error_event(&event, ErrorLogFormat::Json);
assert_eq!(line.iter().filter(|byte| **byte == b'\n').count(), 1);
let value: Value = serde_json::from_slice(&line).unwrap();
assert_eq!(value["message"], "upstream failed\nsecond line");
assert_eq!(value["request_id"], "abc");
}
#[test]
fn retained_history_is_larger_than_the_live_snapshot_but_still_bounded() {
let logs = Logs::default();
for id in 0..(LIVE_WINDOW + 80) {
let mut item = entry();
item.id = id as u64;
logs.push(item);
}
assert_eq!(logs.recent_limit(LIVE_WINDOW).len(), LIVE_WINDOW);
assert_eq!(logs.recent().len(), LIVE_WINDOW + 80);
assert_eq!(
logs.recent_limit(HISTORY_CAPACITY + 1).len(),
LIVE_WINDOW + 80
);
}
}