I am building logging into a python app, and I would like it to be human-readable. At the moment, the debug logs document every function that is called, with argument and return values. This means that practically, a debug log for a nested function call might look like this:
2024-07-29 16:52:26,641: DEBUG: MainController.initialize_components called with args <controllers.main_controller.MainController(0x1699fdcdda0) at 0x000001699F793300>
2024-07-29 16:52:26,643: DEBUG: MainController.setup_connections called with args <controllers.main_controller.MainController(0x1699fdcdda0) at 0x000001699F793300>
2024-07-29 16:52:26,645: DEBUG: MainController.setup_connections returned None
2024-07-29 16:52:26,646: DEBUG: MainController.initialize_components returned None
I would like to make it obvious from reading the logs when things are nested, using indentation, python-style. So the ideal output would be this:
2024-07-29 16:52:26,641: DEBUG: MainController.initialize_components called with args <controllers.main_controller.MainController(0x1699fdcdda0) at 0x000001699F793300>
2024-07-29 16:52:26,643: DEBUG: MainController.setup_connections called with args <controllers.main_controller.MainController(0x1699fdcdda0) at 0x000001699F793300>
2024-07-29 16:52:26,645: DEBUG: MainController.setup_connections returned None
2024-07-29 16:52:26,646: DEBUG: MainController.initialize_components returned None
I am currently achieving my documentation by wrapping class methods with this decorator:
import functools
import logging
def log(_func=None, *, logger):
def decorator_log(func):
@functools.wraps(func)
def wrapper(*args, **kwargs):
if logger.handlers:
current_formatter = logger.handlers[0].formatter
current_formatter.set_tabs(current_formatter.get_tabs() + 1)
self = args[0]
name = f'{self.__class__.__name__}.{func.__name__}'
if logger.root.level < logging.DEBUG:
logger.info(f"Entering {name}")
else:
args_repr = [repr(a) for a in args]
kwargs_repr = [f"{k}={v!r}" for k, v in kwargs.items()]
signature = ", ".join(args_repr + kwargs_repr)
logger.debug(f"{name} called with args {signature}")
try:
result = func(*args, **kwargs)
except Exception as e:
logger.exception(f"Exception raised in {name}: {str(e)}")
raise e
if logger.root.level < logging.DEBUG:
logger.info(f"Leaving {name}")
else:
logger.debug(f"{name} returned {result}")
if logger.handlers:
current_formatter = logger.handlers[0].formatter
current_formatter.set_tabs(current_formatter.get_tabs() - 1)
return result
return wrapper
if _func is None:
return decorator_log
else:
return decorator_log(_func)
I could add an attribute tabs to the logger with setattr and incremement at the start/decrement at the end of the decorator, but this only applies the tabs to the message portion of the output, like so:
2024-07-29 16:52:26,641: DEBUG: MainController.initialize_components called with args <controllers.main_controller.MainController(0x1699fdcdda0) at 0x000001699F793300>
2024-07-29 16:52:26,643: DEBUG: MainController.setup_connections called with args <controllers.main_controller.MainController(0x1699fdcdda0) at 0x000001699F793300>
2024-07-29 16:52:26,645: DEBUG: MainController.setup_connections returned None
2024-07-29 16:52:26,646: DEBUG: MainController.initialize_components returned None
Which is better than nothing, but not quite what I want. How can I update this (ideally without using a global variable) to have variable indentation at the start of each line of logger output?
I ended up using a not quite global variable to achieve this by setting an attribute directing in logging.root:
setattr(logging.root, 'indent', 0)
setattr(logging.root, 'tab_spaces', 4)
setattr(logging.root, 'extra', {'tabs': ' '*(0)})
logging.basicConfig(level=logging.INFO, format="%(tabs)%(asctime)s: %(levelname)s:s%(message)s")
formatter = logging.Formatter("%%(tabs)(asctime)s: %(levelname)s:%(message)s", defaults={'tabs': ''})
root_logger = logging.getLogger()
#console logger
consoleHandler = logging.StreamHandler()
consoleHandler.setFormatter(formatter)
root_logger.addHandler(consoleHandler)
the log_decorator now updates that property to maintain a globally accessible record of the local indentation level
def log(_func=None, *, logger):
def decorator_log(func):
@functools.wraps(func)
def wrapper(*args, **kwargs):
try:
indent = logger.root.indent
tab_spaces = logger.root.tab_spaces
tabs = ' '*(indent * tab_spaces)
logger.root.indent += 1
subtabs = ' '*((indent+1) * tab_spaces)
logger.root.extra = {'tabs': subtabs}
self = args[0]
name = f'{self.__class__.__name__}.{func.__name__}'
if logger.root.level > logging.DEBUG:
logger.info(f"Entering {name}", extra={'tabs': tabs})
else:
args_repr = [repr(a) for a in args]
kwargs_repr = [f"{k}={v!r}" for k, v in kwargs.items()]
signature = ", ".join(args_repr + kwargs_repr)
logger.debug(f"{name} called with args ({signature})", extra={'tabs': tabs})
except:
pass
try:
result = func(*args, **kwargs)
except Exception as e:
logger.exception(f"Exception raised in {name}: {str(e)}", extra={'tabs': tabs})
raise e
else:
if logger.root.level > logging.DEBUG:
logger.info(f"Leaving {name}", extra={'tabs': tabs})
else:
logger.debug(f"{name} returned ({result})", extra={'tabs': tabs})
logger.root.indent -= 1
return result
return wrapper
if _func is None:
return decorator_log
else:
return decorator_log(_func)
Now, any time you want to log something in a class and respect the local indentation level, get the logger as a class variable and call it with the extra arg.
def DummyClass():
logger = logging.getLogger(__name__)
...
logger.info('msg', extra=self.logger.root.extra)
Not pretty, but it works and will not throw errors if you decide not to respect the indentation.
NOTE: this is -very- not thread safe