From 141ddbc06371f7a6a24feb40d915a8af123f6316 Mon Sep 17 00:00:00 2001 From: Jennifer Richards Date: Mon, 25 Nov 2024 12:09:00 -0400 Subject: [PATCH 1/4] chore: log in-flight request lists on worker term --- dev/build/gunicorn.conf.py | 55 +++++++++++++++++++++++++++++++++++--- 1 file changed, 52 insertions(+), 3 deletions(-) diff --git a/dev/build/gunicorn.conf.py b/dev/build/gunicorn.conf.py index 89d3dd58d38..44e364c690e 100644 --- a/dev/build/gunicorn.conf.py +++ b/dev/build/gunicorn.conf.py @@ -48,10 +48,25 @@ } } -def pre_request(worker, req): +# Track in-flight requests and emit a list of what was happeningwhen a worker is terminated. +# For the default sync worker, there will only be one request per PID, but allow for the +# possibility of multiple requests in case we switch to a different worker class. +# +# This dict is only visible within a single worker, but key by pid to guarantee no conflicts. +# +# Use a list rather than a set to allow for the possibility of overlapping identical requests. +in_flight_by_pid: dict[str, list[str]] = {} # pid -> list of in-flight requests + + +def _describe_request(req): + """Generate a consistent description of a request + + The return value is used identify in-flight requests, so it must not vary between the + start and end of handling a request. E.g., do not include a timestamp. + """ client_ip = "-" cf_ray = "-" - for (header, value) in req.headers: + for header, value in req.headers: header = header.lower() if header == "cf-connecting-ip": client_ip = value @@ -61,4 +76,38 @@ def pre_request(worker, req): path = f"{req.path}?{req.query}" else: path = req.path - worker.log.info(f"gunicorn starting to process {req.method} {path} (client_ip={client_ip}, cf_ray={cf_ray})") + return f"{req.method} {path} (client_ip={client_ip}, cf_ray={cf_ray})" + + +def pre_request(worker, req): + """Log the start of a request and add it to the in-flight list""" + request_description = _describe_request(req) + worker.log.info(f"gunicorn starting to process {request_description}") + in_flight = in_flight_by_pid.setdefault(worker.pid, list()) + in_flight.append(request_description) + + +def worker_abort(worker): + """Emit an error log if any requests were in-flight""" + in_flight = in_flight_by_pid.get(worker.pid, set()) + if in_flight is not None: + worker.log.error( + f"Aborted worker {worker.pid} with in-flight requests: {', '.join(in_flight)}" + ) + + +def worker_int(worker): + """Emit an error log if any requests were in-flight""" + in_flight = in_flight_by_pid.get(worker.pid, set()) + if in_flight is not None: + worker.log.error( + f"Interrupted worker {worker.pid} with in-flight requests: {', '.join(in_flight)}" + ) + + +def post_request(worker, req, environ, resp): + """Remove request from in-flight list when we finish handling it""" + request_description = _describe_request(req) + in_flight = in_flight_by_pid.get(worker.pid, set()) + if request_description in in_flight: + in_flight.remove(request_description) From e299bfa7231f9790f93aa27431786308c1bb094d Mon Sep 17 00:00:00 2001 From: Jennifer Richards Date: Mon, 25 Nov 2024 12:09:20 -0400 Subject: [PATCH 2/4] style: Black --- dev/build/gunicorn.conf.py | 15 +++++++-------- 1 file changed, 7 insertions(+), 8 deletions(-) diff --git a/dev/build/gunicorn.conf.py b/dev/build/gunicorn.conf.py index 44e364c690e..6e35a634e70 100644 --- a/dev/build/gunicorn.conf.py +++ b/dev/build/gunicorn.conf.py @@ -12,26 +12,25 @@ "level": "INFO", "handlers": ["console"], "propagate": False, - "qualname": "gunicorn.error" + "qualname": "gunicorn.error", }, - "gunicorn.access": { "level": "INFO", "handlers": ["access_console"], "propagate": False, - "qualname": "gunicorn.access" - } + "qualname": "gunicorn.access", + }, }, "handlers": { "console": { "class": "logging.StreamHandler", "formatter": "json", - "stream": "ext://sys.stdout" + "stream": "ext://sys.stdout", }, "access_console": { "class": "logging.StreamHandler", "formatter": "access_json", - "stream": "ext://sys.stdout" + "stream": "ext://sys.stdout", }, }, "formatters": { @@ -44,8 +43,8 @@ "class": "ietf.utils.jsonlogger.GunicornRequestJsonFormatter", "style": "{", "format": "{asctime}{levelname}{message}{name}{process}", - } - } + }, + }, } # Track in-flight requests and emit a list of what was happeningwhen a worker is terminated. From b23c2c650f289fe2841b12e83cdcf1e1b0785423 Mon Sep 17 00:00:00 2001 From: Jennifer Richards Date: Mon, 25 Nov 2024 12:52:56 -0400 Subject: [PATCH 3/4] chore: suppress empty in-flight logs --- dev/build/gunicorn.conf.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/dev/build/gunicorn.conf.py b/dev/build/gunicorn.conf.py index 6e35a634e70..bba4e13b498 100644 --- a/dev/build/gunicorn.conf.py +++ b/dev/build/gunicorn.conf.py @@ -89,7 +89,7 @@ def pre_request(worker, req): def worker_abort(worker): """Emit an error log if any requests were in-flight""" in_flight = in_flight_by_pid.get(worker.pid, set()) - if in_flight is not None: + if len(in_flight) > 0: worker.log.error( f"Aborted worker {worker.pid} with in-flight requests: {', '.join(in_flight)}" ) @@ -98,7 +98,7 @@ def worker_abort(worker): def worker_int(worker): """Emit an error log if any requests were in-flight""" in_flight = in_flight_by_pid.get(worker.pid, set()) - if in_flight is not None: + if len(in_flight) > 0: worker.log.error( f"Interrupted worker {worker.pid} with in-flight requests: {', '.join(in_flight)}" ) From d6f4d282a1d885d1446e5bbe0ffb65600e532b02 Mon Sep 17 00:00:00 2001 From: Jennifer Richards Date: Mon, 25 Nov 2024 13:04:24 -0400 Subject: [PATCH 4/4] chore: use list consistently --- dev/build/gunicorn.conf.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/dev/build/gunicorn.conf.py b/dev/build/gunicorn.conf.py index bba4e13b498..cabbee0b1e3 100644 --- a/dev/build/gunicorn.conf.py +++ b/dev/build/gunicorn.conf.py @@ -82,13 +82,13 @@ def pre_request(worker, req): """Log the start of a request and add it to the in-flight list""" request_description = _describe_request(req) worker.log.info(f"gunicorn starting to process {request_description}") - in_flight = in_flight_by_pid.setdefault(worker.pid, list()) + in_flight = in_flight_by_pid.setdefault(worker.pid, []) in_flight.append(request_description) def worker_abort(worker): """Emit an error log if any requests were in-flight""" - in_flight = in_flight_by_pid.get(worker.pid, set()) + in_flight = in_flight_by_pid.get(worker.pid, []) if len(in_flight) > 0: worker.log.error( f"Aborted worker {worker.pid} with in-flight requests: {', '.join(in_flight)}" @@ -97,7 +97,7 @@ def worker_abort(worker): def worker_int(worker): """Emit an error log if any requests were in-flight""" - in_flight = in_flight_by_pid.get(worker.pid, set()) + in_flight = in_flight_by_pid.get(worker.pid, []) if len(in_flight) > 0: worker.log.error( f"Interrupted worker {worker.pid} with in-flight requests: {', '.join(in_flight)}" @@ -107,6 +107,6 @@ def worker_int(worker): def post_request(worker, req, environ, resp): """Remove request from in-flight list when we finish handling it""" request_description = _describe_request(req) - in_flight = in_flight_by_pid.get(worker.pid, set()) + in_flight = in_flight_by_pid.get(worker.pid, []) if request_description in in_flight: in_flight.remove(request_description)