Skip to content

fix(adapter): a HEALED dirty-schema migration must not republish bd's Error: line while exiting 0 - #75

Merged
Brian Krabach (bkrabach) merged 2 commits into
mainfrom
lane/kxk-healed-migration-stderr
Sep 3, 2026
Merged

fix(adapter): a HEALED dirty-schema migration must not republish bd's Error: line while exiting 0#75
Brian Krabach (bkrabach) merged 2 commits into
mainfrom
lane/kxk-healed-migration-stderr

Conversation

@bkrabach

Copy link
Copy Markdown
Collaborator

Fixes model_performance-kxk (discovered-from model_performance-wp6).

The leak

amplifier-work-tracker doctor --quick detected a dirty dolt schema migration, dropped, retried,
succeeded, printed All 35 assumptions hold and exited 0 — with this on stderr (evidence
committed on main at docs/lanes/wp6-error-regex-scope/evidence/pr70-doctor-quick.run1-transient.stderr.txt):

project 'contract...': bd init hit a dirty schema migration -- dropping and retrying once: [mysql] ... busy buffer
Error: failed to open Dolt store: failed to initialize schema: ... run 'bd dolt commit' to

An error announcement beside exit 0 is exactly the silent-failure shape
tests/_util.assert_no_silent_failure exists to forbid. Since #74 (802c204) that predicate matches
announcement shapes and Error: is the first one, so a run that recovered correctly could fail
any CLI-tier test — intermittently, with a real-looking message.

Root cause — not what the report assumed

bd's stderr is not escaping around us. That Error: line is inside our own logger.warning.
The call interpolated blob.strip()[:300], and blob is bd's multi-line stderr, so line 2 of the
quoted blob became line 2 of our stderr.

Proof from the committed evidence rather than from reasoning: the quoted text spanning those two
lines is exactly 300 characters and stops mid-sentence at run 'bd dolt commit' to — the slice
boundary, not a line bd chose to end.

That finding is what makes this cheap: reproducing the leak never required reproducing the dirty
store
.

The fix

_quote_handled_output(blob) — used only where this module handled and recovered from a
condition:

  1. Flatten to one line. A multi-line quote puts Error: at the start of a line of our stderr,
    which is where it reads as ours.
  2. Attribute instead of assert. Error:[bd Error]. The word survives (greppable), the
    detail survives (diagnostic), only the impersonation ends.

Truncation moves from the bare [:300] slice to the existing truncate_status (word boundary,
explicit ...[truncated] marker) — the same fragment problem that helper already solved.

BEFORE (two lines; line 2 announces):
  project '...': bd init hit a dirty schema migration -- dropping and retrying once: [mysql] ... busy buffer
  Error: failed to open Dolt store: failed to initialize schema: ... run 'bd dolt commit' to

AFTER (one line; attributed):
  project '...': bd init hit a dirty schema migration -- dropping and retrying once: [mysql] ... busy buffer [bd Error] failed to open Dolt store: ... run 'bd dolt ...[truncated]

The recovery stays visible. Going quiet would also satisfy the check and would be the wrong fix.

Applied at both handled call sites in the file: Workspace.create's dirty-schema self-heal (the
reported one) and move_item's best-effort cleanup of a partially-moved item, which quoted a foreign
blob the same way on a path whose caller continues.

Deliberately not merged with _clean_bd_error. That one builds the text of a real failure on its
way to a non-zero exit, which should announce loudly. The failure path is untouched.

Fail-before, deterministic

tests/unit/test_handled_output_is_not_an_announcement.py drives the real Workspace.create
heal path with a scripted bd init — no bd, no dolt, no network. Against the parent commit
(10 failed / 3 passed, docs/lanes/kxk-healed-migration-stderr/evidence/fail-before.txt):

AssertionError: a handled, recovered condition republished an error announcement:
('error-colon', 'Error:') in "project 'kxkheal': bd init hit a dirty schema migration -- dropping
and retrying once: [mysql] 2026/09/03 01:25:03 connection.go:214 busy buffer\nError: failed to open
Dolt store: ... labels; run 'bd dolt commit' to"

The reproduced string ends at the same 300-character cut as the recorded incident. The condition
was observed once and never reproduced; it is now deterministic.

Both directions are pinned

A fix that only proved the healed run is quiet could have been achieved by swallowing everything.
Same file therefore also pins that a genuine double failure still raises, still exits non-zero,
and still carries bd's own announcement — with assert_no_silent_failure correctly not firing there.

tests/_util.py is not touched: wp6's predicate is correct and its own suite
(tests/unit/test_error_announcement_detection.py, 23 tests) stays green, unmodified.

The defusal covers all five shapes in _util._ERROR_ANNOUNCEMENT_RES, not just the observed one.
Product code cannot import a test helper, so the coupling is closed from the test side:
test_every_known_announcement_shape_has_a_sample goes red if a shape is added to the predicate
without a matching defusal sample.

Verification

Tier Command Result
1 — unit make test-unit 846 passed (43.6 s)
2 — integration make test-integration 367 passed, 3 skipped (15 m 55 s)
3 — cli make test-cli 88 passed, 1 failedmodel_performance-jyg, see below
4 — ledger make test-ledger 26 passed; make ledger-mutateproven 15 / 15
5 — modules make test-module 115 passed (6 m 31 s)
lint/types make check ruff clean, pyright 0 errors

The tier-3 failure is model_performance-jyg, verified rather than assumed:
test_doctor_quick_succeeds_against_the_real_installed_bd dies at the earlier
assert result.returncode == 0 because [FAIL] sweeps.alive reports no heartbeat — the isolated
test root has none. It never reaches assert_no_silent_failure. Same command on this branch against
the real workspace root:

  [PASS] sweeps.alive   reap sweep completed 97s ago (threshold 900s); notify sweep completed 117s ago (threshold 900s)
All 37 assumptions hold. Safe to run parallel agents.
--- exit=0 ---

37/37, measured. error_announcement() over that whole captured output returns None.

Not in scope

  • wp6's option (1), the parseable-channel redesign — not implemented and not required here: the
    root cause is our own interpolation, so there is no channel-separation problem to solve. It remains
    an open owner-level output-contract question.
  • No widening of assert_no_silent_failure.

Spend: $0.00 against a $0 authority. Lane note and evidence:
docs/lanes/kxk-healed-migration-stderr/.

… `Error:` line

`doctor --quick` detected a dirty dolt schema migration, dropped, retried,
succeeded, printed `All 35 assumptions hold` and exited 0 -- with this on
stderr (evidence committed on main at
docs/lanes/wp6-error-regex-scope/evidence/pr70-doctor-quick.run1-transient.stderr.txt):

    project 'contract...': bd init hit a dirty schema migration -- dropping
      and retrying once: [mysql] ... busy buffer
    Error: failed to open Dolt store: failed to initialize schema: ...

An error announcement beside exit 0 is exactly the silent-failure shape
`tests/_util.assert_no_silent_failure` exists to forbid, so a run that
recovered CORRECTLY could fail any CLI-tier test, intermittently, with a
real-looking message.

Root cause, and it is not what the report assumed: bd's stderr is not
escaping around us. That `Error:` line is INSIDE our own `logger.warning`.
The call interpolated `blob.strip()[:300]`, and `blob` is multi-line.
Proof from the committed evidence rather than from reasoning -- the quoted
text spanning those two lines is exactly 300 characters and stops
mid-sentence at "run 'bd dolt commit' to", the slice boundary, not bd's
own line ending. We printed it, on a path where nothing ultimately failed.

Fix: `_quote_handled_output`, used ONLY where this module handled and
recovered from a condition. It flattens the blob to one line (a multi-line
quote puts `Error:` at the start of a line of OUR stderr, which is where it
reads as ours) and attributes each announcement to its source rather than
asserting it -- `Error:` becomes `[bd Error]`. The word survives, the
detail survives, only the impersonation ends. Truncation moves from the
bare `[:300]` slice to `truncate_status`, which cuts on a word boundary and
marks itself.

Deliberately NOT merged with `_clean_bd_error`: that one builds the text of
a real failure on its way to a non-zero exit, which SHOULD announce loudly.
The failure path is untouched, and a test pins that bd's own announcement
still reaches stderr there.

Applied at both handled call sites in the file -- the dirty-schema self-heal
in `Workspace.create`, and the best-effort cleanup of a partially-moved item
in `move_item`, which quoted a foreign blob the same way on a path whose
caller continues.

tests/unit/test_handled_output_is_not_an_announcement.py drives the real
`Workspace.create` heal path with a scripted `bd init`, so the condition
that was observed ONCE and never reproduced is now deterministic with no bd,
no dolt and no network. Against the parent commit it fails with
`('error-colon', 'Error:')` and reproduces the recorded stderr byte for
byte, including the 300-character cut. Both directions are in that one file:
a genuine double failure still raises, still exits non-zero, and still
carries bd's announcement.

Does not touch `assert_no_silent_failure`: wp6's predicate is correct and
its own suite stays green (36 passed with this file).

Refs: model_performance-kxk (discovered-from model_performance-wp6)
@bkrabach
Brian Krabach (bkrabach) marked this pull request as ready for review September 3, 2026 12:19
@bkrabach

Copy link
Copy Markdown
Collaborator Author

Manager verification — FIX. Merging. And the item's premise was wrong in a way that made the fix smaller.

Head a5d1c16, base 98dd2233 = current origin/main — no rebase needed, no conflict.

The root cause is not what the item said, and I verified that rather than taking it

The item (and my own goal text) asserted bd's error announcement was "passed straight through to
stderr"
. It was not. The line was OURS. On origin/main:

logger.warning(
    "project %r: bd init hit a dirty schema migration -- dropping and retrying once: %s",
    name, blob.strip()[:300],          # adapter.py — Workspace.create self-heal
)

blob is bd's multi-line stderr, interpolated into our own warning and sliced at 300 chars. The
lane proved it from the committed evidence rather than by inference: the quoted span is exactly 300
characters and stops mid-sentence at run 'bd dolt commit' to — the slice boundary. Consequence:
reproducing the leak never required a dirty dolt store
, which is why the repro is fully
deterministic (tier 1, no bd, no dolt, no network) instead of the once-observed flake the item feared.

A second instance of the same defect class was found in the same file (move_item's best-effort
cleanup, :1300-1305 on main — another foreign blob quoted verbatim on a path whose caller
continues) and is fixed by the same helper.

Fail-before, reproduced against current main

10 failed, 3 passed

Gates

gate result
unit 846 passed
integration 367 passed, 3 skipped (lane-run, 15m55s)
cli 88 passed, 1 failedjyg, pre-existing
ledger 26 passed (+ ledger-mutate 15/15 proven)
modules 115 passed
ruff check / format clean, 158 files
doctor All 37 assumptions hold — MEASURED

wp6's guarantee is not weakened — checked, not assumed: tests/_util.py is untouched, and
test_error_announcement_detection.py is 23 passed. The fix is on the PRODUCT side, exactly as
scoped. No overlap with wp6 (802c204) or #70 (98dd223): the diff touches adapter.py and one
new test file only.

The one cli failure is jyg: it dies at the earlier assert result.returncode == 0 because the
isolated test root has no sweep heartbeat, so it never reaches assert_no_silent_failure. The lane
verified that environmentally — the same command against the real workspace root gives
[PASS] sweeps.alive and All 37 assumptions hold, exit 0.

One thing done right that is easy to miss

_quote_handled_output is applied only to paths this module handled and recovered from, and was
deliberately not merged with _clean_bd_error, which builds real failure text on its way to a
non-zero exit and must still announce loudly. Defusing both would have been the easy over-reach.

wp6's option (1) (parseable-channel redesign) is NOT required for this defect and was correctly
not implemented — there is no channel-separation problem when the offending line is our own. It
remains an open owner-level question.

Squash + --admin (base-branch policy, as with #72/#74/#70).

@bkrabach
Brian Krabach (bkrabach) merged commit 9d61e42 into main Sep 3, 2026
2 checks passed
@bkrabach
Brian Krabach (bkrabach) deleted the lane/kxk-healed-migration-stderr branch September 6, 2026 02:34
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants