cleveragents-core/tools/_phase4_telemetry.py

"""Phase 4 telemetry extraction for the implementer dispatcher.

Pulls the per-cycle metrics named in
``docs/development/auto-agents-tier-2-3-plan.md`` § Phase 4 from a
completed OpenCode session and emits a single JSONL row to a
configurable sink:

- ``run_id`` — per-cycle UUID
- ``pr_number`` — the work item's number
- ``work_group`` — ``failing_ci_pr`` / ``request_changes_pr`` /
  ``new_issue``
- ``start_ts`` / ``end_ts`` / ``wall_clock_seconds``
- ``time_to_first_edit_seconds`` — derived from the session's
  message stream when available, else ``None``
- ``subagent_max_depth`` — deepest BFS distance observed in the
  OpenCode task-tool subagent tree, sourced from the
  ``_archive_subagent_tree`` walk that runs in
  :func:`_opencode_worker.run_session_blocking`'s finally block.
  ``0`` for a flat session (no subagents), ``N > 0`` for a chain,
  ``None`` when the walk did not run (archive disabled, transport
  error, wrapper session never created)
- ``webfetch_call_count`` — count of message events whose tool name
  is ``webfetch``; ``0`` when the session never invoked one
- ``git_clone_call_count`` — count of bash invocations matching
  ``git clone`` or ``git-isolator-util`` in the session message
  stream; ``0`` when the worker never cloned
- ``validate_edit_call_count`` — count of bash invocations matching
  ``implementer_validate.py validate-edit``
- ``lint_commit_call_count`` — count of bash invocations matching
  ``implementer_validate.py lint-commit``
- ``outcome`` — worker JSON ``outcome`` field
- ``head_sha_advanced`` — ``True`` iff the worker pushed a new
  commit (post-session head_sha differs from pre-session head_sha)
- ``claim_release_seconds_after_exit`` — wall-clock between session
  exit and claim label removal
- ``orchestration_overhead_seconds`` — equals
  ``time_to_first_edit_seconds`` per the plan's definition

The extractor never raises. Every "missing data" path (no session
archive, no message stream, no head_sha drift detection) collapses
to ``None`` for the affected field; the JSONL row carries an
explicit ``null`` so an operator parsing the telemetry can see
which signal was unavailable.

Sink configuration: when ``IMPLEMENTER_DISPATCHER_PHASE4_TELEMETRY``
is set to a directory path, the dispatcher's
``post_session_action`` writes one ``{run_id}.jsonl`` file into it.
Otherwise telemetry is recorded in the cycle archive only (under
``post_session_result.phase4_telemetry``) so an operator can still
recover it post-hoc.
"""

from __future__ import annotations

import json
import logging
import os
import re
import uuid
from datetime import UTC, datetime
from pathlib import Path
from typing import Any

_logger = logging.getLogger("phase4_telemetry")


PHASE4_TELEMETRY_ENV_VAR = "IMPLEMENTER_DISPATCHER_PHASE4_TELEMETRY"


# Regex patterns for counting call shapes in the session message
# stream. Anchored to start-of-line (``re.MULTILINE``) so prose
# mentions like "the worker MUST NOT use ``git clone``" inside
# acceptance-criteria text don't get counted as actual tool
# invocations. Tool-call lines emitted by the worker terminal show
# up indented or at column 0 — we accept arbitrary leading
# whitespace, an optional shell prompt (``$`` / ``#``), and an
# optional ``Bash(`` wrapper that the OpenCode renderer prepends
# to bash invocations. The keyword (``git clone``, ``webfetch``,
# ``implementer_validate``) MUST be the first non-prefix token —
# no greedy ``.*?`` before it — so an LLM message like "the
# worker should never git clone in-session" cannot inflate the
# count. We deliberately stay liberal AFTER the keyword (any
# arguments, any quoting) because Phase 4's purpose is to
# compare order-of-magnitude, not exact frequencies.
#
# OpenCode renders bash tool invocations as ``Bash(command="..."``;
# the bash command itself often chains a ``cd ... && python3 ...``
# preamble before the validator keyword. The two-branch alternation
# below matches both:
#
# 1. ``Bash(command="..."`` wrapper — keyword may appear anywhere
#    inside the wrapped command (after ``cd ... && ``, after pipes,
#    etc.).
# 2. Bare invocation — keyword starts the line (with optional
#    ``python3 ``/path prefix), as it does in synthetic shell-prompt
#    fixtures and direct ``$ ``/``> `` prompt outputs.
#
# Both branches are anchored to start-of-line (``^[\s>$#]*``) so a
# prose mention earlier on the line can't bleed into a match. The
# anonymised session-output fixture under
# ``tests/auto_agents/fixtures/phase4-session-output-sample.txt``
# pins the regex against a representative real session.
_TOOL_LINE_ANCHOR = r"(?m)^[\s>$#]*"
_BARE_INVOCATION = r"(?:python3?\s+)?(?:[^\s]*/)?"


def _tool_line_re(keyword_re: str) -> re.Pattern[str]:
    """Compile a tool-invocation regex matching either an OpenCode
    ``Bash(command=...)`` wrapper or a bare shell invocation.

    The two-branch alternation keeps each branch independently
    anchored to start-of-line so the dispatcher cannot accidentally
    count a prose mention later in the line.
    """
    return re.compile(
        _TOOL_LINE_ANCHOR
        + r"(?:"
        + r"Bash\([^\n]*?"
        + keyword_re
        + r"|"
        + _BARE_INVOCATION
        + keyword_re
        + r")"
    )


_VALIDATE_EDIT_KEYWORD = r"implementer_validate(?:\.py)?\s+validate-edit"
_LINT_COMMIT_KEYWORD = r"implementer_validate(?:\.py)?\s+lint-commit"
_GIT_CLONE_KEYWORD = r"(?:git\s+clone|git-isolator-util)\b"
_WEBFETCH_KEYWORD = r"[Ww]ebfetch\b"

_RE_VALIDATE_EDIT = _tool_line_re(_VALIDATE_EDIT_KEYWORD)
_RE_LINT_COMMIT = _tool_line_re(_LINT_COMMIT_KEYWORD)
_RE_GIT_CLONE = _tool_line_re(_GIT_CLONE_KEYWORD)
_RE_WEBFETCH = _tool_line_re(_WEBFETCH_KEYWORD)


def extract_phase4_telemetry(
    *,
    cycle_id: str | None,
    pr_number: int,
    work_group: str,
    start_ts: str,
    end_ts: str,
    wall_clock_seconds: float | None,
    parsed_json: dict[str, Any] | None,
    raw_response: str,
    terminal_state: str,
    pre_session_head_sha: str | None,
    post_session_head_sha: str | None = None,
    subagent_max_depth: int | None = None,
    # In-cycle tier escalation extras (2026-05-12). Emitted ONLY
    # when the caller passes a non-None value — preserves byte-
    # equivalence of the row schema with the pre-feature build for
    # callers that don't know about escalation (the dispatcher's
    # legacy flag=0 path passes None / omits them).
    #
    # When flag=1, the dispatcher's escalation runner passes the
    # 0-based attempt index, the EscalationAction string, and the
    # tier hint that was sent to the worker. Analysts grouping JSONL
    # rows by ``cycle_id`` see one row per attempt with these fields
    # set; cycles produced in flag=0 mode see one row total without
    # the fields (and aggregators using ``row.get("...")`` get
    # ``None`` as the natural absent value).
    tier_attempt_index: int | None = None,
    escalation_action: str | None = None,
    escalation_tier_hint: int | None = None,
    outcome_synthesised: bool | None = None,
) -> dict[str, Any]:
    """Build a Phase 4 telemetry row from a completed cycle.

    The per-tool call counts (``webfetch_call_count``,
    ``git_clone_call_count``, etc.) are derived from ``raw_response``
    regex matching — the archive may be disabled (the test suite
    sets ``OPENCODE_WORKER_ARCHIVE_DISABLED=1`` autouse) and an absent
    archive must not stop telemetry from emitting at all. The
    ``time_to_first_edit_seconds`` field stays ``None`` for now (no
    cheap derivation path from raw text); callers can fill it in
    from the archive directly when present.

    ``subagent_max_depth`` is sourced from the dispatcher's
    SessionContext, which receives it from
    :func:`_opencode_worker._archive_subagent_tree`'s BFS walk over
    OpenCode's ``/session`` graph. ``None`` is the legacy default
    for callers that do not know the depth (direct unit tests, the
    reviewer dispatcher path before its own plumbing lands).

    Returns a dict ready for JSONL serialisation. Never raises.
    """
    outcome = ""
    if isinstance(parsed_json, dict):
        outcome = str(parsed_json.get("outcome") or "")
    head_sha_advanced: bool | None = None
    if pre_session_head_sha and post_session_head_sha:
        head_sha_advanced = bool(pre_session_head_sha != post_session_head_sha)
    raw = raw_response or ""
    row: dict[str, Any] = {
        "run_id": str(uuid.uuid4()),
        "cycle_id": cycle_id,
        "pr_number": int(pr_number) if pr_number else None,
        "work_group": work_group,
        "start_ts": start_ts,
        "end_ts": end_ts,
        "wall_clock_seconds": (
            float(wall_clock_seconds) if wall_clock_seconds is not None else None
        ),
        "time_to_first_edit_seconds": None,  # not derivable from raw text
        # ``subagent_max_depth`` is provided by the dispatcher's
        # post-session action, which reads SessionContext.subagent_max_depth
        # (sourced from _opencode_worker._archive_subagent_tree's BFS walk).
        # Direct callers that don't know the depth pass ``None`` and the
        # field stays unpopulated, same as the pre-Tier-1 behaviour.
        # Bool is excluded because ``bool`` is a subclass of ``int`` in
        # Python — ``isinstance(True, int)`` is ``True`` and would
        # otherwise pass ``True``/``False`` through as ``1``/``0``,
        # silently corrupting telemetry rows.
        "subagent_max_depth": (
            int(subagent_max_depth)
            if isinstance(subagent_max_depth, int)
            and not isinstance(subagent_max_depth, bool)
            else None
        ),
        "webfetch_call_count": _count_pattern(raw, _RE_WEBFETCH),
        "git_clone_call_count": _count_pattern(raw, _RE_GIT_CLONE),
        "validate_edit_call_count": _count_pattern(raw, _RE_VALIDATE_EDIT),
        "lint_commit_call_count": _count_pattern(raw, _RE_LINT_COMMIT),
        "outcome": outcome or terminal_state,
        "terminal_state": terminal_state,
        "head_sha_advanced": head_sha_advanced,
        "claim_release_seconds_after_exit": None,  # filled in by caller
        "orchestration_overhead_seconds": None,  # equals time_to_first_edit
    }
    # In-cycle tier escalation extras — included only when the
    # caller passes a non-None value. Legacy (flag=0) callers
    # supply nothing here, so the row schema stays byte-equivalent
    # to the pre-feature build.
    if tier_attempt_index is not None:
        row["tier_attempt_index"] = int(tier_attempt_index)
    if escalation_action is not None:
        row["escalation_action"] = str(escalation_action)
    if escalation_tier_hint is not None:
        row["escalation_tier_hint"] = int(escalation_tier_hint)
    if outcome_synthesised is not None:
        # Explicit ``bool(...)`` coercion: the kwarg is typed
        # ``bool | None`` and the ``is not None`` guard above
        # narrows it to ``bool``, but a future caller passing a
        # truthy non-bool (e.g. ``1`` from a JSON deserialiser)
        # would still land here. The coercion normalises the row
        # to a real ``bool`` for downstream JSONL consumers that
        # filter on ``row["outcome_synthesised"] is True``.
        row["outcome_synthesised"] = bool(outcome_synthesised)
    # P4: outcome_disputed — the worker emitted a success outcome
    # but no push reached origin. This is the "worker hallucinates
    # success" failure class observed live on 2026-05-13 (PR #30
    # attempts 1/3, PR #28 cycle 2 attempt 1). The predicate now
    # routes this to ESCALATE (see _implementer_escalation A2 fix),
    # but the row separately records that the worker's verdict
    # didn't match reality so an analyst can grep for the lie rate.
    outcome_lower = (outcome or "").lower()
    if outcome_lower == "resolved" and head_sha_advanced is False:
        row["outcome_disputed"] = True
    return row


def _count_pattern(haystack: str, pattern: re.Pattern[str]) -> int:
    if not haystack:
        return 0
    return len(pattern.findall(haystack))


def write_telemetry_jsonl(row: dict[str, Any]) -> Path | None:
    """Write ``row`` as a single JSONL file under the directory
    pointed at by ``IMPLEMENTER_DISPATCHER_PHASE4_TELEMETRY``.

    Returns the path on success, ``None`` when the env var is unset
    (telemetry stays in the cycle archive only) or when the write
    fails (best-effort — Phase 4 retest still produces useful data
    even with intermittent disk writes).
    """
    sink_dir = os.environ.get(PHASE4_TELEMETRY_ENV_VAR)
    if not sink_dir:
        return None
    try:
        target_dir = Path(sink_dir)
        target_dir.mkdir(parents=True, exist_ok=True)
        run_id = row.get("run_id") or str(uuid.uuid4())
        target = target_dir / f"{run_id}.jsonl"
        with target.open("a", encoding="utf-8") as f:
            json.dump(row, f, sort_keys=True)
            f.write("\n")
        return target
    except OSError as exc:
        _logger.warning(
            "phase4 telemetry write failed (%s); falling back to cycle archive only",
            exc,
        )
        return None


def now_iso() -> str:
    """ISO-8601 UTC timestamp helper. Centralised so the dispatcher
    and the telemetry row use the same clock and the same format."""
    return datetime.now(UTC).isoformat()


__all__ = (
    "PHASE4_TELEMETRY_ENV_VAR",
    "extract_phase4_telemetry",
    "now_iso",
    "write_telemetry_jsonl",
)