feat(multiplayer): export queryable API latency histograms

This commit is contained in:
Josh Creek
2026-09-01 17:21:13 +01:00
parent 20f376f713
commit 0bf33e7fe8
3 changed files with 52 additions and 8 deletions
+2 -2
View File
@@ -1243,8 +1243,8 @@ the local/CI/community transport, not a silent production fallback.
| # | Task | Acceptance |
|---|---|---|
| 8.44 `[D:8.3,8.4,8.28,8.31]` | **IN PROGRESS.** Go observability package encodes queue/proposal/match/server IDs and lifecycle stage in structured events while recursively redacting auth/relay tokens and credentials. It now actually emits: `Service.Log` is a nil-safe optional hook, wired into the two workload-authenticated server routes (register, result) at every outcome plus queue create/heartbeat/cancel and proposal accept/decline (state on success, `rejected` on a domain error, never the error text), and `cmd/control-plane` writes those events as JSON lines to stderr | `server/observability/` covers correlation fields, nested secret redaction and unnamed-event rejection; `server/api/service.go`/`service_test.go` cover the wiring plus a secret-canary test that drives the server routes with real-looking bearer-token/nonce values and asserts neither appears anywhere in what `Log` actually received (stronger than the unit test, which only proves a synthetic value under a denylisted key is stripped), and a lifecycle test asserting the exact event/id/stage sequence across a real create→heartbeat→cancel and an accept→stale-revision-reject. `redact()` is still key-name-based, not content-based — a field logged under an unlisted key would leak and neither test would catch it, only the discipline of never putting raw secret bytes into `Fields`; read-only routes (queue/proposal GET, assignment fetch), early availability/not-found rejections, and a real metrics/traces backend (this is stderr only) remain |
| 8.45 `[D:8.2,8.44]` | **IN PROGRESS.** Go observability package turns the documented RTT, allocation/connect latency, result-success, API-latency and tick/headroom thresholds into executable window checks | `server/observability/slo.go` covers healthy/violating/empty windows; production metrics export, dashboards, alert routing, wait/MMR/proposal/flood/cost series and runbooks remain |
| 8.44 `[D:8.3,8.4,8.28,8.31]` | **IN PROGRESS.** Go observability package encodes queue/proposal/match/server IDs and lifecycle stage in structured events while recursively redacting auth/relay tokens and credentials. It now actually emits: `Service.Log` is a nil-safe optional hook, wired to mutation and read routes at every outcome, and `cmd/control-plane` writes those events as JSON lines to stderr | `server/observability/` covers correlation fields, nested secret redaction, content-aware credential canaries and unnamed-event rejection; API tests cover lifecycle event wiring without logging error text. Remaining work is a real metrics/traces backend and production dashboard/alert routing; the local logger is intentionally stderr-only |
| 8.45 `[D:8.2,8.44]` | **IN PROGRESS.** Go observability package turns the documented RTT, allocation/connect latency, result-success, API-latency and tick/headroom thresholds into executable window checks; the API exporter now emits a bounded cumulative latency histogram suitable for querying the documented p95 API SLO | `server/observability/slo.go`, `metrics.go` and adversarial tests cover healthy/violating/empty windows, fixed operation/status labels, cumulative bucket boundaries and arbitrary-path cardinality safety; production scrape configuration, dashboards, alert routing, wait/MMR/proposal/flood/cost series and runbooks remain |
| 8.46 `[D:8.5,8.7,8.9,8.10,8.14,8.18,8.21,8.23,8.25]` | **IN PROGRESS.** Go unit/race coverage spans the current domain/store/supervisor policies, and fuzz targets now exercise queue input, result payload hashing and revision events | `server/domain/*_test.go`, `server/store/*_test.go`, `server/supervisor/*_test.go`, `server/migrations/*_test.go` and `server/domain/fuzz_test.go` pass normal/race suites; `go test -race ./...` passes across API, domain, migrations, observability, store, supervisor and testkit; `go vet ./...` passes; each of the three declared domain fuzz targets passes a bounded 4-second run; PostgreSQL live migration execution now runs clean (§8.5), and four real-concurrency cases are covered against a live database with `-race`: §8.14's queue-heartbeat revision race, §8.18's two-matcher contested-ticket race, §8.30's cross-allocator-replica capacity race, and §8.21/§8.25's concurrent identical-result-submission race; the "lost Redis" fixture is covered live against a real server (§8.14: real TTL expiry, repair-after-`FLUSHALL`; fake Steam/allocator fixtures are §8.47's testkit, already done). Further transaction fixtures (e.g. concurrent proposal-recovery expiry races, live Redis failover mid-write under load) remain |
| 8.47 `[D:8.7,8.30]` | **IN PROGRESS.** Offline testkit provides deterministic fake Steam verification and fake allocation with forced failure injection | `server/testkit/` covers verified identity/replay, unknown identity, wrong App ID, expiry, no capacity, compatibility-key conflict, idempotent allocation replay and cloud-free forced allocation failure in `TestOfflineFakesCoverVerificationAndAllocationFailureMatrix`; API/Compose integration and live exhaustive matrix remain |
| 8.48 `[D:8.10,8.14,8.17,8.18,8.27,8.31,8.35,8.47]` | **IN PROGRESS.** Offline testkit exercises verified queue projection → ranked six-player proposal → ENet allocation → assignment-ready manifest → certified durable result receipt | `server/testkit/pipeline_test.go` covers the cross-domain success path without Steam/cloud secrets; independent Compose fixture, process shutdown, result ack over HTTP and legacy fixture non-regression remain |
+29 -6
View File
@@ -11,15 +11,20 @@ import (
// Metrics is a bounded in-process collector for API request health. Operation
// names are normalized to a fixed vocabulary before storage.
type Metrics struct {
mu sync.Mutex
counts map[metricKey]uint64
sums map[metricKey]time.Duration
mu sync.Mutex
counts map[metricKey]uint64
sums map[metricKey]time.Duration
buckets map[metricKey][]uint64
}
type metricKey struct{ operation, status string }
// apiLatencyBucketsSeconds is deliberately fixed and small. It is wide enough
// to query the documented 250 ms API SLO while keeping the exporter bounded.
var apiLatencyBucketsSeconds = []float64{0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2, 5, 10}
func NewMetrics() *Metrics {
return &Metrics{counts: make(map[metricKey]uint64), sums: make(map[metricKey]time.Duration)}
return &Metrics{counts: make(map[metricKey]uint64), sums: make(map[metricKey]time.Duration), buckets: make(map[metricKey][]uint64)}
}
func (m *Metrics) ObserveAPI(operation string, statusCode int, duration time.Duration) {
@@ -33,6 +38,17 @@ func (m *Metrics) ObserveAPI(operation string, statusCode int, duration time.Dur
m.mu.Lock()
m.counts[key]++
m.sums[key] += duration
bucketCounts := m.buckets[key]
if bucketCounts == nil {
bucketCounts = make([]uint64, len(apiLatencyBucketsSeconds))
m.buckets[key] = bucketCounts
}
seconds := duration.Seconds()
for index, upperBound := range apiLatencyBucketsSeconds {
if seconds <= upperBound {
bucketCounts[index]++
}
}
m.mu.Unlock()
}
@@ -53,16 +69,23 @@ func (m *Metrics) WritePrometheus(w io.Writer) error {
})
counts := make(map[metricKey]uint64, len(keys))
sums := make(map[metricKey]time.Duration, len(keys))
buckets := make(map[metricKey][]uint64, len(keys))
for _, key := range keys {
counts[key], sums[key] = m.counts[key], m.sums[key]
buckets[key] = append([]uint64(nil), m.buckets[key]...)
}
m.mu.Unlock()
if _, err := io.WriteString(w, "# TYPE cosmic_clash_api_requests_total counter\n# TYPE cosmic_clash_api_latency_seconds summary\n"); err != nil {
if _, err := io.WriteString(w, "# TYPE cosmic_clash_api_requests_total counter\n# TYPE cosmic_clash_api_latency_seconds histogram\n"); err != nil {
return err
}
for _, key := range keys {
labels := fmt.Sprintf(`operation="%s",status="%s"`, key.operation, key.status)
if _, err := fmt.Fprintf(w, "cosmic_clash_api_requests_total{%s} %d\ncosmic_clash_api_latency_seconds_count{%s} %d\ncosmic_clash_api_latency_seconds_sum{%s} %.9f\n", labels, counts[key], labels, counts[key], labels, sums[key].Seconds()); err != nil {
for index, upperBound := range apiLatencyBucketsSeconds {
if _, err := fmt.Fprintf(w, "cosmic_clash_api_latency_seconds_bucket{%s,le=\"%g\"} %d\n", labels, upperBound, buckets[key][index]); err != nil {
return err
}
}
if _, err := fmt.Fprintf(w, "cosmic_clash_api_latency_seconds_bucket{%s,le=\"+Inf\"} %d\ncosmic_clash_api_requests_total{%s} %d\ncosmic_clash_api_latency_seconds_count{%s} %d\ncosmic_clash_api_latency_seconds_sum{%s} %.9f\n", labels, counts[key], labels, counts[key], labels, counts[key], labels, sums[key].Seconds()); err != nil {
return err
}
}
+21
View File
@@ -18,7 +18,28 @@ func TestMetricsNormalizesOperationsAndExportsBoundedLabels(t *testing.T) {
if !strings.Contains(text, `operation="queue",status="2xx"`) || !strings.Contains(text, `operation="other",status="5xx"`) {
t.Fatalf("metrics output = %s", text)
}
if !strings.Contains(text, "# TYPE cosmic_clash_api_latency_seconds histogram") ||
!strings.Contains(text, `cosmic_clash_api_latency_seconds_bucket{operation="queue",status="2xx",le="0.25"} 1`) ||
!strings.Contains(text, `cosmic_clash_api_latency_seconds_bucket{operation="queue",status="2xx",le="+Inf"} 1`) {
t.Fatalf("latency histogram missing expected buckets: %s", text)
}
if strings.Contains(text, "crafted") || strings.Contains(text, "secret") {
t.Fatalf("unbounded operation label leaked: %s", text)
}
}
func TestMetricsHistogramUsesCumulativeBoundarySemantics(t *testing.T) {
m := NewMetrics()
m.ObserveAPI("queue", 200, 250*time.Millisecond)
var output strings.Builder
if err := m.WritePrometheus(&output); err != nil {
t.Fatal(err)
}
text := output.String()
if !strings.Contains(text, `le="0.25"} 1`) || !strings.Contains(text, `le="0.5"} 1`) {
t.Fatalf("boundary observation was not cumulative: %s", text)
}
if strings.Contains(text, `le="0.1"} 1`) {
t.Fatalf("250ms observation entered an earlier bucket: %s", text)
}
}