diff --git a/CHANGELOG.md b/CHANGELOG.md index 63a6554..cd06778 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,9 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/). - feat: `json_logging.EXCLUDED_FIELDS` omits the named fields from every JSON log record. Empty by default, so output is unchanged. Fixes #98 +- docs: FastAPI startup with Uvicorn, the double-initialisation error, and a tested example (`example/fastapi_startup`). + Fixes #106 + - fix: FastAPI application logs and `json_logging.get_correlation_id()` now use the request's correlation id instead of `-` in synchronous (`def`) endpoints (fixes #124, PR #123). When request instrumentation is enabled with `init_request_instrument(app)` (Python 3.9+): diff --git a/README.md b/README.md index f9f3ee2..64521b3 100644 --- a/README.md +++ b/README.md @@ -367,6 +367,13 @@ for reference implementations. - If you using flask, by default option **use_reloader** is set to **True** which will start 2 instances of web application. change it to False to disable this behaviour [\[3\]](#3-more-on-flask-use-reloader) +3. `RuntimeError: Can not call init more than once` with FastAPI. + + - The module that calls `init_fastapi()` ran twice, for example when it is started as a script and uvicorn + also imports it by an import string such as `"app.main:app"`. Start uvicorn with + `python -m uvicorn app.main:app`, or pass the app object to `uvicorn.run(app)`. See + [example/fastapi_startup](example/fastapi_startup/README.md). + # 7. References ## [0] Full logging format references diff --git a/example/fastapi_startup/README.md b/example/fastapi_startup/README.md new file mode 100644 index 0000000..b383e73 --- /dev/null +++ b/example/fastapi_startup/README.md @@ -0,0 +1,67 @@ +# FastAPI startup with json-logging + +`json_logging.init_fastapi()` can only run once per process. This example puts the app and its initialisation in one +module, `app/main.py`, and shows how to start it with uvicorn without importing that module twice. + +## Working patterns + +Run these from the `example/fastapi_startup` directory. + +1. **Import string, started by uvicorn (recommended):** + + ```bash + python -m uvicorn app.main:app --port 8000 + ``` + + uvicorn imports `app.main` once, so the module body runs once. Recommended because it also works with + `--reload` and `--workers` (see below). + +2. **Pass the app object** from a separate launcher, [`run.py`](run.py), that does not contain the app: + + ```python + import uvicorn + + from app.main import app + + if __name__ == "__main__": + uvicorn.run(app, host="127.0.0.1", port=8000) + ``` + + ```bash + python run.py + ``` + + uvicorn receives the app object, not an import string, so it does not import `app.main` again. + +## Reload and multiple workers + +- Use the import-string pattern (1) for `--reload` or `--workers N`. uvicorn needs an import string for both; with + an app object it logs "You must pass the application as an import string to enable 'reload' or 'workers'" and + exits. +- Passing the app object (2) suits a simple single-process start. +- With reload or several workers, each worker is its own process and imports `app.main` once, so + `init_fastapi()` runs once per worker process. That is expected. The error only occurs when the same process + initialises twice. + +## Pattern that fails + +```python +# app/main.py, executed directly +... +if __name__ == "__main__": + uvicorn.run("app.main:app") # imports app.main again, so init_fastapi() runs twice +``` + +This raises `RuntimeError: Can not call init more than once` (issue #106). The module runs once as `__main__` and +again as `app.main`. Either use one of the working patterns above, or keep the launch code out of the module that +creates the app. + +## Verify + +From this directory: + +```bash +python -m pytest ../../tests/test_fastapi_startup.py -q +``` + +or, from the repository root, `python -m pytest tests/test_fastapi_startup.py -q`. diff --git a/example/fastapi_startup/app/__init__.py b/example/fastapi_startup/app/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/example/fastapi_startup/app/main.py b/example/fastapi_startup/app/main.py new file mode 100644 index 0000000..e9db8f7 --- /dev/null +++ b/example/fastapi_startup/app/main.py @@ -0,0 +1,23 @@ +"""Module-level FastAPI setup. Create the app and call json_logging.init_* exactly once per process. + +Start it with either of the working patterns in example/fastapi_startup/README.md. Do not run this file as a +script (`python app/main.py`) while also passing an import string such as "app.main:app" to uvicorn. +""" +import logging + +import fastapi +import json_logging + +app = fastapi.FastAPI() +json_logging.init_fastapi(enable_json=True) +json_logging.init_request_instrument(app) + +logger = logging.getLogger("app") +logger.setLevel(logging.INFO) +logger.addHandler(logging.StreamHandler()) + + +@app.get("/") +def home(): + logger.info("handled request") + return {"correlation_id": json_logging.get_correlation_id()} diff --git a/example/fastapi_startup/run.py b/example/fastapi_startup/run.py new file mode 100644 index 0000000..8362e88 --- /dev/null +++ b/example/fastapi_startup/run.py @@ -0,0 +1,7 @@ +"""Launcher that passes the app object to uvicorn. The app and json-logging are set up in app/main.py, imported once.""" +import uvicorn + +from app.main import app + +if __name__ == "__main__": + uvicorn.run(app, host="127.0.0.1", port=8000) diff --git a/tests/test_fastapi_startup.py b/tests/test_fastapi_startup.py new file mode 100644 index 0000000..268141f --- /dev/null +++ b/tests/test_fastapi_startup.py @@ -0,0 +1,134 @@ +"""Startup patterns for FastAPI applications (issue #106). + +The documented working patterns must initialise json-logging exactly once. The pattern from the report, where a +module started as a script also passes an import string to uvicorn, must keep raising the same error. +""" +import os +import subprocess +import sys +import textwrap +from pathlib import Path + +import pytest + +ROOT = Path(__file__).resolve().parents[1] +EXAMPLE = ROOT / "example" / "fastapi_startup" + + +def _run(code, cwd, extra_path=()): + env = dict(os.environ, PYTHONWARNINGS="ignore") + env["PYTHONPATH"] = os.pathsep.join([str(ROOT), str(cwd), *map(str, extra_path)]) + return subprocess.run([sys.executable, "-c", textwrap.dedent(code)], cwd=cwd, env=env, + capture_output=True, text=True, timeout=60) + + +def test_import_string_pattern_loads_the_app_through_uvicorn_config_and_initialises_once(): + """`python -m uvicorn app.main:app` builds a uvicorn.Config from the import string and calls load(), which + imports app.main. Run that real Config.load() path, without starting a server, and check that the loaded + application is app.main.app and that init_fastapi() ran once.""" + result = _run(""" + import socket, sys + import json_logging, uvicorn + + init_calls = [] + real_init_fastapi = json_logging.init_fastapi + def counting_init_fastapi(*args, **kwargs): + init_calls.append(1) + return real_init_fastapi(*args, **kwargs) + json_logging.init_fastapi = counting_init_fastapi + + def no_bind(self, address): + raise AssertionError("Config.load() must not bind a socket: %r" % (address,)) + socket.socket.bind = no_bind + + config = uvicorn.Config("app.main:app") + config.load() + + app = config.loaded_app + while app is not sys.modules["app.main"].app and hasattr(app, "app"): + app = app.app # uvicorn wraps the application in its own ASGI middleware + assert app is sys.modules["app.main"].app, "uvicorn did not load app.main:app" + assert len(init_calls) == 1, "init_fastapi() ran %d times" % len(init_calls) + print("OK") + """, cwd=EXAMPLE) + assert result.returncode == 0, result.stdout + result.stderr + assert "OK" in result.stdout + + +LAUNCHER_CHECK = """ + import runpy, sys + import json_logging, uvicorn + + init_calls = [] + real_init_fastapi = json_logging.init_fastapi + def counting_init_fastapi(*args, **kwargs): + init_calls.append(1) + return real_init_fastapi(*args, **kwargs) + json_logging.init_fastapi = counting_init_fastapi + + run_calls = [] + uvicorn.run = lambda app, *args, **kwargs: run_calls.append(app) # record instead of serving + + runpy.run_path(%(launcher)r, run_name="__main__") + + assert len(run_calls) == 1, run_calls + assert not isinstance(run_calls[0], str), "uvicorn.run() got an import string: %%r" %% (run_calls[0],) + assert run_calls[0] is sys.modules["app.main"].app, "uvicorn.run() did not get the app object from app.main" + assert len(init_calls) == 1, "init_fastapi() ran %%d times" %% len(init_calls) + print("OK") +""" + + +def test_app_object_launcher_passes_the_app_to_uvicorn_and_initialises_once(): + """Runs example/fastapi_startup/run.py as `python run.py` would, with uvicorn.run() replaced by a recorder.""" + result = _run(LAUNCHER_CHECK % {"launcher": "run.py"}, cwd=EXAMPLE) + assert result.returncode == 0, result.stdout + result.stderr + assert "OK" in result.stdout + + +@pytest.mark.parametrize("launch", [ + 'import importlib, app.main\nimportlib.reload(app.main)\nuvicorn.run(app.main.app)', # initialises again + 'uvicorn.run("app.main:app")', # import string +]) +def test_launcher_check_detects_a_launcher_that_reimports_the_app(tmp_path, launch): + """Negative control: the check above must fail for launchers that do not follow the documented pattern.""" + launcher = tmp_path / "bad_run.py" + launcher.write_text("import uvicorn\nfrom app.main import app\nif __name__ == '__main__':\n" + + textwrap.indent(launch, " ") + "\n") + result = _run(LAUNCHER_CHECK % {"launcher": str(launcher)}, cwd=EXAMPLE) + assert result.returncode != 0 + assert "OK" not in result.stdout + + +def test_reported_pattern_still_raises_the_double_initialisation_error(tmp_path): + """Module run as a script, which also passes an import string to uvicorn, initialises twice.""" + (tmp_path / "app").mkdir() + (tmp_path / "app" / "__init__.py").write_text("") + (tmp_path / "app" / "main.py").write_text(textwrap.dedent(""" + import fastapi, json_logging + from uvicorn.importer import import_from_string + app = fastapi.FastAPI() + json_logging.init_fastapi(enable_json=True) + json_logging.init_request_instrument(app) + if __name__ == "__main__": + import_from_string("app.main:app") # imports this module a second time + """)) + result = _run("import runpy; runpy.run_path('app/main.py', run_name='__main__')", cwd=tmp_path) + assert result.returncode != 0 + assert "RuntimeError: Can not call init more than once" in result.stderr + + +def test_second_initialisation_in_one_process_still_raises(): + result = _run(""" + import json_logging + json_logging.init_fastapi(enable_json=True) + try: + json_logging.init_fastapi(enable_json=True) + except RuntimeError as exc: + assert "Can not call init more than once" in str(exc) + print("RAISED") + else: + raise AssertionError("Expected duplicate initialization to raise RuntimeError") + """, cwd=EXAMPLE) + assert result.returncode == 0, result.stderr + assert "RAISED" in result.stdout