fs-lawrisk/CHECKPOINT_LOGGING_GUIDE.md

300 lines
9.8 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

# 检查点操作详细日志指南
## 📋 概述
已为检查点功能添加详细的日志输出,让你能够实时查看每张表的数据变化和操作进度。
---
## 🔍 日志特点
### 日志级别
- **INFO** - 正常操作信息
- **WARNING** - 重要警告(恢复操作)
- **ERROR** - 错误信息
### 日志格式
```
2025-10-30 14:30:15 [INFO] lawrisk.services.licensing_repo: [CHECKPOINT] Starting checkpoint creation: checkpoint_20251030_143015
```
### 关键标识
- `[CHECKPOINT]` - 检查点相关操作
- `[API]` - API 请求信息
- `[1/8]` - 表恢复进度 (当前表/总表数)
---
## 📊 创建 Checkpoint 日志示例
```
================================================================================
[CHECKPOINT] Starting checkpoint creation: checkpoint_20251030_143015
[CHECKPOINT] Description: 测试备份
================================================================================
[CHECKPOINT] Found 8 tables to backup: regions, themes, business_scopes, permits, risks, region_themes, region_scopes, region_theme_permits
[CHECKPOINT] [1/8] Processing table: regions
[CHECKPOINT] Backing up table: regions
[CHECKPOINT] Backup complete: regions - 5 rows, 3 columns
[CHECKPOINT] [1/8] Table regions backed up: 5 rows
[CHECKPOINT] [2/8] Processing table: themes
[CHECKPOINT] Backing up table: themes
[CHECKPOINT] Backup complete: themes - 12 rows, 3 columns
[CHECKPOINT] [2/8] Table themes backed up: 12 rows
...
[CHECKPOINT] All tables backed up successfully, committing transaction...
[CHECKPOINT] Transaction committed
[CHECKPOINT] Saving checkpoint file: data/checkpoints/checkpoint_20251030_143015.json
================================================================================
[CHECKPOINT] Checkpoint creation COMPLETED: checkpoint_20251030_143015
[CHECKPOINT] Total rows backed up: 1247
[CHECKPOINT] File: data/checkpoints/checkpoint_20251030_143015.json
================================================================================
```
---
## 📈 恢复 Checkpoint 日志示例
```
================================================================================
[API] Received checkpoint restore request: checkpoint_20251030_143015
[API] Request parameters: {'create_auto_backup': 'true'}
[API] Auto-backup enabled: True
[API] Starting restore operation...
================================================================================
[CHECKPOINT] WARNING: Starting restore operation: checkpoint_20251030_143015
[CHECKPOINT] This will OVERWRITE all existing data in the database!
================================================================================
[CHECKPOINT] Creating auto-backup before restore...
================================================================================
[CHECKPOINT] Starting checkpoint creation: auto_backup_before_restore_checkpoint_20251030_143015
...
[CHECKPOINT] Auto-backup created: auto_backup_before_restore_checkpoint_20251030_143015
[CHECKPOINT] Auto-backup contains 1247 rows
================================================================================
[CHECKPOINT] Checkpoint details:
[CHECKPOINT] ID: checkpoint_20251030_143015
[CHECKPOINT] Tables: 8
[CHECKPOINT] Total rows: 1247
[CHECKPOINT] Auto-backup: Yes (auto_backup_before_restore_checkpoint_20251030_143015)
================================================================================
[CHECKPOINT] Building table dependency graph...
[CHECKPOINT] Found 6 table dependencies
[CHECKPOINT] Calculating restore order...
[CHECKPOINT] Restore order: risks -> permits -> business_scopes -> themes -> regions -> region_themes -> region_scopes -> region_theme_permits
[CHECKPOINT] Acquiring exclusive locks on all tables...
[CHECKPOINT] All tables locked exclusively
================================================================================
[CHECKPOINT] Starting restore process...
================================================================================
[CHECKPOINT] [1/8] Preparing to restore table: risks
[CHECKPOINT] Truncating table: risks
[CHECKPOINT] Restoring 100 rows into risks (columns: id, risk_content, legal_basis, document_no, summary)
[CHECKPOINT] Progress: risks - 100/100 rows inserted
[CHECKPOINT] Restore complete: risks - 100 rows successfully inserted
[CHECKPOINT] [1/8] Table risks restored: 100 rows
[CHECKPOINT] [2/8] Preparing to restore table: permits
[CHECKPOINT] Truncating table: permits
[CHECKPOINT] Restoring 50 rows into permits (columns: id, name)
[CHECKPOINT] Progress: permits - 50/50 rows inserted
[CHECKPOINT] Restore complete: permits - 50 rows successfully inserted
[CHECKPOINT] [2/8] Table permits restored: 50 rows
...
[CHECKPOINT] [8/8] Preparing to restore table: region_theme_permits
[CHECKPOINT] Truncating table: region_theme_permits
[CHECKPOINT] Restoring 800 rows into region_theme_permits (columns: region_id, theme_id, permit_id)
[CHECKPOINT] Progress: region_theme_permits - 100/800 rows inserted
[CHECKPOINT] Progress: region_theme_permits - 200/800 rows inserted
[CHECKPOINT] Progress: region_theme_permits - 300/800 rows inserted
...
[CHECKPOINT] Progress: region_theme_permits - 800/800 rows inserted
[CHECKPOINT] Restore complete: region_theme_permits - 800 rows successfully inserted
[CHECKPOINT] [8/8] Table region_theme_permits restored: 800 rows
================================================================================
[CHECKPOINT] All tables restored successfully, committing transaction...
[CHECKPOINT] Transaction committed successfully
================================================================================
================================================================================
[CHECKPOINT] RESTORE COMPLETED SUCCESSFULLY: checkpoint_20251030_143015
[CHECKPOINT] Tables restored: 8/8
[CHECKPOINT] Total rows restored: 1247
[CHECKPOINT] Auto-backup available: auto_backup_before_restore_checkpoint_20251030_143015
================================================================================
[API] Restore completed successfully
[API] Tables restored: 8
[API] Total rows restored: 1247
```
---
## 🚀 如何查看日志
### 方法1: 查看控制台输出
启动应用时,所有日志会直接输出到控制台:
```bash
python app.py
```
### 方法2: 查看日志文件
如果将日志重定向到文件:
```bash
python app.py > checkpoint.log 2>&1
tail -f checkpoint.log
```
### 方法3: 实时监控日志
```bash
# Linux/Mac
tail -f /path/to/app.log | grep -E "(CHECKPOINT|API)"
# Windows (PowerShell)
Get-Content app.log -Wait | Where-Object { $_ -match "(CHECKPOINT|API)" }
```
---
## 📝 日志信息说明
### 创建 Checkpoint 时
| 日志内容 | 含义 |
|---------|------|
| `[CHECKPOINT] Starting checkpoint creation` | 开始创建检查点 |
| `[CHECKPOINT] Found X tables` | 找到X个表 |
| `[CHECKPOINT] [i/N] Processing table` | 正在处理第i个表共N个表 |
| `[CHECKPOINT] Backup complete: table_name - X rows` | 表备份完成X行数据 |
| `[CHECKPOINT] Transaction committed` | 事务提交成功 |
| `[CHECKPOINT] Checkpoint creation COMPLETED` | 检查点创建完成 |
### 恢复 Checkpoint 时
| 日志内容 | 含义 |
|---------|------|
| `[CHECKPOINT] WARNING: Starting restore` | 开始恢复操作警告 |
| `[CHECKPOINT] Creating auto-backup` | 创建自动备份 |
| `[CHECKPOINT] Auto-backup created` | 自动备份创建完成 |
| `[CHECKPOINT] Building table dependency graph` | 构建表依赖关系 |
| `[CHECKPOINT] Calculating restore order` | 计算恢复顺序 |
| `[CHECKPOINT] Restore order: ...` | 显示恢复顺序 |
| `[CHECKPOINT] Acquiring exclusive locks` | 获取表级锁 |
| `[CHECKPOINT] [i/N] Preparing to restore table` | 准备恢复第i个表 |
| `[CHECKPOINT] Truncating table` | 清空表数据 |
| `[CHECKPOINT] Restoring X rows into table` | 开始恢复X行数据 |
| `[CHECKPOINT] Progress: table - Y/Z rows inserted` | 恢复进度已插入Y行共Z行 |
| `[CHECKPOINT] Restore complete: table - X rows` | 表恢复完成共X行 |
| `[CHECKPOINT] Table table_name restored: X rows` | 表恢复统计信息 |
| `[CHECKPOINT] RESTORE COMPLETED SUCCESSFULLY` | 恢复操作成功完成 |
### 错误日志
| 日志内容 | 含义 |
|---------|------|
| `[CHECKPOINT] ERROR: ...` | 发生错误 |
| `[CHECKPOINT] Restore FAILED` | 恢复失败 |
| `[CHECKPOINT] Transaction rolled back` | 事务已回滚 |
| `[CHECKPOINT] Recovery suggestion:` | 恢复建议(使用自动备份) |
---
## 🔧 故障排除
### 问题1: 日志看不到输出
**原因**: 日志被缓冲或重定向
**解决方案**:
1. 确保使用了 `-u` 参数运行Python禁用缓冲
```bash
python -u app.py
```
2. 或者设置环境变量
```bash
export PYTHONUNBUFFERED=1
python app.py
```
### 问题2: 日志信息不完整
**原因**: 日志级别设置过高
**解决方案**:
确保日志级别设置为INFO或DEBUG
```python
import logging
logging.getLogger().setLevel(logging.INFO)
```
### 问题3: 恢复操作卡住
**原因**: 可能正在处理大表,或者等待锁
**解决方案**:
1. 查看日志中的进度信息
2. 等待表锁释放
3. 检查是否有其他会话占用表锁
---
## 📊 性能监控
通过日志可以监控:
1. **备份/恢复速度**
```
每行数据处理时间 = 总时间 / 行数
```
2. **表大小分布**
```
查看每个表的行数
```
3. **依赖关系正确性**
```
验证恢复顺序是否正确
```
4. **事务效率**
```
开始时间 -> 提交时间 = 事务持续时间
```
---
## ⚡ 快速查看命令
### 查看最新日志
```bash
tail -100 checkpoint.log | grep "CHECKPOINT"
```
### 统计处理的行数
```bash
grep "rows inserted" checkpoint.log | awk '{print $6}'
```
### 查看错误信息
```bash
grep -i "error\|failed" checkpoint.log
```
### 监控实时进度
```bash
tail -f checkpoint.log | grep "Progress:"
```
---
**注意**: 所有日志都会立即输出到控制台,无需等待操作完成即可查看进度。