diff --git a/platform/metrics/README.md b/platform/metrics/README.md index 7a2426222..6dae6c4af 100644 --- a/platform/metrics/README.md +++ b/platform/metrics/README.md @@ -20,6 +20,7 @@ For any operation with a clear start and end, use `Begin` and `Complete`: |----------|-------| | `Begin(scope, name, buckets, ...tags)` | `{name}.start` counter +1 and returns an `Op` | | `op.Complete(err, ...tags)` | `{name}.finish` histogram tagged with `result=success\|error\|cancel` and any completion tags | +| `op.CompleteAs(result, ...tags)` | `{name}.finish` histogram tagged with the given `result` and any completion tags, for outcomes the error alone does not classify (for example `result=not_found`) | `buckets` is required at `Begin` because operations differ widely in expected latency. The finish histogram records both the duration distribution and the number of completed operations, so `Complete` does not emit a separate counter. @@ -79,7 +80,7 @@ metrics.NamedCounter(c.scope, "publish", "attempts", 1, metrics.NewTag("topic", ## Duration Buckets -There is no default bucket set. The package exports four common sets: +There is no default bucket set. The package exports five common sets: | Set | Range | Use for | |-----|-------|---------| @@ -87,5 +88,8 @@ There is no default bucket set. The package exports four common sets: | `StorageLatencyBuckets` | ~1ms – 1m | Storage and message-queue round trips such as database reads, writes, publishing, and consuming | | `LongLatencyBuckets` | ~5ms – 4h | Long-running pipeline work and external calls such as builds, lands, pushes, and provider calls | | `ChangeAgeBuckets` | ~1m – 30d | Elapsed time measured from a source-control change's commit timestamp rather than from work this system started | +| `LandLatencyBuckets` | ~1m – 24h | End-to-end request lifecycles, from accepting a land request to its terminal outcome | Pass one of these sets or a custom `tally.DurationBuckets` to `Begin` or `NamedHistogram`. + +For counts recorded with `RecordValue`, such as how many items a unit of work carries or depends on, use `CountBuckets` (0 – 144, Fibonacci-spaced, with zero in its own bucket). diff --git a/platform/metrics/metrics.go b/platform/metrics/metrics.go index aab5feb62..331d07f3c 100644 --- a/platform/metrics/metrics.go +++ b/platform/metrics/metrics.go @@ -153,8 +153,40 @@ var ( 14 * 24 * time.Hour, 30 * 24 * time.Hour, } + + // LandLatencyBuckets suits end-to-end request lifecycles, from accepting a + // land request to its terminal outcome. Resolution is densest between 5 and + // 60 minutes, where typical lands fall, and the tail reaches a day so that + // requests stuck overnight stay distinguishable instead of overflowing. + LandLatencyBuckets = tally.DurationBuckets{ + 1 * time.Minute, + 2 * time.Minute, + 3 * time.Minute, + 5 * time.Minute, + 7*time.Minute + 30*time.Second, + 10 * time.Minute, + 15 * time.Minute, + 20 * time.Minute, + 30 * time.Minute, + 45 * time.Minute, + 1 * time.Hour, + 90 * time.Minute, + 2 * time.Hour, + 3 * time.Hour, + 4 * time.Hour, + 6 * time.Hour, + 8 * time.Hour, + 12 * time.Hour, + 24 * time.Hour, + } ) +// CountBuckets suits small cardinalities recorded with RecordValue, such as how +// many items a unit of work carries or depends on. Zero has its own bucket +// because "none" is a meaningful answer, and the Fibonacci spacing keeps +// resolution where counts usually fall while still separating outliers. +var CountBuckets = tally.ValueBuckets{0, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144} + // Op tracks the lifecycle of a named operation. It captures the start time on // creation, emits a {name}.start counter, and records the duration and result // on a {name}.finish histogram when Complete is called. @@ -200,6 +232,13 @@ func (o Op) Complete(err error, tags ...Tag) { } } + o.CompleteAs(result, tags...) +} + +// CompleteAs records elapsed time on the {name}.finish histogram like Complete, +// but with a caller-chosen result tag. It serves outcomes that the error alone +// does not classify, such as a lookup that found no record. +func (o Op) CompleteAs(result string, tags ...Tag) { tagged(o.scope, tags). Tagged(map[string]string{"result": result}). Histogram("finish", o.buckets). diff --git a/platform/metrics/metrics_test.go b/platform/metrics/metrics_test.go index 52e567fa9..9a6c682b1 100644 --- a/platform/metrics/metrics_test.go +++ b/platform/metrics/metrics_test.go @@ -125,6 +125,46 @@ func TestOp_CompleteWithTags(t *testing.T) { assert.True(t, ok, "expected finish-only tags, got keys: %v", histogramKeys(histograms)) } +func TestOp_CompleteAs(t *testing.T) { + tests := []struct { + name string + result string + tags []Tag + histogramKey string + }{ + { + name: "records the given result", + result: "not_found", + histogramKey: "process.finish+result=not_found", + }, + { + name: "records completion tags alongside the result", + result: "not_found", + tags: []Tag{NewTag("store", "build")}, + histogramKey: "process.finish+result=not_found,store=build", + }, + { + name: "result tag wins over a completion tag of the same key", + result: "not_found", + tags: []Tag{NewTag("result", "success")}, + histogramKey: "process.finish+result=not_found", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + scope := tally.NewTestScope("", nil) + op := Begin(scope, "process", StorageLatencyBuckets) + op.CompleteAs(tt.result, tt.tags...) + + histograms := scope.Snapshot().Histograms() + _, ok := histograms[tt.histogramKey] + assert.True(t, ok, "expected histogram key %s, got keys: %v", tt.histogramKey, histogramKeys(histograms)) + assert.Len(t, histograms, 1) + }) + } +} + func TestNamedCounter(t *testing.T) { scope := tally.NewTestScope("", nil) NamedCounter(scope, "publish", "attempts", 5) @@ -180,6 +220,7 @@ func TestLatencyBuckets_Sorted(t *testing.T) { "StorageLatencyBuckets": StorageLatencyBuckets, "LongLatencyBuckets": LongLatencyBuckets, "ChangeAgeBuckets": ChangeAgeBuckets, + "LandLatencyBuckets": LandLatencyBuckets, } for name, buckets := range sets { t.Run(name, func(t *testing.T) { @@ -192,6 +233,13 @@ func TestLatencyBuckets_Sorted(t *testing.T) { } } +func TestCountBuckets_Sorted(t *testing.T) { + for i := 1; i < len(CountBuckets); i++ { + assert.Greater(t, CountBuckets[i], CountBuckets[i-1], + "CountBuckets[%d] (%v) must be greater than CountBuckets[%d] (%v)", i, CountBuckets[i], i-1, CountBuckets[i-1]) + } +} + // counterKeys extracts map keys for error messages. func counterKeys(m map[string]tally.CounterSnapshot) []string { keys := make([]string, 0, len(m)) diff --git a/service/submitqueue/gateway/server/main.go b/service/submitqueue/gateway/server/main.go index 91cfcdd05..27a56497a 100644 --- a/service/submitqueue/gateway/server/main.go +++ b/service/submitqueue/gateway/server/main.go @@ -366,7 +366,7 @@ func run() error { // Create controllers and wrap them for gRPC. Every store is queue-scoped and // resolves through the factory adapter; land/cancel/log share one materializer. storageFty := storageFactory{backend: store} - materializer := requestcore.NewMaterializer(storageFty) + materializer := requestcore.NewMaterializer(storageFty, requestcore.WithMetricsScope(scope)) pingController := controller.NewPingController(logger, scope) landController := controller.NewLandController(logger.Sugar(), scope, cnt, storageFty, materializer, queueConfigs, queuePauses, registry) cancelController := controller.NewCancelController(logger.Sugar(), scope, storageFty, materializer, registry) diff --git a/submitqueue/extension/storage/BUILD.bazel b/submitqueue/extension/storage/BUILD.bazel index e75af25dd..ec9a4d025 100644 --- a/submitqueue/extension/storage/BUILD.bazel +++ b/submitqueue/extension/storage/BUILD.bazel @@ -22,6 +22,7 @@ go_library( visibility = ["//visibility:public"], deps = [ "//platform/errs:go_default_library", + "//platform/metrics:go_default_library", "//submitqueue/entity:go_default_library", ], ) @@ -32,7 +33,9 @@ go_test( embed = [":go_default_library"], deps = [ "//platform/errs:go_default_library", + "//platform/metrics:go_default_library", "@com_github_stretchr_testify//assert:go_default_library", + "@com_github_uber_go_tally//:go_default_library", ], ) diff --git a/submitqueue/extension/storage/storage.go b/submitqueue/extension/storage/storage.go index f82729269..7cce9bf9e 100644 --- a/submitqueue/extension/storage/storage.go +++ b/submitqueue/extension/storage/storage.go @@ -25,6 +25,7 @@ import ( "fmt" "github.com/uber/submitqueue/platform/errs" + "github.com/uber/submitqueue/platform/metrics" ) // ErrNotFound is returned by storage implementations when the requested record is not found in the database. @@ -40,6 +41,22 @@ func WrapNotFound(err error) error { return fmt.Errorf("%w: %w", ErrNotFound, err) } +// MetricsResultNotFound is the result tag CompleteReadMetricsOp records for a missing record. +const MetricsResultNotFound = "not_found" + +// CompleteReadMetricsOp finishes a store read's metrics. A read that finds no +// record has answered the question rather than failed, so ErrNotFound is recorded +// as result=not_found instead of result=error; every other outcome is classified +// by metrics.Op.Complete. Writes finish with metrics.Op.Complete directly: a write +// whose row is missing is an anomaly and stays counted as an error. +func CompleteReadMetricsOp(op metrics.Op, err error) { + if IsNotFound(err) { + op.CompleteAs(MetricsResultNotFound) + return + } + op.Complete(err) +} + // ErrAlreadyExists is returned by storage implementations when attempting to create a record with an ID that already exists. var ErrAlreadyExists = errors.New("record already exists") diff --git a/submitqueue/extension/storage/storage_test.go b/submitqueue/extension/storage/storage_test.go index 065482eb4..544312bc4 100644 --- a/submitqueue/extension/storage/storage_test.go +++ b/submitqueue/extension/storage/storage_test.go @@ -15,11 +15,14 @@ package storage import ( + "database/sql" "fmt" "testing" "github.com/stretchr/testify/assert" + "github.com/uber-go/tally" "github.com/uber/submitqueue/platform/errs" + "github.com/uber/submitqueue/platform/metrics" ) func TestErrVersionMismatchClassification(t *testing.T) { @@ -30,3 +33,28 @@ func TestErrVersionMismatchClassification(t *testing.T) { assert.False(t, errs.IsUserError(err)) assert.False(t, errs.IsDependencyError(err)) } + +func TestCompleteReadMetricsOp(t *testing.T) { + tests := []struct { + name string + err error + result string + }{ + {name: "success", result: "success"}, + {name: "wrapped not found", err: WrapNotFound(sql.ErrNoRows), result: MetricsResultNotFound}, + {name: "not found wrapped by a caller", err: fmt.Errorf("get build: %w", ErrNotFound), result: MetricsResultNotFound}, + {name: "other error", err: fmt.Errorf("connection refused"), result: "error"}, + {name: "version mismatch", err: ErrVersionMismatch, result: "error"}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + scope := tally.NewTestScope("", nil) + CompleteReadMetricsOp(metrics.Begin(scope, "get", metrics.StorageLatencyBuckets), tt.err) + + histograms := scope.Snapshot().Histograms() + assert.Len(t, histograms, 1) + assert.Contains(t, histograms, "get.finish+result="+tt.result) + }) + } +} diff --git a/submitqueue/gateway/core/request/BUILD.bazel b/submitqueue/gateway/core/request/BUILD.bazel index 8f355ffa7..4776a6963 100644 --- a/submitqueue/gateway/core/request/BUILD.bazel +++ b/submitqueue/gateway/core/request/BUILD.bazel @@ -10,9 +10,11 @@ go_library( importpath = "github.com/uber/submitqueue/submitqueue/gateway/core/request", visibility = ["//visibility:public"], deps = [ + "//platform/metrics:go_default_library", "//submitqueue/entity:go_default_library", "//submitqueue/extension/storage:go_default_library", "//submitqueue/gateway/extension/storage:go_default_library", + "@com_github_uber_go_tally//:go_default_library", ], ) @@ -31,6 +33,7 @@ go_test( "//submitqueue/gateway/extension/storage/mock:go_default_library", "@com_github_stretchr_testify//assert:go_default_library", "@com_github_stretchr_testify//require:go_default_library", + "@com_github_uber_go_tally//:go_default_library", "@org_uber_go_mock//gomock:go_default_library", ], ) diff --git a/submitqueue/gateway/core/request/materializer.go b/submitqueue/gateway/core/request/materializer.go index 80fa1b69a..273bb68b4 100644 --- a/submitqueue/gateway/core/request/materializer.go +++ b/submitqueue/gateway/core/request/materializer.go @@ -19,7 +19,10 @@ import ( "errors" "fmt" "maps" + "time" + "github.com/uber-go/tally" + "github.com/uber/submitqueue/platform/metrics" "github.com/uber/submitqueue/submitqueue/entity" basestorage "github.com/uber/submitqueue/submitqueue/extension/storage" gwstorage "github.com/uber/submitqueue/submitqueue/gateway/extension/storage" @@ -30,12 +33,26 @@ import ( // Every store it touches is queue-scoped, so each call resolves the aggregate once // from the queue carried on the log being persisted. type Materializer struct { - stores gwstorage.Factory + stores gwstorage.Factory + metricsScope tally.Scope +} + +// MaterializerOption configures a Materializer. +type MaterializerOption func(*Materializer) + +// WithMetricsScope emits request lifecycle metrics on scope. Without it the +// materializer emits none. +func WithMetricsScope(scope tally.Scope) MaterializerOption { + return func(m *Materializer) { m.metricsScope = scope } } // NewMaterializer creates a request read-model materializer. -func NewMaterializer(stores gwstorage.Factory) *Materializer { - return &Materializer{stores: stores} +func NewMaterializer(stores gwstorage.Factory, opts ...MaterializerOption) *Materializer { + m := &Materializer{stores: stores, metricsScope: tally.NoopScope} + for _, opt := range opts { + opt(m) + } + return m } // PersistLog appends one audit log and materializes its winning state. @@ -76,6 +93,7 @@ func (m *Materializer) PersistLog(ctx context.Context, log entity.RequestLog) er return fmt.Errorf("failed to update request summary request_id=%s: %w", log.RequestID, err) } updated.Version = newVersion + m.recordLifecycleTransition(summary, updated) summary = updated } @@ -92,6 +110,38 @@ func (m *Materializer) PersistLog(ctx context.Context, log entity.RequestLog) er } } +// recordLifecycleTransition counts a request's public lifecycle milestones from +// one successful summary update. +// +// Each milestone is recorded on the update that crosses it, never on a winning +// log that merely restates it: an orchestrator retry re-publishes a terminal log +// with the same request version and a newer timestamp, which wins logWins and +// rewrites the summary again. Comparing the summary before and after the update +// is what keeps each request counted once. +func (m *Materializer) recordLifecycleTransition(before, after entity.RequestSummary) { + queueTag := metrics.NewTag("queue", after.Queue) + if before.Status == entity.RequestStatusAccepting && after.Status != entity.RequestStatusAccepting { + metrics.NamedCounter(m.metricsScope, "request_lifecycle", "accepted", 1, queueTag) + } + if isTerminalStatus(before.Status) || !isTerminalStatus(after.Status) { + return + } + statusTag := metrics.NewTag("status", string(after.Status)) + metrics.NamedCounter(m.metricsScope, "request_lifecycle", "terminated", 1, + queueTag, statusTag, metrics.NewTag("from_status", string(before.Status))) + if before.ReceivedAtMs <= 0 { + return + } + // Clock skew between the gateway and the orchestrator can put the terminal timestamp before receipt. + elapsed := max(time.Duration(after.StatusTimestampMs-before.ReceivedAtMs)*time.Millisecond, 0) + metrics.NamedHistogram(m.metricsScope, "request_lifecycle", "end_to_end_latency", metrics.LandLatencyBuckets, + queueTag, statusTag).RecordDuration(elapsed) +} + +func isTerminalStatus(status entity.RequestStatus) bool { + return entity.IsRequestStateTerminal(entity.RequestState(status)) +} + // ensureRequestURIMappings retries every immutable mapping, including after partial activation. func ensureRequestURIMappings(ctx context.Context, uris basestorage.RequestURIStore, summary entity.RequestSummary) error { for _, changeURI := range summary.ChangeURIs { diff --git a/submitqueue/gateway/core/request/materializer_test.go b/submitqueue/gateway/core/request/materializer_test.go index 8e4d0564e..e35ccab36 100644 --- a/submitqueue/gateway/core/request/materializer_test.go +++ b/submitqueue/gateway/core/request/materializer_test.go @@ -65,6 +65,103 @@ func TestMaterializer_PersistLog(t *testing.T) { }) } +func TestMaterializer_RecordsLifecycleMetrics(t *testing.T) { + started := testRequestSummary() + started.Status, started.RequestVersion, started.StatusTimestampMs = entity.RequestStatusStarted, 1, 15 + landed := started + landed.Status, landed.RequestVersion, landed.StatusTimestampMs = entity.RequestStatusLanded, 2, 20 + unreceived := started + unreceived.ReceivedAtMs = 0 + statusLog := func(status entity.RequestStatus, version int32, timestampMs int64) entity.RequestLog { + return entity.RequestLog{Queue: "q", RequestID: "1", Type: entity.RequestLogTypeStatus, Status: status, RequestVersion: version, TimestampMs: timestampMs} + } + + tests := []struct { + name string + before entity.RequestSummary + log entity.RequestLog + wantUpdate bool + wantCounters map[string]int64 + wantHistograms []string + }{ + { + name: "accepted log moves the request out of accepting", + before: testRequestSummary(), + log: statusLog(entity.RequestStatusAccepted, 0, 20), + wantUpdate: true, + wantCounters: map[string]int64{"request_lifecycle.accepted+queue=q": 1}, + }, + { + name: "a later status overtaking the accepted log still counts acceptance once", + before: testRequestSummary(), + log: statusLog(entity.RequestStatusStarted, 1, 20), + wantUpdate: true, + wantCounters: map[string]int64{"request_lifecycle.accepted+queue=q": 1}, + }, + { + name: "terminal log finishes the request and records its land time", + before: started, + log: statusLog(entity.RequestStatusLanded, 2, 20), + wantUpdate: true, + wantCounters: map[string]int64{"request_lifecycle.terminated+from_status=started,queue=q,status=landed": 1}, + wantHistograms: []string{"request_lifecycle.end_to_end_latency+queue=q,status=landed"}, + }, + { + name: "missing receipt time counts the finish without a land time", + before: unreceived, + log: statusLog(entity.RequestStatusError, 2, 20), + wantUpdate: true, + wantCounters: map[string]int64{"request_lifecycle.terminated+from_status=started,queue=q,status=error": 1}, + }, + { + name: "re-published terminal log with a newer timestamp rewrites the summary without counting again", + before: landed, + log: statusLog(entity.RequestStatusLanded, 2, 30), + wantUpdate: true, + }, + { + name: "identical terminal redelivery leaves the summary and the metrics alone", + before: landed, + log: statusLog(entity.RequestStatusLanded, 2, 20), + }, + { + name: "cancelling is not a finished status", + before: started, + log: statusLog(entity.RequestStatusCancelling, 0, 20), + wantUpdate: true, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + f := newMaterializerReceiptFixture(gomock.NewController(t)) + f.logs.EXPECT().Insert(gomock.Any(), tt.log).Return(nil) + f.summaries.EXPECT().Get(gomock.Any(), tt.before.RequestID).Return(tt.before, nil) + if tt.wantUpdate { + f.summaries.EXPECT().Update(gomock.Any(), gomock.Any(), tt.before.Version, tt.before.Version+1).Return(nil) + } + f.uris.EXPECT().Create(gomock.Any(), gomock.Any()).Return(nil).AnyTimes() + f.receipts.EXPECT().Create(gomock.Any(), gomock.Any()).Return(nil).AnyTimes() + + require.NoError(t, f.materializer.PersistLog(context.Background(), tt.log)) + + snapshot := f.metrics.Snapshot() + counters := map[string]int64{} + for key, counter := range snapshot.Counters() { + counters[key] = counter.Value() + } + if tt.wantCounters == nil { + tt.wantCounters = map[string]int64{} + } + assert.Equal(t, tt.wantCounters, counters) + histograms := []string{} + for key := range snapshot.Histograms() { + histograms = append(histograms, key) + } + assert.ElementsMatch(t, tt.wantHistograms, histograms) + }) + } +} + func TestMaterializer_PersistenceFailures(t *testing.T) { writeErr := errors.New("storage unavailable") tests := []struct { diff --git a/submitqueue/gateway/core/request/request_receipt_test.go b/submitqueue/gateway/core/request/request_receipt_test.go index a20fbaeb1..a35dd05ec 100644 --- a/submitqueue/gateway/core/request/request_receipt_test.go +++ b/submitqueue/gateway/core/request/request_receipt_test.go @@ -20,6 +20,7 @@ import ( "testing" "github.com/stretchr/testify/require" + "github.com/uber-go/tally" "github.com/uber/submitqueue/submitqueue/entity" "github.com/uber/submitqueue/submitqueue/extension/storage" storagemock "github.com/uber/submitqueue/submitqueue/extension/storage/mock" @@ -33,6 +34,7 @@ type materializerReceiptFixture struct { uris *storagemock.MockRequestURIStore logs *storagemock.MockRequestLogStore receipts *storagemock.MockRequestReceiptStore + metrics tally.TestScope } func newMaterializerReceiptFixture(ctrl *gomock.Controller) materializerReceiptFixture { @@ -40,6 +42,7 @@ func newMaterializerReceiptFixture(ctrl *gomock.Controller) materializerReceiptF summaries: storagemock.NewMockRequestSummaryStore(ctrl), uris: storagemock.NewMockRequestURIStore(ctrl), logs: storagemock.NewMockRequestLogStore(ctrl), receipts: storagemock.NewMockRequestReceiptStore(ctrl), + metrics: tally.NewTestScope("", nil), } stores := gwstoragemock.NewMockStorage(ctrl) stores.EXPECT().GetRequestSummaryStore().Return(f.summaries).AnyTimes() @@ -48,7 +51,7 @@ func newMaterializerReceiptFixture(ctrl *gomock.Controller) materializerReceiptF stores.EXPECT().GetRequestReceiptStore().Return(f.receipts).AnyTimes() factory := gwstoragemock.NewMockFactory(ctrl) factory.EXPECT().For(gomock.Any()).Return(stores, nil).AnyTimes() - f.materializer = NewMaterializer(factory) + f.materializer = NewMaterializer(factory, WithMetricsScope(f.metrics)) return f } diff --git a/submitqueue/gateway/extension/storage/mysql/request_log_store.go b/submitqueue/gateway/extension/storage/mysql/request_log_store.go index d7114127a..c23d5c559 100644 --- a/submitqueue/gateway/extension/storage/mysql/request_log_store.go +++ b/submitqueue/gateway/extension/storage/mysql/request_log_store.go @@ -80,7 +80,7 @@ func (r *requestLogStore) Insert(ctx context.Context, log entity.RequestLog) (re // and never returned to callers. func (r *requestLogStore) List(ctx context.Context, requestID string) (ret []entity.RequestLog, retErr error) { op := metrics.Begin(r.scope, "list", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() rows, err := r.db.QueryContext(ctx, "SELECT queue, request_id, timestamp_ms, type, status, event, request_version, last_error, metadata FROM request_log WHERE queue = ? AND request_id = ? ORDER BY timestamp_ms ASC, salt ASC", diff --git a/submitqueue/gateway/extension/storage/mysql/request_receipt_store.go b/submitqueue/gateway/extension/storage/mysql/request_receipt_store.go index 34e666262..f83e039e9 100644 --- a/submitqueue/gateway/extension/storage/mysql/request_receipt_store.go +++ b/submitqueue/gateway/extension/storage/mysql/request_receipt_store.go @@ -76,7 +76,7 @@ func (r *requestReceiptStore) Create(ctx context.Context, receipt entity.Request func (r *requestReceiptStore) List(ctx context.Context, bounds storage.RequestReceiptRange) (ret []entity.RequestReceipt, retErr error) { op := metrics.Begin(r.scope, "list", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() if err := validateRequestReceiptRange(bounds); err != nil { return nil, err diff --git a/submitqueue/gateway/extension/storage/mysql/request_summary_store.go b/submitqueue/gateway/extension/storage/mysql/request_summary_store.go index 53f57073d..0dfdc35b9 100644 --- a/submitqueue/gateway/extension/storage/mysql/request_summary_store.go +++ b/submitqueue/gateway/extension/storage/mysql/request_summary_store.go @@ -78,7 +78,7 @@ func (s *requestSummaryStore) Create(ctx context.Context, summary entity.Request func (s *requestSummaryStore) Get(ctx context.Context, requestID string) (ret entity.RequestSummary, retErr error) { op := metrics.Begin(s.scope, "get", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() var changeURIsJSON []byte var metadataJSON []byte diff --git a/submitqueue/gateway/extension/storage/mysql/request_uri_store.go b/submitqueue/gateway/extension/storage/mysql/request_uri_store.go index 704f8b876..01913d63c 100644 --- a/submitqueue/gateway/extension/storage/mysql/request_uri_store.go +++ b/submitqueue/gateway/extension/storage/mysql/request_uri_store.go @@ -65,7 +65,7 @@ func (s *requestURIStore) Create(ctx context.Context, mapping entity.RequestURI) func (s *requestURIStore) ListByURI(ctx context.Context, changeURI string, limit int) (ret []entity.RequestURI, retErr error) { op := metrics.Begin(s.scope, "list_by_uri", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() rows, err := s.db.QueryContext(ctx, ` SELECT queue, change_uri, received_at_ms, request_id diff --git a/submitqueue/orchestrator/controller/batch/batch.go b/submitqueue/orchestrator/controller/batch/batch.go index 90846725c..f6012a748 100644 --- a/submitqueue/orchestrator/controller/batch/batch.go +++ b/submitqueue/orchestrator/controller/batch/batch.go @@ -85,7 +85,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er rid, err := sqmq.UnmarshalRequestID(c.topicKey, msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize request ID: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, rid.Queue); err != nil { @@ -94,7 +94,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: rid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", rid.Queue, err) } @@ -102,14 +102,14 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // Fetch request from storage request, err := store.GetRequestStore().Get(ctx, rid.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get request %s: %w", rid.ID, err) } // The payload's queue must match the request's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if rid.Queue != "" && rid.Queue != request.Queue { - metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("payload queue %q does not match queue %q of request %s", rid.Queue, request.Queue, request.ID) } @@ -127,7 +127,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // (RequestStateCancelling). A halted request must never spawn a new batch. // If cancellation races with an attempt already initializing below, speculate re-checks the contained request state before starting work. if entity.IsRequestStateHalted(request.State) { - metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("skipping batch for halted request", "request_id", request.ID, "state", string(request.State), @@ -140,17 +140,17 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // Generate a queue-scoped batch ID. queueCounter, err := c.counters.For(counter.Config{QueueName: request.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "counter_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "counter_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to resolve counter for queue=%s: %w", request.Queue, err) } seq, err := queueCounter.Next(ctx, counterDomainBatch) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "counter_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "counter_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to generate batch ID for queue=%s: %w", request.Queue, err) } batchID, err := id.FromCounter(seq) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "counter_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "counter_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("generated invalid batch ID for queue=%s: %w", request.Queue, err) } @@ -170,7 +170,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // DependencyBatchStates, and nothing is associated with it yet, so a batch // abandoned here is a row nobody can reach. if err := store.GetBatchStore().Create(ctx, batch); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to create batch in batch store: %w", err) } @@ -181,7 +181,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er "batch_id": batch.ID, }) if err := corerequest.PublishLog(ctx, c.registry, logEntry, request.ID, ""); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish request log for request %s: %w", request.ID, err) } @@ -194,8 +194,8 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // another. Enrolment is decided downstream, so duplicates here cost storage, // not correctness. if err := c.publishToDependencyAnalysis(ctx, batch); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) - metrics.NamedCounter(c.metricsScope, opName, "batch_abandoned_creating", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) + metrics.NamedCounter(c.metricsScope, opName, "batch_abandoned_creating", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish batch ID to dependency-analysis topic: %w", err) } diff --git a/submitqueue/orchestrator/controller/build/build.go b/submitqueue/orchestrator/controller/build/build.go index 59e724eb7..2d7015711 100644 --- a/submitqueue/orchestrator/controller/build/build.go +++ b/submitqueue/orchestrator/controller/build/build.go @@ -106,7 +106,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er bid, err := sqmq.UnmarshalBatchID(c.topicKey, msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize batch ID: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, bid.Queue); err != nil { @@ -115,7 +115,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: bid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", bid.Queue, err) } @@ -123,14 +123,14 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // Fetch batch from storage batch, err := store.GetBatchStore().Get(ctx, bid.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get batch %s: %w", bid.ID, err) } // The payload's queue must match the batch's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if bid.Queue != "" && bid.Queue != batch.Queue { - metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("payload queue %q does not match queue %q of batch %s", bid.Queue, batch.Queue, batch.ID) } @@ -139,10 +139,10 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er if errors.Is(err, storage.ErrNotFound) { // No speculation run has funded this head yet, so there is nothing // to dispatch. A later run publishes again once it has. - metrics.NamedCounter(c.metricsScope, opName, "no_path_set", 1) + metrics.NamedCounter(c.metricsScope, opName, "no_path_set", 1, metrics.TagsFromContext(ctx)...) return nil } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get path set for batch %s: %w", batch.ID, err) } @@ -182,7 +182,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er } if entry.Status == entity.SpeculationPathStatusPending { - metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1, metrics.TagsFromContext(ctx)...) } if recovering { @@ -225,10 +225,10 @@ func (c *Controller) startPath(ctx context.Context, store orchstorage.Storage, b case err == nil: // Already dispatched and named; all that can be missing is the signal, // and a re-publish is deduped by the queue when it is not. - metrics.NamedCounter(c.metricsScope, opName, "already_dispatched", 1) + metrics.NamedCounter(c.metricsScope, opName, "already_dispatched", 1, metrics.TagsFromContext(ctx)...) return c.publishBuildSignal(ctx, existing.BuildID, batch.Queue) case !errors.Is(err, storage.ErrNotFound): - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to look up build for path %s attempt %d: %w", entry.ID, entry.Attempt, err) } @@ -239,7 +239,7 @@ func (c *Controller) startPath(ctx context.Context, store orchstorage.Storage, b buildRunner, err := c.buildRunners.For(buildrunner.Config{QueueName: batch.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "trigger_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "trigger_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to build runner for batch %s: %w", batch.ID, err) } @@ -247,7 +247,7 @@ func (c *Controller) startPath(ctx context.Context, store orchstorage.Storage, b // requester / ticket pulled off the originating LandRequest). buildID, err := buildRunner.Trigger(ctx, base, batch, nil) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "trigger_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "trigger_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to trigger build for path %s attempt %d: %w", entry.ID, entry.Attempt, err) } @@ -263,7 +263,7 @@ func (c *Controller) startPath(ctx context.Context, store orchstorage.Storage, b // row to Update against. ErrAlreadyExists is benign — a redelivery // of this message after a previous successful Create. if err := store.GetBuildStore().Create(ctx, build); err != nil && !errors.Is(err, storage.ErrAlreadyExists) { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to record build %s: %w", buildID.ID, err) } @@ -277,7 +277,7 @@ func (c *Controller) startPath(ctx context.Context, store orchstorage.Storage, b // because the dispatch that won may have died before sending it, // and acking this message would retire the redelivery that would // otherwise repair that. - metrics.NamedCounter(c.metricsScope, opName, "lost_dispatch_race", 1) + metrics.NamedCounter(c.metricsScope, opName, "lost_dispatch_race", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("lost the dispatch race; handing both builds to the poll loop", "batch_id", batch.ID, "path_id", entry.ID, @@ -289,16 +289,16 @@ func (c *Controller) startPath(ctx context.Context, store orchstorage.Storage, b } winner, err := store.GetPathBuildStore().Get(ctx, entry.ID, entry.Attempt) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to look up the winning build for path %s attempt %d: %w", entry.ID, entry.Attempt, err) } return c.publishBuildSignal(ctx, winner.BuildID, batch.Queue) } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to link path %s attempt %d to build %s: %w", entry.ID, entry.Attempt, buildID.ID, err) } - metrics.NamedCounter(c.metricsScope, opName, "build_triggered", 1) + metrics.NamedCounter(c.metricsScope, opName, "build_triggered", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("triggered build for speculation path", "batch_id", batch.ID, "path_id", entry.ID, @@ -333,11 +333,11 @@ func (c *Controller) ensureSignal(ctx context.Context, store orchstorage.Storage return nil } if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to look up build for path %s attempt %d: %w", entry.ID, entry.Attempt, err) } - metrics.NamedCounter(c.metricsScope, opName, "signal_ensured", 1) + metrics.NamedCounter(c.metricsScope, opName, "signal_ensured", 1, metrics.TagsFromContext(ctx)...) c.logger.Debugw("re-published build signal on redelivery", "batch_id", batch.ID, "path_id", entry.ID, @@ -362,7 +362,7 @@ func (c *Controller) loadBase(ctx context.Context, store orchstorage.Storage, pa for _, depID := range deps { b, err := store.GetBatchStore().Get(ctx, depID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return nil, fmt.Errorf("failed to get dependency batch %s of path %s: %w", depID, path.ID(), err) } base = append(base, b) @@ -394,7 +394,7 @@ func (c *Controller) publishBuildSignal(ctx context.Context, buildID, queue stri Payload: payload, PartitionKey: buildID, }); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish to buildsignal: %w", err) } return nil diff --git a/submitqueue/orchestrator/controller/buildsignal/buildsignal.go b/submitqueue/orchestrator/controller/buildsignal/buildsignal.go index 0cb66594c..7625af091 100644 --- a/submitqueue/orchestrator/controller/buildsignal/buildsignal.go +++ b/submitqueue/orchestrator/controller/buildsignal/buildsignal.go @@ -142,7 +142,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er buildID, err := sqmq.UnmarshalBuildID(c.topicKey, msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: malformed messages will never succeed. return fmt.Errorf("failed to deserialize build ID: %w", err) } @@ -152,7 +152,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: buildID.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", buildID.Queue, err) } @@ -162,7 +162,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // snapshot the poll loop updates. build, err := store.GetBuildStore().Get(ctx, buildID.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get build %s: %w", buildID.ID, err) } @@ -177,26 +177,26 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // BuildRunner) and lets us short-circuit halted batches before polling. batch, err := store.GetBatchStore().Get(ctx, build.BatchID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get batch %s: %w", build.BatchID, err) } // The payload's queue must match the batch's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if buildID.Queue != "" && buildID.Queue != batch.Queue { - metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("payload queue %q does not match queue %q of batch %s", buildID.Queue, batch.Queue, batch.ID) } buildRunner, err := c.buildRunners.For(buildrunner.Config{QueueName: batch.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "status_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "status_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to build runner for batch %s: %w", batch.ID, err) } status, buildMeta, err := buildRunner.Status(ctx, buildID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "status_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "status_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get status for build %s: %w", buildID.ID, err) } @@ -211,14 +211,14 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er } if stop { if err := buildRunner.Cancel(ctx, buildID); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "cancel_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "cancel_errors", 1, metrics.TagsFromContext(ctx)...) c.logger.Warnw("failed to cancel an unwanted build; the next poll retries", "build_id", build.ID, "batch_id", build.BatchID, "error", err, ) } else { - metrics.NamedCounter(c.metricsScope, opName, "build_cancelled", 1) + metrics.NamedCounter(c.metricsScope, opName, "build_cancelled", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("requested cancellation of a build nothing wants running", "build_id", build.ID, "batch_id", build.BatchID, @@ -236,13 +236,13 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // replay would read the already-updated record and take neither branch. // Publishing first means the replay re-publishes and the queue dedupes. if err := c.publishBuildLogs(ctx, batch, build, status, buildMeta); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish request logs for build %s: %w", build.ID, err) } build.Status = status if err := store.GetBuildStore().Update(ctx, build); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to update status for build %s: %w", build.ID, err) } } @@ -258,12 +258,12 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er if err := c.publishBatchID(ctx, topickey.TopicKeySpeculate, publish.IntentID(batch.ID, "build-signal", build.ID, string(status)), batch.ID, batch.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish to speculate: %w", err) } if status.IsTerminal() { - metrics.NamedCounter(c.metricsScope, opName, "terminal", 1, metrics.NewTag("status", string(status))) + metrics.NamedCounter(c.metricsScope, opName, "terminal", 1, metrics.TagsFromContext(ctx, metrics.NewTag("status", string(status)))...) c.logger.Infow("build reached terminal status", "build_id", build.ID, "batch_id", build.BatchID, @@ -275,7 +275,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // Not terminal yet: hold the delivery so this same message redelivers // after the poll delay, without counting toward the retry limit. delayMs := pollDelay(status) - metrics.NamedCounter(c.metricsScope, opName, "rescheduled", 1, metrics.NewTag("status", string(status))) + metrics.NamedCounter(c.metricsScope, opName, "rescheduled", 1, metrics.TagsFromContext(ctx, metrics.NewTag("status", string(status)))...) delivery.Hold(delayMs) c.logger.Debugw("holding for next build status poll", @@ -376,20 +376,20 @@ func (c *Controller) unwanted(ctx context.Context, store orchstorage.Storage, ba set, err := store.GetSpeculationPathSetStore().Get(ctx, batch.ID) if err != nil { if errors.Is(err, storage.ErrNotFound) { - metrics.NamedCounter(c.metricsScope, opName, "kill_list_anomalies", 1) + metrics.NamedCounter(c.metricsScope, opName, "kill_list_anomalies", 1, metrics.TagsFromContext(ctx)...) c.logger.Warnw("build exists but its head has no path set; keeping the build", "build_id", build.ID, "batch_id", batch.ID, ) return false, nil } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return false, fmt.Errorf("failed to get path set for batch %s: %w", batch.ID, err) } entry, found := findEntry(set, build.PathID) if !found { - metrics.NamedCounter(c.metricsScope, opName, "kill_list_anomalies", 1) + metrics.NamedCounter(c.metricsScope, opName, "kill_list_anomalies", 1, metrics.TagsFromContext(ctx)...) c.logger.Warnw("build exists but its path is gone from the set; keeping the build", "build_id", build.ID, "batch_id", batch.ID, @@ -412,7 +412,7 @@ func (c *Controller) unwanted(ctx context.Context, store orchstorage.Storage, ba link, err := store.GetPathBuildStore().Get(ctx, build.PathID, build.Attempt) if err != nil { if errors.Is(err, storage.ErrNotFound) { - metrics.NamedCounter(c.metricsScope, opName, "kill_list_anomalies", 1) + metrics.NamedCounter(c.metricsScope, opName, "kill_list_anomalies", 1, metrics.TagsFromContext(ctx)...) c.logger.Warnw("build exists but its attempt has no link; keeping the build", "build_id", build.ID, "path_id", build.PathID, @@ -420,7 +420,7 @@ func (c *Controller) unwanted(ctx context.Context, store orchstorage.Storage, ba ) return false, nil } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return false, fmt.Errorf("failed to look up build for path %s attempt %d: %w", build.PathID, build.Attempt, err) } diff --git a/submitqueue/orchestrator/controller/cancel/cancel.go b/submitqueue/orchestrator/controller/cancel/cancel.go index 35ce9417c..11ebbb064 100644 --- a/submitqueue/orchestrator/controller/cancel/cancel.go +++ b/submitqueue/orchestrator/controller/cancel/cancel.go @@ -110,7 +110,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er cancelReq, err := sqmq.UnmarshalCancelRequest(msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize cancel request: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, cancelReq.Queue); err != nil { @@ -119,21 +119,21 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: cancelReq.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", cancelReq.Queue, err) } request, err := store.GetRequestStore().Get(ctx, cancelReq.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get request %s: %w", cancelReq.ID, err) } // The payload's queue must match the request's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if cancelReq.Queue != "" && cancelReq.Queue != request.Queue { - metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("payload queue %q does not match queue %q of request %s", cancelReq.Queue, request.Queue, request.ID) } @@ -148,7 +148,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er ) if entity.IsRequestStateTerminal(request.State) { - metrics.NamedCounter(c.metricsScope, opName, "already_terminal", 1) + metrics.NamedCounter(c.metricsScope, opName, "already_terminal", 1, metrics.TagsFromContext(ctx)...) return nil } @@ -176,7 +176,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er case batch.State.IsCancellable(): foundApplicableBatch = true if err := c.cancelBatch(ctx, store, batch); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_cancel_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_cancel_errors", 1, metrics.TagsFromContext(ctx)...) c.logger.Errorw("failed to cancel batch", "batch_id", batch.ID, "batch_state", string(batch.State), @@ -189,11 +189,11 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er case batch.State == entity.BatchStateLanding: // Land owns the outcome once it has started. Conclude will reconcile the request with that outcome. foundApplicableBatch = true - metrics.NamedCounter(c.metricsScope, opName, "batch_landing", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_landing", 1, metrics.TagsFromContext(ctx)...) case batch.State.IsTerminal(): // The terminal batch outcome wins; conclude may not have reconciled the request yet. foundApplicableBatch = true - metrics.NamedCounter(c.metricsScope, opName, "batch_already_terminal", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_already_terminal", 1, metrics.TagsFromContext(ctx)...) } } @@ -215,17 +215,17 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er func (c *Controller) markCancelling(ctx context.Context, store orchstorage.Storage, request entity.Request) (entity.Request, error) { if request.State == entity.RequestStateCancelling { // Idempotent re-delivery: prior pass already recorded intent. - metrics.NamedCounter(c.metricsScope, opName, "already_cancelling", 1) + metrics.NamedCounter(c.metricsScope, opName, "already_cancelling", 1, metrics.TagsFromContext(ctx)...) return request, nil } newVersion := request.Version + 1 request.State = entity.RequestStateCancelling if err := store.GetRequestStore().Update(ctx, request, request.Version, newVersion); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_update_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_update_errors", 1, metrics.TagsFromContext(ctx)...) return entity.Request{}, fmt.Errorf("failed to mark request %s as cancelling: %w", request.ID, err) } request.Version = newVersion - metrics.NamedCounter(c.metricsScope, opName, "request_cancelling", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_cancelling", 1, metrics.TagsFromContext(ctx)...) return request, nil } @@ -234,11 +234,11 @@ func (c *Controller) markCancelling(ctx context.Context, store orchstorage.Stora func (c *Controller) findBatches(ctx context.Context, store orchstorage.Storage, request entity.Request) ([]entity.Batch, error) { batches, stale, err := corebatch.FindByRequestID(ctx, store, request.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_lookup_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_lookup_errors", 1, metrics.TagsFromContext(ctx)...) return nil, err } if stale > 0 { - metrics.NamedCounter(c.metricsScope, opName, "stale_batch_associations", int64(stale)) + metrics.NamedCounter(c.metricsScope, opName, "stale_batch_associations", int64(stale), metrics.TagsFromContext(ctx)...) } return batches, nil } @@ -263,7 +263,7 @@ func (c *Controller) cancelRequest(ctx context.Context, store orchstorage.Storag } res, err := corerequest.TerminateRequest(ctx, store, c.registry, request.ID, entity.RequestStateCancelled, "", metadata) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_terminate_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_terminate_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to cancel request %s: %w", request.ID, err) } @@ -273,16 +273,16 @@ func (c *Controller) cancelRequest(ctx context.Context, store orchstorage.Storag "request_id", request.ID, "queue", request.Queue, ) - metrics.NamedCounter(c.metricsScope, opName, "request_cancelled", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_cancelled", 1, metrics.TagsFromContext(ctx)...) case corerequest.TerminationOutcomeDiverged: c.logger.Infow("request reached a different terminal state before cancel, skipping", "request_id", request.ID, "queue", request.Queue, "actual_state", string(res.BeforeState), ) - metrics.NamedCounter(c.metricsScope, opName, "request_terminal_divergence", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_terminal_divergence", 1, metrics.TagsFromContext(ctx)...) case corerequest.TerminationOutcomeNotFound: - metrics.NamedCounter(c.metricsScope, opName, "request_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("request %s not found during cancel: %w", request.ID, storage.ErrNotFound) } return nil @@ -315,7 +315,7 @@ func (c *Controller) cancelBatch(ctx context.Context, store orchstorage.Storage, var err error batch, err = corebatch.Transition(ctx, store, batch, entity.BatchStateCancelling) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_update_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_update_errors", 1, metrics.TagsFromContext(ctx)...) // storage.ErrVersionMismatch here means the batch advanced concurrently // (e.g. speculate / land progressed). Returned as-is because the // sentinel is intrinsically retryable; the re-fetch will see the new state @@ -323,23 +323,23 @@ func (c *Controller) cancelBatch(ctx context.Context, store orchstorage.Storage, // again. return fmt.Errorf("failed to mark batch %s as cancelling: %w", batch.ID, err) } - metrics.NamedCounter(c.metricsScope, opName, "batch_cancelling", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_cancelling", 1, metrics.TagsFromContext(ctx)...) } else { - metrics.NamedCounter(c.metricsScope, opName, "batch_already_cancelling", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_already_cancelling", 1, metrics.TagsFromContext(ctx)...) // A prior pass wrote the intent but may have crashed before completing // the membership record move; repair before re-publishing. if err := corebatch.EnsureRecord(ctx, store, batch); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_update_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_update_errors", 1, metrics.TagsFromContext(ctx)...) return err } } if err := c.publishBatchID(ctx, topickey.TopicKeySpeculate, batch.ID, batch.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to hand off cancelled batch %s to speculate: %w", batch.ID, err) } - metrics.NamedCounter(c.metricsScope, opName, "batch_handed_off", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_handed_off", 1, metrics.TagsFromContext(ctx)...) return nil } diff --git a/submitqueue/orchestrator/controller/conclude/conclude.go b/submitqueue/orchestrator/controller/conclude/conclude.go index 62dea9b3d..42e041e7f 100644 --- a/submitqueue/orchestrator/controller/conclude/conclude.go +++ b/submitqueue/orchestrator/controller/conclude/conclude.go @@ -73,7 +73,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er bid, err := sqmq.UnmarshalBatchID(c.topicKey, msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, "process", "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, "process", "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize batch ID: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, bid.Queue); err != nil { @@ -82,7 +82,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: bid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, "process", "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, "process", "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", bid.Queue, err) } @@ -90,14 +90,14 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // Fetch batch from storage batch, err := store.GetBatchStore().Get(ctx, bid.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, "process", "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, "process", "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get batch %s: %w", bid.ID, err) } // The payload's queue must match the batch's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if bid.Queue != "" && bid.Queue != batch.Queue { - metrics.NamedCounter(c.metricsScope, "process", "queue_mismatch", 1) + metrics.NamedCounter(c.metricsScope, "process", "queue_mismatch", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("payload queue %q does not match queue %q of batch %s", bid.Queue, batch.Queue, batch.ID) } @@ -116,7 +116,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // failOnDependency, Cancelled via cancelBatch). requestState, err := batchStateToRequestState(batch.State) if err != nil { - metrics.NamedCounter(c.metricsScope, "process", "unexpected_state_errors", 1) + metrics.NamedCounter(c.metricsScope, "process", "unexpected_state_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("unexpected batch state %q for batch %s: %w", batch.State, batch.ID, err) } @@ -137,7 +137,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er "batch_id": batch.ID, }) if err != nil { - metrics.NamedCounter(c.metricsScope, "process", "terminate_errors", 1) + metrics.NamedCounter(c.metricsScope, "process", "terminate_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to terminate request %s for batch %s: %w", requestID, batch.ID, err) } @@ -149,7 +149,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er "new_state", string(res.AfterState), ) case corerequest.TerminationOutcomeAlreadyInTargetState: - metrics.NamedCounter(c.metricsScope, "process", "already_reconciled", 1) + metrics.NamedCounter(c.metricsScope, "process", "already_reconciled", 1, metrics.TagsFromContext(ctx)...) case corerequest.TerminationOutcomeDiverged: c.logger.Warnw("request already in different terminal state, skipping reconcile", "batch_id", batch.ID, @@ -157,9 +157,9 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er "expected_state", string(requestState), "actual_state", string(res.BeforeState), ) - metrics.NamedCounter(c.metricsScope, "process", "terminal_state_divergence", 1) + metrics.NamedCounter(c.metricsScope, "process", "terminal_state_divergence", 1, metrics.TagsFromContext(ctx)...) case corerequest.TerminationOutcomeNotFound: - metrics.NamedCounter(c.metricsScope, "process", "request_store_errors", 1) + metrics.NamedCounter(c.metricsScope, "process", "request_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get request %s for batch %s: %w", requestID, batch.ID, storage.ErrNotFound) } } diff --git a/submitqueue/orchestrator/controller/dependencyanalysis/dependencyanalysis.go b/submitqueue/orchestrator/controller/dependencyanalysis/dependencyanalysis.go index 91fa13d5e..7f4dea8af 100644 --- a/submitqueue/orchestrator/controller/dependencyanalysis/dependencyanalysis.go +++ b/submitqueue/orchestrator/controller/dependencyanalysis/dependencyanalysis.go @@ -114,7 +114,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er bid, err := sqmq.UnmarshalBatchID(c.topicKey, msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize batch ID: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, bid.Queue); err != nil { @@ -123,21 +123,21 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: bid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", bid.Queue, err) } batch, err := store.GetBatchStore().Get(ctx, bid.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get batch %s: %w", bid.ID, err) } // The payload's queue must match the batch's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if bid.Queue != "" && bid.Queue != batch.Queue { - metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("payload queue %q does not match queue %q of batch %s", bid.Queue, batch.Queue, batch.ID) } @@ -153,7 +153,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er case entity.IsBatchStateHalted(batch.State): // Cancelled or concluded while the analysis message was in flight. // Promoting it now would hand speculate a batch nobody expects to land. - metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1, metrics.TagsFromContext(ctx)...) return nil case batch.State == entity.BatchStateCreating: @@ -165,7 +165,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // A previous batch message for this request was redelivered and minted // this batch too. The first one through here owns the request; this one // stays Creating, where nothing can reach it. - metrics.NamedCounter(c.metricsScope, opName, "skipped_already_enrolled", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_already_enrolled", 1, metrics.TagsFromContext(ctx)...) return nil } @@ -176,7 +176,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er if halted != "" { // Nothing has claimed the request yet, so cancel owned it outright and // has already written its outcome. - metrics.NamedCounter(c.metricsScope, opName, "skipped_halted_request", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_halted_request", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("abandoning batch; contained request is halted", "batch_id", batch.ID, "request_id", halted, @@ -210,9 +210,16 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er batch.Dependencies = dependencies batch, err = corebatch.Transition(ctx, store, batch, entity.BatchStateCreated) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to mark batch %s created: %w", batch.ID, err) } + // Recorded on the Creating→Created transition, which happens once per batch; abandoned batches never reach it. + // Named under batch_shape rather than opName so wildcards over the controller's process.* counters never + // match the histograms' bucket series. + metrics.NamedHistogram(c.metricsScope, "batch_shape", "size", metrics.CountBuckets, metrics.TagsFromContext(ctx)...). + RecordValue(float64(len(batch.Contains))) + metrics.NamedHistogram(c.metricsScope, "batch_shape", "dependencies", metrics.CountBuckets, metrics.TagsFromContext(ctx)...). + RecordValue(float64(len(batch.Dependencies))) c.logger.Infow("batch created", "batch_id", batch.ID, "queue", batch.Queue, @@ -224,15 +231,15 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // have crashed before filing the Created record, without which the next // batch's analysis cannot see this one as a dependency. if err := corebatch.EnsureRecord(ctx, store, batch); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_store_errors", 1, metrics.TagsFromContext(ctx)...) return err } - metrics.NamedCounter(c.metricsScope, opName, "reannounced", 1) + metrics.NamedCounter(c.metricsScope, opName, "reannounced", 1, metrics.TagsFromContext(ctx)...) default: // Speculating or landing: the announcement landed and the batch has // already moved past this stage. - metrics.NamedCounter(c.metricsScope, opName, "already_admitted", 1) + metrics.NamedCounter(c.metricsScope, opName, "already_admitted", 1, metrics.TagsFromContext(ctx)...) return nil } @@ -243,7 +250,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er if err := corerequest.PublishBatchLogs(ctx, c.registry, batch.Queue, batch.Contains, entity.RequestStatusBatched, "", map[string]string{"batch_id": batch.ID}, ); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish request logs for batch %s: %w", batch.ID, err) } @@ -262,11 +269,11 @@ func (c *Controller) requestEnrolledInAnotherBatch(ctx context.Context, store or for _, requestID := range batch.Contains { existing, stale, err := corebatch.FindByRequestID(ctx, store, requestID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_lookup_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_lookup_errors", 1, metrics.TagsFromContext(ctx)...) return false, err } if stale > 0 { - metrics.NamedCounter(c.metricsScope, opName, "stale_batch_associations", int64(stale)) + metrics.NamedCounter(c.metricsScope, opName, "stale_batch_associations", int64(stale), metrics.TagsFromContext(ctx)...) } for _, other := range existing { if other.ID == batch.ID || other.State == entity.BatchStateCreating { @@ -290,7 +297,7 @@ func (c *Controller) associateRequestsWithBatch(ctx context.Context, store orchs for _, requestID := range batch.Contains { association := entity.RequestBatch{RequestID: requestID, BatchID: batch.ID, Version: 1} if err := store.GetRequestBatchStore().Create(ctx, association); err != nil && !errors.Is(err, storage.ErrAlreadyExists) { - metrics.NamedCounter(c.metricsScope, opName, "request_batch_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_batch_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to associate request %s with batch %s: %w", requestID, batch.ID, err) } } @@ -315,12 +322,12 @@ func (c *Controller) claimRequestsForBatch(ctx context.Context, store orchstorag for _, requestID := range batch.Contains { request, err := store.GetRequestStore().Get(ctx, requestID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return false, fmt.Errorf("failed to get request %s of batch %s: %w", requestID, batch.ID, err) } if entity.IsRequestStateHalted(request.State) { - metrics.NamedCounter(c.metricsScope, opName, "request_claim_lost_race", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_claim_lost_race", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("abandoning batch; request was halted during analysis", "batch_id", batch.ID, "request_id", requestID, @@ -334,14 +341,14 @@ func (c *Controller) claimRequestsForBatch(ctx context.Context, store orchstorag claimed.State = entity.RequestStateBatched if err := store.GetRequestStore().Update(ctx, claimed, request.Version, newVersion); err != nil { if errors.Is(err, storage.ErrVersionMismatch) { - metrics.NamedCounter(c.metricsScope, opName, "request_claim_lost_race", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_claim_lost_race", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("abandoning batch; request advanced concurrently (likely cancel)", "batch_id", batch.ID, "request_id", requestID, ) return false, nil } - metrics.NamedCounter(c.metricsScope, opName, "request_claim_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_claim_errors", 1, metrics.TagsFromContext(ctx)...) return false, fmt.Errorf("failed to claim request %s for batch %s: %w", requestID, batch.ID, err) } } @@ -354,7 +361,7 @@ func (c *Controller) firstHaltedRequestID(ctx context.Context, store orchstorage for _, requestID := range batch.Contains { request, err := store.GetRequestStore().Get(ctx, requestID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return "", fmt.Errorf("failed to get request %s of batch %s: %w", requestID, batch.ID, err) } if entity.IsRequestStateHalted(request.State) { @@ -371,18 +378,18 @@ func (c *Controller) firstHaltedRequestID(ctx context.Context, store orchstorage func (c *Controller) resolveDependencies(ctx context.Context, store orchstorage.Storage, batch entity.Batch) ([]string, error) { inFlight, err := corebatch.ListByStates(ctx, store, entity.DependencyBatchStates()) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_store_errors", 1, metrics.TagsFromContext(ctx)...) return nil, fmt.Errorf("failed to get active batches for queue=%s: %w", batch.Queue, err) } analyzer, err := c.analyzers.For(conflict.Config{QueueName: batch.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "conflict_analyzer_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "conflict_analyzer_errors", 1, metrics.TagsFromContext(ctx)...) return nil, fmt.Errorf("failed to build conflict analyzer for queue=%s: %w", batch.Queue, err) } conflicts, err := analyzer.Analyze(ctx, batch, inFlight) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "conflict_analyzer_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "conflict_analyzer_errors", 1, metrics.TagsFromContext(ctx)...) return nil, fmt.Errorf("failed to analyze conflicts for batchID=%s: %w", batch.ID, err) } @@ -414,14 +421,14 @@ func (c *Controller) writeDependentIndexes(ctx context.Context, store orchstorag Version: 1, } if err := store.GetBatchDependentStore().Create(ctx, own); err != nil && !errors.Is(err, storage.ErrAlreadyExists) { - metrics.NamedCounter(c.metricsScope, opName, "batch_dependent_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_dependent_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to create batch dependent index for new batchID=%s: %w", batch.ID, err) } for _, dependencyID := range dependencies { existing, err := store.GetBatchDependentStore().Get(ctx, dependencyID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_dependent_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_dependent_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get batch dependent for batchID=%s: %w", dependencyID, err) } if slices.Contains(existing.Dependents, batch.ID) { @@ -432,7 +439,7 @@ func (c *Controller) writeDependentIndexes(ctx context.Context, store orchstorag updated.Dependents = append(append([]string(nil), existing.Dependents...), batch.ID) newVersion := existing.Version + 1 if err := store.GetBatchDependentStore().Update(ctx, updated, existing.Version, newVersion); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_dependent_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_dependent_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to update batch dependent index for existing batchID=%s and new batchID=%s: %w", dependencyID, batch.ID, err) } } @@ -457,7 +464,7 @@ func (c *Controller) publishToSpeculate(ctx context.Context, batch entity.Batch) Payload: payload, PartitionKey: batch.Queue, }); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish batch ID to speculate topic: %w", err) } diff --git a/submitqueue/orchestrator/controller/dependencyanalysis/dependencyanalysis_test.go b/submitqueue/orchestrator/controller/dependencyanalysis/dependencyanalysis_test.go index b654f881a..6416b3962 100644 --- a/submitqueue/orchestrator/controller/dependencyanalysis/dependencyanalysis_test.go +++ b/submitqueue/orchestrator/controller/dependencyanalysis/dependencyanalysis_test.go @@ -113,6 +113,11 @@ func storageFactoryFor(ctrl *gomock.Controller, store orchstorage.Storage) *orch // conflicts. func newTestController(t *testing.T, ctrl *gomock.Controller, store orchstorage.Storage, analyzer conflict.Analyzer, publisher *queuemock.MockPublisher) *Controller { t.Helper() + return newTestControllerWithScope(t, ctrl, store, analyzer, publisher, tally.NoopScope) +} + +func newTestControllerWithScope(t *testing.T, ctrl *gomock.Controller, store orchstorage.Storage, analyzer conflict.Analyzer, publisher *queuemock.MockPublisher, scope tally.Scope) *Controller { + t.Helper() if analyzer == nil { analyzer = all.New(analyzerCfg) @@ -132,7 +137,7 @@ func newTestController(t *testing.T, ctrl *gomock.Controller, store orchstorage. }) require.NoError(t, err) - return NewController(zaptest.NewLogger(t).Sugar(), tally.NoopScope, storageFactoryFor(ctrl, store), + return NewController(zaptest.NewLogger(t).Sugar(), scope, storageFactoryFor(ctrl, store), analyzerFactory, registry, topickey.TopicKeyDependencyAnalysis, "orchestrator-dependency-analysis") } @@ -248,8 +253,17 @@ func TestController_Process_AnalyzesAndTransitionsToCreated(t *testing.T) { store.EXPECT().GetRequestStore().Return(requestStoreFor(ctrl, liveRequest())).AnyTimes() store.EXPECT().GetRequestBatchStore().Return(noPriorEnrollment(ctrl)).AnyTimes() - controller := newTestController(t, ctrl, store, nil, nil) + scope := tally.NewTestScope("", nil) + controller := newTestControllerWithScope(t, ctrl, store, nil, nil, scope) require.NoError(t, controller.Process(context.Background(), newDelivery(t, ctrl, batch.ID, testQueue))) + + histograms := scope.Snapshot().Histograms() + size, ok := histograms["dependency_analysis_controller.batch_shape.size+"] + require.True(t, ok) + assert.Equal(t, int64(1), size.Values()[1]) + dependencies, ok := histograms["dependency_analysis_controller.batch_shape.dependencies+"] + require.True(t, ok) + assert.Equal(t, int64(1), dependencies.Values()[2]) } // The analyzer may report one in-flight batch several times when more than one @@ -334,8 +348,10 @@ func TestController_Process_RedeliveryAfterTransitionOnlyRepublishes(t *testing. publisher.EXPECT().Publish(gomock.Any(), "log", gomock.Any()).Return(nil).AnyTimes() publisher.EXPECT().Publish(gomock.Any(), "speculate", gomock.Any()).Return(nil) - controller := newTestController(t, ctrl, store, nil, publisher) + scope := tally.NewTestScope("", nil) + controller := newTestControllerWithScope(t, ctrl, store, nil, publisher, scope) require.NoError(t, controller.Process(context.Background(), newDelivery(t, ctrl, batch.ID, testQueue))) + assert.Empty(t, scope.Snapshot().Histograms(), "a batch already created must not be measured again") } // A failure part-way through the index loop leaves the batch in Creating, so diff --git a/submitqueue/orchestrator/controller/dlq/batch.go b/submitqueue/orchestrator/controller/dlq/batch.go index f2f9fca72..591c1669b 100644 --- a/submitqueue/orchestrator/controller/dlq/batch.go +++ b/submitqueue/orchestrator/controller/dlq/batch.go @@ -85,21 +85,21 @@ func (c *batchController) Process(ctx context.Context, delivery consumer.Deliver bid, err := sqmq.UnmarshalBatchID(primaryTopicKey(c.topicKey), msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to decode batch id from dlq payload: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, bid.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1, metrics.TagsFromContext(ctx)...) return nil } if bid.ID == "" { - metrics.NamedCounter(c.metricsScope, opName, "empty_id_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "empty_id_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("dlq payload decoded to empty batch id") } store, err := c.stores.For(orchstorage.Config{QueueName: bid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", bid.Queue, err) } @@ -115,7 +115,7 @@ func (c *batchController) Process(ctx context.Context, delivery consumer.Deliver ) if _, err := failBatch(ctx, store, c.registry, c.logger, bid.ID, lastError, failureMeta); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1, metrics.TagsFromContext(ctx)...) return err } diff --git a/submitqueue/orchestrator/controller/dlq/buildsignal.go b/submitqueue/orchestrator/controller/dlq/buildsignal.go index 500cb6c4b..97e3480e5 100644 --- a/submitqueue/orchestrator/controller/dlq/buildsignal.go +++ b/submitqueue/orchestrator/controller/dlq/buildsignal.go @@ -78,21 +78,21 @@ func (c *buildSignalController) Process(ctx context.Context, delivery consumer.D buildID, err := sqmq.UnmarshalBuildID(primaryTopicKey(c.topicKey), msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to decode build id from dlq payload: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, buildID.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1, metrics.TagsFromContext(ctx)...) return nil } if buildID.ID == "" { - metrics.NamedCounter(c.metricsScope, opName, "empty_id_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "empty_id_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("dlq payload decoded to empty build id") } store, err := c.stores.For(orchstorage.Config{QueueName: buildID.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", buildID.Queue, err) } @@ -114,10 +114,10 @@ func (c *buildSignalController) Process(ctx context.Context, delivery consumer.D // writing it down). There is no batch to reconcile from this // signal; any associated batch reconciles from its own DLQ. c.logger.Warnw("dlq reconcile: build not found, skipping", "build_id", buildID.ID) - metrics.NamedCounter(c.metricsScope, opName, "build_not_found", 1) + metrics.NamedCounter(c.metricsScope, opName, "build_not_found", 1, metrics.TagsFromContext(ctx)...) return nil } - metrics.NamedCounter(c.metricsScope, opName, "build_store_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "build_store_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get build %s: %w", buildID.ID, err) } @@ -125,16 +125,16 @@ func (c *buildSignalController) Process(ctx context.Context, delivery consumer.D // Defensive: a build without a batch is malformed and there is nothing // to fan out to. Log and ack so the DLQ does not grow unbounded. c.logger.Errorw("dlq reconcile: build has empty batch id, skipping", "build_id", buildID.ID) - metrics.NamedCounter(c.metricsScope, opName, "build_missing_batch", 1) + metrics.NamedCounter(c.metricsScope, opName, "build_missing_batch", 1, metrics.TagsFromContext(ctx)...) return nil } if _, err := failBatch(ctx, store, c.registry, c.logger, build.BatchID, lastError, failureMeta); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1, metrics.TagsFromContext(ctx)...) return err } - metrics.NamedCounter(c.metricsScope, opName, "reconciled", 1) + metrics.NamedCounter(c.metricsScope, opName, "reconciled", 1, metrics.TagsFromContext(ctx)...) return nil } diff --git a/submitqueue/orchestrator/controller/dlq/landconflictsignal.go b/submitqueue/orchestrator/controller/dlq/landconflictsignal.go index d9bdddca4..e61679254 100644 --- a/submitqueue/orchestrator/controller/dlq/landconflictsignal.go +++ b/submitqueue/orchestrator/controller/dlq/landconflictsignal.go @@ -73,17 +73,17 @@ func (c *landConflictSignalController) Process(ctx context.Context, delivery con result := &runwaymq.MergeResult{} if err := runwaymq.Unmarshal(msg.Payload, result); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to decode land conflict check result from dlq payload: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, result.GetQueueName()); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1, metrics.TagsFromContext(ctx)...) return nil } store, err := c.stores.For(orchstorage.Config{QueueName: result.GetQueueName()}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", result.GetQueueName(), err) } @@ -99,7 +99,7 @@ func (c *landConflictSignalController) Process(ctx context.Context, delivery con ) if err := failRequest(ctx, store, c.registry, c.logger, result.Id, lastError, failureMeta); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1, metrics.TagsFromContext(ctx)...) return err } diff --git a/submitqueue/orchestrator/controller/dlq/landsignal.go b/submitqueue/orchestrator/controller/dlq/landsignal.go index 96deb0f96..fc3f9eaf7 100644 --- a/submitqueue/orchestrator/controller/dlq/landsignal.go +++ b/submitqueue/orchestrator/controller/dlq/landsignal.go @@ -72,17 +72,17 @@ func (c *landSignalController) Process(ctx context.Context, delivery consumer.De result := &runwaymq.MergeResult{} if err := runwaymq.Unmarshal(msg.Payload, result); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to decode land result from dlq payload: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, result.GetQueueName()); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1, metrics.TagsFromContext(ctx)...) return nil } store, err := c.stores.For(orchstorage.Config{QueueName: result.GetQueueName()}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", result.GetQueueName(), err) } @@ -98,7 +98,7 @@ func (c *landSignalController) Process(ctx context.Context, delivery consumer.De ) if _, err := failBatch(ctx, store, c.registry, c.logger, result.Id, lastError, failureMeta); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1, metrics.TagsFromContext(ctx)...) return err } diff --git a/submitqueue/orchestrator/controller/dlq/request.go b/submitqueue/orchestrator/controller/dlq/request.go index 2761bec1e..6e6fc51f1 100644 --- a/submitqueue/orchestrator/controller/dlq/request.go +++ b/submitqueue/orchestrator/controller/dlq/request.go @@ -118,7 +118,7 @@ func (c *requestController) Process(ctx context.Context, delivery consumer.Deliv rid, err := c.decode(msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) // Malformed DLQ payload is non-retryable: a re-delivery will decode the // same bytes and fail the same way. The framework will route this DLQ // message to its own DLQ if one is configured; otherwise the message is @@ -126,17 +126,17 @@ func (c *requestController) Process(ctx context.Context, delivery consumer.Deliv return fmt.Errorf("failed to decode dlq payload: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, rid.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1, metrics.TagsFromContext(ctx)...) return nil } if rid.ID == "" { - metrics.NamedCounter(c.metricsScope, opName, "empty_id_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "empty_id_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("dlq payload decoded to empty request id") } store, err := c.stores.For(orchstorage.Config{QueueName: rid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", rid.Queue, err) } @@ -159,11 +159,11 @@ func (c *requestController) Process(ctx context.Context, delivery consumer.Deliv // claim and leave it building for a request reported as failed. owner, err := owningBatch(ctx, store, rid.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "batch_lookup_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "batch_lookup_errors", 1, metrics.TagsFromContext(ctx)...) return err } if owner != "" { - metrics.NamedCounter(c.metricsScope, opName, "skipped_owned_by_batch", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_owned_by_batch", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("dlq reconcile: request is carried by a live batch, leaving the outcome to conclude", "request_id", rid.ID, "batch_id", owner, @@ -172,7 +172,7 @@ func (c *requestController) Process(ctx context.Context, delivery consumer.Deliv } if err := failRequest(ctx, store, c.registry, c.logger, rid.ID, lastError, failureMeta); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1, metrics.TagsFromContext(ctx)...) return err } diff --git a/submitqueue/orchestrator/controller/dlq/speculate.go b/submitqueue/orchestrator/controller/dlq/speculate.go index c6f85c104..643646d7b 100644 --- a/submitqueue/orchestrator/controller/dlq/speculate.go +++ b/submitqueue/orchestrator/controller/dlq/speculate.go @@ -90,21 +90,21 @@ func (c *speculateController) Process(ctx context.Context, delivery consumer.Del bid, err := sqmq.UnmarshalBatchID(primaryTopicKey(c.topicKey), msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to decode batch id from dlq payload: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, bid.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_identity_errors", 1, metrics.TagsFromContext(ctx)...) return nil } if bid.ID == "" { - metrics.NamedCounter(c.metricsScope, opName, "empty_id_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "empty_id_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("dlq payload decoded to empty batch id") } store, err := c.stores.For(orchstorage.Config{QueueName: bid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", bid.Queue, err) } @@ -122,13 +122,13 @@ func (c *speculateController) Process(ctx context.Context, delivery consumer.Del "dlq_last_error", lastError, ) metrics.NamedCounter(c.metricsScope, opName, "reconciled", 1, - metrics.NewTag("attribution", attribution)) + metrics.TagsFromContext(ctx, metrics.NewTag("attribution", attribution))...) progressed := false for _, batchID := range culprits { transitioned, err := failBatch(ctx, store, c.registry, c.logger, batchID, lastError, failureMeta) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "reconcile_errors", 1, metrics.TagsFromContext(ctx)...) return err } progressed = progressed || transitioned @@ -185,7 +185,7 @@ func (c *speculateController) retrigger(ctx context.Context, store orchstorage.S live, err := corebatch.ListByStates(ctx, store, entity.ActiveBatchStates()) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to list live batches of queue %s: %w", queue, err) } if len(live) == 0 { @@ -216,11 +216,11 @@ func (c *speculateController) retrigger(ctx context.Context, store orchstorage.S Payload: payload, PartitionKey: queue, }); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to re-trigger speculation for queue %s: %w", queue, err) } - metrics.NamedCounter(c.metricsScope, opName, "retriggered", 1) + metrics.NamedCounter(c.metricsScope, opName, "retriggered", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("re-triggered speculation after dlq reconcile", "queue", queue, "batch_id", next, diff --git a/submitqueue/orchestrator/controller/land/land.go b/submitqueue/orchestrator/controller/land/land.go index 6de5240b0..6146fd5a1 100644 --- a/submitqueue/orchestrator/controller/land/land.go +++ b/submitqueue/orchestrator/controller/land/land.go @@ -100,7 +100,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er bid, err := sqmq.UnmarshalBatchID(c.topicKey, msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize batch ID: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, bid.Queue); err != nil { @@ -109,21 +109,21 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: bid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", bid.Queue, err) } batch, err := store.GetBatchStore().Get(ctx, bid.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get batch %s: %w", bid.ID, err) } // The payload's queue must match the batch's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if bid.Queue != "" && bid.Queue != batch.Queue { - metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1) + metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("payload queue %q does not match queue %q of batch %s", bid.Queue, batch.Queue, batch.ID) } @@ -142,7 +142,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // state transition and fan-out once runway's result returns, so a redelivery // at this stage simply acks. if entity.IsBatchStateHalted(batch.State) { - metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("skipping land for halted batch", "batch_id", batch.ID, "state", string(batch.State), @@ -155,7 +155,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // and runway dedupes on it; the result is matched straight back to the batch. req, err := c.buildLandRequest(ctx, store, batch) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to build land request for batch %s: %w", batch.ID, err) } @@ -165,12 +165,12 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er if err := corerequest.PublishBatchLogs(ctx, c.registry, batch.Queue, batch.Contains, entity.RequestStatusLanding, batch.ID, map[string]string{"batch_id": batch.ID}, ); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish request log for batch %s: %w", batch.ID, err) } if err := c.publish(ctx, c.runwayTopicKey, req, batch.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish to runway merge: %w", err) } diff --git a/submitqueue/orchestrator/controller/landconflictsignal/landconflictsignal.go b/submitqueue/orchestrator/controller/landconflictsignal/landconflictsignal.go index 5a2b59e68..97ff06fe0 100644 --- a/submitqueue/orchestrator/controller/landconflictsignal/landconflictsignal.go +++ b/submitqueue/orchestrator/controller/landconflictsignal/landconflictsignal.go @@ -87,7 +87,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // id is the request id echoed back, so correlate straight to the request. result := &runwaymq.MergeResult{} if err := runwaymq.Unmarshal(msg.Payload, result); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize land conflict check result: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, result.GetQueueName()); err != nil { @@ -96,14 +96,14 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: result.GetQueueName()}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", result.GetQueueName(), err) } request, err := store.GetRequestStore().Get(ctx, result.Id) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get request %s: %w", result.Id, err) } @@ -116,7 +116,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // Short-circuit halted requests: the cancel path owns driving them terminal. if entity.IsRequestStateHalted(request.State) { - metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_halted", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("skipping landconflict signal for halted request", "request_id", request.ID, "state", string(request.State), @@ -125,13 +125,13 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er } if result.Outcome != runwaypb.Outcome_SUCCEEDED { - metrics.NamedCounter(c.metricsScope, opName, "not_landable", 1) + metrics.NamedCounter(c.metricsScope, opName, "not_landable", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("request not landable", "request_id", request.ID, "reason", result.Reason, ) if err := c.failRequest(ctx, store, request, result.Reason); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "fail_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "fail_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to fail request %s: %w", request.ID, err) } return nil @@ -141,19 +141,19 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er newVersion := request.Version + 1 request.State = entity.RequestStateValidated if err := store.GetRequestStore().Update(ctx, request, request.Version, newVersion); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "state_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "state_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to update request %s state to validated: %w", request.ID, err) } request.Version = newVersion logEntry := entity.NewRequestStatusLog(request.Queue, request.ID, entity.RequestStatusValidated, request.Version, "", nil) if err := corerequest.PublishLog(ctx, c.registry, logEntry, request.ID, ""); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "log_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "log_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish request log for %s: %w", request.ID, err) } if err := c.publishRequestID(ctx, topickey.TopicKeyBatch, request.ID, request.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish to batch: %w", err) } diff --git a/submitqueue/orchestrator/controller/landsignal/landsignal.go b/submitqueue/orchestrator/controller/landsignal/landsignal.go index 1178da3d7..0b2970ede 100644 --- a/submitqueue/orchestrator/controller/landsignal/landsignal.go +++ b/submitqueue/orchestrator/controller/landsignal/landsignal.go @@ -89,7 +89,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // id is the batch id echoed back, so correlate straight to the batch. result := &runwaymq.MergeResult{} if err := runwaymq.Unmarshal(msg.Payload, result); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize land result: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, result.GetQueueName()); err != nil { @@ -98,14 +98,14 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: result.GetQueueName()}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", result.GetQueueName(), err) } batch, err := store.GetBatchStore().Get(ctx, result.Id) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get batch %s: %w", result.Id, err) } @@ -123,7 +123,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // not transition (a racing terminal land result must not override the // cancel) and do not fan out. if batch.State == entity.BatchStateCancelling { - metrics.NamedCounter(c.metricsScope, opName, "skipped_cancelling", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_cancelling", 1, metrics.TagsFromContext(ctx)...) return nil } @@ -144,9 +144,9 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // CAS'd without completing the record move), re-fan-out in case that // attempt missed the downstream publishes, then ack. if batch.State.IsTerminal() { - metrics.NamedCounter(c.metricsScope, opName, "skipped_terminal", 1) + metrics.NamedCounter(c.metricsScope, opName, "skipped_terminal", 1, metrics.TagsFromContext(ctx)...) if err := corebatch.EnsureRecord(ctx, store, batch); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "state_update_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "state_update_errors", 1, metrics.TagsFromContext(ctx)...) return err } return c.fanout(ctx, batch.ID, batch.Queue, failureReason) @@ -160,7 +160,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er "steps", result.Steps, ) } else { - metrics.NamedCounter(c.metricsScope, opName, "not_landed", 1) + metrics.NamedCounter(c.metricsScope, opName, "not_landed", 1, metrics.TagsFromContext(ctx)...) newState = entity.BatchStateFailed c.logger.Warnw("batch land failed", "batch_id", batch.ID, @@ -170,7 +170,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er batch, err = corebatch.Transition(ctx, store, batch, newState) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "state_update_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "state_update_errors", 1, metrics.TagsFromContext(ctx)...) return err } @@ -193,11 +193,11 @@ func (c *Controller) fanout(ctx context.Context, batchID, queue, failureReason s concludeMeta = map[string]string{topickey.MetadataKeyFailureReason: failureReason} } if err := c.publish(ctx, topickey.TopicKeyConclude, publish.IntentID(batchID, "conclude", "landed"), batchID, queue, concludeMeta); err != nil { - metrics.NamedCounter(c.metricsScope, "process", "publish_conclude_errors", 1) + metrics.NamedCounter(c.metricsScope, "process", "publish_conclude_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish to conclude: %w", err) } if err := c.publish(ctx, topickey.TopicKeySpeculate, publish.IntentID(batchID, "landed"), batchID, queue, nil); err != nil { - metrics.NamedCounter(c.metricsScope, "process", "publish_speculate_errors", 1) + metrics.NamedCounter(c.metricsScope, "process", "publish_speculate_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish to speculate: %w", err) } return nil diff --git a/submitqueue/orchestrator/controller/ping.go b/submitqueue/orchestrator/controller/ping.go index c788211a2..66afa9459 100644 --- a/submitqueue/orchestrator/controller/ping.go +++ b/submitqueue/orchestrator/controller/ping.go @@ -51,7 +51,7 @@ func (c *PingController) Ping(ctx context.Context, req *pb.PingRequest) (resp *p if req.Message != "" { message = "echo: " + req.Message isEcho = true - metrics.NamedCounter(c.metricsScope, opName, "echo_requests", 1) + metrics.NamedCounter(c.metricsScope, opName, "echo_requests", 1, metrics.TagsFromContext(ctx)...) } hostname, _ := os.Hostname() diff --git a/submitqueue/orchestrator/controller/speculate/BUILD.bazel b/submitqueue/orchestrator/controller/speculate/BUILD.bazel index fce55d080..a2e877077 100644 --- a/submitqueue/orchestrator/controller/speculate/BUILD.bazel +++ b/submitqueue/orchestrator/controller/speculate/BUILD.bazel @@ -46,10 +46,12 @@ go_test( ], embed = [":go_default_library"], deps = [ + "//platform/base/failure:go_default_library", "//platform/base/messagequeue:go_default_library", "//platform/consumer:go_default_library", "//platform/consumer/mock:go_default_library", "//platform/extension/messagequeue/mock:go_default_library", + "//platform/metrics:go_default_library", "//submitqueue/core/messagequeue:go_default_library", "//submitqueue/core/topickey:go_default_library", "//submitqueue/entity:go_default_library", diff --git a/submitqueue/orchestrator/controller/speculate/dispatch.go b/submitqueue/orchestrator/controller/speculate/dispatch.go index c7ce00f36..5328bc9a8 100644 --- a/submitqueue/orchestrator/controller/speculate/dispatch.go +++ b/submitqueue/orchestrator/controller/speculate/dispatch.go @@ -82,7 +82,7 @@ func (c *Controller) dispatch(ctx context.Context, queue string, snap snapshot, // against a snapshot that is now stale anyway; any later // signal on the queue re-plans this head from stored // state. - metrics.NamedCounter(c.metricsScope, opName, "path_set_cas_lost", 1) + metrics.NamedCounter(c.metricsScope, opName, "path_set_cas_lost", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("lost a path set write; the next run re-plans this head", "batch_id", batch.ID, "queue", queue, @@ -91,7 +91,7 @@ func (c *Controller) dispatch(ctx context.Context, queue string, snap snapshot, } // The loop covers every in-flight batch, so the head whose // write failed is usually not the one named on the message. - return c.attributed(err, entity.BatchSubject(batch.ID)) + return c.attributed(ctx, err, entity.BatchSubject(batch.ID)) } } @@ -108,8 +108,8 @@ func (c *Controller) dispatch(ctx context.Context, queue string, snap snapshot, // that went missing. if hasActionablePaths(set) { if err := c.publishBatchID(ctx, topickey.TopicKeyBuild, publish.UniqueID(batch.ID), batch.ID, queue, batch.ID); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) - return c.attributed(fmt.Errorf("failed to publish batch %s to build: %w", batch.ID, err), + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) + return c.attributed(ctx, fmt.Errorf("failed to publish batch %s to build: %w", batch.ID, err), entity.BatchSubject(batch.ID)) } } @@ -132,7 +132,7 @@ func (c *Controller) persist(ctx context.Context, store orchstorage.Storage, set // Treat it as a lost race: the next run reads the winner. return set, storage.ErrVersionMismatch } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return set, fmt.Errorf("failed to create path set for batch %s: %w", set.Head, err) } return set, nil @@ -143,7 +143,7 @@ func (c *Controller) persist(ctx context.Context, store orchstorage.Storage, set if errors.Is(err, storage.ErrVersionMismatch) { return set, err } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return set, fmt.Errorf("failed to update path set for batch %s: %w", set.Head, err) } set.Version = newVersion diff --git a/submitqueue/orchestrator/controller/speculate/finalize.go b/submitqueue/orchestrator/controller/speculate/finalize.go index 420acd7f3..331bde6d6 100644 --- a/submitqueue/orchestrator/controller/speculate/finalize.go +++ b/submitqueue/orchestrator/controller/speculate/finalize.go @@ -122,7 +122,7 @@ func (c *Controller) finalize(ctx context.Context, snap *snapshot) error { continue } if bypassed { - metrics.NamedCounter(c.metricsScope, opName, "bypass", 1) + metrics.NamedCounter(c.metricsScope, opName, "bypass", 1, metrics.TagsFromContext(ctx)...) } c.recordOutcome(snap, batch.ID, decision) decided++ @@ -177,11 +177,11 @@ func (c *Controller) reportSpeculation( "path_id": path.ID, }, ); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1, metrics.TagsFromContext(ctx)...) // Attributed to this head, not the trigger: the loop walks the whole // queue, so the batch whose members could not be told is usually not the // one the message named. - return c.attributed(fmt.Errorf("failed to publish request events for batch %s: %w", batch.ID, err), + return c.attributed(ctx, fmt.Errorf("failed to publish request events for batch %s: %w", batch.ID, err), entity.BatchSubject(batch.ID)) } return nil @@ -207,7 +207,7 @@ func (c *Controller) finalizeCancellations(ctx context.Context, snap *snapshot, if batch.State != entity.BatchStateCancelling { continue } - metrics.NamedCounter(c.metricsScope, opName, "cancel_batch", 1) + metrics.NamedCounter(c.metricsScope, opName, "cancel_batch", 1, metrics.TagsFromContext(ctx)...) set, exists := snap.pathSets[batch.ID] if exists && cancelAllPaths(&set, nowMs) { @@ -219,7 +219,7 @@ func (c *Controller) finalizeCancellations(ctx context.Context, snap *snapshot, // wait for. Statuses here already reflect what the build stages saw — // read folded that in — so a path still reading as unstopped really is. if exists && !allPathsStopped(set) { - metrics.NamedCounter(c.metricsScope, opName, "cancel_awaiting_paths", 1) + metrics.NamedCounter(c.metricsScope, opName, "cancel_awaiting_paths", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("cancelling batch; waiting for its builds to stop", "batch_id", batch.ID, "queue", batch.Queue, @@ -253,7 +253,7 @@ func (c *Controller) commitOutcome(ctx context.Context, snap *snapshot, batch en stored, err := c.persist(ctx, snap.store, set, exists) if err != nil { if errors.Is(err, storage.ErrVersionMismatch) { - metrics.NamedCounter(c.metricsScope, opName, "path_set_cas_lost", 1) + metrics.NamedCounter(c.metricsScope, opName, "path_set_cas_lost", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("lost a path set write; the next run re-plans this head", "batch_id", batch.ID, "queue", batch.Queue, @@ -262,7 +262,7 @@ func (c *Controller) commitOutcome(ctx context.Context, snap *snapshot, batch en snap.markClean(batch.ID) return false, nil } - return false, c.attributed(err, entity.BatchSubject(batch.ID)) + return false, c.attributed(ctx, err, entity.BatchSubject(batch.ID)) } snap.pathSets[batch.ID] = stored snap.markClean(batch.ID) @@ -273,7 +273,13 @@ func (c *Controller) commitOutcome(ctx context.Context, snap *snapshot, batch en // over every decided batch in the queue — rarely the one on the message. landed, err := c.applyOutcome(ctx, snap.store, batch, decision, snap.isTrigger(batch.ID)) if err != nil { - return landed, c.attributed(err, entity.BatchSubject(batch.ID)) + return landed, c.attributed(ctx, err, entity.BatchSubject(batch.ID)) + } + if landed { + // Named under batch_shape rather than opName so wildcards over the controller's process.* counters never + // match the histogram's bucket series. + metrics.NamedHistogram(c.metricsScope, "batch_shape", "paths", metrics.CountBuckets, metrics.TagsFromContext(ctx)...). + RecordValue(float64(len(snap.pathSets[batch.ID].Paths))) } return landed, nil } @@ -332,14 +338,14 @@ func (c *Controller) applyOutcome(ctx context.Context, store orchstorage.Storage // queue would go on listing and hydrating it. if _, err := corebatch.Transition(ctx, store, batch, state); err != nil { if errors.Is(err, storage.ErrVersionMismatch) { - metrics.NamedCounter(c.metricsScope, opName, "outcome_cas_lost", 1) + metrics.NamedCounter(c.metricsScope, opName, "outcome_cas_lost", 1, metrics.TagsFromContext(ctx)...) return false, nil } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return false, err } - metrics.NamedCounter(c.metricsScope, opName, "outcome", 1, metrics.NewTag("outcome", string(decision))) + metrics.NamedCounter(c.metricsScope, opName, "outcome", 1, metrics.TagsFromContext(ctx, metrics.NewTag("outcome", string(decision)))...) c.logger.Infow("batch outcome", "batch_id", batch.ID, "queue", batch.Queue, @@ -367,7 +373,7 @@ func (c *Controller) applyOutcome(ctx context.Context, store orchstorage.Storage // A conclude that goes missing is recovered by fanout, which is // deliberately un-deduplicated. if err := c.publishBatchIDWithMetadata(ctx, topickey.TopicKeyConclude, publish.IntentID(batch.ID, "conclude", "speculate"), batch.ID, batch.Queue, batch.Queue, concludeMeta); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return true, fmt.Errorf("failed to publish batch %s to conclude: %w", batch.ID, err) } } @@ -382,12 +388,12 @@ func (c *Controller) dispatchLand(ctx context.Context, batch entity.Batch) error if err := corerequest.PublishBatchLogs(ctx, c.registry, batch.Queue, batch.Contains, entity.RequestStatusSpeculated, batch.ID, map[string]string{"batch_id": batch.ID}, ); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish request logs for batch %s: %w", batch.ID, err) } if err := c.publishBatchID(ctx, topickey.TopicKeyLand, publish.IntentID(batch.ID, "land-dispatch"), batch.ID, batch.Queue, batch.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish batch %s to land: %w", batch.ID, err) } return nil @@ -416,10 +422,10 @@ func (c *Controller) dispatchLand(ctx context.Context, batch entity.Batch) error // a nudge that re-plans a queue nothing has changed. func (c *Controller) recoverable(ctx context.Context, store orchstorage.Storage, batch entity.Batch) error { if err := c.publishBatchID(ctx, topickey.TopicKeySpeculate, publish.UniqueID(batch.ID), batch.ID, batch.Queue, batch.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish recovery signal for batch %s: %w", batch.ID, err) } - metrics.NamedCounter(c.metricsScope, opName, "recovery_signal_published", 1) + metrics.NamedCounter(c.metricsScope, opName, "recovery_signal_published", 1, metrics.TagsFromContext(ctx)...) return nil } diff --git a/submitqueue/orchestrator/controller/speculate/run.go b/submitqueue/orchestrator/controller/speculate/run.go index c1e4ee99e..61774b11a 100644 --- a/submitqueue/orchestrator/controller/speculate/run.go +++ b/submitqueue/orchestrator/controller/speculate/run.go @@ -63,7 +63,7 @@ func (c *Controller) run(ctx context.Context, store orchstorage.Storage, trigger kept, rejected := filterProposals(proposals, snap) for _, reason := range rejected { metrics.NamedCounter(c.metricsScope, opName, "speculation_rejected", 1, - metrics.NewTag("reason", string(reason))) + metrics.TagsFromContext(ctx, metrics.NewTag("reason", string(reason)))...) c.logger.Warnw("dropped a speculator proposal", "queue", trigger.Queue, "reason", string(reason), @@ -96,7 +96,7 @@ func (c *Controller) admitCreated(ctx context.Context, snap *snapshot) { updated, err := c.admit(ctx, snap.store, batch) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "unadmitted_repair_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "unadmitted_repair_errors", 1, metrics.TagsFromContext(ctx)...) c.logger.Warnw("failed to admit a batch found in created", "batch_id", batch.ID, "queue", batch.Queue, @@ -105,7 +105,7 @@ func (c *Controller) admitCreated(ctx context.Context, snap *snapshot) { continue } - metrics.NamedCounter(c.metricsScope, opName, "unadmitted_repaired", 1) + metrics.NamedCounter(c.metricsScope, opName, "unadmitted_repaired", 1, metrics.TagsFromContext(ctx)...) snap.batches[updated.ID] = updated snap.inFlight[i] = updated snap.speculating = append(snap.speculating, updated) @@ -118,8 +118,8 @@ func (c *Controller) admitCreated(ctx context.Context, snap *snapshot) { func (c *Controller) read(ctx context.Context, store orchstorage.Storage, queue string) (snapshot, error) { inFlight, err := corebatch.ListByStates(ctx, store, entity.ActiveBatchStates()) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) - return snapshot{}, c.attributed(fmt.Errorf("failed to list in-flight batches of queue %s: %w", queue, err), + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) + return snapshot{}, c.attributed(ctx, fmt.Errorf("failed to list in-flight batches of queue %s: %w", queue, err), entity.QueueSubject(queue)) } @@ -148,8 +148,8 @@ func (c *Controller) read(ctx context.Context, store orchstorage.Storage, queue } dep, err := store.GetBatchStore().Get(ctx, depID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) - return snapshot{}, c.attributed(fmt.Errorf("failed to get dependency batch %s of %s: %w", depID, batch.ID, err), + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) + return snapshot{}, c.attributed(ctx, fmt.Errorf("failed to get dependency batch %s of %s: %w", depID, batch.ID, err), entity.BatchSubject(depID)) } snap.batches[depID] = dep @@ -163,8 +163,8 @@ func (c *Controller) read(ctx context.Context, store orchstorage.Storage, queue // Nothing has been funded for this head yet. continue } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) - return snapshot{}, c.attributed(fmt.Errorf("failed to get path set for batch %s: %w", batch.ID, err), + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) + return snapshot{}, c.attributed(ctx, fmt.Errorf("failed to get path set for batch %s: %w", batch.ID, err), entity.BatchSubject(batch.ID)) } changed, err := c.updatePathsFromBuilds(ctx, store, &set) @@ -219,13 +219,13 @@ func (c *Controller) updatePathsFromBuilds(ctx context.Context, store orchstorag if entry.Status == entity.SpeculationPathStatusCancelling { entry.Status = entity.SpeculationPathStatusCancelled changed = true - metrics.NamedCounter(c.metricsScope, opName, "path_cancelled_undispatched", 1) + metrics.NamedCounter(c.metricsScope, opName, "path_cancelled_undispatched", 1, metrics.TagsFromContext(ctx)...) } continue } if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) - return false, c.attributed(fmt.Errorf("failed to look up build for path %s attempt %d: %w", entry.ID, entry.Attempt, err), + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) + return false, c.attributed(ctx, fmt.Errorf("failed to look up build for path %s attempt %d: %w", entry.ID, entry.Attempt, err), entity.BatchSubject(set.Head)) } @@ -238,8 +238,8 @@ func (c *Controller) updatePathsFromBuilds(ctx context.Context, store orchstorag // wedging a whole queue's run on one corrupt row. continue } - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) - return false, c.attributed(fmt.Errorf("failed to get build %s for path %s: %w", link.BuildID, entry.ID, err), + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) + return false, c.attributed(ctx, fmt.Errorf("failed to get build %s for path %s: %w", link.BuildID, entry.ID, err), entity.BatchSubject(set.Head)) } @@ -264,7 +264,7 @@ func (c *Controller) updatePathsFromBuilds(ctx context.Context, store orchstorag entry.Status = result changed = true metrics.NamedCounter(c.metricsScope, opName, "path_outcome_recorded", 1, - metrics.NewTag("status", string(result))) + metrics.TagsFromContext(ctx, metrics.NewTag("status", string(result)))...) } return changed, nil } @@ -306,8 +306,8 @@ func terminalPathStatus(status entity.BuildStatus) entity.SpeculationPathStatus func (c *Controller) ask(ctx context.Context, queue string, snap snapshot) ([]entity.Speculation, error) { spec, err := c.speculators.For(speculator.Config{QueueName: queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "speculator_errors", 1) - return nil, c.attributed(fmt.Errorf("failed to build speculator for queue %s: %w", queue, err), + metrics.NamedCounter(c.metricsScope, opName, "speculator_errors", 1, metrics.TagsFromContext(ctx)...) + return nil, c.attributed(ctx, fmt.Errorf("failed to build speculator for queue %s: %w", queue, err), entity.QueueSubject(queue)) } @@ -320,8 +320,8 @@ func (c *Controller) ask(ctx context.Context, queue string, snap snapshot) ([]en proposals, err := spec.Speculate(ctx, slices.Collect(maps.Values(snap.batches)), sets) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "speculator_errors", 1) - return nil, c.attributed(fmt.Errorf("speculator failed for queue %s: %w", queue, err), + metrics.NamedCounter(c.metricsScope, opName, "speculator_errors", 1, metrics.TagsFromContext(ctx)...) + return nil, c.attributed(ctx, fmt.Errorf("speculator failed for queue %s: %w", queue, err), entity.QueueSubject(queue)) } return proposals, nil diff --git a/submitqueue/orchestrator/controller/speculate/run_test.go b/submitqueue/orchestrator/controller/speculate/run_test.go index c40b172ce..009181751 100644 --- a/submitqueue/orchestrator/controller/speculate/run_test.go +++ b/submitqueue/orchestrator/controller/speculate/run_test.go @@ -1588,6 +1588,10 @@ func TestRun_BypassesUnsettledDependenciesWithFullCoverage(t *testing.T) { counter, ok := h.metrics.Snapshot().Counters()["test.speculate_controller.process.bypass+"] require.True(t, ok) assert.EqualValues(t, 1, counter.Value()) + + paths, ok := h.metrics.Snapshot().Histograms()["test.speculate_controller.batch_shape.paths+"] + require.True(t, ok, "a finalized head records how many paths it speculated") + assert.Equal(t, int64(1), paths.Values()[5]) } // The land stage publishes landing as its first act on the dispatch. Both diff --git a/submitqueue/orchestrator/controller/speculate/speculate.go b/submitqueue/orchestrator/controller/speculate/speculate.go index d8689ea3c..f6d42a452 100644 --- a/submitqueue/orchestrator/controller/speculate/speculate.go +++ b/submitqueue/orchestrator/controller/speculate/speculate.go @@ -98,7 +98,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er bid, err := sqmq.UnmarshalBatchID(c.topicKey, msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize batch ID: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, bid.Queue); err != nil { @@ -107,29 +107,29 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: bid.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. - return c.attributed(fmt.Errorf("failed to resolve storage for queue %q: %w", bid.Queue, err), + return c.attributed(ctx, fmt.Errorf("failed to resolve storage for queue %q: %w", bid.Queue, err), entity.QueueSubject(bid.Queue)) } batch, err := store.GetBatchStore().Get(ctx, bid.ID) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) - return c.attributed(fmt.Errorf("failed to get batch %s: %w", bid.ID, err), + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) + return c.attributed(ctx, fmt.Errorf("failed to get batch %s: %w", bid.ID, err), entity.BatchSubject(bid.ID)) } // The payload's queue must match the batch's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if bid.Queue != "" && bid.Queue != batch.Queue { - metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1) - return c.attributed(fmt.Errorf("payload queue %q does not match queue %q of batch %s", bid.Queue, batch.Queue, batch.ID), + metrics.NamedCounter(c.metricsScope, opName, "queue_mismatch", 1, metrics.TagsFromContext(ctx)...) + return c.attributed(ctx, fmt.Errorf("payload queue %q does not match queue %q of batch %s", bid.Queue, batch.Queue, batch.ID), entity.BatchSubject(batch.ID)) } if batch.State.IsTerminal() { - metrics.NamedCounter(c.metricsScope, opName, "self_heal_terminal", 1) + metrics.NamedCounter(c.metricsScope, opName, "self_heal_terminal", 1, metrics.TagsFromContext(ctx)...) if err := c.fanout(ctx, batch.ID, batch.Queue); err != nil { return err } @@ -145,9 +145,9 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // A Landing batch has left the set finalize walks, so a message naming it // is the only thing that will look at it again. if batch.State == entity.BatchStateLanding { - metrics.NamedCounter(c.metricsScope, opName, "self_heal_landing", 1) + metrics.NamedCounter(c.metricsScope, opName, "self_heal_landing", 1, metrics.TagsFromContext(ctx)...) if err := c.dispatchLand(ctx, batch); err != nil { - return c.attributed(err, entity.BatchSubject(batch.ID)) + return c.attributed(ctx, err, entity.BatchSubject(batch.ID)) } } @@ -171,8 +171,8 @@ func (c *Controller) admit(ctx context.Context, store orchstorage.Storage, batch if err := corerequest.PublishBatchLogs(ctx, c.registry, batch.Queue, batch.Contains, entity.RequestStatusSpeculating, batch.ID, map[string]string{"batch_id": batch.ID}, ); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1) - return batch, c.attributed(fmt.Errorf("failed to publish request logs for batch %s: %w", batch.ID, err), + metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1, metrics.TagsFromContext(ctx)...) + return batch, c.attributed(ctx, fmt.Errorf("failed to publish request logs for batch %s: %w", batch.ID, err), entity.BatchSubject(batch.ID)) } @@ -180,11 +180,11 @@ func (c *Controller) admit(ctx context.Context, store orchstorage.Storage, batch // record has to leave the created bucket with the batch. updated, err := corebatch.Transition(ctx, store, batch, entity.BatchStateSpeculating) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) - return batch, c.attributed(err, entity.BatchSubject(batch.ID)) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) + return batch, c.attributed(ctx, err, entity.BatchSubject(batch.ID)) } - metrics.NamedCounter(c.metricsScope, opName, "admitted", 1) + metrics.NamedCounter(c.metricsScope, opName, "admitted", 1, metrics.TagsFromContext(ctx)...) c.logger.Infow("admitted batch to speculation", "batch_id", updated.ID, "queue", updated.Queue, @@ -202,8 +202,8 @@ func (c *Controller) admit(ctx context.Context, store orchstorage.Storage, batch // is exactly what a stable ID would dedup against. func (c *Controller) fanout(ctx context.Context, batchID, queue string) error { if err := c.publishBatchID(ctx, topickey.TopicKeyConclude, publish.UniqueID(batchID), batchID, queue, queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) - return c.attributed(fmt.Errorf("failed to publish to conclude: %w", err), + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) + return c.attributed(ctx, fmt.Errorf("failed to publish to conclude: %w", err), entity.BatchSubject(batchID)) } return nil @@ -260,10 +260,10 @@ func (c *Controller) publishBatchIDWithMetadata(ctx context.Context, key consume // // Only the attribution is added. Whether the error is retryable stays with the // classifiers, which read the cause underneath this wrapper unchanged. -func (c *Controller) attributed(err error, subjects ...failure.Subject) error { +func (c *Controller) attributed(ctx context.Context, err error, subjects ...failure.Subject) error { for _, s := range subjects { metrics.NamedCounter(c.metricsScope, opName, "attributed_failure", 1, - metrics.NewTag("subject_type", s.Type)) + metrics.TagsFromContext(ctx, metrics.NewTag("subject_type", s.Type))...) } return errs.Attribute(err, subjects...) } diff --git a/submitqueue/orchestrator/controller/speculate/speculate_test.go b/submitqueue/orchestrator/controller/speculate/speculate_test.go index f826d2d9a..b0d88f170 100644 --- a/submitqueue/orchestrator/controller/speculate/speculate_test.go +++ b/submitqueue/orchestrator/controller/speculate/speculate_test.go @@ -24,10 +24,12 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/uber-go/tally" + "github.com/uber/submitqueue/platform/base/failure" entityqueue "github.com/uber/submitqueue/platform/base/messagequeue" "github.com/uber/submitqueue/platform/consumer" consumermock "github.com/uber/submitqueue/platform/consumer/mock" queuemock "github.com/uber/submitqueue/platform/extension/messagequeue/mock" + "github.com/uber/submitqueue/platform/metrics" sqmq "github.com/uber/submitqueue/submitqueue/core/messagequeue" "github.com/uber/submitqueue/submitqueue/core/topickey" "github.com/uber/submitqueue/submitqueue/entity" @@ -340,3 +342,36 @@ func TestProcess_Errors(t *testing.T) { require.Error(t, h.process(t, ctrl, batch.ID)) }) } + +func TestAttributed_CountsFailureWithContextQueueTag(t *testing.T) { + tests := []struct { + name string + ctx context.Context + counterKey string + }{ + { + name: "context carries the queue", + ctx: metrics.WithContextTags(context.Background(), metrics.NewTag("queue", "q")), + counterKey: "test.speculate_controller.process.attributed_failure+queue=q,subject_type=batch", + }, + { + name: "context carries no tags", + ctx: context.Background(), + counterKey: "test.speculate_controller.process.attributed_failure+subject_type=batch", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + scope := tally.NewTestScope("test", nil) + c := &Controller{metricsScope: scope.SubScope("speculate_controller")} + + err := c.attributed(tt.ctx, fmt.Errorf("boom"), failure.Subject{Type: "batch", ID: "b1"}) + + require.Error(t, err) + counter, ok := scope.Snapshot().Counters()[tt.counterKey] + require.True(t, ok, "counters: %v", scope.Snapshot().Counters()) + assert.EqualValues(t, 1, counter.Value()) + }) + } +} diff --git a/submitqueue/orchestrator/controller/start/start.go b/submitqueue/orchestrator/controller/start/start.go index 3a17867f7..85c415bf9 100644 --- a/submitqueue/orchestrator/controller/start/start.go +++ b/submitqueue/orchestrator/controller/start/start.go @@ -80,7 +80,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er landRequest, err := sqmq.UnmarshalLandRequest(msg.Payload) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "deserialize_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: malformed messages will never succeed regardless of retry count return fmt.Errorf("failed to deserialize land request: %w", err) } @@ -90,7 +90,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: landRequest.Queue}) if err != nil { - metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_resolve_errors", 1, metrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", landRequest.Queue, err) } @@ -119,19 +119,19 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // Persist request to storage. ErrAlreadyExists means a queue redelivery of the same // request_id (an at-least-once retry of THIS message), not a cross-request collision. if err := store.GetRequestStore().Create(ctx, request); err != nil && !errors.Is(err, storage.ErrAlreadyExists) { - metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "storage_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to create request: %w", err) } // Record the "new" status in the request log. logEntry := entity.NewRequestStatusLog(request.Queue, request.ID, entity.RequestStatusStarted, request.Version, "", nil) if err := corerequest.PublishLog(ctx, c.registry, logEntry, request.ID, ""); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "request_log_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish request log: %w", err) } if err := c.publish(ctx, topickey.TopicKeyValidate, request.ID, request.Queue); err != nil { - metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1) + metrics.NamedCounter(c.metricsScope, opName, "publish_errors", 1, metrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish to validate: %w", err) } diff --git a/submitqueue/orchestrator/controller/validate/validate.go b/submitqueue/orchestrator/controller/validate/validate.go index ae62fe39a..99d1ea363 100644 --- a/submitqueue/orchestrator/controller/validate/validate.go +++ b/submitqueue/orchestrator/controller/validate/validate.go @@ -96,7 +96,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er rid, err := sqmq.UnmarshalRequestID(c.topicKey, msg.Payload) if err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "deserialize_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "deserialize_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to deserialize request ID: %w", err) } if err := entityqueue.ValidatePayloadQueue(msg, rid.Queue); err != nil { @@ -105,7 +105,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er store, err := c.stores.For(orchstorage.Config{QueueName: rid.Queue}) if err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "storage_resolve_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "storage_resolve_errors", 1, coremetrics.TagsFromContext(ctx)...) // Non-retryable: a missing or unresolvable queue is a malformed message. return fmt.Errorf("failed to resolve storage for queue %q: %w", rid.Queue, err) } @@ -113,14 +113,14 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // Fetch request from storage request, err := store.GetRequestStore().Get(ctx, rid.ID) if err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "storage_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "storage_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to get request %s: %w", rid.ID, err) } // The payload's queue must match the request's authoritative queue; a // mismatch is a malformed message. Non-retryable — reject to the DLQ. if rid.Queue != "" && rid.Queue != request.Queue { - coremetrics.NamedCounter(c.metricsScope, "process", "queue_mismatch", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "queue_mismatch", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("payload queue %q does not match queue %q of request %s", rid.Queue, request.Queue, request.ID) } @@ -138,7 +138,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // (RequestStateCancelling). Without this guard we would still publish to batch // and spawn a batch for a request that should never proceed. if entity.IsRequestStateHalted(request.State) { - coremetrics.NamedCounter(c.metricsScope, "process", "skipped_halted", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "skipped_halted", 1, coremetrics.TagsFromContext(ctx)...) c.logger.Infow("skipping validate for halted request", "request_id", request.ID, "state", string(request.State), @@ -152,7 +152,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // request is validated once, and a redelivery is a retry of that one event. logEntry := entity.NewRequestStatusLog(request.Queue, request.ID, entity.RequestStatusValidating, 0, "", nil) if err := corerequest.PublishLog(ctx, c.registry, logEntry, request.ID, ""); err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "request_log_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "request_log_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish request log for %s: %w", request.ID, err) } @@ -168,19 +168,19 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er "queue", request.Queue, "duplicate_id", dupID, ) - coremetrics.NamedCounter(c.metricsScope, "process", "duplicate_requests", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "duplicate_requests", 1, coremetrics.TagsFromContext(ctx)...) return c.reject(ctx, store, request.ID, fmt.Sprintf("request %s is a duplicate of in-flight request %s", request.ID, dupID)) } // Fetch change metadata changeProvider, err := c.changeProviders.For(changeprovider.Config{QueueName: request.Queue}) if err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "change_provider_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "change_provider_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to build change provider for queue %s: %w", request.Queue, err) } changeInfos, err := changeProvider.Get(ctx, request) if err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "change_provider_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "change_provider_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to fetch change information for request %s: %w", request.ID, err) } @@ -197,7 +197,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er } v, err := c.validators.For(cfg) if err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "validator_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "validator_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to build validator for request %s: %w", request.ID, err) } if v != nil { @@ -206,10 +206,10 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // is left to the consumer's classifiers, so a transient one retries // instead of failing a request nothing was wrong with. if !errors.Is(err, validator.ErrRejected) { - coremetrics.NamedCounter(c.metricsScope, "process", "custom_validation_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "custom_validation_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to validate request %s: %w", request.ID, err) } - coremetrics.NamedCounter(c.metricsScope, "process", "custom_validation_failures", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "custom_validation_failures", 1, coremetrics.TagsFromContext(ctx)...) c.logger.Infow("custom validation rejected request", "request_id", request.ID, "queue", request.Queue, @@ -226,7 +226,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // details (immutable thereafter; no separate enrichment update). Create is // idempotent per (queue, uri, request_id), so redelivery is a no-op. if err := c.claimChanges(ctx, store, request, changeInfos); err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "change_store_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "change_store_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to claim change records for request %s: %w", request.ID, err) } @@ -247,7 +247,7 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er }, } if err := c.publishLandConflictCheck(ctx, req); err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "publish_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "publish_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to publish to runway merge-conflict-check: %w", err) } @@ -271,10 +271,10 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er // validation once rejected. func (c *Controller) reject(ctx context.Context, store orchstorage.Storage, requestID, reason string) error { if _, err := corerequest.TerminateRequest(ctx, store, c.registry, requestID, entity.RequestStateError, reason, nil); err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "terminate_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "terminate_errors", 1, coremetrics.TagsFromContext(ctx)...) return fmt.Errorf("failed to terminate rejected request %s: %w", requestID, err) } - coremetrics.NamedCounter(c.metricsScope, "process", "rejected_requests", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "rejected_requests", 1, coremetrics.TagsFromContext(ctx)...) return nil } @@ -293,7 +293,7 @@ func (c *Controller) checkDuplicate(ctx context.Context, store orchstorage.Stora for _, uri := range request.Change.URIs { records, err := store.GetChangeStore().GetByURI(ctx, uri) if err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "change_store_query_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "change_store_query_errors", 1, coremetrics.TagsFromContext(ctx)...) return "", fmt.Errorf("failed to query change store for request %s uri=%s: %w", request.ID, uri, err) } for _, rec := range records { @@ -310,7 +310,7 @@ func (c *Controller) checkDuplicate(ctx context.Context, store orchstorage.Stora continue } if err != nil { - coremetrics.NamedCounter(c.metricsScope, "process", "storage_errors", 1) + coremetrics.NamedCounter(c.metricsScope, "process", "storage_errors", 1, coremetrics.TagsFromContext(ctx)...) return "", fmt.Errorf("failed to look up overlapping request %s: %w", rec.RequestID, err) } if !entity.IsRequestStateTerminal(owner.State) { diff --git a/submitqueue/orchestrator/extension/storage/mysql/batch_dependent_store.go b/submitqueue/orchestrator/extension/storage/mysql/batch_dependent_store.go index b6463479d..72db79697 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/batch_dependent_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/batch_dependent_store.go @@ -45,7 +45,7 @@ func NewBatchDependentStore(db *sql.DB, scope tally.Scope, queue string) storage // Get retrieves the batch dependent by batch ID. Returns ErrNotFound if the batch dependent is not found. func (s *batchDependentStore) Get(ctx context.Context, batchID string) (ret entity.BatchDependent, retErr error) { op := metrics.Begin(s.scope, "get", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() var bd entity.BatchDependent var dependentsJSON []byte diff --git a/submitqueue/orchestrator/extension/storage/mysql/batch_store.go b/submitqueue/orchestrator/extension/storage/mysql/batch_store.go index 2ac21a71c..34ed9f082 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/batch_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/batch_store.go @@ -45,7 +45,7 @@ func NewBatchStore(db *sql.DB, scope tally.Scope, queue string) storage.BatchSto // Get retrieves a batch by ID. Returns ErrNotFound if the batch is not found. func (s *batchStore) Get(ctx context.Context, id string) (ret entity.Batch, retErr error) { op := metrics.Begin(s.scope, "get", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() var batch entity.Batch var containsJSON []byte diff --git a/submitqueue/orchestrator/extension/storage/mysql/build_store.go b/submitqueue/orchestrator/extension/storage/mysql/build_store.go index 2c5e30b2a..574231ccd 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/build_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/build_store.go @@ -44,7 +44,7 @@ func NewBuildStore(db *sql.DB, scope tally.Scope, queue string) storage.BuildSto // Get retrieves a build by ID. Returns ErrNotFound if the build is not found. func (s *buildStore) Get(ctx context.Context, id string) (ret entity.Build, retErr error) { op := metrics.Begin(s.scope, "get", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() var build entity.Build diff --git a/submitqueue/orchestrator/extension/storage/mysql/build_store_test.go b/submitqueue/orchestrator/extension/storage/mysql/build_store_test.go index dee62ec0e..684cd0127 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/build_store_test.go +++ b/submitqueue/orchestrator/extension/storage/mysql/build_store_test.go @@ -24,6 +24,7 @@ import ( "github.com/go-sql-driver/mysql" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "github.com/uber-go/tally" "github.com/uber/submitqueue/submitqueue/entity" "github.com/uber/submitqueue/submitqueue/extension/storage" @@ -250,3 +251,54 @@ func TestBuildStore_Update(t *testing.T) { }) } } + +// TestBuildStore_NotFoundMetrics covers how a missing row is counted: a read that +// finds nothing has answered and is recorded as not_found, while a write whose row +// is missing is an anomaly and stays an error. +func TestBuildStore_NotFoundMetrics(t *testing.T) { + tests := []struct { + name string + setup func(mock sqlmock.Sqlmock) + call func(store storage.BuildStore) error + metric string + }{ + { + name: "read of a missing build", + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectQuery("SELECT id, batch_id, path_id, attempt, status FROM build"). + WillReturnError(sql.ErrNoRows) + }, + call: func(store storage.BuildStore) error { + _, err := store.Get(context.Background(), "build-1") + return err + }, + metric: "get.finish+result=not_found", + }, + { + name: "write to a missing build", + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectExec("UPDATE build SET").WillReturnResult(sqlmock.NewResult(0, 0)) + }, + call: func(store storage.BuildStore) error { + return store.Update(context.Background(), entity.Build{ID: "build-1"}) + }, + metric: "update_status.finish+result=error", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + db, mock, err := sqlmock.New() + require.NoError(t, err) + defer db.Close() + scope := tally.NewTestScope("", nil) + store := NewBuildStore(db, scope, "monorepo") + tt.setup(mock) + + require.ErrorIs(t, tt.call(store), storage.ErrNotFound) + + assert.Contains(t, scope.Snapshot().Histograms(), tt.metric) + require.NoError(t, mock.ExpectationsWereMet()) + }) + } +} diff --git a/submitqueue/orchestrator/extension/storage/mysql/change_store.go b/submitqueue/orchestrator/extension/storage/mysql/change_store.go index 72921e354..7f6fcecb7 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/change_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/change_store.go @@ -70,7 +70,7 @@ func (s *changeStore) Create(ctx context.Context, record entity.ChangeRecord) (r // PK-prefix scan. func (s *changeStore) GetByURI(ctx context.Context, uri string) (ret []entity.ChangeRecord, retErr error) { op := metrics.Begin(s.scope, "get_by_uri", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() queue := s.queue const query = "SELECT uri, request_id, queue, details, created_at, updated_at, version FROM `change` WHERE queue = ? AND uri = ?" diff --git a/submitqueue/orchestrator/extension/storage/mysql/path_build_store.go b/submitqueue/orchestrator/extension/storage/mysql/path_build_store.go index bbf4afdfa..beccc3534 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/path_build_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/path_build_store.go @@ -45,7 +45,7 @@ func NewPathBuildStore(db *sql.DB, scope tally.Scope, queue string) storage.Path // been recorded for it. func (s *pathBuildStore) Get(ctx context.Context, pathID string, attempt int) (ret entity.PathBuild, retErr error) { op := metrics.Begin(s.scope, "get", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() var pathBuild entity.PathBuild diff --git a/submitqueue/orchestrator/extension/storage/mysql/queue_batch_state_store.go b/submitqueue/orchestrator/extension/storage/mysql/queue_batch_state_store.go index 11302a1f1..b6ee7fe59 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/queue_batch_state_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/queue_batch_state_store.go @@ -44,7 +44,7 @@ func NewQueueBatchStateStore(db *sql.DB, scope tally.Scope, queue string) storag // PK-prefix scan. func (s *queueBatchStateStore) List(ctx context.Context, state entity.BatchState) (ret []entity.QueueBatchState, retErr error) { op := metrics.Begin(s.scope, "list", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() queue := s.queue const query = "SELECT queue, state, batch_id FROM queue_batch_state WHERE queue = ? AND state = ?" diff --git a/submitqueue/orchestrator/extension/storage/mysql/request_batch_store.go b/submitqueue/orchestrator/extension/storage/mysql/request_batch_store.go index e96a0b109..7a6a6c4d3 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/request_batch_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/request_batch_store.go @@ -43,7 +43,7 @@ func NewRequestBatchStore(db *sql.DB, scope tally.Scope, queue string) storage.R func (s *requestBatchStore) GetByRequestID(ctx context.Context, requestID string) (ret []entity.RequestBatch, retErr error) { op := metrics.Begin(s.scope, "get_by_request_id", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() rows, err := s.db.QueryContext(ctx, "SELECT request_id, batch_id, version FROM request_batch WHERE queue = ? AND request_id = ? ORDER BY batch_id", diff --git a/submitqueue/orchestrator/extension/storage/mysql/request_store.go b/submitqueue/orchestrator/extension/storage/mysql/request_store.go index 8671de95c..2de1ea5aa 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/request_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/request_store.go @@ -45,7 +45,7 @@ func NewRequestStore(db *sql.DB, scope tally.Scope, queue string) storage.Reques // Get retrieves a land request by ID. Returns ErrNotFound if the request is not found. func (r *requestStore) Get(ctx context.Context, id string) (ret entity.Request, retErr error) { op := metrics.Begin(r.scope, "get", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() var req entity.Request var changeURIsJSON []byte diff --git a/submitqueue/orchestrator/extension/storage/mysql/speculation_path_set_store.go b/submitqueue/orchestrator/extension/storage/mysql/speculation_path_set_store.go index 6a74733dc..0ca976b91 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/speculation_path_set_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/speculation_path_set_store.go @@ -46,7 +46,7 @@ func NewSpeculationPathSetStore(db *sql.DB, scope tally.Scope, queue string) sto // Returns ErrNotFound if the head has no set. func (s *speculationPathSetStore) Get(ctx context.Context, head string) (ret entity.SpeculationPathSet, retErr error) { op := metrics.Begin(s.scope, "get", metrics.StorageLatencyBuckets) - defer func() { op.Complete(retErr) }() + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() var set entity.SpeculationPathSet var pathsJSON []byte