feat(platform): tini as PID 1, Hypercorn, a log-level setting, the image on CI's Python, an airgapped boot gate before push (#5159)

- Dockerfile: python:3.14-slim, the Python CI tests on (was 3.13). tini from
  apt is PID 1 (ENTRYPOINT tini -- entrypoint.sh): it reaps the zombies ssh
  and ansible leave and forwards SIGTERM.
- cli: Hypercorn's serve() with one worker (run, stream and scheduler state is
  in-process), a 10 s graceful timeout, and SIGTERM/SIGINT as the shutdown
  trigger. Access and error lines go through Steward's logging. --debug keeps
  Quart's reloading dev server.
- Logging: steward/core/logging_setup.py installs one root handler before
  anything logs (until now a library's basicConfig on import was the only
  configuration). Its level is the `log.level` setting (DEBUG/INFO/WARNING/
  ERROR, default INFO), applied at boot and on save in Settings → General.
- CI publish: build, then "The image boots with no internet" (rule 164,
  snippet #3552), then push, so a broken image never reaches a tag (rule 177).
  On an --internal network with its own Postgres, the image must migrate and
  answer /health, run tini as PID 1, serve first-run setup with its assets
  from /static and no third-party host, and exit 0 on SIGTERM. Logs and
  clean-up run always.

Tests: tests/core/test_logging_setup.py; the smoke step itself.
Not in this commit: the dependency lockfile (it conflicts with rule 154 and
is waiting on the operator).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

.forgejo/workflows/ci.yml

@@ -132,9 +132,9 @@ jobs:
         # 401s with it. REGISTRY_TOKEN is a repo Actions secret holding a
         # Forgejo token scoped read:package + write:package.
         run: echo "${{ secrets.REGISTRY_TOKEN }}" | docker login git.fabledsword.com -u bvandeusen --password-stdin
-      - name: Build + push (commit-SHA always; :dev on dev, :latest on main)
+      - name: Build (commit-SHA always; :dev on dev, :latest on main)
         run: |
-          set -euxo pipefail
+          set -eux
           IMAGE=git.fabledsword.com/bvandeusen/steward
           # The moving tag for this ref: dev→:dev, main→:latest (rule 46). main IS
           # the production line, so :latest tracks main's tip; there is no :main.
@@ -150,12 +150,100 @@ jobs:
           # concurrent run could have evicted from the shared daemon (issue #1093).
           if [ -n "$MOVING" ]; then
             docker build -t "$IMAGE:${{ github.sha }}" -t "$IMAGE:$MOVING" .
-            docker push "$IMAGE:${{ github.sha }}"
-            docker push "$IMAGE:$MOVING"
           else
             docker build -t "$IMAGE:${{ github.sha }}" .
-            docker push "$IMAGE:${{ github.sha }}"
           fi
+
+      # Rule 164's check, BETWEEN build and push (rule 177): an image that
+      # can't boot, migrate and serve with no internet never reaches a tag.
+      # An --internal network lets it reach its own Postgres and nothing else;
+      # --network none can't work for an app that needs a database to start.
+      # Embedded DNS works on a user-defined network, unlike the services:
+      # containers above (rule 79), so the app finds Postgres by name.
+      - name: The image boots with no internet
+        env:
+          SMOKE: steward-smoke-${{ github.run_id }}
+        run: |
+          set -eux
+          IMAGE=git.fabledsword.com/bvandeusen/steward:${{ github.sha }}
+          docker network create --internal "$SMOKE-net"
+          docker run -d --name "$SMOKE-pg" --network "$SMOKE-net" \
+            -e POSTGRES_USER=steward -e POSTGRES_PASSWORD=steward -e POSTGRES_DB=steward \
+            postgres:16-alpine
+          # Waits with deadlines (rule 156); pg_isready, not /dev/tcp, which is
+          # a bash builtin and never succeeds under sh.
+          ready=""
+          for _ in $(seq 1 60); do
+            if docker exec "$SMOKE-pg" pg_isready -U steward -d steward -q; then ready=1; break; fi
+            sleep 2
+          done
+          test -n "$ready" || { echo "FATAL: postgres not ready within 120s"; exit 1; }
+
+          docker run -d --name "$SMOKE-app" --network "$SMOKE-net" \
+            -e "STEWARD_DATABASE_URL=postgresql+asyncpg://steward:steward@$SMOKE-pg:5432/steward" \
+            -e STEWARD_SECRET_KEY=smoke-test-placeholder \
+            "$IMAGE"
+          # The image has no curl; its own Python fetches. Prints the body.
+          fetch() {
+            docker exec "$SMOKE-app" python -c 'import sys, urllib.request
+          r = urllib.request.urlopen("http://127.0.0.1:5000" + sys.argv[1], timeout=5)
+          sys.stdout.write(r.read().decode())' "$1"
+          }
+          # Migrations run before the server starts, so /health answering
+          # means the schema applied against a real database.
+          up=""
+          for _ in $(seq 1 60); do
+            if fetch /health >/dev/null 2>&1; then up=1; break; fi
+            sleep 2
+          done
+          if [ -z "$up" ]; then
+            echo "FATAL: Steward never answered /health with no internet access"
+            docker logs "$SMOKE-app" 2>&1 | tail -80
+            exit 1
+          fi
+          fetch /health | grep -q '"ok"'
+
+          # tini is PID 1, so zombies are reaped and SIGTERM reaches Steward.
+          test "$(docker exec "$SMOKE-app" cat /proc/1/comm)" = "tini"
+
+          # A fresh database lands on first-run setup: a real page, its assets
+          # served by Steward itself, and no third-party host in it (rule 155).
+          fetch / > /tmp/smoke-page.html
+          grep -qi "<!doctype html" /tmp/smoke-page.html
+          grep -q "/static/" /tmp/smoke-page.html
+          if grep -Eqi 'https?://(fonts\.|cdn\.|unpkg\.|cdnjs\.|ajax\.)' /tmp/smoke-page.html; then
+            echo "FATAL: the page references a third-party host"
+            grep -Eoi 'https?://[^"'"'"' ]+' /tmp/smoke-page.html
+            exit 1
+          fi
+
+          # A stop is a clean shutdown: SIGTERM through tini to Hypercorn, which
+          # finishes within its graceful timeout and exits 0.
+          docker stop -t 30 "$SMOKE-app"
+          code="$(docker inspect -f '{{.State.ExitCode}}' "$SMOKE-app")"
+          test "$code" = "0" || { echo "FATAL: Steward exited $code on SIGTERM"; exit 1; }
+
+      - name: Push
+        run: |
+          set -eux
+          IMAGE=git.fabledsword.com/bvandeusen/steward
+          docker push "$IMAGE:${{ github.sha }}"
+          if [ "${{ github.ref }}" = "refs/heads/dev" ]; then
+            docker push "$IMAGE:dev"
+          elif [ "${{ github.ref }}" = "refs/heads/main" ]; then
+            docker push "$IMAGE:latest"
+          fi
+
+      - name: Smoke logs
+        if: always()
+        run: docker logs "steward-smoke-${{ github.run_id }}-app" 2>&1 | tail -60 || true
+
+      # A failed smoke must not leave a Postgres and an app on the shared daemon.
+      - name: Smoke clean-up
+        if: always()
+        run: |
+          docker rm -f "steward-smoke-${{ github.run_id }}-app" "steward-smoke-${{ github.run_id }}-pg" >/dev/null 2>&1 || true
+          docker network rm "steward-smoke-${{ github.run_id }}-net" >/dev/null 2>&1 || true
       - name: Prune dangling layers
         if: always()
         run: docker image prune -f

Dockerfile

@@ -1,4 +1,5 @@
-FROM python:3.13-slim
+# The Python CI tests on (ci-python:3.14), so the image runs what was tested.
+FROM python:3.14-slim
 
 RUN DEBIAN_FRONTEND=noninteractive apt-get update \
     && DEBIAN_FRONTEND=noninteractive apt-get install -y --no-install-recommends \
@@ -12,6 +13,9 @@ RUN DEBIAN_FRONTEND=noninteractive apt-get update \
         sshpass \
         # git — clones and pulls Ansible git sources (Settings > Ansible)
         git \
+        # tini — PID 1: reaps the zombies ssh and ansible leave behind and
+        # forwards SIGTERM to Steward so a stop is a graceful shutdown
+        tini \
     && rm -rf /var/lib/apt/lists/*
 
 # Upgrade pip to suppress the version notice
@@ -44,5 +48,5 @@ RUN useradd -m -u 1000 app \
 
 EXPOSE 5000
 
-ENTRYPOINT ["/entrypoint.sh"]
+ENTRYPOINT ["/usr/bin/tini", "--", "/entrypoint.sh"]
 CMD ["steward", "--host", "0.0.0.0", "--port", "5000"]

steward/ansible/executor.py

@@ -96,16 +96,17 @@ def _host_gate(app: "Quart") -> dict:
     return gate
 
 
-async def _claim_hosts(app: "Quart", run_id: str, hosts: set[str]) -> bool:
+async def _claim_hosts(app: "Quart", run_id: str, hosts: set[str]) -> str | None:
     """Hold every host in hosts for run_id, waiting while another run holds
-    any of them. Returns whether it had to wait. Raises _Aborted when the run
-    is cancelled while waiting, HostBusy after HOST_WAIT_SECONDS."""
+    any of them. Returns the line saying what it waited for, or None when it
+    didn't wait. Raises _Aborted when the run is cancelled while waiting,
+    HostBusy after HOST_WAIT_SECONDS."""
     from steward.models.ansible import AnsibleRunStatus
 
     gate = _host_gate(app)
     held: dict[str, str] = gate["held"]
     give_up = time.monotonic() + HOST_WAIT_SECONDS
-    waited = False
+    waited: str | None = None
     while True:
         busy = sorted({held[h] for h in hosts if h in held and held[h] != run_id})
         if not busy:
@@ -119,11 +120,11 @@ async def _claim_hosts(app: "Quart", run_id: str, hosts: set[str]) -> bool:
             names = ", ".join(sorted(h for h in hosts if h in held))
             raise HostBusy(f"gave up after {HOST_WAIT_SECONDS:.0f} s waiting for "
                            f"{names}, held by run {', '.join(busy)}")
-        if not waited:
-            waited = True
+        if waited is None:
+            waited = (f"[queued — waiting for run {', '.join(busy)} "
+                      "to finish on the same host]")
             await _set_status(app, run_id, AnsibleRunStatus.queued)
-            _broadcast(run_id, f"[queued — waiting for run {', '.join(busy)} "
-                               "to finish on the same host]")
+            _broadcast(run_id, waited)
         changed = gate["changed"]
         try:
             # Woken by a release; the short timeout also notices a cancel.
@@ -557,12 +558,19 @@ async def start_run(
     slot_held = False
     try:
         # The hosts first, so a run waiting on a host doesn't sit on a run slot.
-        queued = await _claim_hosts(app, run_id, hosts)
+        # What it waited for goes in the stored output too, so a run that sat
+        # queued says why after the live view is gone.
+        waits: list[str] = []
+        host_wait = await _claim_hosts(app, run_id, hosts)
+        if host_wait:
+            waits.append(host_wait)
         if sem.locked():
-            if not queued:
+            if not waits:
                 await _set_status(app, run_id, AnsibleRunStatus.queued)
-            queued = True
-            _broadcast(run_id, "[queued — waiting for an Ansible run slot]")
+            waits.append("[queued — waiting for an Ansible run slot]")
+            _broadcast(run_id, waits[-1])
+        queued = bool(waits)
+        db_output = "\n".join(waits)
         await sem.acquire()
         slot_held = True
         if run_id in _cancelled:  # cancelled while queued — abort before launching

steward/app.py

@@ -93,6 +93,8 @@ def create_app(
             to_thresholds_cfg, to_access_cfg,
         )
         _settings = load_settings_sync(app.config["DATABASE_URL"])
+        from .core.logging_setup import set_log_level
+        set_log_level(_settings.get("log.level"))
         app.config.update(to_access_cfg(_settings))
         app.config.update(
             DATA_RETENTION_DAYS=_settings.get("data.retention_days", 90),

steward/cli.py

@@ -1,14 +1,56 @@
+import asyncio
+import logging
+import signal
 from pathlib import Path
+
 import click
-from .app import create_app
+
+from .core.logging_setup import configure_logging
+
+# How long a stop waits for requests in flight (and SSE streams) to finish.
+GRACEFUL_TIMEOUT_SECONDS = 10.0
+
+
+def hypercorn_config(host: str, port: int):
+    """Hypercorn as the production server (#5159): one worker, because Steward
+    keeps run, stream and scheduler state in-process; its access and error
+    lines go through Steward's logging, so the log.level setting governs them."""
+    from hypercorn.config import Config
+
+    config = Config()
+    config.bind = [f"{host}:{port}"]
+    config.workers = 1
+    config.graceful_timeout = GRACEFUL_TIMEOUT_SECONDS
+    config.accesslog = logging.getLogger("hypercorn.access")
+    config.errorlog = logging.getLogger("hypercorn.error")
+    config.access_log_format = "%(h)s %(r)s %(s)s %(b)s %(D)s"
+    return config
+
+
+async def _serve(app, config) -> None:
+    from hypercorn.asyncio import serve
+
+    stop = asyncio.Event()
+    loop = asyncio.get_running_loop()
+    for sig in (signal.SIGTERM, signal.SIGINT):
+        loop.add_signal_handler(sig, stop.set)
+    await serve(app, config, shutdown_trigger=stop.wait)
 
 
 @click.command()
 @click.option("--config", default="config.yaml", help="Path to config.yaml")
 @click.option("--host", default="0.0.0.0")
 @click.option("--port", default=5000, type=int)
-@click.option("--debug", is_flag=True, default=False)
+@click.option("--debug", is_flag=True, default=False,
+              help="Quart's development server with the reloader, not Hypercorn.")
 def main(config: str, host: str, port: int, debug: bool) -> None:
     """Start the Steward server."""
+    # Before anything logs; create_app applies the log.level setting once
+    # settings load.
+    configure_logging()
+    from .app import create_app
     app = create_app(config_path=Path(config))
-    app.run(host=host, port=port, debug=debug)
+    if debug:
+        app.run(host=host, port=port, debug=True)
+        return
+    asyncio.run(_serve(app, hypercorn_config(host, port)))

steward/core/logging_setup.py

@@ -0,0 +1,37 @@
+"""Steward's logging: one handler on the root logger, its level a setting (#5159).
+
+Until this, nothing in Steward configured logging. Lines reached the container
+log only because a library called basicConfig on import, so the level and the
+format were whatever that library chose. configure_logging runs first thing in
+the CLI, so a later basicConfig anywhere is a no-op. The level is the
+`log.level` setting, applied once settings load and again when it is saved.
+"""
+from __future__ import annotations
+
+import logging
+import sys
+
+LEVELS = ("DEBUG", "INFO", "WARNING", "ERROR")
+DEFAULT_LEVEL = "INFO"
+FORMAT = "%(asctime)s %(levelname)s [%(name)s] %(message)s"
+
+
+def set_log_level(level: object) -> str:
+    """Set the root level; an unknown value falls back to INFO. Returns the
+    level applied."""
+    name = str(level or "").strip().upper()
+    if name not in LEVELS:
+        name = DEFAULT_LEVEL
+    logging.getLogger().setLevel(name)
+    return name
+
+
+def configure_logging(level: object = DEFAULT_LEVEL) -> str:
+    """Install Steward's handler on the root logger (once) and set its level."""
+    root = logging.getLogger()
+    if not any(getattr(h, "_steward", False) for h in root.handlers):
+        handler = logging.StreamHandler(sys.stderr)
+        handler.setFormatter(logging.Formatter(FORMAT))
+        handler._steward = True  # type: ignore[attr-defined]
+        root.addHandler(handler)
+    return set_log_level(level)

steward/core/settings.py

@@ -53,6 +53,9 @@ DEFAULTS: dict[str, Any] = {
     # The audit log is a security record: kept longer than operational data.
     "audit.retention_days": 365,
     "monitors.poll_interval_seconds": 60,
+    # Root log level: DEBUG, INFO, WARNING or ERROR (steward/core/logging_setup.py).
+    # WARNING also hides the per-request access lines.
+    "log.level": "INFO",
     "smtp.host": "",
     "smtp.port": 587,
     "smtp.tls": True,

steward/settings/routes.py

@@ -7,6 +7,7 @@ from quart import Blueprint, current_app, render_template, request, redirect, ur
 
 from steward.auth.middleware import require_role
 from steward.core.audit import audit_request, log_audit
+from steward.core.logging_setup import LEVELS as LOG_LEVELS, set_log_level
 from steward.models.users import UserRole
 from steward.core.settings import (
     get_all_settings, set_setting, delete_setting,
@@ -93,7 +94,8 @@ async def index():
 async def general():
     async with current_app.db_sessionmaker() as db:
         settings = await get_all_settings(db)
-    return await render_template("settings/general.html", settings=settings)
+    return await render_template("settings/general.html", settings=settings,
+                                 log_levels=LOG_LEVELS)
 
 
 @settings_bp.post("/general/")
@@ -117,6 +119,7 @@ async def save_general():
                               int(form.get("data.retention_days", 90)))
             await set_setting(db, "monitors.poll_interval_seconds",
                               int(form.get("monitors.poll_interval_seconds", 60)))
+            await set_setting(db, "log.level", set_log_level(form.get("log.level")))
     await _reload_app_config()
     await log_audit(current_app, session.get("user_id"), session.get("username", ""),
                     "settings.saved", detail={"section": "general"})

steward/templates/settings/general.html

@@ -74,6 +74,16 @@
            value="{{ settings['monitors.poll_interval_seconds'] }}" style="max-width:120px;">
     <div style="font-size:0.78rem;color:var(--text-muted);margin-top:0.25rem;">Requires restart to take effect.</div>
   </div>
+
+  <div class="form-group">
+    <label>Log level</label>
+    <select name="log.level" style="max-width:160px;">
+      {% for level in log_levels %}
+      <option value="{{ level }}" {% if settings['log.level'] == level %}selected{% endif %}>{{ level | capitalize }}</option>
+      {% endfor %}
+    </select>
+    <div style="font-size:0.78rem;color:var(--text-muted);margin-top:0.25rem;">What reaches the container log. Applies when saved. Warning hides the line logged for each request.</div>
+  </div>
 </div>
 
 <div style="margin-top:1rem;display:flex;align-items:center;gap:1rem;">

tests/core/test_ansible_overlap.py

@@ -47,18 +47,18 @@ def test_a_second_run_on_the_same_host_waits_for_the_first(gate):
     app = gate.app
 
     async def go():
-        assert await executor._claim_hosts(app, "a", {"web"}) is False
+        assert await executor._claim_hosts(app, "a", {"web"}) is None
         b = asyncio.create_task(executor._claim_hosts(app, "b", {"web", "db"}))
         await asyncio.sleep(0.05)
         assert not b.done()
         held = app._ansible_host_gate["held"]
         assert "db" not in held                 # all or nothing: b holds no half
-        assert await executor._claim_hosts(app, "c", {"db"}) is False
+        assert await executor._claim_hosts(app, "c", {"db"}) is None
         executor._release_hosts(app, "c", {"db"})
         await asyncio.sleep(0.05)
         assert not b.done()                     # web is still a's
         executor._release_hosts(app, "a", {"web"})
-        assert await asyncio.wait_for(b, 5) is True
+        assert "waiting for run a" in await asyncio.wait_for(b, 5)
         assert held == {"web": "b", "db": "b"}
 
     asyncio.run(go())

tests/core/test_logging_setup.py

@@ -0,0 +1,57 @@
+"""Logging and the server (#5159): one handler, the level a setting, and
+Hypercorn's lines going through the same logging."""
+import logging
+
+import pytest
+
+from steward.core import logging_setup
+from steward.core.settings import DEFAULTS
+
+
+@pytest.fixture
+def root():
+    root = logging.getLogger()
+    handlers, level = list(root.handlers), root.level
+    yield root
+    root.handlers[:] = handlers
+    root.setLevel(level)
+
+
+def test_configuring_twice_installs_one_handler(root):
+    logging_setup.configure_logging("INFO")
+    logging_setup.configure_logging("DEBUG")
+    ours = [h for h in root.handlers if getattr(h, "_steward", False)]
+    assert len(ours) == 1
+    assert ours[0].formatter._fmt == logging_setup.FORMAT
+    assert root.level == logging.DEBUG
+
+
+@pytest.mark.parametrize("given, applied", [
+    ("warning", "WARNING"), (" Error ", "ERROR"), ("DEBUG", "DEBUG"),
+    ("loud", "INFO"), ("", "INFO"), (None, "INFO"),
+])
+def test_the_level_setting_is_applied_and_an_unknown_one_is_info(root, given, applied):
+    assert logging_setup.set_log_level(given) == applied
+    assert root.level == getattr(logging, applied)
+
+
+def test_a_library_basic_config_after_ours_changes_nothing(root):
+    logging_setup.configure_logging("WARNING")
+    before = list(root.handlers)
+    logging.basicConfig(level=logging.DEBUG, format="%(message)s")
+    assert root.handlers == before and root.level == logging.WARNING
+
+
+def test_the_level_is_a_setting_defaulting_to_info():
+    assert DEFAULTS["log.level"] == "INFO"
+    assert DEFAULTS["log.level"] in logging_setup.LEVELS
+
+
+def test_the_server_is_one_hypercorn_worker_logging_through_steward():
+    from steward.cli import GRACEFUL_TIMEOUT_SECONDS, hypercorn_config
+    config = hypercorn_config("0.0.0.0", 5000)
+    assert config.bind == ["0.0.0.0:5000"]
+    assert config.workers == 1          # run, stream and scheduler state is in-process
+    assert config.graceful_timeout == GRACEFUL_TIMEOUT_SECONDS
+    assert config.accesslog is logging.getLogger("hypercorn.access")
+    assert config.errorlog is logging.getLogger("hypercorn.error")