Залогируй это

С самого начала моей карьеры программиста я на каждом углу встречал напутствия в стиле: «Пишите как можно больше логов, логируйте всё». Но все попытки логировать всё подряд приводили лишь к огромным файлам, в которых ничего не понять. И нигде мне не встречалось вразумительного руководства что и как надо логировать. Что ж, накопив немного опыта, давайте попробуем разобраться в этом вопросе.

Роли и задачи

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

Разработчик

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

• отладка разрабатываемого функционала;
• разбор некорректного поведения системы в прошлом;
• разбор некорректного поведения системы в настоящем;
• определение внешних проблем;

Эксплуатация

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

• мониторинг здоровья сервиса;
• мониторинг связанности среды;
• разбор ошибок при падении или отказе стартовать сервиса;

Служба технической поддержки

Служба технической поддержки разбирает проблемы, возникающие у пользователя. Это могут быть как исторические проблемы, так и воспроизводимые в моменте задачи. Часто специалисты СТП имеют доступ до таких ресурсов, как БД, дашборды метрик, а также логи. Задачи СТП при работе с логами следующие:

• нахождение запроса в прошлом (ориентируясь на время, пользователя или другие ограничения);
• восстановление контекста конкретного запроса;
• нахождение сервиса источника ошибки;
• возможность повторить запрос;

Архитектор

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

• мониторинг различных участков кода на частоту и время обращения;
• разбор отдельных запросов с построением карты взаимодействий;

Автоматические системы

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

• формирование метрик;
• события для сервисов оповещения;

Способы работы с логами

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

Активное / пассивное

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

Исторические данные / воспроизведение инцидента

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

Статистика / конкретный запрос

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

Поиск аномалий / проверка гипотез

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

Инструменты работы с логами

Текстовые процессоры

Первое, что мне приходит на ум в разговоре о логах, это джентльменский набор grep, cut, head, tail, wc и в особо тяжёлых случаях sed и awk. Хотя в последнее время многие системы используют для логов JSON, а это означает, что в инструментарий обязательно надо добавить jq. Эти инструменты отлично подходят не только при работе с логами в файлах, но и в случае использования стека Docker/k8s.

Graylog

Недавно столкнулся с этим инструментом и пока у меня совершенно негативные впечатления, впрочем возможно это связано с рецептом его приготовления. В данном случае готовим его не мы, нам лишь ставят в укор, что логи у нас не того формата, что graylog плохо работает с JSON и лучше использовать формат syslog.

Kibana

Стандарт де-факто в области работы с логами. Идеально работает с JSON, но надо использовать фиксированный набор полей во всех записях, либо сваливать неструктурированный объект в отдельное поле, а дальше использовать полнотекстовый поиск.

Loki

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

Другое

У меня практически нет опыта со стеком на основе ClickHouse, так что ничего не могу про него сказать. Также, конечно, я не упоминаю здесь такие промежуточные инструменты как Logstash и Fluentd. Настройкой каждого из них можно посвятить по отдельной статье и даже не одной, но принципиальной разницы для вопроса «что и как писать в логи?» они не несут.

Форматы

Исходя из инструментов наиболее востребованными форматами для логов являются:

• человекочитаемый Многие системы логов предоставляют из коробки удобный для чтения в консоли формат с подсветкой разных уровней логов цветами, а сообщений жирным текстом, сокращение метки времени (ведь во время отладки мы редко уходим за пределы одного дня).
• syslog Несмотря на свою неказистость этот формат используется многими системами и возможность вывода логов в этом формате может сильно облегчить жизнь в плохо контролируемой среде эксплуатации.
• JSON Набирающий обороты формат для всего, что плохо лежит. Избыточность данных в каждой записи и вольность интерпретации. Используя этот формат надо помнить про то, что многие системы всё же рассчитывают на фиксированный набор полей, по крайней мере для индексации.

Структура записи

Исходя из задач и форматов можно определить набор полей записи лога.

Временная метка

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

Система / подсистема / имя логера

В разных библиотеках эта сущность называется по разному, однако, так или иначе присутствует. Даже в аскетичном стандартном логере Go есть понятие префикса, которое можно использовать для этих целей. Для многих задач, решаемых с помощью логов необходимо сузить набор записей выборки, например, посмотреть логи подсистемы работы с БД или HTTP-интерфейса. Это поле также хорошо работает в связке с уровнем DEBUG.

Уровень

Камень преткновения во всех системах логов. Некоторые, например, создатели Go, считают, что уровень логов излишняя сущность. Но многие системы предлагают набор уровней, так почему бы этим не пользоваться. Давайте же разберёмся какой уровень для чего лучше использовать. Разберём самые распространённые уровни, не затрагивая такие крайности как TRACE, FATAL и CRITICAL.

ERROR

Самый высокий уровень логирования из рассматриваемых. Этот уровень должен срабатывать редко, только в тех случаях, когда сервис или окружение работает некорректно и возникающая ошибка не обработана логикой сервиса. Например, если сервис обращается к внешнему АПИ, которое работает нестабильно постоянно, то сыпать сообщениями уровня ERROR в данном случае мало эффективно. Лучше реализовать систему повторных обращений, буфера отправки или предохранителя, таким образом частые проблемы будут обработаны, а у службы эксплуатации не будет болеть голова от ошибок в неконтролируемой среде. С другой стороны, разрыв соединения с БД или другая непредвиденная ситуация в окружении сервиса хороший повод для логирования ошибки. Таким образом сообщения этого уровня отлично подходят для решения задач

• определение внешних проблем;
• мониторинг здоровья сервиса;
• мониторинг связанности среды;
• разбор ошибок при падении или отказе стартовать сервиса;
• события для сервисов оповещения;

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

• в рамках какого запроса произошла ошибка (url и метод для HTTP);
• кто выполнял запрос (идентификатор пользователя и другие параметры авторизации либо user agent для автоматических систем);
• параметры запроса, если это возможно (довольно деликатный момент из-за персональных данных и других секретов, но если в сообщении об ошибке будет полное описание того как воспроизвести запрос, это бесспорно лучший контекст);
• версия сервиса (часто ошибки возникают во время обновления системы и по времени трудно определить какая версия записала ошибку);
• состояние модели в методе которой возникла ошибка и аргументы вызова этого метода;
• стек вызовов, приведший к ошибке;

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

WARNING

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

• в рамках какого запроса произошла ошибка (url и метод для HTTP);
• кто выполнял запрос (идентификатор пользователя и другие параметры авторизации либо user agent для автоматических систем);

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

Кроме того, так как этот уровень предусматривает более или менее фиксированный набор сообщений можно также использовать его для сообщений с метриками. При этом важна строгость в тексте сообщений, переменные части записи лучше вынести в дополнительную информацию, используя текст сообщения как фиксированную строку для поиска. Лучше обложить такими метриками все вызовы к внешним системам: БД, другие сервисы, стороннее АПИ.

INFO

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

Необходимо чтобы имея только записи этого уровня найти запрос по абстрактному описанию: примерное время, пользователь или идентификатор внешней системы, команда. Какие сущности затрагивались в рамках этого запроса и с каким результатом он завершился. Действительно, использовать более высокие уровни логирования для ошибок авторизации или ошибки в данных запроса может быть излишне (хотя это может оказаться признаком неисправности во внешнем сервисе), но пользователь может заинтересоваться что именно пошло не так, почему его запрос, который он посылал в обед понедельника на прошлой неделе не был выполнен. В данном случае по запросу может не быть записей с уровнем ERROR или WARNING, но необходимо иметь возможность составить контекст и результат запроса.

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

DEBUG

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

Включение DEBUG для подсистемы

На уровне конфигурации сервиса хорошо иметь параметр DEBUG, через который можно указать логи уровня DEBUG каких подсистем надо выводить в stderr. Например с использованием регулярных выражений или масок биндинга RabbitMQ.

Временное включение DEBUG

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

• внутренний HTTP-метод. Удобный с точки зрения реализации, потому как не требует больших доработок, сервисы чаще всего уже имеют http-интерфейс;
• внешнее хранилище конфигурации. База данных или key-value хранилище, которое сервис будет с определённой периодичностью опрашивать, удобно при наличии нескольких экземпляров сервиса, как единое место конфигурации;

Включение DEBUG для конкретного запроса

Наличие в Go такого механизма как контекст запроса позволяет вводить специфику обработки отдельного запроса. Для этого достаточно передать в заголовках некоторый признак, по которому все или некоторые записи в лог в рамках этого запроса будут выведены в stderr.

Запрос

Все сервисы, с которыми мне приходилось работать являются лишь логикой реакции на внешние события, чаще всего на http-вызов. Конечно часто логика реакции оказывается значительно более сложной, например, запрос создаёт задачу по обработке файлов, которая асинхронно продолжается в откреплённой горутине, либо запрос взводит таймер, который должен сработать через несколько часов или даже дней, совершив новые вызовы в другие системы. Это не говоря уже о том, что в рамках одного запроса происходит последовательно-параллельные запросы между сервисами системы. Есть очень маленькая доля событий, происходящих в сервисе, не привязанных к внешним вызовам: старт, разрыв соединения с базой данных, остановка. Для консистентности можно считать старт и остановку сервиса тоже отдельными вызовами со специальными идентификаторами.

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

• команда — уникальное название класса запросов, например, post.new или post.publish. Чаще всего можно применить схему из пары: <сущность>.<действие>;
• идентификатор — уникальный идентификатор отдельного запроса. Если используется система трейсинга, такая как zipkin или jaeger, можно использовать идентификатор трейса;
• инициатор — инициатором может быть система (события старта и остановки), внешняя система (например, определяемая по заголовку User-Agent) либо пользователь (зарегистрированный или по крайней мере отмеченный кукой сессии);

Сообщение

Содержимое сообщение сильно зависит от предназначения сообщения и подробно описано в уровнях логирования.

Другое

• стек вызовов — как уже говорилось, применим для необработанных ошибок;
• дополнительная структурированная информация — может содержать неиндексируемую информацию, специфичную для разных типов записей, например, полный URL запроса или код ответа в подсистеме http-транспорта, привилегии пользователя в прослойке авторизации, идентификаторы запрашиваемых сущностей в подсистеме работы с бд. Также в этой части записи необходимо располагать значения метрик. Обогащая данную часть записи стоит оставаться умеренным и не писать дампы всех объектов, совершенно не нужные в большинстве случаев. Такие слепки могут пригодиться для насыщения контекста ошибки, но не для штатного поведения системы.
• файл и строка — часто встречаемый в библиотеках логирования функционал не имеющий особого применения в жизни. На ранних этапах разработки он позволяет быстро находить вызовы логирования в интересующем участке кода, но по мере развития проекта номер строки, а порой и имя файла меняется, так что лучше использовать уникальное сообщение и имя логгера для этих целей.

Итого

Задача	Уровень	Поиск	Группировка
Отладка разрабатываемого функционала	DEBUG	пассивный	подсистема
Разбор некорректного поведения системы в прошлом	WARNING	время / команда / пользователь	подсистема / запрос
Разбор некорректного поведения системы в настоящем	DEBUG	идентификатор запроса	подсистема / запрос
Определение внешних проблем	ERROR	пассивный
Мониторинг здоровья сервиса	ERROR	пассивный
Мониторинг связанности среды	ERROR	пассивный	подсистема
Разбор ошибок при падении или отказе стартовать сервиса	ERROR	пассивный
Нахождение запроса в прошлом	INFO	время / команда / пользователь	подсистема / запрос
Восстановление контекста конкретного запроса	INFO	время / команда / пользователь	подсистема / запрос
Нахождение сервиса источника ошибки	WARNING	команда	подсистема / запрос
Возможность повторить запрос	INFO	идентификатор запроса	подсистема / запрос
Мониторинг различных участков кода на производительность	WARNING	идентификатор запроса	подсистема / запрос
Разбор отдельных запросов с построением карты	DEBUG	идентификатор запроса	подсистема / запрос
Формирование метрик	WARNING	пассивное	сообщение
События для сервисов оповещения	ERROR	пассивный