From 79057249f5b2cbb832ee56608510783b6cde5b5a Mon Sep 17 00:00:00 2001 From: uditagrawal Date: Mon, 19 Oct 2026 20:43:50 -0700 Subject: [PATCH 1/4] docs: add tested Gunicorn and Flask integration example Adds example/gunicorn_flask (a Flask app plus a gunicorn.conf.py) and a README that explains what each output looks like: master-process messages stay plain text, workers emit JSON application and request logs, Gunicorn's access log is disabled to avoid a duplicate line per request, and records outside a request carry '-' once #125 is merged. tests/test_gunicorn_flask.py starts the example with a real Gunicorn worker on a Unix socket, sends a supplied-ID request and a generated-ID request, and checks that application and request records carry the same IDs and that no gunicorn.access JSON line is written. gunicorn is added to test-requirements.txt for this test; it is skipped when gunicorn is not installed. Local status: the sandbox this change was prepared in refuses Gunicorn's socket connection (EPERM), so the automated test was not run to completion there. The launch and record layout were verified manually earlier. Fixes #25 --- CHANGELOG.md | 3 ++ example/gunicorn_flask/README.md | 48 ++++++++++++++++++ example/gunicorn_flask/app.py | 19 +++++++ example/gunicorn_flask/gunicorn.conf.py | 12 +++++ test-requirements.txt | 1 + tests/test_gunicorn_flask.py | 67 +++++++++++++++++++++++++ 6 files changed, 150 insertions(+) create mode 100644 example/gunicorn_flask/README.md create mode 100644 example/gunicorn_flask/app.py create mode 100644 example/gunicorn_flask/gunicorn.conf.py create mode 100644 tests/test_gunicorn_flask.py 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..1257ad9 --- /dev/null +++ b/example/gunicorn_flask/README.md @@ -0,0 +1,48 @@ +# 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 + +| Output | Format | Notes | +|---|---|---| +| Gunicorn startup and master messages (`Starting gunicorn`, `Listening at`, `Booting worker`) | plain text | json-logging does not run in the master process, so these stay plain text | +| `json_logging` "Update all existing logger" lines at worker start | JSON | emitted when each worker initialises; harmless | +| application logs (`logger: "app"`) | JSON | `correlation_id` is the request's `X-Correlation-ID`, or a generated ID | +| request records (`type: "request"`) | JSON | same `correlation_id` as the application logs of that request | +| `gunicorn.error` records, such as `Worker exiting` | JSON in workers | `correlation_id` is `-`: they are outside any request | + +## Correlation across requests + +- A request that sends `X-Correlation-ID` (or `X-Request-ID`) keeps that value in every application and request log + it produces. +- A request without a 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 `-`. This needs the fix for #125; before + that fix, each such record got a random ID. + +## Gunicorn access log + +`accesslog = None` in `gunicorn.conf.py` avoids a second access line per request. If you prefer Gunicorn's access +log, remove that line, and remember that you then get two records per request. + +## Local test + +`tests/test_gunicorn_flask.py` starts this example on a Unix socket, sends two requests, and checks the JSON output +above. It is skipped if `gunicorn` is not installed. + +## Verification status + +- The launch command and the record layout above were checked against a real Gunicorn 26.2.0 worker over a Unix socket + (saved in `audit/logs/gunicorn-flask-successful-run-2026-10-19.log`). +- The automated test runs in CI on Linux. Recorded status: see the pull request. diff --git a/example/gunicorn_flask/app.py b/example/gunicorn_flask/app.py new file mode 100644 index 0000000..82b821f --- /dev/null +++ b/example/gunicorn_flask/app.py @@ -0,0 +1,19 @@ +"""Flask application for Gunicorn. json-logging is initialised at import time, once per worker process.""" +import logging + +import flask +import json_logging + +app = flask.Flask(__name__) +json_logging.init_flask(enable_json=True) +json_logging.init_request_instrument(app) + +logger = logging.getLogger("app") +logger.setLevel(logging.INFO) +logger.addHandler(logging.StreamHandler()) + + +@app.route("/") +def home(): + logger.info("handled request") + return {"correlation_id": json_logging.get_correlation_id()} diff --git a/example/gunicorn_flask/gunicorn.conf.py b/example/gunicorn_flask/gunicorn.conf.py new file mode 100644 index 0000000..a2fa120 --- /dev/null +++ b/example/gunicorn_flask/gunicorn.conf.py @@ -0,0 +1,12 @@ +"""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. Gunicorn's error log is kept on stdout; its records are JSON only in the workers. +""" +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..e5b6b0d --- /dev/null +++ b/tests/test_gunicorn_flask.py @@ -0,0 +1,67 @@ +"""Flask under a real Gunicorn worker (issue #25). + +Starts example/gunicorn_flask on a Unix socket, sends requests, stops the server, and checks the JSON records written to +stdout. Skipped when gunicorn or httpx is not installed. +""" +import json +import os +import subprocess +import sys +import time +from pathlib import Path + +import pytest + +pytest.importorskip("gunicorn") +httpx = pytest.importorskip("httpx") + +ROOT = Path(__file__).resolve().parents[1] +EXAMPLE = ROOT / "example" / "gunicorn_flask" + + +def _json_records(text): + records = [] + for line in text.splitlines(): + try: + records.append(json.loads(line)) + except ValueError: + pass # gunicorn's own plain-text lines, such as "Starting gunicorn" + return records + + +def test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_id(tmp_path): + socket_path = tmp_path / "gunicorn.sock" + 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", "")]) + process = subprocess.Popen( + [sys.executable, "-m", "gunicorn", "-c", str(EXAMPLE / "gunicorn.conf.py"), "--workers", "1", "app:app"], + cwd=str(EXAMPLE), env=env, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True) + try: + deadline = time.time() + 30 + while not socket_path.exists() and time.time() < deadline and process.poll() is None: + time.sleep(0.1) + assert socket_path.exists(), "gunicorn did not start listening" + + with httpx.Client(transport=httpx.HTTPTransport(uds=str(socket_path)), base_url="http://localhost") as client: + supplied = client.get("/", headers={"X-Correlation-ID": "gunicorn-1"}) + generated = client.get("/") + finally: + process.terminate() + try: + output, _ = process.communicate(timeout=20) + except subprocess.TimeoutExpired: + process.kill() + output, _ = process.communicate() + + assert supplied.status_code == 200 and generated.status_code == 200 + assert supplied.json() == {"correlation_id": "gunicorn-1"} + generated_id = generated.json()["correlation_id"] + assert generated_id not in ("-", "gunicorn-1") + + records = _json_records(output) + app_ids = [r["correlation_id"] for r in records if r.get("logger") == "app"] + request_ids = [r["correlation_id"] for r in records if r.get("type") == "request"] + assert app_ids == ["gunicorn-1", generated_id] + assert request_ids == ["gunicorn-1", generated_id] + # accesslog is disabled in gunicorn.conf.py, so there is no second, Gunicorn-formatted access line. + assert not [r for r in records if r.get("logger") == "gunicorn.access"] From 7d48ae95c97e8510aa06969dfa97f687c27a17e4 Mon Sep 17 00:00:00 2001 From: uditagrawal Date: Mon, 19 Oct 2026 21:57:07 -0700 Subject: [PATCH 2/4] test: wait for gunicorn readiness and fail on malformed JSON in #25 test - Readiness: the test waited only for the Unix socket file to exist, which does not mean the worker accepts requests. It now polls GET /ready over the socket until 200, with a 30 s monotonic deadline and a 2 s per-attempt timeout. It fails early, with gunicorn's full output, if the process exits during startup. - /ready is a route excluded from request logging, so probing adds no records. - Gunicorn's output goes to a file, not a pipe, so a large log cannot block the server. The server is terminated and reaped in a finally block. - The socket lives in a short temporary directory, because macOS limits Unix socket paths to about 104 bytes and pytest's tmp_path can exceed that. - Every line starting with '{' must be valid JSON. Previously malformed lines were skipped silently. - In CI (CI=true) a missing gunicorn fails the test instead of skipping it. - README: states the dependency on #127 explicitly, documents the readiness probe and the --preload assumption. Local status: this sandbox refuses gunicorn's own socket check (EPERM), so the end-to-end run fails here. It fails fast with the output attached. Refs #25 --- example/gunicorn_flask/README.md | 17 ++++-- example/gunicorn_flask/app.py | 8 ++- tests/test_gunicorn_flask.py | 99 ++++++++++++++++++++++---------- 3 files changed, 89 insertions(+), 35 deletions(-) diff --git a/example/gunicorn_flask/README.md b/example/gunicorn_flask/README.md index 1257ad9..c808e46 100644 --- a/example/gunicorn_flask/README.md +++ b/example/gunicorn_flask/README.md @@ -28,18 +28,27 @@ curl -H "X-Correlation-ID: demo-1" http://127.0.0.1:8000/ it produces. - A request without a 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 `-`. This needs the fix for #125; before - that fix, each such record got a random ID. +- Logs written outside a request, such as worker startup and shutdown, get `-`. **This depends on PR #127** (issue + #125) and is not in master until #127 merges. Without it, each such record gets a random ID. ## Gunicorn access log `accesslog = None` in `gunicorn.conf.py` avoids a second access line per request. If you prefer Gunicorn's access log, remove that line, and remember that you then get two records per request. +## Startup and preload + +The example assumes Gunicorn's default startup, where each worker imports `app.py` after it forks. With +`--preload` (or `preload_app = True`) the module is imported once in the master process before forking, so +json-logging is initialised in the master and the workers inherit it. Do not assume the two configurations behave +identically; this example is tested only with the default. + +`/ready` is a readiness probe. It is excluded from request logging, so probing it adds no records. + ## Local test -`tests/test_gunicorn_flask.py` starts this example on a Unix socket, sends two requests, and checks the JSON output -above. It is skipped if `gunicorn` is not installed. +`tests/test_gunicorn_flask.py` starts this example on a Unix socket, waits until `/ready` answers, sends two requests, +and checks the JSON output above. In CI (`CI=true`) a missing `gunicorn` fails the test; elsewhere it is skipped. ## Verification status diff --git a/example/gunicorn_flask/app.py b/example/gunicorn_flask/app.py index 82b821f..a083981 100644 --- a/example/gunicorn_flask/app.py +++ b/example/gunicorn_flask/app.py @@ -6,7 +6,8 @@ app = flask.Flask(__name__) json_logging.init_flask(enable_json=True) -json_logging.init_request_instrument(app) +# /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) @@ -17,3 +18,8 @@ def home(): logger.info("handled request") return {"correlation_id": json_logging.get_correlation_id()} + + +@app.route("/ready") +def ready(): + return "ok" diff --git a/tests/test_gunicorn_flask.py b/tests/test_gunicorn_flask.py index e5b6b0d..0edd65c 100644 --- a/tests/test_gunicorn_flask.py +++ b/tests/test_gunicorn_flask.py @@ -1,58 +1,97 @@ """Flask under a real Gunicorn worker (issue #25). -Starts example/gunicorn_flask on a Unix socket, sends requests, stops the server, and checks the JSON records written to -stdout. Skipped when gunicorn or httpx is not installed. +Starts example/gunicorn_flask on a Unix socket, waits until the worker answers HTTP, sends requests, stops the server, +and checks the JSON records written to stdout. + +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 subprocess import sys +import tempfile import time from pathlib import Path import pytest -pytest.importorskip("gunicorn") -httpx = pytest.importorskip("httpx") +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") 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 def _json_records(text): - records = [] - for line in text.splitlines(): - try: - records.append(json.loads(line)) - except ValueError: - pass # gunicorn's own plain-text lines, such as "Starting gunicorn" - return records + """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 _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 test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_id(tmp_path): + +def test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_id(): + # A short directory: 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: + _run_gunicorn_check(Path(tmp)) + + +def _run_gunicorn_check(tmp_path): socket_path = tmp_path / "gunicorn.sock" + log_path = tmp_path / "gunicorn.log" 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", "")]) - process = subprocess.Popen( - [sys.executable, "-m", "gunicorn", "-c", str(EXAMPLE / "gunicorn.conf.py"), "--workers", "1", "app:app"], - cwd=str(EXAMPLE), env=env, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True) + 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"), "--workers", "1", "app:app"], + cwd=str(EXAMPLE), env=env, stdout=log_file, stderr=subprocess.STDOUT) try: - deadline = time.time() + 30 - while not socket_path.exists() and time.time() < deadline and process.poll() is None: - time.sleep(0.1) - assert socket_path.exists(), "gunicorn did not start listening" - - with httpx.Client(transport=httpx.HTTPTransport(uds=str(socket_path)), base_url="http://localhost") as client: + _wait_until_ready(process, socket_path, log_path) + with httpx.Client(transport=httpx.HTTPTransport(uds=str(socket_path)), base_url="http://localhost", + timeout=REQUEST_TIMEOUT) as client: supplied = client.get("/", headers={"X-Correlation-ID": "gunicorn-1"}) generated = client.get("/") finally: - process.terminate() - try: - output, _ = process.communicate(timeout=20) - except subprocess.TimeoutExpired: - process.kill() - output, _ = process.communicate() + _stop(process) + output = log_path.read_text() assert supplied.status_code == 200 and generated.status_code == 200 assert supplied.json() == {"correlation_id": "gunicorn-1"} generated_id = generated.json()["correlation_id"] @@ -61,7 +100,7 @@ def test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_ records = _json_records(output) app_ids = [r["correlation_id"] for r in records if r.get("logger") == "app"] request_ids = [r["correlation_id"] for r in records if r.get("type") == "request"] - assert app_ids == ["gunicorn-1", generated_id] - assert request_ids == ["gunicorn-1", generated_id] - # accesslog is disabled in gunicorn.conf.py, so there is no second, Gunicorn-formatted access line. + assert app_ids == ["gunicorn-1", generated_id], output + assert request_ids == ["gunicorn-1", generated_id], output + # The /ready probe is excluded from request logging, and accesslog is disabled in gunicorn.conf.py. assert not [r for r in records if r.get("logger") == "gunicorn.access"] From ad48d4132462bb129f1ce7579a3588e3202b44c4 Mon Sep 17 00:00:00 2001 From: uditagrawal Date: Mon, 19 Oct 2026 22:51:05 -0700 Subject: [PATCH 3/4] test: detect Gunicorn access lines in raw output; correct access-log docs - The README said removing accesslog = None turns Gunicorn's access log on. None is already Gunicorn's default, so nothing changes. Document how to turn it on (accesslog = "-" or --access-logfile -) and the duplicate records. - Detect Gunicorn access lines in the raw output, in plain text or wrapped in a JSON record, instead of only checking JSON records for gunicorn.access. - Add a negative control that enables --access-logfile - and checks that the detector finds the extra lines. - Assert that only the two / requests are request-logged (/ready is excluded), that the worker's 'Worker exiting' gunicorn.error record is JSON, and that the workers have exited. - Keep Gunicorn 25+'s control socket in the test's temporary directory. - Narrow the gunicorn.error wording: '-' outside requests needs PR #127. - Drop a reference to a log file that is not in the repository. --- example/gunicorn_flask/README.md | 27 ++++++-- tests/test_gunicorn_flask.py | 111 +++++++++++++++++++++++-------- 2 files changed, 102 insertions(+), 36 deletions(-) diff --git a/example/gunicorn_flask/README.md b/example/gunicorn_flask/README.md index c808e46..5d33eaa 100644 --- a/example/gunicorn_flask/README.md +++ b/example/gunicorn_flask/README.md @@ -20,7 +20,7 @@ curl -H "X-Correlation-ID: demo-1" http://127.0.0.1:8000/ | `json_logging` "Update all existing logger" lines at worker start | JSON | emitted when each worker initialises; harmless | | application logs (`logger: "app"`) | JSON | `correlation_id` is the request's `X-Correlation-ID`, or a generated ID | | request records (`type: "request"`) | JSON | same `correlation_id` as the application logs of that request | -| `gunicorn.error` records, such as `Worker exiting` | JSON in workers | `correlation_id` is `-`: they are outside any request | +| `gunicorn.error` records written by a worker, such as `Worker exiting` | JSON | json-logging reformats the loggers that exist when the worker initialises it. Outside a request `correlation_id` should be `-`, but that needs PR #127 (see below); without it each record gets a random ID | ## Correlation across requests @@ -33,8 +33,18 @@ curl -H "X-Correlation-ID: demo-1" http://127.0.0.1:8000/ ## Gunicorn access log -`accesslog = None` in `gunicorn.conf.py` avoids a second access line per request. If you prefer Gunicorn's access -log, remove that line, and remember that you then get two records per request. +Gunicorn's access log is off unless you configure it; `accesslog = None` in `gunicorn.conf.py` states that default +explicitly. Removing the line does not turn the access log on. To enable it, set a destination: + +```python +accesslog = "-" # stdout +# accesslog = "/var/log/app/access.log" # or a file path +``` + +or pass `--access-logfile -` on the command line. json-logging's request instrumentation still writes its own JSON +request record, so each HTTP request then produces two access records: Gunicorn's line and json-logging's record. +In the workers, Gunicorn's access line is itself wrapped in a JSON record with `"logger": "gunicorn.access"`. Keep the +access log off unless you need Gunicorn's format as well. ## Startup and preload @@ -48,10 +58,13 @@ identically; this example is tested only with the default. ## Local test `tests/test_gunicorn_flask.py` starts this example on a Unix socket, waits until `/ready` answers, sends two requests, -and checks the JSON output above. In CI (`CI=true`) a missing `gunicorn` fails the test; elsewhere it is skipped. +and checks the output above: application and request records share each request's correlation ID, `/ready` is not +logged, there is no Gunicorn access line, and the worker's `Worker exiting` record is JSON. A second test enables +`--access-logfile -` and checks that the access-line detector does find the extra lines. In CI (`CI=true`) a missing +`gunicorn` fails the tests; elsewhere they are skipped. ## Verification status -- The launch command and the record layout above were checked against a real Gunicorn 26.2.0 worker over a Unix socket - (saved in `audit/logs/gunicorn-flask-successful-run-2026-10-19.log`). -- The automated test runs in CI on Linux. Recorded status: see the pull request. +- The launch command and the record layout above were checked by hand against a real Gunicorn 26.2.0 worker over a + Unix socket, with and without `--access-logfile -`. +- The automated tests run in CI on Linux. Recorded status: see the pull request. diff --git a/tests/test_gunicorn_flask.py b/tests/test_gunicorn_flask.py index 0edd65c..4469714 100644 --- a/tests/test_gunicorn_flask.py +++ b/tests/test_gunicorn_flask.py @@ -1,7 +1,7 @@ """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 JSON records written to stdout. +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. @@ -9,6 +9,7 @@ import importlib import json import os +import re import subprocess import sys import tempfile @@ -25,18 +26,30 @@ 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 +# 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 @@ -67,31 +80,52 @@ def _stop(process): process.wait() -def test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_id(): - # A short directory: macOS limits Unix socket paths to about 104 bytes, which pytest's tmp_path can exceed. +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 _run_example(extra_args=()): + """Serve the example, send one request with and one without a correlation header, and stop the server. + + Returns (supplied response, generated response, 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: - _run_gunicorn_check(Path(tmp)) - - -def _run_gunicorn_check(tmp_path): - socket_path = tmp_path / "gunicorn.sock" - log_path = tmp_path / "gunicorn.log" - 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"), "--workers", "1", "app:app"], - cwd=str(EXAMPLE), env=env, stdout=log_file, stderr=subprocess.STDOUT) - try: - _wait_until_ready(process, socket_path, log_path) - with httpx.Client(transport=httpx.HTTPTransport(uds=str(socket_path)), base_url="http://localhost", - timeout=REQUEST_TIMEOUT) as client: - supplied = client.get("/", headers={"X-Correlation-ID": "gunicorn-1"}) - generated = client.get("/") - finally: - _stop(process) - - output = log_path.read_text() + tmp_path = Path(tmp) + socket_path = tmp_path / "gunicorn.sock" + log_path = tmp_path / "gunicorn.log" + args = ["--workers", "1"] + 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) + with httpx.Client(transport=httpx.HTTPTransport(uds=str(socket_path)), base_url="http://localhost", + timeout=REQUEST_TIMEOUT) as client: + supplied = client.get("/", headers={"X-Correlation-ID": "gunicorn-1"}) + generated = client.get("/") + finally: + _stop(process) + output = log_path.read_text() + assert process.returncode is not None + _assert_workers_exited(output) + return supplied, generated, output + + +def test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_id(): + supplied, generated, output = _run_example() + assert supplied.status_code == 200 and generated.status_code == 200 assert supplied.json() == {"correlation_id": "gunicorn-1"} generated_id = generated.json()["correlation_id"] @@ -99,8 +133,27 @@ def _run_gunicorn_check(tmp_path): records = _json_records(output) app_ids = [r["correlation_id"] for r in records if r.get("logger") == "app"] - request_ids = [r["correlation_id"] for r in records if r.get("type") == "request"] + request_records = [r for r in records if r.get("type") == "request"] assert app_ids == ["gunicorn-1", generated_id], output - assert request_ids == ["gunicorn-1", generated_id], output - # The /ready probe is excluded from request logging, and accesslog is disabled in gunicorn.conf.py. - assert not [r for r in records if r.get("logger") == "gunicorn.access"] + # Only the two "/" requests are logged: the /ready probes are excluded from request instrumentation. + assert [(r["request"], r["correlation_id"]) for r in request_records] == \ + [("/", "gunicorn-1"), ("/", generated_id)], output + # 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 + # Worker-side Gunicorn error-log records are JSON once json-logging is initialised in the worker. Their + # correlation_id is '-' only with the fix for #125 (PR #127), so it is not checked here. + assert [r for r in records if r.get("logger") == "gunicorn.error" and r["msg"].startswith("Worker exiting")], \ + 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.""" + supplied, generated, output = _run_example(["--access-logfile", "-"]) + + assert supplied.status_code == 200 and generated.status_code == 200 + access_lines = _access_log_lines(output) + assert len([line for line in access_lines if "GET / HTTP/1.1" in line]) == 2, 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"]) == 2, output From 72d0dfb811ab86e478cf5d6ea8444641af6d5793 Mon Sep 17 00:00:00 2001 From: uditagrawal Date: Tue, 20 Oct 2026 17:48:53 -0700 Subject: [PATCH 4/4] test: cover two Gunicorn workers and outside-request logs; correct docs - Add a two-worker test (the configured count). It waits until both workers have logged their startup record, then checks per worker that each booted, logged 'worker ready' with its own PID and correlation_id '-', and exited with a JSON 'Worker exiting' record with '-'. Request checks are per request, so they do not depend on which worker served it. - app.py logs 'worker ready' at import time, outside any request; the tests assert it gets json_logging.EMPTY_VALUE. Removing #127's Flask guard fails the one- and two-worker tests. - Send an X-Request-ID request as well, and check X-Correlation-ID, X-Request-ID and generated IDs across responses, application logs and request records. - README: remove the 'depends on PR #127' wording (merged); give the stream for each kind of output (errorlog '-' is stderr, accesslog '-' is stdout); say when the 'Update all existing logger' line appears; add the scope of the example (sync worker; gevent, --preload and a custom logconfig not tested) and how init_flask() treats handlers from a custom logging configuration. - gunicorn.conf.py: errorlog '-' writes to stderr, not stdout. --- example/gunicorn_flask/README.md | 111 ++++++++++++++---------- example/gunicorn_flask/app.py | 3 + example/gunicorn_flask/gunicorn.conf.py | 3 +- tests/test_gunicorn_flask.py | 110 +++++++++++++++++------ 4 files changed, 150 insertions(+), 77 deletions(-) diff --git a/example/gunicorn_flask/README.md b/example/gunicorn_flask/README.md index 5d33eaa..6126158 100644 --- a/example/gunicorn_flask/README.md +++ b/example/gunicorn_flask/README.md @@ -14,57 +14,72 @@ curl -H "X-Correlation-ID: demo-1" http://127.0.0.1:8000/ ## What you should see -| Output | Format | Notes | -|---|---|---| -| Gunicorn startup and master messages (`Starting gunicorn`, `Listening at`, `Booting worker`) | plain text | json-logging does not run in the master process, so these stay plain text | -| `json_logging` "Update all existing logger" lines at worker start | JSON | emitted when each worker initialises; harmless | -| application logs (`logger: "app"`) | JSON | `correlation_id` is the request's `X-Correlation-ID`, or a generated ID | -| request records (`type: "request"`) | JSON | same `correlation_id` as the application logs of that request | -| `gunicorn.error` records written by a worker, such as `Worker exiting` | JSON | json-logging reformats the loggers that exist when the worker initialises it. Outside a request `correlation_id` should be `-`, but that needs PR #127 (see below); without it each record gets a random ID | - -## Correlation across requests - -- A request that sends `X-Correlation-ID` (or `X-Request-ID`) keeps that value in every application and request log - it produces. -- A request without a 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 `-`. **This depends on PR #127** (issue - #125) and is not in master until #127 merges. Without it, each such record gets a random ID. - -## Gunicorn access log - -Gunicorn's access log is off unless you configure it; `accesslog = None` in `gunicorn.conf.py` states that default -explicitly. Removing the line does not turn the access log on. To enable it, set a destination: - -```python -accesslog = "-" # stdout -# accesslog = "/var/log/app/access.log" # or a file path -``` - -or pass `--access-logfile -` on the command line. json-logging's request instrumentation still writes its own JSON -request record, so each HTTP request then produces two access records: Gunicorn's line and json-logging's record. -In the workers, Gunicorn's access line is itself wrapped in a JSON record with `"logger": "gunicorn.access"`. Keep the -access log off unless you need Gunicorn's format as well. - -## Startup and preload - -The example assumes Gunicorn's default startup, where each worker imports `app.py` after it forks. With -`--preload` (or `preload_app = True`) the module is imported once in the master process before forking, so -json-logging is initialised in the master and the workers inherit it. Do not assume the two configurations behave -identically; this example is tested only with the default. +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. -## Local test +## Tests -`tests/test_gunicorn_flask.py` starts this example on a Unix socket, waits until `/ready` answers, sends two requests, -and checks the output above: application and request records share each request's correlation ID, `/ready` is not -logged, there is no Gunicorn access line, and the worker's `Worker exiting` record is JSON. A second test enables -`--access-logfile -` and checks that the access-line detector does find the extra lines. In CI (`CI=true`) a missing -`gunicorn` fails the tests; elsewhere they are skipped. +`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: -## Verification status +- **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. -- The launch command and the record layout above were checked by hand against a real Gunicorn 26.2.0 worker over a - Unix socket, with and without `--access-logfile -`. -- The automated tests run in CI on Linux. Recorded status: see the pull request. +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 index a083981..87955a6 100644 --- a/example/gunicorn_flask/app.py +++ b/example/gunicorn_flask/app.py @@ -1,5 +1,6 @@ """Flask application for Gunicorn. json-logging is initialised at import time, once per worker process.""" import logging +import os import flask import json_logging @@ -12,6 +13,8 @@ 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("/") diff --git a/example/gunicorn_flask/gunicorn.conf.py b/example/gunicorn_flask/gunicorn.conf.py index a2fa120..6f38d3e 100644 --- a/example/gunicorn_flask/gunicorn.conf.py +++ b/example/gunicorn_flask/gunicorn.conf.py @@ -1,7 +1,8 @@ """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. Gunicorn's error log is kept on stdout; its records are JSON only in the workers. +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 diff --git a/tests/test_gunicorn_flask.py b/tests/test_gunicorn_flask.py index 4469714..14f03ee 100644 --- a/tests/test_gunicorn_flask.py +++ b/tests/test_gunicorn_flask.py @@ -33,6 +33,7 @@ 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 @@ -89,17 +90,39 @@ def _assert_workers_exited(output): raise AssertionError("gunicorn worker %s is still running after shutdown" % pid) -def _run_example(extra_args=()): - """Serve the example, send one request with and one without a correlation header, and stop the server. +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"] + - Returns (supplied response, generated response, raw output). A short directory is used because macOS limits - Unix socket paths to about 104 bytes, which pytest's tmp_path can exceed. +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", "1"] + 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)) @@ -111,49 +134,80 @@ def _run_example(extra_args=()): 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: - supplied = client.get("/", headers={"X-Correlation-ID": "gunicorn-1"}) - generated = client.get("/") + 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 supplied, generated, 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 test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_id(): - supplied, generated, output = _run_example() +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 - assert supplied.status_code == 200 and generated.status_code == 200 - assert supplied.json() == {"correlation_id": "gunicorn-1"} - generated_id = generated.json()["correlation_id"] - assert generated_id not in ("-", "gunicorn-1") +def test_gunicorn_worker_logs_application_and_request_with_the_same_correlation_id(): + responses, output = _run_example() records = _json_records(output) - app_ids = [r["correlation_id"] for r in records if r.get("logger") == "app"] - request_records = [r for r in records if r.get("type") == "request"] - assert app_ids == ["gunicorn-1", generated_id], output - # Only the two "/" requests are logged: the /ready probes are excluded from request instrumentation. - assert [(r["request"], r["correlation_id"]) for r in request_records] == \ - [("/", "gunicorn-1"), ("/", generated_id)], 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 - # Worker-side Gunicorn error-log records are JSON once json-logging is initialised in the worker. Their - # correlation_id is '-' only with the fix for #125 (PR #127), so it is not checked here. - assert [r for r in records if r.get("logger") == "gunicorn.error" and r["msg"].startswith("Worker exiting")], \ - 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.""" - supplied, generated, output = _run_example(["--access-logfile", "-"]) + responses, output = _run_example(["--access-logfile", "-"]) - assert supplied.status_code == 200 and generated.status_code == 200 + 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]) == 2, 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"]) == 2, output + assert len([r for r in _json_records(output) if r.get("type") == "request"]) == 3, output