kindergarten_java/docs/日志优化方案 - 生产环境错误定位.md

日志优化方案 - 生产环境快速错误定位

文档创建时间：2026-03-26 最后更新：2026-03-26

需求背景

问题描述

生产环境有四个日志文件：

• reading-platform.log - 主日志（INFO 及以上）
• reading-platform-error.log - 错误日志（ERROR 级别）
• reading-platform-request.log - 请求日志
• reading-platform-sql.log - SQL 日志（WARN 及以上）

核心问题：如何在多个日志文件中快速定位同一个请求的错误链路？

解决方案

通过 TraceId（链路追踪 ID） + 增强上下文信息 实现跨日志文件的请求追踪。

核心实现

1. TraceId 生成与传递

为每个请求生成唯一的 8 位 TraceId，在所有日志文件中统一输出。

TraceId 示例：[8DFC19D9]

2. 日志格式

2026-03-26 10:00:00.123 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 请求开始 [userId=1, role=admin]

字段	说明
2026-03-26 10:00:00.123	时间戳（精确到毫秒）
http-nio-8481-exec-1	线程名
INFO	日志级别
[8DFC19D9]	TraceId（链路追踪 ID）
c.l.e.common.aspect.RequestLogAspect	类名缩写
userId=1, role=admin	用户上下文信息

3. 用户上下文信息

在请求日志和异常日志中记录用户信息：

• userId - 用户 ID
• role - 用户角色（admin/school/teacher/parent）
• uri - 请求地址

日志示例

正常请求日志

# reading-platform-request.log
2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - ===== 请求开始 [userId=1, role=admin] =====
2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 接口地址：POST /api/v1/auth/login
2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 请求方法：com.lesingle.edu.controller.AuthController.login
2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 请求参数：{"password":"123456","username":"admin"}
2026-03-26 14:11:11.154 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 响应时间：700ms
2026-03-26 14:11:11.164 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 响应结果：{"code":200,"message":"操作成功"}
2026-03-26 14:11:11.164 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - ===== 请求结束 [userId=1, role=admin] =====

错误日志

# reading-platform-error.log
2026-03-26 14:15:30.123 [http-nio-8481-exec-5] ERROR [8DFC19D9] c.l.e.exception.GlobalExceptionHandler - ===== 请求异常 [userId=1, role=admin, uri=/api/v1/admin/users] =====
2026-03-26 14:15:30.123 [http-nio-8481-exec-5] ERROR [8DFC19D9] c.l.e.exception.GlobalExceptionHandler - 异常信息：数据库连接超时
2026-03-26 14:15:30.123 [http-nio-8481-exec-5] ERROR [8DFC19D9] c.l.e.exception.GlobalExceptionHandler - 异常类型：java.sql.SQLTransientConnectionException
2026-03-26 14:15:30.125 [http-nio-8481-exec-5] ERROR [8DFC19D9] c.l.e.exception.GlobalExceptionHandler - 堆栈信息：
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:770)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:545)
    ...

SQL 日志（慢 SQL）

# reading-platform-sql.log
2026-03-26 14:15:29.500 [http-nio-8481-exec-5] WARN  [8DFC19D9] c.l.e.mapper.UserMapper - SQL 执行超时 (2.5s): SELECT * FROM user WHERE status = 'active' AND ...

生产环境错误定位流程

步骤一：在 error.log 中发现错误

# 实时查看错误日志
tail -f logs/reading-platform-error.log

发现错误日志：

2026-03-26 14:15:30.123 [http-nio-8481-exec-5] ERROR [8DFC19D9] c.l.e.exception.GlobalExceptionHandler - 处理异常：userId=1, role=admin, uri=/api/v1/admin/users

获取 TraceId: [8DFC19D9]

步骤二：使用 TraceId 搜索完整链路

# 方法一：grep 命令搜索所有日志文件
grep "8DFC19D9" logs/*.log

# 方法二：按时间查看主日志
grep "8DFC19D9" logs/reading-platform.log

# 方法三：查看请求日志
grep "8DFC19D9" logs/reading-platform-request.log

# 方法四：查看 SQL 日志
grep "8DFC19D9" logs/reading-platform-sql.log

步骤三：分析完整链路

将搜索结果按时间排序，还原请求的完整执行过程：

# 综合查看该 TraceId 的所有日志
grep "8DFC19D9" logs/reading-platform*.log | sort

输出示例：

2026-03-26 14:15:28.100 [http-nio-8481-exec-5] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 请求开始 [userId=1, role=admin]
2026-03-26 14:15:28.100 [http-nio-8481-exec-5] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 接口地址：GET /api/v1/admin/users
2026-03-26 14:15:28.150 [http-nio-8481-exec-5] INFO  [8DFC19D9] c.l.e.service.UserService - 开始查询用户列表
2026-03-26 14:15:29.500 [http-nio-8481-exec-5] WARN  [8DFC19D9] c.l.e.mapper.UserMapper - SQL 执行超时 (2.5s)
2026-03-26 14:15:30.123 [http-nio-8481-exec-5] ERROR [8DFC19D9] c.l.e.exception.GlobalExceptionHandler - 处理异常：数据库连接超时

步骤四：定位问题根因

根据完整链路日志，快速定位问题：

1. 请求参数：查看 RequestLogAspect 输出的请求参数
2. 业务逻辑：查看 Service 层的业务处理日志
3. SQL 执行：查看 reading-platform-sql.log 中的 SQL 执行情况
4. 异常信息：查看 reading-platform-error.log 中的完整堆栈

日志搜索命令参考

Linux / macOS

# 1. 按 TraceId 搜索
grep "8DFC19D9" logs/*.log

# 2. 按用户 ID 搜索
grep "userId=1" logs/reading-platform*.log

# 3. 按接口路径搜索
grep "/api/v1/admin/users" logs/reading-platform*.log

# 4. 按时间段搜索（最近 100 行）
tail -100 logs/reading-platform-error.log

# 5. 组合搜索（TraceId + 错误）
grep "8DFC19D9" logs/*.log | grep -i "error\|exception"

# 6. 实时跟踪特定 TraceId 的日志
tail -f logs/reading-platform*.log | grep "8DFC19D9"

Windows (PowerShell)

# 1. 按 TraceId 搜索
Select-String -Path "logs\*.log" -Pattern "8DFC19D9"

# 2. 按用户 ID 搜索
Select-String -Path "logs\reading-platform*.log" -Pattern "userId=1"

# 3. 实时跟踪日志
Get-Content logs\reading-platform.log -Wait | Select-String "8DFC19D9"

日志级别配置

开发环境 (dev)

日志类型	级别	输出位置
业务日志	DEBUG	控制台 + FILE
请求日志	INFO	REQUEST_FILE
SQL 日志	DEBUG	控制台 + FILE

测试环境 (test)

日志类型	级别	输出位置
业务日志	INFO	控制台 + FILE + ERROR_FILE
请求日志	INFO	REQUEST_FILE
SQL 日志	INFO	FILE

生产环境 (prod)

日志类型	级别	输出位置
业务日志	INFO	FILE + ERROR_FILE
请求日志	INFO	REQUEST_FILE
SQL 日志	WARN	SQL_FILE（只记录慢 SQL 和错误 SQL）

技术实现

文件清单

文件	说明
TraceIdFilter.java	链路追踪过滤器，生成 TraceId 并放入 MDC
SecurityConfig.java	注册 TraceIdFilter
logback-spring.xml	日志配置，添加 TraceId 输出格式
RequestLogAspect.java	请求日志切面，记录用户信息
GlobalExceptionHandler.java	全局异常处理，记录上下文信息

TraceId 生成规则

• 使用 UUID 的前 8 位（大写）
• 示例：8DFC19D9
• 唯一性保证：UUID 重复概率极低

MDC 上下文管理

// TraceIdFilter.java
MDC.put("traceId", traceId);  // 请求开始时放入
try {
    filterChain.doFilter(request, response);
} finally {
    MDC.clear();  // 请求结束时清理，防止内存泄漏
}

日志平台集成

ELK Stack (Elasticsearch + Logstash + Kibana)

在 Kibana 中搜索 TraceId：

traceId: "8DFC19D9"

Loki + Grafana

在 Grafana 中搜索 TraceId：

{app="reading-platform"} |= "8DFC19D9"

最佳实践

1. 日志简洁：避免输出过长的日志，单行控制在 500 字符以内
2. 结构化：使用 JSON 格式输出复杂对象，便于日志平台解析
3. 敏感信息脱敏：密码、手机号、身份证等敏感信息需要脱敏
4. TraceId 优先：定位问题时首先获取 TraceId，然后搜索完整链路
5. 定期清理：生产环境日志保留 30 天，避免磁盘空间不足

验证方法

开发环境验证

# 1. 启动服务
export SERVER_PORT=8481
cd lesingle-edu-reading-platform-backend
mvn spring-boot:run

# 2. 发送请求
curl http://localhost:8481/api/v1/auth/login -X POST \
  -H "Content-Type: application/json" \
  -d '{"username":"admin","password":"123456"}'

# 3. 查看日志
tail -f logs/reading-platform-request.log

期望输出包含 TraceId：

2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] ...

生产环境验证

# 1. 执行接口请求
# 2. 在 error.log 中查找错误
# 3. 使用 grep 搜索 TraceId
grep "8DFC19D9" logs/*.log

变更记录

日期	变更内容	变更人
2026-03-26	初始版本，实现 TraceId 链路追踪	-
2026-03-26	添加 SQL 错误定位流程和实际验证结果	-

附录：实际验证结果

开发环境 TraceId 验证

启动服务后执行登录接口，查看日志输出：

# 启动服务
export SERVER_PORT=8481
export SPRING_PROFILES_ACTIVE=dev
cd lesingle-edu-reading-platform-backend
mvn spring-boot:run

# 发送登录请求
curl http://localhost:8481/api/v1/auth/login -X POST \
  -H "Content-Type: application/json" \
  -d '{"username":"admin","password":"123456"}'

实际日志输出（reading-platform.log）：

2026-03-26 14:11:10.287 [http-nio-8481-exec-1] DEBUG [8DFC19D9] c.l.edu.common.aspect.LogAspect - 获取当前用户信息失败
2026-03-26 14:11:11.154 [http-nio-8481-exec-1] DEBUG [8DFC19D9] c.l.e.c.s.JwtTokenRedisService - Token stored for user: admin
2026-03-26 14:11:11.154 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.edu.service.impl.AuthServiceImpl - 管理员登录成功，用户名：admin
2026-03-26 14:11:11.178 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.edu.common.aspect.LogAspect - 操作日志记录成功 - 模块：认证管理，操作：用户登录

实际日志输出（reading-platform-request.log）：

2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - ===== 请求开始 [userId=null, role=null] =====
2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 接口地址：POST /api/v1/auth/login
2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 请求方法：com.lesingle.edu.controller.AuthController.login
2026-03-26 14:11:10.455 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 请求参数：{"password":"123456","username":"admin"}
2026-03-26 14:11:11.154 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 响应时间：700ms
2026-03-26 14:11:11.164 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - 响应结果：{"code":200,"message":"操作成功"}
2026-03-26 14:11:11.164 [http-nio-8481-exec-1] INFO  [8DFC19D9] c.l.e.common.aspect.RequestLogAspect - ===== 请求结束 [userId=null, role=null] =====

验证结论：

• TraceId [8DFC19D9] 成功输出到所有日志文件
• 用户上下文信息（userId, role）正确记录
• 请求参数、响应结果、执行时间完整记录

---

附录：SQL 错误定位场景模拟

场景一：SQL 语法错误

错误原因：表名或字段名错误

日志输出示例：

# reading-platform-request.log
2026-03-26 15:00:00.100 [http-nio-8481-exec-3] INFO  [A1B2C3D4] c.l.e.common.aspect.RequestLogAspect - 请求开始 [userId=1, role=admin]
2026-03-26 15:00:00.100 [http-nio-8481-exec-3] INFO  [A1B2C3D4] c.l.e.common.aspect.RequestLogAspect - 接口地址：GET /api/v1/admin/users

# reading-platform-sql.log
2026-03-26 15:00:00.150 [http-nio-8481-exec-3] ERROR [A1B2C3D4] com.lesingle.edu.mapper.UserMapper - SQL 执行错误：
### Error querying database.  Cause: com.mysql.cj.jdbc.exceptions.SQLError: Table 'reading_platform.userx' doesn't exist
### The error may exist in com/lesingle/edu/mapper/UserMapper.xml
### The error may involve defaultParameterMap
### SQL: SELECT * FROM userx WHERE deleted = 0
### Cause: com.mysql.cj.jdbc.exceptions.SQLError: Table 'reading_platform.userx' doesn't exist

# reading-platform-error.log
2026-03-26 15:00:00.160 [http-nio-8481-exec-3] ERROR [A1B2C3D4] c.l.e.exception.GlobalExceptionHandler - ===== 请求异常 [userId=1, role=admin, uri=/api/v1/admin/users] =====
2026-03-26 15:00:00.160 [http-nio-8481-exec-3] ERROR [A1B2C3D4] c.l.e.exception.GlobalExceptionHandler - 异常类型：org.mybatis.spring.MyBatisSystemException
2026-03-26 15:00:00.160 [http-nio-8481-exec-3] ERROR [A1B2C3D4] c.l.e.exception.GlobalExceptionHandler - 异常信息：Error querying database.  Cause: Table 'reading_platform.userx' doesn't exist

定位步骤：

1. 在 error.log 中发现错误，获取 TraceId [A1B2C3D4]
2. 使用 grep "A1B2C3D4" logs/*.log 搜索完整链路
3. 在 sql.log 中查看 SQL 错误原因：表不存在
4. 定位问题：代码中表名写错（userx 应为 user）

---

场景二：数据库连接超时

错误原因：数据库连接池耗尽或网络问题

日志输出示例：

# reading-platform.log
2026-03-26 15:30:00.100 [http-nio-8481-exec-5] INFO  [E5F6G7H8] c.l.e.service.UserService - 开始查询用户列表
2026-03-26 15:30:30.100 [http-nio-8481-exec-5] WARN  [E5F6G7H8] c.l.e.mapper.UserMapper - SQL 执行超时 (30s): SELECT * FROM user WHERE ...

# reading-platform-sql.log
2026-03-26 15:30:30.100 [http-nio-8481-exec-5] WARN  [E5F6G7H8] com.lesingle.edu.mapper - SQL 执行超时警告：
执行时间：30000ms
SQL: SELECT * FROM user WHERE status = 'active' LIMIT 1000

# reading-platform-error.log
2026-03-26 15:30:30.150 [http-nio-8481-exec-5] ERROR [E5F6G7H8] c.l.e.exception.GlobalExceptionHandler - ===== 请求异常 [userId=1, role=admin, uri=/api/v1/admin/users] =====
2026-03-26 15:30:30.150 [http-nio-8481-exec-5] ERROR [E5F6G7H8] c.l.e.exception.GlobalExceptionHandler - 异常类型：org.springframework.jdbc.CannotGetJdbcConnectionException
2026-03-26 15:30:30.150 [http-nio-8481-exec-5] ERROR [E5F6G7H8] c.l.e.exception.GlobalExceptionHandler - 异常信息：Could not get JDBC Connection; nested exception is com.zaxxer.hikari.pool.HikariPool$TimeoutException: Connection is not available, request timed out after 30000ms

定位步骤：

1. 在 error.log 中发现错误，获取 TraceId [E5F6G7H8]
2. 搜索完整链路，发现 SQL 执行耗时 30 秒
3. 在 sql.log 中查看慢 SQL 语句
4. 定位问题：数据库连接池耗尽或 SQL 执行过慢

解决方案：

• 检查数据库连接池配置（max-active 参数）
• 优化慢 SQL（添加索引、减少查询数据量）
• 检查数据库服务器负载

---

场景三：数据约束违规

错误原因：违反唯一约束、外键约束等

日志输出示例：

# reading-platform-request.log
2026-03-26 16:00:00.100 [http-nio-8481-exec-8] INFO  [I9J0K1L2] c.l.e.common.aspect.RequestLogAspect - 请求开始 [userId=1, role=admin]
2026-03-26 16:00:00.100 [http-nio-8481-exec-8] INFO  [I9J0K1L2] c.l.e.common.aspect.RequestLogAspect - 请求参数：{"username":"admin","email":"admin@example.com"}

# reading-platform-sql.log
2026-03-26 16:00:00.150 [http-nio-8481-exec-8] ERROR [I9J0K1L2] com.lesingle.edu.mapper.UserMapper - SQL 执行错误：
### Error updating database.  Cause: com.mysql.cj.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry 'admin' for key 'uk_username'
### SQL: INSERT INTO user (username, email, status) VALUES (?, ?, ?)

# reading-platform-error.log
2026-03-26 16:00:00.160 [http-nio-8481-exec-8] ERROR [I9J0K1L2] c.l.e.exception.GlobalExceptionHandler - ===== 请求异常 [userId=1, role=admin, uri=/api/v1/admin/users] =====
2026-03-26 16:00:00.160 [http-nio-8481-exec-8] ERROR [I9J0K1L2] c.l.e.exception.GlobalExceptionHandler - 异常类型：org.duplicateKeyException
2026-03-26 16:00:00.160 [http-nio-8481-exec-8] ERROR [I9J0K1L2] c.l.e.exception.GlobalExceptionHandler - 异常信息：Duplicate entry 'admin' for key 'uk_username'

定位步骤：

1. 在 error.log 中发现错误，获取 TraceId [I9J0K1L2]
2. 在 request.log 中查看请求参数：username=admin
3. 在 sql.log 中查看错误：唯一约束违规
4. 定位问题：用户名 admin 已存在，无法重复创建

---

附录：常用故障排查命令速查

场景	命令	说明
实时查看错误	tail -f logs/reading-platform-error.log	实时监控错误日志
搜索 TraceId	grep "ABC12345" logs/*.log	搜索指定请求的所有日志
查看慢 SQL	grep "超时|timeout" logs/reading-platform-sql.log	搜索慢 SQL
统计错误数	grep -c "ERROR" logs/reading-platform-error.log	统计错误数量
查看最近 100 行	tail -100 logs/reading-platform.log	查看最近日志
按时间过滤	grep "2026-03-26 14:" logs/*.log	过滤指定时间段
查看用户日志	grep "userId=1" logs/*.log	查看指定用户的所有请求
查看接口日志	grep "/api/v1/admin/users" logs/*.log	查看指定接口的请求