diff --git a/AGENTS.md b/AGENTS.md index 54d1c70ec..c2f7e4bbc 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -143,7 +143,7 @@ Vendor-agnostic, pluggable interfaces with implementations in subdirectories: 3. **Service-scoped resolution** — when only one service of a multi-service domain resolves an extension, its `Factory`, its aggregate, its implementations, its mocks and its schema live at `{domain}/{service}/extension/{ext}/`. The behavioural contracts stay at `{domain}/extension/{ext}/`. 4. Factory interface for dependency injection and lifecycle management (constructed in wiring, not inside `platform/extension` packages). -**Split on reachability, not on declaration.** What a service may resolve is decided by the accessors on its aggregate, so that is the part worth scoping to a service — a gateway holding a four-accessor `Storage` cannot obtain an orchestrator store whatever else it can name. The contracts stay shared because moving them adds no enforcement and costs every domain-level caller a dependency on a service package. `submitqueue/extension/storage` is the worked example: thirteen store contracts, their mocks and the error vocabulary shared, while each service owns its own aggregate, MySQL implementation and schema. +**Split on reachability, not on declaration.** What a service may resolve is decided by the accessors on its aggregate, so that is the part worth scoping to a service — a gateway holding a four-accessor `Storage` cannot obtain an orchestrator store whatever else it can name. The contracts stay shared because moving them adds no enforcement and costs every domain-level caller a dependency on a service package. `submitqueue/extension/storage` is the worked example: fourteen store contracts, their mocks and the error vocabulary shared, while each service owns its own aggregate, MySQL implementation and schema. **Extensions hold contracts and implementations only — not factories or routing.** diff --git a/doc/rfc/service-scoped-extensions.md b/doc/rfc/service-scoped-extensions.md index 555447091..b52698765 100644 --- a/doc/rfc/service-scoped-extensions.md +++ b/doc/rfc/service-scoped-extensions.md @@ -26,7 +26,7 @@ Separating the services onto their own databases already worked — the orchestr 2. An extension shared between a domain's services stays wholly at `{domain}/extension/{ext}/` — including one used by a single service today but expected in both. `submitqueue/extension/queueconfig/` is gateway-only now and stays where it is on that basis. A single-service domain is unaffected: its domain root is its service root, so nothing moves. 3. Storage is the extension this split applied to. `changeprovider`, `validator`, `conflict`, `buildrunner` and `speculation` are orchestrator-only and would qualify under Decision 1, but none has a schema and none was the reason for this change; they stay at `{domain}/extension/` until a later RFC takes them. The trigger for moving storage was a schema that a separate-database deployment must not over-provision. 4. SubmitQueue's storage aggregate splits in two: `submitqueue/gateway/extension/storage/` declares a `Factory` and a four-accessor `Storage`, `submitqueue/orchestrator/extension/storage/` a `Factory` and a nine-accessor `Storage`. Neither can resolve the other's stores. -5. `submitqueue/extension/storage/` keeps the thirteen store contracts, their mocks, the error vocabulary, `Config`, and the package README, which documents the contracts. Its import path does not change, so callers that name only a contract or an error are untouched. +5. `submitqueue/extension/storage/` keeps the fourteen store contracts, their mocks, the error vocabulary, `Config`, and the package README, which documents the contracts. Its import path does not change, so callers that name only a contract or an error are untouched. 6. The contract package is not promoted to `platform/`. It is not cross-domain — `stovepipe/extension/storage/storage.go` already declares its own verbatim copy of the same symbols, so a per-domain error vocabulary is the existing pattern rather than something this RFC introduces. 7. Each half owns its own MySQL schema directory, so the tables a service creates are the tables it reads. A union target over both stays available for deployments that colocate the services — the end-to-end tests and the local compose stack take it and name no service directory. Split schemas are the opt-in, not the default. @@ -49,6 +49,7 @@ Every store, verified against actual usage rather than intent. | `BatchStore` | `batch` | | `BatchDependentStore` | `batch_dependent` | | `QueueBatchStateStore` | `queue_batch_state` | +| `QueueRequestStateStore` | `queue_request_state` | | `BuildStore` | `build` | | `SpeculationPathSetStore` | `speculation_path_set` | | `PathBuildStore` | `path_build` | 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/service/submitqueue/orchestrator/server/main.go b/service/submitqueue/orchestrator/server/main.go index 3d3df9ebe..6a0fa12c9 100644 --- a/service/submitqueue/orchestrator/server/main.go +++ b/service/submitqueue/orchestrator/server/main.go @@ -143,7 +143,7 @@ func run() error { cnt := counterFactory{db: appDB, scope: scope.SubScope("counter")} - store, err := mysqlstorage.NewStorage(appDB, scope.SubScope("storage")) + store, err := mysqlstorage.NewStorage(appDB, scope.SubScope("storage"), mysqlstorage.WithQueueRequestStateRecords()) if err != nil { return fmt.Errorf("failed to create storage: %w", err) } diff --git a/submitqueue/entity/BUILD.bazel b/submitqueue/entity/BUILD.bazel index 6e1561ab1..fc7bda103 100644 --- a/submitqueue/entity/BUILD.bazel +++ b/submitqueue/entity/BUILD.bazel @@ -17,6 +17,7 @@ go_library( "queue_batch_state.go", "queue_config.go", "queue_pause.go", + "queue_request_state.go", "request.go", "request_batch.go", "request_history.go", diff --git a/submitqueue/entity/queue_request_state.go b/submitqueue/entity/queue_request_state.go new file mode 100644 index 000000000..a7ae88c54 --- /dev/null +++ b/submitqueue/entity/queue_request_state.go @@ -0,0 +1,34 @@ +// Copyright (c) 2026 Uber Technologies, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package entity + +// QueueRequestState is a membership record filing one in-queue request under its current +// state. Exactly one record exists for a request from its creation until it reaches a +// terminal state, and none afterwards. +// +// The (Queue, State, RequestID) triple is the record's identity. The record mirrors the +// State of the Request identified by RequestID and changes together with it. +type QueueRequestState struct { + // Queue is the name of the queue the request belongs to. Queue name is defined in the + // configuration and should be unique within the system. + Queue string + // State is the request's current state. Always one of InQueueRequestStates(). + State RequestState + // RequestID is the request's identifier, unique within Queue. + RequestID string + // EnteredAtMs is when the request entered State, in Unix milliseconds. A version-only + // update that keeps the state does not change it. + EnteredAtMs int64 +} diff --git a/submitqueue/entity/request.go b/submitqueue/entity/request.go index 0399518ed..d3e8e6c41 100644 --- a/submitqueue/entity/request.go +++ b/submitqueue/entity/request.go @@ -59,6 +59,18 @@ func IsRequestStateTerminal(s RequestState) bool { return s == RequestStateLanded || s == RequestStateError || s == RequestStateCancelled } +// InQueueRequestStates returns every non-terminal request state: the states a request occupies while it is in its +// queue. Every valid RequestState is either listed here or terminal. Each call returns a fresh slice. +func InQueueRequestStates() []RequestState { + return []RequestState{ + RequestStateStarted, + RequestStateValidated, + RequestStateBatched, + RequestStateProcessing, + RequestStateCancelling, + } +} + // IsRequestStateHalted returns true if the request is either terminal or in the process of being cancelled. // Forward-progress controllers (validate, batch, ...) use this to short-circuit work for requests that the // user has asked to cancel — even though Cancelling is non-terminal, no further pipeline work should start. diff --git a/submitqueue/entity/request_test.go b/submitqueue/entity/request_test.go index 0b85cb843..c8881b84b 100644 --- a/submitqueue/entity/request_test.go +++ b/submitqueue/entity/request_test.go @@ -15,6 +15,7 @@ package entity import ( + "slices" "testing" "github.com/stretchr/testify/assert" @@ -41,6 +42,28 @@ func TestIsRequestStateTerminal(t *testing.T) { } } +func TestInQueueRequestStates(t *testing.T) { + tests := []struct { + state RequestState + inQueue bool + }{ + {RequestStateStarted, true}, + {RequestStateValidated, true}, + {RequestStateBatched, true}, + {RequestStateProcessing, true}, + {RequestStateCancelling, true}, + {RequestStateLanded, false}, + {RequestStateError, false}, + {RequestStateCancelled, false}, + } + for _, tt := range tests { + t.Run(string(tt.state), func(t *testing.T) { + assert.Equal(t, tt.inQueue, slices.Contains(InQueueRequestStates(), tt.state)) + assert.NotEqual(t, tt.inQueue, IsRequestStateTerminal(tt.state), "a valid state is either in-queue or terminal") + }) + } +} + func TestIsRequestStateHalted(t *testing.T) { tests := []struct { state RequestState diff --git a/submitqueue/extension/storage/BUILD.bazel b/submitqueue/extension/storage/BUILD.bazel index e75af25dd..87a3ff598 100644 --- a/submitqueue/extension/storage/BUILD.bazel +++ b/submitqueue/extension/storage/BUILD.bazel @@ -9,6 +9,7 @@ go_library( "change_store.go", "path_build_store.go", "queue_batch_state_store.go", + "queue_request_state_store.go", "request_batch_store.go", "request_log_store.go", "request_receipt_store.go", @@ -22,6 +23,7 @@ go_library( visibility = ["//visibility:public"], deps = [ "//platform/errs:go_default_library", + "//platform/metrics:go_default_library", "//submitqueue/entity:go_default_library", ], ) @@ -32,7 +34,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/README.md b/submitqueue/extension/storage/README.md index 026429d84..eb2cfeefe 100644 --- a/submitqueue/extension/storage/README.md +++ b/submitqueue/extension/storage/README.md @@ -61,7 +61,7 @@ Store interfaces are designed for the storage technology *space*, not for SQL (s **Domain state is often already the index.** Before adding any lookup, check whether an entity the caller already loads enumerates the children — an aggregate that references its parts by ID (e.g. a tree whose paths record their build identities) is the batch→children index, persisted and versioned as domain state. Duplicating that relationship as a database index adds a second source of truth for something the domain already owns. -**When neither applies, the reverse lookup is real — give it its own mapping store.** In the KV space there is no third mechanism: the only way to look up by an attribute is to make that attribute a primary key somewhere. So promote the relationship to a first-class mapping entity — keyed by the lookup attribute, written by the same flow that creates the source entity with idempotent puts, and rebuildable as a projection if it drifts. `ChangeRecord` is the in-repo example: it exists so "which requests claimed this change URI" is a by-key read on (queue, URI). `QueueBatchState` is the same pattern for a mutable attribute: "which batches of this queue are in this state" is a by-key read on (queue, state), maintained as advisory records that move buckets alongside the batch's own state CAS (the shared primitives in `submitqueue/orchestrator/core/batch` own that protocol) — it replaced `BatchStore.GetByQueueAndStates`, which was the contract's one query-by-attribute. Unlike a `KEY idx_*`, the relationship is visible in the contract and portable to any backend. +**When neither applies, the reverse lookup is real — give it its own mapping store.** In the KV space there is no third mechanism: the only way to look up by an attribute is to make that attribute a primary key somewhere. So promote the relationship to a first-class mapping entity — keyed by the lookup attribute, written by the same flow that creates the source entity with idempotent puts, and rebuildable as a projection if it drifts. `ChangeRecord` is the in-repo example: it exists so "which requests claimed this change URI" is a by-key read on (queue, URI). `QueueBatchState` is the same pattern for a mutable attribute: "which batches of this queue are in this state" is a by-key read on (queue, state), maintained as advisory records that move buckets alongside the batch's own state CAS (the shared primitives in `submitqueue/orchestrator/core/batch` own that protocol) — it replaced `BatchStore.GetByQueueAndStates`, which was the contract's one query-by-attribute. `QueueRequestState` applies the pattern to requests and is exact rather than advisory: a backend writes each record as part of the request write it mirrors, so `QueueRequestStateStore` is read-only and needs no transition protocol. Unlike a `KEY idx_*`, the relationship is visible in the contract and portable to any backend. ### Decision path diff --git a/submitqueue/extension/storage/mock/BUILD.bazel b/submitqueue/extension/storage/mock/BUILD.bazel index 49f2907c6..3a39d821f 100644 --- a/submitqueue/extension/storage/mock/BUILD.bazel +++ b/submitqueue/extension/storage/mock/BUILD.bazel @@ -9,6 +9,7 @@ go_library( "change_store_mock.go", "path_build_store_mock.go", "queue_batch_state_store_mock.go", + "queue_request_state_store_mock.go", "request_batch_store_mock.go", "request_log_store_mock.go", "request_receipt_store_mock.go", diff --git a/submitqueue/extension/storage/mock/queue_request_state_store_mock.go b/submitqueue/extension/storage/mock/queue_request_state_store_mock.go new file mode 100644 index 000000000..396f7906b --- /dev/null +++ b/submitqueue/extension/storage/mock/queue_request_state_store_mock.go @@ -0,0 +1,57 @@ +// Code generated by MockGen. DO NOT EDIT. +// Source: queue_request_state_store.go +// +// Generated by this command: +// +// mockgen -source=queue_request_state_store.go -destination=mock/queue_request_state_store_mock.go -package=mock +// + +// Package mock is a generated GoMock package. +package mock + +import ( + context "context" + reflect "reflect" + + entity "github.com/uber/submitqueue/submitqueue/entity" + gomock "go.uber.org/mock/gomock" +) + +// MockQueueRequestStateStore is a mock of QueueRequestStateStore interface. +type MockQueueRequestStateStore struct { + ctrl *gomock.Controller + recorder *MockQueueRequestStateStoreMockRecorder + isgomock struct{} +} + +// MockQueueRequestStateStoreMockRecorder is the mock recorder for MockQueueRequestStateStore. +type MockQueueRequestStateStoreMockRecorder struct { + mock *MockQueueRequestStateStore +} + +// NewMockQueueRequestStateStore creates a new mock instance. +func NewMockQueueRequestStateStore(ctrl *gomock.Controller) *MockQueueRequestStateStore { + mock := &MockQueueRequestStateStore{ctrl: ctrl} + mock.recorder = &MockQueueRequestStateStoreMockRecorder{mock} + return mock +} + +// EXPECT returns an object that allows the caller to indicate expected use. +func (m *MockQueueRequestStateStore) EXPECT() *MockQueueRequestStateStoreMockRecorder { + return m.recorder +} + +// List mocks base method. +func (m *MockQueueRequestStateStore) List(ctx context.Context, state entity.RequestState) ([]entity.QueueRequestState, error) { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "List", ctx, state) + ret0, _ := ret[0].([]entity.QueueRequestState) + ret1, _ := ret[1].(error) + return ret0, ret1 +} + +// List indicates an expected call of List. +func (mr *MockQueueRequestStateStoreMockRecorder) List(ctx, state any) *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "List", reflect.TypeOf((*MockQueueRequestStateStore)(nil).List), ctx, state) +} diff --git a/submitqueue/extension/storage/queue_request_state_store.go b/submitqueue/extension/storage/queue_request_state_store.go new file mode 100644 index 000000000..244d62ef4 --- /dev/null +++ b/submitqueue/extension/storage/queue_request_state_store.go @@ -0,0 +1,37 @@ +// Copyright (c) 2026 Uber Technologies, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package storage + +//go:generate mockgen -source=queue_request_state_store.go -destination=mock/queue_request_state_store_mock.go -package=mock + +import ( + "context" + + "github.com/uber/submitqueue/submitqueue/entity" +) + +// QueueRequestStateStore reads the per-queue membership records that file each in-queue +// request under its current state, so "the requests of queue Q in state S" is a single +// read keyed by (queue, state): a primary-key prefix on any backend, with no secondary +// index or server-side filtering. +// +// The store is read-only. A backend keeps the records in step with the requests it +// stores, as part of the same request write, so a listing reflects every committed +// request write. +type QueueRequestStateStore interface { + // List returns every record filed under the bound queue's given state. An empty + // slice means no request is in that state. Order is unspecified. + List(ctx context.Context, state entity.RequestState) ([]entity.QueueRequestState, error) +} 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 9d84b4ad3..6e47c0b6a 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, @@ -222,12 +229,12 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) er case batch.State == entity.BatchStateCreated: // A prior attempt transitioned but lost its announcement, so // re-announcing is the whole job. - 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 } @@ -238,7 +245,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) } @@ -257,11 +264,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 { @@ -285,7 +292,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) } } @@ -310,12 +317,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, @@ -329,14 +336,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) } } @@ -349,7 +356,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) { @@ -366,18 +373,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) } @@ -409,14 +416,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) { @@ -427,7 +434,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) } } @@ -452,7 +459,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 d16c07ec2..8180483ab 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 @@ -325,8 +339,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/mock/storage_mock.go b/submitqueue/orchestrator/extension/storage/mock/storage_mock.go index 9169780e7..ad7663899 100644 --- a/submitqueue/orchestrator/extension/storage/mock/storage_mock.go +++ b/submitqueue/orchestrator/extension/storage/mock/storage_mock.go @@ -164,6 +164,20 @@ func (mr *MockStorageMockRecorder) GetQueueBatchStateStore() *gomock.Call { return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetQueueBatchStateStore", reflect.TypeOf((*MockStorage)(nil).GetQueueBatchStateStore)) } +// GetQueueRequestStateStore mocks base method. +func (m *MockStorage) GetQueueRequestStateStore() storage.QueueRequestStateStore { + m.ctrl.T.Helper() + ret := m.ctrl.Call(m, "GetQueueRequestStateStore") + ret0, _ := ret[0].(storage.QueueRequestStateStore) + return ret0 +} + +// GetQueueRequestStateStore indicates an expected call of GetQueueRequestStateStore. +func (mr *MockStorageMockRecorder) GetQueueRequestStateStore() *gomock.Call { + mr.mock.ctrl.T.Helper() + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetQueueRequestStateStore", reflect.TypeOf((*MockStorage)(nil).GetQueueRequestStateStore)) +} + // GetRequestBatchStore mocks base method. func (m *MockStorage) GetRequestBatchStore() storage.RequestBatchStore { m.ctrl.T.Helper() diff --git a/submitqueue/orchestrator/extension/storage/mysql/BUILD.bazel b/submitqueue/orchestrator/extension/storage/mysql/BUILD.bazel index 1ebf683c4..76033c7df 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/BUILD.bazel +++ b/submitqueue/orchestrator/extension/storage/mysql/BUILD.bazel @@ -9,6 +9,7 @@ go_library( "change_store.go", "path_build_store.go", "queue_batch_state_store.go", + "queue_request_state_store.go", "request_batch_store.go", "request_store.go", "speculation_path_set_store.go", @@ -34,6 +35,7 @@ go_test( "build_store_test.go", "change_store_test.go", "queue_batch_state_store_test.go", + "queue_request_state_store_test.go", "request_batch_store_test.go", "request_store_test.go", "speculation_path_set_store_test.go", 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/queue_request_state_store.go b/submitqueue/orchestrator/extension/storage/mysql/queue_request_state_store.go new file mode 100644 index 000000000..eb6dcae5c --- /dev/null +++ b/submitqueue/orchestrator/extension/storage/mysql/queue_request_state_store.go @@ -0,0 +1,107 @@ +// Copyright (c) 2026 Uber Technologies, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package mysql + +import ( + "context" + "database/sql" + "errors" + "fmt" + "strings" + + "github.com/uber-go/tally" + "github.com/uber/submitqueue/platform/metrics" + "github.com/uber/submitqueue/submitqueue/entity" + "github.com/uber/submitqueue/submitqueue/extension/storage" +) + +// errQueueRequestStateRecordsDisabled is returned by the store a Storage hands out +// when it was not built WithQueueRequestStateRecords: its request writes keep no +// records, so an empty listing would misreport every queue as idle. +var errQueueRequestStateRecordsDisabled = errors.New("queue request state records are not enabled for this storage") + +type queueRequestStateStore struct { + db *sql.DB + scope tally.Scope + // queue is the queue name this store instance is bound to; every read is scoped to it. + queue string +} + +// NewQueueRequestStateStore creates a new MySQL-backed QueueRequestStateStore. +func NewQueueRequestStateStore(db *sql.DB, scope tally.Scope, queue string) storage.QueueRequestStateStore { + return &queueRequestStateStore{db: db, scope: scope, queue: queue} +} + +// List returns every record filed under the bound queue's state. The WHERE clause +// is a prefix of the (queue, state, request_id) PK, so this is a PK-prefix scan. +func (s *queueRequestStateStore) List(ctx context.Context, state entity.RequestState) (ret []entity.QueueRequestState, retErr error) { + op := metrics.Begin(s.scope, "list", metrics.StorageLatencyBuckets) + defer func() { storage.CompleteReadMetricsOp(op, retErr) }() + + const query = "SELECT queue, state, request_id, entered_at_ms FROM queue_request_state WHERE queue = ? AND state = ?" + rows, err := s.db.QueryContext(ctx, query, s.queue, string(state)) + if err != nil { + return nil, fmt.Errorf("failed to query queue request state records for queue=%s state=%s: %w", s.queue, state, err) + } + defer rows.Close() + + var results []entity.QueueRequestState + for rows.Next() { + var rec entity.QueueRequestState + if err := rows.Scan(&rec.Queue, &rec.State, &rec.RequestID, &rec.EnteredAtMs); err != nil { + return nil, fmt.Errorf("failed to scan queue request state record for queue=%s state=%s: %w", s.queue, state, err) + } + results = append(results, rec) + } + if err := rows.Err(); err != nil { + return nil, fmt.Errorf("failed to iterate queue request state records for queue=%s state=%s: %w", s.queue, state, err) + } + return results, nil +} + +type disabledQueueRequestStateStore struct{} + +func (disabledQueueRequestStateStore) List(context.Context, entity.RequestState) ([]entity.QueueRequestState, error) { + return nil, errQueueRequestStateRecordsDisabled +} + +// fileQueueRequestStateRecord makes the request's membership record match state, within +// the caller's transaction: it removes the record from every other in-queue state and, +// unless state is terminal, files it under state. A version-only update that leaves the +// state unchanged hits the existing record, and the no-op ON DUPLICATE KEY UPDATE keeps its +// original EnteredAtMs; unlike INSERT IGNORE, it does not downgrade other errors to warnings. +func fileQueueRequestStateRecord(ctx context.Context, tx *sql.Tx, queue, requestID string, state entity.RequestState, nowMs int64) error { + inQueue := entity.InQueueRequestStates() + others := make([]any, 0, len(inQueue)) + for _, s := range inQueue { + if s != state { + others = append(others, string(s)) + } + } + deleteQuery := "DELETE FROM queue_request_state WHERE queue = ? AND state IN (?" + strings.Repeat(", ?", len(others)-1) + ") AND request_id = ?" + args := append(append([]any{queue}, others...), requestID) + if _, err := tx.ExecContext(ctx, deleteQuery, args...); err != nil { + return fmt.Errorf("failed to remove stale queue request state records for queue=%s request_id=%s: %w", queue, requestID, err) + } + if entity.IsRequestStateTerminal(state) { + return nil + } + const insertQuery = "INSERT INTO queue_request_state (queue, state, request_id, entered_at_ms) VALUES (?, ?, ?, ?) " + + "ON DUPLICATE KEY UPDATE entered_at_ms = entered_at_ms" + if _, err := tx.ExecContext(ctx, insertQuery, queue, string(state), requestID, nowMs); err != nil { + return fmt.Errorf("failed to file queue request state record for queue=%s request_id=%s state=%s: %w", queue, requestID, state, err) + } + return nil +} diff --git a/submitqueue/orchestrator/extension/storage/mysql/queue_request_state_store_test.go b/submitqueue/orchestrator/extension/storage/mysql/queue_request_state_store_test.go new file mode 100644 index 000000000..38bc10e4d --- /dev/null +++ b/submitqueue/orchestrator/extension/storage/mysql/queue_request_state_store_test.go @@ -0,0 +1,104 @@ +// Copyright (c) 2026 Uber Technologies, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package mysql + +import ( + "context" + "errors" + "testing" + + "github.com/DATA-DOG/go-sqlmock" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/uber/submitqueue/submitqueue/entity" +) + +func TestQueueRequestStateStore_List(t *testing.T) { + first := entity.QueueRequestState{Queue: "monorepo", State: entity.RequestStateValidated, RequestID: "1", EnteredAtMs: 100} + second := entity.QueueRequestState{Queue: "monorepo", State: entity.RequestStateValidated, RequestID: "2", EnteredAtMs: 200} + columns := []string{"queue", "state", "request_id", "entered_at_ms"} + storeErr := errors.New("storage failed") + + tests := []struct { + name string + setup func(sqlmock.Sqlmock) + want []entity.QueueRequestState + wantErr bool + }{ + { + name: "success", + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectQuery("SELECT queue, state, request_id, entered_at_ms FROM queue_request_state"). + WithArgs("monorepo", string(entity.RequestStateValidated)). + WillReturnRows(sqlmock.NewRows(columns). + AddRow(first.Queue, string(first.State), first.RequestID, first.EnteredAtMs). + AddRow(second.Queue, string(second.State), second.RequestID, second.EnteredAtMs)) + }, + want: []entity.QueueRequestState{first, second}, + }, + { + name: "no request in the state", + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectQuery("SELECT queue, state, request_id, entered_at_ms FROM queue_request_state"). + WithArgs("monorepo", string(entity.RequestStateValidated)). + WillReturnRows(sqlmock.NewRows(columns)) + }, + }, + { + name: "query fails", + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectQuery("SELECT queue, state, request_id, entered_at_ms FROM queue_request_state"). + WithArgs("monorepo", string(entity.RequestStateValidated)). + WillReturnError(storeErr) + }, + wantErr: true, + }, + { + name: "row iteration fails", + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectQuery("SELECT queue, state, request_id, entered_at_ms FROM queue_request_state"). + WithArgs("monorepo", string(entity.RequestStateValidated)). + WillReturnRows(sqlmock.NewRows(columns). + AddRow(first.Queue, string(first.State), first.RequestID, first.EnteredAtMs). + RowError(0, storeErr)) + }, + wantErr: true, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + db, mock, err := sqlmock.New() + require.NoError(t, err) + defer db.Close() + tt.setup(mock) + + got, err := NewQueueRequestStateStore(db, testMetrics(), "monorepo").List(context.Background(), entity.RequestStateValidated) + if tt.wantErr { + require.Error(t, err) + } else { + require.NoError(t, err) + assert.Equal(t, tt.want, got) + } + require.NoError(t, mock.ExpectationsWereMet()) + }) + } +} + +func TestDisabledQueueRequestStateStore_ListFails(t *testing.T) { + _, err := disabledQueueRequestStateStore{}.List(context.Background(), entity.RequestStateStarted) + require.ErrorIs(t, err, errQueueRequestStateRecordsDisabled) +} 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..0b090211c 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/request_store.go +++ b/submitqueue/orchestrator/extension/storage/mysql/request_store.go @@ -20,6 +20,7 @@ import ( "encoding/json" "errors" "fmt" + "time" "github.com/go-sql-driver/mysql" "github.com/uber-go/tally" @@ -35,17 +36,62 @@ type requestStore struct { // queue is the queue name this store instance is bound to; every read and // write is scoped to it. queue string + // stateRecords files each written request's queue_request_state record in the + // same transaction as the request row. + stateRecords bool + now func() time.Time } -// NewRequestStore creates a new MySQL-backed RequestStore. +// NewRequestStore creates a new MySQL-backed RequestStore that keeps no +// queue_request_state records. func NewRequestStore(db *sql.DB, scope tally.Scope, queue string) storage.RequestStore { - return &requestStore{db: db, scope: scope, queue: queue} + return newRequestStore(db, scope, queue, false) +} + +func newRequestStore(db *sql.DB, scope tally.Scope, queue string, stateRecords bool) *requestStore { + return &requestStore{db: db, scope: scope, queue: queue, stateRecords: stateRecords, now: time.Now} +} + +// requestWriteTxOptions runs request writes that file a membership record at READ +// COMMITTED. The record DELETE usually matches no rows, and at MySQL's default +// REPEATABLE READ InnoDB would gap-lock where those rows would be; the INSERT that +// follows needs an insert-intention lock that conflicts with gap locks, so two +// concurrent writes for different requests in the same queue and state could +// deadlock. READ COMMITTED takes no gap locks for these lookups. +var requestWriteTxOptions = &sql.TxOptions{Isolation: sql.LevelReadCommitted} + +type execer interface { + ExecContext(ctx context.Context, query string, args ...any) (sql.Result, error) +} + +// writeRequest runs write and, when the store keeps queue_request_state records, +// files the request's record in the same transaction so the two never diverge. +func (r *requestStore) writeRequest(ctx context.Context, request entity.Request, write func(execer) error) error { + if !r.stateRecords { + return write(r.db) + } + tx, err := r.db.BeginTx(ctx, requestWriteTxOptions) + if err != nil { + return fmt.Errorf("failed to begin request write transaction id=%s: %w", request.ID, err) + } + if err := write(tx); err != nil { + _ = tx.Rollback() + return err + } + if err := fileQueueRequestStateRecord(ctx, tx, r.queue, request.ID, request.State, r.now().UnixMilli()); err != nil { + _ = tx.Rollback() + return err + } + if err := tx.Commit(); err != nil { + return fmt.Errorf("failed to commit request write transaction id=%s: %w", request.ID, err) + } + return nil } // 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 @@ -79,25 +125,25 @@ func (r *requestStore) Create(ctx context.Context, request entity.Request) (retE return fmt.Errorf("request %s queue %q does not match the store's bound queue %q", request.ID, request.Queue, r.queue) } - // Marshal the change URIs to JSON changeURIsJSON, err := json.Marshal(request.Change.URIs) if err != nil { return fmt.Errorf("failed to marshal change URIs for request id=%s: %w", request.ID, err) } - _, err = r.db.ExecContext(ctx, - "INSERT INTO request (id, queue, change_uri, land_strategy, state, version) VALUES (?, ?, ?, ?, ?, ?)", - request.ID, request.Queue, changeURIsJSON, request.LandStrategy, request.State, request.Version, - ) - if err != nil { - var mysqlErr *mysql.MySQLError - if errors.As(err, &mysqlErr) && mysqlErr.Number == mysqlErrDuplicateEntry { - return fmt.Errorf("request entity id=%s: %w", request.ID, storage.ErrAlreadyExists) + return r.writeRequest(ctx, request, func(ex execer) error { + _, err := ex.ExecContext(ctx, + "INSERT INTO request (id, queue, change_uri, land_strategy, state, version) VALUES (?, ?, ?, ?, ?, ?)", + request.ID, request.Queue, changeURIsJSON, request.LandStrategy, request.State, request.Version, + ) + if err != nil { + var mysqlErr *mysql.MySQLError + if errors.As(err, &mysqlErr) && mysqlErr.Number == mysqlErrDuplicateEntry { + return fmt.Errorf("request entity id=%s: %w", request.ID, storage.ErrAlreadyExists) + } + return fmt.Errorf("failed to insert request entity id=%s: %w", request.ID, err) } - return fmt.Errorf("failed to insert request entity id=%s: %w", request.ID, err) - } - - return nil + return nil + }) } // Update replaces every non-key field of a land request and writes newVersion if the current persisted version matches oldVersion. @@ -115,31 +161,32 @@ func (r *requestStore) Update(ctx context.Context, request entity.Request, oldVe return fmt.Errorf("failed to marshal change URIs for request id=%s: %w", request.ID, err) } - result, err := r.db.ExecContext(ctx, - "UPDATE request SET change_uri = ?, land_strategy = ?, state = ?, version = ? WHERE queue = ? AND id = ? AND version = ?", - changeURIsJSON, request.LandStrategy, request.State, newVersion, request.Queue, request.ID, oldVersion, - ) - if err != nil { - return fmt.Errorf( - "failed to update request for id=%q oldVersion=%d newVersion=%d: %w", - request.ID, oldVersion, newVersion, err, - ) - } - - rowsAffected, err := result.RowsAffected() - if err != nil { - return fmt.Errorf( - "failed to get rows affected from update for id=%q oldVersion=%d newVersion=%d: %w", - request.ID, oldVersion, newVersion, err, + return r.writeRequest(ctx, request, func(ex execer) error { + result, err := ex.ExecContext(ctx, + "UPDATE request SET change_uri = ?, land_strategy = ?, state = ?, version = ? WHERE queue = ? AND id = ? AND version = ?", + changeURIsJSON, request.LandStrategy, request.State, newVersion, request.Queue, request.ID, oldVersion, ) - } + if err != nil { + return fmt.Errorf( + "failed to update request for id=%q oldVersion=%d newVersion=%d: %w", + request.ID, oldVersion, newVersion, err, + ) + } - if rowsAffected != 1 { - return fmt.Errorf( - "version mismatch for request update: id=%q expected_version=%d: %w", - request.ID, oldVersion, storage.ErrVersionMismatch, - ) - } + rowsAffected, err := result.RowsAffected() + if err != nil { + return fmt.Errorf( + "failed to get rows affected from update for id=%q oldVersion=%d newVersion=%d: %w", + request.ID, oldVersion, newVersion, err, + ) + } - return nil + if rowsAffected != 1 { + return fmt.Errorf( + "version mismatch for request update: id=%q expected_version=%d: %w", + request.ID, oldVersion, storage.ErrVersionMismatch, + ) + } + return nil + }) } diff --git a/submitqueue/orchestrator/extension/storage/mysql/request_store_test.go b/submitqueue/orchestrator/extension/storage/mysql/request_store_test.go index 76e9bdca2..0b6699d6d 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/request_store_test.go +++ b/submitqueue/orchestrator/extension/storage/mysql/request_store_test.go @@ -17,6 +17,7 @@ package mysql import ( "context" "database/sql" + "database/sql/driver" "encoding/json" "fmt" "testing" @@ -305,3 +306,122 @@ func TestRequestStore_Update(t *testing.T) { }) } } + +func TestRequestStore_WritesQueueRequestStateRecords(t *testing.T) { + started := entity.Request{ + ID: "1", + Queue: "monorepo", + Change: change.Change{URIs: []string{"github://github.example.com/uber/submitqueue/pull/123/deadbeef"}}, + LandStrategy: mergestrategy.MergeStrategyRebase, + State: entity.RequestStateStarted, + Version: 1, + } + validated := started + validated.State = entity.RequestStateValidated + landed := started + landed.State = entity.RequestStateLanded + + const insertRecord = "INSERT INTO queue_request_state" + const deleteRecords = "DELETE FROM queue_request_state" + otherStatesThan := func(state entity.RequestState) []driver.Value { + args := []driver.Value{"monorepo"} + for _, s := range entity.InQueueRequestStates() { + if s != state { + args = append(args, string(s)) + } + } + return append(args, "1") + } + + tests := []struct { + name string + write func(storage.RequestStore) error + setup func(sqlmock.Sqlmock) + wantErrIs error + wantErr bool + }{ + { + name: "create files the started record in the same transaction", + write: func(store storage.RequestStore) error { return store.Create(context.Background(), started) }, + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectBegin() + mock.ExpectExec("INSERT INTO request").WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(deleteRecords).WithArgs(otherStatesThan(entity.RequestStateStarted)...).WillReturnResult(sqlmock.NewResult(0, 0)) + mock.ExpectExec(insertRecord).WithArgs("monorepo", "started", "1", sqlmock.AnyArg()).WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectCommit() + }, + }, + { + name: "duplicate create rolls back without touching records", + write: func(store storage.RequestStore) error { return store.Create(context.Background(), started) }, + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectBegin() + mock.ExpectExec("INSERT INTO request").WillReturnError(&mysql.MySQLError{Number: mysqlErrDuplicateEntry}) + mock.ExpectRollback() + }, + wantErrIs: storage.ErrAlreadyExists, + }, + { + name: "state change moves the record", + write: func(store storage.RequestStore) error { return store.Update(context.Background(), validated, 1, 2) }, + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectBegin() + mock.ExpectExec("UPDATE request").WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(deleteRecords).WithArgs(otherStatesThan(entity.RequestStateValidated)...).WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(insertRecord).WithArgs("monorepo", "validated", "1", sqlmock.AnyArg()).WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectCommit() + }, + }, + { + name: "terminal update removes the record without filing a new one", + write: func(store storage.RequestStore) error { return store.Update(context.Background(), landed, 1, 2) }, + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectBegin() + mock.ExpectExec("UPDATE request").WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(deleteRecords).WithArgs(otherStatesThan(entity.RequestStateLanded)...).WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectCommit() + }, + }, + { + name: "version mismatch rolls back without touching records", + write: func(store storage.RequestStore) error { return store.Update(context.Background(), validated, 1, 2) }, + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectBegin() + mock.ExpectExec("UPDATE request").WillReturnResult(sqlmock.NewResult(0, 0)) + mock.ExpectRollback() + }, + wantErrIs: storage.ErrVersionMismatch, + }, + { + name: "failed record write rolls back the request write", + write: func(store storage.RequestStore) error { return store.Update(context.Background(), validated, 1, 2) }, + setup: func(mock sqlmock.Sqlmock) { + mock.ExpectBegin() + mock.ExpectExec("UPDATE request").WillReturnResult(sqlmock.NewResult(0, 1)) + mock.ExpectExec(deleteRecords).WillReturnError(fmt.Errorf("lock wait timeout")) + mock.ExpectRollback() + }, + wantErr: true, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + db, mock, err := sqlmock.New() + require.NoError(t, err) + defer db.Close() + tt.setup(mock) + + err = tt.write(newRequestStore(db, testMetrics(), "monorepo", true)) + switch { + case tt.wantErrIs != nil: + require.ErrorIs(t, err, tt.wantErrIs) + case tt.wantErr: + require.Error(t, err) + default: + require.NoError(t, err) + } + require.NoError(t, mock.ExpectationsWereMet()) + }) + } +} diff --git a/submitqueue/orchestrator/extension/storage/mysql/schema/README.md b/submitqueue/orchestrator/extension/storage/mysql/schema/README.md index 14c09d619..a4a4cb256 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/schema/README.md +++ b/submitqueue/orchestrator/extension/storage/mysql/schema/README.md @@ -2,7 +2,7 @@ ## Queue-leading primary keys -Every table leads its primary key with `queue`: `request` and `batch` on `(queue, id)`, `build` on `(queue, id)`, `batch_dependent` on `(queue, batch_id)`, `request_batch` on `(queue, request_id, batch_id)`, `change` on `(queue, uri, request_id)`, `queue_batch_state` on `(queue, state, batch_id)`, and `speculation_path_set` on `(queue, head)`. A queue-bound store instance prefixes every read and stamps every write with its bound queue, so one queue's rows are unreachable through another queue's binding and every table is shardable by queue. `//tool/linter/queueshard` enforces this, and also rejects any secondary index that does not itself lead with `queue`, since such an index would reintroduce a cross-queue access path. +Every table leads its primary key with `queue`: `request` and `batch` on `(queue, id)`, `build` on `(queue, id)`, `batch_dependent` on `(queue, batch_id)`, `request_batch` on `(queue, request_id, batch_id)`, `change` on `(queue, uri, request_id)`, `queue_batch_state` on `(queue, state, batch_id)`, `queue_request_state` on `(queue, state, request_id)`, and `speculation_path_set` on `(queue, head)`. A queue-bound store instance prefixes every read and stamps every write with its bound queue, so one queue's rows are unreachable through another queue's binding and every table is shardable by queue. `//tool/linter/queueshard` enforces this, and also rejects any secondary index that does not itself lead with `queue`, since such an index would reintroduce a cross-queue access path. The `build` key also removes a cross-queue uniqueness assumption: build IDs are runner-minted, so two queues sharing one CI pipeline may legitimately mint the same identifier. `speculation_path_set` relies on the same property for its head: a batch ID is unique only within its queue. @@ -22,6 +22,25 @@ The `batch` table is keyed by `(queue, id)` and carries no secondary index. List Terminal-state records (and their batches) accumulate as the queue processes work. A prune job should periodically delete records and batches in terminal states (`succeeded`, `failed`, `cancelled`) older than a configurable retention period, keeping both tables bounded so query and write performance stay consistent over time. +## queue_request_state table + +### Composite primary key: `(queue, state, request_id)` + +`queue_request_state` files each in-queue request under its current state (see `entity.QueueRequestState`), so listing a queue's requests by state is a primary-key-prefix scan and the `request` table keeps no secondary index. Unlike `queue_batch_state`, the rows are exact rather than advisory: the MySQL request store writes a request's row in the same transaction as the `request` row, removing it from every other in-queue state and filing it under the new one (`ON DUPLICATE KEY UPDATE entered_at_ms = entered_at_ms`, so a version-only update keeps `entered_at_ms`). That transaction runs at `READ COMMITTED`: the removal usually matches no rows, and at the default `REPEATABLE READ` its gap locks would conflict with concurrent inserts into the same queue and state. A terminal request has no row, so the table only ever holds in-queue requests. The records are kept only by a storage built with `WithQueueRequestStateRecords`, which a deployment enables once the table exists. + +### Rolling out to an existing deployment + +Requests already in flight get a row only on their next write, and a stuck request never writes again. So after creating the table and enabling `WithQueueRequestStateRecords`, backfill once: + +```sql +INSERT INTO queue_request_state (queue, state, request_id, entered_at_ms) +SELECT queue, state, id, FROM request +WHERE state IN ('started', 'validated', 'batched', 'processing', 'cancelling') +ON DUPLICATE KEY UPDATE entered_at_ms = entered_at_ms; +``` + +Run it after enabling the records, not before: a request that changes state between a backfill and the enable would keep its backfilled row under the old state. Rows the store has already written keep their own `entered_at_ms`. For backfilled rows, `entered_at_ms` is the backfill time rather than when the request entered its state, so time-in-state for those requests is understated until their next transition. + ## change table ### Composite primary key: `(queue, uri, request_id)` diff --git a/submitqueue/orchestrator/extension/storage/mysql/schema/queue_request_state.sql b/submitqueue/orchestrator/extension/storage/mysql/schema/queue_request_state.sql new file mode 100644 index 000000000..8c67c5df9 --- /dev/null +++ b/submitqueue/orchestrator/extension/storage/mysql/schema/queue_request_state.sql @@ -0,0 +1,12 @@ +-- Membership records filing each in-queue request under its current state. +-- The (queue, state, request_id) PK *is* the lookup: "requests of queue Q in state S" +-- is a PK-prefix scan, so no secondary index is needed. Rows are written in the same +-- transaction as the request row they mirror and removed when the request reaches a +-- terminal state, so the table only ever holds in-queue requests. +CREATE TABLE IF NOT EXISTS queue_request_state ( + queue VARCHAR(255) NOT NULL, + state VARCHAR(64) NOT NULL, + request_id VARCHAR(255) NOT NULL, + entered_at_ms BIGINT NOT NULL, + PRIMARY KEY (queue, state, request_id) +) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4; 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 diff --git a/submitqueue/orchestrator/extension/storage/mysql/storage.go b/submitqueue/orchestrator/extension/storage/mysql/storage.go index 1309ee86d..cc3c79d1c 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/storage.go +++ b/submitqueue/orchestrator/extension/storage/mysql/storage.go @@ -34,13 +34,28 @@ const mysqlErrDuplicateEntry = 1062 // The wiring layer adapts For into the storage.Factory seam; per-queue backend // routing stays a host decision. type Storage struct { - db *sql.DB - scope tally.Scope + db *sql.DB + scope tally.Scope + queueRequestStateRecords bool +} + +// StorageOption configures a Storage. +type StorageOption func(*Storage) + +// WithQueueRequestStateRecords keeps the queue_request_state membership records in +// step with every request write and serves them through GetQueueRequestStateStore. +// The queue_request_state table must exist before such a Storage writes a request. +func WithQueueRequestStateRecords() StorageOption { + return func(s *Storage) { s.queueRequestStateRecords = true } } // NewStorage creates a new MySQL storage backend over the given connection pool. -func NewStorage(db *sql.DB, scope tally.Scope) (*Storage, error) { - return &Storage{db: db, scope: scope}, nil +func NewStorage(db *sql.DB, scope tally.Scope, opts ...StorageOption) (*Storage, error) { + s := &Storage{db: db, scope: scope} + for _, opt := range opts { + opt(s) + } + return s, nil } // For returns the queue-scoped store aggregate bound to queueName over the @@ -50,13 +65,18 @@ func (s *Storage) For(queueName string) (storage.Storage, error) { if queueName == "" { return nil, fmt.Errorf("queue name must not be empty") } + var queueRequestStateStore basestorage.QueueRequestStateStore = disabledQueueRequestStateStore{} + if s.queueRequestStateRecords { + queueRequestStateStore = NewQueueRequestStateStore(s.db, s.scope.SubScope("queue_request_state_store"), queueName) + } return &boundStorage{ - requestStore: NewRequestStore(s.db, s.scope.SubScope("request_store"), queueName), + requestStore: newRequestStore(s.db, s.scope.SubScope("request_store"), queueName, s.queueRequestStateRecords), requestBatchStore: NewRequestBatchStore(s.db, s.scope.SubScope("request_batch_store"), queueName), changeStore: NewChangeStore(s.db, s.scope.SubScope("change_store"), queueName), batchStore: NewBatchStore(s.db, s.scope.SubScope("batch_store"), queueName), batchDependentStore: NewBatchDependentStore(s.db, s.scope.SubScope("batch_dependent_store"), queueName), queueBatchStateStore: NewQueueBatchStateStore(s.db, s.scope.SubScope("queue_batch_state_store"), queueName), + queueRequestStateStore: queueRequestStateStore, buildStore: NewBuildStore(s.db, s.scope.SubScope("build_store"), queueName), speculationPathSetStore: NewSpeculationPathSetStore(s.db, s.scope.SubScope("speculation_path_set_store"), queueName), pathBuildStore: NewPathBuildStore(s.db, s.scope.SubScope("path_build_store"), queueName), @@ -76,6 +96,7 @@ type boundStorage struct { batchStore basestorage.BatchStore batchDependentStore basestorage.BatchDependentStore queueBatchStateStore basestorage.QueueBatchStateStore + queueRequestStateStore basestorage.QueueRequestStateStore buildStore basestorage.BuildStore speculationPathSetStore basestorage.SpeculationPathSetStore pathBuildStore basestorage.PathBuildStore @@ -114,6 +135,12 @@ func (f *boundStorage) GetQueueBatchStateStore() basestorage.QueueBatchStateStor return f.queueBatchStateStore } +// GetQueueRequestStateStore returns the bound MySQL-backed QueueRequestStateStore. Its +// List fails unless the Storage was built WithQueueRequestStateRecords. +func (f *boundStorage) GetQueueRequestStateStore() basestorage.QueueRequestStateStore { + return f.queueRequestStateStore +} + // GetBuildStore returns the bound MySQL-backed BuildStore. func (f *boundStorage) GetBuildStore() basestorage.BuildStore { return f.buildStore diff --git a/submitqueue/orchestrator/extension/storage/mysql/storage_test.go b/submitqueue/orchestrator/extension/storage/mysql/storage_test.go index 8b74b3e31..98cb2b468 100644 --- a/submitqueue/orchestrator/extension/storage/mysql/storage_test.go +++ b/submitqueue/orchestrator/extension/storage/mysql/storage_test.go @@ -15,12 +15,15 @@ package mysql import ( + "context" "testing" "github.com/DATA-DOG/go-sqlmock" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/uber-go/tally" + + "github.com/uber/submitqueue/submitqueue/entity" ) // testMetrics returns a test metrics scope for use in tests. @@ -51,6 +54,41 @@ func TestNewStorage(t *testing.T) { assert.Error(t, err, "resolving an empty queue name must fail") } +func TestNewStorage_QueueRequestStateRecords(t *testing.T) { + tests := []struct { + name string + opts []StorageOption + wantListErr error + }{ + {name: "disabled by default", wantListErr: errQueueRequestStateRecordsDisabled}, + {name: "enabled by option", opts: []StorageOption{WithQueueRequestStateRecords()}}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + db, mock, err := sqlmock.New() + require.NoError(t, err) + defer db.Close() + if tt.wantListErr == nil { + mock.ExpectQuery("SELECT queue, state, request_id, entered_at_ms FROM queue_request_state"). + WillReturnRows(sqlmock.NewRows([]string{"queue", "state", "request_id", "entered_at_ms"})) + } + + s, err := NewStorage(db, testMetrics(), tt.opts...) + require.NoError(t, err) + bound, err := s.For("monorepo") + require.NoError(t, err) + + _, err = bound.GetQueueRequestStateStore().List(context.Background(), entity.RequestStateStarted) + if tt.wantListErr != nil { + require.ErrorIs(t, err, tt.wantListErr) + } else { + require.NoError(t, err) + } + require.NoError(t, mock.ExpectationsWereMet()) + }) + } +} + func TestMysqlStorage_Close(t *testing.T) { db, mock, err := sqlmock.New() require.NoError(t, err) diff --git a/submitqueue/orchestrator/extension/storage/storage.go b/submitqueue/orchestrator/extension/storage/storage.go index 5b6ebb4c0..a81ee0f75 100644 --- a/submitqueue/orchestrator/extension/storage/storage.go +++ b/submitqueue/orchestrator/extension/storage/storage.go @@ -62,6 +62,9 @@ type Storage interface { // GetQueueBatchStateStore returns the QueueBatchStateStore instance. GetQueueBatchStateStore() basestorage.QueueBatchStateStore + // GetQueueRequestStateStore returns the QueueRequestStateStore instance. + GetQueueRequestStateStore() basestorage.QueueRequestStateStore + // GetBuildStore returns the BuildStore instance. GetBuildStore() basestorage.BuildStore diff --git a/test/integration/submitqueue/extension/storage/mysql/storage_test.go b/test/integration/submitqueue/extension/storage/mysql/storage_test.go index bbc0f07a2..f1decee2f 100644 --- a/test/integration/submitqueue/extension/storage/mysql/storage_test.go +++ b/test/integration/submitqueue/extension/storage/mysql/storage_test.go @@ -78,7 +78,7 @@ func (s *MySQLStorageIntegrationSuite) SetupSuite() { s.log.Logf("Schemas applied successfully") // Create storage instance using the existing database connection - store, err := mysqlstorage.NewStorage(s.db, tally.NoopScope) + store, err := mysqlstorage.NewStorage(s.db, tally.NoopScope, mysqlstorage.WithQueueRequestStateRecords()) require.NoError(t, err, "failed to create storage") gwStore, err := gwmysqlstorage.NewStorage(s.db, tally.NoopScope) diff --git a/test/integration/submitqueue/extension/storage/suite.go b/test/integration/submitqueue/extension/storage/suite.go index a85ad023e..27ad1a706 100644 --- a/test/integration/submitqueue/extension/storage/suite.go +++ b/test/integration/submitqueue/extension/storage/suite.go @@ -18,6 +18,7 @@ import ( "context" "fmt" "sort" + "sync" "testing" orchstorage "github.com/uber/submitqueue/submitqueue/orchestrator/extension/storage" @@ -419,6 +420,143 @@ func (s *StorageContractSuite) TestStorage_QueueBatchStateRecordLifecycle() { assert.ElementsMatch(t, []entity.QueueBatchState{otherQueue}, got) } +// TestStorage_QueueRequestStateRecordsFollowRequestWrites exercises the +// QueueRequestStateStore contract: every committed request write leaves exactly one +// record under the request's current in-queue state, none once it is terminal, and +// a failed write changes nothing. +func (s *StorageContractSuite) TestStorage_QueueRequestStateRecordsFollowRequestWrites() { + t := s.T() + ctx := s.ctx + requestsA := s.forQueue("qrs-queue-a").GetRequestStore() + recordsA := s.forQueue("qrs-queue-a").GetQueueRequestStateStore() + recordsB := s.forQueue("qrs-queue-b").GetQueueRequestStateStore() + + newRequest := func(queue, id string) entity.Request { + return entity.Request{ + ID: id, + Queue: queue, + Change: change.Change{URIs: []string{"github://github.example.com/uber/monorepo/pull/" + id + "/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"}}, + State: entity.RequestStateStarted, + LandStrategy: mergestrategy.MergeStrategyMerge, + Version: 1, + } + } + listIDs := func(records storage.QueueRequestStateStore, state entity.RequestState) []string { + got, err := records.List(ctx, state) + require.NoError(t, err) + ids := make([]string, 0, len(got)) + for _, rec := range got { + assert.Equal(t, state, rec.State) + assert.Positive(t, rec.EnteredAtMs) + ids = append(ids, rec.RequestID) + } + return ids + } + + first, second := newRequest("qrs-queue-a", "1"), newRequest("qrs-queue-a", "2") + require.NoError(t, requestsA.Create(ctx, first)) + require.NoError(t, requestsA.Create(ctx, second)) + require.NoError(t, s.forQueue("qrs-queue-b").GetRequestStore().Create(ctx, newRequest("qrs-queue-b", "1"))) + assert.ElementsMatch(t, []string{"1", "2"}, listIDs(recordsA, entity.RequestStateStarted)) + + validated := first + validated.State = entity.RequestStateValidated + require.NoError(t, requestsA.Update(ctx, validated, 1, 2)) + assert.ElementsMatch(t, []string{"2"}, listIDs(recordsA, entity.RequestStateStarted)) + assert.ElementsMatch(t, []string{"1"}, listIDs(recordsA, entity.RequestStateValidated)) + + enteredValidated, err := recordsA.List(ctx, entity.RequestStateValidated) + require.NoError(t, err) + require.NoError(t, requestsA.Update(ctx, validated, 2, 3)) + afterVersionBump, err := recordsA.List(ctx, entity.RequestStateValidated) + require.NoError(t, err) + assert.Equal(t, enteredValidated, afterVersionBump, "a version-only update keeps the time the state was entered") + + batched := validated + batched.State = entity.RequestStateBatched + require.ErrorIs(t, requestsA.Update(ctx, batched, 2, 3), storage.ErrVersionMismatch) + assert.ElementsMatch(t, []string{"1"}, listIDs(recordsA, entity.RequestStateValidated)) + assert.Empty(t, listIDs(recordsA, entity.RequestStateBatched)) + + landed := second + landed.State = entity.RequestStateLanded + require.NoError(t, requestsA.Update(ctx, landed, 1, 2)) + for _, state := range entity.InQueueRequestStates() { + assert.NotContains(t, listIDs(recordsA, state), "2", "a terminal request has no record") + } + + assert.ElementsMatch(t, []string{"1"}, listIDs(recordsB, entity.RequestStateStarted)) +} + +// TestStorage_QueueRequestStateRecordsUnderConcurrentWrites runs many request writes +// for different requests of one queue at once, the load where membership-record +// transactions could block or deadlock each other on locks taken for records that do +// not exist yet. Every write must succeed and leave its request filed exactly once. +func (s *StorageContractSuite) TestStorage_QueueRequestStateRecordsUnderConcurrentWrites() { + t := s.T() + ctx := s.ctx + const queue = "qrs-concurrent" + const writers = 16 + requests := s.forQueue(queue).GetRequestStore() + records := s.forQueue(queue).GetQueueRequestStateStore() + + newRequest := func(i int) entity.Request { + id := fmt.Sprintf("concurrent-%d", i) + return entity.Request{ + ID: id, + Queue: queue, + Change: change.Change{URIs: []string{"github://github.example.com/uber/monorepo/pull/" + id + "/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"}}, + State: entity.RequestStateStarted, + LandStrategy: mergestrategy.MergeStrategyMerge, + Version: 1, + } + } + // concurrently runs write once per request, all at the same moment, and requires + // every one to succeed. + concurrently := func(write func(i int) error) { + var wg sync.WaitGroup + start := make(chan struct{}) + errs := make([]error, writers) + for i := range writers { + wg.Add(1) + go func() { + defer wg.Done() + <-start + errs[i] = write(i) + }() + } + close(start) + wg.Wait() + for i, err := range errs { + require.NoError(t, err, "write for request %d", i) + } + } + listIDs := func(state entity.RequestState) []string { + got, err := records.List(ctx, state) + require.NoError(t, err) + ids := make([]string, 0, len(got)) + for _, rec := range got { + ids = append(ids, rec.RequestID) + } + return ids + } + allIDs := make([]string, writers) + for i := range writers { + allIDs[i] = newRequest(i).ID + } + + concurrently(func(i int) error { return requests.Create(ctx, newRequest(i)) }) + assert.ElementsMatch(t, allIDs, listIDs(entity.RequestStateStarted)) + + concurrently(func(i int) error { + validated := newRequest(i) + validated.State = entity.RequestStateValidated + return requests.Update(ctx, validated, 1, 2) + }) + assert.Empty(t, listIDs(entity.RequestStateStarted)) + assert.ElementsMatch(t, allIDs, listIDs(entity.RequestStateValidated)) +} + // TestStorage_QueueIsolation verifies a store aggregate bound to one queue can // neither read nor write another queue's records: cross-queue reads miss, and // writes whose entity queue disagrees with the binding are rejected.