Pull to refresh

Как правильно писать логи (?)

Reading time 4 min
Views 59K
Тема может и банальная, но когда программа начинает работать как то не так, и вообще вести себя очень странно, часто приходится читать логи. И много логов, особенно если нет возможности отлаживать программу и не получается воспроизвести ошибку. Наверно каждый выработал для себя какие то правила, что, как и когда логировать. Ниже я хочу рассмотреть несколько правил записи сообщений в лог, а также будет небольшое сравнение библиотек логирования для языков php, ruby и go. Сборщики логов и системы доставки не будут рассматриваться сознательно (их обсуждали уже много раз).

Есть такая linux утилита, а также по совместительству сетевой протокол под названием syslog. И есть целый набор RFC посвящённый syslog, один из них описывает уровни логирования https://en.wikipedia.org/wiki/Syslog#Severity_level (https://tools.ietf.org/html/rfc5424). Согласно rfc 5424 для syslog определено 8 уровней логирования, для которых также дается краткое описание. Данные уровни логирования были переняты многими популярными логерами для разных языков программирования. Например, http://www.php-fig.org/psr/psr-3/ определяет те же самые 8 уровней логирования, а стандартный Ruby logger использует немного сокращённый набор из 5 уровней. Несмотря на формальное указание в каких случаях должен быть использован тот или иной уровень логов, зачастую используется комбинация вроде debug/info/fatal — первый для логирования во время разработки и тестирования, второй и третий в расчёте на продакшен. Потом в какой то момент на продакшене начинает происходить что то не понятное и вдруг оказывается, что info логов не хватает — бежим включать debug. И если они не сильно нагружают систему, то зачастую так и остаются включенными в продакшен окружении. По факту остаётся два сценария, когда нужно иметь логи:

  • что-то происходит и надо знать что
  • что-то сломалось и нужно дополнительно активировать триггер

По триггеру может происходить: уведомление об ошибке на email, аварийное завершение или перезапуск программы или другие типичные сценарии.

В языке Go в котором всё упрощено до предела, стандартный логер тоже прилично покромсали и оставили следующие варианты:

  • Fatal — вывод в лог и немедленный выход в ОС.
  • Panic — вывод в лог и возбуждение «паники» (аналог исключения)
  • Print — просто выводит сообщение в лог

Запутаться, что использовать в конкретной ситуации уже практически невозможно. Но сообщения в таком сильно усеченном виде сложно анализировать, а также настраивать системы оповещения, типично реагирующих на какой нибудь Alert\Fatal\Error в тексте лога.

Я часто при написании программы с нуля повсеместно использую debug уровень для логирования с расчётом, что на продакшене будет выставлен уровень логирования info и тем самым сократится зашумлённость сообщениями. Но в таком подходе часто возникают ситуация, что логов вдруг становится не хватать. Трудно угадать, какая информация понадобиться, что бы отловить редкий баг. Возможно рационально всегда использовать по умолчанию уровень info, а в обработчиках ошибок уровень error и выше. Но если у вас сотни и больше сообщений лога в секунду, то тогда наверно есть смысл тонкой настройки между info/debug. В таких ситуациях уже имеет смысл использовать специализированные решения что бы не просаживать производительность.

Есть ещё тонкий момент, когда вы пишите что то вроде logger.debug(entity.values) — то при выставленном уровне логирования выше debug содержимое entity.values не попадёт в лог, но оно каждый раз будет вычисляться отъедая ресурсы. В Ruby логеру можно передать вместо строки сообщения блок кода: Logger.debug { entity.values }. В таком случае вычисления будут происходить только при выставленном соответствующем уровне лога. В языке Go для реализации ленивого вычисления в логер можно передать объект поддерживающий интерфейс Stringer.

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

Типичный формат строки сообщения в логе можно условно разделить на следующие составные части:

[system info] + [message] + [context]

Где:

  • system info: метка времени, ид процесса, ид потока и другая служебная информация
  • message: текст сообщения
  • context: любая дополнительная информация, контекст может быть общим для сообщений в рамках какой то операции.

Для того, чтобы связать пары запрос\ответ часто используется http заголовок X-Request-ID. Такой заголовок может сгенерировать клиент, или он может быть сгенерирован на стороне сервера. Добавив его в контекст каждой строчки лога появится возможность лёгким движением руки найти все сообщения возникшие в рамках выполнения конкретного запроса. А в случае распределенных систем, заголовок можно передавать дальше по цепочке сетевых вызовов.

Но с единым контекстом в рамках запроса возникает проблема с различными ORM, http клиентами или другими сервисами\библиотеками, которые живут своей жизнью. И ещё хорошо, если они предоставляют возможность переопределить свой стандартный логер хотя бы глобально, а вот выставить контекст для логера в рамках запроса зачастую не реально. Данная проблема в основном актуальна для многопоточной обработки, когда один процесс обслуживает множество запросов. Но например в фрэймворке Rails имеется очень тесная интеграция между всеми компонентами и запросы ActiveRecord могут писаться в лог вместе с глобальным контекстом для текущего сетевого запроса. А в языке Go некоторые библиотеки логирования позволяют динамически создавать новый объект логера с нужным контекстом, выглядит это примерно так:

reqLog := log.WithField("requestID", requestID)

После этого такой экземпляр логера можно передать как зависимость в другие объекты. Но отсутствие стандартизированного интерфейса логирования (например как psr-3 в php) провоцирует создателей библиотек хардкодить малосовместимые реализации логеров. Поэтому если вы пишите свою библиотеку на Go и в ней есть компонент логирования, не забудьте предусмотреть интерфейс для замены логера на пользовательский.

Резюмируя:

  • Логируйте с избытком. Никогда заранее не известно сколько и какой информации в логах понадобится в критический момент.
  • Восемь уровней логирования — вам действительно столько надо? По опыту должно хватить максимум 3-4, и то при условии, что для них настроены обработчики событий.
  • По возможности используйте ленивые вычисления для вывод сообщений в лог
  • Всегда добавляйте текущий контекст в каждое сообщение лога, как минимум requestID.
  • По возможности настраивайте сторонние библиотеки таким образом, чтобы они использовали логер с текущим контекстом запроса.
Only registered users can participate in poll. Log in, please.
Насколько подробно вы покрываете приложение логами?
8.79% У меня всё работает, логи не нужны (или логи пишет только фрэймворк) 35
14.82% Логирую только ошибки 59
35.93% Логирую «интересные» места 143
19.35% Стараюсь покрыть логами всё приложение 77
21.11% Использую несколько уровней логирования с настроенными уведомлениями в зависимости от типа ошибки 84
398 users voted. 134 users abstained.
Tags:
Hubs:
+15
Comments 24
Comments Comments 24

Articles