Структурированное логирование 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,  —  уже тема отдельной статьи.

Читайте также:

• Набор инструментов Go для работы с микросервисами
• Как создать простой планировщик событий в Go
• Думаете, хеш-карты нельзя отсортировать? Еще как можно!

Читайте нас в Telegram, VK и Яндекс.Дзен

---

Перевод статьи Percy Bolmér: How To Use Structured JSON Logging in Golang Applications