Pre Request Logging in Gunicorn

In the previous blog, I discussed how to setup Gunicorn with a Flask app and set some of the Gunicorn configuration variables. One of default configurations is logging the request method, path, and response code after the request has completed.

This article will discuss how to log the method and path before the request starts and why that might be useful.

Here is our simple Flask app, app.py, with two endpoints:

1. /healthcheck which returns "ok"
2. /sleep which sleeps for 10s and then returns "ok"

from flask import Flask, jsonify
import sys
import time
app = Flask(__name__)

@app.route("/healthcheck")
def healthcheck():
    return jsonify({"status": "ok"})

@app.route("/sleep")
def sleep():
    time.sleep(10)
    return jsonify({"status": "ok"})

if __name__ == "__main__":
    app.run(host="0.0.0.0", debug=True, port=8888)

My Gunicorn config file, gunicorn_config.py is:

import multiprocessing

bind = "127.0.0.1:8000"
workers = 1
worker_class = "sync"

errorlog = "-"
loglevel = "info"
accesslog = "-"

To start Gunicorn, I run $ gunicorn --config gunicorn_config.py app:app and then execute the following curl to run the /sleep endpoint: curl localhost:8000/sleep

The logs for this execution look like this:

[2022-05-22 16:09:07 -0500] [46969] [INFO] Starting gunicorn 20.1.0
[2022-05-22 16:09:07 -0500] [46969] [INFO] Listening at: http://127.0.0.1:8000 (46969)
[2022-05-22 16:09:07 -0500] [46969] [INFO] Using worker: sync
[2022-05-22 16:09:07 -0500] [46970] [INFO] Booting worker with pid: 46970
127.0.0.1 - - [22/May/2022:16:09:18 -0500] "GET /sleep HTTP/1.1" 200 16 "-" "curl/7.77.0"

The request path, request method, and response code only get logged after the function has finished executing.

But what if I had a bug in my function? Would I still get the log lines?

It depends on the bug (a bug might generate a 400 error), but recently at work we had a bug causing our worker to die and thus no log lines were printed. Since there were no log lines, we couldn't pinpoint the error in our codebase.

We can simulate this situation by editing our /sleep endpoint to exit.

@app.route("/sleep")
def sleep():
    time.sleep(10)
    sys.exit()
    return jsonify({"status": "ok"})

The log lines after running curl localhost:8000/sleep are:

[2022-05-22 16:13:40 -0500] [47073] [INFO] Starting gunicorn 20.1.0
[2022-05-22 16:13:40 -0500] [47073] [INFO] Listening at: http://127.0.0.1:8000 (47073)
[2022-05-22 16:13:40 -0500] [47073] [INFO] Using worker: sync
[2022-05-22 16:13:40 -0500] [47074] [INFO] Booting worker with pid: 47074
[2022-05-22 16:13:51 -0500] [47074] [INFO] Worker exiting (pid: 47074)
[2022-05-22 16:13:51 -0500] [47080] [INFO] Booting worker with pid: 47080

The fifth line logs the worker being exited and the sixth rebooted, but there is no insight into what line or method caused the kernel to kill the worker.

So to help in debugging, you can add some pre_request logging into our gunicorn_config.py by appending this pre_request function to our file.

def pre_request(worker, req):
    worker.log.info(f"METHOD={req.method} PATH={req.path} WORKER_PID={worker.pid}")

Now my log lines will look like:

[2022-05-22 16:19:05 -0500] [47223] [INFO] Starting gunicorn 20.1.0
[2022-05-22 16:19:05 -0500] [47223] [INFO] Listening at: http://127.0.0.1:8000 (47223)
[2022-05-22 16:19:05 -0500] [47223] [INFO] Using worker: sync
[2022-05-22 16:19:05 -0500] [47224] [INFO] Booting worker with pid: 47224
[2022-05-22 16:19:06 -0500] [47224] [INFO] METHOD=GET PATH=/sleep WORKER_PID=47224
[2022-05-22 16:19:16 -0500] [47224] [INFO] Worker exiting (pid: 47224)
[2022-05-22 16:19:16 -0500] [47230] [INFO] Booting worker with pid: 47230

This pre_logging is extremely helpful because now I see the request method, its path, and the worker PID before any code is run. So if I get a "Worker exiting" log line for a specific worker, I quickly trace back that workers last executed method and can start debugging it.

Happy debugging! 🐜

P.S. Check out the Gunicorn docs for more helpful configurations