Print the correct 'funcName' when logging writer is wrapped in function

Question

I'm currently writing a pretty large algorithm with multiple classes and functions. Along the process, I'm writing information into a JSON log file. Since I add alot of additional information into the log msg, I decided to automate the log writing, by wrapping it into a function - which led to "false" identification of log 'funcName' (as I describe below).

Can anyone help me to allow proper function identification by the logger? or is it possible to edit the 'funcName' within the log before it prints into the log file?

Issue description in code:

assuming df['Test'] = 'X' and df['Method'] = 'dev'
logging.ini contains the logging configuration as described here:

class=FileHandler
level=DEBUG
formatter=json
args=("log_output.json",)
class=pythonjsonlogger.jsonlogger.JsonFormatter
format=%(asctime)s %(name)s  %(funcName)s %(levelname)s %(message)s

Sample code:

import logging
logging.config.fileConfig('logging.ini', disable_existing_loggers=False)
logger = logging.getLogger(__name__)


def LoggerWriter(df, text):
    logger.info('Test: {}; Method: {}; Description: {}'.format(df['Test'], df['Method'], text))


class DoStuff(self):
    def DoSomething(df):
        LoggerWriter(df, 'Start Function')
        ~Stuff are done here
        LoggerWriter(df, 'Finish Function')

The output I get in the log file is (notice the 'funcName'):

{"asctime": "2021-05-30 14:58:31,796", "name": "DoStuff", "funcName": "LoggerWriter", "levelname": "INFO", "message": "Test: X; Method: dev; Description: Start Function."}
{"asctime": "2021-05-30 14:58:42,800", "name": "DoStuff", "funcName": "LoggerWriter", "levelname": "INFO", "message": "Test: X; Method: dev; Description: Finish Function."}

While I want the 'funcName' output to be 'DoSomething' and not 'LoggerWriter' as shown here:

{"asctime": "2021-05-30 14:58:31,796", "name": "DoStuff", "funcName": "DoSomething", "levelname": "INFO", "message": "Test: X; Method: dev; Description: Start Function."}
{"asctime": "2021-05-30 14:58:42,800", "name": "DoStuff", "funcName": "DoSomething", "levelname": "INFO", "message": "Test: X; Method: dev; Description: Finish Function."}

Thank you all for your help! :)

score 1 · Answer 1 · answered May 31 '21 at 06:38

After a lot of both research and trial and error I've figured it out:

The inspect module allows me to identify the call trace of any function (taken from here).
Additionally, I created a logging filter class with a filter function to edit the log record of 'funcName' (By the way, this is how any filter can be added to the logger). The new filter class should be added to the logger using the addFilter function. This solution was taken from here

import inspect
import logging
logging.config.fileConfig('logging.ini', disable_existing_loggers=False)
logger = logging.getLogger(__name__)

class FunctionNameFilter(logging.Filter):
    def filter(self, record):
        function_name = inspect.currentframe()
        function_name = inspect.getouterframes(function_name, 2)
        record.funcName = function_name[6][3]
        return True

logger.addFilter(FunctionNameFilter())

I hope this will help someone in the future :)

Print the correct 'funcName' when logging writer is wrapped in function

1 Answers1