Skip to main content

sz_rust_middleware_facade/
log.rs

1//! 日志系统 — 对齐 PHP `think-logger`
2//!
3//! ## 设计
4//!
5//! - 基于 `sz-orm-logger` 的 `StructuredLogger` 提供日志收集
6//! - 同时通过 `tracing` 宏输出(与 SZ-ORM-Tracing 协同,未来接入 OpenTelemetry)
7//! - 全局单例 `LogFacade`,通过 [`LogFacade::init()`] 初始化、[`LogFacade::instance()`] 获取
8//! - 支持多通道(file/console),对齐 PHP `config/log.php` 的 `channels` 配置
9//!
10//! ## PHP 对齐
11//!
12//! ```php
13//! // PHP think-logger
14//! Log::info('hello');
15//! Log::error('error occurred', ['exception' => $e]);
16//! Log::channel('file')->info('file log');
17//! ```
18//!
19//! ```rust,ignore
20//! // SZ-Rust 等价
21//! use sz_rust_core::log::LogFacade;
22//! LogFacade::instance().unwrap().info("hello");
23//! LogFacade::instance().unwrap().error("error occurred");
24//! ```
25
26use parking_lot::RwLock;
27use std::collections::HashMap;
28use std::sync::OnceLock;
29use sz_rust_infra_facade::config::{LogChannel, LogSection};
30
31// 重导出 sz-orm-logger 核心类型,方便上层直接使用
32pub use sz_rust_orm_facade::logger::{LogEntry, LogLevel, Logger, LoggerFactory, StructuredLogger};
33
34/// 全局日志 facade 单例
35static LOG_FACADE: OnceLock<LogFacade> = OnceLock::new();
36
37/// 日志 facade — 持有默认 `StructuredLogger` 和命名通道
38///
39/// 对齐 PHP `think\facade\Log`,提供全局日志访问点。
40pub struct LogFacade {
41    /// 默认通道名(对应 PHP `config/log.php` 的 `default`)
42    default_channel: String,
43    /// 默认 logger 实例
44    logger: StructuredLogger,
45    /// 命名通道集合(对应 PHP `channels`)
46    channels: RwLock<HashMap<String, StructuredLogger>>,
47}
48
49impl LogFacade {
50    /// 构造 LogFacade 实例(不注册到全局单例)
51    pub fn new(section: &LogSection) -> Self {
52        let default_channel = section.default.clone();
53        let default_log_level = section
54            .channels
55            .get(&default_channel)
56            .map(|c| parse_level(&c.level))
57            .unwrap_or(LogLevel::Info);
58        let logger = StructuredLogger::with_level(default_log_level);
59
60        let mut channels = HashMap::new();
61        for (name, channel_cfg) in &section.channels {
62            channels.insert(name.clone(), channel_to_logger(channel_cfg));
63        }
64
65        LogFacade {
66            default_channel,
67            logger,
68            channels: RwLock::new(channels),
69        }
70    }
71
72    /// 初始化全局日志 facade
73    ///
74    /// 重复调用返回已有实例(不覆盖)。
75    pub fn init(section: &LogSection) -> &'static LogFacade {
76        LOG_FACADE.get_or_init(|| LogFacade::new(section))
77    }
78
79    /// 获取全局日志 facade 实例
80    ///
81    /// 必须先调用 [`LogFacade::init()`] 初始化,否则返回 `None`。
82    pub fn instance() -> Option<&'static LogFacade> {
83        LOG_FACADE.get()
84    }
85
86    /// 获取默认通道名
87    pub fn default_channel(&self) -> &str {
88        &self.default_channel
89    }
90
91    /// 获取默认 logger 引用
92    pub fn logger(&self) -> &StructuredLogger {
93        &self.logger
94    }
95
96    /// 获取指定通道的 logger 引用
97    ///
98    /// 对齐 PHP `Log::channel('file')->info(...)`。
99    pub fn channel(&self, name: &str) -> Option<ChannelRef<'_>> {
100        if self.channels.read().contains_key(name) {
101            Some(ChannelRef {
102                facade: self,
103                name: name.to_string(),
104            })
105        } else {
106            None
107        }
108    }
109
110    /// 获取所有通道名
111    pub fn channel_names(&self) -> Vec<String> {
112        self.channels.read().keys().cloned().collect()
113    }
114
115    /// 记录日志(同时输出到 StructuredLogger 和 tracing)
116    pub fn log(&self, level: LogLevel, msg: &str) {
117        self.logger.log(level, msg);
118        match level {
119            LogLevel::Debug => tracing::debug!("{}", msg),
120            LogLevel::Info => tracing::info!("{}", msg),
121            LogLevel::Warn => tracing::warn!("{}", msg),
122            LogLevel::Error => tracing::error!("{}", msg),
123        }
124    }
125
126    /// 记录 DEBUG 级别日志
127    pub fn debug(&self, msg: &str) {
128        self.log(LogLevel::Debug, msg);
129    }
130
131    /// 记录 INFO 级别日志
132    pub fn info(&self, msg: &str) {
133        self.log(LogLevel::Info, msg);
134    }
135
136    /// 记录 WARN 级别日志
137    pub fn warn(&self, msg: &str) {
138        self.log(LogLevel::Warn, msg);
139    }
140
141    /// 记录 ERROR 级别日志
142    pub fn error(&self, msg: &str) {
143        self.log(LogLevel::Error, msg);
144    }
145}
146
147impl std::fmt::Debug for LogFacade {
148    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
149        f.debug_struct("LogFacade")
150            .field("default_channel", &self.default_channel)
151            .field("channels", &self.channels.read().keys().collect::<Vec<_>>())
152            .finish()
153    }
154}
155
156/// 命名通道引用
157///
158/// 通过 [`LogFacade::channel()`] 获取,提供与默认 logger 相同的日志方法。
159pub struct ChannelRef<'a> {
160    facade: &'a LogFacade,
161    name: String,
162}
163
164impl<'a> ChannelRef<'a> {
165    /// 通道名
166    pub fn name(&self) -> &str {
167        &self.name
168    }
169
170    /// 记录日志到指定通道
171    pub fn log(&self, level: LogLevel, msg: &str) {
172        let guard = self.facade.channels.read();
173        if let Some(logger) = guard.get(&self.name) {
174            logger.log(level, msg);
175        }
176        match level {
177            LogLevel::Debug => tracing::debug!("[{}] {}", self.name, msg),
178            LogLevel::Info => tracing::info!("[{}] {}", self.name, msg),
179            LogLevel::Warn => tracing::warn!("[{}] {}", self.name, msg),
180            LogLevel::Error => tracing::error!("[{}] {}", self.name, msg),
181        }
182    }
183
184    /// 记录 debug 级别日志
185    pub fn debug(&self, msg: &str) {
186        self.log(LogLevel::Debug, msg);
187    }
188
189    /// 记录 info 级别日志
190    pub fn info(&self, msg: &str) {
191        self.log(LogLevel::Info, msg);
192    }
193
194    /// 记录 warn 级别日志
195    pub fn warn(&self, msg: &str) {
196        self.log(LogLevel::Warn, msg);
197    }
198
199    /// 记录 error 级别日志
200    pub fn error(&self, msg: &str) {
201        self.log(LogLevel::Error, msg);
202    }
203}
204
205/// 从字符串解析日志级别
206///
207/// 支持大小写不敏感:`"DEBUG"` / `"debug"` / `"Debug"` 均解析为 `LogLevel::Debug`。
208/// 未知字符串默认为 `LogLevel::Info`。
209pub fn parse_level(s: &str) -> LogLevel {
210    match s.to_lowercase().as_str() {
211        "debug" => LogLevel::Debug,
212        "info" => LogLevel::Info,
213        "warn" | "warning" => LogLevel::Warn,
214        "error" => LogLevel::Error,
215        _ => LogLevel::Info,
216    }
217}
218
219/// 从 `LogChannel` 配置构造 `StructuredLogger`
220fn channel_to_logger(channel: &LogChannel) -> StructuredLogger {
221    StructuredLogger::with_level(parse_level(&channel.level))
222}
223
224// ============================================================================
225// 单元测试
226// ============================================================================
227
228#[cfg(test)]
229mod tests {
230    use super::*;
231    use sz_rust_infra_facade::config::{LogChannel, LogSection};
232
233    /// 构造测试用的 LogSection(含 file + console 两个通道)
234    fn make_log_section() -> LogSection {
235        let mut channels = HashMap::new();
236        channels.insert(
237            "file".to_string(),
238            LogChannel {
239                r#type: "file".to_string(),
240                path: "runtime/logs".to_string(),
241                level: "info".to_string(),
242                max_files: 30,
243                format: "%{time} [%{level}] %{message}".to_string(),
244            },
245        );
246        channels.insert(
247            "console".to_string(),
248            LogChannel {
249                r#type: "console".to_string(),
250                path: String::new(),
251                level: "debug".to_string(),
252                max_files: 0,
253                format: "%{time} [%{level}] %{message}".to_string(),
254            },
255        );
256        LogSection {
257            default: "file".to_string(),
258            channels,
259        }
260    }
261
262    /// 测试 parse_level 各种输入
263    #[test]
264    fn test_parse_level() {
265        assert_eq!(parse_level("debug"), LogLevel::Debug);
266        assert_eq!(parse_level("DEBUG"), LogLevel::Debug);
267        assert_eq!(parse_level("Debug"), LogLevel::Debug);
268        assert_eq!(parse_level("info"), LogLevel::Info);
269        assert_eq!(parse_level("INFO"), LogLevel::Info);
270        assert_eq!(parse_level("warn"), LogLevel::Warn);
271        assert_eq!(parse_level("warning"), LogLevel::Warn);
272        assert_eq!(parse_level("WARN"), LogLevel::Warn);
273        assert_eq!(parse_level("error"), LogLevel::Error);
274        assert_eq!(parse_level("ERROR"), LogLevel::Error);
275        // 未知字符串默认 Info
276        assert_eq!(parse_level("unknown"), LogLevel::Info);
277        assert_eq!(parse_level(""), LogLevel::Info);
278    }
279
280    /// 测试 LogFacade 构造和默认通道
281    #[test]
282    fn test_log_facade_new() {
283        let section = make_log_section();
284        let facade = LogFacade::new(&section);
285
286        assert_eq!(facade.default_channel(), "file");
287        let names = facade.channel_names();
288        assert_eq!(names.len(), 2);
289        assert!(names.contains(&"file".to_string()));
290        assert!(names.contains(&"console".to_string()));
291    }
292
293    /// 测试默认 logger 级别取自 default 通道
294    #[test]
295    fn test_default_logger_level() {
296        let section = make_log_section();
297        let facade = LogFacade::new(&section);
298
299        // file 通道 level=info,所以默认 logger 级别为 Info
300        assert_eq!(facade.logger().level(), LogLevel::Info);
301
302        // Debug 级别应被过滤
303        facade.debug("debug msg - should be filtered");
304        let entries = facade.logger().entries();
305        assert!(entries.iter().all(|e| e.level != LogLevel::Debug));
306    }
307
308    /// 测试日志记录到默认 logger
309    #[test]
310    fn test_log_to_default_logger() {
311        let section = make_log_section();
312        let facade = LogFacade::new(&section);
313
314        facade.info("test info message");
315        facade.warn("test warn message");
316        facade.error("test error message");
317
318        let entries = facade.logger().entries();
319        assert!(entries.iter().any(|e| e.message == "test info message"));
320        assert!(entries.iter().any(|e| e.message == "test warn message"));
321        assert!(entries.iter().any(|e| e.message == "test error message"));
322    }
323
324    /// 测试通过 ChannelRef 访问命名通道
325    #[test]
326    fn test_channel_access() {
327        let section = make_log_section();
328        let facade = LogFacade::new(&section);
329
330        // file 通道存在
331        let file_channel = facade.channel("file");
332        assert!(file_channel.is_some());
333        let file_channel = file_channel.unwrap();
334        assert_eq!(file_channel.name(), "file");
335
336        // console 通道存在
337        let console_channel = facade.channel("console");
338        assert!(console_channel.is_some());
339
340        // 不存在的通道返回 None
341        assert!(facade.channel("nonexistent").is_none());
342    }
343
344    /// 测试 console 通道(level=debug)能记录所有级别
345    #[test]
346    fn test_console_channel_debug_level() {
347        let section = make_log_section();
348        let facade = LogFacade::new(&section);
349
350        let console = facade.channel("console").unwrap();
351        console.debug("debug msg");
352        console.info("info msg");
353        console.warn("warn msg");
354        console.error("error msg");
355
356        // console 通道 level=debug,所有级别都应记录
357        let guard = facade.channels.read();
358        let console_logger = guard.get("console").unwrap();
359        let entries = console_logger.entries();
360        assert_eq!(entries.len(), 4);
361    }
362
363    /// 测试 LogFacade init 全局单例
364    #[test]
365    fn test_log_facade_init_singleton() {
366        let section = make_log_section();
367        let facade = LogFacade::init(&section);
368
369        // instance() 应返回同一实例
370        let facade2 = LogFacade::instance();
371        assert!(facade2.is_some());
372        assert!(std::ptr::eq(facade, facade2.unwrap()));
373
374        // 再次 init 应返回同一实例(不覆盖)
375        let section2 = make_log_section();
376        let facade3 = LogFacade::init(&section2);
377        assert!(std::ptr::eq(facade, facade3));
378    }
379
380    /// 测试从实际配置文件加载日志配置
381    #[test]
382    fn test_load_from_config_file() {
383        // 查找 config 目录
384        let config_dir = std::env::current_dir().ok().and_then(|d| {
385            let mut current = d.clone();
386            for _ in 0..5 {
387                if current.join("config").exists() {
388                    return Some(current.join("config"));
389                }
390                if let Some(parent) = current.parent() {
391                    current = parent.to_path_buf();
392                } else {
393                    break;
394                }
395            }
396            None
397        });
398
399        let Some(config_dir) = config_dir else {
400            eprintln!("跳过:未找到 config 目录");
401            return;
402        };
403
404        let log_path = config_dir.join("log.yml");
405        if !log_path.exists() {
406            eprintln!("跳过:未找到 log.yml");
407            return;
408        }
409
410        let content = std::fs::read_to_string(&log_path).unwrap();
411        let section: LogSection = serde_yaml::from_str(&content).unwrap();
412
413        // 验证默认通道为 file
414        assert_eq!(section.default, "file");
415
416        // 验证有 file 和 console 两个通道
417        assert!(section.channels.contains_key("file"));
418        assert!(section.channels.contains_key("console"));
419
420        // 验证 file 通道配置
421        let file_channel = section.channels.get("file").unwrap();
422        assert_eq!(file_channel.r#type, "file");
423        assert_eq!(file_channel.level, "info");
424        assert_eq!(file_channel.max_files, 30);
425
426        // 验证 console 通道配置
427        let console_channel = section.channels.get("console").unwrap();
428        assert_eq!(console_channel.r#type, "console");
429        assert_eq!(console_channel.level, "debug");
430    }
431
432    /// 测试 LogFacade::new 处理空 channels(默认通道不存在时用 Info 级别)
433    #[test]
434    fn test_log_facade_with_empty_channels() {
435        let section = LogSection::default();
436        let facade = LogFacade::new(&section);
437
438        // 默认通道为空,logger 级别应为 Info(fallback)
439        assert_eq!(facade.logger().level(), LogLevel::Info);
440        assert_eq!(facade.default_channel(), "");
441    }
442
443    /// 测试 LogFacade::Debug 输出
444    #[test]
445    fn test_log_facade_debug_format() {
446        let section = make_log_section();
447        let facade = LogFacade::new(&section);
448
449        let debug_str = format!("{:?}", facade);
450        assert!(debug_str.contains("LogFacade"));
451        assert!(debug_str.contains("file"));
452    }
453}
454// Log 中间件 — 请求/响应日志(对齐 PHP `think-logger`)
455//
456// sz-rust 自研中间件,PHP 端无全局 Log 中间件(PHP `app/middleware.php` 仅含
457// `SessionInit` + `AllowCrossDomain`)。本模块在 [`crate::order::DEFAULT_ORDER`]
458// 中位于第 3 位(`Trace` → `Cors` → **`Log`** → `RateLimit` → `Auth`)。
459//
460// ## 行为
461//
462// 1. **入口**:生成 `RequestId`(如果 extensions 中没有,则新生成),注入 extensions
463// 2. **记录起始时间**:`std::time::Instant::now()`
464// 3. **调用 `next.run(req)`**:传递请求给下游
465// 4. **出口**:根据响应状态码记录日志
466//    - 2xx/3xx → `tracing::info!`
467//    - 4xx → `tracing::warn!`(对齐 PHP `apart_level=['error','sql']` 的级别分离思想)
468//    - 5xx → `tracing::error!`
469//
470// ## 日志字段
471//
472// | 字段 | 来源 | 说明 |
473// |------|------|------|
474// | `request_id` | `generate_request_id()` | 全局唯一计数器 + 时间戳,16 字符 hex |
475// | `method` | `Request::method()` | HTTP 方法 |
476// | `uri` | `Request::uri().path()` | 请求路径(不含查询字符串) |
477// | `status` | `Response::status().as_u16()` | HTTP 状态码 |
478// | `duration_ms` | `Instant::elapsed()` | 请求耗时(毫秒) |
479//
480// ## PHP 对齐
481//
482// PHP 端无 Log 中间件,业务代码通过 `Log::info()` 等主动调用。
483// sz-rust 的 Log 中间件是自研增强,提供:
484// - 请求生命周期自动日志(无需业务代码手动调用)
485// - 请求 ID 追踪(贯穿整个请求链路)
486// - 响应状态码分级日志(4xx Warn / 5xx Error)
487//
488// 日志级别对齐 think-logger 的 4 级(debug/info/warn/error),
489// `apart_level` 思想对齐 PHP `config/log.php` 的 `['error','sql']` 独立文件配置。
490//
491// ## 用法
492//
493// ```ignore
494// use sz_rust_core::middleware::log::log_middleware;
495// use axum::Router;
496//
497// let app: Router = Router::new()
498//     .route("/", axum::routing::get(|| async { "ok" }))
499//     .layer(axum::middleware::from_fn(log_middleware));
500// ```
501
502use axum::extract::Request;
503use axum::middleware::Next;
504use axum::response::Response;
505use std::sync::atomic::{AtomicU64, Ordering};
506use std::time::Instant;
507
508/// 请求 ID(注入到 request extensions,供下游 handler 和日志使用)
509///
510/// 生成方式:全局 `AtomicU64` 计数器 + 当前时间戳,保证进程内唯一。
511/// 格式:16 字符 hex(`{timestamp_secs:08x}{counter:08x}`)。
512#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
513pub struct RequestId {
514    /// 时间戳部分(UNIX 秒)
515    timestamp_secs: u64,
516    /// 计数器部分(进程内递增)
517    counter: u64,
518}
519
520impl RequestId {
521    /// 返回 16 字符 hex 字符串
522    ///
523    /// 格式:`{timestamp_secs:08x}{counter:08x}`(对齐 W3C traceparent 的 16 字符 span_id 长度)。
524    pub fn to_hex(&self) -> String {
525        format!("{:08x}{:08x}", self.timestamp_secs, self.counter)
526    }
527
528    /// 返回时间戳部分
529    pub fn timestamp_secs(&self) -> u64 {
530        self.timestamp_secs
531    }
532
533    /// 返回计数器部分
534    pub fn counter(&self) -> u64 {
535        self.counter
536    }
537}
538
539impl std::fmt::Display for RequestId {
540    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
541        f.write_str(&self.to_hex())
542    }
543}
544
545/// 全局 request_id 计数器(进程内递增)
546static REQUEST_ID_COUNTER: AtomicU64 = AtomicU64::new(0);
547
548/// 生成新的 `RequestId`
549///
550/// 使用全局 `AtomicU64` 计数器 + 当前 UNIX 时间戳,保证进程内唯一。
551/// 多线程安全(`fetch_add` 是原子操作)。
552pub fn generate_request_id() -> RequestId {
553    let counter = REQUEST_ID_COUNTER.fetch_add(1, Ordering::Relaxed);
554    let timestamp_secs = std::time::SystemTime::now()
555        .duration_since(std::time::UNIX_EPOCH)
556        .map(|d| d.as_secs())
557        .unwrap_or(0);
558    RequestId {
559        timestamp_secs,
560        counter,
561    }
562}
563
564/// Log 中间件配置
565#[derive(Debug, Clone, Default)]
566pub struct LogConfig {
567    /// 排除路径(不记录日志,对齐 PHP 端白名单思想)
568    ///
569    /// 支持精确匹配(如 `/health`)和通配符匹配(如 `/health/*`)。
570    pub exclude_paths: Vec<String>,
571}
572
573impl LogConfig {
574    /// 创建带排除路径的配置
575    pub fn with_exclude_paths(mut self, paths: Vec<String>) -> Self {
576        self.exclude_paths = paths;
577        self
578    }
579
580    /// 判断路径是否被排除
581    ///
582    /// 支持精确匹配和 `*` 通配符匹配(复用 [`crate::auth::is_route_allowed`] 的逻辑)。
583    pub fn is_excluded(&self, path: &str) -> bool {
584        crate::auth::is_route_allowed(path, &self.exclude_paths)
585    }
586}
587
588/// 根据响应状态码返回日志级别
589///
590/// 对齐 PHP `config/log.php` 的 `apart_level=['error','sql']` 思想:
591/// - 2xx/3xx → `Info`(成功请求)
592/// - 4xx → `Warn`(客户端错误)
593/// - 5xx → `Error`(服务端错误)
594///
595/// 其他状态码(如 1xx)默认为 `Info`。
596pub fn log_level_for_status(status: u16) -> LogLevel {
597    match status {
598        400..=499 => LogLevel::Warn,
599        500..=599 => LogLevel::Error,
600        _ => LogLevel::Info,
601    }
602}
603
604/// 格式化请求日志消息
605///
606/// 输出格式:`request_id=<hex> method=<METHOD> uri=<path> status=<code> duration_ms=<ms>`
607///
608/// 此函数主要用于测试可验证的纯函数,中间件实际输出通过 `tracing` 宏的结构化字段实现。
609pub fn format_request_log(
610    method: &str,
611    uri: &str,
612    status: u16,
613    duration_ms: u64,
614    request_id: &RequestId,
615) -> String {
616    format!(
617        "request_id={} method={} uri={} status={} duration_ms={}",
618        request_id.to_hex(),
619        method,
620        uri,
621        status,
622        duration_ms
623    )
624}
625
626/// Log 中间件 — 请求/响应日志
627///
628/// ## 校验流程
629///
630/// 1. **提取请求信息**:method, uri(在 `req` 被消费之前)
631/// 2. **生成 RequestId**:如果 extensions 中没有,则新生成
632/// 3. **记录起始时间**:`Instant::now()`
633/// 4. **注入 RequestId**:插入 request extensions
634/// 5. **调用 `next.run(req)`**:传递请求给下游
635/// 6. **计算耗时**:`start.elapsed()`
636/// 7. **记录日志**:根据状态码选择级别,输出结构化日志
637///
638/// ## 排除路径
639///
640/// 如果请求路径在 [`LogConfig::exclude_paths`] 中,则不记录日志(但仍注入 RequestId)。
641///
642/// ## 用法
643///
644/// ```ignore
645/// use sz_rust_core::middleware::log::{log_middleware, LogConfig};
646/// use axum::Router;
647///
648/// let config = LogConfig::default();
649/// let app: Router = Router::new()
650///     .route("/", axum::routing::get(|| async { "ok" }))
651///     .layer(axum::middleware::from_fn_with_state(config, log_middleware_with_config));
652/// ```
653pub async fn log_middleware(req: Request, next: Next) -> Response {
654    log_middleware_inner(req, next, &LogConfig::default()).await
655}
656
657/// 带配置的 Log 中间件
658pub async fn log_middleware_with_config(
659    axum::extract::State(config): axum::extract::State<LogConfig>,
660    req: Request,
661    next: Next,
662) -> Response {
663    log_middleware_inner(req, next, &config).await
664}
665
666async fn log_middleware_inner(req: Request, next: Next, config: &LogConfig) -> Response {
667    // 1. 提取请求信息(在 req 被消费之前)
668    let method = req.method().clone();
669    let uri = req.uri().path().to_string();
670
671    // 2. 生成 RequestId(如果 extensions 中没有,则新生成)
672    let request_id = req
673        .extensions()
674        .get::<RequestId>()
675        .copied()
676        .unwrap_or_else(generate_request_id);
677
678    // 3. 记录起始时间
679    let start = Instant::now();
680
681    // 4. 注入 RequestId 到 extensions
682    let mut req = req;
683    req.extensions_mut().insert(request_id);
684
685    // 5. 调用 next
686    let response = next.run(req).await;
687
688    // 6. 计算耗时
689    let duration_ms = start.elapsed().as_millis() as u64;
690
691    // 7. 记录日志(排除路径不记录)
692    if !config.is_excluded(&uri) {
693        let status = response.status().as_u16();
694        let level = log_level_for_status(status);
695        let request_id_hex = request_id.to_hex();
696
697        match level {
698            LogLevel::Debug => tracing::debug!(
699                request_id = %request_id_hex,
700                method = %method,
701                uri = %uri,
702                status = status,
703                duration_ms = duration_ms,
704                "request completed"
705            ),
706            LogLevel::Info => tracing::info!(
707                request_id = %request_id_hex,
708                method = %method,
709                uri = %uri,
710                status = status,
711                duration_ms = duration_ms,
712                "request completed"
713            ),
714            LogLevel::Warn => tracing::warn!(
715                request_id = %request_id_hex,
716                method = %method,
717                uri = %uri,
718                status = status,
719                duration_ms = duration_ms,
720                "request completed"
721            ),
722            LogLevel::Error => tracing::error!(
723                request_id = %request_id_hex,
724                method = %method,
725                uri = %uri,
726                status = status,
727                duration_ms = duration_ms,
728                "request completed"
729            ),
730        }
731    }
732
733    response
734}
735
736#[cfg(test)]
737mod middleware_tests {
738    use super::*;
739    use axum::body::Body;
740    use axum::http::StatusCode;
741    use axum::Router;
742    use http_body_util::BodyExt;
743    use tower::ServiceExt;
744
745    // ====================================================================
746    // 辅助函数
747    // ====================================================================
748
749    async fn read_body(resp: Response) -> String {
750        let bytes = resp.into_body().collect().await.unwrap().to_bytes();
751        String::from_utf8(bytes.to_vec()).unwrap()
752    }
753
754    fn make_request(method: &str, uri: &str) -> Request {
755        Request::builder()
756            .method(method)
757            .uri(uri)
758            .body(Body::empty())
759            .unwrap()
760    }
761
762    /// 构建测试用 Router
763    fn build_app() -> Router {
764        Router::new()
765            .route(
766                "/ok",
767                axum::routing::get(|| async { axum::http::StatusCode::OK }),
768            )
769            .route(
770                "/notfound",
771                axum::routing::get(|| async { axum::http::StatusCode::NOT_FOUND }),
772            )
773            .route(
774                "/error",
775                axum::routing::get(|| async { axum::http::StatusCode::INTERNAL_SERVER_ERROR }),
776            )
777            .route("/body", axum::routing::get(|| async { "hello" }))
778            .layer(axum::middleware::from_fn(log_middleware))
779    }
780
781    // ====================================================================
782    // RequestId 单元测试
783    // ====================================================================
784
785    #[test]
786    fn test_request_id_to_hex_is_16_chars() {
787        let id = RequestId {
788            timestamp_secs: 0x12345678,
789            counter: 0x9ABCDEF0,
790        };
791        let hex = id.to_hex();
792        assert_eq!(hex.len(), 16);
793        assert_eq!(hex, "123456789abcdef0");
794    }
795
796    #[test]
797    fn test_request_id_to_hex_zero() {
798        let id = RequestId {
799            timestamp_secs: 0,
800            counter: 0,
801        };
802        assert_eq!(id.to_hex(), "0000000000000000");
803    }
804
805    #[test]
806    fn test_request_id_to_hex_max() {
807        let id = RequestId {
808            timestamp_secs: u64::MAX,
809            counter: u64::MAX,
810        };
811        // u64::MAX = 0xFFFFFFFFFFFFFFFF,但 format!("{:08x}", u64::MAX) 会输出 16 字符
812        let hex = id.to_hex();
813        assert_eq!(hex.len(), 32); // 每部分 16 字符,总共 32 字符
814    }
815
816    #[test]
817    fn test_request_id_display_matches_to_hex() {
818        let id = RequestId {
819            timestamp_secs: 0x12345678,
820            counter: 0x9ABCDEF0,
821        };
822        assert_eq!(format!("{}", id), id.to_hex());
823    }
824
825    #[test]
826    fn test_request_id_accessors() {
827        let id = RequestId {
828            timestamp_secs: 100,
829            counter: 200,
830        };
831        assert_eq!(id.timestamp_secs(), 100);
832        assert_eq!(id.counter(), 200);
833    }
834
835    #[test]
836    fn test_request_id_equality() {
837        let id1 = RequestId {
838            timestamp_secs: 1,
839            counter: 2,
840        };
841        let id2 = RequestId {
842            timestamp_secs: 1,
843            counter: 2,
844        };
845        let id3 = RequestId {
846            timestamp_secs: 1,
847            counter: 3,
848        };
849        assert_eq!(id1, id2);
850        assert_ne!(id1, id3);
851    }
852
853    // ====================================================================
854    // generate_request_id 单元测试
855    // ====================================================================
856
857    #[test]
858    fn test_generate_request_id_returns_unique() {
859        let id1 = generate_request_id();
860        let id2 = generate_request_id();
861        // 计数器递增,保证唯一
862        assert_ne!(id1.counter(), id2.counter());
863        assert_eq!(id2.counter(), id1.counter() + 1);
864    }
865
866    #[test]
867    fn test_generate_request_id_hex_is_16_chars() {
868        let id = generate_request_id();
869        let hex = id.to_hex();
870        // 注意:如果 timestamp_secs 或 counter 超过 u32::MAX,hex 会超过 16 字符
871        // 但在正常情况下(timestamp < 2106 年,counter < 40 亿次),hex 是 16 字符
872        assert!(hex.len() >= 16);
873    }
874
875    // ====================================================================
876    // log_level_for_status 单元测试
877    // ====================================================================
878
879    #[test]
880    fn test_log_level_for_2xx_returns_info() {
881        assert_eq!(log_level_for_status(200), LogLevel::Info);
882        assert_eq!(log_level_for_status(201), LogLevel::Info);
883        assert_eq!(log_level_for_status(204), LogLevel::Info);
884    }
885
886    #[test]
887    fn test_log_level_for_3xx_returns_info() {
888        assert_eq!(log_level_for_status(301), LogLevel::Info);
889        assert_eq!(log_level_for_status(302), LogLevel::Info);
890        assert_eq!(log_level_for_status(304), LogLevel::Info);
891    }
892
893    #[test]
894    fn test_log_level_for_4xx_returns_warn() {
895        assert_eq!(log_level_for_status(400), LogLevel::Warn);
896        assert_eq!(log_level_for_status(401), LogLevel::Warn);
897        assert_eq!(log_level_for_status(403), LogLevel::Warn);
898        assert_eq!(log_level_for_status(404), LogLevel::Warn);
899        assert_eq!(log_level_for_status(422), LogLevel::Warn);
900        assert_eq!(log_level_for_status(499), LogLevel::Warn);
901    }
902
903    #[test]
904    fn test_log_level_for_5xx_returns_error() {
905        assert_eq!(log_level_for_status(500), LogLevel::Error);
906        assert_eq!(log_level_for_status(501), LogLevel::Error);
907        assert_eq!(log_level_for_status(502), LogLevel::Error);
908        assert_eq!(log_level_for_status(503), LogLevel::Error);
909        assert_eq!(log_level_for_status(599), LogLevel::Error);
910    }
911
912    #[test]
913    fn test_log_level_for_1xx_returns_info() {
914        // 1xx 信息响应默认为 Info
915        assert_eq!(log_level_for_status(100), LogLevel::Info);
916        assert_eq!(log_level_for_status(101), LogLevel::Info);
917    }
918
919    #[test]
920    fn test_log_level_for_boundary() {
921        // 边界测试:399 → Info,400 → Warn,499 → Warn,500 → Error,599 → Error,600 → Info
922        assert_eq!(log_level_for_status(399), LogLevel::Info);
923        assert_eq!(log_level_for_status(400), LogLevel::Warn);
924        assert_eq!(log_level_for_status(499), LogLevel::Warn);
925        assert_eq!(log_level_for_status(500), LogLevel::Error);
926        assert_eq!(log_level_for_status(599), LogLevel::Error);
927        assert_eq!(log_level_for_status(600), LogLevel::Info);
928    }
929
930    // ====================================================================
931    // format_request_log 单元测试
932    // ====================================================================
933
934    #[test]
935    fn test_format_request_log_basic() {
936        let request_id = RequestId {
937            timestamp_secs: 0x12345678,
938            counter: 0x9ABCDEF0,
939        };
940        let msg = format_request_log("GET", "/api/users", 200, 15, &request_id);
941        assert_eq!(
942            msg,
943            "request_id=123456789abcdef0 method=GET uri=/api/users status=200 duration_ms=15"
944        );
945    }
946
947    #[test]
948    fn test_format_request_log_post_method() {
949        let request_id = RequestId {
950            timestamp_secs: 0,
951            counter: 1,
952        };
953        let msg = format_request_log("POST", "/api/orders", 201, 42, &request_id);
954        assert_eq!(
955            msg,
956            "request_id=0000000000000001 method=POST uri=/api/orders status=201 duration_ms=42"
957        );
958    }
959
960    #[test]
961    fn test_format_request_log_error_status() {
962        let request_id = RequestId {
963            timestamp_secs: 0,
964            counter: 0,
965        };
966        let msg = format_request_log("GET", "/missing", 404, 5, &request_id);
967        assert_eq!(
968            msg,
969            "request_id=0000000000000000 method=GET uri=/missing status=404 duration_ms=5"
970        );
971    }
972
973    #[test]
974    fn test_format_request_log_with_query_string_in_uri() {
975        // uri 应该是原始 path(含查询字符串),由调用方决定是否截取
976        let request_id = RequestId {
977            timestamp_secs: 0,
978            counter: 0,
979        };
980        let msg = format_request_log("GET", "/api?foo=bar", 200, 1, &request_id);
981        assert!(msg.contains("uri=/api?foo=bar"));
982    }
983
984    // ====================================================================
985    // LogConfig 单元测试
986    // ====================================================================
987
988    #[test]
989    fn test_log_config_default_empty_exclude_paths() {
990        let config = LogConfig::default();
991        assert!(config.exclude_paths.is_empty());
992    }
993
994    #[test]
995    fn test_log_config_with_exclude_paths() {
996        let config = LogConfig::default().with_exclude_paths(vec!["/health".to_string()]);
997        assert_eq!(config.exclude_paths, vec!["/health".to_string()]);
998    }
999
1000    #[test]
1001    fn test_log_config_is_excluded_exact_match() {
1002        let config = LogConfig::default().with_exclude_paths(vec!["/health".to_string()]);
1003        assert!(config.is_excluded("/health"));
1004        assert!(!config.is_excluded("/health/detail"));
1005        assert!(!config.is_excluded("/api"));
1006    }
1007
1008    #[test]
1009    fn test_log_config_is_excluded_wildcard_match() {
1010        let config = LogConfig::default().with_exclude_paths(vec!["/health/*".to_string()]);
1011        assert!(config.is_excluded("/health/check"));
1012        assert!(config.is_excluded("/health/deep/nested"));
1013        assert!(!config.is_excluded("/health"));
1014        assert!(!config.is_excluded("/api"));
1015    }
1016
1017    #[test]
1018    fn test_log_config_is_excluded_empty_list() {
1019        let config = LogConfig::default();
1020        assert!(!config.is_excluded("/any"));
1021    }
1022
1023    #[test]
1024    fn test_log_config_is_excluded_multiple_entries() {
1025        let config = LogConfig::default()
1026            .with_exclude_paths(vec!["/health".to_string(), "/metrics/*".to_string()]);
1027        assert!(config.is_excluded("/health"));
1028        assert!(config.is_excluded("/metrics/prometheus"));
1029        assert!(!config.is_excluded("/api"));
1030    }
1031
1032    // ====================================================================
1033    // log_middleware 集成测试
1034    // ====================================================================
1035
1036    #[tokio::test]
1037    async fn test_log_middleware_returns_response_unchanged() {
1038        // 验证中间件不修改响应体
1039        let app = build_app();
1040        let resp = app.oneshot(make_request("GET", "/body")).await.unwrap();
1041        let body = read_body(resp).await;
1042        assert_eq!(body, "hello");
1043    }
1044
1045    #[tokio::test]
1046    async fn test_log_middleware_returns_correct_status() {
1047        let app = build_app();
1048        let resp = app.oneshot(make_request("GET", "/ok")).await.unwrap();
1049        assert_eq!(resp.status(), StatusCode::OK);
1050    }
1051
1052    #[tokio::test]
1053    async fn test_log_middleware_injects_request_id() {
1054        // 验证 request_id 被注入 extensions
1055        let app = Router::new()
1056            .route(
1057                "/",
1058                axum::routing::get(|req: Request| async move {
1059                    let request_id = req.extensions().get::<RequestId>().unwrap();
1060                    format!("request_id:{}", request_id.to_hex())
1061                }),
1062            )
1063            .layer(axum::middleware::from_fn(log_middleware));
1064
1065        let resp = app.oneshot(make_request("GET", "/")).await.unwrap();
1066        assert_eq!(resp.status(), StatusCode::OK);
1067        let body = read_body(resp).await;
1068        assert!(body.starts_with("request_id:"));
1069        // 验证 hex 长度至少 16 字符
1070        let hex = body.strip_prefix("request_id:").unwrap();
1071        assert!(hex.len() >= 16);
1072    }
1073
1074    #[tokio::test]
1075    async fn test_log_middleware_generates_unique_request_ids() {
1076        // 验证多个请求生成不同的 request_id
1077        let app = Router::new()
1078            .route(
1079                "/",
1080                axum::routing::get(|req: Request| async move {
1081                    let request_id = req.extensions().get::<RequestId>().unwrap();
1082                    request_id.to_hex()
1083                }),
1084            )
1085            .layer(axum::middleware::from_fn(log_middleware));
1086
1087        let resp1 = app.clone().oneshot(make_request("GET", "/")).await.unwrap();
1088        let hex1 = read_body(resp1).await;
1089
1090        let resp2 = app.oneshot(make_request("GET", "/")).await.unwrap();
1091        let hex2 = read_body(resp2).await;
1092
1093        assert_ne!(hex1, hex2);
1094    }
1095
1096    #[tokio::test]
1097    async fn test_log_middleware_preserves_existing_request_id() {
1098        // 验证已存在的 request_id 不被覆盖
1099        let existing_id = RequestId {
1100            timestamp_secs: 0xDEADBEEF,
1101            counter: 0x12345678,
1102        };
1103        let app = Router::new()
1104            .route(
1105                "/",
1106                axum::routing::get(|req: Request| async move {
1107                    let request_id = req.extensions().get::<RequestId>().unwrap();
1108                    request_id.to_hex()
1109                }),
1110            )
1111            .layer(axum::middleware::from_fn(log_middleware))
1112            .layer(
1113                tower::ServiceBuilder::new().layer(tower::layer::layer_fn(move |service| {
1114                    tower::util::MapRequest::new(service, move |mut req: Request| {
1115                        req.extensions_mut().insert(existing_id);
1116                        req
1117                    })
1118                })),
1119            );
1120
1121        let resp = app.oneshot(make_request("GET", "/")).await.unwrap();
1122        let body = read_body(resp).await;
1123        assert_eq!(body, "deadbeef12345678");
1124    }
1125
1126    #[tokio::test]
1127    async fn test_log_middleware_records_2xx_status() {
1128        // 验证 2xx 响应正常处理(日志级别由 log_level_for_status 决定)
1129        let app = build_app();
1130        let resp = app.oneshot(make_request("GET", "/ok")).await.unwrap();
1131        assert_eq!(resp.status(), StatusCode::OK);
1132    }
1133
1134    #[tokio::test]
1135    async fn test_log_middleware_records_4xx_status() {
1136        let app = build_app();
1137        let resp = app.oneshot(make_request("GET", "/notfound")).await.unwrap();
1138        assert_eq!(resp.status(), StatusCode::NOT_FOUND);
1139    }
1140
1141    #[tokio::test]
1142    async fn test_log_middleware_records_5xx_status() {
1143        let app = build_app();
1144        let resp = app.oneshot(make_request("GET", "/error")).await.unwrap();
1145        assert_eq!(resp.status(), StatusCode::INTERNAL_SERVER_ERROR);
1146    }
1147
1148    #[tokio::test]
1149    async fn test_log_middleware_with_config_excludes_path() {
1150        // 验证排除路径不记录日志(但仍注入 request_id)
1151        let config = LogConfig::default().with_exclude_paths(vec!["/health".to_string()]);
1152        let app = Router::new()
1153            .route("/health", axum::routing::get(|| async { "healthy" }))
1154            .layer(axum::middleware::from_fn_with_state(
1155                config,
1156                log_middleware_with_config,
1157            ));
1158
1159        let resp = app.oneshot(make_request("GET", "/health")).await.unwrap();
1160        assert_eq!(resp.status(), StatusCode::OK);
1161        let body = read_body(resp).await;
1162        assert_eq!(body, "healthy");
1163    }
1164
1165    #[tokio::test]
1166    async fn test_log_middleware_with_config_wildcard_exclude() {
1167        // 验证通配符排除路径
1168        let config = LogConfig::default().with_exclude_paths(vec!["/metrics/*".to_string()]);
1169        let app = Router::new()
1170            .route(
1171                "/metrics/prometheus",
1172                axum::routing::get(|| async { "metrics" }),
1173            )
1174            .layer(axum::middleware::from_fn_with_state(
1175                config,
1176                log_middleware_with_config,
1177            ));
1178
1179        let resp = app
1180            .oneshot(make_request("GET", "/metrics/prometheus"))
1181            .await
1182            .unwrap();
1183        assert_eq!(resp.status(), StatusCode::OK);
1184    }
1185
1186    #[tokio::test]
1187    async fn test_log_middleware_preserves_method_and_uri() {
1188        // 验证 method 和 uri 被正确提取(通过日志消息格式验证)
1189        // 由于 tracing 宏输出在测试中难以捕获,这里验证中间件不破坏请求
1190        let app = build_app();
1191        let resp = app.oneshot(make_request("GET", "/ok")).await.unwrap();
1192        assert_eq!(resp.status(), StatusCode::OK);
1193    }
1194
1195    #[tokio::test]
1196    async fn test_log_middleware_duration_is_non_negative() {
1197        // 验证 duration_ms 是非负的(通过响应正常返回间接验证)
1198        let app = build_app();
1199        let start = std::time::Instant::now();
1200        let resp = app.oneshot(make_request("GET", "/ok")).await.unwrap();
1201        let elapsed = start.elapsed();
1202        assert!(resp.status().is_success());
1203        // 中间件内部记录的 duration_ms 应该 <= 测试外部的 elapsed
1204        assert!(elapsed.as_millis() < 5000); // 5 秒上限(防止死循环)
1205    }
1206
1207    #[tokio::test]
1208    async fn test_log_middleware_handles_post_request() {
1209        let app = Router::new()
1210            .route(
1211                "/submit",
1212                axum::routing::post(|| async { axum::http::StatusCode::CREATED }),
1213            )
1214            .layer(axum::middleware::from_fn(log_middleware));
1215
1216        let req = Request::builder()
1217            .method("POST")
1218            .uri("/submit")
1219            .body(Body::empty())
1220            .unwrap();
1221        let resp = app.oneshot(req).await.unwrap();
1222        assert_eq!(resp.status(), StatusCode::CREATED);
1223    }
1224
1225    #[tokio::test]
1226    async fn test_log_middleware_chains_with_other_middleware() {
1227        // 验证 Log 中间件与其他中间件链式调用
1228        async fn add_header_middleware(req: Request, next: Next) -> Response {
1229            let mut resp = next.run(req).await;
1230            resp.headers_mut()
1231                .insert("X-Custom", "value".parse().unwrap());
1232            resp
1233        }
1234
1235        let app = Router::new()
1236            .route("/", axum::routing::get(|| async { "ok" }))
1237            .layer(axum::middleware::from_fn(add_header_middleware))
1238            .layer(axum::middleware::from_fn(log_middleware));
1239
1240        let resp = app.oneshot(make_request("GET", "/")).await.unwrap();
1241        assert_eq!(resp.status(), StatusCode::OK);
1242        assert_eq!(resp.headers().get("X-Custom").unwrap(), "value");
1243    }
1244
1245    // ====================================================================
1246    // PHP 行为对齐验证
1247    // ====================================================================
1248
1249    #[test]
1250    fn test_php_apart_level_alignment() {
1251        // 对齐 PHP `config/log.php` 的 `apart_level=['error','sql']` 思想:
1252        // 4xx → Warn(客户端错误,类似 PHP warning)
1253        // 5xx → Error(服务端错误,对齐 PHP error 独立文件)
1254        assert_eq!(log_level_for_status(200), LogLevel::Info);
1255        assert_eq!(log_level_for_status(404), LogLevel::Warn);
1256        assert_eq!(log_level_for_status(500), LogLevel::Error);
1257    }
1258
1259    #[test]
1260    fn test_php_think_logger_level_alignment() {
1261        // 对齐 PHP think-logger 的 4 级日志(debug/info/warn/error)
1262        // sz-rust 的 LogLevel 也是 4 级,一一对应
1263        let levels = [
1264            LogLevel::Debug,
1265            LogLevel::Info,
1266            LogLevel::Warn,
1267            LogLevel::Error,
1268        ];
1269        assert_eq!(levels.len(), 4);
1270    }
1271
1272    #[test]
1273    fn test_request_id_format_aligns_with_w3c_span_id_length() {
1274        // 对齐 W3C traceparent 的 span_id 长度(16 字符 hex)
1275        // 便于未来 Trace 中间件实现时与 trace_id 格式兼容
1276        let id = RequestId {
1277            timestamp_secs: 0x12345678,
1278            counter: 0x9ABCDEF0,
1279        };
1280        assert_eq!(id.to_hex().len(), 16);
1281    }
1282}