fix(dc-plan): unblock startup and stop refresh sync amplification - #231
Merged
Merged
Conversation
Start() ran the workspace and dc_plan startup syncs before starting the HTTP listener. A slow Hilbert round therefore blocked readiness, the startup probe killed the container after 180s, the sync transaction rolled back with the sync not committed, and the next attempt repeated exactly the same work forever. Move both startup syncs into the periodic DC plan sync goroutine and start that goroutine after the listener, so convergence can never gate readiness. The goroutine now converges once immediately before entering the ticker loop, which also removes the previous wait of up to one full ticker period after a restart, and it uses the cancellable context so shutdown can interrupt an in-flight sync.
POST /operator/plans/refresh ran a full SyncWorkspace inline before returning the operator's plans. One SyncWorkspace costs O(plan count) transactions: the workstation projector begins a transaction per plan and the Ego Portal pending pool begins another, so a 150-plan workspace cost about 300 transactions and a 583-plan workspace about 1166. With every activated device polling the endpoint, requests amplified 1:1 into full workspace syncs, exhausted the 25-connection pool and produced thousands of deadlocks and lock wait timeouts per minute. Return the current projection instead and leave convergence to the periodic hilbert sync, which already runs every five minutes and repairs missing workstations idempotently. Plans and workstations can now lag by up to one sync period, which the collection workflow accepts. TestRefreshOperatorPlansFallsBackToStaleProjection tested the removed inline path (it asserted stale=true when the inline sync failed), so it is replaced with TestRefreshOperatorPlansDoesNotSyncInline, which fails on the previous behaviour with five syncs for five requests.
Records the indexes that were created by hand while the dc plan sync outage was being handled, so a rebuilt database cannot reproduce it. Without these indexes the planner falls back to single column indexes whose leading column is non selective (status = 'pending', deleted_at IS NULL), so a statement addressing one plan still scans a large index range. With SELECT ... FOR UPDATE InnoDB locks every row it scans, which is how one per plan UPDATE came to hold hundreds of row locks for seconds and how the two sync paths deadlocked. The statements are guarded with information_schema checks because databases patched during the incident already carry these indexes: a plain ADD INDEX would abort the migration, and a failed migration is fatal at startup and leaves schema_migrations_v2 dirty, blocking every later migration. Verified against the production database, where all five indexes already exist, so the up migration is a no-op and exits cleanly.
The workstation projector and the pending pool both lock rows they only read, and they reach those tables in opposite order: pending pool: workstations -> data_collectors -> robots projector: data_collectors -> robots -> workstations InnoDB reported the resulting deadlock as one transaction holding workstations while waiting for data_collectors, and the other holding data_collectors while waiting for workstations. The index added earlier shrank each footprint from hundreds of rows to one or two, which stopped the observed deadlocks, but the ordering conflict is unchanged: any second concurrent sync of the same workspace brings it back. None of the three lookups below writes the table it reads, and the only write that follows is against tasks, so the lock buys nothing. The lock in ensureProjectedWorkstation is kept deliberately. It is the one that matters for correctness: the unique indexes on workstations only cover is_current rows, so the gap lock taken on a missing row is what stops two concurrent projectors from inserting duplicate workstations. The test suite cannot cover this change. Tests run on sqlite and both helpers return an empty clause for sqlite, so FOR UPDATE is never exercised; the change rests on review and on production observation.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Pull Request Checklist
go test ./...)gofmt -l ./clean,golangci-lint run ./...0 issues)Summary
Unblocks
Start()from the Hilbert dc plan sync, stopsPOST /operator/plans/refreshfrom running a full workspace sync per request, and records the composite indexes that the sync relies on.Motivation
On 2026-09-17 the mercury keystone deployment was serving no traffic: the pod was
0/1, the Service had no ready endpoint, and the container restarted every 180 seconds. Four independent defects combined, and each is addressed here.1. A slow startup sync gated readiness.
Start()ransyncWorkspacesOnStartup()andsyncDCPlansOnStartup()before starting the HTTP listener. The sync never finished inside the 180s startup probe, so the container was killed mid-transaction, the sync rolled back, and the next start repeated exactly the same work — a deterministic loop (6 restarts observed).2. The sync was slow because of a missing composite index. The sync issues
once per
collectedplan (514 of them, all inside one transaction).taskshad no usable composite index, so the planner usedindex_merge(intersect(idx_dc_plan, idx_status))and scanned everystatus = 'pending'entry.EXPLAIN ANALYZEmeasuredactual rows = 109053on that branch and 1955 ms for a statement addressing eleven plans. With(dc_plan_id, status, deleted_at)the same statement is a covering index lookup at 0.063 ms.3.
refreshamplified one request into a full workspace sync.RefreshOperatorPlansranSyncWorkspaceinline before returning the plan list, and oneSyncWorkspacecosts O(plan count) transactions because the workstation projector and the pending pool each begin a transaction per plan (ws=12 with 150 plans ≈ 300 transactions; ws=4 with 583 plans ≈ 1166). Every activated device polls this endpoint, so requests amplified 1:1 into full syncs: 74 requests → 69 syncs → ~22,000 transactions in 3 minutes against a 25-connection pool, which produced 476 deadlocks and 5,712context deadline exceededevents in 3 minutes and exhausted the pool.4. Two paths deadlocked on a lock-order cycle.
SHOW ENGINE INNODB STATUSshowed the pending pool path holdingworkstationsand waiting fordata_collectors, while the projector helddata_collectorsand waited forworkstations. Both lock rows they only read. The index in (2) shrank each footprint from hundreds of rows to one or two, which stopped the observed deadlocks, but the ordering conflict was untouched.Changes
Modified Files
[internal/server/server.go](internal/server/server.go)—Start()no longer calls the two startup syncs before the listener;startPeriodicDCPlanSync()now runs them inside its goroutine, immediately before entering the ticker loop.syncDCPlansOnStartup()is deleted. The startup workspace sync now takes a context so shutdown can cancel it.[internal/api/handlers/dc_plan.go](internal/api/handlers/dc_plan.go)—RefreshOperatorPlansreturns the current projection instead of syncing first. The response contract, path, auth and fields are unchanged.[internal/api/handlers/operator_plan_test.go](internal/api/handlers/operator_plan_test.go)—fakeOperatorPlanSyncercounts calls.TestRefreshOperatorPlansFallsBackToStaleProjectiontested the removed inline path and is replaced byTestRefreshOperatorPlansDoesNotSyncInline.[internal/services/dc_plan_workstation_projection.go](internal/services/dc_plan_workstation_projection.go)—resolveProjectionCollectorandresolveProjectionRobotno longer take row locks; both are read-only and the write that follows targetsworkstations.ensureProjectedWorkstationkeeps its lock, with a comment explaining why: the unique indexes onworkstationsonly coveris_currentrows, so the gap lock on a missing row is what prevents two concurrent projectors from inserting duplicate workstations.[internal/services/dc_plan_task_supply.go](internal/services/dc_plan_task_supply.go)—loadTaskSupplyWorkstationno longer takes row locks; it is a read-only lookup whose only write that follows targetstasks, and its three-table join previously locked every scanned row.Added Files
[internal/storage/database/migrations/v2/000023_dc_plan_sync_lookup_indexes.up.sql](internal/storage/database/migrations/v2/000023_dc_plan_sync_lookup_indexes.up.sql)— addstasks(dc_plan_id, status, deleted_at),data_collectors(operator_id, deleted_at),robots(device_id, deleted_at),workstations(workspace_id, deleted_at)andepisodes(deleted_at, dc_plan_id, cloud_synced, qa_status, duration_sec).[internal/storage/database/migrations/v2/000023_dc_plan_sync_lookup_indexes.down.sql](internal/storage/database/migrations/v2/000023_dc_plan_sync_lookup_indexes.down.sql)— drops them.The migration guards every statement with an
information_schemacheck and runs the DDL withALGORITHM=INPLACE, LOCK=NONE. This matters: production already carries all five indexes because they were created by hand while the incident was being handled, and a plainADD INDEXwould abort the migration.cmd/keystone-edge/main.gocallslogger.Fatalfwhen migration fails, and golang-migrate marksschema_migrations_v2dirty before executing, so an aborted migration is fatal at startup and blocks every later migration.Type of Change
Impact Analysis
Breaking Changes
None. No API path, request field or response field changes.
Backward Compatibility
Fully backward compatible for clients. Devices need no changes: ego-portal still calls
POST /operator/plans/refreshon the same schedule and reads the same fields.One behaviour change worth flagging to reviewers: plan and workstation freshness is now bounded by the periodic sync interval (currently 5 minutes) plus the device's own poll interval (60s), instead of being forced on every refresh. This was discussed and accepted.
stalein the response now means "the projection was not synced for this request" and isfalsewhile the sync service is configured; ego-portal reads onlyitems, notstale.Testing
Test Cases
go test ./...)gofmt -l ./clean,go vet ./...cleangolangci-lint run ./...reports 0 issuesTest Coverage
TestRefreshOperatorPlansDoesNotSyncInlineissues five requests against a counting fake and assertsSyncWorkspaceis never called. On the previous code it fails withrefresh must not sync, but SyncWorkspace was called 5 time(s), which is the 1:1 amplification measured in production.Gaps reviewers should know about
modernc.org/sqliteand both*ForUpdateClausehelpers return an empty string for sqlite, soFOR UPDATEis never exercised and sqlite has no deadlock semantics. This change rests on review and production observation.rc=0, all five indexes intact). The branch where the indexes do not exist yet — building them online — has not been exercised on a staging clone.Performance Impact
Measured on the production database during and after the incident-handling index change:
context deadline exceededInnodb_data_readPOST /operator/plans/refreshdrops from seconds (waiting for a full sync) to single-digit millisecondsThe periodic sync still performs O(plan count) transactions (~2,300 per round for 1,822 plans) and takes ~33 seconds per round, of which the database accounts for under 10 seconds and the remainder is the Hilbert HTTP fetch. Batching those transactions is a deliberate follow-up, not part of this PR.
Documentation
Related Issues
Additional Notes
Operational notes for whoever deploys this:
schema_migrations_v2on production is atversion=22, dirty=0, so this migration advances it to 23.POST /api/v1/workspaces/{workspace_id}/dc-plans/sync(admin-only) still exists and is the only manual convergence trigger. It is the fallback if the ticker ever stalls, but it should not be called in a loop:SyncWorkspacestill has no per-workspace mutex.[SERVER] Starting HTTP servershould appear before the[HILBERT-SYNC]lines, and the pod should reach1/1immediately rather than after a 180s probe timeout.innodb_buffer_pool_size, previously reverted to the 128 MB default on restart, has been persisted separately on production withSET PERSIST.Deliberately not included
Kept out to keep this PR focused and independently revertible:
SyncWorkspacePOST /workspaces/:id/dc-plans/syncstill locks the plan row vialoadTaskSupplyPlan; that lock has weak value but is left alone for nowdcPlanAutoSyncIntervalNotes for Reviewers
internal/server/server.go: the two startup syncs moved into the periodic goroutine, so they now run concurrently with request handling instead of before it, and shutdown waits on them. The goroutine closesdonein adefer, soShutdownstill returns; the context passed is cancellable.tasks. The lock inensureProjectedWorkstationmust stay.ADD INDEXplus an operational step, that is a valid alternative — but a failed migration is fatal at startup and leaves the version dirty.Checklist for Reviewers