rust + tonic + opentelemetry を利用した分散トレース

概要

rust + tonic + opentelemetry を利用した場合の分散トレースを実装する方法を調査する
自分用メモ

モチベーション

opentelemetry を利用することでアプリケーションはバックエンドを気にすることなく、
トレースをエクスポートできる。

これまで単一のアプリケーション上のトレースを otel-collector で収集して、バックエンドとして tempo に送信、最終的には grafana でトレースを見ることはできていたが、
複数のアプリケーションにまたがった分散トレースには対応していなかった。

そのため、tonic を利用した grpc マイクロサービスを実装して、クライアントとサーバ間の一連の処理が単一のトレースと取得できるようにする方法を調査する。

外部クレートを使った実装

以下クレートを利用するだけで比較的容易に実装は可能だった
（tracing-opentelemetry-instrumentation-sdk のリポジトリの examples/grpc が今回やりたいことのまんまだった）

• init-tracing-opentelemetry:
  • provider や propagator, subscriber の初期化を行う
  • https://github.com/davidB/tracing-opentelemetry-instrumentation-sdk/tree/main/init-tracing-opentelemetry
• tonic-tracing-opentelemetry:
  • リクエストにトレース情報を追加する、レスポンスから現在のトレース情報を取得する機能を提供する
  • https://github.com/davidB/tracing-opentelemetry-instrumentation-sdk/tree/main/tonic-tracing-opentelemetry

ただ、opentelemetry の provider や propagator、subscriber の初期化は自前で実装したいので、
ここでは init-tracing-opentelemetry クレートを使わない実装をしてつまずいたところをまとめる。

※tonic-tracing-opentelemetry は基本的に実装は変わらなそうなので、こちらはそのまま利用

つまずいたところ

トレース情報がサーバに送信されない

tonic-tracing-opentelemetry を使ってもトレース情報がサーバに送信されない問題が起きた。

トレース情報がサーバに送信できなかった時の tracer や propagator などの初期化コードは以下の通り

ダメなコード

pub fn init_tracer() -> OtelGuard{
    let resource = opentelemetry_sdk::Resource::new(
        vec![
            opentelemetry::KeyValue::new(resource::SERVICE_NAME, env!("CARGO_PKG_NAME")),
            opentelemetry::KeyValue::new(resource::SERVICE_VERSION, env!("CARGO_PKG_VERSION")),
            ]
        );
    
    let builder = opentelemetry_sdk::trace::TracerProvider::builder();
    
    // debug ビルドの場合は stdout に、それ以外の場合は otlp に送信する 
    let builder = if !cfg!(debug_assertions) {
        builder.with_batch_exporter(SpanExporter::builder().with_tonic().with_endpoint("grpc://otel-collector:4317").with_protocol(opentelemetry_otlp::Protocol::Grpc).with_timeout(Duration::from_secs(10)).build().unwrap(),opentelemetry_sdk::runtime::Tokio)
    } else {
        builder.with_simple_exporter(opentelemetry_stdout::SpanExporter::default())
    };
    let provider = builder
        .with_sampler(Sampler::ParentBased(Box::new(Sampler::TraceIdRatioBased(1.0))))
        .with_id_generator(RandomIdGenerator::default())
        // .with_resource(resource)
        .build();

    let tracer = provider.tracer("");
    let telemetry = tracing_opentelemetry::layer().with_tracer(tracer).with_error_records_to_exceptions(true);

    // propagator の初期化
    let propagator = opentelemetry::propagation::TextMapCompositePropagator::new(vec![
        Box::new(opentelemetry_sdk::propagation::TraceContextPropagator::new()),
        Box::new(opentelemetry_sdk::propagation::BaggagePropagator::new())    
    ]);

    opentelemetry::global::set_text_map_propagator(propagator);
    opentelemetry::global::set_tracer_provider(provider.clone());

    let subscriber = Registry::default()
        .with(telemetry)
        .with(tracing_subscriber::filter::EnvFilter::new(Level::INFO.as_str()))
        .with(
            tracing_subscriber::fmt::layer().json()
                .with_timer(tracing_subscriber::fmt::time::uptime()));
    tracing::subscriber::set_global_default(subscriber).unwrap();
    
    OtelGuard {
        tracer_provider: provider,
    }
}

ダメなコードとOkなコードの差分

サーバにトレース情報を送信できたコードと上のコードの差分は以下の通り

    let subscriber = Registry::default()
        .with(telemetry)
-       .with(tracing_subscriber::filter::EnvFilter::new(Level::INFO.as_str())).
+       .with(build_loglevel_filter_layer())
        .with(
            tracing_subscriber::fmt::layer().json()
                .with_timer(tracing_subscriber::fmt::time::uptime()));
    ...
}

+ pub fn build_loglevel_filter_layer() -> tracing_subscriber::filter::EnvFilter {
+     // filter what is output on log (fmt)
+     // std::env::set_var("RUST_LOG", "warn,otel::tracing=info,otel=debug");
+     std::env::set_var(
+         "RUST_LOG",
+         format!(
+             // `otel::tracing` should be a level info to emit opentelemetry trace & span
+             // `otel::setup` set to debug to log detected resources, configuration read
+             "{},otel::tracing=trace",
+             std::env::var("RUST_LOG")
+                 .or_else(|_| std::env::var("OTEL_LOG_LEVEL"))
+                 .unwrap_or_else(|_| "info".to_string())
+         ),
+     );
+     EnvFilter::from_default_env()
+ }

原因

サーバにトレース情報を送信できなかった原因は tonic-tracing-opentelemetry クレート上でtrace レベルでスパン作成していたが、フィルタで info レベル以下のスパンは無効なものになっていたため。

具体的には otel::tracing=trace と指定されている

変更前のコードだと filter レイヤーで info レベル以上のスパンのみが有効になっているが、
変更後のコードだと otel::tracing に関しては trace レベル以上であれば有効になっている。

例えば、filter で info を指定していた場合は、trace や debug レベルでスパンを作成してもIDが付与されていない状態で生成される。

let span = tracing::debug_span!("hogehoge");
println!("{:?}",span);
// output: Span { none: true }

そのため、トレース情報をリクエストに追加するときにスパンが有効なものであるかどうかのチェックに引っ掛かり、
リクエストにトレース情報を追加できないという状態に陥っていた。

/// opentelemetry-sdk::propagation::trace_context.rs より
/// リクエストにトレース情報を追加処理の実装
impl TextMapPropagator for TraceContextPropagator {
    fn inject_context(&self, cx: &Context, injector: &mut dyn Injector) {
        let span = cx.span();
        let span_context = span.span_context();
            /// スパンIDとトレースIDがセットされている場合のみリクエストにトレース情報をついかｓ
            if span_context.is_valid() { 
            let header_value = format!(
                "{:02x}-{}-{}-{:02x}",
                SUPPORTED_VERSION,
                span_context.trace_id(),
                span_context.span_id(),
                span_context.trace_flags() & TraceFlags::SAMPLED
            );
            injector.set(TRACEPARENT_HEADER, header_value);
            injector.set(TRACESTATE_HEADER, span_context.trace_state().header());
        }
    }
}

tonic-tracing-opentelemetry には tracing_level_info という feature があるので、
info レベルでスパンを作成するようにしたい場合はこちらの feature を有効化する