diff --git a/.forgejo/workflows/ci.yml b/.forgejo/workflows/ci.yml index f26ac07..1e3ec37 100644 --- a/.forgejo/workflows/ci.yml +++ b/.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 "&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 diff --git a/Dockerfile b/Dockerfile index 8b293bf..62b906c 100644 --- a/Dockerfile +++ b/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"] diff --git a/steward/app.py b/steward/app.py index 15d9d5a..d9356df 100644 --- a/steward/app.py +++ b/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), diff --git a/steward/cli.py b/steward/cli.py index aafdd8f..c65ad6a 100644 --- a/steward/cli.py +++ b/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))) diff --git a/steward/core/logging_setup.py b/steward/core/logging_setup.py new file mode 100644 index 0000000..ee5da1b --- /dev/null +++ b/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) diff --git a/steward/core/settings.py b/steward/core/settings.py index feab97c..3c70c12 100644 --- a/steward/core/settings.py +++ b/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, diff --git a/steward/settings/routes.py b/steward/settings/routes.py index 13a7533..bacd81a 100644 --- a/steward/settings/routes.py +++ b/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"}) diff --git a/steward/templates/settings/general.html b/steward/templates/settings/general.html index 5d9e3e1..68b9478 100644 --- a/steward/templates/settings/general.html +++ b/steward/templates/settings/general.html @@ -74,6 +74,16 @@ value="{{ settings['monitors.poll_interval_seconds'] }}" style="max-width:120px;">
Requires restart to take effect.
+ +
+ + +
What reaches the container log. Applies when saved. Warning hides the line logged for each request.
+
diff --git a/tests/core/test_logging_setup.py b/tests/core/test_logging_setup.py new file mode 100644 index 0000000..d1b1177 --- /dev/null +++ b/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")