14. Логирование. structured logging
Брайану Кернигану принадлежит знаменитое высказывание: «Самым эффективным инструментом отладки по-прежнему остается вдумчивое размышление в сочетании с разумно расставленными операторами печати».
Однако в современном облачном мире, когда ваш бинарник исполняется на десятках серверов в нескольких дата-центрах, обычный fmt.Println или неструктурированный log.Printf теряют всякую ценность. Текстовые строки «что-то пошло не так при обработке пользователя 123» превращаются в кошмар для систем мониторинга: сборщикам логов (Loki, Elasticsearch, Vector) приходится тратить колоссальные ресурсы CPU на разбор строк регулярными выражениями.
Настоящее промышленное логирование должно быть структурированным: лог — это не строка для чтения человеком, а типизированное событие для машины, представленное набором пар «ключ-значение» или компактным JSON-документом.
flowchart TD
A["Горутина вызывает slog.Info"] --> B["Формирование slog.Attr<br>в стеке без аллокаций"]
B --> C["JSONHandler сериализует<br>в байтовый буфер"]
C --> D["Запись в io.Writer"]
D --> E{"Буферизация?"}
E -->|"Нет"| F["syscall write<br>каждый вызов<br>высокий overhead"]
E -->|"Да bufio"| G["Накопление до 4KB<br>один syscall write<br>низкий overhead"]
G --> H["Kernel Space<br>передача данных в драйвер"]
classDef src fill:#0f172a,stroke:#6366f1,stroke-width:2px,color:#f8fafc;
classDef opt fill:#1e293b,stroke:#38bdf8,stroke-width:2px,color:#f8fafc;
classDef warn fill:#450a0a,stroke:#f43f5e,stroke-width:2px,color:#f8fafc;
classDef succ fill:#064e3b,stroke:#10b981,stroke-width:2px,color:#f8fafc;
class A,B,C,D src;
class E opt;
class F warn;
class G,H succ;
Философия структурированного логирования
В эпоху микросервисов и распределенных систем текстовые логи в формате time - level - message умерли. Они не машинно-читаемы, не поддаются эффективному агрегированию и требуют дорогостоящего regex-парсинга на стороне сборщиков (Loki, ELK). Структурированное логирование заменяет нечитаемые строки на предсказуемые пары ключ-значение или JSON-объекты, превращая логи из текста для человека в данные для машины.
До Go 1.21 сообщество полагалось на logrus, zap или zerolog. Начиная с Go 1.21, стандартная библиотека предоставляет log/slog — оптимизированный, типобезопасный и контекстно-ориентированный логгер, который покрывает 95% production-требований без внешних зависимостей.
Под капотом. Архитектура log/slog
В основе slog лежит интерфейс Handler. Это не просто обертка над io.Writer, а конечный автомат, отвечающий за фильтрацию уровней, форматирование и запись.
type Handler interface {
Enabled(ctx context.Context, level Level) bool
Handle(ctx context.Context, r Record) error
WithAttrs(attrs []Attr) Handler
WithGroup(name string) Handler
}
log/slog.Logger — это легковесный wrapper, который делегирует всю работу Handler. При вызове slog.Info("msg", "key", val):
- Создается
slog.Record(хранит уровень, время, сообщение и атрибуты) - Вызывается
handler.Handle() - Атрибуты сериализуются и записываются в
io.Writer
Инициализация production-логгера
package main
import (
"io"
"log/slog"
"os"
)
func setupLogger() *slog.Logger {
opts := &slog.HandlerOptions{
Level: slog.LevelInfo,
AddSource: true, // Добавляет файл и строку вызова
ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
// Кастомизация атрибутов (например, переименование time -> ts)
if a.Key == slog.TimeKey {
a.Key = "ts"
}
return a
},
}
// JSON-формат предпочтителен для production
handler := slog.NewJSONHandler(os.Stdout, opts)
return slog.New(handler)
}
Механика записи и Mechanical Sympathy
Запись в os.Stdout или os.Stderr — это прямой системный вызов write(). Каждый Write переключает контекст Ring 3 → Ring 0, сбрасывает буферы ядра и может вызвать блокировку из-за contention на терминальном драйвере или pipe (в Docker/Kubernetes).
Для высоконагруженных сервисов всегда оборачивайте вывод в bufio.Writer или используйте пул буферов. Без буферизации 10 000 RPS с логами на каждый запрос = 10 000 syscall/sec, что легко съедает 15-30% CPU.
// Production-ready инициализация с буферизацией
func setupBufferedLogger() *slog.Logger {
w := bufio.NewWriter(os.Stdout)
// Важно: bufio.Writer НЕ потоко-безопасен по умолчанию.
// slog.Handler гарантирует синхронизацию на уровне Handler,
// но для максимальной производительности лучше использовать
// slog.NewJSONHandler с кастомным io.Writer, который сам управляет lock.
// Стандартный JSONHandler уже имеет встроенную синхронизацию через sync.Mutex.
handler := slog.NewJSONHandler(w, &slog.HandlerOptions{Level: slog.LevelInfo})
logger := slog.New(handler)
// Запуск фоновой горутин для периодического сброса буфера
go func() {
ticker := time.NewTicker(500 * time.Millisecond)
defer ticker.Stop()
for range ticker.C {
w.Flush() // Принудительный сброс, чтобы логи не терялись при панике
}
}()
return logger
}
Контекстуальное логирование и request-scoped данные
В PHP/Laravel вы можете использовать глобальные массивы или Log::withContext(). В Go контекст передается явно. slog интегрируется с context.Context через slog.WithContext и slog.FromContext.
// Middleware для добавления request_id
func logContextMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
reqID := uuid.New().String()
// Обогащаем контекст атрибутами логгера
logger := slog.Default().With("request_id", reqID, "user_agent", r.UserAgent())
ctx := slog.WithContext(r.Context(), logger)
next.ServeHTTP(w, r.WithContext(ctx))
})
}
// Использование в обработчике
func handleRequest(w http.ResponseWriter, r *http.Request) {
// Извлекаем обогащенный логгер
log := slog.Default()
if ctxLog := slog.FromContext(r.Context()); ctxLog != nil {
log = ctxLog
}
log.Info("processing request", "method", r.Method, "path", r.URL.Path)
// ... бизнес-логика
log.Info("request completed", "duration_ms", 42)
}
Это позволяет строить цепочку логов: Global -> Request -> Handler -> DB, где каждый уровень автоматически наследует атрибуты предыдущего без явного проброса.
Асинхронный логгер для Highload
Стандартный slog синхронный. Если io.Writer блокируется (медленный диск, переполненный pipe), вся горутина обработчика встанет. Для систем с SLO < 50ms требуется асинхронный логгер.
type AsyncHandler struct {
handler slog.Handler
ch chan slog.Record
done chan struct{}
}
func NewAsyncHandler(base slog.Handler, queueSize int) *AsyncHandler {
h := &AsyncHandler{
handler: base,
ch: make(chan slog.Record, queueSize),
done: make(chan struct{}),
}
go h.run()
return h
}
func (h *AsyncHandler) run() {
for r := range h.ch {
_ = h.handler.Handle(context.Background(), r)
}
if c, ok := h.handler.(io.Closer); ok {
_ = c.Close()
}
close(h.done)
}
func (h *AsyncHandler) Handle(ctx context.Context, r slog.Record) error {
// Контракт slog.Handler требует вызова r.Clone() при асинхронной обработке,
// чтобы предотвратить гонки данных за слайсы атрибутов при возврате из Handle
cloned := r.Clone()
select {
case h.ch <- cloned:
return nil
default:
// Очередь полна. Либо дропаем, либо пишем в stderr.
// В production надежнее дропнуть, чем заблокировать рабочую горутину.
_, _ = os.Stderr.WriteString("log queue full, dropping record\n")
return nil
}
}
// Остальные методы Enabled, WithAttrs, WithGroup делегируются base handler
Сравнение подходов
| Метод | Аллокации | CPU overhead | Контекст | Использование |
|---|---|---|---|---|
fmt.Println / log.Println |
Высокие (строки) | Низкий | Нет | Только для CLI/дебага |
log/slog (sync) |
Нулевые для примитивов | Средний | Встроенный context |
95% production-сервисов |
uber/zap (async) |
Нулевые | Минимальный | Ручной прокид | Extreme low-latency, трейдинг |
rs/zerolog |
Низкие | Низкий | Встроенный | Микросервисы с фокусом на JSON |
Итог
- Используйте
log/slogсJSONHandlerкак стандарт для новых проектов на Go 1.21+. - Избегайте
slog.Anyдля известных типов, используйтеslog.String,slog.Intдля zero-allocation. - Всегда буферизуйте
io.Writerчерезbufioили пулы для минимизации syscallwrite. - Интегрируйте логгер с
context.Contextдля автоматического наследованияrequest_id,user_id,trace_id. - Для highload-сервисов с жесткими SLO реализуйте асинхронный логгер с bounded-каналом и graceful drain при shutdown.
- Никогда не блокируйте горутины обработчика медленным I/O логгера — лучше дропнуть лог, чем потерять RPS.
Следующая статья: 15. Error handling в сервисах