3

Very often when writing framework code, I would prefer the caller's line number and file name to be logged. For example, if I detect improper use of a framerwork level API call, I would like to log that.... not as an in-framework error but as "caller error".

This only comes into play when writing low level libraries and systems that use introspectionn.

Is there any way to get the logger to log "one level up"? Can I create a custom LogRecord and then modify it and use it within the installed loggers somehow? Trying to figure this out.

For example something like this:

def set(self, x):
   if x not in self._cols:
      log.error("Invalid attribute for set", stack_level=-1)
Erik Aronesty
  • 11,620
  • 5
  • 64
  • 44

3 Answers3

3

OK, I figured this out for python prior to 3.8:

First, you need to use inspect to get the frame. Then modify the extra= parameter in log with the info. But you also have to override makerecord to prevent the inappropriate guards that prevent log from working filename and linenumber overrides.

def myMakeRecord(self, name, level, fn, lno, msg, args, exc_info, func, extra, sinfo):
    rv = logging.LogRecord(name, level, fn, lno, msg, args, exc_info, func, sinfo)
    if extra is not None:
        rv.__dict__.update(extra)
    return rv

def mylog(logger, msg, level, *args)
    logging.Logger.makeRecord = myMakeRecord
    frame = inspect.currentframe()
    caller = frame.f_back
    override = {
        "lineno":caller.f_lineno,
        "filename":os.path.basename(caller.f_code.co_filename),
    }
    logger.log(level, msg, extra=override, *args)

Oddly, I couldn't get this to work when extra and sinfo had default values of none (like they do in the original definition). Maybe myMakeRecord should use *args.... but that would require grabbing extra = args[9] ... which is odd.... but maybe less bad (more likely to be future proof).

Erik Aronesty
  • 11,620
  • 5
  • 64
  • 44
3

This is easy to find on google now since it was added to python 3.8, and it was mentioned in the other answer but here is a better explanation. You were close with the stack_level argument, but it should be stacklevel and the value should be 2. For example you can do:

import logging

def fun():
    logging.basicConfig(format='line %(lineno)s : %(message)s')
    log = logging.getLogger(__name__)
    log.error('Something is wrong', stacklevel=2)

if __name__ == '__main__':
    fun()

This will output:

line 9 : Something is wrong

If the stacklevel was set to the default of 1, it would output:

line 6 : Something is wrong

From the documentation: https://docs.python.org/3/library/logging.html#logging.Logger.debug

The third optional keyword argument is stacklevel, which defaults to 1. If greater than 1, the corresponding number of stack frames are skipped when computing the line number and function name set in the LogRecord created for the logging event. This can be used in logging helpers so that the function name, filename and line number recorded are not the information for the helper function/method, but rather its caller. The name of this parameter mirrors the equivalent one in the warnings module.

Karl Molina
  • 93
  • 8
1

I did the same as Erik, but with some changes:

import logging
import inspect
from os import path

loggers_dict = {}


def myMakeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):
    if extra and 'pathname' in extra:
        fn = extra.pop('pathname')
    rv = logging.LogRecord(name, level, fn, lno, msg, args, exc_info, func)
    if extra is not None:
        rv.__dict__.update(extra)
    return rv


logging.Logger.makeRecord = myMakeRecord


def getLogger():
    fn, lno, func = base_logger.findCaller()
    extras = {'pathname': fn, 'lineno': lno, 'funcName': func}
    fnn = path.normcase(fn)
    caller_name = inspect.modulesbyfile.get(fnn, inspect.getmodule(None, fn).__name__)

    if caller_name not in loggers_dict:
        loggers_dict[caller_name] = logging.getLogger(caller_name)
    return loggers_dict[caller_name], extras


def myLogDebug(*msg):
    log, extras = getLogger()
    if len(msg) == 1:
        log.debug(msg[0], extra=extras)
    else:
        log.debug(' '.join(map(str, msg)), extra=extras)

The main thing here is the legacy, everywhere people has put the call myLogDebug on the code, then would be a messy if I change everything. Other problem was the python 2.7 version, would be nice if I could use the param stacklevel from this thread.

Then I modified some stuff to get the right caller stack frame level, and doesn't change anything from original method.

EDIT - 1

caller_name = inspect.modulesbyfile.get(fnn, inspect.getmodule(None, fn).__name__)

This part is an little hack, just to don't run all the time getmodule from inspect module. There is an dict (an inside cache modulesbyfile) who gets direct access to module names after first getmodule.

Sometimes debug an track the source helps, it's not documented.

meszias
  • 91
  • 1
  • 4