4
\$\begingroup\$

I use the below code to include context specific information in logging record (see obj).

import logging

def setup_logging():
    logger = logging.getLogger('sample')
    logger.setLevel(logging.INFO)

    f = logging.Formatter(
        "%(asctime)s | %(levelname)-7s | %(funcName)-10s | %(obj)-20s | %(message)s")
    s = logging.StreamHandler()
    s.setFormatter(f)

    logger.addHandler(s)
    logger.addFilter(ContextFilter())
    return logger

class ContextFilter(logging.Filter):
    def filter(self, record):
        record.obj = getattr(record, "obj", "")
        return True

class ContextLogger:
    def __init__(self, logger, obj):
        self.logger = logger
        self.obj = obj

    def log(self, msg, level=logging.INFO):
        log_func = {
            logging.INFO: self.logger.info,
            logging.WARN: self.logger.warn,
            logging.ERROR: self.logger.error,
            logging.DEBUG: self.logger.debug,
        }
        log_func[level](msg, extra={"obj": self.obj})

    def info(self, msg):
        self.log(msg, logging.INFO)

    def error(self, msg):
        self.log(msg, logging.ERROR)
    
    def warn(self, msg):
        self.log(msg, logging.WARN)

    def debug(self, msg):
        self.log(msg, logging.DEBUG)

The information is recorded in each class via __repr__ dunder method.

Example

class B:
    def __init__(self, a, b, logger):
        self.a = a
        self.b = b
        self.logger = logger
        self.logger_ = ContextLogger(logger, self)
        self.logger.info('plain info')
        self.logger_.info('context info')

    def __repr__(self):
        return f"a: {self.a}"
    
    def method(self):
        try:
            return float('a')
        except Exception as e:
            self.logger_.error(e)

def f(logger):
    b1 = B('Joe', 48, logger)
    b1.method()

def start():
    logger = setup_logging()
    logger.info('here')
    f(logger)

start()

Output

2023-08-08 13:13:02,494 | INFO    | start      |                      | here
2023-08-08 13:13:02,499 | INFO    | __init__   |                      | plain info
2023-08-08 13:13:02,500 | INFO    | log        | a: Joe               | context info
2023-08-08 13:13:02,503 | ERROR   | log        | a: Joe               | could not convert string to float: 'a'

I am not particularly convinced about

  • need for logging level methods inside ContextLogger
  • need for separate classes for ContextLogger and ContextFilter
  • cost of initializing ContextLogger with each class instance
  • occupying __repr__ for the purpose of context
  • no support for ad hoc context value (e.g. logging.info('msg', 'alternative value'))
\$\endgroup\$

1 Answer 1

Reset to default
1
\$\begingroup\$ 
import logging

Yay! You use a familiar interface. So we already know how to use it.

def setup_logging():

A typical initial call would be to logging.basicConfig() (which of course uses old-style / inconsistent camelCase for historic reasons). Consider naming this def basic_config, or setup_config, as a hint to the Gentle Reader that they should start here.

    logger.setLevel(logging.INFO)

Consider making INFO a keyword default parameter in the signature. So folks can easily call the function without giving it much thought, but then can adjust the level to taste when they're grappling with a debugging session.

    def filter(self, record):

The constant True return value is just fine, of course, though slightly surprising. Consider adding a # comment or """docstring""" that mentions we "evaluate this for side effects".

... not particularly convinced about ... need for separate class for ... ContextFilter

Well, you kind of have to code it as you did, since you're conforming to a public API that you can't change.

But let's take a step back. The whole "filter nothing while imposing side effects" aspect seems a bit strained, not a natural way to express Author's Intent. The .obj attribute is used later on:

        log_func[level](msg, extra={"obj": self.obj})

Why not do the getattr() at that point? With side effects, or without, on the .obj attribute.

The four {debug, info, warn, error} helpers seem a bit tedious. I'm not sure they're pulling their weight.

Couldn't we have a single helper, which we pass the log level into?

    def __init__(self, a, b, logger):

No, passing in a logger is just weird. Please reconsider that decision. Typically a logger is part of the global (or module-level) environment.

        self.logger = logger
        self.logger_ = ContextLogger(logger, self)

Those are distinct names. But we really need a better name, perhaps .ctx_logger

In __repr__(), it's unclear why we ignore b. It's a pretty generic identifier, so we're missing some review context. Surely the original source code describes more interesting objects.

OIC, from f() it appears that (a, b) denotes (name, age).

    def method(self):
        try:
            return float('a')
        except Exception as e:
            self.logger_.error(e)

Maybe that's a typo, and author intended float(self.a) ? Or self.b if we're interested in "age". Without type hints in the signatures, it's hard to say.

This unconditionally errors, but I'll pretend that it sometimes returns a float.

Let's just gloss over method being the wrong name for this method; I assume that with more review context we would see the actual intent.

The return type for method is Union[float|None]. This seems Bad. Rather than offering a total function on all inputs, it would probably be better to offer a partial function which either raises or returns a float. To "handle" errors, via logging, seems ill advised. To fall off the bottom with implicit return None seems worse. Minimally, make the return value explicit, for the benefit of the Gentle Reader.

It's unclear how one should reason about the contract offered to the caller, and that seems to impact the overall design. It's usually better for higher layers to catch such errors, optionally log the event, and worry about remediation or simply do a re-raise.

Notice that exceptions carry lots of metadata. The inspect module can help you traverse the call stack to learn about the signature of the method which blew up.

This code base does not appear to achieve its design goals in a maintainable way, largely due to an odd design which favors low-level error handling. Better to catch errors further up the stack, and then inspect exception attributes to obtain the identical logging output which the current code produces.

\$\endgroup\$

You must log in to answer this question.