426 lines
18 KiB
Rust
426 lines
18 KiB
Rust
mod tests {
|
|
use super::*;
|
|
use tracing_subscriber::prelude::*;
|
|
|
|
fn entry() -> LogEntry {
|
|
LogEntry {
|
|
event: "request",
|
|
protocol_error: None,
|
|
reason: None,
|
|
error_detail: None,
|
|
error: None,
|
|
local_addr: Some("192.0.2.1:443".into()),
|
|
tls_sni: Some("app.example".into()),
|
|
sni: Some("app.example".into()),
|
|
authority: None,
|
|
matched_by: None,
|
|
vhost: Some("app".into()),
|
|
route: Some("root".into()),
|
|
cache_effective_enabled: Some(true),
|
|
transform_effective_enabled: Some(false),
|
|
backend: Some("origin".into()),
|
|
id: 7,
|
|
request_id: "0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef".into(),
|
|
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")), "_unmatched");
|
|
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["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.reason = Some("tls_handshake_error");
|
|
item.error_detail = Some("invalid handshake".into());
|
|
item.error = Some("invalid handshake".into());
|
|
item.sni = Some("app.example".into());
|
|
item.authority = Some("app.example:443".into());
|
|
item.matched_by = Some("sni");
|
|
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["reason"], "tls_handshake_error");
|
|
assert_eq!(value["error_detail"], "invalid handshake");
|
|
assert_eq!(value["error"], "invalid handshake");
|
|
assert_eq!(value["sni"], "app.example");
|
|
assert_eq!(value["authority"], "app.example:443");
|
|
assert_eq!(value["matched_by"], "sni");
|
|
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 protocol_identity_fields_are_bounded_and_strip_controls() {
|
|
let value = protocol_identity_field(Some(format!("host\n{}", "€".repeat(300)))).unwrap();
|
|
assert!(!value.contains('\n'));
|
|
assert!(value.is_char_boundary(value.len()));
|
|
assert!(value.len() <= 515);
|
|
assert!(value.ends_with("..."));
|
|
}
|
|
|
|
#[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_redaction_preserves_json_and_debug_escaping_without_leaking_secret_suffixes() {
|
|
for secret in ["pem-data", "left\"right", "left\\right", "ending\\", "left\\\"right", "first\nsecond"] {
|
|
let plain = serde_json::to_string(&serde_json::json!({
|
|
"private_key": secret, "visible": "keep"
|
|
})).unwrap();
|
|
let redacted = redact_text(&plain);
|
|
let value: Value = serde_json::from_str(&redacted).unwrap();
|
|
assert_eq!(value["private_key"], "[REDACTED]");
|
|
assert_eq!(value["visible"], "keep");
|
|
|
|
// EventVisitor::record_debug uses this exact formatting operation.
|
|
let debug = format!("{plain:?}");
|
|
let debug_redacted = redact_text(&debug);
|
|
let decoded: String = serde_json::from_str(&debug_redacted).unwrap();
|
|
let value: Value = serde_json::from_str(&decoded).unwrap();
|
|
assert_eq!(value["private_key"], "[REDACTED]");
|
|
assert_eq!(value["visible"], "keep");
|
|
assert_eq!(
|
|
redact_text(&format!("before {debug} after")),
|
|
format!("before {debug_redacted} after")
|
|
);
|
|
}
|
|
}
|
|
|
|
#[test]
|
|
fn error_redaction_removes_private_pem_and_preserves_public_diagnostics() {
|
|
for label in ["PRIVATE KEY", "RSA PRIVATE KEY", "EC PRIVATE KEY", "ENCRYPTED PRIVATE KEY"] {
|
|
let input = format!("before -----BEGIN {label}-----\nsynthetic-secret\n-----END {label}----- after");
|
|
assert_eq!(redact_text(&input), "before [REDACTED PRIVATE KEY] after");
|
|
}
|
|
let public = "-----BEGIN CERTIFICATE-----\npublic-test-data\n-----END CERTIFICATE-----";
|
|
assert_eq!(redact_text(public), public);
|
|
}
|
|
|
|
#[test]
|
|
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([
|
|
("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");
|
|
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]
|
|
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
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn full_history_evicts_oldest_keeps_exact_fields_and_does_not_count_eviction_as_drop() {
|
|
fn history_entry(id: usize) -> LogEntry {
|
|
let mut item = entry();
|
|
item.id = id as u64;
|
|
item.time_ms += id as u64;
|
|
item.path = format!("/history/{id}");
|
|
item.authority = Some("app.example:443".into());
|
|
item.matched_by = Some("host");
|
|
item.upstream_error = Some("diagnostic with \"quotes\" and UTF-8: €".into());
|
|
item
|
|
}
|
|
let logs = Logs::default();
|
|
for id in 0..HISTORY_CAPACITY + 3 {
|
|
logs.push(history_entry(id));
|
|
}
|
|
let retained = logs.recent_limit(HISTORY_CAPACITY + 1);
|
|
assert_eq!(retained.len(), HISTORY_CAPACITY);
|
|
assert_eq!(
|
|
retained.iter().map(|item| item.id).collect::<Vec<_>>(),
|
|
(3..HISTORY_CAPACITY + 3).rev().map(|id| id as u64).collect::<Vec<_>>()
|
|
);
|
|
for item in [&retained[0], &retained[HISTORY_CAPACITY / 2], retained.last().unwrap()] {
|
|
assert_eq!(
|
|
serde_json::to_value(item).unwrap(),
|
|
serde_json::to_value(history_entry(item.id as usize)).unwrap()
|
|
);
|
|
}
|
|
assert_eq!(logs.recent_limit(0).len(), 0);
|
|
assert_eq!(logs.recent_limit(2)[0].id, (HISTORY_CAPACITY + 2) as u64);
|
|
assert_eq!(logs.dropped.load(Ordering::Relaxed), 0);
|
|
let stats = logs.stats();
|
|
assert_eq!(stats.queue_capacity, SINK_QUEUE);
|
|
assert_eq!(stats.queue_dropped, 0, "disabled sinks must not enqueue");
|
|
assert_eq!(stats.sent, 0);
|
|
assert_eq!(stats.errors, 0);
|
|
}
|
|
|
|
#[tokio::test]
|
|
async fn history_contention_counts_one_drop_but_preserves_live_and_file_delivery() {
|
|
let directory = tempfile::tempdir().unwrap();
|
|
let path = directory.path().join("access.jsonl");
|
|
let mut settings = Settings::default();
|
|
settings.file.enabled = true;
|
|
settings.file.path = path.to_string_lossy().into_owned();
|
|
let shutdown = CancellationToken::new();
|
|
let logs = Logs::start(settings, shutdown.clone());
|
|
let mut live = logs.subscribe();
|
|
let mut sentinel = entry();
|
|
sentinel.id = 6;
|
|
let mut history = logs.entries.lock().unwrap();
|
|
history.push_back(sentinel.clone());
|
|
|
|
let mut item = entry();
|
|
item.path = "/contention/€\"quoted\"".into();
|
|
item.authority = Some("app.example:443".into());
|
|
item.matched_by = Some("host");
|
|
let expected = serde_json::to_value(&item).unwrap();
|
|
let producer = logs.clone();
|
|
let (finished, completion) = std::sync::mpsc::channel();
|
|
let worker = std::thread::spawn(move || {
|
|
producer.push(item);
|
|
finished.send(()).unwrap();
|
|
});
|
|
// Release the guard before joining even on failure, so an accidental
|
|
// blocking-lock regression fails this test instead of hanging the suite.
|
|
let completed = completion.recv_timeout(Duration::from_secs(2));
|
|
drop(history);
|
|
worker.join().unwrap();
|
|
completed.expect("history contention must not block live/sink delivery");
|
|
|
|
assert_eq!(logs.dropped.load(Ordering::Relaxed), 1);
|
|
assert_eq!(serde_json::to_value(logs.recent()).unwrap(), json!([sentinel]));
|
|
assert_eq!(serde_json::to_value(live.try_recv().unwrap()).unwrap(), expected);
|
|
assert!(matches!(live.try_recv(), Err(broadcast::error::TryRecvError::Empty)));
|
|
|
|
let persisted = tokio::time::timeout(Duration::from_secs(5), async {
|
|
loop {
|
|
if let Ok(content) = tokio::fs::read_to_string(&path).await {
|
|
if content.ends_with('\n') && logs.stats().sent == 1 {
|
|
break content;
|
|
}
|
|
}
|
|
tokio::time::sleep(Duration::from_millis(20)).await;
|
|
}
|
|
}).await.expect("contended history entry must still reach the configured file sink");
|
|
shutdown.cancel();
|
|
assert_eq!(persisted.lines().count(), 1);
|
|
assert_eq!(serde_json::from_str::<Value>(persisted.trim_end()).unwrap(), expected);
|
|
let stats = logs.stats();
|
|
assert_eq!(stats.queue_capacity, SINK_QUEUE);
|
|
assert_eq!(stats.queue_dropped, 0);
|
|
assert_eq!(stats.sent, 1);
|
|
assert_eq!(stats.errors, 0);
|
|
}
|
|
}
|