diff --git a/Cargo.lock b/Cargo.lock index 865dd57..a3b2488 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -294,8 +294,10 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1aa79e62e7697b8e29b513a68abacf485adcd1fe8284a4316c5ae868e6633327" dependencies = [ "iana-time-zone", + "js-sys", "num-traits", "serde", + "wasm-bindgen", "windows-link", ] @@ -347,6 +349,7 @@ dependencies = [ "bincode", "bitflags 2.13.1", "blake3", + "chrono", "clap", "crossterm", "csv", diff --git a/Cargo.toml b/Cargo.toml index 6d01b5c..c793da9 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -14,7 +14,7 @@ default = ["cli", "tui", "jsp"] full = ["cli", "tui", "serve", "mcp", "jsp", "search-sql-v2"] cli = ["clap"] tui = ["ratatui", "crossterm"] -serve = ["dep:axum", "dep:tokio", "dep:tower-http", "dep:rust-embed", "dep:mime_guess"] +serve = ["dep:axum", "dep:chrono", "dep:tokio", "dep:tower-http", "dep:rust-embed", "dep:mime_guess"] mcp = ["dep:rmcp", "dep:schemars", "dep:tokio"] jsp = [] search-sql-v2 = [] @@ -42,6 +42,7 @@ clap = { version = "4", features = ["derive"], optional = true } ratatui = { version = "0.29", optional = true } crossterm = { version = "0.28", optional = true } axum = { version = "0.7", optional = true } +chrono = { version = "0.4", optional = true } tokio = { version = "1", features = ["rt-multi-thread", "macros", "io-std", "io-util"], optional = true } rmcp = { version = "1.7", features = ["server", "transport-io"], optional = true } schemars = { version = "0.8", optional = true } diff --git a/src/server/access_log.rs b/src/server/access_log.rs index 6c32727..bddbce3 100644 --- a/src/server/access_log.rs +++ b/src/server/access_log.rs @@ -7,8 +7,10 @@ use std::sync::Mutex; use axum::extract::ConnectInfo; use axum::extract::Request; use axum::http::header; +use axum::http::Version; use axum::middleware::Next; use axum::response::Response; +use chrono::{DateTime, FixedOffset, Local}; #[derive(Clone, Copy, PartialEq, Eq)] pub enum LogLevel { @@ -40,12 +42,18 @@ pub fn init(log_dir: &Path, log_level: LogLevel) { pub async fn access_log_middleware(request: Request, next: Next) -> Response { let method = request.method().clone(); let uri = request.uri().clone(); + let uri_str = uri.to_string(); + let version = request.version(); let client_ip = request .extensions() .get::>() .map(|ci| ci.0.ip().to_string()); + let user_agent = + header_value_str(request.headers().get(header::USER_AGENT)).map(str::to_string); + let referer = header_value_str(request.headers().get(header::REFERER)).map(str::to_string); + let is_debug = LOG_LEVEL .lock() .map(|g| *g == LogLevel::Debug) @@ -68,13 +76,16 @@ pub async fn access_log_middleware(request: Request, next: Next) -> Response { None }; - log_request( - method.as_str(), - &uri.to_string(), + log_request(&AccessLogEntry { + method: method.as_str(), + uri: &uri_str, + version, status, latency_ms, - client_ip.as_deref(), - ); + remote_addr: client_ip.as_deref(), + user_agent: user_agent.as_deref(), + referer: referer.as_deref(), + }); if let (Some(req_h), Some(resp_h)) = (req_headers, resp_headers) { log_debug_details(&req_h, &resp_h); @@ -114,6 +125,10 @@ fn extract_debug_headers(headers: &axum::http::HeaderMap, is_response: bool) -> } } +fn header_value_str(value: Option<&axum::http::HeaderValue>) -> Option<&str> { + value.and_then(|v| v.to_str().ok()) +} + fn is_static_asset(uri: &str) -> bool { // Split at '?' to get the path portion only let path = uri.split('?').next().unwrap_or(uri); @@ -137,85 +152,171 @@ fn is_static_asset(uri: &str) -> bool { || path.starts_with("favicon") } -fn log_request(method: &str, uri: &str, status: u16, latency_ms: u64, remote_addr: Option<&str>) { - if is_static_asset(uri) { +/// A single HTTP request to be written to the access log. +struct AccessLogEntry<'a> { + method: &'a str, + uri: &'a str, + version: Version, + status: u16, + latency_ms: u64, + remote_addr: Option<&'a str>, + user_agent: Option<&'a str>, + referer: Option<&'a str>, +} + +fn log_request(entry: &AccessLogEntry<'_>) { + if is_static_asset(entry.uri) { return; } - let timestamp = chrono_now(); - let ip_part = remote_addr.unwrap_or("-"); - let line = format!( - "{} INFO \"{} {} HTTP/1.1\" {} {}ms {}", - timestamp, method, uri, status, latency_ms, ip_part - ); - eprintln!("{}", &line); + let line = format_combined_line(&now_timestamp(), entry); + write_line(&line); +} - if let Ok(mut guard) = HTTP_LOG.lock() { - if let Some(ref mut f) = *guard { - let _ = writeln!(f, "{}", &line); - } - } +/// Apache Combined Log Format line. +/// +/// `%h - - [%t] "%r" %s %b "%{Referer}i" "%{User-agent}i" ms` +fn format_combined_line(timestamp: &DateTime, entry: &AccessLogEntry<'_>) -> String { + let remote = entry.remote_addr.unwrap_or("-"); + let request_line = format!( + "{} {} {}", + entry.method, + entry.uri, + http_version_str(entry.version) + ); + format!( + "{} - - [{}] \"{}\" {} - \"{}\" \"{}\" {}ms", + remote, + clf_timestamp(timestamp), + request_line, + entry.status, + entry.referer.unwrap_or("-"), + entry.user_agent.unwrap_or("-"), + entry.latency_ms + ) } fn log_debug_details(req_headers: &str, resp_headers: &str) { - let timestamp = chrono_now(); + let timestamp = iso_timestamp(&now_timestamp()); let req_line = format!("{} DEBUG req: {}", timestamp, req_headers); let resp_line = format!("{} DEBUG res: {}", timestamp, resp_headers); - eprintln!("{}", &req_line); - eprintln!("{}", &resp_line); + write_line(&req_line); + write_line(&resp_line); +} + +fn write_line(line: &str) { + eprintln!("{}", line); if let Ok(mut guard) = HTTP_LOG.lock() { if let Some(ref mut f) = *guard { - let _ = writeln!(f, "{}", &req_line); - let _ = writeln!(f, "{}", &resp_line); + let _ = writeln!(f, "{}", line); } } } -fn chrono_now() -> String { - let now = std::time::SystemTime::now(); - let secs = now - .duration_since(std::time::UNIX_EPOCH) - .unwrap_or_default() - .as_secs(); - let days = secs / 86400; - let time_of_day = secs % 86400; - let h = time_of_day / 3600; - let m = (time_of_day % 3600) / 60; - let s = time_of_day % 60; - - let mut year = 1970_u32; - let mut remaining = days; - loop { - let dy = if is_leap(year) { 366 } else { 365 }; - if remaining < dy { - break; - } - remaining -= dy; - year += 1; +fn now_timestamp() -> DateTime { + Local::now().fixed_offset() +} + +fn clf_timestamp(timestamp: &DateTime) -> String { + timestamp.format("%d/%b/%Y:%H:%M:%S %z").to_string() +} + +fn iso_timestamp(timestamp: &DateTime) -> String { + timestamp.format("%Y-%m-%d %H:%M:%S %z").to_string() +} + +fn http_version_str(version: Version) -> &'static str { + match version { + Version::HTTP_09 => "HTTP/0.9", + Version::HTTP_10 => "HTTP/1.0", + Version::HTTP_11 => "HTTP/1.1", + Version::HTTP_2 => "HTTP/2", + Version::HTTP_3 => "HTTP/3", + _ => "HTTP/?", } +} - let mut month = 1_u32; - let mut day = remaining + 1; - for &mo in &[31, 28, 31, 30, 31, 30, 31, 31, 30, 31, 30, 31] { - let md = if month == 2 && is_leap(year) { - mo + 1 - } else { - mo - }; - if day <= md { - break; - } - day -= md; - month += 1; +#[cfg(test)] +mod tests { + use super::*; + use chrono::TimeZone; + + fn fixed_ts( + offset_secs: i32, + year: i32, + month: u32, + day: u32, + hour: u32, + min: u32, + sec: u32, + ) -> DateTime { + FixedOffset::east_opt(offset_secs) + .unwrap() + .with_ymd_and_hms(year, month, day, hour, min, sec) + .unwrap() } - format!( - "{:04}-{:02}-{:02} {:02}:{:02}:{:02}", - year, month, day, h, m, s - ) -} + #[test] + fn clf_timestamp_formats_with_offset() { + let ts = fixed_ts(8 * 3600, 2026, 7, 31, 4, 16, 31); + assert_eq!(clf_timestamp(&ts), "31/Jul/2026:04:16:31 +0800"); + } -fn is_leap(y: u32) -> bool { - (y.is_multiple_of(4) && !y.is_multiple_of(100)) || y.is_multiple_of(400) + #[test] + fn clf_timestamp_utc_offset() { + let ts = fixed_ts(0, 2026, 1, 1, 0, 0, 0); + assert_eq!(clf_timestamp(&ts), "01/Jan/2026:00:00:00 +0000"); + } + + #[test] + fn clf_timestamp_negative_offset() { + let ts = fixed_ts(-5 * 3600, 2026, 12, 25, 23, 59, 59); + assert_eq!(clf_timestamp(&ts), "25/Dec/2026:23:59:59 -0500"); + } + + #[test] + fn http_version_rendering() { + assert_eq!(http_version_str(Version::HTTP_09), "HTTP/0.9"); + assert_eq!(http_version_str(Version::HTTP_10), "HTTP/1.0"); + assert_eq!(http_version_str(Version::HTTP_11), "HTTP/1.1"); + assert_eq!(http_version_str(Version::HTTP_2), "HTTP/2"); + assert_eq!(http_version_str(Version::HTTP_3), "HTTP/3"); + } + + #[test] + fn combined_line_full_format() { + let ts = fixed_ts(8 * 3600, 2026, 7, 31, 4, 16, 31); + let entry = AccessLogEntry { + method: "GET", + uri: "/api/v1/nodes/search-sql?q=dat_trd_equity", + version: Version::HTTP_11, + status: 200, + latency_ms: 16070, + remote_addr: Some("127.0.0.1"), + user_agent: None, + referer: None, + }; + let line = format_combined_line(&ts, &entry); + let expected = r#"127.0.0.1 - - [31/Jul/2026:04:16:31 +0800] "GET /api/v1/nodes/search-sql?q=dat_trd_equity HTTP/1.1" 200 - "-" "-" 16070ms"#; + assert_eq!(line, expected); + } + + #[test] + fn combined_line_defaults_dash() { + let ts = fixed_ts(0, 2026, 7, 31, 4, 16, 31); + let entry = AccessLogEntry { + method: "POST", + uri: "/api/v1/query", + version: Version::HTTP_2, + status: 201, + latency_ms: 5, + remote_addr: None, + user_agent: Some("codeweb-test"), + referer: Some("http://localhost/"), + }; + let line = format_combined_line(&ts, &entry); + let expected = r#"- - - [31/Jul/2026:04:16:31 +0000] "POST /api/v1/query HTTP/2" 201 - "http://localhost/" "codeweb-test" 5ms"#; + assert_eq!(line, expected); + } } diff --git a/src/server/handlers.rs b/src/server/handlers.rs index 08fa22b..a261e80 100644 --- a/src/server/handlers.rs +++ b/src/server/handlers.rs @@ -34,9 +34,9 @@ pub fn router(state: AppState) -> Router { .route("/api/v1/query", post(execute_query)) .route("/api/v1/export", get(export)) .route("/api/v1/graph", get(graph_data)) + .fallback(super::assets::serve_asset) .layer(CorsLayer::permissive()) .layer(middleware::from_fn(access_log::access_log_middleware)) - .fallback(super::assets::serve_asset) .with_state(state) } diff --git a/tests/serve_api.rs b/tests/serve_api.rs index 2b55936..2b7ec03 100644 --- a/tests/serve_api.rs +++ b/tests/serve_api.rs @@ -201,4 +201,37 @@ mod tests { let json: serde_json::Value = serde_json::from_str(&body).unwrap(); assert_eq!(json["total"], 0); } + + #[test] + fn test_serve_access_log_combined_format() { + let port = 19883; + let mut child = start_server(port); + + get(port, "/api/v1/stats"); + let (status, _) = get(port, "/api/v1/nope-not-a-route"); + assert_eq!(status, 404); + stop_server(&mut child); + + let log_path = project_root().join(".codeweb/http.log"); + let content = std::fs::read_to_string(&log_path) + .expect("http.log should be written to /.codeweb/http.log"); + let re = regex::Regex::new( + r#"^\S+ - - \[[0-9]{2}/[A-Z][a-z]{2}/[0-9]{4}:[0-9]{2}:[0-9]{2}:[0-9]{2} [+-][0-9]{4}\] "GET /api/v1/stats HTTP/1\.1" 200 - "[^"]*" "[^"]*" [0-9]+ms$"#, + ) + .expect("valid regex"); + assert!( + content.lines().any(|l| re.is_match(l)), + "expected a combined-format access log line, got:\n{}", + content + ); + let re_404 = regex::Regex::new( + r#"^[^\s]+ - - \[[^\]]*\] "GET /api/v1/nope-not-a-route HTTP/1\.1" 404 - "[^"]*" "[^"]*" [0-9]+ms$"#, + ) + .expect("valid 404 regex"); + assert!( + content.lines().any(|l| re_404.is_match(l)), + "expected a 404 (fallback-served) request to be access-logged, got:\n{}", + content + ); + } }