Логирование в Rust с log и tracing

Когда в программе что-то идёт не так, хочется знать, что она делала прямо перед этим. Для этого и нужно логирование. Лог похож на судовой журнал: короткие записи, у каждой есть время и уровень важности, и потом по ним можно понять, что произошло.

Можно, конечно, расставить println! повсюду, но скоро ты упрёшься в его ограничения. Его не выключить, не меняя код. Нельзя сказать «покажи мне только предупреждения». И он смешивает твои отладочные заметки с настоящим выводом программы. Крейты для логирования в Rust решают все три проблемы. На этой странице ты познакомишься с двумя самыми популярными: log (вместе с env_logger) и tracing.

Почему не просто println!?

Вот разница на одной картинке:

	println!	крейт для логирования
Включить/выключить без перекомпиляции	Нет	Да, переменной RUST_LOG
Уровни (error, warn, info, …)	Нет	Да
Показывает, откуда пришло сообщение	Нет	Да (имя модуля)
Куда пишет	stdout	по умолчанию в stderr (env_logger)

Последняя строка важнее, чем кажется. stdout — это настоящий результат программы, тот, что кто-то может перенаправить в файл или в другую программу. stderr — это боковой канал для сообщений о работе программы. Логам место в stderr: тогда my_app > result.txt сохранит только результат, а логи всё равно появятся в терминале.

Фасад log и env_logger

Крейт log даёт пять макросов, по одному на каждый уровень, от самого серьёзного к наименее серьёзному: error!, warn!, info!, debug! и trace!. Они работают как println! — с тем же форматированием через {}.

Но сам по себе log ничего не печатает. Это фасад (facade): стандартный набор макросов, которыми может пользоваться любая библиотека, не выбирая, как показывать сообщения. А приложение выбирает логгер, который их действительно выводит. Самый простой — env_logger. Добавь оба в проект:

cargo add log env_logger

[dependencies]
log = "0.4"
env_logger = "0.11"

Теперь один раз вызови env_logger::init() в начале main — и логируй:

use log::{debug, error, info, warn};

fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("вызов divide: a={a}, b={b}");
    if b == 0.0 {
        warn!("отказываюсь делить {a} на ноль");
        return None;
    }
    Some(a / b)
}

fn main() {
    env_logger::init();
    info!("калькулятор запускается");

    println!("10 / 4 = {:?}", divide(10.0, 4.0));
    println!("1 / 0 = {:?}", divide(1.0, 0.0));

    error!("так выглядит строка с ошибкой");
}

Вывод:

10 / 4 = Some(2.5)
1 / 0 = None

▶ Попробуй сам

Выше показан только stdout — настоящий результат программы. Строки лога уходят в stderr. В Playground они появляются в отдельной области «Standard Error».

Обрати внимание: по умолчанию env_logger показывает только ошибки. Чтобы увидеть больше, задай переменную окружения RUST_LOG при запуске программы. Вот как выглядели stderr и stdout вместе, когда мы запустили программу в терминале через RUST_LOG=debug cargo run (каждую метку времени мы заменили на … — у тебя там будут текущие дата и время):

[… INFO  my_app] калькулятор запускается
[… DEBUG my_app] вызов divide: a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] вызов divide: a=1, b=0
[… WARN  my_app] отказываюсь делить 1 на ноль
1 / 0 = None
[… ERROR my_app] так выглядит строка с ошибкой

В каждой строке лога видны уровень и модуль, из которого она пришла (my_app — имя крейта). Простые строки без квадратных скобок — это вывод println!.

Выбираем, что видеть, через RUST_LOG

Уровень показывает сам себя и всё, что серьёзнее. Так что RUST_LOG=warn показывает предупреждения и ошибки, а RUST_LOG=trace — всё подряд.

RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # только warn и error
RUST_LOG=off cargo run       # никаких логов

В Windows PowerShell сначала задай переменную: $env:RUST_LOG="debug"; cargo run.

Ещё можно фильтровать по модулю. Это очень удобно, когда библиотека слишком болтлива или тебя интересует только одна часть кода. Вот программа с модулем db:

use log::{debug, info};

mod db {
    use log::{debug, trace};

    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("ищем пользователя {id}");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("результат поиска: {name:?}");
        name
    }
}

fn main() {
    env_logger::init();
    info!("сервер запускается");

    for id in [1, 3] {
        match db::find_user(id) {
            Some(name) => println!("пользователь {id}: {name}"),
            None => println!("пользователь {id}: не найден"),
        }
    }

    debug!("все поиски завершены");
}

Вывод:

пользователь 1: Ada
пользователь 3: не найден

▶ Попробуй сам

Несколько фильтров, которые мы попробовали, и что они напечатали в stderr (метки времени заменены на …):

$ RUST_LOG=my_app=trace cargo run       # всё из нашего крейта
[… INFO  my_app] сервер запускается
[… TRACE my_app::db] ищем пользователя 1
[… DEBUG my_app::db] результат поиска: Some("Ada")
пользователь 1: Ada
[… TRACE my_app::db] ищем пользователя 3
[… DEBUG my_app::db] результат поиска: None
пользователь 3: не найден
[… DEBUG my_app] все поиски завершены

$ RUST_LOG=my_app::db=debug cargo run   # только модуль db, от debug и выше
[… DEBUG my_app::db] результат поиска: Some("Ada")
пользователь 1: Ada
[… DEBUG my_app::db] результат поиска: None
пользователь 3: не найден

Правила можно объединять через запятую: RUST_LOG=info,my_app::db=trace значит «info для всего, но trace для модуля db». Одна маленькая ловушка: в фильтре имя крейта пишется с подчёркиваниями. Пакет my-app логирует под именем my_app.

Уровень по умолчанию прямо в коде

Часто хочется, чтобы info было видно, даже когда RUST_LOG не задана. Для этого вместо init() используй env_logger::Builder. Там же можно выключить метку времени — это удобно для маленьких утилит:

use env_logger::Env;
use log::{debug, info};

fn main() {
    // Показываем `info` и выше, если RUST_LOG не говорит иначе.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();

    info!("приложение запущено");
    debug!("это видно только с RUST_LOG=debug");

    let total: u32 = (1..=10).sum();
    println!("итого = {total}");
}

Вывод:

итого = 55

▶ Попробуй сам

Без метки времени настоящий stderr после cargo run короткий и чистый:

[INFO  my_app] приложение запущено

Структурированное логирование с tracing

log даёт строки текста. tracing даёт события с данными, сгруппированные в спаны (spans). Его сделала команда Tokio, и именно его используют асинхронные веб-фреймворки вроде axum. Добавь его так:

cargo add tracing tracing-subscriber

Три идеи, которые нужно усвоить:

• События (events) — это как строки лога: info!, warn! и компания, с теми же именами, что в log.
• Поля (fields) прикрепляют данные в виде ключ = значение: info!(user_id = 42, "вход выполнен"). Инструменты умеют искать и фильтровать по этим полям, а не разбирать текст.
• Спаны (spans) описывают отрезок работы, например «обработка заказа 7». Каждое событие внутри спана помечается им.

Как и log, tracing ничего не показывает без подписчика (subscriber). Стандартный — tracing_subscriber::fmt(). Один сюрприз: по умолчанию он пишет в stdout, поэтому мы отправляем его в stderr через .with_writer(std::io::stderr):

use tracing::{info, info_span, warn};

fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stderr)
        .init();

    info!(user_id = 42, "вход выполнен");

    let span = info_span!("checkout", order_id = 7);
    let _guard = span.enter();

    let items = [1200, 350, 999];
    let total: u32 = items.iter().sum();
    info!(items = items.len(), total, "корзина подсчитана");

    if total > 2000 {
        warn!(total, limit = 2000, "заказ нужно проверить вручную");
    }

    println!("сумма заказа: {total}");
}

Вывод:

сумма заказа: 2549

▶ Попробуй сам

Вот stderr нашего запуска (метки времени заменены на …, цвета убраны):

…  INFO my_app: вход выполнен user_id=42
…  INFO checkout{order_id=7}: my_app: корзина подсчитана items=3 total=2549
…  WARN checkout{order_id=7}: my_app: заказ нужно проверить вручную total=2549 limit=2000

Видишь, что последние две строки начинаются с checkout{order_id=7}? Это и есть спан. Пока _guard жив, каждое событие находится «внутри» оформления заказа. Просто total — это сокращение для total = total.

#[instrument]: спан для каждого вызова

Создавать спаны вручную быстро надоедает. Поставь #[instrument] на функцию, и tracing будет создавать спан при каждом вызове, записывая аргументы как поля (они должны реализовывать Debug):

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

#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "скидка посчитана");
    price - off
}

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::DEBUG)
        .with_writer(std::io::stderr)
        .init();

    let final_price = apply_discount(2500, 10);
    info!(final_price, "готово");
    println!("итоговая цена: {final_price}");
}

Вывод:

итоговая цена: 2250

▶ Попробуй сам

stderr нашего запуска:

… DEBUG apply_discount{price=2500 percent=10}: my_app: скидка посчитана off=250
…  INFO my_app: готово final_price=2250

Подписчик fmt() показывает info и выше, если не сказать ему иное, — поэтому мы задали .with_max_level(tracing::Level::DEBUG). Если хочешь, чтобы RUST_LOG работала так же, как с env_logger, включи feature env-filter и используй EnvFilter:

[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter"] }

use tracing_subscriber::EnvFilter;

tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::from_default_env())
    .with_writer(std::io::stderr)
    .init();

Что выбрать?

• Маленькая CLI-утилита или скрипт? log + env_logger. Минимум настройки, простой текст — и готово.
• Веб-сервер, асинхронный код или много задач одновременно? tracing. Спаны помнят, к какому запросу относится сообщение, даже когда одновременно идут сотни запросов.
• Пишешь библиотеку? Используй только макросы (log или tracing) и никогда не вызывай init(). Как показывать логи, решает приложение.

Выбирать навсегда не обязательно. Стандартная настройка tracing-subscriber подхватывает и сообщения крейта log, так что библиотеки с любым из них показываются вместе.

Частые ошибки

Забыть настроить логгер. Если ни разу не вызвать env_logger::init() (или init() подписчика tracing), макросы прекрасно компилируются и печатают… ничего. Ни ошибки, ни предупреждения. Если логи пропали, сначала проверь это, а потом — RUST_LOG.

Вызвать init() дважды. Глобальный логгер может быть только один. Второй вызов вызывает панику. Вот настоящее сообщение:

thread 'main' (12345) panicked at …/env_logger-0.11.11/src/logger.rs:901:16:
env_logger::init should not be called after logger initialized: SetLoggerError(())

Паника говорит, что env_logger::init нельзя вызывать после того, как логгер уже инициализирован. Вызывай его один раз, в самом начале main. В тестах пиши let _ = env_logger::builder().is_test(true).try_init(); — этот вариант возвращает ошибку, а не паникует.

Сразу уронить guard спана. let _ = span.enter(); выглядит безобидно, но _ — это не имя переменной: guard уничтожается на той же строке, и спан сразу заканчивается. Наш запуск напечатал INFO my_app: handling request вообще без спана. Дай guard имя, например let _guard = span.enter();, чтобы он жил до конца области видимости.

Итоги

• Используй крейт для логирования вместо println!: так можно фильтровать по уровню и держать логи в stderr, отдельно от настоящего вывода.
• log даёт error!, warn!, info!, debug!, trace!; env_logger::init() их печатает.
• RUST_LOG управляет тем, что ты видишь: RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace.
• tracing добавляет структурированные поля (info!(user_id = 42, "вход выполнен")) и спаны; #[instrument] создаёт спан на каждый вызов функции.
• Библиотеки используют только макросы; приложение один раз настраивает логгер.

Проверь себя

Проверь себя

1. Ты запускаешь программу с env_logger, не задав RUST_LOG. Какие строки лога ты увидишь?

Все Только info! и выше Только error! Вообще никаких

2. Куда env_logger по умолчанию пишет сообщения лога?

stdout stderr В файл log.txt

3. Что показывает RUST_LOG=warn?

Только предупреждения Предупреждения и всё менее серьёзное Предупреждения и ошибки

4. Что делает #[instrument] на функции?

Замеряет время функции и печатает его Создаёт спан при каждом вызове, с аргументами в виде полей Ускоряет функцию Включает логирование во всей программе

5. Ты пишешь крейт-библиотеку. Что ей делать с логированием?

Использовать макросы логирования, а настройку логгера оставить приложению Вызывать env_logger::init() при загрузке библиотеки Использовать println!, чтобы всё всегда было видно

Результат: 0 / 5

Что почитать

• Документация крейта log (на английском) — пять макросов и как работает фасад, включая советы авторам библиотек.
• Документация env_logger (на английском) — полный синтаксис RUST_LOG и все параметры Builder.
• Документация tracing (на английском) — спаны, события, поля и #[instrument] во всех подробностях.
• Документация tracing-subscriber (на английском) — параметры форматирования, EnvFilter и вывод в JSON.
• Getting started with Tracing — Tokio (на английском) — понятное пошаговое введение от команды, которая поддерживает tracing.