Структурні поля в log/slog: operation, id, duration

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, то пошук перетворюється на археологію: «у якому столітті ми це логували й як називали?».

Ми закріплюємо мінімальний словник із трьох ключів:

operation

string

"task_add"

id

42

duration

time.Duration

3*time.Millisecond

Це не означає, що інших полів не може бути. Просто якщо ви почнете саме з цих трьох, ваші логи вже стануть у рази кориснішими, а далі ви додаватимете поля свідомо, а не «бо можна».

2. Поле operation: стабільна назва сценарію

operation — це ваш «якір» у логах: коротка мітка, яка відповідає на запитання «що взагалі відбувалося?». Добре підібраний operation допомагає вам швидко відокремити «лог про додавання задач» від «лог про виведення списку» без читання кожного повідомлення.

Практична мета operation проста: щоб ви могли на око (у текстових логах) або фільтром (у JSON-логах) зібрати всі записи одного сценарію.

Приклад: логуємо операцію «додати задачу»

Почнемо з найпростішого прикладу: один запис Info з полем operation.

package main

import (
	"log/slog"
	"os"
)

func main() {
	logger := slog.New(slog.NewTextHandler(os.Stderr, nil))

	logger.Info(
		"команду запущено",
		slog.String("operation", "task_add"),
	)
	// Приклад виводу (приблизно):
	// time=... level=INFO msg="команду запущено" operation=task_add
}

Тут важливо, що "команду запущено" — це короткий текст, а «яку саме команду» ми не зашиваємо в рядок, а кладемо в 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(
		"задачу створено",
		slog.String("operation", "task_add"),
		slog.Int("id", taskID),
	)
	// time=... level=INFO msg="задачу створено" operation=task_add id=42
}

Тут ми використовуємо slog.Int, тому що id у нас числовий.

id як int або як string — що обрати

У межах нашого курсу й невеликого CLI найчастіше зручно починати з int. Його простіше парсити з аргументів, простіше друкувати, простіше порівнювати.

Але інколи id природно рядковий: наприклад, "a7f3c9" або UUID. Тоді нормально робити так:

logger.Info("задачу завантажено",
	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 відповідає «як довго?». І це поле швидко стає одним із найкорисніших, тому що воно вловлює погіршення продуктивності ще до того, як хтось встигне написати обурений 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(
		"операцію завершено",
		slog.String("operation", "demo_sleep"),
		slog.Duration("duration", time.Since(start)),
	)
	// time=... level=INFO msg="операцію завершено" operation=demo_sleep duration=10ms
}

Зверніть увагу: ми не пишемо «завершено за 10ms» у тексті. Ми кладемо тривалість у поле duration. Текст залишається стабільним.

Мікропатерн: помічник для 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(
		"задачу додано",
		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, "використання: todo add <title>")
		return
	}

	title := os.Args[2]
	runAdd(logger, store, title)
}

У реальній програмі ви б ще обробляли помилки, підтримували більше команд, зберігали задачі між запусками тощо. Але навіть на цьому «скелеті» вже видно: operation, id і duration природно лягають у код.

Невелика схема: що ми зробили

Іноді корисно побачити це як потік подій: де вимірюємо час і де пишемо поля.

flowchart TD
	A["Користувач: todo add 'молоко'"] --> 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?», то така схема швидко допомагає: ви буквально бачите, де проходить межа між «контрактом результату» й «діагностикою».

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 і логи, а потім дивуються, чому тести й скрипти зламалися.
Якщо ви друкуєте «ідентифікатор задачі» у stdout, а поруч туди ж додаєте «DEBUG: task added…», то будь-який користувацький скрипт, який очікував одне число, раптом отримує кашу. Дотримуйтеся дисципліни: результат команди — у stdout, логи — у stderr.