25. Логирование и observability

tracing — структурированные события и spans

tracing — фреймворк инструментации, вытеснивший простой log в асинхронном Rust-коде. Ключевое отличие от плоского логирования: события (event!) существуют внутри иерархических spans, которые естественно отражают вложенность async-задач — то, с чем плоский log в многопоточном/асинхронном контексте справляется плохо.

use tracing::{info, warn, debug, instrument};

#[instrument(skip(pool), fields(user.id = %id))]
async fn get_user(pool: &sqlx::PgPool, id: i64) -> Result<User, sqlx::Error> {
    debug!("fetching user from database");

    let user = sqlx::query_as!(User, "SELECT id, name FROM users WHERE id = $1", id)
        .fetch_optional(pool)
        .await?;

    match user {
        Some(u) => {
            info!(name = %u.name, "user found");
            Ok(u)
        }
        None => {
            warn!("user not found");
            Err(sqlx::Error::RowNotFound)
        }
    }
}

Атрибут #[instrument] автоматически оборачивает функцию в span с именем функции, полями из параметров (кроме указанных в skip) и корректно работает с async fn — span "приостанавливается" вместе с задачей при await и "возобновляется" при возобновлении полла, в отличие от thread-local контекста в синхронных логгерах.

tracing-subscriber — форматирование и вывод

tracing сам по себе только собирает события; за форматирование и вывод отвечает tracing-subscriber — композиция слоёв (Layer), каждый из которых обрабатывает поток событий независимо (например, JSON в файл + человекочитаемый вывод в stderr + экспорт в OpenTelemetry одновременно).

use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, fmt};

fn init_tracing() {
    let filter = EnvFilter::try_from_default_env()
        .unwrap_or_else(|_| EnvFilter::new("info,my_service=debug"));

    tracing_subscriber::registry()
        .with(filter)
        .with(fmt::layer().json().with_target(true).with_current_span(true))
        .init();
}

#[tokio::main]
async fn main() {
    init_tracing();
    tracing::info!(version = env!("CARGO_PKG_VERSION"), "service starting");
    // ...
}

Переменная окружения RUST_LOG (читается через EnvFilter::from_default_env) позволяет менять уровень логирования per-модуль без пересборки: RUST_LOG=warn,my_service::db=trace.

Structured logging — поля вместо текста

Главный принцип структурированного логирования — данные передаются как типизированные поля (key=value), а не форматируются в текстовую строку. Это позволяет системе сбора логов (Loki, Elasticsearch) индексировать и фильтровать по полям без парсинга регулярками.

// плохо: неструктурированная строка, сложно парсить и агрегировать
tracing::info!("user {} logged in from {}", user_id, ip);

// хорошо: типизированные поля, легко фильтровать по user_id или ip
tracing::info!(
    user_id = %user_id,
    ip = %ip,
    method = "password",
    "user logged in"
);

// %x — Display, ?x — Debug; выбор влияет на формат в выводе
#[derive(Debug)]
struct RequestMeta { path: String, status: u16 }

let meta = RequestMeta { path: "/api/users".into(), status: 200 };
tracing::info!(?meta, "request completed"); // meta=RequestMeta { path: "/api/users", status: 200 }

Correlation ID и распространение контекста

В распределённой системе один пользовательский запрос проходит через несколько сервисов — correlation ID (или trace ID) связывает все логи и spans этого запроса воедино. В axum он обычно устанавливается middleware на входе и прокидывается в исходящие запросы через заголовки.

use axum::{extract::Request, middleware::Next, response::Response};
use tracing::Instrument;
use uuid::Uuid;

async fn correlation_id_middleware(mut req: Request, next: Next) -> Response {
    let correlation_id = req.headers()
        .get("x-correlation-id")
        .and_then(|v| v.to_str().ok())
        .map(String::from)
        .unwrap_or_else(|| Uuid::new_v4().to_string());

    let span = tracing::info_span!("request", correlation_id = %correlation_id);

    let mut response = next.run(req).instrument(span).await;
    response.headers_mut().insert(
        "x-correlation-id",
        correlation_id.parse().unwrap(),
    );
    response
}

Все события внутри .instrument(span), включая логи из вложенных async-вызовов, автоматически наследуют поле correlation_id — не нужно вручную прокидывать его как параметр в каждую функцию.

OpenTelemetry — распределённый трейсинг

OpenTelemetry (OTel) — вендор-нейтральный стандарт для трейсов, метрик и логов. Крейт tracing-opentelemetry связывает существующие tracing::Span с OTel-моделью, экспортируя их в Jaeger, Tempo или любой OTLP-совместимый коллектор.

use opentelemetry::trace::TracerProvider;
use opentelemetry_otlp::WithExportConfig;
use tracing_subscriber::layer::SubscriberExt;

fn init_otel_tracing() -> Result<(), Box<dyn std::error::Error>> {
    let exporter = opentelemetry_otlp::SpanExporter::builder()
        .with_tonic()
        .with_endpoint("http://otel-collector:4317")
        .build()?;

    let provider = opentelemetry_sdk::trace::TracerProvider::builder()
        .with_batch_exporter(exporter, opentelemetry_sdk::runtime::Tokio)
        .build();

    let tracer = provider.tracer("my-service");
    let otel_layer = tracing_opentelemetry::layer().with_tracer(tracer);

    tracing_subscriber::registry()
        .with(tracing_subscriber::EnvFilter::new("info"))
        .with(tracing_subscriber::fmt::layer())
        .with(otel_layer)
        .init();

    Ok(())
}

После этого все #[instrument]-функции и spans автоматически становятся частью распределённого трейса: если контекст трейса передан через заголовок traceparent (W3C Trace Context), spans в разных сервисах объединяются в единое дерево вызовов.

Метрики — счётчики, гистограммы, gauges

Крейт metrics с фасадом (аналогично log/tracing) даёт единый API инструментации, а конкретная реализация экспорта подключается отдельно — например, metrics-exporter-prometheus для /metrics эндпоинта.

use metrics::{counter, histogram, gauge};
use metrics_exporter_prometheus::PrometheusBuilder;
use std::time::Instant;

fn init_metrics() {
    // поднимает HTTP-сервер на :9000/metrics в формате Prometheus
    PrometheusBuilder::new()
        .with_http_listener(([0, 0, 0, 0], 9000))
        .install()
        .expect("failed to install Prometheus exporter");
}

async fn handle_request(method: &str, path: &str) {
    let start = Instant::now();
    gauge!("http_requests_in_flight").increment(1.0);

    // ... обработка запроса ...

    gauge!("http_requests_in_flight").decrement(1.0);
    counter!("http_requests_total", "method" => method.to_string(), "path" => path.to_string()).increment(1);
    histogram!("http_request_duration_seconds", "path" => path.to_string())
        .record(start.elapsed().as_secs_f64());
}

• Counter — монотонно растущее значение (число запросов, ошибок)
• Gauge — значение, которое может расти и убывать (текущие соединения, размер очереди)
• Histogram — распределение значений по бакетам (латентность, размер тела запроса) — основа для percentile-графиков (p50/p95/p99)

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

В продакшене полезно менять уровень логирования без рестарта сервиса — например, временно включить debug-логи для конкретного модуля при расследовании инцидента. tracing_subscriber::reload даёт хендл для изменения фильтра на лету.

use tracing_subscriber::{reload, filter::EnvFilter, layer::SubscriberExt, util::SubscriberInitExt};

fn init_reloadable_tracing() -> reload::Handle<EnvFilter, tracing_subscriber::Registry> {
    let filter = EnvFilter::new("info");
    let (filter_layer, reload_handle) = reload::Layer::new(filter);

    tracing_subscriber::registry()
        .with(filter_layer)
        .with(tracing_subscriber::fmt::layer())
        .init();

    reload_handle
}

// эндпоинт для изменения уровня без рестарта
async fn set_log_level(handle: reload::Handle<EnvFilter, tracing_subscriber::Registry>, new_filter: String) -> Result<(), Box<dyn std::error::Error>> {
    let new_env_filter = EnvFilter::new(new_filter);
    handle.reload(new_env_filter)?;
    Ok(())
}

Производительность логирования на hot path

Логирование не должно быть узким местом. tracing спроектирован так, что отключённые уровни (например, debug! при фильтре info) почти не стоят производительности — проверка уровня происходит до вычисления аргументов события благодаря ленивой оценке макросов.

// аргументы вычисляются только если span/event действительно будет записан —
// дорогая функция expensive_debug_info() не вызовется при выключенном debug-уровне
tracing::debug!(info = ?expensive_debug_info(), "detailed diagnostic");

// для по-настоящему горячего пути используйте tracing::enabled! явно,
// чтобы избежать даже создания промежуточных значений
if tracing::enabled!(tracing::Level::TRACE) {
    let snapshot = build_expensive_snapshot();
    tracing::trace!(?snapshot, "state snapshot");
}