Логирование по-человечески: что писать, а что нет

Открыл лог ночного прогона: 40 мегабайт строк «ok» и «done». Что упало и на каком адресе, из него не вытащить.

Хочу навести порядок раз и навсегда. Делю на три корзины: пишем всегда, пишем под флагом отладки, не пишем ни при каких обстоятельствах. Пока набросал так:

INFO  старт задания, id, число входных строк
INFO  финал: сколько ок, сколько ошибок, сколько минут
WARN  повтор попытки, номер попытки, причина
ERROR исключение с трассировкой
DEBUG заголовки запроса и первые 200 байт ответа

Что бы вы добавили или выкинули?

Выкинул бы INFO на каждую позицию, если он у тебя есть. Оставь счётчик раз в сотню.

И к каждой строке пришей id задания. Без него два параллельных прогона в одном файле уже не разобрать.

Главное, чего в твоём списке нет: время и формат строки. Тут половина боли.

Время писать в UTC и в ISO, потому что локальное время на сервере рано или поздно разъедется с локальным временем на ноутбуке, и ты будешь сводить две ленты вручную. Формат лучше сразу держать машиночитаемым, чтобы потом не выдумывать регулярки по собственному логу.

Я перешёл на JSON построчно и обратно не вернулся:

import json, logging, time

class JsonFmt(logging.Formatter): def format(self, r): d = { "ts": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime(r.created)), "lvl": r.levelname, "msg": r.getMessage(), "mod": r.module, } if r.exc_info: d["exc"] = self.formatException(r.exc_info) d.update(getattr(r, "polya", {})) return json.dumps(d, ensure_ascii=False)

h = logging.StreamHandler() h.setFormatter(JsonFmt()) logging.basicConfig(level=logging.INFO, handlers=[h]) ```

После этого разбор лога сводится к jq, и никакого grep по кускам фразы.

а трассировку целиком писать не жирно? у меня она страниц на пять бывает

Вот за это спасибо, jq у меня везде стоит, а формат я до сих пор лепил под глаз.

Женя, трассировку пиши целиком, но один раз на событие. Жирно становится, когда её печатают внутри цикла повторов по три раза подряд.

Ещё одна корзина, которой у тебя нет: чего в логе быть не должно никогда. Пароли, куки, строка подключения с логином внутри. Один раз положил такой файл в общий каталог и потом менял доступы по всему хозяйству.

Гоняю перед выкладкой короткую проверку:

мы такие поля режем прямо в форматтере, чтобы не надеяться на память

Добавлю замер, раз тема живая. Прогнал один и тот же обход на 30 тысяч запросов с DEBUG и с INFO: файл 610 мегабайт против четырёх, общее время дольше на восемь минут. Диск на арендованной машине не резиновый, запись в лог стоит времени.

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

Собрал итог, чтобы не потерялось.

Плюс id задания в каждой строке, время в UTC, JSON построчно и фильтр секретов в форматтере. Разложилось по полкам, спасибо.