Отображение правильного имени funcName при использовании функции логгера в пользовательском классе

Это строка форматирования, которую я использую для ведения журнала:

'%(asctime)s - %(levelname)-10s - %(funcName)s - %(message)s'

Но чтобы показать сообщения о регистрации, у меня есть обертка, делающая немного больше (я настраиваю разные уровни журналов, настраиваю различные бэкэнды ведения журнала, предоставляю удобные функции для доступа к пользовательским уровням и т.д.):

class MyLogger(logging.Logger):

    def split_line(self, level, message):
        ....
        self.log.(level, line)

    def progress(self, message):
        self.split_line(PROGRESS, message)

С этой настройкой всякий раз, когда я записываю что-то:

def myfunc():
    log.progress('Hello')

Я получаю:

013-10-27 08:47:30,130 - PROGRESS   - split_line - Hello

Это не то, что я хотел, а именно:

013-10-27 08:47:30,130 - PROGRESS   - myfunc     - Hello

Как я могу сказать регистратору использовать правильный контекст для имени функции? Я думаю, что это будет на самом деле на два уровня выше на стеке.

ИЗМЕНИТЬ

Это тестовая программа, показывающая проблему:

import sys
import logging

PROGRESS = 1000

class MyLogger(logging.Logger):

    PROGRESS = PROGRESS
    LOG_FORMATTER = '%(asctime)s - %(levelname)-10s - %(funcName)s - %(message)s'
    DEF_LOGGING_LEVEL = logging.WARNING

    def __init__(self, log_name, level=None):
        logging.Logger.__init__(self, log_name)
        self.formatter = logging.Formatter(self.LOG_FORMATTER)
        self.initLogger(level)

    def initLogger(self, level=None):
        self.setLevel(level or self.DEF_LOGGING_LEVEL)
        self.propagate = False

    def add_handler(self, log_file, use_syslog):
        if use_syslog : hdlr = logging.handlers.SysLogHandler(address='/dev/log')
        elif log_file : hdlr = logging.FileHandler(log_file)
        else          : hdlr = logging.StreamHandler(sys.stderr)
        hdlr.setFormatter(self.formatter)
        self.addHandler(hdlr)
        return hdlr

    def addHandlers(self, log_file=None, progress_file=None, use_syslog=False):
        self.logger_hdlr = self.add_handler(log_file, use_syslog)
        if progress_file:
            self.progress_hdlr = self.add_handler(progress_file, use_syslog)
            self.progress_hdlr.setLevel(self.PROGRESS)
        else:
            self.progress_hdlr = None

    def split_line(self, level, txt, *args):
        txt = txt % (args)
        for line in txt.split('\n'):
            self.log(level, line)

    def progress(self, txt, *args):
        self.split_line(self.PROGRESS, txt, *args)

logging.setLoggerClass(MyLogger)
logging.addLevelName(PROGRESS, 'PROGRESS')
logger = logging.getLogger(__name__)
logger.addHandlers()

name = 'John'
logger.progress('Hello %s\nHow are you doing?', name)

Выдает:

2013-10-27 09:47:39,577 - PROGRESS   - split_line - Hello John
2013-10-27 09:47:39,577 - PROGRESS   - split_line - How are you doing?

Ответы

Ответ 1

По существу, код, который виноват, лежит в классе Logger:

Этот метод

def findCaller(self):
    """
    Find the stack frame of the caller so that we can note the source
    file name, line number and function name.
    """
    f = currentframe()
    #On some versions of IronPython, currentframe() returns None if
    #IronPython isn't run with -X:Frames.
    if f is not None:
        f = f.f_back
    rv = "(unknown file)", 0, "(unknown function)"
    while hasattr(f, "f_code"):
        co = f.f_code
        filename = os.path.normcase(co.co_filename)
        if filename == _srcfile:
            f = f.f_back
            continue
        rv = (co.co_filename, f.f_lineno, co.co_name)
        break
    return rv

возвращает первую функцию в цепочке вызывающих, которая не принадлежит текущему модулю.

Вы можете подклассифицировать Logger и переопределить этот метод, добавив немного более сложную логику. пропуская другой уровень глубины вызова или добавляя другое условие.

В вашем особом случае, вероятно, будет проще воздержаться от автоматического разделения линии и сделать

logger.progress('Hello %s', name)
logger.progress('How are you doing?')

или сделать

def splitter(txt, *args)
    txt = txt % (args)
    for line in txt.split('\n'):
        yield line

for line in splitter('Hello %s\nHow are you doing?', name):
    logger.progress(line)

и иметь

def progress(self, txt, *args):
    self.log(self.PROGRESS, txt, *args)

Вероятно, это сэкономит вам много головной боли.

ИЗМЕНИТЬ 2: Нет, это не поможет. Теперь он покажет вам progress как имя вашей вызывающей функции...

Ответ 2

Спасибо @cygnusb и другим, которые уже предоставили полезные указатели. Я решил использовать метод Python 3.4 Logger.findCaller в качестве отправной точки. Следующее решение было протестировано с Python 2.7.9 и 3.4.2. Этот код предназначен для размещения в его собственном модуле. Он дает правильный ответ только с одной итерацией цикла.

import io
import sys

def _DummyFn(*args, **kwargs):
    """Placeholder function.

    Raises:
        NotImplementedError
    """
    _, _ = args, kwargs
    raise NotImplementedError()

# _srcfile is used when walking the stack to check when we've got the first
# caller stack frame, by skipping frames whose filename is that of this
# module source. It therefore should contain the filename of this module's
# source file.
_srcfile = os.path.normcase(_DummyFn.__code__.co_filename)
if hasattr(sys, '_getframe'):
    def currentframe():
        return sys._getframe(3)
else:  # pragma: no cover
    def currentframe():
        """Return the frame object for the caller stack frame."""
        try:
            raise Exception
        except Exception:
            return sys.exc_info()[2].tb_frame.f_back

class WrappedLogger(logging.Logger):
    """Report context of the caller of the function that issues a logging call.

    That is, if

        A() -> B() -> logging.info()

    Then references to "%(funcName)s", for example, will use A context
    rather than B context.

    Usage:
        logging.setLoggerClass(WrappedLogger)
        wrapped_logging = logging.getLogger("wrapped_logging")
    """
    def findCaller(self, stack_info=False):
        """Return the context of the caller parent.

        Find the stack frame of the caller so that we can note the source
        file name, line number and function name.

        This is based on the standard python 3.4 Logger.findCaller method.
        """
        sinfo = None
        f = currentframe()
        # On some versions of IronPython, currentframe() returns None if
        # IronPython isn't run with -X:Frames.
        if f is not None:
            f = f.f_back

        if sys.version_info.major == 2:
            rv = "(unknown file)", 0, "(unknown function)"
        else:
            rv = "(unknown file)", 0, "(unknown function)", sinfo

        while hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
            if filename == _srcfile or filename == logging._srcfile:
                f = f.f_back
                continue
            # We want the frame of the caller of the wrapped logging function.
            # So jump back one more frame.
            f = f.f_back
            co = f.f_code
            if sys.version_info.major == 2:
            rv = "(unknown file)", 0, "(unknown function)"
        else:
            rv = "(unknown file)", 0, "(unknown function)", sinfo

        while hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
            if filename == _srcfile or filename == logging._srcfile:
                f = f.f_back
                continue
            # We want the frame of the caller of the wrapped logging function.
            # So jump back one more frame.
            f = f.f_back
            co = f.f_code
            if sys.version_info.major == 2:
                rv = co.co_filename, f.f_lineno, co.co_name
            else:
                if stack_info:
                    sio = io.StringIO()
                    sio.write('Stack (most recent call last):\n')
                    traceback.print_stack(f, file=sio)
                    sinfo = sio.getvalue()
                    if sinfo[-1] == '\n':
                        sinfo = sinfo[:-1]
                    sio.close()
                rv = co.co_filename, f.f_lineno, co.co_name, sinfo
            break

        return rv

Ответ 3

Прежде всего, согласно вашему коду, понятно, почему это происходит, levelname и funcName "принадлежит" self.log, поэтому, когда вы вызываете self.log(level, line), levelname есть level и funcName line.

У вас есть 2 варианта ИМХО:

Чтобы использовать модуль inspect, чтобы получить текущий метод и доставить его внутри сообщения, вы можете проанализировать его и использовать его очень легко.
Лучшим подходом будет использование inspect внутри split_line для получения метода "отец" вы можете изменить число (3) в следующем коде, чтобы "играть" с иерархией методов.

пример использования метода проверки для получения текущего метода

from inspect import stack

class Foo:
    def __init__(self):
        print stack()[0][3]

f = Foo()

Ответ 4

Вы можете объединить метод progress и метод split_line:

def progress(self, txt, *args, **kwargs):
    if self.isEnabledFor(self.PROGRESS):
        txt = txt % (args)
        for line in txt.split('\n'):
            self._log(self.PROGRESS, line, [], **kwargs)

Ответ 5

Как было предложено в первом ответе, подклассификация класса Logger и использование logging.setLoggerClass должны сделать трюк. Вам понадобится модифицированная функция findCaller, которая обрабатывает ваши завернутые функциональные вызовы.

Поместите следующее в модуль, так как метод класса findCaller выполняет поиск первого вызова из файла, который не является текущим исходным именем файла.

import inspect
import logging
import os

if hasattr(sys, 'frozen'): #support for py2exe
    _srcfile = "logging%s__init__%s" % (os.sep, __file__[-4:])
elif __file__[-4:].lower() in ['.pyc', '.pyo']:
    _srcfile = __file__[:-4] + '.py'
else:
    _srcfile = __file__
_srcfile = os.path.normcase(_srcfile)

class WrappedLogger(logging.Logger):
    def __init__(self,name):
        logging.Logger.__init__(self, name)

    def findCaller(self):
        """
        Find the stack frame of the caller so that we can note the source
        file name, line number and function name.
        """
        # get all outer frames starting from the current frame
        outer = inspect.getouterframes(inspect.currentframe())
        # reverse the order, to search from out inward
        outer.reverse()
        rv = "(unknown file)", 0, "(unknown function)"    

        pos = 0
        # go through all frames
        for i in range(0,len(outer)):
            # stop if we find the current source filename
            if outer[i][1] == _srcfile:
                # the caller is the previous one
                pos=i-1
                break

        # get the frame (stored in first tuple entry)
        f = outer[pos][0]

        co = f.f_code
        rv = (co.co_filename, f.f_lineno, co.co_name)

        return rv
# Usage:
logging.setLoggerClass(WrappedLogger)
log = logging.getLogger("something")

Ответ 6

Кто-то дал правильный ответ. Я сделаю резюме.

logging.Logger.findCaller(), он фильтрует фреймы стека с помощью logging._srcfile в оригинальном пакете logging.

Таким образом, мы делаем то же самое, фильтруем нашу собственную оболочку логгера my_log_module._srcfile. Мы динамически заменяем метод logging.Logger.findCaller() вашего экземпляра регистратора.

Кстати, пожалуйста, не создавайте подкласс logging.Logger, пакет logging не предназначен для ООП, когда findCaller, pitty... да?

# file: my_log_module.py, Python-2.7, define your logging wrapper here
import sys
import os
import logging
my_logger = logging.getLogger('my_log')

if hasattr(sys, '_getframe'): currentframe = lambda: sys._getframe(3)
# done filching

#
# _srcfile is used when walking the stack to check when we've got the first
# caller stack frame.
#
_srcfile = os.path.normcase(currentframe.__code__.co_filename)

def findCallerPatch(self, *args):
    """
    Find the stack frame of the caller so that we can note the source
    file name, line number and function name.
    """
    f = currentframe()
    #On some versions of IronPython, currentframe() returns None if
    #IronPython isn't run with -X:Frames.
    if f is not None:
        f = f.f_back
    rv = "(unknown file)", 0, "(unknown function)"
    while hasattr(f, "f_code"):
        co = f.f_code
        filename = os.path.normcase(co.co_filename)
        if filename == _srcfile:
            f = f.f_back
            continue
        rv = (co.co_filename, f.f_lineno, co.co_name)
        break
    return rv

# DO patch
my_logger.findCaller = findCallerPatch

Хорошо, все готово. Теперь вы можете использовать свой регистратор в других модулях, добавить формат сообщения регистрации: lino, путь, имя метода, blablabla

# file: app.py
from my_log_module import my_logger
my_logger.debug('I can check right caller now')

Или вы можете использовать элегантный способ, но не используйте глобальный logging.setLoggerClass

# file: my_log_modue.py
import logging
my_logger = logging.getLogger('my_log')

class MyLogger(logging.Logger):
    ...

my_logger.__class__ = MyLogger

Ответ 7

Благодаря @glglgl я мог придумать продвинутый поиск findCaller

Обратите внимание, что инициализация _logging_srcfile и _this_srcfile - вдохновлена исходным кодом протокола python

Конечно, вы можете поместить свои собственные правила в findCaller() - здесь я просто исключаю все из файла, где находится пользовательский регистратор, ИСКЛЮЧАЕТ функцию test_logging.

ВАЖНО пользовательский регистратор извлекается только при передаче имени в getLogger(name) factory. Если вы просто выполните logging.getLogger(), вы получите RootLogger, который не является вашим регистратором.

import sys
import os
import logging
# from inspect import currentframe
currentframe = lambda: sys._getframe(3)
_logging_srcfile = os.path.normcase(logging.addLevelName.__code__.co_filename)
_this_srcfile = __file__


def test_logging():
    logger = logging.getLogger('test')
    handler = logging.StreamHandler(sys.stderr)
    handler.setFormatter(logging.Formatter('%(funcName)s: %(message)s'))
    handler.setLevel(11)
    logger.addHandler(handler)
    logger.debug('Will not print')
    logger.your_function('Test Me')


class CustomLogger(logging.getLoggerClass()):
    def __init__(self, name, level=logging.NOTSET):
        super(CustomLogger, self).__init__(name, level)

    def your_function(self, msg, *args, **kwargs):
        # whatever you want to do here...
        self._log(12, msg, args, **kwargs)

    def findCaller(self):
        """
        Find the stack frame of the caller so that we can note the source
        file name, line number and function name.

        This function comes straight from the original python one
        """
        f = currentframe()
        # On some versions of IronPython, currentframe() returns None if
        # IronPython isn't run with -X:Frames.
        if f is not None:
            f = f.f_back
        rv = "(unknown file)", 0, "(unknown function)"
        while hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
            ## original condition
            # if filename == _logging_srcfile:
            ## PUT HERE YOUR CUSTOM CONDITION, eg:
            ## skip also this file, except the test_logging method which is used for debug
            if co.co_name != 'test_logging' and filename in [_logging_srcfile, _this_srcfile]:
                f = f.f_back
                continue
            rv = (co.co_filename, f.f_lineno, co.co_name)
            break
        return rv

logging.setLoggerClass(CustomLogger)