Observability/Средний ~ 55 мин

Structured logging в Go: slog, context и request id

Логи нужны не для того, чтобы "что-то печаталось". Во время инцидента они должны отвечать на конкретные вопросы:

какой запрос или job сломался;
в каком компоненте это произошло;
какая зависимость была затронута;
можно ли повторить операцию;
есть ли рядом trace, metric spike или deploy.

Хороший лог - это событие в виде данных. Человек читает msg, машина фильтрует поля. Если поля хаотичные, то через месяц команда начинает искать ошибки регулярками по тексту и вручную вспоминать, как назывался идентификатор: requestID, request_id, rid или trace.

В Go для курса берем стандартный log/slog: он есть в стандартной библиотеке с Go 1.21, умеет JSON handler, уровни, With, WithGroup, ReplaceAttr и динамический LevelVar.

Лог как контракт

Плохой лог:

error while convert

Он не отвечает почти ни на что. Какой route? Какая валюта? Ошибка пользователя или инфраструктуры? Можно ли найти соседние события?

Хороший лог:

{
  "time": "2026-05-06T12:00:00Z",
  "level": "ERROR",
  "msg": "convert request failed",
  "event": "convert.failed",
  "service": "ratedesk-api",
  "env": "production",
  "version": "1.12.4",
  "request_id": "req_42",
  "trace_id": "6b6d9c9c7c8f4c8e9a4c7a0a5a8f2e01",
  "span_id": "f3d8a7b1c2d3e4f5",
  "http.method": "POST",
  "http.route": "/convert",
  "http.status_code": 500,
  "http.duration_ms": 183,
  "currency.from": "USD",
  "currency.to": "EUR",
  "error.kind": "dependency_timeout",
  "error.message": "postgres query timeout"
}

Здесь msg можно читать глазами, а event, request_id, trace_id, http.route, error.kind можно использовать в Loki, Elastic/OpenSearch, Grafana и runbook.

Базовая log schema

Схему лучше описать прямо в README или docs/observability/logging.md. Минимальный набор для backend-сервиса:

Поле	Пример	Зачем
`time`	`2026-05-06T12:00:00Z`	Время события.
`level`	`INFO`, `WARN`, `ERROR`	Фильтрация по важности.
`msg`	`convert request failed`	Читаемый текст.
`event`	`convert.failed`	Стабильный machine-readable код.
`service`	`ratedesk-api`	Кто породил лог.
`env`	`prod`, `stage`, `local`	Окружение.
`version`	git SHA или semver	Связь с релизом.
`component`	`http`, `repository`, `consumer`	Зона кода.
`request_id`	`req_...`	Корреляция без tracing.
`trace_id`	hex trace id	Переход в trace.
`span_id`	hex span id	Точный span внутри trace.
`http.method`	`POST`	HTTP-разрез.
`http.route`	`/convert`	Нормализованный route, не raw URL.
`http.status_code`	`500`	Статус ответа.
`http.duration_ms`	`183`	Длительность запроса.
`error.kind`	`validation`, `db_timeout`	Классификация ошибки.
`error.message`	`context deadline exceeded`	Текст ошибки без секретов.

Важно отделять event от msg. Текст можно улучшать, переводить, уточнять. event должен оставаться стабильным, иначе сохраненные запросы и alert rules начнут ломаться.

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

Политика уровней должна быть скучной и предсказуемой:

Level	Когда использовать	Когда не использовать
`DEBUG`	Временная диагностика, детали retry, payload shape без PII.	Постоянный production-шум.
`INFO`	Жизненный цикл сервиса, успешные важные business events, access logs.	Каждая внутренняя функция.
`WARN`	Деградация, fallback, retry exhausted soon, подозрительное состояние.	Обычная 404/validation ошибка.
`ERROR`	Операция не выполнена из-за ошибки системы или зависимости.	Любая пользовательская ошибка.

rate not found может быть доменной ошибкой и HTTP 404, а не ERROR. postgres timeout или kafka publish failed - почти всегда ERROR.

Настройка slog

package observability

import (
    "log/slog"
    "os"
    "strings"
)

var level slog.LevelVar

func redactAttr(_ []string, a slog.Attr) slog.Attr {
    key := strings.ToLower(a.Key)
    switch key {
    case "password", "token", "access_token", "refresh_token",
        "authorization", "cookie", "secret", "api_key":
        return slog.String(a.Key, "[REDACTED]")
    }
    return a
}

func NewLogger(service, env, version string) *slog.Logger {
    if env == "local" || env == "dev" {
        level.Set(slog.LevelDebug)
    } else {
        level.Set(slog.LevelInfo)
    }

    handler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        Level:       &level,
        AddSource:   env != "production",
        ReplaceAttr: redactAttr,
    })

    return slog.New(handler).With(
        "service", service,
        "env", env,
        "version", version,
    )
}

ReplaceAttr не заменяет нормальную security-политику, но это хороший последний барьер. Лучше редактировать секреты централизованно, чем надеяться, что каждый разработчик вспомнит про это в каждом handler.

Request id

request_id - минимальный ключ корреляции. Он работает даже без OpenTelemetry и distributed tracing.

Правила:

если клиент прислал валидный X-Request-Id, сохраняем его;
если не прислал, генерируем;
возвращаем id в response header;
кладем id в context.Context;
добавляем id во все logs на пути запроса.

package observability

import (
    "context"
    "crypto/rand"
    "encoding/hex"
    "net/http"
)

type requestIDKey struct{}

func WithRequestID(ctx context.Context, id string) context.Context {
    return context.WithValue(ctx, requestIDKey{}, id)
}

func RequestID(ctx context.Context) string {
    id, _ := ctx.Value(requestIDKey{}).(string)
    return id
}

func newRequestID() string {
    var b [16]byte
    if _, err := rand.Read(b[:]); err != nil {
        return "req_unknown"
    }
    return "req_" + hex.EncodeToString(b[:])
}

func RequestIDMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        id := r.Header.Get("X-Request-Id")
        if id == "" || len(id) > 128 {
            id = newRequestID()
        }

        w.Header().Set("X-Request-Id", id)
        next.ServeHTTP(w, r.WithContext(WithRequestID(r.Context(), id)))
    })
}

Logger из context

Не надо прокидывать requestID string через все слои. Передавайте context.Context, а logger собирайте на границе transport/middleware.

type loggerKey struct{}

func WithLogger(ctx context.Context, logger *slog.Logger) context.Context {
    return context.WithValue(ctx, loggerKey{}, logger)
}

func Logger(ctx context.Context, fallback *slog.Logger) *slog.Logger {
    logger, _ := ctx.Value(loggerKey{}).(*slog.Logger)
    if logger == nil {
        return fallback
    }
    return logger
}

Middleware:

func LoggingMiddleware(base *slog.Logger, next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK}

        logger := base.With(
            "request_id", RequestID(r.Context()),
            "http.method", r.Method,
            "http.route", routePattern(r),
        )

        if sc := trace.SpanContextFromContext(r.Context()); sc.IsValid() {
            logger = logger.With(
                "trace_id", sc.TraceID().String(),
                "span_id", sc.SpanID().String(),
            )
        }

        ctx := WithLogger(r.Context(), logger)
        next.ServeHTTP(rec, r.WithContext(ctx))

        logger.Info("http request completed",
            "event", "http.request.completed",
            "http.status_code", rec.status,
            "http.duration_ms", time.Since(start).Milliseconds(),
        )
    })
}

В реальном router используйте route pattern (/users/{id}), а не r.URL.Path (/users/123). Полный path с id создает лишнюю кардинальность и в логах, и в метриках.

Echo middleware

В учебном backend используется Echo v4, поэтому тот же контракт удобно завернуть в middleware. Важно брать route pattern через c.Path(), а не raw path.

func EchoRequestID() echo.MiddlewareFunc {
    return func(next echo.HandlerFunc) echo.HandlerFunc {
        return func(c echo.Context) error {
            id := c.Request().Header.Get("X-Request-Id")
            if id == "" || len(id) > 128 {
                id = newRequestID()
            }

            c.Response().Header().Set("X-Request-Id", id)
            req := c.Request()
            ctx := WithRequestID(req.Context(), id)
            c.SetRequest(req.WithContext(ctx))

            return next(c)
        }
    }
}

func EchoAccessLog(base *slog.Logger) echo.MiddlewareFunc {
    return func(next echo.HandlerFunc) echo.HandlerFunc {
        return func(c echo.Context) error {
            start := time.Now()
            req := c.Request()

            logger := base.With(
                "request_id", RequestID(req.Context()),
                "http.method", req.Method,
                "http.route", c.Path(),
            )
            if sc := trace.SpanContextFromContext(req.Context()); sc.IsValid() {
                logger = logger.With(
                    "trace_id", sc.TraceID().String(),
                    "span_id", sc.SpanID().String(),
                )
            }

            ctx := WithLogger(req.Context(), logger)
            c.SetRequest(req.WithContext(ctx))

            err := next(c)
            if err != nil {
                c.Error(err)
            }

            status := c.Response().Status
            level := slog.LevelInfo
            if status >= 500 {
                level = slog.LevelError
            }

            logger.Log(ctx, level, "http request completed",
                "event", "http.request.completed",
                "http.status_code", status,
                "http.duration_ms", time.Since(start).Milliseconds(),
            )
            return nil
        }
    }
}

Подключение:

e := echo.New()
logger := observability.NewLogger("ratedesk-api", cfg.Env, cfg.Version)
e.Use(observability.EchoRequestID())
e.Use(observability.EchoAccessLog(logger))

Error taxonomy

Если все ошибки логируются как error, во время инцидента придется читать текст каждой. Заведите небольшую классификацию:

`error.kind`	Пример
`validation`	Некорректный input.
`not_found`	Доменный объект не найден.
`dependency_timeout`	Timeout PostgreSQL, Redis, provider API.
`dependency_unavailable`	Connection refused, broker down.
`conflict`	Optimistic lock, duplicate command.
`internal`	Неожиданная ошибка приложения.

Для expected domain errors можно логировать INFO или WARN, а для dependency/system failures - ERROR.

func LogError(ctx context.Context, base *slog.Logger, msg string, err error, attrs ...any) {
    logger := Logger(ctx, base)
    fields := []any{
        "event", "operation.failed",
        "error.kind", classify(err),
        "error.message", safeErrorMessage(err),
    }
    fields = append(fields, attrs...)
    logger.Error(msg, fields...)
}

Таксономия должна рождаться рядом с границей, где ошибка получает смысл:

Слой	Что знает	Что ставит
Repository/adapter	PostgreSQL timeout, Redis unavailable, provider 502.	`dependency_timeout`, `dependency_unavailable`.
Usecase	Доменный конфликт, rate not found, stale data policy.	`conflict`, `not_found`, `stale_data`.
Transport	HTTP status, route, validation body.	`validation`, `unauthorized`, `bad_request`.

Не заставляйте domain layer импортировать logging package. Domain возвращает типизированную ошибку, а transport/usecase boundary превращает ее в error.kind, HTTP/gRPC status и span status.

Тестирование логов

Логи можно и нужно тестировать. Проверяйте JSON-поля как данные, а не через fragile substring по всей строке.

func TestLoggerRedactsSecrets(t *testing.T) {
    var buf bytes.Buffer
    logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{
        ReplaceAttr: redactAttr,
    }))

    logger.Info("login failed",
        "event", "auth.login.failed",
        "request_id", "req_test",
        "Authorization", "Bearer secret",
        "password", "qwerty",
    )

    var got map[string]any
    if err := json.Unmarshal(buf.Bytes(), &got); err != nil {
        t.Fatal(err)
    }
    if got["request_id"] != "req_test" {
        t.Fatalf("request_id = %v", got["request_id"])
    }
    if got["Authorization"] != "[REDACTED]" {
        t.Fatalf("authorization was not redacted: %v", got["Authorization"])
    }
    if got["password"] != "[REDACTED]" {
        t.Fatalf("password was not redacted: %v", got["password"])
    }
}

Для access log добавьте тест через httptest или Echo test context: входящий X-Request-Id должен вернуться в response и попасть в JSON log.

Что нельзя логировать

Не логируйте:

access token, refresh token, API key, password;
Authorization, Cookie, Set-Cookie;
полный номер карты, CVV, приватные ключи;
паспортные данные и PII без явного основания;
большие request/response body целиком;
SQL с чувствительными параметрами;
ошибки, в которые случайно попали секреты.

Если payload нужен для диагностики, логируйте форму и безопасные признаки: payload_size, schema_version, field_count, currency.from, currency.to, но не весь JSON.

stdout в контейнерах

В контейнере приложение обычно пишет JSON logs в stdout/stderr. Оно не должно само писать application logs в файл внутри контейнера.

Типовая схема:

Go app stdout
  -> container runtime
  -> node agent / sidecar / collector
  -> Loki, Elasticsearch, OpenSearch or vendor
  -> Grafana/Kibana/OpenSearch Dashboards

Ротация, доставка и retention - ответственность runtime/collector/backend. Приложение отвечает за смысл и структуру события.

Loki, Alloy и labels

Loki дешевле и проще, когда вам нужен поиск рядом с Grafana и связь logs -> traces -> metrics. Важное ограничение: Loki индексирует labels, а не весь JSON как Elasticsearch. Поэтому labels должны быть низкокардинальными:

Хорошие labels:

service="ratedesk-api"
env="production"
level="error"
namespace="mentor"

Плохие labels:

request_id="req_..."
trace_id="..."
user_id="42"
order_id="..."
error_message="..."

request_id и trace_id оставляйте JSON-полями, по которым можно искать, но не превращайте их в labels.

На 6 мая 2026 Promtail уже EOL с 2 марта 2026. Для новых учебных материалов основной путь лучше показывать через Grafana Alloy, а Promtail упоминать как legacy/migration topic.

Пример Alloy-фрагмента для файловых логов:

local.file_match "containers" {
  path_targets = [{
    __path__ = "/var/log/containers/*.log",
    job      = "kubernetes",
  }]
}

loki.source.file "containers" {
  targets    = local.file_match.containers.targets
  forward_to = [loki.write.default.receiver]
}

loki.write "default" {
  endpoint {
    url = "http://loki:3100/loki/api/v1/push"
  }
}

ELK/EFK

ELK - Elasticsearch + Logstash + Kibana. EFK обычно заменяет Logstash на Fluent Bit или Fluentd. В новых проектах часто встречается OpenSearch + OpenSearch Dashboards.

Сильные стороны Elastic/OpenSearch:

полнотекстовый поиск;
сложные фильтры и агрегации по JSON;
ingest pipelines и enrichment;
index lifecycle management;
удобство для security/audit/search-heavy сценариев.

Цена:

больше operational complexity;
нужно думать о shards, mappings, rollover, retention;
дорого хранить все подряд без политики;
можно сломать cluster высокой кардинальностью и огромными документами.

Для курса разумный путь: обязательный профиль Loki + Grafana, optional профиль ELK/EFK с README-сравнением.

Поиск в логах

Примеры запросов должны лежать рядом с runbook, иначе во время инцидента их будут вспоминать руками.

LogQL:

{service="ratedesk-api", env="production"} |= "req_01H"
{service="ratedesk-api"} | json | trace_id="6b6d9c9c7c8f4c8e9a4c7a0a5a8f2e01"
{service="ratedesk-api"} | json | event="convert.failed" | error_kind="dependency_timeout"

Elastic/OpenSearch:

service:"ratedesk-api" AND request_id:"req_01H"
service:"ratedesk-api" AND trace_id:"6b6d9c9c7c8f4c8e9a4c7a0a5a8f2e01"
event:"convert.failed" AND error.kind:"dependency_timeout"

Если таких запросов нет в README/runbook, pipeline логов формально есть, но incident workflow все еще слабый.

Retention

Retention не должен быть один для всех логов:

Тип логов	Примерный срок	Комментарий
Debug/dev	часы или дни	Дешево удалять.
Application prod	7-30 дней	Основной debug инцидентов.
Audit/security	90+ дней	Отдельные правила доступа и хранения.
High-volume access	3-14 дней	Часто агрегируется в метрики.

В Elastic/OpenSearch используйте data streams или time-based indexes, rollover и delete phase. В Loki контролируйте cardinality labels и объем ingestion.

Антипаттерны

fmt.Printf в production-коде вместо logger.
Логи без request_id.
Разные имена одного поля в разных слоях.
ERROR для нормальных 404/validation.
Логирование request/response body целиком.
Секреты в логах.
request_id как Loki label.
Многострочные stack traces, которые collector не умеет склеивать.
Логи в файл внутри контейнера.
Debug включен в prod навсегда.

Практика

В RateDesk добавьте:

internal/observability/logger.go с slog.JSONHandler.
RequestIDMiddleware.
LoggingMiddleware с access log.
Единые поля request_id, trace_id, span_id, http.method, http.route, http.status_code, http.duration_ms, error.kind.
Redaction для секретных ключей.
README-раздел с log schema.
Loki/Alloy pipeline, где logs ищутся по request_id, а из log entry можно перейти в trace по trace_id.
Тесты на redaction, request_id и обязательные access-log поля.

Acceptance:

X-Request-Id возвращается клиенту;
id есть в logs;
Authorization и Cookie не попадают в logs;
request_id и trace_id не являются Loki labels;
not_found не логируется как production incident;
Echo middleware использует route pattern, а не raw path;
в MR есть примеры LogQL/Elastic-запросов для поиска одного запроса.

Интерактивная практика

Quiz+10 XP

Какое поле опаснее всего класть в Loki label?

service
env
request_id
level

Predict+15 XP

Что выведет этот код?

package main

import "fmt"

func LogLevel(status int) string {
    if status >= 500 {
        return "error"
    }
    return "info"
}

func main() {
    fmt.Println(LogLevel(404))
    fmt.Println(LogLevel(503))
}

Задача+20 XP

Реализуй LogPolicy: request_id хранится как обычное поле, password нужно редактировать, user_id_label нельзя делать label.

Gosloglogsrequest idcontextPIIcorrelationLokiELK