Files
YG_FT/日志使用指南.md

531 lines
18 KiB
Markdown
Raw Normal View History

2026-08-21 09:42:03 +08:00
# 远光智炼 — 日志使用指南
> 版本v2.0 | 适用范围:后端开发 & 运维 & 测试 & 业务排查
---
## 一、日志系统总览
本平台的日志系统由三个核心组件构成,所有日志均输出为 **JSON 结构化格式**,按用途分流到不同文件。
**所有日志的 `message` 字段均为中文**,直接可读,无需解析 JSON 字段即可知道"谁干了什么"。
```
backend/app/core/
├── logging.py ← 日志基础设施(格式化、脱敏、滚动、中间件)
└── op_log.py ← 操作日志(@op_log 装饰器 + log_operation 函数)
```
### 1.1 日志文件分流
日志文件存放在 `backend/logs/` 目录,按日期命名,按大小滚动:
| 文件名格式 | 用途 | 记录内容 | 保留周期 |
|-----------|------|---------|---------|
| `app-biz-YYYY-MM-DD.log` | **业务日志** | 用户操作(登录、删除、创建、停止等) | 7 天 |
| `app-access-YYYY-MM-DD.log` | **访问日志** | 所有 HTTP 请求的方法、路径、状态码、耗时 | 15 天 |
| `app-error-YYYY-MM-DD.log` | **错误日志** | 仅 ERROR 级别,含完整堆栈 | 30 天 |
> 每个文件超过配置的 `max_bytes`(默认 100MB时自动滚动为 `.1`、`.2` 后缀文件。
### 1.2 日志数据流
```
用户请求
FastAPI 中间件 (logging.py: request_logging_middleware)
│── 生成 traceIdUUID
│── 写入 app-access中文 messageHTTP请求 DELETE /路径 → 200耗时xxms
路由处理函数
│── @op_log 装饰器自动记录操作
│ ├── 写入 app-biz中文 message用户[admin] 删除模型推理「cmp_xxx」结果成功
│ └── 写入 operation_logs 表(数据库审计)
│── 手动调用 biz_logger.info()
│ └── 写入 app-biz中文 message用户创建数据处理任务成功
└── 异常时
├── 写入 app-error中文 message + 完整堆栈)
└── 写入 app-biz中文 message用户[xxx] 删除xxx结果失败PoolTimeout: xxx
```
---
## 二、日志格式说明
### 2.1 业务日志app-biz— 中文 message 示例
每条业务日志的 `message` 字段直接用中文描述"谁干了什么",一眼就能看懂:
```json
{
"@timestamp": "2026-08-20T08:38:45.516+08:00",
"level": "INFO",
"logger": "app.biz",
"traceId": "31a4773a-e2ac-4ec7-8dd7-0e2431ec982e",
"message": "用户[admin] 删除模型推理「cmp_74e0d2f34b43」结果成功",
"clientIp": "127.0.0.1",
"fields": {
"action": "delete",
"bizModule": "model-inference",
"durationMs": 6799.44,
"opStatus": "success",
"targetId": "cmp_74e0d2f34b43",
"targetName": "cmp_74e0d2f34b43",
"targetType": "inference",
"username": "admin",
"requestMethod": "DELETE",
"requestPath": "/modelTF/model-inference/cmp_74e0d2f34b43"
}
}
```
**怎么读**:直接看 `message` 字段 → `用户[admin] 删除模型推理「cmp_74e0d2f34b43」结果成功`
失败时的 message 示例:
```json
"message": "用户[admin] 删除模型训练「ft_001」结果失败PoolTimeout: database connection timeout"
```
### 2.2 访问日志app-access— 中文 message 示例
```json
{
"@timestamp": "2026-08-20T08:38:45.657+08:00",
"level": "INFO",
"logger": "app.access",
"traceId": "31a4773a-e2ac-4ec7-8dd7-0e2431ec982e",
"message": "HTTP请求 DELETE /modelTF/model-inference/cmp_74e0d2f34b43 → 200耗时175.06ms",
"clientIp": "127.0.0.1",
"fields": {
"request_method": "DELETE",
"request_path": "/modelTF/model-inference/cmp_74e0d2f34b43",
"status_code": 200,
"duration_ms": 175.06,
"client_ip": "127.0.0.1"
}
}
```
**怎么读**:直接看 `message``HTTP请求 DELETE /modelTF/model-inference/cmp_74e0d2f34b43 → 200耗时175.06ms`
### 2.3 错误日志app-error— 中文 message 示例
```json
{
"@timestamp": "2026-08-20T08:59:27.017+08:00",
"level": "ERROR",
"logger": "app.workers.compute_poller",
"traceId": "-",
"message": "计算轮询执行失败",
"error": {
"type": "PoolTimeout",
"message": "计算轮询执行失败",
"stack_trace": "Traceback (most recent call last):\n File \"compute_poller.py\", line 23 ..."
}
}
```
**怎么读**`message``计算轮询执行失败`,再看 `error.type``error.stack_trace` 确认具体原因。
### 2.4 message 格式速查
| 日志类型 | message 格式 | 示例 |
|---------|-------------|------|
| 业务操作成功 | `用户[xxx] 动词+模块+对象,结果:成功` | `用户[admin] 删除模型推理「cmp_001」结果成功` |
| 业务操作失败 | `用户[xxx] 动词+模块+对象,结果:失败(异常类型: 异常消息)` | `用户[admin] 删除模型训练「ft_001」结果失败PoolTimeout: 超时)` |
| 系统操作 | `系统 动词+模块+对象,结果:成功` | `系统 退出登录用户,结果:成功` |
| HTTP 请求 | `HTTP请求 方法 路径 → 状态码耗时xxms` | `HTTP请求 DELETE /modelTF/xxx → 200耗时175ms` |
| HTTP 异常 | `HTTP请求异常 方法 路径耗时xxms— 服务内部错误` | `HTTP请求异常 POST /modelTF/xxx耗时5000ms— 服务内部错误` |
| 后台任务 | 中文描述 | `计算轮询执行失败``数据处理预览完成` |
---
## 三、如何看日志
### 3.1 快速查看某天的操作
```bash
# 查看今天用户做了哪些操作(直接看 message 字段)
cat backend/logs/app-biz-2026-08-20.log | python -m json.tool
# 在 PowerShell 中格式化查看
Get-Content backend/logs/app-biz-2026-08-20.log | ForEach-Object { ($_ | ConvertFrom-Json).message }
```
输出效果(只看 message
```
用户[admin] 删除模型推理「cmp_74e0d2f34b43」结果成功
用户[admin] 删除模型管理「tm_aaaa8e5ad5d7」结果成功
用户创建数据处理任务成功
用户停止数据处理任务成功
用户发布数据处理任务成功
```
### 3.2 按用户筛选
```bash
# Linux/Mac
grep '"username":"admin"' backend/logs/app-biz-2026-08-20.log
# PowerShell
Select-String -Path backend/logs/app-biz-2026-08-20.log -Pattern '"username":"admin"'
```
### 3.3 按操作类型筛选
```bash
# 查看所有删除操作
grep '"action":"delete"' backend/logs/app-biz-2026-08-20.log
# 查看所有失败的操作
grep '"opStatus":"failure"' backend/logs/app-biz-2026-08-20.log
# 用中文关键词搜索(直接搜 message 中的中文)
grep '删除' backend/logs/app-biz-2026-08-20.log
grep '失败' backend/logs/app-biz-2026-08-20.log
grep '登录' backend/logs/app-biz-2026-08-20.log
```
### 3.4 按链路追踪traceId排查
```bash
# 拿到一个 traceId 后,搜索所有相关日志
grep '31a4773a-e2ac-4ec7-8dd7-0e2431ec982e' backend/logs/app-*.log
```
这会同时匹配 `app-biz``app-access``app-error` 三个文件,让你看到该请求的完整链路:
- `app-biz`:用户做了什么操作
- `app-access`HTTP 请求的方法、路径、状态码
- `app-error`:有没有触发错误
### 3.5 查看错误
```bash
# 当天的所有错误
cat backend/logs/app-error-2026-08-20.log | python -m json.tool
# 只看错误类型
Get-Content backend/logs/app-error-2026-08-20.log | ForEach-Object { ($_ | ConvertFrom-Json).error.type }
```
---
## 四、开发指南:如何写日志
### 4.1 使用 `@op_log` 装饰器(推荐)
对于所有写操作(创建、删除、启动、停止等),在路由函数上加 `@op_log` 装饰器,自动记录操作日志:
```python
from app.core.op_log import op_log, OpModule, OpAction
@router.delete("/model-eval/{eval_id}")
@op_log(module=OpModule.MODEL_EVAL, action=OpAction.DELETE, target_type="eval")
async def delete_eval(eval_id: str, current_user: dict, request: Request):
# 你的业务逻辑
store.delete_eval(eval_id)
return {"message": "删除成功"}
```
装饰器会自动生成中文 message例如
> `用户[admin] 删除模型评测「eval_001」结果成功`
同时自动:
- 捕获成功/失败状态
- 记录操作耗时(`durationMs`
- 记录请求方法和路径(`requestMethod``requestPath`
- 失败时记录完整异常堆栈
- 同时写入 `app-biz` 文件日志 + `operation_logs` 数据库表
### 4.2 手动调用 `biz_logger`
对于不方便用装饰器的场景(如多步骤操作、流程中间节点),使用 `StructuredLogger`
```python
from app.core.logging import get_structured_logger
biz_logger = get_structured_logger("app.biz.data_process")
# 记录成功message 直接用中文)
biz_logger.info("用户创建数据处理任务成功", taskId="dpt_001", processType="unstructured")
# 记录失败
biz_logger.error("用户发布数据处理任务失败", taskId="dpt_001", errorType="ConnectionError")
```
### 4.3 模块和动作中文映射表
`@op_log` 装饰器会自动将模块和动作翻译为中文,无需手动处理:
| 英文(代码常量) | 中文(日志显示) |
|-----------------|----------------|
| `fine-tune` | 模型训练 |
| `model-eval` | 模型评测 |
| `model-inference` | 模型推理 |
| `model-manage` | 模型管理 |
| `dataset` | 数据集 |
| `data-process` | 数据处理 |
| `data-convert` | 数据转换 |
| `compute` | 算力节点 |
| `system` | 系统 |
| 动作(英文) | 动作(中文) |
|-------------|-------------|
| `create` | 创建 |
| `update` | 更新 |
| `delete` | 删除 |
| `start` | 启动 |
| `stop` | 停止 |
| `upload` | 上传 |
| `download` | 下载 |
| `login` | 登录 |
| `logout` | 退出登录 |
| `publish` | 发布 |
| `retry` | 重试 |
---
## 五、错误排查实战示例
### 场景一:用户反馈"删除模型评测任务后列表仍显示该记录"
#### 第一步:确认操作是否被记录
用户说在 8 月 20 日 08:38 左右执行了删除操作。先查业务日志:
```bash
# 方法 1用中文关键词搜最傻瓜
grep '删除' backend/logs/app-biz-2026-08-20.log
# 方法 2用英文字段搜更精确
grep '"action":"delete"' backend/logs/app-biz-2026-08-20.log | grep 'model-eval'
```
找到记录,直接看 `message` 字段:
```json
{
"@timestamp": "2026-08-20T08:38:45.516+08:00",
"level": "INFO",
"logger": "app.biz",
"traceId": "31a4773a-e2ac-4ec7-8dd7-0e2431ec982e",
"message": "用户[admin] 删除模型推理「cmp_74e0d2f34b43」结果成功",
"fields": {
"action": "delete",
"bizModule": "model-inference",
"opStatus": "success",
"targetId": "cmp_74e0d2f34b43",
"username": "admin",
"durationMs": 6799.44,
"requestMethod": "DELETE",
"requestPath": "/modelTF/model-inference/cmp_74e0d2f34b43"
}
}
```
**一眼就能读明白**`用户[admin]``08:38:45` 删除了模型推理 `cmp_74e0d2f34b43`,操作成功,耗时 6.8 秒。
#### 第二步:用 traceId 追踪完整请求链路
拿到 `traceId` 后,搜索所有日志文件:
```bash
grep '31a4773a-e2ac-4ec7-8dd7-0e2431ec982e' backend/logs/app-*.log
```
会看到两条日志,`message` 直接告诉你发生了什么:
1. **app-biz**`用户[admin] 删除模型推理「cmp_74e0d2f34b43」结果成功`
2. **app-access**`HTTP请求 DELETE /modelTF/model-inference/cmp_74e0d2f34b43 → 200耗时175.06ms`
#### 第三步:确认是否有错误
```bash
grep '31a4773a-e2ac-4ec7-8dd7-0e2431ec982e' backend/logs/app-error-2026-08-20.log
```
没有匹配 → 没有错误。
#### 排查结论
| 日志文件 | message | 结论 |
|---------|---------|------|
| `app-biz` | `用户[admin] 删除模型推理「cmp_xxx」结果成功` | 后端删除成功 |
| `app-access` | `HTTP请求 DELETE /modelTF/... → 200` | 接口正常返回 |
| `app-error` | 无 | 没有异常 |
**结论**:删除操作本身没问题,问题出在查询逻辑(列表接口未过滤软删除记录)。
---
### 场景二:数据库连接超时导致后台轮询失败
用户反馈"训练任务状态一直不更新"。
#### 第一步:查看错误日志
```bash
cat backend/logs/app-error-2026-08-19.log
```
直接看 `message`
```json
{
"@timestamp": "2026-08-19T11:19:10.341+08:00",
"level": "ERROR",
"logger": "app.workers.compute_poller",
"traceId": "-",
"message": "计算轮询执行失败",
"error": {
"type": "PoolTimeout",
"stack_trace": "...\npsycopg_pool.PoolTimeout: couldn't get a connection after 30.00 sec"
}
}
```
**一眼读明白**`计算轮询执行失败`,错误类型是 `PoolTimeout`(数据库连接池超时)。
#### 第二步:确认频率
```bash
grep '计算轮询执行失败' backend/logs/app-error-2026-08-19.log | wc -l
```
从 11:19 到 13:49每 33 秒一条,共 30+ 条 → 数据库不可用持续约 2.5 小时。
#### 排查结论
| 问题 | 原因 | 解决方案 |
|------|------|---------|
| 训练任务状态不更新 | 数据库连接池超时PoolTimeout后台轮询无法查询任务状态 | 检查 PostgreSQL 服务是否存活;增大连接池配置;检查网络连通性 |
---
### 场景三:数据处理预览失败(网络超时)
用户反馈"点击数据处理预览后一直转圈"。
#### 第一步:查看错误日志
```bash
grep '数据处理' backend/logs/app-error-2026-08-20.log
```
```json
{
"@timestamp": "2026-08-20T08:59:27.017+08:00",
"level": "ERROR",
"logger": "app.api.v1.endpoints.data_process",
"traceId": "7e00377f-12ed-4130-bd40-8bbd0bc4992b",
"message": "数据处理预览失败 task_id=dpt_54045fd0ec744cc4ab8c preview_run_id=dpprun_8453fe1f349e4913809e duration_ms=45254.31",
"error": {
"type": "LocalEntryNotFoundError",
"stack_trace": "...httpx.ConnectTimeout: [WinError 10060] 由于连接方在一段时间后没有正确答复..."
}
}
```
**一眼读明白**`数据处理预览失败`task_id 是 `dpt_54045fd0ec744cc4ab8c`,耗时 45 秒,错误类型是 `LocalEntryNotFoundError`,根因是网络超时(`WinError 10060`)。
#### 第二步:用 traceId 看请求链路
```bash
grep '7e00377f-12ed-4130-bd40-8bbd0bc4992b' backend/logs/app-access-2026-08-20.log
```
```json
{
"message": "HTTP请求 POST /modelTF/data-process/dpt_54045fd0ec744cc4ab8c/preview/start → 500耗时45255ms",
"fields": {
"request_method": "POST",
"request_path": "/modelTF/data-process/dpt_54045fd0ec744cc4ab8c/preview/start",
"status_code": 500
}
}
```
**一眼读明白**`POST 请求返回了 500`,耗时 45 秒(网络超时导致)。
#### 排查结论
| 问题 | 原因 | 解决方案 |
|------|------|---------|
| 数据处理预览一直转圈 | docling 需要从 HuggingFace 下载模型,网络连接超时 | 检查网络连通性;配置 HuggingFace 镜像源;或预下载模型到本地缓存 |
---
## 六、日志文件位置速查
```
backend/logs/
├── app-biz-2026-08-20.log ← 今天的业务操作日志(用户干了啥)
├── app-biz-2026-08-20.log.1 ← 滚动后的旧业务日志
├── app-access-2026-08-20.log ← 今天的访问日志HTTP 请求记录)
├── app-error-2026-08-20.log ← 今天的错误日志ERROR + 堆栈)
├── backend-2026-08-20.log ← 兼容旧格式(全部日志)
└── error-2026-08-19.log ← 兼容旧错误日志
```
> **提示**:日期会自动变化,文件名中的日期就是当天。超过保留周期的旧文件会被自动清理。
---
## 七、快速排查口诀
```
1. 先看 app-biz —— 谁干了什么,成功还是失败(直接看 message
2. 再看 app-access —— 请求了什么路径,返回什么状态码
3. 有错误看 app-error —— 什么异常,堆栈在哪一行
4. 用 traceId 串联三个文件 —— 一个请求的完整链路
```
**中文关键词速查**
| 想查什么 | 搜什么关键词 |
|---------|------------|
| 删除操作 | `删除` |
| 创建操作 | `创建` |
| 登录/退出 | `登录``退出登录` |
| 失败的操作 | `结果:失败` |
| HTTP 请求 | `HTTP请求` |
| HTTP 异常 | `HTTP请求异常` |
| 计算轮询 | `计算轮询` |
| 数据处理 | `数据处理` |
---
## 八、开发检查清单
新增接口或修改业务逻辑时,请对照此清单:
- [ ] 所有写操作create/delete/start/stop/update是否加了 `@op_log` 装饰器?
- [ ] 手动 `biz_logger` 的 message 是否用了中文描述?
- [ ] 多步骤流程是否用 `biz_logger.info()` 记录了关键中间节点?
- [ ] 异常分支是否用 `logger.exception()` 记录了失败原因?
- [ ] 日志中是否包含了足够的业务上下文(`taskId``datasetId` 等)?
- [ ] 是否避免了在日志中打印密码、token 等敏感信息?(系统已自动脱敏,但仍需注意)
- [ ] 是否避免了在 for/while 循环内打印 INFO 级别日志?
---
## 九、核心源码位置
| 功能 | 文件位置 | 关键类/函数 |
|------|---------|------------|
| 日志配置入口 | `backend/app/core/logging.py` | `configure_logging()` |
| JSON 格式化 | `backend/app/core/logging.py` | `JsonLogFormatter` |
| 链路追踪 | `backend/app/core/logging.py` | `TraceIdFilter``request_id_var` |
| 敏感数据脱敏 | `backend/app/core/logging.py` | `mask_sensitive_dict()``mask_value()` |
| 大对象截断 | `backend/app/core/logging.py` | `truncate_large_value()` |
| 文件滚动 | `backend/app/core/logging.py` | `DateSizeRotatingFileHandler` |
| 请求日志中间件 | `backend/app/core/logging.py` | `setup_request_logging()` |
| 结构化日志器 | `backend/app/core/logging.py` | `StructuredLogger``get_structured_logger()` |
| 操作日志装饰器 | `backend/app/core/op_log.py` | `@op_log``log_operation()` |
| 操作日志常量 | `backend/app/core/op_log.py` | `OpModule``OpAction``OpStatus` |
| 中文 message 生成 | `backend/app/core/op_log.py` | `_build_cn_message()``MODULE_CN``ACTION_CN``TARGET_TYPE_CN` |