From 8ac5e64d8a1bd3d837efa63950f71ceefa083c1a Mon Sep 17 00:00:00 2001 From: Minseong Choi Date: Tue, 30 Jun 2026 13:11:49 +0900 Subject: [PATCH] feat(metrics): observe felis_start_duration_seconds across the start lifecycle MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Wire the fourth mandated §23 metric to a real producer. The histogram spans two reconcile passes, so anchor and observation must persist in status: - Add status.startRequestedAt, set once on the first Starting reconcile of a start attempt and cleared on Stopped so the next start re-anchors. - Observe felis_start_duration_seconds exactly when readiness is first reached (ReadySignalAt - StartRequestedAt), guarded so a server that reaches ready without a Starting pass records nothing. - Mirror the field into the deepcopy and the structural CRD schema so the apiserver does not prune it on patchStatus round-trips. - Promote prometheus/client_golang and client_model to direct deps now that the operator and its tests import them. Tests drive a step clock through Starting -> Running asserting the exact observed duration, and through Running -> Stopped asserting the metric is observed once and the anchor clears. --- .../felis.lolicon.best_minecraftservers.yaml | 10 ++ go.mod | 4 +- .../felis/v1alpha1/minecraftserver_types.go | 7 ++ .../felis/v1alpha1/zz_generated.deepcopy.go | 3 + internal/operator/reconciler.go | 21 ++++ internal/operator/reconciler_test.go | 102 ++++++++++++++++++ 6 files changed, 145 insertions(+), 2 deletions(-) diff --git a/deploy/crd/felis.lolicon.best_minecraftservers.yaml b/deploy/crd/felis.lolicon.best_minecraftservers.yaml index 01ca290..9739a28 100644 --- a/deploy/crd/felis.lolicon.best_minecraftservers.yaml +++ b/deploy/crd/felis.lolicon.best_minecraftservers.yaml @@ -383,6 +383,16 @@ spec: description: ReadySignalAt is when the first RCON probe succeeded. format: date-time type: string + startRequestedAt: + description: |- + StartRequestedAt is when the current start attempt was first observed + (the first Starting reconcile after desiredState=Running). It anchors the + felis_start_duration_seconds histogram (spec §23): the operator observes + ReadySignalAt-StartRequestedAt the moment readiness is first reached, then + clears this on stop so the next start re-anchors. Persisted in status + because the two endpoints fall in different reconcile passes. + format: date-time + type: string type: object type: object served: true diff --git a/go.mod b/go.mod index d96e88e..526124f 100644 --- a/go.mod +++ b/go.mod @@ -10,6 +10,8 @@ require ( github.com/charmbracelet/lipgloss v1.1.0 github.com/golang-jwt/jwt/v5 v5.2.1 github.com/jackc/pgx/v5 v5.7.1 + github.com/prometheus/client_golang v1.19.1 + github.com/prometheus/client_model v0.6.1 golang.org/x/crypto v0.27.0 k8s.io/api v0.31.3 k8s.io/apimachinery v0.31.3 @@ -68,8 +70,6 @@ require ( github.com/muesli/termenv v0.16.0 // indirect github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/pkg/errors v0.9.1 // indirect - github.com/prometheus/client_golang v1.19.1 // indirect - github.com/prometheus/client_model v0.6.1 // indirect github.com/prometheus/common v0.55.0 // indirect github.com/prometheus/procfs v0.15.1 // indirect github.com/rivo/uniseg v0.4.7 // indirect diff --git a/internal/apis/felis/v1alpha1/minecraftserver_types.go b/internal/apis/felis/v1alpha1/minecraftserver_types.go index 9b1f99e..7f1faba 100644 --- a/internal/apis/felis/v1alpha1/minecraftserver_types.go +++ b/internal/apis/felis/v1alpha1/minecraftserver_types.go @@ -234,6 +234,13 @@ type MinecraftServerStatus struct { LiveMotd string `json:"liveMotd,omitempty"` // ReadySignalAt is when the first RCON probe succeeded. ReadySignalAt *metav1.Time `json:"readySignalAt,omitempty"` + // StartRequestedAt is when the current start attempt was first observed + // (the first Starting reconcile after desiredState=Running). It anchors the + // felis_start_duration_seconds histogram (spec §23): the operator observes + // ReadySignalAt-StartRequestedAt the moment readiness is first reached, then + // clears this on stop so the next start re-anchors. Persisted in status + // because the two endpoints fall in different reconcile passes. + StartRequestedAt *metav1.Time `json:"startRequestedAt,omitempty"` // ObservedGeneration is the spec generation this status reflects. ObservedGeneration int64 `json:"observedGeneration,omitempty"` // Conditions are the standard metav1 conditions (Ready, RconReached, ...). diff --git a/internal/apis/felis/v1alpha1/zz_generated.deepcopy.go b/internal/apis/felis/v1alpha1/zz_generated.deepcopy.go index b8ddaba..7119443 100644 --- a/internal/apis/felis/v1alpha1/zz_generated.deepcopy.go +++ b/internal/apis/felis/v1alpha1/zz_generated.deepcopy.go @@ -115,6 +115,9 @@ func (in *MinecraftServerStatus) DeepCopyInto(out *MinecraftServerStatus) { if in.ReadySignalAt != nil { out.ReadySignalAt = in.ReadySignalAt.DeepCopy() } + if in.StartRequestedAt != nil { + out.StartRequestedAt = in.StartRequestedAt.DeepCopy() + } if in.Conditions != nil { l := make([]metav1.Condition, len(in.Conditions)) for i := range in.Conditions { diff --git a/internal/operator/reconciler.go b/internal/operator/reconciler.go index a647fc8..2ec3647 100644 --- a/internal/operator/reconciler.go +++ b/internal/operator/reconciler.go @@ -10,6 +10,7 @@ import ( "time" "felis.lolicon.best/internal/apis/felis/v1alpha1" + "felis.lolicon.best/internal/metrics" appsv1 "k8s.io/api/apps/v1" corev1 "k8s.io/api/core/v1" apierrors "k8s.io/apimachinery/pkg/api/errors" @@ -235,6 +236,16 @@ func (r *Reconciler) markStarting(server *v1alpha1.MinecraftServer, reason, msg server.Status.Phase = v1alpha1.PhaseStarting server.Status.Ready = false server.Status.ObservedGeneration = server.Generation + // Anchor felis_start_duration_seconds (spec §23) at the first Starting pass of + // this start attempt. Set-once (cleared on stop) so re-entrant Starting + // reconciles preserve the original anchor and the observed duration spans the + // whole start, not just the last requeue. A server that reaches readiness + // without ever passing through Starting leaves this nil, and markRunningReady + // skips the observation rather than recording a bogus one. + if server.Status.StartRequestedAt == nil { + t := r.now() + server.Status.StartRequestedAt = &t + } server.Status.Endpoint = v1alpha1.EndpointStatus{Mode: v1alpha1.EndpointFallback, Address: server.Spec.FallbackServer} server.Status.LiveMotd = server.Spec.Motd.Starting r.setCondition(server, v1alpha1.ConditionReady, metav1.ConditionFalse, reason, msg) @@ -248,6 +259,13 @@ func (r *Reconciler) markRunningReady(server *v1alpha1.MinecraftServer) { if server.Status.ReadySignalAt == nil { t := r.now() server.Status.ReadySignalAt = &t + // Observe felis_start_duration_seconds (spec §23) exactly once, when + // readiness is first reached. StartRequestedAt was persisted by an earlier + // Starting reconcile; if it is nil the server became ready without a + // Starting pass and there is no meaningful start interval to record. + if server.Status.StartRequestedAt != nil { + metrics.StartDurationSeconds.Observe(t.Sub(server.Status.StartRequestedAt.Time).Seconds()) + } } server.Status.Endpoint = v1alpha1.EndpointStatus{Mode: v1alpha1.EndpointDirect, Address: gameAddress(server)} server.Status.LiveMotd = server.Spec.Motd.Running @@ -269,6 +287,9 @@ func (r *Reconciler) markStopped(server *v1alpha1.MinecraftServer) { server.Status.Ready = false server.Status.ObservedGeneration = server.Generation server.Status.ReadySignalAt = nil + // Clear the start anchor so the next Running transition re-anchors and + // felis_start_duration_seconds measures the new start, not since the last one. + server.Status.StartRequestedAt = nil server.Status.Players = v1alpha1.PlayersStatus{} server.Status.Endpoint = v1alpha1.EndpointStatus{Mode: v1alpha1.EndpointFallback, Address: server.Spec.FallbackServer} server.Status.LiveMotd = server.Spec.Motd.Stopped diff --git a/internal/operator/reconciler_test.go b/internal/operator/reconciler_test.go index d6285e9..6ec1260 100644 --- a/internal/operator/reconciler_test.go +++ b/internal/operator/reconciler_test.go @@ -8,7 +8,9 @@ import ( "time" "felis.lolicon.best/internal/apis/felis/v1alpha1" + "felis.lolicon.best/internal/metrics" "felis.lolicon.best/internal/operator" + dto "github.com/prometheus/client_model/go" appsv1 "k8s.io/api/apps/v1" corev1 "k8s.io/api/core/v1" apierrors "k8s.io/apimachinery/pkg/api/errors" @@ -121,6 +123,18 @@ func markPodReady(t *testing.T, c client.Client, name string) { } } +// markPodTerminated simulates the StatefulSet's pods finishing termination after +// a scale-to-zero, which the fake client does not do on its own. +func markPodTerminated(t *testing.T, c client.Client, name string) { + t.Helper() + sts := getSTS(t, c, name) + sts.Status.Replicas = 0 + sts.Status.ReadyReplicas = 0 + if err := c.Status().Update(context.Background(), sts); err != nil { + t.Fatalf("update sts status: %v", err) + } +} + func TestReconcileRunning_CreatesWorkloadAndInjectsGracefulShutdown(t *testing.T) { r, c := newReconciler(t, fakeProber{}, runningServer(), rconSecret()) @@ -296,3 +310,91 @@ func isConditionTrue(server *v1alpha1.MinecraftServer, condType string) bool { } func ptrTime(t metav1.Time) *metav1.Time { return &t } + +// startDurationState reads the global felis_start_duration_seconds histogram's +// accumulated sample count and sum directly (Histogram implements Metric.Write), +// so assertions can be expressed as deltas and never depend on observations +// other tests made into the same process-wide collector. +func startDurationState(t *testing.T) (count uint64, sum float64) { + t.Helper() + var m dto.Metric + if err := metrics.StartDurationSeconds.Write(&m); err != nil { + t.Fatalf("read start_duration_seconds histogram: %v", err) + } + return m.GetHistogram().GetSampleCount(), m.GetHistogram().GetSampleSum() +} + +// TestReconcileRunning_ObservesStartDuration proves the felis_start_duration_seconds +// wiring (spec §23) end-to-end across reconcile passes: the Starting pass anchors +// status.startRequestedAt, the value survives the patchStatus round-trip, and the +// first Running pass observes ReadySignalAt-StartRequestedAt into the histogram. +// A step-advancing clock (90s between the two passes) makes the observed duration +// a non-zero, exact value rather than the 0 a constant clock would yield. +func TestReconcileRunning_ObservesStartDuration(t *testing.T) { + r, c := newReconciler(t, fakeProber{}, runningServer(), rconSecret()) + + base := time.Date(2026, 6, 25, 12, 0, 0, 0, time.UTC) + clock := base + // Override the constant fixedNow with a clock the test advances between passes. + // now() is stable within a single reconcile; only the explicit bump moves it. + r.Now = func() metav1.Time { return metav1.NewTime(clock) } + + beforeCount, beforeSum := startDurationState(t) + + reconcile(t, r, "survival") // Starting: anchors startRequestedAt = base + starting := getServer(t, c, "survival") + if starting.Status.StartRequestedAt == nil || !starting.Status.StartRequestedAt.Equal(ptrTime(metav1.NewTime(base))) { + t.Fatalf("startRequestedAt = %v, want %v", starting.Status.StartRequestedAt, base) + } + + clock = base.Add(90 * time.Second) // 90s elapse before the pod reports ready + markPodReady(t, c, "survival") + reconcile(t, r, "survival") // Running: observes 90s and sets readySignalAt + + ready := getServer(t, c, "survival") + if ready.Status.Phase != v1alpha1.PhaseRunning || !ready.Status.Ready { + t.Fatalf("status = %s ready=%v, want Running ready", ready.Status.Phase, ready.Status.Ready) + } + + afterCount, afterSum := startDurationState(t) + if got := afterCount - beforeCount; got != 1 { + t.Fatalf("histogram sample count delta = %d, want exactly 1 observation", got) + } + if got := afterSum - beforeSum; got != 90 { + t.Errorf("observed start duration = %vs, want 90s", got) + } +} + +// TestReconcileRunning_StartDurationObservedOnce guards against a re-observation +// bug: once a server is Running, further reconciles must not re-Observe the +// histogram (the once-only readySignalAt guard owns the Observe), and a Stop must +// clear startRequestedAt so a subsequent start re-anchors instead of measuring +// from the original boot. +func TestReconcileRunning_StartDurationObservedOnce(t *testing.T) { + r, c := newReconciler(t, fakeProber{}, runningServer(), rconSecret()) + + reconcile(t, r, "survival") // Starting + markPodReady(t, c, "survival") + reconcile(t, r, "survival") // Running -> one observation + + afterFirst, _ := startDurationState(t) + + reconcile(t, r, "survival") // still Running -> must NOT observe again + afterSecond, _ := startDurationState(t) + if afterSecond != afterFirst { + t.Errorf("re-reconcile of a Running server observed again: %d -> %d", afterFirst, afterSecond) + } + + // Stopping must clear the anchor so the next start measures afresh. + stopped := getServer(t, c, "survival") + stopped.Spec.DesiredState = v1alpha1.DesiredStopped + if err := c.Update(context.Background(), stopped); err != nil { + t.Fatalf("set desiredState=Stopped: %v", err) + } + reconcile(t, r, "survival") // scales spec to 0; pods still terminating + markPodTerminated(t, c, "survival") // pods finish draining + reconcile(t, r, "survival") // reaches Stopped, clears startRequestedAt + if s := getServer(t, c, "survival"); s.Status.StartRequestedAt != nil { + t.Errorf("startRequestedAt = %v after Stop, want nil so the next start re-anchors", s.Status.StartRequestedAt) + } +}