Настройка логирования в python. Повышаем информативность лога

Всем привет. Хочу поговорить про модуль логирования в Python, а именно стандартный модуль "logging". Описывать по шагам как его применять - я не буду, тут о другом. Что мы ждем от лога? - правильно, информативности. и особенно в том месте лога где содержится информация об ошибке.

Рассмотрим простой пример, создадим логгер и поймаем ошибку выхода за пределы списка:

import logging

logfile = 'log_1.log'

log = logging.getLogger("my_log")
log.setLevel(logging.INFO)
FH = logging.FileHandler(logfile)
basic_formater = logging.Formatter('%(asctime)s : [%(levelname)s] : %(message)s')
FH.setFormatter(basic_formater)
log.addHandler(FH)

A = [i for i in range(5)]
log.info("start program")
try:
    for i in range(6):
        print (A[i]**2)
        log.info("program calculate square " + str(A[i]))
except:
	log.error("произошла ошибка")
log.info("end program")

лог будет выглядеть так-

2021-02-16 13:06:40,391 : [INFO] : start program
2021-02-16 13:06:40,391 : [INFO] : program calculate square 0
2021-02-16 13:06:40,407 : [INFO] : program calculate square 1
2021-02-16 13:06:40,407 : [INFO] : program calculate square 2
2021-02-16 13:06:40,407 : [INFO] : program calculate square 3
2021-02-16 13:06:40,422 : [INFO] : program calculate square 4
2021-02-16 13:06:40,422 : [ERROR] : произошла ошибка
2021-02-16 13:06:40,422 : [INFO] : end program

Строка с ошибкой не несет в себе ничего, кроме факта наличия ошибки. Хотелось бы больше. Можно перехватить сообщение об ошибке из класса "Exception", меняем

except Exception as Ex:
	log.error(Ex)

Получаем:

2021-02-16 13:13:22,371 : [INFO] : program calculate square 4
2021-02-16 13:13:22,371 : [ERROR] : list index out of range
2021-02-16 13:13:22,371 : [INFO] : end program

Уже лучше, но не понятно где именно произошла ошибка, в каком модуле, каком файле, на какой строке...

Конечно, модуль "logging" позволяет задавать формат лога и включать в него "полезную информацию". почему тут кавычки?- потому что модуль делает это своебразно, например если ошибка возникла в функции "foo" а для логирования мы используем отдельную функцию "error_log" то в логе будет запись, что ошибка произошла в модуле "error_log", а не там, где это было на самом деле. Т.е. в логе мы видим откуда (файл, модуль, строка) был вызван метод log.error(текст), но нам это по сути не интересно.

Подробнее разберем наверное самый важный вопрос для разработчика - "на какой строчке ошибка"?

Если мы изменим наш базовый формат лога

basic_formater = logging.Formatter('%(asctime)s : [%(levelname)s] [%(lineno)d] : %(message)s')

Получим

2021-02-16 13:53:44,635 : [INFO] [17] : program calculate square 4
2021-02-16 13:53:44,635 : [ERROR] [19] : list index out of range
2021-02-16 13:53:44,635 : [INFO] [20] : end program

Видно, что номер строки [19] - это не та строка, где произошла ошибка (16). Как и в примере с именем модуля, мы обломались. Как быть?

Можно вытащить полный текст ошибки из модуля "traceback"

import traceback
...
...
except :
	log.error(traceback.format_exc())

И получим

2021-02-16 14:59:14,142 : [ERROR] [20] : Traceback (most recent call last):
File "C:\Users\***\Desktop\logg.py", line 17, in print (A[i]**2) IndexError: list index out of range

Отлично, в логе видим "line 17", там и ошибка. Круто.

Но что, если все таки нам нужно поменять формат? чтобы номер строки ошибки был не где-то там в тексте, а на самом видно месте, как это можно сделать?

Номер строки ошибки можно получить конструкцией:

frame = traceback.extract_tb(sys.exc_info()[2])
line_no = str(frame[0]).split()[4]

И пойдем еще дальше - будем менять формат только для ошибок. Т.к. с какой строчки прошло INFO - нам не интересно. Для этого определим отдельную функцию, итоговый код будет такой:

import logging
import traceback
import sys

logfile = 'log_1.log'

log = logging.getLogger("my_log")
log.setLevel(logging.INFO)
FH = logging.FileHandler(logfile, encoding='utf-8')
## задаем базовый формат сообщения в логе
basic_formater = logging.Formatter('%(asctime)s : [%(levelname)s] : %(message)s')
FH.setFormatter(basic_formater)
log.addHandler(FH)

## функция для записи в лог сообщений об ошибке
def error_log(line_no):
  ## задаем формат ошибочных сообщений, добавляем номер строки
	err_formater = logging.Formatter('%(asctime)s : [%(levelname)s][LINE ' + line_no + '] : %(message)s')
	## устанавливаем формат ошибок в логгер
  FH.setFormatter(err_formater)
	log.addHandler(FH)
	## пишем сообщение error
	log.error(traceback.format_exc())
	## возвращаем базовый формат сообщений
	FH.setFormatter(basic_formater)
	log.addHandler(FH)

A = [i for i in range(5)]
log.info("start program")
try:
    for i in range(6):
        print (A[i]**2)
        log.info("program calculate square " + str(A[i]))
except :
        frame = traceback.extract_tb(sys.exc_info()[2])
        line_no = str(frame[0]).split()[4]
        ## вызываем функцию записи ошибки и передаем в нее номер строки с ошибкой
        error_log(line_no)

log.info("end program")

и сам лог

2021-02-16 15:39:06,972 : [INFO] : start program
2021-02-16 15:39:06,990 : [INFO] : program calculate square 0
2021-02-16 15:39:06,992 : [INFO] : program calculate square 1
2021-02-16 15:39:06,992 : [INFO] : program calculate square 2
2021-02-16 15:39:06,992 : [INFO] : program calculate square 3
2021-02-16 15:39:07,007 : [INFO] : program calculate square 4
2021-02-16 15:39:07,007 : [ERROR][LINE 32] : Traceback (most recent call last):
File "C:\Users\***\Desktop\logg.py", line 32, in print (A[i]**2) IndexError: list index out of range

2021-02-16 15:39:07,007 : [INFO] : end program

Так лог получается информативнее, чем это позволяют стандартные методы модуля "logging"

Tags:
python, python3, логирование, logger

You can't comment this post because its author is not yet a full member of the community. You will be able to contact the author only after he or she has been invited by someone in the community. Until then, author's username will be hidden by an alias.