From 5812386676bfc320a107e53162dcab4edf54f5f1 Mon Sep 17 00:00:00 2001 From: Josh Creek <8179928+jcreek@users.noreply.github.com> Date: Tue, 1 Sep 2026 16:14:20 +0100 Subject: [PATCH] feat(observability): log authenticated read routes --- multiplayer-next.md | 2 ++ server/api/service.go | 23 ++++++++++++++--- server/api/service_test.go | 51 ++++++++++++++++++++++++++++++++++++++ 3 files changed, 73 insertions(+), 3 deletions(-) diff --git a/multiplayer-next.md b/multiplayer-next.md index a0c294b4..9534f9c0 100644 --- a/multiplayer-next.md +++ b/multiplayer-next.md @@ -1400,3 +1400,5 @@ Allocated Godot startup now derives its `min-players` floor from the verified si The former display-name reclaim weakness (flagged item C) is now closed for allocated matches: the signed `PlayerID` is retained in the server roster and slot, and both reconnect reclaim and late-join promotion carry that stable identity across peer-id changes. Display-name matching remains only as a legacy fallback for unauthenticated direct servers. A focused adversarial unit test covers changed names, same-name impostors, missing identities, and the direct-server fallback. Allocated supervisor launch arguments now have a direct regression guard: authoritative match/server/image/assignment-expiry values replace stale child placeholders without mutating the caller’s command slice or disturbing unrelated arguments; dynamic Agones port propagation remains covered by the existing startup test. This closes the local implementation portion of task 8.29; live Agones passthrough/NAT and multi-match validation remain infrastructure gates. + +Read-only authenticated queue, proposal, assignment, legacy profile, and ranked-profile routes now emit lifecycle-safe observability events for successful, rejected, and not-found reads. An API regression exercises all five real HTTP routes and verifies the event set; event fields remain free of credentials. This closes the local read-route portion of task 8.44; metrics/traces export, dashboards, and alert routing remain operational work. diff --git a/server/api/service.go b/server/api/service.go index a52b6ef1..86041dde 100644 --- a/server/api/service.go +++ b/server/api/service.go @@ -124,7 +124,7 @@ type Service struct { TierPolicy domain.TierPolicy RateLimiter *RateLimiter // Log receives a credential-safe structured event for lifecycle-relevant - // mutations (currently: server registration and result submission). Nil + // reads and mutations. 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) @@ -601,15 +601,18 @@ func (s *Service) queueMutation(w http.ResponseWriter, r *http.Request) { } var ticket domain.QueueTicket var err error + now := s.now() if s.QueueBackend != nil { - ticket, err = s.QueueBackend.Get(r.Context(), playerID, parts[0], s.now()) + ticket, err = s.QueueBackend.Get(r.Context(), playerID, parts[0], now) } else { - ticket, err = s.Queue.Get(playerID, parts[0], s.now()) + ticket, err = s.Queue.Get(playerID, parts[0], now) } if err != nil { + s.logEvent(observability.Event{Event: "queue_get", QueueID: parts[0], Stage: "rejected", OccurredAt: now}) writeDomainError(w, err) return } + s.logEvent(observability.Event{Event: "queue_get", QueueID: ticket.TicketID, Stage: strings.ToLower(string(ticket.State)), OccurredAt: now}) writeJSON(w, http.StatusOK, toQueueResponse(ticket)) return } @@ -695,6 +698,7 @@ func (s *Service) proposalMutation(w http.ResponseWriter, r *http.Request) { if s.ProposalBackend != nil { proposalValue, providerErr := s.ProposalBackend.Get(r.Context(), playerID, parts[0], s.now()) if providerErr != nil { + s.logEvent(observability.Event{Event: "proposal_get", ProposalID: parts[0], Stage: "rejected", OccurredAt: s.now()}) writeError(w, http.StatusNotFound, "not_found") return } @@ -702,6 +706,7 @@ func (s *Service) proposalMutation(w http.ResponseWriter, r *http.Request) { exists = true } if !exists || proposal == nil || !proposal.HasParticipant(playerID) { + s.logEvent(observability.Event{Event: "proposal_get", ProposalID: parts[0], Stage: "rejected", OccurredAt: s.now()}) writeError(w, http.StatusNotFound, "not_found") return } @@ -709,6 +714,7 @@ func (s *Service) proposalMutation(w http.ResponseWriter, r *http.Request) { if proposal.Expire(now) { s.publishProposalEvent(*proposal, now) } + s.logEvent(observability.Event{Event: "proposal_get", ProposalID: proposal.ProposalID, Stage: strings.ToLower(string(proposal.State)), OccurredAt: now}) writeJSON(w, http.StatusOK, toProposalResponse(*proposal)) return } @@ -776,20 +782,24 @@ func (s *Service) assignment(w http.ResponseWriter, r *http.Request) { return } if s.Assignment == nil { + s.logEvent(observability.Event{Event: "assignment_get", MatchID: parts[0], Stage: "rejected", OccurredAt: s.now()}) writeError(w, http.StatusServiceUnavailable, "assignment_unavailable") return } now := s.now() view, err := s.Assignment(r.Context(), playerID, parts[0], now) if err != nil || view.MatchID != parts[0] || view.PlayerID != playerID { + s.logEvent(observability.Event{Event: "assignment_get", MatchID: parts[0], ServerID: view.ServerID, Stage: "rejected", OccurredAt: now}) writeError(w, http.StatusNotFound, "not_found") return } if view.ServerID == "" || view.Slot < 0 || view.Slot > 5 || view.ProtocolVersion < 1 || (view.Transport != "enet" && view.Transport != "steam_sdr") || view.JoinAuthorisation == "" || !validAssignmentEndpoint(view.Endpoint) || view.ExpiresAt.IsZero() || !now.Before(view.ExpiresAt) { + s.logEvent(observability.Event{Event: "assignment_get", MatchID: parts[0], ServerID: view.ServerID, Stage: "rejected", OccurredAt: now}) writeError(w, http.StatusServiceUnavailable, "assignment_unavailable") return } _ = s.PublishControlPlaneEvent(assignmentChangedEvent(view, now)) + s.logEvent(observability.Event{Event: "assignment_get", MatchID: view.MatchID, ServerID: view.ServerID, Stage: "assignment_ready", OccurredAt: now}) writeJSON(w, http.StatusOK, view) } @@ -830,13 +840,16 @@ func (s *Service) profile(w http.ResponseWriter, r *http.Request) { } profile, exists, err := s.rankedProfileFor(r.Context(), playerID) if err != nil { + s.logEvent(observability.Event{Event: "profile_get", Stage: "rejected", OccurredAt: s.now()}) writeError(w, http.StatusServiceUnavailable, "ranked_profile_unavailable") return } if !exists { + s.logEvent(observability.Event{Event: "profile_get", Stage: "not_found", OccurredAt: s.now()}) writeError(w, http.StatusNotFound, "not_found") return } + s.logEvent(observability.Event{Event: "profile_get", Stage: "ok", OccurredAt: s.now()}) writeJSON(w, http.StatusOK, map[string]any{ "player_id": playerID, "rating": profile.Value, @@ -856,18 +869,22 @@ func (s *Service) rankedProfile(w http.ResponseWriter, r *http.Request) { } profile, exists, err := s.rankedProfileFor(r.Context(), playerID) if err != nil { + s.logEvent(observability.Event{Event: "ranked_profile_get", Stage: "rejected", OccurredAt: s.now()}) writeError(w, http.StatusServiceUnavailable, "ranked_profile_unavailable") return } if !exists { + s.logEvent(observability.Event{Event: "ranked_profile_get", Stage: "not_found", OccurredAt: s.now()}) writeError(w, http.StatusNotFound, "not_found") return } tier, err := domain.RankedTier(profile, s.TierPolicy) if err != nil { + s.logEvent(observability.Event{Event: "ranked_profile_get", Stage: "rejected", OccurredAt: s.now()}) writeError(w, http.StatusServiceUnavailable, "ranked_profile_unavailable") return } + s.logEvent(observability.Event{Event: "ranked_profile_get", Stage: "ok", OccurredAt: s.now()}) writeJSON(w, http.StatusOK, rankedProfileResponse{Rating: profile.Value, RD: profile.RD, Volatility: profile.Volatility, RankedGames: profile.RankedGames, Tier: string(tier), Provisional: domain.RankedIsProvisional(profile), SeasonID: profile.LastSeasonID}) } diff --git a/server/api/service_test.go b/server/api/service_test.go index c5e6a045..c3f95206 100644 --- a/server/api/service_test.go +++ b/server/api/service_test.go @@ -961,6 +961,57 @@ func TestQueueRecoveryAPIIsAuthenticatedOwnerOnlyAndExpiresStaleTickets(t *testi _ = response.Body.Close() } +func TestReadOnlyAPIsEmitLifecycleEvents(t *testing.T) { + now := time.Unix(1000, 0).UTC() + sessions := domain.NewSessionStore() + session, token, err := sessions.Issue("player-a", time.Hour, now) + if err != nil { + t.Fatal(err) + } + queue := domain.NewQueue() + if _, err := queue.Create("player-a", "ticket-read-123456", "create-read-123456", domain.Candidate{PlayerID: "player-a", TicketID: "ticket-read-123456", Playlist: domain.Casual, EnqueuedAt: now}, now); err != nil { + t.Fatal(err) + } + proposal, err := domain.NewProposal("proposal-read-123456", domain.Casual, []string{"player-a", "player-b"}, now) + if err != nil { + t.Fatal(err) + } + events := make([]observability.Event, 0) + service := &Service{ + Sessions: sessions, Queue: queue, Proposals: map[string]*domain.Proposal{proposal.ProposalID: &proposal}, + RankedProfiles: map[string]domain.RankedProfile{"player-a": {Rating: domain.Rating{Value: 1500, RD: 100, Volatility: 0.06}}}, + TierPolicy: domain.DefaultTierPolicy(), Now: func() time.Time { return now }, + Assignment: func(_ context.Context, playerID, matchID string, _ time.Time) (AssignmentView, error) { + return AssignmentView{MatchID: matchID, PlayerID: playerID, ServerID: "server-read", Slot: 0, ProtocolVersion: 1, Transport: "enet", Endpoint: "127.0.0.1:30001", JoinAuthorisation: "join-token", ExpiresAt: now.Add(time.Minute)}, nil + }, + Log: func(event observability.Event) { events = append(events, event) }, + } + server := httptest.NewServer(service.Handler()) + defer server.Close() + auth := "Bearer " + session.SessionID + ":" + token + for _, path := range []string{"/v1/queue/ticket-read-123456", "/v1/proposals/proposal-read-123456", "/v1/assignments/match-read-123456", "/api/v1/profile", "/v1/profile/ranked"} { + req, _ := http.NewRequest(http.MethodGet, server.URL+path, nil) + req.Header.Set("Authorization", auth) + response, requestErr := http.DefaultClient.Do(req) + if requestErr != nil { + t.Fatal(requestErr) + } + if response.StatusCode != http.StatusOK { + t.Fatalf("GET %s status = %d", path, response.StatusCode) + } + response.Body.Close() + } + seen := map[string]bool{} + for _, event := range events { + seen[event.Event] = true + } + for _, eventName := range []string{"queue_get", "proposal_get", "assignment_get", "profile_get", "ranked_profile_get"} { + if !seen[eventName] { + t.Fatalf("read event %q missing from %+v", eventName, events) + } + } +} + func TestAuthenticatedProposalAPIUsesRevisionAndIdempotencyPolicy(t *testing.T) { now := time.Unix(1000, 0).UTC() sessions := domain.NewSessionStore()