diff --git a/CHANGELOG.md b/CHANGELOG.md index cd06778..4243115 100644 --- a/CHANGELOG.md +++ b/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+): diff --git a/example/gunicorn_flask/README.md b/example/gunicorn_flask/README.md new file mode 100644 index 0000000..6126158 --- /dev/null +++ b/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. diff --git a/example/gunicorn_flask/app.py b/example/gunicorn_flask/app.py new file mode 100644 index 0000000..87955a6 --- /dev/null +++ b/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" diff --git a/example/gunicorn_flask/gunicorn.conf.py b/example/gunicorn_flask/gunicorn.conf.py new file mode 100644 index 0000000..6f38d3e --- /dev/null +++ b/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" diff --git a/test-requirements.txt b/test-requirements.txt index bdcfb1c..d118997 100644 --- a/test-requirements.txt +++ b/test-requirements.txt @@ -6,6 +6,7 @@ sanic fastapi uvicorn requests +gunicorn httpx flake8 pytest diff --git a/tests/test_gunicorn_flask.py b/tests/test_gunicorn_flask.py new file mode 100644 index 0000000..14f03ee --- /dev/null +++ b/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