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

Всем привет. Хочу поговорить про модуль логирования в 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"