import logging\r\n\r\nlogging.basicConfig(level=logging.DEBUG,\r\n filename='basic_config_test1.log',\r\n format='%(asctime)s %(levelname)s:%(message)s')\r\n\r\n\r\ndef basic_config_test1():\r\n logging.debug(\"debug log test\")\r\n logging.error(\"error log test\")\r\n<\/pre>\nLanciando il codice, un nuovo basic_config_test1.log file viene generato con il seguente contenuto, fatta eccezione per le date, che dipendono chiaramente dal tempo di esecuzione.<\/p>\n
2020-05-08 17:19:29,220 DEBUG:debug log test\r\n2020-05-08 17:19:29,221 ERROR:error log test\r\n<\/pre>\nNOTA: il metodo basicConfig() si riferisce alla configurazione del root logger e sortisce il suo effetto soltanto la prima volta in cui viene chiamato a runtime.<\/p>\n
DEBUG-level log sono ora visibili, e tali log sono stampati con la seguente struttura personalizzata:<\/p>\n
%(asctime)s: ora e giorno in formato locale dell\u2019esecuzione della riga \n%(levelname)s: livello di severit\u00e0 del messaggio \n%(message)s: messaggio vero e proprio<\/p>\n
Per completare il tutto ecco una tabella descrittiva delle opzioni del metodo basicConfig():<\/p>\n
<\/p>\n
Questo \u00e8 un modo semplice e pratico per configurare piccoli script. Seguendo le best practice di Python raccomandiamo di gestire un’istanza del logger per ogni modulo dell’applicazione<\/strong>, ma \u00e8 comprensibile che l\u2019utilizzo delle sole funzionalit\u00e0 del metodo <\/span>basicConfig() <\/span>possa risultare impegnativo e poco pulito. Ora ci concentreremo sulle tecniche per migliorare la soluzione di logging di base.<\/span><\/p>\nBest practice: una istanza di logging per ogni modulo<\/span><\/h2>\nSeguendo gli standard sulle best practice, possiamo impostare una soluzione a singolo logger per istanza. Un buon approccio, che si adatta molto bene, \u00e8 facile da configurare e dunque dovrebbe essere preso in considerazione quando si ha a che fare con applicazioni di grandi dimensioni<\/strong> che devono essere ridimensionate, \u00e8 sfruttare il metodo <\/span>getLogger()<\/span> integrato.<\/span><\/p>\n <\/p>\n
logger = logging.getLogger(__name__)<\/pre>\nIl metodo presentato crea un nuovo logger, differente da quello di root. L\u2019argomento __name__ corrisponde al fully qualified name del modulo dal quale il metodo viene richiamato. Questo permette inoltre di tenere in considerazione il nome del logger come parte integrante di una riga di log, creando dinamicamente il nome del logger sulla base del modulo con il quale si sta lavorando in quel momento.<\/p>\n
\u00c8 possibile recuperare il nome del logger con %(name)s come mostrato nel seguente esempio.<\/p>\n
# logging_test1.py\r\n\r\nimport logging\r\n\r\nlogging.basicConfig(level=logging.DEBUG,\r\n filename='basic_config_test1.log',\r\n format='%(asctime)s %(name)s %(levelname)s:%(message)s')\r\n\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\ndef basic_config_test1():\r\n logger.debug(\"debug log test 1\")\r\n logger.error(\"error log test 1\")\r\n\r\n\r\n# logging_test2.py\r\n\r\nimport logging\r\nimport logging_test1\r\n\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\n\r\ndef basic_config_test2():\r\n logger.debug(\"debug log test 2\")\r\n logger.error(\"error log test 2\")\r\n<\/pre>\nOra si \u00e8 creata una configurazione decisamente migliore;<\/strong> ogni modulo descrive se stesso all\u2019interno del log stream e tutto risulta molto pi\u00f9 chiaro. Ciononostante, il logger creato nel modulo logging_test2, utilizzer\u00e0 la stessa configurazione del logger creato nel modulo logging_test1, ovvero la configurazione del root logger. Come gi\u00e0 accennato, la seconda invocazione di basicConfig() non sortir\u00e0 effetto. Di conseguenza, eseguire sia basic_config_test1() che basic_config_test2() risulter\u00e0 nella creazione di un singolo file basic_config_test1.log con il seguente contenuto.<\/p>\n2020-05-09 19:37:59,607 logging_test1 DEBUG:debug log test 1\r\n2020-05-09 19:37:59,607 logging_test1 ERROR:error log test 1\r\n2020-05-09 19:38:05,183 logging_test2 DEBUG:debug log test 2\r\n2020-05-09 19:38:05,183 logging_test2 ERROR:error log test 2\r\n<\/pre>\nA seconda del contesto dell\u2019applicazione, usare una singola configurazione per ogni logger istanziato nei moduli potrebbe non essere sufficiente. Nella prossima sezione verr\u00e0 analizzato come generare e distribuire le configurazioni di logging tra moduli diversi mediante fileConfig() o dictConfig().<\/p>\n
Usare fileConfig() e dictConfig()<\/h2>\n Anche se utilizzare basicConfig() rappresenta un modo rapido per iniziare a organizzare il logging, le configurazioni basate su file o dizionario offrono pi\u00f9 opzioni per andare incontro alle proprie esigenze, consentire pi\u00f9 di un logger nella propria applicazione e inviare il log a destinazioni diverse in base a fattori specifici .<\/p>\n
Questo \u00e8 anche il metodo preferito di framework come Django e Flask per impostare il logging nei progetti. Nelle prossime sezioni, daremo un’occhiata pi\u00f9 da vicino su come impostare una corretta configurazione basata su file o dizionario.<\/p>\n
fileConfig()<\/h2>\n I file di configurazione devono aderire a questa struttura, contenente alcuni elementi chiave.<\/p>\n
[loggers]: nome dei logger che si devono configurare. \n[handlers]: handler da usare per logger specifici (es. consoleHandler, fileHandler). \n[formatters]: il formato da applicare ad ogni logger.<\/p>\n
Ogni sezione del file (denominata al plurale) dovrebbe includere una o pi\u00f9 chiavi, separate da virgola, da collegare alla configurazione principale:<\/p>\n
[loggers]\r\nkeys=root,secondary\r\n<\/pre>\nThe keys are used to traverse the file and read appropriate configurations for each section. The keys are defined as [_], where the section name is logger, handler, or formatter which are predefined as said before.<\/p>\n
Le chiavi sono utilizzate per attraversare il file e leggere le configurazioni appropriate per ogni singola sezione. Le chiavi sono definite secondo la forma [_], dove pu\u00f2 valere logger, handler o formatter come descritto poc\u2019anzi.<\/p>\n
Un semplice file di configurazione per il logging (logging.ini) \u00e8 mostrato di seguito.<\/p>\n
[loggers]\r\nkeys=root,custom\r\n\r\n[handlers]\r\nkeys=fileHandler,streamHandler\r\n\r\n[formatters]\r\nkeys=formatter\r\n\r\n[logger_root]\r\nlevel=DEBUG\r\nhandlers=fileHandler\r\n\r\n[logger_custom]\r\nlevel=ERROR\r\nhandlers=streamHandler\r\n\r\n[handler_fileHandler]\r\nclass=FileHandler\r\nlevel=DEBUG\r\nformatter=formatter\r\nargs=(\"\/path\/to\/log\/test.log\",)\r\n\r\n[handler_streamHandler]\r\nclass=StreamHandler\r\nlevel=ERROR\r\nformatter=formatter\r\n\r\n[formatter_formatter]\r\nformat=%(asctime)s %(name)s - %(levelname)s:%(message)s\r\n<\/pre>\nLe best practice di Python raccomandano di mantenere un solo handler per logger,<\/strong> basandosi sul concetto di eredit\u00e0 del logger per la propagazione delle propriet\u00e0. Ci\u00f2 significa che \u00e8 sufficiente specificare una configurazione in un logger padre per averla ereditata da tutti i logger figli senza doverla impostare in ognuno di essi. Un buon esempio di ci\u00f2 \u00e8 un uso intelligente del logger root come genitore.<\/p>\nRitornando al discorso principale, una volta preparato un file di configurazione, \u00e8 possibile collegarlo ad un logger con queste semplici righe di codice:<\/p>\n
import logging.config\r\n\r\nlogging.config.fileConfig('\/path\/to\/logging.ini',\r\n disable_existing_loggers=False)\r\nlogger = logging.getLogger(__name__)\r\n<\/pre>\nQuesto esempio include il parametro disable_existing_loggers valorizzato a False, garantendo che tutti i logger preesistenti non vengano rimossi quando lo snippet di codice viene eseguito; questo \u00e8 indubbiamente un buon consiglio, perch\u00e8 molti moduli sono soliti definire un root logger ancora prima che fileConfig() venga chiamato.<\/p>\n
dictConfig()<\/h2>\n L\u2019esempio di configurazione del logger cos\u00ec come visto finora si pu\u00f2 descrivere anche mediante una comune struttura a dizionario. Tale dizionario seguir\u00e0 la struttura presentata gi\u00e0 con fileConfig() con sezioni concernenti logger, handler e formatter pi\u00f9 la presenza di alcuni parametri globali di utilit\u00e0. Di seguito un esempio:<\/p>\n
import logging.config\r\n\r\n\r\nconfig = {\r\n \"version\": 1,\r\n \"disable_existing_loggers\": False,\r\n \"formatters\": {\r\n \"standard\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n }\r\n },\r\n \"handlers\": {\r\n \"standard\": {\r\n \"class\": \"logging.StreamHandler\",\r\n \"formatter\": \"standard\"\r\n }\r\n },\r\n \"loggers\": {\r\n \"\": {\r\n \"handlers\": [\"standard\"],\r\n \"level\": logging.INFO\r\n }\r\n }\r\n}\r\n<\/pre>\nPer applicare questa configurazione \u00e8 sufficiente passare questo oggetto come parametro del dict config:<\/p>\n
logging.config.dictConfig(config)<\/pre>\ndictConfig() di base disabilita gli altri logger, a meno che disable_existing_loggers sia valorizzato a False cos\u00ec come fileConfig()nell\u2019esempio precedente.<\/p>\n
Tale configurazione pu\u00f2 anche essere salvata in un file YAML e da l\u00ec configurata. Molti sviluppatori spesso preferiscono utilizzare dictConfig() rispetto a fileConfig(), questo perch\u00e8 ha molti pi\u00f9 spunti di configurazione, pi\u00f9 facile da leggere e pi\u00f9 mantenibile.<\/p>\n
Formattare i log secondo lo standard JSON<\/h2>\n Grazie al modo in cui \u00e8 progettato, \u00e8 facile estendere il modulo di logging. Poich\u00e9 l\u2019obiettivo \u00e8 automatizzare il logging e integrarlo con Kibana, si desidera un formato pi\u00f9 adatto per l’aggiunta di propriet\u00e0 personalizzate e pi\u00f9 compatibile con i carichi di lavoro personalizzati. Quindi \u00e8 necessario configurare un formattatore JSON.<\/strong><\/p>\nSe si vuole, \u00e8 possibile loggare in formato JSON creando un formattatore personalizzato che trasforma i record di log in una stringa codificata JSON:<\/p>\n
import logging\r\nimport json\r\n\r\n\r\nclass JsonFormatter:\r\n def format(self, record):\r\n formatted_record = dict()\r\n\r\n for key in ['created', 'levelname', 'pathname', 'msg']:\r\n formatted_record[key] = getattr(record, key)\r\n\r\n return json.dumps(formatted_record, indent=4)\r\n\r\n\r\nhandler = logging.StreamHandler()\r\nhandler.formatter = JsonFormatter()\r\n\r\nlogger = logging.getLogger(__name__)\r\nlogger.addHandler(handler)\r\n\r\nlogger.error(\"Test\")\r\n<\/pre>\nSe non si vuole creare da zero il proprio formattatore custom, si pu\u00f2 fare riferimento a diverse librerie, sviluppate dalla community Python, che permettono di convertire i propri log in formato JSON. Una di queste \u00e8 python-json-logger . Per prima cosa bisogna installare la libreria nel proprio ambiente di sviluppo:<\/p>\n
pip install python-json-logger<\/pre>\nOra \u00e8 possibile aggiornare la configurazione del dizionario per modificare un formattatore esistente o creare un nuovo formattatore da zero che generi stringhe in JSON come nell\u2019esempio seguente. Per usare un formattatore JSON basta specificare pythonjsonlogger.jsonlogger.JsonFormatter come valore della propriet\u00e0 “class”. Nella chiave “format” si possono definire gli attributi da aggiungere ai record di log:<\/p>\n
import logging.config \r\n\r\n\r\nconfig = {\r\n \"version\": 1,\r\n \"disable_existing_loggers\": False,\r\n \"formatters\": {\r\n \"standard\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n },\r\n \"json\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n \"class\": \"pythonjsonlogger.jsonlogger.JsonFormatter\"\r\n }\r\n },\r\n \"handlers\": {\r\n \"standard\": {\r\n \"class\": \"logging.StreamHandler\",\r\n \"formatter\": \"json\"\r\n }\r\n },\r\n \"loggers\": {\r\n \"\": {\r\n \"handlers\": [\"standard\"],\r\n \"level\": LogLevel.INFO.value\r\n }\r\n }\r\n}\r\n\r\nlogging.config.dictConfig(config)\r\nlogger = logging.getLogger(__name__)\r\n<\/pre>\nI log inviati alla console, attraverso l\u2019handler standard, verranno scritti in formato JSON.<\/p>\n
Una volta inclusa la classe pythonjsonlogger.jsonlogger.JsonFormatter nel proprio file di configurazione di logging, la funzione dictConfig() \u00e8 in grado di creare un\u2019istanza di questo formattatore, ammesso che il codice venga eseguito in un ambiente di lavoro nel quale \u00e8 possibile importare il modulo python-json-logger.<\/p>\n
Aggiungere informazioni contestuali ai propri log<\/h2>\n Se si ha la necessit\u00e0 di aggiungere un p\u00f2 di contesto ai propri log, il modulo di logging di Python fornisce la possibilit\u00e0 di aggiungere attributi custom.<\/strong> Un modo elegante per arricchire i propri log richiede l\u2019uso della classe LoggerAdapter.<\/p>\nlogger = logging.LoggerAdapter(logger, {\"custom_key1\": \"custom_value1\", \"custom_key2\": \"custom_value2\"})<\/pre>\nCi\u00f2 aggiunge effettivamente attributi personalizzati a tutti i record che attraversano quel logger. \nSi noti che ci\u00f2 influisce su tutti i record di log nell’applicazione, comprese le librerie o altri framework che potrebbero essere in uso e per i quali si stanno emettendo log. Questo snippet pu\u00f2 essere usato per aggiungere attributi quali ID di richiesta univoci su tutte le righe di log, per tenere traccia delle richieste, o per aggiungere ulteriori informazioni contestuali.<\/p>\n
Python: gestione delle exception e tracebacks<\/h2>\n Di default<\/strong> gli errori non includono nessuna informazione di traceback. Il log mostrer\u00e0 semplicemente l\u2019eccezione come errore, senza dettagli aggiuntivi. Per essere sicuri che logging.error() mostri l\u2019intero traceback, \u00e8 necessario aggiungere la propriet\u00e0 exc_info valorizzata a True. Per mostrare la differenza, si provi a loggare una eccezione con e senza exc_info.<\/p>\nimport logging.config\r\n\r\n\r\nconfig = {\r\n \"version\": 1,\r\n \"disable_existing_loggers\": False,\r\n \"formatters\": {\r\n \"standard\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n },\r\n \"json\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n \"class\": \"pythonjsonlogger.jsonlogger.JsonFormatter\"\r\n }\r\n },\r\n \"handlers\": {\r\n \"standard\": {\r\n \"class\": \"logging.StreamHandler\",\r\n \"formatter\": \"json\"\r\n }\r\n },\r\n \"loggers\": {\r\n \"\": {\r\n \"handlers\": [\"standard\"],\r\n \"level\": logging.INFO\r\n }\r\n }\r\n}\r\n\r\nlogging.config.dictConfig(config)\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\ndef test():\r\n try:\r\n raise NameError(\"fake NameError\")\r\n except NameError as e:\r\n logger.error(e)\r\n logger.error(e, exc_info=True)\r\n<\/pre>\nSe eseguiamo il metodo test(), quest\u2019ultimo generer\u00e0 il seguente output:<\/p>\n
{\"asctime\": \"2020-05-10T16:43:12+0200\", \"name\": \"logging_test\", \"levelname\": \"ERROR\", \"message\": \"fake NameError\"}\r\n \r\n{\"asctime\": \"2020-05-10T16:43:12+0200\", \"name\": \"logging_test\", \"levelname\": \"ERROR\", \"message\": \"fake NameError\", \"exc_info\": \"Traceback (most recent call last):\\n File \\\"\/Users\/aleric\/Projects\/logging-test\/src\/logging_test.py\\\", line 39, in test\\n raise NameError(\\\"fake NameError\\\")\\nNameError: fake NameError\"}\r\n<\/pre>\nCome possiamo vedere, la prima riga non fornisce molte informazioni sull’errore a parte un messaggio generico fake NameError; invece, la seconda riga, aggiungendo la propriet\u00e0 exc_info = True, mostra il traceback completo, che include informazioni sui metodi coinvolti e numeri di riga da seguire per vedere dove \u00e8 stata sollevata l’eccezione.<\/p>\n
In alternativa si pu\u00f2 ottenere lo stesso risultato usando logger.exception() da un exception handler come nell’esempio seguente:<\/p>\n
def test():\r\n try:\r\n raise NameError(\"fake NameError\")\r\n except NameError as e:\r\n logger.error(e)\r\n logger.exception(e)\r\n<\/pre>\nQuesto snippet permette di recuperare le stesse informazioni di traceback dell\u2019esempio precedente. Ci\u00f2 ha anche il vantaggio di impostare il livello di priorit\u00e0 del logging su logging.ERROR.<\/p>\n
Indipendentemente dal metodo utilizzato per acquisire il traceback, la disponibilit\u00e0 di tutte le informazioni sulle eccezioni complete nei log \u00e8 fondamentale per il monitoraggio e la risoluzione dei problemi delle prestazioni delle applicazioni.<\/p>\n
Catturare eccezioni non gestite<\/h2>\n Anche pensando a diversi scenari, \u00e8 chiaro che non \u00e8 possibile gestire ogni possibile eccezione che la propria applicazione pu\u00f2 generare. \u00c8 comunque possibile loggare eccezioni non gestite in modo da poterle esaminare in seguito.<\/p>\n
Un’eccezione risulta non gestita se generata al di fuori di un blocco try \/ except o se \u00e8 di un tipo diverso da quelli specificati in uno o pi\u00f9 statement except.<\/p>\n
Se un’eccezione non viene gestita nel metodo che in cui viene generata, viene trasmessa al metodo superiore che pu\u00f2, eventualmente, contenere la logica di gestione della stessa. Questo meccanismo trasmette l\u2019eccezione fino al metodo main, ammesso che i metodi sottostanti non contengano la logica di gestione di quella tipologia di eccezione.<\/p>\n
Se non viene gestita l’interprete invocher\u00e0 sys.excepthook(). Le informazioni di traceback non verranno loggate se non esplicitamente specificato all\u2019interno di un handler non predefinito (ad esempio un fileHandler).<\/p>\n
\u00c8 possibile utilizzare la libreria traceback di Python<\/strong> per formattare il traceback ed includerlo nel log record.<\/p>\nPer esaminare il comportamento descritto sopra, modifichiamo la funzione di esempio in modo che venga generata un\u2019eccezione non gestita dal blocco try \/ except:<\/p>\n
import logging.config\r\nimport traceback\r\n\r\nconfig = {\r\n \"version\": 1,\r\n \"disable_existing_loggers\": False,\r\n \"formatters\": {\r\n \"standard\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n },\r\n \"json\": {\r\n \"format\": \"%(asctime)s %(name)s %(levelname)s %(message)s\",\r\n \"datefmt\": \"%Y-%m-%dT%H:%M:%S%z\",\r\n \"class\": \"pythonjsonlogger.jsonlogger.JsonFormatter\"\r\n }\r\n },\r\n \"handlers\": {\r\n \"standard\": {\r\n \"class\": \"logging.StreamHandler\",\r\n \"formatter\": \"json\"\r\n }\r\n },\r\n \"loggers\": {\r\n \"\": {\r\n \"handlers\": [\"standard\"],\r\n \"level\": logging.INFO\r\n }\r\n }\r\n}\r\n\r\nlogging.config.dictConfig(config)\r\nlogger = logging.getLogger(__name__)\r\n\r\n\r\ndef test():\r\n try:\r\n raise OSError(\"fake OSError\")\r\n except NameError as e:\r\n logger.error(e, exc_info=True)\r\n except:\r\n logger.error(\"Uncaught exception: %s\", traceback.format_exc())\r\n<\/pre>\nSe eseguiamo il codice verr\u00e0 lanciata un\u2019eccezione di tipo OSError non gestita dalla logica di try-except. Nonostante ci\u00f2, grazie alla porzione di codice definita nel secondo blocco except, l\u2019eccezione verr\u00e0 comunque loggata:<\/p>\n
{\"asctime\": \"2020-05-10T17:04:05+0200\", \"name\": \"logging_test\", \"levelname\": \"ERROR\", \"message\": \"Uncaught exception: Traceback (most recent call last):\\n File \\\"\/Users\/aleric\/Projects\/logging-test\/src\/logging_test4.py\\\", line 38, in test\\n raise OSError(\\\"fake OSError\\\")\\nOSError: fake OSError\\n\"}<\/pre>\nLoggare il traceback completo di ogni eccezione, gestita o meno, garantisce una visibilit\u00e0 cruciale<\/strong> sugli errori generati in real-time, e permette di investigare le cause generanti.<\/p>\nQuesta \u00e8 la fine della parte uno di due del nostro articolo. Nella prossima parte vedremo come aggregare i log usando Amazon Kinesis Data Firehose ed Amazon ElasticSearch Service, e Kibana per analizzare i log in una dashboard<\/strong> centralizzata ed altamente customizzabile.<\/p>\nRimanete sintonizzati \ud83d\ude42<\/p>\n
Vai alla Parte II<\/a><\/p>\n","protected":false},"excerpt":{"rendered":"Le applicazioni, nel momento in cui passano in produzione, perdono la capacit\u00e0 di fornire direttamente informazioni su cosa sta succedendo […]<\/p>\n","protected":false},"author":6,"featured_media":1447,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[477],"tags":[269,261,265,273],"class_list":["post-1394","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-cloud-native-development","tag-amazon-elasticsearch-service","tag-amazon-kinesis-data-firehose","tag-kibana","tag-python"],"yoast_head":"\n
Parte I: Best practice per il logging su Python e come integrarsi con la dashboard di Kibana tramite AWS Kinesis Data Firehose ed Amazon Elasticsearch Service - Proud2beCloud Blog<\/title>\n \n \n \n \n \n \n \n \n \n \n \n \n\t \n\t \n\t \n \n \n \n \n \n \n\t \n\t \n\t \n