让 ffmpeg 的报错能进日志，并堵住三处会直接毁掉整块渲染的坑

背景：线上第 153/648 块失败，三个编码器依次报同一个 "exit status 0xffffffea" （EINVAL）。可用的线索只有这一句 —— 因为 ffmpeg 自己的输出走的是 os.Stderr，服务模式下没人看，等于丢掉了。所以这轮先解决"看不到原因"，再顺手补几处防御。一、把 ffmpeg 的报错留在日志里 runFFmpegWith 给 stderr 挂一个只保留最后 40 行的 writer（进度行用 \r 刷新，一并按行处理），失败时把这段附在错误上再由上层 lPrintErrf 写进日志。顺带过滤掉每次启动都打印的版本/编译配置那几行（configuration 一行就一千多字符，留着会把真正的报错挤出去）。实测效果：报错里直接能看到 "moov atom not found" / "Error opening input: Invalid data found"。二、跟编码器无关的失败不再挨个回退滤镜图建不起来、输入文件打不开这类问题，换个编码器结果一模一样。原来会把同一件事重跑三遍（hevc_qsv → h264_qsv → libx264），既浪费时间又在日志里刷三行看不出区别的错误。现在命中这些关键词就直接报出完整错误。三、头像 split 的份数必须和真正用到的份数一致统计头像用量时按整块弹幕算，生成 overlay 时才做可见性裁剪：同一 uid 在本块有多条、其中一条整条落在块外的话，split 会多出一个没人接收的输出 pad， ffmpeg 直接 EINVAL 退出（报错完全看不出跟弹幕有关）。抽出 danmuVisibleInChunk 让统计、生成 overlay、写块字幕三处用同一个判断。四、缓存命中要校验文件完整，下载改成原子写原来只看"文件在不在"，被写一半的 PNG 会被当成可用缓存塞给 ffmpeg 当输入。现在要求 PNG 以 IEND 收尾（16 字节以下直接判无效），下载先写 .part 再改名，旧位置搬过来的文件同样要过这道校验。五、头像直径至少为 1 有人把 danmuFontSize 填成 1、2 时 avatarSize 会算出 0，而 scale=0:0 会让 ffmpeg 直接 EINVAL、整块渲染失败。验证： - gofmt / go vet / go build 通过；go test 全绿（16.8s）；go test -race 全绿（22.8s）； staticcheck -checks=all 零告警 - 新增 diagnostics_test.go（10 个）与 split_pad_test.go（1 个）用例；反向验证扩到 21 项全过 - 隔离实例：e2e.py 37 项、smoke_extra.py 33 项、smoke_late_danmu.py（越界弹幕场景）全过；另用一个损坏的 mp4 实测，任务失败时日志里能看到 ffmpeg 的原话，且没有出现编码器回退
2026-09-26 12:15:14 +08:00
parent a2b7185a7b
commit 3eb4aa3102
4 changed files with 586 additions and 26 deletions
@@ -0,0 +1,309 @@
+package main
+
+import (
+	"bytes"
+	"errors"
+	"fmt"
+	"image"
+	"image/png"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"path/filepath"
+	"strings"
+	"sync/atomic"
+	"testing"
+)
+
+// ==================== ffmpeg 报错的可见性 ====================
+
+// 尾部 writer 只留最近若干行（ffmpeg 的进度行会不停刷）
+func TestTailWriterKeepsLastLines(t *testing.T) {
+	w := newTailWriter(3)
+	fmt.Fprint(w, "第1行\n第2行\n第3行\r第4行\n第5行\n")
+	got := w.String()
+	if !strings.Contains(got, "第5行") {
+		t.Fatalf("应当保留最后一行：%q", got)
+	}
+	if strings.Contains(got, "第1行") || strings.Contains(got, "第2行") {
+		t.Fatalf("超出保留行数的旧内容应当被丢掉：%q", got)
+	}
+	if lines := strings.Split(got, "\n"); len(lines) != 3 {
+		t.Fatalf("应当只留 3 行，实际 %d 行：%q", len(lines), got)
+	}
+}
+
+// 失败时要把 ffmpeg 自己的报错带上，不然只剩一句 exit status
+func TestFFmpegResultCarriesStderr(t *testing.T) {
+	err := ffmpegResult(errors.New("exit status 0xffffffea"), "Error binding filtergraph inputs/outputs")
+	if err == nil {
+		t.Fatal("应当返回错误")
+	}
+	msg := err.Error()
+	if !strings.Contains(msg, "exit status 0xffffffea") || !strings.Contains(msg, "Error binding filtergraph") {
+		t.Fatalf("错误里应当同时有退出状态和 ffmpeg 的说明，实际：%s", msg)
+	}
+
+	// 成功时不带任何东西
+	if got := ffmpegResult(nil, "随便什么输出"); got != nil {
+		t.Fatalf("成功时应当返回 nil，实际 %v", got)
+	}
+	// 没有 stderr 时保持原样
+	plain := errors.New("exit status 1")
+	if got := ffmpegResult(plain, "   "); got != plain {
+		t.Fatalf("没有 ffmpeg 输出时应当原样返回，实际 %v", got)
+	}
+}
+
+// 跟编码器无关的失败不该挨个回退重试
+func TestEncoderMightHelp(t *testing.T) {
+	unrelated := []string{
+		"Error binding filtergraph inputs/outputs: Invalid argument",
+		"Error initializing filtergraph",
+		"Error opening input: No such file or directory",
+	}
+	for _, msg := range unrelated {
+		if encoderMightHelp(errors.New(msg)) {
+			t.Fatalf("这类失败跟编码器无关，不该回退重试：%s", msg)
+		}
+	}
+	related := []string{
+		"Error initializing output stream 0:0 -- Error while opening encoder",
+		"hevc_qsv: Function not implemented",
+	}
+	for _, msg := range related {
+		if !encoderMightHelp(errors.New(msg)) {
+			t.Fatalf("编码器自身的失败应当允许回退：%s", msg)
+		}
+	}
+}
+
+// ==================== 头像缓存完整性 ====================
+
+func tinyPNG(t *testing.T) []byte {
+	t.Helper()
+	var buf bytes.Buffer
+	if err := png.Encode(&buf, image.NewRGBA(image.Rect(0, 0, 8, 8))); err != nil {
+		t.Fatal(err)
+	}
+	return buf.Bytes()
+}
+
+// 半截的 PNG 不能被当成可用缓存
+func TestValidCachedAvatar(t *testing.T) {
+	dir := t.TempDir()
+	good := tinyPNG(t)
+
+	full := filepath.Join(dir, "full.png")
+	if err := os.WriteFile(full, good, 0644); err != nil {
+		t.Fatal(err)
+	}
+	if !validCachedAvatar(full) {
+		t.Fatal("完整的 PNG 应当算有效")
+	}
+
+	// 砍掉尾巴（模拟下载中断）
+	cut := filepath.Join(dir, "cut.png")
+	if err := os.WriteFile(cut, good[:len(good)-8], 0644); err != nil {
+		t.Fatal(err)
+	}
+	if validCachedAvatar(cut) {
+		t.Fatal("半截 PNG 不该算有效")
+	}
+
+	empty := filepath.Join(dir, "empty.png")
+	if err := os.WriteFile(empty, nil, 0644); err != nil {
+		t.Fatal(err)
+	}
+	if validCachedAvatar(empty) {
+		t.Fatal("空文件不该算有效")
+	}
+	if validCachedAvatar(filepath.Join(dir, "不存在.png")) {
+		t.Fatal("不存在的文件不该算有效")
+	}
+}
+
+// 命中的是半截缓存时要重新下载，下载完必须是完整 PNG
+func TestEnsureAvatarRedownloadsBrokenCache(t *testing.T) {
+	withJobFlags(t, true, false, false)
+	dir := t.TempDir()
+
+	var hits int64
+	body := tinyPNG(t)
+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		atomic.AddInt64(&hits, 1)
+		w.Header().Set("Content-Type", "image/png")
+		_, _ = w.Write(body)
+	}))
+	defer srv.Close()
+
+	url := srv.URL + "/a.png"
+	path := filepath.Join(dir, avatarCacheName(42, url))
+	// 先摆一个「写了一半」的缓存
+	if err := os.WriteFile(path, body[:len(body)-8], 0644); err != nil {
+		t.Fatal(err)
+	}
+	if validCachedAvatar(path) {
+		t.Fatal("前置条件不成立：半截文件应当被判为无效")
+	}
+
+	got := ensureAvatar(42, url, dir)
+	if got != path {
+		t.Fatalf("应当返回缓存路径 %q，实际 %q", path, got)
+	}
+	if atomic.LoadInt64(&hits) == 0 {
+		t.Fatal("半截缓存应当触发重新下载")
+	}
+	if !validCachedAvatar(path) {
+		t.Fatal("重新下载之后应当是完整的 PNG")
+	}
+}
+
+// 完好的缓存不该再走网络
+func TestEnsureAvatarUsesGoodCache(t *testing.T) {
+	withJobFlags(t, true, false, false)
+	dir := t.TempDir()
+
+	var hits int64
+	body := tinyPNG(t)
+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		atomic.AddInt64(&hits, 1)
+		_, _ = w.Write(body)
+	}))
+	defer srv.Close()
+
+	url := srv.URL + "/b.png"
+	path := filepath.Join(dir, avatarCacheName(43, url))
+	if err := os.WriteFile(path, body, 0644); err != nil {
+		t.Fatal(err)
+	}
+	if got := ensureAvatar(43, url, dir); got != path {
+		t.Fatalf("应当直接命中缓存，实际 %q", got)
+	}
+	if n := atomic.LoadInt64(&hits); n != 0 {
+		t.Fatalf("完好的缓存不该再请求网络，实际 %d 次", n)
+	}
+}
+
+// 下载过程中不会留下能被误用的半截文件
+func TestDownloadAvatarWritesAtomically(t *testing.T) {
+	withJobFlags(t, true, false, false)
+	dir := t.TempDir()
+
+	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		_, _ = w.Write(tinyPNG(t))
+	}))
+	defer srv.Close()
+
+	url := srv.URL + "/c.png"
+	path := filepath.Join(dir, avatarCacheName(44, url))
+	if err := downloadAvatar(44, url, path); err != nil {
+		t.Fatalf("下载不该失败：%v", err)
+	}
+	if !validCachedAvatar(path) {
+		t.Fatal("下载完的缓存应当是完整 PNG")
+	}
+	// 临时文件不该留下
+	if entries, err := os.ReadDir(dir); err == nil {
+		for _, e := range entries {
+			if strings.HasSuffix(e.Name(), ".part") {
+				t.Fatalf("不该留下临时文件：%s", e.Name())
+			}
+		}
+	}
+}
+
+// 记录当前日志长度，返回一个能读到之后新增内容的函数
+func logCursor() func() string {
+	logString.Lock()
+	start := logString.str.Len()
+	logString.Unlock()
+	return func() string {
+		logString.Lock()
+		defer logString.Unlock()
+		data := logString.str.String()
+		if start > len(data) {
+			return data // 中间被 Reset 过，那就给全部
+		}
+		return data[start:]
+	}
+}
+
+// 头像输入打不开属于「跟编码器无关」的失败：不该挨个编码器回退重试，
+// 而且 ffmpeg 自己的报错必须留在日志里（否则只剩一句 exit status 0xffffffea）
+func TestRenderChunkDoesNotFallBackOnUnrelatedFailure(t *testing.T) {
+	ffmpegFile := getFFmpeg()
+	if ffmpegFile == "" {
+		t.Skip("找不到 ffmpeg，跳过")
+	}
+	withJobFlags(t, true, false, false)
+	dir := t.TempDir()
+
+	video := filepath.Join(dir, "in.mp4")
+	makeTinyVideo(t, ffmpegFile, video, "red")
+
+	uid := int64(1)
+	chunk := danmuChunk{start: 0, end: 1, records: []danmuRecord{
+		{Time: 0.2, UID: uid, Name: "甲", Content: "正常一条", Lane: 0, Width: 100},
+	}}
+	ctx := &burnContext{
+		ffmpegFile: ffmpegFile,
+		videoFile:  video,
+		outFile:    filepath.Join(dir, "out.mp4"),
+		meta:       danmuMeta{PlayResX: 160, PlayResY: 120, FontSize: 20},
+		// 头像文件根本不存在：ffmpeg 打开输入就会失败
+		avatars: map[int64]string{uid: filepath.Join(dir, "根本没有这个头像.png")},
+		dir:     dir,
+		// 故意不指定 encoder：从候选列表第一个开始，才能看出有没有挨个回退
+	}
+	ad, gap := avatarSize(ctx.meta.FontSize), avatarGap(ctx.meta.FontSize)
+	if err := writeChunkAss(filepath.Join(dir, "chunk.ass"), ctx.meta, chunk, 0, ad, gap); err != nil {
+		t.Fatal(err)
+	}
+
+	read := logCursor()
+	err := ctx.renderChunk(chunk, "chunk.ass", filepath.Join(dir, "out.mp4"), false, nil)
+	if err == nil {
+		t.Fatal("头像打不开时应当渲染失败")
+	}
+	msg := err.Error()
+	if !strings.Contains(msg, "ffmpeg 最后的输出") {
+		t.Fatalf("错误里应当带上 ffmpeg 自己的输出：%s", msg)
+	}
+	if log := read(); strings.Contains(log, "回退到") {
+		t.Fatalf("输入打不开跟编码器无关，不该挨个回退重试：\n%s", log)
+	}
+}
+
+// 启动时那段版本/编译配置要过滤掉，别把真正的报错挤出日志
+func TestTailWriterSkipsStartupNoise(t *testing.T) {
+	w := newTailWriter(10)
+	fmt.Fprint(w, "ffmpeg version n9.0.2-3\n"+
+		"  built with gcc 16.2.0\n"+
+		"  configuration: --prefix=/ffbuild --enable-gpl --enable-libass 等等很长的一行\n"+
+		"  libavutil      61.  1.102 / 61.  1.102\n"+
+		"  libswscale     10.  1.102 / 10.  1.102\n"+
+		"[in#0 @ 0x1] moov atom not found\n"+
+		"Error opening input files: Invalid data found when processing input\n")
+	got := w.String()
+	for _, noise := range []string{"ffmpeg version", "configuration:", "libavutil", "libswscale", "built with"} {
+		if strings.Contains(got, noise) {
+			t.Fatalf("启动信息应当被过滤掉（%s），实际：%q", noise, got)
+		}
+	}
+	if !strings.Contains(got, "moov atom not found") || !strings.Contains(got, "Invalid data found") {
+		t.Fatalf("真正的报错必须保留：%q", got)
+	}
+}
+
+// 头像直径再小也要 >= 1，否则 scale=0:0 会让 ffmpeg 直接 EINVAL
+func TestAvatarSizeNeverZero(t *testing.T) {
+	for _, fs := range []int{0, 1, 2, 5, 42, 60} {
+		if got := avatarSize(fs); got < 1 {
+			t.Fatalf("字号 %d 算出的头像直径是 %d，应当至少为 1", fs, got)
+		}
+	}
+	if got := avatarSize(60); got != 48 {
+		t.Fatalf("正常字号的口径不该变：60 -> %d（应为 48）", got)
+	}
+}