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

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

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

19.05.2017 04:49

ZurgInq 24 11000 Источник

Тема может и банальная, но когда программа начинает работать как то не так, и вообще вести себя очень странно, часто приходится читать логи. И много логов, особенно если нет возможности отлаживать программу и не получается воспроизвести ошибку. Наверно каждый выработал для себя какие то правила, что, как и когда логировать. Ниже я хочу рассмотреть несколько правил записи сообщений в лог, а также будет небольшое сравнение библиотек логирования для языков 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.
По возможности настраивайте сторонние библиотеки таким образом, чтобы они использовали логер с текущим контекстом запроса.

Насколько подробно вы покрываете приложение логами?

	У меня всё работает, логи не нужны (или логи пишет только фрэймворк)
	Логирую только ошибки
	Логирую «интересные» места
	Стараюсь покрыть логами всё приложение
	Использую несколько уровней логирования с настроенными уведомлениями в зависимости от типа ошибки

Проголосовало 257 человек. Воздержалось 87 человек.

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

Поделиться с друзьями

-->

Комментарии (24)

deemytch

19.05.2017 08:36

#10225004

[4] pry(main)> log = Logger.new STDERR, level: :info;
[5] pry(main)> log.debug "МанаМана#{ print 'Нелениво'; 1+2 }"
Нелениво=> true
[6] pry(main)> log.debug { "МанаМана#{ print 'Нелениво'; 1+2 }" }
=> true

Спасибо. Не знал.

man55
19.05.2017 08:38
#10225012
Немного не в контексте статьи, но тем не менее есть еще один пункт к выводам:
- думайте, куда вы пишете
При использовании накопителей на флэш-памяти особо удачливый логгер может протереть в памяти дырку за время, намного меньшее ожидаемого времени жизни системы
1. Dmitry_4
  19.05.2017 12:00
  #10225448
  Пишите логи в АНБ, там места хватит

SirEdvin
19.05.2017 08:50
#10225024
Логируйте с избытком. Никогда заранее не известно сколько и какой информации в логах понадобиться в критический момент.
А потом копайтесь несколько часов в логах в попытках найти нужное. Мне кажется, лучше все-таки соблюдать баланс.
1. Pakos
  19.05.2017 09:40
  #10225098
  +1
  Вот потому и есть уровни логирования (например, 5), когда всё ок — можно настроить чуть не минимум, когда нужно разобраться — включаем mode=DEBUG в конфиге и он пишет всё, включая содержимое запросов и поток данных с устройств, разбираться придётся часы, но без этого — недели.
  1. SirEdvin
    19.05.2017 11:08
    #10225322
    +2
    Возможно, зависит от проекта, но у меня есть для таких случаев дебаг.
    А для случаев, где один сбой за месяц, то копать такие логи нужно будет ооооочень долго.
    
    alexkunin
    19.05.2017 16:04
    #10226054
    +2
    Заказчик скажет «я ничего не делал, но тут в инвойсе не тот продукт и не та цена, а еще период неправильный, и теперь мы третьей конторе должны кучу денег!» (я утрирую до неузнаваемости реальный кейс) — и дебаг не поможет, потому что ситуация уже случилась, шагов к репродьюсу нет, вертись как хочешь.
    
    Лучше иметь то, в чем копаться, чем не иметь ничего. Ну, и фильтруем логи при разборе, конечно же — по времени, по айдишникам, и т.д.
    
    SirEdvin
    19.05.2017 17:51
    #10226196
    А насколько медленее оно будет работать с таким логгированием?
    Если логгировать каждый шаг, причем со стектрейсом, то тормоза будут просто ужастные.
    А если нет, то всегда есть шанс, что логи не помогут. Причем процент того, когда логи помогут посчитать будет сложно.
    
    alexkunin
    19.05.2017 18:06
    #10226226
    Стектрейс на каждом шаге — это уж слишком. Достаточно стектрейс на непойманных эксепшнах. Если вы видите сообщение в логе, то вы можете найти место в коде, откуда оно произошло, а оттуда уже можно прикинуть и цепочку вызовов. Всяческие событийно ориентированные архитектуры это усложняют, конечно же, и в таком случае можно трейс события логировать, или может ID события — в момент его создания и в момент его обработки. И тогда стектрейс просчитывается без особых сложностей.
    
    Кроме того, логировать определенные вещи не стоит (проверять, например, арифметику процессора, или результаты вычислений библиотечных функций). А некоторые другие вещи стоит логировать практически всегда (общение с пеймент гейтвеем, авторизацию админов, критические действия с бизнес-данными).
    
    всегда есть шанс, что логи не помогут. Причем процент того, когда логи помогут посчитать будет сложно
    Зачем вам этот процент? И шанс, что логи не помогут, есть всегда — логи потерялись, серверное время «сползло», ошибка случилась в дебрях АПИ третьей стороны, и т.д. Лично мне достаточно того, что этот шанс заметно уменьшается — вместо (или вместе с) путанных показаний участников событий я вижу логи, которые могу сопоставить с кодом и данными.
    
    Плюс, опять же, к ситуации, что я описал: клиент говорит «я сделал А, Б, потом Ц, и вот результат Д!», а ты ему можешь обоснованно заявить «нет, вы сделали Е, К, и Л, и закономерным результатом оказалось Ё». В моей практике уже не раз и не два такое было.
1. neolink
  19.05.2017 09:56
  #10225130
  +3
  найти что-то в большом логе когда оно там есть и в маленьком когда его там нет немного разные вещи
1. AterCattus
  19.05.2017 13:09
  #10225654
  Лучше иметь такую возможность, чем остаться с сообщением про баг/сбой и невозможностью по логам понять, что было.
1. bormotov
  19.05.2017 14:03
  #10225840
  если вы копаетесь в логах несколько часов — значит вы их неправильно пишите.
  
  даже если на продакшине всегда включен DEBUG — кому-то использовать grep религия не позволяет?
  1. SirEdvin
    19.05.2017 14:05
    #10225848
    если вы копаетесь в логах несколько часов — значит вы их неправильно пишите.
    Писать логи "правильно" довольно сложно. Ну и как их правильно не пиши, парсинг в духе ELK прикрутить все равно нужно.
    
    даже если на продакшине всегда включен DEBUG — кому-то использовать grep религия не позволяет?
    В результате все равно гиганские стены текста.
    
    bormotov
    19.05.2017 14:42
    #10225910
    Писать логи — легко. Ниже написал комментарий «в общем виде». Складывание в ELK и прочие инструменты — конечно, но эти инструменты должны облегчать жизнь вполне конкретным людям. То есть задачу «писать правильно лог» — нужно рассматривать как одно из требований к продукту.
    
    > В результате все равно гиганские стены текста.
    
    Простите, не понимаю. Лог, а по-русски, «протокол» — это такой поток записей. Причем, в общем случае, на эти записи накладываются совсем небольшие требования, типа «иметь отметку времени» и «иметь loglevel». Если вам этих требований для структурирования мало — никто не мешает в log message добавить то, что облегчит вам фильтрацию. Хоть grep'ом, хоть ELK, хоть еще чем-то.
    
    Не вижу вообще никаких проблем. Если это ваш продукт — вы сами пишите логи для себя.
    Когда люди готовят для себя еду, они же не насыпают туда килограммы соли или перца, что есть невозможно? Бывает, в первый раз сыпанул, но есть же второй раз, третий раз…
    
    SirEdvin
    19.05.2017 14:45
    #10225918
    Простите, не понимаю. Лог, а по-русски, «протокол» — это такой поток записей.
    А теперь представьте, что у вас в системе куча различных документов с которыми происходит куча различных событий.
    Скажем, для 6-7 типов документов по 50 событий в минуту. Причем для каждого документа различные источники изменений, различные действия и так далее. И все идея "правильного логгирования" без чего-то в духе ELK превращается в тыкву, потому что разобрать это через grep — практически невозможно.
    
    Правильно писать логи — это очень не просто, а поэтому совет "пишите больше" похож на совет "резать двумя руками хлеб быстрее". Он далеко не для всех.
    
    bormotov
    19.05.2017 16:11
    #10226060
    +2
    Давайте посчитаем, мне так сложно сравнить. Возьмем более круглые значения для ровности
    
    10 типов документов, 60 событий в минуту (1 в секунду). 3600*10 строк в час? 24 часа?
    864000 строк в сутки?
    
    Взял навскидку из багрепорта посылку, там логи порядка 100М за сутки — 440803 строки, например. Похоже на вашу ситуацию? Всего в два раза меньше.
    
    У нас «правильное логгиирование» обязует разработчика использовать loglevel'ы, вполне опредленным образом
    
    * DEBUG — то, что будет читать только разработчик
    * INFO — то, что может почитать инженер поддержки, но не факт
    * WARNING — то, что читает инженер поддержки
    * ERROR — то, что обязательно читает инженер поддержки, и на что реагируют алерты.
    
    итак, из этик 440К строк:
    
    * DEBUG — ~356K
    * INFO — ~81K
    * WARNING — 3K
    * ERROR — 86 строк
    
    Еще раз — я не против ELK. Даже очень за. Но вот сейчас мне хватило просто grep и wc -l, что бы выдать вам эти цифры. Ровно так-же, зная имена модулей, и дальше по архитектуре приложения, я могу получать простым grep'ом нужные срезы. Вот, например, есть у нас некий «ServiceManager» — он в этот лог написал ~253K строк. И в то же время, было всего 123 строки, когда этот самый «ServiceManager» писал «Can't connect to host».
    
    Это просто одна команда:
    
    grep ServiceManager" some.log | grep «Can't connect to host» | less
    
    Вы говорите, что практически невозможно написать такую команду?
    
    SirEdvin
    19.05.2017 17:54
    #10226198
    Помимо того, что ваш пример немного… странный, так как не у всех такая архитектура, что бы ее можно было разбить на части (например, вы кастомизируете CRM или ERP системы, и тогда у вас проблемки), меня очень смущает, что когда ServiceManager пишет "Can't connect to host" это не ошибка.
    
    Более реальный пример того, для чего реально нужны логи привели мне выше, но там все равно нужно выбирать.
    
    Для того, что бы понять, о каких проблемах я говорю, гляньте, например, систему модулей в odoo. Там очень много мест, где меняются документы и вместе с их изменениями нужно писать стек трейс и кучу другого мусора. И разберать это через grep (а ведь там многострочные сообщения!) это все равно, что стрелять с пращи по дракону.
    
    splav_asv
    20.05.2017 13:35
    #10226912
    -1
    Многострочные сообщения можно свести к однострочным экранированием. Когда нужно легко привести к нормальному виду.

nikola_sa
19.05.2017 10:13
#10225182
Можно использовать инструменты сбора и анализа логов, искать станет проще.

kloppspb
19.05.2017 12:19
#10225498
+1
Восемь уровней логирования — вам действительно столько надо?

Может и не надо. Но для себя давно придумал дополнительную фичу: вкл/выкл вывода в лог определённых строк независимо от log_level. Выглядит это так (использую как навесной фильтр для Log::Any::Adapter, думаю, для других языков/библиотек можно что-то аналогичное придумать):
```
# конфиг: log_comments => 0
$log->info( '//Что-то что-то что-то что-то, что-то есть у бегемота' );
# В лог не запишется ничего даже при log_level => trace

# конфиг: log_comments => 1
$log->debug( '#Слонёнок ужасно умный. И попугай тоже ужасно умный.' );
# Сейчас - запишется (признак комментария будет вырезан), если log_level => debug и дальше

# конфиг: log_comments => 0
$log->debug( ';Они оба ужасно умные. Просто один другого умней…' );
# А сейчас, при том же log_level - нет.
```
Зачем это надо? Ну, есть такие юзкейсы, где мне это бывает полезно :)
1. ZurgInq
  19.05.2017 13:09
  #10225656
  Похоже это аналог log4j, а там можно создавать отдельные экземпляры логеров со своими настройками для каждого класса. Что действительно очень удобно.
  1. kloppspb
    19.05.2017 13:18
    #10225680
    Log::Any — это прокси, принимающий в качестве адаптера любой логгер, в том числе и log4*. Вот тут подробней: хабр:: Логирование чего угодно в Perl. Фильтр навешивается поверх прокси и работает с любым адаптером независимо от его настроек.

bormotov
19.05.2017 14:27
#10225890
Что бы правильно писать лог, нужно как можно более четко понимать зачем. Если говорить более формально — какой у вас общий процесс (вашей работы) работы, в котором потребуется читать этот лог?

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

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

* оперативное оповещение о проблемах
* разбор инцидентов

После того, как с целями разобрались, нужно выяснить, кто пользователи. Опять-же, навскидку

* дежурный службы поддержки
* сервисный инженер
* разработчик

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

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

Аналогично можно предположить, что для сервисного инженера, который будет разбираться с инцидентом, километровые traceback'и мало что скажут, а вот возможность четко понять какой модуль (с прикладной точки зрения) и в какой момент поломался, или что именно сделал «не так» — важно.

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

Когда вы распишите эти три момента (цели, пользователи, требования каждого пользователя), будет более-менее четка картина, что, когда и как писать логи.

Какие сообщения на какой loglevel выводить, нужны ли логах traceback'и или нет, и вот это всё.

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

polarnik
20.05.2017 20:13
#10227114
Спасибо за статью.

Есть ещё тонкий момент, когда вы пишите что то вроде logger.debug(entity.values) — то при выставленном уровне логирования выше debug содержимое entity.values не попадёт в лог, но оно каждый раз будет вычисляться отъедая ресурсы.
Тут нужны эксперименты. Для каждого логера свой правильный путь. Если для получения уровня логирования компилятор задействует inline-преобразование, то при таком коде получения entity.values не будет:
```
if (logger.IsDebug) logger.debug(entity.values);
```
Если надежды на inline нет, то нужно добавлять переменную — это плохой стиль, но будет быстро.
```
bool isDebug = logger.IsDebug;
// bool isDebug = logger.isDebug();

if(isDebug) logger.debug(entity.values);
```