1. Полезные поля в структурных логах
Когда вы только начинаете, кажется, что главное в логе — это «человеческая» фраза: «не смогли добавить задачу». Но как только у вас появляется несколько команд, несколько функций и хотя бы один пользователь, выясняется, что вы ищете не фразу, а событие: какая операция? над какой сущностью? сколько времени заняло? И вот тут поля выигрывают.
Представьте две ситуации.
Первая: у вас есть лог-строка.
// "task added: id=42 in 3ms"Выглядит мило, но это “просто текст”. Вторая: у вас есть лог-запись, где operation=task_add, id=42, duration=3ms. Теперь вы можете:
- быстро отфильтровать только operation=task_add;
- сгруппировать по operation;
- найти все события по конкретному id;
- построить статистику по duration.
И самое приятное: вам не нужно «парсить глазами» или регулярками выдирать куски из предложения.
В log/slog поля — это не украшение, а главный смысл структурного логирования. log/slog — часть стандартной библиотеки, то есть это не «модная внешняя зависимость», а официальный инструмент языка.
Мини-словарь ключей: operation, id, duration
Чтобы логи реально работали, важен простой принцип: один смысл — один ключ. Если сегодня вы пишете op, завтра operation, а послезавтра action, то поиск превращается в археологию: «в каком веке мы это логировали и как называли?».
Мы закрепляем минимальный словарь из трёх ключей:
| Ключ | Тип (обычно) | Что означает по смыслу | Пример значения |
|---|---|---|---|
|
|
«Что мы делали» (короткое имя операции) | |
|
int или string | «С чем мы это делали» (идентификатор сущности) | |
|
|
«Сколько заняло» (время выполнения операции) | |
Это не значит, что других полей быть не может. Просто если вы начнёте ровно с этих трёх, ваши логи уже станут в разы полезнее, и дальше вы будете добавлять поля осознанно, а не «потому что можно».
2. Поле operation: стабильное имя сценария
operation — это ваш «якорь» в логах: короткая метка, которая отвечает на вопрос «что вообще происходило?». Хорошее operation помогает вам быстро отделить «лог про добавление задач» от «лога про вывод списка» без чтения каждого сообщения.
Практическая цель operation: чтобы вы могли глазами (в text-логах) или фильтром (в JSON-логах) собрать все записи по одному сценарию.
Пример: логируем операцию «добавить задачу»
Начнём с самого маленького примера: одна запись Info с полем operation.
package main
import (
"log/slog"
"os"
)
func main() {
logger := slog.New(slog.NewTextHandler(os.Stderr, nil))
logger.Info(
"started command",
slog.String("operation", "task_add"),
)
// Пример вывода (примерно):
// time=... level=INFO msg="started command" operation=task_add
}
Здесь важно, что "started command" — это короткий текст, а «какая именно команда» мы не зашиваем в строку, а кладём в operation.
Как выбирать значения operation
Есть несколько очень практичных правил, которые спасают от хаоса, даже если вы про них не думали заранее.
Во-первых, operation должно быть коротким и стабильным. Если вы будете формировать operation динамически (например, "task_add_title_"+title), то вы получите бесконечное количество разных значений, и фильтрация станет бессмысленной.
Во-вторых, удобно выбирать operation как «имя сценария», а не «имя функции». Функции вы будете переименовывать и дробить, а сценарий «добавить задачу» останется «добавить задачу».
В-третьих, не делайте operation предложением. "adding new task to list" — это уже похоже на сообщение. operation — это скорее метка, чем текст. Хорошие варианты: "task_add", "task_done", "task_list".
3. Поле id: связываем события с сущностью
Как только у вас появляется сущность (у нас это «задача» в todo-приложении), вам почти всегда нужно уметь ответить на вопрос: «а это про какую задачу?». И вот здесь id становится вашим лучшим другом. Даже если вы не храните задачи в базе данных, у вас всё равно будет какой-то идентификатор: число, строка, UUID.
Главная идея: id — это поле, которое связывает разные события в логах с одной и той же сущностью.
Пример: логируем id для созданной задачи
Предположим, вы уже получили taskID := 42. Логируем.
package main
import (
"log/slog"
"os"
)
func main() {
logger := slog.New(slog.NewTextHandler(os.Stderr, nil))
taskID := 42
logger.Info(
"task created",
slog.String("operation", "task_add"),
slog.Int("id", taskID),
)
// time=... level=INFO msg="task created" operation=task_add id=42
}Здесь мы используем slog.Int, потому что id у нас числовой.
id как int или как string — что выбрать
В рамках нашего курса и маленького CLI чаще всего удобно начинать с int. Его проще парсить из аргументов, проще печатать, проще сравнивать.
Но иногда id естественно строковый: например, "a7f3c9" или UUID. Тогда нормально делать так:
logger.Info("task loaded",
slog.String("operation", "task_get"),
slog.String("id", "a7f3c9"),
)Важнее не «тип как в учебнике», а стабильность типа. Если вы сегодня пишете id как число, а завтра — как строку, то анализ логов превращается в сюрприз: «а почему часть записей id=42, а часть id="042"?».
Несколько идентификаторов: когда нужен второй ключ
Да, иногда одного id мало. Но в этой лекции мы держим минимализм: один id.
Если вам нужно больше идентификаторов, лучше вводить более конкретные ключи: task_id, user_id, file_id. Это уже следующий уровень «словаря полей». Здесь мы тренируем дисциплину: хотя бы один идентификатор, но всегда.
4. Поле duration: измеряем время выполнения
Если operation отвечает «что делали?», а id — «с чем?», то duration отвечает «как долго?». И это поле быстро становится любимым, потому что оно ловит деградации производительности ещё до того, как кто-то успел написать angry-issue «ваше приложение тормозит».
В Go измерение длительности обычно делается через start := time.Now() и потом time.Since(start). Приятный нюанс: time в Go умеет учитывать монотонные часы, поэтому time.Since(start) корректно работает даже если системное «настенное» время прыгало.
Пример: duration как поле
package main
import (
"log/slog"
"os"
"time"
)
func main() {
logger := slog.New(slog.NewTextHandler(os.Stderr, nil))
start := time.Now()
time.Sleep(10 * time.Millisecond)
logger.Info(
"operation finished",
slog.String("operation", "demo_sleep"),
slog.Duration("duration", time.Since(start)),
)
// time=... level=INFO msg="operation finished" operation=demo_sleep duration=10ms
}Обратите внимание: мы не пишем «finished in 10ms» в тексте. Мы кладём длительность в поле duration. Текст остаётся стабильным.
Микро-паттерн: helper для duration
Чтобы не писать time.Since(start) везде руками, удобно завести маленький помощник, который возвращает slog.Attr. Тогда код логирования становится «чище глазами».
package main
import (
"log/slog"
"time"
)
func durationAttr(start time.Time) slog.Attr {
return slog.Duration("duration", time.Since(start))
}Этот helper — маленький, но он дисциплинирует: вы всегда называете поле одинаково (duration), и всегда кладёте туда именно time.Duration.
5. Встраиваем operation/id/duration в CLI-приложение todo
Теперь давайте соберём всё в кусочки, которые выглядят как реальный код CLI. Мы не будем строить сложную архитектуру (это отдельная тема), но сделаем достаточно, чтобы вы почувствовали: «ага, вот где эти поля реально живут».
Сценарий такой: команда add создаёт задачу и логирует событие с operation, id, duration.
Модель и простое хранилище в памяти
Начнём с мини-хранилища, которое выдаёт автоинкрементный ID.
package main
import "time"
type Task struct {
ID int
Title string
CreatedAt time.Time
}
type TaskStore struct {
nextID int
tasks []Task
}
func (s *TaskStore) Add(title string) Task {
s.nextID++
t := Task{ID: s.nextID, Title: title, CreatedAt: time.Now()}
s.tasks = append(s.tasks, t)
return t
}Код нарочно простой: без файлов, без баз данных, без магии. Нам сейчас важны логи, а не вечное хранение задач (иначе мы случайно проведём лекцию про persistence, а это уже другой сериал).
Настройка slog и базовый логгер
Соберём логгер, который пишет в stderr, чтобы не мешать результату команды.
package main
import (
"log/slog"
"os"
)
func newLogger() *slog.Logger {
return slog.New(slog.NewTextHandler(os.Stderr, nil))
}Да, это «в две строчки». И да, так и должно быть: хороший логгер — это не обязательно «100 строк конфигурации», особенно в учебном CLI.
Команда add: логируем operation, id, duration
Теперь самое вкусное: оборачиваем выполнение команды измерением времени и пишем структурный лог.
package main
import (
"fmt"
"log/slog"
"time"
)
func runAdd(logger *slog.Logger, store *TaskStore, title string) {
start := time.Now()
task := store.Add(title)
// stdout: контракт результата команды
fmt.Printf("%d\n", task.ID) // например: 1
// stderr: диагностика (логи)
logger.Info(
"task added",
slog.String("operation", "task_add"),
slog.Int("id", task.ID),
slog.Duration("duration", time.Since(start)),
)
}Здесь прям видно разделение обязанностей: fmt.Printf печатает «результат» (ID задачи), а logger.Info печатает «что происходило внутри».
Мини-main: связываем всё в одну программу
Сделаем совсем простой main, который ожидает add <title>. Мы не используем flag, потому что это отдельные лекции про CLI-дизайн, а наша задача — поля логов.
package main
import (
"fmt"
"os"
)
func main() {
logger := newLogger()
store := &TaskStore{}
if len(os.Args) < 3 || os.Args[1] != "add" {
fmt.Fprintln(os.Stderr, "usage: todo add <title>")
return
}
title := os.Args[2]
runAdd(logger, store, title)
}В реальной программе вы бы ещё обрабатывали ошибки, поддерживали больше команд, хранили задачи между запусками и так далее. Но даже на этом «скелете» уже видно: operation, id, duration ложатся в код естественно.
Небольшая схема: что мы сделали
Иногда полезно увидеть это как поток событий: где измеряем время и где пишем поля.
flowchart TD
A["Пользователь: todo add 'milk'"] --> B["runAdd: start := time.Now()"]
B --> C["store.Add -> Task{ID}"]
C --> D[stdout: печатаем ID]
D --> E[stderr: logger.Info с operation/id/duration]
E --> F[Конец]
Если вы когда-нибудь ловили баг «почему у меня вывод в stdout сломался?», то такая схема быстро лечит: вы буквально видите, где проходит граница «контракт результата» vs «диагностика».
6. Типичные ошибки при работе с operation, id, duration
Ошибка №1: operation меняется каждый раз и превращается в бесконечный зоопарк.
Очень соблазнительно сделать operation «красивым» и включить туда детали: имя пользователя, заголовок задачи, параметры фильтра. В итоге вы получаете тысячи уникальных operation, и фильтрация по ним теряет смысл. operation должно быть коротким, из маленького фиксированного набора, а детали должны уходить в отдельные поля.
Ошибка №2: id то число, то строка — и никто не понимает, как искать.
Сегодня вы логируете id как 42, завтра как "42", послезавтра как "042". Глаз это ещё как-то переживёт, а автоматический анализ логов начнёт грустить. Выберите тип и формат и держите его стабильным: если id у вас int, логируйте как slog.Int("id", id) везде.
Ошибка №3: duration прячут в текст сообщения, а поле называют то t, то elapsed, то time_ms.
Когда длительность находится внутри строки, вы не можете нормально агрегировать и сравнивать времена. Когда ключ называется по-разному, вы не можете стабильно фильтровать и строить статистику. Делайте duration отдельным полем и называйте его одинаково: duration.
Ошибка №4: измеряют duration “как попало” и получают странные цифры.
Частый баг — поставить start := time.Now() слишком поздно (уже после половины работы) или слишком рано (до парсинга аргументов, хотя вы хотели мерить только работу хранилища). Тут нет единственного правильного ответа, но есть правило: измеряйте то, что вы реально хотите сравнивать. И да, time.Since(start) в Go — нормальный базовый способ, он учитывает монотонное время.
Ошибка №5: мешают stdout и логи, а потом удивляются, почему тесты и скрипты сломались.
Если вы печатаете «ID задачи» в stdout, а рядом туда же добавляете «DEBUG: task added…», то любой пользовательский скрипт, который ожидал одно число, внезапно получает кашу. Держите дисциплину: результат команды — в stdout, логи — в stderr.
ПЕРЕЙДИТЕ В ПОЛНУЮ ВЕРСИЮ