Tokio tracing

Внешние ссылки:

Наблюдаемость / Observability

Наблюдаемость позволяет понять систему извне, задавая вопросы о ней, при этом не зная ее внутреннего устройства. Кроме того, она позволяет легко устранять неполадки и решать новые проблемы, то есть «неизвестные неизвестные». Она также поможет вам ответить на вопрос «почему что-то происходит?».

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

Терминология

  • Событие журнала (Log event/message) - событие, произошедшее в конкретный момент времени;
  • Промежуток (Span record) - запись потока исполнения в системе за период времени. Он также выполняет функции контекста для событий журнала и родителя для под-промежутков;
  • Трасса (trace) - полная запись потока исполнения в системе от получения запроса до отправки ответа. Это по сути промежуток-родитель, или корневой промежуток;
  • Подписчик (subscriber) - реализует способ сбора данных трассы, например, запись их в стандартный вывод;
  • Контекст трассировки (Tracing Context): набор значений, которые будут передаваться между службами

Установка

cargo add tracing
cargo add tracing-subscriber -F json

Использование

Инициализация

Простая инициализация и отслеживание событий:

use tracing::info;

fn main() {
    // Установка глобального сборщика по конфигурации
    tracing_subscriber::fmt::init();

    let number_of_yaks = 3;

    // новое событие, вне промежутков
    info!(number_of_yaks, "preparing to shave yaks");
}

Ручная инициализация свойств подписчика для форматирования лога:

fn setup_tracing() {
    let subscriber = tracing_subscriber::fmt()
        .json() // нужно cargo add tracing-subscriber -F json
        .with_max_level(tracing::Level::TRACE) // МАХ уровень логирования
        .compact() // компактный лог
        .with_file(true) // показывать файл-исходник
        .with_line_number(true) // показать номера строк кода
        .with_thread_ids(true) // показать ID потока с событием
        .with_target(false) // не показывать цель (модуль) события
        .finish();

    tracing::subscriber::set_global_default(subscriber).unwrap();

    tracing::info!("Starting up");
    tracing::warn!("Are you sure this is a good idea?");
    tracing::error!("This is an error!");
}

Трассировка в синхронном режиме

use tracing::{instrument, warn};

#[instrument]
fn sync_tracing() {
    warn!("event 1");
    sync_tracing_sub();
}

#[instrument]
fn sync_tracing_sub() {
    warn!("event 2");
}

fn main() {
    setup_tracing();
    sync_tracing();
}

Макрос #[instrument] автоматически создаёт промежутки (spans) для функций, а подписчик (subscriber) настроен выводить промежутки в stdout.

Трассировка потоков в асинхронном режиме

use tracing_subscriber::fmt::format::FmtSpan;

#[tracing::instrument] // инструмент следит за временем работы
async fn hello() {
    tokio::time::sleep(tokio::time::Duration::from_secs(1)).await;
}

#[tokio::main] // cargo add tokio -F time,macros,rt-multi-thread
async fn main() -> anyhow::Result<()> {
    let subscriber = tracing_subscriber::fmt()
        .json()
        .compact()
        .with_file(true)
        .with_line_number(true)
        .with_thread_ids(true)
        .with_target(false)
        .with_span_events(FmtSpan::ENTER | FmtSpan::CLOSE) // вход и выход
        .finish();                                   // потока отслеживать

    tracing::subscriber::set_global_default(subscriber).unwrap();

    hello().await;
    Ok(())
}

В итоге получаем лог работы потока с временем задержки:

2024-12-24T14:30:17.378906Z  INFO ThreadId(01) hello: src/main.rs:3: {"message":"enter"} {}
2024-12-24T14:30:18.383596Z  INFO ThreadId(01) hello: src/main.rs:3: {"message":"enter"} {}
2024-12-24T14:30:18.383653Z  INFO ThreadId(01) hello: src/main.rs:3: {"message":"enter"} {}
2024-12-24T14:30:18.383675Z  INFO ThreadId(01) hello: src/main.rs:3: {"message":"close","time.busy":"179µs","time.idle":"1.00s"} {}

Запись журнала в хранилище

Внешние ссылки:

Для записи журнала применяется отдельный модуль tracing-appender:

cargo add tracing-appender

У него много функций не только записи в облачные службы типа Datadog, но и создание журнала с дозаписью (минутной, часовой, дневной), а также запись как неблокирующее действие во время многопоточного исполнения.

Пример инициализации неблокирующей записи журнала в файл (лучше всего как JSON), одновременно вывод на экран и организация часового журнала с дозаписью (rolling):

use tracing::{instrument, warn};

// тянем std::io::Write признак в режиме неблокирования
use tracing_subscriber::fmt::writer::MakeWriterExt; 

fn setup_tracing() {
    // инициализация файла с дозаписью
    let logfile = tracing_appender::rolling::hourly("/some/directory", "app-log");
    // уровень записи при логировании = INFO
    let stdout = std::io::stdout.with_max_level(tracing::Level::INFO);

    let subscriber = tracing_subscriber::fmt()
        .with_max_level(tracing::Level::TRACE)
        .json()
        .compact()
        .with_file(true)
        .with_line_number(true)
        .with_thread_ids(true)
        .with_target(false)
        .with_writer(stdout.and(logfile)) // обязательно указать запись тут
        .finish();                        // в файл и в stdout консоль
    tracing::subscriber::set_global_default(subscriber).unwrap();
}

#[instrument]
fn sync_tracing() {
    warn!("event 1");
    sync_tracing_sub();
}

#[instrument]
fn sync_tracing_sub() {
    warn!("event 2");
}

fn main() {
    setup_tracing();
    sync_tracing();
}