Node.jsでオブザーバビリティトレースとログを織り交ぜる
Olivia Novak
Dev Intern · Leapcell

はじめに
現代の分散システムにおいて、アプリケーションの動作を理解し、問題を迅速に診断することは最優先事項です。アプリケーションがスケールし、より複雑になるにつれて、従来のログ記録のみ、または独立したトレースツールのみに頼っていては不十分です。アプリケーションログが、トレースによって提供される実行パス、コンポーネント間のやり取り、およびタイミング情報といった、根本的な運用コンテキストと本質的にリンクされている、ホリスティックなビューが必要です。ここで、ログ記録フレームワークをトレースシステムと連携させることが非常に価値のあるものになります。
Node.jsエコシステムでは、Pinoは高性能ロガーとして際立っており、OpenTelemetryはトレースを含むテレメトリデータの収集における業界標準として登場しました。PinoとOpenTelemetryの間のギャップを埋めることで、トレースコンテキストでログを強化し、デバッグ、パフォーマンス分析、および全体的なシステム理解のために、それらを大幅に強力にすることができます。この記事では、この重要な接続を確立するプロセスをガイドし、最終的にアプリケーションのオブザーバビリティを向上させます。
オブザーバビリティの柱
実装の詳細に入る前に、私たちが扱うコアコンセプトを簡単に定義しましょう。
- オブザーバビリティ: システムの外部出力を検査することによって、その内部状態を推測する能力。これは、システムについて任意の質問をし、システムが提供するデータ(ログ、メトリクス、トレース)から回答を得ることです。
- ログ: アプリケーション内で発生するイベントの、個別のタイムスタンプ付きレコード。それらは、何が起こったのか、いつ起こったのか、そして時にはなぜ起こったのかについての詳細なテキスト情報を提供します。Pinoは、Node.jsにおける構造化された高性能ログ記録に最適です。
- トレース: 分散システム全体のリクエストまたはトランザクションの、エンドツーエンドの旅を表します。トレースは1つ以上のスパンで構成され、各スパンは論理的な作業単位(例:関数呼び出し、データベースクエリ、APIリクエスト)を表します。トレースは、サービス境界を越えたコンテキスト、因果関係、およびレイテンシ情報を提供します。OpenTelemetryは、トレースの生成と収集のためのベンダーに依存しない標準を提供します。
- トレースコンテキスト: トレースとその現在のスパンを識別する情報。このコンテキストは、プロセスやサービス境界を越えて伝播され、個々のスパンをリンクして完全なトレースを形成できるようにします。主要なコンポーネントには、
traceId
とspanId
が含まれます。
目標は、これらのトレースコンテキストをPinoログに注入し、問題のあるログエントリから、その完全な実行パスを示す関連トレースへ、容易に移動できるようにすることです。
PinoログとOpenTelemetryトレースの連携
PinoとOpenTelemetryを統合する原則は単純です。ログが発行されるたびに、現在のOpenTelemetry traceId
とspanId
をログレコードに含めたいと考えます。これにより、直接的な相関関係が確立されます。
ステップ1: OpenTelemetryの設定
まず、アプリケーションがOpenTelemetryでインストルメントされていることを確認します。これには、必要なSDKおよび自動インストルメンテーションパッケージのインストールが含まれます。
npm install @opentelemetry/sdk-node @opentelemetry/api @opentelemetry/auto-instrumentations-node npm install @opentelemetry/exporter-collector --save-dev # またはOTLP gRPCのような別のエクスポート
次に、アプリケーションのエントリポイント(例:src/instrumentation.js
またはsrc/tracing.js
)でOpenTelemetryを初期化します。
// src/tracing.js import { NodeSDK } from '@opentelemetry/sdk-node'; import { ConsoleSpanExporter } from '@opentelemetry/sdk-trace-base'; import { Resource } from '@opentelemetry/resources'; import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions'; import { PeriodicExportingSpanProcessor } from '@opentelemetry/sdk-trace-base'; import { HttpInstrumentation } from '@opentelemetry/instrumentation-http'; import { ExpressInstrumentation } from '@opentelemetry/instrumentation-express'; import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-grpc'; // 例:OTLPエクスポート const sdk = new NodeSDK({ resource: new Resource({ [SemanticResourceAttributes.SERVICE_NAME]: 'my-nodejs-app', [SemanticResourceAttributes.SERVICE_VERSION]: '1.0.0', }), spanProcessor: new PeriodicExportingSpanProcessor(new OTLPTraceExporter()), // または開発用に new ConsoleSpanExporter() instrumentations: [ new HttpInstrumentation(), new ExpressInstrumentation(), // PostgreSQL用の @opentelemetry/instrumentation-pg のような他の関連インストルメンテーションを追加 ], }); sdk.start(); console.log('OpenTelemetry tracing initialized.'); // トレースがシャットダウン時にフラッシュされることを保証するために process.on('SIGTERM', () => { sdk.shutdown() .then(() => console.log('Tracing terminated')) .catch((error) => console.log('Error terminating tracing', error)) .finally(() => process.exit(0)); });
このインストルメンテーションを有効にしてアプリケーションを実行することを忘れないでください。
node -r ./src/tracing.js src/index.js
ステップ2: Pinoトレースコンテキストの統合
Pinoは、「バインディング」または「チャイルドロガー」と呼ばれる強力な機能を提供しており、ログレコードにコンテキストプロパティを追加できます。@opentelemetry/api
のtrace.getSpanContext()
メソッドを活用して、現在のトレースIDとスパンIDを取得できます。
まず、Pinoをインストールします。
npm install pino
次に、Pinoロガーインスタンスを作成します。重要なのは、トレースコンテキストを挿入するためにpino-caller
またはカスタム関数を使用することです。便利な方法は、コンテキストが利用可能な各リクエストまたは操作に対してチャイルドロガーを作成することです。
Express.jsを使用した例を見てみましょう。
// src/index.js (OpenTelemetryインストルメンテーションの後) import express from 'express'; import pino from 'pino'; import { trace } from '@opentelemetry/api'; const app = express(); const port = 3000; // ベースPinoロガーを作成 const logger = pino({ level: process.env.LOG_LEVEL || 'info', formatters: { // このフォーマッターは、相関IDがトップレベルにあることを保証します log: (obj) => { if (obj.traceId && obj.spanId) { return { traceId: obj.traceId, spanId: obj.spanId, ...obj }; } return obj; }, }, }); // OpenTelemetryトレースコンテキストをロガーに注入するミドルウェア app.use((req, res, next) => { const currentSpan = trace.getSpan(trace.activeContext()); if (currentSpan) { const spanContext = currentSpan.spanContext(); if (spanContext.traceId && spanContext.spanId) { // traceIdとspanIdを持つチャイルドロガーを作成 req.log = logger.child({ traceId: spanContext.traceId, spanId: spanContext.spanId, }); req.log.debug('Request started'); // 例:ログ } else { req.log = logger; // トレースコンテキストなし、ベースロガーを使用 } } else { req.log = logger; // アクティブなスパンなし、ベースロガーを使用 } next(); }); app.get('/', (req, res) => { req.log.info('Handling root request'); // 別のスパンを生成する可能性のある作業をシミュレート const myService = { doSomething: (log) => { log.debug('Doing something important in service'); // ここで、これが別のモジュール/関数であった場合、新しいスパンを作成できます // const newSpan = tracer.startSpan('myService.doSomething'); // newSpan.end(); } }; myService.doSomething(req.log); res.send('Hello from Node.js with correlated logs!'); }); app.get('/error', (req, res) => { req.log.error('An error occurred during request processing!'); res.status(500).send('Something went wrong!'); }); app.listen(port, () => { logger.info(`App listening at http://localhost:${port}`); });
この例では:
- aベースの
pino
ロガーを作成します。 - ミドルウェアが受信リクエストをインターセプトします。
- ミドルウェア内で、
trace.getSpan(trace.activeContext())
を使用して、現在アクティブなOpenTelemetryスパンを取得します。 - スパンが存在する場合、その
traceId
とspanId
が抽出されます。 logger.child({ traceId, spanId })
を使用してチャイルドロガーが作成されます。このチャイルドロガーは、生成するすべてのログにこれらのプロパティを自動的に含めます。req.log
には、リクエスト処理チェーン全体からアクセスできるように、このチャイルドロガーが割り当てられます。
これで、/
にリクエストを行うと、コンソール(またはログ宛先)は、読みやすくフォーマットされた以下のようなログを表示します。
{ "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6", "spanId": "f7e8d9c0b1a2e3f4", "level": 30, "time": 1678886400000, "pid": 12345, "hostname": "my-host", "msg": "Request started" } { "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6", "spanId": "f7e8d9c0b1a2e3f4", "level": 30, "time": 1678886400000, "pid": 12345, "hostname": "my-host", "msg": "Handling root request" } { "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6", "spanId": "f7e8d9c0b1a2e3f4", "level": 20, "time": 1678886400000, "pid": 12345, "hostname": "my-host", "msg": "Doing something important in service" }
同じリクエストに関連するすべてのログにtraceId
とspanId
が一貫して存在することに注意してください。この強力な相関関係こそが、強力なオブザーバビリティを可能にします。
アプリケーションとメリット
このセットアップにより、いくつかのメリットが得られます。
- より高速な根本原因分析: エラーログが表示された場合、その
traceId
を使用して関連するトレース全体を取得し、そのリクエストに関与したすべての操作、サービス、およびタイミングを確認できます。これにより、無関係なログをふるいにかけるのに費やす時間が大幅に短縮されます。 - コンテキストリッチなログ: 各ログエントリには、それが属する操作のコンテキストがあります。たとえその操作が複数のサービスにまたがる場合でもです。
- デバッグの改善: ログ管理システムで
traceId
によってログをフィルタリングして、特定のユーザーインタラクションまたはプロセスに関連するログのみを表示し、イベントの逐次的な物語を提供できます。 - パフォーマンスボトルネックの特定: ログをトレースのタイミングと相関させることで、コードのどの部分、またはどの外部呼び出しに時間がかかりすぎているかを正確に特定し、必要に応じて詳細なログにドリルダウンできます。
- 統一されたオブザーバビリティエクスペリエンス: ログ管理システム(Elastic Stack、Splunk、Sumo Logic、Datadogなど)およびAPMツール(Jaeger、Zipkin、Datadog APM、New Relicなど)は、これらの相関IDを活用して、トレースとともにログを表示し、アプリケーションの健全性とパフォーマンスの真に統合されたビューを提供できます。
結論
PinoログとOpenTelemetryトレースの統合は、Node.jsアプリケーションで包括的なオブザーバビリティを実現するための基本的なステップです。トレースIDとスパンIDをログレコードに直接埋め込むことで、個々のテレメトリ信号を、システム動作の強力で相互接続された物語に変えます。この相関関係は、デバッグを簡素化し、根本原因分析を加速し、アプリケーションの運用状態をより明確に理解できるようにします。このプラクティスを採用することは、オブザーバビリティ戦略を断片的な洞察から、分散システムの真に首尾一貫した理解へと進めることを意味します。