From f1e3953c3194c8d3a4223c4f54cfe6e1acc34e3f Mon Sep 17 00:00:00 2001 From: uditagrawal Date: Mon, 19 Oct 2026 20:40:38 -0700 Subject: [PATCH 1/4] docs: clarify FastAPI initialisation and Uvicorn startup json_logging.init_fastapi() can run only once per process. The reported RuntimeError ("Can not call init more than once") occurs when a module is started as a script and uvicorn also imports it through an import string, so the module body runs twice. Adds example/fastapi_startup, a small app with a README that documents the two working launch patterns (python -m uvicorn app.main:app, and passing the app object to uvicorn.run) and the pattern that fails, plus a FAQ entry. tests/test_fastapi_startup.py checks that both working patterns initialise once, and that the reported pattern and a second init in one process still raise the same error. No library code changes; the protection against double initialisation is kept as it is. Fixes #106 --- CHANGELOG.md | 3 + README.md | 7 +++ example/fastapi_startup/README.md | 50 ++++++++++++++++ example/fastapi_startup/app/__init__.py | 0 example/fastapi_startup/app/main.py | 23 ++++++++ tests/test_fastapi_startup.py | 77 +++++++++++++++++++++++++ 6 files changed, 160 insertions(+) create mode 100644 example/fastapi_startup/README.md create mode 100644 example/fastapi_startup/app/__init__.py create mode 100644 example/fastapi_startup/app/main.py create mode 100644 tests/test_fastapi_startup.py 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..baaf4c8 --- /dev/null +++ b/example/fastapi_startup/README.md @@ -0,0 +1,50 @@ +# 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. + +2. **Pass the app object:** + + ```python + # run.py, a separate launcher that does not contain the app + import uvicorn + from app.main import app + + if __name__ == "__main__": + uvicorn.run(app, host="127.0.0.1", port=8000) + ``` + + ```bash + python run.py + ``` + +## 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 + +```bash +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/tests/test_fastapi_startup.py b/tests/test_fastapi_startup.py new file mode 100644 index 0000000..22dfba5 --- /dev/null +++ b/tests/test_fastapi_startup.py @@ -0,0 +1,77 @@ +"""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_example_app_is_importable_and_initialises_once(): + result = _run(""" + import importlib + main = importlib.import_module("app.main") + from uvicorn.importer import import_from_string + assert import_from_string("app.main:app") is main.app # what `uvicorn app.main:app` does + print("OK") + """, cwd=EXAMPLE) + assert result.returncode == 0, result.stderr + assert "OK" in result.stdout + + +def test_app_object_pattern_initialises_once_without_serving(): + result = _run(""" + from app.main import app + import json_logging + assert app is not None and json_logging.get_correlation_id() == json_logging.EMPTY_VALUE + print("OK") + """, cwd=EXAMPLE) + assert result.returncode == 0, result.stderr + assert "OK" 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") + """, cwd=EXAMPLE) + assert result.returncode == 0, result.stderr + assert "RAISED" in result.stdout From 19e2639214de8cb4971dc4d2b770298fd9822cd2 Mon Sep 17 00:00:00 2001 From: uditagrawal Date: Mon, 19 Oct 2026 21:55:37 -0700 Subject: [PATCH 2/4] test: fail explicitly when duplicate FastAPI initialisation succeeds The second-initialisation test only asserted that the subprocess printed a marker, so a failure reported only a missing marker. Add an explicit else branch that raises AssertionError with the expected outcome. Verified both ways: with the guard intact the four startup tests pass; with the guard removed in a copy, the test fails with the new message. --- tests/test_fastapi_startup.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/test_fastapi_startup.py b/tests/test_fastapi_startup.py index 22dfba5..45572d4 100644 --- a/tests/test_fastapi_startup.py +++ b/tests/test_fastapi_startup.py @@ -72,6 +72,8 @@ def test_second_initialisation_in_one_process_still_raises(): 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 From f4c04b5ba893ce59559ea91906357193a69e831c Mon Sep 17 00:00:00 2001 From: uditagrawal Date: Mon, 19 Oct 2026 22:43:55 -0700 Subject: [PATCH 3/4] test: run the FastAPI app-object launcher instead of only importing the app The previous test imported app.main and never exercised the documented uvicorn.run(app) launcher. Add example/fastapi_startup/run.py, the launcher the README already described, and run it as __main__ with uvicorn.run() replaced by a recorder. The test checks that uvicorn.run() gets the app object from app.main, not an import string, and that init_fastapi() runs once. Negative controls confirm the check fails for a launcher that reloads the app module or passes an import string. --- example/fastapi_startup/README.md | 6 ++-- example/fastapi_startup/run.py | 7 +++++ tests/test_fastapi_startup.py | 50 ++++++++++++++++++++++++++----- 3 files changed, 53 insertions(+), 10 deletions(-) create mode 100644 example/fastapi_startup/run.py diff --git a/example/fastapi_startup/README.md b/example/fastapi_startup/README.md index baaf4c8..3678460 100644 --- a/example/fastapi_startup/README.md +++ b/example/fastapi_startup/README.md @@ -15,11 +15,11 @@ Run these from the `example/fastapi_startup` directory. uvicorn imports `app.main` once, so the module body runs once. -2. **Pass the app object:** +2. **Pass the app object** from a separate launcher, [`run.py`](run.py), that does not contain the app: ```python - # run.py, a separate launcher that does not contain the app import uvicorn + from app.main import app if __name__ == "__main__": @@ -30,6 +30,8 @@ Run these from the `example/fastapi_startup` directory. python run.py ``` + uvicorn receives the app object, not an import string, so it does not import `app.main` again. + ## Pattern that fails ```python 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 index 45572d4..7240a2f 100644 --- a/tests/test_fastapi_startup.py +++ b/tests/test_fastapi_startup.py @@ -34,17 +34,51 @@ def test_example_app_is_importable_and_initialises_once(): assert "OK" in result.stdout -def test_app_object_pattern_initialises_once_without_serving(): - result = _run(""" - from app.main import app - import json_logging - assert app is not None and json_logging.get_correlation_id() == json_logging.EMPTY_VALUE - print("OK") - """, cwd=EXAMPLE) - assert result.returncode == 0, result.stderr +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() From fd1f35f43cf64a23d92c7806af7a7ad92ed63786 Mon Sep 17 00:00:00 2001 From: uditagrawal Date: Tue, 20 Oct 2026 17:09:21 -0700 Subject: [PATCH 4/4] docs: fix the FastAPI example's test command; test uvicorn.Config loading - The example README says to run commands from example/fastapi_startup but gave a repository-root test path, which finds no tests there. Use ../../tests/test_fastapi_startup.py, and mention the root-relative form. - Document reload and multiple workers: uvicorn requires the import-string pattern for both (an app object exits with an error), the app-object pattern suits a single process, and init_fastapi() running once per worker process is expected. - Replace the import_from_string() check with the real uvicorn.Config(...).load() path that 'python -m uvicorn app.main:app' uses. The test checks the loaded app is app.main.app, that init_fastapi() ran once, and that no socket is bound. --- example/fastapi_startup/README.md | 19 ++++++++++++++++-- tests/test_fastapi_startup.py | 33 +++++++++++++++++++++++++------ 2 files changed, 44 insertions(+), 8 deletions(-) diff --git a/example/fastapi_startup/README.md b/example/fastapi_startup/README.md index 3678460..b383e73 100644 --- a/example/fastapi_startup/README.md +++ b/example/fastapi_startup/README.md @@ -13,7 +13,8 @@ Run these from the `example/fastapi_startup` directory. python -m uvicorn app.main:app --port 8000 ``` - uvicorn imports `app.main` once, so the module body runs once. + 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: @@ -32,6 +33,16 @@ Run these from the `example/fastapi_startup` directory. 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 @@ -47,6 +58,10 @@ creates the app. ## Verify +From this directory: + ```bash -python -m pytest tests/test_fastapi_startup.py -q +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/tests/test_fastapi_startup.py b/tests/test_fastapi_startup.py index 7240a2f..268141f 100644 --- a/tests/test_fastapi_startup.py +++ b/tests/test_fastapi_startup.py @@ -22,15 +22,36 @@ def _run(code, cwd, extra_path=()): capture_output=True, text=True, timeout=60) -def test_example_app_is_importable_and_initialises_once(): +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 importlib - main = importlib.import_module("app.main") - from uvicorn.importer import import_from_string - assert import_from_string("app.main:app") is main.app # what `uvicorn app.main:app` does + 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.stderr + assert result.returncode == 0, result.stdout + result.stderr assert "OK" in result.stdout