Как стать автором
Обновить

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

Время на прочтение 4 мин
Количество просмотров 58K
Тема может и банальная, но когда программа начинает работать как то не так, и вообще вести себя очень странно, часто приходится читать логи. И много логов, особенно если нет возможности отлаживать программу и не получается воспроизвести ошибку. Наверно каждый выработал для себя какие то правила, что, как и когда логировать. Ниже я хочу рассмотреть несколько правил записи сообщений в лог, а также будет небольшое сравнение библиотек логирования для языков 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.
  • По возможности настраивайте сторонние библиотеки таким образом, чтобы они использовали логер с текущим контекстом запроса.
Только зарегистрированные пользователи могут участвовать в опросе. Войдите, пожалуйста.
Насколько подробно вы покрываете приложение логами?
8.84% У меня всё работает, логи не нужны (или логи пишет только фрэймворк) 35
14.65% Логирую только ошибки 58
36.11% Логирую «интересные» места 143
19.19% Стараюсь покрыть логами всё приложение 76
21.21% Использую несколько уровней логирования с настроенными уведомлениями в зависимости от типа ошибки 84
Проголосовали 396 пользователей. Воздержались 134 пользователя.
Теги:
Хабы:
+15
Комментарии 24
Комментарии Комментарии 24

Публикации

Истории

Работа

Программист Ruby
11 вакансий
PHP программист
133 вакансии
Ruby on Rails
10 вакансий
Go разработчик
139 вакансий

Ближайшие события

Московский туристический хакатон
Дата 23 марта – 7 апреля
Место
Москва Онлайн