fix(serve): standard Apache Combined Log Format for HTTP access log (fix #126)

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 }

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::<ConnectInfo<SocketAddr>>()
         .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" <latency>ms`
+fn format_combined_line(timestamp: &DateTime<FixedOffset>, 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<FixedOffset> {
+    Local::now().fixed_offset()
+}
+
+fn clf_timestamp(timestamp: &DateTime<FixedOffset>) -> String {
+    timestamp.format("%d/%b/%Y:%H:%M:%S %z").to_string()
+}
+
+fn iso_timestamp(timestamp: &DateTime<FixedOffset>) -> 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> {
+        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);
+    }
 }

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)
 }
 

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 <project>/.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
+        );
+    }
 }