OpenTelemetryを使って初めてその便利さに気づいた話

この記事は「OpenTelemetry Advent Calendar 2023」の20日目の記事です。

はじめに

先日、ローカル環境でではありますがOpenTelemetryを実際にアプリケーションに組み込んで使ってみました。
OpenTelemetry自体は前から知っていたのですが、実際にアプリケーションで使ったのは初めてです。
実際に使ってみるまでは、OpenTelemetryについては

トレースちゃんと見られると便利そうだよね
とはいえOpenTelemetryってパフォーマンス改善のときに役立つんでしょ?
普段の運用ならメトリクスとログが見えていればトレースはなくてもなんとかなるんじゃない? ログ見ればエラーの原因とか分かるし

と思っていました。
しかし、実際に使ってみると「OpenTelemetry、運用だけじゃなくて開発のフェーズでも役立つじゃん!!」と思ったので、その経緯などを書いてみようと思います。

OpenTelemetryを使ってみた

以下のようなサンプルアプリを元に説明します。

github.com

構成としてはマイクロサービスっぽい作りになっており、React製のフロントエンドのWebアプリからgatewayにHTTPリクエストを送り、内部で別のサービスを呼び出していくという構成です。

実際に試したときは業務で開発しているシステムでやってみたのですが、それをそのまま出すわけには行かないので説明用の簡単なアプリケーションを作りました。

コード自体はシンプルで、HTTPのAPIが一個だけあり、そこにリクエストを送るとダミーのレスポンスが返るようになっています。
OpenTelemetry関連のコードも、基本的にはドキュメントに書かれているものを流用しています。

トレースの情報は、Dockerで建てたJaegerのコンテナに送っています。
ブラウザからJaegerに直接トレースのデータを送る際は、Jaegerの起動オプションとして --collector.otlp.http.cors.allowed-origins='*' と --collector.otlp.http.cors.allowed-headers='*' を追加してCORSの制約を解除する必要があります。
本来は * ではなく、適切な値を設定するのが望ましいかと思います。
また、ちゃんと動かすのであればJaegerに直接データを送るのではなく、OpenTelemetry Collectorを間に挟み、さらにブラウザとCollctorの間にNginxなどのリバースプロキシを挟む方が良いです。
これは、OpenTelementryのドキュメントにも記載されています。

opentelemetry.io

動かしてみた

作ったアプリケーションを動かしたところ、エラーのレスポンスが返されました。
普段であれば、サーバーのログを目grepして原因を調べることが多いのですが、今回はJaegerのUIからトレースのデータを見てみました。
エラーになったリクエストのトレースのデータを見ると、以下の画像のようになっていました。

service-bの処理でエラーになっていることが一発で分かります。
さらにエラーになった処理の詳細を開いてみると、以下の画像のようになっていました。

エラーの内容から、service-bからservice-cにリクエストを送る際に名前解決がIPv6で行われたことが分かります。
service-cはIPv4でしかリクエストを受け付けていないので、名前解決後に接続を試みて接続できなかったということが分かりました。

ちなみにこの挙動は、Node.js 17から --dns-result-order オプションのデフォルト値が verbatim に変わったことで、DNSリゾルバが返した順序をそのまま使うようになった事によるものです。

github.com

IPv6のアドレスがIPv4よりも先に来た場合に、使われるIPアドレスがIPv6のものとなり、今回のような挙動となります。
Node.js v19.3.0から追加された `autoSelectFamily` オプション(デフォルト値: true )を使えば、IPv4とIPv6それぞれで解決されたIPアドレスに対して接続を試み、接続できた場合にそれを採用する。という挙動になります。
github.com

動かしてみて気付いたこと

感覚ではありますが、ログを調べて原因を調査するよりも、何倍も早く原因の特定ができたように思います。
その理由について深掘りしてみると、「ログがhuman readableではない」ことが原因のように思います。
昨今のアプリケーションログは構造化ログであるケースが多く、目grepをする際は適切にパースして必要な情報を拾っていく必要があります。
特にエラー発生時のスタックトレースなどは、複数行で表示しないと分かりづらいように思います。

一方トレースのデータは、Jaegerなどのソフトウェアで容易に可視化ができ、どこまで正常に動いてどこでエラーが起きたのかを直感的に表示できるため、ログから調査するよりも素早い調査ができるのではないかと思います。
また、エラーになった箇所の情報と実際のエラーの情報がリンクしているため、どこをどう直せばよいのかもすぐに分かります。

このように、ローカル環境でアプリケーションの開発を行う場合であってもOpenTelemetryの計装を行いトレースのデータを記録することで、開発をより効率的に行えるようになると感じました。