From 39c86901742fe99578302d07e59c57183ee309b0 Mon Sep 17 00:00:00 2001 From: Christopher Bartz Date: Tue, 13 Oct 2026 13:26:10 +0000 Subject: [PATCH] test(e2e): log runner VM consoles when no runner registers --- charms/tests/e2e/conftest.py | 147 +++++++++++++++ charms/tests/e2e/test_garm_e2e.py | 24 ++- charms/tests/unit/test_e2e_runner_consoles.py | 173 ++++++++++++++++++ charms/tests/unit/test_e2e_runner_polling.py | 2 +- 4 files changed, 339 insertions(+), 7 deletions(-) create mode 100644 charms/tests/unit/test_e2e_runner_consoles.py diff --git a/charms/tests/e2e/conftest.py b/charms/tests/e2e/conftest.py index eff2fa98..7739012d 100644 --- a/charms/tests/e2e/conftest.py +++ b/charms/tests/e2e/conftest.py @@ -30,9 +30,11 @@ # suite (e.g. charms/tests/integration) is collected in the same session. from tests.integration.conftest import ( # noqa: F401 _collect_debug_info, + _credential_sentinels, _deploy_configurator, _garm_login, _get_garm_address, + _redact_sentinels, deploy_garm_app_no_integration_fixture, deploy_postgresql_server_fixture, garm_app_image_fixture, @@ -62,6 +64,17 @@ CA_CHANNEL = "1/stable" E2E_TUNNEL_LOCAL_PORT = 18080 E2E_TUNNEL_LOCAL_TLS_PORT = 18443 +CONSOLE_REFRESH_INTERVAL = 60 +# Enough to reach back past the cloud-init final stage, where the tunnel and the +# GARM install wrapper log, without replaying the whole kernel boot. +CONSOLE_LINES = 300 +# The console lands in a public log, and with boot debug on GARM's install script +# traces the instance's callback JWT and the tokens it hands curl and config.sh. +# Group 1 is kept, so the redaction marker shows which value went. +CONSOLE_SECRET_PATTERNS = ( + re.compile(r"()eyJ[\w-]+\.[\w-]+\.[\w-]+"), + re.compile(r"(?i)(bearer\s+|--token\s+|token[\"']?\s*[=:]\s*[\"']?)[^\s\"']+"), +) # The rock ships the GARM server only, so the client comes from an upstream # release. Pinned, with its published digest, so a new release cannot change the @@ -658,6 +671,140 @@ def _tunnel_pre_install_script(target: str, user: str, private_key_b64: str) -> """ +@pytest.fixture(name="runner_consoles") +def runner_consoles_fixture(openstack_credentials: dict[str, str]) -> "RunnerConsoles": + """Console recorder for the runner VMs a single test waits on.""" + return RunnerConsoles(openstack_credentials) + + +class RunnerConsoles: + """Serial-console snapshots of runner VMs, logged when none of them registers. + + A VM whose bootstrap never calls back leaves no trace in GARM: only its console + shows whether the tunnel came up and how far cloud-init got. GARM's + bootstrap-timeout reaper deletes such a VM before the wait for it gives up, so + consoles are read while the VMs run and only logged once the wait has failed. + """ + + def __init__( + self, + credentials: dict[str, str], + refresh_interval: float = CONSOLE_REFRESH_INTERVAL, + ): + """Initialize the recorder. + + Args: + credentials: OpenStack credentials, as the openstack_credentials fixture + returns them. + refresh_interval: Minimum seconds between two reads of the same console. + """ + self._credentials = credentials + self._refresh_interval = refresh_interval + self._session: tuple[str, str] | None = None + self._snapshots: dict[str, str] = {} + self._read_at: dict[str, float] = {} + + def record(self, instances: list[dict]) -> None: + """Snapshot the console of every running instance not read recently. + + Never raises: a failed read is logged and retried on a later call. + + Args: + instances: Instance payloads as returned by the GARM API. + """ + now = time.monotonic() + for instance in instances: + name, server_id = instance.get("name"), instance.get("provider_id") + if not name or not server_id or instance.get("status") != "running": + continue + read_at = self._read_at.get(name) + if read_at is not None and now - read_at < self._refresh_interval: + continue + self._read_at[name] = now + try: + self._snapshots[name] = self._read_console(server_id) + except (requests.RequestException, ValueError, KeyError) as exc: + logger.warning("Could not read the console of runner VM %s: %s", name, exc) + + def log(self) -> None: + """Log the latest snapshot of every recorded console, redacted.""" + if not self._snapshots: + logger.error("No runner VM console was captured") + return + sentinels = _credential_sentinels() + for name, output in self._snapshots.items(): + redacted = _redact_sentinels(output, sentinels) + for pattern in CONSOLE_SECRET_PATTERNS: + redacted = pattern.sub(r"\1[REDACTED]", redacted) + logger.error( + "Last %d console lines of runner VM %s:\n%s", CONSOLE_LINES, name, redacted + ) + + def _read_console(self, server_id: str) -> str: + """Return the tail of one server's console output.""" + if self._session is None: + self._session = self._authenticate() + token, compute_url = self._session + response = requests.post( + f"{compute_url}/servers/{server_id}/action", + json={"os-getConsoleOutput": {"length": CONSOLE_LINES}}, + headers={"X-Auth-Token": token}, + timeout=30, + ) + if response.status_code == 401: + # The wait outlives a Keystone token; authenticate again on the next read. + self._session = None + response.raise_for_status() + return response.json()["output"] + + def _authenticate(self) -> tuple[str, str]: + """Return a Keystone token and the public compute endpoint of the region.""" + creds = self._credentials + auth_url = creds["auth_url"].rstrip("/") + if not auth_url.endswith("/v3"): + auth_url = f"{auth_url}/v3" + response = requests.post( + f"{auth_url}/auth/tokens", + json={ + "auth": { + "identity": { + "methods": ["password"], + "password": { + "user": { + "name": creds["username"], + "domain": {"name": creds["user_domain_name"]}, + "password": creds["password"], + } + }, + }, + "scope": { + "project": { + "name": creds["project_name"], + "domain": {"name": creds["project_domain_name"]}, + } + }, + } + }, + timeout=30, + ) + response.raise_for_status() + token = response.headers["X-Subject-Token"] + compute_url = next( + ( + endpoint["url"] + for service in response.json()["token"]["catalog"] + if service.get("type") == "compute" + for endpoint in service.get("endpoints", []) + if endpoint.get("interface") == "public" + and endpoint.get("region_id") == creds["region_name"] + ), + None, + ) + if compute_url is None: + raise ValueError(f"no public compute endpoint in region {creds['region_name']}") + return token, compute_url.rstrip("/") + + @dataclass(frozen=True) class GarmCli: """A garm-cli already pointed at the deployed GARM as an administrator. diff --git a/charms/tests/e2e/test_garm_e2e.py b/charms/tests/e2e/test_garm_e2e.py index 6edf0069..df3aad3d 100644 --- a/charms/tests/e2e/test_garm_e2e.py +++ b/charms/tests/e2e/test_garm_e2e.py @@ -14,7 +14,7 @@ import jubilant import pytest import requests -from tests.e2e.conftest import GarmCli +from tests.e2e.conftest import GarmCli, RunnerConsoles from tests.integration.conftest import ( _collect_debug_info, _garm_login, @@ -61,6 +61,7 @@ def test_garm_agent_shell( garm_with_ingress: str, e2e_scaleset: str, garm_cli: GarmCli, + runner_consoles: RunnerConsoles, ): """ arrange: The E2E scale set deployed with enable-shell, holding a registered runner @@ -73,7 +74,9 @@ def test_garm_agent_shell( over that websocket in both directions. """ _skip_unless_agent_url_is_tls(juju, garm_with_ingress) - instance = _wait_for_runner_online(juju, garm_with_ingress, e2e_scaleset) + instance = _wait_for_runner_online( + juju, garm_with_ingress, e2e_scaleset, runner_consoles + ) runner_name = instance["name"] _wait_for_shell_capability(juju, garm_with_ingress, runner_name) # The terminal echoes the command as typed, so a plain marker would be found @@ -89,7 +92,12 @@ def test_garm_agent_shell( logger.info("Agent shell on %s executed a command successfully", runner_name) -def test_garm_e2e(juju: jubilant.Juju, garm_with_ingress: str, e2e_scaleset: str): +def test_garm_e2e( + juju: jubilant.Juju, + garm_with_ingress: str, + e2e_scaleset: str, + runner_consoles: RunnerConsoles, +): """ arrange: GARM deployed with postgresql + traefik ingress; garm-configurator holding real ProdStack credentials, a stable runner-image name, and a unique run label; @@ -109,7 +117,7 @@ def test_garm_e2e(juju: jubilant.Juju, garm_with_ingress: str, e2e_scaleset: str ref = os.environ.get("GITHUB_HEAD_REF") or required_env("GITHUB_REF_NAME") # Wait for runner VM to spawn and register before dispatching - _wait_for_runner_online(juju, garm_with_ingress, label) + _wait_for_runner_online(juju, garm_with_ingress, label, runner_consoles) github_client = create_github_app_client(E2E_APP_ENV) @@ -174,6 +182,7 @@ def _wait_for_runner_online( juju: jubilant.Juju, garm_app: str, runner_label: str, + consoles: RunnerConsoles, timeout: int = 25 * 60, poll_interval: int = 15, ) -> dict: @@ -183,6 +192,7 @@ def _wait_for_runner_online( juju: Juju client for the model GARM is deployed in. garm_app: Name of the deployed GARM application. runner_label: Unique runner label configured by the E2E fixture. + consoles: Recorder for the consoles of the VMs that never register. timeout: Seconds to wait before failing the test. poll_interval: Seconds between polls. @@ -232,6 +242,7 @@ def _wait_for_runner_online( ) instances_response.raise_for_status() instances = instances_response.json() or [] + consoles.record(instances) summary = sorted( f"{i.get('name')}: status={i.get('status')} " f"runner_status={i.get('runner_status')}" @@ -269,8 +280,8 @@ def _wait_for_runner_online( # URL. An empty last observation means no instance was found for the label; # pending_create means the provider never picked one up; running with a # pending runner_status means the VM booted but its bootstrap never called - # back, with GARM's own logs -- collected next, through the sentinel - # redactor -- carrying the reason. + # back, with the VM consoles and GARM's own logs -- logged next, through the + # sentinel redactor -- carrying the reason. if last_instances: logger.error( "Last instances observed for runner label %s (possibly reaped by GARM's " @@ -284,6 +295,7 @@ def _wait_for_runner_online( ) else: logger.error("No instance was ever observed for runner label %s", runner_label) + consoles.log() _collect_debug_info(juju, garm_app) pytest.fail( f"No runner serving label {runner_label!r} reached a registered state " diff --git a/charms/tests/unit/test_e2e_runner_consoles.py b/charms/tests/unit/test_e2e_runner_consoles.py new file mode 100644 index 00000000..6ac8dcbb --- /dev/null +++ b/charms/tests/unit/test_e2e_runner_consoles.py @@ -0,0 +1,173 @@ +# Copyright 2026 Canonical Ltd. +# See LICENSE file for licensing details. +"""Model-free tests for the E2E runner console capture. + +The capture only ever runs when a live E2E run is already failing, so a broken +fetch or a redaction gap would otherwise surface as a lost diagnostic or a leaked +token in a public log -- never as a red test. +""" + +import itertools +import logging +from unittest.mock import Mock + +import pytest +import requests +from tests.e2e import conftest as fixtures +from tests.e2e import test_garm_e2e as e2e + +CREDENTIALS = { + "auth_url": "https://keystone.example:5000/v3", + "username": "tenant-bot", + "password": "tenant-password", + "project_name": "project", + "user_domain_name": "Default", + "project_domain_name": "Default", + "region_name": "RegionOne", + "network": "net", +} +COMPUTE_URL = "https://nova.example:8774/v2.1" +RUNNING_VM = {"name": "garm-abc", "status": "running", "provider_id": "server-1"} + + +def _keystone_response() -> Mock: + """Build a Keystone token response whose catalog lists compute in two regions.""" + catalog = [ + { + "type": "compute", + "endpoints": [ + {"interface": "public", "region_id": "Other", "url": "https://other"}, + {"interface": "internal", "region_id": "RegionOne", "url": "https://int"}, + {"interface": "public", "region_id": "RegionOne", "url": COMPUTE_URL}, + ], + } + ] + return Mock( + headers={"X-Subject-Token": "keystone-token"}, + json=Mock(return_value={"token": {"catalog": catalog}}), + ) + + +def _console_response(output: str) -> Mock: + """Build a Nova os-getConsoleOutput response.""" + return Mock(json=Mock(return_value={"output": output})) + + +def test_runner_consoles_logs_redacted_console_of_reaped_vm(monkeypatch, caplog): + """ + arrange: A running runner VM whose console carries the tunnel log line, the tenant + password, a JWT and a bearer header. + act: Record the VM while it runs, then log after it is gone from the instance list. + assert: The tunnel line is logged with every secret redacted -- the snapshot has to + outlive GARM's reaper, and the log it lands in is public. + """ + jwt = "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJnYXJtIn0.c2lnbmF0dXJl" + console = ( + "[e2e-tunnel] ERROR: tunnel never came up\n" + "login tenant-password\n" + f"BEARER_TOKEN={jwt}\n" + "curl -H 'Authorization: Bearer opaque-callback-token' https://garm\n" + "GITHUB_TOKEN=AABBCCDDEEFF\n" + ) + post = Mock(side_effect=[_keystone_response(), _console_response(console)]) + monkeypatch.setattr(fixtures.requests, "post", post) + monkeypatch.setenv("OS_PASSWORD", CREDENTIALS["password"]) + consoles = fixtures.RunnerConsoles(CREDENTIALS) + + consoles.record([RUNNING_VM]) + with caplog.at_level(logging.ERROR): + consoles.log() + + assert post.call_args_list[1].args[0] == f"{COMPUTE_URL}/servers/server-1/action" + assert post.call_args_list[1].kwargs["headers"]["X-Auth-Token"] == "keystone-token" + assert "garm-abc" in caplog.text + assert "[e2e-tunnel] ERROR: tunnel never came up" in caplog.text + for secret in ("tenant-password", jwt, "opaque-callback-token", "AABBCCDDEEFF"): + assert secret not in caplog.text + + +@pytest.mark.parametrize( + "instances", + [ + pytest.param([{**RUNNING_VM, "provider_id": None}], id="no-provider-id"), + pytest.param([{**RUNNING_VM, "status": "creating"}], id="not-running"), + pytest.param([RUNNING_VM, RUNNING_VM], id="within-refresh-interval"), + ], +) +def test_runner_consoles_skips_unreadable_or_fresh_vms(monkeypatch, instances): + """ + arrange: Instances without a server yet, not booted yet, or seen twice in a row. + act: Record each instance list. + assert: At most one console read happens, so the poll loop does not hammer Nova. + """ + post = Mock(side_effect=[_keystone_response(), _console_response("boot")]) + monkeypatch.setattr(fixtures.requests, "post", post) + consoles = fixtures.RunnerConsoles(CREDENTIALS) + + for instance in instances: + consoles.record([instance]) + + console_reads = [c for c in post.call_args_list if "/servers/" in c.args[0]] + assert len(console_reads) <= 1 + + +@pytest.mark.parametrize( + "failure", + [ + pytest.param(requests.ConnectionError("unreachable"), id="unreachable"), + pytest.param(Mock(headers={}, json=Mock(return_value={})), id="no-token"), + pytest.param( + Mock( + headers={"X-Subject-Token": "t"}, + json=Mock(return_value={"token": {"catalog": []}}), + ), + id="no-compute-endpoint", + ), + ], +) +def test_runner_consoles_never_raises_on_openstack_errors(monkeypatch, caplog, failure): + """ + arrange: Keystone unreachable, answering without a token, or without compute. + act: Record a running VM and log. + assert: Neither call raises and the failure is logged, so diagnostics cannot turn + a runner that failed to register into a different, misleading error. + """ + monkeypatch.setattr(fixtures.requests, "post", Mock(side_effect=[failure])) + consoles = fixtures.RunnerConsoles(CREDENTIALS) + + with caplog.at_level(logging.WARNING): + consoles.record([RUNNING_VM]) + consoles.log() + + assert "console" in caplog.text.lower() + + +def test_wait_for_runner_online_logs_consoles_on_timeout(monkeypatch): + """ + arrange: A scale set whose only VM runs but never registers. + act: Wait for a registered runner until the timeout expires. + assert: Every poll is offered to the console recorder and its snapshots are logged + before the test fails, while the VM is still up and once it has been reaped. + """ + scalesets = [{"id": 5, "enabled": True, "tags": [{"name": "e2e-x"}]}] + get = Mock( + side_effect=[ + Mock(status_code=200, json=Mock(return_value=scalesets)), + Mock(json=Mock(return_value=[RUNNING_VM])), + ] + ) + monkeypatch.setattr(e2e.requests, "get", get) + monkeypatch.setattr(e2e, "_get_garm_address", Mock(return_value="garm")) + monkeypatch.setattr(e2e, "_garm_login", Mock(return_value="token")) + # Stays past the deadline once reached: logging reads the same patched clock. + clock = itertools.chain([0, 1], itertools.repeat(100)) + monkeypatch.setattr(e2e.time, "time", Mock(side_effect=clock)) + monkeypatch.setattr(e2e.time, "sleep", Mock()) + monkeypatch.setattr(e2e, "_collect_debug_info", Mock()) + consoles = Mock() + + with pytest.raises(pytest.fail.Exception): + e2e._wait_for_runner_online(Mock(), "garm", "e2e-x", consoles, timeout=10) + + consoles.record.assert_called_once_with([RUNNING_VM]) + consoles.log.assert_called_once_with() diff --git a/charms/tests/unit/test_e2e_runner_polling.py b/charms/tests/unit/test_e2e_runner_polling.py index ae76cda1..154378ab 100644 --- a/charms/tests/unit/test_e2e_runner_polling.py +++ b/charms/tests/unit/test_e2e_runner_polling.py @@ -86,7 +86,7 @@ def test_runner_polling_resolves_enabled_scaleset_by_label(monkeypatch, name): monkeypatch.setattr(e2e.time, "sleep", Mock()) monkeypatch.setattr(e2e, "_collect_debug_info", Mock()) - e2e._wait_for_runner_online(Mock(), "garm", label, timeout=10) + e2e._wait_for_runner_online(Mock(), "garm", label, Mock(), timeout=10) assert [call.args[0] for call in get.call_args_list] == [ "http://garm:8080/api/v1/scalesets",