feat(stovepipe): report how long a build failure went undetected

Emit the elapsed time from the commit a failed build validated against, as a
histogram tagged with the queue and the build strategy. A histogram because the
distribution over failures is the point: how long a break typically survives,
not how long the last one did.

The observation belongs to the stage that records the failure. A failure is the
moment a break becomes known, and an elapsed time is only meaningful against it
— unlike the last-known-green age, there is no later moment to sample it from,
so it cannot be moved off the delivery path onto a clock. It is confined to
failures, made after the outcome is durable, and swallows every fault: a failed
observation is counted with the step that failed and never disturbs the outcome
already written.

A full build pins no base commit, so its failures are counted as unmeasurable
rather than timed, which keeps the ordinary case out of the error series.

Author: mnoah1

platform/metrics/metrics.go

@@ -106,6 +106,28 @@ var (
 		2 * time.Hour,
 		4 * time.Hour,
 	}
+
+	// ChangeAgeBuckets suits durations measured from a source-control change's
+	// commit timestamp. They span minutes to a month because that is the honest
+	// range of such a signal: a break caught in minutes and one that survived a
+	// fortnight are both ordinary observations, and collapsing the tail would hide
+	// exactly the cases worth seeing.
+	ChangeAgeBuckets = tally.DurationBuckets{
+		1 * time.Minute,
+		5 * time.Minute,
+		15 * time.Minute,
+		30 * time.Minute,
+		1 * time.Hour,
+		2 * time.Hour,
+		4 * time.Hour,
+		8 * time.Hour,
+		12 * time.Hour,
+		24 * time.Hour,
+		48 * time.Hour,
+		7 * 24 * time.Hour,
+		14 * 24 * time.Hour,
+		30 * 24 * time.Hour,
+	}
 )
 
 // Op tracks the lifecycle of a named operation. It captures the start time on

platform/metrics/metrics_test.go

@@ -165,6 +165,7 @@ func TestLatencyBuckets_Sorted(t *testing.T) {
 		"FastLatencyBuckets":    FastLatencyBuckets,
 		"StorageLatencyBuckets": StorageLatencyBuckets,
 		"LongLatencyBuckets":    LongLatencyBuckets,
+		"ChangeAgeBuckets":      ChangeAgeBuckets,
 	}
 	for name, buckets := range sets {
 		t.Run(name, func(t *testing.T) {

service/stovepipe/server/main.go

@@ -421,7 +421,7 @@ func registerPrimaryControllers(
 	}
 	count++
 
-	buildSignalController := buildsignal.NewController(logger, scope, store, brf, registry, stovepipemq.TopicKeyBuildSignal, "stovepipe-buildsignal")
+	buildSignalController := buildsignal.NewController(logger, scope, store, brf, scf, registry, stovepipemq.TopicKeyBuildSignal, "stovepipe-buildsignal")
 	if err := c.Register(buildSignalController); err != nil {
 		return count, fmt.Errorf("failed to register buildsignal controller: %w", err)
 	}

stovepipe/controller/buildsignal/BUILD.bazel

@@ -13,6 +13,7 @@ go_library(
         "//stovepipe/core/messagequeue:go_default_library",
         "//stovepipe/entity:go_default_library",
         "//stovepipe/extension/buildrunner:go_default_library",
+        "//stovepipe/extension/sourcecontrol:go_default_library",
         "//stovepipe/extension/storage:go_default_library",
         "@com_github_uber_go_tally//:go_default_library",
         "@org_uber_go_zap//:go_default_library",
@@ -33,6 +34,8 @@ go_test(
         "//stovepipe/entity:go_default_library",
         "//stovepipe/extension/buildrunner:go_default_library",
         "//stovepipe/extension/buildrunner/mock:go_default_library",
+        "//stovepipe/extension/sourcecontrol:go_default_library",
+        "//stovepipe/extension/sourcecontrol/mock:go_default_library",
         "//stovepipe/extension/storage:go_default_library",
         "//stovepipe/extension/storage/mock:go_default_library",
         "@com_github_stretchr_testify//assert:go_default_library",

stovepipe/controller/buildsignal/buildsignal.go

@@ -18,12 +18,17 @@
 // releases the queue's build slot, projects the outcome onto the request, and
 // publishes the request id to record. See
 // doc/rfc/stovepipe/steps/buildsignal.md.
+//
+// It reads source control for one thing only: a failure is the moment a break
+// becomes known, so the stage that records the failure is the only place the time
+// it went undetected can be measured.
 package buildsignal
 
 import (
 	"context"
 	"errors"
 	"fmt"
+	"time"
 
 	"github.com/uber-go/tally"
 	entityqueue "github.com/uber/submitqueue/platform/base/messagequeue"
@@ -33,6 +38,7 @@ import (
 	stovepipemq "github.com/uber/submitqueue/stovepipe/core/messagequeue"
 	"github.com/uber/submitqueue/stovepipe/entity"
 	"github.com/uber/submitqueue/stovepipe/extension/buildrunner"
+	"github.com/uber/submitqueue/stovepipe/extension/sourcecontrol"
 	"github.com/uber/submitqueue/stovepipe/extension/storage"
 	"go.uber.org/zap"
 )
@@ -57,39 +63,49 @@ var (
 // the request, and publishes the request id to record. Implements
 // consumer.Controller.
 type Controller struct {
-	logger        *zap.SugaredLogger
-	metricsScope  tally.Scope
-	stores        storage.Factory
-	buildRunners  buildrunner.Factory
-	registry      consumer.TopicRegistry
-	topicKey      consumer.TopicKey
-	consumerGroup string
+	logger         *zap.SugaredLogger
+	metricsScope   tally.Scope
+	stores         storage.Factory
+	buildRunners   buildrunner.Factory
+	sourceControls sourcecontrol.Factory
+	registry       consumer.TopicRegistry
+	topicKey       consumer.TopicKey
+	consumerGroup  string
 }
 
 // Verify Controller implements consumer.Controller interface at compile time.
 var _ consumer.Controller = (*Controller)(nil)
 
-// _opName is the metric operation name shared by every emit in this file.
-const _opName = "buildsignal"
+const (
+	// _opName is the metric operation name for this stage's own handling counters.
+	_opName = "buildsignal"
+
+	// _opBuildFailure is the metric operation name for the failure-detection
+	// observation. It is named for what is measured rather than for this stage, so
+	// the series an operator alerts on does not move if the stage does.
+	_opBuildFailure = "build_failure"
+)
 
 // NewController creates a new buildsignal controller.
 func NewController(
 	logger *zap.SugaredLogger,
 	scope tally.Scope,
 	stores storage.Factory,
 	buildRunners buildrunner.Factory,
+	sourceControls sourcecontrol.Factory,
 	registry consumer.TopicRegistry,
 	topicKey consumer.TopicKey,
 	consumerGroup string,
 ) *Controller {
 	return &Controller{
-		logger:        logger.Named("buildsignal_controller"),
-		metricsScope:  scope.SubScope("buildsignal_controller"),
-		stores:        stores,
-		buildRunners:  buildRunners,
-		registry:      registry,
-		topicKey:      topicKey,
-		consumerGroup: consumerGroup,
+		logger:         logger.Named("buildsignal_controller"),
+		metricsScope:   scope.SubScope("buildsignal_controller"),
+		stores:         stores,
+		buildRunners:   buildRunners,
+		sourceControls: sourceControls,
+		registry:       registry,
+		topicKey:       topicKey,
+		consumerGroup:  consumerGroup,
 	}
 }
 
@@ -270,10 +286,70 @@ func (c *Controller) markOutcome(ctx context.Context, store storage.Storage, req
 		metrics.NamedCounter(c.metricsScope, _opName, "outcomes", 1,
 			metrics.NewTag("state", string(state)),
 		)
+		// Reported from the write that records the failure, so only the writer of an
+		// outcome reports it: a redelivery returns above without a second sample.
+		if state == entity.RequestStateFailed {
+			c.reportDetectionLatency(ctx, *request)
+		}
 		return nil
 	}
 }
 
+// reportDetectionLatency records how long the break this build failed on went
+// undetected, measured from the commit timestamp of the base it validated against. A
+// histogram rather than a gauge because the distribution over failures is the point:
+// how long a break typically survives, not how long the last one did.
+//
+// The observation is best-effort — every way it can fail is counted and swallowed,
+// never affecting the outcome that was just recorded. It costs a source-control call
+// on the delivery path, which this measurement cannot trade away the way a
+// current-state signal can: there is no later moment to sample an elapsed time from,
+// because it is only meaningful against the failure that just became known. The call
+// is confined to failures and made after the outcome is durable.
+func (c *Controller) reportDetectionLatency(ctx context.Context, request entity.Request) {
+	queueTag := metrics.NewTag("queue", request.Queue)
+	strategyTag := metrics.NewTag("strategy", string(request.BuildStrategy))
+
+	// Only a strategy that validates a delta pins a base commit, so a full build has
+	// no baseline to measure from. Its failures are counted rather than timed: absent
+	// here is the ordinary case, not a fault.
+	if request.BaseURI == "" {
+		metrics.NamedCounter(c.metricsScope, _opBuildFailure, "detection_missing", 1, queueTag, strategyTag)
+		return
+	}
+
+	sourceControl, err := c.sourceControls.For(sourcecontrol.Config{QueueName: request.Queue})
+	if err != nil {
+		c.detectionError(queueTag, "resolve_source_control", request.Queue, err)
+		return
+	}
+
+	info, err := sourceControl.ChangeInfo(ctx, request.BaseURI)
+	if err != nil || info.CreatedAt.IsZero() {
+		c.detectionError(queueTag, "get_change_info", request.Queue, err)
+		return
+	}
+
+	// A commit dated in the future means the provider's clock disagrees with ours;
+	// a negative latency would corrupt the distribution rather than describe it.
+	latency := time.Since(info.CreatedAt)
+	if latency < 0 {
+		c.detectionError(queueTag, "future_change", request.Queue, nil)
+		return
+	}
+
+	metrics.NamedHistogram(c.metricsScope, _opBuildFailure, "time_to_detection", metrics.ChangeAgeBuckets,
+		queueTag, strategyTag,
+	).RecordDuration(latency)
+}
+
+// detectionError counts an observation that could not be made, tagged with the step
+// that failed so an unmeasurable failure can be told apart from a broken dependency.
+func (c *Controller) detectionError(queueTag metrics.Tag, step, queue string, err error) {
+	metrics.NamedCounter(c.metricsScope, _opBuildFailure, "detection_errors", 1, queueTag, metrics.NewTag("step", step))
+	c.logger.Errorw("failed to observe build failure detection latency", "queue", queue, "step", step, "error", err)
+}
+
 // releaseBuildSlot CAS-decrements the queue's in_flight_count, reopening the process
 // concurrency gate now that this request's build is over. It decrements relatively
 // (preserving concurrent updates), clamps at zero, and retries on version conflicts.