mirror of
https://github.com/jcreek/CosmicClash.git
synced 2026-09-13 03:12:03 +00:00
feat(multiplayer): wire structured event logging into server routes
server/observability existed fully unit-tested but was imported by nothing outside its own package -- no HTTP handler ever called it, so its credential redaction protected zero real log output. Wire it into Service via an optional Log field (nil-safe, so every existing Service literal keeps compiling unchanged) and call it from the two workload-authenticated server routes -- register and result -- at every outcome: unauthorized, rejected, conflict and success. Wire cmd/control-plane to actually emit those events as JSON lines on stderr. Add a secret canary test that drives both routes end to end with realistic bearer-token and result-nonce values and asserts neither literal secret appears anywhere in what Service.Log actually received -- a stronger claim than the existing observability unit test, which only proves redact() strips a synthetic value under a denylisted key name. redact() is still key-name-based, not content-based: a future call site that logs a secret under an unlisted key name would not be caught by this test or by redact() itself, only by the same discipline applied here of never putting raw request/token bytes into Fields. Queue, proposal and assignment mutation routes are not wired yet.
This commit is contained in:
+31
-3
@@ -19,6 +19,7 @@ import (
|
|||||||
"time"
|
"time"
|
||||||
|
|
||||||
"github.com/cosmic-clash/cosmic-clash/server/domain"
|
"github.com/cosmic-clash/cosmic-clash/server/domain"
|
||||||
|
"github.com/cosmic-clash/cosmic-clash/server/observability"
|
||||||
)
|
)
|
||||||
|
|
||||||
const maxBodyBytes = 8 << 10
|
const maxBodyBytes = 8 << 10
|
||||||
@@ -116,9 +117,21 @@ type Service struct {
|
|||||||
RankedProfiles map[string]domain.RankedProfile
|
RankedProfiles map[string]domain.RankedProfile
|
||||||
TierPolicy domain.TierPolicy
|
TierPolicy domain.TierPolicy
|
||||||
RateLimiter *RateLimiter
|
RateLimiter *RateLimiter
|
||||||
proposalMu sync.Mutex
|
// Log receives a credential-safe structured event for lifecycle-relevant
|
||||||
eventsMu sync.Mutex
|
// mutations (currently: server registration and result submission). Nil
|
||||||
events *eventHub
|
// 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 {
|
func (s *Service) Handler() http.Handler {
|
||||||
@@ -431,6 +444,7 @@ func (s *Service) serverMutation(w http.ResponseWriter, r *http.Request) {
|
|||||||
now := s.now()
|
now := s.now()
|
||||||
binding, err := s.WorkloadVerify(partsAuth[1], now)
|
binding, err := s.WorkloadVerify(partsAuth[1], now)
|
||||||
if err != nil || binding.ServerID != parts[0] {
|
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")
|
writeError(w, http.StatusUnauthorized, "unauthorized")
|
||||||
return
|
return
|
||||||
}
|
}
|
||||||
@@ -440,17 +454,26 @@ func (s *Service) serverMutation(w http.ResponseWriter, r *http.Request) {
|
|||||||
return
|
return
|
||||||
}
|
}
|
||||||
if input.MatchID == "" || input.MatchID != binding.MatchID || input.ProtocolVersion < 1 || !validImageDigest(input.ImageDigest) {
|
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")
|
writeError(w, http.StatusUnprocessableEntity, "invalid_request")
|
||||||
return
|
return
|
||||||
}
|
}
|
||||||
if err := s.ServerRegistrar.RegisterServer(r.Context(), binding, input.ProtocolVersion, input.AssignmentReady, key, now); err != nil {
|
if err := s.ServerRegistrar.RegisterServer(r.Context(), binding, input.ProtocolVersion, input.AssignmentReady, key, now); err != nil {
|
||||||
|
stage := "invalid"
|
||||||
if errors.Is(err, domain.ErrConflict) {
|
if errors.Is(err, domain.ErrConflict) {
|
||||||
|
stage = "conflict"
|
||||||
writeError(w, http.StatusConflict, "conflict")
|
writeError(w, http.StatusConflict, "conflict")
|
||||||
} else {
|
} else {
|
||||||
writeError(w, http.StatusUnprocessableEntity, "invalid_request")
|
writeError(w, http.StatusUnprocessableEntity, "invalid_request")
|
||||||
}
|
}
|
||||||
|
s.logEvent(observability.Event{Event: "server_register", MatchID: binding.MatchID, ServerID: parts[0], Stage: stage, OccurredAt: now})
|
||||||
return
|
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)
|
w.WriteHeader(http.StatusNoContent)
|
||||||
return
|
return
|
||||||
}
|
}
|
||||||
@@ -459,6 +482,7 @@ func (s *Service) serverMutation(w http.ResponseWriter, r *http.Request) {
|
|||||||
return
|
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) {
|
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")
|
writeError(w, http.StatusUnprocessableEntity, "invalid_request")
|
||||||
return
|
return
|
||||||
}
|
}
|
||||||
@@ -469,13 +493,17 @@ func (s *Service) serverMutation(w http.ResponseWriter, r *http.Request) {
|
|||||||
return
|
return
|
||||||
}
|
}
|
||||||
if err := s.ResultSubmitter.SubmitResult(r.Context(), key, result, binding, payload, now); err != nil {
|
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") {
|
if errors.Is(err, domain.ErrResultConflict) || strings.Contains(err.Error(), "conflict") {
|
||||||
|
stage = "conflict"
|
||||||
writeError(w, http.StatusConflict, "conflict")
|
writeError(w, http.StatusConflict, "conflict")
|
||||||
} else {
|
} else {
|
||||||
writeError(w, http.StatusUnprocessableEntity, "invalid_request")
|
writeError(w, http.StatusUnprocessableEntity, "invalid_request")
|
||||||
}
|
}
|
||||||
|
s.logEvent(observability.Event{Event: "server_result", MatchID: binding.MatchID, ServerID: parts[0], Stage: stage, OccurredAt: now})
|
||||||
return
|
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)
|
w.WriteHeader(http.StatusAccepted)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -2,10 +2,12 @@ package api
|
|||||||
|
|
||||||
import (
|
import (
|
||||||
"bufio"
|
"bufio"
|
||||||
|
"bytes"
|
||||||
"context"
|
"context"
|
||||||
"encoding/binary"
|
"encoding/binary"
|
||||||
"encoding/json"
|
"encoding/json"
|
||||||
"errors"
|
"errors"
|
||||||
|
"fmt"
|
||||||
"io"
|
"io"
|
||||||
"net"
|
"net"
|
||||||
"net/http"
|
"net/http"
|
||||||
@@ -15,6 +17,7 @@ import (
|
|||||||
"time"
|
"time"
|
||||||
|
|
||||||
"github.com/cosmic-clash/cosmic-clash/server/domain"
|
"github.com/cosmic-clash/cosmic-clash/server/domain"
|
||||||
|
"github.com/cosmic-clash/cosmic-clash/server/observability"
|
||||||
)
|
)
|
||||||
|
|
||||||
type queueBackendSpy struct{ createCalls, heartbeatCalls, cancelCalls, getCalls int }
|
type queueBackendSpy struct{ createCalls, heartbeatCalls, cancelCalls, getCalls int }
|
||||||
@@ -1067,6 +1070,86 @@ func TestContractServerRoutesAdaptTwoSegmentPaths(t *testing.T) {
|
|||||||
response.Body.Close()
|
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) {
|
func TestServerRegistrationAPIRequiresBoundWorkloadAndValidDigest(t *testing.T) {
|
||||||
now := time.Unix(1000, 0).UTC()
|
now := time.Unix(1000, 0).UTC()
|
||||||
binding := domain.WorkloadBinding{AllocationID: "allocation-1", MatchID: "match-1", ServerID: "server-1"}
|
binding := domain.WorkloadBinding{AllocationID: "allocation-1", MatchID: "match-1", ServerID: "server-1"}
|
||||||
|
|||||||
@@ -13,6 +13,7 @@ import (
|
|||||||
|
|
||||||
"github.com/cosmic-clash/cosmic-clash/server/api"
|
"github.com/cosmic-clash/cosmic-clash/server/api"
|
||||||
"github.com/cosmic-clash/cosmic-clash/server/migrations"
|
"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/cosmic-clash/cosmic-clash/server/store"
|
||||||
_ "github.com/jackc/pgx/v5/stdlib"
|
_ "github.com/jackc/pgx/v5/stdlib"
|
||||||
"github.com/redis/go-redis/v9"
|
"github.com/redis/go-redis/v9"
|
||||||
@@ -90,9 +91,21 @@ func newAPIHandler(db *sql.DB, indexes ...api.CandidateIndex) http.Handler {
|
|||||||
CandidateIndex: candidateIndex,
|
CandidateIndex: candidateIndex,
|
||||||
ProbeRecorder: store.PostgresQueue{DB: db},
|
ProbeRecorder: store.PostgresQueue{DB: db},
|
||||||
Now: func() time.Time { return time.Now().UTC() },
|
Now: func() time.Time { return time.Now().UTC() },
|
||||||
|
Log: logEvent,
|
||||||
}).Handler()
|
}).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 {
|
func envOrDefault(name, fallback string) string {
|
||||||
if value := os.Getenv(name); value != "" {
|
if value := os.Getenv(name); value != "" {
|
||||||
return value
|
return value
|
||||||
|
|||||||
Reference in New Issue
Block a user