各RailsアプリにOpenTelemetryを組み込み、収集したデータをJaegerで表示してみた

最近「オブザーバビリティ(Observability)」が気になっていたので、オライリーの「オブザーバビリティ・エンジニアリング」を読みました。
O'Reilly Japan - オブザーバビリティ・エンジニアリング

　
その本の7章ではOpenTelemetryが紹介されていました。

OpenTelemetryの公式サイトを見ると、

OpenTelemetry is a collection of tools, APIs, and SDKs. Use it to instrument, generate, collect, and export telemetry data (metrics, logs, and traces) to help you analyze your software’s performance and behavior.

https://opentelemetry.io/

とあり、気になりました。

そこで、各RailsアプリにOpenTelemetryを組み込んでみたときのメモを残します。

　
目次

環境

• Rails 7.0.5
• opentelemetry-sdk 1.2
• opentelemetry-instrumentation-all 0.39.1
• opentelemetry-exporter-otlp 0.25.0
• Jaeger 1.46.0

　
今回は、1つのRailsアプリにOpenTelemetryを組み込み、収集したデータをコンソールへ出力するところからはじめます。

最終的には、Railsで2つのアプリ (parent_app と child_app)にそれぞれOpenTelemetryを組み込み、Jaegerで収集したデータを表示するところまでためします。

なお、今回の2つのRailsアプリはともにAPIモードで rails new したものを使います。

また、ざっくりとした全体図は以下のとおりです。

┌─────────┐        ┌──────────────┐      ┌──────────────┐
│ Browser │        │ parent_app   ├─────►│ child_app    │
│         ├───────►│              │      │              │
└─────────┘        │              │◄─────┤              │
                   └───────┬──────┘      └───────┬──────┘
                           │                     │
                           │                     │
                           │                     │
                           │      ┌───────┐      │
                           │      │       │      │
                           └─────►│Jaeger │◄─────┘
                                  │       │
                                  └───────┘

　
ちなみに、OpenTelemetryの各機能に関する言語ごとの状況は以下にありました。RubyだとTracesのみStable、あとは未実装のようです。
Instrumentation | OpenTelemetry

1つのRailsアプリにOpenTelemetryを組み込む

OpenTelemetryの公式ドキュメントを読んだところ、まずはRubyの Automatic instrumentation に沿って試してみるのが良さそうでした。
Automatic instrumentation | OpenTelemetry

Railsアプリを作成

はじめに、APIモードで rails new します。

続いて、必要なgemをGemfileへ追加します。コンソールに出力する場合は以下の2つのgemを追加すれば良さそうでした。

gem "opentelemetry-sdk", "~> 1.2"
gem "opentelemetry-instrumentation-all", "~> 0.39.1"

Gemfileに追加したら、 bundle install しておきます。

OpenTelemetryの設定ファイルを追加

次に、 config/initializers/opentelemetry.rb ファイルを作成し、OpenTelemetry用の設定を追加します。なお、今回はためすだけなので、

• service_name は適当な名前 (parent_app)
• use_all ですべてのinstrumentationを使う

とします。

また、以下の公式ドキュメントによると、収集したデータをコンソールへ出力する場合は、環境変数 OTEL_TRACES_EXPORTER を設定しておけば良さそうでした。今回はためすだけなので、設定ファイルに記載してしまいます。
Run the instrumented app | Getting Started | OpenTelemetry

なお、公式ドキュメントの環境変数 OTEL_TRACES_EXPORTER の説明には console の記載はなかったため、Ruby版だけで使えるものかもしれません。
Environment Variable Specification | OpenTelemetry

　
設定ファイルの全体像はこんな感じです。

config/initializers/opentelemetry.rb

# 収集したデータをコンソールへ出力する
ENV['OTEL_TRACES_EXPORTER'] = 'console'

# OpenTelemetryの設定
OpenTelemetry::SDK.configure do |c|
  c.service_name = 'parent_app' # 適当な名前
  c.use_all() # enables all instrumentation!
end

コントローラとルーティングを追加

コントローラではJSONを返します。

hello_controller.rb

class HelloController < ApplicationController
  def index
    render json: {message: 'hello'}
  end
end

コントローラを元にルーティングを作成します。

なお、後でリソースベースではないルーティングを追加することから、 get な書き方にしています。

routes.rb

Rails.application.routes.draw do
  get '/hello',  to: 'hello#index'
end

動作確認

これでアプリが完成したので、作成したRailsアプリを起動します。なお、後でRailsアプリを追加するため、ポートは 9000 にしておきます。

　
curlで動作確認をすると、レスポンスがありました。

$ curl http://localhost:9000/hello

{"message":"hello"}

　
また、コンソールにも収集したデータが出力されていました。

#<struct OpenTelemetry::SDK::Trace::SpanData 
  name="HelloController#index", 
  kind=:server,
  status=#<OpenTelemetry::Trace::Status:0x00007f5eb5e16250 @code=1, @description="">,
  parent_span_id="\x00\x00\x00\x00\x00\x00\x00\x00",
  total_recorded_attributes=8, 
  total_recorded_events=0, 
  total_recorded_links=0, 
  start_timestamp=1687597098836007785, 
  end_timestamp=1687597098965513677, 
  attributes={
    "http.method"=>"GET", 
    "http.host"=>"localhost:3000", 
    "http.scheme"=>"http", 
    "http.target"=>"/hello", 
    "http.user_agent"=>"curl/7.81.0", 
    "code.namespace"=>"HelloController", 
    "code.function"=>"index", 
    "http.status_code"=>200
  }, 
  links=nil, 
  events=nil, 
  resource=#<OpenTelemetry::SDK::Resources::Resource:0x00007f5eb74a8658 
    @attributes={
      "service.name"=>"parent_app", 
      "process.pid"=>1050472, 
      "process.command"=>"/path/to/parent_app/bin/rails", 
      "process.runtime.name"=>"ruby", 
      "process.runtime.version"=>"3.2.2", 
      "process.runtime.description"=>"ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-linux]", 
      "telemetry.sdk.name"=>"opentelemetry", 
      "telemetry.sdk.language"=>"ruby", 
      "telemetry.sdk.version"=>"1.2.1"
    }>, 
    instrumentation_scope=#<struct OpenTelemetry::SDK::InstrumentationScope 
      name="OpenTelemetry::Instrumentation::Rack",
      version="0.23.2">, 
    span_id="I\xBC\xFB#\xEA\xC7u\xD8",
    trace_id="^\xF3Z\x0E`\x04\xCC\xCB\xC9\x99\x83\xB8\x12\t3\xCD", 
    trace_flags=#<OpenTelemetry::Trace::TraceFlags:0x00007f5eb5e6e360 @flags=1>, 
    tracestate=#<OpenTelemetry::Trace::Tracestate:0x00007f5eb5e6d050 @hash={}>>

連携する各RailsアプリにOpenTelemetryを組み込む

続いて、連携する各RailsアプリにOpenTelemetryを組み込んでみます。

なお、連携したときに取得できるデータは

• trace_id は同じ
• span_id は別

となる想定です。

連携先のRailsアプリを作成

まず、連携先のRailsアプリである child_app をAPIモードで rails new します。

続いて、 config/initializers/opentelemetry.rb を作成します。 service_name 以外は parent_app と同じとします。

# 収集したデータをコンソールへ出力する
ENV['OTEL_TRACES_EXPORTER'] = 'console'

# OpenTelemetryの設定
OpenTelemetry::SDK.configure do |c|
  c.service_name = 'child_app' # 適当な名前
  c.use_all() # enables all instrumentation!
end

　
そして、コントローラとルーティングを作成します。

messages_controller.rb

class MessagesController < ApplicationController
  def index
    render json: {message: 'Hi from child'}
  end
end

　
routes.rb

Rails.application.routes.draw do
  resources :messages, only: %i[index]
end

Ruby版での、Context Propagation設定について

parent_app と child_app で同じ trace_id を使う場合、 Context Propagationという仕組みを使って trace_id を連携先に渡す必要があります。
Context Propagation | Overview | OpenTelemetry

trace_id を渡す方法としてはいくつかあるようでした。
Propagators Distribution | Propagators API | OpenTelemetry

　
Ruby版ではどうすればよいのかを見たところ、

The OpenTelemetry Ruby SDK will take care of context propagation as long as your service is leveraging auto-instrumented libraries.

https://opentelemetry.io/docs/instrumentation/ruby/manual/#context-propagation

とのことでした。

また、その値はどこに設定されるかというと

In order to propagate trace context over the wire, a propagator must be registered with the OpenTelemetry SDK. The W3 TraceContext and Baggage propagators are configured by default

https://opentelemetry.io/docs/instrumentation/ruby/manual/#context-propagation

のようで、デフォルトではHTTPリクエストヘッダの traceparent に自動で設定されそうです。

　
そこで、traceparent をもらう側である child_app でHTTPリクエストヘッダの中身をコンソール出力し、自動的に設定されているかを確認します。

今回は application_controller.rb にログ出力処理を追加します。
参考：Rails でリクエストの HTTP ヘッダを取得してログに出力する - xyk blog

class ApplicationController < ActionController::API
  before_action :log_http_headers
  before_action :log_all_http_headers

  private def log_http_headers
    logger.info('traceparent header ===============>')
    logger.info(request.headers['HTTP_TRACEPARENT'])
    logger.info('traceparent header <===============')
  end

  private def log_all_http_headers
    logger.info('all request header ===============>')
    request.headers.sort.map { |k, v| logger.info "#{k}:#{v}" }
    logger.info('all request header <===============')
  end
end

parent_appからchild_appへ、Faradayを使って連携する

残すは、 parent_app から child_app へHTTPリクエストを飛ばすところです。

今回は Faraday gemを使って、連携処理を実装します。
lostisland/faraday: Simple, but flexible HTTP client library, with support for multiple backends.

　
parent_appのGemfileに faraday を追加し、bundle install します。

gem 'faraday'

　
今回はデモ的なアプリのため、 parent_app のコントローラにてFaradayを使った連携処理を実装してしまいます。

class HelloController < ApplicationController
  def message_from_child
    response = Faraday.get('http://localhost:9001/messages')
    render json: {message: response.body}
  end
end

　
ルーティングも追加します。

Rails.application.routes.draw do
  get '/message_from_child',  to: 'hello#message_from_child'
end

動作確認

以上で準備ができたため、 parent_app を9000ポートで、 child_app を9001ポートでそれぞれ起動します。

curlで動作確認すると、連携した結果が返ってきました。

$ curl http://localhost:9000/message_from_child

{"message":"{\"message\":\"Hi from child\"}"}

　
parent_app ではOpenTelemetryによりコンソールへ4件出力されていました。気になるところだけ抜粋します。

#<struct OpenTelemetry::SDK::Trace::SpanData 
  name="connect",
  kind=:internal, 
  parent_span_id="-3\xEE\x9CL\xE3\x10\xB9", 
  start_timestamp=1687670979094625151, 
  end_timestamp=1687670979095422757,
  attributes={"net.peer.name"=>"localhost", "net.peer.port"=>9001},
  span_id="&)8Om\x0Ft\xD1", 
  trace_id="\xC0H\xF1\xDBW%\x87p_\xC5\xD4\x1F\x15\x7FX\x8F", ...

#<struct OpenTelemetry::SDK::Trace::SpanData 
  name="HTTP GET", 
  kind=:client, 
  parent_span_id="-3\xEE\x9CL\xE3\x10\xB9",
  start_timestamp=1687670979097511327, 
  end_timestamp=1687670979195886262,
  attributes={"http.method"=>"GET", "http.scheme"=>"http", "http.target"=>"/messages", "net.peer.name"=>"localhost", "net.peer.port"=>9001, "http.status_code"=>200},
  span_id="\x9F\x18\xEC\x85Z\xCC\x15\xC7",
  trace_id="\xC0H\xF1\xDBW%\x87p_\xC5\xD4\x1F\x15\x7FX\x8F", ...

#<struct OpenTelemetry::SDK::Trace::SpanData 
  name="HTTP GET",
  kind=:client,
  parent_span_id="'\xB1-RT\xBA\xB0\xB8", 
  start_timestamp=1687670979094368383, 
  end_timestamp=1687670979198343682,
  attributes={"http.method"=>"GET", "http.url"=>"http://localhost:9001/messages", "net.peer.name"=>"localhost", "http.status_code"=>200},span_id="-3\xEE\x9CL\xE3\x10\xB9", 
  trace_id="\xC0H\xF1\xDBW%\x87p_\xC5\xD4\x1F\x15\x7FX\x8F", ...

#<struct OpenTelemetry::SDK::Trace::SpanData 
  name="HelloController#message_from_child", 
  kind=:server, 
  parent_span_id="\x00\x00\x00\x00\x00\x00\x00\x00", 
  start_timestamp=1687670979019617738, 
  end_timestamp=1687670979200919667,
  attributes={"http.method"=>"GET", "http.host"=>"localhost:9000", "http.scheme"=>"http", "http.target"=>"/message_from_child", "http.user_agent"=>"curl/7.81.0", "code.namespace"=>"HelloController", "code.function"=>"message_from_child", "http.status_code"=>200},
  span_id="'\xB1-RT\xBA\xB0\xB8", 
  trace_id="\xC0H\xF1\xDBW%\x87p_\xC5\xD4\x1F\x15\x7FX\x8F", ...

　
一方、 child_app では、HTTPリクエストヘッダとOpenTelemetryのデータが出力されていました。

traceparent header ===============>
00-c048f1db572587705fc5d41f157f588f-9f18ec855acc15c7-01
traceparent header <===============
all request header ===============>
GATEWAY_INTERFACE:CGI/1.2
HTTP_ACCEPT:*/*
HTTP_ACCEPT_ENCODING:gzip;q=1.0,deflate;q=0.6,identity;q=0.3
HTTP_HOST:localhost:9001
HTTP_TRACEPARENT:00-c048f1db572587705fc5d41f157f588f-9f18ec855acc15c7-01
HTTP_USER_AGENT:Faraday v2.7.7
HTTP_VERSION:HTTP/1.1
...
#<struct OpenTelemetry::SDK::Trace::SpanData name="MessagesController#index", kind=:server, 
parent_span_id="\x9F\x18\xEC\x85Z\xCC\x15\xC7",
start_timestamp=1687670979102702979, 
end_timestamp=1687670979192294516, 
attributes={"http.method"=>"GET", "http.host"=>"localhost:9001", "http.scheme"=>"http", "http.target"=>"/messages", "http.user_agent"=>"Faraday v2.7.7", "code.namespace"=>"MessagesController", "code.function"=>"index", "http.status_code"=>200},
span_id="\xFF\xAEW'\xC8s*\xE2",
trace_id="\xC0H\xF1\xDBW%\x87p_\xC5\xD4\x1F\x15\x7FX\x8F", ...

　
上記より、

• trace_id は \xC0H\xF1\xDBW%\x87p_\xC5\xD4\x1F\x15\x7FX\x8F で同じ
• span_id はそれぞれ違う

となっており、想定通りでした。

Jaegerで収集したデータを表示する

ここまではOpenTelemetryで収集したデータをコンソールへ出力していました。

ただ、それだと正しく収集できているかわかりづらいため、OpenTelemetryで収集したデータを何かに渡して表示してみます。

公式ドキュメントによると、表示するための方法として

• OpenTelemetry controllerを介して渡す
• Jaegerなどのツールへ直接渡す

があるようでした。
OTLP endpoint | Exporters | OpenTelemetry

今回は、お手軽そうな、Jaegerへ直接データを渡して表示する方法をためしてみます。

Jaegerの準備

Jaegerの準備について、今回はオールインワンのDockerイメージを使うことにします。
Getting Started — Jaeger documentation

また、Docker Composeを使ってJaegerを起動します。

なお、Jaegerの公式ドキュメントに従い、

• ポート 16686
  • JaegerのUI表示用
• ポート 4318
  • OpenTelemetry連携用

のポートを開けておきます。

　
Docker ComposeがV2になったので、 compose.yaml ファイルに内容を記載していきます。
Docker Compose V2で変わったdocker-compose.ymlの書き方

services:
  jaeger:
    image: jaegertracing/all-in-one:1.46
    ports:
      - "16686:16686"
      - "4318:4318"

　
準備ができたら起動しておきます。

$ docker compose up -d

Railsアプリの修正

今までコンソールへ出力していたため、設定を変更します。

parent_app と child_app ともに、 ENV['OTEL_TRACES_EXPORTER'] = 'console' をコメントアウトします。

# 以下の行をコメントアウトするだけ
# ENV['OTEL_TRACES_EXPORTER'] = 'console'

OpenTelemetry::SDK.configure do |c|
  c.service_name = 'child_app'
  c.use_all() # enables all instrumentation!
end

　
また、Jaegerへ連携できるよう、gem opentelemetry-exporter-otlp をGemfileへ追加し、bundle install しておきます。

動作確認

curlで2つのRailsアプリが連携するエンドポイントへリクエストを飛ばすと、レスポンスが返ってきました。

$ curl http://localhost:9000/message_from_child

{"message":"{\"message\":\"Hi from child\"}"}t

　
続いて、Jaeger UIへアクセスします。
http://localhost:16686/

Searchの Service で parent_app を選択し、 Find Trace ボタンを押すと、トレースの一覧が表示されます。

　
トレースをクリックすると、詳細が表示されました。Jaegerへのデータの連携ができているようです。

ActiveJobで連携したときの収集データをJaegerで表示する

ここまでは同期的な連携についてOpenTelemetryで見てきました。

次はActiveJobを使った非同期連携の場合にはどのように表示されるか見ていきます。

child_appに非同期連携用エンドポイントを作成

コントローラに create メソッドを追加します。

また、リクエストパラメータを正しく受け取れているか確認するため、ログに内容を出力します。

class MessagesController < ApplicationController
  def create
    message = params[:message]

    logger.info('=== start ===============>')
    logger.info(message)
    logger.info('<== end   ================')
  end
end

　
ルーティングも追加します。

Rails.application.routes.draw do
  resources :messages, only: %i[index create]
end

parent_appにActiveJobとそれを起動するエンドポイントを追加

まずはActiveJobから追加します。

ジョブの中で child_app へリクエストを飛ばす処理を実装します。

class ParentJob < ApplicationJob
  queue_as :default

  def perform(message)
    connection = Faraday.new('http://localhost:9001')
    connection.post('/messages') do |cn|
      cn.headers['Content-Type'] = 'application/json'
      cn.body = {message: message}.to_json
    end
  end
end

　
続いて、ActiveJobを起動するエンドポイントを作成します。今回は

• child_app に1回リクエストを飛ばす
• そのレスポンスを待って、ActiveJobを起動する
• 起動したかどうかは待たず、JSONレスポンスを返す

という実装にします。

class HelloController < ApplicationController
  def child_and_job
    Faraday.get('http://localhost:9001/messages')

    ParentJob.perform_later('hi')

    render json: {message: 'done'}
  end
end

　
最後にルーティングを追加します。

Rails.application.routes.draw do
  post '/child_and_job', to: 'hello#child_and_job'
end

動作確認

curlでPOSTリクエストすると、レスポンスが返ってきます。

$ curl -X POST http://localhost:9000/child_and_job

{"message":"done"}

　
parent_app のログを見ると、ジョブが実行されていることがわかります。

Started POST "/child_and_job" for 127.0.0.1 at 2023-06-25 15:54:32 +0900
...
[ActiveJob] Enqueued ParentJob (Job ID: 16556578-1068-4399-ba1f-af7357cce95f) to Async(default) with arguments: "hi"
Completed 200 OK in 19ms (Views: 0.3ms | Allocations: 2924)

[ActiveJob] [ParentJob] [16556578-1068-4399-ba1f-af7357cce95f] Performing ParentJob (Job ID: 16556578-1068-4399-ba1f-af7357cce95f) from Async(default) enqueued at 2023-06-25T06:54:32Z with arguments: "hi"
[ActiveJob] [ParentJob] [16556578-1068-4399-ba1f-af7357cce95f] Performed ParentJob (Job ID: 16556578-1068-4399-ba1f-af7357cce95f) from Async(default) in 12.6ms

　
続いて child_app のログを見ると、2回リクエストのあったことが分かります。

ただ、 traceparent の値は

• 同期リクエスト
  • 00-c453de21927acd7934f7c6ecccae49df-d637e607cad1965d-01
• ジョブでのリクエスト
  • 00-7f626290dceb8d0240510406231d95d9-81a81c320e463a99-01

と異なっていました。

Started GET "/messages" for 127.0.0.1 at 2023-06-25 15:54:32 +0900
traceparent header ===============>
00-c453de21927acd7934f7c6ecccae49df-d637e607cad1965d-01
traceparent header <===============
Completed 200 OK in 4ms (Views: 0.3ms | Allocations: 1140)


Started POST "/messages" for 127.0.0.1 at 2023-06-25 15:54:32 +0900
Processing by MessagesController#create as */*
  Parameters: {"message"=>"hi"}
traceparent header ===============>
00-7f626290dceb8d0240510406231d95d9-81a81c320e463a99-01
traceparent header <===============
=== start ===============>
hi
<== end   ================
Completed 204 No Content in 4ms (Allocations: 1193)

　
Jaegerにて確認すると、2つのトレースが表示されました。

　
1つは同期リクエストのトレースでした。

　
もう1つは、ジョブでのリクエストのトレースでした。

　
これにより、 traceparent の値が異なると、Jaegerでは別のトレースとして表示されることが分かりました。

　
以上で、OpenTelemetryで収集したデータをJaegerで表示するところまでできました。

資料

• OpenTelemetryでWebシステムの処理を追跡しよう - DjangoCongress JP 2022 - Google スライド
• 分散トレーシングとOpenTelemetryのススメ/Getting started distributed tracing and OpenTelemetry - Speaker Deck
• 今日から分散トレーシングに対応しないといけなくなった人のための opentelemetry-go 入門 - Cybozu Inside Out | サイボウズエンジニアのブログ
• 2022年版 OpenTelemetryを知れば世界が平和に - じゃあ、おうちで学べる
• 仕様と実装から理解するOpenTelemetryの全体像
• [OpenTelemetry] Ruby(Rails) で ZipkinやJaegerを動かす | Fand.jp Blog
• Ruby | OpenTelemetry
• OpenTelemetry for Ruby | Honeycomb
• Cloud RunでOpenTelemetry Collectorをサイドカーとして動かす
• NginxでOpenTelemetry（旧バージョンを含む） - ymtdzzz.dev
• OpenTelemetryのカレンダー | Advent Calendar 2022 - Qiita
• Observability Conference 2022レポート 記事一覧 | Think IT（シンクイット）

ソースコード

Githubに上げました。
https://github.com/thinkAmi-sandbox/rails_with_opentelemetry-example

　
今回のプルリクはこちら。
https://github.com/thinkAmi-sandbox/rails_with_opentelemetry-example/pull/1