Scoreboard/server/internal/httpapi/intercept_log_test.go

package httpapi_test

import (
	"bytes"
	"errors"
	"log/slog"
	"net/http"
	"strings"
	"testing"
	"time"

	"git.yeij.top/AskaEth/Scoreboard/server/internal/httpapi"
)

// logEnv 把服务端日志抓进内存缓冲：日志分级与拦截点只有真的抓到才能断言。
// 用 DEBUG 级别建 handler，WARN/INFO/ERROR 与默认级别下的可见性差异由用例分别断言。
func logEnv(t *testing.T) (*testEnv, *bytes.Buffer) {
	t.Helper()
	buf := &bytes.Buffer{}
	logger := slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
	env := newTestEnvWith(t, func(o *httpapi.Options) { o.Logger = logger })
	return env, buf
}

// waitLog 等到日志里出现 want 之后返回整段日志。
// 一部分日志（审计 INFO、拦截 WARN）在响应写完之后才落，不能立刻就读缓冲。
func waitLog(t *testing.T, buf *bytes.Buffer, want string) string {
	t.Helper()
	for i := 0; i < 200; i++ {
		if got := buf.String(); strings.Contains(got, want) {
			return got
		}
		time.Sleep(5 * time.Millisecond)
	}
	t.Fatalf("等不到日志片段 %q，当前日志：\n%s", want, buf.String())
	return ""
}

// recorderClient 建号并登录，返回 recorder 客户端。
func recorderClient(t *testing.T, env *testEnv) *http.Client {
	t.Helper()
	env.createUser("recorder", "recorder-pass", "recorder")
	client, _ := env.client()
	env.login(client, "recorder", "recorder-pass")
	return client
}

// 拦截点必须指向真正做校验的那段代码，而不是 response.go 里的构造函数。
func TestInterceptLogPointsAtValidator(t *testing.T) {
	env, buf := logEnv(t)
	ids := env.seed(t)
	client := recorderClient(t, env)

	// avgMode 校验发生在 repo_events.go 的 normalizeAvgMode。
	status, env2 := env.do(client, http.MethodPost, "/api/events", map[string]any{
		"sportId": ids.sport, "code": "E-BAD", "name": "非法小项", "avgMode": "bogus",
	}, true)
	if status != http.StatusBadRequest || env2.Error == nil {
		t.Fatalf("非法 avgMode 应 400，得到 %d %+v", status, env2.Error)
	}

	logs := waitLog(t, buf, "请求被拦截")
	if !strings.Contains(logs, `"origin":"internal/httpapi/repo_events.go:`) ||
		!strings.Contains(logs, "normalizeAvgMode") {
		t.Fatalf("WARN 行应指出拦截点是 normalizeAvgMode，得到：\n%s", logs)
	}
	for _, forbidden := range []string{"response.go", "badRequest", "newAPIError", "/home/"} {
		if strings.Contains(logs, forbidden) {
			t.Fatalf("拦截点不该出现 %q（应指向校验代码、且不带开发机路径），得到：\n%s", forbidden, logs)
		}
	}
}

// 分级：4xx 有 WARN 与 DEBUG、没有 ERROR；5xx 用 ERROR；成功的写操作只有 INFO 放行。
func TestInterceptLogLevels(t *testing.T) {
	t.Run("4xx", func(t *testing.T) {
		env, buf := logEnv(t)
		ids := env.seed(t)
		client := recorderClient(t, env)
		env.do(client, http.MethodPost, "/api/events", map[string]any{
			"sportId": ids.sport, "code": "E-BAD", "name": "非法小项", "avgMode": "bogus",
		}, true)

		logs := waitLog(t, buf, `"level":"WARN"`)
		// WARN 是默认 info 级别下可见的那行：为什么被拦 + 拦截点都要在里面。
		if !strings.Contains(logs, `"reason":"avgMode 只能是 valid / all"`) {
			t.Fatalf("WARN 行应写明被拦原因，得到：\n%s", logs)
		}
		if !strings.Contains(logs, `"origin":"internal/httpapi/repo_events.go:`) {
			t.Fatalf("WARN 行应带拦截点，得到：\n%s", logs)
		}
		logs = waitLog(t, buf, `"level":"DEBUG"`)
		if !strings.Contains(logs, `"msg":"拦截上下文"`) || !strings.Contains(logs, `"detail":"bogus"`) {
			t.Fatalf("DEBUG 行应带完整上下文与 detail，得到：\n%s", logs)
		}
		if strings.Contains(logs, `"level":"ERROR"`) {
			t.Fatalf("4xx 不该出现 ERROR，得到：\n%s", logs)
		}
	})

	t.Run("5xx", func(t *testing.T) {
		// 未知 action 现在是 4xx，5xx 的日志行为改用真正的下发失败（写 socket 失败）来触发。
		sender := &strictDisplaySender{failWith: errors.New("写 socket 失败: broken pipe")}
		buf := &bytes.Buffer{}
		logger := slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
		env := newTestEnvWith(t, func(o *httpapi.Options) {
			o.Logger = logger
			o.Display = sender
		})
		client := recorderClient(t, env)

		status, _ := env.do(client, http.MethodPost, "/api/display/command",
			map[string]any{"action": "goto", "payload": map[string]any{"page": "medals"}}, true)
		if status != http.StatusInternalServerError {
			t.Fatalf("下发失败应 500，得到 %d", status)
		}
		logs := waitLog(t, buf, `"level":"ERROR"`)
		if !strings.Contains(logs, `"origin":"internal/httpapi/handlers_results.go:`) ||
			!strings.Contains(logs, "displayCommandHandler") {
			t.Fatalf("ERROR 行应带上拦截点，得到：\n%s", logs)
		}
		if strings.Contains(logs, `"level":"WARN"`) {
			t.Fatalf("5xx 不该同时按 WARN 记，得到：\n%s", logs)
		}
	})

	t.Run("放行", func(t *testing.T) {
		env, buf := logEnv(t)
		client := recorderClient(t, env)

		status, env2 := env.do(client, http.MethodPost, "/api/teams", map[string]any{
			"code": "Z9", "name": "第九分公司",
		}, true)
		if status != http.StatusOK || !env2.OK {
			t.Fatalf("新建单位应 200，得到 %d %+v", status, env2.Error)
		}
		logs := waitLog(t, buf, "操作已放行")
		for _, want := range []string{`"level":"INFO"`, `"action":"team.create"`, `"entity":"team"`, `"actor":"recorder#`} {
			if !strings.Contains(logs, want) {
				t.Fatalf("放行日志应含 %s，得到：\n%s", want, logs)
			}
		}
		// 一次审计条目一行 INFO：登录 + 新建单位共 2 行，别在同一次请求里重复刷。
		if n := strings.Count(logs, "操作已放行"); n != 2 {
			t.Fatalf("放行日志应恰好 2 行（登录 + 新建单位），得到 %d 行：\n%s", n, logs)
		}
		if strings.Contains(logs, `"level":"WARN"`) || strings.Contains(logs, `"level":"ERROR"`) {
			t.Fatalf("成功请求不该有 WARN/ERROR，得到：\n%s", logs)
		}
	})
}

// 日志不能整段记请求体：带证件号的新建人员请求（成功与 409 两条路径）都不该把证件号打出来。
func TestInterceptLogKeepsBodyOut(t *testing.T) {
	env, buf := logEnv(t)
	client := recorderClient(t, env)
	const idCard = "110101199001019999"

	env.do(client, http.MethodPost, "/api/athletes", map[string]any{
		"name": "张三", "gender": "男", "teamId": 1, "idCard": idCard, "active": true,
	}, true)
	// 同一个证件号再来一次：409 的 WARN 也不该带出证件号。
	env.do(client, http.MethodPost, "/api/athletes", map[string]any{
		"name": "张三", "gender": "男", "teamId": 1, "idCard": idCard, "active": true,
	}, true)

	logs := waitLog(t, buf, "操作已放行")
	if !strings.Contains(logs, "请求被拦截") {
		t.Fatalf("第二次建档应被拦截并记 WARN，得到：\n%s", logs)
	}
	if strings.Contains(logs, idCard) {
		t.Fatalf("日志里出现了证件号原文，说明请求体被打了进去：\n%s", logs)
	}
}

// 导入的行级拦截每一条都要有一行 DEBUG，带行号与拦截点。
func TestImportRowInterceptLogs(t *testing.T) {
	env, buf := logEnv(t)
	env.seed(t)
	client := recorderClient(t, env)

	body := importHeader + "\n" +
		"M100,男子,A,张三,110101199001011234,男,,,,已报到,\n" +
		"M100,男子,A,李四,110101199001011235,男,,,,,\n"
	status, resp := env.postImport(t, client, "/api/entries/import", body, "")
	if status != http.StatusOK {
		t.Fatalf("导入应 200，得到 %d %+v", status, resp.Error)
	}
	result := decodeData[map[string]any](t, resp)
	if result["skipped"] != float64(1) {
		t.Fatalf("非法 status 的那行应被跳过: %+v", result)
	}

	logs := waitLog(t, buf, "导入行被拦截")
	if !strings.Contains(logs, `"row":2`) || !strings.Contains(logs, "无法识别") {
		t.Fatalf("行级 DEBUG 应带行号与原因，得到：\n%s", logs)
	}
	if !strings.Contains(logs, "internal/httpapi/handlers_config.go:") ||
		!strings.Contains(logs, "importEntriesWith") {
		t.Fatalf("行级 DEBUG 应带拦截点，得到：\n%s", logs)
	}
	if n := strings.Count(logs, "导入行被拦截"); n != 1 {
		t.Fatalf("一条行级错误应只记一行 DEBUG，得到 %d 行：\n%s", n, logs)
	}
}