diff --git a/README.md b/README.md index 6ed2e97..0aeb6e9 100644 --- a/README.md +++ b/README.md @@ -133,4 +133,219 @@ rust_logger/ │ │ └── postgres.rs # 数据库输出实现 │ ├── core.rs # Logger 核心逻辑 (Channel, Spawn) │ └── cleaner.rs # 清理输出协程 -``` \ No newline at end of file +``` + + +为了展示 **TraceID** 的真正威力，我们将模拟一个 **高并发的 Web 服务场景**。 + +在这个场景中，如果不使用 TraceID，多个用户的日志会像“洗牌”一样混在一起，根本无法区分谁是谁。使用了 TraceID 后，我们就能像“抓线头”一样把一次请求的完整路径提出来。 + +--- + +### 第一步：准备工作 (不可跳过) + +因为我们在 `LogRecord` 中增加了 `trace_id`，你必须更新数据库表结构，否则程序运行会报错。 + +**请在 PostgreSQL 中执行：** + +```sql +-- 1. 增加字段 +ALTER TABLE app_logs ADD COLUMN trace_id VARCHAR(64); + +-- 2. 建立索引 (查询全靠它) +CREATE INDEX idx_logs_trace_id ON app_logs(trace_id); +``` + +--- + +### 第二步：编写业务代码 (`order-service/src/main.rs`) + +我们需要引入 `uuid` 来生成唯一的 ID。 + +**Cargo.toml:** +```toml +[dependencies] +# ... 其他依赖 +uuid = { version = "1.0", features = ["v4"] } +``` + +**main.rs:** +在这个例子中，我们模拟**两个并发请求**同时进入系统。 + +```rust +use rust_logger::{ + context::with_trace_id, // 核心：上下文管理器 + log_info, log_error, set_global_logger, + Logger, LoggerConfig, LogLevel, LogCleaner, + outputs::{ConsoleOutput, PostgresOutput, FileOutput} +}; +use sqlx::postgres::PgPoolOptions; +use std::time::Duration; +use uuid::Uuid; +use std::sync::Arc; + +#[tokio::main] +async fn main() -> anyhow::Result<()> { + // 1. 初始化 DB + let db_url = std::env::var("DATABASE_URL").expect("DATABASE_URL must be set"); + let pool = PgPoolOptions::new().connect(&db_url).await?; + + // 2. 初始化 Logger (同时输出到 Console, DB, File) + let file_output = FileOutput::new("logs", "order-service").await?; + + let config = LoggerConfig { + min_level: LogLevel::INFO, + outputs: vec![ + Box::new(ConsoleOutput), + Box::new(PostgresOutput::new(pool.clone())), // DB + Box::new(file_output), // File + ], + }; + + set_global_logger(Logger::init("order-service", config)); + + // 3. 启动清理任务 (可选) + LogCleaner::new(7).with_db_cleanup(pool.clone()).start(); + + println!(">>> 服务启动，开始模拟并发请求...\n"); + + // 4. 模拟并发：同时处理两个用户的下单请求 + // 场景： + // - 用户 A (Alice) 下单成功 + // - 用户 B (Bob) 下单失败 + + let request_a = tokio::spawn(mock_http_handler("Alice", "ITEM-001", true)); + let request_b = tokio::spawn(mock_http_handler("Bob", "ITEM-999", false)); // 模拟库存不足 + + // 等待请求处理完成 + let _ = tokio::join!(request_a, request_b); + + // 等待日志写入完毕 + tokio::time::sleep(Duration::from_secs(1)).await; + println!("\n>>> 模拟结束。请查看数据库或文件日志。"); + + Ok(()) +} + +// 模拟 HTTP 请求入口 (Middleware 层) +async fn mock_http_handler(user: &str, item_id: &str, is_success: bool) { + // 1. 生成 TraceID (通常从 HTTP Header "X-Trace-ID" 获取，没有则生成) + let trace_id = Uuid::new_v4().to_string(); + + // 2. 【关键】使用 with_trace_id 包裹整个业务逻辑 + // 只要在这个闭包里，无论调用多深层的函数，log_info! 都会自动带上 ID + with_trace_id(trace_id.clone(), async move { + log_info!("收到下单请求: User={}, Item={}", user, item_id); + + // 进入业务逻辑层 + process_order(user, item_id, is_success).await; + + log_info!("请求处理完毕，返回响应给 {}", user); + }).await; +} + +// 模拟业务逻辑层 (Service 层) +async fn process_order(user: &str, item_id: &str, simulate_success: bool) { + log_info!("正在检查库存: {}", item_id); + tokio::time::sleep(Duration::from_millis(50)).await; // 模拟耗时 + + if simulate_success { + log_info!("库存充足，开始扣款..."); + payment_service(user, 100).await; + log_info!("下单成功！订单号: ORDER-{}", Uuid::new_v4()); + } else { + log_error!("库存不足！商品 {} 缺货", item_id); + log_info!("订单已取消"); + } +} + +// 模拟底层服务 (DAO/RPC 层) +async fn payment_service(user: &str, amount: i32) { + // 注意：这里我们没有传 trace_id 参数，但 log_info 依然能获取到它！ + log_info!("扣款成功: User={}, Amount=${}", user, amount); +} +``` + +--- + +### 第三步：运行结果与证明 + +运行代码后，我们来看看 **为什么 TraceID 是分布式的救命稻草**。 + +#### 1. 如果没有 TraceID (灾难现场) +在控制台或文件中，由于是异步并发，日志会是**时间交错**的。你看到的可能是这样： + +```text +2026-01-22 10:00:01 [INFO] 收到下单请求: User=Alice +2026-01-22 10:00:01 [INFO] 收到下单请求: User=Bob <-- 乱入 +2026-01-22 10:00:02 [INFO] 正在检查库存: ITEM-001 +2026-01-22 10:00:02 [INFO] 正在检查库存: ITEM-999 <-- 分不清谁是谁了 +2026-01-22 10:00:03 [ERROR] 库存不足！ +2026-01-22 10:00:03 [INFO] 库存充足，开始扣款... <-- 谁库存充足？谁不足？ +2026-01-22 10:00:04 [INFO] 扣款成功 +``` +**问题**：当 Bob 投诉说“我下单失败了”，你看着日志里的“扣款成功”会陷入沉思：到底扣没扣 Bob 的钱？ + +#### 2. 使用 TraceID 后 (真相大白) +现在查看生成的文件日志 `logs/order-service-YYYY-MM-DD.log`，或者查看数据库。 + +**实际输出：** +```text +[INFO] [550e8400-e29b...] - 收到下单请求: User=Alice +[INFO] [a1b2c3d4-ffff...] - 收到下单请求: User=Bob +[INFO] [550e8400-e29b...] - 正在检查库存: ITEM-001 +[INFO] [a1b2c3d4-ffff...] - 正在检查库存: ITEM-999 +[ERROR] [a1b2c3d4-ffff...] - 库存不足！商品 ITEM-999 缺货 +[INFO] [a1b2c3d4-ffff...] - 订单已取消 +[INFO] [550e8400-e29b...] - 库存充足，开始扣款... +[INFO] [550e8400-e29b...] - 扣款成功: User=Alice, Amount=$100 +``` +虽然行还是交错的，但我们可以清楚地看到 ID `a1b2c3d4...` (Bob) 对应的是 **ERROR**，而 ID `550e8400...` (Alice) 对应的是 **扣款成功**。 + +--- + +### 第四步：如何追查问题 (Audit) + +当生产环境出现问题时，正确的排查姿势如下： + +#### 场景：客服转来一个工单，用户 Bob 说 10:00 左右下单失败了。 + +**1. 模糊搜索定位 TraceID** +你不知道 TraceID，但知道时间和用户。 +使用 `grep` 或 SQL： + +```sql +-- 查找 Bob 在那个时间点的第一条日志，为了拿 TraceID +SELECT trace_id, message, created_at +FROM app_logs +WHERE message LIKE '%Bob%' + AND created_at BETWEEN '2026-01-22 10:00:00' AND '2026-01-22 10:05:00' +LIMIT 1; +``` +**结果**：拿到 TraceID = `a1b2c3d4-ffff...` + +**2. 全链路还原 (The Magic Query)** +拿着这个 ID，查询该请求的一生。 + +```sql +SELECT created_at, log_level, module, message +FROM app_logs +WHERE trace_id = 'a1b2c3d4-ffff-...' +ORDER BY created_at ASC; +``` + +**还原出的故事：** +1. `10:00:01` [INFO] 收到请求 (module: `mock_http_handler`) +2. `10:00:02` [INFO] 检查库存 ITEM-999 (module: `process_order`) +3. `10:00:03` [ERROR] **库存不足！** (module: `process_order`) <--- **找到原因了！** +4. `10:00:03` [INFO] 订单取消 + +**结论**：你可以自信地回复工单：“经排查，用户下单失败是因为商品 ITEM-999 此时没有库存了，系统正确拦截，未扣款。” + +--- + +### 总结 TraceID 的三大好处 + +1. **解耦并发**：在高并发系统中（每秒几千个请求），TraceID 是唯一能把属于同一个请求的日志“聚合”在一起的键。 +2. **跨越边界**：虽然本例只演示了一个服务，但 TraceID 通常会通过 HTTP Header 传给下游服务（Payment Service, Stock Service）。这样你在 Kibana/Grafana 里搜一个 TraceID，能看到跨越 5 个微服务的完整调用链。 +3. **无侵入开发**：你的开发人员不需要在写 `payment_service` 时手动传递 `trace_id` 参数，他们只需要写 `log_info!`，库会自动完成剩下的工作。 \ No newline at end of file