diff --git a/multiplayer-next.md b/multiplayer-next.md index 9366f357..3636326b 100644 --- a/multiplayer-next.md +++ b/multiplayer-next.md @@ -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 | diff --git a/server/observability/metrics.go b/server/observability/metrics.go index 80d3db2c..6c4bb6a2 100644 --- a/server/observability/metrics.go +++ b/server/observability/metrics.go @@ -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 } } diff --git a/server/observability/metrics_test.go b/server/observability/metrics_test.go index 4ea6a9a3..c318f996 100644 --- a/server/observability/metrics_test.go +++ b/server/observability/metrics_test.go @@ -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) + } +}