test: wait for observable service-log state instead of racing the child

The three suites asserted on log CONTENT immediately after start_service
returned. The readiness contract without a stdout marker is 'process
alive == ready' — start_service never waits for output — so the tests
carried a latent race: the child's first write must land before the
read/stop. The #447-campaign guard refactor made the parent path faster
and CI runners started losing that race deterministically (empty tail,
an empty-log blob finalization deleting the live log, a missing declared
output). Verified on a CI debug run: with a pre-read wait the same
assertions pass on the same runner.

Fix: one helper polls the live log for the observable condition each
test actually depends on; every assertion is unchanged. No product code
is touched.

Co-authored-by: Ouroboros <311266734+ouroboros-agent@users.noreply.github.com>
This commit is contained in:
Anton Razzhigaev 2026-09-01 19:01:27 +00:00
parent dfd7f05626
commit 4ea736c6a5

View file

@ -11,6 +11,30 @@ from ouroboros.tools.registry import ToolRegistry
from ouroboros.tools.services import archive_task_service_logs, prune_service_logs
def _wait_for_service_log(drive, task_id, name, predicate, timeout_sec=15.0):
"""Wait until the service's live log satisfies ``predicate``.
The start_service readiness contract without a stdout marker is "process
alive == ready" — it never waits for output. These suites assert on log
CONTENT, so they must wait for the observable condition themselves: on a
slow CI runner the child's first write can land well after start_service
returns (a latent race exposed when the guard path got faster), and the
assertions below are about redaction/finalization, never about timing.
"""
log_path = drive / "services" / task_id / name
deadline = time.time() + timeout_sec
while time.time() < deadline:
try:
if predicate(log_path.read_bytes() if log_path.exists() else b""):
return
except OSError:
pass
time.sleep(0.1)
raise AssertionError(
f"service log {log_path} did not satisfy the wait predicate within {timeout_sec}s"
)
def _force_advanced_runtime(monkeypatch):
from ouroboros import config as cfg
@ -80,6 +104,7 @@ def test_service_logs_redact_secret_assignments(tmp_path, monkeypatch):
"readiness": {"timeout_sec": 1},
})
assert json.loads(start)["state"] in {"running", "exited"}
_wait_for_service_log(drive, "task-1", "secretlog.log", lambda b: b"OPENAI_API_KEY=" in b)
logs = json.loads(registry.execute("service_logs", {"name": "secretlog", "tail": 500}))
registry.execute("stop_service", {"name": "secretlog"})
@ -537,6 +562,7 @@ def test_stop_service_retains_live_log_when_full_blob_omitted(tmp_path, monkeypa
"cmd": [sys.executable, "-c", "print('x' * 100, flush=True)"],
"readiness": {"timeout_sec": 1},
})
_wait_for_service_log(drive, "task-oversize", "oversize.log", lambda b: len(b) > 100)
stopped = json.loads(registry.execute("stop_service", {"name": "oversize"}))
finalization = stopped["log_finalization"]
@ -846,6 +872,7 @@ def test_service_outputs_register_artifacts_on_stop(tmp_path, monkeypatch):
"readiness": {"timeout_sec": 1},
})
assert "LIGHT_MODE_BLOCKED" not in start
_wait_for_service_log(drive, "task-service-output", "artifact_service.log", lambda b: b"READY" in b)
stopped = json.loads(registry.execute("stop_service", {"name": "artifact_service"}))