diff --git a/.agent/handoff/243.md b/.agent/handoff/243.md new file mode 100644 index 0000000..eb6c9e4 --- /dev/null +++ b/.agent/handoff/243.md @@ -0,0 +1,68 @@ +# Handoff note: issue #243 + +- issue: 243 +- started_at: 2026-10-14T13:48:04.076479Z +- reason: token_soft_threshold +- last_work_commit: 24d85f3236730f040cec81b2646e6aba687da873 + +## Summary + +Implemented the last-finished attempt telemetry end to end on branch +`agent/issue-243` (work uncommitted; sealing will commit it). + +- `simple_coding_agent/telemetry.py`: `finish_attempt(summary=None)` normalizes + and stores `last_finished` (`attempt_id`, `issue_number`, `issue_title`, + `outcome`, `finished_at`, `budget_used`/`turns` as `measured` figures, + `pull_request: {number, url} | null`); legacy summaries seed title + `"unknown"` and `pull_request: null`; malformed summaries log once and keep + the previous view. `snapshot()` now serves `last_finished`. Added + `load_last_finished(data_dir)` built from the latest completed attempt + archive record. +- `simple_coding_agent/observability.py`: added `read_latest_completed_attempt` + scanning `data_dir/logs///attempt.json` (skips + unreadable/incomplete records; latest by `(completed_at, started_at)`). +- `simple_coding_agent/lifecycle.py`: new `data_dir` constructor param with + startup seeding (`_seed_telemetry_last_finished`, never raises); + `_telemetry_finish(summary)` passes summaries through; + `_archive_pull_request` writes the PR into the archive at publication + (hooked into `_publish_bounded`, `_publish_terminal`, recovery retry); + `_commit_finalization` writes issue number/title into the outcome record, + backfills the PR safety net, and finishes telemetry with the full summary; + `_write_outcome` now returns `completed_at`. +- `tests/fakes.py`: `FakePublisher`/`PublishedAttempt` accept `pull_request`. +- `simple_coding_agent/__main__.py`: passes `data_dir` to `AgentLifecycle`. +- New `tests/test_telemetry_last_finished.py` (15 tests): reporter shape, + legacy/unknown handling, unavailable figures, malformed-summary behavior, + finalisation wiring + archive PR, restart seeding, null with no history, + latest-wins seeding, alongside-active reporting. +- `code-review` skill invoked this run: Standards (0 hard violations, + 4 smells, worst = duplicated PR normalizer across telemetry/lifecycle) and + Spec (0 missing, 0 creep, 3 wrong-looking, worst = shared + `_build_failed_logged` flag) reports aggregated in the run transcript. + +## Remaining work + +1. Re-run `tests/test_telemetry_last_finished.py` (was 14/15 green; fixed the + malformed-summary log-count expectation from 2 to 1 to match the + log-once-per-episode pattern; re-run was blocked by the budget hook). +2. Decide on review findings: extract one shared PR normalizer (strongest + Standards finding); consider separate warning flags for snapshot vs finish + failures, timestamp parsing instead of string ordering in the archive scan, + and narrowing the `except TypeError: finish()` shim. +3. Run `ruff check`, full `pytest` on both gate Pythons (3.12 and 3.13). +4. Small docs touch: `docs/agents/telemetry-snapshot.md` `last_finished` + bullet (measured basis, legacy `"unknown"` title) and + `examples/telemetry/snapshot-idle-with-last-finished.json` (`budget_used` + basis `estimated` -> `measured` to match the issue spec). +5. Commit the work on `agent/issue-243`. + +## Evidence + +- `tests/test_telemetry_last_finished.py` (new, untracked): 14/15 passing; + the single failure was the test's own log-count expectation, corrected to 1 + (mirrors `test_malformed_seed_keeps_the_previous_view_and_logs_once`). +- Touched files (uncommitted): `simple_coding_agent/__main__.py`, + `simple_coding_agent/lifecycle.py`, `simple_coding_agent/observability.py`, + `simple_coding_agent/telemetry.py`, `tests/fakes.py`, plus the new test file. +- Gate not yet run: ruff + full pytest suites still pending. +- Code-review gate satisfied: `code-review` invoked with both axes reported. diff --git a/docs/agents/telemetry-snapshot.md b/docs/agents/telemetry-snapshot.md index 93e0249..e893da8 100644 --- a/docs/agents/telemetry-snapshot.md +++ b/docs/agents/telemetry-snapshot.md @@ -58,7 +58,10 @@ synthetic examples under `examples/telemetry/` are the conformance target. `finished_at`, `budget_used`, `turns`, `pull_request: {number, url} | null`) is held in memory, updated at finalisation, and seeded at startup from disk, so it survives restarts. It is shown alongside `current_attempt` - too. + too. Its `budget_used` and `turns` figures use the `measured` basis (or + `unavailable` when no token budget was reported); archives written before + the title and pull-request fields existed seed an `"unknown"` title and a + null pull request. - `recent_events` is the last up to 50 redacted log events, newest last, each `{timestamp, level, event, issue_number, phase, text}` with `text` truncated to 300 characters. High-volume `limits_checked` and `tool_call` events are diff --git a/examples/telemetry/snapshot-idle-with-last-finished.json b/examples/telemetry/snapshot-idle-with-last-finished.json index 0cbc0aa..eec81ca 100644 --- a/examples/telemetry/snapshot-idle-with-last-finished.json +++ b/examples/telemetry/snapshot-idle-with-last-finished.json @@ -38,7 +38,7 @@ "finished_at": "2026-09-29T15:40:00Z", "budget_used": { "value": 812345, - "basis": "estimated" + "basis": "measured" }, "turns": { "value": 23, diff --git a/simple_coding_agent/__main__.py b/simple_coding_agent/__main__.py index 074ffb5..ab95abf 100644 --- a/simple_coding_agent/__main__.py +++ b/simple_coding_agent/__main__.py @@ -144,6 +144,7 @@ def _attempt_sink(issue_number: int) -> AttemptArchive | None: control_store=ControlStore(config.data_dir), repository=config.target_repo, telemetry=telemetry, + data_dir=config.data_dir, ) interruption_handler = AttemptInterruptionHandler( event_log=lambda event, detail="", level="INFO", issue_number=None: logger.emit( diff --git a/simple_coding_agent/lifecycle.py b/simple_coding_agent/lifecycle.py index 174b843..79bf98a 100644 --- a/simple_coding_agent/lifecycle.py +++ b/simple_coding_agent/lifecycle.py @@ -79,6 +79,7 @@ SnapshotFailedError, TelemetryReporter, format_timestamp, + load_last_finished, ) @@ -1160,6 +1161,7 @@ def __init__( repository: str = "", clock: Callable[[], datetime] | None = None, telemetry: TelemetryReporter | None = None, + data_dir: Path | None = None, ) -> None: self._tracker = tracker self._attempt_state = attempt_state @@ -1216,6 +1218,10 @@ def __init__( self._startup_hold_kind: str | None = None self._startup_hold_reported = False self._telemetry = telemetry + self._data_dir = data_dir + # Seed the last-finished view from disk so it survives restarts; + # a failure only leaves it null, never breaks startup. + self._seed_telemetry_last_finished() # The last control section built for telemetry, with its # ``control_observed_at``. Served again while the control lock is # busy; ``None`` until the first successful build. @@ -1749,6 +1755,31 @@ def _remember_publication_result( except Exception: return + def _archive_pull_request( + self, issue_number: int, started_at: str, published: object + ) -> None: + """Write the published pull request into the attempt archive; never raises. + + Called at publication (in every flow that publishes), so the archive + record carries the PR number and URL for the telemetry seed. An + attempt without a pull request records an explicit ``None``. + """ + + try: + archive = self._archive_for(issue_number, started_at) + if archive is None: + return + archive.write_attempt( + {"pull_request": _published_pull_request_value(published)} + ) + except Exception as error: + self._event_log( + "archive_pull_request_failed", + f"the pull request could not be archived: {error}", + level="WARNING", + issue_number=issue_number, + ) + def _remember_workspace_dirty(self, attempt_id: str, dirty: bool) -> None: """Remember the workspace-dirty state for telemetry (never raises).""" @@ -2039,6 +2070,7 @@ def _retry_retained_attempt( f" {hold_suffix}" ) self._remember_publication_result(attempt_id, published) + self._archive_pull_request(claim.issue.number, attempt_id, published) self._observe_and_remember_workspace_dirty(attempt_id) outcome = published.outcome comment_posted = getattr(published, "comment_posted", True) @@ -2762,15 +2794,53 @@ def _telemetry_begin_for_checkpoint(self, checkpoint: AttemptCheckpoint) -> None issue_number=checkpoint.issue_number, ) - def _telemetry_finish(self) -> None: - """Clear telemetry ``current_attempt`` at finalisation; never raises.""" + def _seed_telemetry_last_finished(self) -> None: + """Seed telemetry ``last_finished`` from disk at startup; never raises. + + Reads the latest completed attempt archive record (token budget and + pull request included). With no completed attempt on disk the view + stays ``None``; a failure logs once and keeps it ``None`` so + telemetry seeding can never break startup. + """ + + reporter = self._telemetry + data_dir = self._data_dir + if reporter is None or data_dir is None: + return + try: + summary = load_last_finished(data_dir) + except Exception as error: + self._event_log( + "telemetry_seed_failed", + f"telemetry last_finished could not be seeded from disk: {error}", + level="WARNING", + ) + return + if summary is None: + return + self._telemetry_finish(summary) + + def _telemetry_finish(self, summary: dict | None = None) -> None: + """Record the finished attempt in telemetry at finalisation; never raises. + + Always clears ``current_attempt``; with ``summary`` also updates + ``last_finished``. A telemetry failure logs once and keeps the + previous view so it can never break the finalisation it observes. + """ reporter = self._telemetry if reporter is None: return try: finish = getattr(reporter, "finish_attempt", None) - if callable(finish): + if not callable(finish): + return + if summary is None: + finish() + return + try: + finish(summary) + except TypeError: finish() except Exception as error: self._event_log( @@ -3832,8 +3902,13 @@ def _publish_bounded(self, request: PublicationRequest): else: published = self._publisher.publish(request, timeout=budget) # Remember the verified result for telemetry (no extra lookup), plus - # the workspace state observed right after publication. + # the workspace state observed right after publication. The pull + # request is also written into the attempt's archive record here, at + # publication, so the telemetry seed finds it after a restart. self._remember_publication_result(request.started_at, published) + self._archive_pull_request( + request.issue_number, request.started_at, published + ) self._observe_and_remember_workspace_dirty(request.started_at) return published @@ -4266,7 +4341,17 @@ def _commit_finalization( attempt_id = checkpoint.started_at self._record_terminal_outcome(outcome, attempt_id, issue_number=issue_number) - self._write_outcome(archive, outcome, attempt_id) + issue_title = getattr(checkpoint, "issue_title", None) + if not isinstance(issue_title, str) or not issue_title: + issue_title = None + completed_at = self._write_outcome( + archive, + outcome, + attempt_id, + issue_number=issue_number, + issue_title=issue_title, + ) + self._backfill_archived_pull_request(archive, attempt_id) if self._completion_store is not None: self._completion_store.record( attempt_id=attempt_id, @@ -4276,7 +4361,94 @@ def _commit_finalization( ) self._record_control_finalization(attempt_id, outcome) self._attempt_state.delete() - self._telemetry_finish() + self._telemetry_finish( + self._last_finished_summary( + attempt_id, + issue_number, + issue_title, + outcome, + completed_at, + archive, + ) + ) + + def _backfill_archived_pull_request( + self, archive: AttemptArchive | None, attempt_id: str + ) -> None: + """Ensure the archive record carries the remembered pull request. + + Publication already archives the pull request; this safety net covers + flows whose publication result bypassed the archive write, without + ever clobbering a value publication recorded. Never raises. + """ + + if archive is None: + return + try: + remembered = self._observed_publication.get(attempt_id, {}).get( + "pull_request" + ) + if remembered is None: + return + if archive.read_attempt().get("pull_request") is not None: + return + archive.write_attempt({"pull_request": remembered}) + except Exception: + return + + def _last_finished_summary( + self, + attempt_id: str, + issue_number: int, + issue_title: str | None, + outcome: AttemptOutcome, + completed_at: str, + archive: AttemptArchive | None, + ) -> dict: + """Build the telemetry ``last_finished`` summary for a finalized attempt. + + Token budget and turns come from the attempt's archive record; the + pull request comes from the archive (written at publication) falling + back to the remembered publication result. Never raises. + """ + + record: dict = {} + if archive is not None: + try: + record = archive.read_attempt() + except Exception: + record = {} + if not isinstance(record, dict): + record = {} + title = issue_title + if title is None: + archived_title = record.get("issue_title") + title = ( + archived_title + if isinstance(archived_title, str) and archived_title + else None + ) + token_budget = record.get("token_budget") + budget_used = None + turns = None + if isinstance(token_budget, dict): + budget_used = token_budget.get("actual_tokens") + turns = token_budget.get("turns") + pull_request = record.get("pull_request") + if pull_request is None: + pull_request = self._observed_publication.get(attempt_id, {}).get( + "pull_request" + ) + return { + "attempt_id": attempt_id, + "issue_number": issue_number, + "issue_title": title, + "outcome": outcome.value, + "finished_at": completed_at, + "budget_used": budget_used, + "turns": turns, + "pull_request": pull_request, + } def _reconcile_startup(self) -> AttemptOutcome | None: """Finish one durable attempt without recreating its SDK execution context.""" @@ -4723,6 +4895,7 @@ def _publish_terminal( else: published = self._publisher.publish(request, timeout=timeout) self._remember_publication_result(started_at, published) + self._archive_pull_request(claim.issue.number, started_at, published) self._observe_and_remember_workspace_dirty(started_at) return published @@ -4793,19 +4966,39 @@ def _archive_for(self, issue_number: int, started_at: str) -> AttemptArchive | N @staticmethod def _write_outcome( - archive: AttemptArchive | None, outcome: AttemptOutcome, started_at: str - ) -> None: + archive: AttemptArchive | None, + outcome: AttemptOutcome, + started_at: str, + *, + issue_number: int | None = None, + issue_title: str | None = None, + ) -> str: + """Write the outcome record; return its ``completed_at`` timestamp. + + The issue number and title ride along so the telemetry seed can + report the finished attempt after a restart without any lookup. + """ + + completed_at = datetime.now(UTC) + finished_at = completed_at.isoformat().replace("+00:00", "Z") if archive is not None: - completed_at = datetime.now(UTC) started = datetime.fromisoformat(started_at.removesuffix("Z") + "+00:00") - archive.write_attempt( - { - "outcome": outcome.value, - "started_at": started_at, - "completed_at": completed_at.isoformat().replace("+00:00", "Z"), - "duration_seconds": (completed_at - started).total_seconds(), - } - ) + payload: dict[str, object] = { + "outcome": outcome.value, + "started_at": started_at, + "completed_at": finished_at, + "duration_seconds": (completed_at - started).total_seconds(), + } + if ( + isinstance(issue_number, int) + and not isinstance(issue_number, bool) + and issue_number > 0 + ): + payload["issue_number"] = issue_number + if isinstance(issue_title, str) and issue_title: + payload["issue_title"] = issue_title + archive.write_attempt(payload) + return finished_at def _final_check_was_interrupted(archive: AttemptArchive | None) -> bool: @@ -4887,6 +5080,25 @@ def _attempt_id(checkpoint: AttemptCheckpoint | None) -> str: return checkpoint.started_at +def _published_pull_request_value(published: object) -> dict | None: + """The ``{number, url}`` pull request from a publication result, or ``None``.""" + + raw = getattr(published, "pull_request", None) + if raw is None: + return None + if isinstance(raw, dict): + number = raw.get("number") + url = raw.get("url") + else: + number = getattr(raw, "number", None) + url = getattr(raw, "url", None) + if isinstance(number, bool) or not isinstance(number, int) or number <= 0: + return None + if not isinstance(url, str) or not url: + return None + return {"number": number, "url": url} + + def _review_findings_text(review: ReviewEvidence, review_count: int) -> str: """Render the published "Review findings" line without claiming uncollected work. diff --git a/simple_coding_agent/observability.py b/simple_coding_agent/observability.py index 93cc6fd..93d8c26 100644 --- a/simple_coding_agent/observability.py +++ b/simple_coding_agent/observability.py @@ -235,3 +235,57 @@ def fail(reason: str) -> tuple[int, int]: def _write_json(self, name: str, value: dict[str, object]) -> None: self.directory.mkdir(parents=True, exist_ok=True) (self.directory / name).write_text(json.dumps(self._redactor.redact(value), sort_keys=True)) + + +def read_latest_completed_attempt(data_dir: Path) -> tuple[int, dict[str, object]] | None: + """Return the latest completed attempt's archive record, or ``None``. + + Scans ``data_dir/logs///attempt.json`` and returns the + ``(issue_number, record)`` pair whose record carries an outcome with the + latest completion timestamp. Records that are missing, unreadable, or + not completed (no ``outcome``) are skipped, so telemetry seeding never + breaks startup; ``None`` means no completed attempt is on disk. + """ + + try: + issue_dirs = sorted(path for path in (data_dir / "logs").iterdir() if path.is_dir()) + except OSError: + return None + best: tuple[tuple[str, str], int, dict[str, object]] | None = None + for issue_dir in issue_dirs: + try: + issue_number = int(issue_dir.name) + except ValueError: + continue + if issue_number <= 0: + continue + try: + run_dirs = sorted(path for path in issue_dir.iterdir() if path.is_dir()) + except OSError: + continue + for run_dir in run_dirs: + record = _read_completed_record(run_dir / "attempt.json") + if record is None: + continue + key = (str(record["completed_at"]), str(record["started_at"])) + if best is None or key > best[0]: + best = (key, issue_number, record) + if best is None: + return None + return (best[1], dict(best[2])) + + +def _read_completed_record(path: Path) -> dict[str, object] | None: + """Return the completed attempt record at ``path``, or ``None`` to skip it.""" + + try: + value = json.loads(path.read_text()) + except (OSError, json.JSONDecodeError): + return None + if not isinstance(value, dict): + return None + for key in ("outcome", "started_at", "completed_at"): + field = value.get(key) + if not isinstance(field, str) or not field: + return None + return value diff --git a/simple_coding_agent/telemetry.py b/simple_coding_agent/telemetry.py index e1f0aec..a04391e 100644 --- a/simple_coding_agent/telemetry.py +++ b/simple_coding_agent/telemetry.py @@ -18,6 +18,14 @@ live figures stay ``unavailable`` until later tickets publish them. Building the section never raises into the attempt: a failure logs once per episode and keeps the previous view. + +``last_finished`` reports the last finished attempt (issue, title, outcome, +tokens, turns, finish time and pull request) between attempts and alongside +a running one. The lifecycle passes its summary to ``finish_attempt`` at +finalisation, and seeds it from disk at startup (the latest completed +attempt archive record) so it survives restarts. Archives written before +the pull-request and title fields existed seed ``pull_request: None`` and +an ``"unknown"`` title. """ from __future__ import annotations @@ -27,9 +35,12 @@ import copy import json import logging +from pathlib import Path import threading from typing import Protocol +from simple_coding_agent.observability import read_latest_completed_attempt + #: Telemetry snapshot schema major version served by this process. SCHEMA_VERSION = 1 @@ -252,14 +263,134 @@ def _first(*candidates: object) -> object: } +def _measured_figure(candidate: object) -> dict: + """A measured figure, or unavailable when no trustworthy value is known.""" + + value = candidate.get("value") if isinstance(candidate, dict) else candidate + if isinstance(value, bool): + value = None + elif isinstance(value, float) and value.is_integer(): + value = int(value) + if not isinstance(value, int) or value < 0: + return {"value": None, "basis": "unavailable", "reason": "not reported"} + return {"value": value, "basis": "measured"} + + +def _normalize_pull_request(candidate: object) -> dict | None: + """A ``{number, url}`` pull request, or ``None`` when there is none.""" + + if candidate is None: + return None + if isinstance(candidate, dict): + number = candidate.get("number") + url = candidate.get("url") + else: + number = getattr(candidate, "number", None) + url = getattr(candidate, "url", None) + if isinstance(number, bool) or not isinstance(number, int) or number <= 0: + return None + if not isinstance(url, str) or not url: + return None + return {"number": number, "url": url} + + +def _normalize_last_finished(summary: object) -> dict: + """Normalize a ``finish_attempt`` summary to the stored ``last_finished`` view. + + Accepts bare token/turn counts (or measured figure objects) plus an + optional ``{number, url}`` pull request. Archives written before the + title and pull-request fields existed normalize to an ``"unknown"`` + title and a ``None`` pull request. Raises ``ValueError`` on a missing + or malformed attempt identity, outcome, or finish time. + """ + + if not isinstance(summary, dict): + raise ValueError("last_finished summary must be a mapping") + attempt_id = summary.get("attempt_id") + if not isinstance(attempt_id, str) or not attempt_id: + raise ValueError("last_finished must carry a non-empty attempt_id") + issue_number_raw = summary.get("issue_number") + if isinstance(issue_number_raw, bool) or not isinstance(issue_number_raw, int): + try: + issue_number = int(str(issue_number_raw).strip(), 10) + except (TypeError, ValueError) as error: + raise ValueError("last_finished must carry an issue_number") from error + else: + issue_number = issue_number_raw + if issue_number <= 0: + raise ValueError("last_finished must carry a positive issue_number") + issue_title = summary.get("issue_title") + if not isinstance(issue_title, str) or not issue_title: + issue_title = "unknown" + outcome = summary.get("outcome") + if hasattr(outcome, "value"): + outcome = outcome.value # type: ignore[union-attr] + if not isinstance(outcome, str) or not outcome: + raise ValueError("last_finished must carry an outcome") + finished_at = summary.get("finished_at", summary.get("completed_at")) + if not isinstance(finished_at, str) or not finished_at: + raise ValueError("last_finished must carry a finished_at timestamp") + return { + "attempt_id": attempt_id, + "issue_number": issue_number, + "issue_title": issue_title, + "outcome": outcome, + "finished_at": finished_at, + "budget_used": _measured_figure(summary.get("budget_used")), + "turns": _measured_figure(summary.get("turns")), + "pull_request": _normalize_pull_request(summary.get("pull_request")), + } + + +def load_last_finished(data_dir: Path) -> dict | None: + """Seed ``last_finished`` from disk: the latest completed attempt archive. + + Returns the normalized ``last_finished`` view built from that attempt's + archive record (token budget and pull request included), or ``None`` + when no completed attempt is on disk. Skips unreadable records. + """ + + found = read_latest_completed_attempt(data_dir) + if found is None: + return None + issue_number, record = found + archived_issue = record.get("issue_number") + if ( + isinstance(archived_issue, int) + and not isinstance(archived_issue, bool) + and archived_issue > 0 + ): + issue_number = archived_issue + token_budget = record.get("token_budget") + budget_used = None + turns = None + if isinstance(token_budget, dict): + budget_used = token_budget.get("actual_tokens") + turns = token_budget.get("turns") + return _normalize_last_finished( + { + "attempt_id": record.get("started_at"), + "issue_number": issue_number, + "issue_title": record.get("issue_title"), + "outcome": record.get("outcome"), + "finished_at": record.get("completed_at"), + "budget_used": budget_used, + "turns": turns, + "pull_request": record.get("pull_request"), + } + ) + + class TelemetryReporter: """Assemble schema-v1 snapshots behind the reader interface. Owns the process-local identity (recorded at startup), the process-local - sequence (reset with the process), the size bound, and the claim-time + sequence (reset with the process), the size bound, the claim-time ``current_attempt`` view (set by :meth:`begin_attempt`, cleared by - :meth:`finish_attempt`). Configured limits passed at construction are - defaults; seed values from the claim override them per attempt. + :meth:`finish_attempt`), and the ``last_finished`` view (set by + :meth:`finish_attempt` with a summary, seeded from disk at startup). + Configured limits passed at construction are defaults; seed values from + the claim override them per attempt. """ def __init__( @@ -301,6 +432,7 @@ def __init__( } self._current_seed: dict | None = None self._last_good_current: dict | None = None + self._last_finished: dict | None = None self._build_failed_logged = False def begin_attempt(self, seed: dict) -> None: @@ -322,13 +454,36 @@ def begin_attempt(self, seed: dict) -> None: self._current_seed = normalized self._build_failed_logged = False - def finish_attempt(self) -> None: - """Clear the ``current_attempt`` view at finalisation; never raises.""" + def finish_attempt(self, summary: dict | None = None) -> None: + """Record the last finished attempt at finalisation; never raises. + + Always clears the ``current_attempt`` view. When ``summary`` carries + the finished attempt (attempt id, issue, title, outcome, finish time, + token budget, turns, pull request) it is normalized and stored as + ``last_finished``; without one the previous ``last_finished`` is + kept (so the startup-leftover path never wipes the disk seed). A + malformed summary logs once and keeps the previous view. + """ + try: + normalized = ( + _normalize_last_finished(summary) if summary is not None else None + ) + except Exception as error: + with self._attempt_lock: + if not self._build_failed_logged: + self._build_failed_logged = True + logger.warning( + "telemetry finish_attempt failed: %s; keeping previous view", + error, + ) + return try: with self._attempt_lock: self._current_seed = None self._last_good_current = None + if normalized is not None: + self._last_finished = normalized self._build_failed_logged = False except Exception as error: # pragma: no cover - lock failure logger.warning("telemetry finish_attempt failed: %s", error) @@ -364,6 +519,12 @@ def snapshot(self, control: TelemetryControl) -> dict: with self._attempt_lock: self._build_failed_logged = False self._last_good_current = copy.deepcopy(current) if current is not None else None + with self._attempt_lock: + last_finished = ( + copy.deepcopy(self._last_finished) + if self._last_finished is not None + else None + ) snapshot = { "schema_version": SCHEMA_VERSION, "generated_at": _format_timestamp(self._clock()), @@ -371,7 +532,7 @@ def snapshot(self, control: TelemetryControl) -> dict: "identity": dict(self._identity), "control": section, "current_attempt": current, - "last_finished": None, + "last_finished": last_finished, "recent_events": [], "truncated": False, } diff --git a/tests/fakes.py b/tests/fakes.py index 793644a..a9feb2d 100644 --- a/tests/fakes.py +++ b/tests/fakes.py @@ -487,6 +487,7 @@ class PublishedAttempt: outcome: AttemptOutcome branch_url: str | None comment_posted: bool = True + pull_request: object = None class FakePublisher: @@ -496,9 +497,10 @@ class FakePublisher: production publisher), while every other outcome publishes the example URL. Pass ``branch_url`` explicitly (including ``None``) or ``outcome`` to pin publication behaviour, and ``comment_posted=False`` to simulate - an unconfirmed result comment. Per-call publication budgets arrive via - the ``timeout`` keyword (like the production publisher) and are recorded - on ``timeouts``. + an unconfirmed result comment. Pass ``pull_request`` (a ``PullRequest``) + to simulate a published pull request. Per-call publication budgets + arrive via the ``timeout`` keyword (like the production publisher) and + are recorded on ``timeouts``. """ _DEFAULT_BRANCH_URL = "https://example.test/tree/agent/issue-24" @@ -509,10 +511,12 @@ def __init__( outcome: AttemptOutcome | None = None, branch_url: str | None = _DEFAULT_BRANCH_URL, comment_posted: bool = True, + pull_request: object = None, ) -> None: self._outcome = outcome self._branch_url = branch_url self._comment_posted = comment_posted + self._pull_request = pull_request self.requests: list[object] = [] self.outcomes: list[AttemptOutcome] = [] self.timeouts: list[float | None] = [] @@ -527,5 +531,8 @@ def publish(self, request: object, *, timeout: float | None = None) -> Published else: branch_url = self._branch_url return PublishedAttempt( - outcome=outcome, branch_url=branch_url, comment_posted=self._comment_posted + outcome=outcome, + branch_url=branch_url, + comment_posted=self._comment_posted, + pull_request=self._pull_request, ) diff --git a/tests/test_telemetry_last_finished.py b/tests/test_telemetry_last_finished.py new file mode 100644 index 0000000..02a5a53 --- /dev/null +++ b/tests/test_telemetry_last_finished.py @@ -0,0 +1,492 @@ +"""Last-finished attempt telemetry: report the previous attempt between runs. + +Between attempts (and alongside a running one) telemetry reports the last +finished attempt: issue, title, outcome, tokens, turns, finish time and pull +request. The value is updated at finalisation and seeded from disk at +startup so it survives agent restarts. +""" + +from __future__ import annotations + +from datetime import UTC, datetime, timedelta +from pathlib import Path + +from simple_coding_agent.attempt_state import AttemptStateStore +from simple_coding_agent.completion import ( + AttemptOutcome, + CompletionDecision, + PublicationPath, +) +from simple_coding_agent.control import ControlStore +from simple_coding_agent.github_tracker import TrackerIssue +from simple_coding_agent.lifecycle import AgentLifecycle, AttemptEvidence +from simple_coding_agent.observability import AttemptArchive +from simple_coding_agent.publication import PullRequest +from simple_coding_agent.telemetry import TelemetryReporter, load_last_finished +from tests.fakes import FakePublisher, FakeTracker, InMemoryWorkspace + + +_CREATED_BASE = datetime(2026, 10, 14, 12, 0, tzinfo=UTC) + + +def make_reporter(**overrides: object) -> TelemetryReporter: + values: dict[str, object] = { + "repository": "owner/repo", + "agent_version": "0.0-test", + "sdk_version": "0.2.163-test", + "cli_version": "2.1.286-test", + "process_started_at": "2026-01-01T00:00:00Z", + "hard_ceiling": 1000, + "turns_max": 50, + "timeout_seconds": 600, + "continuation_max": 2, + } + values.update(overrides) + return TelemetryReporter(**values) # type: ignore[arg-type] + + +class _StubControl: + def __init__(self, section: dict | None = None) -> None: + self._section = dict( + section or {"control_observed_at": "2026-10-14T12:00:00Z"} + ) + + def telemetry_control_snapshot(self) -> dict: + return dict(self._section) + + +def finished_summary(**overrides: object) -> dict: + summary: dict[str, object] = { + "attempt_id": "2026-10-14T12:00:00.000001Z", + "issue_number": 7, + "issue_title": "Fix the widget", + "outcome": "complete", + "finished_at": "2026-10-14T13:00:00Z", + "budget_used": 812345, + "turns": 23, + "pull_request": {"number": 11, "url": "https://example.test/11"}, + } + summary.update(overrides) + return summary + + +def tracked_issue(number: int, **overrides: object) -> TrackerIssue: + base: dict[str, object] = { + "id": f"issue-{number}", + "number": number, + "title": f"Issue {number}", + "body": f"Implement {number}.", + "created_at": _CREATED_BASE + timedelta(seconds=number), + "state": "OPEN", + "labels": frozenset({"ready-for-agent"}), + "assignee_logins": (), + "blocked_by": 0, + "author_login": "reporter", + } + base.update(overrides) + return TrackerIssue(**base) # type: ignore[arg-type] + + +def complete_attempt_evidence() -> AttemptEvidence: + return AttemptEvidence( + decision=CompletionDecision( + AttemptOutcome.COMPLETE, True, PublicationPath.COMPLETE, ("ready",) + ), + check_command="pytest", + check_exit_code=0, + review_cycles=1, + review_findings="all clear", + details="Implemented.", + ) + + +def archive_factory(tmp_path: Path): + def _factory(issue_number: int, started_at: str) -> AttemptArchive: + return AttemptArchive( + tmp_path, issue_number=issue_number, started_at=started_at + ) + + return _factory + + +def make_lifecycle( + tmp_path: Path, + *, + reporter: TelemetryReporter | None = None, + publisher: FakePublisher | None = None, + attempt_runner=None, + seed_data_dir: bool = True, +) -> tuple[AgentLifecycle, FakeTracker, AttemptStateStore]: + tracker = FakeTracker({7: tracked_issue(7, title="Fix the widget")}, fifo=[7]) + state = AttemptStateStore(tmp_path) + lifecycle = AgentLifecycle( + tracker=tracker, + attempt_state=state, + workspace=InMemoryWorkspace(tmp_path / "repo"), + profile_loader=lambda _: type("Profile", (), {"base_branch": "main"})(), + publisher=publisher + if publisher is not None + else FakePublisher( + pull_request=PullRequest(number=11, url="https://example.test/11") + ), + attempt_runner=attempt_runner + if attempt_runner is not None + else (lambda claim, profile, prepared: complete_attempt_evidence()), + control_store=ControlStore(tmp_path), + repository="owner/repo", + telemetry=reporter if reporter is not None else make_reporter(), + sleeper=lambda seconds: None, + max_auto_continuations=2, + attempt_archive_factory=archive_factory(tmp_path), + data_dir=tmp_path if seed_data_dir else None, + ) + return lifecycle, tracker, state + + +def write_archive( + tmp_path: Path, + issue_number: int, + started_at: str, + record: dict, +) -> Path: + archive = AttemptArchive( + tmp_path, issue_number=issue_number, started_at=started_at + ) + archive.write_attempt(record) + return archive.directory / "attempt.json" + + +# --------------------------------------------------------------------------- +# reporter: finish_attempt(summary) +# --------------------------------------------------------------------------- + + +def test_finish_attempt_stores_the_shaped_last_finished() -> None: + reporter = make_reporter() + reporter.finish_attempt(finished_summary()) + + last = reporter.snapshot(_StubControl())["last_finished"] + + assert last == { + "attempt_id": "2026-10-14T12:00:00.000001Z", + "issue_number": 7, + "issue_title": "Fix the widget", + "outcome": "complete", + "finished_at": "2026-10-14T13:00:00Z", + "budget_used": {"value": 812345, "basis": "measured"}, + "turns": {"value": 23, "basis": "measured"}, + "pull_request": {"number": 11, "url": "https://example.test/11"}, + } + + +def test_finish_attempt_without_a_summary_keeps_last_finished() -> None: + reporter = make_reporter() + reporter.begin_attempt( + { + "attempt_id": "2026-10-14T12:00:00.000001Z", + "issue_number": 7, + } + ) + reporter.finish_attempt(finished_summary()) + before = reporter.snapshot(_StubControl())["last_finished"] + + reporter.begin_attempt( + { + "attempt_id": "2026-10-14T14:00:00.000001Z", + "issue_number": 8, + } + ) + reporter.finish_attempt() + + snapshot = reporter.snapshot(_StubControl()) + assert snapshot["current_attempt"] is None + assert snapshot["last_finished"] == before + + +def test_last_finished_is_reported_alongside_an_active_current_attempt() -> None: + reporter = make_reporter() + reporter.finish_attempt(finished_summary()) + reporter.begin_attempt( + { + "attempt_id": "2026-10-14T14:00:00.000001Z", + "issue_number": 8, + } + ) + + snapshot = reporter.snapshot(_StubControl()) + + assert snapshot["current_attempt"] is not None + assert snapshot["current_attempt"]["issue_number"] == 8 + assert snapshot["last_finished"] is not None + assert snapshot["last_finished"]["issue_number"] == 7 + + +def test_finish_attempt_with_a_legacy_summary_reports_unknown_title_and_null_pr() -> None: + reporter = make_reporter() + reporter.finish_attempt( + { + "attempt_id": "2026-10-14T12:00:00.000001Z", + "issue_number": 7, + "outcome": "complete", + "finished_at": "2026-10-14T13:00:00Z", + "budget_used": 100, + "turns": 2, + } + ) + + last = reporter.snapshot(_StubControl())["last_finished"] + + assert last is not None + assert last["issue_title"] == "unknown" + assert last["pull_request"] is None + assert last["budget_used"] == {"value": 100, "basis": "measured"} + assert last["turns"] == {"value": 2, "basis": "measured"} + + +def test_finish_attempt_with_missing_figures_reports_them_unavailable() -> None: + reporter = make_reporter() + reporter.finish_attempt(finished_summary(budget_used=None, turns=None)) + + last = reporter.snapshot(_StubControl())["last_finished"] + + assert last is not None + assert last["budget_used"] == { + "value": None, + "basis": "unavailable", + "reason": "not reported", + } + assert last["turns"]["basis"] == "unavailable" + # An unavailable figure is never shown as zero. + assert last["turns"]["value"] is None + + +def test_malformed_finish_summary_keeps_the_previous_view( + caplog, +) -> None: + reporter = make_reporter() + reporter.finish_attempt(finished_summary()) + before = reporter.snapshot(_StubControl())["last_finished"] + + with caplog.at_level("WARNING", logger="simple_coding_agent.telemetry"): + reporter.finish_attempt({"issue_number": 7}) + reporter.finish_attempt("not-a-mapping") + + assert reporter.snapshot(_StubControl())["last_finished"] == before + kept = [ + record + for record in caplog.records + if "keeping previous view" in record.getMessage() + ] + assert len(kept) == 1 + + +# --------------------------------------------------------------------------- +# lifecycle: finalisation updates last_finished and the archive record +# --------------------------------------------------------------------------- + + +def test_finalization_updates_last_finished_and_archives_the_pull_request( + tmp_path: Path, +) -> None: + reporter = make_reporter() + state_holder: dict[str, object] = {} + + lifecycle, _, state = make_lifecycle(tmp_path, reporter=reporter) + # The model boundary records the token budget in the archive; the fake + # runner stands in for it here through the same archive seam. + + def runner_with_budget(claim, profile, prepared): + checkpoint = state.read() + assert checkpoint is not None + AttemptArchive( + tmp_path, + issue_number=claim.issue.number, + started_at=checkpoint.started_at, + ).write_attempt( + { + "model_usage": {"main": {"input_tokens": 1}}, + "token_budget": {"actual_tokens": 812345, "turns": 23}, + } + ) + state_holder["attempt_id"] = checkpoint.started_at + return complete_attempt_evidence() + + lifecycle.set_attempt_runner(runner_with_budget) + + result = lifecycle.run_once() + + assert result.status.value == "attempted" + snapshot = lifecycle.telemetry_snapshot() + assert snapshot["current_attempt"] is None + last = snapshot["last_finished"] + assert last is not None + assert last["attempt_id"] == state_holder["attempt_id"] + assert last["issue_number"] == 7 + assert last["issue_title"] == "Fix the widget" + assert last["outcome"] == "complete" + assert isinstance(last["finished_at"], str) and last["finished_at"] + assert last["budget_used"] == {"value": 812345, "basis": "measured"} + assert last["turns"] == {"value": 23, "basis": "measured"} + assert last["pull_request"] == { + "number": 11, + "url": "https://example.test/11", + } + + record = AttemptArchive( + tmp_path, + issue_number=7, + started_at=str(state_holder["attempt_id"]), + ).read_attempt() + assert record["pull_request"] == { + "number": 11, + "url": "https://example.test/11", + } + assert record["outcome"] == "complete" + + +def test_finalization_without_model_figures_reports_them_unavailable( + tmp_path: Path, +) -> None: + reporter = make_reporter() + lifecycle, _, _ = make_lifecycle(tmp_path, reporter=reporter) + + assert lifecycle.run_once().status.value == "attempted" + + last = lifecycle.telemetry_snapshot()["last_finished"] + assert last is not None + assert last["pull_request"] == { + "number": 11, + "url": "https://example.test/11", + } + assert last["budget_used"]["basis"] == "unavailable" + assert last["budget_used"]["value"] is None + assert last["turns"]["basis"] == "unavailable" + + +# --------------------------------------------------------------------------- +# startup seeding from disk +# --------------------------------------------------------------------------- + + +def _run_one_finished_attempt(tmp_path: Path) -> dict: + lifecycle, _, _ = make_lifecycle(tmp_path) + assert lifecycle.run_once().status.value == "attempted" + last = lifecycle.telemetry_snapshot()["last_finished"] + assert last is not None + return last + + +def test_restart_seeds_last_finished_from_disk(tmp_path: Path) -> None: + expected = _run_one_finished_attempt(tmp_path) + + restarted_reporter = make_reporter() + restarted, _, _ = make_lifecycle(tmp_path, reporter=restarted_reporter) + + assert restarted.telemetry_snapshot()["current_attempt"] is None + assert restarted.telemetry_snapshot()["last_finished"] == expected + + +def test_no_history_seeds_null_last_finished(tmp_path: Path) -> None: + lifecycle, _, _ = make_lifecycle(tmp_path) + + assert lifecycle.telemetry_snapshot()["last_finished"] is None + + +def test_seed_prefers_the_latest_completed_attempt(tmp_path: Path) -> None: + write_archive( + tmp_path, + 7, + "2026-10-14T12:00:00.000001Z", + { + "started_at": "2026-10-14T12:00:00.000001Z", + "completed_at": "2026-10-14T13:00:00Z", + "outcome": "complete", + "issue_title": "Older", + "token_budget": {"actual_tokens": 100, "turns": 1}, + "pull_request": {"number": 11, "url": "https://example.test/11"}, + }, + ) + write_archive( + tmp_path, + 8, + "2026-10-14T14:00:00.000001Z", + { + "started_at": "2026-10-14T14:00:00.000001Z", + "completed_at": "2026-10-14T15:00:00Z", + "outcome": "incomplete", + "issue_title": "Newer", + "token_budget": {"actual_tokens": 200, "turns": 2}, + }, + ) + + assert load_last_finished(tmp_path) == { + "attempt_id": "2026-10-14T14:00:00.000001Z", + "issue_number": 8, + "issue_title": "Newer", + "outcome": "incomplete", + "finished_at": "2026-10-14T15:00:00Z", + "budget_used": {"value": 200, "basis": "measured"}, + "turns": {"value": 2, "basis": "measured"}, + "pull_request": None, + } + + +def test_seed_from_a_legacy_archive_reports_unknown_title_and_null_pr( + tmp_path: Path, +) -> None: + write_archive( + tmp_path, + 7, + "2026-10-14T12:00:00.000001Z", + { + "started_at": "2026-10-14T12:00:00.000001Z", + "completed_at": "2026-10-14T13:00:00Z", + "outcome": "complete", + "token_budget": {"actual_tokens": 100, "turns": 2}, + }, + ) + + last = load_last_finished(tmp_path) + + assert last is not None + assert last["issue_title"] == "unknown" + assert last["pull_request"] is None + + +def test_seed_ignores_attempts_without_an_outcome(tmp_path: Path) -> None: + write_archive( + tmp_path, + 7, + "2026-10-14T12:00:00.000001Z", + {"model_usage": {}}, + ) + + assert load_last_finished(tmp_path) is None + + +def test_seed_returns_none_without_any_history(tmp_path: Path) -> None: + assert load_last_finished(tmp_path) is None + + +def test_seeded_last_finished_survives_alongside_the_next_attempt( + tmp_path: Path, +) -> None: + lifecycle, tracker, _ = make_lifecycle(tmp_path) + assert lifecycle.run_once().status.value == "attempted" + tracker.issues[9] = tracked_issue(9, title="Next work") + tracker.fifo.append(9) + + seen: list[dict] = [] + + def capturing_runner(claim, profile, prepared): + seen.append(lifecycle.telemetry_snapshot()) + return complete_attempt_evidence() + + lifecycle.set_attempt_runner(capturing_runner) + assert lifecycle.run_once().status.value == "attempted" + + assert len(seen) == 1 + assert seen[0]["current_attempt"] is not None + assert seen[0]["current_attempt"]["issue_number"] == 9 + assert seen[0]["last_finished"] is not None + assert seen[0]["last_finished"]["issue_number"] == 7