docs: add tested Gunicorn and Flask integration example

CHANGELOG.md

@@ -23,6 +23,9 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/).
 - docs: FastAPI startup with Uvicorn, the double-initialisation error, and a tested example (`example/fastapi_startup`).
   Fixes #106
 
+- docs: tested Gunicorn and Flask example (`example/gunicorn_flask`) covering worker initialisation, request
+  instrumentation, JSON output, and the Gunicorn access log. Fixes #25
+
 - 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+):

example/gunicorn_flask/README.md

@@ -0,0 +1,85 @@
+# Flask under Gunicorn with json-logging
+
+`app.py` initialises json-logging once per Gunicorn worker process, at import time, and enables request
+instrumentation. `gunicorn.conf.py` turns off Gunicorn's own access log, because json-logging already writes one JSON
+request record per request.
+
+## Run
+
+```bash
+cd example/gunicorn_flask
+gunicorn -c gunicorn.conf.py app:app
+curl -H "X-Correlation-ID: demo-1" http://127.0.0.1:8000/
+```
+
+## What you should see
+
+The output mixes plain text and JSON. Gunicorn's master process never runs json-logging; each worker initialises it
+when it imports `app.py`.
+
+| Output | Stream | Format | Notes |
+|---|---|---|---|
+| Gunicorn master and boot messages (`Starting gunicorn`, `Listening at`, `Booting worker`) | stderr | plain text | written by the master, or by a worker before it has initialised json-logging |
+| `json_logging` "Update all existing logger" line, once per worker | stdout | JSON | appears when JSON is enabled and the root logger has no handlers; harmless |
+| `worker ready` application log, once per worker | stderr | JSON | logged outside any request, so `correlation_id` is `-` |
+| application logs during a request (`logger: "app"`) | stderr | JSON | `correlation_id` is the request's ID (see below) |
+| request records (`type: "request"`) | stdout | JSON | json-logging's request instrumentation; same `correlation_id` as that request's application logs |
+| `gunicorn.error` records written by a worker, such as `Worker exiting` | stderr | JSON | outside any request, so `correlation_id` is `-` |
+
+## Correlation IDs
+
+- A request that sends `X-Correlation-ID` keeps that value in every application and request log it produces. If that
+  header is absent, `X-Request-ID` is used (`json_logging.CORRELATION_ID_HEADERS` sets the order).
+- A request without either header gets one generated ID, shared by its application and request logs. Different
+  requests get different IDs.
+- Logs written outside a request, such as worker startup and shutdown, get `-` (`json_logging.EMPTY_VALUE`).
+
+## Gunicorn access and error logs
+
+| Setting | Effect |
+|---|---|
+| `accesslog = None` (this example, and Gunicorn's default) | no Gunicorn access log |
+| `accesslog = "-"` or `--access-logfile -` | Gunicorn access log on **stdout** |
+| `accesslog = "/path/access.log"` | Gunicorn access log in that file |
+| `errorlog = "-"` (this example) | Gunicorn error log on **stderr** |
+
+Removing `accesslog = None` does not turn the access log on; you must set a destination. Gunicorn's access log is
+separate from json-logging's request instrumentation, so with both enabled each HTTP request produces two access
+records: Gunicorn's line (in a worker, wrapped in a JSON record with `"logger": "gunicorn.access"`) and json-logging's
+request record. Keep Gunicorn's access log off unless you need its format as well.
+
+## Scope: worker class, preload and custom logging configuration
+
+This example and its tests use Gunicorn's default **sync** worker, Gunicorn's built-in logging setup, and the default
+startup in which each worker imports `app.py` after it forks.
+
+- **gevent and other worker classes** (issue #25 uses `worker_class = "gevent"`) are not exercised by these tests.
+- **`--preload`** (`preload_app = True`) imports `app.py` once in the master before forking, so json-logging is
+  initialised in the master and the workers inherit it. This is not tested here either.
+- **A custom `logconfig` / `logging.conf`** changes which handlers exist and where they write. When `init_flask()`
+  runs in a worker, it replaces the formatter of every handler on every named logger that exists at that moment,
+  including `gunicorn.error`, `gunicorn.access` and loggers from your `logging.conf`, so custom formats on those
+  handlers become JSON. Handlers on the **root** logger are not changed unless you also call
+  `json_logging.config_root_logger()` after the logging configuration has been applied.
+
+To adapt the example to an existing setup such as the one in issue #25, keep its two essentials: call
+`json_logging.init_flask(enable_json=True)` and `json_logging.init_request_instrument(app)` in the module the workers
+import, and either turn Gunicorn's access log off or accept the duplicate records. Then check the output of your own
+configuration (worker class, `logconfig`, root handlers) the way `tests/test_gunicorn_flask.py` does.
+
+`/ready` is a readiness probe. It is excluded from request logging, so probing it adds no records.
+
+## Tests
+
+`tests/test_gunicorn_flask.py` starts this example with real Gunicorn on a Unix socket, waits until `/ready` answers,
+sends requests with `X-Correlation-ID`, with `X-Request-ID` and with no header, stops the server, and checks the
+output:
+
+- **one worker:** application and request records carry each request's ID, the `worker ready` and `Worker exiting`
+  records are JSON with `-`, `/ready` is not request-logged, and there is no Gunicorn access line;
+- **two workers** (the configured count): both workers boot, log `worker ready` with their own PID, and exit with a
+  JSON `Worker exiting` record; each request's ID is checked whichever worker served it;
+- **access log enabled** (`--access-logfile -`): the access-line detector finds Gunicorn's lines, so the "no access
+  line" check above is meaningful.
+
+In CI (`CI=true`) a missing `gunicorn` fails the tests; elsewhere they are skipped.

example/gunicorn_flask/app.py

@@ -0,0 +1,28 @@
+"""Flask application for Gunicorn. json-logging is initialised at import time, once per worker process."""
+import logging
+import os
+
+import flask
+import json_logging
+
+app = flask.Flask(__name__)
+json_logging.init_flask(enable_json=True)
+# /ready is a readiness probe: it is excluded from request logging so that probing never adds records.
+json_logging.init_request_instrument(app, exclude_url_patterns=[r"^/ready$"])
+
+logger = logging.getLogger("app")
+logger.setLevel(logging.INFO)
+logger.addHandler(logging.StreamHandler())
+# Logged outside any request, so its correlation_id is json_logging.EMPTY_VALUE ("-"). One per worker process.
+logger.info("worker ready", extra={"props": {"pid": os.getpid()}})
+
+
+@app.route("/")
+def home():
+    logger.info("handled request")
+    return {"correlation_id": json_logging.get_correlation_id()}
+
+
+@app.route("/ready")
+def ready():
+    return "ok"

example/gunicorn_flask/gunicorn.conf.py

@@ -0,0 +1,13 @@
+"""Gunicorn settings for the json-logging example.
+
+Request instrumentation already writes one JSON request record per request, so Gunicorn's own access log is turned
+off to avoid duplicate access lines (accesslog = "-" would write it to stdout). errorlog = "-" writes Gunicorn's
+error log to stderr; its records are JSON only in the workers, after json-logging is initialised.
+"""
+import os
+
+bind = os.environ.get("GUNICORN_BIND", "127.0.0.1:8000")
+workers = 2
+accesslog = None
+errorlog = "-"
+loglevel = "info"

test-requirements.txt

@@ -6,6 +6,7 @@ sanic
 fastapi
 uvicorn
 requests
+gunicorn
 httpx
 flake8
 pytest

tests/test_gunicorn_flask.py

@@ -0,0 +1,213 @@
+"""Flask under a real Gunicorn worker (issue #25).
+
+Starts example/gunicorn_flask on a Unix socket, waits until the worker answers HTTP, sends requests, stops the server,
+and checks the records written to stdout and stderr.
+
+Gunicorn is required in CI (the CI environment variable is set by GitHub Actions): a missing install fails the test
+instead of skipping it. Elsewhere the test is skipped when gunicorn or httpx is not installed.
+"""
+import importlib
+import json
+import os
+import re
+import subprocess
+import sys
+import tempfile
+import time
+from pathlib import Path
+
+import pytest
+
+IN_CI = os.environ.get("CI") == "true"
+if IN_CI:
+    importlib.import_module("gunicorn")  # fail, do not skip, if the CI install is missing gunicorn
+    httpx = importlib.import_module("httpx")
+else:
+    pytest.importorskip("gunicorn")
+    httpx = pytest.importorskip("httpx")
+
+from gunicorn.config import Config as GunicornConfig  # noqa: E402  (after the import guard above)
+
+ROOT = Path(__file__).resolve().parents[1]
+EXAMPLE = ROOT / "example" / "gunicorn_flask"
+STARTUP_TIMEOUT = 30.0      # seconds, monotonic clock
+REQUEST_TIMEOUT = 2.0       # seconds per HTTP attempt
+STOP_TIMEOUT = 20.0         # seconds for gunicorn to exit after SIGTERM
+EMPTY_VALUE = "-"           # json_logging.EMPTY_VALUE; json_logging is not imported in this process
+
+# The request line and status of Gunicorn's access log format ('"GET / HTTP/1.1" 200'). Matches the plain-text line
+# and the same text inside a JSON record, where the quotes are escaped. json-logging's own request records keep the
+# method, path and status in separate fields, so they do not match.
+ACCESS_LOG_LINE = re.compile(r'\\?"(?:GET|HEAD|POST|PUT|PATCH|DELETE|OPTIONS) /\S* HTTP/\d(?:\.\d)?\\?" \d{3}\b')
+
+
+def _json_records(text):
+    """Every line that starts with '{' must be a valid JSON record. Gunicorn's own plain-text lines are skipped."""
+    return [json.loads(line) for line in text.splitlines() if line.startswith("{")]
+
+
+def _access_log_lines(text):
+    """Gunicorn access-log lines in the raw output, in plain text or JSON form."""
+    return [line for line in text.splitlines() if ACCESS_LOG_LINE.search(line)]
+
+
+def _wait_until_ready(process, socket_path, log_path):
+    """Poll the worker over HTTP until /ready answers 200, with a fixed monotonic deadline."""
+    deadline = time.monotonic() + STARTUP_TIMEOUT
+    last_error = None
+    with httpx.Client(transport=httpx.HTTPTransport(uds=str(socket_path)), base_url="http://localhost",
+                      timeout=REQUEST_TIMEOUT) as client:
+        while time.monotonic() < deadline:
+            if process.poll() is not None:
+                raise AssertionError("gunicorn exited during startup with code %s:\n%s"
+                                     % (process.returncode, log_path.read_text()))
+            if socket_path.exists():
+                try:
+                    if client.get("/ready").status_code == 200:
+                        return
+                except httpx.TransportError as exc:
+                    last_error = exc
+            time.sleep(0.1)
+    raise AssertionError("gunicorn did not answer /ready within %.0fs (last error: %r)\n%s"
+                         % (STARTUP_TIMEOUT, last_error, log_path.read_text()))
+
+
+def _stop(process):
+    process.terminate()
+    try:
+        process.wait(timeout=STOP_TIMEOUT)
+    except subprocess.TimeoutExpired:
+        process.kill()
+        process.wait()
+
+
+def _assert_workers_exited(output):
+    for pid in re.findall(r"Booting worker with pid: (\d+)", output):
+        try:
+            os.kill(int(pid), 0)
+        except ProcessLookupError:
+            continue
+        raise AssertionError("gunicorn worker %s is still running after shutdown" % pid)
+
+
+def _wait_for_ready_workers(process, log_path, count):
+    """Wait until `count` workers have logged their startup record. /ready answering only proves that one worker
+    is up; with several workers the others may still be importing the app."""
+    deadline = time.monotonic() + STARTUP_TIMEOUT
+    while time.monotonic() < deadline:
+        if process.poll() is not None:
+            raise AssertionError("gunicorn exited during startup with code %s:\n%s"
+                                 % (process.returncode, log_path.read_text()))
+        if len(_worker_ready_records(log_path.read_text())) >= count:
+            return
+        time.sleep(0.1)
+    raise AssertionError("%d gunicorn workers did not start within %.0fs\n%s"
+                         % (count, STARTUP_TIMEOUT, log_path.read_text()))
+
+
+def _worker_ready_records(text):
+    # Only complete lines: the log file may be read while a worker is still writing a record.
+    lines = [line for line in text.splitlines(keepends=True) if line.endswith("\n")]
+    return [r for r in _json_records("".join(lines)) if r.get("logger") == "app" and r.get("msg") == "worker ready"]
+
+
+def _run_example(extra_args=(), workers=1):
+    """Serve the example with `workers` worker processes, send three requests (X-Correlation-ID, X-Request-ID, no
+    header), and stop the server.
+
+    Returns (responses keyed "supplied", "request_id" and "generated", raw output). A short directory is used
+    because macOS limits Unix socket paths to about 104 bytes, which pytest's tmp_path can exceed.
+    """
+    with tempfile.TemporaryDirectory(prefix="gu", dir="/tmp") as tmp:
+        tmp_path = Path(tmp)
+        socket_path = tmp_path / "gunicorn.sock"
+        log_path = tmp_path / "gunicorn.log"
+        args = ["--workers", str(workers)]
+        if "control_socket" in GunicornConfig().settings:   # Gunicorn 25+: keep its control socket out of $HOME
+            args += ["--control-socket", str(tmp_path / "gunicorn.ctl")]
+        env = dict(os.environ, PYTHONWARNINGS="ignore", GUNICORN_BIND="unix:" + str(socket_path))
+        env["PYTHONPATH"] = os.pathsep.join([str(ROOT), str(EXAMPLE), os.environ.get("PYTHONPATH", "")])
+        with open(log_path, "w") as log_file:   # a file rather than a pipe: no deadlock when output is large
+            process = subprocess.Popen(
+                [sys.executable, "-m", "gunicorn", "-c", str(EXAMPLE / "gunicorn.conf.py")] + args
+                + list(extra_args) + ["app:app"],
+                cwd=str(EXAMPLE), env=env, stdout=log_file, stderr=subprocess.STDOUT)
+        try:
+            _wait_until_ready(process, socket_path, log_path)
+            _wait_for_ready_workers(process, log_path, workers)
+            with httpx.Client(transport=httpx.HTTPTransport(uds=str(socket_path)), base_url="http://localhost",
+                              timeout=REQUEST_TIMEOUT) as client:
+                responses = {
+                    "supplied": client.get("/", headers={"X-Correlation-ID": "gunicorn-1"}),
+                    "request_id": client.get("/", headers={"X-Request-ID": "gunicorn-req-2"}),
+                    "generated": client.get("/"),
+                }
+        finally:
+            _stop(process)
+        output = log_path.read_text()
+    assert process.returncode is not None
+    _assert_workers_exited(output)
+    return responses, output
+
+
+def _assert_requests_correlate(responses, records):
+    """Each request's response, application log and request record carry the same correlation ID, whichever worker
+    handled it. Returns the generated ID."""
+    assert all(r.status_code == 200 for r in responses.values())
+    ids = {name: r.json()["correlation_id"] for name, r in responses.items()}
+    assert ids["supplied"] == "gunicorn-1"
+    assert ids["request_id"] == "gunicorn-req-2"
+    assert ids["generated"] not in (EMPTY_VALUE, "gunicorn-1", "gunicorn-req-2")
+    handled = [r["correlation_id"] for r in records if r.get("logger") == "app" and r.get("msg") == "handled request"]
+    request_records = [r for r in records if r.get("type") == "request"]
+    assert handled == list(ids.values())
+    # Only the "/" requests are logged: the /ready probes are excluded from request instrumentation.
+    assert [(r["request"], r["correlation_id"]) for r in request_records] == [("/", i) for i in ids.values()]
+    return ids["generated"]
+
+
+def _assert_worker_lifecycle(output, records, workers):
+    """Every booted worker logged its startup record outside a request and a JSON 'Worker exiting' record, both with
+    the empty correlation ID."""
+    booted = sorted(int(pid) for pid in re.findall(r"Booting worker with pid: (\d+)", output))
+    assert len(booted) == workers and len(set(booted)) == workers, output
+    ready = [r for r in records if r.get("logger") == "app" and r.get("msg") == "worker ready"]
+    assert sorted(r["pid"] for r in ready) == booted, output
+    assert {r["correlation_id"] for r in ready} == {EMPTY_VALUE}, output
+    exiting = [r for r in records if r.get("logger") == "gunicorn.error" and r["msg"].startswith("Worker exiting")]
+    assert sorted(int(re.search(r"pid: (\d+)", r["msg"]).group(1)) for r in exiting) == booted, output
+    assert {r["correlation_id"] for r in exiting} == {EMPTY_VALUE}, output
+
+
+def test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_id():
+    responses, output = _run_example()
+    records = _json_records(output)
+
+    _assert_requests_correlate(responses, records)
+    _assert_worker_lifecycle(output, records, workers=1)
+    # accesslog = None in gunicorn.conf.py: no Gunicorn access line, in plain text or JSON, for any request.
+    assert _access_log_lines(output) == [], output
+    assert not [r for r in records if r.get("logger") == "gunicorn.access"], output
+
+
+def test_two_workers_start_log_and_exit_cleanly():
+    """The example's configured worker count. Which worker serves a request is up to Gunicorn, so request checks are
+    per request; the lifecycle checks are per worker."""
+    responses, output = _run_example(workers=2)
+    records = _json_records(output)
+
+    _assert_worker_lifecycle(output, records, workers=2)
+    _assert_requests_correlate(responses, records)
+    assert _access_log_lines(output) == [], output
+
+
+def test_access_log_detector_finds_lines_when_gunicorn_access_logging_is_enabled():
+    """Negative control: with Gunicorn's access log turned on, the detector above must report the extra lines."""
+    responses, output = _run_example(["--access-logfile", "-"])
+
+    assert all(r.status_code == 200 for r in responses.values())
+    access_lines = _access_log_lines(output)
+    assert len([line for line in access_lines if "GET / HTTP/1.1" in line]) == 3, output
+    assert [line for line in access_lines if "GET /ready HTTP/1.1" in line], output    # Gunicorn logs probes too
+    # json-logging still writes its own request records, so each "/" request now has two access records.
+    assert len([r for r in _json_records(output) if r.get("type") == "request"]) == 3, output