From f9823452aaa3ae3646ad5df662b88a77fa938a07 Mon Sep 17 00:00:00 2001 From: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> Date: Thu, 3 Sep 2026 04:22:16 -0700 Subject: [PATCH 1/2] fix(adapter): a HEALED dirty-schema migration must not republish bd's `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) --- .../evidence/fail-after.txt | 49 +++ .../evidence/fail-before.txt | 211 ++++++++++++ src/amplifier_work_tracker/adapter.py | 95 ++++- ...t_handled_output_is_not_an_announcement.py | 326 ++++++++++++++++++ 4 files changed, 679 insertions(+), 2 deletions(-) create mode 100644 docs/lanes/kxk-healed-migration-stderr/evidence/fail-after.txt create mode 100644 docs/lanes/kxk-healed-migration-stderr/evidence/fail-before.txt create mode 100644 tests/unit/test_handled_output_is_not_an_announcement.py diff --git a/docs/lanes/kxk-healed-migration-stderr/evidence/fail-after.txt b/docs/lanes/kxk-healed-migration-stderr/evidence/fail-after.txt new file mode 100644 index 0000000..802d976 --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/evidence/fail-after.txt @@ -0,0 +1,49 @@ +=== AFTER the fix: the new file + wp6's own file === +2026-09-03T11:21:54Z +============================= test session starts ============================== +platform linux -- Python 3.12.13, pytest-9.1.1, pluggy-1.6.0 -- /home/bkrabach/dev/hw-model-performance/lanes/kxk-healed-migration-stderr/amplifier-work-tracker/.venv/bin/python +cachedir: .pytest_cache +rootdir: /home/bkrabach/dev/hw-model-performance/lanes/kxk-healed-migration-stderr/amplifier-work-tracker +configfile: pyproject.toml +plugins: anyio-4.15.0, asyncio-1.4.0, amplifier-core-1.6.1 +asyncio: mode=Mode.STRICT, debug=False, asyncio_default_fixture_loop_scope=None, asyncio_default_test_loop_scope=function +collecting ... collected 36 items + +tests/unit/test_handled_output_is_not_an_announcement.py::test_a_healed_dirty_migration_leaves_no_error_announcement PASSED [ 2%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_the_healed_warning_is_a_single_line PASSED [ 5%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_a_migration_that_really_fails_still_raises PASSED [ 8%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_a_migration_that_really_fails_exits_non_zero_and_announces PASSED [ 11%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_every_known_announcement_shape_has_a_sample PASSED [ 13%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[error-colon] PASSED [ 16%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[error-running] PASSED [ 19%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[json-error-field] PASSED [ 22%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[python-traceback] PASSED [ 25%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[unknown-command] PASSED [ 27%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_keeps_the_detail_readable PASSED [ 30%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_reports_emptiness_rather_than_nothing PASSED [ 33%] +tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_truncates_at_a_word_boundary PASSED [ 36%] +tests/unit/test_error_announcement_detection.py::test_pr70_description_is_prose_not_an_announcement PASSED [ 38%] +tests/unit/test_error_announcement_detection.py::test_healthy_doctor_run_carrying_pr70s_description_is_not_a_silent_failure PASSED [ 41%] +tests/unit/test_error_announcement_detection.py::test_mentioning_errors_is_not_announcing_one[Write conflicts surface as retryable serialization errors] PASSED [ 44%] +tests/unit/test_error_announcement_detection.py::test_mentioning_errors_is_not_announcing_one[reports UNAVAILABLE (not ERROR) per project] PASSED [ 47%] +tests/unit/test_error_announcement_detection.py::test_mentioning_errors_is_not_announcing_one[an infrastructure read failure raises BeadsUnavailableError] PASSED [ 50%] +tests/unit/test_error_announcement_detection.py::test_mentioning_errors_is_not_announcing_one[this command never reports an error it did not observe] PASSED [ 52%] +tests/unit/test_error_announcement_detection.py::test_mentioning_errors_is_not_announcing_one[ERROR and UNAVAILABLE are different readings of the same field] PASSED [ 55%] +tests/unit/test_error_announcement_detection.py::test_mentioning_errors_is_not_announcing_one[{"ok": true, "error": null}] PASSED [ 58%] +tests/unit/test_error_announcement_detection.py::test_mentioning_errors_is_not_announcing_one[{"ok": true, "error": ""}] PASSED [ 61%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[Error: unknown command "reclaim"] PASSED [ 63%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[reaping stale holds...\nError: unknown command "reclaim"\n] PASSED [ 66%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[ brokenqueue TOTAL - READY - HELD - ERROR: database unreachable] PASSED [ 69%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[ERROR: tokens file not found: /etc/awt/tokens.json] PASSED [ 72%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[amplifier-work-tracker: error: unrecognized arguments: --nope] PASSED [ 75%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[internal error: connection reset by peer] PASSED [ 77%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[{"custody": {"error": "dolt: connection refused"}}] PASSED [ 80%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[error running bd list --json] PASSED [ 83%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[unknown command "reclaim" for "bd"] PASSED [ 86%] +tests/unit/test_error_announcement_detection.py::test_real_error_announcements_are_still_caught[Traceback (most recent call last):\n File "cli.py", line 1\n] PASSED [ 88%] +tests/unit/test_error_announcement_detection.py::test_the_shipped_reap_bug_still_fails_the_assertion PASSED [ 91%] +tests/unit/test_error_announcement_detection.py::test_an_announced_error_with_a_nonzero_exit_is_fine PASSED [ 94%] +tests/unit/test_error_announcement_detection.py::test_announcements_are_found_across_the_stdout_stderr_seam PASSED [ 97%] +tests/unit/test_error_announcement_detection.py::test_the_failure_message_names_which_shape_fired PASSED [100%] + +============================== 36 passed in 0.21s ============================== diff --git a/docs/lanes/kxk-healed-migration-stderr/evidence/fail-before.txt b/docs/lanes/kxk-healed-migration-stderr/evidence/fail-before.txt new file mode 100644 index 0000000..361e507 --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/evidence/fail-before.txt @@ -0,0 +1,211 @@ +FF...FFFFFFFF [100%] +=================================== FAILURES =================================== +__________ test_a_healed_dirty_migration_leaves_no_error_announcement __________ + +scripted = ._make at 0xea4f3e65d3a0> +caplog = <_pytest.logging.LogCaptureFixture object at 0xea4f3e83acf0> + + def test_a_healed_dirty_migration_leaves_no_error_announcement(scripted, caplog): + """The reproduction, and the fix, in one test. + + Against the parent commit this FAILS at the `error_announcement` + assertion with `shape=error-colon matched='Error:'` -- the recorded leak, + on demand. + """ + caplog.set_level(logging.WARNING, logger="amplifier_work_tracker.adapter") + ws, run = scripted((1, OBSERVED_BD_BLOB), (0, "")) + + path = ws.create(PROJECT) + + # The heal actually happened -- otherwise this test proves nothing about + # the heal path. + assert run.init_calls == 2, f"expected a retry after the dirty migration, got {run.calls}" + assert path.name == PROJECT + + stderr = _stderr_of(caplog) + + # 1. The recovery stays VISIBLE. Going quiet would also pass the check + # below, and would be the wrong fix. + assert "dropping and retrying once" in stderr + assert "dirty schema migration" in stderr + + # 2. bd's detail survives, so the line is still diagnostic. + assert "busy buffer" in stderr + assert "failed to open Dolt store" in stderr + + # 3. ... but it no longer ANNOUNCES. This is the whole item. +> assert _util.error_announcement(stderr) is None, ( + "a handled, recovered condition republished an error announcement: " + f"{_util.error_announcement(stderr)!r} in {stderr!r}" + ) +E 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: failed to initialize schema: schema migration: pending schema migrations alter pre-existing dirty tables: comments, compaction_snapshots, dependencies, events, issue_snapshots, labels; run 'bd dolt commit' to" +E assert ('error-colon', 'Error:') is None +E + where ('error-colon', 'Error:') = ("project 'kxkheal': bd init hit a dirty schema migration -- dropping and retrying once: [mysql] 2026/09/03 01:25:03 co...g dirty tables: comments, compaction_snapshots, dependencies, events, issue_snapshots, labels; run 'bd dolt commit' to") +E + where = _util.error_announcement + +tests/unit/test_handled_output_is_not_an_announcement.py:184: AssertionError +---------------------------- Captured stdout setup ----------------------------- +Starting server with Config HP="127.0.0.1:36673"|T="28800000"|R="false"|L="info" +---------------------------- Captured stderr setup ----------------------------- +time="2026-09-03T04:20:50-07:00" level=info msg="Creating root@localhost superuser" +time="2026-09-03T04:20:50-07:00" level=info msg="Server ready. Accepting connections." +time="2026-09-03T04:20:50-07:00" level=warning msg="secure_file_priv is set to \"\", which is insecure." +time="2026-09-03T04:20:50-07:00" level=warning msg="Any user with GRANT FILE privileges will be able to read any file which the sql-server process can read." +time="2026-09-03T04:20:50-07:00" level=warning msg="Please consider restarting the server with secure_file_priv set to a safe (or non-existent) directory." +time="2026-09-03T04:20:50-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=1 +time="2026-09-03T04:20:50-07:00" level=info msg=ConnectionClosed connectionID=1 +----------------------------- Captured stderr call ----------------------------- +time="2026-09-03T04:20:50-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2 +time="2026-09-03T04:20:50-07:00" level=info msg=ConnectionClosed connectionID=2 +------------------------------ Captured log call ------------------------------- +WARNING amplifier_work_tracker.adapter:adapter.py:4794 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 +Error: failed to open Dolt store: failed to initialize schema: schema migration: pending schema migrations alter pre-existing dirty tables: comments, compaction_snapshots, dependencies, events, issue_snapshots, labels; run 'bd dolt commit' to +___________________ test_the_healed_warning_is_a_single_line ___________________ + +scripted = ._make at 0xea4f3e63ea20> +caplog = <_pytest.logging.LogCaptureFixture object at 0xea4f3e83c0e0> + + def test_the_healed_warning_is_a_single_line(scripted, caplog): + """A quoted multi-line blob is half the illusion: it puts bd's `Error:` + at the START of a line of our stderr, which is where a reader (and a + log scraper) reads it as ours. One record, one line.""" + caplog.set_level(logging.WARNING, logger="amplifier_work_tracker.adapter") + ws, _ = scripted((1, OBSERVED_BD_BLOB), (0, "")) + ws.create(PROJECT) + + heal_lines = [r.getMessage() for r in caplog.records if "dirty schema migration" in r.getMessage()] + assert len(heal_lines) == 1 +> assert "\n" not in heal_lines[0] +E assert '\n' not in "project 'kx...t commit' to" +E +E '\n' is contained here: +E usy buffer +E Error: failed to open Dolt store: failed to initialize schema: schema migration: pending schema migrations alter pre-existing dirty tables: comments, compaction_snapshots, dependencies, events, issue_snapshots, labels; run 'bd dolt commit' to + +tests/unit/test_handled_output_is_not_an_announcement.py:206: AssertionError +----------------------------- Captured stderr call ----------------------------- +time="2026-09-03T04:20:50-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=3 +time="2026-09-03T04:20:50-07:00" level=info msg=ConnectionClosed connectionID=3 +------------------------------ Captured log call ------------------------------- +WARNING amplifier_work_tracker.adapter:adapter.py:4794 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 +Error: failed to open Dolt store: failed to initialize schema: schema migration: pending schema migrations alter pre-existing dirty tables: comments, compaction_snapshots, dependencies, events, issue_snapshots, labels; run 'bd dolt commit' to +__________ test_quote_handled_output_defuses_every_shape[error-colon] __________ + +shape = 'error-colon' + + @pytest.mark.parametrize("shape", sorted(SHAPE_SAMPLES)) + def test_quote_handled_output_defuses_every_shape(shape): + sample = SHAPE_SAMPLES[shape] + # The sample really is an announcement before the treatment -- otherwise + # this test could pass against a function that does nothing at all. + assert _util.error_announcement(sample) is not None, shape +> quoted = A._quote_handled_output(sample) + ^^^^^^^^^^^^^^^^^^^^^^^ +E AttributeError: module 'amplifier_work_tracker.adapter' has no attribute '_quote_handled_output' + +tests/unit/test_handled_output_is_not_an_announcement.py:298: AttributeError +_________ test_quote_handled_output_defuses_every_shape[error-running] _________ + +shape = 'error-running' + + @pytest.mark.parametrize("shape", sorted(SHAPE_SAMPLES)) + def test_quote_handled_output_defuses_every_shape(shape): + sample = SHAPE_SAMPLES[shape] + # The sample really is an announcement before the treatment -- otherwise + # this test could pass against a function that does nothing at all. + assert _util.error_announcement(sample) is not None, shape +> quoted = A._quote_handled_output(sample) + ^^^^^^^^^^^^^^^^^^^^^^^ +E AttributeError: module 'amplifier_work_tracker.adapter' has no attribute '_quote_handled_output' + +tests/unit/test_handled_output_is_not_an_announcement.py:298: AttributeError +_______ test_quote_handled_output_defuses_every_shape[json-error-field] ________ + +shape = 'json-error-field' + + @pytest.mark.parametrize("shape", sorted(SHAPE_SAMPLES)) + def test_quote_handled_output_defuses_every_shape(shape): + sample = SHAPE_SAMPLES[shape] + # The sample really is an announcement before the treatment -- otherwise + # this test could pass against a function that does nothing at all. + assert _util.error_announcement(sample) is not None, shape +> quoted = A._quote_handled_output(sample) + ^^^^^^^^^^^^^^^^^^^^^^^ +E AttributeError: module 'amplifier_work_tracker.adapter' has no attribute '_quote_handled_output' + +tests/unit/test_handled_output_is_not_an_announcement.py:298: AttributeError +_______ test_quote_handled_output_defuses_every_shape[python-traceback] ________ + +shape = 'python-traceback' + + @pytest.mark.parametrize("shape", sorted(SHAPE_SAMPLES)) + def test_quote_handled_output_defuses_every_shape(shape): + sample = SHAPE_SAMPLES[shape] + # The sample really is an announcement before the treatment -- otherwise + # this test could pass against a function that does nothing at all. + assert _util.error_announcement(sample) is not None, shape +> quoted = A._quote_handled_output(sample) + ^^^^^^^^^^^^^^^^^^^^^^^ +E AttributeError: module 'amplifier_work_tracker.adapter' has no attribute '_quote_handled_output' + +tests/unit/test_handled_output_is_not_an_announcement.py:298: AttributeError +________ test_quote_handled_output_defuses_every_shape[unknown-command] ________ + +shape = 'unknown-command' + + @pytest.mark.parametrize("shape", sorted(SHAPE_SAMPLES)) + def test_quote_handled_output_defuses_every_shape(shape): + sample = SHAPE_SAMPLES[shape] + # The sample really is an announcement before the treatment -- otherwise + # this test could pass against a function that does nothing at all. + assert _util.error_announcement(sample) is not None, shape +> quoted = A._quote_handled_output(sample) + ^^^^^^^^^^^^^^^^^^^^^^^ +E AttributeError: module 'amplifier_work_tracker.adapter' has no attribute '_quote_handled_output' + +tests/unit/test_handled_output_is_not_an_announcement.py:298: AttributeError +_____________ test_quote_handled_output_keeps_the_detail_readable ______________ + + def test_quote_handled_output_keeps_the_detail_readable(): + """Defusing is not redacting. The words a human would grep for survive.""" +> quoted = A._quote_handled_output(OBSERVED_BD_BLOB) + ^^^^^^^^^^^^^^^^^^^^^^^ +E AttributeError: module 'amplifier_work_tracker.adapter' has no attribute '_quote_handled_output' + +tests/unit/test_handled_output_is_not_an_announcement.py:304: AttributeError +_______ test_quote_handled_output_reports_emptiness_rather_than_nothing ________ + + def test_quote_handled_output_reports_emptiness_rather_than_nothing(): +> assert A._quote_handled_output("") == "(bd reported no detail)" + ^^^^^^^^^^^^^^^^^^^^^^^ +E AttributeError: module 'amplifier_work_tracker.adapter' has no attribute '_quote_handled_output' + +tests/unit/test_handled_output_is_not_an_announcement.py:313: AttributeError +____________ test_quote_handled_output_truncates_at_a_word_boundary ____________ + + def test_quote_handled_output_truncates_at_a_word_boundary(): + """The old `[:300]` slice cut mid-sentence ("run 'bd dolt commit' to"), + which is exactly the fragment problem `truncate_status` already solved.""" +> quoted = A._quote_handled_output("word " * 200) + ^^^^^^^^^^^^^^^^^^^^^^^ +E AttributeError: module 'amplifier_work_tracker.adapter' has no attribute '_quote_handled_output' + +tests/unit/test_handled_output_is_not_an_announcement.py:321: AttributeError +--------------------------- Captured stderr teardown --------------------------- +time="2026-09-03T04:20:51-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=6 +time="2026-09-03T04:20:51-07:00" level=info msg=ConnectionClosed connectionID=6 +time="2026-09-03T04:20:51-07:00" level=info msg="Server closing listener. No longer accepting connections." +time="2026-09-03T04:20:51-07:00" level=info msg="stats stopped: context canceled" +=========================== short test summary info ============================ +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_a_healed_dirty_migration_leaves_no_error_announcement +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_the_healed_warning_is_a_single_line +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[error-colon] +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[error-running] +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[json-error-field] +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[python-traceback] +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_defuses_every_shape[unknown-command] +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_keeps_the_detail_readable +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_reports_emptiness_rather_than_nothing +FAILED tests/unit/test_handled_output_is_not_an_announcement.py::test_quote_handled_output_truncates_at_a_word_boundary +10 failed, 3 passed in 0.27s +exit=1 diff --git a/src/amplifier_work_tracker/adapter.py b/src/amplifier_work_tracker/adapter.py index 8e0514f..430220f 100644 --- a/src/amplifier_work_tracker/adapter.py +++ b/src/amplifier_work_tracker/adapter.py @@ -1298,11 +1298,15 @@ def _delete_item_rows_best_effort( env=_bd_env(), # non-interactive: see `_bd_env`'s docstring ) if p.returncode != 0: + # Same reasoning as the dirty-schema heal in `Workspace.create`: the + # caller's operation continues, so this warning must describe the + # failed cleanup rather than republish dolt's announcement onto a + # stderr that will accompany exit 0. logger.warning( "best-effort cleanup of partially-moved item %r in %r failed: %s", item_id, db, - (p.stderr or p.stdout or "").strip()[:300], + _quote_handled_output(p.stderr or p.stdout), ) @@ -2243,6 +2247,88 @@ def _clean_bd_error(blob: str | None, *, limit: int = STATUS_ERROR_MAX) -> str: return truncate_status(raw, limit) +# -------------------------------------------------------------------------- +# Quoting foreign output on a HANDLED path. +# +# `logger.warning` and above reach a plain CLI invocation's stderr with no +# handler configured at all -- Python's "handler of last resort", the same +# mechanism `_clean_bd_error` documents above. So a warning that interpolates +# a subprocess's stderr verbatim republishes THAT program's error +# ANNOUNCEMENT as if it were this command's own. +# +# Measured, `model_performance-kxk`: `doctor --quick` detected a dirty schema +# migration, dropped, retried, succeeded, printed `All 35 assumptions hold` +# and exited 0 -- with this on stderr: +# +# 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: ... +# +# That second line is NOT bd's stderr escaping around us. It is inside our +# own warning: `blob.strip()[:300]` is a MULTI-LINE blob, and the quoted text +# in the recorded evidence is exactly 300 characters long -- it stops +# mid-sentence at "run 'bd dolt commit' to", the slice boundary. We printed +# it, on a path where nothing ultimately failed. +# +# From outside, an error announcement alongside exit 0 is indistinguishable +# from the silent-failure shape `tests/_util.assert_no_silent_failure` exists +# to forbid, so a HEALED run can fail a CLI-tier test intermittently, with a +# real-looking message. That is the worst kind of flake. +# +# The fix is NOT to go quiet. The recovery must stay visible and the cause is +# worth reading. It is to quote bd's text as DESCRIPTION rather than +# republish it as ANNOUNCEMENT -- the exact distinction `model_performance-wp6` +# drew (802c204) when it stopped the predicate matching prose. Two narrow +# transformations: +# +# 1. Flatten to one line. A multi-line quoted blob puts `Error:` at the +# start of a line of OUR stderr, which is precisely where it reads as +# ours rather than as quoted material. +# 2. Attribute each announcement to bd instead of asserting it: `Error:` +# becomes `[bd Error]`. The word survives (still greppable), the detail +# survives (still readable); only the impersonation ends. +# +# The rules below deliberately cover EVERY shape in +# `tests/_util._ERROR_ANNOUNCEMENT_RES`, not just the one observed -- a +# handled path must not republish any of them. Product code cannot import a +# test helper, so `tests/unit/test_handled_output_is_not_an_announcement.py` +# closes the loop from the other side: it runs the real test-side predicate +# over this function's output, and goes red if a shape is ever added there +# without being defused here. +# -------------------------------------------------------------------------- +_HANDLED_OUTPUT_DEFUSALS: tuple[tuple[re.Pattern[str], str], ...] = ( + # JSON error field first: `"error":` must not be reshaped by the + # colon-announcement rule below, which would leave the JSON key mangled. + (re.compile(r'("error")\s*:', re.IGNORECASE), r"\1 ="), + (re.compile(r"\b(error|fatal|panic)\s*:", re.IGNORECASE), r"[bd \1]"), + (re.compile(r"\b(error)(\s+running\b)", re.IGNORECASE), r"[bd \1]\2"), + (re.compile(r"\bunknown\s+command\b", re.IGNORECASE), "unknown-command"), + (re.compile(r"(Traceback \(most recent call last\))\s*:"), r"\1"), +) + + +def _quote_handled_output(blob: str | None, *, limit: int = STATUS_ERROR_MAX) -> str: + """Render another program's output for quoting inside a log line on a + path this module HANDLED -- see the block comment above for the measured + leak this exists to stop. + + Distinct from `_clean_bd_error`, and the two must not be merged. + `_clean_bd_error` builds the text of a `BeadsError` -- a real failure, + on its way to a non-zero exit, which SHOULD announce loudly. This one is + for the opposite case: a condition that was detected and recovered from, + where the announcement would be a lie. + + Returns one line, with every error-announcement shape attributed to its + source rather than asserted, truncated at a word boundary. + """ + one_line = " ".join((blob or "").split()) + if not one_line: + return "(bd reported no detail)" + for pattern, replacement in _HANDLED_OUTPUT_DEFUSALS: + one_line = pattern.sub(replacement, one_line) + return truncate_status(one_line, limit) + + @dataclass class ListResult: """What `Beads.list_bounded` actually returned, and how it relates to @@ -4791,11 +4877,16 @@ def create(self, name: str) -> Path: # schema migration -- never from normal item # operations. Drop the residue and retry exactly once # rather than permanently burning this name. + # `_quote_handled_output`, never a bare slice of `blob`: + # this line goes to a plain CLI's stderr, and the retry + # below is expected to SUCCEED. Republishing bd's own + # `Error:` here is what made a healed run look like a + # silent failure (`model_performance-kxk`). logger.warning( "project %r: bd init hit a dirty schema migration -- dropping " "and retrying once: %s", name, - blob.strip()[:300], + _quote_handled_output(blob), ) try: drop_database(name) diff --git a/tests/unit/test_handled_output_is_not_an_announcement.py b/tests/unit/test_handled_output_is_not_an_announcement.py new file mode 100644 index 0000000..df251f3 --- /dev/null +++ b/tests/unit/test_handled_output_is_not_an_announcement.py @@ -0,0 +1,326 @@ +"""Tier 1 -- a HANDLED condition must never republish another program's +error ANNOUNCEMENT onto a stderr that will accompany exit 0. + +The observed leak (`model_performance-kxk`), verbatim from +`docs/lanes/wp6-error-regex-scope/evidence/pr70-doctor-quick.run1-transient.stderr.txt` +on main: + + project 'contract1788423815748rm': bd init hit a dirty schema migration + -- dropping and retrying once: [mysql] ... busy buffer + Error: failed to open Dolt store: failed to initialize schema: schema + migration: pending schema migrations alter pre-existing dirty tables: + comments, ...; run 'bd dolt commit' to + +`doctor --quick` printed `All 35 assumptions hold` and exited 0 underneath +that. From outside, an error announcement alongside exit 0 IS the +silent-failure shape `tests/_util.assert_no_silent_failure` exists to +forbid -- so a run that recovered correctly could fail a CLI-tier test. + +The root cause is not bd's stderr escaping around us. The `Error:` line is +INSIDE our own `logger.warning`: the old 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. + +WHY THIS FILE IS TIER 1. The condition was observed ONCE and did not +reproduce on the immediately following run: a real dirty dolt store is not +something a test can conjure on demand. But the leak never needed a real +dirty store -- it needed bd to hand `Workspace.create` that blob once. That +IS reproducible, deterministically, with no bd, no dolt, and no network, by +scripting the single `bd init` call the heal path branches on. So this file +pins the actual product path (`Workspace.create`'s dirty-schema self-heal), +not a re-implementation of it. + +BOTH DIRECTIONS LIVE HERE ON PURPOSE, for the reason +`test_error_announcement_detection.py` gives for the same choice: the +failure mode is not "too quiet" or "too loud", it is the two collapsing. +A fix that only proved the healed run is quiet could have been achieved by +swallowing everything, which would retire the guarantee that a genuine +failure still announces. +""" + +from __future__ import annotations + +import logging +import subprocess + +import pytest + +from amplifier_work_tracker import adapter as A +from amplifier_work_tracker import cli + +from .. import _util + +# -------------------------------------------------------------------------- +# The blob bd actually emitted, reconstructed from the committed evidence. +# +# Two lines, because that is what made the second one read as OUR +# announcement once it was interpolated into a log message. +# -------------------------------------------------------------------------- + +OBSERVED_BD_BLOB = ( + "[mysql] 2026/09/03 01:25:03 connection.go:214 busy buffer\n" + "Error: failed to open Dolt store: failed to initialize schema: schema migration: " + "pending schema migrations alter pre-existing dirty tables: comments, " + "compaction_snapshots, dependencies, events, issue_snapshots, labels; " + "run 'bd dolt commit' to commit the working set\n" +) + +# The same failure signature WITHOUT any of `_LEAKING_BD_INTERNALS_PATTERNS` +# (no `bd dolt commit`, no `run 'bd `). Used for the genuine-failure half: +# `_clean_bd_error` passes this through verbatim, so the announcement bd made +# is still visible in the CLI's own failure message. That is what proves the +# defusal is confined to the handled path. +GENUINE_FAILURE_BLOB = ( + "Error: failed to initialize schema: schema migration: pending schema migrations " + "alter pre-existing dirty tables: comments, events\n" +) + +PROJECT = "kxkheal" + + +class _ScriptedRun: + """Stands in for `adapter._run_bounded`, the single call site every + `bd`/`dolt`/`git` subprocess in the module goes through. + + Only `bd init` is scripted; everything else (the `git init`/`git commit` + bootstrap, `bd metrics off`) succeeds silently, which is what they do on + a healthy box. + """ + + def __init__(self, *init_results: tuple[int, str]): + self.init_results = list(init_results) + self.calls: list[list[str]] = [] + + def __call__(self, args, **kwargs): + self.calls.append(list(args)) + if list(args[:2]) == ["bd", "init"]: + rc, err = self.init_results.pop(0) if self.init_results else (0, "") + return subprocess.CompletedProcess(list(args), rc, "", err) + return subprocess.CompletedProcess(list(args), 0, "", "") + + @property + def init_calls(self) -> int: + return sum(1 for c in self.calls if c[:2] == ["bd", "init"]) + + +class _AnsweringProject: + """`Workspace.create` finishes by proving the project actually answers. + Nothing in this file is about that step.""" + + def list(self, *a, **kw): + return [] + + +@pytest.fixture +def scripted(monkeypatch, tmp_path): + """A `Workspace` rooted in `tmp_path` whose bd calls are scripted. + + Returns a factory: `scripted(*init_results) -> (workspace, run)`. + """ + + def _make(*init_results: tuple[int, str]): + run = _ScriptedRun(*init_results) + monkeypatch.setattr(A, "_run_bounded", run) + monkeypatch.setattr(A, "drop_database", lambda name: True) + monkeypatch.setattr( + A.Workspace, "project", lambda self, name, actor=None: _AnsweringProject() + ) + # `bd metrics off` is once-per-process; reset so the call is scripted + # rather than skipped depending on test ordering. + monkeypatch.setattr(A, "_TELEMETRY_OFF_ATTEMPTED", False, raising=False) + return A.Workspace(tmp_path), run + + return _make + + +def _stderr_of(caplog) -> str: + """Reconstruct what a plain CLI invocation would put on stderr. + + `logger.warning` and above reach stderr through Python's handler of last + resort, which has NO formatter -- it writes `record.getMessage()`, the + fully-interpolated message and nothing else. That is exactly what the + recorded evidence file contains (bare messages, no level prefix), so + joining `getMessage()` reproduces those bytes rather than approximating + them. `caplog` is used only to reach the records; the reconstruction, not + pytest's own formatting, is what gets asserted on. + """ + return "\n".join(r.getMessage() for r in caplog.records) + + +# -------------------------------------------------------------------------- +# The healed run: quiet about failure, still loud about the recovery. +# -------------------------------------------------------------------------- + + +def test_a_healed_dirty_migration_leaves_no_error_announcement(scripted, caplog): + """The reproduction, and the fix, in one test. + + Against the parent commit this FAILS at the `error_announcement` + assertion with `shape=error-colon matched='Error:'` -- the recorded leak, + on demand. + """ + caplog.set_level(logging.WARNING, logger="amplifier_work_tracker.adapter") + ws, run = scripted((1, OBSERVED_BD_BLOB), (0, "")) + + path = ws.create(PROJECT) + + # The heal actually happened -- otherwise this test proves nothing about + # the heal path. + assert run.init_calls == 2, f"expected a retry after the dirty migration, got {run.calls}" + assert path.name == PROJECT + + stderr = _stderr_of(caplog) + + # 1. The recovery stays VISIBLE. Going quiet would also pass the check + # below, and would be the wrong fix. + assert "dropping and retrying once" in stderr + assert "dirty schema migration" in stderr + + # 2. bd's detail survives, so the line is still diagnostic. + assert "busy buffer" in stderr + assert "failed to open Dolt store" in stderr + + # 3. ... but it no longer ANNOUNCES. This is the whole item. + assert _util.error_announcement(stderr) is None, ( + "a handled, recovered condition republished an error announcement: " + f"{_util.error_announcement(stderr)!r} in {stderr!r}" + ) + + # 4. And the tier-3 invariant itself, run against exactly this stderr + # beside the exit code a healed run really produces. + _util.assert_no_silent_failure( + subprocess.CompletedProcess(["doctor", "--quick"], 0, "All 35 assumptions hold\n", stderr) + ) + + +def test_the_healed_warning_is_a_single_line(scripted, caplog): + """A quoted multi-line blob is half the illusion: it puts bd's `Error:` + at the START of a line of our stderr, which is where a reader (and a + log scraper) reads it as ours. One record, one line.""" + caplog.set_level(logging.WARNING, logger="amplifier_work_tracker.adapter") + ws, _ = scripted((1, OBSERVED_BD_BLOB), (0, "")) + ws.create(PROJECT) + + heal_lines = [ + r.getMessage() for r in caplog.records if "dirty schema migration" in r.getMessage() + ] + assert len(heal_lines) == 1 + assert "\n" not in heal_lines[0] + + +# -------------------------------------------------------------------------- +# The genuine failure: still loud, still non-zero. This is the half that a +# too-eager fix would silently retire. +# -------------------------------------------------------------------------- + + +def test_a_migration_that_really_fails_still_raises(scripted): + """Both attempts fail -> `create` refuses, it does not return a path. + Nothing about the defusal reaches this path.""" + ws, run = scripted((1, GENUINE_FAILURE_BLOB), (1, GENUINE_FAILURE_BLOB)) + + with pytest.raises(A.BeadsError) as excinfo: + ws.create(PROJECT) + + assert run.init_calls == 2, "the retry must still be attempted before giving up" + message = str(excinfo.value) + assert "bd init failed" in message + # The failure path goes through `_clean_bd_error`, never + # `_quote_handled_output`: bd's own announcement is preserved verbatim. + assert _util.error_announcement(message) is not None + assert "[bd " not in message + + +def test_a_migration_that_really_fails_exits_non_zero_and_announces(scripted, monkeypatch, capsys): + """The same failure at the CLI surface: `cmd_new` -> `die` -> exit 1, + with the announcement on stderr. + + Asserted together with `assert_no_silent_failure`, which must NOT fire + here: an announcement beside a non-zero exit is a program reporting its + failure correctly. That is the guarantee `model_performance-wp6` shipped, + and this test is where this change proves it did not weaken it. + """ + ws, _ = scripted((1, GENUINE_FAILURE_BLOB), (1, GENUINE_FAILURE_BLOB)) + monkeypatch.setattr(cli, "_guard", lambda: None) + monkeypatch.setattr(cli, "_ws", lambda a: ws) + monkeypatch.setattr(A, "database_exists", lambda name: False) + + args = type("A", (), {"name": PROJECT, "root": str(ws.root)})() + with pytest.raises(SystemExit) as excinfo: + cli.cmd_new(args) + + exit_code = excinfo.value.code + assert isinstance(exit_code, int) and exit_code != 0 + captured = capsys.readouterr() + assert "bd init failed" in captured.err + + result = subprocess.CompletedProcess(["new", PROJECT], exit_code, captured.out, captured.err) + assert _util.error_announcement(captured.err) is not None, ( + "a genuine failure must still announce -- if this goes None, the " + "defusal has leaked onto the failure path" + ) + _util.assert_no_silent_failure(result) # announcement + non-zero exit is correct + + +# -------------------------------------------------------------------------- +# The coupling. Product code cannot import a test helper, so the guarantee +# is closed from this side instead: every shape the tier-3 predicate knows +# about must be defused by `_quote_handled_output`. +# -------------------------------------------------------------------------- + +# One representative blob per shape in `_util._ERROR_ANNOUNCEMENT_RES`. +SHAPE_SAMPLES: dict[str, str] = { + "error-colon": "Error: failed to open Dolt store", + "json-error-field": '{"error": "connection refused", "code": 2}', + "error-running": "error running migration step 4", + "unknown-command": 'unknown command "reclaim" for "bd"', + "python-traceback": "Traceback (most recent call last):\n File x\nValueError: nope", +} + + +def test_every_known_announcement_shape_has_a_sample(): + """If a shape is added to the predicate without a sample here, this goes + red -- which is the point. A coupling test that silently covers only the + old shapes is not a coupling test.""" + known = {name for name, _ in _util._ERROR_ANNOUNCEMENT_RES} + assert known == set(SHAPE_SAMPLES), ( + "shapes without a defusal sample: " + f"{sorted(known - set(SHAPE_SAMPLES))}; stale samples: " + f"{sorted(set(SHAPE_SAMPLES) - known)}" + ) + + +@pytest.mark.parametrize("shape", sorted(SHAPE_SAMPLES)) +def test_quote_handled_output_defuses_every_shape(shape): + sample = SHAPE_SAMPLES[shape] + # The sample really is an announcement before the treatment -- otherwise + # this test could pass against a function that does nothing at all. + assert _util.error_announcement(sample) is not None, shape + quoted = A._quote_handled_output(sample) + assert _util.error_announcement(quoted) is None, f"{shape} survived: {quoted!r}" + + +def test_quote_handled_output_keeps_the_detail_readable(): + """Defusing is not redacting. The words a human would grep for survive.""" + quoted = A._quote_handled_output(OBSERVED_BD_BLOB) + assert "busy buffer" in quoted + assert "failed to open Dolt store" in quoted + assert "dirty tables" in quoted + assert "error" in quoted.lower(), "the word itself must survive -- people grep for it" + assert "\n" not in quoted + + +def test_quote_handled_output_reports_emptiness_rather_than_nothing(): + assert A._quote_handled_output("") == "(bd reported no detail)" + assert A._quote_handled_output(None) == "(bd reported no detail)" + assert A._quote_handled_output(" \n\t ") == "(bd reported no detail)" + + +def test_quote_handled_output_truncates_at_a_word_boundary(): + """The old `[:300]` slice cut mid-sentence ("run 'bd dolt commit' to"), + which is exactly the fragment problem `truncate_status` already solved.""" + quoted = A._quote_handled_output("word " * 200) + assert quoted.endswith("...[truncated]") + assert len(quoted) <= A.STATUS_ERROR_MAX + len(" ...[truncated]") From a5d1c1698471cc54303c37b40fd9c3b66cf3c5ec Mon Sep 17 00:00:00 2001 From: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> Date: Thu, 3 Sep 2026 04:55:40 -0700 Subject: [PATCH 2/2] docs(kxk): lane DONE-NOTE + evidence (fail-before/after, all five tiers, doctor 37/37) --- .../kxk-healed-migration-stderr/DONE-NOTE.md | 166 ++++++++++++++++++ .../evidence/doctor-quick-real-root.txt | 46 +++++ .../evidence/tier1-unit.txt | 27 +++ .../evidence/tier2-integration.txt | 32 ++++ .../evidence/tier3-cli.txt | 37 ++++ .../evidence/tier4-ledger.txt | 28 +++ .../evidence/tier5-module.txt | 32 ++++ 7 files changed, 368 insertions(+) create mode 100644 docs/lanes/kxk-healed-migration-stderr/DONE-NOTE.md create mode 100644 docs/lanes/kxk-healed-migration-stderr/evidence/doctor-quick-real-root.txt create mode 100644 docs/lanes/kxk-healed-migration-stderr/evidence/tier1-unit.txt create mode 100644 docs/lanes/kxk-healed-migration-stderr/evidence/tier2-integration.txt create mode 100644 docs/lanes/kxk-healed-migration-stderr/evidence/tier3-cli.txt create mode 100644 docs/lanes/kxk-healed-migration-stderr/evidence/tier4-ledger.txt create mode 100644 docs/lanes/kxk-healed-migration-stderr/evidence/tier5-module.txt diff --git a/docs/lanes/kxk-healed-migration-stderr/DONE-NOTE.md b/docs/lanes/kxk-healed-migration-stderr/DONE-NOTE.md new file mode 100644 index 0000000..893ea45 --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/DONE-NOTE.md @@ -0,0 +1,166 @@ +# kxk — a HEALED dirty-schema migration must not leak bd's `Error:` line while exiting 0 + +Item: `model_performance-kxk` (project `model_performance`), discovered-from `model_performance-wp6`. +Branch: `lane/kxk-healed-migration-stderr`. Repo: `microsoft/amplifier-work-tracker`. +Spend authority: **$0** (pure code change). **Actual API/DTU spend: $0.00.** No infrastructure +created, so no `infra_ledger.sh` row and no teardown. + +**Outcome: branch A — RESOLVED.** Every deliverable is DONE. Nothing was dropped, and the cap never +bound (there was nothing to buy: the whole item is a code change, and the reproduction turned out to +need no runs at all — see below). + +--- + +## The finding that changed the fix + +The item, and the goal, both describe the leak as bd's stderr being "passed straight through" +underneath our own log line. **That is not what happens, and it matters, because it makes the fix +smaller and the reproduction free.** + +The `Error:` line is **inside our own `logger.warning`**. `Workspace.create`'s dirty-schema self-heal +interpolated `blob.strip()[:300]`, and `blob` is bd's **multi-line** stderr — so the second line of +that quoted blob became the second line of *our* stderr, where it reads as this program's own +announcement. + +Proof, taken from the committed evidence rather than from reasoning +(`docs/lanes/wp6-error-regex-scope/evidence/pr70-doctor-quick.run1-transient.stderr.txt`, on main): +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 there. + +``` +$ python3 - <<'PY' +lines = open('.../pr70-doctor-quick.run1-transient.stderr.txt').read().split('\n') +blob = lines[0].split('retrying once: ',1)[1] + '\n' + lines[1] +print(len(blob)) # -> 300 +PY +``` + +Consequence: **the leak never needed a dirty dolt store.** It needed bd to hand `create()` that blob +once. That is scriptable, so the "hard part" the goal flagged — *"observed ONCE and not on the +immediately following run"* — dissolved. The reproduction is deterministic, tier 1, no bd, no dolt, +no network, no spend. + +## What changed + +`src/amplifier_work_tracker/adapter.py` + +* New `_quote_handled_output(blob)` — for quoting **another program's output on a path this module + handled and recovered from**. Two narrow transformations: + 1. **Flatten to one line.** A multi-line quote puts `Error:` at the start of a line of *our* + stderr, which is precisely where a reader (or a log scraper) reads it as ours. + 2. **Attribute instead of assert.** `Error:` → `[bd Error]`. The word survives (people grep for + it), the detail survives (still diagnostic), only the impersonation ends. + Truncation moves from the bare `[:300]` slice to the existing `truncate_status` — word boundary, + explicit `...[truncated]` marker — which is the same fragment problem that helper already solved. +* Applied at **both** handled call sites in the file: the dirty-schema self-heal in + `Workspace.create` (the reported one) 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. Same + defect, same file, one helper. Named here rather than done silently. + +**Deliberately not merged with `_clean_bd_error`.** That one builds the text of a real `BeadsError` +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. + +Before / after, on the verbatim recorded blob: + +``` +BEFORE (two lines of our stderr; line 2 announces): + project 'contract...rm': 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; word-boundary truncation): + project 'contract...rm': bd init hit a dirty schema migration -- dropping and retrying once: [mysql] ... busy buffer [bd Error] failed to open Dolt store: failed to initialize schema: ... run 'bd dolt ...[truncated] +``` + +`tests/unit/test_handled_output_is_not_an_announcement.py` (13 tests) drives the **real** +`Workspace.create` heal path with a scripted `bd init`, and reconstructs what a plain CLI invocation +would put on stderr from `record.getMessage()` — which is literally what Python's handler of last +resort writes, since it has no formatter. Both directions live in that one file, for the reason +wp6's own file gives for the same choice. + +## Deliverables + +| Deliverable | State | Evidence | +|---|---|---| +| A healed migration leaves no error announcement on stderr; the `dropping and retrying once` line survives | **DONE** | `test_a_healed_dirty_migration_leaves_no_error_announcement` asserts *all four*: heal happened (2 `bd init` calls), recovery line present, bd's detail present, `error_announcement(...) is None`, and `assert_no_silent_failure` passes on the healed stderr beside exit 0 | +| A migration that genuinely FAILS still announces loudly and exits non-zero | **DONE** | `test_a_migration_that_really_fails_still_raises` (raises `BeadsError`, retry still attempted, `error_announcement(...) is not None`, `[bd ` absent) and `test_a_migration_that_really_fails_exits_non_zero_and_announces` (`cmd_new` → `die` → exit 1, announcement present on stderr, `assert_no_silent_failure` correctly does **not** fire) | +| Fail-before: reproduce the leak, flag it on the parent, not flag it after | **DONE — and deterministic** | `evidence/fail-before.txt` (10 failed / 3 passed on the parent), `evidence/fail-after.txt` (36 passed) | +| wp6's guarantee is not weakened | **DONE** | `tests/unit/test_error_announcement_detection.py` — 23 tests, all green, unmodified. `tests/_util.py` untouched (`git diff --stat` shows it is not in the change) | +| All four documented tiers + the modules suite, BY NAME | **DONE (one known-not-mine failure)** | table below | +| DRAFT PR on origin (`lane/kxk-healed-migration-stderr`) | **DONE** | see `publication` in `DONE.json` — values read back from the remote, not from local `git log` | +| DONE-NOTE.md at `docs/lanes/kxk-healed-migration-stderr/` | **DONE** | this file | + +### Was the repro deterministic? + +**Yes — fully, and with no spend.** This is a stronger answer than the goal expected, and it is +because of the root-cause finding above: reproducing the *leak* never required reproducing the *dirty +store*. Run against the parent commit, the new test fails with: + +``` +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" +``` + +Note the reproduced string ends at `run 'bd dolt commit' to` — the **same 300-character cut** as the +recorded incident. It is the recorded leak, not a lookalike. + +What is *not* claimed: no run in this lane produced a genuinely dirty dolt store. The end-to-end +`doctor` run below is green and never entered the heal path, so it corroborates nothing about the +fix and is recorded only for the two things it does prove (below). The guarantee rests on the +deterministic tier-1 test of the real product path. + +## Test tiers, by name + +| 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 failed** — the failure is `model_performance-jyg`, see below | +| 4 — ledger | `make test-ledger` | **26 passed**; `make ledger-mutate` → **proven 15 / 15**, none unproven | +| 5 — modules | `make test-module` | **115 passed** (6 m 31 s) | +| lint/types | `make check` | ruff clean (157 files formatted), pyright **0 errors** | + +**The tier-3 failure is `model_performance-jyg`, and that was verified rather than asserted.** +`test_doctor_quick_succeeds_against_the_real_installed_bd` dies at +`assert result.returncode == 0` — the *earlier* assertion — because `[FAIL] sweeps.alive` reports +`no heartbeat ever recorded for the reap sweep loop`. It never reaches `assert_no_silent_failure`. +The cause is environmental: the test's isolated root has no sweep heartbeats. Running the same +command on this branch's code against the **real** workspace root +(`evidence/doctor-quick-real-root.txt`): + +``` + [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, not computed** — and `error_announcement()` over that entire captured output +returns `None`. Two things that proves: the tier-3 failure is the environment, not this change; and +this branch's `doctor` emits no announcement on a healthy run. (It proves nothing about the heal +path, which it did not enter.) + +`model_performance-c0e` (modules reap-recovery) and the `test_supervisor_web.py` port-binding flake +did **not** fire in these runs. Neither was chased. + +## Deviations and choices recorded + +1. **Direction (1), as the goal preferred** — re-label bd's stderr on the heal path. Direction (2), + wp6's parseable-channel redesign, was **not** implemented and is **not** required: the root cause + is our own interpolation, so there is no channel-separation problem to solve here. That remains an + open owner-level output-contract question, untouched. +2. **`tests/_util.py` was not widened, narrowed, or edited.** The fix is entirely product-side, as + the scope-out demanded. +3. **Second call site fixed too** (`move_item`'s best-effort cleanup). Same defect class, same file, + same helper — declared here rather than slipped in. +4. **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 ever added to the + predicate without a matching defusal sample. Widening the predicate later cannot silently outrun + the product fix. +5. **The goal's authoring rule on cap arithmetic does not apply** — the authority is `$0` for a pure + code change with no run-buying deliverable, so there is no `runs × arms × per-run` arithmetic to + show and none to check. No residue, nothing unspendable, no branch-B condition. +6. Did not widen into `jyg` or `c0e`. diff --git a/docs/lanes/kxk-healed-migration-stderr/evidence/doctor-quick-real-root.txt b/docs/lanes/kxk-healed-migration-stderr/evidence/doctor-quick-real-root.txt new file mode 100644 index 0000000..ab1fc08 --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/evidence/doctor-quick-real-root.txt @@ -0,0 +1,46 @@ +### doctor --quick against the REAL workspace root (this branch's code) +### Purpose: (a) measure the assumption count, (b) show sweeps.alive PASSes here, +### which is what makes the tier-3 failure environmental (model_performance-jyg). +2026-09-03T11:29:27Z +--- stdout+stderr, verbatim --- +project 'contract178843496795atomic': healing an abandoned creation attempt (lock /tmp/awtcontract_7r6582yp/projects/contract178843496795atomic/.create.lock named a dead pid) before retrying + [PASS] version bd 1.1.2 + [PASS] capabilities all required bd commands present + [PASS] read.unavailable_not_absent an infrastructure read failure raises BeadsUnavailableError with its cause intact on read/claim and reports UNAVAILABLE (not ERROR) per project, while genuine absence on a healthy database still reports plain 'not found' + [PASS] resolve.fenced stale holder refused, as required + [PASS] resolve.divergent_text_refused resolving a closed item with different text refuses and writes nothing + [PASS] resolve.identical_text_idempotent re-sending identical resolution text is an idempotent success + [PASS] reopen.reopens a resolved item reopens unassigned and is directly claimable again + [PASS] reopen.clears_closed_at reopen clears closed_at (the documented, surfaced accounting cost) + [PASS] reopen.close_reason_disposition reopen clears close_reason (measured), and the wrapper's archive comment preserves the previous resolution regardless + [PASS] reopen.emits_event bd records a `reopened` events row, attributed + [PASS] defer.refuses_resolved defer on a resolved item refuses, writes nothing, and names `reopen` + [PASS] block.refuses_resolved block on a resolved item refuses, writes nothing, and names `reopen` + [PASS] release.reopens_unresolved release reopens a held item with no resolution, and it is re-claimable + [PASS] claim.subcommand --claim present, rejects --assignee as expected + [PASS] claim.atomic skipped (--quick); run full doctor before trusting parallel agents + [PASS] claim.directed_atomic skipped (--quick); run full doctor before trusting parallel agents + [PASS] link.nonblocking discovered-from is non-blocking + [PASS] list.includes_closed all-flag required and working + [PASS] list.status_filter_includes_closed an explicit --status filter shows closed items without --all + [PASS] show.dependents reverse link visible (1 links) + [PASS] read.no_mutation repeated reads (including not-found/wrong-project misses) leave status, holder, and metadata unchanged + [PASS] resolution.readable resolution text round-trips + [PASS] timestamps.readable created_at/updated_at/closed_at all round-trip as real datetimes + [PASS] metadata.roundtrip arbitrary JSON metadata round-trips + [PASS] project.name_rules dotted names appear usable now; validator may be relaxed + [PASS] custody.fresh_survives a fresh renewal survives regardless of total hold duration + [PASS] custody.stale_reclaimed stale custody is reclaimed: custody stale -- last seen 3601s ago (ttl 900s) + [PASS] custody.idle_not_exempt awaiting_human with stale custody is still reclaimed: custody stale -- last seen 3601s ago (ttl 900s) + [PASS] custody.fenced old holder's renew and resolve are both refused after takeover + [PASS] project.removal remove() drops both the directory and database; re-create afterward is genuinely empty + [PASS] project.create_atomic an abandoned creation lock (dead pid) is healed automatically and create() completes fresh in the same call; path=/tmp/awtcontract_7r6582yp/projects/contract178843496795atomic + [PASS] project.creation_state_reporting creation_state distinguishes none/creating/abandoned correctly + [PASS] service.installed installed and active (unit: /home/bkrabach/.config/systemd/user/amplifier-work-tracker.service) + [PASS] systemd.user_bus_reachable systemctl --user show-environment succeeded + [PASS] dolt.reachable dolt sql-server responds on 127.0.0.1:3308 + [PASS] sweeps.alive reap sweep completed 97s ago (threshold 900s); notify sweep completed 117s ago (threshold 900s) + [PASS] service.restart_policy installed unit has Restart=always -- survives a clean/unintended exit + +All 37 assumptions hold. Safe to run parallel agents. +--- exit=0 --- diff --git a/docs/lanes/kxk-healed-migration-stderr/evidence/tier1-unit.txt b/docs/lanes/kxk-healed-migration-stderr/evidence/tier1-unit.txt new file mode 100644 index 0000000..461a9ed --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/evidence/tier1-unit.txt @@ -0,0 +1,27 @@ +### TIER 1 -- make test-unit +2026-09-03T11:22:21Z +tests/unit/test_widgets_contract.py::test_firewall_passes_token_only_and_avoids_false_positives[a ’ b · c] PASSED [ 98%] +tests/unit/test_widgets_contract.py::test_firewall_passes_token_only_and_avoids_false_positives[y] PASSED [ 98%] +tests/unit/test_widgets_contract.py::test_firewall_passes_token_only_and_avoids_false_positives[
4
] PASSED [ 98%] +tests/unit/test_widgets_contract.py::test_render_enforce_raises_on_violation PASSED [ 98%] +tests/unit/test_widgets_contract.py::test_dashboard_registry_has_the_five_v2_panels PASSED [ 99%] +tests/unit/test_widgets_contract.py::test_dashboard_widget_needs_are_real_context_fields PASSED [ 99%] +tests/unit/test_widgets_contract.py::test_every_dashboard_widget_obeys_the_firewall_when_populated PASSED [ 99%] +tests/unit/test_widgets_contract.py::test_every_dashboard_widget_obeys_the_firewall_when_empty PASSED [ 99%] +tests/unit/test_widgets_contract.py::test_routed_output_is_byte_identical_to_inline_builder[empty] PASSED [ 99%] +tests/unit/test_widgets_contract.py::test_routed_output_is_byte_identical_to_inline_builder[populated] PASSED [ 99%] +tests/unit/test_workspace_remove.py::test_remove_without_force_refuses_before_touching_disk PASSED [ 99%] +tests/unit/test_workspace_remove.py::test_remove_with_force_false_explicitly_still_refuses PASSED [ 99%] +tests/unit/test_workspace_remove.py::test_remove_rejects_invalid_name_before_touching_disk PASSED [100%] + +=============================== warnings summary =============================== +tests/unit/test_webapp_setup.py:29 + /home/bkrabach/dev/hw-model-performance/lanes/kxk-healed-migration-stderr/amplifier-work-tracker/tests/unit/test_webapp_setup.py:29: StarletteDeprecationWarning: Using `httpx` with `starlette.testclient` is deprecated; install `httpx2` instead. + from starlette.testclient import TestClient # noqa: E402 + +.venv/lib/python3.12/site-packages/starlette/testclient.py:53 + /home/bkrabach/dev/hw-model-performance/lanes/kxk-healed-migration-stderr/amplifier-work-tracker/.venv/lib/python3.12/site-packages/starlette/testclient.py:53: DeprecationWarning: The anyio.abc.BlockingPortal alias is deprecated, use anyio.from_thread.BlockingPortal instead. + _PortalFactoryType = Callable[[], AbstractContextManager[anyio.abc.BlockingPortal]] + +-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html +======================= 846 passed, 2 warnings in 43.56s ======================= diff --git a/docs/lanes/kxk-healed-migration-stderr/evidence/tier2-integration.txt b/docs/lanes/kxk-healed-migration-stderr/evidence/tier2-integration.txt new file mode 100644 index 0000000..53720e9 --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/evidence/tier2-integration.txt @@ -0,0 +1,32 @@ +### TIER 2 -- make test-integration (real bd + shared dolt) +2026-09-03T11:38:31Z +tests/integration/test_write_readback.py::test_comment_raises_when_bd_reports_success_but_no_comment_landed PASSED [ 96%] +tests/integration/test_write_readback.py::test_defer_verifies_by_readback_when_the_wrapper_reports_conflict PASSED [ 96%] +tests/integration/test_write_readback.py::test_defer_raises_when_bd_reports_success_but_the_status_did_not_move PASSED [ 97%] +tests/integration/test_write_readback.py::test_block_verifies_by_readback_when_the_wrapper_reports_conflict PASSED [ 97%] +tests/integration/test_write_readback.py::test_unblock_verifies_by_readback_when_the_wrapper_reports_conflict PASSED [ 97%] +tests/integration/test_write_readback.py::test_add_dependency_verifies_by_readback_when_the_wrapper_reports_conflict PASSED [ 97%] +tests/integration/test_write_readback.py::test_add_dependency_raises_when_bd_reports_success_but_no_edge_landed PASSED [ 98%] +tests/integration/test_write_readback.py::test_take_custody_verifies_by_readback_when_the_wrapper_reports_conflict PASSED [ 98%] +tests/integration/test_write_readback.py::test_renew_custody_verifies_by_readback_when_the_wrapper_reports_conflict PASSED [ 98%] +tests/integration/test_write_readback.py::test_renew_custody_raises_when_bd_reports_success_but_the_record_did_not_move PASSED [ 98%] +tests/integration/test_write_readback.py::test_supersede_verifies_by_readback_when_the_wrapper_reports_conflict PASSED [ 99%] +tests/integration/test_write_readback.py::test_reopen_verifies_by_readback_when_the_wrapper_reports_conflict PASSED [ 99%] +tests/integration/test_write_readback.py::test_reopen_still_raises_when_readback_shows_the_reopen_genuinely_did_not_land PASSED [ 99%] +tests/integration/test_write_readback.py::test_move_refuses_when_the_copy_reports_success_but_the_rows_are_not_there PASSED [100%] + +=============================== warnings summary =============================== +tests/integration/test_observatory_web.py:20 + /home/bkrabach/dev/hw-model-performance/lanes/kxk-healed-migration-stderr/amplifier-work-tracker/tests/integration/test_observatory_web.py:20: StarletteDeprecationWarning: Using `httpx` with `starlette.testclient` is deprecated; install `httpx2` instead. + from starlette.testclient import TestClient # noqa: E402 + +.venv/lib/python3.12/site-packages/starlette/testclient.py:53 + /home/bkrabach/dev/hw-model-performance/lanes/kxk-healed-migration-stderr/amplifier-work-tracker/.venv/lib/python3.12/site-packages/starlette/testclient.py:53: DeprecationWarning: The anyio.abc.BlockingPortal alias is deprecated, use anyio.from_thread.BlockingPortal instead. + _PortalFactoryType = Callable[[], AbstractContextManager[anyio.abc.BlockingPortal]] + +-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html +=========================== short test summary info ============================ +SKIPPED [1] tests/integration/test_web.py:699: bd set no `owner` on this item -- happens where the environment has no git identity (e.g. a bare CI container with no `git config user.email`). `owner` is an environment-provided value, not a code invariant; the environment-independent humanization guarantees are covered by test_humanize_identity_* in tests/unit. +SKIPPED [1] tests/integration/test_web_pwa.py:234: Pillow not installed (dev/build-only tool) +SKIPPED [1] tests/integration/test_web_pwa.py:249: Pillow not installed (dev/build-only tool) +============ 367 passed, 3 skipped, 2 warnings in 954.56s (0:15:54) ============ diff --git a/docs/lanes/kxk-healed-migration-stderr/evidence/tier3-cli.txt b/docs/lanes/kxk-healed-migration-stderr/evidence/tier3-cli.txt new file mode 100644 index 0000000..214a112 --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/evidence/tier3-cli.txt @@ -0,0 +1,37 @@ +### TIER 3 -- make test-cli +2026-09-03T11:23:16Z +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2723 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2724 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2723 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2724 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2725 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2725 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2726 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2727 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2726 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2727 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2728 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2728 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2729 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2729 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2730 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2730 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2731 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2731 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2732 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2732 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2733 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2733 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2734 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2734 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2735 +time="2026-09-03T04:27:24-07:00" level=warning msg="error running query" connectTime="2026-09-03 04:27:24.942700665 -0700 PDT m=+248.484588765" connectionID=2735 error="database not found: contract1788434799710rm" queryTime="2026-09-03 04:27:24.944609541 -0700 PDT m=+248.486497641" +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2735 +time="2026-09-03T04:27:24-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2736 +time="2026-09-03T04:27:24-07:00" level=info msg=ConnectionClosed connectionID=2736 +time="2026-09-03T04:27:25-07:00" level=info msg=NewConnection DisableClientMultiStatements=false connectionID=2737 +time="2026-09-03T04:27:25-07:00" level=info msg=ConnectionClosed connectionID=2737 +=========================== short test summary info ============================ +FAILED tests/cli/test_cli_surface.py::test_doctor_quick_succeeds_against_the_real_installed_bd +=================== 1 failed, 88 passed in 296.13s (0:04:56) =================== +make: *** [Makefile:34: test-cli] Error 1 diff --git a/docs/lanes/kxk-healed-migration-stderr/evidence/tier4-ledger.txt b/docs/lanes/kxk-healed-migration-stderr/evidence/tier4-ledger.txt new file mode 100644 index 0000000..9554058 --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/evidence/tier4-ledger.txt @@ -0,0 +1,28 @@ +### TIER 4 -- make test-ledger +2026-09-03T11:23:11Z +ledger/checks/test_ledger_integrity.py::test_row_ids_are_well_formed_unique_and_ordered PASSED [ 65%] +ledger/checks/test_ledger_integrity.py::test_every_row_has_a_legal_disposition_and_its_required_fields PASSED [ 69%] +ledger/checks/test_ledger_integrity.py::test_every_row_quote_verifies_against_the_contract_bytes PASSED [ 73%] +ledger/checks/test_ledger_integrity.py::test_every_clause_id_is_a_bare_identifier_the_contract_actually_names PASSED [ 76%] +ledger/checks/test_ledger_integrity.py::test_every_core_clause_is_cited_by_at_least_one_row PASSED [ 80%] +ledger/checks/test_ledger_integrity.py::test_every_assertion_ref_resolves PASSED [ 84%] +ledger/checks/test_ledger_integrity.py::test_every_probe_belongs_to_a_row PASSED [ 88%] +ledger/checks/test_ledger_integrity.py::test_every_probe_has_a_declared_mutation PASSED [ 92%] +ledger/checks/test_ledger_integrity.py::test_the_mutation_harness_runs_and_every_mutation_flips_its_probe_red PASSED [ 96%] +ledger/checks/test_ledger_integrity.py::test_indexed_cites_are_reserved_for_measured_rows PASSED [100%] + +============================== 26 passed in 0.65s ============================== + +### make ledger-mutate +DENOMINATOR (this is the record) + pinning mutations proven 0 / 0 + pinning probes covered proven 0 / 0 + conformance mutations proven 15 / 15 + ALL mutations proven 15 / 15 + +UNPROVEN, named with reason + (none) + +Flip direction for every pinning probe above: VIOLATION-MOVEMENT. +A pinning probe going red means the behaviour moved TOWARD the contract: +update the row to CONFORMS and retarget the probe in the SAME change. diff --git a/docs/lanes/kxk-healed-migration-stderr/evidence/tier5-module.txt b/docs/lanes/kxk-healed-migration-stderr/evidence/tier5-module.txt new file mode 100644 index 0000000..56ca10c --- /dev/null +++ b/docs/lanes/kxk-healed-migration-stderr/evidence/tier5-module.txt @@ -0,0 +1,32 @@ +### TIER 5 -- make test-module (modules/tool-work-tracker/tests, NOT in testpaths) +2026-09-03T11:31:48Z +modules/tool-work-tracker/tests/test_work_status.py::test_status_reports_success_when_there_is_nothing_to_report PASSED [ 87%] +modules/tool-work-tracker/tests/test_work_status.py::test_status_reports_failure_when_a_project_cannot_be_listed PASSED [ 88%] +modules/tool-work-tracker/tests/test_work_status.py::test_status_still_reports_every_healthy_project_alongside_a_broken_one PASSED [ 89%] +modules/tool-work-tracker/tests/test_work_status.py::test_status_row_carries_the_full_per_status_breakdown PASSED [ 90%] +modules/tool-work-tracker/tests/test_work_status.py::test_claim_on_an_empty_queue_still_reports_success_with_claimed_null PASSED [ 91%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_subscribe_is_idempotent_and_validates_project PASSED [ 92%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_subscribe_refuses_unknown_project PASSED [ 93%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_unsubscribe_is_idempotent PASSED [ 93%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_subscriptions_lists_current_state PASSED [ 94%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_claim_auto_subscribes_to_its_project PASSED [ 95%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_reminder_snapshot_reports_subscribed_project_counts PASSED [ 96%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_reminder_snapshot_empty_when_no_subscriptions PASSED [ 97%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_reminder_snapshot_reports_holding_and_fresh_custody PASSED [ 98%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_reminder_snapshot_reports_custody_stale_true_past_ttl PASSED [ 99%] +modules/tool-work-tracker/tests/test_work_subscribe.py::test_reminder_snapshot_never_mutates_or_touches_custody PASSED [100%] + +=============================== warnings summary =============================== +modules/tool-work-tracker/tests/test_conformance_fixtures.py::test_fixture2_bad_half_stale_holders_resolve_is_refused_after_a_real_reap +modules/tool-work-tracker/tests/test_conformance_fixtures.py::test_fixture2_good_half_integrator_close_of_a_reclaimed_item_still_succeeds +modules/tool-work-tracker/tests/test_conformance_fixtures.py::test_fixture3_a_fenced_reclaim_clears_the_latch_with_no_manual_step +modules/tool-work-tracker/tests/test_reap_recovery.py::test_explicit_resolve_refusal_after_reap_clears_held_and_allows_new_claim +modules/tool-work-tracker/tests/test_reap_recovery.py::test_explicit_declare_refusal_after_reap_clears_held_and_allows_new_claim +modules/tool-work-tracker/tests/test_reap_recovery.py::test_background_renew_loop_detects_reap_and_clears_held_state + /home/bkrabach/dev/hw-model-performance/lanes/kxk-healed-migration-stderr/amplifier-work-tracker/.venv/lib/python3.12/site-packages/_pytest/stash.py:108: RuntimeWarning: coroutine 'alarm_for_reclaimed_item' was never awaited + del self._storage[key] + Enable tracemalloc to get traceback where the object was allocated. + See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info. + +-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html +================= 115 passed, 6 warnings in 391.23s (0:06:31) ==================