Logging decorator with basicConfig settings as arguments

Question

EDIT : I restructured the question and added headings in the hope it will be easier to read

The Problem

I'm trying to add some functionality to the logging decorator in the python decorator library.

One of the options I wanted to add is being able to set the logging level by providing a dictionary as input. However, no matter what level I set it always returns the same results.

---

The failing test

After running the setup code below, I'm testing it by running the following:

@log_with(setConfig={'level':logging.INFO})
def c(msg):
    print(msg)

c('OMG!!')

which returns:

INFO:__main__:Running c


DEBUG:__main__:The following arguments have been received:# <-- This should not be here
('OMG!!',)

The following keyword arguments have been received:
{}


INFO:__main__:Returning c
OMG!!

I'm using WinPython 2.7.6 in a portable, non-registered way if this matters. The test fails in the qtconsole

---

The set up code

import functools, logging


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

class log_with(object):
    '''Logging decorator that allows you to log with a
specific logger or set one up on the go.
'''

    def __init__(self,logger=None,funcentry='Running {}',funcexit='Returning {}',setConfig=None):

        self.logger        = logger
        self.ENTRY_MESSAGE = funcentry
        self.EXIT_MESSAGE  = funcexit
        self.setConfig     = setConfig


    def __call__(self, func):
        '''Returns a wrapper that wraps func.
The wrapper will log the entry and exit points of the function
with specified level.
'''
        # set logger if it was not set earlier
        if not self.logger:
            self.logger = logging.getLogger(func.__module__)
            logging.basicConfig(**self.setConfig)

        @functools.wraps(func)
        def wrapper(*args, **kwds):
            self.logger.info(self.ENTRY_MESSAGE.format(func.__name__)+'\n\n')
            self.logger.debug("The following arguments have been received:\n{}\n\nThe following keyword arguments have been received:\n{}\n\n".format(args,kwds))
            try:
                f_result = func(*args, **kwds)
                self.logger.info(self.EXIT_MESSAGE.format(func.__name__))
                return f_result
            except Exception:
                self.logger.exception("An exception was raised:\n\n")
        return wrapper

---

Ideas I had and things I tried

Resetting all handlers

I tried to amend the if not self.logger loop in the decorator by removing all handlers that might exist, i.e.

....
if not self.logger:
    for handler in logging.root.handlers[:]:
        logging.root.removeHandler(handler)
....

based on this SO answer however this didn't work either, i.e. the output stayed the same.

I don't understand decorators and/or the logging module!

I removed

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

and ran the code again. This time no logging message was printed to screen at all. To me this means that there is something wrong with the if not self.logger loop in the __call__ method, i.e. the logger is not created.

I have no idea why though.....

Answer 1

Here is what I learned:

1. It looks like using basicConfig() sets some global variables for logging. Changing the logging level seems to change it globally rather than just for this call.

2. Whether implementing a decorator as a class or as a function seems to make a difference. While not totally sure, I believe that by implementing my self.setConfig in __init__, I changed the class for all functions I decorated. I deduct this from the solution I found, which is implementing the decorator as a function:

This it what seems to work (even though I'm a little puzzled about the order in which things are returned):

def log_with_func(funcentry='Running {}',funcexit='Returning {}',setConfig=None):
    ENTRY_MESSAGE = funcentry
    EXIT_MESSAGE  = funcexit
    def func(f):
        @functools.wraps(f)
        def wrapper(*args, **kwds):
            for handler in logging.root.handlers[:]:
                logging.root.removeHandler(handler)
            logger = logging.getLogger(__name__)
            if setConfig:
                logging.basicConfig(**setConfig)
            else:
                logging.basicConfig(level=logging.INFO)
            logger.info(ENTRY_MESSAGE.format(f.__name__)+'\n\n')
            logger.debug("The following arguments have been received:\n{}\n\nThe following keyword arguments have been received:\n{}\n\n".format(args,kwds))
            try:
                f_result = f(*args, **kwds)
                logger.info(EXIT_MESSAGE.format(f.__name__))
                return f_result
            except Exception:
                logger.exception("An exception was raised:\n\n")
        return wrapper
    return func

Applied it looks like this:

In [24]: @log_with_func()
    ...: def aa(msg):
    ...:     print(msg + 'from a')
    ...:     

In [25]: @log_with_func(setConfig={'level':logging.DEBUG})
    ...: def bb(msg):
    ...:     print(msg + 'from b')
    ...:     

In [26]: print(aa('OMG!!!'))
    ...: print(bb('OMG!!!'))
    ...: print(aa('OMG!!!'))
    ...: 
INFO:__main__:Running aa


INFO:__main__:Returning aa
INFO:__main__:Running bb


DEBUG:__main__:The following arguments have been received:
('OMG!!!',)

The following keyword arguments have been received:
{}


INFO:__main__:Returning bb
INFO:__main__:Running aa


INFO:__main__:Returning aa
OMG!!!from a
None
OMG!!!from b
None
OMG!!!from a
None

In [27]: