Skip to content

Commit e75ffb7

Browse files
committed
fix(github): surface a mirrored control rejection on every path an operator reads
- Mirror settled control requests from the stop/cancel progress reads. Those paths reconcile a terminal remote and end the drive, so a rejection the data plane settled after the last regular poll would otherwise never be recorded. - Append the rejection notice to the terminal summary comment, not only to the progress comment the summary supersedes. - Omit the attribution clause when the stored request names no operator, so a proxied command is not credited to SchemaBot's internal forwarding caller. - Rewrite the remote apply identifier out of the mirrored reason on an operation-scoped drive, where the parent apply carries no external id. - Name an unrecognized settled status in a warning instead of dropping it silently. - Document the rejection counter and the release operation in the metrics reference, and count release as a known control operation.
1 parent 2a084a1 commit e75ffb7

9 files changed

Lines changed: 215 additions & 30 deletions

pkg/metrics/README.md

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,7 @@ available, such as `repository`, `github_app`, and `installation_id`.
3939
| `schemabot.github.rate_limit.remaining` | Gauge | environment, operation, resource, repository, github_app, installation_id | GitHub primary rate limit requests remaining for the observed API resource |
4040
| `schemabot.github.rate_limit.used` | Gauge | environment, operation, resource, repository, github_app, installation_id | GitHub primary rate limit requests used for the observed API resource |
4141
| `schemabot.control_operations_total` | Counter | operation, database, environment, status | Control operations (cutover, stop, start, etc.) |
42+
| `schemabot.remote_control_requests.rejected_total` | Counter | operation, engine, database, deployment, environment | Control requests a remote data plane accepted and its own driver then failed, mirrored back so the operator learns the command never took effect — see [Control Operations](#control-operations) |
4243
| `schemabot.lock_operations_total` | Counter | operation, database, environment, status | Lock acquire/release operations |
4344
| `schemabot.direct_write_authorization.total` | Counter | operation, database, environment, status, reason | Per-database direct-write (CLI/API) authorization decisions at the handler layer |
4445
| `schemabot.operator.resumed_total` | Counter | database, environment, previous_state | Applies resumed by the operator |
@@ -95,10 +96,12 @@ available, such as `repository`, `github_app`, and `installation_id`.
9596
9697
**status** (status checks): `success`, `error`, `skipped`, `stale`, `noop`, `blocked` (operation outcome, not GitHub Check Run conclusion)
9798
98-
**operation** (control): `cutover`, `stop`, `start`, `volume`, `revert`, `skip_revert`, `rollback_plan`
99+
**operation** (control): `cutover`, `stop`, `start`, `volume`, `revert`, `skip_revert`, `release`, `rollback_plan`
99100
100101
**status** (control): `success`, `error`, `rejected`
101102
103+
**engine** (control): the engine that rejected the command, as recorded on the apply (for example `spirit`, `planetscale`)
104+
102105
**operation** (locks): `acquire`, `release`
103106
104107
**status** (locks): `success`, `conflict`, `not_found`, `not_owned`, `error`
@@ -290,8 +293,18 @@ Operation values:
290293
| `volume` | Change the engine's throttling or volume setting for an apply. |
291294
| `revert` | Request that the engine revert an apply. |
292295
| `skip_revert` | Skip the post-deploy revert window for an apply. |
296+
| `release` | Release a rollout paused after a failure so the remaining work proceeds. |
293297
| `rollback_plan` | Generate a rollback plan from a previous completed apply. |
294298
299+
`schemabot.remote_control_requests.rejected_total` counts the same operations
300+
from the other side: a control request the data plane acknowledged and its own
301+
driver then failed. Acceptance only means the request was queued, so without
302+
this mirror the operator is told the command succeeded and never learns the
303+
effect did not land. A non-zero rate names the operation and `engine` that is
304+
refusing operator commands — chart it by operation to see which control surface
305+
is unsupported or broken on that engine, and read the apply log entry recorded
306+
alongside it for the engine's own reason.
307+
295308
### Lock Operations
296309
297310
`schemabot.lock_operations_total` tracks database-level lock acquisition and

pkg/metrics/metrics.go

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -740,11 +740,12 @@ var knownControlOperations = map[string]bool{
740740
"volume": true,
741741
"revert": true,
742742
"skip_revert": true,
743+
"release": true,
743744
"rollback_plan": true,
744745
}
745746

746747
// RecordControlOperation increments the control operations counter.
747-
// Operation should be one of: cutover, stop, start, volume, revert, skip_revert, rollback_plan.
748+
// Operation should be one of: cutover, stop, start, volume, revert, skip_revert, release, rollback_plan.
748749
// Status should be "success" or "error".
749750
func RecordControlOperation(ctx context.Context, operation, database, deployment, environment, status string) {
750751
if !knownControlOperations[operation] {

pkg/tern/grpc_client.go

Lines changed: 37 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -896,10 +896,7 @@ func (c *GRPCClient) processPendingStopControlRequest(ctx context.Context, apply
896896
}
897897
}
898898

899-
progress, err := c.client.Progress(ctx, &ternv1.ProgressRequest{
900-
ApplyId: remoteID,
901-
Environment: apply.Environment,
902-
})
899+
progress, err := c.controlPathProgress(ctx, apply, remoteID)
903900
if err != nil {
904901
return true, fmt.Errorf("sync remote gRPC stop for apply %s remote %s: %w", apply.ApplyIdentifier, remoteID, err)
905902
}
@@ -1014,7 +1011,7 @@ func (c *GRPCClient) processPendingCancelControlRequest(ctx context.Context, app
10141011
logRemoteControlResend(ctx, logger, apply, controlReq, now)
10151012
}
10161013
}
1017-
progress, err := c.client.Progress(ctx, &ternv1.ProgressRequest{ApplyId: remoteID, Environment: apply.Environment})
1014+
progress, err := c.controlPathProgress(ctx, apply, remoteID)
10181015
if err != nil {
10191016
return true, fmt.Errorf("sync remote gRPC cancel for apply %s remote %s: %w", apply.ApplyIdentifier, remoteID, err)
10201017
}
@@ -1050,6 +1047,23 @@ func (c *GRPCClient) processPendingCancelControlRequest(ctx context.Context, app
10501047
return false, nil
10511048
}
10521049

1050+
// controlPathProgress polls remote progress on behalf of a control-request path
1051+
// and mirrors any control rejections the response carries. A cancel or stop that
1052+
// reconciles a terminal remote ends the drive, so the regular poll loop never
1053+
// runs again: a rejection the data plane settled after the last regular poll
1054+
// reaches the operator only if it is mirrored from here.
1055+
func (c *GRPCClient) controlPathProgress(ctx context.Context, apply *storage.Apply, remoteID string) (*ternv1.ProgressResponse, error) {
1056+
progress, err := c.client.Progress(ctx, &ternv1.ProgressRequest{
1057+
ApplyId: remoteID,
1058+
Environment: apply.Environment,
1059+
})
1060+
if err != nil {
1061+
return nil, err
1062+
}
1063+
c.mirrorRemoteControlRejections(ctx, apply, remoteID, progress.SettledControlRequests)
1064+
return progress, nil
1065+
}
1066+
10531067
func (c *GRPCClient) processPendingCancelOrStopControlRequest(ctx context.Context, apply *storage.Apply, scope applyTaskScope) (bool, error) {
10541068
if handled, err := c.processPendingCancelControlRequest(ctx, apply, scope); handled || err != nil {
10551069
return handled, err
@@ -1063,10 +1077,7 @@ func (c *GRPCClient) completeRemoteStopFromTerminalProgress(ctx context.Context,
10631077
// tracks its remote apply on the operation, not on the parent apply's
10641078
// ExternalID.
10651079
remoteID := scope.remoteApplyID(apply)
1066-
progress, err := c.client.Progress(ctx, &ternv1.ProgressRequest{
1067-
ApplyId: remoteID,
1068-
Environment: apply.Environment,
1069-
})
1080+
progress, err := c.controlPathProgress(ctx, apply, remoteID)
10701081
if err != nil {
10711082
logger.WarnContext(ctx, "remote gRPC stop error could not be reconciled from progress",
10721083
append(apply.MutableLogAttrs(),
@@ -1134,10 +1145,7 @@ func (c *GRPCClient) completeRemoteCancelFromTerminalProgress(ctx context.Contex
11341145
// tracks its remote apply on the operation, not on the parent apply's
11351146
// ExternalID.
11361147
remoteID := scope.remoteApplyID(apply)
1137-
progress, err := c.client.Progress(ctx, &ternv1.ProgressRequest{
1138-
ApplyId: remoteID,
1139-
Environment: apply.Environment,
1140-
})
1148+
progress, err := c.controlPathProgress(ctx, apply, remoteID)
11411149
if err != nil {
11421150
logger.WarnContext(ctx, "remote gRPC cancel error could not be reconciled from progress",
11431151
append(apply.MutableLogAttrs(),
@@ -1669,7 +1677,12 @@ func mirrorRemoteVolume(logger *slog.Logger, apply *storage.Apply, remoteVolume
16691677
// operator retries the operation, so a mirror that fails is retried on the next
16701678
// tick rather than aborting the drive, and a mirror that succeeds is surfaced
16711679
// exactly once (RecordRemoteFailure reports whether the stored row changed).
1672-
func (c *GRPCClient) mirrorRemoteControlRejections(ctx context.Context, apply *storage.Apply, settled []*ternv1.SettledControlRequest) {
1680+
//
1681+
// remoteID is the remote identifier this drive addressed. The data plane's
1682+
// message names its own apply, which is meaningless to the operator reading the
1683+
// PR — and on an operation-scoped drive the parent apply's ExternalID is empty,
1684+
// so the remote identifier is only redactable when it is passed in here.
1685+
func (c *GRPCClient) mirrorRemoteControlRejections(ctx context.Context, apply *storage.Apply, remoteID string, settled []*ternv1.SettledControlRequest) {
16731686
if c.storage == nil || apply == nil || len(settled) == 0 {
16741687
return
16751688
}
@@ -1695,13 +1708,21 @@ func (c *GRPCClient) mirrorRemoteControlRejections(ctx context.Context, apply *s
16951708
continue
16961709
}
16971710
if entry.Status != string(storage.ControlRequestFailed) {
1711+
// Only a failure needs mirroring, and completion is handled above. A
1712+
// newer data plane reporting some other terminal status would drop the
1713+
// request here, so name it rather than skipping silently.
1714+
logger.Warn("data plane reported a settled control request in an unrecognized status; it will not reach the operator",
1715+
append(apply.MutableLogAttrs(),
1716+
"operation", entry.Operation,
1717+
"status", entry.Status,
1718+
"settled_at", entry.SettledAt)...)
16981719
continue
16991720
}
17001721
message := remoteControlRejectionMessage(entry)
17011722
changed, err := controlStore.RecordRemoteFailure(ctx, &storage.ApplyControlRequest{
17021723
ApplyID: apply.ID,
17031724
Operation: operation,
1704-
ErrorMessage: apply.OperatorFacingMessage(message),
1725+
ErrorMessage: apply.OperatorFacingMessage(message, remoteID),
17051726
RequestedBy: entry.RequestedBy,
17061727
})
17071728
if err != nil {
@@ -3895,7 +3916,7 @@ func (c *GRPCClient) pollForCompletion(ctx context.Context, apply *storage.Apply
38953916
logger.Info("mirrored remote volume level onto control-plane apply options",
38963917
append(apply.MutableLogAttrs(), "volume", resp.Volume)...)
38973918
}
3898-
c.mirrorRemoteControlRejections(ctx, apply, resp.SettledControlRequests)
3919+
c.mirrorRemoteControlRejections(ctx, apply, remoteID, resp.SettledControlRequests)
38993920

39003921
terminal := isTerminalProtoState(resp.State)
39013922
if terminal {

pkg/tern/grpc_client_test.go

Lines changed: 80 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -570,6 +570,7 @@ type capturingTernServer struct {
570570
progressTables []*ternv1.TableProgress
571571
progressVolume int32
572572
progressError string
573+
progressSettled []*ternv1.SettledControlRequest
573574
progressErr error
574575
startErr error
575576
cancelErr error
@@ -676,6 +677,7 @@ func (s *capturingTernServer) Progress(_ context.Context, req *ternv1.ProgressRe
676677
tables := s.progressTables
677678
volume := s.progressVolume
678679
errorMessage := s.progressError
680+
settled := s.progressSettled
679681
err := s.progressErr
680682
s.mu.Unlock()
681683
if err != nil {
@@ -684,7 +686,13 @@ func (s *capturingTernServer) Progress(_ context.Context, req *ternv1.ProgressRe
684686
if !psSet {
685687
ps = ternv1.State_STATE_COMPLETED
686688
}
687-
return &ternv1.ProgressResponse{State: ps, Tables: tables, Volume: volume, ErrorMessage: errorMessage}, nil
689+
return &ternv1.ProgressResponse{
690+
State: ps,
691+
Tables: tables,
692+
Volume: volume,
693+
ErrorMessage: errorMessage,
694+
SettledControlRequests: settled,
695+
}, nil
688696
}
689697
func (s *capturingTernServer) Logs(context.Context, *ternv1.LogsRequest) (*ternv1.LogsResponse, error) {
690698
return &ternv1.LogsResponse{}, nil
@@ -2242,6 +2250,77 @@ func TestGRPCClient_ProcessPendingCancelControlRequestCompletesWholeApply(t *tes
22422250
assert.Nil(t, cancelReq)
22432251
}
22442252

2253+
// A cancel that reconciles a terminal remote ends the drive, so the regular
2254+
// poll loop never runs again. A control command the data plane settled after
2255+
// the last regular poll — here a volume change its engine refused — reaches the
2256+
// operator only if the cancel path's own progress read mirrors it; otherwise the
2257+
// operator is left believing a command they were told was accepted took effect.
2258+
func TestGRPCClient_CancelPathMirrorsSettledControlRejections(t *testing.T) {
2259+
server := &capturingTernServer{
2260+
progressState: ternv1.State_STATE_CANCELLED,
2261+
progressStateSet: true,
2262+
progressTables: []*ternv1.TableProgress{{
2263+
Namespace: "default",
2264+
TableName: "users",
2265+
Status: state.Task.Cancelled,
2266+
}},
2267+
progressSettled: []*ternv1.SettledControlRequest{{
2268+
Operation: string(storage.ControlOperationVolume),
2269+
Status: string(storage.ControlRequestFailed),
2270+
ErrorMessage: "throttle endpoint returned 404",
2271+
RequestedBy: "cli:alice",
2272+
}},
2273+
}
2274+
client, cleanup := testCapturingGRPCClient(t, server)
2275+
defer cleanup()
2276+
2277+
apply := &storage.Apply{
2278+
ID: 7,
2279+
ApplyIdentifier: "apply-grpc-cancel-mirror",
2280+
ExternalID: "remote-grpc-cancel-mirror",
2281+
PlanID: 99,
2282+
Database: "testdb",
2283+
DatabaseType: storage.DatabaseTypeMySQL,
2284+
Environment: "staging",
2285+
State: state.Apply.Running,
2286+
}
2287+
task := &storage.Task{
2288+
ID: 11,
2289+
TaskIdentifier: "task-users",
2290+
ApplyID: apply.ID,
2291+
Namespace: "default",
2292+
TableName: "users",
2293+
State: state.Task.Running,
2294+
}
2295+
controlRequests := &testControlRequestStore{requests: []*storage.ApplyControlRequest{{
2296+
ApplyID: apply.ID,
2297+
Operation: storage.ControlOperationCancel,
2298+
Status: storage.ControlRequestPending,
2299+
RequestedBy: "cli:alice",
2300+
}}}
2301+
storedApply := *apply
2302+
logs := &mockApplyLogStore{}
2303+
client.storage = &mockStorage{
2304+
applies: &mockApplyStore{apply: &storedApply},
2305+
tasks: &mockTaskStore{tasks: []*storage.Task{task}},
2306+
logs: logs,
2307+
controlRequests: controlRequests,
2308+
}
2309+
2310+
handled, err := client.processPendingCancelControlRequest(t.Context(), apply, wholeApplyTaskScope())
2311+
require.NoError(t, err)
2312+
require.True(t, handled)
2313+
2314+
rejected, err := controlRequests.GetByOperation(t.Context(), apply.ID, storage.ControlOperationVolume)
2315+
require.NoError(t, err)
2316+
require.NotNil(t, rejected, "the rejection the data plane settled must survive the drive that ends here")
2317+
assert.Equal(t, storage.ControlRequestFailed, rejected.Status)
2318+
assert.Contains(t, rejected.ErrorMessage, "throttle endpoint returned 404")
2319+
assert.Equal(t, "cli:alice", rejected.RequestedBy)
2320+
assert.True(t, hasLogMessageContaining(logs.logs, "Volume was accepted but not applied"),
2321+
"the operator must find the rejection on the schema change's log")
2322+
}
2323+
22452324
func TestGRPCClient_ProcessPendingCancelOperationLeavesApplyCancelPending(t *testing.T) {
22462325
// A multi-deployment apply has one durable cancel request shared by every
22472326
// deployment. One operation reaching a terminal remote state must not

pkg/tern/grpc_control_rejection_integration_test.go

Lines changed: 9 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -115,7 +115,7 @@ func TestGRPCClient_MirrorsRemoteControlRejection(t *testing.T) {
115115
Status: string(storage.ControlRequestCompleted),
116116
}}
117117

118-
client.mirrorRemoteControlRejections(ctx, apply, rejection)
118+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, rejection)
119119

120120
stored, err := stor.ControlRequests().GetByOperation(ctx, apply.ID, storage.ControlOperationVolume)
121121
require.NoError(t, err)
@@ -136,7 +136,7 @@ func TestGRPCClient_MirrorsRemoteControlRejection(t *testing.T) {
136136
// The data plane reports the same rejection on every poll until the
137137
// operator retries the operation; mirroring it again must not append a
138138
// second entry.
139-
client.mirrorRemoteControlRejections(ctx, apply, rejection)
139+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, rejection)
140140
logs, err = stor.ApplyLogs().GetByApply(ctx, apply.ID)
141141
require.NoError(t, err)
142142
assert.Equal(t, 1, countLogMessages(logs, "Volume was accepted but not applied"),
@@ -182,7 +182,7 @@ func TestGRPCClient_MirrorLeavesAReissuedCommandPending(t *testing.T) {
182182

183183
// The data plane has not seen the new request yet, so it keeps reporting the
184184
// old one it settled.
185-
client.mirrorRemoteControlRejections(ctx, apply, []*ternv1.SettledControlRequest{{
185+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, []*ternv1.SettledControlRequest{{
186186
Operation: string(storage.ControlOperationCutover),
187187
Status: string(storage.ControlRequestFailed),
188188
ErrorMessage: "cutover was not applied because apply is recovering",
@@ -235,8 +235,8 @@ func TestGRPCClient_MirrorReattributesARejectionToTheOperatorWhoReissuedIt(t *te
235235
}}
236236
}
237237

238-
client.mirrorRemoteControlRejections(ctx, apply, rejection("cli:alice"))
239-
client.mirrorRemoteControlRejections(ctx, apply, rejection("cli:bob"))
238+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, rejection("cli:alice"))
239+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, rejection("cli:bob"))
240240

241241
stored, err := stor.ControlRequests().GetByOperation(ctx, apply.ID, storage.ControlOperationVolume)
242242
require.NoError(t, err)
@@ -272,7 +272,7 @@ func TestGRPCClient_MirrorRetiresARejectionTheDataPlaneLaterCompleted(t *testing
272272
defer cleanup()
273273
client.storage = stor
274274

275-
client.mirrorRemoteControlRejections(ctx, apply, []*ternv1.SettledControlRequest{{
275+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, []*ternv1.SettledControlRequest{{
276276
Operation: string(storage.ControlOperationVolume),
277277
Status: string(storage.ControlRequestFailed),
278278
ErrorMessage: "throttle endpoint returned 404",
@@ -281,7 +281,7 @@ func TestGRPCClient_MirrorRetiresARejectionTheDataPlaneLaterCompleted(t *testing
281281
requireControlRequestStatus(t, stor, apply.ID, storage.ControlOperationVolume, storage.ControlRequestFailed)
282282

283283
// The operator re-issues volume; this time the data plane applies it.
284-
client.mirrorRemoteControlRejections(ctx, apply, []*ternv1.SettledControlRequest{{
284+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, []*ternv1.SettledControlRequest{{
285285
Operation: string(storage.ControlOperationVolume),
286286
Status: string(storage.ControlRequestCompleted),
287287
RequestedBy: "cli:alice",
@@ -359,7 +359,7 @@ func TestGRPCClient_MirrorKeepsTheOperatorNameOnALocallyQueuedRequest(t *testing
359359
failLocallyQueuedControlRequest(t, dsn, stor, apply.ID, storage.ControlOperationCutover,
360360
"octocat", "cutover request was not applied because apply is failed")
361361

362-
client.mirrorRemoteControlRejections(ctx, apply, []*ternv1.SettledControlRequest{{
362+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, []*ternv1.SettledControlRequest{{
363363
Operation: string(storage.ControlOperationCutover),
364364
Status: string(storage.ControlRequestFailed),
365365
ErrorMessage: "deploy request is not in a cutover-ready state",
@@ -403,7 +403,7 @@ func TestGRPCClient_MirrorReattributesToANamedOperator(t *testing.T) {
403403
failLocallyQueuedControlRequest(t, dsn, stor, apply.ID, storage.ControlOperationCutover,
404404
"octocat", "cutover request was not applied because apply is failed")
405405

406-
client.mirrorRemoteControlRejections(ctx, apply, []*ternv1.SettledControlRequest{{
406+
client.mirrorRemoteControlRejections(ctx, apply, apply.ExternalID, []*ternv1.SettledControlRequest{{
407407
Operation: string(storage.ControlOperationCutover),
408408
Status: string(storage.ControlRequestFailed),
409409
ErrorMessage: "deploy request is not in a cutover-ready state",

pkg/tern/local_client_test.go

Lines changed: 30 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -651,6 +651,36 @@ func (s *testControlRequestStore) FailPending(_ context.Context, applyID int64,
651651
return nil
652652
}
653653

654+
// RecordRemoteFailure mirrors the store's contract: a pending row is a live
655+
// request this plane has not forwarded yet, so a settled report describes a
656+
// superseded attempt and is ignored; anything else takes the remote reason.
657+
func (s *testControlRequestStore) RecordRemoteFailure(_ context.Context, req *storage.ApplyControlRequest) (bool, error) {
658+
for _, existing := range s.requests {
659+
if existing.ApplyID != req.ApplyID || existing.Operation != req.Operation {
660+
continue
661+
}
662+
if existing.Status == storage.ControlRequestPending {
663+
return false, nil
664+
}
665+
if existing.Status == storage.ControlRequestFailed &&
666+
existing.ErrorMessage == req.ErrorMessage &&
667+
existing.RequestedBy == req.RequestedBy {
668+
return false, nil
669+
}
670+
existing.Status = storage.ControlRequestFailed
671+
existing.ErrorMessage = req.ErrorMessage
672+
if req.RequestedBy != "" {
673+
existing.RequestedBy = req.RequestedBy
674+
}
675+
return true, nil
676+
}
677+
stored := cloneTestControlRequest(req)
678+
stored.ID = int64(len(s.requests) + 1)
679+
stored.Status = storage.ControlRequestFailed
680+
s.requests = append(s.requests, stored)
681+
return true, nil
682+
}
683+
654684
func cloneTestControlRequest(req *storage.ApplyControlRequest) *storage.ApplyControlRequest {
655685
if req == nil {
656686
return nil

0 commit comments

Comments
 (0)