Skip to content

Stop recovery adopting workflows this executor is already running - #493

Merged
devhawk merged 4 commits into
mainfrom
fix-flaky-tests
Sep 14, 2026
Merged

devhawk merged 4 commits into
mainfrom
fix-flaky-tests

Conversation

@devhawk

@devhawk devhawk commented Sep 12, 2026

Copy link
Copy Markdown
Collaborator

Fixes #488, fixes #491. Very likely fixes #477 (see caveat below). Fixes #490, which is unrelated to the rest.

One defect behind three reports

#477, #488 and #491 are the same bug: the launch-time recovery sweep adopting a workflow that this process started microseconds earlier, and running its body a second time.

start() bounds the sweep with withEndTime(Instant.now()), read at the end of launch, and the filter is created_at <= endTime at millisecond granularity. There is nothing between that read and the caller's first startWorkflow, so the two land in the same millisecond and the just-inserted row is <= the cutoff. From the #488 job:

20:35:25.577  DBOS Executor started
20:35:25.577  startWorkflow ... insertWorkflowStatus outcome-ownership-failed-deleted-...
20:35:25.579  executeWorkflow task throwingWorkflow ...        <- run A (the test's)
20:35:25.580  recoverWorkflow execute outcome-ownership-...
20:35:25.581  insertWorkflowStatus outcome-ownership-...       <- row re-inserted
20:35:25.583  executeWorkflow task throwingWorkflow ...        <- run B (recovery's)
20:35:25.583  updateWorkflowOutcome ... status ERROR           <- run A
20:35:25.584  updateWorkflowOutcome ... status ERROR           <- run B

Both copies run to completion and race to record the outcome. What each test noticed differed:

ActiveWorkflowGuard does not stop this. It is released just before the terminal outcome write, so a recovery landing in that window acquires the ID and re-runs the body.

The change

The sweep's cutoff moves to the top of start(), before the isRunning gate. Everything start() goes on to do — the app-version hash over every registered workflow, the executor service, migrations, queue and scheduler start, listener callbacks — now lands between the read and the earliest a caller can start a workflow.

The one-millisecond step-back stays, doing a different job: placement buys margin, the step-back makes the bound exclusive. created_at is written from System.currentTimeMillis() (the same clock this reads), so <= cutoff - 1ms is exactly < cutoff on a millisecond-granular column. Without it a start() that finishes inside a millisecond — already-migrated database, no queues, no listeners — reopens the same hole.

recoverWorkflow skips a workflow whose ID is active on this executor. recoverPendingWorkflows(), the Conductor/AdminServer entry point, carries no time bound at all, so this is the only thing standing between an operator-triggered recovery and a duplicate execution.

What this does not fix

The launch path is now closed deterministically: the sweep can only see workflows created strictly before this process started, and none of those is running in it.

The operator-triggered path is narrowed, not closed. The active-ID check is a sample, not a lock, and during the ActiveWorkflowGuard release window the ID is absent from the map — so a recovery landing exactly there still passes the check. Closing that means changing the release-before-write ordering, which is the invariant CancelResumeRaceTest exists to pin down, and is a design call rather than a flaky-test fix. Left alone deliberately.

Separately: #490

DBOSExecutorTest.sleep asserted a 2s sleep returns within 2400ms. That measures the round trip around the sleep — launch, checkpoint, poll, resume, outcome write — not the sleep, so it reddens on whichever job is slowest. Widened to a bound only a repeated sleep could break, the same correction #482 made to ChaosTest and the queue tests, which missed this one.

Testing

RecoveryServiceTest.recoveryLeavesAWorkflowThisExecutorIsRunningAlone drives recovery directly, since the millisecond collision that produced these failures is not something a test can schedule. Confirmed it fails without the recoverWorkflow guard — recovery re-inserts the deleted row — and passes with it.

33 tests pass across RecoveryServiceTest, WorkflowOutcomeOwnershipTest, AsyncWorkflowTest, CancelResumeRaceTest and DBOSExecutorTest; spotlessCheck, compileTestJava and javadoc clean.

I have left #477 for CI to confirm rather than closing it on reasoning: its original run logs have expired, so the link to this root cause is inferred from the test's shape (setUp() launches, runCancelAndPark() starts a workflow immediately) rather than observed. Worth a few green runs before trusting it.

🤖 Generated with Claude Code

Two flaky tests (#477, #488) and a duplicate execution (#491) trace back to one
defect: the launch-time recovery sweep adopting a workflow that this process
started microseconds earlier.

The sweep's query is bounded with `withEndTime(Instant.now())`, which filters
`created_at <= endTime` at millisecond granularity. `launch()` returns inside
the same millisecond that the first workflow can be started in, so an inclusive
bound lets the sweep see it. CI caught it twice with the two events landing in
the same logged millisecond:

    20:35:25.577 DBOS Executor started
    20:35:25.577 startWorkflow ... insertWorkflowStatus outcome-ownership-...
    20:35:25.580 recoverWorkflow execute outcome-ownership-...
    20:35:25.581 insertWorkflowStatus outcome-ownership-...     <- row re-inserted
    20:35:25.583 executeWorkflow task ...                       <- body runs again

Both copies then run to completion and race to record the outcome. In
WorkflowOutcomeOwnershipTest the re-insert also resurrects the row the test
deleted, so the live run's error write matches after all and it reports its own
failure instead of failing fast -- which is what #488 saw. In AsyncWorkflowTest
the workflow body simply executes twice (#491). #477 is the same shape, an
extra run counted, though its CI logs have since expired.

Two changes:

- The launch sweep's cutoff steps back a millisecond, so it can only see
  workflows that genuinely predate this process. Anything started from launch
  onwards is being run by a live execution and is not orphaned, however PENDING
  its row looks.

- recoverWorkflow skips a workflow whose ID is active on this executor.
  ActiveWorkflowGuard already rejects a duplicate dispatch, but it is released
  just before the terminal outcome write, so a recovery landing in that window
  acquires the ID and runs the body again. recoverPendingWorkflows carries no
  time bound at all, so this is also what stands between an operator-triggered
  recovery and a duplicate execution.

Separately, and unrelated to the above: DBOSExecutorTest.sleep (#490) asserted
a 2s sleep returns within 2400ms, which measures
the round trip around the sleep rather than the sleep, and goes red on whichever
job is slowest. Widened to a bound only a repeated sleep could break -- the same
correction #482 made to ChaosTest and the queue tests, which missed this one.

The regression test drives recovery directly, since the millisecond collision
that produced these failures is not something a test can schedule. It fails
without the recoverWorkflow guard, with recovery re-inserting the deleted row.
Comment thread transact/src/main/java/dev/dbos/transact/execution/DBOSExecutor.java Outdated

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Changes recommended

One or more issues must be addressed before approval.

Get a fresh assessment by requesting another Copilot review.

Pull request overview

Moves launch recovery cutoff before executor startup and skips active in-process workflows; also relaxes the sleep timing test.

Changes:

  • Prevents startup recovery from adopting newly created workflows.
  • Adds an active-workflow recovery guard and regression test.
  • Replaces the overly strict sleep timing bound.
File summaries
File Description
transact/src/test/java/dev/dbos/transact/execution/RecoveryServiceTest.java Updated as part of this pull request.
transact/src/test/java/dev/dbos/transact/execution/DBOSExecutorTest.java Updated as part of this pull request.
transact/src/main/java/dev/dbos/transact/execution/DBOSExecutor.java Updated as part of this pull request.
Review details

Suppressed comments (2)

transact/src/main/java/dev/dbos/transact/execution/DBOSExecutor.java:1220

  • An active entry guarantees this workflow already inserted a row, so this branch should use the same fail-if-missing behavior as the adoption path. If recovery races deletion (as this test does), retrieveWorkflow returns a polling handle with failIfMissing=false, so getResult() waits forever for a row that recovery deliberately did not recreate instead of reporting DBOSNonExistentWorkflowException. Return a fail-if-missing handle here.
      return retrieveWorkflow(workflowId);

transact/src/main/java/dev/dbos/transact/execution/DBOSExecutor.java:1220

  • This is only a sample check, not an ownership handoff. ActiveWorkflowGuard.release() removes the ID before the terminal outcome write, so recovery arriving in that interval sees no entry, re-inserts/executes the workflow, and can still duplicate its side effects. Since recoverPendingWorkflows has no cutoff, this path still violates the no-duplicate guarantee; recovery must coordinate with outcome ownership or the active entry must cover that window.
    if (activeWorkflows.containsKey(workflowId)) {
      logger.debug("recoverWorkflow skip active {}", workflowId);
      return retrieveWorkflow(workflowId);
  • Files reviewed: 3/3 changed files
  • Comments generated: 3
  • Review effort level: Lite

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread transact/src/test/java/dev/dbos/transact/execution/RecoveryServiceTest.java Outdated
The active-workflow check landed ahead of the queue branch, so recovering a
queued workflow running on this executor returned before clearQueueAssignment.
The row stayed PENDING instead of going back to ENQUEUED, and the concurrency
slot the execution held was never freed -- StaticQueuesTest and
DynamicQueuesTest testQueueConcurrencyUnderRecovery both failed on it across
every CI job.

Releasing the assignment is owed whether or not the workflow is live here, so
it goes first; the active check now suppresses only the re-execution below it.

The handle it returns is fail-if-missing. An active entry means this executor
inserted the row, so a row deleted since is gone for good: getResult() should
surface DBOSNonExistentWorkflowException rather than poll for one recovery
deliberately did not put back.

Also corrects the new test's rationale. It described recovery re-inserting the
deleted row, which cannot happen -- executeWorkflowById reads the status and
throws on null well before persistWorkflow. The test still fails without the
guard, just by that throw rather than by observing a second execution.
3c829bf moved the active-workflow guard below the queue branch so that
recovering a queued workflow running on this executor would still release its
assignment. That reintroduces the duplicate execution the guard exists to
prevent, in a worse form: clearQueueAssignment flips the live row back to
ENQUEUED and returns before the guard is ever consulted, so a second runner is
admitted by the next dequeue while the first is still going. When the first
execution finishes, recordWorkflowOutput finds the row no longer PENDING, its
result is discarded, and the workflow parks waiting for the duplicate's outcome.

The premise behind that move -- that the assignment had to be released to free a
leaked concurrency slot -- does not hold. An activeWorkflows entry means the
execution is live here, so the slot is not leaked, it is in use, and it is
released when the workflow completes. Recovery's job is to adopt orphans; a
workflow this executor is still running is not one, and the correct handling is
to leave its row entirely alone.

Both testQueueConcurrencyUnderRecovery tests asserted the old behaviour
(recovering wf1/wf2 sets them back to ENQUEUED while they are still blocked),
which is the assertion that drove the reordering. They now expect the live rows
to stay PENDING. Each also gained a closing counter assertion: only
blockedWorkflow increments it, so the count still being 2 after all three
workflows finish is a direct check that recovery started no second execution.
@devhawk
devhawk merged commit b3af7fa into main Sep 14, 2026
12 checks passed
@devhawk
devhawk deleted the fix-flaky-tests branch September 14, 2026 21:53
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

4 participants