Log Python (nome da função, nome do arquivo, número da linha) usando um único arquivo

109

Estou tentando aprender como funciona um aplicativo. E para isso estou inserindo comandos de depuração como a primeira linha do corpo de cada função com o objetivo de registrar o nome da função, bem como o número da linha (dentro do código) onde envio uma mensagem para a saída do log. Por fim, como este aplicativo é composto por muitos arquivos, desejo criar um único arquivo de log para poder entender melhor o fluxo de controle do aplicativo.

Aqui está o que eu sei:

  1. para obter o nome da função, posso usar, function_name.__name__mas não quero usar o function_name (para que eu pudesse copiar e colar rapidamente um genérico Log.info("Message")no corpo de todas as funções). Eu sei que isso pode ser feito em C usando __func__macro, mas não tenho certeza sobre python.

  2. para obter o nome do arquivo e o número da linha, vi que (e acredito que) meu aplicativo está usando a locals()função Python , mas em uma sintaxe que não conheço completamente, por exemplo: options = "LOG.debug('%(flag)s : %(flag_get)s' % locals())e tentei usando like LOG.info("My message %s" % locals())que produz algo semelhante {'self': <__main__.Class_name object at 0x22f8cd0>}. Alguma entrada sobre isso, por favor?

  3. Eu sei como usar o log e adicionar manipulador a ele para registrar em um arquivo, mas não tenho certeza se um único arquivo pode ser usado para registrar todas as mensagens de log na ordem correta das chamadas de função no projeto.

Eu apreciaria muito qualquer ajuda.

Obrigado!

user1126425
fonte
Você pode entrar no depurador Python usando import pdb; pdb.set_trace()e, em seguida, percorrer o código de forma interativa. Isso pode ajudá-lo a rastrear o fluxo do programa.
Matthew Schinckel
Boa ideia! Obrigado Matt. Ainda seria útil obter um log conforme mencionado na pergunta para que eu não precise depurar todas as vezes. Além disso, você conhece um IDE para python que seja tão bom quanto o Eclipse para Java (ctrl + clique leva você à definição da função) que eu possa usar para tornar a depuração mais fácil?
user1126425

Respostas:

28

Você tem algumas perguntas marginalmente relacionadas aqui.

Vou começar com o mais fácil: (3). Usando, loggingvocê pode agregar todas as chamadas a um único arquivo de log ou outro destino de saída: elas estarão na ordem em que ocorreram no processo.

Em seguida: (2). locals()fornece um dicionário do escopo atual. Assim, em um método que não possui outros argumentos, você tem selfno escopo, que contém uma referência à instância atual. O truque usado que o está deixando perplexo é a formatação da string usando um dict como o RHS do %operador. "%(foo)s" % barserá substituído por qualquer que seja o valor de bar["foo"].

Finalmente, você pode usar alguns truques de introspecção, semelhantes aos usados ​​por pdbque pode registrar mais informações:

def autolog(message):
    "Automatically log the current function details."
    import inspect, logging
    # Get the previous frame in the stack, otherwise it would
    # be this function!!!
    func = inspect.currentframe().f_back.f_code
    # Dump the message + the name of this function to the log.
    logging.debug("%s: %s in %s:%i" % (
        message, 
        func.co_name, 
        func.co_filename, 
        func.co_firstlineno
    ))

Isso registrará a mensagem passada, mais o nome da função (original), o nome do arquivo em que a definição aparece e a linha nesse arquivo. Dê uma olhada em inspect - Inspecione objetos ativos para obter mais detalhes.

Como mencionei em meu comentário anterior, você também pode entrar em um pdbprompt de depuração interativo a qualquer momento inserindo a linha import pdb; pdb.set_trace()e executando novamente o programa. Isso permite que você percorra o código, inspecionando os dados conforme sua escolha.

Matthew Schinckel
fonte
Obrigado Matt! Vou tentar esta função autolog. Eu estou um pouco confuso quanto ao uso de dict como RHS do operador%: Será '%(foo)s : %(bar)s'que também imprimiria o bar["foo"]valor de? Ou é um pouco diferente do seu exemplo?
user1126425
Basicamente, tudo no formulário %(<foo>)sé substituído pelo valor do objeto referenciado no dicionário <foo>. Há mais exemplos / detalhes em docs.python.org/library/stdtypes.html#string-formatting
Matthew Schinckel
3
A resposta de @synthesizerpatel é muito mais útil.
Jan
503

A resposta correta para isso é usar a funcNamevariável já fornecida

import logging
logger = logging.getLogger('root')
FORMAT = "[%(filename)s:%(lineno)s - %(funcName)20s() ] %(message)s"
logging.basicConfig(format=FORMAT)
logger.setLevel(logging.DEBUG)

Em seguida, em qualquer lugar que você quiser, basta adicionar:

logger.debug('your message') 

Exemplo de saída de um script em que estou trabalhando agora:

[invRegex.py:150 -          handleRange() ] ['[A-Z]']
[invRegex.py:155 -     handleRepetition() ] [[<__main__.CharacterRangeEmitter object at 0x10ba03050>, '{', '1', '}']]
[invRegex.py:197 -          handleMacro() ] ['\\d']
[invRegex.py:155 -     handleRepetition() ] [[<__main__.CharacterRangeEmitter object at 0x10ba03950>, '{', '1', '}']]
[invRegex.py:210 -       handleSequence() ] [[<__main__.GroupEmitter object at 0x10b9fedd0>, <__main__.GroupEmitter object at 0x10ba03ad0>]]
synthesizerpatel
fonte
61
Essa deveria ter sido a resposta!
user3885927
1
Ótimo ... Uma coisa a acrescentar, podemos nomear o arquivo de log para ser igual ao arquivo de código dinamicamente? Ex: Eu tentei logging.basicConfig (filename = "% (filename)", format = FORMAT) para pegar o nome do arquivo dinamicamente, mas tomou um valor estático. alguma sugestão?
Outlier
2
@Outlier Não, a forma recomendada para conseguir isso é através degetLogger(__name__)
farthVader
2
Tenho uma pergunta: em algum lugar em Java, li que não é recomendável imprimir o número da linha, pois leva mais tempo para descobrir de qual linha o logger está sendo chamado. Em python isso não é verdade?
McSonk,
2
Irrelevante, mas logging.getLogger('root')provavelmente não é o que você está esperando, não é o rootlogger, mas um logger comum com o nome 'root'.
0xc0de
5

funcname, linenameE linenofornecer informações sobre a última função que fez o registro.

Se você tiver um wrapper de logger (por exemplo, singleton logger), a resposta de @sintesizerpatel pode não funcionar para você.

Para descobrir os outros chamadores na pilha de chamadas, você pode fazer:

import logging
import inspect

class Singleton(type):
    _instances = {}

    def __call__(cls, *args, **kwargs):
        if cls not in cls._instances:
            cls._instances[cls] = super(Singleton, cls).__call__(*args, **kwargs)
        return cls._instances[cls]

class MyLogger(metaclass=Singleton):
    logger = None

    def __init__(self):
        logging.basicConfig(
            level=logging.INFO,
            format="%(asctime)s - %(threadName)s - %(message)s",
            handlers=[
                logging.StreamHandler()
            ])

        self.logger = logging.getLogger(__name__ + '.logger')

    @staticmethod
    def __get_call_info():
        stack = inspect.stack()

        # stack[1] gives previous function ('info' in our case)
        # stack[2] gives before previous function and so on

        fn = stack[2][1]
        ln = stack[2][2]
        func = stack[2][3]

        return fn, func, ln

    def info(self, message, *args):
        message = "{} - {} at line {}: {}".format(*self.__get_call_info(), message)
        self.logger.info(message, *args)
SpiralDev
fonte
1
Sua resposta foi exatamente o que eu precisava para resolver meu problema. Obrigado.
Erro - Remorso sintático
Desde Python 3.8, as loggingclasses suportes pilha nível pular out-of-the-box: Métodos como log(), debug(), etc. agora aceitar um stacklevelargumento. Veja a documentação .
amain