Why Your Logs Are Useless and How to Fix It in Half an Hour

WILD

Administrator
Staff member
ADMIN
SELLER
SUPREME
MEMBER
Joined
Jan 21, 2025
Messages
220
Reaction score
631
Deposit
0$
3:00 утра, оповещение, служба возвращает ошибку 500. Откройте журналы и посмотрите:

2026-05-12 03:14:22 ОШИБКА Что-то пошло не так
2026-05-12 03:14:22 ОШИБКА Не удалось обработать запрос
2026-05-12 03:14:23 ОШИБКА Произошла непредвиденная ошибка
2026-05-12 03:14:23 ИНФО Запрос выполнен

Какой запрос не удался? Какой пользователь? Какая конечная точка? Какая ошибка? В журнале этого нет.

Вы начинаете переключаться между строками по временной метке, пытаясь вручную сопоставить их, но если сервис обрабатывает 100 запросов в секунду, то логи от разных запросов перемешиваются, и разделить их становится невозможно.

Проблема не в количестве логов или уровне детализации. Проблема в формате. Текстовые логи создаются для человека, сидящего перед терминалом и читающего их глазами. Но в 3 часа ночи при 100 запросах в секунду вы ничего не сможете найти глазами. Вам нужны логи, созданные для машины: с возможностью фильтрации, группировки и полями, которые можно использовать для построения запросов.

Это структурированное логирование. Текст против JSON.

Обычный лог:

2026-05-12 03:14:22 ОШИБКА Не удалось обработать платеж для пользователя 12345: истекло время ожидания соединения
Объясните с помощью

Вся информация закодирована в строке: идентификатор пользователя, тип ошибки, операция. Для фильтрации по user_id потребуется регулярное выражение. Для поиска всех случаев превышения времени ожидания потребуется еще одно регулярное выражение. Для подсчета количества ошибок по типу потребуется третье. Каждое регулярное выражение перестанет работать при незначительном изменении формата сообщения.

Структурированный журнал — это тот же набор данных, но каждое поле в нем разделено:

{
"временная метка": "2026-05-12T03:14:22.456Z",
"уровень": "ошибка",
"сообщение": "Не удалось обработать платеж",
"user_id": 12345,
"payment_id": "pay_abc123",
"ошибка": "таймаут подключения",
"сервис": "платежный API",
"request_id": "req_xyz789",
"duration_ms": 5023
}
Объясните с помощью

Теперь jq 'select(.user_id == 12345)' возвращает все события для этого пользователя. В Kibana или Loki запрос service="payment-api" AND level="error" AND duration_ms > 3000 покажет все медленные ошибки за последний час. Никаких регулярных выражений, никакого угадывания формата.
Python: structlog

Python использует structlog для структурированного логирования. Он работает поверх стандартной системы логирования или в автономном режиме и может быть настроен за 10 минут.

pip install structlog
Объясните с помощью

импорт structlog

structlog.configure(
процессоры=[
structlog.contextvars.merge_contextvars,
structlog.processors.add_log_level,
structlog.processors.TimeStamper(fmt="iso"),
structlog.processors.format_exc_info,
structlog.processors.JSONRenderer(),
],
logger_factory=structlog.PrintLoggerFactory(),
)

log = structlog.get_logger()
Объясните с помощью

Здесь стоит пояснить, что такое «процессоры». В structlog каждое событие журнала проходит через цепочку процессоров: один добавляет метку времени, другой — уровень, третий — контекстные переменные, а последний сериализует его в JSON. Вы можете добавить свои собственные процессоры: например, процессор, который маскирует адреса электронной почты или удаляет поля, содержащие персональные данные.

Применение:

log.info("payment_started", user_id=123, amount=99.99, currency="USD")
log.error("payment_failed", user_id=123, error="timeout", retry_count=2)
Объясните с помощью

Выход:

{"event": "payment_started", "user_id": 123, "amount": 99.99, "currency": "USD", "level": "info", "timestamp": "2026-05-12T03:14:22Z"}
{"event": "payment_failed", "user_id": 123, "error": "timeout", "retry_count": 2, "level": "error", "timestamp": "2026-05-12T03:14:27Z"}
Объясните с помощью

Обратите внимание: вы не формируете строку вручную (f"Payment failed for user {user_id}: {error}"). Вы передаете поля в качестве именованных аргументов. Structlog определяет, как их форматировать. В продакшене это JSON. В разработке вы можете переключиться на красивый текстовый вывод с цветами (заменив JSONRenderer на ConsoleRenderer). Код логирования остается неизменным.
Идентификатор запроса: Связывание журналов одного запроса

Наиболее ценной особенностью структурированного логирования является возможность связать все записи одного запроса с одним идентификатором. Без этого при 100 запросах в секунду строки из разных запросов перемешиваются, что делает невозможным определение того, какая запись относится к какому запросу.

В FastAPI это делается с помощью промежуточного ПО и контекстных функций:
import uuid
from starlette.middleware.base import BaseHTTPMiddleware

class RequestIDMiddleware(BaseHTTPMiddleware):
async def dispatch(self, request, call_next):
request_id = request.headers.get("X-Request-ID", str(uuid.uuid4()))

structlog.contextvars.clear_contextvars()
structlog.contextvars.bind_contextvars(
request_id=request_id,
method=request.method,
path=request.url.path,
)

response = await call_next(request)
response.headers["X-Request-ID"] = request_id
return response

app = FastAPI()
app.add_middleware(RequestIDMiddleware)
Explain with

bind_contextvars binds fields to the current execution context (asyncio task). After this, every call to log.info(...), log.error(...) anywhere in request processing automatically contains the request_id, method, and path. There's no need to pass them through all functions, and there's no need to pass the logger as an argument.

@app.get("/api/orders/{order_id}")
async def get_order(order_id: int):
log.info("fetching_order", order_id=order_id)
order = await db.fetch_order(order_id)
if not order:
log.warning("order_not_found", order_id=order_id)
raise HTTPException(404)
log.info("order_fetched", order_id=order_id, status=order.status)
return order
Explain with

All three log entries will contain the same request_id. In Kibana, you can filter by it and see the full request path: what was searched for, whether it was found, and how long it took.

If you're using Django instead of FastAPI, the principle is the same: middleware that binds request_id to thread-local or contextvars. For Flask, it's the before_request hook.
Go: slog from the standard library

Since version 1.21, structured logging has been included out of the box, with no dependencies. The log/slog package has become part of the standard library.

import (
"log/slog"
"os"
)

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

slog.Info("server started", "port", 8080, "env", "production")
slog.Error("payment failed",
"user_id", 123,
"error", "connection timeout",
"duration_ms", 5023,
)
}
Explain with

Before slog, the Go community had zerolog, zap, and logrus—each with its own API, its own levels, and its own formats. Slog doesn't completely replace them (zerolog, for example, has zero-allocation logging, which can be critical at 100K RPS), but for most services, Slog is sufficient and doesn't require a dependency.

Request ID in Go is bound via context:

func RequestIDMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
requestID := r.Header.Get("X-Request-ID")
if requestID == "" {
requestID = uuid.New().String()
}

logger := slog.Default().With("request_id", requestID,
"method", r.Method, "path", r.URL.Path)
ctx := context.WithValue(r.Context(), "logger", logger)

w.Header().Set("X-Request-ID", requestID)
next.ServeHTTP(w, r.WithContext(ctx))
})
}
Объясните с помощью

Метод With создает дочерний логгер с привязанными полями. Все записи, проходящие через этот логгер, будут содержать request_id, method и path.
Что следует регистрировать, а что нет.

На этот вопрос нет однозначного ответа, но здесь применим здравый смысл.

Регистрируйте начало и конец обработки запроса (с параметром duration_ms — это бесценно для диагностики задержек). Регистрируйте ошибки с указанием контекста: не просто «ошибка», а операция, входные данные и ответ от конечного пользователя. Регистрируйте вызовы внешних сервисов: какой сервис, сколько времени они ожидали и статус ответа. Регистрируйте бизнес-события: заказ создан, платеж обработан, пользователь заблокирован — это будет полезно для расследования инцидентов и аналитики.

Не регистрируйте пароли, токены, номера карт или персональные данные. Это нарушение GDPR/Федерального закона № 152, за которое предусмотрены штрафы. Не регистрируйте целиком тела запросов и ответов: объем данных огромен, внутри содержатся конфиденциальные данные, и в 99% случаев вам нужны два или три поля, а не все тело запроса. Не регистрируйте данные на уровне отладки (DEBUG) в производственной среде: поток данных забьет ваш диск и Kibana, и в них будет мало полезной информации.

# Плохой
log.info("login", username=username, password=password)
log.info("request", body=request.body)

# Хороший
log.info("login_attempt", username=username)
log.info("order_received", order_id=data["id"], amount=data["amount"])
Объясните с помощью

Как избежать утопления при большой нагрузке

При 10 000 запросов в секунду и 5 строках логов на запрос вы генерируете 50 000 строк в секунду. За сутки это более 4 миллиардов строк. Даже в формате JSON это терабайты.

Решение заключается в выборочной обработке. Регистрируется 10% запросов INFO, но 100% ошибок. Объём трафика снижается на порядок, и диагностика работает: все ошибки видны, нормальный трафик регистрируется выборочно.

импорт случайных чисел
импорт structlog

class SamplegProcessor:
def __init__(self, sample_rate=0.1):
self.sample_rate = sample_rate

def __call__(self, logger, method_name, event_dict):
Добавьте SamplingProcessor(0.1) в цепочку обработки structlog. 10% INFO, 100% WARNING и выше. Для большинства задач этого достаточно: если ошибка воспроизводится в 10% запросов, вы её увидите. Если же она воспроизводится в 0,01%, вам нужна трассировка, а не логи.

Структурированное логирование позволяет найти конкретный запрос в 3 часа ночи за минуту, понять, что с ним произошло и кто виноват. JSON вместо текста, request_id для корреляции, slog или structlog вместо print и fmt.Println. Полчаса на настройку, и вы будете расследовать следующее оповещение гораздо быстрее.

Если у вас есть собственные подходы к логированию или вы обнаружили ошибку, пожалуйста, поделитесь ими в комментариях. Спасибо за внимание.
 
Top Bottom