Структурированное логирование с slog

Структурированное логирование с slog

С Go 1.21 в stdlib появился log/slog - структурированное логирование из коробки. Раньше команды выбирали между logrus, zap, zerolog; теперь у всех есть единый стандартный API.

Три столпа observability: logs, metrics, traces связаны через trace_id

Почему не fmt.Println

// ПЛОХО: парсить grep-ом, не агрегировать
fmt.Printf("User %s logged in from %s\n", userID, ip)

// ХОРОШО: ключ-значение → JSON → индексируется
slog.Info("user logged in", "user_id", userID, "ip", ip)
// {"time":"...","level":"INFO","msg":"user logged in","user_id":"123","ip":"192.168.1.1"}
<?php
declare(strict_types=1);

use Psr\Log\LoggerInterface;

final class LoginService
{
    public function __construct(private readonly LoggerInterface $logger) {}

    public function handle(string $userId, string $ip): void
    {
        // ПЛОХО: строковая конкатенация, ничего не агрегировать
        $this->logger->info('User ' . $userId . ' logged in from ' . $ip);

        // ХОРОШО: контекст - массив; Monolog JsonFormatter сериализует в JSON
        $this->logger->info('user logged in', [
            'user_id' => $userId,
            'ip' => $ip,
        ]);
    }
}

В PHP стандарт - PSR-3 (Psr\Log\LoggerInterface), индустриальная реализация - Monolog. В Symfony логгер инжектится через DI (MonologBundle).

В продакшене логи попадают в систему агрегации (Loki, Elasticsearch, CloudWatch). Структурированный вывод позволяет искать по полям: user_id="123", фильтровать по level, строить графики ошибок по сервисам.

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

slog.Debug("detailed info")    // отключён в проде по умолчанию
slog.Info("normal operation")  // штатные события: запросы, фоновые задачи
slog.Warn("something unusual") // деградация, retry, fallback
slog.Error("failed", "err", err) // требует внимания, но не падение
<?php
declare(strict_types=1);

use Psr\Log\LoggerInterface;

final class OrderProcessor
{
    public function __construct(private readonly LoggerInterface $logger) {}

    public function process(int $orderId, ?\Throwable $err = null): void
    {
        $this->logger->debug('detailed info', ['order_id' => $orderId]);
        $this->logger->info('normal operation', ['order_id' => $orderId]);
        $this->logger->warning('something unusual', ['order_id' => $orderId]);

        if ($err !== null) {
            $this->logger->error('failed', [
                'order_id' => $orderId,
                'exception' => $err,
            ]);
        }
    }
}

PSR-3 определяет восемь уровней (RFC 5424): debug, info, notice, warning, error, critical, alert, emergency. На практике хватает debug/info/warning/error.

Правило: DEBUG для разработки, INFO для бизнес-событий, WARN для аномалий, ERROR для проблем. Если на каждый ERROR никто не среагирует - это WARN.

Настройка JSON-handler

opts := &slog.HandlerOptions{
    Level:     slog.LevelInfo,
    AddSource: true, // добавляет file:line - полезно при поиске
}
handler := slog.NewJSONHandler(os.Stdout, opts)
slog.SetDefault(slog.New(handler))
<?php
declare(strict_types=1);

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Formatter\JsonFormatter;
use Monolog\Processor\IntrospectionProcessor;

$handler = new StreamHandler('php://stdout', Logger::INFO);
$handler->setFormatter(new JsonFormatter());

$logger = new Logger('app');
$logger->pushHandler($handler);
// IntrospectionProcessor добавляет file/line/class - аналог AddSource: true
$logger->pushProcessor(new IntrospectionProcessor(Logger::DEBUG));

В Monolog handler-ы пишут в разные приёмники (StreamHandler, SyslogHandler, RotatingFileHandler), а formatters задают формат. Для прода - JsonFormatter, для CLI разработки - LineFormatter.

В Symfony это настраивается декларативно в config/packages/monolog.yaml: каналы, handler-ы, форматтеры. Контроллеры и сервисы получают LoggerInterface через autowiring.

Контекстные поля через With

logger := slog.Default().With(
    "service", "user-api",
    "version", "1.2.3",
)
logger.Info("request",
    "method", "GET",
    "path", "/users",
    "status", 200,
    "duration_ms", 42,
)
<?php
declare(strict_types=1);

use Monolog\Logger;
use Monolog\LogRecord;

$logger = (new Logger('user-api'))->withName('user-api');
$logger->pushProcessor(static function (LogRecord $record): LogRecord {
    $record->extra['service'] = 'user-api';
    $record->extra['version'] = '1.2.3';
    return $record;
});

$logger->info('request', [
    'method' => 'GET',
    'path' => '/users',
    'status' => 200,
    'duration_ms' => 42,
]);

В Monolog аналог - Logger::withName() плюс processor, который добавляет статические поля ко всем записям. Каждая запись получает их без дублирования в info().

Processor создаёт новый logger со «прилипшими» полями - это дешевле, чем дублировать их в каждом вызове. В Go удобно прокидывать через context.WithValue, чтобы handler-ы и сервисы логировали с одинаковыми атрибутами; в PHP роль ctx играет request-scope DI-контейнер.

Correlation ID (request ID)

Один HTTP-запрос порождает десятки логов: middleware, handler, сервис, репозиторий. Correlation ID связывает их вместе.

Correlation ID проходит через middleware, handler, service, repository и попадает в каждый лог

type ctxKey string
const correlationKey ctxKey = "correlation_id"

func correlationMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        id := r.Header.Get("X-Correlation-ID")
        if id == "" {
            id = uuid.New().String()
        }
        ctx := context.WithValue(r.Context(), correlationKey, id)
        w.Header().Set("X-Correlation-ID", id)
        next.ServeHTTP(w, r.WithContext(ctx))
    })
}

// В handler-ах
func loggerFromCtx(ctx context.Context) *slog.Logger {
    if id, ok := ctx.Value(correlationKey).(string); ok {
        return slog.Default().With("correlation_id", id)
    }
    return slog.Default()
}
<?php
declare(strict_types=1);

use Symfony\Component\EventDispatcher\EventSubscriberInterface;
use Symfony\Component\HttpKernel\Event\RequestEvent;
use Symfony\Component\HttpKernel\KernelEvents;
use Symfony\Component\Uid\Uuid;
use Monolog\LogRecord;

final class CorrelationIdSubscriber implements EventSubscriberInterface
{
    public function __construct(private CorrelationIdHolder $holder) {}

    public static function getSubscribedEvents(): array
    {
        return [KernelEvents::REQUEST => ['onRequest', 250]];
    }

    public function onRequest(RequestEvent $event): void
    {
        $request = $event->getRequest();
        $id = $request->headers->get('X-Correlation-ID') ?? Uuid::v4()->toRfc4122();
        $this->holder->set($id);
        $request->attributes->set('correlation_id', $id);
    }
}

// Monolog processor читает значение из holder-а
final class CorrelationIdProcessor
{
    public function __construct(private readonly CorrelationIdHolder $holder) {}

    public function __invoke(LogRecord $record): LogRecord
    {
        $record->extra['correlation_id'] = $this->holder->get();
        return $record;
    }
}

В Symfony correlation_id ставит EventSubscriber на kernel.request, а Monolog processor добавляет его ко всем записям. PHP не имеет ctx-объекта, как Go: значение хранится в request-scope сервисе (DI scope 'request') или в request attributes.

Если запрос проходит через несколько микросервисов, header X-Correlation-ID пробрасывается дальше - так трейс ID связывает все сервисы.

Агрегация: Loki vs ELK

Куда складывать логи в проде:

  • Grafana Loki - индексирует только labels, тело лога хранится сжатым. Дёшево по памяти и диску. Хорошо для большого объёма низкочастотных запросов.
  • Elasticsearch (ELK) - полнотекстовый индекс по всем полям. Дороже, но мощный поиск и аналитика. Подходит для security-аудита, форензики.
  • CloudWatch / Stackdriver - managed-сервисы облаков. Удобно, но дороже на больших объёмах.
# docker-compose: связка Loki + Promtail + Grafana
services:
  loki:
    image: grafana/loki:latest
    ports: ["3100:3100"]
  promtail:
    image: grafana/promtail:latest
    volumes:
 - /var/log:/var/log
 - ./promtail.yml:/etc/promtail/config.yml

Что логировать и что НЕ логировать

✅ Логируй:

  • Входящие запросы: метод, путь, статус, длительность, user_id
  • Ошибки: с контекстом (что пытались сделать, какой ID объекта)
  • Бизнес-события: оплата, регистрация, изменение прав
  • Долгие операции: миграция, импорт, фоновая задача

❌ НЕ логируй:

  • Пароли, токены, JWT, API-ключи
  • Номера карт, CVV, PII (паспорт, ИНН)
  • Целые тела запросов и ответов на больших объёмах
  • Каждый шаг алгоритма в горячем цикле - раздуёт стоимость хранения

Связь логов с трейсами: trace_id в каждой записи

Когда инцидент случился в проде, у вас есть три сигнала: логи, метрики, трейсы. Полезны они вместе. Если в логе видна ошибка, но непонятно, что происходило вокруг - нужно перейти в Jaeger. Это делается через trace_id и span_id, прокинутые в каждую запись лога.

import (
    "go.opentelemetry.io/contrib/bridges/otelslog"
)

// Готовый bridge: каждый лог автоматически получит trace_id/span_id
// из активного OpenTelemetry span в ctx
logger := otelslog.NewLogger("user-api")
logger.InfoContext(ctx, "user logged in", "user_id", userID)
// {"level":"INFO","msg":"user logged in","user_id":"123",
//  "trace_id":"4bf92f3577b34da6a3ce929d0e0e4736",
//  "span_id":"00f067aa0ba902b7"}
<?php
declare(strict_types=1);

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Formatter\JsonFormatter;
use OpenTelemetry\Contrib\Logs\Monolog\Handler as OtelMonologHandler;
use OpenTelemetry\API\Trace\TracerProviderInterface;
use OpenTelemetry\API\Trace\Span;

$logger = new Logger('user-api');
$handler = new StreamHandler('php://stdout');
$handler->setFormatter(new JsonFormatter());
$logger->pushHandler($handler);

// Processor: добавляет trace_id и span_id из активного span
$logger->pushProcessor(static function (\Monolog\LogRecord $record): \Monolog\LogRecord {
    $spanContext = Span::getCurrent()->getContext();
    if ($spanContext->isValid()) {
        $record->extra['trace_id'] = $spanContext->getTraceId();
        $record->extra['span_id'] = $spanContext->getSpanId();
    }
    return $record;
});

$logger->info('user logged in', ['user_id' => $userId]);

В PHP аналог - пакет open-telemetry/opentelemetry-logger-monolog: processor вытаскивает активный span из глобального контекста OTel SDK и пишет trace_id/span_id в каждую запись Monolog.

В Symfony это покрыто бандлами open-telemetry/opentelemetry-auto-symfony плюс open-telemetry/opentelemetry-logger-monolog - подключаются один раз, дальше работают прозрачно для всего приложения.

Если не хочется тянуть OTel-зависимость, можно достать span context руками - паттерн полезно понимать:

func tracingHandler(inner slog.Handler) slog.Handler {
    return &traceContextHandler{inner: inner}
}

type traceContextHandler struct{ inner slog.Handler }

func (h *traceContextHandler) Handle(ctx context.Context, r slog.Record) error {
    if span := trace.SpanFromContext(ctx); span.SpanContext().IsValid() {
        sc := span.SpanContext()
        r.AddAttrs(
            slog.String("trace_id", sc.TraceID().String()),
            slog.String("span_id", sc.SpanID().String()),
        )
    }
    return h.inner.Handle(ctx, r)
}
<?php
declare(strict_types=1);

use Monolog\LogRecord;
use OpenTelemetry\API\Trace\Span;

final readonly class TraceContextProcessor
{
    public function __invoke(LogRecord $record): LogRecord
    {
        $context = Span::getCurrent()->getContext();
        if ($context->isValid()) {
            $record->extra['trace_id'] = $context->getTraceId();
            $record->extra['span_id'] = $context->getSpanId();
        }
        return $record;
    }
}

В PHP роль кастомного handler играет Monolog processor. Контекст ctx отсутствует - активный span хранится в Context::getCurrent() SDK-а OpenTelemetry.

В Grafana и аналогичных UI это даёт «click on log line → open trace» - мгновенный переход между сигналами при расследовании. Без trace_id в логах вы будете руками искать соответствующий trace по таймстампу - это медленно и часто неточно.

Динамический уровень логирования

В проде нельзя постоянно держать DEBUG (объём вырастет в десятки раз и убьёт стоимость). Но и без DEBUG расследовать сложные инциденты тяжело. Решение - менять уровень на лету, без рестарта сервиса.

var levelVar = new(slog.LevelVar) // ноль = LevelInfo

func main() {
    levelVar.Set(slog.LevelInfo)
    handler := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        Level: levelVar,
    })
    slog.SetDefault(slog.New(handler))

    http.HandleFunc("/admin/log-level", func(w http.ResponseWriter, r *http.Request) {
        switch r.URL.Query().Get("level") {
        case "debug":
            levelVar.Set(slog.LevelDebug)
        case "info":
            levelVar.Set(slog.LevelInfo)
        case "warn":
            levelVar.Set(slog.LevelWarn)
        case "error":
            levelVar.Set(slog.LevelError)
        }
        slog.InfoContext(r.Context(), "log level changed", "level", levelVar.Level().String())
    })
}
<?php
declare(strict_types=1);

use Monolog\Handler\StreamHandler;
use Monolog\Handler\FilterHandler;
use Monolog\Logger;
use Symfony\Component\Cache\Adapter\RedisAdapter;

final readonly class DynamicLevelHandler
{
    public function __construct(private \Redis $redis) {}

    public function currentLevel(): \Monolog\Level
    {
        $value = $this->redis->get('app:log_level') ?: 'info';
        return match ($value) {
            'debug' => \Monolog\Level::Debug,
            'warning' => \Monolog\Level::Warning,
            'error' => \Monolog\Level::Error,
            default => \Monolog\Level::Info,
        };
    }
}

// В контроллере /admin/log-level (за внутренней аутентификацией!)
final class LogLevelController
{
    public function __construct(private readonly \Redis $redis) {}

    public function set(string $level): void
    {
        $allowed = ['debug', 'info', 'warning', 'error'];
        if (in_array($level, $allowed, true)) {
            $this->redis->set('app:log_level', $level);
        }
    }
}

В PHP-FPM долго живёт мастер-процесс, воркеры рождаются и умирают часто. Один процесс не может атомарно «переключить уровень» сразу всем. Решение - хранить текущий уровень в Redis/APCu, а Monolog FilterHandler читает его при каждом запросе.

slog.LevelVar в Go атомарно перечитывается на каждый вызов лога - это безопасно при конкурентной нагрузке. Use case: SRE заметил аномалию, включает DEBUG на 10 минут на одном инстансе, собирает детали, возвращает INFO. Endpoint должен быть закрыт от внешнего мира (только во внутренней сети, под аутентификацией) - иначе атакующий уронит вас через flood DEBUG-логов.

Redaction чувствительных полей через ReplaceAttr

Раньше уже было сказано: не пишите пароли и токены в логи. На практике их туда заносят случайно - структура, в которой лежит password, передаётся в slog.Any("user", user). Защита - фильтр на уровне Handler-а: список запрещённых ключей.

var redactedKeys = map[string]bool{
    "password":     true,
    "token":        true,
    "card_number":  true,
    "ssn":          true,
    "authorization": true,
}

func redactHandler(w io.Writer) slog.Handler {
    return slog.NewJSONHandler(w, &slog.HandlerOptions{
        ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
            if redactedKeys[strings.ToLower(a.Key)] {
                return slog.String(a.Key, "[REDACTED]")
            }
            return a
        },
    })
}

// Использование
slog.Info("login attempt",
    "email", "user@example.com",
    "password", "secret123", // → "[REDACTED]"
)
<?php
declare(strict_types=1);

use Monolog\LogRecord;

final readonly class RedactingProcessor
{
    private const REDACTED_KEYS = [
        'password',
        'token',
        'card_number',
        'ssn',
        'authorization',
    ];

    public function __invoke(LogRecord $record): LogRecord
    {
        foreach ($record->context as $key => $_) {
            if (in_array(strtolower((string) $key), self::REDACTED_KEYS, true)) {
                $record->context[$key] = '[REDACTED]';
            }
        }
        return $record;
    }
}

$logger->pushProcessor(new RedactingProcessor());
$logger->info('login attempt', [
    'email' => 'user@example.com',
    'password' => 'secret123', // → '[REDACTED]'
]);

В PHP redaction делается processor-ом, который пробегает по $record->context и заменяет значения по ключам.

Processor вызывается для каждой записи перед сериализацией. Можно маскировать по pattern (regex на «похоже на номер карты»), но это дороже и даёт false positives. Защита от случайного попадания PII лучше работает на этапе review: чёткие правила, какие поля можно логировать.

Logger через context, а не глобальный slog.Default

Глобальный slog.Default() неудобен: нельзя подменить в тесте, нельзя обогатить request-scope атрибутами (correlation_id, user_id). Прокидывание logger через context решает обе проблемы.

type ctxKey struct{}

var loggerKey = ctxKey{}

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

func LoggerFromCtx(ctx context.Context) *slog.Logger {
    if l, ok := ctx.Value(loggerKey).(*slog.Logger); ok {
        return l
    }
    return slog.Default()
}

// middleware: обогатить logger correlation_id, прокинуть в ctx
func loggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        corrID := r.Header.Get("X-Correlation-ID")
        if corrID == "" {
            corrID = uuid.New().String()
        }
        l := slog.Default().With(
            "correlation_id", corrID,
            "method", r.Method,
            "path", r.URL.Path,
        )
        ctx := WithLogger(r.Context(), l)
        next.ServeHTTP(w, r.WithContext(ctx))
    })
}

// в handler
func usersHandler(w http.ResponseWriter, r *http.Request) {
    l := LoggerFromCtx(r.Context())
    l.Info("fetching users", "limit", 100)
    // Логи автоматически содержат correlation_id, method, path
}
<?php
declare(strict_types=1);

use Symfony\Component\EventDispatcher\EventSubscriberInterface;
use Symfony\Component\HttpKernel\Event\RequestEvent;
use Symfony\Component\HttpKernel\KernelEvents;
use Symfony\Component\Uid\Uuid;
use Monolog\LogRecord;

final class RequestContextSubscriber implements EventSubscriberInterface
{
    public function __construct(private RequestContextHolder $holder) {}

    public static function getSubscribedEvents(): array
    {
        return [KernelEvents::REQUEST => ['onRequest', 256]];
    }

    public function onRequest(RequestEvent $event): void
    {
        $request = $event->getRequest();
        $this->holder->set(
            $request->headers->get('X-Correlation-ID') ?? Uuid::v4()->toRfc4122(),
            $request->getMethod(),
            $request->getPathInfo(),
        );
    }
}

// Processor, добавляющий контекст к каждой записи
final readonly class RequestContextProcessor
{
    public function __construct(private RequestContextHolder $holder) {}

    public function __invoke(LogRecord $record): LogRecord
    {
        $record->extra['correlation_id'] = $this->holder->correlationId();
        $record->extra['method'] = $this->holder->method();
        $record->extra['path'] = $this->holder->path();
        return $record;
    }
}

// В контроллере: LoggerInterface уже содержит все атрибуты
final class UsersController
{
    public function __construct(private readonly LoggerInterface $logger) {}

    public function list(): void
    {
        $this->logger->info('fetching users', ['limit' => 100]);
    }
}

В PHP нет context.Context - его роль играет request-scope DI-контейнер. Сервис получает обогащённый logger через конструктор, а добавление contextual-полей делает EventSubscriber на kernel.request.

В DI-фреймворках (Wire, Fx, Symfony DI) base-logger создаётся один раз при старте, дальше каждый сервис получает свою копию с прилипшими атрибутами. В Symfony это делается через monolog.logger теги каналов: UserRepository получает @logger.user_repo, и каждая запись отмечена 'channel' => 'user_repo'.

Производительность

slog аллоцирует, если передавать slog.Any(key, val). Для горячих путей используй типизированные хелперы:

slog.LogAttrs(ctx, slog.LevelInfo, "request",
    slog.String("path", path),
    slog.Int("status", status),
    slog.Duration("dur", elapsed),
)
<?php
declare(strict_types=1);

// ХОРОШО: placeholders + плоский context
$this->logger->info('request {method} {path}', [
    'method' => $method,
    'path' => $path,
    'status' => $status,
    'duration_ms' => $durationMs,
]);

// ПЛОХО: тяжёлый объект - сериализатор пройдёт по всем полям
$this->logger->info('request', ['request' => $request]);

В PHP горячий путь обычно упирается не в логгер, а в сериализацию. Главная оптимизация - не передавать тяжёлые объекты в context. Используй PSR-3 placeholder-синтаксис для интерполяции - Monolog отложит её до момента, когда handler действительно сериализует запись.

В Monolog можно отфильтровать тяжёлые контексты на уровне Handler через FilterHandler или вынести их в отдельный канал (debug-канал, который пишет только в файл и не уходит в Loki).

Sampling логов на горячих путях

Если endpoint обрабатывает 10K RPS и каждый пишет 5 строк лога - это 50K строк/сек. Сэмплирование (например, логировать каждый 100-й запрос или все ошибочные плюс 1% успешных) сокращает объём при сохранении репрезентативности. Реализуется как кастомный slog.Handler, который пропускает часть записей.

type samplingHandler struct {
    inner slog.Handler
    rate  int
}

func (h *samplingHandler) Handle(ctx context.Context, r slog.Record) error {
    if r.Level >= slog.LevelError || rand.Intn(h.rate) == 0 {
        return h.inner.Handle(ctx, r)
    }
    return nil
}
<?php
declare(strict_types=1);

use Monolog\Handler\AbstractHandler;
use Monolog\Handler\HandlerInterface;
use Monolog\LogRecord;
use Monolog\Level;

final class SamplingHandler extends AbstractHandler
{
    public function __construct(
        private readonly HandlerInterface $inner,
        private readonly int $rate,
    ) {
        parent::__construct();
    }

    public function handle(LogRecord $record): bool
    {
        if ($record->level->value >= Level::Error->value || random_int(1, $this->rate) === 1) {
            return $this->inner->handle($record);
        }
        return false;
    }
}

В Monolog сэмплирование реализуется через SamplingHandler (часть пакета) или собственный handler-обёртку.

Мини-практика

Добавь middleware для логирования HTTP-запросов: метод, путь, статус, длительность, correlation ID. Используй slog.LogAttrs и пробрось correlation ID в context. Прогони сервер через curl -H "X-Correlation-ID: test-123" и убедись, что ID появляется в логах handler-а.

Зарегистрируйтесь бесплатно, чтобы пройти квиз, решить задание с автопроверкой и вести прогресс.