logging with filters

Question

I'm using Logging (import logging) to log messages.

Within 1 single module, I am logging messages at the debug level my_logger.debug('msg');

Some of these debug messages come from function_a() and others from function_b(); I'd like to be able to enable/disable logging based on whether they come from a or from b;

I'm guessing that I have to use Logging's filtering mechanism.

Can someone show me how the code below would need to be instrumented to do what I want?

import logging
logger = logging.getLogger( "module_name" )

def function_a( ... ):
    logger.debug( "a message" )

def function_b( ... ):
    logger.debug( "another message" )

if __name__ == "__main__":
    logging.basicConfig( stream=sys.stderr, level=logging.DEBUG )

    #don't want function_a()'s noise -> ....
    #somehow filter-out function_a's logging
    function_a()

    #don't want function_b()'s noise -> ....
    #somehow filter-out function_b's logging
    function_b()

If I scaled this simple example to more modules and more funcs per module, I'd be concerned about lots of loggers;

Can I keep it down to 1 logger per module? Note that the log messages are "structured", i.e. if the function(s) logging it are doing some parsing work, they all contain a prefix logger.debug("parsing: xxx") - can I somehow with a single line just shut-off all "parsing" messages (regardless of the module/function emitting the message?)

Elvinaelvira

Answer 1

Just implement a subclass of logging.Filter: http://docs.python.org/library/logging.html#filter-objects. It will have one method, filter(record), that examines the log record and returns True to log it or False to discard it. Then you can install the filter on either a Logger or a Handler by calling its addFilter(filter) method.

Example:

class NoParsingFilter(logging.Filter):
    def filter(self, record):
        return not record.getMessage().startswith('parsing')

logger.addFilter(NoParsingFilter())

Or something like that, anyway.

Tommy

I had to add the filter to the handler. – Sevigny

@GringoSuave The reason for that is likely because handlers propagate, but filters don't: saltycrane.com/blog/2014/02/… – Mader

This filter will skip those messages if you add the filter(), I use that in combination of --verbose argument. If the argument is not present, then I add the filter. Works neat to add logging VISUAL MARKERS in the stdout that you only need in very certain circumstances. Do not comment a logging messge anymore. – Ermey

Answer 2

Do not use global. It's an accident waiting to happen.

You can give your loggers any "."-separated names that are meaningful to you.

You can control them as a hierarchy. If you have loggers named a.b.c and a.b.d, you can check the logging level for a.b and alter both loggers.

You can have any number of loggers -- they're inexpensive.

The most common design pattern is one logger per module. See Naming Python loggers

Do this.

import logging

logger= logging.getLogger( "module_name" )
logger_a = logger.getLogger( "module_name.function_a" )
logger_b = logger.getLogger( "module_name.function_b" )

def function_a( ... ):
    logger_a.debug( "a message" )

def function_b( ... ):
    logger_b.debug( "another message" )

if __name__ == "__main__":
    logging.basicConfig( stream=sys.stderr, level=logging.DEBUG )
    logger_a.setLevel( logging.DEBUG )
    logger_b.setLevel( logging.WARN )

    ... etc ...

Anzus

thanks S.Lott for your reply; this would work; however, if i scaled my simple example to more modules and more funcs per module, i'd be concerned about lots of loggers; can i keep it down to 1 logger per module? note that the log messages are "structured", i.e. if the function(s) logging it are doing some parsing work, they all contain a prefix logger.debug("parsing: ...") - can i somehow with a single line just shut-off all "parsing" messages (regardless of the module/function emitting the message?) – Elvinaelvira

Answer 3

I found a simpler way using functions in your main script:

# rm 2to3 messages
def filter_grammar_messages(record):
    if record.funcName == 'load_grammar':
        return False
    return True

def filter_import_messages(record):
    if record.funcName == 'init' and record.msg.startswith('Importing '):
        return False
    return True

logging.getLogger().addFilter(filter_grammar_messages)  # root
logging.getLogger('PIL.Image').addFilter(filter_import_messages)

Sevigny

Is PIL.Image the file name? – Abecedarium

No, it is the name of the PIL logger, just an example that I happened to need. Every library will have a different name, probably its name. – Sevigny

Answer 4

I've found a bit easier way how to filter default logging configuration on following problem using sshtunel module, supressing INFO level messages.

Default reporting with first 2 undesired records looked as follows:

2020-11-10 21:53:28,114  INFO       paramiko.transport: Connected (version 2.0, client OpenSSH_7.9p1)
2020-11-10 21:53:28,307  INFO       paramiko.transport: Authentication (password) successful!
2020-11-10 21:53:28,441  INFO       |-->QuerySSH: Query execution successful.

Logger configuration update:

logging.basicConfig(
            level=logging.INFO,
            format='%(asctime)s  %(levelname)-10s %(name)s: %(message)s',
            handlers=[
                logging.StreamHandler(),
                logging.FileHandler(self.logging_handler)
            ]
        )

# Filter paramiko.transport debug and info from basic logging configuration
logger_descope = logging.getLogger('paramiko.transport')
logger_descope.setLevel(logging.WARN)

And result I am happy with looks like this:

2020-11-10 22:00:48,755  INFO       |-->QuerySSH: Query execution successful.

Yearning