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, а конечный автомат, отвечающий за фильтрацию уровней, форматирование и запись.

Go
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):

  1. Создается slog.Record (хранит уровень, время, сообщение и атрибуты)
  2. Вызывается handler.Handle()
  3. Атрибуты сериализуются и записываются в io.Writer

Инициализация production-логгера

Go
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.

Go
// 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.

Go
// 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 требуется асинхронный логгер.

Go
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

Итог

  1. Используйте log/slog с JSONHandler как стандарт для новых проектов на Go 1.21+.
  2. Избегайте slog.Any для известных типов, используйте slog.String, slog.Int для zero-allocation.
  3. Всегда буферизуйте io.Writer через bufio или пулы для минимизации syscall write.
  4. Интегрируйте логгер с context.Context для автоматического наследования request_id, user_id, trace_id.
  5. Для highload-сервисов с жесткими SLO реализуйте асинхронный логгер с bounded-каналом и graceful drain при shutdown.
  6. Никогда не блокируйте горутины обработчика медленным I/O логгера — лучше дропнуть лог, чем потерять RPS.

Следующая статья: 15. Error handling в сервисах