Node.jsをOpenTelemetryでトレーシングしてみる

はじめに

Node.js(JavaScript)でOpenTelemetryを扱う記事が少ないため、トレーシングまわりの基本的なノウハウをまとめてみました。
本記事では、Instrumentationを使用した自動トレース収集、startSpan()メソッド呼び出しによる手動トレース収集まわりを扱います。

OpenTelemetryとは？

マイクロサービスのような分散環境で、トレースやメトリクスを計測するフレームワーク。
可視化ツール（ZipkinやJaegerなど）と組み合わせることで、どの処理でどれだけ時間がかかっているのか解析しやすくなります。

おおまかな特徴

• CNCFがOpenTelemetryプロジェクトをホストしている（2015年設立）
• 従来のフレームワークに見られたベンダロックインを排除したオープンさがコンセプト
• 言語ごとにライブラリを提供
• 使用するライブラリを差し替えれば、手続きはそのままに、異なるツールとの連携が可能になる

やってみること

クライアント・サーバからトレースデータを集め、Zipkinでグラフ化してみます。
サンプルとして、クライアントが２種類のREST-APIを呼び出す構成を対象に行います。

実行環境

• MacOS X
• node: v13.8.0
• npm: v7.5.3
• express: v4.17.1
• OpenTelemetry: v0.17

1. サンプル構成の作成

まずはベースとなるクライアント・サーバのサンプルを作成します。

1.1 サンプル作成

プロジェクトにExpressとAxiosをインストールします。

$ npm install express axios

下表に示す３種類のソースファイルを作成します。

ファイル名	実装内容
api1server.js	API1のリクエストを受け付け、2秒後にレスポンスを返す
api2server.js	API1のリクエストを受け付け、1秒後にレスポンスを返す
client.js	API1、API2を順々に同期的に呼び出す

api-server1.js

'use strict';

const express = require('express');
const app = express();
const PORT = 8180;

const data = { name: "orange", price: 200};

async function setupRoutes() {
  app.use(express.json());

  app.get('/api/price', async (req, res) => {

    // 2秒後にレスポンスを返す
    setTimeout(() => {
      res.json(data);
    }, 2000);
  });
}

setupRoutes().then(() => {
  app.listen(PORT);
  console.log(`Listening on http://localhost:${PORT}`);
});

api-server2.js

'use strict';

const express = require('express');
const app = express();
const PORT = 8280;

const data = { name: "melon", price: 600};

async function setupRoutes() {
  app.use(express.json());

  app.get('/api/price', async (req, res) => {

    // 1秒後にレスポンスを返す
    setTimeout(() => {
      res.json(data);
    }, 1000);
  });
}

setupRoutes().then(() => {
  app.listen(PORT);
  console.log(`Listening on http://localhost:${PORT}`);
});

client.js

'use strict';

const axios = require('axios').default;

async function makeRequest() {

  // 1つ目のAPIを呼び出す
  await axios.get('http://localhost:8180/api/price')
  .then(res => console.log("API1: OK"))
  .catch(err => console.log("API1: ERROR"));

  // 2つ目のAPIを呼び出す
  await axios.get('http://localhost:8280/api/price')
  .then(res => console.log("API2: OK"))
  .catch(err => console.log("API2: ERROR"));

  // 5秒後に終了する
  setTimeout(() => { 
    console.log('Completed.');
  }, 5000);
}

makeRequest();

1.2 サンプルの動作確認

以下の手順で、２種類のサーバを起動し、Clientを起動します。
API1とAPI2を順々に呼び出し、それぞれ結果OKとなるはずです。

# Server1の起動
$ node api-server1.js 
Listening on http://localhost:8180

# Server2の起動
$ node api-server2.js 
Listening on http://localhost:8280

# Clientの起動
$ node client.js 
API1: OK
API2: OK
Completed.

2. Zipkinの構築

トレースデータを可視化するために、DockerコンテナのZipkinを構築します。

$ docker run -d -p 9411:9411 openzipkin/zipkin

ブラウザから localhost:9411 にアクセスすると、以下の画面が表示されます。

3. OpenTelemetryの組み込み

3.1 パッケージのインストール

それでは、１章で作成したサンプルにOpenTelemetryを組み込んでいきます。
まずは必要となるパッケージをプロジェクトにインストールします。

$ npm install \
  @opentelemetry/core \
  @opentelemetry/node \
  @opentelemetry/tracing \
  @opentelemetry/instrumentation \
  @opentelemetry/exporter-zipkin
  @opentelemetry/plugin-http \
  @opentelemetry/plugin-express

3.2 tracer.jsの作成

クライアント・サーバ両方が共通で使用するExporter設定(tracer.js)を作成します。

tracer.js

const opentelemetry = require('@opentelemetry/api');
const { registerInstrumentations } = require('@opentelemetry/instrumentation');
const { NodeTracerProvider } = require('@opentelemetry/node');
const { SimpleSpanProcessor, ConsoleSpanExporter } = require('@opentelemetry/tracing');
const { ZipkinExporter } = require('@opentelemetry/exporter-zipkin');

module.exports = (serviceName) => {
  const provider = new NodeTracerProvider();

  registerInstrumentations({
    tracerProvider: provider,
  });

  const exporter = new ZipkinExporter({ serviceName });
  provider.addSpanProcessor(new SimpleSpanProcessor(exporter));
  provider.addSpanProcessor(new SimpleSpanProcessor(new ConsoleSpanExporter()));
  provider.register();

  return opentelemetry.trace.getTracer('api-call-app');
};

Exporterとはトレースデータの出力先となるオブジェクトです。
今回は以下２つのExporterを設定し、２箇所に同時に出力されるようにしています。

使用するExporter	出力先
ZipkinExporter	Zipkin
ConsoleSpanExporter	コンソール画面

また、registerInstrumentations()を呼び出すことで、先ほどnpm installコマンドでインストールしたInstrumentationパッケージ（自動トレース出力）が使用されるようになります。
今回のサンプルでは、plugin-httpとplugin-expressの２つのInstrumentationが有効化されています。

3.3 クライアント側への組み込み

続いて、クライアント側ソースにOpenTelemetryのコードを追加します。

client.js

'use strict';

// 追加
const tracer = require('./tracer')('client');
const api = require('@opentelemetry/api');

const axios = require('axios').default;

// async function makeRequest() {
function makeRequest() {
  const span = tracer.startSpan('client.makeRequest()', {
    kind: api.SpanKind.CLIENT,
  });

  api.context.with(api.setSpan(api.ROOT_CONTEXT, span), async () => {

    // 1つ目のAPIを呼び出す
    await axios.get('http://localhost:8180/api/price')
    .then(res => span.setStatus({ code: api.SpanStatusCode.OK }))
    .catch(err => span.setStatus({ code: api.SpanStatusCode.ERROR, message: err.message }));

    // 2つ目のAPIを呼び出す
    await axios.get('http://localhost:8280/api/price')
    .then(res => span.setStatus({ code: api.SpanStatusCode.OK }))
    .catch(err => span.setStatus({ code: api.SpanStatusCode.ERROR, message: err.message }));
  });

  // 5秒後に終了する
  setTimeout(() => { 
    span.end();
    console.log('Completed.');
  }, 5000);
}

makeRequest();

クライアント側への追加内容は以下となります。

1. Exporterの作成（tracer.js呼び出し）
2. トレースデータを構成するSpanの作成（startSpan()の実行）
3. ContextにSpanを設定し、API実行のタイミングでサーバ側へSpanを伝搬させる
4. 最後にSpan.end()でSpanを終了する

用語説明になりますが、個々の測定区間をSpanと呼び、Spanの集合がTraceとなります。
以下の図のように、Spanは親子関係を持つこともできます。

3.4 サーバ側への組み込み

api-server1.js

'use strict';

// 追加
const tracer = require('./tracer')('api-server1');
const api = require('@opentelemetry/api');

const express = require('express');
const app = express();
const PORT = 8180;

const data = { name: "orange", price: 200};

async function setupRoutes() {
  app.use(express.json());

  app.get('/api/price', async (req, res) => {

    // 2秒後にレスポンスを返す
    setTimeout(() => {
      res.json(data);
    }, 2000);
  });
}

setupRoutes().then(() => {
  app.listen(PORT);
  console.log(`Listening on http://localhost:${PORT}`);
});

サーバ側への追加内容はExporterの設定のみです。
api-server2.jsにも同様の追加を行います（ソースは掲載省略）。

3.5 動作確認

1章と同様に、サーバ２つを再度起動し、クライアントを起動します。

$ node client.js 

Zipkinの画面にアクセスし、検索条件：serviceName=clientを指定して、先ほど収集したトレースデータを表示します。
以下のような５段のトレースデータが表示されれば成功です。

それぞれのトレースデータは以下を表します。

	収集箇所	説明	収集手段
1段目	クライアント	startSpan()で作成したSpanの所要時間	手動
2段目	クライアント	サーバ1に対するhttp getのリクエスト送信〜レスポンス受信までの所要時間	自動
3段目	サーバ1	リクエスト受信〜レスポンス送信までの所要時間	自動
4段目	クライアント	サーバ2に対するhttp getのリクエスト送信〜レスポンス受信までの所要時間	自動
5段目	サーバ2	リクエスト受信〜レスポンス送信までの所要時間	自動

※収集手段＝自動は、Instrumentationが自動収集トレースデータです。

１段目の手動収集はクライアント側の以下の処理で行われています。

const span = tracer.startSpan('client.makeRequest()', {
  kind: api.SpanKind.CLIENT,
});

api.context.with(api.setSpan(api.ROOT_CONTEXT, span), async () => {
  :
});

理想としてはクライアント側もすべて自動収集にしたいところですが、プロセス間通信のトレースデータ収集を行う場合、現時点では明示的にROOT_CONTEXT上にSpanを生成しておく必要があります。
これを行わないと、２種類のAPI呼び出しに別々のtracer-idが割り振られてしまい、Zipkin上で別々のトレースデータとして扱われてしまいます。

おわりに

解析に有用なトレースデータを少ない手順で収集できるのはとても便利です。
ただ、使用するパッケージのバージョンによって手続きが異なっていて、少しでもズレた手続きをすると収集がうまくいかなくなるなど、成功パターンを編み出すのに結構時間がかかりました。
今後のバージョンアップで、もう少し使い方に自由度が出るといいなぁと願っています。