Начало работы с Tracing

Крейт tracing - это фреймворк для инструментирования программ на Rust с целью сбора структурированной, событийно-ориентированной диагностической информации.

В асинхронных системах, таких как Tokio, интерпретация традиционных лог-сообщений часто может быть довольно сложной. Поскольку отдельные задачи мультиплексируются в одном потоке, связанные события и строки логов перемешиваются, что затрудняет отслеживание потока логики. tracing расширяет диагностику в стиле логирования, позволяя библиотекам и приложениям записывать структурированные события с дополнительной информацией о временности и причинности — в отличие от лог-сообщения, Span в tracing имеет время начала и окончания, может входить и выходить из потока выполнения и может существовать внутри вложенного дерева подобных спэнов. Для представления вещей, которые происходят в единственный момент времени, tracing предоставляет дополнительную концепцию событий. И Span, и Event являются структурированными, с возможностью записывать типизированные данные, а также текстовые сообщения.

Вы можете использовать tracing для:

Настройка

Для начала добавьте tracing и tracing-subscriber как зависимости:

[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"

Крейт tracing предоставляет API, который мы будем использовать для отправки трассировок. Крейт tracing-subscriber предоставляет некоторые базовые утилиты для перенаправления этих трассировок внешним слушателям (например, stdout).

Подписка на трассировки

Если вы создаете исполняемый файл (в отличие от библиотеки), вам нужно зарегистрировать tracing подписчика. Подписчики - это типы, которые обрабатывают трассировки, отправляемые вашим приложением и его зависимостями, и могут выполнять такие задачи, как вычисление метрик, мониторинг ошибок и повторная отправка трассировок во внешний мир (например, в journald, stdout или демон open-telemetry).

В большинстве случаев вы должны зарегистрировать свой tracing подписчик как можно раньше в вашей функции main. Например, тип FmtSubscriber, предоставляемый tracing-subscriber, который печатает форматированные трассировки и события в stdout, может быть зарегистрирован так:

mod mini_redis {
      pub type Error = Box<dyn std::error::Error + Send + Sync>;
      pub type Result<T> = std::result::Result<T, Error>;
}
#[tokio::main]
pub async fn main() -> mini_redis::Result<()> {
    // создаем подписчика, который печатает форматированные трассировки в stdout
    let subscriber = tracing_subscriber::FmtSubscriber::new();
    // используем этого подписчика для обработки трассировок, отправленных после этого момента
    tracing::subscriber::set_global_default(subscriber)?;
/*
    ...
*/ Ok(())
}

Если вы запустите ваше приложение сейчас, вы можете увидеть некоторые события трассировки, отправленные Tokio, но вам нужно будет изменить ваше собственное приложение для отправки трассировок, чтобы получить максимальную отдачу от tracing.

Конфигурация подписчика

В приведенном выше примере мы настроили FmtSubscriber с его конфигурацией по умолчанию. Однако tracing-subscriber также предоставляет ряд способов настройки поведения FmtSubscriber, таких как настройка формата вывода, включение дополнительной информации (такой как идентификаторы потоков или местоположения исходного кода) в логи и запись логов куда-то кроме stdout.

Например:

#![allow(unused)]
fn main() {
// Начинаем настраивать подписчика `fmt`
let subscriber = tracing_subscriber::fmt()
    // Используем более компактный, сокращенный формат лога
    .compact()
    // Отображаем пути к файлам исходного кода
    .with_file(true)
    // Отображаем номера строк исходного кода
    .with_line_number(true)
    // Отображаем идентификатор потока, на котором было записано событие
    .with_thread_ids(true)
    // Не отображаем цель события (путь модуля)
    .with_target(false)
    // Собираем подписчика
    .finish();
}

Для деталей о доступных опциях конфигурации см. документацию tracing_subscriber::fmt.

В дополнение к типу FmtSubscriber из tracing-subscriber, другие Subscriber могут реализовывать свои собственные способы записи данных tracing. Это включает альтернативные форматы вывода, анализ и агрегацию, а также интеграцию с другими системами, такими как распределенная трассировка или сервисы агрегации логов. Ряд крейтов предоставляет дополнительные реализации Subscriber, которые могут быть интересны. См. здесь для (неполного) списка дополнительных реализаций Subscriber.

Наконец, в некоторых случаях может быть полезно объединить несколько различных способов записи трассировок вместе, чтобы построить единственный Subscriber, который реализует несколько поведений. Для этой цели крейт tracing-subscriber предоставляет трейт Layer, который представляет компонент, который может быть скомпонован вместе с другими Layer для формирования Subscriber. См. здесь для деталей об использовании Layer.

Отправка спэнов и событий

Самый простой способ отправлять спэны - с помощью прока-макрос аннотации instrument, предоставляемой tracing, которая переписывает тела функций для отправки спэнов каждый раз, когда они вызываются; например:

#![allow(unused)]
fn main() {
#[tracing::instrument]
fn trace_me(a: u32, b: u32) -> u32 {
    a + b
}
}

Каждый вызов trace_me будет отправлять tracing Span, который:

  1. имеет уровень важности info ("золотая середина" важности),
  2. назван trace_me,
  3. имеет поля a и b, чьи значения являются аргументами trace_me

Атрибут instrument высоко настраиваем; например, для трассировки метода в mini-redis-server, который обрабатывает каждое соединение:

#![allow(unused)]
fn main() {
struct Handler {
    connection: tokio::net::TcpStream,
}
pub type Error = Box<dyn std::error::Error + Send + Sync>;
pub type Result<T> = std::result::Result<T, Error>;
use tracing::instrument;

impl Handler {
    /// Обработать одно соединение.
    #[instrument(
        name = "Handler::run",
        skip(self),
        fields(
            // `%` сериализует IP-адрес пира с помощью `Display`
            peer_addr = %self.connection.peer_addr().unwrap()
        ),
    )]
    async fn run(&mut self) -> mini_redis::Result<()> {
/*
        ...
*/ Ok::<_, _>(())
    }
}
}

mini-redis-server теперь будет отправлять tracing Span для каждого входящего соединения, который:

  1. имеет уровень важности info ("золотая середина" важности),
  2. назван Handler::run,
  3. имеет некоторые структурированные данные, связанные с ним.
    • fields(...) указывает, что отправляемый спэн должен включать представление fmt::Display SocketAddr соединения в поле под названием peer_addr.
    • skip(self) указывает, что отправляемый спэн не должен записывать отладочное представление Handler.

Вы также можете построить Span вручную, вызвав макрос span! или любой из его уровневых сокращений (error_span!, warn_span!, info_span!, debug_span!, trace_span!).

Чтобы отправлять события, вызовите макрос event! или любой из его уровневых сокращений (error!, warn!, info!, debug!, trace!). Например, чтобы залогировать, что клиент отправил некорректную команду:

#![allow(unused)]
fn main() {
type Error = Box<dyn std::error::Error + Send + Sync>;
type Result<T> = std::result::Result<T, Error>;
struct Command;
impl Command {
    fn from_frame<T>(frame: T) -> Result<()> {
        Result::Ok(())
    }
    fn from_error<T>(err: T) {}
}
let frame = ();
// Преобразуем redis frame в структуру команды. Это возвращает
// ошибку, если frame не является валидной redis командой.
let cmd = match Command::from_frame(frame) {
    Ok(cmd) => cmd,
    Err(cause) => {
        // Frame был некорректным и не мог быть разобран. Это
        // вероятно указывает на проблему с клиентом (в отличие
        // от нашего сервера), поэтому мы (1) отправляем предупреждение...
        //
        // Синтаксис здесь - это сокращение, предоставляемое крейтом
        // `tracing`. Это можно рассматривать как аналогичное:
        //      tracing::warn! {
        //          cause = format!("{}", cause),
        //          "failed to parse command from frame"
        //      };
        // `tracing` предоставляет структурированное логирование, поэтому информация
        // "логируется" как пары ключ-значение.
        tracing::warn! {
            %cause,
            "failed to parse command from frame"
        };
        // ...и (2) отвечаем клиенту с ошибкой:
        Command::from_error(cause)
    }
};
}

Если вы запустите ваше приложение, вы теперь будете видеть события, украшенные контекстом их спэна, отправленные для каждого входящего соединения, которое оно обрабатывает.