feat(multiplayer): extend event logging to queue and proposal mutations

Wire the same Service.Log hook added for the server register/result
routes into queue create/heartbeat/cancel and proposal accept/decline:
log the resulting state on success (queue_create, queue_heartbeat,
queue_cancel, proposal_response) or 'rejected' on a domain error,
using only the ticket/proposal ID and outcome -- never the domain
error text itself, which isn't documented as credential-free.

Read-only routes (queue GET, proposal GET, assignment fetch) and the
early availability/not-found rejections that return before reaching
the domain call are deliberately not logged in this pass.

Covered by a new end-to-end test driving real create/heartbeat/cancel
and an accept followed by a stale-revision accept (fenced for real by
the domain layer behind proposalBackendSpy, unlike the dumb queue
spy), asserting the exact sequence of events logged.
This commit is contained in:
Josh Creek
2026-09-01 13:10:08 +01:00
parent 1490ff7fcf
commit 4eaa3304c3
2 changed files with 121 additions and 0 deletions
+34
View File
@@ -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")
+87
View File
@@ -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"}