Skip to content
blog.takenoko.dev
Blog

OpenTelemetry JS: 構造化ログへtrace_idを自動付与する仕組み

はじめに

Section titled “はじめに”

システムを運用する上で、問題発生時の原因調査やパフォーマンス分析のために、ログとトレース情報を紐付けて追跡することは非常に重要です。 アプリケーションの error ログを発見しても、ログの内容によってはエラーが発生したことしかわからないこともあります。

OpenTelemetry JavaScript SDK（以下、OpenTelemetry JS SDK）は、このような課題を解決するための強力な機能を提供します。とくに、構造化ログに対してtrace_idやspan_idといったトレース情報を自動で付与する仕組みは、Observability（可観測性）を大きく向上させます。

業務で運用・管理している REAT API サーバにおいて、ログのトレース機能を導入するため、OpenTelemetry について学習を開始しました。 その API サーバは Node.js で構築されており、Express フレームワークを採用し、ログ処理には winston を利用しています。

この記事では、OpenTelemetry JS SDK がどのようにして、この自動的な trace_id のログへの挿入を実現しているのか、学習で分かった内容をまとめます。

  • OpenTelemetry JS SDKがtrace_idをログに自動付与する基本的な流れ
  • ロギングライブラリ（例: Winston, Pino）の動作に介入し、トレース情報を挿入する Instrumentation の仕組み (@opentelemetry/instrumentation)
  • 簡単な設定で、既存のログ出力コードを変更せずにトレース情報を付与する方法

使用バージョン

Section titled “使用バージョン”
バージョン
MacSequoia 15.4.1
Node.js22.15.0
pnpm10.6.4

成果物

Section titled “成果物”

https://github.com/kntks/blog-code/tree/main/2025/05/opentelemetry-js

コード紹介

Section titled “コード紹介”

この記事で使用するコードを簡単に紹介します。

今回は、OpenTelemetryのgetting-started にあるサンプルをベースにしたコードを利用します。

src/logger.ts
import { createLogger, format, transports } from "winston";


const logger = createLogger({
  transports: [new transports.Console()],
  format: format.combine(
    format.timestamp({ alias: "time" }),
    format(({ timestamp, ...rest }) => rest)(),
    format.errors({ stack: true }),
    format.splat(),
    format.json(),
  ),
});


export default logger;
src/app.ts
import express, { type Express } from "express";
import logger from "./logger";


const PORT: number = Number.parseInt(process.env.PORT || "8080");
const app: Express = express();


function getRandomNumber(min: number, max: number) {
  return Math.floor(Math.random() * (max - min + 1) + min);
}


app.get(
  "/rolldice",
  (req, res, next) => next(), // middleware function
  (req, res) => {
    logger.info("Received request to /rolldice");
    res.send(getRandomNumber(1, 6).toString());
  },
);


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

まずは計装をせず、サーバー起動後、ターミナルの別タブで curl http://localhost:8080/rolldice を実行してみます。すると以下のようなログが出力されます。

Terminal window
$ pnpm ts-node src/app.ts
Listening for requests on http://localhost:8080
{"level":"info","message":"Received request to /rolldice","time":"2025-05-05T03:01:55.079Z"}

計装 (Instrumentation) の方法と選択肢

Section titled “計装 (Instrumentation) の方法と選択肢”

計装方法の選択肢

Section titled “計装方法の選択肢”

調査した結果、計装方法は全部で5つあると思われます。

1. @opentelemetry/auto-instrumentations-node/register を使う方法 (ゼロコード)

Section titled “1. @opentelemetry/auto-instrumentations-node/register を使う方法 (ゼロコード)”

@opentelemetry/auto-instrumentations-node/register をアプリケーション起動時に一緒に使用する方法であり、計装のためのコードを書きません。

Terminal window
$ OTEL_TRACES_EXPORTER="console" pnpm ts-node -r @opentelemetry/auto-instrumentations-node/register src/app.ts

参考：

2. @opentelemetry/sdk-node と @opentelemetry/auto-instrumentations-node を組み合わせる方法

Section titled “2. @opentelemetry/sdk-node と @opentelemetry/auto-instrumentations-node を組み合わせる方法”

@opentelemetry/auto-instrumentations-node モジュールには、すべてのサポートされている instrumentations を含んでいます。このモジュールは getNodeAutoInstrumentations という関数があり、この関数を NodeSDK のオプションに設定します。

instrumentations はデフォルトで enabled: true なので、不要な instrumentation は明示的に false にする必要があります。各プラグインの設定は、enabled プロパティと同じように設定できます。

src/instrumentation.sdk-auto.ts
import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node";
import { NodeSDK } from "@opentelemetry/sdk-node";
import { ConsoleSpanExporter } from "@opentelemetry/sdk-trace-node";
import { SimpleSpanProcessor } from "@opentelemetry/sdk-trace-node";


const sdk = new NodeSDK({
  traceExporter: new ConsoleSpanExporter(),
  spanProcessor: new SimpleSpanProcessor(new ConsoleSpanExporter()),
  instrumentations: [
    getNodeAutoInstrumentations({
      "@opentelemetry/instrumentation-fs": { enabled: false },
      "@opentelemetry/instrumentation-express": {
        ignoreLayers: [
          // 設定を追加できる
        ],
      },
    }),
  ],
});


sdk.start();

今回使用したい @opentelemetry/instrumentation-express と @opentelemetry/instrumentation-winston はすでに @opentelemetry/auto-instrumentations-node に含まれているため、設定はこれで完了です。

アプリを起動後、curl http://localhost:8080/rolldice を実行した結果を載せます。

$ pnpm ts-node -r ./src/instrumentation.sdk-auto.ts src/app.ts
Terminal window
$ pnpm ts-node -r ./src/instrumentation.sdk-auto.ts src/app.ts
Listening for requests on http://localhost:8080
{"level":"info","message":"Received request to /rolldice","span_id":"e7949ac71bb4ad83","time":"2025-05-05T03:04:22.139Z","trace_flags":"01","trace_id":"86ac35ea1fd72899dce9fa8bf191c265"}
{
  resource: {
    attributes: {
      'host.name': 'dummy',
      'host.arch': 'arm64',
      'host.id': 'dummy',
      'process.pid': 20749,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
      'process.command_args': [
        '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
        '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
        '-r',
        './src/instrumentation.sdk-auto.ts',
        'src/app.ts'
      ],
      'process.runtime.version': '22.15.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
      'process.owner': 'user',
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '86ac35ea1fd72899dce9fa8bf191c265',
  parentSpanContext: {
    traceId: '86ac35ea1fd72899dce9fa8bf191c265',
    spanId: 'a63fc4f6d5c8ffa4',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'middleware - query',
  id: 'b3dcd73d11fa72a7',
  kind: 0,
  timestamp: 1746414262137000,
  duration: 455.291,
  attributes: {
    'http.route': '/',
    'express.name': 'query',
    'express.type': 'middleware'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'host.name': 'dummy',
      'host.arch': 'arm64',
      'host.id': 'dummy',
      'process.pid': 20749,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
      'process.command_args': [
        '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
        '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
        '-r',
        './src/instrumentation.sdk-auto.ts',
        'src/app.ts'
      ],
      'process.runtime.version': '22.15.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
      'process.owner': 'user',
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '86ac35ea1fd72899dce9fa8bf191c265',
  parentSpanContext: {
    traceId: '86ac35ea1fd72899dce9fa8bf191c265',
    spanId: 'a63fc4f6d5c8ffa4',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'middleware - expressInit',
  id: 'b99fa6373d9d432b',
  kind: 0,
  timestamp: 1746414262138000,
  duration: 213.834,
  attributes: {
    'http.route': '/',
    'express.name': 'expressInit',
    'express.type': 'middleware'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'host.name': 'dummy',
      'host.arch': 'arm64',
      'host.id': 'dummy',
      'process.pid': 20749,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
      'process.command_args': [
        '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
        '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
        '-r',
        './src/instrumentation.sdk-auto.ts',
        'src/app.ts'
      ],
      'process.runtime.version': '22.15.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
      'process.owner': 'user',
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '86ac35ea1fd72899dce9fa8bf191c265',
  parentSpanContext: {
    traceId: '86ac35ea1fd72899dce9fa8bf191c265',
    spanId: 'a63fc4f6d5c8ffa4',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'request handler - /rolldice',
  id: 'e7949ac71bb4ad83',
  kind: 0,
  timestamp: 1746414262139000,
  duration: 6260.666,
  attributes: {
    'http.route': '/rolldice',
    'express.name': '/rolldice',
    'express.type': 'request_handler'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'host.name': 'dummy',
      'host.arch': 'arm64',
      'host.id': 'dummy',
      'process.pid': 20749,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
      'process.command_args': [
        '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
        '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
        '-r',
        './src/instrumentation.sdk-auto.ts',
        'src/app.ts'
      ],
      'process.runtime.version': '22.15.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
      'process.owner': 'user',
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-http',
    version: '0.200.0',
    schemaUrl: undefined
  },
  traceId: '86ac35ea1fd72899dce9fa8bf191c265',
  parentSpanContext: undefined,
  traceState: undefined,
  name: 'GET /rolldice',
  id: 'a63fc4f6d5c8ffa4',
  kind: 1,
  timestamp: 1746414262135000,
  duration: 9985.459,
  attributes: {
    'http.url': 'http://localhost:8080/rolldice',
    'http.host': 'localhost:8080',
    'net.host.name': 'localhost',
    'http.method': 'GET',
    'http.scheme': 'http',
    'http.target': '/rolldice',
    'http.user_agent': 'curl/8.7.1',
    'http.flavor': '1.1',
    'net.transport': 'ip_tcp',
    'net.host.ip': '::1',
    'net.host.port': 8080,
    'net.peer.ip': '::1',
    'net.peer.port': 49958,
    'http.status_code': 200,
    'http.status_text': 'OK',
    'http.route': '/rolldice'
  },
  status: { code: 0 },
  events: [],
  links: []
}

3. @opentelemetry/sdk-node と個別のInstrumentationを組み合わせる方法

Section titled “3. @opentelemetry/sdk-node と個別のInstrumentationを組み合わせる方法”

この方法では、必要なInstrumentationのみを明示的に指定して計装できます。自動計装よりも依存パッケージを最小限に抑えられ、不要なInstrumentationの読み込みを避けられるのが利点です。

src/instrumentation.sdk-manual.ts
import { ExpressInstrumentation } from "@opentelemetry/instrumentation-express";
import { HttpInstrumentation } from "@opentelemetry/instrumentation-http";
import { WinstonInstrumentation } from "@opentelemetry/instrumentation-winston";
import { NodeSDK } from "@opentelemetry/sdk-node";
import { ConsoleSpanExporter } from "@opentelemetry/sdk-trace-node";
import { SimpleSpanProcessor } from "@opentelemetry/sdk-trace-node";


const sdk = new NodeSDK({
  traceExporter: new ConsoleSpanExporter(),
  spanProcessor: new SimpleSpanProcessor(new ConsoleSpanExporter()),
  instrumentations: [
    new HttpInstrumentation(),
    new ExpressInstrumentation(),
    new WinstonInstrumentation(),
  ],
});


sdk.start();
$ pnpm ts-node -r ./src/instrumentation.sdk-manual.ts src/app.ts
Terminal window
$ pnpm ts-node -r ./src/instrumentation.sdk-manual.ts src/app.ts
Listening for requests on http://localhost:8080
{"level":"info","message":"Received request to /rolldice","span_id":"c15cfa5393d4366a","time":"2025-05-05T03:13:27.694Z","trace_flags":"01","trace_id":"10da2e8c2be711fa2d78ea2c7cc5fcf4"}
{
  resource: {
    attributes: {
      'host.name': 'dummy',
      'host.arch': 'arm64',
      'host.id': 'dummy',
      'process.pid': 22669,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
      'process.command_args': [
        '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
        '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
        '-r',
        './src/instrumentation.sdk-manual.ts',
        'src/app.ts'
      ],
      'process.runtime.version': '22.15.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
      'process.owner': 'user',
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '10da2e8c2be711fa2d78ea2c7cc5fcf4',
  parentSpanContext: {
    traceId: '10da2e8c2be711fa2d78ea2c7cc5fcf4',
    spanId: '90ee83bac678a166',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'middleware - query',
  id: 'f4708b4b5f0225af',
  kind: 0,
  timestamp: 1746414807692000,
  duration: 543.666,
  attributes: {
    'http.route': '/',
    'express.name': 'query',
    'express.type': 'middleware'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'host.name': 'dummy',
      'host.arch': 'arm64',
      'host.id': 'dummy',
      'process.pid': 22669,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
      'process.command_args': [
        '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
        '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
        '-r',
        './src/instrumentation.sdk-manual.ts',
        'src/app.ts'
      ],
      'process.runtime.version': '22.15.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
      'process.owner': 'user',
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '10da2e8c2be711fa2d78ea2c7cc5fcf4',
  parentSpanContext: {
    traceId: '10da2e8c2be711fa2d78ea2c7cc5fcf4',
    spanId: '90ee83bac678a166',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'middleware - expressInit',
  id: '8f4a4e4867d3516f',
  kind: 0,
  timestamp: 1746414807693000,
  duration: 247.583,
  attributes: {
    'http.route': '/',
    'express.name': 'expressInit',
    'express.type': 'middleware'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'host.name': 'dummy',
      'host.arch': 'arm64',
      'host.id': 'dummy',
      'process.pid': 22669,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
      'process.command_args': [
        '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
        '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
        '-r',
        './src/instrumentation.sdk-manual.ts',
        'src/app.ts'
      ],
      'process.runtime.version': '22.15.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
      'process.owner': 'user',
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '10da2e8c2be711fa2d78ea2c7cc5fcf4',
  parentSpanContext: {
    traceId: '10da2e8c2be711fa2d78ea2c7cc5fcf4',
    spanId: '90ee83bac678a166',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'request handler - /rolldice',
  id: 'c15cfa5393d4366a',
  kind: 0,
  timestamp: 1746414807694000,
  duration: 6889.292,
  attributes: {
    'http.route': '/rolldice',
    'express.name': '/rolldice',
    'express.type': 'request_handler'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'host.name': 'dummy',
      'host.arch': 'arm64',
      'host.id': 'dummy',
      'process.pid': 22669,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
      'process.command_args': [
        '/Users/user/.local/share/mise/installs/node/22.15.0/bin/node',
        '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
        '-r',
        './src/instrumentation.sdk-manual.ts',
        'src/app.ts'
      ],
      'process.runtime.version': '22.15.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/user/blog-code/2025/05/opentelemetry-js/node_modules/ts-node/dist/bin.js',
      'process.owner': 'user',
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-http',
    version: '0.200.0',
    schemaUrl: undefined
  },
  traceId: '10da2e8c2be711fa2d78ea2c7cc5fcf4',
  parentSpanContext: undefined,
  traceState: undefined,
  name: 'GET /rolldice',
  id: '90ee83bac678a166',
  kind: 1,
  timestamp: 1746414807690000,
  duration: 11441.208,
  attributes: {
    'http.url': 'http://localhost:8080/rolldice',
    'http.host': 'localhost:8080',
    'net.host.name': 'localhost',
    'http.method': 'GET',
    'http.scheme': 'http',
    'http.target': '/rolldice',
    'http.user_agent': 'curl/8.7.1',
    'http.flavor': '1.1',
    'net.transport': 'ip_tcp',
    'net.host.ip': '::1',
    'net.host.port': 8080,
    'net.peer.ip': '::1',
    'net.peer.port': 50085,
    'http.status_code': 200,
    'http.status_text': 'OK',
    'http.route': '/rolldice'
  },
  status: { code: 0 },
  events: [],
  links: []
}

4. @opentelemetry/instrumentation と @opentelemetry/auto-instrumentations-node を組み合わせる方法

Section titled “4. @opentelemetry/instrumentation と @opentelemetry/auto-instrumentations-node を組み合わせる方法”

@opentelemetry/sdk-node ではなく、@opentelemetry/instrumentation を使用して計装する方法です。@opentelemetry/sdk-node を使用しない場合は、手動でトレーサーを作成する必要があります。

src/instrumentation.register-auto.ts
import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node";
import { registerInstrumentations } from "@opentelemetry/instrumentation";
import {
  ConsoleSpanExporter,
  NodeTracerProvider,
  SimpleSpanProcessor,
} from "@opentelemetry/sdk-trace-node";


const provider = new NodeTracerProvider({
  spanProcessors: [new SimpleSpanProcessor(new ConsoleSpanExporter())],
});


registerInstrumentations({
  instrumentations: [
    getNodeAutoInstrumentations({
      "@opentelemetry/instrumentation-fs": { enabled: false },
    }),
  ],
  tracerProvider: provider,
});


provider.register();
$ pnpm ts-node -r ./src/instrumentation.register-auto.ts src/app.ts
Terminal window
$ pnpm ts-node -r ./src/instrumentation.register-auto.ts src/app.ts
Listening for requests on http://localhost:8080
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '2f67891348370bbddabca37bc37978a3',
  parentSpanContext: {
    traceId: '2f67891348370bbddabca37bc37978a3',
    spanId: '1f2f25bdb99a3b89',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'middleware - query',
  id: 'eb4371e55ccad4e9',
  kind: 0,
  timestamp: 1746414878584000,
  duration: 552.625,
  attributes: {
    'http.route': '/',
    'express.name': 'query',
    'express.type': 'middleware'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '2f67891348370bbddabca37bc37978a3',
  parentSpanContext: {
    traceId: '2f67891348370bbddabca37bc37978a3',
    spanId: '1f2f25bdb99a3b89',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'middleware - expressInit',
  id: 'c14efced348d0f52',
  kind: 0,
  timestamp: 1746414878586000,
  duration: 255.959,
  attributes: {
    'http.route': '/',
    'express.name': 'expressInit',
    'express.type': 'middleware'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{"level":"info","message":"Received request to /rolldice","span_id":"0d61d7f123599c35","time":"2025-05-05T03:14:38.588Z","trace_flags":"01","trace_id":"2f67891348370bbddabca37bc37978a3"}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '2f67891348370bbddabca37bc37978a3',
  parentSpanContext: {
    traceId: '2f67891348370bbddabca37bc37978a3',
    spanId: '1f2f25bdb99a3b89',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'request handler - /rolldice',
  id: '0d61d7f123599c35',
  kind: 0,
  timestamp: 1746414878587000,
  duration: 6083.459,
  attributes: {
    'http.route': '/rolldice',
    'express.name': '/rolldice',
    'express.type': 'request_handler'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-http',
    version: '0.200.0',
    schemaUrl: undefined
  },
  traceId: '2f67891348370bbddabca37bc37978a3',
  parentSpanContext: undefined,
  traceState: undefined,
  name: 'GET /rolldice',
  id: '1f2f25bdb99a3b89',
  kind: 1,
  timestamp: 1746414878581000,
  duration: 13029,
  attributes: {
    'http.url': 'http://localhost:8080/rolldice',
    'http.host': 'localhost:8080',
    'net.host.name': 'localhost',
    'http.method': 'GET',
    'http.scheme': 'http',
    'http.target': '/rolldice',
    'http.user_agent': 'curl/8.7.1',
    'http.flavor': '1.1',
    'net.transport': 'ip_tcp',
    'net.host.ip': '::1',
    'net.host.port': 8080,
    'net.peer.ip': '::1',
    'net.peer.port': 50111,
    'http.status_code': 200,
    'http.status_text': 'OK',
    'http.route': '/rolldice'
  },
  status: { code: 0 },
  events: [],
  links: []
}

5. @opentelemetry/instrumentation と 個別のInstrumentationを組み合わせる方法

Section titled “5. @opentelemetry/instrumentation と 個別のInstrumentationを組み合わせる方法”

この方法は、registerInstrumentations を使って必要な Instrumentation を個別に指定し、柔軟に構成できる手動計装のパターンです。NodeTracerProvider を自分で生成し、provider.register() で有効化します。instrumentations 配列に必要なプラグイン（ここでは HTTP, Express, Winston）を追加することで、最小限の依存でトレース情報をログに付与できます。

src/instrumentation.register-manual.ts
import { registerInstrumentations } from "@opentelemetry/instrumentation";
import { ExpressInstrumentation } from "@opentelemetry/instrumentation-express";
import { HttpInstrumentation } from "@opentelemetry/instrumentation-http";
import { WinstonInstrumentation } from "@opentelemetry/instrumentation-winston";
import {
  ConsoleSpanExporter,
  NodeTracerProvider,
  SimpleSpanProcessor,
} from "@opentelemetry/sdk-trace-node";


const provider = new NodeTracerProvider({
  spanProcessors: [new SimpleSpanProcessor(new ConsoleSpanExporter())],
});


registerInstrumentations({
  instrumentations: [
    new HttpInstrumentation(),
    new ExpressInstrumentation(),
    new WinstonInstrumentation(),
  ],
  tracerProvider: provider,
});


provider.register();
$ pnpm ts-node -r ./src/instrumentation.register-manual.ts src/app.ts
Terminal window
$ pnpm ts-node -r ./src/instrumentation.register-manual.ts src/app.ts
Listening for requests on http://localhost:8080
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '17a08017da90a7b7eb10da4c93ba7144',
  parentSpanContext: {
    traceId: '17a08017da90a7b7eb10da4c93ba7144',
    spanId: '0ad8653a16b3730e',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'middleware - query',
  id: '61ea88320ca78bfd',
  kind: 0,
  timestamp: 1746414936322000,
  duration: 379.167,
  attributes: {
    'http.route': '/',
    'express.name': 'query',
    'express.type': 'middleware'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '17a08017da90a7b7eb10da4c93ba7144',
  parentSpanContext: {
    traceId: '17a08017da90a7b7eb10da4c93ba7144',
    spanId: '0ad8653a16b3730e',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'middleware - expressInit',
  id: '444aca524023ba11',
  kind: 0,
  timestamp: 1746414936324000,
  duration: 220.583,
  attributes: {
    'http.route': '/',
    'express.name': 'expressInit',
    'express.type': 'middleware'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{"level":"info","message":"Received request to /rolldice","span_id":"0215bc0c06da0089","time":"2025-05-05T03:15:36.325Z","trace_flags":"01","trace_id":"17a08017da90a7b7eb10da4c93ba7144"}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-express',
    version: '0.48.1',
    schemaUrl: undefined
  },
  traceId: '17a08017da90a7b7eb10da4c93ba7144',
  parentSpanContext: {
    traceId: '17a08017da90a7b7eb10da4c93ba7144',
    spanId: '0ad8653a16b3730e',
    traceFlags: 1,
    traceState: undefined
  },
  traceState: undefined,
  name: 'request handler - /rolldice',
  id: '0215bc0c06da0089',
  kind: 0,
  timestamp: 1746414936325000,
  duration: 4438.541,
  attributes: {
    'http.route': '/rolldice',
    'express.name': '/rolldice',
    'express.type': 'request_handler'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '2.0.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-http',
    version: '0.200.0',
    schemaUrl: undefined
  },
  traceId: '17a08017da90a7b7eb10da4c93ba7144',
  parentSpanContext: undefined,
  traceState: undefined,
  name: 'GET /rolldice',
  id: '0ad8653a16b3730e',
  kind: 1,
  timestamp: 1746414936321000,
  duration: 9306.334,
  attributes: {
    'http.url': 'http://localhost:8080/rolldice',
    'http.host': 'localhost:8080',
    'net.host.name': 'localhost',
    'http.method': 'GET',
    'http.scheme': 'http',
    'http.target': '/rolldice',
    'http.user_agent': 'curl/8.7.1',
    'http.flavor': '1.1',
    'net.transport': 'ip_tcp',
    'net.host.ip': '::1',
    'net.host.port': 8080,
    'net.peer.ip': '::1',
    'net.peer.port': 50235,
    'http.status_code': 200,
    'http.status_text': 'OK',
    'http.route': '/rolldice'
  },
  status: { code: 0 },
  events: [],
  links: []
}

NodeSDK vs registerInstrumentations

Section titled “NodeSDK vs registerInstrumentations”

@opentelemetry/sdk-node パッケージが提供する NodeSDK クラスと、@opentelemetry/instrumentation パッケージが提供する registerInstrumentations 関数の違いについて気になっていたので、コードリーディングをしてみました。

わかったこととして、NodeSDK は、トレーシングやメトリクスの計装を簡単に行うためのラッパーで、内部で registerInstrumentations を使用しています。
どちらの方法でも計装は可能ですが、NodeSDK を利用すると計装の設定や初期化がより簡単に行えるというメリットがあります。

opentelemetry-js/experimental/packages/opentelemetry-sdk-node/src/sdk.ts
export class NodeSDK {
  // ...省略...


  public start(): void {
    if (this._disabled) {
      return;
    }


    registerInstrumentations({
      instrumentations: this._instrumentations,
    });


  // ...省略...
  }
  // ...省略...
}

引用：https://github.com/open-telemetry/opentelemetry-js/blob/v2.0.0/experimental/packages/opentelemetry-sdk-node/src/sdk.ts#L335-L342

Winston: ログへの trace_id 挿入メカニズム (コードリーディング)

Section titled “Winston: ログへの trace_id 挿入メカニズム (コードリーディング)”

このセクションでは、@opentelemetry/instrumentation-winston を使用して、Winston のログに trace_id を挿入するメカニズムをコードリーディングします。

src/instrumentation.winston.ts
import { registerInstrumentations } from "@opentelemetry/instrumentation";
import { HttpInstrumentation } from "@opentelemetry/instrumentation-http";
import { WinstonInstrumentation } from "@opentelemetry/instrumentation-winston";
import {
  ConsoleSpanExporter,
  NodeTracerProvider,
  SimpleSpanProcessor,
} from "@opentelemetry/sdk-trace-node";


const provider = new NodeTracerProvider({
  spanProcessors: [new SimpleSpanProcessor(new ConsoleSpanExporter())],
});


registerInstrumentations({
  instrumentations: [new HttpInstrumentation(), new WinstonInstrumentation()],
  tracerProvider: provider,
});


provider.register();

実際に実行した結果は以下のようになります。

Terminal window
$ pnpm ts-node -r ./src/instrumentation.winston.ts src/app.ts
Listening for requests on http://localhost:8080
{"level":"info","message":"Received request to /rolldice","span_id":"8f68009a9be86a4d","time":"2025-05-04T14:15:07.848Z","trace_flags":"01","trace_id":"37860a461a51356ca3aa171ce39628b4"}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      # ...省略...
    }
  },
}

@opentelemetry/instrumentation-winston

Section titled “@opentelemetry/instrumentation-winston”

はじめに、@opentelemetry/instrumentation-winston の中身を見てみましょう。

@opentelemetry/instrumentation-winston は、Winston のログにトレース情報を挿入するための計装ライブラリです。具体的には、Winston のログメッセージに trace_id や span_id を追加します。
コードを読んでみると @opentelemetry/instrumentation-winston は Span が存在する場合、ログとして出力するレコードに Object.assign を使うことで trace_id や span_id を自動的に挿入するようです。

plugins/node/opentelemetry-instrumentation-winston/src/instrumentation.ts
export class WinstonInstrumentation extends InstrumentationBase<WinstonInstrumentationConfig> {
  // ...省略...


  private _handleLogCorrelation(record: Record<string, string>) {
    if (!this.getConfig().disableLogCorrelation) {
      const span = trace.getSpan(context.active());
      if (span) {
        const spanContext = span.spanContext();
        if (isSpanContextValid(spanContext)) {
          const fields = {
            trace_id: spanContext.traceId,
            span_id: spanContext.spanId,
            trace_flags: `0${spanContext.traceFlags.toString(16)}`,
          };
          const enhancedRecord = Object.assign(record, fields);
          this._callHook(span, enhancedRecord);
          return enhancedRecord;
        }
      }
    }
    return record;
  }
  // ...省略...
}

引用：https://github.com/open-telemetry/opentelemetry-js-contrib/blob/instrumentation-winston-v0.45.0/plugins/node/opentelemetry-instrumentation-winston/src/instrumentation.ts#L227-L245

理解しやすくするために、簡単なコードを書いてみました。

const record = {
  message: "Received request to /rolldice",
  level: "info",
  // [Symbol(level)]: 'info'
};


const fields = {
  trace_id: "aaaaa",
  span_id: "bbbb",
  trace_flags: "01",
};


const enhandedRecord = Object.assign(record, fields);
console.log(enhandedRecord);


// output:
// {
//   "message": "Received request to /rolldice",
//   "level": "info",
//   "trace_id": "aaaaa",
//   "span_id": "bbbb",
//   "trace_flags": "01"
// }

TypesScript playground

ここでコードリーディングを終わってもいいのですが、せっかくなので、もう少し深掘りしてみます。 _handleLogCorrelation メソッドの呼び出し元は、WinstonInstrumentation クラスの _getPatchedWrite メソッドです。

plugins/node/opentelemetry-instrumentation-winston/src/instrumentation.ts
export class WinstonInstrumentation extends InstrumentationBase<WinstonInstrumentationConfig> {
  // ...省略...


  private _getPatchedWrite() {
    return (original: Winston3LogMethod) => {
      const instrumentation = this;
      return function patchedWrite(
        this: never,
        ...args: Parameters<typeof original>
      ) {
        const record = args[0];
        instrumentation._handleLogCorrelation(record);
        return original.apply(this, args);
      };
    };
  }
  // ...省略...
}

https://github.com/open-telemetry/opentelemetry-js-contrib/blob/instrumentation-winston-v0.45.0/plugins/node/opentelemetry-instrumentation-winston/src/instrumentation.ts#L134-L146

さらに _getPatchedWrite メソッドは、WinstonInstrumentation クラスの init メソッドで呼び出されます。
どうやら、WinstonInstrumentation クラスの init メソッドで、Winston の logger.prototype.write メソッドをラップしているようです。

さて _wrap メソッドは何者でしょうか？

plugins/node/opentelemetry-instrumentation-winston/src/instrumentation.ts
export class WinstonInstrumentation extends InstrumentationBase<WinstonInstrumentationConfig> {
  // ...省略...


  protected init() {
    const winstons3instrumentationNodeModuleDefinition =
      new InstrumentationNodeModuleDefinition(
        'winston',
        winston3Versions,
        moduleExports => moduleExports,
        () => {},
        [
          new InstrumentationNodeModuleFile(
            'winston/lib/winston/logger.js',
            winston3Versions,
            (logger: Winston3Logger) => {
              if (isWrapped(logger.prototype['write'])) {
                this._unwrap(logger.prototype, 'write');
              }
              this._wrap(logger.prototype, 'write', this._getPatchedWrite());


              // ...省略...


              return logger;
            },
            // ...省略...
          ),
        ]
      );
}

https://github.com/open-telemetry/opentelemetry-js-contrib/blob/instrumentation-winston-v0.45.0/plugins/node/opentelemetry-instrumentation-winston/src/instrumentation.ts#L45-L81

@opentelemetry/instrumentation

Section titled “@opentelemetry/instrumentation”

WinstonInstrumentation クラスは、 @opentelemetry/instrumentation パッケージの InstrumentationBase クラスを継承しています。その InstrumentationBase クラスの _wrap メソッドは、モジュールのメソッドをラップするためのメソッドです。

_wrap メソッドは、さらに内部で、wrap 関数を使用しています。次は wrap 関数を import している shimmer パッケージを見てみます。

experimental/packages/opentelemetry-instrumentation/src/platform/node/instrumentation.ts
export abstract class InstrumentationBase<
    ConfigType extends InstrumentationConfig = InstrumentationConfig,
  >
  extends InstrumentationAbstract<ConfigType>
  implements types.Instrumentation<ConfigType>
{
  // ...省略...


  protected override _wrap: typeof wrap = (moduleExports, name, wrapper) => {
    if (isWrapped(moduleExports[name])) {
      this._unwrap(moduleExports, name);
    }
    if (!utilTypes.isProxy(moduleExports)) {
      // メモ：_getPatchedWrite メソッドは Proxy オブジェクトではないため、この条件分岐に入る
      return wrap(moduleExports, name, wrapper);
    } else {
      const wrapped = wrap(Object.assign({}, moduleExports), name, wrapper);
      Object.defineProperty(moduleExports, name, {
        value: wrapped,
      });
      return wrapped;
    }
  };


  // ...省略...
}

https://github.com/open-telemetry/opentelemetry-js/blob/v2.0.0/experimental/packages/opentelemetry-instrumentation/src/platform/node/instrumentation.ts#L74-L87

shimmer

Section titled “shimmer”

shimmer は、Node.js のモジュールのメソッドをラップし、デフォルトの振る舞いを変更するライブラリです。

shimmer は内部で Object.defineProperty を使用して、元のメソッドをラップした新しいメソッドで上書きしています。

shimmer/index.js
function defineProperty (obj, name, value) {
  var enumerable = !!obj[name] && obj.propertyIsEnumerable(name)
  Object.defineProperty(obj, name, {
    configurable: true,
    enumerable: enumerable,
    writable: true,
    value: value
  })
}


// ...省略...


function wrap (nodule, name, wrapper) {
  // ...省略（引数のバリデーション）...


  var original = nodule[name]
  var wrapped = wrapper(original, name)


  defineProperty(wrapped, '__original', original)
  defineProperty(wrapped, '__unwrap', function () {
    if (nodule[name] === wrapped) defineProperty(nodule, name, original)
  })
  defineProperty(wrapped, '__wrapped', true)


  defineProperty(nodule, name, wrapped)
  return wrapped
}

https://github.com/othiym23/shimmer/blob/v1.2.0/index.js#L12-L58

まとめ

Section titled “まとめ”

この記事では、OpenTelemetry JS SDK がどのようにして構造化ログに trace_id を自動で付与するのか、その仕組みを学習しました。

@opentelemetry/instrumentation-winston のようなロギングライブラリ用の Instrumentation が、write といったメソッドをラップ（パッチ）します。ログ出力が呼び出されると、Instrumentation は現在の Context から trace_id や span_id を取得し、それらをログレコードに自動的に挿入する流れを学習しました。

計装方法には、NodeSDK を使う方法や registerInstrumentations を直接使う方法など、複数の選択肢があることも学びました。NodeSDK は設定を簡略化する高レベル API であり、registerInstrumentations はより細かい制御が可能な低レベル API です。プロジェクトの要件に応じて適切な方法を選択することが重要だと考えられます。

これらの仕組みにより、開発者は既存のログ出力コードを変更することなく、ログとトレースの自動的な紐付けを実現できます。OpenTelemetry を活用することで、問題発生時の原因究明やパフォーマンス分析がより効率的になることを期待します。今後は、他の Instrumentation の活用や、収集したデータをバックエンドに送信する Exporter の設定などを試していきたいです。

参考

Section titled “参考”

おまけ

Section titled “おまけ”

ここではコードリーディングでわかったことをメモしておきます。

context は globalThis から確認できる

Section titled “context は globalThis から確認できる”

context は ContextAPI クラスから取得でき、このオブジェクトはシングルトンです。

https://github.com/open-telemetry/opentelemetry-js/blob/v2.0.0/api/src/api/context.ts https://github.com/open-telemetry/opentelemetry-js/blob/v2.0.0/api/src/internal/global-utils.ts#L78

実際にコードから確認してみると、globalThis に opentelemetry.js.api.1 というシンボルが定義されていることがわかりました。

const GLOBAL_OPENTELEMETRY_API_KEY = Symbol.for(`opentelemetry.js.api.1`);


// @ts-ignore
console.log(globalThis[GLOBAL_OPENTELEMETRY_API_KEY].context);
Tags: