На днях я решил удариться в логгирование на питоне 🗃

Своей главной задачей я ставил разделение логов по разным файлам, исключительно для удобства работы с логами 🕹

Всё началось с того, что я решил засунуть настройки для логгирования в конфиг приложения: формат лога, уровень логгирования, логгеры, сообщения от которых я не хочу видеть. Ручками всё это разбирал и настраивал логи проекта. Однако позже я узнал, что питон поддерживает конфиг-файлы с настройками логгирования. На этом этапе я в слезах боролся с ужаснейшим форматом конфига. Дальше я заметил, что в документации примеры именно в yml. Но когда я просто изменил формат — оно не заработало 🥲
Как оказалось, вместо logging.config.fileConfig стоило взять logging.config.dictConfig и передать туда словарь со всеми настройками, которые я успешно прочитал через библиотеку PyYaml. Теперь подключение логирования у меня выглядело следующим образом (не обращайте внимания на фильтр, я позже объясню, что это).
Спустя некоторое время я смог реализовать минимальный рабочий конфиг (обратите внимание, что в начале конфига прописана первая версия. Это обязательный атрибут dictConfig'а).
Тут всё предельно просто: создаём форматтер для того, чтобы у нас логи были в красивом формате, дальше — обработчик логов.
Я создал два: для вывода в консоль и для записи в файл. Для вывода в консоль я использовал стандартный logging.StreamHandler, а для записи в файл logging.handlers.RotatingFileHandler, который позволяет ограничить размер файла, в который будут записаны все логи. Обоим обработчикам я передал наш форматтер.
Далее логгеры. Для начала я решил создать лишь один логгер, не считая основного root логгера. Всё, что будет указано у root логгера будет заимствованно и остальными логгерами. Таким образом все логи, написанные с помощью logger1 у меня пишутся как в консоль, так и в файл logs/all.log.

И с этого места начинается всё самое интересное. У меня в проекте несколько логгеров и для того, чтобы их писать в разные файлы, я создал разные обработчики.
Теперь обработчику для записи в консоль я передал класс rich.logging.RichHandler из библиотеки rich, чтобы вывод в терминал был красивым и разноцветным 😍
Дальше я захотел все ошибки дублировать в файле с ошибками, тут нам и понадобится наш вышеупомянутый фильтр. Я создал обработчик file_errors в фильтрах которого и передал наш фильтр.

Не меняя ни строки кода в проекте я получил развёрнутое подробное логгирование приложения. Такой конфиг легко расширять.
Я решил попробовать реализовать обработчик, который будет отправлять сообщения с логами в телеграм. Я понимаю, что это не лучшая идея, но ради интереса я решил это реализовать. И в итоге код обработчика вышел на 10 строк, а в конфиге я добавил всего 3 строки и получил возможность писать сообщения нужных мне логгеров в телеграм чат

📖 Про slog

Ещё недавно в Go не было встроенного структурированного логгера (логгера по уровням, со всякими key=value полями, который может писать json в разные системы сбора). Поэтому в большинстве проектов использовались сторонние логгеры (хотя, есть и люди, которые пишут log.Printf("[DEBUG] something happend") и радуются жизни, но я не из таких). Я же, в свою очередь предпочел zerolog.

zerolog предлагает возможность (хотя и не заставляет) прокидывать логгер через контекст. Таким образом вы можете внутри middleware добавлять в логер какие-то поля, такие как request_id, и использовать "расширенный" логгер в хендлере.
Хотя и "фу, context.WithValue", я привык к такому решению и мне оно казалось стандартным допущением.

Однако в стандартной библиотеке появился log/slog. К моему удивлению, функционала для вставки и извлечения логгера из/в контекст не оказалось. Меня это удивило и я, не долго думая, сам реализовал этот функционал. Но потом задумался: "разработчики go ведь не идиоты (хотя я лично знаю много людей, готовых спорить с этим утверждением), как они предлагают использовать логгер?".

slog умеет держать логгер в глобальном atomic.Pointer. И я начал анализировать, а нормально ли использовать глобальный логгер для приложения? С одной стороны весьма удобно, импортировал и юзаешь. Но это немного усложняет тестирование, выходит не очень явно и в целом как-то так себе, глобалы всё-таки...

Но главной причиной отказа от этого решения для меня являлось не понимание того, как же мне заткнуть request_id в логгер и прокинуть в handler логгер вместе с ним. Ведь не буду я в каждом логе руками request_id прописывать.

Хочу подчеркнуть, проблемой было непонимание. Здесь я углубился: на что способен slog? И был приятно удивлён. После стандартного логгера в python примитивность slog меня огорчила. Ведь всё, что у нас есть, текстовый и json логгер (handler) и пара методов для записи логов. Но в моменте мне открылась сила декораторов. Дело в том, что декорируя Handler, который использует логгер, вы можете сделать всё. Буквально всё. От цветного вывода в консоль и записи в несколько источников (хоть в telegram сообщения шли), до тех же самых request_id.

Осознав это, я будто познал тайны мироздания...
Вот, как я решил проблему request_id:

type RequestIDLogger struct {
  slog.Handler
}

func (l *RequestIDLogger) Handle(ctx context.Context, r slog.Record) error {
  request := getRequestID(ctx)

  r.AddAttrs(slog.String("request_id", request))

  err := l.Handler.Handle(ctx, r)
  if err != nil {
    return fmt.Errorf("failed to run parent of RequestIDLogger handler: %w", err)
  }

  return nil
}

Но использовать глобальный логгер я всё равно не захотел, поэтому распихал их по структурам, как обычно в Go делается dependency injection.
Кажется, это наилучший компромисс между всеми подходами.

Теперь middleware генерирует для каждого запроса request_id и добавляет его в контекст, а handler в slog.Logger извлекает его и добавляет при записи логов.

Кстати, slog уже оброс кучей всяких handler. Много интересного можно найти в awesome slog (думаю, тут есть всё, что вам может пригодиться).

#go #golang #logging #slog