From adb19c2c6232edcc2b91abc8b94db20383356d75 Mon Sep 17 00:00:00 2001 From: Francesco Vadicamo Date: Wed, 15 Jul 2026 00:22:49 +0000 Subject: [PATCH 1/3] fix(startup): validate before serving so a failed step exits without a traceback BUG-025: the ARCH-057 sequence ran inside the ASGI lifespan, so a failed step's `raise SystemExit(1)` travelled out into uvicorn, which logged a raw Python traceback next to the structured [STARTUP ERROR]. NFR-009 asks for the remediable message instead of the stack dump, and it applied to all 11 steps. Move the sequence into a loop-agnostic `_run_startup()` and add a `main()` container entrypoint (`python -m vektra_app.main`) that runs validation in the very loop that will serve, then calls uvicorn with `lifespan="off"`. A failed step now logs its [STARTUP ERROR] and exits non-zero with no ASGI involvement and no traceback; startup and serving share one event loop, so async resources built during validation stay bound to the loop that serves requests. The ASGI lifespan keeps validating (and raising SystemExit) for the in-process /TestClient path, so `test_missing_llm_provider_aborts_startup` is unchanged. Remove the now-passing `xfail(strict=True)` on `test_no_raw_traceback_on_startup_failure`. Proven on the container: a config-validation failure and a database_connectivity failure each emit the structured error, exit 1, and log no traceback; a valid config still reaches `startup_complete` and serves. Traceability: REQ-011, NFR-009, ARCH-057, DEBT-031 (found by), BUG-024 (same surface) Co-Authored-By: Claude Opus 4.8 (1M context) --- docker/entrypoint.sh | 8 ++- tests/test_startup.py | 20 ++---- vektra-app/README.md | 12 +++- vektra-app/src/vektra_app/main.py | 107 +++++++++++++++++++++++++----- 4 files changed, 114 insertions(+), 33 deletions(-) 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() From f4363fa05dc05f5728de5c20cd943160b4d40495 Mon Sep 17 00:00:00 2001 From: Francesco Vadicamo Date: Wed, 15 Jul 2026 00:41:24 +0000 Subject: [PATCH 2/3] docs(backlog): mark BUG-025 done with resolution Records the validate-before-serving fix (PR #111): the ARCH-057 sequence now runs in main() ahead of uvicorn (lifespan="off") so a failed step exits with its structured [STARTUP ERROR] and no traceback; the lifespan keeps the SystemExit path for the in-process test. Notes the uvicorn 0.36 get_loop_factory() gotcha found on the container, and the on-container proof. Co-Authored-By: Claude Opus 4.8 (1M context) --- .s2s/BACKLOG.md | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) 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) From 12ba845822fd26fde88a2e5f961d78a7e325250e Mon Sep 17 00:00:00 2001 From: Francesco Vadicamo Date: Wed, 15 Jul 2026 01:05:05 +0000 Subject: [PATCH 3/3] docs(changelog): record the BUG-025 startup traceback fix Adds an Unreleased > Fixed entry for the validate-before-serving change, matching the manually maintained Keep a Changelog convention. The existing config (min_length) entry noted BUG-025 as "filed, not fixed here"; this records the fix. Co-Authored-By: Claude Opus 4.8 (1M context) --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) 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.