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) }