"""TDD — Phase 4: observability and return-dict invariants. process_mpack_index_job must return a result dict that a monitoring dashboard or alerting rule can consume without re-parsing log lines. Phase 4 invariants: 1. Return dict contains the canonical five keys (counts + timing). 2. All count values are non-negative integers. 3. mpack_size_bytes matches the byte length of what was stored. 4. elapsed_ms is a positive float. 5. The structured summary log line is emitted with index_rows, graph_rows, and elapsed. Canonical return dict keys from process_mpack_index_job: mpack_index_written — rows upserted into MusehubMPackIndex (int) byte_ranges_computed — number of byte-range entries computed (int) commit_graph_written — rows upserted into MusehubCommitGraph (int) mpack_size_bytes — raw wire size of the stored mpack (int) elapsed_ms — wall-clock duration of the job (float ms) """ from __future__ import annotations import datetime import logging import pathlib import msgpack import pytest import pytest_asyncio from httpx import AsyncClient, ASGITransport from sqlalchemy import select from sqlalchemy.ext.asyncio import AsyncSession from musehub.auth.request_signing import MSignContext, require_signed_request, optional_signed_request from musehub.db.database import get_db from musehub.db.musehub_repo_models import MusehubRepo from musehub.main import app from muse.core.object_store import write_object from muse.core.mpack import build_mpack from muse.core.paths import muse_dir from muse.core.snapshot import compute_commit_id, compute_snapshot_id from muse.core.commits import CommitRecord, write_commit from muse.core.refs import write_branch_ref from muse.core.snapshots import SnapshotRecord, write_snapshot from muse.core.types import blob_id _AUTH_CTX = MSignContext( handle="gabriel", identity_id="sha256:" + "0" * 64, is_agent=False, is_admin=True, ) _N_FILES = 8 _N_COMMITS = 4 _FILES_CHANGED = 2 _BLOB_SIZE = 128 # Canonical return dict keys for process_mpack_index_job. _REQUIRED_KEYS: frozenset[str] = frozenset({ "mpack_index_written", "byte_ranges_computed", "commit_graph_written", "mpack_size_bytes", "elapsed_ms", }) # ── fixtures ──────────────────────────────────────────────────────────────── @pytest_asyncio.fixture() async def client(db_session: AsyncSession) -> None: async def _override_get_db() -> None: yield db_session app.dependency_overrides[get_db] = _override_get_db app.dependency_overrides[require_signed_request] = lambda: _AUTH_CTX app.dependency_overrides[optional_signed_request] = lambda: _AUTH_CTX async with AsyncClient( transport=ASGITransport(app=app), base_url="https://localhost:1337", ) as c: yield c app.dependency_overrides.clear() @pytest_asyncio.fixture() async def repo(client: AsyncClient) -> None: resp = await client.post( "/api/repos", json={"owner": "gabriel", "name": "phase4-obs-test", "visibility": "public", "initialize": False}, ) assert resp.status_code in (200, 201), resp.text data = resp.json() yield data["slug"] await client.delete(f"/api/repos/{data['repoId']}") def _make_repo(tmp: pathlib.Path) -> tuple[pathlib.Path, str, dict]: tmp.mkdir(parents=True, exist_ok=True) dot = muse_dir(tmp) dot.mkdir() (dot / "repo.json").write_text('{"repo_id":"phase4-test","owner":"gabriel"}') for d in ("commits", "snapshots", "objects"): (dot / d).mkdir() (dot / "refs" / "heads").mkdir(parents=True) (dot / "HEAD").write_text("ref: refs/heads/main\n") (dot / "config.toml").write_text("") blob_ids: list[str] = [] for i in range(_N_FILES): data = f"base-{i:04d}".encode() + b"x" * _BLOB_SIZE oid = blob_id(data) write_object(tmp, oid, data) blob_ids.append(oid) base_manifest = {f"src/file_{i:04d}.py": blob_ids[i] for i in range(_N_FILES)} parent = None tip = "" ts = datetime.datetime(2026, 1, 1, tzinfo=datetime.timezone.utc) for i in range(_N_COMMITS): manifest = dict(base_manifest) for j in range(_FILES_CHANGED): idx = (i * _FILES_CHANGED + j) % _N_FILES raw = f"c{i:04d}-f{j}".encode() + b"y" * _BLOB_SIZE oid = blob_id(raw) write_object(tmp, oid, raw) manifest[f"src/file_{idx:04d}.py"] = oid sid = compute_snapshot_id(manifest) write_snapshot(tmp, SnapshotRecord(snapshot_id=sid, manifest=manifest)) msg = f"commit-{i:05d}" cid = compute_commit_id( parent_ids=[parent] if parent else [], snapshot_id=sid, message=msg, committed_at_iso=ts.isoformat(), author="gabriel", ) write_commit(tmp, CommitRecord( commit_id=cid, branch="main", snapshot_id=sid, message=msg, committed_at=ts, parent_commit_id=parent, parent2_commit_id=None, author="gabriel", metadata={}, structured_delta=None, sem_ver_bump="none", breaking_changes=[], agent_id="", model_id="", toolchain_id="", prompt_hash="", signature="", signer_key_id="", )) parent = cid tip = cid ts += datetime.timedelta(seconds=60) write_branch_ref(tmp, "main", tip) mpack = build_mpack(tmp, [tip], have=[]) return tmp, tip, mpack async def _push_mpack( repo_slug: str, mpack: dict, head: str, db_session: AsyncSession, ) -> tuple[str, int]: """Store mpack in MemoryBackend and create a mpack.index job row. Returns (job_id, stored_byte_length) so tests can verify mpack_size_bytes. """ import musehub.storage.backends as _backends_mod from datetime import datetime, timezone from musehub.core.genesis import compute_job_id as _compute_job_id from musehub.db.musehub_jobs_models import MusehubBackgroundJob repo_row = (await db_session.execute( select(MusehubRepo).where(MusehubRepo.slug == repo_slug) )).scalar_one() repo_id = repo_row.repo_id wire_bytes = msgpack.packb(mpack, use_bin_type=True) mpack_key = "sha256:" + __import__("hashlib").sha256(wire_bytes).hexdigest() n_objects = len(mpack.get("blobs") or []) backend = _backends_mod.get_backend() await backend.put_mpack(mpack_key, wire_bytes) now = datetime.now(tz=timezone.utc) job_id = _compute_job_id(repo_id, "mpack.index", now.isoformat()) db_session.add(MusehubBackgroundJob( job_id=job_id, repo_id=repo_id, job_type="mpack.index", payload={ "mpack_key": mpack_key, "pusher_id": "sha256:" + "0" * 64, "branch": "main", "head": head, "force": False, "declared_objects_count": n_objects, }, status="pending", created_at=now, attempt=0, )) await db_session.flush() return job_id, len(wire_bytes) # ── Phase 4 tests ─────────────────────────────────────────────────────────── @pytest.mark.asyncio async def test_return_dict_has_required_keys( client: AsyncClient, repo: str, tmp_path: pathlib.Path, db_session: AsyncSession, ) -> None: """Return dict contains all five canonical keys. These keys let monitoring dashboards query job results without parsing log lines. Any missing key is a regression in the observability contract. """ _, head, mpack = _make_repo(tmp_path / "repo") job_id, _ = await _push_mpack(repo, mpack, head, db_session) from musehub.services.musehub_wire import process_mpack_index_job result = await process_mpack_index_job(db_session, job_id) await db_session.commit() missing = _REQUIRED_KEYS - set(result.keys()) assert not missing, ( f"process_mpack_index_job return dict is missing keys: {missing}\n" f"Got keys: {sorted(result.keys())}" ) @pytest.mark.asyncio async def test_all_counts_are_non_negative( client: AsyncClient, repo: str, tmp_path: pathlib.Path, db_session: AsyncSession, ) -> None: """Every count value in the return dict is a non-negative integer.""" _, head, mpack = _make_repo(tmp_path / "repo") job_id, _ = await _push_mpack(repo, mpack, head, db_session) from musehub.services.musehub_wire import process_mpack_index_job result = await process_mpack_index_job(db_session, job_id) await db_session.commit() count_keys = ("mpack_index_written", "byte_ranges_computed", "commit_graph_written", "mpack_size_bytes") bad = {k: result[k] for k in count_keys if result[k] < 0} assert not bad, f"Negative count values in result: {bad}" @pytest.mark.asyncio async def test_mpack_size_bytes_matches_stored_bytes( client: AsyncClient, repo: str, tmp_path: pathlib.Path, db_session: AsyncSession, ) -> None: """mpack_size_bytes matches the byte length of what was stored in the backend.""" _, head, mpack = _make_repo(tmp_path / "repo") job_id, stored_byte_length = await _push_mpack(repo, mpack, head, db_session) from musehub.services.musehub_wire import process_mpack_index_job result = await process_mpack_index_job(db_session, job_id) await db_session.commit() assert "mpack_size_bytes" in result, f"mpack_size_bytes missing. Got: {sorted(result.keys())}" assert result["mpack_size_bytes"] == stored_byte_length, ( f"mpack_size_bytes {result['mpack_size_bytes']} != stored {stored_byte_length}" ) @pytest.mark.asyncio async def test_elapsed_ms_is_positive( client: AsyncClient, repo: str, tmp_path: pathlib.Path, db_session: AsyncSession, ) -> None: """elapsed_ms is a positive float — zero would indicate a timer bug.""" _, head, mpack = _make_repo(tmp_path / "repo") job_id, _ = await _push_mpack(repo, mpack, head, db_session) from musehub.services.musehub_wire import process_mpack_index_job result = await process_mpack_index_job(db_session, job_id) await db_session.commit() assert result["elapsed_ms"] > 0, ( f"elapsed_ms={result['elapsed_ms']} — must be positive (timer checkpoint bug?)" ) @pytest.mark.asyncio async def test_summary_log_contains_index_and_graph_counts( client: AsyncClient, repo: str, tmp_path: pathlib.Path, db_session: AsyncSession, caplog: pytest.LogCaptureFixture, ) -> None: """The ✅ done summary log line contains index_rows, graph_rows, and elapsed. Ops teams grep a single log line per job for the full result — not seven separate lines. The summary must contain these three fields so log-based alerts stay in sync with the return dict. """ _, head, mpack = _make_repo(tmp_path / "repo") job_id, _ = await _push_mpack(repo, mpack, head, db_session) from musehub.services.musehub_wire import process_mpack_index_job with caplog.at_level(logging.INFO, logger="musehub.services.musehub_wire_shared"): result = await process_mpack_index_job(db_session, job_id) await db_session.commit() summary_lines = [ r.message for r in caplog.records if "mpack.index" in r.message and "done" in r.message ] assert summary_lines, ( "No '✅ [mpack.index] done' summary log line found.\n" f"All mpack.index log lines: {[r.message for r in caplog.records if 'mpack.index' in r.message]}" ) summary = summary_lines[-1] _REQUIRED_LOG_FIELDS = ("index_rows", "graph_rows", "elapsed") missing_fields = [f for f in _REQUIRED_LOG_FIELDS if f not in summary] assert not missing_fields, ( f"Summary log line missing fields: {missing_fields}\n" f"Summary: {summary!r}" )