From 8a48af6a3bfd1b757bd7cc2ef32fb2a0989d95b9 Mon Sep 17 00:00:00 2001 From: brother7 <7brother7@gmail.com> Date: Tue, 28 Jul 2026 10:36:32 +0800 Subject: [PATCH] =?UTF-8?q?=E4=BF=AE=E5=A4=8Dbug=E5=8F=8A=E6=B7=BB?= =?UTF-8?q?=E5=8A=A0=E6=97=A5=E5=BF=97=E6=89=93=E5=8D=B0?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- docs/backend-production-handoff.md | 8 + findings.md | 14 + progress.md | 13 + server/internal/httpapi/http_logging.go | 480 +++++++++++++++ .../httpapi/public_integration_test.go | 133 +++++ server/internal/httpapi/server.go | 86 ++- .../internal/httpapi/server_logging_test.go | 553 ++++++++++++++++++ server/internal/httpapi/staff.go | 2 +- task_plan.md | 15 + 9 files changed, 1292 insertions(+), 12 deletions(-) create mode 100644 server/internal/httpapi/http_logging.go create mode 100644 server/internal/httpapi/public_integration_test.go create mode 100644 server/internal/httpapi/server_logging_test.go diff --git a/docs/backend-production-handoff.md b/docs/backend-production-handoff.md index 0fec2c3..390aaa1 100644 --- a/docs/backend-production-handoff.md +++ b/docs/backend-production-handoff.md @@ -28,6 +28,14 @@ MAINTENANCE_BATCH_SIZE=500 `DATABASE_URL` 必须使用 `require`、`verify-ca` 或 `verify-full` 之一；生产 API 会拒绝 `sslmode=disable` 和 `MIGRATE_ON_START=true`。 +## 结构化接口日志 + +- 关键业务 API 的 `http request` 日志包含 `request`、`response`、状态码、耗时和 `request_id`；JSON 正文单向最多记录 64 KiB，超过后只记录字节数与 `body_truncated=true`。 +- 手机号只保留后四位；账号名脱敏；密码、姓名/称谓、Cookie、Authorization、Token、内嵌私密链接及 Idempotency-Key 原值不得写入日志。 +- 访客状态和公示屏请求使用路由模板记录路径，不记录真实 Token。 +- SSE `/api/events` 与历史 CSV 导出不记录响应正文；CSV 可能包含个人信息，只记录请求筛选、状态码和正文省略原因。 +- Ingress/Nginx 的 access log 也必须使用路由模板或关闭上述 Token 路径的 URI 记录，应用内脱敏无法清理上游代理已经写出的原始 URI。 + ## Kubernetes 发布顺序 1. 运维先执行数据库迁移 Job，容器命令为 `/usr/local/bin/migrate`。 diff --git a/findings.md b/findings.md index 91166a7..e725ce8 100644 --- a/findings.md +++ b/findings.md @@ -567,3 +567,17 @@ - 项目创建、项目基础信息与运行规则已经使用 form submit 和明确保存按钮；后台唯一的点击即提交维护项是账号维护。 - 账号维护现在本地组合角色、状态和项目权限草稿，仅在用户点击“保存修改”后调用一次更新 API。 - 服务端对最后一个启用管理员的降级或停用返回 `409 LAST_ACTIVE_ADMIN`，不再仅依赖前端防误触。 + +# 2026-07-28 关键接口日志审计 + +- 当前 `accessLog` 只记录 request_id、method、path、status 和 duration_ms，不记录业务出入参。 +- 统一中间件比逐 Handler 埋点更小、更不易漏接口；仅对 `/api/` 业务接口记录正文，健康检查、SSE 事件流和 CSV 导出不捕获正文。 +- 手机号、密码、Cookie、Authorization、状态 token 等不能原样写日志；JSON 字段需递归脱敏，查询参数也需按字段名脱敏。 +- 请求/响应正文必须设置大小上限，防止队列快照、历史查询等大响应放大日志和内存占用。 +- 文档明确禁止普通应用日志记录完整手机号、姓名、密码、Cookie 与访客/公示 Token；实现采用现有路由白名单、递归脱敏及 64 KiB 上限。 +- 现有中间件顺序还会让 panic 绕过访问日志并丢失 request_id；将 request_id 和 accessLog 放在 recoverPanic 外层后，500 可被统一记录。 +- SSE 与 CSV 下载不捕获响应正文；Idempotency-Key 仅记录是否存在，不记录原值。 +- 请求正文先按路由对应 DTO 严格校验；未知字段、类型错误或不支持的正文只记录省略原因，避免攻击者借无效请求向普通日志写入任意隐私内容。 +- 查询参数按路由白名单投影；历史手机号查询只保留尾四位，其他自由查询只记录是否存在。 +- 账号名的 `username`、`display_name`、`created_by`、`requested_by` 等别名统一脱敏，UUID 形态用户名也不例外。 +- ResponseWriter 仅在底层实际支持时暴露 `http.Flusher`；已提交响应后发生 panic 时不再追加错误 JSON。 diff --git a/progress.md b/progress.md index d56a368..aef179e 100644 --- a/progress.md +++ b/progress.md @@ -654,3 +654,16 @@ - 新建页与真实项目维护页均完成 1440×1000 和 390×844 响应式验收：三处分区、四个规则分组、既有数据回填、成对输入对齐及无横向溢出均通过。 - 浏览器控制台无 error/warn，临时视口已恢复，Phase 33 全部验收项完成。 - 台账收尾后再次执行目标差异格式检查，结果仍为通过。 + +# Session: 2026-07-28（关键接口结构化出入参日志） + +- 已启动路由、日志中间件与敏感字段审计。 +- 已确定以现有访问日志中间件为统一入口，保持 Handler 契约不变。 +- 成功标准：关键 API 有结构化输入/输出、敏感字段脱敏、正文大小受控、流式/文件接口不捕获正文、日志不影响业务响应。 +- 已新增日志回归测试；旧实现准确复现四项失败：真实 Token 路径、缺少出入参、重复 WriteHeader 覆盖状态、panic 无访问日志。 +- 已实现路由白名单、JSON 旁路捕获、递归脱敏、64 KiB 上限、SSE/CSV 排除、模板路径及 panic 链修正。 +- 聚焦测试已通过：业务 Handler 仍收到完整请求、客户端仍收到完整响应，日志中不含手机号、密码、姓氏、Token 或 Idempotency-Key 原值。 +- 独立安全审查发现并关闭账号别名、未知字段和 Flusher 能力三个边界；新增 UUID 形态用户名、无效 JSON、历史查询、CSV/SSE 与已写响应后 panic 回归。 +- 已更新生产交接文档，补充结构化日志字段、脱敏规则、正文上限及 Ingress URI 脱敏要求。 +- 最终验证通过：`go test ./... -count=1`、`go vet ./...`、`go build ./cmd/api`、`git diff --check`。 +- `go test -race` 因当前 Windows Go 环境关闭 CGO 未运行；未发现由此遗留的功能失败。 diff --git a/server/internal/httpapi/http_logging.go b/server/internal/httpapi/http_logging.go new file mode 100644 index 0000000..9958bef --- /dev/null +++ b/server/internal/httpapi/http_logging.go @@ -0,0 +1,480 @@ +package httpapi + +import ( + "bytes" + "encoding/json" + "errors" + "io" + "net/http" + "regexp" + "strconv" + "strings" + "time" + + "calllinesystem/server/internal/security" +) + +const ( + maxLoggedBody = 64 << 10 + redactedLogText = "[REDACTED]" +) + +var ( + phoneInLogTextPattern = regexp.MustCompile(`(?:\+[0-9][0-9 ()-]{6,20}[0-9]|[0-9]{10,15})`) + importantLogRoutes = map[string]struct{}{ + "POST /api/staff/auth/login": {}, + "POST /api/staff/auth/logout": {}, + "GET /api/staff/auth/me": {}, + "POST /api/admin/auth/login": {}, + "POST /api/admin/auth/logout": {}, + "GET /api/admin/auth/me": {}, + "GET /api/staff/projects": {}, + "GET /api/staff/projects/{id}/queue": {}, + "POST /api/staff/projects/{id}/tickets": {}, + "POST /api/staff/projects/{id}/call-next": {}, + "GET /api/public/status/{token}": {}, + "GET /api/public/projects": {}, + "POST /api/public/projects/{id}/tickets": {}, + "POST /api/public/status/search": {}, + "POST /api/internal/status/search": {}, + "GET /api/display/{token}/snapshot": {}, + "GET /api/events": {}, + "GET /api/admin/overview": {}, + "GET /api/admin/users": {}, + "POST /api/admin/users": {}, + "PUT /api/admin/users/{id}": {}, + "POST /api/admin/projects": {}, + "PUT /api/admin/projects/{id}": {}, + "PUT /api/admin/projects/{id}/settings": {}, + "GET /api/admin/history/tickets": {}, + "GET /api/admin/history/tickets/{id}": {}, + "GET /api/admin/history/batches": {}, + "GET /api/admin/history/batches/{id}": {}, + "GET /api/admin/history/summary": {}, + "GET /api/admin/history/export.csv": {}, + } +) + +type logBodyCapture struct { + body bytes.Buffer + total int + truncated bool +} + +func (capture *logBodyCapture) Write(value []byte) (int, error) { + capture.total += len(value) + remaining := maxLoggedBody - capture.body.Len() + if remaining <= 0 { + if len(value) > 0 { + capture.truncated = true + } + return len(value), nil + } + toCopy := min(remaining, len(value)) + if toCopy > 0 { + _, _ = capture.body.Write(value[:toCopy]) + } + if toCopy < len(value) { + capture.truncated = true + } + return len(value), nil +} + +type logCaptureReadCloser struct { + io.ReadCloser + capture *logBodyCapture +} + +func (reader *logCaptureReadCloser) Read(value []byte) (int, error) { + n, err := reader.ReadCloser.Read(value) + if n > 0 { + _, _ = reader.capture.Write(value[:n]) + } + return n, err +} + +func shouldCaptureLogBody(r *http.Request) bool { + if !strings.HasPrefix(r.URL.Path, "/api/") { + return false + } + return r.URL.Path != "/api/events" && r.URL.Path != "/api/admin/history/export.csv" +} + +func isImportantLogRoute(r *http.Request) bool { + _, ok := importantLogRoutes[logRoutePattern(r)] + return ok +} + +func logRoutePattern(r *http.Request) string { + if route := strings.TrimSpace(r.Pattern); route != "" { + return route + } + return r.Method + " " + r.URL.Path +} + +func logPath(r *http.Request) string { + pattern := strings.TrimSpace(r.Pattern) + if pattern != "" { + if _, path, found := strings.Cut(pattern, " "); found { + return path + } + return pattern + } + switch { + case strings.HasPrefix(r.URL.Path, "/api/public/status/"): + return "/api/public/status/{token}" + case strings.HasPrefix(r.URL.Path, "/api/display/") && strings.HasSuffix(r.URL.Path, "/snapshot"): + return "/api/display/{token}/snapshot" + default: + return r.URL.Path + } +} + +func requestLogDetails(r *http.Request, capture *logBodyCapture) map[string]any { + details := make(map[string]any) + pathParams := make(map[string]any) + if id := strings.TrimSpace(r.PathValue("id")); id != "" { + if validateUUID(id) == nil { + pathParams["id"] = id + } else { + pathParams["id"] = "[INVALID]" + } + } + if token := strings.TrimSpace(r.PathValue("token")); token != "" { + pathParams["token"] = redactedLogText + } + if len(pathParams) > 0 { + details["path_params"] = pathParams + } + + if values := r.URL.Query(); len(values) > 0 { + query := make(map[string]any, len(values)) + omitted := 0 + for field, items := range values { + if !allowedLogQueryField(logRoutePattern(r), field) { + omitted += len(items) + continue + } + sanitized := make([]any, 0, len(items)) + for _, item := range items { + sanitized = append(sanitized, sanitizeLogQueryValue(field, item)) + } + query[field] = sanitized + } + if omitted > 0 { + query["_omitted_parameter_count"] = omitted + } + details["query"] = query + } + if strings.TrimSpace(r.Header.Get("Idempotency-Key")) != "" { + details["idempotency_key_present"] = true + } + appendCapturedLogBody(details, capture, r.Header.Get("Content-Type"), func(value any) (any, bool) { + return sanitizeRequestLogBody(r, capture.body.Bytes(), value) + }) + if len(details) == 0 { + return nil + } + return details +} + +func responseLogDetails(r *http.Request, recorder *statusRecorder) map[string]any { + if recorder.body == nil { + switch r.URL.Path { + case "/api/events": + return map[string]any{"body_omitted": "event_stream"} + case "/api/admin/history/export.csv": + return map[string]any{"body_omitted": "file_download"} + default: + return nil + } + } + details := make(map[string]any) + appendCapturedLogBody(details, recorder.body, recorder.Header().Get("Content-Type"), func(value any) (any, bool) { + return sanitizeLogValue("", value), true + }) + if len(details) == 0 { + return nil + } + return details +} + +func appendCapturedLogBody( + target map[string]any, + capture *logBodyCapture, + contentType string, + sanitize func(any) (any, bool), +) { + if capture == nil || capture.total == 0 { + return + } + target["body_bytes"] = capture.total + if contentType != "" { + target["content_type"] = contentType + } + if capture.truncated { + target["body_truncated"] = true + return + } + + var value any + if err := json.Unmarshal(capture.body.Bytes(), &value); err != nil { + target["body_omitted"] = "invalid_or_non_json" + return + } + sanitized, ok := sanitize(value) + if !ok { + target["body_omitted"] = "invalid_or_unsupported_request_json" + return + } + target["body"] = sanitized +} + +func sanitizeRequestLogBody(r *http.Request, raw []byte, value any) (any, bool) { + schema := requestLogSchema(logRoutePattern(r)) + if schema == nil { + return nil, false + } + decoder := json.NewDecoder(bytes.NewReader(raw)) + decoder.DisallowUnknownFields() + if err := decoder.Decode(schema); err != nil { + return nil, false + } + if err := decoder.Decode(&struct{}{}); !errors.Is(err, io.EOF) { + return nil, false + } + return sanitizeLogValue("", value), true +} + +func requestLogSchema(route string) any { + switch route { + case "POST /api/staff/auth/login", "POST /api/admin/auth/login": + return &loginRequest{} + case "POST /api/staff/projects/{id}/tickets", "POST /api/public/projects/{id}/tickets": + return &createTicketRequest{} + case "POST /api/staff/projects/{id}/call-next": + return &callNextRequest{} + case "POST /api/public/status/search", "POST /api/internal/status/search": + return &publicPhoneQueryRequest{} + case "POST /api/admin/users", "PUT /api/admin/users/{id}": + return &adminUserRequest{} + case "POST /api/admin/projects", "PUT /api/admin/projects/{id}": + return &adminProjectRequest{} + case "PUT /api/admin/projects/{id}/settings": + return &updateProjectSettingsRequest{} + default: + return nil + } +} + +func allowedLogQueryField(route, field string) bool { + switch route { + case "GET /api/events": + return field == "project_id" + case "GET /api/admin/history/tickets": + return isLogQueryField(field, "from", "to", "project_id", "status", "query", "page", "page_size") + case "GET /api/admin/history/tickets/{id}": + return field == "reveal" + case "GET /api/admin/history/batches": + return isLogQueryField(field, "from", "to", "project_id", "status", "query", "page", "page_size") + case "GET /api/admin/history/summary": + return isLogQueryField(field, "from", "to", "project_id", "status", "query") + case "GET /api/admin/history/export.csv": + return isLogQueryField(field, "from", "to", "project_id", "status", "query", "include_personal", "confirm") + default: + return false + } +} + +func isLogQueryField(field string, allowed ...string) bool { + for _, candidate := range allowed { + if field == candidate { + return true + } + } + return false +} + +func sanitizeLogQueryValue(field, value string) any { + switch field { + case "project_id": + if validateUUID(value) != nil { + return "[INVALID]" + } + return value + case "from", "to": + if _, err := time.Parse("2006-01-02", value); err != nil { + return "[INVALID]" + } + return value + case "status": + status := strings.ToUpper(strings.TrimSpace(value)) + if !historyTicketStatuses[status] && !historyBatchStatuses[status] { + return "[INVALID]" + } + return status + case "page", "page_size": + number, err := strconv.Atoi(value) + if err != nil || number < 1 { + return "[INVALID]" + } + return number + case "include_personal", "confirm", "reveal": + switch strings.ToLower(strings.TrimSpace(value)) { + case "true", "1": + return true + case "false", "0": + return false + default: + return "[INVALID]" + } + case "query": + if normalized, err := security.NormalizePhone(value); err == nil { + return maskPhoneForLog(normalized) + } + if value == "" { + return "" + } + return "[PRESENT]" + default: + return "[OMITTED]" + } +} + +func sanitizeLogValue(field string, value any) any { + normalizedField := normalizeLogField(field) + switch { + case isPhoneLogField(normalizedField): + if strings.Contains(normalizedField, "hmac") || + strings.Contains(normalizedField, "cipher") || + strings.Contains(normalizedField, "nonce") { + return redactedLogText + } + phone, ok := value.(string) + if !ok { + return redactedLogText + } + return maskPhoneForLog(phone) + case normalizedField == "last_name" || + normalizedField == "surname" || + normalizedField == "honorific" || + normalizedField == "public_url" || + normalizedField == "status_path": + return redactedLogText + case isUserIdentifierLogField(normalizedField): + identifier, ok := value.(string) + if !ok { + return redactedLogText + } + return maskIdentifierForLog(identifier) + case normalizedField == "query" || + normalizedField == "search" || + normalizedField == "q": + query, ok := value.(string) + if ok { + if normalized, err := security.NormalizePhone(query); err == nil { + return maskPhoneForLog(normalized) + } + } + case normalizedField == "visitor_notice": + return "[OMITTED]" + case isCredentialLogField(normalizedField): + return redactedLogText + } + + switch typed := value.(type) { + case map[string]any: + sanitized := make(map[string]any, len(typed)) + for childField, childValue := range typed { + sanitized[childField] = sanitizeLogValue(childField, childValue) + } + return sanitized + case []any: + sanitized := make([]any, 0, len(typed)) + for _, childValue := range typed { + sanitized = append(sanitized, sanitizeLogValue(field, childValue)) + } + return sanitized + case string: + return sanitizeLogString(field, typed) + default: + return value + } +} + +func sanitizeLogString(field string, value string) string { + if strings.Contains(value, "/visitor/") || + strings.Contains(value, "/api/public/status/") || + strings.Contains(value, "/api/display/") { + return redactedLogText + } + return phoneInLogTextPattern.ReplaceAllStringFunc(value, maskPhoneForLog) +} + +func normalizeLogField(field string) string { + return strings.ToLower(strings.ReplaceAll(strings.TrimSpace(field), "-", "_")) +} + +func isPhoneLogField(field string) bool { + return strings.Contains(field, "phone") || + strings.Contains(field, "mobile") || + strings.Contains(field, "contact") || + field == "tel" || + strings.HasSuffix(field, "_tel") +} + +func isCredentialLogField(field string) bool { + return strings.Contains(field, "password") || + strings.Contains(field, "passwd") || + strings.Contains(field, "token") || + strings.Contains(field, "cookie") || + strings.Contains(field, "authorization") || + strings.Contains(field, "secret") || + strings.Contains(field, "ciphertext") || + strings.HasSuffix(field, "_nonce") || + strings.Contains(field, "hmac") || + strings.HasSuffix(field, "_hash") || + strings.Contains(field, "digest") || + field == "key" || + strings.HasSuffix(field, "_key") || + field == "pin" || + strings.Contains(field, "otp") || + strings.Contains(field, "captcha") || + strings.Contains(field, "verification_code") +} + +func isUserIdentifierLogField(field string) bool { + switch field { + case "username", "display_name", "created_by", "created_by_name", "requested_by", "requested_by_name": + return true + default: + return strings.HasSuffix(field, "_username") + } +} + +func maskPhoneForLog(value string) string { + digits := make([]byte, 0, len(value)) + for i := 0; i < len(value); i++ { + if value[i] >= '0' && value[i] <= '9' { + digits = append(digits, value[i]) + } + } + if len(digits) < 4 { + return redactedLogText + } + return "****" + string(digits[len(digits)-4:]) +} + +func maskIdentifierForLog(value string) string { + runes := []rune(strings.TrimSpace(value)) + switch len(runes) { + case 0: + return "" + case 1: + return "***" + case 2: + return string(runes[0]) + "***" + default: + return string(runes[0]) + "***" + string(runes[len(runes)-1]) + } +} diff --git a/server/internal/httpapi/public_integration_test.go b/server/internal/httpapi/public_integration_test.go new file mode 100644 index 0000000..a32ec9e --- /dev/null +++ b/server/internal/httpapi/public_integration_test.go @@ -0,0 +1,133 @@ +package httpapi + +import ( + "bytes" + "context" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" + "time" + + "calllinesystem/server/internal/config" + "calllinesystem/server/internal/database" + "calllinesystem/server/internal/model" + "calllinesystem/server/internal/security" + + "github.com/google/uuid" +) + +func TestPublicCreateTicketIgnoresDuplicateFromEndedSession(t *testing.T) { + dsn := strings.TrimSpace(os.Getenv("TEST_DATABASE_URL")) + if dsn == "" { + t.Skip("TEST_DATABASE_URL is not set") + } + + ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) + defer cancel() + logger := slog.New(slog.NewTextHandler(io.Discard, nil)) + db, err := database.Open(ctx, dsn, logger) + if err != nil { + t.Fatal(err) + } + defer database.Close(db) + sqlDB, err := database.SQLDB(db) + if err != nil { + t.Fatal(err) + } + if err := database.Migrate(ctx, sqlDB, logger); err != nil { + t.Fatal(err) + } + + server, err := New(db, config.Config{ + Environment: "development", + EncryptionKey: bytes.Repeat([]byte{0x41}, 32), + PhoneHMACKey: bytes.Repeat([]byte{0x42}, 32), + }, logger) + if err != nil { + t.Fatal(err) + } + now := time.Date(2026, 7, 28, 1, 0, 0, 0, time.UTC) + server.now = func() time.Time { return now } + + var actor model.User + if err := db.Where("username = ?", model.PublicVisitorUsername).First(&actor).Error; err != nil { + t.Fatal(err) + } + projectID := uuid.NewString() + project := model.Project{ + ID: projectID, Code: strings.ToUpper("PUB" + uuid.NewString()[:6]), Name: "Public duplicate regression", + Status: model.ProjectRunning, Timezone: "Asia/Shanghai", TicketPrefix: "A", + CallBatchSize: 5, CallMode: model.CallModeBoth, + MaxCallTicketCount: 100, DefaultCallPeopleCount: 1, MaxCallPeopleCount: 100, + MinPartySize: 1, MaxPartySize: 10, GracePeriodMinutes: 5, + ETAMode: model.ETAFixedBatch, AverageBatchIntervalSeconds: 60, + ContinuousRatePerMinute: 2, ETABufferMinutes: 5, ETAIntervalSeconds: 60, + VisitorNotice: "", DeviceSimulationMode: "DISABLED", CreatedAt: now, UpdatedAt: now, + } + if err := db.Create(&project).Error; err != nil { + t.Fatal(err) + } + endedAt := now.Add(-12 * time.Hour) + oldSession := model.QueueSession{ + ID: uuid.NewString(), ProjectID: projectID, BusinessDate: now.AddDate(0, 0, -1), + Status: "ENDED", NextTicketNumber: 2, Revision: 1, + OpenedAt: now.Add(-24 * time.Hour), ClosedAt: &endedAt, CreatedAt: now.Add(-24 * time.Hour), UpdatedAt: endedAt, + } + currentSession := model.QueueSession{ + ID: uuid.NewString(), ProjectID: projectID, BusinessDate: now, + Status: "RUNNING", NextTicketNumber: 1, Revision: 0, + OpenedAt: now, CreatedAt: now, UpdatedAt: now, + } + if err := db.Create(&oldSession).Error; err != nil { + t.Fatal(err) + } + if err := db.Create(¤tSession).Error; err != nil { + t.Fatal(err) + } + + phone := "13800138000" + phoneCiphertext, phoneNonce, err := server.cipher.Encrypt(phone, []byte("phone:"+projectID)) + if err != nil { + t.Fatal(err) + } + phoneHMAC := server.cipher.Digest(phone) + oldTicket := model.QueueTicket{ + ID: uuid.NewString(), ProjectID: projectID, QueueSessionID: oldSession.ID, + TicketNumber: 1, DisplayNumber: "00001", PartySize: 1, + PublicTokenHash: security.HashToken(uuid.NewString()), + PhoneCiphertext: phoneCiphertext, PhoneNonce: phoneNonce, PhoneHMAC: &phoneHMAC, + Honorific: "游客", Status: model.TicketWaiting, JoinedAt: oldSession.OpenedAt, + PersonalDataPurgeAt: now.Add(30 * 24 * time.Hour), CreatedBy: actor.ID, + CreatedAt: oldSession.OpenedAt, UpdatedAt: oldSession.OpenedAt, + } + if err := db.Create(&oldTicket).Error; err != nil { + t.Fatal(err) + } + + recorder := httptest.NewRecorder() + request := httptest.NewRequest(http.MethodPost, "/api/public/projects/"+projectID+"/tickets", + strings.NewReader(`{"phone":"13800138000","honorific":"游客","party_size":1,"allow_duplicate":false}`)) + request.Header.Set("Idempotency-Key", "public-ended-session-"+uuid.NewString()) + + server.Handler().ServeHTTP(recorder, request) + + if recorder.Code != http.StatusCreated { + t.Fatalf("status = %d, want 201; body = %s", recorder.Code, recorder.Body.String()) + } + + duplicateRecorder := httptest.NewRecorder() + duplicateRequest := httptest.NewRequest(http.MethodPost, "/api/public/projects/"+projectID+"/tickets", + strings.NewReader(`{"phone":"13800138000","honorific":"游客","party_size":1,"allow_duplicate":false}`)) + duplicateRequest.Header.Set("Idempotency-Key", "public-current-session-"+uuid.NewString()) + + server.Handler().ServeHTTP(duplicateRecorder, duplicateRequest) + + if duplicateRecorder.Code != http.StatusConflict || !strings.Contains(duplicateRecorder.Body.String(), `"code":"DUPLICATE_PHONE"`) { + t.Fatalf("current-session duplicate status = %d, want 409 DUPLICATE_PHONE; body = %s", + duplicateRecorder.Code, duplicateRecorder.Body.String()) + } +} diff --git a/server/internal/httpapi/server.go b/server/internal/httpapi/server.go index eb3cd04..9f1c0a9 100644 --- a/server/internal/httpapi/server.go +++ b/server/internal/httpapi/server.go @@ -104,7 +104,7 @@ func (s *Server) Handler() http.Handler { mux.Handle("GET /api/admin/history/batches/{id}", s.requireAdmin(http.HandlerFunc(s.adminHistoryBatch))) mux.Handle("GET /api/admin/history/summary", s.requireAdmin(http.HandlerFunc(s.adminHistorySummary))) mux.Handle("GET /api/admin/history/export.csv", s.requireAdmin(http.HandlerFunc(s.adminHistoryExport))) - return s.recoverPanic(s.requestID(s.accessLog(s.securityHeaders(mux)))) + return s.requestID(s.accessLog(s.recoverPanic(s.securityHeaders(mux)))) } func (s *Server) health(w http.ResponseWriter, _ *http.Request) { @@ -144,32 +144,84 @@ func (s *Server) requestID(next http.Handler) http.Handler { type statusRecorder struct { http.ResponseWriter - status int + status int + wroteHeader bool + body *logBodyCapture } func (r *statusRecorder) WriteHeader(status int) { + if r.wroteHeader { + return + } r.status = status + r.wroteHeader = true r.ResponseWriter.WriteHeader(status) } -func (r *statusRecorder) Flush() { - if flusher, ok := r.ResponseWriter.(http.Flusher); ok { - flusher.Flush() +func (r *statusRecorder) Write(value []byte) (int, error) { + if !r.wroteHeader { + r.WriteHeader(http.StatusOK) } + n, err := r.ResponseWriter.Write(value) + if n > 0 && r.body != nil { + _, _ = r.body.Write(value[:n]) + } + return n, err +} + +func (r *statusRecorder) Unwrap() http.ResponseWriter { + return r.ResponseWriter +} + +func (r *statusRecorder) responseStarted() bool { + return r.wroteHeader +} + +type flushStatusRecorder struct { + *statusRecorder +} + +func (r *flushStatusRecorder) Flush() { + if !r.wroteHeader { + r.WriteHeader(http.StatusOK) + } + r.ResponseWriter.(http.Flusher).Flush() } func (s *Server) accessLog(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { started := s.now() - recorder := &statusRecorder{ResponseWriter: w, status: http.StatusOK} - next.ServeHTTP(recorder, r) - s.logger.Info("http request", + var requestBody *logBodyCapture + var responseBody *logBodyCapture + if shouldCaptureLogBody(r) { + requestBody = &logBodyCapture{} + responseBody = &logBodyCapture{} + if r.Body != nil { + r.Body = &logCaptureReadCloser{ReadCloser: r.Body, capture: requestBody} + } + } + recorder := &statusRecorder{ResponseWriter: w, status: http.StatusOK, body: responseBody} + var responseWriter http.ResponseWriter = recorder + if _, ok := w.(http.Flusher); ok { + responseWriter = &flushStatusRecorder{statusRecorder: recorder} + } + next.ServeHTTP(responseWriter, r) + attributes := []any{ "request_id", requestID(r.Context()), "method", r.Method, - "path", r.URL.Path, + "path", logPath(r), "status", recorder.status, "duration_ms", time.Since(started).Milliseconds(), - ) + } + if isImportantLogRoute(r) { + if request := requestLogDetails(r, requestBody); request != nil { + attributes = append(attributes, "request", request) + } + if response := responseLogDetails(r, recorder); response != nil { + attributes = append(attributes, "response", response) + } + } + s.logger.Info("http request", attributes...) }) } @@ -187,7 +239,19 @@ func (s *Server) recoverPanic(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { defer func() { if recovered := recover(); recovered != nil { - s.logger.Error("panic recovered", "request_id", requestID(r.Context()), "error", recovered, "stack", string(debug.Stack())) + responseStarted := false + if state, ok := w.(interface{ responseStarted() bool }); ok { + responseStarted = state.responseStarted() + } + s.logger.Error("panic recovered", + "request_id", requestID(r.Context()), + "error", recovered, + "response_started", responseStarted, + "stack", string(debug.Stack()), + ) + if responseStarted { + return + } writeError(w, fmt.Errorf("panic: %v", recovered)) } }() diff --git a/server/internal/httpapi/server_logging_test.go b/server/internal/httpapi/server_logging_test.go new file mode 100644 index 0000000..50917f1 --- /dev/null +++ b/server/internal/httpapi/server_logging_test.go @@ -0,0 +1,553 @@ +package httpapi + +import ( + "bytes" + "encoding/json" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" +) + +func TestAccessLogCapturesSanitizedJSONWithoutChangingExchange(t *testing.T) { + const ( + phone = "13912345678" + lastName = "林" + publicToken = "public-token-sentinel" + idempotencyKey = "idempotency-key-sentinel" + projectID = "11111111-1111-4111-8111-111111111111" + username = "operator-sentinel" + uuidUsername = "22222222-2222-4222-8222-222222222222" + ) + requestBody := `{"phone":"` + phone + `","last_name":"` + lastName + + `","honorific":"先生","party_size":2,"allow_duplicate":false}` + responseBody := `{"ticket":{"id":"ticket-1","phone":"` + phone + `","last_name":"` + lastName + + `","honorific":"先生","status":"WAITING"},"public_token":"` + publicToken + + `","public_url":"/visitor/` + publicToken + `","status_path":"/api/public/status/` + publicToken + + `","user":{"username":"` + username + `","display_name":"` + username + + `"},"history":{"created_by":"` + username + `","requested_by":"` + uuidUsername + + `","requested_by_name":"` + username + `"},"revision":7}` + + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + handler := server.requestID(server.accessLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + got, err := io.ReadAll(r.Body) + if err != nil { + t.Fatalf("read request body: %v", err) + } + if string(got) != requestBody { + t.Fatalf("handler request body changed: got %q", got) + } + w.Header().Set("Content-Type", "application/json; charset=utf-8") + w.WriteHeader(http.StatusCreated) + if _, err := io.WriteString(w, responseBody); err != nil { + t.Fatalf("write response: %v", err) + } + }))) + + request := httptest.NewRequest(http.MethodPost, + "/api/public/projects/"+projectID+"/tickets", + strings.NewReader(requestBody)) + request.Pattern = "POST /api/public/projects/{id}/tickets" + request.SetPathValue("id", projectID) + request.Header.Set("Content-Type", "application/json") + request.Header.Set("X-Request-ID", "request-123") + request.Header.Set("Idempotency-Key", idempotencyKey) + recorder := httptest.NewRecorder() + + handler.ServeHTTP(recorder, request) + + if recorder.Code != http.StatusCreated { + t.Fatalf("status = %d, want 201", recorder.Code) + } + if recorder.Body.String() != responseBody { + t.Fatalf("response body changed: got %q", recorder.Body.String()) + } + + entry := logEntryByMessage(t, logs.Bytes(), "http request") + if entry["path"] != "/api/public/projects/{id}/tickets" { + t.Fatalf("logged path = %#v", entry["path"]) + } + requestLog := mustLogObject(t, entry["request"], "request") + if requestLog["idempotency_key_present"] != true { + t.Fatalf("idempotency presence = %#v", requestLog["idempotency_key_present"]) + } + pathParams := mustLogObject(t, requestLog["path_params"], "request.path_params") + if pathParams["id"] != projectID { + t.Fatalf("path id = %#v", pathParams["id"]) + } + requestJSON := mustLogObject(t, requestLog["body"], "request.body") + if requestJSON["phone"] != "****5678" || + requestJSON["last_name"] != "[REDACTED]" || + requestJSON["honorific"] != "[REDACTED]" { + t.Fatalf("request body was not sanitized: %#v", requestJSON) + } + + responseLog := mustLogObject(t, entry["response"], "response") + responseJSON := mustLogObject(t, responseLog["body"], "response.body") + ticket := mustLogObject(t, responseJSON["ticket"], "response.body.ticket") + if ticket["phone"] != "****5678" || ticket["last_name"] != "[REDACTED]" || ticket["honorific"] != "[REDACTED]" { + t.Fatalf("response ticket was not sanitized: %#v", ticket) + } + for _, field := range []string{"public_token", "public_url", "status_path"} { + if responseJSON[field] != "[REDACTED]" { + t.Fatalf("%s = %#v, want redacted", field, responseJSON[field]) + } + } + user := mustLogObject(t, responseJSON["user"], "response.body.user") + history := mustLogObject(t, responseJSON["history"], "response.body.history") + if user["username"] != "o***l" || user["display_name"] != "o***l" || + history["created_by"] != "o***l" || history["requested_by"] != "2***2" || + history["requested_by_name"] != "o***l" { + t.Fatalf("user identifiers were not masked: user=%#v history=%#v", user, history) + } + + logText := logs.String() + for _, secret := range []string{phone, lastName, publicToken, idempotencyKey, username, uuidUsername} { + if strings.Contains(logText, secret) { + t.Fatalf("log leaked secret %q: %s", secret, logText) + } + } +} + +func TestAccessLogRedactsValidLoginCredentials(t *testing.T) { + const ( + username = "operator-sentinel" + password = "password-sentinel" + ) + requestBody := `{"username":"` + username + `","password":"` + password + `"}` + responseBody := `{"user":{"id":"user-1","username":"` + username + `","display_name":"` + username + `","role":"STAFF"}}` + + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + handler := server.requestID(server.accessLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + got, err := io.ReadAll(r.Body) + if err != nil || string(got) != requestBody { + t.Fatalf("login body changed: %q, err=%v", got, err) + } + w.Header().Set("Content-Type", "application/json") + _, _ = io.WriteString(w, responseBody) + }))) + request := httptest.NewRequest(http.MethodPost, "/api/staff/auth/login", strings.NewReader(requestBody)) + request.Pattern = "POST /api/staff/auth/login" + request.Header.Set("Content-Type", "application/json") + request.Header.Set("X-Request-ID", "login-request") + recorder := httptest.NewRecorder() + + handler.ServeHTTP(recorder, request) + + entry := logEntryByMessage(t, logs.Bytes(), "http request") + requestJSON := mustLogObject(t, mustLogObject(t, entry["request"], "request")["body"], "request.body") + if requestJSON["username"] != "o***l" || requestJSON["password"] != "[REDACTED]" { + t.Fatalf("login request was not sanitized: %#v", requestJSON) + } + if strings.Contains(logs.String(), username) || strings.Contains(logs.String(), password) { + t.Fatalf("login credentials leaked into log: %s", logs.String()) + } +} + +func TestAccessLogOmitsUnknownOrInvalidRequestFields(t *testing.T) { + const ( + password = "password-sentinel" + privateNote = "private-note-sentinel" + camelSurname = "林" + numericPhone = "13787654321" + ) + requestBody := `{"username":"operator","password":"` + password + `","note":"` + privateNote + + `","lastName":"` + camelSurname + `","phone":` + numericPhone + `}` + + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + handler := server.requestID(server.accessLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, _ = io.ReadAll(r.Body) + writeError(w, &apiError{Status: http.StatusBadRequest, Code: "INVALID_JSON", Message: "请求内容格式不正确"}) + }))) + request := httptest.NewRequest(http.MethodPost, "/api/staff/auth/login", strings.NewReader(requestBody)) + request.Pattern = "POST /api/staff/auth/login" + request.Header.Set("Content-Type", "application/json") + request.Header.Set("X-Request-ID", "invalid-request") + recorder := httptest.NewRecorder() + + handler.ServeHTTP(recorder, request) + + entry := logEntryByMessage(t, logs.Bytes(), "http request") + requestLog := mustLogObject(t, entry["request"], "request") + if requestLog["body_omitted"] != "invalid_or_unsupported_request_json" { + t.Fatalf("invalid body omission = %#v", requestLog) + } + if _, ok := requestLog["body"]; ok { + t.Fatalf("invalid request body was logged: %#v", requestLog) + } + for _, secret := range []string{password, privateNote, camelSurname, numericPhone} { + if strings.Contains(logs.String(), secret) { + t.Fatalf("invalid request leaked %q: %s", secret, logs.String()) + } + } +} + +func TestAccessLogOnlyLogsAllowedHistoryQueryParameters(t *testing.T) { + const ( + phone = "+1 (202) 555-1234" + unknownSecret = "unknown-query-sentinel" + ) + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + handler := server.requestID(server.accessLog(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + writeJSON(w, http.StatusOK, map[string]any{"tickets": []any{}}) + }))) + request := httptest.NewRequest(http.MethodGet, + "/api/admin/history/tickets?from=2026-07-01&to=2026-07-28&query=%2B1+%28202%29+555-1234&page=2&unknown="+unknownSecret, + nil) + request.Pattern = "GET /api/admin/history/tickets" + request.Header.Set("X-Request-ID", "query-request") + recorder := httptest.NewRecorder() + + handler.ServeHTTP(recorder, request) + + entry := logEntryByMessage(t, logs.Bytes(), "http request") + query := mustLogObject(t, mustLogObject(t, entry["request"], "request")["query"], "request.query") + if values := mustLogArray(t, query["query"], "request.query.query"); values[0] != "****1234" { + t.Fatalf("history phone query = %#v", values[0]) + } + if query["_omitted_parameter_count"] != float64(1) { + t.Fatalf("omitted query count = %#v", query["_omitted_parameter_count"]) + } + if strings.Contains(logs.String(), phone) || strings.Contains(logs.String(), unknownSecret) { + t.Fatalf("history query leaked into log: %s", logs.String()) + } +} + +func TestAccessLogTruncatesLargeBodiesWithoutChangingExchange(t *testing.T) { + requestBody := `{"visitor_notice":"REQUEST-LARGE-SENTINEL-` + strings.Repeat("x", 128<<10) + `"}` + responseBody := `{"note":"RESPONSE-LARGE-SENTINEL-` + strings.Repeat("y", 128<<10) + `"}` + + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + handler := server.requestID(server.accessLog(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + got, err := io.ReadAll(r.Body) + if err != nil { + t.Fatalf("read request body: %v", err) + } + if string(got) != requestBody { + t.Fatalf("handler received %d bytes, want %d", len(got), len(requestBody)) + } + w.Header().Set("Content-Type", "application/json") + if _, err := io.WriteString(w, responseBody); err != nil { + t.Fatalf("write response: %v", err) + } + }))) + + request := httptest.NewRequest(http.MethodPut, "/api/admin/projects/11111111-1111-4111-8111-111111111111/settings", strings.NewReader(requestBody)) + request.Pattern = "PUT /api/admin/projects/{id}/settings" + request.SetPathValue("id", "11111111-1111-4111-8111-111111111111") + request.Header.Set("Content-Type", "application/json") + request.Header.Set("X-Request-ID", "request-large") + recorder := httptest.NewRecorder() + + handler.ServeHTTP(recorder, request) + + if recorder.Body.String() != responseBody { + t.Fatalf("client received %d bytes, want %d", recorder.Body.Len(), len(responseBody)) + } + entry := logEntryByMessage(t, logs.Bytes(), "http request") + requestLog := mustLogObject(t, entry["request"], "request") + responseLog := mustLogObject(t, entry["response"], "response") + if requestLog["body_truncated"] != true || responseLog["body_truncated"] != true { + t.Fatalf("truncation flags missing: request=%#v response=%#v", requestLog, responseLog) + } + if _, ok := requestLog["body"]; ok { + t.Fatalf("truncated request body should not be logged: %#v", requestLog) + } + if _, ok := responseLog["body"]; ok { + t.Fatalf("truncated response body should not be logged: %#v", responseLog) + } + if strings.Contains(logs.String(), "REQUEST-LARGE-SENTINEL") || + strings.Contains(logs.String(), "RESPONSE-LARGE-SENTINEL") { + t.Fatalf("large body content leaked into log") + } +} + +func TestStatusRecorderKeepsFirstWireStatus(t *testing.T) { + recorder := httptest.NewRecorder() + status := &statusRecorder{ResponseWriter: recorder, status: http.StatusOK} + status.WriteHeader(http.StatusCreated) + status.WriteHeader(http.StatusInternalServerError) + + if status.status != http.StatusCreated { + t.Fatalf("recorded status = %d, want 201", status.status) + } + if recorder.Code != http.StatusCreated { + t.Fatalf("wire status = %d, want 201", recorder.Code) + } +} + +func TestAccessLogDoesNotAdvertiseUnsupportedFlusher(t *testing.T) { + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + handler := server.requestID(server.accessLog(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + if _, ok := w.(http.Flusher); ok { + t.Fatal("wrapped writer advertised unsupported http.Flusher") + } + writeJSON(w, http.StatusOK, map[string]any{"status": "ok"}) + }))) + request := httptest.NewRequest(http.MethodGet, "/api/public/projects", nil) + request.Pattern = "GET /api/public/projects" + request.Header.Set("X-Request-ID", "writer-request") + recorder := &nonFlushingResponseWriter{header: make(http.Header)} + + handler.ServeHTTP(recorder, request) + + if recorder.status != http.StatusOK || recorder.body.String() != "{\"status\":\"ok\"}\n" { + t.Fatalf("wrapped response changed: status=%d body=%q", recorder.status, recorder.body.String()) + } +} + +func TestRecoveredPanicHasRequestIDAndAccessLog(t *testing.T) { + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + request := httptest.NewRequest(http.MethodGet, "/readyz", nil) + request.Header.Set("X-Request-ID", "panic-request") + recorder := httptest.NewRecorder() + + server.Handler().ServeHTTP(recorder, request) + + if recorder.Code != http.StatusInternalServerError { + t.Fatalf("panic status = %d, want 500", recorder.Code) + } + panicEntry := logEntryByMessage(t, logs.Bytes(), "panic recovered") + accessEntry := logEntryByMessage(t, logs.Bytes(), "http request") + if panicEntry["request_id"] != "panic-request" || accessEntry["request_id"] != "panic-request" { + t.Fatalf("request ids: panic=%#v access=%#v", panicEntry["request_id"], accessEntry["request_id"]) + } + if accessEntry["status"] != float64(http.StatusInternalServerError) { + t.Fatalf("access status = %#v, want 500", accessEntry["status"]) + } +} + +func TestRecoveredPanicAfterWriteDoesNotAppendErrorBody(t *testing.T) { + const responseBody = `{"status":"started"}` + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + handler := server.requestID(server.accessLog(server.recoverPanic(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusOK) + _, _ = io.WriteString(w, responseBody) + panic("panic-after-write") + })))) + request := httptest.NewRequest(http.MethodGet, "/api/public/projects", nil) + request.Pattern = "GET /api/public/projects" + request.Header.Set("X-Request-ID", "panic-after-write") + recorder := httptest.NewRecorder() + + handler.ServeHTTP(recorder, request) + + if recorder.Code != http.StatusOK || recorder.Body.String() != responseBody { + t.Fatalf("panic changed committed response: status=%d body=%q", recorder.Code, recorder.Body.String()) + } + panicEntry := logEntryByMessage(t, logs.Bytes(), "panic recovered") + accessEntry := logEntryByMessage(t, logs.Bytes(), "http request") + if panicEntry["response_started"] != true || accessEntry["status"] != float64(http.StatusOK) { + t.Fatalf("panic/access metadata: panic=%#v access=%#v", panicEntry, accessEntry) + } +} + +func TestHandlerLogsTokenRoutesUsingTemplates(t *testing.T) { + tests := []struct { + name string + path string + wantPath string + }{ + { + name: "visitor status token", + path: "/api/public/status/visitor-token-sentinel", + wantPath: "/api/public/status/{token}", + }, + { + name: "display token", + path: "/api/display/display-token-sentinel/snapshot", + wantPath: "/api/display/{token}/snapshot", + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + request := httptest.NewRequest(http.MethodGet, test.path, nil) + request.Header.Set("X-Request-ID", "token-request") + recorder := httptest.NewRecorder() + + server.Handler().ServeHTTP(recorder, request) + + entry := logEntryByMessage(t, logs.Bytes(), "http request") + if entry["path"] != test.wantPath { + t.Fatalf("path = %#v, want %q", entry["path"], test.wantPath) + } + if strings.Contains(logs.String(), "token-sentinel") { + t.Fatalf("token path leaked into log: %s", logs.String()) + } + }) + } +} + +func TestAccessLogOmitsEventStreamAndCSVResponseBodies(t *testing.T) { + tests := []struct { + name string + method string + path string + pattern string + contentType string + body string + wantReason string + flush bool + }{ + { + name: "event stream", + method: http.MethodGet, + path: "/api/events?project_id=project-1", + pattern: "GET /api/events", + contentType: "text/event-stream", + body: "data: STREAM-SENTINEL\n\n", + wantReason: "event_stream", + flush: true, + }, + { + name: "personal CSV export", + method: http.MethodGet, + path: "/api/admin/history/export.csv?include_personal=true&confirm=true", + pattern: "GET /api/admin/history/export.csv", + contentType: "text/csv; charset=utf-8", + body: "phone,last_name\n13912345678,林\n", + wantReason: "file_download", + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + var logs bytes.Buffer + server := &Server{ + logger: slog.New(slog.NewJSONHandler(&logs, nil)), + now: time.Now, + } + handler := server.requestID(server.accessLog(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Type", test.contentType) + if _, err := io.WriteString(w, test.body); err != nil { + t.Fatalf("write response: %v", err) + } + if test.flush { + flusher, ok := w.(http.Flusher) + if !ok { + t.Fatal("response writer lost http.Flusher") + } + flusher.Flush() + } + }))) + request := httptest.NewRequest(test.method, test.path, nil) + request.Pattern = test.pattern + request.Header.Set("X-Request-ID", "omit-request") + recorder := httptest.NewRecorder() + + handler.ServeHTTP(recorder, request) + + if recorder.Body.String() != test.body { + t.Fatalf("response body changed: got %q", recorder.Body.String()) + } + entry := logEntryByMessage(t, logs.Bytes(), "http request") + responseLog := mustLogObject(t, entry["response"], "response") + if responseLog["body_omitted"] != test.wantReason { + t.Fatalf("body omission = %#v, want %q", responseLog["body_omitted"], test.wantReason) + } + if strings.Contains(logs.String(), "STREAM-SENTINEL") || + strings.Contains(logs.String(), "13912345678") || + strings.Contains(logs.String(), "林") { + t.Fatalf("omitted response body leaked into log: %s", logs.String()) + } + }) + } +} + +func logEntryByMessage(t *testing.T, content []byte, message string) map[string]any { + t.Helper() + for _, line := range bytes.Split(bytes.TrimSpace(content), []byte("\n")) { + var entry map[string]any + if err := json.Unmarshal(line, &entry); err != nil { + t.Fatalf("decode log entry: %v\n%s", err, line) + } + if entry["msg"] == message { + return entry + } + } + t.Fatalf("log message %q not found:\n%s", message, content) + return nil +} + +func mustLogObject(t *testing.T, value any, name string) map[string]any { + t.Helper() + object, ok := value.(map[string]any) + if !ok { + t.Fatalf("%s = %#v, want object", name, value) + } + return object +} + +func mustLogArray(t *testing.T, value any, name string) []any { + t.Helper() + array, ok := value.([]any) + if !ok { + t.Fatalf("%s = %#v, want array", name, value) + } + return array +} + +type nonFlushingResponseWriter struct { + header http.Header + body bytes.Buffer + status int +} + +func (writer *nonFlushingResponseWriter) Header() http.Header { + return writer.header +} + +func (writer *nonFlushingResponseWriter) WriteHeader(status int) { + if writer.status == 0 { + writer.status = status + } +} + +func (writer *nonFlushingResponseWriter) Write(value []byte) (int, error) { + if writer.status == 0 { + writer.status = http.StatusOK + } + return writer.body.Write(value) +} diff --git a/server/internal/httpapi/staff.go b/server/internal/httpapi/staff.go index c0172ca..2997473 100644 --- a/server/internal/httpapi/staff.go +++ b/server/internal/httpapi/staff.go @@ -298,7 +298,7 @@ func (s *Server) createTicketForActor(w http.ResponseWriter, r *http.Request, ac phoneDigest := s.cipher.Digest(phone) var duplicates []model.QueueTicket if err := tx.Select("id", "display_number", "status"). - Where("project_id = ? AND phone_hmac = ? AND status IN ?", projectID, phoneDigest, + Where("project_id = ? AND queue_session_id = ? AND phone_hmac = ? AND status IN ?", projectID, session.ID, phoneDigest, []string{model.TicketWaiting, model.TicketCalled, model.TicketArrived}). Order("joined_at ASC").Find(&duplicates).Error; err != nil { return err diff --git a/task_plan.md b/task_plan.md index b1dcad1..914b37a 100644 --- a/task_plan.md +++ b/task_plan.md @@ -516,3 +516,18 @@ Phase 42（运营统计模块标题区呼吸空间优化） - [x] 补齐定时、手动关闭、文案和滚动布局回归测试 - [x] 通过前端测试、类型检查、生产构建和视觉验收 - **Status:** complete + +### Phase 43: 关键接口结构化出入参日志（2026-07-28） +- [x] 盘点关键 API、既有访问日志与敏感字段 +- [x] 为统一日志中间件补充请求/响应捕获回归测试 +- [x] 实现 JSON 出入参、查询参数脱敏与日志大小限制 +- [x] 排除流式事件、文件导出和健康检查等不适合记录正文的接口 +- [x] 完成 Go 全量测试、静态检查与隐私泄漏扫描 +- **Status:** complete + +#### Errors Encountered +| Error | Attempt | Resolution | +|---|---:|---| +| PowerShell 中复杂 `rg` 正则的双引号终止符与字符类转义失败 | 2 | 拆成单引号、小范围查询后完成敏感字段盘点 | +| 新增日志回归首次运行按预期失败：原始路径泄露、无正文、状态码被覆盖、panic 无访问日志 | 1 | 实现模板路径、旁路捕获、首次状态保护并调整中间件顺序，聚焦测试转绿 | +| Windows Go 环境关闭 CGO，`go test -race` 无法启动 | 1 | 不重复同一失败；使用全量测试、聚焦并发安全审查、`go vet` 和构建完成本轮验证 |