Skip to content

postmortem · · 12 min

A skip is a placeholder, not a verdict

Sixty-three thousand records could never import again because the first run to see them wrote 'skipped' into a ledger that treated every row as final. Then a retry re-armed a quarter of a million failed rows behind a phase barrier that had already moved on, and reported success. Two postmortems from one migration engine, and the four-word rule that fixed both.

The migration engine from the previous post has one table at its centre: a ledger with a unique index on (tenant, source, kind, source_id), claimed in the same transaction as every write. That design is right. Two of the details around it were wrong in ways that produced no error, no red test and no log line — just a run that finished green with the wrong data.

This post is the two incidents, what each looked like from the outside, how I found them, and the fixes with their guards. Nothing here is specific to the product; the failure modes belong to any importer with an idempotency ledger and a phased plan.

Incident one: the poisoned ledger

What it looked like

A customer's first full run crashed its contacts and deals phases on a validation bug. The notes and activities phases still ran, and because their parents were missing, every note and every activity was skipped with the reason "not linked to any record". Fair enough — a note with no contact, company or deal to hang on has nowhere to go.

The validation bug was fixed. The next full run imported 125,000 contacts and 67,000 deals cleanly. And wrote zero notes and zero activities.

The run page said:

terminal
Notes       51,972 skipped
Activities   9,955 skipped

That was the tell, though I did not read it as one at first: a clean 100% skip. Not a single failure, not a single import. When every row of a kind takes the same branch, the branch is not judging rows.

What was happening

The original claim was a plain insert on the unique index:

terminal
INSERT INTO migration_records (tenant_id, source, kind, source_id, action, reason, ...)
VALUES (...)
ON CONFLICT (tenant_id, source, kind, source_id) DO NOTHING
RETURNING id

If the insert returned a row, you won the slot and your write committed. If it returned nothing, someone had the slot, and your write rolled back. Simple, and correct for the case it was written for: two workers, or two runs, writing the same row. Exclusivity is the point.

But skip() went through the same path. A skip wrote a claim. From then on the slot belonged to a run that had done nothing with it, and every later attempt — including the one with the parents finally present — found the slot taken, rolled back, and reported the row as skipped again. 63,164 records were permanently blocked with no bug left in the writer.

A skip that claims the slot blocks every later runbeforerun 1: parents missing → skippedledger: skippedrun 2: parents present → conflictstill skipped× 63,164 rowsafterrun 1: parents missing → skippedplaceholderrun 2: takes the slot → importedledger: created

A created or matched row stays exclusive. A skipped row is a placeholder that any later verdict may replace.

How I found it

Not from the log. The run log is capped at 200 entries, and the 200 it kept were from a different phase. What told me was grouping the ledger itself:

terminal
SELECT kind, action, reason, migration_id, count(*)
FROM migration_records
WHERE tenant_id = $1 AND kind IN ('note', 'activity')
GROUP BY 1, 2, 3, 4
ORDER BY 5 DESC;

Every skipped note carried the reason from run one and run one's id, days after run two had "processed" it. The ledger was telling me the truth about the wrong run.

The fix: four words

A skip is a placeholder, not a verdict. In SQL:

terminal
ON CONFLICT (tenant_id, source, kind, source_id) DO UPDATE SET
  migration_id = EXCLUDED.migration_id,
  record_type  = EXCLUDED.record_type,
  record_id    = EXCLUDED.record_id,
  action       = EXCLUDED.action,
  reason       = EXCLUDED.reason,
  created_at   = EXCLUDED.created_at
WHERE migration_records.action = 'skipped'
RETURNING id

A created or matched slot still refuses everything — the WHERE fails, no row is returned, the caller rolls back. A skipped slot is overwritten by whatever comes next. That one clause unblocked all 63,164 records without touching the data; the next notes-and-activities run simply took them over.

My first draft of the fix excluded one case: a skip overwriting a skip, on the theory that two overlapping runs could flip-flop a reason. Two weeks later that exclusion cost me a morning. After a recovery run, every one of 8,000 still-unlinkable activities carried the first run's reason and owner, so the reason they had been skipped today was invisible. Overlapping runs cannot happen — admission control refuses a second live run per workspace — so the latest verdict is the truth, and the clause now reads exactly as above.

The guard

The spec pins all three directions, because loosening any one of them silently is how this comes back:

terminal
it "lets an import take over a slot that was only ever skipped" do
  write_once(migration: earlier, kind: "note", source_id: "29",
             action: "skipped", reason: "not linked to any record")
  note = write_once(migration: later, kind: "note", source_id: "29") { 4471 }
  expect(note).to eq(4471)
  expect(row("note", "29")).to have_attributes(action: "created", migration_id: later.id)
end

it "still refuses to take over a slot that was CREATED — exclusivity is the point" do
  write_once(migration: earlier, kind: "company", source_id: "42") { create_company("Acme") }
  expect(write_once(migration: later, kind: "company", source_id: "42") { create_company("Acme again") }).to be_nil
  expect(Company.where(name: "Acme again")).not_to exist
end

it "lets a later skip refresh the reason and owner, so the ledger reports the latest attempt" do
  write_once(migration: earlier, kind: "note", source_id: "29", action: "skipped", reason: "not linked")
  write_once(migration: later,   kind: "note", source_id: "29", action: "skipped", reason: "empty body")
  expect(row("note", "29")).to have_attributes(reason: "empty body", migration_id: later.id)
end

The vocabulary it forced

Once skipped slots could be taken over, a rerun started reporting numbers like "9,165 activities skipped" — and 1,053 of those were activities that had been imported the day before and were simply already there. A skip means "needs a fresh run"; an existing row needs nothing. So the engine now has four outcomes, not three:

OutcomeMeaningWhat the user should do
importedwritten by this runnothing
already herematched by dedupe, or claimed by an earlier runnothing
skippedcould not be written, with a reasonfix the cause, run again
failedraised, task retryable from its cursorretry

The bar on the run page draws them in that order: good, nothing to do, needs a fresh run, broken.

Incident two: the retry that stranded a quarter of a million rows

What it looked like

A run finished as partial: contacts had failed on the validation bug, and the run page offered "Retry failed". The customer pressed it. The run went back to running, the queue showed no work at all, and a few minutes later the page said "Migration succeeded" — over a stats card still showing 234,856 failed records.

What was happening

Retry re-armed the failed tasks by renaming them pending. Correct. But a failed task keeps the phase it was seeded in, and the barrier only moves forward: a phase closes once nothing in it is pending or running, and a failed task is neither. So by the time the run ended, current_phase was past every phase that had failures — contacts had failed at phase 2 while the run finished at phase 5.

Every path that could pick up work was gated on current_phase: enqueue_pending! targets it, the reaper's refill filters on it, and the advance is fenced on it. Re-armed tasks at phase 2 under a barrier at 5 were unreachable by every enqueue path there was. Nothing ran.

Then the reaper called the advance on the tail phase, which had no pending tasks of its own, so it walked forward into finalize! — where the success check was failed.zero?. It was true. The failures had just been renamed pending.

Re-armed tasks behind the barrierafter retry, before the fixphase 1 donephase 2 · pendingphase 3 donephase 4 donephase 5 donebarrier= 5enqueue looks only at the barrier's phase → finds nothing → reaper advances → finalize sees failed = 0 → "succeeded"after the fixphase 1 donephase 2 · runningphase 3phase 4phase 5the barrier rewinds to the earliest pending phase; the tail phases re-close in order as their tasks are found done

Every enqueue path is gated on the barrier. Re-arming work without moving the barrier strands it.

The fix, in two places

Retry rewinds the barrier to where the work actually is, and the finaliser refuses to declare an outcome while work is still queued:

terminal
def retry_failed!(migration)
  MigrationTask.where(migration_id: migration.id, status: %w[failed cancelled])
               .update_all(status: "pending", last_error: nil, updated_at: Time.current)

  earliest = MigrationTask.where(migration_id: migration.id, status: "pending").minimum(:phase)
  return finalize!(migration) if earliest.nil?

  migration.update_columns(current_phase: earliest, updated_at: Time.current)
  migration.transition!("running", message: "Resuming unfinished batches.")
  enqueue_pending!(migration, earliest)
end

def finalize!(migration)
  tasks = MigrationTask.where(migration_id: migration.id)
  # Refuse to go terminal while anything is still queued — unless the run
  # is being cancelled, where "queued" is exactly what is being abandoned.
  if tasks.where(status: %w[pending running]).exists? && !migration.cancellation_requested?
    earliest = tasks.where(status: %w[pending running]).minimum(:phase)
    migration.update_columns(current_phase: earliest, updated_at: Time.current)
    return enqueue_pending!(migration, earliest)
  end
  failed   = tasks.where(status: "failed").count
  imported = rollup(migration).values.sum { |s| s["imported"].to_i }
  status   = if migration.cancellation_requested? then "cancelled"
             elsif failed.zero?                    then "succeeded"
             elsif imported.positive?              then "partial"
             else                                       "failed"
             end
  migration.update_columns(stats: rollup(migration), api_token: nil)
  migration.transition!(status)
end

The %w[failed cancelled] is the third thing this code learned. Stop marks a run's queued tasks cancelled, and a task mid-flight at that moment finishes as cancelled with its checkpoint intact. Re-arming only failed made a stopped run unresumable: the only way to finish a stopped email phase was a sibling run that re-fetched every deal. Now the same endpoint is Retry on a partial run and Resume on a stopped one, with the same admission check as starting a run, and the UI labels it accordingly with the count of what will actually run.

The guards

Each example fails when its fix is reverted, and I checked that by reverting:

terminal
it "rewinds the barrier to the phase the failed work actually lives in" do
  migration.update_columns(current_phase: 5)
  task(kind: "companies", phase: 1, status: "succeeded")
  task(kind: "contacts",  phase: 2, status: "failed")
  Planner.retry_failed!(migration)
  expect(migration.reload.current_phase).to eq(2)
end

it "refuses to call a run succeeded while work is still queued" do
  task(kind: "contacts", phase: 2, status: "pending")
  Planner.finalize!(migration)
  expect(migration.reload.status).to eq("running")
end

it "re-arms cancelled batches too, so a stopped run resumes where it left off" do
  migration.update_columns(status: "cancelled", current_phase: 5)
  stopped = task(kind: "emails", phase: 5, status: "cancelled")
  Planner.retry_failed!(migration)
  expect(stopped.reload.status).to eq("pending")
  expect(migration.reload.status).to eq("running")
end

The pattern under both incidents

Both bugs were the same shape: a state written for one purpose being read for another. A skip's claim was written to mean "we looked at this" and read to mean "this is taken". A failed task's phase was written to mean "where it was seeded" and read, after re-arming, to mean "where the barrier must be". Neither reader was wrong about the value; each was wrong about what the value promised.

The rule I took from it: when a row can be revisited, decide up front which of its states are final and which are placeholders, write that decision into the constraint (the WHERE in the conflict clause, the guard in the finaliser), and pin each direction with a test that you have watched fail. The ledger was always going to be revisited. I just hadn't said so in SQL.

Working through something like this? I help teams ship AI and cloud systems that hold up, and cost what they should.