はじめに
こんにちは、バックエンドエンジニアのよしかわです。
今回の題材は Rust で tracing::info! などを呼び出すコードのテストです。Rust のプログラムで処理の進捗やエラーを出力するのに tracing の tracing::info! や tracing::error! を使うケースは珍しくないと思います。このとき全ての出力をテストする必要はないかもしれません。しかし重要な出力についてテストしたい場合もあるのではないでしょうか。以下ではそのような場合に使えるかもしれない道具立てをいくつかご紹介します。
これはエモーションテック Advent Calendar 2023 19日目の記事です。
その１: tracing-mock
１つめは tracing 本体のテストにも使われている tracing-mock です。下記の例にあるような細かいテストが可能なようです。
use tracing::subscriber::with_default; use tracing_mock::{subscriber, expect, field}; #[tracing::instrument] fn yak_shaving(number_of_yaks: u32) { tracing::info!(number_of_yaks, "preparing to shave yaks"); let number_shaved = number_of_yaks; // shave_all tracing::info!( all_yaks_shaved = number_shaved == number_of_yaks, "yak shaving completed." ); } let yak_count: u32 = 3; let span = expect::span().named("yak_shaving"); let (subscriber, handle) = subscriber::mock() .new_span( span.clone() .with_field(expect::field("number_of_yaks").with_value(&yak_count).only()), ) .enter(span.clone()) .event( expect::event().with_fields( expect::field("number_of_yaks") .with_value(&yak_count) .and(field::msg("preparing to shave yaks")) .only(), ), ) .event( expect::event().with_fields( expect::field("all_yaks_shaved") .with_value(&true) .and(field::msg("yak shaving completed.")) .only(), ), ) .exit(span.clone()) .only() .run_with_handle(); with_default(subscriber, || { yak_shaving(yak_count); }); handle.assert_finished();https://github.com/tokio-rs/tracing/tree/tracing-subscriber-0.3.18/tracing-mock#examples
ただし tracing-mock は現在(2023年12月13日)のところ crates.io から取得できません。README の Usage にあるような方法で GitHub から直接取得する必要があります。tracing-mock だけでなく tracing についても GitHub からの取得になるので Cargo.toml のメンテナンスが煩雑になりそうなのは懸念点です。API の安定性も気になります。そのため今のところはエモーションテック社内で tracing-mock を使用していません。
その２: tracing_test
２つめはサードパーティーのクレートの一つである tracing_test *1です。下記の例のような簡単なテストには tracing-mock より tracing_test の方が向いているかもしれません。
#[tokio::test] #[traced_test] async fn test_logs_are_captured() { // Local log info!("This is being logged on the info level"); // Log from a spawned task (which runs in a separate thread) tokio::spawn(async { warn!("This is being logged on the warn level from a spawned task"); }) .await .unwrap(); // Ensure that certain strings are or aren't logged assert!(logs_contain("logged on the info level")); assert!(logs_contain("logged on the warn level")); assert!(!logs_contain("logged on the error level")); // Ensure that the string `logged` is logged exactly twice logs_assert(|lines: &[&str]| { match lines.iter().filter(|line| line.contains("logged")).count() { 2 => Ok(()), n => Err(format!("Expected two matching logs, but found {}", n)), } }); }https://docs.rs/tracing-test/0.2.4/tracing_test/#usage
注意点はいくつか暗黙的な要素があるところでしょうか。例えば
logs_contain などの関数は #[traced_test] により裏で定義され、Subscriber の初期化処理も背後に隠されていて変更できません。とくに Subscriber については自動でグローバルなものが登録されます。このグローバルな Subscriber が既存のテストコードに一部干渉したこともありエモーションテックの社内では tracing_test を使用していません。
その３: MockMakeWriter
３つめは tracing-subscriber のテスト内部で定義されている MockMakeWriter です。方法１の tracing-mock と同じく tracing のリポジトリに含まれています。利用例は tracing のリポジトリ内を検索すると見つかります。tracing_test と異なりマクロの裏に隠される要素はありません。
fn assert_info_hello(subscriber: impl Into<Dispatch>, buf: MockMakeWriter, expected: &str) { let _default = set_default(&subscriber.into()); tracing::info!("hello"); let result = buf.get_string(); assert_eq!(expected, result) }https://github.com/tokio-rs/tracing/blob/tracing-subscriber-0.3.18/tracing-subscriber/src/fmt/format/mod.rs#L1910-L1916
残念ながら MockMakeWriter は外部に公開されておらず tracing-mock のような方法での参照もできません。しかし実装は単純で長さも100行未満なので丸ごとの複製もできなくはないです。もし MockMakeWriter を複製して使うなら、追加で次のような Capture を定義し組み合わせて使うと便利かもしれません。
use std::sync::{Arc, Mutex}; use tracing::subscriber::{set_default, DefaultGuard}; use tracing::Subscriber; use tracing_subscriber::fmt::{FormatEvent, FormatFields, Layer, MakeWriter}; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::registry::LookupSpan; use tracing_subscriber::{registry, EnvFilter}; pub(crate) struct Capture { make_writer: MockMakeWriter, #[allow(dead_code)] guard: DefaultGuard, } impl Capture { pub fn start(subscriber: impl Subscriber + for<'a> LookupSpan<'a> + Send + Sync) -> Self { Self::start_with_fmt_layer( subscriber, Layer::new() .compact() .with_ansi(false) .with_target(false) .without_time(), ) } pub fn start_with_fmt_layer< S: Subscriber + for<'a> LookupSpan<'a> + Send + Sync, N: for<'a> FormatFields<'a> + Send + Sync + 'static, E: FormatEvent<S, N> + Send + Sync + 'static, W, >( subscriber: S, layer: Layer<S, N, E, W>, ) -> Self { let buffer = Arc::new(Mutex::new(Vec::new())); let make_writer = MockMakeWriter::new(Arc::clone(&buffer)); Self { make_writer: MockMakeWriter::new(Arc::clone(&buffer)), guard: set_default(subscriber.with(layer.with_writer(make_writer))), } } pub fn extract(&self) -> String { self.make_writer.get_string() } }
「その２」の tracing_test の例を Capture を使う形へ書き換えると概ね*2下記のようになります。マクロを剥がした分だけ記述の柔軟性の点では有利かと思います。
#[tokio::test] async fn test_logs_are_captured() { let capture = Capture::start(registry().with(EnvFilter::new("trace"))); // Local log tracing::info!("This is being logged on the info level"); // Log from a spawned task (which runs in a separate thread) tokio::spawn(async { tracing::warn!("This is being logged on the warn level from a spawned task"); }) .await .unwrap(); let logs = capture.extract(); // Ensure that certain strings are or aren't logged assert!(logs.contains("logged on the info level")); assert!(logs.contains("logged on the warn level")); assert!(!logs.contains("logged on the error level")); // Ensure that the string `logged` is logged exactly twice let n = logs .split('\n') .filter(|line| line.contains("logged")) .count(); assert_eq!(n, 2, "Expected two matching logs, but found {n}"); }
エモーションテック社内では最近 Capture に近いコードの試用を始めました。まだ日が浅いためか簡単なテストでしか試していないためなのか、今のところ困った点は出ていません。
おわりに
サービス運用において信頼できるトレース情報は欠かせません。今回ご紹介した内容はいずれも一長一短ではありますが、トレース情報の信頼性を担保する上で参考になるところがもしあれば嬉しく思います。
エモーションテックでは顧客体験・従業員体験の改善をサポートし世の中の体験を変えるプロダクトを開発しており、その中で Rust や tracing も利用しております。もし弊社での開発に興味を持って頂けましたら、ぜひ採用ページからご応募をお願いいたします。
*1:最近 tracing 本体の内部用途のために追加された tracing-test とは別物です
