From aec4539f90abf8236fb8275943fcc829129c023f Mon Sep 17 00:00:00 2001 From: John Preston Date: Wed, 2 Sep 2026 23:57:22 +0400 Subject: [PATCH] [ai] Match the completion marker as a whole log line Task: 2026/09/02/match-the-test-complete-marker-as-a-whole-line --- .agents/shared/test-loop.md | 8 ++- .../skills/process-inbox/scripts/workspace.py | 21 ++++++-- .../process-inbox/scripts/workspace_test.py | 54 +++++++++++++++++++ 3 files changed, 78 insertions(+), 5 deletions(-) diff --git a/.agents/shared/test-loop.md b/.agents/shared/test-loop.md index 86530fd4e8..94c9984e94 100644 --- a/.agents/shared/test-loop.md +++ b/.agents/shared/test-loop.md @@ -504,7 +504,8 @@ so it can never run against real account data. The overlay must: - Log through `test_log.h` (`Step`/`Pass`/`Fail`/`Check`/`Note`/`CheckNear`/`LogGeometry`) — it already writes the flushed absolute-path log and the exact `TEST_STEP` / `TEST_RESULT` / `SCREENSHOT` / `TEST_COMPLETE` markers the external runner parses. Never hand-roll marker - strings or log files. + strings or log files. The runner reads `TEST_COMPLETE` as a whole line, so a stage name, note + or check detail that quotes the marker inside a longer line is safe and never ends the run. - **Capture the target tightly** with `CaptureWidget`/`CaptureRect` — the specific widget / row / glyph, unambiguously in frame at usable resolution. A full-window grab that leaves the target clipped, off-screen, or thumbnail-sized is NOT acceptable evidence — if the target @@ -613,7 +614,10 @@ command, environment, exit-code, log, artifact and control evidence. from launch** and a quiet-log watchdog while polling `/test_log.txt`, detects `TEST_COMPLETE` versus process death (crash) versus the caps elapsing (hang), kills any straggler, and returns one JSON report with the parsed markers, stderr tail, fresh crash - diagnostics, `crashpad_dumps_added`, `death_signals`, and `stale_crash_cleared`. + diagnostics, `crashpad_dumps_added`, `death_signals`, and `stale_crash_cleared`. The + completion marker is matched as a **whole log line** — a line equal to `TEST_COMPLETE` once + trailing whitespace is dropped — and never as a substring, so a line that merely quotes it, + such as `NOTE: mtp: rpc retry code=500 type=TEST_COMPLETE request=0x…`, is not a completion. `TEST_COMPLETE` alone is not success: when the process writes it and then dies, the verdict is `died-after-complete`, not `complete`, on any of three independent signals — a non-zero `exit_code`, a new `.dmp` in the live `tdata/dumps/completed/` Crashpad database across the run, diff --git a/.agents/skills/process-inbox/scripts/workspace.py b/.agents/skills/process-inbox/scripts/workspace.py index 9e0b0bf753..2e607c4d04 100755 --- a/.agents/skills/process-inbox/scripts/workspace.py +++ b/.agents/skills/process-inbox/scripts/workspace.py @@ -2302,6 +2302,21 @@ def parse_test_log(text): } +def log_marks_complete(text): + # Whole-line match, never a substring. A line that merely contains the + # literal would otherwise end a live run: a note, stage name or check + # detail quoting the marker, or the permanent MTP seam's + # "rpc retry code=500 type=TEST_COMPLETE request=0x..." row, whose type + # comes straight from a server-sent rpc_error. Trailing whitespace is + # dropped so a stray space or a reader that leaves a CR still counts; + # leading whitespace is not, because Test::Complete() writes the marker + # flush left. + return any( + line.rstrip() == TEST_COMPLETE_MARKER + for line in text.splitlines() + ) + + def tail_of_file(path, lines=60): if not path.is_file(): return None @@ -2378,9 +2393,9 @@ def command_test_run(args): last_change = now complete = False if size > 0: - complete = TEST_COMPLETE_MARKER in log_path.read_text( + complete = log_marks_complete(log_path.read_text( encoding="utf-8", errors="replace" - ) + )) if complete and complete_seen_at is None: complete_seen_at = now exit_code = process.poll() @@ -2408,7 +2423,7 @@ def command_test_run(args): if log_path.is_file() else "" ) - test_complete = TEST_COMPLETE_MARKER in log_text + test_complete = log_marks_complete(log_text) crash_report_fresh = ( working.is_file() and working.stat().st_mtime_ns != working_before diff --git a/.agents/skills/process-inbox/scripts/workspace_test.py b/.agents/skills/process-inbox/scripts/workspace_test.py index bf90c1b157..ca468779ef 100644 --- a/.agents/skills/process-inbox/scripts/workspace_test.py +++ b/.agents/skills/process-inbox/scripts/workspace_test.py @@ -1908,6 +1908,28 @@ class MechanicsTest(unittest.TestCase): self.assertEqual(markers["steps"], ["gated stage self-test: arm"]) self.assertEqual(markers["screenshots"], ["/tmp/fake.png"]) + def test_log_marks_complete_reads_the_marker_as_a_whole_line(self): + for text in [ + "TEST_COMPLETE", + "TEST_COMPLETE\n", + "TEST_COMPLETE\r\n", + "TEST_COMPLETE ", + "TEST_STEP: open settings\nTEST_COMPLETE\n", + "NOTE: waiting\nTEST_COMPLETE", + ]: + self.assertTrue(workspace.log_marks_complete(text), repr(text)) + for text in [ + "", + "NOTE: waiting for TEST_COMPLETE\n", + "NOTE: mtp: rpc retry code=500 type=TEST_COMPLETE " + "request=0x0000002d\n", + "TEST_COMPLETED\n", + "TEST_COMPLETE_LATER\n", + " TEST_COMPLETE\n", + "TEST_RESULT: PASS: TEST_COMPLETE\n", + ]: + self.assertFalse(workspace.log_marks_complete(text), repr(text)) + def test_test_run_reports_a_death_after_complete(self): with tempfile.TemporaryDirectory() as temporary: root = Path(temporary) @@ -2128,6 +2150,38 @@ class MechanicsTest(unittest.TestCase): self.assertIsNone(result["exit_code"]) self.assertEqual(result["death_signals"], []) + def test_test_run_refuses_a_line_that_only_contains_the_marker(self): + with tempfile.TemporaryDirectory() as temporary: + root = Path(temporary) + debug = make_portable_root(root) + line = ( + "NOTE: mtp: rpc retry code=500 type=TEST_COMPLETE" + " request=0x0000002d" + ) + exe = write_fake_exe(debug / "Telegram", ( + 'LOG="$TDESKTOP_TEST_EVIDENCE_DIR/test_log.txt"\n' + f'echo "{line}" >> "$LOG"\n' + "sleep 30\n" + ), ( + 'set "LOG=%TDESKTOP_TEST_EVIDENCE_DIR%\\test_log.txt"\n' + f'echo {line}>>"%LOG%"\n' + ":loop\ngoto loop\n" + )) + result = run_test_run( + exe, root / "run1", quiet=2.0, grace=1.0, + ) + self.assertEqual(result["outcome"], "quiet-killed") + self.assertEqual(result["verdict_hint"], "hang") + self.assertFalse(result["test_complete"]) + self.assertIsNone(result["exit_code"]) + self.assertEqual(result["death_signals"], []) + self.assertEqual( + Path(result["log_path"]).read_text( + encoding="utf-8", errors="replace" + ).splitlines(), + [line], + ) + def test_test_run_reports_a_grace_kill_with_a_dump(self): with tempfile.TemporaryDirectory() as temporary: root = Path(temporary).resolve()