Cómo agregar un nivel de registro personalizado a la función de registro de Python

Me gustaría tener TRACE (5) de nivel de registro para mi aplicación, ya que no creo que debug()sea ​​suficiente. Además log(5, msg)no es lo que quiero. ¿Cómo puedo agregar un nivel de registro personalizado a un registrador de Python?

Tengo una mylogger.pycon el siguiente contenido:

import logging

@property
def log(obj):
    myLogger = logging.getLogger(obj.__class__.__name__)
    return myLogger

En mi código lo uso de la siguiente manera:

class ExampleClass(object):
    from mylogger import log

    def __init__(self):
        '''The constructor with the logger'''
        self.log.debug("Init runs")

Ahora me gustaria llamar self.log.trace("foo bar")

Gracias de antemano por tu ayuda.

Editar (8 de diciembre de 2016): cambié la respuesta aceptada a pfa que es, en mi humilde opinión, una excelente solución basada en la muy buena propuesta de Eric S.

@Eric S.

La respuesta de Eric S. es excelente, pero aprendí experimentando que esto siempre hará que los mensajes registrados en el nuevo nivel de depuración se impriman, independientemente del nivel de registro establecido. Por lo tanto, si crea un número de nivel nuevo 9, si llama setLevel(50), los mensajes de nivel inferior se imprimirán erróneamente.

Para evitar que eso suceda, necesita otra línea dentro de la función "debugv" para verificar si el nivel de registro en cuestión está realmente habilitado.

Ejemplo fijo que comprueba si el nivel de registro está habilitado:

import logging
DEBUG_LEVELV_NUM = 9 
logging.addLevelName(DEBUG_LEVELV_NUM, "DEBUGV")
def debugv(self, message, *args, **kws):
    if self.isEnabledFor(DEBUG_LEVELV_NUM):
        # Yes, logger takes its '*args' as 'args'.
        self._log(DEBUG_LEVELV_NUM, message, args, **kws) 
logging.Logger.debugv = debugv

Si nos fijamos en el código para class Loggeren logging.__init__.pypara Python 2.7, esto es lo que todas las funciones de registro estándar hacen (.critical, .debug, etc.).

Aparentemente, no puedo publicar respuestas a las respuestas de otros por falta de reputación ... espero que Eric actualice su publicación si ve esto. =)

Tomé la respuesta "evitar ver lambda" y tuve que modificar dónde se estaba agregando log_at_my_log_level. Yo también vi el problema que hizo Paul "No creo que esto funcione. ¿No necesitas logger como primer argumento en log_at_my_log_level?" Esto funcionó para mi

import logging
DEBUG_LEVELV_NUM = 9 
logging.addLevelName(DEBUG_LEVELV_NUM, "DEBUGV")
def debugv(self, message, *args, **kws):
    # Yes, logger takes its '*args' as 'args'.
    self._log(DEBUG_LEVELV_NUM, message, args, **kws) 
logging.Logger.debugv = debugv

Combinando todas las respuestas existentes con un montón de experiencia de uso, creo que he elaborado una lista de todas las cosas que se deben hacer para garantizar un uso completamente fluido del nuevo nivel. Los pasos a continuación asumen que está agregando un nuevo nivel TRACEcon valor logging.DEBUG - 5 == 5:

1. logging.addLevelName(logging.DEBUG - 5, 'TRACE') debe invocarse para que el nuevo nivel se registre internamente para que se pueda hacer referencia a él por su nombre.
2. El nuevo nivel necesita ser añadido como un atributo a loggingsí mismo para mantener la coherencia: logging.TRACE = logging.DEBUG - 5.
3. Es tracenecesario agregar un método llamado al loggingmódulo. Se debe comportarse igual debug, info, etc.
4. Es tracenecesario agregar un método llamado a la clase de registrador configurada actualmente. Dado que esto no está 100% garantizado logging.Logger, utilícelo logging.getLoggerClass()en su lugar.

Todos los pasos se ilustran en el método siguiente:

def addLoggingLevel(levelName, levelNum, methodName=None):
    """
    Comprehensively adds a new logging level to the `logging` module and the
    currently configured logging class.

    `levelName` becomes an attribute of the `logging` module with the value
    `levelNum`. `methodName` becomes a convenience method for both `logging`
    itself and the class returned by `logging.getLoggerClass()` (usually just
    `logging.Logger`). If `methodName` is not specified, `levelName.lower()` is
    used.

    To avoid accidental clobberings of existing attributes, this method will
    raise an `AttributeError` if the level name is already an attribute of the
    `logging` module or if the method name is already present 

    Example
    -------
    >>> addLoggingLevel('TRACE', logging.DEBUG - 5)
    >>> logging.getLogger(__name__).setLevel("TRACE")
    >>> logging.getLogger(__name__).trace('that worked')
    >>> logging.trace('so did this')
    >>> logging.TRACE
    5

    """
    if not methodName:
        methodName = levelName.lower()

    if hasattr(logging, levelName):
       raise AttributeError('{} already defined in logging module'.format(levelName))
    if hasattr(logging, methodName):
       raise AttributeError('{} already defined in logging module'.format(methodName))
    if hasattr(logging.getLoggerClass(), methodName):
       raise AttributeError('{} already defined in logger class'.format(methodName))

    # This method was inspired by the answers to Stack Overflow post
    # http://stackoverflow.com/q/2183233/2988730, especially
    # http://stackoverflow.com/a/13638084/2988730
    def logForLevel(self, message, *args, **kwargs):
        if self.isEnabledFor(levelNum):
            self._log(levelNum, message, args, **kwargs)
    def logToRoot(message, *args, **kwargs):
        logging.log(levelNum, message, *args, **kwargs)

    logging.addLevelName(levelNum, levelName)
    setattr(logging, levelName, levelNum)
    setattr(logging.getLoggerClass(), methodName, logForLevel)
    setattr(logging, methodName, logToRoot)

Esta pregunta es bastante antigua, pero simplemente traté el mismo tema y encontré una forma similar a las ya mencionadas que me parece un poco más limpia. Esto se probó en 3.4, por lo que no estoy seguro de si los métodos utilizados existen en versiones anteriores:

from logging import getLoggerClass, addLevelName, setLoggerClass, NOTSET

VERBOSE = 5

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

        addLevelName(VERBOSE, "VERBOSE")

    def verbose(self, msg, *args, **kwargs):
        if self.isEnabledFor(VERBOSE):
            self._log(VERBOSE, msg, args, **kwargs)

setLoggerClass(MyLogger)

¿Quién inició la mala práctica de usar métodos internos ( self._log) y por qué cada respuesta se basa en eso? La solución pitónica sería usar self.logen su lugar para que no tenga que meterse con ninguna cosa interna:

import logging

SUBDEBUG = 5
logging.addLevelName(SUBDEBUG, 'SUBDEBUG')

def subdebug(self, message, *args, **kws):
    self.log(SUBDEBUG, message, *args, **kws) 
logging.Logger.subdebug = subdebug

logging.basicConfig()
l = logging.getLogger()
l.setLevel(SUBDEBUG)
l.subdebug('test')
l.setLevel(logging.DEBUG)
l.subdebug('test')

Me resulta más fácil crear un nuevo atributo para el objeto del registrador que pasa la función log (). Creo que el módulo del registrador proporciona addLevelName () y log () por esta misma razón. Por lo tanto, no se necesitan subclases ni nuevos métodos.

import logging

@property
def log(obj):
    logging.addLevelName(5, 'TRACE')
    myLogger = logging.getLogger(obj.__class__.__name__)
    setattr(myLogger, 'trace', lambda *args: myLogger.log(5, *args))
    return myLogger

ahora

mylogger.trace('This is a trace message')

debería funcionar como se esperaba.

Si bien ya tenemos muchas respuestas correctas, lo siguiente es, en mi opinión, más pitónico:

import logging

from functools import partial, partialmethod

logging.TRACE = 5
logging.addLevelName(logging.TRACE, 'TRACE')
logging.Logger.trace = partialmethod(logging.Logger.log, logging.TRACE)
logging.trace = partial(logging.log, logging.TRACE)

Si desea usar mypyen su código, se recomienda agregar # type: ignorepara evitar que las advertencias agreguen atributos.

Creo que tendrás que crear una subclase de la Loggerclase y agregar un método llamado traceque básicamente llama Logger.logcon un nivel inferior a DEBUG. No he probado esto, pero esto es lo que indican los documentos .

Consejos para crear un registrador personalizado:

1. No use _log, use log(no tiene que verificar isEnabledFor)
2. el módulo de registro debe ser el que crea la instancia del registrador personalizado, ya que hace algo de magia getLogger, por lo que deberá configurar la clase a través desetLoggerClass
3. No necesita definir __init__para el registrador, clase si no está almacenando nada

# Lower than debug which is 10
TRACE = 5
class MyLogger(logging.Logger):
    def trace(self, msg, *args, **kwargs):
        self.log(TRACE, msg, *args, **kwargs)

Cuando llame a este registrador, utilice setLoggerClass(MyLogger)para convertirlo en el registrador predeterminado degetLogger

logging.setLoggerClass(MyLogger)
log = logging.getLogger(__name__)
# ...
log.trace("something specific")

Necesitará setFormatter, setHandlery setLevel(TRACE)en la handlery en la logmisma a SE realidad esta traza bajo nivel

Esto funcionó para mí:

import logging
logging.basicConfig(
    format='  %(levelname)-8.8s %(funcName)s: %(message)s',
)
logging.NOTE = 32  # positive yet important
logging.addLevelName(logging.NOTE, 'NOTE')      # new level
logging.addLevelName(logging.CRITICAL, 'FATAL') # rename existing

log = logging.getLogger(__name__)
log.note = lambda msg, *args: log._log(logging.NOTE, msg, args)
log.note('school\'s out for summer! %s', 'dude')
log.fatal('file not found.')

El problema lambda / funcName se soluciona con logger._log como señaló @marqueed. Creo que usar lambda parece un poco más limpio, pero el inconveniente es que no puede aceptar argumentos de palabras clave. Yo nunca lo he usado, así que no es problema.

  NOTA configuración: ¡la escuela terminó en verano! tipo
  Configuración FATAL: archivo no encontrado.

En mi experiencia, esta es la solución completa al problema de la operación ... para evitar ver "lambda" como la función en la que se emite el mensaje, profundice:

MY_LEVEL_NUM = 25
logging.addLevelName(MY_LEVEL_NUM, "MY_LEVEL_NAME")
def log_at_my_log_level(self, message, *args, **kws):
    # Yes, logger takes its '*args' as 'args'.
    self._log(MY_LEVEL_NUM, message, args, **kws)
logger.log_at_my_log_level = log_at_my_log_level

Nunca intenté trabajar con una clase de registrador independiente, pero creo que la idea básica es la misma (use _log).

Adición al ejemplo de Mad Physicists para obtener el nombre de archivo y el número de línea correctos:

def logToRoot(message, *args, **kwargs):
    if logging.root.isEnabledFor(levelNum):
        logging.root._log(levelNum, message, args, **kwargs)

basado en la respuesta fijada, escribí un pequeño método que crea automáticamente nuevos niveles de registro

def set_custom_logging_levels(config={}):
    """
        Assign custom levels for logging
            config: is a dict, like
            {
                'EVENT_NAME': EVENT_LEVEL_NUM,
            }
        EVENT_LEVEL_NUM can't be like already has logging module
        logging.DEBUG       = 10
        logging.INFO        = 20
        logging.WARNING     = 30
        logging.ERROR       = 40
        logging.CRITICAL    = 50
    """
    assert isinstance(config, dict), "Configuration must be a dict"

    def get_level_func(level_name, level_num):
        def _blank(self, message, *args, **kws):
            if self.isEnabledFor(level_num):
                # Yes, logger takes its '*args' as 'args'.
                self._log(level_num, message, args, **kws) 
        _blank.__name__ = level_name.lower()
        return _blank

    for level_name, level_num in config.items():
        logging.addLevelName(level_num, level_name.upper())
        setattr(logging.Logger, level_name.lower(), get_level_func(level_name, level_num))

config puede algo así:

new_log_levels = {
    # level_num is in logging.INFO section, that's why it 21, 22, etc..
    "FOO":      21,
    "BAR":      22,
}

Como alternativa a agregar un método adicional a la clase Logger, recomendaría usar el Logger.log(level, msg)método.

import logging

TRACE = 5
logging.addLevelName(TRACE, 'TRACE')
FORMAT = '%(levelname)s:%(name)s:%(lineno)d:%(message)s'


logging.basicConfig(format=FORMAT)
l = logging.getLogger()
l.setLevel(TRACE)
l.log(TRACE, 'trace message')
l.setLevel(logging.DEBUG)
l.log(TRACE, 'disabled trace message')

Estoy confundido; con python 3.5, al menos, simplemente funciona:

import logging


TRACE = 5
"""more detail than debug"""

logging.basicConfig()
logging.addLevelName(TRACE,"TRACE")
logger = logging.getLogger('')
logger.debug("n")
logger.setLevel(logging.DEBUG)
logger.debug("y1")
logger.log(TRACE,"n")
logger.setLevel(TRACE)
logger.log(TRACE,"y2")
    

salida:

DEBUG: root: y1

TRACE: root: y2

En caso de que alguien quiera una forma automatizada de agregar un nuevo nivel de registro al módulo de registro (o una copia del mismo) dinámicamente, he creado esta función, expandiendo la respuesta de @ pfa:

def add_level(log_name,custom_log_module=None,log_num=None,
                log_call=None,
                   lower_than=None, higher_than=None, same_as=None,
              verbose=True):
    '''
    Function to dynamically add a new log level to a given custom logging module.
    <custom_log_module>: the logging module. If not provided, then a copy of
        <logging> module is used
    <log_name>: the logging level name
    <log_num>: the logging level num. If not provided, then function checks
        <lower_than>,<higher_than> and <same_as>, at the order mentioned.
        One of those three parameters must hold a string of an already existent
        logging level name.
    In case a level is overwritten and <verbose> is True, then a message in WARNING
        level of the custom logging module is established.
    '''
    if custom_log_module is None:
        import imp
        custom_log_module = imp.load_module('custom_log_module',
                                            *imp.find_module('logging'))
    log_name = log_name.upper()
    def cust_log(par, message, *args, **kws):
        # Yes, logger takes its '*args' as 'args'.
        if par.isEnabledFor(log_num):
            par._log(log_num, message, args, **kws)
    available_level_nums = [key for key in custom_log_module._levelNames
                            if isinstance(key,int)]

    available_levels = {key:custom_log_module._levelNames[key]
                             for key in custom_log_module._levelNames
                            if isinstance(key,str)}
    if log_num is None:
        try:
            if lower_than is not None:
                log_num = available_levels[lower_than]-1
            elif higher_than is not None:
                log_num = available_levels[higher_than]+1
            elif same_as is not None:
                log_num = available_levels[higher_than]
            else:
                raise Exception('Infomation about the '+
                                'log_num should be provided')
        except KeyError:
            raise Exception('Non existent logging level name')
    if log_num in available_level_nums and verbose:
        custom_log_module.warn('Changing ' +
                                  custom_log_module._levelNames[log_num] +
                                  ' to '+log_name)
    custom_log_module.addLevelName(log_num, log_name)

    if log_call is None:
        log_call = log_name.lower()

    setattr(custom_log_module.Logger, log_call, cust_log)
    return custom_log_module