Структурированное логирование с slog
Структурированное логирование с slog
С Go 1.21 в stdlib появился log/slog - структурированное логирование из коробки. Раньше команды выбирали между logrus, zap, zerolog; теперь у всех есть единый стандартный API.
Почему не 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 связывает их вместе.
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-обёртку.
- Python - logging: уровни, handlers, formatters, root pitfalls - тот же подход в Python: RotatingFileHandler, JSON-вывод, root logger anti-patterns
Мини-практика
Добавь middleware для логирования HTTP-запросов: метод, путь, статус, длительность, correlation ID. Используй slog.LogAttrs и пробрось correlation ID в context. Прогони сервер через curl -H "X-Correlation-ID: test-123" и убедись, что ID появляется в логах handler-а.