批量上传游离文件问题诊断与修复

背景

我这边用的时候发现批量上传文件时会产生大量游离文件（orphan files）。游离文件是指：S3 中存在加密文件，但元数据索引中没有对应记录，导致文件在应用中”不可见”。

为了定位问题，我们设计并实现了完整的日志系统，最终成功定位到并发竞态条件并修复。

第一阶段：日志系统设计与实现

1.1 后端日志文件管理

设计目标：

每次内核启动创建独立日志文件，便于追溯
文件名包含精确到秒的时间戳，易于识别
同时输出到控制台和文件，方便调试
前端可查看历史日志列表

实现方案：

// mobile.go - 日志初始化
func setupLogFile(logDir string) {
    // 创建 logs 目录
    logsDir := filepath.Join(logDir, "logs")
    os.MkdirAll(logsDir, 0755)
 
    // 生成时间戳文件名：core_2025-12-20_10-34-31.log
    timestamp := time.Now().Format("2006-01-02_15-04-05")
    logFilePath = filepath.Join(logsDir, fmt.Sprintf("core_%s.log", timestamp))
 
    // 创建日志文件
    logFile, _ = os.Create(logFilePath)
 
    // 同时输出到控制台和文件
    multiWriter := io.MultiWriter(os.Stdout, logFile)
    log.SetOutput(multiWriter)
    log.SetFlags(log.Ldate | log.Ltime | log.Lmicroseconds)
}

关键技术点：

使用 io.MultiWriter 实现双写（控制台 + 文件）
日志格式包含微秒级时间戳，便于分析并发问题
日志目录由前端传入（Android 应用数据目录）

1.2 日志 API 设计

三个 API 端点：

API	方法	功能
`/api/v1/logs`	GET	列出所有日志文件（按时间倒序）
`/api/v1/logs/:filename`	GET	读取指定日志文件内容
`/api/v1/logs`	DELETE	清空历史日志（保留当前）

Server 结构体扩展：

type Server struct {
    // ... 其他字段
    logFilePath string // 当前日志文件路径
    logsDir     string // 日志目录
}
 
func (s *Server) SetLogFilePath(path string) {
    s.logFilePath = path
    if path != "" {
        s.logsDir = filepath.Dir(path)
    }
}

1.3 前端日志查看页面

Flutter 实现：

_CoreLogsPage：显示日志文件列表，当前文件有”当前”标记
_LogContentPage：显示具体日志内容，支持刷新和复制
右上角清空按钮，确认后删除历史日志

1.4 Android 端集成

日志目录传递链路：

1
Flutter (app_state.dart)
2
    ↓ 获取 appDir = getApplicationDocumentsDirectory()
3
    ↓ 传入 config['logDir'] = appDir.path
4
Kotlin (MainActivity.kt)
5
    ↓ 接收 logDir 参数
6
    ↓ 调用 Mobile.startWithParamsAndLogDir(..., logDir)
7
Go (mobile.go)
8
    ↓ setupLogFile(cfg.LogDir)
9
    ↓ server.SetLogFilePath(logFilePath)

第二阶段：上传流程 Debug 打点

2.1 前端打点

// app_state.dart - _startUploadJob
debugPrint('[UPLOAD] _startUploadJob: ${job.fileName}, path: ${job.remotePath}');
debugPrint('[UPLOAD] calling api.uploadFile: $adjustedName');
debugPrint('[UPLOAD] api.uploadFile result: success=${result.isSuccess}, error=${result.error}');
 
// api_client.dart - uploadFile
debugPrint('[API] uploadFile: $fileName to $remotePath');
debugPrint('[API] sending POST /api/v1/files/upload');
debugPrint('[API] upload response: ${response.statusCode}');

2.2 后端打点

// server.go - uploadFile
log.Printf("[UPLOAD] uploadFile called")
log.Printf("[UPLOAD] received file: %s, size: %d", header.Filename, header.Size)
log.Printf("[UPLOAD] path: %s", path)
log.Printf("[UPLOAD] generated fileID: %s", fileID)
log.Printf("[UPLOAD] starting encryption...")
log.Printf("[UPLOAD] encryption done, encrypted size: %d", encryptedBuf.Len())
log.Printf("[UPLOAD] uploading to S3...")
log.Printf("[UPLOAD] S3 upload done: %s", s3Key)
log.Printf("[UPLOAD] updating metadata index...")
log.Printf("[UPLOAD] upload complete: %s -> %s", header.Filename, fileID)

第三阶段：问题定位

3.1 日志分析

批量上传 15 个文件后，日志显示如下模式：

1
10:34:53.879699 [UPLOAD] uploadFile called
2
10:34:53.882455 [UPLOAD] uploadFile called
3
10:34:53.941421 [UPLOAD] uploadFile called
4
10:34:53.953698 [UPLOAD] received file: log_list-17.sig, size: 684
5
...
6
10:34:54.128270 [UPLOAD] updating metadata index...
7
10:34:54.183614 [UPLOAD] updating metadata index...
8
10:34:54.246703 [UPLOAD] updating metadata index...

关键发现：多个请求几乎同时到达 updating metadata index...

3.2 问题根因：并发竞态条件

updateMetadataIndex 的原始实现：

func (s *Server) updateMetadataIndex(ctx context.Context, file *FileMetadata) error {
    meta, err := s.loadMetadataIndex(ctx)  // 1. 读取
    if err != nil {
        return err
    }
    meta.Files[file.ID] = file              // 2. 修改
    return s.saveMetadataIndex(ctx, meta)   // 3. 保存
}

竞态场景：

1
时间线    请求A                    请求B
2
─────────────────────────────────────────────────
3
T1       读取元数据 (10个文件)
4
T2                                读取元数据 (10个文件)
5
T3       添加文件11
6
T4       保存 (11个文件)
7
T5                                添加文件12
8
T6                                保存 (11个文件，覆盖了A的结果！)
9
─────────────────────────────────────────────────
10
结果：文件11 丢失，变成游离文件

每次元数据更新约 100-200ms，在高并发场景下，多个请求的读-写周期会重叠，导致后写入的请求覆盖先写入的结果。

第四阶段：问题修复

4.1 解决方案：互斥锁

在 Server 结构体中添加元数据操作专用锁：

type Server struct {
    // ... 其他字段
    metaMu sync.Mutex // 元数据索引互斥锁
}
 
func (s *Server) updateMetadataIndex(ctx context.Context, file *FileMetadata) error {
    s.metaMu.Lock()
    defer s.metaMu.Unlock()
 
    log.Printf("[META] updateMetadataIndex: %s (%s)", file.Name, file.ID)
 
    meta, err := s.loadMetadataIndex(ctx)
    if err != nil {
        log.Printf("[META] loadMetadataIndex failed: %v", err)
        return err
    }
 
    if meta.Files == nil {
        meta.Files = make(map[string]*FileMetadata)
    }
    meta.Files[file.ID] = file
 
    log.Printf("[META] saving metadata with %d files", len(meta.Files))
    err = s.saveMetadataIndex(ctx, meta)
    if err != nil {
        log.Printf("[META] saveMetadataIndex failed: %v", err)
    }
    return err
}

4.2 修复后的行为

1
时间线    请求A                    请求B
2
─────────────────────────────────────────────────
3
T1       获取锁 ✓
4
T2       读取元数据 (10个文件)     等待锁...
5
T3       添加文件11               等待锁...
6
T4       保存 (11个文件)          等待锁...
7
T5       释放锁                   获取锁 ✓
8
T6                                读取元数据 (11个文件)
9
T7                                添加文件12
10
T8                                保存 (12个文件)
11
─────────────────────────────────────────────────
12
结果：两个文件都正确保存

4.3 性能影响

元数据更新从并行变为串行
每次更新约 100-200ms
100 个文件额外增加 10-20 秒总时间
但保证了数据正确性，避免游离文件产生

后续优化方向（如需）：

批量合并写入：收集多个更新请求后一次性写入
乐观锁：读取时记录版本，写入时检查版本，冲突重试
增量更新：只写入变更部分而非整个索引

总结

阶段	工作内容
日志系统	后端日志文件管理 + 日志查看 API + 前端日志页面
Debug 打点	前后端上传流程关键节点打印
问题定位	通过时间戳分析发现并发更新元数据
根因分析	读-修改-写操作无原子性保证
修复方案	`sync.Mutex` 互斥锁保护元数据操作

经验教训：

涉及共享状态的并发操作必须考虑同步机制
详细的日志打印是定位并发问题的关键
微秒级时间戳能清晰展示请求的时序关系