ライブラリ

tracing

概要

tracingは構造化・非同期ロギングとスパンベースの可観測性を提供する現代的なRustライブラリです。従来のロギングマクロ（info!、error!等）に加え、分散トレーシングとメトリクス収集に対応し、マイクロサービス環境での監視に最適化されています。2025年マイクロサービスとクラウドネイティブ環境でのRust開発において急速に採用拡大しており、構造化ログと分散トレーシングの重要性増加により、本格的な本番システムでの選択肢として注目されています。

詳細

tracing 2025年版は、可観測性を重視するモダンなRustプロジェクトでの標準的な選択肢となりつつあります。従来のログ出力機能を超えて、アプリケーションの実行フローを追跡する「スパン」という概念を導入し、分散システムでのリクエスト追跡、パフォーマンス分析、デバッグを強力にサポート。非同期処理との親和性が高く、Tokioエコシステムとの統合により、高性能な非同期アプリケーションでの利用価値が高く評価されています。

主な特徴

• 構造化ロギング: key-value形式でのリッチなコンテキスト情報管理
• スパンベーストレーシング: 処理の開始から終了までの追跡とネスト構造
• 非同期対応: Tokio等の非同期ランタイムとの完全統合
• 分散トレーシング: OpenTelemetryとの統合による分散システム可視化
• メトリクス収集: パフォーマンス指標の自動収集と分析
• 拡張可能なSubscriberシステム: プラガブルな出力先とフォーマット

メリット・デメリット

メリット

• マイクロサービスやクラウドネイティブ環境での優れた可観測性
• 非同期処理との完全統合によりパフォーマンス低下を最小化
• OpenTelemetryサポートによる業界標準の分散トレーシング対応
• 構造化ログによる機械的な解析とクエリが容易
• スパン機能により複雑な処理フローの可視化が可能
• 豊富なエコシステムと活発なコミュニティサポート

デメリット

• 従来のログライブラリと比較して学習コストが高い
• 単純なアプリケーションには機能が過剰になる場合がある
• 設定とSubscriberの理解に時間を要する
• メモリ使用量が従来のログライブラリより多い傾向
• デバッグ時の出力が複雑で初心者には理解が困難
• 小規模プロジェクトでは導入コストが見合わない場合がある

参考ページ

• tracing GitHub リポジトリ
• tracing Rust ドキュメント
• Tracing Book

書き方の例

インストールと基本セットアップ

# Cargo.tomlに依存関係を追加
[dependencies]
tracing = "0.1"
tracing-subscriber = "0.3"

# 非同期アプリケーションでの推奨セットアップ
tokio = { version = "1.0", features = ["full"] }
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }
tracing-opentelemetry = "0.21"  # OpenTelemetry統合用
tracing-appender = "0.2"        # ファイル出力用

基本的なロギング（従来のlogクレート互換）

use tracing::{info, warn, error, debug, trace};
use tracing_subscriber;

fn main() {
    // 基本的なSubscriberの初期化
    tracing_subscriber::init();

    // 従来のログライブラリと同様の使用方法
    trace!("トレースレベルの詳細情報");
    debug!("デバッグ情報: アプリケーション開始");
    info!("情報: 設定ファイルを読み込みました");
    warn!("警告: 一時的な設定を使用中");
    error!("エラー: データベース接続に失敗");

    // 構造化ログ（key-value形式）
    info!(
        user_id = 12345,
        action = "login",
        ip_address = "192.168.1.100",
        "ユーザーがログインしました"
    );

    // 変数の展開
    let request_id = "req_abcd1234";
    let response_time_ms = 150;
    
    info!(
        request_id,
        response_time_ms,
        "リクエスト処理が完了しました"
    );
}

スパンベーストレーシング

use tracing::{info, warn, error, span, Level, instrument};
use tracing_subscriber;

#[tokio::main]
async fn main() {
    tracing_subscriber::init();

    info!("アプリケーション開始");

    // 手動スパン作成
    let span = span!(Level::INFO, "user_registration", user_id = 12345);
    let _enter = span.enter();

    info!("ユーザー登録プロセス開始");
    
    // ネストしたスパン
    register_user("[email protected]").await;
    
    info!("ユーザー登録プロセス完了");
}

// 自動スパン生成（instrument属性使用）
#[instrument]
async fn register_user(email: &str) -> Result<u64, String> {
    info!("ユーザー登録開始");
    
    // データベース操作のスパン
    let user_id = create_user_in_database(email).await?;
    
    // メール送信のスパン
    send_welcome_email(email, user_id).await?;
    
    info!(user_id, "ユーザー登録が正常に完了");
    Ok(user_id)
}

#[instrument(skip(email), fields(email = %email))]
async fn create_user_in_database(email: &str) -> Result<u64, String> {
    info!("データベースにユーザーを作成中");
    
    // データベース操作のシミュレーション
    tokio::time::sleep(tokio::time::Duration::from_millis(100)).await;
    
    let user_id = 12345; // 生成されたユーザーID
    info!(user_id, "ユーザーがデータベースに作成されました");
    
    Ok(user_id)
}

#[instrument]
async fn send_welcome_email(email: &str, user_id: u64) -> Result<(), String> {
    info!("ウェルカムメール送信中");
    
    // メール送信のシミュレーション
    tokio::time::sleep(tokio::time::Duration::from_millis(200)).await;
    
    info!("ウェルカムメールの送信が完了");
    Ok(())
}

高度なSubscriber設定とフィルタリング

use tracing::{info, warn, error, Level};
use tracing_subscriber::{
    fmt,
    layer::SubscriberExt,
    util::SubscriberInitExt,
    EnvFilter,
    Registry,
};
use tracing_appender::{rolling, non_blocking};

fn main() {
    // 複数の出力先を持つSubscriberの設定
    let file_appender = rolling::daily("logs", "app.log");
    let (non_blocking, _guard) = non_blocking(file_appender);

    let subscriber = Registry::default()
        .with(EnvFilter::from_default_env()
            .add_directive("myapp=debug".parse().unwrap())
            .add_directive("myapp::database=trace".parse().unwrap()))
        .with(fmt::Layer::new()
            .with_writer(std::io::stdout)
            .with_ansi(true)
            .with_level(true)
            .with_target(true)
            .with_thread_ids(true)
            .with_thread_names(true))
        .with(fmt::Layer::new()
            .with_writer(non_blocking)
            .with_ansi(false)
            .json());

    subscriber.init();

    info!("設定されたSubscriberでアプリケーション開始");

    // さまざまなモジュールからのログ
    database_operations();
    network_operations();
    business_logic();
}

mod database {
    use tracing::{info, debug, error, instrument, span, Level};

    #[instrument]
    pub fn connect() -> Result<(), &'static str> {
        debug!("データベース接続設定を読み込み中");
        info!("データベースに接続しました");
        Ok(())
    }

    #[instrument(skip(query), fields(query_type = "SELECT"))]
    pub fn execute_query(query: &str) -> Result<Vec<String>, &'static str> {
        let span = span!(Level::DEBUG, "query_execution", query_length = query.len());
        let _enter = span.enter();
        
        debug!("SQLクエリ実行中");
        
        // クエリ実行のシミュレーション
        std::thread::sleep(std::time::Duration::from_millis(50));
        
        info!(rows_affected = 3, "クエリが正常に実行されました");
        Ok(vec!["row1".to_string(), "row2".to_string(), "row3".to_string()])
    }
}

mod network {
    use tracing::{info, warn, error, instrument};

    #[instrument]
    pub fn send_http_request(url: &str) -> Result<String, &'static str> {
        info!("HTTPリクエスト送信開始");
        
        // ネットワーク処理のシミュレーション
        std::thread::sleep(std::time::Duration::from_millis(300));
        
        info!(status_code = 200, "HTTPリクエストが成功");
        Ok("response_data".to_string())
    }

    #[instrument]
    pub fn handle_timeout() {
        warn!("ネットワークタイムアウトが発生");
        error!("接続がタイムアウトしました");
    }
}

fn database_operations() {
    let _ = database::connect();
    let _ = database::execute_query("SELECT * FROM users WHERE active = true");
}

fn network_operations() {
    let _ = network::send_http_request("https://api.example.com/data");
    network::handle_timeout();
}

fn business_logic() {
    info!("ビジネスロジック処理開始");
    info!("ビジネスロジック処理完了");
}

非同期処理とOpenTelemetry統合

use tracing::{info, instrument, Span};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
use tracing_opentelemetry::OpenTelemetryLayer;
use opentelemetry::{global, KeyValue};
use opentelemetry_sdk::{
    trace::{self, TracerProvider},
    Resource,
};
use opentelemetry_jaeger::JaegerPipeline;

#[tokio::main]
async fn main() -> Result<(), Box<dyn std::error::Error + Send + Sync + 'static>> {
    // OpenTelemetryトレーサーの設定
    global::set_text_map_propagator(opentelemetry_jaeger::Propagator::new());
    
    let tracer = opentelemetry_jaeger::new_agent_pipeline()
        .with_service_name("myapp")
        .install_simple()?;

    // Subscriberの設定
    tracing_subscriber::registry()
        .with(tracing_subscriber::EnvFilter::new("myapp=debug"))
        .with(tracing_subscriber::fmt::layer())
        .with(OpenTelemetryLayer::new(tracer))
        .init();

    info!("分散トレーシング対応アプリケーション開始");

    // 分散トレーシング対応の処理
    process_order("order_12345").await?;

    // OpenTelemetryのシャットダウン
    global::shutdown_tracer_provider();
    Ok(())
}

#[instrument]
async fn process_order(order_id: &str) -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
    info!("注文処理開始");
    
    // カスタム属性の追加
    Span::current().set_attribute(KeyValue::new("order.priority", "high"));
    
    // 各ステップの処理
    validate_order(order_id).await?;
    reserve_inventory(order_id).await?;
    process_payment(order_id).await?;
    ship_order(order_id).await?;
    
    info!("注文処理完了");
    Ok(())
}

#[instrument]
async fn validate_order(order_id: &str) -> Result<(), &'static str> {
    info!("注文検証中");
    tokio::time::sleep(tokio::time::Duration::from_millis(50)).await;
    
    // バリデーション結果
    Span::current().set_attribute(KeyValue::new("validation.result", "success"));
    info!("注文検証完了");
    Ok(())
}

#[instrument]
async fn reserve_inventory(order_id: &str) -> Result<(), &'static str> {
    info!("在庫確保中");
    tokio::time::sleep(tokio::time::Duration::from_millis(100)).await;
    
    let reserved_items = 3;
    Span::current().set_attribute(KeyValue::new("inventory.reserved_items", reserved_items));
    info!(reserved_items, "在庫確保完了");
    Ok(())
}

#[instrument]
async fn process_payment(order_id: &str) -> Result<(), &'static str> {
    info!("決済処理中");
    tokio::time::sleep(tokio::time::Duration::from_millis(200)).await;
    
    let amount = 9999;
    Span::current().set_attribute(KeyValue::new("payment.amount", amount));
    Span::current().set_attribute(KeyValue::new("payment.method", "credit_card"));
    
    info!(amount, "決済処理完了");
    Ok(())
}

#[instrument]
async fn ship_order(order_id: &str) -> Result<(), &'static str> {
    info!("配送手配中");
    tokio::time::sleep(tokio::time::Duration::from_millis(80)).await;
    
    let tracking_number = "TRK123456789";
    Span::current().set_attribute(KeyValue::new("shipping.tracking_number", tracking_number));
    
    info!(tracking_number, "配送手配完了");
    Ok(())
}

カスタムSubscriberとメトリクス収集

use tracing::{info, warn, error, Subscriber, Event, Id, span};
use tracing_subscriber::{
    layer::{Context, SubscriberExt},
    Layer, Registry,
};
use std::collections::HashMap;
use std::sync::{Arc, Mutex};
use std::time::{Duration, Instant};

// カスタムメトリクス収集Layer
#[derive(Debug, Clone)]
struct MetricsLayer {
    metrics: Arc<Mutex<Metrics>>,
}

#[derive(Debug, Default)]
struct Metrics {
    log_counts: HashMap<String, u64>,
    error_counts: HashMap<String, u64>,
    span_durations: HashMap<String, Vec<Duration>>,
}

impl MetricsLayer {
    fn new() -> Self {
        Self {
            metrics: Arc::new(Mutex::new(Metrics::default())),
        }
    }

    fn print_metrics(&self) {
        let metrics = self.metrics.lock().unwrap();
        
        println!("\n=== メトリクス レポート ===");
        
        println!("ログカウント:");
        for (level, count) in &metrics.log_counts {
            println!("  {}: {}", level, count);
        }
        
        println!("エラーカウント:");
        for (target, count) in &metrics.error_counts {
            println!("  {}: {}", target, count);
        }
        
        println!("スパン実行時間 (平均):");
        for (name, durations) in &metrics.span_durations {
            if !durations.is_empty() {
                let avg = durations.iter().sum::<Duration>() / durations.len() as u32;
                println!("  {}: {:?}", name, avg);
            }
        }
    }
}

impl<S> Layer<S> for MetricsLayer
where
    S: Subscriber,
{
    fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
        let mut metrics = self.metrics.lock().unwrap();
        
        // ログレベル別カウント
        let level = event.metadata().level().to_string();
        *metrics.log_counts.entry(level.clone()).or_insert(0) += 1;
        
        // エラーレベルの場合、ターゲット別カウント
        if *event.metadata().level() == tracing::Level::ERROR {
            let target = event.metadata().target().to_string();
            *metrics.error_counts.entry(target).or_insert(0) += 1;
        }
    }

    fn on_enter(&self, id: &Id, ctx: Context<'_, S>) {
        // スパン開始時刻を記録
        if let Some(span) = ctx.span(id) {
            span.extensions_mut().insert(Instant::now());
        }
    }

    fn on_exit(&self, id: &Id, ctx: Context<'_, S>) {
        // スパン実行時間を計算
        if let Some(span) = ctx.span(id) {
            if let Some(start_time) = span.extensions().get::<Instant>() {
                let duration = start_time.elapsed();
                let span_name = span.name().to_string();
                
                let mut metrics = self.metrics.lock().unwrap();
                metrics.span_durations
                    .entry(span_name)
                    .or_insert_with(Vec::new)
                    .push(duration);
            }
        }
    }
}

#[tokio::main]
async fn main() {
    let metrics_layer = MetricsLayer::new();
    
    // カスタムSubscriberの設定
    let subscriber = Registry::default()
        .with(tracing_subscriber::fmt::layer())
        .with(metrics_layer.clone());

    tracing::subscriber::set_global_default(subscriber)
        .expect("Failed to set subscriber");

    info!("カスタムメトリクス収集開始");

    // 様々な処理の実行
    for i in 0..5 {
        process_request(i).await;
    }

    // 意図的なエラーの発生
    error!("テストエラー1");
    error!("テストエラー2");
    warn!("警告メッセージ");

    // メトリクスの表示
    metrics_layer.print_metrics();
}

#[tracing::instrument]
async fn process_request(request_id: usize) {
    info!(request_id, "リクエスト処理開始");
    
    // 処理時間のばらつきを作るためのランダムな遅延
    let delay = 50 + (request_id * 25);
    tokio::time::sleep(tokio::time::Duration::from_millis(delay as u64)).await;
    
    if request_id % 3 == 0 {
        error!("リクエスト処理エラー");
    } else {
        info!(request_id, "リクエスト処理完了");
    }
}

実用的なWebアプリケーション統合例

use tracing::{info, warn, error, instrument, Span};
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
use uuid::Uuid;
use std::collections::HashMap;

// リクエストIDの生成とコンテキスト管理
#[derive(Debug, Clone)]
struct RequestContext {
    request_id: String,
    user_id: Option<u64>,
    ip_address: String,
}

impl RequestContext {
    fn new(user_id: Option<u64>, ip_address: String) -> Self {
        Self {
            request_id: Uuid::new_v4().to_string(),
            user_id,
            ip_address,
        }
    }

    fn attach_to_span(&self) {
        let span = Span::current();
        span.record("request_id", &self.request_id);
        span.record("user_id", &self.user_id.unwrap_or(0));
        span.record("ip_address", &self.ip_address);
    }
}

#[tokio::main]
async fn main() {
    // 本格的なWebアプリケーション向けSubscriber設定
    tracing_subscriber::registry()
        .with(
            tracing_subscriber::EnvFilter::try_from_default_env()
                .unwrap_or_else(|_| "myapp=debug,tower_http=debug".into()),
        )
        .with(tracing_subscriber::fmt::layer()
            .with_target(false)
            .with_timer(tracing_subscriber::fmt::time::UtcTime::rfc_3339())
            .with_level(true))
        .init();

    info!("Webアプリケーション開始");

    // 複数のリクエスト処理をシミュレート
    let requests = vec![
        (Some(12345), "192.168.1.100"),
        (None, "10.0.0.50"),
        (Some(67890), "203.0.113.25"),
    ];

    for (user_id, ip) in requests {
        let ctx = RequestContext::new(user_id, ip.to_string());
        handle_http_request(ctx).await;
    }
}

#[instrument(
    skip(ctx),
    fields(
        request_id = %ctx.request_id,
        user_id = ctx.user_id,
        ip_address = %ctx.ip_address
    )
)]
async fn handle_http_request(ctx: RequestContext) {
    info!("HTTPリクエスト受信");
    
    // リクエスト処理
    match process_business_logic(&ctx).await {
        Ok(result) => {
            info!(result = %result, "リクエスト処理成功");
        }
        Err(e) => {
            error!(error = %e, "リクエスト処理失敗");
        }
    }
}

#[instrument(skip(ctx))]
async fn process_business_logic(ctx: &RequestContext) -> Result<String, &'static str> {
    ctx.attach_to_span();
    
    info!("ビジネスロジック処理開始");
    
    // 認証チェック
    if let Some(user_id) = ctx.user_id {
        authenticate_user(user_id).await?;
    } else {
        warn!("未認証ユーザーからのリクエスト");
    }
    
    // データ処理
    let data = fetch_data().await?;
    let processed_data = transform_data(data).await?;
    
    info!("ビジネスロジック処理完了");
    Ok(processed_data)
}

#[instrument]
async fn authenticate_user(user_id: u64) -> Result<(), &'static str> {
    info!("ユーザー認証開始");
    
    // 認証処理のシミュレーション
    tokio::time::sleep(tokio::time::Duration::from_millis(30)).await;
    
    // ユーザー情報の記録
    Span::current().record("user_role", "premium");
    
    info!("ユーザー認証成功");
    Ok(())
}

#[instrument]
async fn fetch_data() -> Result<HashMap<String, String>, &'static str> {
    info!("データ取得開始");
    
    // データベースクエリのシミュレーション
    tokio::time::sleep(tokio::time::Duration::from_millis(100)).await;
    
    let mut data = HashMap::new();
    data.insert("key1".to_string(), "value1".to_string());
    data.insert("key2".to_string(), "value2".to_string());
    
    info!(records_count = data.len(), "データ取得完了");
    Ok(data)
}

#[instrument(skip(data))]
async fn transform_data(data: HashMap<String, String>) -> Result<String, &'static str> {
    info!(input_size = data.len(), "データ変換開始");
    
    // データ変換処理のシミュレーション
    tokio::time::sleep(tokio::time::Duration::from_millis(50)).await;
    
    let result = serde_json::to_string(&data).unwrap_or_else(|_| "{}".to_string());
    
    info!(output_size = result.len(), "データ変換完了");
    Ok(result)
}