3つのPrimary Signalsをどうアプリケーションに実装するか？　Logs、Metrics、Tracesの指針と注意点

可観測性で重要な「エラーハンドリング」

相原魁氏：ようやく本題です。可観測性、3つのPrimary Signalsをどのように現場で使うのか、それらがどんなものなのかを知ったので、最後に、では実際にそれを完璧にアプリケーションに実装するためにはどのようにするべきかという話をしようと思います。

（スライドを示して）いきなり可観測性の話ではなくなりますが、可観測性を語る上で大事なのがエラーハンドリングです。実際にLogsやMetricsはエラーが起きた時にロギングしたり、エラーの数をMetricsとして出力したりするので、エラーを起点とすることが多いです。

そのため、エラーハンドリングの1つ目の指針としてエラーをどう取り扱うかは、呼び出し元に決めることが非常に重要になります。呼び出し元がエラーハンドリングを正しくできないと、ログやMetricsみたいな情報を取得、出力しづらくなるからです。あとは必要なコンテキストを付与することです。

それでは、この指針についてそれぞれ見ていきましょう。先ほど「エラーを受け取ったらただロギングするだけ」みたいな例を挙げましたが、指針では、doSomethingの呼び出し元ではこのエラーをどう取り扱うかがコントロールできません。

このdoSomethingの呼び出し元では、実際にはエラーが起きた時にリトライをしてもう一度やり直したいかもしれないのに、勝手にエラーを握り潰してログに出力しているだけだと、そういうことがコントロールできません。

そもそもエラーを握り潰している場合もそうですし、先ほど話したものは全部そうです。

ではどうするべきかですが、ここで先ほどの指針に従いソースコードを書き直してみます。まず、呼び出し元がそのエラーをどう取り扱うかを決めるためには、エラーを返してあげる必要があります。

（スライドを示して）これはGoの例ですが、Goではそのエラーを返り値として返すことによって、その呼び出し元にエラーを伝播させられるので、まずこうする必要があります。

2番目として、必要なコンテキストを付与するか、どのように実装するべきかは言語ごとに変わってくるのですが、GoやRustのような言語では、そのエラーにコンテキスト情報を付与できるので、そこで実際にどんなリクエストでどんな関数がどのようにしてこけたかのコンテキスト情報を付与した上で、呼び出し元にエラーを返すことが必要です。

例外がある時の対処法

例外がある言語だと少し表現の仕方が変わってしまうので、今から話したいと思います。例外で表現しようと思ったら、独自の例外の型を用意して、その独自の例外の型に返ってきた例外をラップして返すみたいなことをしたり、エラーが発生した時に例外を送出するみたいなことをすると思います。

しかし一般的に言われることとして、例外を乱用してはいけないということがあります。『達人プログラマー』というお薦めの本があって、そこにも書いてあるのですが、例外は言葉のとおりあくまで例外なので、ふだん起こり得るフローでは使ってはいけません。

一般的に言われるのは、バリデーションのエラーです。ユーザーがEメールのパラメータを外から入力できる時に、そのEメールのアドレスとして適切ではない文字列を入れた時に、バリデーションではエラーを返しますが、そういう時に例外を使ってはいけません。なぜなら、ユーザーがEメールアドレスではない文字列を入れることはふだん起こり得るフローだからです。

そこでマーティン・ファウラーは、Notificationパターンを使うべきだと主張しているとか。あと、エラーハンドラという、エラーが起きた時に呼ばれる無名関数かなにかを外から与えられるようにして、例外を使わずともエラーをコントロールできるようにすることが行われています。

そのため、必要なコンテキストを付与するとは言ったものの、例外しかない言語では慎重に設計を考える必要があります。例外はだいたいスタックトレースを持っているので、一般的に例外を生成するコストが高いと言われています。なので、気軽に使うにはちょっとよくないよという話です。

Logsを取得・出力する時の指針

次にLogsを取得・出力する時の指針ですが、第1にユーザーの個人情報みたいな秘匿情報を記録しないことがとても大切になります。なぜなら、先ほど話したように可観測性は、ソースコードに詳しくない人が外部から状況を判断できるために必要なので、当然、可観測性に関するシグナルはすべて、閲覧者は制限なく見ることができる必要があります。

一方で、秘匿情報を記録されてしまうと、偉い人しか見られなくなってしまったり、ログの閲覧者が制限されてしまうので、ログやMetricsみたいなものには、誰かが見られなくなってしまうような秘匿情報を記録しないのが大前提です。

次に、どのイベントにひもづくログであるかを記録することです。最後は、分析しやすいフォーマットにします。これも指針を1つずつ見ていきます。

最初にやりがちなパターンとして、GETのパラメータとしてパスワードの入力を受け取ってしまうことです。これは徳丸先生（徳丸浩氏）の徳丸本（『体系的に学ぶ安全なWebアプリケーションの作り方第2版脆弱性が生まれる原理と対策の実践』）にも書いてありますが、すごくよくない例です。

（スライドを示して）なぜよくないのかというと、このようなパスでリクエストを受けてしまうと、HTTPサーバのアクセスログには、そのままパスワードが記録されてしまうからです。

1文目はURIの一部なので、HTTPのサーバはURIもそのままアクセスログにリンクしてしまい、これで「誰々さんのパスワードが『foobar』である」ということが、ログの閲覧者全員にわかってしまいます。そもそもHTTPのURIに秘匿情報を含めるのはアンチパターンです。

「ではこれを実際どうするべきか」という話は本題とはずれますが、GETの代わりにPOSTを使って、HTTPのボディにパスワードを含めることが対策として考えられます。

ほかには、先ほどバリデーションの話をしたんですけど、ユーザーのような外部から入力を受け付ける時に、それをそのままロギングしないのもとても大事なことです。

先ほどはEメールの例を挙げましたが、例えばユーザーの電話番号を受け取っている場合に、ユーザーの電話番号をバリデーションして、電話番号として正しくないフォーマットであればユーザーにエラーを返すような処理を考えます。

バリデーションにエラーが発生した時に、ユーザーに対して「あなたが入力したパラメータはこうこうこう違いますから直してください」という指示ができるように、どのようにしてバリデーションが失敗したかをロギングしたくなると思います。

ただ、電話番号にハイフンがなかっただけだからバリデーションをしたのに、ハイフンが付いていなかった電話番号をそのままロギングしてしまうと、ログの閲覧者からユーザーの電話番号が丸見えなわけです。なので、こういうこともよくありません。

加えて、先ほど「惜しいところまで行っている」と言った例ですが、エラーを受け取ってそのエラーをスタックトレースつきで出力するのは、一見よくできているのですが問題があります。

（スライドを示して）これは、順番が前後してしまった話ですが、HTTPサーバでは慣例的にRequestIDが付与されていて、このRequestIDを使うことによって、リクエストを一意に識別できるという話をしました。

このRequestIDをログに含めることで、どんなリクエストにひもづいたログなのかを表現できます。これをエラーログやアクセスログの両方に含めておくことによって、仮にこのアクセスログのステータスコードが500でエラーが起きていた場合に、その500になったリクエストにひもづくエラーログをRequestIDから検索することによって、詳細なエラーログにたどり着けます。

そのため、ここでは"%+v"でスタックトレースを出力するのに加えてRequestIDを付与しておくと、アクセスログからその原因をたどりたい時に、RequestIDを使って検索できるということです。

ログの出力元やスタックトレースを含めることも重要で、ソースコードのどこで原因となるイベントが発生したかを調べられるととても便利です。

例えばエラーログ以外のよくある例だと、「どんなファイル名のどの要請でこのログを吐いています」という情報も、ログに出力することによって、実際にバグにつながるようなログだった場合に、そのバグを改修するためにログの閲覧者はそのログがどういう状況で吐かれたのかを判断できる必要があり、その時にファイル名や行数があると便利ですよという話です。

先ほどスタックトレースが話に出てきましたが、スタックトレースは情報量が多く、ログの閲覧者として取れる情報が多い反面、その分データ量も大きくなってしまうので、なんでもかんでもスタックトレースを吐いてしまうと、先ほどから話しているようにログはテキストデータで保存のコストが大きいので、お金がたくさん必要になってしまいます。

そのため、一般にINFO系のログ、ただの閲覧者に対する付加的な情報として吐いているログは大した調査はしないので、そのログを見た後に詳細な調査が必要なエラーに限ってスタックトレースを出力することが多いです。

最後に、分析のしやすいフォーマットにするという指針に関しては、ログはJSONで吐きましょうという話です。主要なLogsのObservabillity Platform、AWSだと「Amazon CloudWatch Logs」というサービスがあるという話を先ほどしました。

そのような主要なLogsを閲覧するプラットフォームは、ソフトウェア側にJSONをパースする機能を備えているので、ログをJSONで吐いておくと分析がしやすいという特徴があります。これは深く考えず、とりあえずJSONで吐いておけばよいと言えます。

実際には、JSON以外にもいろいろなフォーマットがありますが、プラットフォームのサポートが厚いのはJSONなので、とりあえずJSONを使っておくのがよいと思います。

ログレベルは先ほど出てきたINFOなどたくさんあって、例えばエラーに関してもWARN、ERROR、CRITICALという3つのログレベルがあります。

ではこのWARNを無視していいのかというとそういうこともなく、不用意にログレベルを増やしてしまうと、結果無視されるログが増えてしまいます。それは可観測性においてなんの意味も持たないので、最初は少ないログレベルから始めましょうという話をしたかったスライドです。

Metricsの指針の1つ、USEメソッド

次はMetricsの指針です。MetricsにはUSEメソッドとREDメソッドという2つの有名なメソッドがあって、これらに従っておけば十分です。

まずUSEメソッドは、ブレンダン・グレッグというNetflixでシニアパフォーマンスエンジニアをやっている、パフォーマンスエンジニアリング界の偉い人が提唱したMetricsの収集の方法論です。これは、あるリソースに対して使用率、飽和、エラー、それぞれUtilization、Saturations、Errorsを収集すれば十分と主張しています。

それぞれのリソースに対してどんなMetricsを収集するべきかは、USEメソッドの記事に書いてあります。

（スライドを示して）例えば、古典的なTCPサーバで考えた時に、Utilizationは、アクティブなWorkerの数÷すべてのWorkerの数です。例えばこれは3つのWorkerがあって、そのうち2つが使われているので、Utilizationは66パーセントであることを出力すべきだということです。

Saturationsは飽和状態のことで、リクエストがあふれた状態です。TCP（Transmission Control Protocol）サーバは、ソケットのバックログに今からさばかれるリクエストを入れておいて、それをMasterプロセスが一つひとつWorkerに飛ばしていくようなアーキテクチャを取ることがあります。

このバックログに入っている、待っているリクエストの数みたいなものをSaturationsとして表現します。例えばUtilizationが100パーセントでも、待ちのジョブが1個もなければそれは問題ないわけです。Utilizationからだけだと正しく情報を判断できないので、Saturationsも組み合わせて使うというのがUSEメソッドです。

あとはErrorsでいうと、TCPのソケットでは、バックログが全部埋まった場合にECONNREFUSEDというエラーのシグナルが返るのですが、その数を数えておいてMetricsとして出力することで、実際にユーザーがどのくらいリクエストに失敗したのかを取れます。

（スライドを示して）これがそのUSEメソッドの記事にある、あるリソースに問題がありそうな時にどのように調査すべきかというフローチャートです。エラーが出力されているのであれば問題なので調査すべきだし、エラーがないのであれば今度はUtilizationにあたりをつけてというように調査していくフローチャートになっているので、調査の時にはこちらを活用してください。

REDメソッド

USEメソッドはリソース単位の監視であったことに対して、REDメソッドが主眼を置いているのは、サービス単位の監視になります。実際にこのREDメソッドが提案された時の文章には、request-drivenのサービス、つまりHTTPサーバみたいなリクエストを受け付けるサービスで有効なものと言われていて、これらはRate、Errors、Durationという3つのMetricsを収集することが推奨されています。

（スライドを示して）検索エンジンで考えてもらえばこんな感じです。リクエストの秒間リクエスト数と、レスポンスのエラー数、レスポンスのレイテンシを収集するとよいと言われています。

先ほど見たログで実行時間を計測する例ですが、この手のものはMetricsとして管理することでコストを安くできます。

出力の方法としては、先ほども話したOpenMetricsの形式での出力が必要になっています。それにはアプリケーションがそのまま出力するパターンと、アプリケーションが吐いたなにかをエージェントがOpenMetricsの形式で出力するパターンがあります。

アプリケーションに組み込む場合は、Prometheusにはクライアントライブラリがあって、クライアントライブラリを使うと、アプリケーションがPrometheus形式のMetricsを吐けるようになるので、そのようにして出力することが多いです。

USEメソッドやREDメソッドに従うメリット

（スライドを示して）こういったUSEメソッドやREDメソッドに従うことのメリットですが、Metricsは収集した後、先ほどお話ししたアラートで監視やダッシュボード上で可視化をするわけですが、そういった処理を共通化させやすい点があります。

実際に私が作っている可観測性のプラットフォーム（Observabillity Platform）ではダッシュボードをいろいろ提供していて、非常に多くのメトリクスを可視化しています。

すべてのアプリケーションで同じメソッドに従ってMetricsを収集しているので、アプリケーションの開発者は特に設定することなく、自分のアプリケーションに対してこのようなダッシュボードを手に入れられます。

（スライドを示して）これは監視の項目で、これもすべてのアプリケーションで同じメソッドに従っているから、流用が可能となっています。

これは、レスポンスタイムのダッシュボードです。

Tracesの指針

最後に、Tracesの指針ですが、これは非常に簡単で、OpenTelemetryを使っておくだけで済みます。

OpenTelemetryは先ほども話したものですが、もともとOpenCensusは、TracesやMetricsの収集を補助するライブラリですが、OpenTelemetryになってからもそれは引き続き各言語向きにライブラリを提供することは続けられていて、実際GoやJavaなど、いろいろな言語で提供されています。

このOpenTelemetryのSDKの機能を使うと、Metricsとトレースを出力する機能があったり、先ほど紹介をしたPrometheusのクライアントライブラリは、OpenTelemetryを使う場合は必要ありません。

あとは、各種クライアントに対して自動で気の利いたMetricsやトレースを収集してくれる機能があるので、とりあえずこれを入れておくだけで、HTTPのクライアントから外部のサービスにリクエストする時のMetricsの収集が済みます。

これは最終的にはログの標準化まで見据えているようなので、将来的には「何も考えず、OpenTelemetryにSDKを入れておくだけで十分」という世界観が実現される可能性があります。

先ほどRequestIDを含める話をしましたが、このOpenTelemetryを導入すると、いちいちRequestIDをどこかから引っ張ってこなくても、trace-idを代わりに利用できます。

OpenTelemetryは、先ほど少し話したW3C Trace Contextという仕様に基づいてサービス間でトレースの情報を引き回しているのですが、それを引き回すこともOpenTelemetryのSDKを入れることによって自動的にやってくれるようになるのが、自動Propagationの機能です。

これを使うと、RequestIDの代わりに使える新たなIDが手に入るので、これを使うことで同じような効果を得られます。

まとめると、エラーハンドリングをするにあたっては、エラーをどう取り扱うかは呼び出し元に決めさせることが非常に重要です。Logs（に大切なの）は、個人情報を含めないこと、どのイベントにひもづくログであるかを記録すること、分析のしやすいフォーマットにすることです。Metricsは2つのメソッドに従ってください。TracesはとりあえずOpenTelemetryを使っておくだけで十分です。