修复bug及添加日志打印
This commit is contained in:
@@ -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`。
|
||||
|
||||
14
findings.md
14
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。
|
||||
|
||||
13
progress.md
13
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 未运行;未发现由此遗留的功能失败。
|
||||
|
||||
480
server/internal/httpapi/http_logging.go
Normal file
480
server/internal/httpapi/http_logging.go
Normal file
@@ -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])
|
||||
}
|
||||
}
|
||||
133
server/internal/httpapi/public_integration_test.go
Normal file
133
server/internal/httpapi/public_integration_test.go
Normal file
@@ -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())
|
||||
}
|
||||
}
|
||||
@@ -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))
|
||||
}
|
||||
}()
|
||||
|
||||
553
server/internal/httpapi/server_logging_test.go
Normal file
553
server/internal/httpapi/server_logging_test.go
Normal file
@@ -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)
|
||||
}
|
||||
@@ -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
|
||||
|
||||
15
task_plan.md
15
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` 和构建完成本轮验证 |
|
||||
|
||||
Reference in New Issue
Block a user