CODEWITHSUNDEEP
pythonloggingwrapper
user4913191
user4913191

Reputation:

Wrapper causes change in the funcName attribute in custom python logger

I have created a wrapper in custom python logger to add additional attributes in the log formatter.

logFormat = logging.Formatter('[%(levelname)s],[%(asctime)-15s], %(API_SERVER)s, %(funcName)s,%(lineno)d, %(message)s')

Additional Attribute -> API_SERVER

The log shows the wrapper method as the funcName instead of actual funcName.

[DEBUG],[2017-05-23 17:52:13,865], jupiter-api-server, loggingMethodsWrapper,91, Response returned from DolphinD is 200, returning status success, to caller.

Wrapper Code -->

def loggingMethodsWrapper(self, logLevelMethod, *kargs):
    # Calling method logging methods dynamcially
    # Add the parameters in the extra if you want to add
    # more columns in logging format
    getattr(self.log, logLevelMethod)(
          *kargs, extra={'API_SERVER': self.API_SERVER})

Upvotes: 2

Views: 1663

Answers (5)

tito
tito

Reputation: 21

I didn't find it in off documentation, but if we check the source code for methods debug/info/error/etc..., we can simply change 'stacklevel' to change the caller name

In your wrapper, you probably want to add smth like that:

loggerWrapper.debug("log text", *args, stacklevel=<N>)

where is N - is the number of levels to look up to find a correct caller.

from logger sources:

 def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False,
             stacklevel=1):

Upvotes: 2

jamburg
jamburg

Reputation: 11

I had the same problem, I had number of different functions, wrote nice and clean wrapper with logging. In that situation of course I need to have feedback, what function it is. I copied source from github, that is responsible for that pain, and deleted just few lines

# enable overwritting log record attributes
# I know, dirty cheating



def makeRecord(self, name, level, fn, lno, msg, args, exc_info,
               func=None, extra=None, sinfo=None):
"""
A factory method which can be overridden in subclasses to create
specialized LogRecords.
"""
rv = logging._logRecordFactory(name, level, fn, lno, msg, args, exc_info, func,
                               sinfo)
if extra is not None:
    for key in extra:
        rv.__dict__[key] = extra[key]
return rv


logging.Logger.makeRecord = makeRecord

than changed reference for that method in Logger class so now I can set attributes of LogRecord, even if they are already used, like funcName

so wrapper looks like this

def log_string_convertors(convertor: callable):
    @wraps(convertor)
    def wrapper(string: str):
        result: str = convertor(string)
        logger.debug("%s->%s", string, result,
                 extra={"input": string, "output": result, "funcName": convertor.__name__})
    return result

return wrapper

I am saving LogRecords to json to be able to analyze them with program later, so I am adding some additional attributes like input and output

Upvotes: 1

SpiralDev
SpiralDev

Reputation: 7321

You can use inspect package to get previous function's name. Here's an example of singleton wrapper of logging functionality that shows 'true' caller:

import logging
import inspect

class Singleton(type):
    _instances = {}

    def __call__(cls, *args, **kwargs):
        if cls not in cls._instances:
            cls._instances[cls] = super(Singleton, cls).__call__(*args, **kwargs)
        return cls._instances[cls]

class MyLogger(metaclass=Singleton):
    logger = None

    def __init__(self):
        logging.basicConfig(
            level=logging.INFO,
            format="%(asctime)s - %(threadName)s - %(message)s",
            handlers=[
                logging.StreamHandler()
            ])

        self.logger = logging.getLogger(__name__ + '.logger')

    @staticmethod
    def __get_call_info():
        stack = inspect.stack()

        # stack[1] gives previous function (info in our case)
        # stack[2] gives before previous function and so on

        fn = stack[2][1]
        ln = stack[2][2]
        func = stack[2][3]

        return fn, func, ln

    def info(self, message, *args):
        message = "{} - {} at line {}: {}".format(*self.__get_call_info(), message)
        self.logger.info(message, *args)

Upvotes: 0

user4913191
user4913191

Reputation:

Log.py

class Log(Singleton):
log = None
caller = None
def __init__(self):
    ### Configure log
    # TODO: The config has to come from Dictconfig YAML file
    logFolder = CONSTANTS['LOG']['DIR']
    self.API_SERVER = API_SERVER
    caller = inspect.stack()[1][3]
    print caller
    self.log = logging.getLogger(__name__)

    # If handlers are already set donot do it again
    if not len(self.log.handlers):
        logFormat = logging.Formatter('[%(levelname)s],[%(asctime)-15s], %(API_SERVER)s, %(caller)s,%(lineno)d, %(message)s')

def loggingMethodsWrapper(self, logLevelMethod, *kargs):
    # Calling method logging methods dynamically
    # Add the parameters in the extra if you want to add
    # more columns in logging format

    getattr(self.log, logLevelMethod)(
          *kargs, extra={'API_SERVER': self.API_SERVER, 'caller': self.caller})

Example API File -->

from flask import Flask, Response, request
from base import base
from jupiter_api.lib.jupFlaskClassy import *

from jupiter_api.business.accounts import accounts as bzAccounts
from jupiter_api.business.role_decorators import permGate, login_required
from flask.ext.cors import CORS
from jupiter_api.utils.log import Log
Log = Log()

class accounts(base):

    supported_methods = "OPTIONS, GET, POST, DELETE"
    ##  GET request to pull all user accounts
    @route('/<userId>/<companyId>/accounts/<accountId>', methods=['GET'])
    @permGate('list_accounts')
    @login_required
    def get_details(self, userId, companyId, accountId):
        #import pdb; pdb.set_trace()
        Log.debug("In get accounts for user")

        # Validate arguments
        if not userId or not companyId:
            return self.invalidData()

        # Print arguments
        Log.debug("Getting account details for user %s ", userId)

Note - I have 100s of APIs similar to the Accounts API that are calling Log().

Upvotes: 0

xgord
xgord

Reputation: 4776

The wrong function name is happening because loggingMethodsWrapper is the one actually doing the call to log.


What you want seems to be function that calls loggingMethodsWrapper. The fix is to change your formatter so that it doesn't include %(funcName)s and move that to be part of the arguments passed to %(message)s or as an extra parameter.


Opt 1:

Doing this, a dirty fix would be to have your wrapper walk up the stack and grab the next function up.

In python2 this would like:

caller = inspect.stack()[1][3]

On python3 this would be:

caller = inspect.stack()[1].filename

So:

logFormat = logging.Formatter('[%(levelname)s],[%(asctime)-15s], %(API_SERVER)s, %(CALLER)s,%(lineno)d, %(message)s')

...

def loggingMethodsWrapper(self, logLevelMethod, *kargs):
    caller = # python-specific method of getting caller
    getattr(self.log, logLevelMethod)(
          *kargs, extra={'CALLER' : caller, 'API_SERVER': self.API_SERVER})


Opt 2:

Simple fix if you can change caller -- passing the function name to your logger wrapper

loggingMethodsWrapper(self, func_name, logLevelMethod, *kargs):
    ....

and then when you call it

def foo():
    loggingMethodsWrapper(foo.__name__, log_level, ...)

Upvotes: 1

Related Questions