Python logging from multiple package hierarchies (without using root logger)

user_6078062 0
Viewed 677

I need to set up logging for a fairly specific setup. In short, I want to handle logging from a common piece of library code in two different "parent" modules.

  app_one \
     app_one_main.py
  app_two \
     app_two_main.py
  lib_package \
     lib_module.py

Both app_one_main and app_two_main import lib_module (code below).

These modules obviously do not share the same package structure, so logging messages from lib_module won't propagate up to app_one or app_two by default, if I'm using getLogger(__name__)

Restrictions

  • Both app_one and app_two will be running in the same Python session, so I can't globally manipulate the hierarchy of the logger in lib_module.
  • I can't manipulate the global root logger because of the way my code is integrated into a larger system.
  • app_one and app_two have different handlers. For instance, they write their logs to different files.

Some Ideas

  1. This answer suggests passing a parent logger into functions of the library code. This would work, I guess, but it would break almost all of my existing code and I'm not thrilled about passing around loggers this way.
  2. I could subclass logging.Logger and override Logger.parent such that it finds any loggers in its enclosing scopes. I've implemented something similar in the past, but it seems a bit over-engineered and it would break a lot of features of the default logging system.

Code

(this code does not even pretend to work. It's just a rough starting place.)

# app_one_main.py

import logging
from lib_package import lib_module

logger = logging.getLogger(__name__)

stream_handler = logging.StreamHandler()
stream_handler.setFormatter(logging.Formatter("APP ONE: %(message)s"))
logger.addHandler(stream_handler)

def log_app_one():
    logger.warning("hello from app_one_main")
    lib_module.do_the_thing()

# app_two_main.py

import logging
from lib_package import lib_module

logger = logging.getLogger(__name__)

stream_handler = logging.StreamHandler()
stream_handler.setFormatter(logging.Formatter("APP TWO: %(message)s"))
logger.addHandler(stream_handler)

def log_app_two():
    logger.warning("hello from app_two_main")
    lib_module.do_the_thing()

# lib_module.py

import logging

logger = logging.getLogger(__name__)

def do_the_thing():
    logger.warning("hello from library code")

Desired Result

app_one and app_two will ultimately run on another platform like Maya, which provides a single python session. Both modules will be imported into that same session.

So, if I ran app_one_main.log_app_one(), I would want:

APP ONE: hello from app_one_main
APP ONE: hello from library code

And app_two_main.log_app_two():

APP TWO: hello from app_two_main
APP TWO: hello from library code
logging packaging python
2 Answers

The primary problem is that you are instantiating Logger objects directly instead of using getLogger to get them for you. The Logger objects doc says Loggers should NEVER be instantiated directly, but always through the module-level function logging.getLogger(name). When getLogger creates a Logger it also inserts it into the logging hierarchy so that they can be configured by others. You just have free floating Logger objects.

Your library logger is called lib_package.lib_module. Once you move to getLogger any other module can get the package logger lib_package, configure it, and then any of its sub loggers will also work.

app_one_main.py

import logging
from lib_package import lib_module

# setup logging output for this module
stream_handler = logging.StreamHandler()
stream_handler.setFormatter(logging.Formatter("APP ONE: %(message)s"))
logger = logging.getLogger(__name__)
#logger.setLevel(logging.INFO)
logger.addHandler(stream_handler)

# add handler other modules / packages
pkg_logger = logging.getLogger('lib_package')
pkg_logger.addHandler(stream_handler)
#pkg_logger.setLevel(logging.INFO)
del pkg_logger

logger.warning("hello from app_one_main")
lib_module.do_the_thing()

lib_package/lib_module.py

# lib_module.py

import logging

logger = logging.getLogger(__name__)

def do_the_thing():
    logger.warning("hello from library code")
user_6420700

This is where I've landed.

Overview

I'm creating a common logger for all of my tools to use, and a new Filter subclass for handlers that live on it. The filter ensures that only messages that originated from dependencies of the same parent module as the filter itself will be handled. Theoretically, you could use this Filter class and the stack lookup mechanism on the root logger instead of this "base logger".

Code

custom_logging module

The special sauce is in StackFilter. It compares the modules in the current execution stack to one stored on instantiation. There might be some edge cases where this won't work, but I haven't found them yet.

import logging
import inspect

# Loggers
BASE_LOGGER_NAME = "_base_logger_"

def get_base_logger():
    return logging.getLogger(BASE_LOGGER_NAME)

def get_logger(name):
    return logging.getLogger(BASE_LOGGER_NAME + "." + name)


# Filtering
class StackFilter(logging.Filter):
    def __init__(self):
        self.stack = set(enclosing_modules())
        super(StackFilter, self).__init__()

    def filter(self, record):
        calling_stack = set(enclosing_modules())
        return self.stack.issubset(calling_stack)

def enclosing_modules():
    frame = inspect.currentframe()

    frame_count = 0
    _frame = frame
    while _frame:
        frame_count += 1
        _frame = _frame.f_back
    mods = [None] * frame_count

    i = 0
    while frame:
        try:
            mods[i] = frame.f_globals["__name__"]
        except:
            pass
        i += 1
        frame = frame.f_back

    return mods

# Logging Handlers
def add_console_output(formatter=None):
    base_logger = get_base_logger()
    handler = logging.StreamHandler()
    if formatter:
        handler.setFormatter(formatter)
    handler.addFilter(StackFilter())
    base_logger.addHandler(handler)

The rest of the code is very similar to the original question, but I added a new module to check my work.

fake_maya/fake_maya_main.py

this will play the part of Maya today, just a place where my various tools will be imported and run.

from app_one import app_one_main
from app_two import app_two_main

app_one_main.log_it()
app_two_main.log_it()

app_one/app_one_main.py

from lib_package import lib_module
import logging
import custom_logging

logger = custom_logging.get_logger(__name__)
formatter = logging.Formatter("APP ONE: %(message)s")
custom_logging.add_console_output(formatter)

def log_it():
    logger.warning("hello from app_one_main")
    lib_module.do_the_thing()

app_two/app_two_main.py

from lib_package import lib_module
import logging
import custom_logging

logger = custom_logging.get_logger(__name__)
formatter = logging.Formatter("APP TWO: %(message)s")
custom_logging.add_console_output(formatter)

def log_it():
    logger.warning("hello from app_two_main")
    lib_module.do_the_thing()

lib_package.lib_module.py

import custom_logging

logger = custom_logging.get_logger(__name__)

def do_the_thing():
    logger.warning("hello from library code")
user_60780620
Related