Add session ID or some unique ID per session in python logs

Viewed 833

I have python flask micro-service in which we're using python's logging library. I want to add request session ID or any other unique ID per session in logs, so i can easily grep the logs for that particular request.

We have on micro-service in java in which we have done the same thing using this.. I want to do the same thing in python.How can i do this.

Also we already have lots of logs in our existing code i want achieve this with modifying existing logs call(or maybe some little modification like passing some argument to log function)

Currently our logging format is like this

formatter = logging.Formatter('[%(asctime)s] - [%(threadName)s] [%(thread)d] - %(levelname)s in %(module)s at %(lineno)d: %(message)s')
2 Answers

Either use an adapter or add a filter to your log. An adapter would wrap your logger, while with a Filter you would be modifying the LogRecord object.

Using the adapter would work somewhat like this:

import logging

# either user flasks builtin app.logger, or replace with your own logger
request_id = 123 # implement however you prefer
app.logger = CustomAdapter(app.logger, {'request_id': request_id})

and use %(request_id)s in your formatter somewhere. app.logger is the standard logger that flask provides.

I found this way to add request ids to flask logs on this blog post from McPolemic. I adapted it a bit here.

You will need to implement your own logging.Filter (RequestIdFilter) that will add the req_id attribute to the record. Then, the Formatter (log_formatter) will parse the record and find the req_id and print it.

Since we are creating the req_id from the flask.g.request_id param, it will be the same id used throughout the request.

# server.py
import uuid
import logging
import flask
from flask import Flask

def get_request_id():
    if getattr(flask.g, 'request_id', None):
        return flask.g.request_id

    new_uuid = uuid.uuid4().hex[:10]
    flask.g.request_id = new_uuid

    return new_uuid

class RequestIdFilter(logging.Filter):
    # This is a logging filter that makes the request ID available for use in
    # the logging format. Note that we're checking if we're in a request
    # context, as we may want to log things before Flask is fully loaded.
    def filter(self, record):
        record.req_id = get_request_id() if flask.has_request_context() else ''
        return True


logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

# The StreamHandler responsible for displaying
# logs in the console.
sh = logging.StreamHandler()
sh.addFilter(RequestIdFilter())

# Note: the "req_id" param name must be the same as in
# RequestIdFilter.filter
log_formatter = logging.Formatter(
    fmt="%(module)s: %(asctime)s - %(levelname)s - ID: %(req_id)s - %(message).1000s"
)
sh.setFormatter(log_formatter)
logger.addHandler(sh)

app = Flask(__name__)


@app.route("/")
def hello():
    logger.info("Hello world!")
    logger.info("I am a log inside the /hello endpoint")
    return "Hello World!"


if __name__ == "__main__":
    app.run()

Then, run this server:

python server.py

Finally, run this inside your Python console:

>>> import requests
>>> r = requests.get("http://localhost:5000/"); r.text
'Hello World!'
>>> r = requests.get("http://localhost:5000/"); r.text
'Hello World!'

And the logs will show:

server: 2022-08-01 15:35:26,201 - INFO - ID: 2f0e2341aa - Hello world!
server: 2022-08-01 15:35:26,202 - INFO - ID: 2f0e2341aa - I am a log inside the /hello endpoint
127.0.0.1 - - [01/Aug/2022 15:35:26] "GET / HTTP/1.1" 200 -
server: 2022-08-01 15:35:30,698 - INFO - ID: 1683ba71d9 - Hello world!
server: 2022-08-01 15:35:30,698 - INFO - ID: 1683ba71d9 - I am a log inside the /hello endpoint
127.0.0.1 - - [01/Aug/2022 15:35:30] "GET / HTTP/1.1" 200 -

Note that on different requests, the ids were modified, but they remained unchanged on the same request.

Related