docs: Explain FastAPI double initialization with Uvicorn Closes #106 (documentation)

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+):

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

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`.

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()}

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)

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