test(e2e): log runner VM consoles when no runner registers

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.

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 "