From 772db3b711578479217861cf4dfc3fae0a883e1d Mon Sep 17 00:00:00 2001 From: xiaoli <32010753+NO3623@users.noreply.github.com> Date: Mon, 3 Aug 2026 17:26:57 +0800 Subject: [PATCH] fix(serve): standardize access log format and trace empty-match - #126: write access logs in Apache Combined Log Format (IP first, CLF timestamp with timezone, real HTTP version, status, bytes, Referer, User-Agent, latency) using chrono instead of hand-rolled date math - #125: /api/v1/trace with no matching node returns 200 with an empty result object instead of 404 - add chrono as a serve-gated optional dependency - add serve_api integration tests for both behaviors Pre-existing, unrelated failures on this toolchain (verified identical on the base commit): - clippy --features full -- -D warnings: 8 errors in untouched files - cargo test --features full: test_path_mapping_applied fails on Windows (forward-slash path assertion) --- Cargo.lock | 1 + Cargo.toml | 3 +- src/server/access_log.rs | 137 +++++++++++++++++++++------------------ src/server/handlers.rs | 9 ++- tests/serve_api.rs | 43 ++++++++++++ 5 files changed, 128 insertions(+), 65 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 865dd57..e80cfd6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -344,6 +344,7 @@ name = "codeweb" version = "0.8.9" dependencies = [ "axum", + "chrono", "bincode", "bitflags 2.13.1", "blake3", diff --git a/Cargo.toml b/Cargo.toml index 6d01b5c..7ddd199 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:tokio", "dep:tower-http", "dep:rust-embed", "dep:mime_guess", "dep:chrono"] mcp = ["dep:rmcp", "dep:schemars", "dep:tokio"] jsp = [] search-sql-v2 = [] @@ -48,6 +48,7 @@ schemars = { version = "0.8", optional = true } tower-http = { version = "0.6", features = ["cors"], optional = true } rust-embed = { version = "8", optional = true } mime_guess = { version = "2", optional = true } +chrono = { version = "0.4", optional = true } csv = "1" indicatif = "0.18.4" pathdiff = "0.2.3" diff --git a/src/server/access_log.rs b/src/server/access_log.rs index 6c32727..2c38780 100644 --- a/src/server/access_log.rs +++ b/src/server/access_log.rs @@ -6,9 +6,10 @@ use std::sync::Mutex; use axum::extract::ConnectInfo; use axum::extract::Request; -use axum::http::header; +use axum::http::{header, Version}; use axum::middleware::Next; use axum::response::Response; +use chrono::Local; #[derive(Clone, Copy, PartialEq, Eq)] pub enum LogLevel { @@ -40,12 +41,16 @@ 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 version = version_str(request.version()).to_string(); let client_ip = request .extensions() .get::>() .map(|ci| ci.0.ip().to_string()); + let referer = header_str(request.headers(), header::REFERER); + let user_agent = header_str(request.headers(), header::USER_AGENT); + let is_debug = LOG_LEVEL .lock() .map(|g| *g == LogLevel::Debug) @@ -61,6 +66,7 @@ pub async fn access_log_middleware(request: Request, next: Next) -> Response { let response = next.run(request).await; let latency_ms = start.elapsed().as_millis() as u64; let status = response.status().as_u16(); + let bytes = header_str(response.headers(), header::CONTENT_LENGTH); let resp_headers = if is_debug { extract_debug_headers(response.headers(), true) @@ -68,13 +74,17 @@ pub async fn access_log_middleware(request: Request, next: Next) -> Response { None }; - log_request( - method.as_str(), - &uri.to_string(), + log_request(&AccessEntry { + remote_addr: client_ip.as_deref(), + method: method.as_str(), + uri: &uri.to_string(), + version: &version, status, + bytes: &bytes, + referer: &referer, + user_agent: &user_agent, latency_ms, - client_ip.as_deref(), - ); + }); if let (Some(req_h), Some(resp_h)) = (req_headers, resp_headers) { log_debug_details(&req_h, &resp_h); @@ -83,6 +93,25 @@ pub async fn access_log_middleware(request: Request, next: Next) -> Response { response } +fn 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/1.1", + } +} + +fn header_str(headers: &axum::http::HeaderMap, name: axum::http::HeaderName) -> String { + headers + .get(name) + .and_then(|v| v.to_str().ok()) + .unwrap_or("-") + .to_string() +} + /// Extract key headers for debug logging. /// `is_response`: true = response headers (Content-Type, Content-Length), /// false = request headers (Content-Type, Content-Length, User-Agent). @@ -137,85 +166,67 @@ 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) { +struct AccessEntry<'a> { + remote_addr: Option<&'a str>, + method: &'a str, + uri: &'a str, + version: &'a str, + status: u16, + bytes: &'a str, + referer: &'a str, + user_agent: &'a str, + latency_ms: u64, +} + +fn log_request(entry: &AccessEntry) { + if is_static_asset(entry.uri) { return; } - let timestamp = chrono_now(); - let ip_part = remote_addr.unwrap_or("-"); + let ip_part = entry.remote_addr.unwrap_or("-"); + let timestamp = clf_timestamp(); let line = format!( - "{} INFO \"{} {} HTTP/1.1\" {} {}ms {}", - timestamp, method, uri, status, latency_ms, ip_part + "{} - - [{}] \"{} {} {}\" {} {} \"{}\" \"{}\" {}ms", + ip_part, + timestamp, + entry.method, + entry.uri, + entry.version, + entry.status, + entry.bytes, + entry.referer, + entry.user_agent, + entry.latency_ms ); - eprintln!("{}", &line); + eprintln!("{}", line); if let Ok(mut guard) = HTTP_LOG.lock() { if let Some(ref mut f) = *guard { - let _ = writeln!(f, "{}", &line); + let _ = writeln!(f, "{}", line); } } } fn log_debug_details(req_headers: &str, resp_headers: &str) { - let timestamp = chrono_now(); + let timestamp = debug_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); + eprintln!("{}", req_line); + eprintln!("{}", resp_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, "{}", req_line); + let _ = writeln!(f, "{}", resp_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; - } - - 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; - } - - format!( - "{:04}-{:02}-{:02} {:02}:{:02}:{:02}", - year, month, day, h, m, s - ) +/// Apache CLF timestamp: [dd/Mon/yyyy:HH:MM:SS +ZZZZ] +fn clf_timestamp() -> String { + Local::now().format("%d/%b/%Y:%H:%M:%S %z").to_string() } -fn is_leap(y: u32) -> bool { - (y.is_multiple_of(4) && !y.is_multiple_of(100)) || y.is_multiple_of(400) +fn debug_timestamp() -> String { + Local::now().format("%Y-%m-%dT%H:%M:%S%:z").to_string() } diff --git a/src/server/handlers.rs b/src/server/handlers.rs index 08fa22b..dc13306 100644 --- a/src/server/handlers.rs +++ b/src/server/handlers.rs @@ -453,7 +453,14 @@ async fn trace( let graph = state.graph(); if matches.is_empty() { - return Err(StatusCode::NOT_FOUND); + return Ok(Json(serde_json::json!({ + "target": Value::Null, + "callers": [], + "callees": [], + "caller_count": 0, + "callee_count": 0, + "truncated": false, + }))); } let (start_idx, _) = &matches[0]; diff --git a/tests/serve_api.rs b/tests/serve_api.rs index 2b55936..85ce385 100644 --- a/tests/serve_api.rs +++ b/tests/serve_api.rs @@ -201,4 +201,47 @@ mod tests { let json: serde_json::Value = serde_json::from_str(&body).unwrap(); assert_eq!(json["total"], 0); } + + #[test] + fn test_serve_trace_empty_returns_200() { + let port = 19883; + let mut child = start_server(port); + + let (status, body) = get(port, "/api/v1/trace?from=nonexistent_node_xyz"); + stop_server(&mut child); + + assert_eq!(status, 200); + let json: serde_json::Value = serde_json::from_str(&body).unwrap(); + assert!(json["target"].is_null()); + assert_eq!(json["caller_count"], 0); + assert_eq!(json["callee_count"], 0); + assert!(json["callers"].is_array()); + assert!(json["callers"].as_array().unwrap().is_empty()); + assert!(json["callees"].is_array()); + assert!(json["callees"].as_array().unwrap().is_empty()); + assert_eq!(json["truncated"], false); + } + + #[test] + fn test_serve_access_log_combined_format() { + let port = 19884; + let mut child = start_server(port); + + let (status, _body) = get(port, "/api/v1/nodes/search-sql?q=zzz_unique_marker"); + stop_server(&mut child); + + assert_eq!(status, 200); + let log_path = project_root().join(".codeweb/http.log"); + let content = std::fs::read_to_string(&log_path) + .unwrap_or_else(|_| panic!("http.log missing at {}", log_path.display())); + let re = regex::Regex::new( + r#"^\S+ - - \[\d{2}/[A-Z][a-z]{2}/\d{4}:\d{2}:\d{2}:\d{2} [+-]\d{4}\] "GET /api/v1/nodes/search-sql\?q=zzz_unique_marker HTTP/1\.1" 200 (\d+|-)(\s+"[^"]*"){2} \d+ms$"#, + ) + .unwrap(); + assert!( + content.lines().any(|l| re.is_match(l)), + "no CLF access log line for request. log content:\n{}", + content + ); + } }