diff --git a/server/api/service.go b/server/api/service.go index d7b5ef4e..d0ffc3c8 100644 --- a/server/api/service.go +++ b/server/api/service.go @@ -134,6 +134,28 @@ func (s *Service) logEvent(event observability.Event) { } } +// logQueueOutcome logs a queue-ticket mutation's result: the ticket's +// resulting state on success, or "rejected" on a domain error. It never logs +// the error text itself -- domain errors here are not documented as +// credential-free, and the stage name already tells an operator what to look +// up (the ticket ID, still recorded either way). +func (s *Service) logQueueOutcome(event, ticketID string, ticket domain.QueueTicket, err error, now time.Time) { + if err != nil { + s.logEvent(observability.Event{Event: event, QueueID: ticketID, Stage: "rejected", OccurredAt: now}) + return + } + s.logEvent(observability.Event{Event: event, QueueID: ticket.TicketID, Stage: strings.ToLower(string(ticket.State)), OccurredAt: now}) +} + +// logProposalOutcome mirrors logQueueOutcome for proposal accept/decline. +func (s *Service) logProposalOutcome(proposalID string, proposal domain.Proposal, err error, now time.Time) { + if err != nil { + s.logEvent(observability.Event{Event: "proposal_response", ProposalID: proposalID, Stage: "rejected", OccurredAt: now}) + return + } + s.logEvent(observability.Event{Event: "proposal_response", ProposalID: proposal.ProposalID, Stage: strings.ToLower(string(proposal.State)), OccurredAt: now}) +} + func (s *Service) Handler() http.Handler { mux := http.NewServeMux() mux.HandleFunc("/healthz", s.health) @@ -263,9 +285,11 @@ func (s *Service) queueCreate(w http.ResponseWriter, r *http.Request) { if s.QueueBackend != nil { ticket, err := s.QueueBackend.Create(r.Context(), playerID, input.TicketID, key, spec, now) if err != nil { + s.logQueueOutcome("queue_create", input.TicketID, ticket, err, now) writeDomainError(w, err) return } + s.logQueueOutcome("queue_create", input.TicketID, ticket, nil, now) s.projectCandidate(r.Context(), ticket) s.publishTicketEvent(ticket, now) writeJSON(w, http.StatusCreated, toQueueResponse(ticket)) @@ -293,9 +317,11 @@ func (s *Service) queueCreate(w http.ResponseWriter, r *http.Request) { } ticket, err := s.Queue.Create(playerID, input.TicketID, key, candidate, now) if err != nil { + s.logQueueOutcome("queue_create", input.TicketID, ticket, err, now) writeDomainError(w, err) return } + s.logQueueOutcome("queue_create", input.TicketID, ticket, nil, now) s.projectCandidate(r.Context(), ticket) s.publishTicketEvent(ticket, now) writeJSON(w, http.StatusCreated, toQueueResponse(ticket)) @@ -581,10 +607,16 @@ func (s *Service) queueMutation(w http.ResponseWriter, r *http.Request) { ticket, err = s.Queue.Cancel(playerID, ticketID, key, revision, now) } } + eventName := "queue_heartbeat" + if parts[1] == "cancel" { + eventName = "queue_cancel" + } if err != nil { + s.logQueueOutcome(eventName, ticketID, ticket, err, now) writeDomainError(w, err) return } + s.logQueueOutcome(eventName, ticketID, ticket, nil, now) if ticket.State == domain.Cancelled { s.removeCandidate(r.Context(), ticket.TicketID) } else { @@ -679,9 +711,11 @@ func (s *Service) proposalMutation(w http.ResponseWriter, r *http.Request) { updated, err = proposal.Respond(playerID, key, parts[1] == "accept", revision, now) } if err != nil { + s.logProposalOutcome(parts[0], updated, err, now) writeDomainError(w, err) return } + s.logProposalOutcome(parts[0], updated, nil, now) if updated.State == domain.Accepted && s.ProposalPromoter != nil { if err := s.ProposalPromoter.Promote(r.Context(), updated, now); err != nil { writeError(w, http.StatusServiceUnavailable, "match_promotion_unavailable") diff --git a/server/api/service_test.go b/server/api/service_test.go index 1619a38b..4b013601 100644 --- a/server/api/service_test.go +++ b/server/api/service_test.go @@ -1150,6 +1150,93 @@ func TestServerMutationLoggingNeverLeaksRequestSecrets(t *testing.T) { } } +func TestQueueAndProposalMutationsLogLifecycleEvents(t *testing.T) { + now := time.Unix(1000, 0).UTC() + queueBackend := &queueBackendSpy{} + proposal, err := domain.NewProposal("proposal-1", domain.Casual, []string{"player-1", "player-2"}, now) + if err != nil { + t.Fatal(err) + } + proposalBackend := &proposalBackendSpy{proposal: proposal} + var captured []observability.Event + service := &Service{ + SessionBackend: &sessionBackendSpy{}, + QueueBackend: queueBackend, + ProposalBackend: proposalBackend, + Now: func() time.Time { return now }, + Log: func(event observability.Event) { captured = append(captured, event) }, + } + server := httptest.NewServer(service.Handler()) + defer server.Close() + auth := "Bearer session-1:token-1" + request := func(method, path, body string, headers map[string]string) *http.Response { + req, _ := http.NewRequest(method, server.URL+path, strings.NewReader(body)) + req.Header.Set("Authorization", auth) + for key, value := range headers { + req.Header.Set(key, value) + } + response, err := http.DefaultClient.Do(req) + if err != nil { + t.Fatal(err) + } + return response + } + + create := request(http.MethodPost, "/v1/queue", `{"ticket_id":"ticket-1","playlist":"casual","client_build":"build-1","protocol_version":1}`, map[string]string{"Idempotency-Key": "log-create-key-123456"}) + if create.StatusCode != http.StatusCreated { + t.Fatalf("create status = %d", create.StatusCode) + } + create.Body.Close() + + heartbeat := request(http.MethodPost, "/v1/queue/ticket-1/heartbeat", `{}`, map[string]string{"Idempotency-Key": "log-heartbeat-key-123456", "If-Match-Revision": "0"}) + if heartbeat.StatusCode != http.StatusOK { + t.Fatalf("heartbeat status = %d", heartbeat.StatusCode) + } + heartbeat.Body.Close() + + cancel := request(http.MethodPost, "/v1/queue/ticket-1/cancel", `{}`, map[string]string{"Idempotency-Key": "log-cancel-key-123456", "If-Match-Revision": "0"}) + if cancel.StatusCode != http.StatusOK { + t.Fatalf("cancel status = %d", cancel.StatusCode) + } + cancel.Body.Close() + + respond := request(http.MethodPost, "/v1/proposals/proposal-1/accept", `{}`, map[string]string{"Idempotency-Key": "log-respond-key-123456", "If-Match-Revision": "0"}) + if respond.StatusCode != http.StatusOK { + t.Fatalf("proposal accept status = %d", respond.StatusCode) + } + respond.Body.Close() + + // Same stale revision again -- the real domain.Proposal.Respond behind + // proposalBackendSpy fences this for real, unlike the dumb queue spy + // above, so this proves the rejection path logs too. + staleRespond := request(http.MethodPost, "/v1/proposals/proposal-1/accept", `{}`, map[string]string{"Idempotency-Key": "log-respond-key-234567", "If-Match-Revision": "0"}) + if staleRespond.StatusCode != http.StatusConflict { + t.Fatalf("stale proposal accept status = %d", staleRespond.StatusCode) + } + staleRespond.Body.Close() + + want := []struct{ event, id, stage string }{ + {"queue_create", "ticket-1", "queued"}, + {"queue_heartbeat", "ticket-1", "queued"}, + {"queue_cancel", "ticket-1", "cancelled"}, + {"proposal_response", "proposal-1", "open"}, + {"proposal_response", "proposal-1", "rejected"}, + } + if len(captured) != len(want) { + t.Fatalf("captured %d events, want %d: %+v", len(captured), len(want), captured) + } + for i, w := range want { + got := captured[i] + gotID := got.QueueID + if got.Event == "proposal_response" { + gotID = got.ProposalID + } + if got.Event != w.event || gotID != w.id || got.Stage != w.stage { + t.Fatalf("event[%d] = %+v, want {%s %s %s}", i, got, w.event, w.id, w.stage) + } + } +} + func TestServerRegistrationAPIRequiresBoundWorkloadAndValidDigest(t *testing.T) { now := time.Unix(1000, 0).UTC() binding := domain.WorkloadBinding{AllocationID: "allocation-1", MatchID: "match-1", ServerID: "server-1"}