blog法人カードのクラウド型発行・管理サービスpaild2024-04-02Rustでオブザーバビリティを実現するにはお手伝いの@helloyukiです。最近tokioの提供するtracingに関していろいろ調べごとをしました。したクレートを十分に使いこなすにはどうすればいいかを考える上で、自分なりに考えがまとまってきたので記事にしたいと思います。筆者はRust以外のプログラミング言語でのオブザーバビリティ関連の事項についてはまったくわかりません。Rust以外の事情は考慮しない記事となっている点にご注意ください。log)を出力するために使用できるクレートです。「構造化ログ」については後述します。私もこの一文を読んではじめて知ったのですが、tokioランタイム以外でも動くように実装されているようです。tokioのような非同期処理を行うシステムでは、従来のログの読み取りは大変困難を伴います。主にはログ同士の因果関係の把握が難しいという困難性を伴います。いうのも、tokioが管理する個々の「タスク」は多重化されており、それによってタスクから書き出されたログ同士の流れが逐次的にならないためです。どのログが何の処理のあとに書き出されたものかを判定するのが非同期処理性によって困難になっているのが現代の非同期処理を用いるアプリケーションの抱える課題である、ということです。tracingはこのような問題を、後述するSpanやEventと呼ばれる概念を使って解決することを目指しています。consoleなどに食わせて閲覧することができ、これにより非同期処理ランタイム上で動くアプリケーションであっても、ログ同士の因果関係や流れを追うことができるようになり、トラブル発生当時ないしは現在のシステムの状態を、トレーシングログを経由して窺い知ることができるというわけです。オブザーバビリティ、テレメトリ、構造化ログtracingクレートの裏側にあるのは、オブザーバビリティと構造化ログというふたつの概念です。これらについて簡単に復習しておきましょう。オブザーバビリティオブザーバビリティ(可観測性)は基本的にはシステムの状態を観測可能な状態にしておくことを指しています。最近の議論を見ているとどうやら複数定義があるようです。筆者はオブザーバビリティに関しては初学者である関係上、これらの定義に関する厳密な議論は提供できません。情報として両者を挙げておくに留めておきます。最初の定義は、いわゆるモニタリングツールを提供するSaaSベンダーが主に提唱するものです。代表的なベンダーであるNewRelic社の定義を拝借しておきましょう。オブザーバビリティ(Observability)は、日本語で「可観測性」あるいは「観測する能力」などと訳されます。システム上で何らかの異常が起こった際に、それを通知するだけでなく、どこで何が起こったのか、なぜ起こったのかを把握する能力を表す指標、あるいは仕組みを指します。オブザーバビリティでは、アプリケーションの稼働に伴って生まれる膨大な情報の中から、内部状況を把握するためのデータを取得し、複雑なシステムの状態やアプリケーションの動きを可視化します。エラーという結果だけでなく、そこに至るまでの道筋を逆にたどって、どこにトラブルの原因があるのかを探り出すのです。そのため、予期せぬトラブルに対しても有効に機能します。newrelic.comNewRelic社の議論では、監視、モダン監視、オブザーバビリティの順に取り上げて議論しています。それぞれの定義は下記の通りであり、そしてオブザーバビリティは最初の「監視」と「モダン監視」の現代のシステムに適用する際の課題点の解決を図ろうとするものである、と位置付けているようです。「CPU使用率が90%に到達したら、アラートを送る」という設定をしておくこと。これによって知ることができる情報は、「CPU使用率が90%を超えた」という事実だけであり、「なぜそれが起こったのか」までは知ることができず、別途調査が必要になる。アラートの設定はエンジニアがあらかじめ想定したものに限られる。未知の情報を知ることは難しい。上記の監視に加えて、たとえばサービスレベルにどのような影響を与えたかや、UI/UXがどうなったかまでを検出することを目指す。これもやはり同様に結局のところ想定済みの事象に対して設定が行われるものであり、ある種のリアクティブなものであると言える。システム全体の内部状況を把握するために情報同士を関連づけて保存しておくことで、「なぜその事象が起こったのか」を知ることができる。問題全容の把握はもちろん、想定外の事態に対しても迅速に対応できるようになる。オブザーバビリティを実現する手段として「オブザーバビリティ3本柱」という要素を列挙します[*1]。(なおこれはのちに説明するテレメトリと呼ばれる概念に属するものであり、再度引用することになります。CPU使用率ならそれを、秒単位などで定期的に取得する。何が起きているのかを知ることができる。原因にたどり着くための処理プロセスを可視化したもの。どこで問題が起きたかを知ることができる。アプリケーションなどから出力されるテキスト情報。何が起きたのかを知ることができる。ひとつの定義を紹介しておきます。これは書籍『オブザーバビリティ・エンジニアリング』に書かれているもので、著者らは定義を次のように考えているようです。[*2]「オブザーバビリティ」とは、システムがどのような状態になったとしても、それがどんなに斬新で奇妙なものであっても、どれだけ理解し説明できるかを示す尺度です。そのような斬新で奇妙な状態に対しても、事前にデバッグの必要性を定義したり予測したりすることなく、システムの状態データのあらゆるディメンションやそれらの組み合わせについてアドホックに調査し、よりデバッグ可能であるようにする必要があります。新しいコードをデプロイする必要がなく、どんな斬新で奇妙な状態でも理解できるなら、オブザーバビリティがあると言えます。この定義では、「新しいコードをデプロイする必要がなく」という部分が肝になると思いました。本番で障害が起き、それがどうやら再現可能だということがわかると、時々ログを仕込んだモジュールを本番に再びデプロイして、そのログの状況を見るという対応を取ることがあると思います。この定義によれば(おそらくは)それが必要な時点で、オブザーバビリティがない状態であると言えるのだと思います。オブザーバビリティのあるシステムであれば、すでに出力されているトレーシングログの状況やモニタリングダッシュボード上に表示された状況を見るだけで、システムに何が起きていて、その原因がなんだったのかわかるというわけです。本番環境で原因のわかりにくい事象に直面し、何度もデバッグログを仕込んでやっとの思いで解決した経験があるエンジニアであれば、とても理想的な話のように映るかもしれません。テレメトリオブザーバビリティというのは目標ないしは、思想・概念に近いものだと思いますが、これを向上させるための手段として議論にあがるのが、テレメトリと呼ばれるものです。[*3]NewRelic社の解説記事上で登場したような、3つの柱として紹介されることが多いように思われます。CPU使用率ならそれを、秒単位などで定期的に取得する。何が起きているのかを知ることができる。原因にたどり着くための処理プロセスを可視化したもの。どこで問題が起きたかを知ることができる。アプリケーションなどから出力されるテキスト情報。何が起きたのかを知ることができる。構造化ログさて、定義はいくつかあるオブザーバビリティですが、肝となるのは「何が起きたのか」や「なぜ起きているのか」を検出できることです。それを可能にする手段としてテレメトリが位置付けられていたわけです。テレメトリの核を担う手段として、「構造化ログ」と呼ばれるものがあります。構造化ログは、従来のロギングとはまた異なるロギングの手法です。従来の人間が読みやすいロギングは非構造化ログと呼ばれますが、このロギングの仕方では、機械的に集計をかけてたとえばグラフなどに指標を表示させるのが難しいという課題がありました。従来のログは少なくとも人間が読んでその場でアプリケーション内部で何が起きているかを想像することを目的としていたためこれで十分だったわけですが、そうなると調査可能な範囲はその場にいる人間の目で追える範囲、となってしまいます。なるとたとえば、現代のアプリケーションでよくあるような複雑化した分散システムのログを追うのが非常に難しくなるなどの課題が出てくることになりました。構造化ログは機械による集計を前提として整理されたログです。調査担当者が見たい観点でクエリをかけてビューワーなどでログ内に含まれる指標の情報を閲覧し、そこから洞察を得ることを目的としています。構造化ログを知るには実際のログを見てしまった方が早いと思います。実際のログのイメージは下記です。access"...要するに、ログ内のプロパティないしはフィールドが所定の形式で定義されており、たとえばgrepなどでキーワードを拾って検索をかけると効率よくログを絞り込める状態になっている状態のログのことを指します。人間にとっては多少見にくいかもしれませんが、機械が読み取る際にはとても効率のよい形になっています。ログの形式として最もよく見るのはJSONでしょうか。その他の候補として、スペース区切りでkey=valueで値を並べるlogfmtという形式[*4]や、タブ区切りでkey:valueで値を並べるLTSVという形式[*5]があがることも多いようです。このようにデータを任意の方法で紹介できるようにし、システムの内部状態を理解することこそがオブザーバビリティのゴールであると言えます。ここからは、この構造化ログをRust製のアプリケーションで出力するための手段として、tracingクレートを紹介します。tracingクレートを実際に利用しながら、実アプリケーションに組み込む際に利用できるTipsについても簡単に紹介します。tracingを使う少し話が脱線しましたが、ここからは具体的なtracingクレートの使い方に移ります。核となる概念を掴むtracingクレートには、核となる概念が3つあります。イベント(Event)、スパン(Span)、サブスクライバ(Subscriber)です。スパンは、ある期間内で起きたことを記録します。アプリケーションを起動するとひとつのスパンに入りますし、また自身で新しいスパンを生成し、それを利用することもできます。イベントは、その時点での出来事を指します。イメージとしては通常のロギングとそんなに大差ないかもしれません。あるスパンの範囲内に起きた出来事を示すよう、紐付けすることができます。サブスクライバは、アプリケーションを実行している最中に発生したスパンやイベントのログを収集するために使用されます。あるスパンに入ったり出たり、あるいはイベントが発生した際にサブスクライバのメソッドが呼び出され、記録されます。tracingクレートを使用しているときはとくに、自分が今スパンをはじめているのか、イベントを発行しているのかを意識するとオブザーバビリティ向上に貢献できるはずです。本記事でもこうした区別を大事にしながら解説を進めます。スパン、イベント、サブスクライバを使ってみるそれではこれらの概念を利用して、簡単な実装例を示してみます。呼び出されると5秒処理がかかることを模した関数を呼び出す流れの中で、スパンとイベントを使って実際にどのようなログが出力されるのかを確認します。トレーシングログの出力設定を行っている。`.json`を呼び出すと、一旦JSON形式で出力できるようになる。info_span!を使って、スパンを作成している。このクロージャー内に含まれる処理はすべて、このスパンに入れられる。});}このコードを実行すると、たとえば次のようなログ出力結果を得ることができます。tracing::info!マクロが呼び出されたタイミングでログが出力されます。これがイベントにあたります。server"},"target":"tracing","filename":"src/bin/tracing.rs","line_number":20,"span":{"name":"main"},"spans":[{"name":"main"}]}出力されるログは、人間にとっては多少読みにくいかもしれません。jqなどのコマンドを使ってパースすると驚くほど読みやすくなります。人間向きではありませんが、機械が解析するには読みやすいように作られています。どのスパンから発行されたか(spanフィールドの情報)とどのスパンに紐づいているか(spansフィールド)も情報として残されています。設定としてwith_line_numberとwith_fileをそれぞれtrueとしているため、どのファイルのどの行に書かれたコードに関連するログかというのも、ログを見ただけでわかるようになっています。注意点ですが、スパンを切っただけでは(コード内ではinfo_span!を呼び出しただけでは)ログを出力することはありません。言うなれば、スパンは概念です。実際にログが出力されるのはイベントが発行されてから(info!)です。スパンはイベントに紐づけられることによってはじめて、私たちが確認できる形で目の前に現れます。実際のWebアプリケーションで使用する簡易的なプログラムで紹介してきましたが、たとえばaxumなどのHTTPサーバーに組み込む場合にはどうしたらよいのでしょうか。これを簡単に確認します。下記は、リクエストが送られてくると、そのリクエストの内容をおうむ返しするエンドポイントを用意したサンプルコードです。所定の形式でJSONをリクエストボディに含むリクエストを送信すると、その内容をそのままレスポンスとして返すものを実装しています。返す過程で擬似的なバリデーションチェックを用意しており、条件を満たさないとエラーとしてレスポンスが返されます。その過程で、いくつかログを出力するようになっています。トレーシングログの出力設定を行っている。`.json`を呼び出すと、一旦JSON形式で出力できるようになる。ユーザー作成を想定したモックのエンドポイント。させるようにしている。推奨されている(もしくは、tracing::Instrumentトレイトの使用が必要)。`res.entity`のようにすると、いわゆるフィールドを設定できる。これらは、分散トレーシングのツールで確認したり検索をかけるさいに便利である。`?user`で、`std::fmt::Debug`の出力結果をログに残せる。詳しい省略記法は`tracing`のドキュメントを参照のこと。同様に、`err.kind`と`err.message`というディメンジョンを設定している。`%err`のようにすると、`std::fmt::Display`の出力結果をログに残せる。Err("ユーザー名が短すぎます。4文字以上に設定してください。String,}tracingには、関数に対して指定できる#[tracing::instrument]というマクロがあります。これはスパンを扱うマクロです。関数にアトリビュートをつけておくと、裏でスパンに入るための処理を自動でつけ、関数全体をひとつのスパンとすることができるようになります。非同期処理版の場合の注意点ですが、非同期関数のスパンにはこのtracing::instrumentマクロか、もしくはtracing::Instrumentトレイトを使用する必要があります。Span::enterなどでスパンに一度入った際、awaitを跨いでenter用のガードを持たせると正しくないトレースを吐くことがあるようです。tracing::Instrumentトレイトを使う場合は、これをuseしておくと、たとえばFutureにinstrumentというメソッドが生えてきます。実際のログは下記のように出力されます。}","name":"create_user"}]}{"timestamp":"2024-03-28T07:03:45.686050Z","level":"ERROR","fields":{"error.kind":"validation","error.message":"ユーザー名が短すぎます。3文字以上に設定してください。}","name":"create_user"}]}Tipsフィールドの設定ロギングの際「フィールド」を設定できるという点と、非構造化ログと構造化ログの出力の切り替えに関するTipsを最後に紹介します。ログの出力時に使えるTipsとして、このロギングにはいわゆる「フィールド」を設定できるという点が挙げられます。今回実装したHTTPサーバー版のログは実は、次のような実装が含まれています。`res.entity`のようにすると、いわゆるフィールドを設定できる。これらは、分散トレーシングのツールで確認したり検索をかけるさいに便利である。`?user`で、`std::fmt::Debug`の出力結果をログに残せる。詳しい省略記法は`tracing`のドキュメントを参照のこと。同様に、`err.kind`と`err.message`というディメンジョンを設定している。`%err`のようにすると、`std::fmt::Display`の出力結果をログに残せる。}コメントの通りではあるのですが、response.body、error.kind、error.messageのようにフィールドを指定しています。後ろの?userや%errは、それぞれDebugでの出力ないしはDisplayを利用した出力の省略記法です。フィールドをつけてロギングの内容を整理しておくと、フィールド名を辿ってログに対するフィルターをかけることができ便利です。意外と見落とされがちなテクニックだと思うので、ぜひ活用してみるとよいと思います。詳しい実装方法はドキュメントのこの部分に記載されています。ちなみにですが、ここには任意のフィールドを設定可能です。フィールドの命名方法ですが、おそらくプロダクト全体を通してルール付けして統一しておいた方がわかりやすいと思います。マクロの独自記法を利用させていると、どうしても微妙なブレが出てきてしまうことが考えられます。この命名のブレはできればなくしておきたいものです。参考になる例として、Pavexというクレートが行なっている設定方法がひとつあげられます。strで定義しています。マクロ側ではこれを次のようなコードと共に呼び出すことができます。この手法を利用すると、プロダクト内で個々のエンジニアが思い思いのフィールド名をつけてしまうという事態を避けることができるはずです。デメリットとしては、少しまどろっこしい書き方が必要になるという点と、?や%などの省略記法は利用できなくなる点でしょうか。Pavexでは、?や%のような独自の記法を利用できなくなる点を補うために、専用の関数を別途用意して対応しています。(下記のコードはPavexのexamplesから引用しています。...構造化ログと非構造化ログの切り替え次は構造化ログの扱いについてです。筆者が開発する際は常に構造化ログを出力しているかというとそうでもなく、たとえばローカルでの起動時(いわゆるデバッグビルド)には非構造化ログを出力しておき、本番環境に移った場合(いわゆるリリースビルド)に構造化ログにしておく、といった切り替えを行なっています。Rustの場合は#[cfg(debug_assertions)]というマクロでデバッグビルドかリリースビルドかは簡単にスイッチングできるので、実装も楽だと思います。次のように実装すると実現できます。app).await.unwrap();}まとめtracingクレートは意外と新規概念が多く、使いこなすまでに結構時間がかかると思います。私が理解に苦労したと感じたポイントを中心にまとめました。多くの現場ではenv_loggerをはじめとする普通のロギングと変わらない使い方をしているところが多そうですが、そうではなくて、本来tracingクレートを使って達成したい目標であるはずのオブザーバビリティの向上のために使えるTipsも紹介しました。最後に、実はペイルドではすでにOpenTelemetryの記事を執筆しており、関連記事として下記をあげておきます。tracing導入の次の一手としてはOpenTelemetry化がありえるわけですが、ペイルドではDatadogの利用でOpenTelemetryを使用しています。https://www.oreilly.co.jp/books/9784814400126/*1:記事内ではにはさらに「イベント」も含めて4つとしているようですが、オブザーバビリティ3本柱がよく紹介される関係で、今回は3つに留めておきます。*2:ところで著者らはこの段落の後で、上述したようなNewRelic社をはじめとしたベンダーの提供する「オブザーバビリティ」の定義は、単にテレメトリと同義であることを主張するだけで、オブザーバビリティの定義それ自体を矮小化している(意訳)という主張をしています。そもそもテレメトリと同義であるとみなす記事を見つけることができず、正直その批判が妥当なものか少し理解しかねています。Whitepaper(https://github.com/cncf/tag-observability/blob/main/whitepaper.md#observability-signals)上ではこの3本柱は「シグナル(Signals)」という用語が使われているようです。一方で「テレメトリ」として紹介している例や記事が多く、一旦テレメトリという用語を採用していますが、これが正しいのかはよくわかっていません。3引用をストックしましたストック一覧を見る閉じる引用するにはまずログインしてくださいログイン閉じる引用をストックできませんでした。再度お試しください閉じる限定公開記事のため引用できません。