diff --git a/README.md b/README.md index f25d358cd6..9d88fd90dc 100644 --- a/README.md +++ b/README.md @@ -49,8 +49,19 @@ until you restart the kernel, load it by path with Supported US and UK build commands always start the local telemetry emitter service. It reports live progress to the hosted collector when the operator's existing Hugging Face login is accepted; otherwise it retains the events -locally and the build continues. This live event path is independent of the -staging run files described below. +locally and the build continues. Every build on a host shares one local +event spool; a service that finds it locked by another process waits for it +until shortly before the build stops waiting. One that still cannot register +prints one warning line, without a traceback, and the build adds its own +warning and runs without telemetry, hosted or local. Checkouts at different +versions share the spool too. Its schema migrations only add to it, and each +records the revisions it builds on, so an older checkout keeps using a spool +that a newer one migrated, and a service delivers the events queued by any +version. Two kinds of checkout are refused instead, in one line, and build +without telemetry: one on a branch whose spool migration differs from the one +applied, and one from before October 2026, which cannot read that record, once +the spool has been migrated past the revision it knows. This live event path +is independent of the staging run files described below. US fiscal refresh builds also write pre-release staging run files **by default**. Progress JSON is uploaded to `policyengine/populace-us-staging` diff --git a/changelog.d/telemetry-spool-lock-startup.fixed.md b/changelog.d/telemetry-spool-lock-startup.fixed.md new file mode 100644 index 0000000000..387d66cccc --- /dev/null +++ b/changelog.d/telemetry-spool-lock-startup.fixed.md @@ -0,0 +1,5 @@ +A build on a busy host no longer loses its hosted telemetry when another build holds the shared local spool (`~/.cache/microcosm/telemetry/events.sqlite3`) while its emitter service starts. Before, the service's registration gave up after SQLite's 5 s busy wait, the service exited, and a SQLAlchemy traceback landed on the build's stderr. Now the build passes the time it will stop waiting (`--ready-deadline`). The service waits for the lock until 0.5 s before then: each SQLite wait ends by that point and lasts at most 5 s, a failed attempt is retried with jittered backoff, and the whole wait is capped at 60 s. Without a deadline it makes one 5 s attempt, as before. If the spool is still locked, it prints one warning line and exits with status 75 before the build gives up. Any other startup failure is also one line: status 2 for invalid arguments, 1 otherwise. SIGINT ends the service quietly, as SIGTERM does. + +Opening a spool already at the current schema takes no write lock. Retention pruning moved from spool open and every append to the delivery worker. It deletes in batches of 500 rows, each in its own short transaction, pauses 25 ms between batches so other builds' writers get the lock, and works at most 1 s per worker tick. A prune with nothing to remove only reads. Migrations run in one `BEGIN IMMEDIATE` transaction. Concurrent first opens of a new spool no longer fail with "table already exists"; about half of eight simultaneous opens did before. An interrupted migration leaves no partial schema, and a spool stamped by a migration this checkout does not know is refused without taking the lock. + +The delivery worker skips a failed step for one tick instead of dying. Heartbeats, delivery, and the check that records a killed build keep running. Lock contention is retried silently, and any other error prints one line per error type. An unexpected delivery error backs off like a collector failure. Warnings never raise on a closed stderr, and the service stops serving if its worker ever dies. A build that closes and exits while a worker step is still running is no longer recorded as an unexpected exit after its completion. diff --git a/changelog.d/telemetry-spool-shared-versions.fixed.md b/changelog.d/telemetry-spool-shared-versions.fixed.md new file mode 100644 index 0000000000..17a4fc679b --- /dev/null +++ b/changelog.d/telemetry-spool-shared-versions.fixed.md @@ -0,0 +1,5 @@ +Checkouts at different microcosm versions on one host keep sharing the local telemetry spool (`~/.cache/microcosm/telemetry/events.sqlite3`). Before, once a newer checkout applied a spool migration, every older checkout's emitter service refused the spool, and its builds ran without hosted telemetry until the checkout was updated. + +Spool migrations after the first must now be additive: to a table that already exists they may only append ordinary nullable or defaulted columns and add plain non-unique indexes, never rebuild it, change its rows or give it a trigger. A test holds every packaged revision to that. Each migration also records the spool's lineage, the migrating checkout's history. An older checkout whose head is in that lineage uses the spool as it is, without migrating it or taking the write lock, and services of every version deliver each other's queued events. A checkout whose history diverges from the spool's, such as a branch with a different migration, is still refused in one line. The revision is now read again once the migration lock is held, so an opener that waited while a newer checkout migrated no longer fails with "Can't locate revision". + +This covers checkouts from this change on. One from before it still refuses a spool migrated past `20261007_01`, and if it migrates a spool itself it records no lineage, which the next checkout at that revision then records. So the next spool migration should land after this change has reached build hosts, on a branch that includes it. diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter.py index c9fb5aaf7d..7fc1dcc2f8 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter.py @@ -196,6 +196,11 @@ def start( str(os.getpid()), "--heartbeat-seconds", str(heartbeat_seconds), + # The service retries spool lock contention until just before + # this wall-clock time, when the wait below gives up. One token, + # so a past or negative deadline is not read as an option. + "--ready-deadline=" + + repr(datetime.now(UTC).timestamp() + startup_timeout_seconds), ] if development_collector_url is not None: command.extend( diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/__main__.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/__main__.py index 2981038314..3b150ef5c1 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/__main__.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/__main__.py @@ -1,5 +1,11 @@ """Module execution entry point for the telemetry emitter service.""" +import signal + from microcosm.build.telemetry_emitter_service.main import main +# The service runs in its own session, so an interrupt reaches it only when +# sent on purpose. End at once, as SIGTERM does, rather than print a +# KeyboardInterrupt traceback on the build's stderr. +signal.signal(signal.SIGINT, signal.SIG_DFL) raise SystemExit(main()) diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/alembic/env.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/alembic/env.py index 2cb2edcc25..640ecfcf46 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/alembic/env.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/alembic/env.py @@ -3,6 +3,7 @@ from alembic import context from sqlalchemy.engine import Connection +from microcosm.build.telemetry_emitter_service.constants import SPOOL_LINEAGE_TABLE from microcosm.build.telemetry_emitter_service.models import SpoolModel _MISSING_CONNECTION_ERROR = ( @@ -10,6 +11,12 @@ ) +def _include_name(name: str | None, type_: str, parent_names: object) -> bool: + # The migration runner keeps the lineage table, as Alembic keeps + # alembic_version, so the models do not describe it. + return not (type_ == "table" and name == SPOOL_LINEAGE_TABLE) + + def run_migrations() -> None: """Run migrations on the connection supplied by the emitter service.""" @@ -20,6 +27,7 @@ def run_migrations() -> None: connection=connection, target_metadata=SpoolModel.metadata, render_as_batch=True, + include_name=_include_name, ) with context.begin_transaction(): context.run_migrations() diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/alembic/script.py.mako b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/alembic/script.py.mako index f059f7642d..010b7ad238 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/alembic/script.py.mako +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/alembic/script.py.mako @@ -20,7 +20,7 @@ depends_on: str | Sequence[str] | None = ${repr(depends_on)} def upgrade() -> None: - """Apply this schema revision.""" + """Apply this schema revision, additively: see ``migrations.py``.""" ${upgrades if upgrades else "pass"} diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/collector.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/collector.py index 0d7e4d294a..5b8bc08e4a 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/collector.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/collector.py @@ -4,7 +4,6 @@ import json import os -import sys import time import urllib.error import urllib.request @@ -42,6 +41,10 @@ TOKEN_EXCHANGE_PATH, TOKEN_REFRESH_MARGIN_SECONDS, ) +from microcosm.build.telemetry_emitter_service.contention import ( + is_transient_spool_error, +) +from microcosm.build.telemetry_emitter_service.diagnostics import write_warning from microcosm.build.telemetry_emitter_service.spool import EventSpool @@ -168,6 +171,17 @@ def flush_once(self) -> bool: if time.monotonic() < self._next_attempt_at: return False + try: + return self._flush_pending_runs() + except Exception as error: + # The worker runs this every second and survives the error, so an + # unexpected one backs off like a collector failure rather than + # repeating requests every tick. A busy spool is retried next tick. + if not is_transient_spool_error(error): + self._defer_retry() + raise + + def _flush_pending_runs(self) -> bool: made_progress = False for registration in self.spool.pending_runs(): run_id = str(registration["run_id"]) @@ -220,7 +234,7 @@ def _collector_token(self, registration: Mapping[str, Any]) -> str | None: hf_token = _huggingface_token() if not hf_token: if not self._warned_no_token: - print(NO_CREDENTIAL_MESSAGE, file=sys.stderr, flush=True) + write_warning(NO_CREDENTIAL_MESSAGE) self._warned_no_token = True self._make_local_only(registration, LOCAL_ONLY_MISSING_CREDENTIAL) return None @@ -293,5 +307,5 @@ def _defer_retry(self) -> None: def _warn_denied(self, registration_key: str, message: str) -> None: if registration_key in self._warned_denied: return - print(message, file=sys.stderr, flush=True) + write_warning(message) self._warned_denied.add(registration_key) diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/constants.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/constants.py index 83163fe53c..06d3b7a1a4 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/constants.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/constants.py @@ -58,7 +58,26 @@ MAX_RETRY_SECONDS: Final = 60.0 DATABASE_TIMEOUT_SECONDS: Final = 5 +# Kept by the migration runner beside alembic_version: every revision in the +# history of the checkout that last migrated the spool. +SPOOL_LINEAGE_TABLE: Final = "spool_lineage" PRUNE_INTERVAL_SECONDS: Final = 60.0 +PRUNE_BATCH_ROWS: Final = 500 +# SQLite's busy handler polls rather than queueing, so another process rarely +# gets the lock between two back-to-back transactions. Prune pauses between +# batches and works at most PRUNE_STEP_SECONDS per worker tick. +PRUNE_BATCH_PAUSE_SECONDS: Final = 0.025 +PRUNE_STEP_SECONDS: Final = 1.0 +# Every concurrent build on a host shares one spool, so a write can find it +# locked for longer than SQLite's own busy wait. Startup waits for the lock, +# and retries lock errors with jittered, doubling pauses, until the margin +# before the build stops waiting for readiness; every SQLite wait in that time +# also ends by then. The margin covers binding the socket and the build's ping. +SPOOL_RETRY_INITIAL_SECONDS: Final = 0.05 +SPOOL_RETRY_MAX_SECONDS: Final = 0.25 +READY_DEADLINE_MARGIN_SECONDS: Final = 0.5 +STARTUP_RETRY_LIMIT_SECONDS: Final = 60.0 +SPOOL_LOCKED_EXIT_STATUS: Final = 75 # EX_TEMPFAIL from sysexits.h DEFAULT_HEARTBEAT_SECONDS: Final = 60.0 DEFAULT_DRAIN_SECONDS: Final = 15.0 @@ -73,3 +92,26 @@ UNSUPPORTED_ACTION_ERROR: Final = "unsupported local telemetry action" LOCAL_MESSAGE_TOO_LARGE_ERROR: Final = "local telemetry message exceeds 1 MiB" FAILURE_CLASS_UNEXPECTED_PROCESS_EXIT: Final = "unexpected_process_exit" + +READY_DEADLINE_ERROR: Final = "ready deadline must be a number of seconds" +UNKNOWN_SPOOL_REVISION_ERROR: Final = ( + "telemetry spool schema revision {revision!r} is not in this microcosm's " + "migration history, whose head is {head!r}, and the spool does not record " + "it as descending from {head!r}" +) +SPOOL_LOCKED_WARNING: Final = ( + "warning: the local telemetry emitter service could not register this build " + "in its spool {spool}: another process kept the spool locked for " + "{waited_seconds:.1f} s ({error})." +) +SERVICE_ARGUMENTS_WARNING: Final = ( + "warning: the local telemetry emitter service could not start: {error}" +) +SERVICE_FAILED_WARNING: Final = ( + "warning: the local telemetry emitter service stopped: {error_type}: {error}" +) +WORKER_STEP_WARNING: Final = ( + "warning: the local telemetry emitter service's delivery worker hit " + "{error_type} ({error}) and will keep running." +) +MAX_WARNING_ERROR_CHARS: Final = 300 diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/contention.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/contention.py new file mode 100644 index 0000000000..de0655b4e4 --- /dev/null +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/contention.py @@ -0,0 +1,75 @@ +"""Bounded retry for lock contention on the shared telemetry spool.""" + +from __future__ import annotations + +import random +import sqlite3 +import time +from collections.abc import Callable + +from sqlalchemy.exc import DBAPIError + +from microcosm.build.telemetry_emitter_service.constants import ( + SPOOL_RETRY_INITIAL_SECONDS, + SPOOL_RETRY_MAX_SECONDS, +) + +# SQLite reports extended result codes; the low byte is the primary code. +_PRIMARY_RESULT_CODE_MASK = 0xFF +_TRANSIENT_RESULT_CODES = frozenset({sqlite3.SQLITE_BUSY, sqlite3.SQLITE_LOCKED}) + + +def is_transient_spool_error(error: BaseException) -> bool: + """Return whether an error is SQLite lock contention that a retry can clear. + + That is SQLITE_BUSY ("database is locked") or SQLITE_LOCKED, raised + directly by ``sqlite3`` or wrapped by SQLAlchemy. Schema, constraint and + I/O errors are not transient. + """ + + if isinstance(error, DBAPIError): + error = error.orig + if not isinstance(error, sqlite3.Error): + return False + code = getattr(error, "sqlite_errorcode", None) + return ( + isinstance(code, int) + and code & _PRIMARY_RESULT_CODE_MASK in _TRANSIENT_RESULT_CODES + ) + + +def retry_spool_contention[T]( + operation: Callable[[], T], + *, + deadline: float, + clock: Callable[[], float] = time.monotonic, + sleep: Callable[[float], None] = time.sleep, + jitter: Callable[[float, float], float] = random.uniform, +) -> T: + """Run ``operation``, retrying spool lock contention until ``deadline``. + + ``deadline`` is a ``clock`` reading. The first attempt always runs. After a + transient lock error the next attempt waits a jittered backoff that starts + at ``SPOOL_RETRY_INITIAL_SECONDS`` and doubles up to + ``SPOOL_RETRY_MAX_SECONDS``. When that attempt would not start before + ``deadline``, or the wait overran it, the last lock error is raised instead. Any other error is + raised at once. Each attempt may itself wait in SQLite's busy handler, so + this bounds when attempts start, not when the last one ends. + """ + + delay = SPOOL_RETRY_INITIAL_SECONDS + while True: + try: + return operation() + except Exception as error: + if not is_transient_spool_error(error): + raise + wait = jitter(delay / 2, delay) + if clock() + wait >= deadline: + raise + contended = error + sleep(wait) + if clock() >= deadline: + # The sleep overran, as it can on a loaded host. + raise contended + delay = min(SPOOL_RETRY_MAX_SECONDS, delay * 2) diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/database.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/database.py index 75d32d96ba..8b94747358 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/database.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/database.py @@ -2,10 +2,11 @@ from __future__ import annotations +from collections.abc import Callable from pathlib import Path -from sqlalchemy import URL, create_engine -from sqlalchemy.engine import Engine +from sqlalchemy import URL, create_engine, event +from sqlalchemy.engine import Connection, Engine from sqlalchemy.orm import Session, sessionmaker from microcosm.build.telemetry_emitter_service.constants import ( @@ -19,13 +20,49 @@ def sqlite_database_url(path: Path | str) -> URL: return URL.create("sqlite+pysqlite", database=str(Path(path))) -def create_spool_engine(path: Path | str) -> Engine: - """Create the SQLAlchemy engine used by one emitter service process.""" +def create_spool_engine( + path: Path | str, + *, + immediate_transactions: bool = False, + busy_timeout_seconds: Callable[[], float] | None = None, +) -> Engine: + """Create the SQLAlchemy engine used by one emitter service process. - return create_engine( + ``busy_timeout_seconds`` is read each time a connection is checked out and + caps how long one statement waits in SQLite's busy handler for another + process's lock; by default that is ``DATABASE_TIMEOUT_SECONDS``. + + By default Python's sqlite3 module opens a transaction only before a data + change, never before DDL. With ``immediate_transactions`` every SQLAlchemy + transaction is instead one ``BEGIN IMMEDIATE`` transaction: it takes the + write lock at the start, waiting in SQLite's busy handler, and holds it + until commit. This is SQLAlchemy's documented pysqlite recipe for + transactional DDL. + """ + + engine = create_engine( sqlite_database_url(path), connect_args={"timeout": DATABASE_TIMEOUT_SECONDS}, ) + if busy_timeout_seconds is not None: + + def apply_busy_timeout(dbapi_connection, connection_record, proxy) -> None: + milliseconds = max(0, round(busy_timeout_seconds() * 1000)) + dbapi_connection.execute(f"PRAGMA busy_timeout = {milliseconds}") + + event.listen(engine, "checkout", apply_busy_timeout) + if immediate_transactions: + event.listen(engine, "connect", _disable_driver_transactions) + event.listen(engine, "begin", _begin_immediate) + return engine + + +def _disable_driver_transactions(dbapi_connection, connection_record) -> None: + dbapi_connection.isolation_level = None + + +def _begin_immediate(connection: Connection) -> None: + connection.exec_driver_sql("BEGIN IMMEDIATE") def create_spool_session_factory(engine: Engine) -> sessionmaker[Session]: diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/diagnostics.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/diagnostics.py new file mode 100644 index 0000000000..5eaa5d52ee --- /dev/null +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/diagnostics.py @@ -0,0 +1,38 @@ +"""One-line warnings on the build's stderr, which the service inherits.""" + +from __future__ import annotations + +import sys + +from sqlalchemy.exc import DBAPIError + +from microcosm.build.telemetry_emitter_service.constants import ( + MAX_WARNING_ERROR_CHARS, +) + + +def describe_error(error: BaseException) -> str: + """Return one short line describing an error, for a warning on stderr. + + SQLAlchemy's message repeats the SQL statement and its parameters, which + can hold a registration or event payload, and a documentation link on later + lines, so a wrapped driver error is described by the driver's own message. + """ + + if isinstance(error, DBAPIError) and error.orig is not None: + error = error.orig + lines = str(error).strip().splitlines() + return (lines[0] if lines else type(error).__name__)[:MAX_WARNING_ERROR_CHARS] + + +def write_warning(message: str) -> None: + """Print one line to stderr without ever raising. + + The service runs in its own session, so it can outlive a build whose + stderr was a pipe that has since closed; a failed write must not stop it. + """ + + try: + print(message, file=sys.stderr, flush=True) + except (OSError, ValueError): + pass diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/main.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/main.py index 2872bf91a8..e377f457dc 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/main.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/main.py @@ -4,21 +4,54 @@ import argparse import json +import math +import time from pathlib import Path +from typing import NoReturn from microcosm.build.telemetry_emitter_service.collector import CollectorDelivery from microcosm.build.telemetry_emitter_service.constants import ( DEFAULT_HEARTBEAT_SECONDS, + READY_DEADLINE_ERROR, + READY_DEADLINE_MARGIN_SECONDS, + SERVICE_ARGUMENTS_WARNING, + SERVICE_FAILED_WARNING, + SPOOL_LOCKED_EXIT_STATUS, + SPOOL_LOCKED_WARNING, + STARTUP_RETRY_LIMIT_SECONDS, +) +from microcosm.build.telemetry_emitter_service.contention import ( + is_transient_spool_error, + retry_spool_contention, +) +from microcosm.build.telemetry_emitter_service.diagnostics import ( + describe_error, + write_warning, ) from microcosm.build.telemetry_emitter_service.resources import ProcessTreeSampler from microcosm.build.telemetry_emitter_service.runtime import EmitterService from microcosm.build.telemetry_emitter_service.spool import EventSpool +def _seconds(value: str) -> float: + seconds = float(value) + if math.isnan(seconds): + raise argparse.ArgumentTypeError(READY_DEADLINE_ERROR) + return seconds + + +class _ArgumentParser(argparse.ArgumentParser): + """Report invalid arguments in one line, like every other startup failure.""" + + def error(self, message: str) -> NoReturn: + write_warning(SERVICE_ARGUMENTS_WARNING.format(error=message)) + raise SystemExit(2) + + def build_parser() -> argparse.ArgumentParser: """Create the service command-line parser.""" - parser = argparse.ArgumentParser() + parser = _ArgumentParser() parser.add_argument("--socket", type=Path, required=True) parser.add_argument("--spool", type=Path, required=True) parser.add_argument("--development-collector-url") @@ -29,25 +62,117 @@ def build_parser() -> argparse.ArgumentParser: type=float, default=DEFAULT_HEARTBEAT_SECONDS, ) + parser.add_argument( + "--ready-deadline", + type=_seconds, + help=( + "Unix time at which the build stops waiting for readiness. Until " + "shortly before then, startup retries spool lock contention; " + "without it, startup makes one attempt." + ), + ) return parser +def startup_deadline( + ready_deadline: float | None, + *, + now_unix: float, + now_monotonic: float, +) -> float | None: + """Return the ``time.monotonic()`` reading at which startup gives up. + + The build passes its own give-up time as Unix time, the clock both + processes share. The margin leaves time to bind the socket and answer the + build's ping before the build gives up. The limit bounds the wait however + far the deadline or the wall clock moves, so a service whose build has died + still gives up. Without a deadline from the build, there is none here. + """ + + if ready_deadline is None: + return None + remaining = min(ready_deadline - now_unix, STARTUP_RETRY_LIMIT_SECONDS) + return now_monotonic + remaining - READY_DEADLINE_MARGIN_SECONDS + + +def open_registered_spool( + path: Path, + registration: dict[str, object], + *, + deadline: float | None, +) -> EventSpool: + """Open the spool and register this producer, waiting out lock contention. + + With a ``deadline``, startup waits for another process's lock until then: + each SQLite wait ends by it, and an attempt that fails on the lock is + retried while one can still start before it. Without one, a single attempt + waits as long as any statement does, ``DATABASE_TIMEOUT_SECONDS``. The spool + returned waits normally. + """ + + opened: list[EventSpool] = [] + + def attempt() -> EventSpool: + if not opened: + opened.append(EventSpool(path, busy_deadline=deadline)) + opened[0].register(registration) + return opened[0] + + spool = retry_spool_contention( + attempt, + deadline=-math.inf if deadline is None else deadline, + ) + spool.busy_deadline = None + return spool + + def main(argv: list[str] | None = None) -> int: - """Run the telemetry emitter service until the build disconnects.""" + """Run the telemetry emitter service until the build disconnects. + + The socket is bound only once this build is registered, so a build that + finds the service ready can queue events. The service's stderr is the + build's, so a failure is one line, never a traceback. Exit status 75 means + another process kept the spool locked past the startup deadline, 2 that + the arguments were invalid, and 1 any other failure. + """ args = build_parser().parse_args(argv) - registration = json.loads(args.registration_json) - spool = EventSpool(args.spool) - service = EmitterService( - socket_path=args.socket, - registration=registration, - spool=spool, - delivery=CollectorDelivery( - spool, - development_collector_url=args.development_collector_url, - ), - sampler=ProcessTreeSampler(args.parent_pid), - heartbeat_seconds=args.heartbeat_seconds, + started_at = time.monotonic() + deadline = startup_deadline( + args.ready_deadline, + now_unix=time.time(), + now_monotonic=started_at, ) - service.run() + try: + registration = json.loads(args.registration_json) + spool = open_registered_spool(args.spool, registration, deadline=deadline) + service = EmitterService( + socket_path=args.socket, + registration=registration, + spool=spool, + delivery=CollectorDelivery( + spool, + development_collector_url=args.development_collector_url, + ), + sampler=ProcessTreeSampler(args.parent_pid), + heartbeat_seconds=args.heartbeat_seconds, + ) + service.run() + except Exception as error: + if is_transient_spool_error(error): + write_warning( + SPOOL_LOCKED_WARNING.format( + spool=args.spool, + waited_seconds=time.monotonic() - started_at, + error=describe_error(error), + ) + ) + return SPOOL_LOCKED_EXIT_STATUS + write_warning( + SERVICE_FAILED_WARNING.format( + error_type=type(error).__name__, + error=describe_error(error), + ) + ) + return 1 return 0 diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/migrations.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/migrations.py index c1c69c61c2..71c65d3468 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/migrations.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/migrations.py @@ -1,32 +1,108 @@ -"""Programmatic Alembic migration entry points for the telemetry spool.""" +"""Programmatic Alembic migration entry points for the telemetry spool. + +Every checkout and worktree on a host shares one spool, so checkouts at +different microcosm versions open the same file, and an older one can find it +migrated past its own head. Every revision after the first is therefore +additive. It may create tables. To a table that already exists it may only +append ordinary columns that are nullable or have a default, and add plain, +non-unique indexes. It never rebuilds, renames or drops such a table, changes +or deletes its rows, or gives it a trigger. A test holds every packaged +revision to this (``test_telemetry_spool_versions.py``). The rule is +deliberately stricter than compatibility needs, and it covers the schema, not +what rows mean: + +- Rows a newer version writes must stay deliverable by older services. Those + upload every run whose ``upload_state`` is ``pending``, and read ``run_id`` + and ``producer_id`` from its registration and ``event_id`` from each event. +- A new table needs its own retention. Older services neither prune it nor + deliver from it. + +A change older code cannot use does not belong in this history; it needs a new +spool file. + +Whenever this module moves a spool to a new revision it also records the +spool's lineage: every revision in the history of the checkout that moved it. +A checkout that does not know a spool's revision uses the spool as it is when +that lineage includes both that revision and its own head, and refuses it +otherwise, as when a branch with a different migration stamped it. A checkout +from before lineage was recorded can move the revision without recording it; +the next checkout at that revision records it. +""" from __future__ import annotations -from collections.abc import Iterator +from collections.abc import Callable, Iterator from contextlib import contextmanager +from dataclasses import dataclass +from enum import StrEnum from importlib.resources import as_file, files +from importlib.resources.abc import Traversable from pathlib import Path from alembic import command from alembic.config import Config from alembic.migration import MigrationContext from alembic.script import ScriptDirectory +from sqlalchemy import Column, MetaData, Table, Text, delete, insert, inspect, select from sqlalchemy.engine import Connection, Engine +from microcosm.build.telemetry_emitter_service.constants import ( + DATABASE_TIMEOUT_SECONDS, + SPOOL_LINEAGE_TABLE, + UNKNOWN_SPOOL_REVISION_ERROR, +) from microcosm.build.telemetry_emitter_service.database import create_spool_engine _MIGRATION_TARGET = "head" +_LINEAGE = Table( + SPOOL_LINEAGE_TABLE, + MetaData(), + Column("revision", Text, primary_key=True), +) + + +class SpoolRevisionState(StrEnum): + """Where a spool's revision lies relative to one checkout's history.""" + + AT_HEAD = "at_head" + BEHIND = "behind" + AHEAD = "ahead" + INCOMPATIBLE = "incompatible" + + +class IncompatibleSpoolRevisionError(RuntimeError): + """The spool's revision neither precedes nor descends from this head.""" + + +@dataclass(frozen=True) +class MigrationHistory: + """One checkout's spool migrations: its head and every revision up to it. + + ``bases`` are the revisions with no parent. Every checkout's history + starts from them, so no checkout needs a lineage to place a spool there. + """ + + head: str | None + revisions: frozenset[str] + bases: frozenset[str] + @contextmanager def alembic_config( *, connection: Connection | None = None, + script_location: Traversable | None = None, ) -> Iterator[Config]: - """Yield Alembic configuration with migrations on the filesystem.""" + """Yield Alembic configuration with migrations on the filesystem. + + ``script_location`` is a migration directory laid out like the packaged + one, which it defaults to; tests pass other checkouts' histories. + """ - migration_resources = files(__package__).joinpath("alembic") - with as_file(migration_resources) as migration_directory: + if script_location is None: + script_location = files(__package__).joinpath("alembic") + with as_file(script_location) as migration_directory: config = Config() config.set_main_option("script_location", str(migration_directory)) if connection is not None: @@ -34,12 +110,120 @@ def alembic_config( yield config -def upgrade_spool_database(engine: Engine) -> None: - """Apply every committed spool migration to an engine.""" +def classify_spool_revision( + revision: str | None, + lineage: frozenset[str] | None, + history: MigrationHistory, +) -> SpoolRevisionState: + """Return where a spool stamped ``revision`` lies relative to ``history``. + + ``lineage`` is the history the spool records, or ``None`` if it records + none. A revision missing from this checkout's history is usable as it is + only when that lineage holds both it and this checkout's head: a checkout + descended from this one then migrated the spool, additively. + """ + + if revision == history.head: + return SpoolRevisionState.AT_HEAD + if revision is None or revision in history.revisions: + return SpoolRevisionState.BEHIND + if lineage is not None and {revision, history.head} <= lineage: + return SpoolRevisionState.AHEAD + return SpoolRevisionState.INCOMPATIBLE + + +def upgrade_spool_database( + engine: Engine, + *, + busy_timeout_seconds: Callable[[], float] = lambda: DATABASE_TIMEOUT_SECONDS, + script_location: Traversable | None = None, +) -> SpoolRevisionState: + """Bring a spool behind this checkout's head up to it, one process at a time. + + Returns where the spool's revision lay before the call. A spool at head, or + past it on a line descended from it, is only read, so opening it takes no + write lock. Neither does refusing any other revision this checkout does not + know, which raises ``IncompatibleSpoolRevisionError``. Otherwise the whole + upgrade, DDL, version stamp and lineage, runs in one ``BEGIN IMMEDIATE`` + transaction whose statements each wait for another process's lock as long + as ``busy_timeout_seconds()`` allows. Without that transaction two services + opening a new spool at once interleave their DDL, and one fails with "table + already exists". The revision is read again once the lock is held, so a + service that waited for it finds the spool where the last migrator left it, + and changes nothing unless it is still behind. + + A spool at this head with no lineage, or another's, was moved there by a + checkout from before lineage was recorded. Its lineage is written under the + same lock, so that older checkouts can use it. + """ + + history = migration_history(script_location) + with engine.connect() as connection: + state, lineage_recorded = _inspect_spool(connection, history) + if state is not SpoolRevisionState.BEHIND and lineage_recorded: + return state + migration_engine = create_spool_engine( + engine.url.database, + immediate_transactions=True, + busy_timeout_seconds=busy_timeout_seconds, + ) + try: + with migration_engine.begin() as connection: + state, lineage_recorded = _inspect_spool(connection, history) + if state is SpoolRevisionState.BEHIND: + with alembic_config( + connection=connection, + script_location=script_location, + ) as config: + command.upgrade(config, _MIGRATION_TARGET) + if state is SpoolRevisionState.BEHIND or not lineage_recorded: + _record_lineage(connection, history) + finally: + migration_engine.dispose() + return state + + +def _inspect_spool( + connection: Connection, + history: MigrationHistory, +) -> tuple[SpoolRevisionState, bool]: + """Return the spool's state and whether its lineage is in order. + + Only a spool at this checkout's head can have its lineage found wanting, + since only then does this checkout know what it should be. A spool at a + base revision needs none. + """ + + revision = MigrationContext.configure(connection).get_current_revision() + lineage = None + if revision is not None and revision not in history.bases: + lineage = _recorded_lineage(connection) + state = classify_spool_revision(revision, lineage, history) + if state is SpoolRevisionState.INCOMPATIBLE: + raise IncompatibleSpoolRevisionError( + UNKNOWN_SPOOL_REVISION_ERROR.format(revision=revision, head=history.head) + ) + lineage_recorded = ( + state is not SpoolRevisionState.AT_HEAD + or revision in history.bases + or lineage == history.revisions + ) + return state, lineage_recorded - with engine.begin() as connection: - with alembic_config(connection=connection) as config: - command.upgrade(config, _MIGRATION_TARGET) + +def _recorded_lineage(connection: Connection) -> frozenset[str] | None: + if not inspect(connection).has_table(SPOOL_LINEAGE_TABLE): + return None + return frozenset(connection.scalars(select(_LINEAGE.c.revision))) + + +def _record_lineage(connection: Connection, history: MigrationHistory) -> None: + _LINEAGE.create(connection, checkfirst=True) + connection.execute(delete(_LINEAGE)) + connection.execute( + insert(_LINEAGE), + [{"revision": revision} for revision in sorted(history.revisions)], + ) def current_database_revision(path: Path | str) -> str | None: @@ -53,8 +237,40 @@ def current_database_revision(path: Path | str) -> str | None: engine.dispose() -def migration_head_revision() -> str | None: - """Return the single current head from the packaged migration history.""" +def recorded_spool_lineage(path: Path | str) -> frozenset[str] | None: + """Return the lineage one spool database records, or ``None`` if none.""" + + engine = create_spool_engine(path) + try: + with engine.connect() as connection: + return _recorded_lineage(connection) + finally: + engine.dispose() + + +def migration_history(script_location: Traversable | None = None) -> MigrationHistory: + """Return a checkout's migration history, by default the packaged one.""" + + with alembic_config(script_location=script_location) as config: + scripts = ScriptDirectory.from_config(config) + return MigrationHistory( + head=scripts.get_current_head(), + revisions=frozenset(script.revision for script in scripts.walk_revisions()), + bases=frozenset(scripts.get_bases()), + ) + + +def migration_head_revision( + script_location: Traversable | None = None, +) -> str | None: + """Return the single current head from a checkout's migration history.""" + + return migration_history(script_location).head + + +def migration_revisions( + script_location: Traversable | None = None, +) -> frozenset[str]: + """Return every revision in a checkout's migration history.""" - with alembic_config() as config: - return ScriptDirectory.from_config(config).get_current_head() + return migration_history(script_location).revisions diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/runtime.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/runtime.py index 0bb1d9c2a4..79197fa028 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/runtime.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/runtime.py @@ -7,7 +7,7 @@ import socket import threading import time -from collections.abc import Mapping +from collections.abc import Callable, Mapping from pathlib import Path from typing import Any @@ -24,6 +24,15 @@ SOCKET_LISTEN_BACKLOG, UNSUPPORTED_ACTION_ERROR, WORKER_INTERVAL_SECONDS, + WORKER_STEP_WARNING, +) +from microcosm.build.telemetry_emitter_service.contention import ( + is_transient_spool_error, + retry_spool_contention, +) +from microcosm.build.telemetry_emitter_service.diagnostics import ( + describe_error, + write_warning, ) from microcosm.build.telemetry_emitter_service.resources import ProcessTreeSampler from microcosm.build.telemetry_emitter_service.spool import EventSpool @@ -100,11 +109,14 @@ def __init__( self.drain_seconds = max(0.0, drain_seconds) self._stop = threading.Event() self._last_stage = STAGE_CREATED + self._reported_error_types: set[str] = set() def run(self) -> None: - """Serve local messages until the client closes or exits.""" + """Serve local messages until the client closes or exits. + + The spool must already hold this producer's registration. + """ - self.spool.register(self.registration) self.socket_path.parent.mkdir(parents=True, exist_ok=True) try: self.socket_path.unlink(missing_ok=True) @@ -115,7 +127,7 @@ def run(self) -> None: server.settimeout(SOCKET_ACCEPT_TIMEOUT_SECONDS) worker = threading.Thread(target=self._worker, daemon=True) worker.start() - self._serve(server) + self._serve(server, worker) worker.join(timeout=self.drain_seconds + WORKER_INTERVAL_SECONDS) finally: self.socket_path.unlink(missing_ok=True) @@ -124,8 +136,11 @@ def run(self) -> None: except OSError: pass - def _serve(self, server: socket.socket) -> None: - while not self._stop.is_set(): + def _serve(self, server: socket.socket, worker: threading.Thread) -> None: + # Only the worker notices that the build died without closing, so a + # service whose worker has stopped must stop too, or it would serve a + # dead build forever. + while not self._stop.is_set() and worker.is_alive(): try: connection, _ = server.accept() except TimeoutError: @@ -186,34 +201,99 @@ def _handle(self, message: Mapping[str, Any]) -> None: raise ValueError(UNSUPPORTED_ACTION_ERROR) def _worker(self) -> None: + # A failed step is skipped for this tick only. The parent check below + # must keep running: it is the only thing that stops a service whose + # build died without closing it. next_heartbeat = time.monotonic() + self.heartbeat_seconds while not self._stop.wait(WORKER_INTERVAL_SECONDS): now = time.monotonic() # Sample every worker iteration so short-lived build children are # much less likely to disappear between stage and heartbeat events. - self.sampler.sample() - if now >= next_heartbeat: - self.spool.append( - self.registration, - _heartbeat_event(self._last_stage), - resources=self.sampler.sample(), - ) + self._attempt(self.sampler.sample) + # A heartbeat that fails stays due, so the next tick retries it. + if now >= next_heartbeat and self._attempt(self._append_heartbeat): next_heartbeat = now + self.heartbeat_seconds - self.delivery.flush_once() - if not self.sampler.parent_alive(): - self.spool.append( - self.registration, - _unexpected_exit_event(self._last_stage), - resources=self.sampler.sample(), - ) + self._attempt(self.spool.prune_if_due) + self._attempt(self.delivery.flush_once) + # A build that closed while this tick ran may already have exited + # cleanly; only a build that never closed died unexpectedly. + if not self._stop.is_set() and not self._parent_alive(): + self._attempt(self._append_unexpected_exit) self._stop.set() break + # A build that closes within its first tick never reached the prune + # above, and a host of such builds would never enforce retention. + self._attempt(self.spool.prune_if_due) self._drain() + def _parent_alive(self) -> bool: + # A parent that cannot be checked is treated as gone: the alternative + # is a service that may outlive its build. + try: + return self.sampler.parent_alive() + except Exception as error: + self._report(error) + return False + + def _append_heartbeat(self) -> None: + self.spool.append( + self.registration, + _heartbeat_event(self._last_stage), + resources=self.sampler.sample(), + ) + + def _append_unexpected_exit(self) -> None: + # This is the only record of a build that was killed, so it waits out + # lock contention for as long as the shutdown drain may take. + retry_spool_contention( + lambda: self.spool.append( + self.registration, + _unexpected_exit_event(self._last_stage), + resources=self.sampler.sample(), + ), + deadline=time.monotonic() + self.drain_seconds, + clock=time.monotonic, + sleep=time.sleep, + ) + + def _attempt(self, step: Callable[[], object]) -> bool: + """Run one worker step, reporting rather than raising its failure.""" + + try: + step() + except Exception as error: + self._report(error) + return False + return True + + def _report(self, error: Exception) -> None: + # Lock contention clears by itself and the step runs again on a later + # tick, so it is not worth a line in the build's log. Anything else is + # reported once per error type. + if is_transient_spool_error(error): + return + error_type = type(error).__name__ + if error_type in self._reported_error_types: + return + self._reported_error_types.add(error_type) + write_warning( + WORKER_STEP_WARNING.format( + error_type=error_type, + error=describe_error(error), + ) + ) + def _drain(self) -> None: deadline = time.monotonic() + self.drain_seconds - while self.spool.has_deliverable() and time.monotonic() < deadline: - if not self.delivery.flush_once(): + while time.monotonic() < deadline: + progressed = False + try: + if not self.spool.has_deliverable(): + return + progressed = self.delivery.flush_once() + except Exception as error: + self._report(error) + if not progressed: remaining = deadline - time.monotonic() if remaining > 0: time.sleep(min(DRAIN_RETRY_SECONDS, remaining)) diff --git a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/spool.py b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/spool.py index 1ef43c5269..a4e7df3d7e 100644 --- a/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/spool.py +++ b/packages/microcosm-build/src/microcosm/build/telemetry_emitter_service/spool.py @@ -2,21 +2,26 @@ from __future__ import annotations +import math import threading import time import uuid from collections.abc import Mapping from datetime import UTC, datetime, timedelta +from importlib.resources.abc import Traversable from pathlib import Path from typing import Any -from sqlalchemy import func, select -from sqlalchemy.orm import Session +from sqlalchemy import Integer, delete, func, select, tuple_ from microcosm.build.telemetry_emitter_service.constants import ( BATCH_SIZE, + DATABASE_TIMEOUT_SECONDS, MAX_QUEUED_BYTES, + PRUNE_BATCH_PAUSE_SECONDS, + PRUNE_BATCH_ROWS, PRUNE_INTERVAL_SECONDS, + PRUNE_STEP_SECONDS, RETENTION_DAYS, UPLOAD_STATE_LOCAL_ONLY, UPLOAD_STATE_PENDING, @@ -31,7 +36,6 @@ from microcosm.build.telemetry_emitter_service.models import ( TelemetryEventRecord, TelemetryRunRecord, - serialized_json_length, ) from microcosm.build.telemetry_emitter_service.timestamps import utc_now from microcosm.build.telemetry_protocol import TELEMETRY_SCHEMA_VERSION @@ -40,19 +44,60 @@ class EventSpool: """Small SQLite queue shared by successive emitter service processes.""" - def __init__(self, path: Path | str) -> None: + def __init__( + self, + path: Path | str, + *, + busy_deadline: float | None = None, + script_location: Traversable | None = None, + ) -> None: + """Open the spool, migrating it to this checkout's schema if behind. + + ``script_location`` replaces the packaged migration history, so tests + can open one spool as checkouts at different versions. + """ + self.path = Path(path) self.path.parent.mkdir(parents=True, exist_ok=True) try: self.path.parent.chmod(0o700) except OSError: pass - self._engine = create_spool_engine(self.path) - upgrade_spool_database(self._engine) + # A time.monotonic() reading that startup sets: until it is cleared, + # no statement waits past it for another process's lock. + self.busy_deadline = busy_deadline + self._engine = create_spool_engine( + self.path, + busy_timeout_seconds=self.busy_timeout_seconds, + ) + try: + upgrade_spool_database( + self._engine, + busy_timeout_seconds=self.busy_timeout_seconds, + script_location=script_location, + ) + except BaseException: + self._engine.dispose() + raise self._session_factory = create_spool_session_factory(self._engine) self._lock = threading.RLock() - self._last_prune_at = 0.0 - self.prune() + # Retention is enforced by the service's delivery worker through + # prune_if_due, not here: pruning needs the write lock whenever a row + # has expired, and this constructor runs before the build's readiness + # ping is answered. + self._last_prune_at: float | None = None + + def busy_timeout_seconds(self) -> float: + """How long a statement may wait for another process's lock. + + At most ``DATABASE_TIMEOUT_SECONDS``, and never past ``busy_deadline`` + while one is set. Applied each time a connection is checked out. + """ + + if self.busy_deadline is None: + return DATABASE_TIMEOUT_SECONDS + remaining = self.busy_deadline - time.monotonic() + return min(DATABASE_TIMEOUT_SECONDS, max(0.0, remaining)) def register(self, registration: Mapping[str, Any]) -> None: """Create or refresh a producer registration.""" @@ -124,8 +169,6 @@ def append( ) run.next_sequence = sequence + 1 run.updated_at = utc_now() - if time.monotonic() - self._last_prune_at >= PRUNE_INTERVAL_SECONDS: - self.prune() return payload def pending_runs(self) -> list[dict[str, Any]]: @@ -210,49 +253,134 @@ def has_pending(self) -> bool: with self._lock, self._session_factory() as session: return session.scalar(statement) is not None - def prune(self) -> None: - """Enforce the age and total-size retention limits.""" + def prune_if_due(self) -> None: + """Prune when due, at most ``PRUNE_STEP_SECONDS`` of work per call. + + The first call prunes. After a prune finishes, or fails, the next waits + ``PRUNE_INTERVAL_SECONDS``: a failed attempt still counts, so a spool + that another process keeps locked is not rescanned every worker tick. + A prune that runs out of its step continues on the next call, so a + large backlog drains over several ticks. + """ + + now = time.monotonic() + if ( + self._last_prune_at is not None + and now - self._last_prune_at < PRUNE_INTERVAL_SECONDS + ): + return + self._last_prune_at = now + if not self.prune(time_budget_seconds=PRUNE_STEP_SECONDS): + self._last_prune_at = None + + def prune(self, *, time_budget_seconds: float = math.inf) -> bool: + """Enforce the age and total-size retention limits. + Rows go in batches of ``PRUNE_BATCH_ROWS``, each its own short + transaction, with a ``PRUNE_BATCH_PAUSE_SECONDS`` pause between batches + outside this process's lock, so other processes' writers and this + build's events get in while a backlog drains. A spool with nothing to + remove is only read. Returns whether the prune finished; it stops + between batches once ``time_budget_seconds`` have passed. + """ + + deadline = time.monotonic() + time_budget_seconds cutoff = (datetime.now(UTC) - timedelta(days=RETENTION_DAYS)).isoformat() - with self._lock, self._session_factory.begin() as session: - expired_events = session.scalars( - select(TelemetryEventRecord).where( - TelemetryEventRecord.created_at < cutoff - ) - ) - for event in expired_events: - session.delete(event) - session.flush() - stored_characters = session.scalar( - select( - func.coalesce( - func.sum(func.length(TelemetryEventRecord.payload)), - 0, - ) - ) + is_expired = TelemetryEventRecord.created_at < cutoff + if self._any(select(TelemetryEventRecord.event_id).where(is_expired)): + expired = ( + select(TelemetryEventRecord.event_id) + .where(is_expired) + .limit(PRUNE_BATCH_ROWS) ) - excess = int(stored_characters or 0) - MAX_QUEUED_BYTES - if excess > 0: - self._remove_oldest_bytes(session, excess) - expired_runs = session.scalars( - select(TelemetryRunRecord).where( - TelemetryRunRecord.updated_at < cutoff, - ~TelemetryRunRecord.events.any(), - ) + in_batch = TelemetryEventRecord.event_id.in_(expired) + while self._delete(TelemetryEventRecord, in_batch) == PRUNE_BATCH_ROWS: + if not self._pause_between_batches(deadline): + return False + oldest_first = self._oldest_events_over_size_limit() + for start in range(0, len(oldest_first), PRUNE_BATCH_ROWS): + if start and not self._pause_between_batches(deadline): + return False + batch = oldest_first[start : start + PRUNE_BATCH_ROWS] + self._delete(TelemetryEventRecord, TelemetryEventRecord.event_id.in_(batch)) + is_expired_run = ( + TelemetryRunRecord.updated_at < cutoff, + ~TelemetryRunRecord.events.any(), + ) + if self._any(select(TelemetryRunRecord.run_id).where(*is_expired_run)): + expired_runs = ( + select(TelemetryRunRecord.run_id, TelemetryRunRecord.producer_id) + .where(*is_expired_run) + .limit(PRUNE_BATCH_ROWS) ) - for run in expired_runs: - session.delete(run) - self._last_prune_at = time.monotonic() + in_batch = tuple_( + TelemetryRunRecord.run_id, TelemetryRunRecord.producer_id + ).in_(expired_runs) + while self._delete(TelemetryRunRecord, in_batch) == PRUNE_BATCH_ROWS: + if not self._pause_between_batches(deadline): + return False + return True + + def _any(self, statement) -> bool: + """Return whether a read-only query matches any row.""" + + with self._lock, self._session_factory() as session: + return session.scalar(statement.limit(1)) is not None @staticmethod - def _remove_oldest_bytes(session: Session, excess: int) -> None: - statement = select(TelemetryEventRecord).order_by( - TelemetryEventRecord.created_at, - TelemetryEventRecord.sequence, - ) - removed = 0 - for event in session.scalars(statement): - session.delete(event) - removed += serialized_json_length(event.payload) - if removed >= excess: - break + def _pause_between_batches(deadline: float) -> bool: + """Pause before the next batch, or return False when out of time.""" + + if time.monotonic() + PRUNE_BATCH_PAUSE_SECONDS >= deadline: + return False + time.sleep(PRUNE_BATCH_PAUSE_SECONDS) + return True + + def _delete(self, model, criterion) -> int: + """Delete one batch of matching rows in its own transaction.""" + + with self._lock, self._session_factory.begin() as session: + return session.execute( + delete(model) + .where(criterion) + .execution_options(synchronize_session=False) + ).rowcount + + def _used_bytes(self) -> int: + """Return the bytes of the pages the spool file uses, without a scan.""" + + with self._lock, self._engine.connect() as connection: + page_size = connection.exec_driver_sql("PRAGMA page_size").scalar() + pages = connection.exec_driver_sql("PRAGMA page_count").scalar() + free_pages = connection.exec_driver_sql("PRAGMA freelist_count").scalar() + return (pages - free_pages) * page_size + + def _oldest_events_over_size_limit(self) -> list[str]: + """Return the oldest events whose removal brings storage under the cap.""" + + # Every stored payload lies on a used page, so a file that uses no more + # than the cap cannot hold more than the cap. That spares the usual + # prune a read of every payload; other writers cannot commit while + # such a read runs. + if self._used_bytes() <= MAX_QUEUED_BYTES: + return [] + stored = func.length(TelemetryEventRecord.payload, type_=Integer) + with self._lock, self._session_factory() as session: + excess = ( + session.scalar(select(func.coalesce(func.sum(stored), 0))) + - MAX_QUEUED_BYTES + ) + doomed: list[str] = [] + if excess <= 0: + return doomed + oldest = select(TelemetryEventRecord.event_id, stored).order_by( + TelemetryEventRecord.created_at, + TelemetryEventRecord.sequence, + TelemetryEventRecord.event_id, + ) + for event_id, length in session.execute(oldest): + doomed.append(event_id) + excess -= length + if excess <= 0: + break + return doomed diff --git a/packages/microcosm-build/tests/engine_free/shared/test_telemetry_emitter.py b/packages/microcosm-build/tests/engine_free/shared/test_telemetry_emitter.py index cee28f4349..72ad5aa283 100644 --- a/packages/microcosm-build/tests/engine_free/shared/test_telemetry_emitter.py +++ b/packages/microcosm-build/tests/engine_free/shared/test_telemetry_emitter.py @@ -61,8 +61,8 @@ def _recent_timestamp() -> str: """A stored-row timestamp inside the spool's retention window. - The spool prunes rows older than ``RETENTION_DAYS`` when it opens, so a - fixed calendar date in a migrated-spool fixture expires a week later. + The service's delivery worker prunes rows older than ``RETENTION_DAYS``, + so a fixed calendar date in a migrated-spool fixture expires a week later. """ return (datetime.now(UTC) - timedelta(minutes=5)).isoformat() @@ -640,6 +640,7 @@ def test_local_socket_acknowledges_after_durable_queue( ) spool = EventSpool(tmp_path / "events.sqlite3") registration = _registration() + spool.register(registration) emitter = EmitterService( socket_path=socket_path, registration=registration, diff --git a/packages/microcosm-build/tests/engine_free/shared/test_telemetry_spool_contention.py b/packages/microcosm-build/tests/engine_free/shared/test_telemetry_spool_contention.py new file mode 100644 index 0000000000..eade7baec1 --- /dev/null +++ b/packages/microcosm-build/tests/engine_free/shared/test_telemetry_spool_contention.py @@ -0,0 +1,1822 @@ +"""The telemetry emitter service under lock contention on its shared spool. + +Every concurrent build on a host shares one SQLite spool. These tests hold +its write lock from a second connection (``BEGIN IMMEDIATE``), the way another +build's service does while it writes, and check that a starting service waits +the lock out instead of exiting, that concurrent first opens migrate one at a +time, and that nothing it prints on the build's stderr is a traceback. +""" + +from __future__ import annotations + +import contextlib +import io +import json +import math +import os +import shutil +import signal +import socket +import sqlite3 +import subprocess +import sys +import tempfile +import threading +import time +from datetime import UTC, datetime, timedelta +from pathlib import Path +from types import SimpleNamespace +from unittest import mock + +import alembic.op +import pytest +from alembic import command +from hypothesis import HealthCheck, example, given, settings +from hypothesis import strategies as st +from sqlalchemy import event as sqlalchemy_event +from sqlalchemy import inspect, select +from sqlalchemy.exc import IntegrityError, OperationalError + +from microcosm.build.telemetry_emitter import LocalTelemetryEmitter, TelemetryRun +from microcosm.build.telemetry_emitter_constants import TELEMETRY_SERVICE_MODULE +from microcosm.build.telemetry_emitter_service import collector as collector_module +from microcosm.build.telemetry_emitter_service import database as database_module +from microcosm.build.telemetry_emitter_service import main as main_module +from microcosm.build.telemetry_emitter_service import runtime as runtime_module +from microcosm.build.telemetry_emitter_service import spool as spool_module +from microcosm.build.telemetry_emitter_service.collector import CollectorDelivery +from microcosm.build.telemetry_emitter_service.constants import ( + DATABASE_TIMEOUT_SECONDS, + PRUNE_INTERVAL_SECONDS, + PRUNE_STEP_SECONDS, + READY_DEADLINE_MARGIN_SECONDS, + RETENTION_DAYS, + SPOOL_LOCKED_EXIT_STATUS, + SPOOL_RETRY_INITIAL_SECONDS, + SPOOL_RETRY_MAX_SECONDS, + STARTUP_RETRY_LIMIT_SECONDS, +) +from microcosm.build.telemetry_emitter_service.contention import ( + is_transient_spool_error, + retry_spool_contention, +) +from microcosm.build.telemetry_emitter_service.database import create_spool_engine +from microcosm.build.telemetry_emitter_service.diagnostics import ( + describe_error, + write_warning, +) +from microcosm.build.telemetry_emitter_service.migrations import ( + alembic_config, + current_database_revision, + migration_head_revision, +) +from microcosm.build.telemetry_emitter_service.models import ( + SpoolModel, + TelemetryEventRecord, + TelemetryRunRecord, +) +from microcosm.build.telemetry_emitter_service.runtime import EmitterService +from microcosm.build.telemetry_emitter_service.spool import EventSpool +from microcosm.build.telemetry_protocol import ( + BUILD_COMPLETED_MESSAGE, + BUILD_STARTED_MESSAGE, + LOCAL_PING_MESSAGE, +) + +_LOOPBACK_COLLECTOR = "http://127.0.0.1:9" +_SPOOL_STATES = ("fresh", "at_head", "at_head_with_expired_rows") + + +def _registration(run_id: str = "run-a") -> dict[str, object]: + return TelemetryRun( + run_id=run_id, + country_code="US", + pipeline="test-pipeline", + producer_id="producer-a", + ).as_registration() + + +def _event(stage_id: str = "compile") -> dict[str, object]: + return {"event_type": "stage", "stage_id": stage_id, "status": "started"} + + +def _close(spool: EventSpool) -> None: + spool._engine.dispose() + + +def _prepare_spool(path: Path, state: str) -> None: + """Leave ``path`` as a new file, a spool at head, or one with expired rows.""" + + if state == "fresh": + sqlite3.connect(path).close() + return + spool = EventSpool(path) + if state == "at_head_with_expired_rows": + registration = _registration("expired-run") + spool.register(registration) + spool.append(registration, _event()) + expired = (datetime.now(UTC) - timedelta(days=RETENTION_DAYS + 1)).isoformat() + with spool._session_factory.begin() as session: + session.query(TelemetryEventRecord).update({"created_at": expired}) + _close(spool) + + +@contextlib.contextmanager +def _write_lock(path: Path): + """Hold the spool's write lock from another connection, as a writer would.""" + + connection = sqlite3.connect(path, isolation_level=None) + try: + connection.execute("BEGIN IMMEDIATE") + yield connection + finally: + if connection.in_transaction: + connection.rollback() + connection.close() + + +_SOCKET_DIRECTORIES: list[Path] = [] + + +def _short_socket_path() -> Path: + # macOS limits AF_UNIX paths to roughly 100 bytes, too few for tmp_path. + directory = Path(tempfile.mkdtemp(prefix="microcosm-test-", dir="/tmp")) + _SOCKET_DIRECTORIES.append(directory) + return directory / "e.sock" + + +@pytest.fixture(autouse=True) +def _remove_socket_directories(): + yield + while _SOCKET_DIRECTORIES: + shutil.rmtree(_SOCKET_DIRECTORIES.pop(), ignore_errors=True) + + +def _run_main(arguments: list[str], *, timeout: float) -> int: + """Run the service's main(), failing rather than hanging if it never returns.""" + + status: list[int] = [] + thread = threading.Thread( + target=lambda: status.append(main_module.main(arguments)), daemon=True + ) + thread.start() + thread.join(timeout) + assert not thread.is_alive(), f"main() still running after {timeout} s" + return status[0] + + +def _ping(socket_path: Path) -> bool: + try: + with socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) as client: + client.settimeout(0.5) + client.connect(str(socket_path)) + client.sendall(LOCAL_PING_MESSAGE) + return client.recv(16) == b"ok\n" + except OSError: + return False + + +def _close_service(socket_path: Path) -> None: + with socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) as client: + client.settimeout(2) + client.connect(str(socket_path)) + client.sendall(b'{"action":"close"}\n') + assert client.recv(16) == b"ok\n" + + +def _service_arguments( + socket_path: Path, + spool_path: Path, + *, + ready_deadline: float | None, +) -> list[str]: + arguments = [ + "--socket", + str(socket_path), + "--spool", + str(spool_path), + "--registration-json", + json.dumps(_registration()), + "--parent-pid", + str(os.getpid()), + "--development-collector-url", + _LOOPBACK_COLLECTOR, + ] + if ready_deadline is not None: + arguments.append(f"--ready-deadline={ready_deadline!r}") + return arguments + + +def _lock_error(code: int = sqlite3.SQLITE_BUSY) -> OperationalError: + driver_error = sqlite3.OperationalError("database is locked") + driver_error.sqlite_errorcode = code + return OperationalError("INSERT INTO telemetry_runs ...", {}, driver_error) + + +# --- Startup waits out a held lock ------------------------------------------ + + +@pytest.mark.parametrize("state", _SPOOL_STATES) +def test_service_registers_once_a_held_spool_lock_is_released( + tmp_path, monkeypatch, capsys, state +) -> None: + """In process: the lock outlasts several SQLite waits, so startup retries. + + Each wait is capped at 0.1 s here, and the lock is held until two attempts + have failed on it. + """ + + monkeypatch.setattr(spool_module, "DATABASE_TIMEOUT_SECONDS", 0.1) + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, state) + socket_path = _short_socket_path() + outcomes: list[tuple[str, float, BaseException | None]] = [] + + def recording(name, operation): + def wrapped(*args, **kwargs): + try: + result = operation(*args, **kwargs) + except BaseException as error: + outcomes.append((name, time.monotonic(), error)) + raise + outcomes.append((name, time.monotonic(), None)) + return result + + return wrapped + + monkeypatch.setattr(EventSpool, "__init__", recording("open", EventSpool.__init__)) + monkeypatch.setattr( + EventSpool, "register", recording("register", EventSpool.register) + ) + status: list[int] = [] + arguments = _service_arguments( + socket_path, spool_path, ready_deadline=time.time() + 60 + ) + service = threading.Thread( + target=lambda: status.append(main_module.main(arguments)), daemon=True + ) + + def failures() -> list[BaseException]: + return [error for _, _, error in outcomes if error is not None] + + try: + with _write_lock(spool_path): + service.start() + # Hold the lock until startup has failed on it twice, however long + # the host takes, so one SQLite wait cannot explain the success. + deadline = time.monotonic() + 60 + while len(failures()) < 2: + assert time.monotonic() < deadline, "startup never retried" + assert service.is_alive(), f"service exited with {status}" + time.sleep(0.02) + assert not socket_path.exists() + released_at = time.monotonic() + deadline = time.monotonic() + 60 + while not _ping(socket_path): + assert time.monotonic() < deadline, "service never became ready" + assert service.is_alive(), f"service exited with {status}" + time.sleep(0.02) + ready_at = time.monotonic() + finally: + # Stop the service even when an assertion above failed. + if socket_path.exists(): + _close_service(socket_path) + service.join(timeout=60) + + assert not service.is_alive() + assert status == [0] + assert all(is_transient_spool_error(error) for error in failures()) + name, finished_at, error = outcomes[-1] + assert (name, error) == ("register", None) + assert finished_at >= released_at + assert ready_at >= released_at + assert "Traceback" not in capsys.readouterr().err + + +def test_service_exits_75_with_one_line_before_the_build_stops_waiting( + tmp_path, capsys +) -> None: + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, "at_head") + socket_path = _short_socket_path() + arguments = _service_arguments( + socket_path, + spool_path, + ready_deadline=time.time() + READY_DEADLINE_MARGIN_SECONDS + 0.5, + ) + + with _write_lock(spool_path): + started = time.monotonic() + status = _run_main(arguments, timeout=30) + waited = time.monotonic() - started + + assert status == SPOOL_LOCKED_EXIT_STATUS + # The build would give up at margin + 0.5 s; the service has already + # said why and exited. + assert waited < READY_DEADLINE_MARGIN_SECONDS + 0.5 + assert not socket_path.exists() + error_output = capsys.readouterr().err + assert error_output.count("\n") == 1 + assert error_output.startswith( + "warning: the local telemetry emitter service could not register" + ) + assert str(spool_path) in error_output + assert "(database is locked)" in error_output + assert "Traceback" not in error_output + + +def test_startup_waits_for_the_lock_as_long_as_the_build_waits(tmp_path) -> None: + """Never worse than one long SQLite wait. + + With a 3 s build budget, the client's default before #1166, a lock held for + 1.5 s is waited out, as the old service's single 5 s busy wait did. + """ + + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, "at_head") + socket_path = _short_socket_path() + arguments = _service_arguments( + socket_path, spool_path, ready_deadline=time.time() + 3.0 + ) + status: list[int] = [] + service = threading.Thread( + target=lambda: status.append(main_module.main(arguments)), daemon=True + ) + try: + with _write_lock(spool_path): + service.start() + time.sleep(1.5) + deadline = time.monotonic() + 10 + while not _ping(socket_path): + assert time.monotonic() < deadline, f"service never ready: {status}" + assert service.is_alive(), f"service exited with {status}" + time.sleep(0.02) + finally: + if socket_path.exists(): + _close_service(socket_path) + service.join(timeout=60) + assert not service.is_alive() + assert status == [0] + + +def test_unexpected_service_failure_is_one_line_with_status_1(tmp_path, capsys) -> None: + occupied = tmp_path / "not-a-directory" + occupied.write_text("") + arguments = _service_arguments( + _short_socket_path(), + occupied / "events.sqlite3", + ready_deadline=time.time() + 60, + ) + + assert _run_main(arguments, timeout=30) == 1 + + error_output = capsys.readouterr().err + assert error_output.count("\n") == 1 + assert error_output.startswith( + "warning: the local telemetry emitter service stopped: " + ) + assert "Traceback" not in error_output + + +def _parse_ready_deadline(value: str): + return main_module.build_parser().parse_args( + [ + "--socket", + "s", + "--spool", + "q", + "--registration-json", + "{}", + "--parent-pid", + "1", + "--ready-deadline", + value, + ] + ) + + +def test_ready_deadline_rejects_nan_and_caps_infinity(capsys) -> None: + with pytest.raises(SystemExit) as raised: + _parse_ready_deadline("nan") + assert raised.value.code == 2 + # Invalid arguments are one line on the build's stderr, not a usage block. + assert capsys.readouterr().err == ( + "warning: the local telemetry emitter service could not start: " + "argument --ready-deadline: ready deadline must be a number of seconds\n" + ) + + arguments = _parse_ready_deadline("inf") + deadline = main_module.startup_deadline( + arguments.ready_deadline, now_unix=time.time(), now_monotonic=100.0 + ) + assert deadline == ( + 100.0 + STARTUP_RETRY_LIMIT_SECONDS - READY_DEADLINE_MARGIN_SECONDS + ) + + +def test_startup_waits_end_by_the_deadline_and_the_spool_then_waits_normally( + tmp_path, +) -> None: + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, "at_head") + spool = EventSpool(spool_path, busy_deadline=time.monotonic() + 0.3) + try: + with _write_lock(spool_path): + started = time.monotonic() + with pytest.raises(OperationalError): + spool.register(_registration()) + waited = time.monotonic() - started + assert waited < 1.0 + # A far deadline still waits no longer than a normal statement, and a + # past one does not wait at all. + spool.busy_deadline = time.monotonic() + 100 + assert spool.busy_timeout_seconds() == DATABASE_TIMEOUT_SECONDS + spool.busy_deadline = time.monotonic() - 1 + assert spool.busy_timeout_seconds() == 0 + finally: + _close(spool) + + registered = main_module.open_registered_spool( + spool_path, _registration(), deadline=time.monotonic() + 10 + ) + try: + assert registered.busy_deadline is None + with registered._engine.connect() as connection: + milliseconds = connection.exec_driver_sql("PRAGMA busy_timeout").scalar() + assert milliseconds == DATABASE_TIMEOUT_SECONDS * 1000 + finally: + _close(registered) + + +def test_without_a_deadline_startup_makes_one_normal_attempt(tmp_path) -> None: + """A build that passes no deadline gets the old behaviour: one 5 s wait.""" + + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, "at_head") + opened: list[EventSpool] = [] + original_init = EventSpool.__init__ + + def recording_init(self, *args, **kwargs): + original_init(self, *args, **kwargs) + opened.append(self) + + with mock.patch.object(EventSpool, "__init__", recording_init): + spool = main_module.open_registered_spool( + spool_path, _registration(), deadline=None + ) + try: + assert [item.busy_deadline for item in opened] == [None] + assert spool.busy_timeout_seconds() == DATABASE_TIMEOUT_SECONDS + finally: + _close(spool) + + +def test_build_keeps_telemetry_when_the_spool_is_locked_past_a_busy_wait( + tmp_path, capfd, real_local_telemetry +) -> None: + """End to end: the real client starts the real service process.""" + + spool_path = tmp_path / "spool" / "events.sqlite3" + spool_directory = spool_path.parent + _prepare_spool(spool_path, "at_head") + # Opening the spool sets its directory to 0o700, which tells this test + # when the service has reached the spool without a process inspector. + spool_directory.chmod(0o750) + started: dict[str, object] = {} + + def start() -> None: + started["emitter"] = LocalTelemetryEmitter.start( + run_id="locked-spool-run", + country_code="US", + pipeline="test-pipeline", + development_collector_url=_LOOPBACK_COLLECTOR, + spool_path=spool_path, + heartbeat_seconds=60, + startup_timeout_seconds=90, + ) + started["returned_at"] = time.monotonic() + + client = threading.Thread(target=start, daemon=True) + with _write_lock(spool_path): + client.start() + deadline = time.monotonic() + 60 + while spool_directory.stat().st_mode & 0o777 != 0o700: + assert time.monotonic() < deadline, "service never opened the spool" + assert client.is_alive(), "client returned before the service opened" + time.sleep(0.02) + # One full SQLite busy wait, and then some, passes with the lock held. + time.sleep(DATABASE_TIMEOUT_SECONDS + 1.0) + assert client.is_alive(), "client stopped waiting while the spool was locked" + released_at = time.monotonic() + client.join(timeout=90) + + emitter = started["emitter"] + assert isinstance(emitter, LocalTelemetryEmitter) + try: + assert emitter.available + assert started["returned_at"] > released_at + emitter.stage("compile", message="Compiling.") + emitter.complete() + assert emitter._process is not None + assert emitter._process.wait(timeout=30) == 0 + finally: + # A failed assertion must not leave the service running. + if emitter._process is not None and emitter._process.poll() is None: + emitter._process.terminate() + emitter._process.wait(timeout=10) + + spool = EventSpool(spool_path) + try: + events = spool.batch("locked-spool-run", emitter.run.producer_id) + finally: + _close(spool) + assert [event["sequence"] for event in events] == list(range(1, len(events) + 1)) + assert events[0]["message"] == BUILD_STARTED_MESSAGE + assert events[-1]["message"] == BUILD_COMPLETED_MESSAGE + assert "Traceback" not in capfd.readouterr().err + + +def test_service_process_reports_a_locked_spool_in_one_line(tmp_path) -> None: + """The real process: exit 75 and a single stderr line, no traceback.""" + + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, "at_head") + socket_path = _short_socket_path() + with _write_lock(spool_path): + completed = subprocess.run( + [ + sys.executable, + "-m", + TELEMETRY_SERVICE_MODULE, + # A deadline already past allows one attempt. + *_service_arguments( + socket_path, spool_path, ready_deadline=time.time() + ), + ], + stdin=subprocess.DEVNULL, + capture_output=True, + text=True, + timeout=180, + ) + + assert completed.returncode == SPOOL_LOCKED_EXIT_STATUS + lines = [line for line in completed.stderr.splitlines() if line.strip()] + assert len(lines) == 1, completed.stderr + assert lines[0].startswith( + "warning: the local telemetry emitter service could not register" + ) + assert not socket_path.exists() + + +def test_an_interrupted_service_exits_without_a_traceback(tmp_path) -> None: + """SIGINT ends the real process as SIGTERM does, with nothing on stderr.""" + + spool_path = tmp_path / "spool" / "events.sqlite3" + _prepare_spool(spool_path, "at_head") + # Opening the spool sets its directory to 0o700: the service is retrying. + spool_path.parent.chmod(0o750) + socket_path = _short_socket_path() + with _write_lock(spool_path): + process = subprocess.Popen( + [ + sys.executable, + "-m", + TELEMETRY_SERVICE_MODULE, + *_service_arguments( + socket_path, spool_path, ready_deadline=time.time() + 60 + ), + ], + stdin=subprocess.DEVNULL, + stdout=subprocess.DEVNULL, + stderr=subprocess.PIPE, + text=True, + ) + try: + deadline = time.monotonic() + 120 + while spool_path.parent.stat().st_mode & 0o777 != 0o700: + assert time.monotonic() < deadline, "service never opened the spool" + assert process.poll() is None, "service exited before opening" + time.sleep(0.02) + process.send_signal(signal.SIGINT) + _, error_output = process.communicate(timeout=30) + finally: + if process.poll() is None: + process.kill() + process.wait() + + assert process.returncode == -signal.SIGINT + assert error_output == "" + + +def test_client_passes_its_wait_as_a_wall_clock_ready_deadline( + tmp_path, monkeypatch, real_local_telemetry +) -> None: + commands: list[list[str]] = [] + + class ExitedProcess: + def poll(self): + return 1 + + def wait(self, timeout=None): + return 1 + + def popen(command, **kwargs): + commands.append(command) + return ExitedProcess() + + monkeypatch.setattr("microcosm.build.telemetry_emitter.subprocess.Popen", popen) + before = time.time() + LocalTelemetryEmitter.start( + run_id="deadline", + country_code="US", + pipeline="test-pipeline", + development_collector_url=_LOOPBACK_COLLECTOR, + spool_path=tmp_path / "events.sqlite3", + startup_timeout_seconds=42, + ) + after = time.time() + + (command,) = commands + (argument,) = [part for part in command if part.startswith("--ready-deadline=")] + ready_deadline = float(argument.removeprefix("--ready-deadline=")) + assert before + 42 <= ready_deadline <= after + 42 + # One token, so the service parses even a deadline that is already past. + assert ( + main_module.build_parser() + .parse_args( + ["--socket", "s", "--spool", "q", "--registration-json", "{}"] + + ["--parent-pid", "1", "--ready-deadline=-inf"] + ) + .ready_deadline + == -math.inf + ) + + +@given( + ready_deadline=st.floats(-1e6, 1e6), + now_unix=st.floats(-1e6, 1e6), + now_monotonic=st.floats(0, 1e6), +) +def test_startup_gives_up_before_the_build_and_within_the_limit( + ready_deadline, now_unix, now_monotonic +) -> None: + deadline = main_module.startup_deadline( + ready_deadline, now_unix=now_unix, now_monotonic=now_monotonic + ) + waits = deadline - now_monotonic + budget = ready_deadline - now_unix + # It stops at least the margin before the build gives up, and within the + # limit however far away the build's deadline is. + assert waits <= budget - READY_DEADLINE_MARGIN_SECONDS + 1e-6 + assert waits <= STARTUP_RETRY_LIMIT_SECONDS - READY_DEADLINE_MARGIN_SECONDS + 1e-6 + # And it uses all of that time: nothing is left on the table. + assert waits >= min(budget, STARTUP_RETRY_LIMIT_SECONDS) - ( + READY_DEADLINE_MARGIN_SECONDS + 1e-6 + ) + assert ( + main_module.startup_deadline( + None, now_unix=now_unix, now_monotonic=now_monotonic + ) + is None + ) + + +# --- Migrations run one process at a time, atomically ----------------------- + + +def test_opening_a_spool_at_head_takes_no_write_lock(tmp_path) -> None: + """Retention runs in the worker, so expired rows don't lock the opener.""" + + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, "at_head_with_expired_rows") + + with _write_lock(spool_path): + started = time.monotonic() + spool = EventSpool(spool_path) + opened_in = time.monotonic() - started + try: + assert opened_in < DATABASE_TIMEOUT_SECONDS + assert spool.has_pending() + finally: + _close(spool) + + +def test_a_failed_migration_leaves_no_partial_schema(tmp_path, monkeypatch) -> None: + spool_path = tmp_path / "events.sqlite3" + + def fail(*args, **kwargs): + raise RuntimeError("migration interrupted") + + monkeypatch.setattr(alembic.op, "create_index", fail) + with pytest.raises(RuntimeError, match="migration interrupted"): + EventSpool(spool_path) + + connection = sqlite3.connect(spool_path) + try: + tables = connection.execute( + "SELECT name FROM sqlite_master WHERE type = 'table'" + ).fetchall() + finally: + connection.close() + assert tables == [] + + +def test_an_opener_waits_for_a_migration_in_progress(tmp_path, monkeypatch) -> None: + """A second opener waits, then finds the spool at head and changes nothing. + + Before migrations took the write lock first, the waiting opener had + already read an empty schema and failed with "table already exists". + """ + + spool_path = tmp_path / "events.sqlite3" + sqlite3.connect(spool_path).close() + migrator = create_spool_engine(spool_path, immediate_transactions=True) + opened: list[EventSpool] = [] + failures: list[BaseException] = [] + + def open_spool() -> None: + try: + opened.append(EventSpool(spool_path)) + except BaseException as error: + failures.append(error) + + second = threading.Thread(target=open_spool, daemon=True) + waiting = threading.Event() + begin_immediate = database_module._begin_immediate + + def signalling_begin_immediate(connection) -> None: + waiting.set() + begin_immediate(connection) + + try: + with migrator.begin() as connection: + # Only the opener's migration engine is created after this point. + monkeypatch.setattr( + database_module, "_begin_immediate", signalling_begin_immediate + ) + second.start() + # The opener has asked for the write lock this migration holds. + assert waiting.wait(timeout=30), "the opener never began its migration" + time.sleep(0.2) + assert second.is_alive() + SpoolModel.metadata.create_all(connection) + connection.exec_driver_sql( + "CREATE TABLE alembic_version (version_num VARCHAR(32) NOT NULL, " + "CONSTRAINT alembic_version_pkc PRIMARY KEY (version_num))" + ) + connection.exec_driver_sql( + "INSERT INTO alembic_version (version_num) VALUES (?)", + (migration_head_revision(),), + ) + second.join(timeout=DATABASE_TIMEOUT_SECONDS + 5) + finally: + migrator.dispose() + + assert failures == [] + (spool,) = opened + _close(spool) + assert current_database_revision(spool_path) == migration_head_revision() + check = create_spool_engine(spool_path) + try: + with ( + check.begin() as connection, + alembic_config(connection=connection) as config, + ): + command.check(config) + assert set(inspect(check).get_table_names()) == { + "alembic_version", + "telemetry_events", + "telemetry_runs", + } + finally: + check.dispose() + + +_CONCURRENT_OPEN = """ +import sys, time +from pathlib import Path +from microcosm.build.telemetry_emitter_service.spool import EventSpool +barrier, path, index = Path(sys.argv[1]), sys.argv[2], sys.argv[3] +(barrier / ("ready-" + index)).touch() +while not (barrier / "go").exists(): + time.sleep(0.001) +spool = EventSpool(path) +spool.register({"run_id": "run-" + index, "producer_id": "producer-" + index}) +""" + + +def test_concurrent_first_opens_of_a_new_spool_all_succeed(tmp_path) -> None: + """Before migrations took the write lock, about half of these failed.""" + + spool_path = tmp_path / "events.sqlite3" + barrier = tmp_path / "barrier" + barrier.mkdir() + count = 6 + processes = [ + subprocess.Popen( + [sys.executable, "-c", _CONCURRENT_OPEN, str(barrier), str(spool_path)] + + [str(index)], + stdin=subprocess.DEVNULL, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + text=True, + ) + for index in range(count) + ] + try: + # Release every process at once, after all of them have imported. + deadline = time.monotonic() + 120 + while len(list(barrier.glob("ready-*"))) < count: + assert time.monotonic() < deadline, "workers never became ready" + assert all(process.poll() is None for process in processes) + time.sleep(0.01) + (barrier / "go").touch() + results = [process.communicate(timeout=120) for process in processes] + finally: + for process in processes: + if process.poll() is None: + process.kill() + process.wait() + + assert [process.returncode for process in processes] == [0] * count, results + assert current_database_revision(spool_path) == migration_head_revision() + connection = sqlite3.connect(spool_path) + try: + (registered,) = connection.execute( + "SELECT count(*) FROM telemetry_runs" + ).fetchone() + finally: + connection.close() + assert registered == count + + +# --- Retention moved off the readiness and event paths ----------------------- + + +def test_appends_never_prune(tmp_path, monkeypatch) -> None: + spool = EventSpool(tmp_path / "events.sqlite3") + pruned: list[float] = [] + monkeypatch.setattr(spool, "prune", lambda: pruned.append(time.monotonic())) + registration = _registration() + spool.register(registration) + try: + for _ in range(3): + spool.append(registration, _event()) + assert pruned == [] + finally: + _close(spool) + + +@given( + gaps=st.lists(st.floats(0, 3 * PRUNE_INTERVAL_SECONDS), max_size=30), + results=st.lists( + st.sampled_from(["finished", "unfinished", "failed"]), max_size=30 + ), +) +# A call exactly one interval after a finished prune is due. +@example(gaps=[PRUNE_INTERVAL_SECONDS], results=["finished", "finished"]) +@settings(suppress_health_check=[HealthCheck.function_scoped_fixture]) +def test_prune_runs_once_per_interval_until_a_backlog_is_drained( + monkeypatch, gaps, results +) -> None: + clock = SimpleNamespace(now=1_000.0) + monkeypatch.setattr( + spool_module, "time", SimpleNamespace(monotonic=lambda: clock.now) + ) + attempts: list[tuple[float, str]] = [] + outcomes = iter(results) + + def prune(*, time_budget_seconds): + assert time_budget_seconds == PRUNE_STEP_SECONDS + result = next(outcomes, "finished") + attempts.append((clock.now, result)) + if result == "failed": + raise _lock_error() + return result == "finished" + + # prune_if_due reads only the schedule and prune, so no database is needed. + spool = EventSpool.__new__(EventSpool) + spool._last_prune_at = None + spool.prune = prune + calls = [clock.now] + for gap in gaps: + calls.append(calls[-1] + gap) + for now in calls: + clock.now = now + with contextlib.suppress(OperationalError): + spool.prune_if_due() + + # Reference schedule: the first call prunes. A later call prunes at once + # when the previous prune ran out of its step; otherwise once the interval + # has passed since the previous attempt, whether it finished or failed. + expected: list[float] = [] + for now in calls: + previous = attempts[len(expected) - 1] if expected else None + if ( + previous is None + or previous[1] == "unfinished" + or now - previous[0] >= PRUNE_INTERVAL_SECONDS + ): + expected.append(now) + assert [at for at, _ in attempts] == expected + + +# --- Lock-error classification ------------------------------------------------ + + +def test_only_busy_and_locked_result_codes_are_transient() -> None: + """Every primary code with several extensions, raw and wrapped.""" + + busy_or_locked = {5, 6} # SQLITE_BUSY and SQLITE_LOCKED, from the SQLite docs + for primary in range(256): + for extension in (0, 1, 2, 3, 255): + code = primary | extension << 8 + error = sqlite3.OperationalError("message") + error.sqlite_errorcode = code + expected = primary in busy_or_locked + assert is_transient_spool_error(error) is expected, code + assert is_transient_spool_error(_lock_error(code)) is expected, code + + +def test_real_sqlite_errors_are_classified_by_what_retrying_can_fix(tmp_path) -> None: + """Differential check against errors SQLite itself raises.""" + + path = tmp_path / "errors.sqlite3" + engine = create_spool_engine(path) + impatient = sqlite3.connect(path, timeout=0, isolation_level=None) + try: + with engine.begin() as connection: + connection.exec_driver_sql("CREATE TABLE t (id INTEGER PRIMARY KEY)") + connection.exec_driver_sql("INSERT INTO t VALUES (1)") + with _write_lock(path): + with pytest.raises(sqlite3.OperationalError) as locked: + impatient.execute("INSERT INTO t VALUES (2)") + with pytest.raises(OperationalError) as exists: + with engine.begin() as connection: + connection.exec_driver_sql("CREATE TABLE t (id INTEGER)") + with pytest.raises(IntegrityError) as duplicate: + with engine.begin() as connection: + connection.exec_driver_sql("INSERT INTO t VALUES (1)") + finally: + impatient.close() + engine.dispose() + + assert is_transient_spool_error(locked.value) + assert not is_transient_spool_error(exists.value) + assert not is_transient_spool_error(duplicate.value) + assert not is_transient_spool_error(RuntimeError("database is locked")) + assert describe_error(exists.value) == "table t already exists" + + +# --- The retry helper --------------------------------------------------------- + +# Lock errors are weighted up and attempts are often short, so most examples +# retry several times and many give up within one wait of the deadline. +_OUTCOME = st.sampled_from(["locked", "locked", "locked", "ok", "fatal"]) +_ATTEMPT_SECONDS = st.one_of(st.just(0.0), st.floats(0, 0.3), st.floats(0, 6)) +_LOCKED_THEN_OK = [("locked", 0.0)] * 6 + [("ok", 0.0)] + + +@given( + outcomes=st.lists( + st.tuples(_OUTCOME, _ATTEMPT_SECONDS), + min_size=1, + max_size=40, + ), + window=st.one_of(st.just(-math.inf), st.floats(-1, 3), st.floats(-5, 60)), + jitter_fraction=st.floats(0, 1), + # How far each sleep overruns, as sleeps do on a loaded host. + oversleeps=st.lists(st.one_of(st.just(0.0), st.floats(0, 3)), max_size=8), +) +# The first retry's full wait (0.05 s) would cross a deadline 0.04 s away, or +# start exactly on one 0.05 s away. +@example(outcomes=_LOCKED_THEN_OK, window=0.04, jitter_fraction=1.0, oversleeps=[]) +@example(outcomes=_LOCKED_THEN_OK, window=0.05, jitter_fraction=1.0, oversleeps=[]) +# Six retries fit, so the delays must double up to the cap. +@example(outcomes=_LOCKED_THEN_OK, window=10.0, jitter_fraction=0.5, oversleeps=[]) +# The first sleep fits a deadline 1 s away but wakes 3 s late, past it. +@example(outcomes=_LOCKED_THEN_OK, window=1.0, jitter_fraction=0.5, oversleeps=[3.0]) +def test_retry_respects_its_deadline_and_backoff( + outcomes, window, jitter_fraction, oversleeps +): + clock = SimpleNamespace(now=100.0) + deadline = clock.now + window + attempt_starts: list[float] = [] + jitters: list[tuple[float, float, float, float]] = [] # (at, low, high, wait) + waits: list[tuple[float, float]] = [] # (started, seconds) + wakes: list[float] = [] + late = iter(oversleeps) + + def operation(): + index = len(attempt_starts) + attempt_starts.append(clock.now) + kind, duration = outcomes[min(index, len(outcomes) - 1)] + clock.now += duration + if kind == "locked": + raise _lock_error() + if kind == "fatal": + raise ValueError("schema error") + return index + + def jitter(low, high): + wait = low + jitter_fraction * (high - low) + jitters.append((clock.now, low, high, wait)) + return wait + + def sleep(seconds): + waits.append((clock.now, seconds)) + clock.now += seconds + next(late, 0.0) + wakes.append(clock.now) + + try: + result = retry_spool_contention( + operation, + deadline=deadline, + clock=lambda: clock.now, + sleep=sleep, + jitter=jitter, + ) + except ValueError: + outcome = "fatal" + except OperationalError: + outcome = "locked" + else: + outcome = "ok" + + kinds = [outcomes[min(i, len(outcomes) - 1)][0] for i in range(len(attempt_starts))] + # Every attempt but the last was a lock error, and the result is the last's. + assert all(kind == "locked" for kind in kinds[:-1]) + assert kinds[-1] == outcome + if outcome == "ok": + assert result == len(attempt_starts) - 1 + # The first attempt always runs; every later one starts before the deadline, + # even after a sleep that overran, and no wait is asked to reach it. + assert all(start < deadline for start in attempt_starts[1:]) + assert all(started + seconds < deadline for started, seconds in waits) + overran = bool(wakes) and wakes[-1] >= deadline + # Each lock error draws one wait in [delay / 2, delay]; delays double to a + # cap; every wait drawn is slept except one that would reach the deadline, + # and every sleep is followed by an attempt unless it woke too late. + assert len(jitters) == kinds.count("locked") + assert len(waits) == len(attempt_starts) - 1 + overran + for index, (_, low, high, wait) in enumerate(jitters): + assert high == min( + SPOOL_RETRY_MAX_SECONDS, SPOOL_RETRY_INITIAL_SECONDS * 2**index + ) + assert low == high / 2 + assert low <= wait <= high + assert [seconds for _, seconds in waits] == [ + wait for _, _, _, wait in jitters[: len(waits)] + ] + # A lock error escapes only when its retry could not start before the + # deadline: the wait would reach it, or the sleep woke past it. + if outcome == "locked": + at, _, _, wait = jitters[-1] + assert at + wait >= deadline or overran + else: + assert not overran + + +def test_retry_with_no_deadline_makes_one_attempt() -> None: + attempts: list[int] = [] + + def operation(): + attempts.append(1) + raise _lock_error() + + with pytest.raises(OperationalError): + retry_spool_contention(operation, deadline=-math.inf, sleep=pytest.fail) + assert attempts == [1] + + +# --- The delivery worker keeps running ---------------------------------------- + + +class _Outcomes: + """Hands each worker step the next scripted outcome, recording failures.""" + + def __init__(self, script: list[str]) -> None: + self._script = iter(script) + self.raised: list[str] = [] + + def next(self, value=None): + kind = next(self._script, "ok") + if kind == "locked": + self.raised.append("OperationalError") + raise _lock_error() + if kind == "runtime": + self.raised.append("RuntimeError") + raise RuntimeError("collector bug") + if kind == "value": + self.raised.append("ValueError") + raise ValueError("bad response") + return value + + +@settings(suppress_health_check=[HealthCheck.function_scoped_fixture]) +@given( + script=st.lists( + st.sampled_from(["ok", "ok", "locked", "runtime", "value"]), max_size=200 + ), + ticks=st.integers(1, 30), + parent_dies_at=st.one_of(st.none(), st.integers(1, 30)), + parent_check_raises=st.booleans(), + closed_at=st.one_of(st.none(), st.integers(1, 30)), + heartbeat_seconds=st.sampled_from([1.0, 2.0, 3.5]), +) +def test_worker_survives_any_step_failure( + monkeypatch, + script, + ticks, + parent_dies_at, + parent_check_raises, + closed_at, + heartbeat_seconds, +) -> None: + """The worker never dies, checks its build every tick, and tells a crash + from a clean close. + + ``closed_at`` is the tick on which the build's close arrives while a step + runs, as it does when the accept thread handles it mid-tick; the build may + then exit before the tick ends. ``parent_check_raises`` makes the check of + a dead build raise instead of returning False. + """ + + clock = SimpleNamespace(now=0.0, tick=0) + monkeypatch.setattr( + runtime_module, + "time", + SimpleNamespace( + monotonic=lambda: clock.now, + sleep=lambda seconds: setattr(clock, "now", clock.now + seconds), + ), + ) + outcomes = _Outcomes(script) + appended: list[tuple[int, str]] = [] + parent_checks: list[int] = [] + + class Stop: + def __init__(self) -> None: + self.flag = False + + def wait(self, timeout): + clock.now += timeout + clock.tick += 1 + return self.flag or clock.tick > ticks + + def set(self): + self.flag = True + + def is_set(self): + return self.flag + + def append(registration, event, *, resources=None): + outcomes.next() + appended.append((clock.tick, event["event_type"] + ":" + event["status"])) + + def parent_alive(): + parent_checks.append(clock.tick) + alive = parent_dies_at is None or clock.tick < parent_dies_at + if not alive and parent_check_raises: + raise OverflowError("signed integer is greater than maximum") + return alive + + def flush_once(): + if clock.tick == closed_at: + service._stop.set() + return outcomes.next(False) + + service = EmitterService( + socket_path=Path("/unused"), + registration=_registration(), + spool=SimpleNamespace( + append=append, + prune_if_due=outcomes.next, + has_deliverable=lambda: outcomes.next(False), + ), + delivery=SimpleNamespace(flush_once=flush_once), + sampler=SimpleNamespace( + sample=lambda: outcomes.next({}), parent_alive=parent_alive + ), + heartbeat_seconds=heartbeat_seconds, + drain_seconds=2.0, + ) + service._stop = Stop() + heartbeat_attempts: list[tuple[int, float, bool]] = [] + append_heartbeat = service._append_heartbeat + + def recorded_heartbeat() -> None: + try: + append_heartbeat() + except Exception: + heartbeat_attempts.append((clock.tick, clock.now, False)) + raise + heartbeat_attempts.append((clock.tick, clock.now, True)) + + service._append_heartbeat = recorded_heartbeat + exit_records: list[int] = [] + append_unexpected_exit = service._append_unexpected_exit + + def recorded_unexpected_exit() -> None: + exit_records.append(clock.tick) + append_unexpected_exit() + + service._append_unexpected_exit = recorded_unexpected_exit + error_output = io.StringIO() + + with contextlib.redirect_stderr(error_output): + service._worker() # never raises + + closed = closed_at is not None and closed_at <= ticks + last_tick = min( + tick for tick in (ticks, parent_dies_at, closed_at) if tick is not None + ) + # The parent is checked on every tick until it is found dead, except on the + # tick the build closed. + assert parent_checks == [ + tick for tick in range(1, last_tick + 1) if not (closed and tick == closed_at) + ] + # A build that died without closing is recorded once, on the tick it is + # found, which stops the loop; a build that closed first never is. + crashed = ( + parent_dies_at is not None + and parent_dies_at <= ticks + and (not closed or parent_dies_at < closed_at) + ) + assert exit_records == ([parent_dies_at] if crashed else []) + assert service._stop.is_set() is (crashed or closed) + # Reference heartbeat schedule: due one interval after the start or the + # last success; a failed heartbeat stays due and is retried next tick. + due = heartbeat_seconds + expected_ticks: list[int] = [] + attempts = iter(heartbeat_attempts) + for tick in range(1, last_tick + 1): + now = float(tick) + if now >= due: + expected_ticks.append(tick) + attempt_tick, _, succeeded = next(attempts) + assert attempt_tick == tick + if succeeded: + due = now + heartbeat_seconds + assert [tick for tick, _, _ in heartbeat_attempts] == expected_ticks + # One line per error type other than lock contention, which is silent. + reported = { + name for name in outcomes.raised if name in {"RuntimeError", "ValueError"} + } + if crashed and parent_check_raises: + reported.add("OverflowError") + lines = error_output.getvalue().splitlines() + assert len(lines) == len(reported) + assert {line.split(" hit ")[1].split(" ")[0] for line in lines} == reported + assert not any("Traceback" in line for line in lines) + + +@settings(suppress_health_check=[HealthCheck.function_scoped_fixture]) +@given( + script=st.lists(st.sampled_from(["ok", "locked", "runtime", "value"]), max_size=60), + deliverable=st.lists(st.booleans(), max_size=60), + drain_seconds=st.sampled_from([0.0, 0.4, 2.0, 5.0]), +) +def test_drain_survives_any_failure_and_keeps_its_deadline( + monkeypatch, script, deliverable, drain_seconds +) -> None: + clock = SimpleNamespace(now=0.0) + monkeypatch.setattr( + runtime_module, + "time", + SimpleNamespace( + monotonic=lambda: clock.now, + sleep=lambda seconds: setattr(clock, "now", clock.now + seconds), + ), + ) + outcomes = _Outcomes(script) + answers = iter(deliverable) + checks: list[float] = [] + + def has_deliverable() -> bool: + checks.append(clock.now) + outcomes.next() + return next(answers, False) + + def flush_once() -> bool: + clock.now += 0.01 + outcomes.next() + return False + + service = EmitterService( + socket_path=Path("/unused"), + registration=_registration(), + spool=SimpleNamespace(has_deliverable=has_deliverable), + delivery=SimpleNamespace(flush_once=flush_once), + sampler=SimpleNamespace(), + heartbeat_seconds=60, + drain_seconds=drain_seconds, + ) + error_output = io.StringIO() + + with contextlib.redirect_stderr(error_output): + service._drain() # never raises + + # It never runs past its deadline, and checks again after every failure + # until nothing is deliverable or the deadline passes. + assert clock.now <= drain_seconds + 0.01 + 1e-9 + assert all(check < drain_seconds for check in checks) + reported = { + name for name in outcomes.raised if name in {"RuntimeError", "ValueError"} + } + assert len(error_output.getvalue().splitlines()) == len(reported) + + +def test_unexpected_exit_waits_out_lock_contention(monkeypatch) -> None: + clock = SimpleNamespace(now=0.0) + monkeypatch.setattr( + runtime_module, + "time", + SimpleNamespace( + monotonic=lambda: clock.now, + sleep=lambda seconds: setattr(clock, "now", clock.now + seconds), + ), + ) + attempts: list[float] = [] + + def append(registration, event, *, resources=None): + attempts.append(clock.now) + clock.now += 0.2 + if len(attempts) < 4: + raise _lock_error() + + service = EmitterService( + socket_path=Path("/unused"), + registration=_registration(), + spool=SimpleNamespace(append=append), + delivery=SimpleNamespace(), + sampler=SimpleNamespace(sample=dict), + heartbeat_seconds=60, + drain_seconds=15, + ) + + assert service._attempt(service._append_unexpected_exit) + assert len(attempts) == 4 + assert attempts[-1] < 15 + + +def test_service_stops_serving_when_its_worker_dies(tmp_path) -> None: + """Only the worker notices a dead build, so serving must not outlive it.""" + + spool = EventSpool(tmp_path / "events.sqlite3") + spool.register(_registration()) + socket_path = _short_socket_path() + service = EmitterService( + socket_path=socket_path, + registration=_registration(), + spool=spool, + delivery=SimpleNamespace(flush_once=lambda: False), + sampler=SimpleNamespace(sample=dict, parent_alive=lambda: True), + heartbeat_seconds=60, + drain_seconds=0, + ) + service._worker = lambda: None # returns at once without stopping the service + serving = threading.Thread(target=service.run, daemon=True) + try: + serving.start() + serving.join(timeout=10) + assert not serving.is_alive() + assert not socket_path.exists() + finally: + # A failing run must not leave a server thread behind. + service._stop.set() + serving.join(timeout=5) + _close(spool) + + +class _GoneStream: + """A stderr whose reader has exited, like a build piped through ``tee``.""" + + def write(self, text): + raise BrokenPipeError(32, "Broken pipe") + + def flush(self): + raise BrokenPipeError(32, "Broken pipe") + + +def test_warnings_never_raise_when_the_builds_stderr_is_gone(monkeypatch) -> None: + monkeypatch.setattr(sys, "stderr", _GoneStream()) + write_warning("the service keeps running") + closed = io.StringIO() + closed.close() + monkeypatch.setattr(sys, "stderr", closed) + write_warning("the service keeps running") + + monkeypatch.setattr(sys, "stderr", _GoneStream()) + service = EmitterService( + socket_path=Path("/unused"), + registration=_registration(), + spool=SimpleNamespace(), + delivery=SimpleNamespace(), + sampler=SimpleNamespace(), + heartbeat_seconds=60, + ) + + def bug() -> None: + raise RuntimeError("collector bug") + + assert service._attempt(bug) is False + + +def test_delivery_backs_off_after_an_unexpected_error(monkeypatch) -> None: + """The worker survives the error, so it must not turn into a request a tick.""" + + requests: list[str] = [] + + def post(url, payload, bearer_token, **kwargs): + requests.append(url) + return 200, {"access_token": "collector-token", "expires_in": None} + + monkeypatch.setattr(collector_module, "_http_post", post) + monkeypatch.setenv("HF_TOKEN", "hf-test-token") + delivery = CollectorDelivery( + SimpleNamespace(pending_runs=lambda: [_registration()]), + development_collector_url=_LOOPBACK_COLLECTOR, + ) + + with pytest.raises(TypeError): + delivery.flush_once() + assert delivery.flush_once() is False + assert len(requests) == 1 + + +def test_delivery_retries_a_locked_spool_on_the_next_tick(monkeypatch) -> None: + attempts: list[int] = [] + + def pending_runs(): + attempts.append(1) + raise _lock_error() + + delivery = CollectorDelivery( + SimpleNamespace(pending_runs=pending_runs), + development_collector_url=_LOOPBACK_COLLECTOR, + ) + for _ in range(3): + with pytest.raises(OperationalError): + delivery.flush_once() + assert len(attempts) == 3 + + +def test_a_spool_from_an_unknown_migration_is_refused_without_the_write_lock( + tmp_path, +) -> None: + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, "at_head") + connection = sqlite3.connect(spool_path) + connection.execute("UPDATE alembic_version SET version_num = 'from_elsewhere'") + connection.commit() + connection.close() + + with _write_lock(spool_path): + started = time.monotonic() + with pytest.raises(RuntimeError, match="'from_elsewhere' is not in"): + EventSpool(spool_path) + assert time.monotonic() - started < DATABASE_TIMEOUT_SECONDS + + +# --- Retention in short batches, matching the single-pass rule ---------------- + +_STAMP_ORIGIN = datetime(2026, 10, 9, 12, tzinfo=UTC) + + +def _stamp(age_days: float, index: int) -> str: + # The index keeps stamps distinct, so the oldest-first order is unambiguous. + return ( + _STAMP_ORIGIN - timedelta(days=age_days) + timedelta(microseconds=index) + ).isoformat() + + +@settings(max_examples=40, deadline=None) +@given( + events=st.lists( + st.tuples( + st.integers(0, 2), # run + st.floats(0, 2 * RETENTION_DAYS), # age in days + st.integers(0, 60), # padding characters + ), + max_size=18, + ), + run_ages=st.lists(st.floats(0, 2 * RETENTION_DAYS), min_size=3, max_size=3), + # None leaves the real 100 MiB cap, so only age removes rows. + cap_fraction=st.one_of(st.none(), st.floats(0, 1.2)), + batch_rows=st.integers(1, 4), + step_budget=st.sampled_from([0.0, math.inf]), +) +# More expired rows than one batch, with no size pressure to hide a leftover. +@example( + events=[(0, 10.0, 5)] * 6, + run_ages=[1.0, 1.0, 1.0], + cap_fraction=None, + batch_rows=2, + step_budget=math.inf, +) +# Removing the oldest live event (20 characters of 50) fits the cap exactly. +@example( + events=[(0, 1.0, 10), (0, 1.0, 20)], + run_ages=[1.0, 1.0, 1.0], + cap_fraction=0.6, + batch_rows=2, + step_budget=math.inf, +) +def test_batched_prune_matches_the_single_pass_retention_rule( + tmp_path_factory, events, run_ages, cap_fraction, batch_rows, step_budget +) -> None: + """Differential: the batched prune keeps exactly what one pass would. + + The reference is the retention rule the single-transaction prune applied: + drop events past ``RETENTION_DAYS``; then, oldest first, drop events until + the stored payloads fit ``MAX_QUEUED_BYTES``; then drop expired runs that + have no events left. + """ + + spool = EventSpool(tmp_path_factory.mktemp("prune") / "events.sqlite3") + keys = [(f"run-{index}", f"producer-{index}") for index in range(3)] + rows: list[dict[str, object]] = [] + try: + with spool._session_factory.begin() as session: + for index, (run_id, producer_id) in enumerate(keys): + session.add( + TelemetryRunRecord( + run_id=run_id, + producer_id=producer_id, + registration={"run_id": run_id, "producer_id": producer_id}, + next_sequence=1, + upload_state="pending", + local_only_reason=None, + updated_at=_stamp(run_ages[index], index), + ) + ) + for index, (run, age, padding) in enumerate(events): + run_id, producer_id = keys[run] + payload = {"pad": "x" * padding} + row = { + "event_id": f"event-{index:02d}", + "run": keys[run], + "created_at": _stamp(age, index), + "sequence": index, + "length": len( + json.dumps(payload, separators=(",", ":"), sort_keys=True) + ), + } + rows.append(row) + session.add( + TelemetryEventRecord( + event_id=row["event_id"], + run_id=run_id, + producer_id=producer_id, + sequence=index, + payload=payload, + created_at=row["created_at"], + ) + ) + cutoff = (_STAMP_ORIGIN - timedelta(days=RETENTION_DAYS)).isoformat() + live = [row for row in rows if row["created_at"] >= cutoff] + cap = ( + spool_module.MAX_QUEUED_BYTES + if cap_fraction is None + else int(cap_fraction * sum(row["length"] for row in live)) + ) + batches: list[int] = [] + delete = spool._delete + + def recording_delete(model, criterion) -> int: + deleted = delete(model, criterion) + batches.append(deleted) + return deleted + + spool._delete = recording_delete + frozen_now = mock.Mock(wraps=datetime) + frozen_now.now.return_value = _STAMP_ORIGIN + with ( + mock.patch.object(spool_module, "MAX_QUEUED_BYTES", cap), + mock.patch.object(spool_module, "PRUNE_BATCH_ROWS", batch_rows), + mock.patch.object(spool_module, "PRUNE_BATCH_PAUSE_SECONDS", 0.0), + mock.patch.object(spool_module, "datetime", frozen_now), + ): + # A zero budget stops after every batch, so the prune is resumed + # call by call until it reports that it finished. + calls = 1 + while not spool.prune(time_budget_seconds=step_budget): + calls += 1 + assert calls <= len(events) + 3 + with spool._session_factory() as session: + kept_events = set( + session.scalars(select(TelemetryEventRecord.event_id)).all() + ) + kept_runs = set( + session.execute( + select( + TelemetryRunRecord.run_id, + TelemetryRunRecord.producer_id, + ) + ).all() + ) + finally: + _close(spool) + + expected_events = {row["event_id"] for row in live} + excess = sum(row["length"] for row in live) - cap + for row in sorted(live, key=lambda row: (row["created_at"], row["sequence"])): + if excess <= 0: + break + expected_events.discard(row["event_id"]) + excess -= row["length"] + expected_runs = { + key + for index, key in enumerate(keys) + if _stamp(run_ages[index], index) >= cutoff + or any(row["run"] == key and row["event_id"] in expected_events for row in rows) + } + assert kept_events == expected_events + assert kept_runs == expected_runs + # Each transaction deleted at most one batch. + assert all(deleted <= batch_rows for deleted in batches) + + +def test_a_prune_with_nothing_to_remove_only_reads(tmp_path) -> None: + """An idle prune runs every minute in every service; it takes no lock.""" + + spool_path = tmp_path / "events.sqlite3" + spool = EventSpool(spool_path) + try: + registration = _registration() + spool.register(registration) + spool.append(registration, _event()) + with _write_lock(spool_path): + started = time.monotonic() + assert spool.prune() is True + assert time.monotonic() - started < 1.0 + assert spool.has_pending() + finally: + _close(spool) + + +def test_prune_pauses_between_batches_outside_the_process_lock( + tmp_path, monkeypatch +) -> None: + spool = EventSpool(tmp_path / "events.sqlite3") + pauses: list[bool] = [] + try: + registration = _registration() + spool.register(registration) + for _ in range(5): + spool.append(registration, _event()) + expired = (datetime.now(UTC) - timedelta(days=RETENTION_DAYS + 1)).isoformat() + with spool._session_factory.begin() as session: + session.query(TelemetryEventRecord).update({"created_at": expired}) + + def pause(seconds: float) -> None: + # This build's event path takes the same lock, so it must be free. + pauses.append(spool._lock._is_owned()) + + monkeypatch.setattr(spool_module, "PRUNE_BATCH_ROWS", 2) + monkeypatch.setattr( + spool_module, + "time", + SimpleNamespace(monotonic=time.monotonic, sleep=pause), + ) + assert spool.prune() is True + assert not spool.has_pending() + finally: + _close(spool) + + # Five rows in batches of two: a pause after each full batch, never while + # this process holds its lock. + assert pauses == [False, False] + + +def test_a_prune_out_of_time_stops_between_batches_and_resumes( + tmp_path, monkeypatch +) -> None: + spool = EventSpool(tmp_path / "events.sqlite3") + try: + registration = _registration() + spool.register(registration) + for _ in range(5): + spool.append(registration, _event()) + expired = (datetime.now(UTC) - timedelta(days=RETENTION_DAYS + 1)).isoformat() + with spool._session_factory.begin() as session: + session.query(TelemetryEventRecord).update({"created_at": expired}) + monkeypatch.setattr(spool_module, "PRUNE_BATCH_ROWS", 2) + monkeypatch.setattr(spool_module, "PRUNE_BATCH_PAUSE_SECONDS", 0.0) + + remaining = [] + while not spool.prune(time_budget_seconds=0.0): + remaining.append(len(spool.batch("run-a", "producer-a", limit=10))) + remaining.append(len(spool.batch("run-a", "producer-a", limit=10))) + finally: + _close(spool) + + # One batch per call: five rows go two, two, then one. + assert remaining == [3, 1, 0] + + +def test_a_service_that_closes_within_its_first_tick_still_prunes(tmp_path) -> None: + """Short builds must not leave retention unenforced on a host forever.""" + + spool_path = tmp_path / "events.sqlite3" + _prepare_spool(spool_path, "at_head_with_expired_rows") + spool = EventSpool(spool_path) + registration = _registration() + spool.register(registration) + socket_path = _short_socket_path() + service = EmitterService( + socket_path=socket_path, + registration=registration, + spool=spool, + delivery=SimpleNamespace(flush_once=lambda: False), + sampler=SimpleNamespace(sample=dict, parent_alive=lambda: True), + heartbeat_seconds=60, + drain_seconds=0, + ) + serving = threading.Thread(target=service.run, daemon=True) + try: + assert spool.has_pending() + serving.start() + deadline = time.monotonic() + 30 + while not _ping(socket_path): + assert time.monotonic() < deadline, "service never became ready" + time.sleep(0.01) + # Closed at once, well inside the worker's first one-second tick. + _close_service(socket_path) + serving.join(timeout=30) + assert not serving.is_alive() + assert not spool.has_pending() + finally: + service._stop.set() + serving.join(timeout=5) + _close(spool) + + +def test_expired_runs_are_deleted_in_batches(tmp_path, monkeypatch) -> None: + spool = EventSpool(tmp_path / "events.sqlite3") + deleted: list[tuple[str, int]] = [] + pauses: list[float] = [] + try: + for index in range(5): + spool.register({"run_id": f"run-{index}", "producer_id": "producer-a"}) + expired = (datetime.now(UTC) - timedelta(days=RETENTION_DAYS + 1)).isoformat() + with spool._session_factory.begin() as session: + session.query(TelemetryRunRecord).update({"updated_at": expired}) + delete = spool._delete + + def recording_delete(model, criterion) -> int: + count = delete(model, criterion) + deleted.append((model.__tablename__, count)) + return count + + spool._delete = recording_delete + monkeypatch.setattr(spool_module, "PRUNE_BATCH_ROWS", 2) + monkeypatch.setattr( + spool_module, + "time", + SimpleNamespace(monotonic=time.monotonic, sleep=pauses.append), + ) + assert spool.prune() is True + with spool._session_factory() as session: + remaining = session.scalars(select(TelemetryRunRecord.run_id)).all() + finally: + _close(spool) + + # Five runs in batches of two, with a pause after each full batch. + assert deleted == [ + ("telemetry_runs", 2), + ("telemetry_runs", 2), + ("telemetry_runs", 1), + ] + assert len(pauses) == 2 + assert remaining == [] + + +def test_a_spool_under_the_size_cap_is_not_scanned(tmp_path, monkeypatch) -> None: + """The size check reads the file's page counts, not every payload.""" + + spool = EventSpool(tmp_path / "events.sqlite3") + statements: list[str] = [] + try: + registration = _registration() + spool.register(registration) + for _ in range(3): + spool.append(registration, _event()) + sqlalchemy_event.listen( + spool._engine, + "before_cursor_execute", + lambda conn, cursor, statement, *rest: statements.append(statement), + ) + assert spool.prune() is True + assert not [text for text in statements if "sum(" in text.lower()] + assert len(spool.batch("run-a", "producer-a")) == 3 + + # Over the cap, the payloads are summed and the oldest events go. + statements.clear() + monkeypatch.setattr(spool_module, "MAX_QUEUED_BYTES", 1) + assert spool.prune() is True + assert [text for text in statements if "sum(" in text.lower()] + assert spool.batch("run-a", "producer-a") == [] + finally: + _close(spool) diff --git a/packages/microcosm-build/tests/engine_free/shared/test_telemetry_spool_versions.py b/packages/microcosm-build/tests/engine_free/shared/test_telemetry_spool_versions.py new file mode 100644 index 0000000000..2b33b47047 --- /dev/null +++ b/packages/microcosm-build/tests/engine_free/shared/test_telemetry_spool_versions.py @@ -0,0 +1,1991 @@ +"""Checkouts at different microcosm versions sharing one telemetry spool. + +Every checkout and worktree on a host opens the same spool, so a build can find +it migrated by a newer checkout, or by a branch with a different migration. +These tests open one spool as several checkouts at once: the packaged migration +history, and temporary copies of it that carry synthetic later revisions. They +check that an older checkout keeps using a spool a newer one migrated, that +events queued by either version are delivered by the other, that a checkout +whose history diverges from the spool's is refused without the write lock, and +that every revision is additive, which is what lets older code rely on the +migrated schema. +""" + +from __future__ import annotations + +import contextlib +import functools +import json +import os +import re +import shutil +import sqlite3 +import subprocess +import sys +import tempfile +import textwrap +import threading +import time +from collections.abc import Callable +from dataclasses import dataclass +from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer +from importlib.resources import as_file, files +from pathlib import Path + +import pytest +from alembic import command +from alembic.script import ScriptDirectory +from hypothesis import HealthCheck, event, given, settings +from hypothesis import strategies as st + +from microcosm.build.telemetry_emitter import LocalTelemetryEmitter, TelemetryRun +from microcosm.build.telemetry_emitter_constants import TELEMETRY_SERVICE_MODULE +from microcosm.build.telemetry_emitter_service import collector as collector_module +from microcosm.build.telemetry_emitter_service import migrations as migrations_module +from microcosm.build.telemetry_emitter_service.collector import CollectorDelivery +from microcosm.build.telemetry_emitter_service.constants import ( + DATABASE_TIMEOUT_SECONDS, + SPOOL_LINEAGE_TABLE, +) +from microcosm.build.telemetry_emitter_service.database import create_spool_engine +from microcosm.build.telemetry_emitter_service.migrations import ( + IncompatibleSpoolRevisionError, + MigrationHistory, + SpoolRevisionState, + alembic_config, + classify_spool_revision, + current_database_revision, + migration_head_revision, + migration_history, + recorded_spool_lineage, + upgrade_spool_database, +) +from microcosm.build.telemetry_emitter_service.spool import EventSpool +from microcosm.build.telemetry_protocol import ( + BUILD_COMPLETED_MESSAGE, + BUILD_STARTED_MESSAGE, +) + +_SERVICE_PACKAGE = "microcosm.build.telemetry_emitter_service" +_INITIAL_REVISION = "20261007_01" +_LOOPBACK_COLLECTOR = "http://127.0.0.1:9" +_BOOKKEEPING_TABLES = frozenset({"alembic_version", SPOOL_LINEAGE_TABLE}) + + +@functools.cache +def _packaged_head() -> str: + head = migration_head_revision() + assert head is not None + return head + + +def _registration(run_id: str, producer_id: str) -> dict[str, object]: + return TelemetryRun( + run_id=run_id, + country_code="US", + pipeline="test-pipeline", + producer_id=producer_id, + ).as_registration() + + +def _event(stage_id: str) -> dict[str, object]: + return {"event_type": "stage", "stage_id": stage_id, "status": "started"} + + +def _close(spool: EventSpool) -> None: + spool._engine.dispose() + + +@contextlib.contextmanager +def _write_lock(path: Path): + """Hold the spool's write lock from another connection, as a writer would.""" + + connection = sqlite3.connect(path, isolation_level=None) + try: + connection.execute("BEGIN IMMEDIATE") + yield connection + finally: + if connection.in_transaction: + connection.rollback() + connection.close() + + +def _tables(path: Path) -> set[str]: + connection = sqlite3.connect(path) + try: + return { + name + for (name,) in connection.execute( + "SELECT name FROM sqlite_master WHERE type = 'table'" + ) + } + finally: + connection.close() + + +def _stamp(path: Path, revision: str, lineage: frozenset[str] | None) -> None: + """Stamp a spool as another checkout's migration would have left it.""" + + connection = sqlite3.connect(path) + try: + connection.execute("UPDATE alembic_version SET version_num = ?", (revision,)) + connection.execute(f"DROP TABLE IF EXISTS {SPOOL_LINEAGE_TABLE}") + if lineage is not None: + connection.execute( + f"CREATE TABLE {SPOOL_LINEAGE_TABLE} " + "(revision TEXT NOT NULL PRIMARY KEY)" + ) + connection.executemany( + f"INSERT INTO {SPOOL_LINEAGE_TABLE} (revision) VALUES (?)", + [(name,) for name in sorted(lineage)], + ) + connection.commit() + finally: + connection.close() + + +# --- Other checkouts' migration histories ------------------------------------ + +_REVISION_SOURCE = '''"""Synthetic revision {revision} in a test checkout's history.""" + +import sqlalchemy as sa +from alembic import op + +revision = {revision!r} +down_revision = {down_revision!r} +branch_labels = None +depends_on = None + + +def upgrade() -> None: +{upgrade} + + +def downgrade() -> None: + raise NotImplementedError +''' + + +@dataclass(frozen=True) +class _Revision: + revision: str + down_revision: str + upgrade: str + + def source(self) -> str: + return _REVISION_SOURCE.format( + revision=self.revision, + down_revision=self.down_revision, + upgrade=textwrap.indent(textwrap.dedent(self.upgrade).strip(), " "), + ) + + +def _additive_revision(revision: str, down_revision: str | None = None) -> _Revision: + """A later revision like the next one in flight, which adds a table (#1151). + + It also adds a nullable column, a defaulted NOT NULL column and an index to + the tables older code writes. Names carry the revision, so sibling and + descendant revisions never collide. + """ + + return _Revision( + revision, + down_revision or _packaged_head(), + f""" + op.create_table( + "graph_publication_jobs_{revision}", + sa.Column("publication_id", sa.Text(), primary_key=True), + sa.Column("status", sa.Text(), nullable=False), + ) + op.add_column( + "telemetry_runs", + sa.Column("region_{revision}", sa.Text(), nullable=True), + ) + op.add_column( + "telemetry_events", + sa.Column( + "attempts_{revision}", + sa.Integer(), + nullable=False, + server_default="0", + ), + ) + op.create_index( + "telemetry_events_created_{revision}", + "telemetry_events", + ["created_at"], + ) + """, + ) + + +def _checkout(root: Path, *revisions: _Revision) -> Path: + """Write one checkout's migration history: the packaged one plus more.""" + + with as_file(files(_SERVICE_PACKAGE).joinpath("alembic")) as packaged: + shutil.copytree(packaged, root, ignore=shutil.ignore_patterns("__pycache__")) + for revision in revisions: + (root / "versions" / f"v{revision.revision}.py").write_text(revision.source()) + return root + + +class _Collector: + """Accept everything a CollectorDelivery sends, recording the events.""" + + def __init__(self) -> None: + self.events: list[dict[str, object]] = [] + self.registrations: list[dict[str, object]] = [] + + def post(self, url, payload, token, *, timeout=5.0): + if url.endswith("/v1/auth/huggingface/exchange"): + return 200, {"access_token": "collector-token", "expires_in": 3600} + if url.endswith("/v1/runs"): + self.registrations.append(dict(payload)) + return 201, {"registered": True} + self.events.extend(payload["events"]) + return 202, {"accepted": len(payload["events"]), "duplicates": 0} + + +@pytest.fixture +def collector(monkeypatch) -> _Collector: + fake = _Collector() + monkeypatch.setattr(collector_module, "_http_post", fake.post) + monkeypatch.setattr(collector_module, "_huggingface_token", lambda: "hf-token") + return fake + + +def _deliver(spool: EventSpool) -> None: + CollectorDelivery(spool, development_collector_url=_LOOPBACK_COLLECTOR).flush_once() + + +# --- An older checkout keeps using a spool a newer one migrated -------------- + + +def test_an_older_checkout_uses_a_spool_a_newer_checkout_migrated(tmp_path) -> None: + spool_path = tmp_path / "events.sqlite3" + newer = _checkout(tmp_path / "newer", _additive_revision("future")) + _close(EventSpool(spool_path, script_location=newer)) + assert current_database_revision(spool_path) == "future" + assert recorded_spool_lineage(spool_path) == migration_history(newer).revisions + + # The older checkout only reads, so another writer's lock does not delay it. + with _write_lock(spool_path): + started = time.monotonic() + older = EventSpool(spool_path) + opened_in = time.monotonic() - started + try: + assert opened_in < DATABASE_TIMEOUT_SECONDS + registration = _registration("older-run", "older-producer") + older.register(registration) + queued = [older.append(registration, _event(stage)) for stage in "abc"] + assert older.batch("older-run", "older-producer") == queued + older.acknowledge([queued[0]["event_id"]]) + older.prune() + assert older.pending_runs() == [registration] + assert older.batch("older-run", "older-producer") == queued[1:] + finally: + _close(older) + + engine = create_spool_engine(spool_path) + try: + assert upgrade_spool_database(engine) is SpoolRevisionState.AHEAD + finally: + engine.dispose() + assert current_database_revision(spool_path) == "future" + assert "graph_publication_jobs_future" in _tables(spool_path) + + +def test_events_queued_by_either_version_are_delivered_by_the_other( + tmp_path, collector +) -> None: + spool_path = tmp_path / "events.sqlite3" + newer = EventSpool( + spool_path, + script_location=_checkout(tmp_path / "newer", _additive_revision("future")), + ) + older = EventSpool(spool_path) + try: + older_run = _registration("older-run", "older-producer") + older.register(older_run) + from_older = [older.append(older_run, _event(stage)) for stage in "ab"] + _deliver(newer) + assert collector.events == from_older + assert not older.has_pending() + + newer_run = _registration("newer-run", "newer-producer") + newer.register(newer_run) + from_newer = [newer.append(newer_run, _event(stage)) for stage in "ab"] + _deliver(older) + assert collector.events == from_older + from_newer + assert not newer.has_pending() + assert collector.registrations == [older_run, newer_run] + finally: + _close(older) + _close(newer) + + +def _stored_rows(path: Path) -> dict[str, list[dict[str, object]]]: + connection = sqlite3.connect(path) + connection.row_factory = sqlite3.Row + try: + return { + table: sorted( + (dict(row) for row in connection.execute(f"SELECT * FROM {table}")), + key=repr, + ) + for table in ("telemetry_runs", "telemetry_events") + } + finally: + connection.close() + + +def test_upgrading_keeps_every_queued_row_and_its_delivery(tmp_path, collector) -> None: + spool_path = tmp_path / "events.sqlite3" + older = EventSpool(spool_path) + try: + pending = _registration("pending-run", "producer-a") + older.register(pending) + queued = [older.append(pending, _event(stage)) for stage in "abc"] + local = _registration("local-run", "producer-b") + older.register(local) + older.append(local, _event("a")) + older.make_local_only("local-run", "producer-b", "missing_credential") + finally: + _close(older) + before = _stored_rows(spool_path) + + newer = EventSpool( + spool_path, + script_location=_checkout(tmp_path / "newer", _additive_revision("future")), + ) + try: + after = _stored_rows(spool_path) + for table, rows in before.items(): + kept = ({column: row[column] for column in rows[0]} for row in after[table]) + assert sorted(kept, key=repr) == rows + assert {row["region_future"] for row in after["telemetry_runs"]} == {None} + assert {row["attempts_future"] for row in after["telemetry_events"]} == {0} + _deliver(newer) + finally: + _close(newer) + assert collector.events == queued + + +def test_a_live_older_service_keeps_queuing_across_a_newer_migration(tmp_path) -> None: + """SQLite re-prepares an open connection's statements after the change.""" + + spool_path = tmp_path / "events.sqlite3" + older = EventSpool(spool_path) + try: + registration = _registration("older-run", "older-producer") + older.register(registration) + older.append(registration, _event("a")) + _close( + EventSpool( + spool_path, + script_location=_checkout( + tmp_path / "newer", _additive_revision("future") + ), + ) + ) + assert current_database_revision(spool_path) == "future" + older.append(registration, _event("b")) + older.prune() + events = older.batch("older-run", "older-producer") + finally: + _close(older) + assert [(event["sequence"], event["stage_id"]) for event in events] == [ + (1, "a"), + (2, "b"), + ] + + +def test_an_opener_that_waited_out_a_newer_migration_changes_nothing( + tmp_path, monkeypatch +) -> None: + """It found the spool behind, then got the lock after a newer checkout. + + Without the second look under the lock, Alembic would try to upgrade a + spool stamped with a revision this opener does not know, and fail. + """ + + spool_path = tmp_path / "events.sqlite3" + middle = _additive_revision("middle") + opener = _checkout(tmp_path / "opener", middle) + newer = _checkout( + tmp_path / "newer", middle, _additive_revision("future", "middle") + ) + _close(EventSpool(spool_path)) + results: list[SpoolRevisionState | BaseException] = [] + # The opener builds its locking engine only after its read-only look found + # the spool behind, so the migration below starts after that look. + found_behind = threading.Event() + create_engine_for_migrations = migrations_module.create_spool_engine + + def create_spool_engine_and_signal(path, **options): + if options.get("immediate_transactions"): + found_behind.set() + return create_engine_for_migrations(path, **options) + + monkeypatch.setattr( + migrations_module, "create_spool_engine", create_spool_engine_and_signal + ) + + def open_spool() -> None: + engine = create_spool_engine(spool_path) + try: + results.append( + upgrade_spool_database( + engine, busy_timeout_seconds=lambda: 60, script_location=opener + ) + ) + except BaseException as error: + results.append(error) + finally: + engine.dispose() + + waiting = threading.Thread(target=open_spool, daemon=True) + migrator = create_spool_engine(spool_path, immediate_transactions=True) + try: + with migrator.begin() as connection: + waiting.start() + assert found_behind.wait(timeout=60), results + with alembic_config(connection=connection, script_location=newer) as config: + command.upgrade(config, "head") + migrations_module._record_lineage(connection, migration_history(newer)) + waiting.join(timeout=90) + finally: + migrator.dispose() + + assert results == [SpoolRevisionState.AHEAD] + assert current_database_revision(spool_path) == "future" + # The opener left the newer checkout's lineage alone. Had it written its + # own, the spool's revision would be missing from it, and every older + # checkout would be refused from then on. + assert recorded_spool_lineage(spool_path) == migration_history(newer).revisions + for script_location in (None, opener, newer): + _close(EventSpool(spool_path, script_location=script_location)) + + +def test_an_older_append_waits_out_a_newer_migration_in_progress(tmp_path) -> None: + """The event waits in SQLite's busy handler while the migration holds the lock. + + One that outlasts that 5 s wait is lost, as behind any long writer. + """ + + spool_path = tmp_path / "events.sqlite3" + newer = _checkout(tmp_path / "newer", _additive_revision("future")) + older = EventSpool(spool_path) + registration = _registration("older-run", "older-producer") + older.register(registration) + older.append(registration, _event("a")) + appended: list[dict[str, object] | BaseException] = [] + + def append() -> None: + try: + appended.append(older.append(registration, _event("b"))) + except BaseException as error: + appended.append(error) + + appending = threading.Thread(target=append, daemon=True) + migrator = create_spool_engine(spool_path, immediate_transactions=True) + try: + with migrator.begin() as connection: + with alembic_config(connection=connection, script_location=newer) as config: + command.upgrade(config, "head") + migrations_module._record_lineage(connection, migration_history(newer)) + appending.start() + time.sleep(0.5) + assert appending.is_alive(), appended + appending.join(timeout=60) + events = older.batch("older-run", "older-producer") + finally: + migrator.dispose() + _close(older) + + assert [type(result) for result in appended] == [dict], appended + assert [(event["sequence"], event["stage_id"]) for event in events] == [ + (1, "a"), + (2, "b"), + ] + assert current_database_revision(spool_path) == "future" + + +def test_a_failed_upgrade_leaves_the_schema_the_stamp_and_the_lineage( + tmp_path, monkeypatch +) -> None: + """They commit together, so an upgrade that fails last undoes all three.""" + + spool_path = tmp_path / "events.sqlite3" + _close(EventSpool(spool_path)) + lineage = recorded_spool_lineage(spool_path) + record_lineage = migrations_module._record_lineage + + def record_lineage_then_fail(connection, history) -> None: + record_lineage(connection, history) + raise RuntimeError("interrupted after the lineage") + + monkeypatch.setattr(migrations_module, "_record_lineage", record_lineage_then_fail) + with pytest.raises(RuntimeError, match="interrupted after the lineage"): + EventSpool( + spool_path, + script_location=_checkout(tmp_path / "newer", _additive_revision("future")), + ) + + assert current_database_revision(spool_path) == _packaged_head() + assert recorded_spool_lineage(spool_path) == lineage + assert "graph_publication_jobs_future" not in _tables(spool_path) + assert "region_future" not in _runs_columns(spool_path) + + +@pytest.mark.parametrize( + "created_by", ["a lineage-recording runner", "an older runner"] +) +def test_a_checkout_at_head_records_the_lineage_an_older_runner_left_out( + tmp_path, created_by +) -> None: + """A checkout from before lineage was recorded migrated the spool. + + Until a lineage-recording checkout at that revision opens it, an older + checkout cannot tell that the revision descends from its own head. + """ + + spool_path = tmp_path / "events.sqlite3" + newer = _checkout(tmp_path / "newer", _additive_revision("future")) + if created_by == "a lineage-recording runner": + _close(EventSpool(spool_path)) + state = _open_as_runner_without_lineage(spool_path, newer) + assert state is SpoolRevisionState.BEHIND + assert current_database_revision(spool_path) == "future" + assert recorded_spool_lineage(spool_path) == ( + migration_history().revisions + if created_by == "a lineage-recording runner" + else None + ) + with pytest.raises(IncompatibleSpoolRevisionError): + EventSpool(spool_path) + + _close(EventSpool(spool_path, script_location=newer)) + assert recorded_spool_lineage(spool_path) == migration_history(newer).revisions + # Recorded once: with the lock held elsewhere, the next opens only read. + with _write_lock(spool_path): + started = time.monotonic() + _close(EventSpool(spool_path, script_location=newer)) + older = EventSpool(spool_path) + assert time.monotonic() - started < DATABASE_TIMEOUT_SECONDS + try: + registration = _registration("older-run", "older-producer") + older.register(registration) + assert older.append(registration, _event("a"))["sequence"] == 1 + finally: + _close(older) + + +def _initial_checkout(root: Path) -> Path: + """A checkout whose history is the initial revision alone.""" + + _checkout(root) + with alembic_config(script_location=root) as config: + for script in ScriptDirectory.from_config(config).walk_revisions(): + if script.down_revision is not None: + Path(script.path).unlink() + return root + + +def test_a_spool_at_the_initial_revision_needs_no_lineage(tmp_path) -> None: + """Every history starts there, so nothing is written and no lock is taken. + + Every spool that exists when lineage-recording checkouts arrive is in + this state. + """ + + spool_path = tmp_path / "events.sqlite3" + initial = _initial_checkout(tmp_path / "initial") + state = _open_as_runner_without_lineage(spool_path, initial) + assert state is SpoolRevisionState.BEHIND + assert current_database_revision(spool_path) == _INITIAL_REVISION + assert recorded_spool_lineage(spool_path) is None + + with _write_lock(spool_path): + started = time.monotonic() + spool = EventSpool(spool_path, script_location=initial) + assert time.monotonic() - started < DATABASE_TIMEOUT_SECONDS + _close(spool) + assert recorded_spool_lineage(spool_path) is None + + +def test_the_lineage_table_is_not_part_of_the_schema_alembic_checks(tmp_path) -> None: + spool_path = tmp_path / "events.sqlite3" + _close(EventSpool(spool_path)) + assert recorded_spool_lineage(spool_path) == migration_history().revisions + engine = create_spool_engine(spool_path) + try: + with ( + engine.begin() as connection, + alembic_config(connection=connection) as config, + ): + command.check(config) + finally: + engine.dispose() + + +# --- Diverged and unknown histories are refused without the lock ------------- + + +def test_a_branch_with_a_different_migration_is_refused_without_the_lock( + tmp_path, +) -> None: + spool_path = tmp_path / "events.sqlite3" + branch_a = _checkout(tmp_path / "a", _additive_revision("branch_a")) + branch_b = _checkout(tmp_path / "b", _additive_revision("branch_b")) + _close(EventSpool(spool_path, script_location=branch_a)) + lineage = recorded_spool_lineage(spool_path) + + with _write_lock(spool_path): + started = time.monotonic() + with pytest.raises( + IncompatibleSpoolRevisionError, + match=( + "revision 'branch_a' is not in this microcosm's migration history, " + "whose head is 'branch_b'" + ), + ): + EventSpool(spool_path, script_location=branch_b) + assert time.monotonic() - started < DATABASE_TIMEOUT_SECONDS + + assert current_database_revision(spool_path) == "branch_a" + assert recorded_spool_lineage(spool_path) == lineage + assert "graph_publication_jobs_branch_b" not in _tables(spool_path) + # The revision both branches descend from still uses the spool. + _close(EventSpool(spool_path)) + + +@pytest.mark.parametrize( + ("lineage", "usable"), + [ + pytest.param(None, False, id="no-recorded-lineage"), + pytest.param({""}, False, id="lineage-without-the-stamp"), + pytest.param({"future"}, False, id="lineage-without-this-head"), + pytest.param({"", "future"}, True, id="descends-from-this-head"), + ], +) +def test_a_spool_stamped_with_a_future_revision_is_used_only_if_it_descends( + tmp_path, lineage, usable +) -> None: + spool_path = tmp_path / "events.sqlite3" + _close(EventSpool(spool_path)) + if lineage is not None: + lineage = frozenset( + _packaged_head() if name == "" else name for name in lineage + ) + _stamp(spool_path, "future", lineage) + + if not usable: + with pytest.raises(IncompatibleSpoolRevisionError, match="'future'"): + EventSpool(spool_path) + return + spool = EventSpool(spool_path) + try: + registration = _registration("run", "producer") + spool.register(registration) + assert spool.append(registration, _event("a"))["sequence"] == 1 + finally: + _close(spool) + assert current_database_revision(spool_path) == "future" + + +# --- End to end: the real client and service processes ------------------------ + + +class _CollectorHandler(BaseHTTPRequestHandler): + requests: list[tuple[str, dict[str, object]]] + + def do_POST(self): + length = int(self.headers.get("Content-Length", "0")) + payload = json.loads(self.rfile.read(length)) + self.requests.append((self.path, payload)) + if self.path.endswith("/v1/auth/huggingface/exchange"): + status, response = 200, {"access_token": "token", "expires_in": 3600} + elif self.path == "/v1/runs": + status, response = 201, {"registered": True} + else: + status = 202 + response = {"accepted": len(payload["events"]), "duplicates": 0} + body = json.dumps(response).encode() + self.send_response(status) + self.send_header("Content-Type", "application/json") + self.send_header("Content-Length", str(len(body))) + self.end_headers() + self.wfile.write(body) + + def log_message(self, format, *args): + return + + +@contextlib.contextmanager +def _collector_server(): + requests: list[tuple[str, dict[str, object]]] = [] + handler = type("Handler", (_CollectorHandler,), {"requests": requests}) + server = ThreadingHTTPServer(("127.0.0.1", 0), handler) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + try: + yield f"http://127.0.0.1:{server.server_port}", requests + finally: + server.shutdown() + thread.join(timeout=5) + server.server_close() + + +def test_an_older_build_delivers_its_own_and_newer_events_through_a_migrated_spool( + tmp_path, monkeypatch, capfd, real_local_telemetry +) -> None: + """The real client starts the real (older) service on a newer spool.""" + + spool_path = tmp_path / "events.sqlite3" + newer = EventSpool( + spool_path, + script_location=_checkout(tmp_path / "newer", _additive_revision("future")), + ) + try: + newer_run = _registration("newer-run", "newer-producer") + newer.register(newer_run) + from_newer = [newer.append(newer_run, _event(stage)) for stage in "ab"] + finally: + _close(newer) + + monkeypatch.setenv("HF_TOKEN", "hf-ambient-test-token") + with _collector_server() as (collector_url, requests): + emitter = LocalTelemetryEmitter.start( + run_id="older-build", + country_code="US", + pipeline="test-pipeline", + development_collector_url=collector_url, + spool_path=spool_path, + heartbeat_seconds=60, + startup_timeout_seconds=60, + ) + assert emitter.available + emitter.stage("compile", message="Compiling.") + emitter.complete() + assert emitter._process is not None + assert emitter._process.wait(timeout=60) == 0 + + delivered: dict[str, list[dict[str, object]]] = {} + for path, payload in requests: + if path.endswith("/events"): + for event in payload["events"]: + delivered.setdefault(str(event["run_id"]), []).append(event) + assert delivered["newer-run"] == from_newer + older_events = delivered["older-build"] + assert [event["sequence"] for event in older_events] == list( + range(1, len(older_events) + 1) + ) + assert older_events[0]["message"] == BUILD_STARTED_MESSAGE + assert older_events[-1]["message"] == BUILD_COMPLETED_MESSAGE + assert current_database_revision(spool_path) == "future" + # On a loaded host the client may warn that one send outlived its 0.2 s + # wait; the service still queued it. It must never have refused the spool. + stderr = capfd.readouterr().err + assert "emitter service stopped" not in stderr + assert "Traceback" not in stderr + + +def test_the_service_refuses_a_diverged_spool_in_one_line(tmp_path) -> None: + """The real process: status 1 and one stderr line naming both revisions.""" + + spool_path = tmp_path / "events.sqlite3" + _close(EventSpool(spool_path)) + _stamp(spool_path, "elsewhere", frozenset({"other_root", "elsewhere"})) + # The service refuses the spool before it would bind this. + socket_path = tmp_path / "emitter.sock" + completed = subprocess.run( + [ + sys.executable, + "-m", + TELEMETRY_SERVICE_MODULE, + "--socket", + str(socket_path), + "--spool", + str(spool_path), + "--registration-json", + json.dumps(_registration("run", "producer")), + "--parent-pid", + "1", + "--development-collector-url", + _LOOPBACK_COLLECTOR, + ], + stdin=subprocess.DEVNULL, + capture_output=True, + text=True, + timeout=180, + ) + + assert completed.returncode == 1 + lines = [line for line in completed.stderr.splitlines() if line.strip()] + assert lines == [ + "warning: the local telemetry emitter service stopped: " + "IncompatibleSpoolRevisionError: telemetry spool schema revision " + f"'elsewhere' is not in this microcosm's migration history, whose head " + f"is {_packaged_head()!r}, and the spool does not record it as " + f"descending from {_packaged_head()!r}" + ] + assert not socket_path.exists() + assert current_database_revision(spool_path) == "elsewhere" + + +# --- Properties over revision trees ------------------------------------------- + + +@st.composite +def _revision_trees(draw, max_revisions: int = 4) -> list[int | None]: + """Parent indices of a revision tree; revision 0 is the packaged head.""" + + count = draw(st.integers(min_value=1, max_value=max_revisions)) + return [None] + [ + draw(st.integers(min_value=0, max_value=index - 1)) + for index in range(1, count + 1) + ] + + +def _ancestry(parents: list[int | None], node: int) -> frozenset[int]: + """``node`` and every revision it descends from.""" + + lineage = {node} + while (parent := parents[node]) is not None: + lineage.add(parent) + node = parent + return frozenset(lineage) + + +def _expected_state( + parents: list[int | None], stamp: int | None, head: int +) -> SpoolRevisionState: + """The model: which way the spool lies from a checkout, by ancestry alone.""" + + if stamp == head: + return SpoolRevisionState.AT_HEAD + if stamp is None or stamp in _ancestry(parents, head): + return SpoolRevisionState.BEHIND + if head in _ancestry(parents, stamp): + return SpoolRevisionState.AHEAD + return SpoolRevisionState.INCOMPATIBLE + + +@settings(max_examples=300, deadline=None) +@given( + parents=_revision_trees(max_revisions=6), + head=st.integers(min_value=0, max_value=6), + stamp=st.one_of(st.none(), st.integers(min_value=0, max_value=6)), + recorded=st.sampled_from(["exact", "absent", "without-stamp", "without-root"]), +) +def test_classification_follows_ancestry_alone(parents, head, stamp, recorded) -> None: + head %= len(parents) + names = [f"r{index}" for index in range(len(parents))] + history = MigrationHistory( + head=names[head], + revisions=frozenset(names[node] for node in _ancestry(parents, head)), + bases=frozenset({names[0]}), + ) + if stamp is None: + state = classify_spool_revision(None, None, history) + assert state is SpoolRevisionState.BEHIND + return + stamp %= len(parents) + lineage = frozenset(names[node] for node in _ancestry(parents, stamp)) + lineage = { + "exact": lineage, + "absent": None, + "without-stamp": lineage - {names[stamp]}, + "without-root": lineage - {names[0]}, + }[recorded] + state = classify_spool_revision(names[stamp], lineage, history) + + expected = _expected_state(parents, stamp, head) + # Being ahead by ancestry is not enough: the spool must say so, by + # recording both its own revision and this checkout's head. + if expected is SpoolRevisionState.AHEAD and ( + lineage is None or not {names[stamp], names[head]} <= lineage + ): + expected = SpoolRevisionState.INCOMPATIBLE + assert state is expected + + +def _data_version(connection: sqlite3.Connection) -> int: + return connection.execute("PRAGMA data_version").fetchone()[0] + + +def _runs_columns(path: Path) -> set[str]: + connection = sqlite3.connect(path) + try: + return { + row[1] for row in connection.execute("PRAGMA table_info(telemetry_runs)") + } + finally: + connection.close() + + +def _open_as_runner_without_lineage( + path: Path, script_location: Path | None +) -> SpoolRevisionState: + """Open as a checkout from before lineage was recorded, like #1168's runner. + + It refuses a revision it does not know. Otherwise it upgrades to its head + in one ``BEGIN IMMEDIATE`` transaction, and records no lineage. + """ + + history = migration_history(script_location) + revision = current_database_revision(path) + if revision == history.head: + return SpoolRevisionState.AT_HEAD + if revision is not None and revision not in history.revisions: + return SpoolRevisionState.INCOMPATIBLE + engine = create_spool_engine(path, immediate_transactions=True) + try: + with ( + engine.begin() as connection, + alembic_config( + connection=connection, script_location=script_location + ) as config, + ): + command.upgrade(config, "head") + finally: + engine.dispose() + return SpoolRevisionState.BEHIND + + +@dataclass +class _ModelSpool: + stamp: int | None = None + lineage: frozenset[int] | None = None + + +def _model_open( + parents: list[int | None], + spool: _ModelSpool, + node: int, + records_lineage: bool, + *, + needs_no_lineage: frozenset[int], +) -> tuple[SpoolRevisionState, bool]: + """What one open should find and whether it should write; updates ``spool``. + + A runner from before lineage was recorded upgrades without recording it and + refuses every revision it does not know. A lineage-recording runner records + it on each upgrade, repairs it at its own head unless that revision is one + every history starts from (``needs_no_lineage``), and accepts an unknown + revision only on the recorded lineage. + """ + + ancestry = _ancestry(parents, node) + if spool.stamp == node: + repair = ( + records_lineage + and node not in needs_no_lineage + and spool.lineage != ancestry + ) + if repair: + spool.lineage = ancestry + return SpoolRevisionState.AT_HEAD, repair + if spool.stamp is None or spool.stamp in ancestry: + spool.stamp = node + if records_lineage: + spool.lineage = ancestry + return SpoolRevisionState.BEHIND, True + if ( + records_lineage + and spool.lineage is not None + and {spool.stamp, node} <= spool.lineage + ): + return SpoolRevisionState.AHEAD, False + return SpoolRevisionState.INCOMPATIBLE, False + + +def _open_in_order( + root: Path, parents: list[int | None], opens: list[tuple[int, bool]] +) -> tuple[list[SpoolRevisionState], int | None]: + """Open one spool as each checkout in turn, checking the model after each. + + Each open is a revision and whether that checkout's runner records + lineage. Returns each open's state and the revision the spool ends at. + """ + + names = [_packaged_head()] + [f"node_{index}" for index in range(1, len(parents))] + revisions = { + node: _additive_revision(names[node], names[parents[node]]) + for node in range(1, len(parents)) + } + checkouts: dict[int, Path | None] = {0: None} + for node in range(1, len(parents)): + lineage = sorted(_ancestry(parents, node) - {0}) + checkouts[node] = _checkout( + root / f"checkout_{node}", *(revisions[ancestor] for ancestor in lineage) + ) + spool_path = root / "events.sqlite3" + sqlite3.connect(spool_path).close() + observer = sqlite3.connect(spool_path) + model = _ModelSpool() + states: list[SpoolRevisionState] = [] + # Revision 0 stands for the whole packaged history, whatever its length. + packaged = migration_history() + needs_no_lineage = frozenset({0} if names[0] in packaged.bases else ()) + try: + for node, records_lineage in opens: + before = _data_version(observer) + expected, writes = _model_open( + parents, + model, + node, + records_lineage, + needs_no_lineage=needs_no_lineage, + ) + if records_lineage: + engine = create_spool_engine(spool_path) + try: + state = upgrade_spool_database( + engine, script_location=checkouts[node] + ) + except IncompatibleSpoolRevisionError: + state = SpoolRevisionState.INCOMPATIBLE + finally: + engine.dispose() + else: + state = _open_as_runner_without_lineage(spool_path, checkouts[node]) + assert state is expected + runner = "a lineage-recording" if records_lineage else "an older" + event(f"{runner} runner found the spool {state}") + if writes and state is SpoolRevisionState.AT_HEAD: + event("a checkout at head recorded a missing or stale lineage") + states.append(state) + # Only an upgrade or a lineage repair writes; every other open reads. + assert (_data_version(observer) != before) == writes + assert model.stamp is not None + assert current_database_revision(spool_path) == names[model.stamp] + assert recorded_spool_lineage(spool_path) == ( + None + if model.lineage is None + else packaged.revisions | {names[other] for other in model.lineage} + ) + # The schema is exactly that of the spool's revision: refused + # checkouts added nothing. + applied = _ancestry(parents, model.stamp) - {0} + synthetic = range(1, len(parents)) + tables = _tables(spool_path) + columns = _runs_columns(spool_path) + assert { + other + for other in synthetic + if f"graph_publication_jobs_{names[other]}" in tables + } == applied + assert { + other for other in synthetic if f"region_{names[other]}" in columns + } == applied + if state is not SpoolRevisionState.INCOMPATIBLE: + # Everything this checkout's schema has is in the spool. + assert _ancestry(parents, node) - {0} <= applied + finally: + observer.close() + return states, model.stamp + + +@settings( + max_examples=40, + deadline=None, + suppress_health_check=[HealthCheck.too_slow], +) +@given( + parents=_revision_trees(max_revisions=3), + opens=st.lists( + st.tuples(st.integers(min_value=0, max_value=3), st.booleans()), + min_size=1, + max_size=8, + ), +) +def test_opens_in_any_order_by_checkouts_on_a_revision_tree_match_the_model( + tmp_path_factory, parents, opens +) -> None: + """Including checkouts whose runner predates lineage, and never records it.""" + + states, _ = _open_in_order( + tmp_path_factory.mktemp("tree"), + parents, + [(node % len(parents), records_lineage) for node, records_lineage in opens], + ) + assert len(states) == len(opens) + + +@settings( + max_examples=12, + deadline=None, + suppress_health_check=[HealthCheck.too_slow], +) +@given( + length=st.integers(min_value=1, max_value=4), + opens=st.lists(st.integers(min_value=0, max_value=4), min_size=1, max_size=5), +) +def test_lineage_recording_checkouts_on_one_line_of_history_are_never_refused( + tmp_path_factory, length, opens +) -> None: + parents = [None] + list(range(length)) + opens = [node % len(parents) for node in opens] + states, stamp = _open_in_order( + tmp_path_factory.mktemp("line"), parents, [(node, True) for node in opens] + ) + assert SpoolRevisionState.INCOMPATIBLE not in states + # The spool ends at the newest revision any checkout brought. + assert stamp == max(opens) + + +# --- Every revision is additive ------------------------------------------------ +# +# The check is a guard, not a proof that older code keeps working. It holds a +# migration to a short list of operations on the tables that existed before +# it, and confirms that rows the real spool code stored survive it and can +# still be written naming only the old columns. + + +@dataclass(frozen=True) +class _TableShape: + sql: str + columns: dict[str, tuple[object, ...]] + indexes: frozenset[tuple[object, ...]] + triggers: frozenset[tuple[str, str]] + + +def _shape(path: Path) -> dict[str, _TableShape]: + """Every table's stored definition, columns, indexes and triggers.""" + + connection = sqlite3.connect(path) + try: + shapes: dict[str, _TableShape] = {} + for table, sql in connection.execute( + "SELECT name, sql FROM sqlite_master " + "WHERE type = 'table' AND name NOT LIKE 'sqlite_%'" + ).fetchall(): + if table in _BOOKKEEPING_TABLES: + continue + columns = { + name: (declared.upper(), notnull, default, primary_key, hidden) + for _, name, declared, notnull, default, primary_key, hidden in ( + connection.execute(f'PRAGMA table_xinfo("{table}")') + ) + } + indexes = set() + for _, index, unique, origin, partial in connection.execute( + f'PRAGMA index_list("{table}")' + ).fetchall(): + keys = tuple( + (name, descending, collation) + for _, _, name, descending, collation, key in connection.execute( + f'PRAGMA index_xinfo("{index}")' + ) + if key + ) + (index_sql,) = connection.execute( + "SELECT sql FROM sqlite_master WHERE type = 'index' AND name = ?", + (index,), + ).fetchone() + # SQLite numbers the indexes behind PRIMARY KEY and UNIQUE + # itself, so they are compared by definition, not name. + indexes.add( + (index if origin == "c" else None, unique, origin, partial) + + (keys, index_sql) + ) + shapes[table] = _TableShape( + sql=sql, + columns=columns, + indexes=frozenset(indexes), + triggers=frozenset( + connection.execute( + "SELECT name, sql FROM sqlite_master " + "WHERE type = 'trigger' AND tbl_name = ?", + (table,), + ) + ), + ) + return shapes + finally: + connection.close() + + +def _inserted_text(before: str, after: str) -> str | None: + """What ``after`` adds to ``before`` in one place, or ``None`` otherwise. + + ``ALTER TABLE … ADD COLUMN`` inserts the column into the stored definition + after the last column, ahead of any table constraints. A rename, a drop + or a rebuilt table changes the definition some other way. + """ + + prefix = len(os.path.commonprefix([before, after])) + suffix = len(os.path.commonprefix([before[::-1], after[::-1]])) + suffix = min(suffix, len(before) - prefix, len(after) - prefix) + if prefix + suffix != len(before): + return None + return after[prefix : len(after) - suffix] + + +_CONSTRAINT_OR_EXPRESSION = re.compile( + r"\b(CHECK|UNIQUE|PRIMARY|GENERATED|AS)\b", re.IGNORECASE +) + + +def _shape_violations( + before: dict[str, _TableShape], after: dict[str, _TableShape] +) -> list[str]: + problems: list[str] = [] + for table, old in before.items(): + new = after.get(table) + if new is None: + problems.append(f"{table}: removed") + continue + added = _inserted_text(old.sql, new.sql) + if added is None: + problems.append(f"{table}: definition changed, not only extended") + elif _CONSTRAINT_OR_EXPRESSION.search(added): + problems.append(f"{table}: new columns carry a constraint or expression") + for column in old.columns.keys() - new.columns.keys(): + problems.append(f"{table}.{column}: removed") + for column, definition in new.columns.items(): + if column in old.columns: + if old.columns[column] != definition: + problems.append(f"{table}.{column}: changed") + continue + _, notnull, default, primary_key, hidden = definition + if hidden: + problems.append(f"{table}.{column}: new column is generated") + if primary_key: + problems.append(f"{table}.{column}: new column is in the primary key") + if notnull and default is None: + problems.append( + f"{table}.{column}: new column is NOT NULL without a default" + ) + for index in sorted(old.indexes - new.indexes, key=repr): + problems.append(f"{table}: index {index[0] or index[4]} removed or changed") + for name, unique, _, partial, keys, _ in sorted( + new.indexes - old.indexes, key=repr + ): + if unique: + problems.append(f"{table}: new index {name or keys} is unique") + if partial: + problems.append(f"{table}: new index {name or keys} is partial") + if any(column is None for column, _, _ in keys): + problems.append( + f"{table}: new index {name or keys} is on an expression" + ) + if new.triggers != old.triggers: + problems.append(f"{table}: triggers changed") + return problems + + +_NAME = r'(?:["`\[]?\w+["`\]]?\s*\.\s*)?["`\[]?(\w+)["`\]]?' +_ROW_STATEMENTS = ( + ( + "INSERT", + re.compile(rf"(?:INSERT|REPLACE)(?:\s+OR\s+\w+)?\s+INTO\s+{_NAME}", re.I), + ), + ("UPDATE", re.compile(rf"UPDATE(?:\s+OR\s+\w+)?\s+{_NAME}", re.I)), + ("DELETE", re.compile(rf"DELETE\s+FROM\s+{_NAME}", re.I)), +) +_ALTER_TABLE = re.compile(rf"ALTER\s+TABLE\s+{_NAME}\s+(\w+)", re.I) +_DROP = re.compile(rf"DROP\s+(TABLE|INDEX|TRIGGER)\s+(?:IF\s+EXISTS\s+)?{_NAME}", re.I) +_CREATE_TRIGGER = re.compile( + rf"CREATE\s+(?:TEMP\s+|TEMPORARY\s+)?TRIGGER\b.*?\bON\s+{_NAME}", re.I | re.S +) +_HARMLESS_STATEMENT = re.compile( + r"(BEGIN|COMMIT|ROLLBACK|SAVEPOINT|RELEASE|PRAGMA|SELECT|ANALYZE|" + r"CREATE\s+(?:UNIQUE\s+)?INDEX|CREATE\s+TABLE|CREATE\s+VIEW)\b", + re.I, +) + + +def _statement_violations( + statements: list[str], before: dict[str, _TableShape] +) -> list[str]: + """Statements the migration ran that the policy does not allow. + + On a table that already existed, only ``ALTER TABLE … ADD COLUMN`` and + ``CREATE INDEX`` are allowed: no inserted, updated or deleted rows, no + other ``ALTER``, no ``DROP`` and no trigger. Whatever a statement would + spare of the rows this check seeds, it is refused for its kind. + """ + + indexes = { + index[0]: table + for table, shape in before.items() + for index in shape.indexes + if index[0] + } + triggers = { + name: table for table, shape in before.items() for name, _ in shape.triggers + } + refused = "statement not allowed on an existing table" + problems: list[str] = [] + for statement in statements: + statement = statement.strip() + if statement.startswith("--"): + continue # SQLite's own checks, traced as comments + rows = [ + (kind, found.group(1)) + for kind, pattern in _ROW_STATEMENTS + # A WITH clause can precede the verb, so look past the start. + for found in pattern.finditer(statement) + if statement.upper().startswith(("WITH", kind, "REPLACE")) + ] + if rows: + problems += [ + f"{table}: {refused}: {kind}" for kind, table in rows if table in before + ] + elif found := _ALTER_TABLE.match(statement): + table, action = found.groups() + if table in before and action.upper() != "ADD": + problems.append(f"{table}: {refused}: ALTER TABLE {action.upper()}") + elif found := _DROP.match(statement): + kind, name = found.group(1).upper(), found.group(2) + table = {"TABLE": name, "INDEX": indexes.get(name)}.get( + kind, triggers.get(name) + ) + if table in before: + problems.append(f"{table}: {refused}: DROP {kind} {name}") + elif found := _CREATE_TRIGGER.match(statement): + if found.group(1) in before: + problems.append(f"{found.group(1)}: {refused}: CREATE TRIGGER") + elif not _HARMLESS_STATEMENT.match(statement): + problems.append(f"statement to review by hand: {statement[:60]}") + return problems + + +@functools.cache +def _stored_by_the_spool(label: str) -> dict[str, list[dict[str, object]]]: + """The rows this checkout's spool code stores for one build's runs. + + A pending run with two events, a local-only run with one and a registered + run with none, read back as stored: valid JSON, both upload states. + """ + + with tempfile.TemporaryDirectory() as directory: + path = Path(directory) / "events.sqlite3" + spool = EventSpool(path) + try: + pending = _registration(f"{label}-pending", f"{label}-producer") + spool.register(pending) + for stage in "ab": + spool.append(pending, _event(stage)) + local = _registration(f"{label}-local", f"{label}-producer") + spool.register(local) + spool.append(local, _event("a")) + spool.make_local_only(f"{label}-local", f"{label}-producer", "test") + spool.register(_registration(f"{label}-idle", f"{label}-producer")) + finally: + _close(spool) + return _stored_rows(path) + + +# Rows for tables the spool code above does not fill, by table name: a +# function from 0 (a row to seed) or 1 (a row to write afterwards) to a valid +# row. A revision that adds a table whose constraints refuse arbitrary values +# gives it rows here, so that the revision after it can be checked. +_ROWS_FOR_OTHER_TABLES: dict[str, Callable[[int], dict[str, object]]] = {} + + +def _sample(declared: str, index: int) -> object: + """A value of a column's affinity, distinct for each ``index``.""" + + if "INT" in declared: + return index + 1 + if any(part in declared for part in ("CHAR", "CLOB", "TEXT")): + return f"value-{index}" + if not declared or "BLOB" in declared: + return f"value-{index}".encode() + if any(part in declared for part in ("REAL", "FLOA", "DOUB")): + return index + 0.5 + return index + 1 + + +def _writable_columns(shape: _TableShape) -> list[str]: + return [name for name, definition in shape.columns.items() if not definition[4]] + + +def _rows(table: str, shape: _TableShape, variant: int) -> list[list[object]]: + """Rows for one table, each in the order of its writable columns.""" + + columns = _writable_columns(shape) + stored = _stored_by_the_spool(("seeded", "written")[variant]) + if table in stored: + return [[row[column] for column in columns] for row in stored[table]] + if table in _ROWS_FOR_OTHER_TABLES: + row = _ROWS_FOR_OTHER_TABLES[table](variant) + return [[row[column] for column in columns]] + return [[_sample(shape.columns[column][0], variant) for column in columns]] + + +def _insert( + connection: sqlite3.Connection, table: str, shape: _TableShape, row: list[object] +) -> None: + columns = _writable_columns(shape) + connection.execute( + f'INSERT INTO "{table}" ({", ".join(f'"{name}"' for name in columns)}) ' + f"VALUES ({', '.join('?' for _ in columns)})", + row, + ) + + +def _old_rows( + connection: sqlite3.Connection, table: str, shape: _TableShape +) -> list[tuple[object, ...]]: + columns = ", ".join(f'"{name}"' for name in _writable_columns(shape)) + return sorted(connection.execute(f'SELECT {columns} FROM "{table}"'), key=repr) + + +def _write_violations(path: Path, before: dict[str, _TableShape]) -> list[str]: + """Insert, update and delete rows in each table naming only old columns.""" + + problems: list[str] = [] + connection = sqlite3.connect(path, isolation_level=None) + try: + for table, shape in before.items(): + columns = _writable_columns(shape) + key = [name for name in columns if shape.columns[name][3]] or columns + others = [name for name in columns if name not in key] + where = " AND ".join(f'"{name}" = ?' for name in key) + try: + for row in _rows(table, shape, 1): + values = dict(zip(columns, row, strict=True)) + key_values = [values[name] for name in key] + _insert(connection, table, shape, row) + if others: + connection.execute( + f'UPDATE "{table}" SET ' + + ", ".join(f'"{name}" = ?' for name in others) + + f" WHERE {where}", + [values[name] for name in others] + key_values, + ) + connection.execute( + f'DELETE FROM "{table}" WHERE {where}', key_values + ) + except sqlite3.Error as error: + problems.append( + f"{table}: a write naming only its existing columns failed: {error}" + ) + finally: + connection.close() + return problems + + +def _additivity_violations( + path: Path, migrate: Callable[[Callable[[str], None]], None] +) -> list[str]: + """Why ``migrate`` breaks the additive-only rule on ``path``, if it does. + + ``migrate`` runs the migration in one transaction and passes every + statement SQLite executes to the function it is given. Before it, each + table is given the rows the real spool code stores, or arbitrary rows for + tables that code does not fill. + """ + + before = _shape(path) + connection = sqlite3.connect(path) + try: + for table, shape in before.items(): + for row in _rows(table, shape, 0): + try: + _insert(connection, table, shape, row) + except sqlite3.Error as error: + raise AssertionError( + f"give table {table!r} valid rows in _ROWS_FOR_OTHER_TABLES: " + f"it refuses arbitrary ones ({error})" + ) from error + connection.commit() + seeded = { + table: _old_rows(connection, table, shape) + for table, shape in before.items() + } + finally: + connection.close() + + statements: list[str] = [] + try: + migrate(statements.append) + except Exception as error: + reason = (str(error).strip().splitlines() or [type(error).__name__])[0] + return [f"the migration failed in its transaction: {reason}"] + + after = _shape(path) + problems = _statement_violations(statements, before) + problems += _shape_violations(before, after) + connection = sqlite3.connect(path) + try: + for table, shape in before.items(): + try: + rows = _old_rows(connection, table, shape) + except sqlite3.Error: + continue # the table or a column went, which is reported above + if rows != seeded[table]: + problems.append(f"{table}: existing rows changed") + finally: + connection.close() + surviving = { + table: shape + for table, shape in before.items() + if table in after and set(shape.columns) <= set(after[table].columns) + } + return problems + _write_violations(path, surviving) + + +def _revision_additivity_violations( + script_location: Path | None, revision: str, parent: str, directory: Path +) -> list[str]: + directory.mkdir(parents=True) + path = directory / "events.sqlite3" + # As upgrade_spool_database migrates: one BEGIN IMMEDIATE transaction. + engine = create_spool_engine(path, immediate_transactions=True) + + def upgrade_to(target: str, trace: Callable[[str], None] | None = None) -> None: + with ( + engine.begin() as connection, + alembic_config( + connection=connection, script_location=script_location + ) as config, + ): + driver_connection = connection.connection.driver_connection + driver_connection.set_trace_callback(trace) + try: + command.upgrade(config, target) + finally: + driver_connection.set_trace_callback(None) + + try: + upgrade_to(parent) + return _additivity_violations(path, lambda trace: upgrade_to(revision, trace)) + finally: + engine.dispose() + + +def _parents(down_revision: str | tuple[str, ...] | None) -> tuple[str, ...]: + if down_revision is None: + return () + return (down_revision,) if isinstance(down_revision, str) else down_revision + + +def test_every_packaged_revision_after_the_initial_one_is_additive(tmp_path) -> None: + """The initial revision creates the schema or adopts a pre-Alembic spool.""" + + with alembic_config() as config: + scripts = list(ScriptDirectory.from_config(config).walk_revisions()) + roots = {script.revision for script in scripts if script.down_revision is None} + assert roots == {_INITIAL_REVISION} + for script in scripts: + for parent in _parents(script.down_revision): + directory = tmp_path / f"{script.revision}-from-{parent}" + assert ( + _revision_additivity_violations( + None, script.revision, parent, directory + ) + == [] + ), script.revision + + +def test_a_later_additive_revision_passes_the_same_check(tmp_path) -> None: + newer = _checkout(tmp_path / "newer", _additive_revision("future")) + assert ( + _revision_additivity_violations( + newer, "future", _packaged_head(), tmp_path / "check" + ) + == [] + ) + + +# The generated column and the conditional statements are the ones an earlier +# version of this check passed: its seeded rows held no JSON and no real +# upload state, so they neither tripped the expression nor matched the WHERE. +_OVERFLOW_ON_VALID_JSON = ( + "ALTER TABLE telemetry_events ADD COLUMN synthetic_overflow INTEGER GENERATED ALWAYS " + "AS (CASE WHEN json_valid(payload_json) THEN abs(-9223372036854775808) " + "ELSE 0 END) VIRTUAL" +) +_NULL_FOR_PENDING_RUNS = ( + "ALTER TABLE telemetry_runs ADD COLUMN synthetic_gate INT GENERATED ALWAYS AS " + "(CASE WHEN upload_state = 'pending' THEN NULL ELSE 1 END) VIRTUAL NOT NULL" +) +_DELETE_VALID_EVENTS = "DELETE FROM telemetry_events WHERE json_valid(payload_json)" +_HOLD_PENDING_RUNS = ( + "UPDATE telemetry_runs SET upload_state = 'held' WHERE upload_state = 'pending'" +) + +_BREAKING_REVISIONS = { + "drop-column": ( + 'op.drop_column("telemetry_runs", "local_only_reason")', + "telemetry_runs.local_only_reason: removed", + ), + "unique-index": ( + 'op.create_index("synthetic_unique_index", "telemetry_runs", ' + '["run_id", "updated_at"], unique=True)', + "telemetry_runs: new index synthetic_unique_index is unique", + ), + "required-column": ( + """ + with op.batch_alter_table("telemetry_runs", recreate="always") as batch: + batch.add_column( + sa.Column("synthetic_note", sa.Text(), nullable=False, server_default="x") + ) + with op.batch_alter_table("telemetry_runs", recreate="always") as batch: + batch.alter_column("synthetic_note", server_default=None) + """, + "telemetry_runs.synthetic_note: new column is NOT NULL without a default", + ), + "type-change": ( + """ + with op.batch_alter_table("telemetry_events") as batch: + batch.alter_column("sequence", type_=sa.Text()) + """, + "telemetry_events.sequence: changed", + ), + "rewritten-rows": ( + "op.execute(\"UPDATE telemetry_runs SET upload_state = 'held'\")", + "telemetry_runs: existing rows changed", + ), + "conditional-update": ( + f"op.execute({_HOLD_PENDING_RUNS!r})", + "telemetry_runs: statement not allowed on an existing table: UPDATE", + ), + "conditional-delete": ( + f"op.execute({_DELETE_VALID_EVENTS!r})", + "telemetry_events: statement not allowed on an existing table: DELETE", + ), + "generated-column": ( + f"op.execute({_OVERFLOW_ON_VALID_JSON!r})", + "telemetry_events.synthetic_overflow: new column is generated", + ), + "vacuum": ( + """ + op.create_table("synthetic_table", sa.Column("body", sa.Text())) + op.execute("VACUUM") + """, + "the migration failed in its transaction", + ), +} + + +@pytest.mark.parametrize("name", sorted(_BREAKING_REVISIONS)) +def test_the_additivity_check_rejects_a_breaking_alembic_revision( + tmp_path, name +) -> None: + body, problem = _BREAKING_REVISIONS[name] + branch = _checkout( + tmp_path / "branch", _Revision("breaking", _packaged_head(), body) + ) + problems = _revision_additivity_violations( + branch, "breaking", _packaged_head(), tmp_path / "check" + ) + assert any(found.startswith(problem) for found in problems), problems + + +def _recreate( + connection: sqlite3.Connection, + table: str, + edit: Callable[[str], str], + *, + leading_values: str = "", +) -> None: + """SQLite's documented twelve-step table change, as Alembic's batch mode.""" + + (sql,) = connection.execute( + "SELECT sql FROM sqlite_master WHERE type = 'table' AND name = ?", (table,) + ).fetchone() + indexes = [ + index_sql + for (index_sql,) in connection.execute( + "SELECT sql FROM sqlite_master " + "WHERE type = 'index' AND tbl_name = ? AND sql IS NOT NULL", + (table,), + ) + ] + # SQLite quotes the name in the definition it stores after a rename. + renamed, count = re.subn( + rf'^CREATE TABLE "?{table}"? \(', f"CREATE TABLE {table}_new (", edit(sql) + ) + assert count == 1, sql + connection.execute(renamed) + connection.execute(f"INSERT INTO {table}_new SELECT {leading_values}* FROM {table}") + connection.execute(f"DROP TABLE {table}") + connection.execute(f"ALTER TABLE {table}_new RENAME TO {table}") + for index_sql in indexes: + connection.execute(index_sql) + + +def _edited(old: str, new: str) -> Callable[[str], str]: + def edit(sql: str) -> str: + assert old in sql, sql + return sql.replace(old, new, 1) + + return edit + + +def _sql(*statements: str) -> Callable[[sqlite3.Connection], object]: + def apply(connection: sqlite3.Connection) -> None: + for statement in statements: + connection.execute(statement) + + return apply + + +_ALLOWED_CHANGES: dict[str, Callable[[sqlite3.Connection], object]] = { + "new-table": _sql( + "CREATE TABLE synthetic_jobs " + "(publication_id TEXT PRIMARY KEY, status TEXT NOT NULL)" + ), + "new-table-with-check": _sql( + "CREATE TABLE synthetic_states (state TEXT NOT NULL " + "CHECK (state IN ('queued', 'done')))" + ), + "new-table-referencing-runs": _sql( + "CREATE TABLE synthetic_receipts (run_id TEXT, producer_id TEXT, " + "FOREIGN KEY (run_id, producer_id) " + "REFERENCES telemetry_runs (run_id, producer_id))" + ), + "new-table-filled-from-old-rows": _sql( + "CREATE TABLE synthetic_notes (run_id TEXT, note TEXT)", + "INSERT INTO synthetic_notes (run_id) SELECT run_id FROM telemetry_runs", + ), + "nullable-column": _sql( + "ALTER TABLE telemetry_runs ADD COLUMN synthetic_region TEXT" + ), + "defaulted-column": _sql( + "ALTER TABLE telemetry_events ADD COLUMN synthetic_attempts INTEGER NOT NULL DEFAULT 0" + ), + "plain-index": _sql( + "CREATE INDEX synthetic_plain_index ON telemetry_runs (updated_at)" + ), +} + +# Each maps to a problem it must be reported as when applied alone. They are +# applied in this order, after any allowed changes. +_FORBIDDEN_CHANGES: dict[str, tuple[Callable[[sqlite3.Connection], object], str]] = { + "drop-column": ( + _sql("ALTER TABLE telemetry_runs DROP COLUMN local_only_reason"), + "telemetry_runs.local_only_reason: removed", + ), + "rename-column": ( + _sql("ALTER TABLE telemetry_events RENAME COLUMN created_at TO queued_at"), + "telemetry_events: statement not allowed on an existing table: " + "ALTER TABLE RENAME", + ), + "drop-index": ( + _sql("DROP INDEX telemetry_events_run_sequence"), + "telemetry_events: index telemetry_events_run_sequence removed", + ), + "replaced-index": ( + _sql( + "DROP INDEX telemetry_events_run_sequence", + "CREATE INDEX telemetry_events_run_sequence " + "ON telemetry_events (run_id, producer_id, sequence)", + ), + "telemetry_events: statement not allowed on an existing table: DROP INDEX", + ), + "unique-index": ( + _sql( + "CREATE UNIQUE INDEX synthetic_unique_index ON telemetry_runs (run_id, updated_at)" + ), + "telemetry_runs: new index synthetic_unique_index is unique", + ), + "partial-index": ( + _sql( + "CREATE INDEX synthetic_partial_index ON telemetry_events (created_at) " + "WHERE sequence > 0" + ), + "telemetry_events: new index synthetic_partial_index is partial", + ), + "expression-index": ( + _sql( + "CREATE INDEX synthetic_expression_index ON telemetry_events (length(payload_json))" + ), + "telemetry_events: new index synthetic_expression_index is on an expression", + ), + "trigger": ( + _sql( + "CREATE TRIGGER synthetic_trigger AFTER INSERT ON telemetry_runs " + "BEGIN SELECT 1; END" + ), + "telemetry_runs: statement not allowed on an existing table: CREATE TRIGGER", + ), + "rewritten-rows": ( + _sql("UPDATE telemetry_runs SET upload_state = 'held'"), + "telemetry_runs: existing rows changed", + ), + "conditional-update": ( + _sql(_HOLD_PENDING_RUNS), + "telemetry_runs: existing rows changed", + ), + "deleted-rows": ( + _sql("DELETE FROM telemetry_events"), + "telemetry_events: existing rows changed", + ), + "conditional-delete": ( + _sql(_DELETE_VALID_EVENTS), + "telemetry_events: existing rows changed", + ), + "delete-through-a-with-clause": ( + _sql( + "WITH doomed AS (SELECT event_id FROM telemetry_events) " + "DELETE FROM telemetry_events WHERE event_id IN (SELECT event_id FROM doomed)" + ), + "telemetry_events: statement not allowed on an existing table: DELETE", + ), + "inserted-rows": ( + _sql( + "INSERT INTO telemetry_runs " + "(run_id, producer_id, registration_json, updated_at) " + "VALUES ('extra', 'extra', '{}', '2026-10-09T00:00:00+00:00')" + ), + "telemetry_runs: statement not allowed on an existing table: INSERT", + ), + "generated-column": ( + _sql(_OVERFLOW_ON_VALID_JSON), + "telemetry_events.synthetic_overflow: new column is generated", + ), + "constrained-generated-column": ( + _sql(_NULL_FOR_PENDING_RUNS), + "the migration failed in its transaction: NOT NULL constraint failed", + ), + "column-with-check": ( + _sql( + "ALTER TABLE telemetry_events ADD COLUMN synthetic_flag INTEGER DEFAULT 0 " + "CHECK (synthetic_flag = 0)" + ), + "telemetry_events: new columns carry a constraint or expression", + ), + "required-column": ( + lambda connection: _recreate( + connection, + "telemetry_runs", + _edited("(\n\t", "(\n\tsynthetic_note TEXT NOT NULL, \n\t"), + leading_values="'x', ", + ), + "telemetry_runs.synthetic_note: new column is NOT NULL without a default", + ), + "type-change": ( + lambda connection: _recreate( + connection, + "telemetry_events", + _edited("sequence INTEGER NOT NULL", "sequence TEXT NOT NULL"), + ), + "telemetry_events.sequence: changed", + ), + "check-constraint": ( + lambda connection: _recreate( + connection, + "telemetry_events", + lambda sql: sql[: sql.rindex(")")] + ", \n\tCHECK (sequence > 0)\n)", + ), + "telemetry_events: definition changed, not only extended", + ), + "collation": ( + lambda connection: _recreate( + connection, + "telemetry_runs", + _edited("upload_state TEXT", "upload_state TEXT COLLATE RTRIM"), + ), + "telemetry_runs: definition changed, not only extended", + ), + "identical-rebuild": ( + lambda connection: _recreate(connection, "telemetry_runs", lambda sql: sql), + "telemetry_runs: statement not allowed on an existing table: DROP TABLE", + ), + "drop-table": ( + _sql("DROP TABLE telemetry_events"), + "telemetry_events: removed", + ), + "vacuum": ( + _sql("VACUUM"), + "the migration failed in its transaction: cannot VACUUM", + ), +} + + +@pytest.fixture(scope="module") +def spool_at_packaged_head(tmp_path_factory) -> Path: + path = tmp_path_factory.mktemp("template") / "events.sqlite3" + _close(EventSpool(path)) + return path + + +def _change( + path: Path, + allowed: list[str], + forbidden: list[str], + trace: Callable[[str], None] | None = None, +) -> None: + """Apply the named changes in one ``BEGIN IMMEDIATE`` transaction.""" + + connection = sqlite3.connect(path, isolation_level=None) + try: + connection.set_trace_callback(trace) + connection.execute("BEGIN IMMEDIATE") + try: + for name in _ALLOWED_CHANGES: + if name in allowed: + _ALLOWED_CHANGES[name](connection) + for name, (apply, _) in _FORBIDDEN_CHANGES.items(): + if name in forbidden: + apply(connection) + connection.execute("COMMIT") + except BaseException: + if connection.in_transaction: + connection.execute("ROLLBACK") + raise + finally: + connection.close() + + +@pytest.mark.parametrize("name", list(_FORBIDDEN_CHANGES)) +def test_the_additivity_check_names_each_forbidden_change( + tmp_path, spool_at_packaged_head, name +) -> None: + path = tmp_path / "events.sqlite3" + shutil.copyfile(spool_at_packaged_head, path) + problems = _additivity_violations( + path, lambda trace: _change(path, [], [name], trace) + ) + assert any(found.startswith(_FORBIDDEN_CHANGES[name][1]) for found in problems), ( + problems + ) + + +@settings(max_examples=80, deadline=None) +@given( + allowed=st.lists(st.sampled_from(sorted(_ALLOWED_CHANGES)), unique=True), + forbidden=st.lists(st.sampled_from(sorted(_FORBIDDEN_CHANGES)), unique=True), +) +def test_the_additivity_check_flags_exactly_the_forbidden_changes( + tmp_path_factory, spool_at_packaged_head, allowed, forbidden +) -> None: + """And on whatever it accepts, this checkout's spool code still works.""" + + directory = tmp_path_factory.mktemp("changes") + checked = directory / "checked.sqlite3" + shutil.copyfile(spool_at_packaged_head, checked) + problems = _additivity_violations( + checked, lambda trace: _change(checked, allowed, forbidden, trace) + ) + assert bool(problems) == bool(forbidden), problems + if forbidden: + return + + # A newer checkout stamped this spool after making exactly these changes. + used = directory / "used.sqlite3" + shutil.copyfile(spool_at_packaged_head, used) + _change(used, allowed, []) + _stamp(used, "future", migration_history().revisions | {"future"}) + spool = EventSpool(used) + try: + registration = _registration("run", "producer") + spool.register(registration) + queued = [spool.append(registration, _event(stage)) for stage in "ab"] + assert spool.pending_runs() == [registration] + assert spool.batch("run", "producer") == queued + spool.acknowledge([queued[0]["event_id"]]) + spool.make_local_only("run", "producer", "test") + spool.prune() + assert spool.batch("run", "producer") == queued[1:] + assert not spool.has_deliverable() + finally: + _close(spool)