diff --git a/server/api/service.go b/server/api/service.go index a4698241..d7b5ef4e 100644 --- a/server/api/service.go +++ b/server/api/service.go @@ -19,6 +19,7 @@ import ( "time" "github.com/cosmic-clash/cosmic-clash/server/domain" + "github.com/cosmic-clash/cosmic-clash/server/observability" ) const maxBodyBytes = 8 << 10 @@ -116,9 +117,21 @@ type Service struct { RankedProfiles map[string]domain.RankedProfile TierPolicy domain.TierPolicy RateLimiter *RateLimiter - proposalMu sync.Mutex - eventsMu sync.Mutex - events *eventHub + // Log receives a credential-safe structured event for lifecycle-relevant + // mutations (currently: server registration and result submission). Nil + // is a valid, silent no-op -- every call site must stay optional so + // existing Service literals that don't set it keep working unchanged. + Log func(observability.Event) + proposalMu sync.Mutex + eventsMu sync.Mutex + events *eventHub +} + +// logEvent is a nil-safe wrapper so call sites never need their own guard. +func (s *Service) logEvent(event observability.Event) { + if s.Log != nil { + s.Log(event) + } } func (s *Service) Handler() http.Handler { @@ -431,6 +444,7 @@ func (s *Service) serverMutation(w http.ResponseWriter, r *http.Request) { now := s.now() binding, err := s.WorkloadVerify(partsAuth[1], now) if err != nil || binding.ServerID != parts[0] { + s.logEvent(observability.Event{Event: "server_" + parts[1], ServerID: parts[0], Stage: "unauthorized", OccurredAt: now}) writeError(w, http.StatusUnauthorized, "unauthorized") return } @@ -440,17 +454,26 @@ func (s *Service) serverMutation(w http.ResponseWriter, r *http.Request) { return } if input.MatchID == "" || input.MatchID != binding.MatchID || input.ProtocolVersion < 1 || !validImageDigest(input.ImageDigest) { + s.logEvent(observability.Event{Event: "server_register", MatchID: binding.MatchID, ServerID: parts[0], Stage: "rejected", OccurredAt: now}) writeError(w, http.StatusUnprocessableEntity, "invalid_request") return } if err := s.ServerRegistrar.RegisterServer(r.Context(), binding, input.ProtocolVersion, input.AssignmentReady, key, now); err != nil { + stage := "invalid" if errors.Is(err, domain.ErrConflict) { + stage = "conflict" writeError(w, http.StatusConflict, "conflict") } else { writeError(w, http.StatusUnprocessableEntity, "invalid_request") } + s.logEvent(observability.Event{Event: "server_register", MatchID: binding.MatchID, ServerID: parts[0], Stage: stage, OccurredAt: now}) return } + readyStage := "process_ready" + if input.AssignmentReady { + readyStage = "assignment_ready" + } + s.logEvent(observability.Event{Event: "server_register", MatchID: binding.MatchID, ServerID: parts[0], Stage: readyStage, OccurredAt: now, Fields: map[string]any{"protocol_version": input.ProtocolVersion}}) w.WriteHeader(http.StatusNoContent) return } @@ -459,6 +482,7 @@ func (s *Service) serverMutation(w http.ResponseWriter, r *http.Request) { return } if input.MatchID == "" || binding.MatchID != input.MatchID || len(input.ResultNonce) < 16 || len(input.ResultNonce) > 128 || input.Score.Team0 < 0 || input.Score.Team1 < 0 || (input.IntegrityState != domain.IntegrityCertified && input.IntegrityState != domain.IntegritySuppressed && input.IntegrityState != domain.IntegrityReview) { + s.logEvent(observability.Event{Event: "server_result", MatchID: binding.MatchID, ServerID: parts[0], Stage: "rejected", OccurredAt: now}) writeError(w, http.StatusUnprocessableEntity, "invalid_request") return } @@ -469,13 +493,17 @@ func (s *Service) serverMutation(w http.ResponseWriter, r *http.Request) { return } if err := s.ResultSubmitter.SubmitResult(r.Context(), key, result, binding, payload, now); err != nil { + stage := "invalid" if errors.Is(err, domain.ErrResultConflict) || strings.Contains(err.Error(), "conflict") { + stage = "conflict" writeError(w, http.StatusConflict, "conflict") } else { writeError(w, http.StatusUnprocessableEntity, "invalid_request") } + s.logEvent(observability.Event{Event: "server_result", MatchID: binding.MatchID, ServerID: parts[0], Stage: stage, OccurredAt: now}) return } + s.logEvent(observability.Event{Event: "server_result", MatchID: binding.MatchID, ServerID: parts[0], Stage: "accepted", OccurredAt: now, Fields: map[string]any{"integrity_state": string(input.IntegrityState), "team_0": input.Score.Team0, "team_1": input.Score.Team1}}) w.WriteHeader(http.StatusAccepted) } diff --git a/server/api/service_test.go b/server/api/service_test.go index 8858ae3d..1619a38b 100644 --- a/server/api/service_test.go +++ b/server/api/service_test.go @@ -2,10 +2,12 @@ package api import ( "bufio" + "bytes" "context" "encoding/binary" "encoding/json" "errors" + "fmt" "io" "net" "net/http" @@ -15,6 +17,7 @@ import ( "time" "github.com/cosmic-clash/cosmic-clash/server/domain" + "github.com/cosmic-clash/cosmic-clash/server/observability" ) type queueBackendSpy struct{ createCalls, heartbeatCalls, cancelCalls, getCalls int } @@ -1067,6 +1070,86 @@ func TestContractServerRoutesAdaptTwoSegmentPaths(t *testing.T) { response.Body.Close() } +// TestServerMutationLoggingNeverLeaksRequestSecrets is a secret canary: it +// drives the register and result routes end to end with realistic-looking +// bearer tokens and a result nonce, captures every event actually emitted +// through Service.Log during those real requests, and asserts the literal +// secret values never appear anywhere in the encoded output -- not just that +// observability.redact() strips a synthetic value under a known key name (see +// TestEncodeCorrelatesStagesAndRedactsNestedCredentials in the observability +// package for that narrower unit test). +func TestServerMutationLoggingNeverLeaksRequestSecrets(t *testing.T) { + const bearerToken = "wl-canary-secret-do-not-log-9f8e7d6c5b4a" + const resultNonce = "nonce-canary-secret-value-1a2b3c4d5e6f" + now := time.Unix(1000, 0).UTC() + binding := domain.WorkloadBinding{AllocationID: "allocation-1", MatchID: "match-1", ServerID: "server-1"} + registrar := &serverRegistrarSpy{} + submitter := &resultSubmitterSpy{} + var captured [][]byte + service := &Service{ + Now: func() time.Time { return now }, + WorkloadVerify: func(token string, _ time.Time) (domain.WorkloadBinding, error) { + if token != bearerToken { + return domain.WorkloadBinding{}, errors.New("bad token") + } + return binding, nil + }, + ServerRegistrar: registrar, + ResultSubmitter: submitter, + Log: func(event observability.Event) { + payload, err := observability.Encode(event) + if err != nil { + t.Fatalf("encode event: %v", err) + } + captured = append(captured, payload) + }, + } + server := httptest.NewServer(service.Handler()) + defer server.Close() + + registerBody := `{"match_id":"match-1","protocol_version":1,"image_digest":"sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa","assignment_ready":true}` + req, _ := http.NewRequest(http.MethodPost, server.URL+"/v1/servers/server-1/register", strings.NewReader(registerBody)) + req.Header.Set("Authorization", "Bearer "+bearerToken) + req.Header.Set("Idempotency-Key", "canary-register-key-1") + response, err := http.DefaultClient.Do(req) + if err != nil || response.StatusCode != http.StatusNoContent { + t.Fatalf("register status=%v err=%v", response.StatusCode, err) + } + response.Body.Close() + + resultBody := fmt.Sprintf(`{"match_id":"match-1","result_nonce":%q,"score":{"team_0":3,"team_1":2},"integrity_state":"CERTIFIED"}`, resultNonce) + req, _ = http.NewRequest(http.MethodPost, server.URL+"/v1/servers/server-1/result", strings.NewReader(resultBody)) + req.Header.Set("Authorization", "Bearer "+bearerToken) + req.Header.Set("Idempotency-Key", "canary-result-key-1234") + response, err = http.DefaultClient.Do(req) + if err != nil || response.StatusCode != http.StatusAccepted { + t.Fatalf("result status=%v err=%v", response.StatusCode, err) + } + response.Body.Close() + + // An unauthorized attempt must also log nothing sensitive -- it's the one + // call site handling a token that never even verified successfully. + req, _ = http.NewRequest(http.MethodPost, server.URL+"/v1/servers/server-1/register", strings.NewReader(registerBody)) + req.Header.Set("Authorization", "Bearer wrong-"+bearerToken) + req.Header.Set("Idempotency-Key", "canary-register-key-2") + response, err = http.DefaultClient.Do(req) + if err != nil || response.StatusCode != http.StatusUnauthorized { + t.Fatalf("unauthorized register status=%v err=%v", response.StatusCode, err) + } + response.Body.Close() + + if len(captured) == 0 { + t.Fatal("no events were logged; the canary can't prove anything") + } + all := string(bytes.Join(captured, []byte("\n"))) + if strings.Contains(all, bearerToken) { + t.Fatalf("bearer token leaked into logged events: %s", all) + } + if strings.Contains(all, resultNonce) { + t.Fatalf("result nonce leaked into logged events: %s", all) + } +} + func TestServerRegistrationAPIRequiresBoundWorkloadAndValidDigest(t *testing.T) { now := time.Unix(1000, 0).UTC() binding := domain.WorkloadBinding{AllocationID: "allocation-1", MatchID: "match-1", ServerID: "server-1"} diff --git a/server/cmd/control-plane/main.go b/server/cmd/control-plane/main.go index 7a22c32a..2493944d 100644 --- a/server/cmd/control-plane/main.go +++ b/server/cmd/control-plane/main.go @@ -13,6 +13,7 @@ import ( "github.com/cosmic-clash/cosmic-clash/server/api" "github.com/cosmic-clash/cosmic-clash/server/migrations" + "github.com/cosmic-clash/cosmic-clash/server/observability" "github.com/cosmic-clash/cosmic-clash/server/store" _ "github.com/jackc/pgx/v5/stdlib" "github.com/redis/go-redis/v9" @@ -90,9 +91,21 @@ func newAPIHandler(db *sql.DB, indexes ...api.CandidateIndex) http.Handler { CandidateIndex: candidateIndex, ProbeRecorder: store.PostgresQueue{DB: db}, Now: func() time.Time { return time.Now().UTC() }, + Log: logEvent, }).Handler() } +// logEvent writes one credential-safe structured event per line to stderr. +// Best-effort: a logging failure must never fail or block the request it +// describes, so encode errors are swallowed rather than surfaced. +func logEvent(event observability.Event) { + payload, err := observability.Encode(event) + if err != nil { + return + } + fmt.Fprintln(os.Stderr, string(payload)) +} + func envOrDefault(name, fallback string) string { if value := os.Getenv(name); value != "" { return value