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


Умение писать в логфайл полезную информацию – одно из важнейших. Тем удивительнее разнообразие и бесполезность порою происходящего (видел в большом и небедном продакшене строки без даты и времени, очень удобно было пытаться понять, таки упало днём или ночью? – что характерно, даже после трёх напоминаний разработчики не шмагли в дату, бывает такое с высокооплачиваемыми и самоуважаемыми специалистами).

Так вот, лог должен отвечать на главный (и в 99% случаев единственный) вопрос: что и когда произошло. Тут все три слова в bold’е важны.

Сценарий:

  1. Саппорту в пятницу вечером свалился тикет от клиента – в четверг «у меня ничего не работало пять минут!».
  2. В субботу дежурный саппорт перекинул тикет в раздел вашего сервиса.
  3. В понедельник утром менеджер сервиса перекинул тикет на вас.
  4. У вас таких тикетов уже десятка два накопилось (ага, бюджета на ещё одного программиста ни у кого нет).
  5. Во вторник вы добираетесь до тикета.
  6. С четверга по вторник сервера намолотили 20Gb логов. Вы в задумчивости.

Первая задача анализа формулируется так: в большом массиве строк быстро найти проблему.


В-нулевых, научитесь пользоваться grep (Unix / Linux) и findstr (Windows). Все эти свистелки по сбору и красивому показу логов типа ЁЛКи действительно очень удобны, пока не оказываешься на удалённом сервере наедине со огромным стогом сена, в нём иголка, а в руках у вас только вилы. А очень надо. Т.ч. учитесь, лишним точно не будет – уж grep’ом вы в 20Gb текста быстрее найдёте нужное, чем глазами.

Во-первых, если речь не идёт про stacktrace ошибок, каждая строка должна начинаться с даты и времени с точностью до ms. Это позволит вам… да блин, ну очевидно же.

Выглядит как-то так: 2019:12:10 12:31:40.678 ...

Во-вторых, хорошо бы добавить к строке категорию (категории). Это может быть уровень логирования (INFO, WARN, ERROR и т.д. – называется «severity level», пример можно посмотреть в InfoSphere от IBM, а так-то полно примеров). Может быть модуль, из которого упало (NETWORK, COMMAND и т.д. – пример можно посмотреть в MongoDB, там оно называется компонентами). Это позволит вам отсекать лишнее или сразу смотреть на нужное, если подозреваете, что проблема в определённом модуле.

Выглядит как-то так: 2019:12:10 12:31:40.678 WARN NETWORK ...

В-третьих, дальше есть смысл наращивать строку чем-то, что однозначно (по возможности) идентифицирует сессию / пользователя / устройство. Это может быть IP (как это делается в Nginx). Может быть логин или UID пользователя. Может быть UID сессии, который вы присвоите при первом действии пользователя. В любом случае эти значения должны привязать происходящее к «объекту». Вам ничем не поможет запись 2 + 2 в логе, но поможет Петров: 2 + 2.

Выглядит как-то так: 2019:12:10 12:31:40.678 WARN NETWORK 127.0.0.1 "Petrov" ...

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

Выглядит как-то так: 2019:12:10 12:31:40.678 WARN NETWORK 127.0.0.1 "Petrov" /helloworld 45 qa 34ms

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

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


Понятно, есть штуки, которые не стоит (а то и нельзя) писать в лог. Как минимум, в штатном режиме. Если вы локально у себя занимаетесь отладкой, можно всё.

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

Во-вторых, не надо писать в лог бинарные стримы (файлы, BLOB и т.д.). Мало того, что лог забивается, так это и неудобно, всё равно не можете толком искать по бинарям.

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


Особо следует подчеркнуть: надо писать именно строками именно в файлы.

Во-первых, файлами проще оперировать (бекапить, чистить, обрабатывать скриптами), чем базами данных, в которые вы сливаете накопившееся.

Во-вторых, каждое обновление баз данных (и другого софта, внутри которого логи) – риск потерять всё. Были случаи.

В-третьих, это просто, дёшево, прогнозируемо.


Вернёмся к сценарию. Если были соблюдены описанные выше рекомендации, вы находите проблему за пять минут:

  1. Отсечка по дате (четверг) и предполагаемому времени (рабочий день клиента).
  2. Отсечка по идентификатору клиента.
  3. Отсечка по severity = ERROR.
  4. Осмотр найденного.
  5. Выявление сбойнувшего компонента (STORAGE).

К тикету прикладывается строка из лога: 2019:11:28 15:10:39.123 ERROR STORAGE 127.0.0.1 "Ivanov" [Saving group profile: Invalid access] user 14ms. Дальше уже по логу операций админки проверяете, а не сбросили ли случайно (и быстро вернули) директору птицефабрики роль CEO в роль user. Оп, догадка подтвердилась. Тикет закрывается.

Все довольны.