Профессиональный подход к ведению логов

Логи можно сравнить с уликами на месте преступления, а разработчиков — с криминалистами. Роль логов трудно переоценить, ведь когда необходимо найти баг или причину сбоя, сразу обращаются к ним. Подобно тому, как отсутствие улик приводит к нераскрытым делам, отсутствие содержательных логов осложняет диагностику и устранение ошибок, превращая их в затянувшийся или вовсе невыполнимый процесс. Мне приходилось наблюдать, как люди мучились с такими инструментами, как Strace и tcpdump, или развертывали новый код в продакшене во время сбоя лишь затем, чтобы получить больше лог-файлов для выявления проблемы.

Как говорится: “Хорошо подготовиться — половину дела сделать”, так что каждому профессиональному разработчику следует научиться эффективно вести логи и быть готовым к работе с ними. В данной статье мы не только рассмотрим список полезных практик логирования в приложении, но и разберем теоретические основы данного процесса: что записываем, когда и кто этим должен заниматься.

Как осуществляется процесс отладки?

Прежде чем начать разговор о логах, необходимо ответить на два вопроса:

Что такое программа?

Как осуществляется отладка, в которой логи играют важную роль?

Программа как переходы состояний

Программа — это серия переходов между состояниями.

Состояния — это вся информация, которую программа хранит в своей памяти в определенный момент времени, а код программы определяет то, как она переходит от одного состояния к другому. Разработчики, использующие императивные языки программирования, такие как Java, зачастую акцентируют больше внимания на самом процессе (коде), чем состояниях. Однако понимание того, что программа является серией состояний, очень важно, поскольку они существенно ближе к тому, что должна делать программа, а не как.

Допустим, есть робот, задача которого — заполнить бензобак машины. Если мы рассмотрим выполняемые им действия как переходы состояний, то ему необходимо перейти от состояния (бак пустой, в наличии 50 $) к состоянию (бак полный, в наличии 15 $). Если же мы описываем его как процесс, то он должен найти заправку, доставить туда машину и заплатить. Конечно же, процесс имеет большое значение, но состояния дают более точную оценку правильности программы.

Отладка

Отладка — это мысленная реконструкция переходов состояний. Разработчики проигрывают в уме сценарий программы: как она принимает вводные данные, проходит через ряд изменений состояний и осуществляет вывод, а затем определяют, что пошло не так. Во время разработки этот мыслительный процесс подкрепляется использованием отладчика. Однако в продакшене делать это уже гораздо сложнее, поэтому на данном этапе чаще прибегают к помощи логов.

Что записывать в лог ?

Понимая суть процесса отладки, мы с легкостью ответим на этот вопрос:

Логи должны содержать информацию, необходимую для реконструкции переходов состояний.

Невозможно, да и не нужно, фиксировать все состояния во все отрезки времени. Например, полиции достаточно лишь нескольких точных набросков, а не видеоклона, для поимки преступника. Тоже самое относится и к логам: разработчикам нужно только внести в них информацию о том, когда происходит переход в критическое состояние. Кроме того, логи должны содержать ключевые характеристики текущего состояния и причину перехода.

Переход в критическое состояние

Не все переходы состояний стоит записывать в лог. Важно рассмотреть программу как серию изменяемых состояний, разделить их на фазы и затем сосредоточиться на времени, когда выполнение переходит от одной фазы к другой.

Предположим, что существуют 3 фазы запуска приложения:

загрузка настроек программы;
подключение к зависимостям;
запуск сервера.

Запуск приложения с точки зрения переходов состояний

Было бы очень разумно вести логи в начале и конце каждой фазы. Если бы произошла ошибка на этапе подключения к зависимостям и приложение бы зависло, то логи отчетливо показали бы, что после загрузки настроек оно вошло во вторую фазу процесса, не завершив его. Располагая этой информацией, разработчики смогли бы быстро определить проблему.

Ключевые характеристики

Логирование состояний напоминает создание эскизов программы только с учетом ключевых характеристик основ бизнес-логики. Если есть информация закрытого характера, например персональные данные, то ее также нужно записать в лог, но в завуалированном виде.

Например, когда HTTP-сервер переходит из состояния ожидания запроса в состояние получения запроса, он должен зафиксировать в логе HTTP-метод и URL, так как они описывают основы HTTP-запроса. Остальные его элементы (заголовки или часть тела сообщения) записываются в том случае, если их значения влияют на бизнес-логику. Например, если поведение сервера сильно отличается между состояниями Content-Type:application/json и Content-Type:multipart/form-data, заголовок следует записать.

Причина перехода состояния

Логирование причины перехода состояния чрезвычайно полезно для отладки. Логи должны кратко охватывать содержание предыдущих и следующих состояний, а также объяснять их причины. Они помогают разработчикам получить общую картину и ориентироваться в процессе реконструкции (отладки) выполнения программы.

Пример

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

Вот несколько анти-шаблонов логов, в которых отсутствуют ключевые характеристики состояния и причины:

[2020–04–20T03:36:57+00:00] server.go: Error processing request (Запрос на обработку ошибок)
[2020–04–20T03:36:57+00:00] server.go: SSN rejected (Номер социального страхования отклонен)
[2020–04–20T03:36:57+00:00] server.go: SSN rejected for user UUID “123e4567-e89b-12d3-a456–426655440000” (Номер социального страхования отклонен для пользователя UUID “123e4567-e89b-12d3-a456–426655440000”)

Все они содержат определенную информацию, но ее недостаточно для ответов на вопросы, которые могут возникнуть у разработчиков в процессе поиска ошибки. Какой запрос не смог обработать сервер? Почему номер социального страхования был отклонен? Какой пользователь столкнулся с этой ситуацией? Грамотный и полезный для отладки лог будет выглядеть так:

[2020–04–20T03:36:57+00:00] server.go: Received a SSN request(track id: “e4a49a27–1063–4ab3–9075-cf5faec22a16”) from user uuid “123e4567-e89b-12d3-a456–426655440000”(previous state), rejecting it(next state) because the server is expecting SSN format AAA-GG-SSSS but got **-***(why)

([2020–04–20T03:36:57+00:00] server.go: Получен запрос номера социального страхования (трек id: “e4a49a27–1063–4ab3–9075-cf5faec22a16”) от пользователя user uuid “123e4567-e89b-12d3-a456–426655440000” (предыдущее состояние), запрос отклонен (следующее состояние), так как сервер требует номер социального страхования в формате AAA-GG-SSSS, а получил **-*** (причина)

Кто должен записывать логи?

Типичная ошибка, которую многие допускают, связана с тем, “кто” должен фиксировать информацию. Ведение логов не теми функциями оборачивается дублированием или дефицитом информации.

Программа как уровни абстракции

Большинство грамотно созданных программ подобны пирамиде с уровнями абстракции. Классы/функции верхних уровней разбивают сложную задачу на подзадачи, тогда как классы/функции нижних уровней абстрагируют реализацию подзадач, таких как черные ящики, и предоставляют интерфейсы для вызова верхним уровнем. Эта парадигма облегчает программирование, поскольку каждый уровень сосредоточен на своей логике, не беспокоясь о всевозможных деталях.

Уровни абстракции

Например, веб-сайт может состоять из следующих уровней: бизнес-логика, HTTP и TCP/IP. Реагируя на URL-запрос, уровень бизнес-логики решает, какую веб-страницу показать, и отправляет ее контент на уровень HTTP, где он превращается в HTTP-ответ. Следующий уровень TCP/IP преобразует HTTP-ответ в пакеты TCP и рассылает их.

Ведите логи только на правильных уровнях

Как следствие абстракции, разные уровни имеют разные степени понимания выполняемой задачи. В предыдущем примере уровень HTTP не владел данными ни о количестве отправляемых пакетов TCP, ни о намерении пользователей в момент URL-запроса. Предпринимая попытку логирования, разработчикам следует выбрать правильный уровень, который содержит полную информацию о переходах состояний и причинах.

Вернемся к нашему примеру проверки корректности номера социального страхования. Допустим, что логика его проверки обернута в класс Validator следующим образом:

public class Validator {
    // другие функции проверки... 
 
  public static void validateSSN(String ssn) throws ValidationException {
    // выполнение проверки 
    String regex = "^(?!000|666)[0-8][0-9]{2}-(?!00)[0-9]{2}-?!0000)[0-9]{4}$";
    Pattern pattern = Pattern.compile(regex);
    Matcher matcher = pattern.matcher(ssn);
 
    if (!matcher.matches()) {
      // --> Записываем в лог местоположение A <--
      logger.info("Bad SSN blah, blah, blah...");
      throw new ValidationException(String.format("expecting SSN format AAA-GG-SSSS but got %s", ssn.replaceAll("\\d", "*")));
    }
  }
}

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

public class Validator {
    // другие функции проверки...
 
  public static void validateUserUpdateRequest(UserUpdateRequestreq) {
    // проверка другого атрибута req ...
 
    try {
      validateSSN(req.ssn);
    } catch (ValidationException e) {
      // --> Записываем в лог местоположение B <--
     logger.info(String.format("Received a user update request(track id %s) from user uuid %s, rejecting it because %s", req.trackID, req.uid, e.getMessage()));
      // другая логика обработки ошибки ...
    }
 
    // остальная логика...
  }
}

Существует два местоположения (A и B) для записи логов об ошибке проверки номера социального страхования, но только B владеет достаточной для этого информацией . В A программа не знает, ни какой запрос она обрабатывает, ни от какого пользователя он поступает. Логирование просто добавляет деталей. Будет лучше, если validateUserUpdateRequest выбросит ошибку из вызывающего компонента (validateRequest), содержащего больше контекста для лога.

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

Сколько должно быть логов?

Существует очевидное соотношение между объемом логов и их полезностью. Чем более содержательные логи, тем легче реконструировать переходы состояний. Вы можете воспользоваться двумя способами контроля количества логов:

Установите соотношение между логами и рабочей нагрузкой

Для контроля объема логов сначала важно его правильно измерить. Большинство программ имеют 2 типа рабочей нагрузки:

получение рабочих элементов (запросов) и последующая реакция на них;
запрос рабочих элементов откуда-либо и последующее выполнение действий.

В большинстве случаев процесс логирования запускается рабочей нагрузкой: чем больше ее у программы, тем больше логов она записывает. Могут быть и другие логи, не связанные с рабочей нагрузкой, но они становятся малозначимыми, когда программа начинает работу. Разработчики должны сохранять соотношение # логов и # рабочих элементов линейным. Иначе говоря:

# логов = X * # рабочих элементов+ константы

где X можно определить, изучив код. Разработчики должны иметь хорошее представление об X-факторах для своих программ и приводить их в соответствие с возможностями логирования и бюджетом. Вот еще несколько типичных случаев X:

0 < X < 1. Это значит, что логи отбираются выборочно, и не у всех рабочих элементов они есть, например ведётся запись только ошибок или используются другие алгоритмы отбора логов. Это способствует снижению объемов лога, но при этом может ограничить возможности поиска проблемы.
X ~ 1. Это значит, что в среднем каждый рабочий элемент производит примерно одну запись. И это целесообразно до тех пор, пока один лог содержит достаточно информации (подробно в разделе “Что записывать в лог?”).
X >> 1. У разработчиков должна быть весомая причина для того, чтобы X был существенно больше, чем 1. Когда рабочая нагрузка возрастает, например в случае с сервером, на который обрушивается внезапный шквал HTTP-запросов, то X лишь усиливает ее и чрезмерно нагружает инфраструктуру логирования, что обычно вызывает проблемы.

Используйте уровни логов

Что, если X все еще слишком большой даже после оптимизации? На помощь приходят уровни логов. Если X намного больше, чем 1, то можно поместить логи на уровень DEBUG, тем самым снизив X уровня INFO. В процессе устранения неполадок программа может временно выполняться на этом уровне для предоставления дополнительной информации.

Краткие выводы

Чтобы профессионально писать логи, следует рассматривать программу как серию переходов состояний с уровнями абстракции. Владея теоретическими знаниями, можно ответить на ключевые вопросы о логировании в приложении:

1.Когда писать логи? В момент перехода в критическое состояние.

2.Что записывать в лог? Ключевыехарактеристики текущего состояния и причину перехода состояния.

3.Кто должен записывать логи? Логирование должно происходить на правильном уровне, содержащем достаточно информации.

4.Каким должно быть количество логов? Определите X-фактор (по формуле # логов = X * # рабочих элементов+ константы) и настройте его экономно, но выгодно.

Перевод статьи Neal Hu: Logging Like a Pro

Поделиться статьей:

Вернуться к статьям