Python logger always outputting debug messages regardless of filter

Question

I'm currently creating a subclass of logging.Logger, which has a filter based on level, and this level can change between logging calls (hence why I'm doing this with a filter, as opposed to setLevel()). However, it seems that my logger always prints out messages with level DEBUG, regardless of the filter. Here's my code below

import logging


class _LevelFilter(logging.Filter):

    def filter(self, record):
        SimpleLogger.setLevel(_DEFAULT_LEVEL)
        return 1 if SimpleLogger.isEnabledFor(record.levelno) else 0


class _SimpleLogger(logging.getLoggerClass()):
    def __init__(self, name=None, level=logging.DEBUG):
        super().__init__(name, level)
        self.setLevel(logging.DEBUG)
        _handler = logging.StreamHandler()
        _handler.setLevel(logging.DEBUG)
        self.addHandler(_handler)
        self.addFilter(_LevelFilter())


_DEFAULT_LEVEL = 'WARNING'
SimpleLogger = _SimpleLogger()

if __name__ == '__main__':
    SimpleLogger.debug('testing debug')
    SimpleLogger.info('testing info')
    SimpleLogger.warning('testing warning')
    SimpleLogger.critical('testing critical')
    SimpleLogger.debug('testing debug')

The code above gives the following output:

testing debug
testing warning
testing critical
testing debug

I know that if I declare SimpleLogger as a separate variable instead of a subclass, it works, but I need to use the subclass for various reasons. For reference, here is a version not using the subclass that works.

SimpleLogger = logging.getLogger()
SimpleLogger.setLevel(logging.DEBUG)

_handler = logging.StreamHandler()
_handler.setLevel(logging.DEBUG)
SimpleLogger.addHandler(_handler)
SimpleLogger.addFilter(_LevelFilter())

_DEFAULT_LEVEL = 'WARNING'

I cannot figure out for the life of me why the debug messages are always printing. The differences between the subclass and non-subclass versions are not very big, and setting the level should cause debug and info messages to not appear. Any help would be appreciated, thanks!

There might be something wrong with your python installation, what python version do you use? It works in the newest python: https://onlinegdb.com/rkVJ0NA0V — Finomnis, Jun 12 '19 at 08:55
I just tried a reinstallation of Anaconda, but I'm still getting the same result. — David Wang, Jun 12 '19 at 16:40
Ok another update: it turns out my code works in python 3.6, but not python 3.7. However, it seems like the changes made in the logging library for python 3.7 shouldn't affect my code. — David Wang, Jun 12 '19 at 16:49

David Wang · Accepted Answer · 2019-06-14T00:16:26.607

I finally found the solution! So it turns out that python 3.7 introduces a cache to the logger that caches results from isEnabledFor(). Since the filter runs after the initial isEnabledFor() check, the old result was still cached, which led to this weird behavior. The solution is to not use a filter in this way. Instead, I really wanted an alternative way to get the effective level of the logger. ~~Here is the code for the fixed logger:~~

Edit: It turns out that my original solution still doesn't work, and the cache problem is still there. It seems this is specific to loggers that subclass from logging.getLoggerClass(), so you need to clear the cache every time. The new solution is below. (Also, I simplified it a lot to only include the necessary stuff.)

class _SimpleLogger(logging.getLoggerClass()):
    def __init__(self, name=None, level=logging.DEBUG):
        super().__init__(name, level)
        _handler = logging.StreamHandler()
        self.addHandler(_handler)

    def isEnabledFor(self, level):
        # Clears logging cache introduced in Python 3.7.
        # Clear here since this is called by all logging methods that write.
        self._cache = {}  # Set instead of calling clear() for compatibility with Python <3.7
        return super().isEnabledFor(level)

# Confirm that this works
if __name__ == "__main__":
    logger = SimpleLogger()
    logger.setLevel(logging.DEBUG)
    # Next 4 logs should print
    logger.debug('d')
    logger.info('i')
    logger.warning('w')
    logger.error('e')

    # Only warning and error logs should print
    logger.setLevel(logging.WARNING)
    logger.debug('d')
    logger.info('i')
    logger.warning('w')
    logger.error('e')

Good catch! You should accept your answer as the correct solution so that your problem appears solved. — alexanderhurst, Jun 12 '19 at 17:52
Unfortunately, I have to wait 2 days to accept my own answer. However, I'll make sure to do that! — David Wang, Jun 12 '19 at 17:56

Python logger always outputting debug messages regardless of filter

1 Answers1