feat(metrics): observe felis_start_duration_seconds across the start lifecycle

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.

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

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

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, ...).

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 {

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

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)
+	}
+}