Урок 24: Логирование — zerolog, контекстное, sampling

Урок 24. Логирование — zerolog, контекстное, sampling

🔄 Node.js → Go (ключевые аналоги):

winston / pino → github.com/rs/zerolog
logger.info({ user }, 'message') → log.Info().Interface("user", u).Msg("message")
logger.child({ requestId }) → log.With().Str("request_id", id).Logger()
pino-pretty → zerolog.ConsoleWriter
morgan (HTTP-логирование) → middleware с zerolog

📋 Что изучаем

zerolog — zero-allocation JSON-логгер для продакшена
- Уровни логирования: Trace, Debug, Info, Warn, Error, Fatal, Panic
- Контекстное логирование — проброс request ID, user ID
- Структурированные поля — Str, Int, Err, Interface, Time
- Sub-logger — создание логгера с предзаполненными полями
- Sampling — снижение объёма логов в проде
- HTTP middleware — автоматическое логирование запросов
- Запись в файл + ротация (lumberjack)

📦 Инициализация проекта

mkdir go-logging && cd go-logging
go mod init go-logging

# Устанавливаем зависимости
go get github.com/rs/zerolog
go get github.com/google/uuid
go get gopkg.in/natefinch/lumberjack.v2
go mod tidy

# Создаём структуру
mkdir -p internal/logger
mkdir -p internal/middleware
mkdir -p cmd/server

💻 Файл: `internal/logger/logger.go`

package logger

import (
    "context"
    "io"
    "os"
    "time"

    "github.com/rs/zerolog"
    "gopkg.in/natefinch/lumberjack.v2"
)

// ContextKey — тип для ключей контекста
type ContextKey string

const (
    RequestIDKey ContextKey = "request_id"
    UserIDKey    ContextKey = "user_id"
)

// Config — конфигурация логгера
type Config struct {
    Level      string // trace, debug, info, warn, error, fatal, panic
    Output     string // stdout, file
    FilePath   string // путь к файлу (если Output == "file")
    MaxSizeMB  int    // максимальный размер файла до ротации
    MaxBackups int    // количество старых файлов
    Console    bool   // человекочитаемый вывод (для разработки)
    Sampling   *SamplingConfig
}

type SamplingConfig struct {
    Initial    int           // первые N сообщений
    Thereafter int           // затем 1 из N
    Tick       time.Duration // интервал сброса
}

// New — создаёт zerolog.Logger
func New(cfg Config) zerolog.Logger {
    // 1. Выбираем writer
    var output io.Writer

    switch cfg.Output {
    case "file":
        output = &lumberjack.Logger{
            Filename:   cfg.FilePath,
            MaxSize:    cfg.MaxSizeMB,
            MaxBackups: cfg.MaxBackups,
            Compress:   true,
        }
    default:
        output = os.Stdout
    }

    // 2. Console writer для разработки
    if cfg.Console {
        output = zerolog.ConsoleWriter{
            Out:        output,
            TimeFormat: time.RFC3339,
            NoColor:    false,
        }
    }

    // 3. Настраиваем уровень
    level := parseLevel(cfg.Level)
    log := zerolog.New(output).
        Level(level).
        With().
        Timestamp().
        Caller(). // Добавляет файл:строку
        Logger()

    // 4. Sampling (для продакшена)
    if cfg.Sampling != nil {
        log = log.Sample(&zerolog.BurstSampler{
            Burst:  cfg.Sampling.Initial,
            Period: cfg.Sampling.Tick,
            NextSampler: &zerolog.BasicSampler{
                N: uint32(cfg.Sampling.Thereafter),
            },
        })
    }

    return log
}

// DefaultDevelopment — логгер для локальной разработки
func DefaultDevelopment() zerolog.Logger {
    return New(Config{
        Level:   "debug",
        Output:  "stdout",
        Console: true,
    })
}

// DefaultProduction — логгер для продакшена (JSON + sampling)
func DefaultProduction() zerolog.Logger {
    return New(Config{
        Level:  "info",
        Output: "stdout",
        Sampling: &SamplingConfig{
            Initial:    100,
            Thereafter: 100,
            Tick:       1 * time.Second,
        },
    })
}

// ╔══════════════════════════════════════════════════════════╗
// ║  КОНТЕКСТНОЕ ЛОГИРОВАНИЕ                               ║
// ╚══════════════════════════════════════════════════════════╝

// WithRequestID — добавляет request ID в контекст
func WithRequestID(ctx context.Context, id string) context.Context {
    return context.WithValue(ctx, RequestIDKey, id)
}

// WithUserID — добавляет user ID в контекст
func WithUserID(ctx context.Context, id string) context.Context {
    return context.WithValue(ctx, UserIDKey, id)
}

// FromContext — извлекает логгер из контекста (или глобальный)
func FromContext(ctx context.Context) *zerolog.Logger {
    logger := zerolog.Ctx(ctx)
    if logger.GetLevel() == zerolog.Disabled {
        // Если логгер не был добавлен — создаём
        l := DefaultDevelopment()
        logger = &l
    }
    return logger
}

// CtxWithLogger — кладёт логгер в контекст с полями из контекста
func CtxWithLogger(ctx context.Context, log zerolog.Logger) context.Context {
    // Добавляем поля из контекста
    if reqID, ok := ctx.Value(RequestIDKey).(string); ok {
        log = log.With().Str("request_id", reqID).Logger()
    }
    if userID, ok := ctx.Value(UserIDKey).(string); ok {
        log = log.With().Str("user_id", userID).Logger()
    }
    return log.WithContext(ctx)
}

// ╔══════════════════════════════════════════════════════════╗
// ║  ВСПОМОГАТЕЛЬНЫЕ ФУНКЦИИ                                ║
// ╚══════════════════════════════════════════════════════════╝

func parseLevel(level string) zerolog.Level {
    switch level {
    case "trace":
        return zerolog.TraceLevel
    case "debug":
        return zerolog.DebugLevel
    case "info":
        return zerolog.InfoLevel
    case "warn":
        return zerolog.WarnLevel
    case "error":
        return zerolog.ErrorLevel
    case "fatal":
        return zerolog.FatalLevel
    default:
        return zerolog.InfoLevel
    }
}

💻 Файл: `internal/middleware/logging.go`

package middleware

import (
    "net/http"
    "time"

    "github.com/google/uuid"
    "github.com/rs/zerolog"
    "go-logging/internal/logger"
)

// LoggingMiddleware — HTTP middleware для логирования запросов
func LoggingMiddleware(log zerolog.Logger) func(http.Handler) http.Handler {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
            start := time.Now()

            // Генерируем или получаем request ID
            reqID := r.Header.Get("X-Request-ID")
            if reqID == "" {
                reqID = uuid.New().String()
            }
            w.Header().Set("X-Request-ID", reqID)

            // Добавляем request ID в контекст
            ctx := logger.WithRequestID(r.Context(), reqID)

            // Создаём sub-logger с полями запроса
            reqLogger := log.With().
                Str("request_id", reqID).
                Str("method", r.Method).
                Str("path", r.URL.Path).
                Str("remote_addr", r.RemoteAddr).
                Str("user_agent", r.UserAgent()).
                Logger()

            // Кладём логгер в контекст
            ctx = logger.CtxWithLogger(ctx, reqLogger)
            r = r.WithContext(ctx)

            // Логируем начало запроса
            reqLogger.Debug().Msg("request started")

            // Оборачиваем ResponseWriter для захвата статуса
            wrapped := &responseWriter{ResponseWriter: w, statusCode: http.StatusOK}

            // Выполняем запрос
            next.ServeHTTP(wrapped, r)

            // Логируем завершение
            duration := time.Since(start)
            logEvent := reqLogger.Info().
                Int("status", wrapped.statusCode).
                Dur("duration", duration).
                Int("bytes_written", wrapped.bytesWritten)

            // Добавляем ошибку для 5xx
            if wrapped.statusCode >= 500 {
                logEvent = reqLogger.Error().
                    Int("status", wrapped.statusCode).
                    Dur("duration", duration)
            }

            logEvent.Msg("request completed")
        })
    }
}

// RecoveryMiddleware — ловит паники и логирует их
func RecoveryMiddleware(log zerolog.Logger) func(http.Handler) http.Handler {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
            defer func() {
                if rec := recover(); rec != nil {
                    logger.FromContext(r.Context()).
                        Error().
                        Interface("panic", rec).
                        Bytes("stack", debug.Stack()).
                        Msg("panic recovered")

                    http.Error(w, "Internal Server Error", http.StatusInternalServerError)
                }
            }()
            next.ServeHTTP(w, r)
        })
    }
}

// responseWriter — обёртка для захвата статуса и размера ответа
type responseWriter struct {
    http.ResponseWriter
    statusCode   int
    bytesWritten int
}

func (rw *responseWriter) WriteHeader(code int) {
    rw.statusCode = code
    rw.ResponseWriter.WriteHeader(code)
}

func (rw *responseWriter) Write(b []byte) (int, error) {
    n, err := rw.ResponseWriter.Write(b)
    rw.bytesWritten += n
    return n, err
}

import "runtime/debug"

💻 Файл: `cmd/server/main.go`

package main

import (
    "context"
    "errors"
    "fmt"
    "net/http"
    "os"
    "os/signal"
    "syscall"
    "time"

    "github.com/rs/zerolog"
    "go-logging/internal/logger"
    "go-logging/internal/middleware"
)

// Service — имитация бизнес-логики
type Service struct{}

func (s *Service) GetUser(ctx context.Context, id string) (string, error) {
    log := logger.FromContext(ctx)

    log.Debug().Str("user_id", id).Msg("fetching user from database")

    // Имитация задержки
    time.Sleep(50 * time.Millisecond)

    if id == "error" {
        err := errors.New("database connection lost")
        log.Error().Err(err).Str("user_id", id).Msg("failed to fetch user")
        return "", err
    }

    log.Info().Str("user_id", id).Msg("user fetched successfully")
    return fmt.Sprintf("User-%s", id), nil
}

func main() {
    // Создаём логгер (development или production)
    var log zerolog.Logger
    if os.Getenv("APP_ENV") == "production" {
        log = logger.DefaultProduction()
    } else {
        log = logger.DefaultDevelopment()
    }

    log.Info().Msg("server starting...")
    log.Debug().Str("env", os.Getenv("APP_ENV")).Msg("configuration")

    svc := &Service{}

    // Создаём роутер
    mux := http.NewServeMux()

    mux.HandleFunc("GET /api/users/{id}", func(w http.ResponseWriter, r *http.Request) {
        id := r.PathValue("id")

        // Извлекаем логгер из контекста (с request_id!)
        log := logger.FromContext(r.Context())

        // Логируем с дополнительным контекстом
        log.Info().
            Str("endpoint", "get_user").
            Str("user_id", id).
            Msg("handling request")

        user, err := svc.GetUser(r.Context(), id)
        if err != nil {
            log.Error().Err(err).Msg("failed to get user")
            http.Error(w, "Internal error", http.StatusInternalServerError)
            return
        }

        // Демонстрация структурированных полей
        log.Info().
            Str("user", user).
            Int("response_size", len(user)).
            Msg("sending response")

        w.Header().Set("Content-Type", "application/json")
        fmt.Fprintf(w, `{"user": "%s"}`, user)
    })

    // Эндпоинт для демонстрации паники
    mux.HandleFunc("GET /api/panic", func(w http.ResponseWriter, r *http.Request) {
        log := logger.FromContext(r.Context())
        log.Warn().Msg("about to panic!")
        panic("something went terribly wrong!")
    })

    // Эндпоинт для демонстрации ошибки
    mux.HandleFunc("GET /api/error", func(w http.ResponseWriter, r *http.Request) {
        log := logger.FromContext(r.Context())
        log.Error().
            Str("error_code", "ERR_DB_TIMEOUT").
            Dur("timeout", 5*time.Second).
            Msg("database timeout")

        http.Error(w, `{"error":"database timeout"}`, http.StatusGatewayTimeout)
    })

    // Эндпоинт для демонстрации разных уровней логирования
    mux.HandleFunc("GET /api/log-levels", func(w http.ResponseWriter, r *http.Request) {
        log := logger.FromContext(r.Context())

        log.Trace().Msg("trace: very detailed debugging")
        log.Debug().Msg("debug: useful for development")
        log.Info().Msg("info: something happened")
        log.Warn().Msg("warn: something concerning")
        log.Error().Msg("error: something failed")

        fmt.Fprintf(w, "All log levels demonstrated. Check console.\n")
    })

    // Применяем middleware
    handler := middleware.LoggingMiddleware(log)(mux)
    handler = middleware.RecoveryMiddleware(log)(handler)

    server := &http.Server{
        Addr:    ":8080",
        Handler: handler,
    }

    // Graceful shutdown
    go func() {
        log.Info().Str("addr", server.Addr).Msg("server listening")
        if err := server.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) {
            log.Fatal().Err(err).Msg("server failed")
        }
    }()

    quit := make(chan os.Signal, 1)
    signal.Notify(quit, syscall.SIGINT, syscall.SIGTERM)
    <-quit

    log.Warn().Msg("shutting down server...")

    ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
    defer cancel()

    if err := server.Shutdown(ctx); err != nil {
        log.Error().Err(err).Msg("server shutdown error")
    }

    log.Info().Msg("server stopped")
}

🚀 Запуск и тестирование

# Development режим (консольный вывод)
go run ./cmd/server/main.go

# Production режим (JSON + sampling)
APP_ENV=production go run ./cmd/server/main.go

# Тестирование эндпоинтов
curl http://localhost:8080/api/users/42
curl -H "X-Request-ID: my-custom-id" http://localhost:8080/api/users/123
curl http://localhost:8080/api/error
curl http://localhost:8080/api/log-levels
curl http://localhost:8080/api/panic
curl http://localhost:8080/api/users/error

# Запись в файл
APP_ENV=production LOG_OUTPUT=file LOG_FILE=/tmp/app.log \
  go run ./cmd/server/main.go

📊 Уровни логирования в zerolog

Уровень	Метод	Когда использовать
Trace (-1)	`log.Trace()`	Очень детальная отладка (в проде выключен)
Debug (0)	`log.Debug()`	Отладка, разработка
Info (1)	`log.Info()`	Штатные события: запросы, создание сущностей
Warn (2)	`log.Warn()`	Предупреждения: retry, деградация
Error (3)	`log.Error()`	Ошибки, требующие внимания
Fatal (4)	`log.Fatal()`	Критическая ошибка → os.Exit(1)
Panic (5)	`log.Panic()`	Критическая ошибка → panic()

📊 Популярные логгеры для Go

Библиотека	Особенности	Аналог в Node.js
zerolog	Zero allocation, самый быстрый, JSON	pino
zap	Очень быстрый, structured, от Uber	pino
logrus	Structured, много плагинов, медленнее	winston
slog (std)	Стандартная библиотека Go 1.21+	console.log с уровнями

⚠️ Типичные ошибки:

Логирование чувствительных данных: Пароли, токены, PII не должны попадать в логи.
- Слишком много логов: Debug в проде — лишняя нагрузка. Используйте sampling.
- Забыли Msg() в конце: Zerolog не пишет лог, пока не вызван Msg() или Send().
- Контекст без логгера: zerolog.Ctx() возвращает disabled-логгер, если не добавили.

💡 Практический совет:

💡 Best practices от сеньоров:

Структурированный JSON: Все поля — отдельные ключи. Не пишите текст в одно поле message.
- Request ID во всех логах: Пробрасывайте через контекст. Ищите по ID в ELK/Loki.
- Sampling в проде: Логируйте не каждый запрос, а 1 из N для снижения нагрузки.
- Fatal только в main: Fatal вызывает os.Exit — defer не выполнится.
- Логируйте ошибки ОДИН раз: Либо в middleware, либо в сервисе. Не дублируйте.

🔑 Ключевые концепции

Что нужно запомнить из этого урока:

zerolog — zero-allocation логгер: Самый производительный JSON-логгер для Go.
- Цепочка вызовов: log.Info().Str(“key”, “val”).Int(“count”, 42).Msg(“message”).
- Контекстное логирование: log.WithContext(ctx) / zerolog.Ctx(ctx).
- Sub-logger: log.With().Str(“service”, “auth”).Logger() — предзаполненные поля.
- Sampling: Ограничение количества логов в единицу времени.
- Msg() обязателен: Без него лог не записывается.

💡 Для Node.js разработчика:

zerolog — прямой аналог pino. Zero-allocation, JSON, невероятно быстрый.
- Цепочка методов — вместо объекта: log.info({ user }, 'msg') → log.Info().Interface("user", u).Msg("msg").
- Контекстный логгер — как logger.child({ requestId }) в pino.
- Sampling встроен в zerolog (BurstSampler). В pino — через плагин.
- Lumberjack для ротации — как winston-daily-rotate-file.

← Предыдущий урок Следующий урок →

Урок 24: Логирование — zerolog, контекстное, sampling

Урок 24. Логирование — zerolog, контекстное, sampling

📋 Что изучаем

📦 Инициализация проекта

💻 Файл: internal/logger/logger.go

💻 Файл: internal/middleware/logging.go

💻 Файл: cmd/server/main.go

🚀 Запуск и тестирование

📊 Уровни логирования в zerolog

📊 Популярные логгеры для Go

🔑 Ключевые концепции

Что нужно запомнить из этого урока:

💻 Файл: `internal/logger/logger.go`

💻 Файл: `internal/middleware/logging.go`

💻 Файл: `cmd/server/main.go`