golang

Go: логирование

  • пятница, 21 ноября 2025 г. в 00:00:04
https://habr.com/ru/articles/968196/

Введение

В этой статье затронем такую банальную тему, как логирование. Казалось бы, какие трудности здесь могут быть? Логирование, как написание тестов. Всё просто! Более того, когда я начинал писать свои первые тесты, я уже всё знал про тестирование, по крайней мере мне так казалось. А с логом-то ещё проще. Если тесты могут получиться нестабильными, то лог никак не повлияет на ход выполнения программы (если, конечно, библиотека не начнёт паниковать от переданных параметров). К тому же будем рассматривать лог уровня debug, т.е. просто журналировать работу нехитрого сервиса. Наблюдать за выполнением логики всегда проще, чем создавать эту самую логику. Тем не менее, на практике наблюдаются некоторые тонкости, которые я постараюсь донести до читателей.

Подопытный кролик

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

Допустим, у нас есть некоторый код:

package main

import "github.com/sirupsen/logrus"

var logger *logrus.Logger

func main() {
	logger = logrus.New()
	logger.Formatter = &logrus.JSONFormatter{}
	logger.SetLevel(logrus.DebugLevel)

	sum(1, 2, 3, 4, 5)
}

func sum(values ...int) int {
	var result int

	temp := dublication(values...)
	temp = triplication(temp...)

	for _, v := range temp {
		result += v
	}

	return result
}

func dublication(values ...int) []int {
	result := make([]int, 0, len(values))
	for _, v := range values {
		result = append(result, 2*v)
	}

	return result
}

func triplication(values ...int) []int {
	result := make([]int, 0, len(values))
	for _, v := range values {
		result = append(result, 3*v)
	}

	return result
}

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

Логирование всего

Например, можно логировать "каждый чих":

func sum(values ...int) int {
	logger.Debugf("sum values: %v", values)
	var result int

	logger.Debug("before dublication")
	temp := dublication(values...)
	logger.Debug("after dublication")
	logger.Debug("before triplication")
	temp = triplication(temp...)
	logger.Debug("after triplication")

	logger.Debug("before sum")
	for _, v := range temp {
		result += v
	}
	logger.Debug("after sum")
	logger.Debugf("result: %v", result)

	return result
}

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

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

{"level":"debug","msg":"sum values: [1 2 3 4 5]","time":"2025-10-17T20:39:06Z"}
{"level":"debug","msg":"before dublication","time":"2025-10-17T20:39:06Z"}
{"level":"debug","msg":"after dublication","time":"2025-10-17T20:39:06Z"}
{"level":"debug","msg":"before triplication","time":"2025-10-17T20:39:06Z"}
{"level":"debug","msg":"after triplication","time":"2025-10-17T20:39:06Z"}
{"level":"debug","msg":"before sum","time":"2025-10-17T20:39:06Z"}
{"level":"debug","msg":"after sum","time":"2025-10-17T20:39:06Z"}
{"level":"debug","msg":"result: 90","time":"2025-10-17T20:39:06Z"}

Одно и то же действие, например dublication, логируется дважды. Кажется, достаточно наличие факта запуска того или иного метода/функции.

Логирование контрольных точек

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

func sum(values ...int) int {
	logger.Debugf("sum values: %v", values)
	var result int

	temp := dublication(values...)
	logger.Debug("dublication")
	temp = triplication(temp...)
	logger.Debug("triplication")

	for _, v := range temp {
		result += v
	}
	logger.Debugf("result: %v", result)

	return result
}

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

{"level":"debug","msg":"values: [1 2 3 4 5]","time":"2025-10-15T20:50:33Z"}
{"level":"debug","msg":"dublications","time":"2025-10-15T20:50:33Z"}
{"level":"debug","msg":"triplications","time":"2025-10-15T20:50:33Z"}
{"level":"debug","msg":"result: 90","time":"2025-10-15T20:50:33Z"}

Дублирование лога

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

func dublication(values ...int) []int {
	logger.Debugf("dublication values: %v", values)
	result := make([]int, 0, len(values))
	for _, v := range values {
		result = append(result, 2*v)
	}
	logger.Debugf("dublication result: %v", result)

	return result
}

func triplication(values ...int) []int {
	logger.Debugf("triplication values: %v", values)
	result := make([]int, 0, len(values))
	for _, v := range values {
		result = append(result, 3*v)
	}
	logger.Debugf("triplication result: %v", result)

	return result
}

Для лучшего восприятия данных о ходе выполнения программы логируется факт запуска функции и её результат. После запуска программы сформируется лог:

{"level":"debug","msg":"sum values: [1 2 3 4 5]","time":"2025-10-15T21:04:03Z"}
{"level":"debug","msg":"dublication values: [1 2 3 4 5]","time":"2025-10-15T21:04:03Z"}
{"level":"debug","msg":"dublication result: [2 4 6 8 10]","time":"2025-10-15T21:04:03Z"}
{"level":"debug","msg":"dublications","time":"2025-10-15T21:04:03Z"}
{"level":"debug","msg":"triplication values: [2 4 6 8 10]","time":"2025-10-15T21:04:03Z"}
{"level":"debug","msg":"triplication result: [6 12 18 24 30]","time":"2025-10-15T21:04:03Z"}
{"level":"debug","msg":"triplications","time":"2025-10-15T21:04:03Z"}
{"level":"debug","msg":"sum result: 90","time":"2025-10-15T21:04:03Z"}

Читаемость кода не пострадала, а вот в самом логе всё равно чувствуется избыточность - логируется запуск логики в самих функциях dublication, triplication, и то же самое видим в вызывающей функции sum: 

temp := dublication(values...)
logger.Debug("dublication")
temp = triplication(temp...)
logger.Debug("triplication")

Более того, это хорошая почва для нарушения принципа DRY. Если бы в примере были другие функции, которые используют dublication, triplication, то запуск этих функций пришлось бы продублировать и в них тоже. В итоге получается больший объём кода, который нужно как-то поддерживать, следить за синхронизацией одного и того же лога в разных частях системы. При этом подобные действия никак не улучшают информативность логирования.

Минимальный лог

Как не нарушить принцип DRY в таком нехитром деле? - логику функции лучше логировать только в самой функции:

package main

import "github.com/sirupsen/logrus"

var logger *logrus.Logger

func main() {
	logger = logrus.New()
	logger.Formatter = &logrus.JSONFormatter{}
	logger.SetLevel(logrus.DebugLevel)

	sum(1, 2, 3, 4, 5)
}

func sum(values ...int) int {
	logger.Debugf("sum values: %v", values)
	var result int
	temp := dublication(values...)
	temp = triplication(temp...)
	for _, v := range temp {
		result += v
	}
	logger.Debugf("result: %v", result)

	return result
}

func dublication(values ...int) []int {
	logger.Debugf("dublication values: %v", values)
	result := make([]int, 0, len(values))
	for _, v := range values {
		result = append(result, 2*v)
	}
	logger.Debugf("dublication result: %v", result)

	return result
}

func triplication(values ...int) []int {
	logger.Debugf("triplication values: %v", values)
	result := make([]int, 0, len(values))
	for _, v := range values {
		result = append(result, 3*v)
	}
	logger.Debugf("triplication result: %v", result)

	return result
}
{"level":"debug","msg":"sum values: [1 2 3 4 5]","time":"2025-11-17T20:40:14Z"}
{"level":"debug","msg":"dublication values: [1 2 3 4 5]","time":"2025-11-17T20:40:14Z"}
{"level":"debug","msg":"dublication result: [2 4 6 8 10]","time":"2025-11-17T20:40:14Z"}
{"level":"debug","msg":"triplication values: [2 4 6 8 10]","time":"2025-11-17T20:40:14Z"}
{"level":"debug","msg":"triplication result: [6 12 18 24 30]","time":"2025-11-17T20:40:14Z"}
{"level":"debug","msg":"result: 90","time":"2025-11-17T20:40:14Z"}

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

Страхование автомобиля

Что ж?!... обсудили разные походы логирования. Соглашусь, что многие вещи можно отнести к вопросу вкуса. Поэтому не будем спорить, если у кого-то иное мнение, а лучше решим задачку. Так сказать, обкатаем свои стили на практике. Предположим у нас есть система, связанная со страхованием автомобилей. Т.е. клиент создаёт заявку, в которой указывает желаемую сумму страховки. А эта система анализирует данные пользователя и сообщает на какую сумму готова застраховать:

{
  "client": {
    "name": "Остап Бендер",
    "age": 33,
    "experience": 9
  },
  "car": {
    "brand": "mazda",
    "mileage": 500,
    "release": 2024
  },
  "sum": 1000000
}

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

curl -i -X POST 127.0.0.1:8080/v1/applications -d "{\"client\": {\"name\": \"Остап Бендер\",\"age\":33,\"experience\": 9}, \"car\": {\"brand\": \"mazda\", \"mileage\": 500, \"release\": 2024}, \"sum\": 1000000}"

В ответ система присылает json:

{
  "insurance_sum": 600000
}

Остап Бендер хотел застраховать 1 000 000, а получил одобрение лишь на 600 000. Если изменить немного данные заявки:

{
  "client": {
    "name": "Шура Балаганов",
    "age": 29,
    "experience": 10
  },
  "car": {
    "brand": "honda",
    "mileage": 250,
    "release": 2024
  },
  "sum": 1000000
}
curl -i -X POST 127.0.0.1:8080/v1/applications -d "{\"client\": {\"name\": \"Шура Балаганов\",\"age\":29,\"experience\": 10}, \"car\": {\"brand\": \"honda\", \"mileage\": 250, \"release\": 2024}, \"sum\":1000000}"
{
  "insurance_sum": 300000
}

результат получится другой. Например, Шуре Балаганову вместо желаемого миллиона одобрили всего на 300 000. И это не самый плохой результат.

{
  "client": {
    "name": "Ипполит Матвеевич",
    "age": 53,
    "experience": 30
  },
  "car": {
    "brand": "toyota",
    "mileage": 10000,
    "release": 2015
  },
  "sum": 1000000
}
curl -i -X POST 127.0.0.1:8080/v1/applications -d "{\"client\": {\"name\": \"Ипполит Матвеевич\",\"age\":53,\"experience\": 30}, \"car\": {\"brand\": \"toyota\", \"mileage\": 10000, \"release\": 2015}, \"sum\":1000000}"
{
  "insurance_sum": 0
}

Ипполиту Матвеевичу вообще отказали в страховке. Возникает вполне естественный вопрос: а почему такие разные результаты? Ответ мы сможем найти в логе.

Поиск по логу

Ни в одном адекватном коммерческом проекте я не видел, чтобы кто-то писал лог в файл. Обычно для хранения и анализа лога используют такие системы, как Graylog. Но в рассматриваемой системе по страхованию авто, конечно, ничего подобного нет - лог пишется в файл. Здесь может возникнуть негодование некоторых читателей, т.к. такой подход уж больно далёк от реальных вещей. Не секрет, что современные системы пишут очень много лога. Именно на больших объёмах данных могут возникнуть трудности с пониманием того, что произошло в системе. Тем не менее, для демонстрационного примера нет необходимости создавать большой объём лога, а уж тем более разворачивать Graylog. Достаточно имитации проблемы - нужно договориться не открывать файл, а для получения лога использовать старую добрую команду "grep". Таким образом, как и в реальном логе ничего не сможем получить без фильтрации. Тем более, если открыть Graylog, то сразу найти нужную информацию практически не возможно. В реальном логе для получения чего-то полезного необходимо тоже фильтровать.

Похоже, осталось определиться по каким параметрам будем искать. А что мы знаем про клиентов? - имена. Попробуем найти лог для Остапа Бендера:

grep -rin 'бендер' app.log

Но, к сожалению, такой поиск возвращает пустой результат. Как будем искать? Не знаете?... И я не знаю. Гадать, конечно, можно, но смысла в этом нет - нужно открывать код:

package main

import (
	"encoding/json"
	"fmt"
	"net/http"
	"os"

	"github.com/gorilla/mux"
	"github.com/sirupsen/logrus"
)

var log *logrus.Logger

type Car struct {
	Brand   string `json:"brand"`
	Mileage int    `json:"mileage"`
	Release int    `json:"release"`
}

type Client struct {
	Name       string `json:"name"`
	Age        int    `json:"age"`
	Experience int    `json:"experience"`
}

type Application struct {
	Client Client  `json:"client"`
	Car    Car     `json:"car"`
	Sum    float32 `json:"sum"`
}

func main() {
	logFile, err := os.OpenFile("app.log", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0765)
	if err != nil {
		logrus.Fatalf("failed to open log file: %s", err)
	}
	defer logFile.Close()

	log = logrus.New()
	log.Formatter = &logrus.JSONFormatter{}
	log.SetLevel(logrus.DebugLevel)
	log.SetOutput(logFile)

	r := mux.NewRouter()
	r.HandleFunc("/v1/applications", applicationHandler).Methods("POST")

	http.ListenAndServe(":8080", r)
}

func applicationHandler(w http.ResponseWriter, r *http.Request) {
	var app Application
	err := json.NewDecoder(r.Body).Decode(&app)
	if err != nil {
		w.WriteHeader(http.StatusBadRequest)

		return
	}
	defer r.Body.Close()

	sum := calculate(app)
	result, err := json.Marshal(struct {
		InsuranceSum float32 `json:"insurance_sum"`
	}{
		InsuranceSum: sum,
	})
	if err != nil {
		w.WriteHeader(http.StatusInternalServerError)

		return
	}

	w.WriteHeader(http.StatusOK)
	w.Write(result)
}

func calculate(app Application) float32 {
	var result float32
	defer func() {
		log.Debug(
			fmt.Sprintf("calculate: %.2f", result),
		)
	}()

	if inBlackList(app.Client) {
		return result
	}
	result = ageFactor(app.Client) * experienceFactor(app.Client) * app.Sum

	return result
}

func inBlackList(c Client) bool {
	bl := map[string]struct{}{
		"Ипполит Матвеевич": struct{}{},
	}

	_, ok := bl[c.Name]
	if ok {
		log.Debug("in black list")
	}

	return ok
}

func ageFactor(c Client) float32 {
	var result float32
	age := c.Age
	switch {
	case age < 18:
	case age < 30:
		result = 0.3
	case age < 60:
		result = 1
	case age < 80:
		result = 0.3
	case age > 80:
	}

	log.Debug(
		fmt.Sprintf("ageFactor: %.2f", result),
	)

	return result
}

func experienceFactor(c Client) float32 {
	var result float32
	exp := c.Experience
	switch {
	case exp < 1:
	case exp < 10:
		result = 0.6
	default:
		result = 1
	}

	log.Debug(
		fmt.Sprintf("ageFactor: %.2f", result),
	)

	return result
}

И только познакомившись с кодом, приходит понимание о том, как искать нужную информацию. Система имеет функцию calculate, которая рассчитывает сумму страхования. При расчёте проверяется наличие заявителя в чёрном списке, далее рассчитываются различные коэффициенты, зависящие от возраста, стажа вождения и т.д. Т.е. что получается? Для того чтобы ответить на элементарный вопрос клиента "Почему система рассчитала такую сумму?" нужно подключать разработчика, т.к. только он взаимодействует с кодом. Ни о какой поддержке 1-ого, 2-ого уровня речи быть не может. Разработчику приходится вместо создания новых возможностей системы или исправления ошибок заниматься не своей работой. Это замедляет разработку, к тому же тех. поддержка дорогой получается - специалисту нужно будет в любом случае оплатить его труд. Но для стартапов, возможно, это не проблема, а способ выжить. На первых порах денег не много, тех. поддержки может и не быть. Но в реальном мире системы намного сложнее, а код значительно хуже. К тому же разработчик мог подключиться уже к существующему проекту. При таком раскладе для ответа на большинство вопросов специалисту приходится построчно дебажить выполнение логики, чтобы понять, какой функционал запускается, и какие фразы нужно использовать для поиска лога. Таким образом, всё равно приходится тратить много времени на поверхностную оценку работы системы. И здесь могут найтись любители "поразбираться в деталях", и сказать, что разработчик в любом случае должен всё знать про систему. И будут правы. Т.е. снова упираемся во "вкусовщину". Хорошо, давайте уже достанем нужный лог:

grep -rin 'age' app.log
app.log:1:{"level":"debug","msg":"ageFactor: 1.00","time":"2025-11-02T08:32:55Z"}
app.log:2:{"level":"debug","msg":"ageFactor: 0.60","time":"2025-11-02T08:32:55Z"}
app.log:4:{"level":"debug","msg":"ageFactor: 0.30","time":"2025-11-02T08:32:59Z"}
app.log:5:{"level":"debug","msg":"ageFactor: 1.00","time":"2025-11-02T08:32:59Z"}

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

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

log.WithFields(logrus.Fields{
	"client.name": c.Name,
}).Debug(fmt.Sprintf("ageFactor: %.2f", result))

После аналогичной корректировки лога во всех функциях, связанных с расчётом, появится возможность получения полной информации для конкретного клиента:

grep -rin 'Шура Балаганов' app.log
app.log:12:{"client.name":"Шура Балаганов","level":"debug","msg":"ageFactor: 0.30","time":"2025-11-04T15:27:15Z"}
app.log:13:{"client.name":"Шура Балаганов","level":"debug","msg":"experienceFactor: 1.00","time":"2025-11-04T15:27:15Z"}
app.log:14:{"client.name":"Шура Балаганов","level":"debug","msg":"calculate: 300000.00","time":"2025-11-04T15:27:15Z"}

Итого

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

  1. Логику функций должны логировать сами функции

  2. Параметры лога должны определять конкретную запись лога