Skip to Content
ConventionsЛогирование

Логирование

Одинаковый формат логов во всех сервисах: одна команда в Grafana должна одинаково работать для user, review, media и любого будущего сервиса.

log/slog — стандарт

Используй log/slog из stdlib. Никаких logrus, zap, zerolog, log.Printf в прод-коде.

Handler

JSON → stdout. Никогда в файл. Никогда plain text в prod (plain-текст допустим только в локальной отладке через SERVICE_LOG_FORMAT=text, если сервис поддерживает такой флаг).

Настройка в cmd/server/main.go:

func newLogger(level string) *slog.Logger {
    var lv slog.Level
    _ = lv.UnmarshalText([]byte(level))
    h := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        Level:     lv,
        AddSource: false,
    })
    return slog.New(h).With(
        "service", "review",
    )
}

service навешивается один раз на корневой логгер — дальше везде присутствует как структурное поле. AddSource=false в prod: путь к файлу и номер строки съедает cardinality в логах; включай в dev.

Уровни

УровеньКогда использоватьПример
DEBUGЛокальная отладка. В prod выключен (INFO-порог).log.Debug("cache lookup", "key", key, "hit", hit)
INFOБизнес-события: «что произошло».log.Info("review created", "review_id", r.ID, "user_id", userID)
WARNRetryable ошибки, degraded path, таймаут одного из соседей.log.Warn("redis timeout, falling back to db", "err", err)
ERRORUnhandled ошибка, требует внимания.log.Error("publish outbox", "err", err, "topic", topic)

DEBUG в prod всегда выключен. INFO — базовый уровень прод-логгера.

Не пиши INFO на каждый HTTP-запрос — access-лог пишет middleware. INFO на уровне service — только значимые события (создан/удалён/сменил состояние).

Обязательные структурные поля

На каждой записи (через middleware log.FromCtx(ctx)), как минимум:

ПолеЗначение
request_idИз X-Request-Id header’а. Генерируется RequestID middleware на входе.
user_idbigint пользователя, если запрос authenticated. Иначе отсутствует.
routeПаттерн маршрута (/v1/reviews/{id}), не «фактический URL».
serviceИмя сервиса. Навешивается один раз в newLogger.
correlation_idCross-service id, прокидывается из header’а и из Kafka metadata.

Логгер прокидывается через ctx:

package log
 
type ctxKey int
const ctxKeyLogger ctxKey = iota
 
func Into(ctx context.Context, l *slog.Logger) context.Context {
    return context.WithValue(ctx, ctxKeyLogger, l)
}
 
func FromCtx(ctx context.Context) *slog.Logger {
    if l, ok := ctx.Value(ctxKeyLogger).(*slog.Logger); ok && l != nil {
        return l
    }
    return slog.Default()
}

Middleware оборачивает базовый логгер per-request:

func WithLog(base *slog.Logger) func(http.Handler) http.Handler {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
            l := base.With(
                "request_id", middleware.GetReqID(r.Context()),
                "route", chi.RouteContext(r.Context()).RoutePattern(),
            )
            ctx := log.Into(r.Context(), l)
            next.ServeHTTP(w, r.WithContext(ctx))
        })
    }
}

Handler / service пишет так:

log.FromCtx(ctx).Info("review created",
    "review_id", review.ID,
    "place_id", review.PlaceID,
    "user_id", userID,
)

Ошибки

log.FromCtx(ctx).Error("publish outbox",
    "err", err,
    "topic", topic,
    "aggregate_id", id,
)
  • Сообщение — статическое: "publish outbox", а не "publish outbox failed: "+err.Error(). Это даёт возможность группировать ошибки в дашборде по сообщению.
  • Ошибка — поле: "err", err. slog сам вызовет err.Error() и положит как строку в JSON.
  • Никогда не используй err.Error() как сообщение.

PII запрещено в логах

Категорически нельзя писать в лог в открытом виде:

  • email,
  • phone,
  • полный JWT (access/refresh),
  • password, password_hash,
  • OAuth access_token, OAuth refresh_token,
  • device_id (может быть идентификатором устройства),
  • IP-адрес (в ряде юрисдикций — PII).

Если нужно увидеть поле в логе — маскируй. Хелперы живут в pkg/pii/:

package pii
 
import "strings"
 
// MaskEmail: "abdymaget@gmail.com" → "a***@gmail.com"
func MaskEmail(s string) string {
    at := strings.Index(s, "@")
    if at <= 0 {
        return "***"
    }
    return s[:1] + "***" + s[at:]
}
 
// MaskPhone: "+77011234567" → "+7 701 *** ** 67"
func MaskPhone(s string) string {
    if len(s) < 4 {
        return "***"
    }
    return "*** " + s[len(s)-4:]
}
 
// MaskToken: возвращает короткий непривязанный хеш для поиска по логам.
func MaskToken(s string) string {
    sum := sha256.Sum256([]byte(s))
    return hex.EncodeToString(sum[:])[:16]
}

Использование:

log.FromCtx(ctx).Info("login attempt",
    "user_id", userID,
    "email_masked", pii.MaskEmail(req.Email),
)

Что можно логировать

  • user_id (bigint) — это публичный технический идентификатор, он уже безопасен.
  • review_id, place_id, session_id — внутренние ID.
  • event_type, topic — метаданные Kafka.
  • duration_ms, status_code.
  • error_code (sentinel-код ошибки) — не полное сообщение, которое мог бы показать пользователь. error_code=not_found, а не error_message="user 42 not found" (в последнем утекает существование конкретного id).

Sampling для hot path

Если endpoint обрабатывает > 1000 req/s — логировать каждый успешный запрос не нужно, это только греет диск. Но sampling должен быть детерминированным по trace_id: все записи одного trace либо полностью попадают в sampled-набор, либо полностью выпадают.

Проблема недетерминированного rand.Float64() < p. Per-request random означает, что в пределах одного trace одна запись лога попадёт в sampled, а следующая — нет. Восстановить полную картину запроса по trace невозможно: половина строк просто отсутствует.

Правило. Sampling выполняется детерминированно на основе trace_id. Все логи одного trace либо все логируются, либо все — нет.

Реализация:

// sampleByTrace возвращает true для `rate`-доли trace'ов детерминированно.
// rate = 0.01 → 1% trace'ов полностью залогированы, остальные — нет.
//
// Политика при нестандартном trace_id: fail-OPEN (логируем). Лучше лишний
// лог, чем потерянная запись в цепочке инцидента. Все такие случаи
// считаем в метрику, чтобы поймать системные проблемы с trace_id.
func sampleByTrace(traceID string, rate float64) bool {
    if rate <= 0 {
        return false
    }
    if rate >= 1 {
        return true
    }
    if len(traceID) < 8 {
        sampleTraceMalformed.WithLabelValues("too_short").Inc()
        return true
    }
    // Последние 8 hex-символов (32 бита) — наиболее энтропийная часть
    // в W3C trace-id, безопасно использовать как хеш.
    suffix := traceID[len(traceID)-8:]
    v, err := strconv.ParseUint(suffix, 16, 32)
    if err != nil {
        sampleTraceMalformed.WithLabelValues("parse_error").Inc()
        return true
    }
    // Округление через math.Round, чтобы rate=0.01 давал стабильно ~1%,
    // а не 0.99% из-за truncation.
    threshold := uint32(math.Round(rate * float64(math.MaxUint32)))
    return uint32(v) < threshold
}

sampleTraceMalformed — CounterVec{reason} в том же пакете. Alert: rate(log_sample_trace_malformed_total[15m]) > 0 → ticket: в trace- propagation сломалось, надо чинить отдельно (unwanted fail-open означает, что часть логов идёт мимо sampling’а и может пересоздать давление на Loki).

Использование в middleware / handler:

if sampleByTrace(traceIDFromCtx(ctx), 0.01) {
    log.FromCtx(ctx).Info("request served", "status", status, "duration_ms", d)
}

Rate-конфигурация по уровням

  • Hot-path access-log (успешные 2xx) — sample 1% (0.01).
  • ERROR (5xx, panic) — никогда не sample, логируй все без исключения.
  • WARN — sample 10% (0.10).
  • DEBUG в prod — off (0.00); включается только по явному per-request debug-флагу в header.

Rate задаётся env-переменными, никаких hard-coded значений в коде:

LOG_SAMPLE_RATE_INFO=0.01
LOG_SAMPLE_RATE_WARN=0.10
LOG_SAMPLE_RATE_DEBUG=0.00

Anti-pattern

rand.Float64() < rate без привязки к trace_id — запрещён. Trace с частичными логами бесполезен для отладки: ты видишь, что запрос стартовал, но не видишь, где именно он упал, потому что половина промежуточных записей выпала в rand-lottery.

Correlation-Id vs Request-Id

Два разных ID, не путай:

  • Request-Id (X-Request-Id, поле request_id в логе) — идентификатор одного HTTP-запроса. Генерируется на входе в сервис (chimw.RequestID или приходит от Gateway) и живёт только в пределах этого запроса.
  • Correlation-Id (X-Correlation-Id, Kafka metadata Correlation-Id, поле correlation_id в логе) — идентификатор цепочки, которая может пройти через несколько сервисов и Kafka. Может совпадать с Request-Id (если Gateway положил то же значение), но не обязан.
  • traceparent — W3C-стандарт OpenTelemetry (trace_id + span_id), отдельный канал для distributed tracing. Не путай с Correlation-Id.

Correlation-Id прокидывается через всё:

  • HTTP: header X-Correlation-Id, читается middleware, кладётся в ctx и в логгер.
  • Kafka: metadata Correlation-Id (envelope) → при consume ложится в ctx через Watermill middleware CorrelationID.
  • Logger: поле correlation_id присутствует во всех записях одного запроса/сообщения.

Если header не пришёл — middleware генерирует ULID. Для исходящих HTTP-вызовов в другой сервис — передавай X-Correlation-Id из ctx.

Запреты

  • fmt.Println / fmt.Printf / log.Print в прод-коде — запрещены. CI-lint (forbidigo) отлавливает.
  • panic("...") ради «залогировать и упасть» — нет. Возвращай error, логируй на ERROR, решение об exit принимает вызывающий уровень.
  • Логирование в цикле на каждый элемент — убивает производительность и читаемость. Лог на батч — да, лог на каждую итерацию — нет.
  • log.FromCtx(context.Background()) в handler/service — это значит, что ты где-то потерял per-request логгер. Чини цепочку ctx.

Пример полной цепочки

func (h *ReviewHandler) CreateReview(w http.ResponseWriter, r *http.Request) {
    ctx := r.Context()
    var req CreateReviewRequest
    if err := decodeJSON(r, &req); err != nil {
        writeError(w, http.StatusBadRequest, "invalid_request", "bad json")
        return
    }
    if err := validate(req); err != nil {
        writeError(w, http.StatusBadRequest, "invalid_input", "validation failed")
        return
    }
    userID, _ := middleware.UserIDFrom(ctx)
    review, err := h.svc.Create(ctx, service.CreateReviewCommand{
        UserID:  userID,
        PlaceID: req.PlaceID,
        Rating:  req.Rating,
    })
    if err != nil {
        log.FromCtx(ctx).Warn("create review failed", "err", err, "place_id", req.PlaceID)
        mapServiceError(w, err)
        return
    }
    log.FromCtx(ctx).Info("review created", "review_id", review.ID, "place_id", review.PlaceID)
    writeJSON(w, http.StatusCreated, map[string]any{"data": review})
}

Вывод в stdout:

{"time":"...","level":"INFO","msg":"review created","service":"review","request_id":"01HZ..","route":"/v1/reviews","user_id":42,"review_id":1001,"place_id":7}

По этому JSON-у Grafana/Loki строит поиск за 5 секунд. По fmt.Printf("review %d created\n", id) — никак.

См. также

  • observability — как логи соединяются с метриками и трейсами.
  • security — правила маскирования PII, запрет логировать секреты и Authorization header.
Last updated on
События (Kafka)Тестирование