Когда использовать принты и как переходить на нормальное логирование. Постарался объяснить необходимость этого, описать сам переход и уровни логгирования простым языком. Не затронул конфигурирование и работу с сервером логов, это темы отдельных статей.
Зачем логировать
Логирование не нужно. Вообще бесполезная штука. С одной оговоркой: пока всё идет как надо.
Когда что-то сломалось, надо смотреть логи. Чтобы было на что смотреть, надо писать логи. Если вы, как и я, иногда допускаете ошибки, надо писать логи. Иначе будет больно.
Принты
Если возникает какая-то проблема-баг, для обнаружения причины в простейшем случае можно использовать десяток print(). И в маленьких проектах, на 100 строк или до 1000 это вполне адекватное решение. Ничего сложнее там как правило не нужно.
Если вы воспользуетесь принтом для дебага в бОльшем проекте, после исправления бага у вас будет выбор из трех вариантов. Для каждого варианта я указал вероятность, что читающий этот код назовет вас мудаком.
- оставить принты как есть. 90%. Потому-что это некрасиво и мешает работе и дебагу в другом месте.
- закомментировать принты, чтобы можно потом быстро раскомментировать и продебажить еще разок. 50%. Потому-что это некрасиво, а еще коменты устаревают. Будете краснеть на код ревью. "Вы разве не знаете, что оставлять закомментированный код - это плохой тон?"
- удалить принты во славу код ревью. 10%. Без принтов с понятными комментариями, код может показать не таким понятным. А чтобы его продебажить, надо будет эти принты опять добавлять.
Еще одной проблемой принта является его назначение. Принт печатает в консоль (стандартный вывод). И если вы пишете скрипт, который например печатает имена файлов или что-то подобное для записи в файл или подобной обработки, то принты там используются по назначению. Дебажные принты там будут лишними.
Решение всех перечисленных проблем - система логирования.
Простые логи на коленке, DEBUG и INFO
Итак, задача состоит в том, чтобы иметь аналог принтов для дебага, но он не должен мешать и раздражать.
В логировании это решается разделением на уровни. И раз мы начали с ловли багов, для нее используются уровни DEBUG и INFO. По-хорошему, надо воспользоваться стандартным питоновским модулем logging, но сначала проиллюстрирую более понятной самоделкой. Пишем в начале нужного файла такой класс:
class logger:
level = 10
@staticmethod
def log(level, text, *args):
print(level, (text % args) if args else text)
@classmethod
def debug(cls, text, *args):
if cls.level <= 10:
cls.log("DEBUG", text, *args)
@classmethod
def info(cls, text, *args):
if cls.level <= 20:
cls.log("INFO", text, *args)
Использовать его просто. Вместо print("var:", var) надо писать logger.debug("var: %s", var) или logger.info("start operation"). Плюсы:
- Их можно быстро отключить для всего файла. Не комментируя или удаляя кучу строчек, а увеличивая
logger.level. Значение "10" будет показывать всё, "20" только INFO, а "21" и больше - не будет показывать ничего. - Их не обязательно удалять из кода. И никто не будет против, так как их можно скрыть.
- А еще у нас есть не один принт, а DEBUG и INFO.
INFO можно повесить на более важные операции, которые что констатируют. Например, старт и стоп операций (особенно тех, которые запускаются по времени и что-то долго делают). Можно вывести время выполнения функции или какую-нибудь важную айдишку. Можно повесить на редкие важные события: регистрацию и удаление пользователя, денежные транзакции, создание каких-то полезных объектов, например, статей. Главное, чтобы их не было сильно много. Если статьи создаются тысячами в день, это скорее не info, а debug.
DEBUG же можно использовать для ... дебага. Можно показывать любые переменные, структуры, джейсоны, dir(obj). Втыкать в каждый if и else, чтобы видеть, как отрабатывает алгоритм. В том числе внутри цикла.
DEBUG обычно нет смысла использовать просто так. Только для отладки программы и ловли багов. Информации в этом режиме выводится гораздо больше, поэтому пока багов нет, её лучше выключать.
ERROR, WARNING, CRITICAL, EXCEPTION
ERROR
Следующая тройка уровней. Главный из них - ERROR. Дополним наш класс:
@classmethod
def warning(cls, text, *args):
if cls.level <= 30:
cls.log("WARNING", text, *args)
@classmethod
def error(cls, text, *args):
if cls.level <= 40:
cls.log("ERROR", text, *args)
@classmethod
def critical(cls, text, *args):
if cls.level <= 50:
cls.log("CRITICAL", text, *args)
Зачем же нужен ERROR, если ошибка - это плохо? Если мы встречаем ошибку в коде, то надо её не логировать, а исправлять. Ведь так? Не совсем. Бывают ситуации, когда это бывает полезно. Приведу примеры.
Внешний API. Характерной особенностью любого сервиса, который мы можем использовать в нашем коде является возможность отказа. Если от нашей БД мы ждем безотказной работы, то вызывая google для поиска, или сервис погоды, или создание твита, или список чатов в Slack, мы можем получить не то, что ожидаем.
Например, есть код получения каких-то каналов:
def get_channels():
response = requests.get("http://example.com/api/channels/")
if response.status_code != 200:
logger.error("wrong status code %s", response.status_code)
return None
result = response.json()
# TODO здесь нужна проверка на ratelimit
if not result.get("ok") or "channels" not in result:
logger.error("response not success. Service error: %s", result.get('error'))
return None
return result["channels"]
Можно еще добавить проверок. Обернуть json() в try или сделать проверку типа channels. Пока это неважно, это всего лишь пример.
Этот код может работать 100 раз подряд хорошо и правильно, выдавая какой-то массив с данными. Но на 101 результат может отличаться. Может быть 502 или 403 ошибка. Или ratelimit, если мы вызываем сервис слишком часто, а он отслеживает количество запросов в секунду. Эти данные мы можешь потом увидеть в логах и добавить в код правильное реагирование на теперь уже штатные ситуации. Например, при ratelimit можно добавить после response.json() такую проверку:
if not result.get("ok") and result.get('error') == "ratelimit":
logger.info("ratelimit")
time.sleep(1)
return get_channels()
Это уже штатная ситуация, мы о ней знаем и маркируем её не ERROR, а INFO.
Нештатная ситуация. Например, нужны какие-то данные, но нам приходит пустой словарь. Или нам нужен объект, но его почему-то нет в БД. В таком случае логируем и прерываем алгоритм.
WARNING
WARNING - это как ERROR, только не так страшно. Используется, когда потенциально проблема есть, но сейчас мы можем её обойти. В предыдущем примере можно заменить вызов INFO на logger.warning("ratelimit"), если для нас это хоть и штатная, но неприятная ситуация, которая возникать не должна. По моему опыту, используется реже, чем ERROR.
CRITICAL
CRITICAL - это как ERROR, но смертельно. Для процесса. ERROR мы можем залогировать для потомков и продолжить работу. В случае, если при возникновении ситуации мы продолжить работу не можем, используется CRITICAL. Например, нельзя открыть сокет или нет доступа к БД или нет файла, из которого скрипт должен взять данные. Используется еще реже, чем WARNING. В обычной жизни вообще можете про него забыть. Когда он понадобится, вы про него вспомните.
EXCEPTION
EXCEPTION - это как ERROR, но с трейсбэком. Обычно в него оборачивается большой блок кода, в котором нет ошибок (ха-ха), но может и есть немного, а где именно - неизвестно.
@classmethod
def exception(cls, text, *args):
if cls.level <= 40:
cls.log("ERROR", text, *args)
import traceback
print(traceback.format_exc())
Пример: чат-бот получает команду от пользователя. Он должен что-то сделать, неважно что. А после прислать в пользователю в ответ "Успешно" и счастливый смайлик. Но если не получилось, ответ должен быть "Сорян, произошла ошибка", а смайлик грустный.
def handle_action(command):
try:
many_many_work(command)
except Exception:
logger.exception("error in handle action %s", command)
return "Sorry, an error occurred =("
else:
return "Success =)"
Проверяя потом логи на предмет перехваченных ошибок, можно увидеть подобную запись:
ERROR error in handle action send_sms
Traceback (most recent call last):
File "/src/chatbot.py", line 214, in handle_action
many_many_work(command)
File "/src/chatbot.py", line 281, in many_many_work
raise ValueError('asdf')
ValueError: asdf
Или что-то более длинное и реалистичное.
Еще несколько улучшений
Это не финальная версия. К этому и так уже полезному классу можно накрутить еще фишек и будет еще удобней.
Можно вынести класс в отдельный файл, переименовать в BaseLogger и наследовать в каждом файле маленький логгер от него, с указанием персонального уровня логирования:
class logger(BaseLogger):
level = 30
Хорошо бы при этом еще отличать логи из одного файла от другого, для этого нам поможет встроенная переменная __name__:
class BaseLogger:
level = 30
name = __name__
@classmethod
def log(cls, level, text, *args):
print(cls.name, level, (text % args) if args else text)
class logger(BaseLogger):
name = __name__
level = 10
Есть еще набор улучшений, который можно сделать, чтобы пользоваться было еще удобнее:
- Научить наш логгер печатать не только в консоль через print, но и в файл. И еще куда угодно.
- Конфигурировать логгер не из файла с кодом, в котором расположен логгер, а из конфига.
- Возможность писать логи из разных файлов (логгеров) в разные места (логфайлы).
- Возможность фильтрации.
- Возможность из того же конфига настраивать вывод. Чтобы можно было дату и номер строки. Или не добавлять. Или в разных местах выдавать разные по виду логи.
Делать мы это конечно же не будем. Ведь уже написан стандартный модуль logging и внешний loguru, в которых всё это уже сделано и сделано хорошо.
Стандартный модуль logging
Описывать полностью я его не буду. Многие это уже сделали, а еще к нему есть нормальная документация.
Вкратце, в начале каждого файла с кодом надо написать
import logging
logger = logging.getLogger(__name__)
и дальше использовать logger.debug и прочие методы, точно так же, как мой самописный логгер.
А вот настройка - дело уже более сложное и муторное.
Еще можно настроить логгирование не в консоль или файлы, а в сервис наподобие ElasticSearch. Это имеет смысл, если у вас сложная система из кучи компонентов и нескольких серверов. Уследить за ней через файлы будет сложно.
Комментарии