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();
}

Инициализация единого трассировщика на проекте

В составе Workspace трассировщик следует инициализировать единожды и далее использовать во всём проекте.

Для этого на верхнем уровне Workspace в Cargo.toml вписываем зависимость с применением по всему Workspace:

[workspace]
members = [ "authentication", "common-log","hello_world", "login"]

[dependencies]
tracing.workspace = true
tracing-appender.workspace = true
tracing-subscriber.workspace = true

[workspace.dependencies]
tracing = "0.1.41"
tracing-appender = "0.2.3"
tracing-subscriber = { version = "0.3.19", features = ["json"] }

Далее, создаём lib crate в Workspace (например, common-logging), у которого в Cargo.toml вписываем:

[dependencies]
tracing = { workspace = true }
tracing-appender = { workspace = true }
tracing-subscriber = { workspace = true }

В файле lib.rs инициализируем логгер:

use tracing_subscriber::fmt::writer::MakeWriterExt;

pub fn setup_tracing() {
    let logfile = tracing_appender::rolling::hourly("./log", "auth");
    let stdout = std::io::stdout.with_max_level(tracing::Level::INFO);
    let subscriber = tracing_subscriber::fmt()
        .json()
        .with_max_level(tracing::Level::TRACE)
        .compact()
        .with_file(true)
        .with_line_number(true)
        .with_thread_ids(true)
        .with_target(false)
        .with_writer(stdout.and(logfile))
        .finish();
    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");

    // Проверка разных сообщений логгера:
    //tracing::info!("INFO TEXT");
    //tracing::warn!("WARNING TEXT");
    //tracing::error!("ERROR TEXT");
    //tracing::debug!("DEBUG TEXT");
}

#[cfg(test)]
mod tests {
    //use super::*;
}

Использование в других крейтах

В библиотеках (Cargo.toml):

[dependencies]
common-logging = { path = "../common-logging" }
tracing = { workspace = true }
tracing-appender = { workspace = true }
tracing-subscriber = { workspace = true }

В библиотеках (lib.rs):

use tracing::{debug, error, info, warn};
pub fn greet_user(name: &str) -> String {
    info!("Library _greet_user_ function called"); // вызов логгера
    format!("Hello {name}")
}

В бинарном крейте (Cargo.toml):

[dependencies]
common-log = { path = "../common-log" }
tracing = { workspace = true }
tracing-appender = { workspace = true }
tracing-subscriber = { workspace = true }

В бинарном крейте (main.rs):

use common_log::setup_tracing;
use tracing::{debug, error, info, warn};

fn main() {
    setup_tracing(); // инициализация логгера из библиотеки common-log
    info!("Logger initialized. App started."); // вызов логгера
}

Лог будет сохранён в папке /log/ в бинарном крейте, так как из него делается вызов инициализации.

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

#[cfg(test)]
mod tests {
    use super::*;
    use common_logging::setup_tracking;

    #[test]
    fn test_something() {
        init_test_logger();
        // ваш тест
    }
}

Настройка через переменные окружения

# Установка уровня логирования
RUST_LOG=debug cargo run
RUST_LOG=my_library=debug,info cargo run

# Для конкретного крейта
RUST_LOG=my_library=debug cargo run