diff --git a/.s2s/BACKLOG.md b/.s2s/BACKLOG.md index 669a54b..3da37fb 100644 --- a/.s2s/BACKLOG.md +++ b/.s2s/BACKLOG.md @@ -165,7 +165,7 @@ They need Docker, and they now carry the `integration` marker, so the unit runs ### BUG-025: a startup failure prints a raw Python traceback next to the structured error -**Status**: planned | **Priority**: medium | **Created**: 2026-07-14 +**Status**: done (2026-07-15) | **Priority**: medium | **Created**: 2026-07-14 **Origin**: DEBT-031 (2026-07-14). Surfaced by running `tests/test_startup.py` for the first time. **Context**: ARCH-057 exists so that a misconfiguration is reported clearly (REQ-011, NFR-009): a structured, remediable error rather than a stack dump. Step 1 does emit exactly that — @@ -185,10 +185,18 @@ Alternatives considered: suppressing uvicorn's exception logging (fragile, and h **Caution**: this touches the boot path, which is the surface BUG-024 broke. `vektra-app/tests/test_app.py::test_missing_llm_provider_aborts_startup` drives the lifespan in-process and expects `SystemExit`; a change to a hard exit there would kill the test runner. **Acceptance criteria**: -- [ ] A misconfigured env var produces the structured `[STARTUP ERROR]` block and **no** `Traceback (most recent call last)` in container output -- [ ] Holds for a step other than config validation (e.g. database connectivity), not just step 1 -- [ ] The container still exits non-zero -- [ ] The `xfail(strict=True)` on `tests/test_startup.py::test_no_raw_traceback_on_startup_failure` is removed; strict mode makes the suite go red if the fix lands and the marker is left behind +- [x] A misconfigured env var produces the structured `[STARTUP ERROR]` block and **no** `Traceback (most recent call last)` in container output +- [x] Holds for a step other than config validation (e.g. database connectivity), not just step 1 +- [x] The container still exits non-zero +- [x] The `xfail(strict=True)` on `tests/test_startup.py::test_no_raw_traceback_on_startup_failure` is removed; strict mode makes the suite go red if the fix lands and the marker is left behind + +**Resolution** (PR #111): the recommended approach, with one refinement kept from the caution. The 11-step sequence moved into a loop-agnostic `_run_startup()` that raises `StartupValidationError` (never `SystemExit`), plus a matching `_run_shutdown()`. A new `main()` container entrypoint (`python -m vektra_app.main`, wired in `docker/entrypoint.sh`) runs the validation in the very event loop that will serve, then calls uvicorn with `lifespan="off"`. A failed step logs its `[STARTUP ERROR]` and exits non-zero with no ASGI and no traceback; because startup and serving share one loop, the async resources built during validation (DB engine, HTTP clients) stay bound to the loop that serves. + +The refinement: rather than gutting the lifespan, it **keeps** validating and raising `SystemExit` — but only for the in-process/TestClient path. So `test_missing_llm_provider_aborts_startup` (the BUG-024 tripwire the caution named) is untouched and still green; the container simply never takes that path. The container serving through `main()` is the only shipped boot path, and it is traceback-free. + +One gotcha found on the container, not in tests: uvicorn 0.36 removed `Config.setup_event_loop()` in favour of `get_loop_factory()`; the first cut called the former and produced a *different* traceback. Fixed by `asyncio.run(_serve(...), loop_factory=config.get_loop_factory())`, which also preserves uvloop (the CLI default). The lesson is the one this file already preaches: verify on the container, not just the tests. + +**Proven on the container** (rebuilt image, throwaway `docker compose run`, dev stack left running): empty `VEKTRA_LLM_PROVIDER` → `[STARTUP ERROR] Step: config_validation`, exit 1, no traceback; unreachable DB → step 1 completes, then `[STARTUP ERROR] Step: database_connectivity`, exit 1, no traceback (the non-step-1 case the criteria demand); valid `.env` → all 11 steps logged, `startup_complete`, `Uvicorn running on http://0.0.0.0:8000`. Both integration jobs (pgvector, qdrant) pass in CI, exercising the un-`xfail`ed test end-to-end. **Traceability**: REQ-011, NFR-009, ARCH-057, DEBT-031 (found by), BUG-024 (same surface) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0643343..134f3f0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,6 +28,7 @@ Convention (Keep a Changelog 1.1.0): ### Fixed - **config**: `VEKTRA_LLM_PROVIDER=""` was accepted and the stack **booted and served with an empty LLM provider**, deferring the misconfiguration to the first query — which is the one thing the ARCH-057 startup sequence exists to prevent (REQ-011, NFR-009). The field is required, but typed as a bare `str`, and `""` is a perfectly valid `str`, so pydantic never raised and step 1 never fired. It is now `min_length=1`, so an empty value fails at startup with the same structured, remediable error an absent one already produced. Found by running `tests/test_startup.py` for the first time (DEBT-031): the test had asserted this exact behaviour since it was written, believing `docker run -e VAR=` *unset* the variable when it in fact sets it to the empty string — so it had been asserting against a value the product happily accepted. Nobody found out, because nothing ever ran it. This is the third time a suite in this repo turned out to be broken the moment someone executed it. The same test also caught **BUG-025** (filed, not fixed here): the structured error is emitted and then `raise SystemExit(1)` travels out of the ASGI lifespan into uvicorn, which logs a `Traceback` after it — so a typo'd env var yields the good message *and* a stack dump, where NFR-009 asks for the former instead of the latter. Fixing that means validating before `uvicorn.run()` rather than inside the lifespan, i.e. touching the boot path BUG-024 broke, so it is tracked on its own; the assertion is `xfail(strict=True)`, which turns the suite red the moment the fix lands and the marker is left behind. +- **startup**: a failed ARCH-057 startup step printed a raw Python `Traceback` next to the structured `[STARTUP ERROR]`, where NFR-009 asks for the remediable message *instead of* the stack dump (BUG-025, REQ-011). The 11-step sequence ran inside the ASGI lifespan, so an aborting step's `raise SystemExit(1)` travelled out into uvicorn, which logged the exception before "Application startup failed." — and it applied to every step, not just config validation. The sequence now lives in a loop-agnostic `_run_startup()` that raises `StartupValidationError` (never `SystemExit`), and the container serves through a new `main()` entrypoint (`python -m vektra_app.main`, wired in `docker/entrypoint.sh`) that runs the validation in the very event loop that will serve, then starts uvicorn with `lifespan="off"`. A failed step logs its `[STARTUP ERROR]` and exits non-zero with no ASGI and no traceback; sharing one loop keeps the async resources built during validation (DB engine, HTTP clients) bound to the loop that serves, and `config.get_loop_factory()` preserves uvloop (the CLI default that uvicorn 0.36 stopped exposing through `setup_event_loop()`). The lifespan keeps validating and raising `SystemExit` for the in-process/TestClient path, so `test_missing_llm_provider_aborts_startup` is untouched; the `xfail(strict=True)` on `test_no_raw_traceback_on_startup_failure` is removed. Proven on the container for a config-validation failure and a database_connectivity failure (structured error, exit 1, no traceback) and a valid boot (all 11 steps logged, `startup_complete`, `Uvicorn running`). The required check names (`CI gate`, `Integration tests + NFR gates`) are unchanged. - **tests**: five suites that no runner executed now run, all five found by the guard above the moment it was pointed at `develop` (DEBT-031). Four are `integration`-marked — `vektra-admin/tests/test_integration.py`, `vektra-index/tests/test_integration.py`, `vektra-index/tests/test_benchmark.py`, `vektra-ingest/tests/test_integration.py` — so every unit run excluded them by `-m "not integration"`, while the only job that ran `-m integration` named `vektra-app/tests/` alone: DEBT-030 wired up vektra-app by hand and left the identical hole open in three neighbouring packages. The fifth is `tests/test_startup.py`, the ARCH-057 startup-validation suite, whose own docstring states it requires the stack "started by integration.yml" — it did not run there, because that workflow names `tests/integration/` and nothing named `tests/`. It was watching the precise surface BUG-024 broke, and it was watching nothing. The `app-integration` job becomes `package-integration` and targets `vektra-*/tests -m integration`, a glob on purpose: the hand-written package list is the thing that has now failed twice, and a package added tomorrow is picked up with no edit. `tests/test_startup.py` joins the job that already brings the stack up. Unlike vektra-app's suites in DEBT-030 these four had **not** rotted — 52 integration tests pass — but that was luck, not a property of the arrangement. The five suites under `tests/` were also missing the `integration` marker they require, which is what made them indistinguishable from unit tests `make test` had merely forgotten; `tests/nfr/test_performance.py` remains deliberately unrun (it needs a live LLM that GitHub Actions does not have) and is the single justified entry in the guard's `EXPECTED_UNRUN`, where a reviewer can see it. The required check names (`CI gate`, `Integration tests + NFR gates`) are unchanged. - **tests**: the local `.env` reached **every** test package, including the three that carried the DEBT-025 scrub fixture (DEBT-029). litellm calls `dotenv.load_dotenv()` at import and finds the repo `.env` by walking up from its own module inside `.venv/`, so the developer's configuration landed in `os.environ` — and the scrub could not stop it, because the scrub runs *before* the test body while the import that re-injects the file happens *inside* it. Measured: after `import litellm` in a test, a config left at its default resolved to the value in the developer's `.env` (`qdrant`) rather than the code's default (`pgvector`) in all four packages checked, `vektra-core` and `vektra-shared` included. Tests therefore ran a different code path locally than in CI, which is the one thing a test must not do. `vektra_shared.testing` now sets `LITELLM_MODE` before litellm can be imported, so litellm skips the dotenv load entirely; all eight test packages import the single shared fixture, and a structural test fails if a package is added without it. Two empty `tests/__init__.py` files (analytics, learn) that made pytest derive the same module name for two conftests were removed. - **tests**: `vektra-app`'s two Docker-backed test files (the ARCH-057 startup sequence and the REQ-011/NFR-009 error contract) now run in CI, in an `app-integration` job gated by the integration aggregator (DEBT-030). They were run by nothing — and, unrun, they had rotted: both built the test container's URL with `str(make_url(...))`, which masks the password as `***`, so Alembic authenticated with a literal `***` and every test errored at setup. They had never worked. Fixed; 8 tests pass. `vektra-app` also never registered the `integration` marker it relies on. diff --git a/docker/entrypoint.sh b/docker/entrypoint.sh index 6d3a3c5..f343491 100644 --- a/docker/entrypoint.sh +++ b/docker/entrypoint.sh @@ -21,9 +21,11 @@ case "$CMD_TARGET" in alembic upgrade head echo "Starting Vektra API server..." - exec uvicorn vektra_app.main:app \ - --host 0.0.0.0 \ - --port 8000 + # main() validates (ARCH-057) before calling uvicorn, so a misconfiguration + # prints its structured [STARTUP ERROR] and exits non-zero without an ASGI + # traceback (BUG-025, NFR-009). Do not switch back to `uvicorn ...:app`: that + # runs the validation inside the lifespan and reintroduces the traceback. + exec python -m vektra_app.main ;; migrate) diff --git a/tests/test_startup.py b/tests/test_startup.py index 084f56b..4287e2a 100644 --- a/tests/test_startup.py +++ b/tests/test_startup.py @@ -108,20 +108,14 @@ def test_graceful_failure_on_missing_config() -> None: ) -@pytest.mark.xfail( - strict=True, - reason=( - "BUG-025: the structured [STARTUP ERROR] block is emitted, but `raise " - "SystemExit(1)` then travels out of the ASGI lifespan into uvicorn, which logs " - "the exception — so the operator gets the good message and a Python traceback. " - "NFR-009 asks for the former instead of the latter, not both. Fixing it means " - "validating before uvicorn.run() rather than inside the lifespan, which is the " - "boot path BUG-024 broke, so it is tracked separately. strict=True: when " - "BUG-025 lands this test XPASSes and the suite goes red until the marker goes." - ), -) def test_no_raw_traceback_on_startup_failure() -> None: - """A misconfiguration is reported, not dumped as a stack trace (REQ-011, NFR-009).""" + """A misconfiguration is reported, not dumped as a stack trace (REQ-011, NFR-009). + + BUG-025 fix: the container runs `python -m vektra_app.main`, which validates + (ARCH-057) before uvicorn.run(). A failed step logs its structured + [STARTUP ERROR] and exits non-zero without the ASGI lifespan, so uvicorn + never logs a traceback beside the good message. + """ output = _run_with_empty_llm_provider() assert "Traceback (most recent call last)" not in output, ( "Raw traceback leaked in startup failure output" diff --git a/vektra-app/README.md b/vektra-app/README.md index c2b18ce..4f4a164 100644 --- a/vektra-app/README.md +++ b/vektra-app/README.md @@ -10,6 +10,16 @@ assets at `/admin/static`. ## Usage +Production / container: run the module entrypoint. It runs the ARCH-057 +validation before starting uvicorn, so a misconfiguration exits with a +structured `[STARTUP ERROR]` and no traceback (BUG-025, NFR-009). + +```bash +python -m vektra_app.main +``` + +Local development with live reload (validation runs inside the ASGI lifespan): + ```bash -uvicorn vektra_app.main:app --host 0.0.0.0 --port 8000 +uvicorn vektra_app.main:app --reload --host 0.0.0.0 --port 8000 ``` diff --git a/vektra-app/src/vektra_app/main.py b/vektra-app/src/vektra_app/main.py index c30b6b9..72acabf 100644 --- a/vektra-app/src/vektra_app/main.py +++ b/vektra-app/src/vektra_app/main.py @@ -9,6 +9,7 @@ from __future__ import annotations +import asyncio import logging import time import uuid @@ -19,6 +20,7 @@ from urllib.parse import urlparse import structlog +import uvicorn from fastapi import FastAPI, Request from fastapi.middleware.cors import CORSMiddleware from fastapi.responses import JSONResponse @@ -488,9 +490,14 @@ async def _step_11_qdrant_check( # --------------------------------------------------------------------------- -@asynccontextmanager -async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: - """Run the 11-step startup validation, then yield for serving.""" +async def _run_startup(app: FastAPI) -> None: + """Run the ARCH-057 11-step validation and assemble application state. + + Raises StartupValidationError if a hard step fails. The two callers decide + how that failure is surfaced: main() (the container path) logs it and exits + cleanly, with no ASGI and no traceback (BUG-025, NFR-009); the ASGI lifespan + re-raises SystemExit for the in-process/TestClient path. + """ start_time = time.monotonic() configure_structlog() @@ -498,16 +505,14 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: try: settings = VektraSettings() except ValidationError as exc: - err = StartupValidationError( + raise StartupValidationError( step="config_validation", detail=str(exc), remediation=( "Set all required environment variables. At minimum: " "VEKTRA_LLM_PROVIDER (e.g., 'ollama/llama3' or 'openai/gpt-4o')." ), - ) - log.error("startup_failed", error=err.to_plain_text()) - raise SystemExit(1) from exc + ) from exc # Initialize database engine (needed by steps 2-5) init_db(settings.database_url) @@ -537,15 +542,13 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: step_1_ms = int((time.monotonic() - start_time) * 1000) log.info("startup_step_complete", step="config_validation", duration_ms=step_1_ms) + # A failed hard step raises StartupValidationError, which propagates to the + # caller; the step's own startup_step_complete line is then skipped. for step_name, step_fn in steps: step_start = time.monotonic() - try: - await step_fn() - duration_ms = int((time.monotonic() - step_start) * 1000) - log.info("startup_step_complete", step=step_name, duration_ms=duration_ms) - except StartupValidationError as exc: - log.error("startup_failed", error=exc.to_plain_text()) - raise SystemExit(1) from exc + await step_fn() + duration_ms = int((time.monotonic() - step_start) * 1000) + log.info("startup_step_complete", step=step_name, duration_ms=duration_ms) total_ms = int((time.monotonic() - start_time) * 1000) log.info("startup_complete", total_duration_ms=total_ms) @@ -575,10 +578,11 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: app.state.learn_service = registry.get("learn", "default") app.state.learn_require_enrollment = settings.learn_require_enrollment - yield - # Shutdown +async def _run_shutdown(app: FastAPI) -> None: + """Best-effort teardown: close remote provider clients and the DB engine.""" log.info("shutdown_started") + registry: ProviderRegistry = app.state.registry # Close remote provider HTTP clients (TEI, FEAT-024) best-effort for category in ("embedding", "reranker"): try: @@ -598,6 +602,27 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: log.info("shutdown_complete") +@asynccontextmanager +async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: + """ASGI lifespan for in-process serving (tests, local `uvicorn ...:app`). + + The shipped container serves through main() (validate-before-serve, so a + misconfiguration never reaches uvicorn's ASGI machinery — BUG-025). This + path remains for TestClient and local runs: a failed step can only abort + ASGI startup by raising, and uvicorn logs that as a traceback, which is + acceptable here because it never runs in the container. + """ + try: + await _run_startup(app) + except StartupValidationError as exc: + log.error("startup_failed", error=exc.to_plain_text()) + raise SystemExit(1) from exc + try: + yield + finally: + await _run_shutdown(app) + + # --------------------------------------------------------------------------- # Middleware: correlation ID (ARCH-008) # --------------------------------------------------------------------------- @@ -779,3 +804,53 @@ def _get_cors_origins() -> list[str]: app = create_app() + + +# --------------------------------------------------------------------------- +# Container entrypoint: validate before serving (BUG-025, NFR-009) +# --------------------------------------------------------------------------- + + +async def _serve(app: FastAPI, server: uvicorn.Server) -> int: + """Validate, then serve, then tear down — all in one event loop. + + Returns the process exit code. A failed validation step logs its structured + error and returns 1 without ever starting the ASGI server, so uvicorn never + logs a traceback (BUG-025). Startup and serving share a single loop, so the + async resources built during validation (DB engine, HTTP clients) stay bound + to the loop that goes on to serve requests. + """ + try: + await _run_startup(app) + except StartupValidationError as exc: + log.error("startup_failed", error=exc.to_plain_text()) + return 1 + try: + await server.serve() + finally: + await _run_shutdown(app) + return 0 + + +def main() -> None: + """Run the ARCH-057 validation ahead of uvicorn, then serve. + + docker/entrypoint.sh invokes `python -m vektra_app.main`. Validating before + uvicorn.run() (rather than inside the ASGI lifespan) lets a failed step print + its structured [STARTUP ERROR] and exit non-zero with no traceback, which is + what NFR-009 asks for. `lifespan="off"` keeps uvicorn from also driving the + lifespan, so the sequence never runs twice. + """ + config = uvicorn.Config(app, host="0.0.0.0", port=8000, lifespan="off") + server = uvicorn.Server(config) + # Validation and serving share one loop, built from uvicorn's own factory so + # the server still gets uvloop (the CLI default) rather than plain asyncio. + # get_loop_factory() is uvicorn's supported hook for this since it dropped + # setup_event_loop() in 0.36. + raise SystemExit( + asyncio.run(_serve(app, server), loop_factory=config.get_loop_factory()) + ) + + +if __name__ == "__main__": + main()