本記事は hooqアドベントカレンダー 17日目の記事です!
hooqはメソッドを ? 演算子にフックする属性マクロです。本アドカレではhooqの使い方を始め、hooqマクロを作成するにあたり得た知識、Rustのエラーハンドリング・エラーロギング周りの話をまとめています。
今回は、「hooq属性マクロは#[tracing::instrument]属性マクロとも相性が良い!」という話をします!
? 演算子の位置でログを出したい
hooqマクロを使うことで、エラートレースもどきを簡単に得られます。
しかし、hooqの制作進捗をつぶやく中で、「tracingを使うからhooqは自分は使わないかな...」といった声(意訳)を何回か聞きました。
筆者は簡単なアプリではanyhow (か最近はcolor-eyreなど) を使っていたため1、tracingは業務を通した表面的な知識しかないのですが、なるほど #[tracing::instrument] を使えば確かにログを通してエラートレースもどき「 スパントレース (span trace)」を得られます!仕組みは異なりますが、バックトレース系統の技術を使わずにエラー発生の流れおよび位置を知ることができるわけです。
しかしながら待ってください。 #[tracing::instrument] マクロにはできなくて、#[hooq::hooq] マクロならできることがあります...!
それは「エラーを返した式の ? 演算子がある行を取得する」 ことです!
#[tracing::instrument(err)] を関数に付与した場合、エラー発生時にログが送出されスパン情報の一つとして行情報( code.line.number )が得られます。しかしこれは 関数定義行 2です!実際にエラーが発生した行を表していません。
これは些細なことでしょうか...?確かに本当に細かいちょっとした違いかもしれません。
では同じ種類のエラーが発生する複数の ? 演算子が一つの関数にたくさん含まれている場合などはどうでしょうか...?エラー発生箇所特定までの時間に差が出てくるかと思います。
二郎ラーメンで例えれば少なくとも、「 ニンニク入りか否か 」ぐらいの差はあるでしょう!筆者はニンニク入りの方が好きなのでhooq入りだとこんなに美味しいんだよという話をします。
tracingのみでは関数定義行しかわからない
というわけでニンニク...じゃなかったhooqなしのtracingとhooqありのtracingを比較するPoCを用意しました!
- hooqなし: https://github.com/anotherhollow1125/todo_app_tracing
- hooqあり: https://github.com/anotherhollow1125/todo_app_tracing_hooq
最小構成例を作ればよかったかもしれませんが一応それなりに動くaxum式Web TODOアプリにしました。トレースはjaegerで見られるようにしました。
jaeger導入の参考にさせていただきました
: Rust での tracing | blog.ojisan.io
少しだけ情報が古くなっているので公式ドキュメントも合わせて確認ください。
以下は今回例として取り上げるバリデーション部分になります! fn try_from(...) {...} にエラー時にログを送出する #[tracing::instrument(err)] を付けています。
src/model.rs
ソースコード
GitHubが見れない時用に直接コードも貼っておきます。
use crate::errors::ValidationError;
use crate::new_types::NonEmptyString;
use chrono::{DateTime, Utc};
#[derive(serde::Serialize, Debug)]
pub struct ToDoItem {
pub id: u32,
pub title: String,
pub content: String,
pub started_at: DateTime<Utc>,
pub deadline_at: Option<DateTime<Utc>>,
}
#[derive(serde::Deserialize, Debug)]
pub struct ToDoItemInput {
pub title: Option<String>,
pub content: Option<String>,
pub started_at: Option<DateTime<Utc>>,
pub deadline_at: Option<DateTime<Utc>>,
}
#[derive(serde::Serialize, Debug)]
pub struct ValidatedToDoItem {
pub id: u32,
pub title: NonEmptyString,
pub content: NonEmptyString,
pub started_at: DateTime<Utc>,
pub deadline_at: Option<DateTime<Utc>>,
}
impl TryFrom<(u32, ToDoItemInput)> for ValidatedToDoItem {
type Error = ValidationError;
#[tracing::instrument(err)]
fn try_from(
(
id,
ToDoItemInput {
title,
content,
started_at,
deadline_at: deadline,
},
): (u32, ToDoItemInput),
) -> Result<Self, Self::Error> {
let title = NonEmptyString::try_new(title.unwrap_or("untitled".to_string()))?;
let content = NonEmptyString::try_new(content.unwrap_or("default".to_string()))?;
let started_at = started_at.unwrap_or_else(Utc::now);
// deadlineが存在する場合、started_atより後であること
if let Some(deadline) = deadline
&& deadline <= started_at
{
return Err(ValidationError::new(
"deadline_at must be after started_at.",
));
}
Ok(ValidatedToDoItem {
id,
title,
content,
started_at,
deadline_at: deadline,
})
}
}
impl From<ValidatedToDoItem> for ToDoItem {
fn from(item: ValidatedToDoItem) -> Self {
ToDoItem {
id: item.id,
title: item.title.into_inner(),
content: item.content.into_inner(),
started_at: item.started_at,
deadline_at: item.deadline_at,
}
}
}
src/model.rsの46, 47行が今回PoCで特に扱いたいエラーハンドリング行です。
46| let title = NonEmptyString::try_new(title.unwrap_or("untitled".to_string()))?;
47| let content = NonEmptyString::try_new(content.unwrap_or("default".to_string()))?;
「空文字列」の時にバリデーションエラーになるという「同じエラーが発生する」箇所です!恣意的な例に見えるかもしれませんが、意外と起きうる状況でしょう。
タイトルかコンテンツのどちらかについてフロントエンドのバリデーションが抜けていて、空文字列が渡されてきた時にエラーになってしまうのだとします。
関数定義行しか得られない場合、Logsでは両者の見分けはつきません。 以下 jaegerのLogsのスクショです。
ちなみにTagsを見ると違いはわかります
今回はスキップせず引数部分もキャプチャするようにしたため、LogsではなくTagsからどちらが空文字列であったかわかります。
しかし 今回はたまたまここで判別できた というだけで、見たいエラー種がバリデーションではない場合など、この方法が効かない時の方が多いでしょう。
34行目は #[tracing::instrument(err)] fn try_from(...) {...} の冒頭がある行を示しているのみです。 どこの ? でエラーが起きたんだよ って感じです!
tracing × hooq = ? 演算子がある行取得!
#[tracing::instrument(err)]
上記のマクロ付与箇所を、
#[hooq::hooq(tracing)]
#[tracing::instrument]
に変えましょう! (err) を付けなくなるのでinstrumentマクロによるエラー時ログ送出はなくなりますが、今度はhooqマクロが ? 演算子箇所にエラーロギングをフックしてくれるため、 ? 演算子の行をログに吐き出す ようになります!
属性マクロの付与順について
#[hooq::hooq(tracing)] の方が小さいマクロで展開結果の予測がつきやすいです。一方で #[tracing::instrument] はなかなかえぐい量のコードを吐きます。
属性マクロは上から下に順に適用されるので、先に #[hooq::hooq(tracing)] を持ってきてください!
適用順番の詳細は別記事にまとめました: 【Rust】属性マクロは上下どちらから適用(展開)されるのか? #macro - Qiita
impl TryFrom<(u32, ToDoItemInput)> for ValidatedToDoItem {
type Error = ValidationError;
- #[tracing::instrument(err)]
+ #[hooq::hooq(tracing)]
+ #[tracing::instrument]
fn try_from(
(
id,
ToDoItemInput {
title,
content,
started_at,
deadline_at: deadline,
},
): (u32, ToDoItemInput),
) -> Result<Self, Self::Error> {
let title = NonEmptyString::try_new(title.unwrap_or("untitled".to_string()))?;
let content = NonEmptyString::try_new(content.unwrap_or("default".to_string()))?;
let started_at = started_at.unwrap_or_else(Utc::now);
// ...省略...
Ok(ValidatedToDoItem {
id,
title,
content,
started_at,
deadline_at: deadline,
})
}
}
titleが空文字列の場合と、contentが空文字列の場合が区別できるようになりました!
※ マクロが1行増えたためない場合と比べ1行分ずれています
これで素早くフロントエンド担当にエラー報告ができますね!めでたしめでたしです。
hooqがしたことの詳細
#[hooq::hooq(tracing)] を付与すると、式と ? 演算子の間に以下のメソッドが挿入されるようになります。
.inspect_err(|e| {
let path = ファイルパス;
let line = 行;
let col = 列;
let expr = フック対象の式を文字列化したもの;
::tracing::error!(
path,
line,
col,
error = %e,
expr,
);
})
src/model.rs 該当箇所のcargo expand
impl TryFrom<(u32, ToDoItemInput)> for ValidatedToDoItem {
type Error = ValidationError;
fn try_from(
(
id,
ToDoItemInput { title, content, started_at, deadline_at: deadline },
): (u32, ToDoItemInput),
) -> Result<Self, Self::Error> {
/*
* tracing::instrument による出力部分
*
* ...これと比べたらhooqは全然可愛くみえる...
*/
{
{
let title = NonEmptyString::try_new(
title.unwrap_or("untitled".to_string()),
)
.inspect_err(|e| {
let path = "src/model.rs";
let line = 47usize;
let col = 85usize;
let expr = "NonEmptyString::try_new(title.unwrap_or(\"untitled\".to_string()))?";
{
// tracing::error! の展開結果
};
})?;
let content = NonEmptyString::try_new(
content.unwrap_or("default".to_string()),
)
.inspect_err(|e| {
let path = "src/model.rs";
let line = 48usize;
let col = 88usize;
let expr = "NonEmptyString::try_new(content.unwrap_or(\"default\".to_string()))?";
{
// tracing::error! の展開結果
};
})?;
let started_at = started_at.unwrap_or_else(Utc::now);
Ok(ValidatedToDoItem {
id,
title,
content,
started_at,
deadline_at: deadline,
})
}
}
}
}
hooqが行っているのはこれだけです!シンプル!
余談ですが、 error! 以外のレベルも簡単に指定可能にしたいと考えています。ただ筆者がtracingに慣れておらず塩梅がわからないため、その実装は一旦後回しになっています。
まとめ・所感
この記事をしっかり読んでくださった方向けに最後に免責事項を書いておきます。
今回、自分がずっとやりたかった「 ? 演算子におけるログ送出」を自分なりの方法で実現できたので、そのPoCをとりあえず掲載しました。何が言いたいかというと 他の手段の模索・検証はまだしていません 。
- 「
std::backtrace::Backtraceを使えばもっと簡単に同じことができるけど?」- tracingのログにそのまま出力すればよいのでしょうか...?解法としては単純明快ですがスパントレースとのシナジーがなさそうです。
- 「tracingクレートのこの機能を使えば...」
- 実は筆者が知らないだけで指定方法を工夫すると
?の位置までわかるとか...?
- 実は筆者が知らないだけで指定方法を工夫すると
こういった知見がもしあれば ぜひ知りたい です!
自分の知る範囲では代わりの手段を簡単に見つけることができなかったのがhooqを作ることにした理由の一つです。明日以降のアドカレ執筆を通してその他の手段を自分でも模索したいと考えていますが、もし詳しい方いましたら是非(優しく)教えてほしいです!
というわけで、ここまで読んでいただきありがとうございました!





