python logging: how to add customized logging message without break original code?

Question

let say have a simple function which return sum of two number

import logging

def fun(a, b):
    logging.info("something important")
    return a + b

if i need to add, let say user_id, then setup a customized logging can do the job

File Customized Logging:mylogger.py
import logging

mylogger = logging.getLogger('mylogger')
handle = logging.StreamHandler()
handle.setFormatter(logging.Formatter("%(asctime)s [%(levelname)s] %(threadName)s (%(filename)s:%(lineno)d) userid:%(userId)s %(message)s"))
mylogger.setLevel(logging.INFO)
--------------------------------------------------------------------------------------
File Fun fun.py
from mylogger import mylogger as logging

def fun(a, b, user_id)
    logging.info("something important", extra = {'userId':user_id})
    return a + b

There are two major drawbacks from above code: a) extra parameters must be set b) user_id must be passed though the function

In my real business code, thousands of logging are called from multi-layers, modifing them one by one is highly in-efficient.

Besides, userinfo is gained at interface layer (flask route file), but logging in database layer need up to five times params passing, i have to add params to at least 300 functions, could lead the whole project to a mess.

My question is: is there an elegant solution which add userinfo to logging without change original function code?

I tried to use a decorator

class my_logger(object):

    def __init__(self, user_info, format_str, register_name):
        self.user_info = user_info 
        self.logger = logging.getLogger(register_name)
        handler = logging.StreamHandler()
        handler.setFormatter(logging.Formatter(format_str))
        handler.setLevel(logging.INFO)
        self.logger.addHandler(handler)
        self.logger.setLevel(logging.INFO)


    def __call__(self, func):
        def wrapper(*args, **kwargs):
            self.logger.info("xxx", extra=self.user_info)
            return func(*args, **kwargs)
        return wrapper

But in this way the logging inside the function remain unchanged

score 0 · Answer 1 · answered Feb 22 '23 at 13:14

You could use a context filter that gets the arguments of the endpoint:

import logging

class ContextFilter(logging.Filter):
    def filter(self, record):
        from flask import request

        # Add the userid from the args to the endpoint
        record.userId = request.args.get("userid")
        return True

mylogger = logging.getLogger('mylogger')
handle = logging.StreamHandler()
handle.setFormatter(logging.Formatter("%(asctime)s [%(levelname)s] %(threadName)s (%(filename)s:%(lineno)d) userid:%(userId)s %(message)s"))
handle.addFilter(ContextFilter())
mylogger.setLevel(logging.INFO)

Then, instanciate the Flask logger to mylogger:

app.logger = mylogger

and inside your endpoints, do:

_log = logging.getLogger("mylogger")

def fun(a, b)
    _log.info("something important")
    return a + b

@app.route("/add", methods=["GET"])
def add():
    app.info("Inside /add")
    res = fun(a, b)
    return {"res": res}, 200

Also, you could use flask.g to store and access contextual data of the call:

class ContextFilter(logging.Filter):
    def filter(self, record):
        if not getattr(flask.g, "userid", None):
            # Fetch userid inside the cookies for example,
            # or generate some random value
            userid = XXXX
        else:
            # Keep the current value already stored inside flask.g
            # for the current call
            # After the call ends (you return), flask.g is reset
            userid = getattr(flask.g, "userid")
        
        # This will ensure the userid will not change for the entirety
        # of the call.
        record.userId = userid
        return True

_{Note: I did not test the first solution, but I did test the second one, and it worked well for my purposes.}

python logging: how to add customized logging message without break original code?

1 Answers1