Registrazione di un'applicazione in Python

Recentemente ho lavorato in una piccola applicazione standalone per console Python e ho ereditato del codice da un altro team. Sebbene alcuni di noi abbiano scritto piccoli script Python in passato, nessuno di noi ha esperienza in Python.

Una cosa che mi ha infastidito è stato il modo in cui è stato effettuato il logging: il modulo di avvio configurerebbe la registrazione e passerebbe l'oggetto logger come parametro per tutte le altre funzioni e moduli, non solo ingombrante ma anche difficile da testare.

Inizieremo un nuovo progetto nel prossimo futuro e mi piacerebbe trovare un modo migliore di registrare un'applicazione console Python standalone.

Per Java, utilizzerei slf4j o log4j, definendo un file di configurazione del registro e quindi creando un logger per ogni classe in una singola riga.

Dopo la ricerca, ho costruito una dimostrazione del concetto di aggiungere un log ad un'applicazione Python, ma sono abbastanza sicuro che non sia buono, quindi mi piacerebbe vedere come potrei migliorarlo.

Requisiti:

1. fornisce l'accesso in modo semplice, preferibilmente iniziando a inizializzarlo con una sola riga nei moduli Python

2. la registrazione non deve interferire con i test delle unità

3. non dovrebbe impedire l'esecuzione indipendente dei singoli moduli

4. durante l'esecuzione in produzione, c'è un parametro opzionale, --debug, che dovrebbe cambiare il livello di registrazione da INFO a DEBUG.

Idea di design: un modulo "factory" fornirà la creazione di logger. Quando viene chiamato per la prima volta, il primo client diventa il logger principale, da cui erediteranno tutti gli altri. Se il root logger esiste già, basta creare un logger standard.

log.log_factory.py

import logging

__root_logger_initialized = False
__root_logger_name = ''


def create_logger(logger_name, logging_level=logging.INFO, log_file_name='log.log'):

    global __root_logger_initialized, __root_logger_name

    if __root_logger_initialized:
        hierarchized_logger_name = __root_logger_name + '.' + logger_name
        return logging.getLogger(hierarchized_logger_name)

    __root_logger_name = logger_name
    return __create_root_logger(logger_name, logging_level, log_file_name)


def __create_root_logger(logger_name, logging_level, log_file_name):
    global __root_logger_initialized
    __root_logger_initialized = True
    logger = logging.getLogger(logger_name)
    logger.setLevel(logging_level)
    log_file_handler = logging.FileHandler(log_file_name, mode='w')  # TODO: remove mode W!
    log_formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    log_file_handler.setFormatter(log_formatter)
    logger.addHandler(log_file_handler)
    return logger

Il caricatore dell'applicazione, main.py , è il modulo che avvierà l'applicazione:

import logging
from log.log_factory import create_logger

# need to be here, *before* importing other modules, otherwise, they will be defining the log
# first, ignoring the log level that should be set by the starting point.
# TODO is there any way to circumvent this?
logger = create_logger(__name__, logging.DEBUG)

from a_file import some_function as a_some_function

logger.info("calling a")
a_some_function()
logger.info("a called")

Gli altri moduli creeranno il logger e lo useranno, sotto il logger root creato da main.py:

a_file.py

from log.log_factory import create_logger

logger = create_logger(__name__)


def some_function():
    logger.info("info message")
    logger.warning("warning message")
    logger.debug("debug message")
    logger.critical("critical message")
    return "abc"

L'esecuzione di main.py produce questo output:

2018-10-09 17:40:01,038 - __main__ - INFO - calling a
2018-10-09 17:40:01,038 - __main__.a_file - INFO - info message
2018-10-09 17:40:01,038 - __main__.a_file - WARNING - warning message
2018-10-09 17:40:01,039 - __main__.a_file - DEBUG - debug message
2018-10-09 17:40:01,039 - __main__.a_file - CRITICAL - critical message
2018-10-09 17:40:01,039 - __main__ - INFO - a called

E se eseguo il test dell'unità test_unit_sample.py :

import unittest

from a_file import some_function


class SampleTest(unittest.TestCase):

    def test_some_test(self):
        response = some_function()
        self.assertEqual("abc", response)


if __name__ == "__main__":
    unittest.main()

Il test funziona senza problemi e il file di registro è ancora creato, sebbene utilizzi solo i valori predefiniti (livello INFO, invece di DEBUG, come previsto):

2018-10-09 17:45:11,718 - a_file - INFO - info message
2018-10-09 17:45:11,719 - a_file - WARNING - warning message
2018-10-09 17:45:11,719 - a_file - CRITICAL - critical message

In termini di funzionalità, questo è più o meno quello che stavo cercando.

Le mie domande:

1. Per fare in modo che le configurazioni del log main.py raggiungano prima log.log_factory, ho bisogno di chiamare la factory prima importando i miei altri moduli, che è davvero pessimo - c'è un modo in cui io potrebbe aggirare questo?

2. Quando eseguo l'unit_test, verrà creato un file di registro nella directory che contiene il test - è possibile evitare questo?

3. Oltre ai punti precedenti, quali sono i problemi che dovrei risolvere nel codice precedente?

4. Sto reinventando la ruota?

__root_logger_initialized = False
__root_logger_name = 'application'
__root_logger = None


def create_logger(logger_name, logging_level=logging.INFO, log_file_name='log.log'):

    global __root_logger_initialized, __root_logger_name

    if not __root_logger_initialized:
        __create_root_logger(logging_level, log_file_name)
        __root_logger_initialized = True

    hierarchized_logger_name = __root_logger_name + '.' + logger_name
    return logging.getLogger(hierarchized_logger_name)


def __create_root_logger(logging_level, log_file_name):
    global __root_logger
    logger = logging.getLogger(__root_logger_name)
    logger.setLevel(logging_level)
    log_file_handler = logging.FileHandler(log_file_name, mode='w')  # TODO: remove mode W!
    log_formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    log_file_handler.setFormatter(log_formatter)
    logger.addHandler(log_file_handler)
    __root_logger = logger


def get_root_logger():
    return __root_logger


def change_logging_level(logging_level):
    __root_logger.setLevel(logging_level)

import logging

from log.logger_factory import get_root_logger, change_logging_level
from a_file import some_function as a_some_function
from util.another_file import another_function


logger = get_root_logger()
change_logging_level(logging.DEBUG)

logger.info("calling a_some_function")
a_some_function()
logger.info("a_some_function called")
logger.info("calling another_function")
another_function()
logger.info("another_function called")