Структурированное логирование JSON в приложениях на Golang



Книга Структурированное логирование JSON в приложениях на Golang

Что такое «структурированное логирование»?


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


Есть много отличных инструментов для парсинга логов. Мне, например, очень нравится ElasticSearch. Но большинство из них рассчитано на структурированные логи, а не на двоичные большие объекты с обычным текстом (и не факт, что эти объекты записаны в нужном формате).


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


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


"" not allowed

Логи быстро заполнялись, а старые лог-файлы стали огромными. Неудивительно, ведь bash-скриптов было около 50–60. Все они очень большие и запускались часто. Поэтому на отслеживание бага ушло довольно много времени, которое было бы легко сэкономить, используя структурированные логи.


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


А что, если бы в этой моей ужасной системе использовалось структурированное логирование? Тогда вывод был бы примерно таким:


{ "date": "2001-02-03", "service": "buggy-script", "level": "Warning", "message": "'' not allowed", "context": "validateInputFunction"}

Удобные структурированные логи на Golang


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


  • rs/zerolog  —  мой основной пакет логирования с невероятно быстрыми структурированными логами в формате JSON.
  • sirupsen/logrus  —  пожалуй, самый популярный пакет логирования, использующий структурированные логи JSON.
  • uber-go/zap  —  супербыстрый логгер со структурированными логами JSON.
  • natefinch/lumberjack  —  пакет ротации логов, применяющий в основном логи с файлами.

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


Сравним вывод zerolog с выводом обычного пакета логов и посмотрим, как выглядит структурированный лог. Вот код:


package main

import (
"log"
zlog "github.com/rs/zerolog/log"
)

func main() {
log.Print("Hello")
zlog.Print("Hello")
}

Вывод (первая строка — обычный логгер, вторая строка — zerolog):


2021/08/04 21:19:40 Hello
{"level":"debug", "time":"2021-08-04T21:19:40+02:00","message":"Hello"}

Видите? Логи в выводе zerolog в формате JSON намного проще принимать централизованным логгером, таким как Elasticsearch.


Но что, если надо добавить еще полей JSON? Это довольно легко сделать с помощью цепочечного API zerolog. Большинство функций возвращает zerolog. Событие, которое позволяет вызывать функции рекурсивно.


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


package main

import (
"github.com/rs/zerolog/log"
)

func main() {

// Лог с именем сервиса
log.Info().
Str("service", "my-service").
Int("Some integer", 10).
Msg("Hello")
}

Контекстные поля, добавленные в JSON:


{"level":"info","service":"my-service","Some integer":10,"time":"2021-08-04T21:30:56+02:00","message":"Hello"}

Функция Info() здесь для контроля за тем, какой уровень ведения журнала использовать. Да-да, есть уровни ведения журнала. Здорово, когда есть еще один дополнительный слой для контроля логов.


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


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


package main

import (
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
)

func main() {

// Применяем глобальный уровень zerolog для недопущения логирования zerolog любых отладочных сообщений
debug := false
// Применяем уровень ведения журнала в начале приложения
zerolog.SetGlobalLevel(zerolog.InfoLevel)
if debug {
zerolog.SetGlobalLevel(zerolog.DebugLevel)
}
// Лог с именем сервиса
log.Info().
Str("service", "my-service").
Int("Some integer", 10).
Msg("Hello")
// Журнал отладки
log.Debug().Msg("Exiting Program")
}

Единственный вывод программы — логи Info, так как у отладки debug значение false:


{"level":"info","service":"my-service","Some integer":10,"time":"2021-08-04T21:37:09+02:00","message":"Hello"}

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


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


Как насчет принципа Don’t Repeat Yourself (DRY)?


Сейчас вы, наверное, думаете: «Отлично, логи выглядят здорово». Но не слишком ли много текста для простого лога, ведь придется все время повторять имя сервиса?


К счастью, zerolog позволяет создавать настраиваемые логгеры со значениями по умолчанию.


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


package main

import (
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
)

var (
HelloCounter = 1
logger zerolog.Logger
)

func main() {
// Создаем логгер с полями по умолчанию
logger = log.With().
Str("service", "my-service").
Str("node", "localhost").
Logger()

Hello()
Hello()
}
func Hello() {
// Лог с именем сервиса
logger.Info().
Int("count", HelloCounter).
Msg("Hello")
HelloCounter++
}

Вывод логгера с использованием принципа DRY:


{"level":"info","service":"my-service","node":"localhost","count":1,"time":"2021-08-04T21:47:34+02:00","message":"Hello"}
{"level":"info","service":"my-service","node":"localhost","count":2,"time":"2021-08-04T21:47:34+02:00","message":"Hello"}

Заключение


Надеюсь, вы убедились в простоте использования библиотеки Zerolog. Она здорово помогла мне в разработке. А то, как эти логи из Stdout поступают в популярные фреймворки типа Elasticsearch,  —  уже тема отдельной статьи.



429   0  
    Ничего не найдено.

Добавить ответ:
Отменить.