Hono のログを Pino と OpenTelemetry で計装する

Hono + Pino
  ├── Logs   ── OTLP/HTTP ──┐
  └── Traces ── OTLP/HTTP ──┘
                            ▼
                 OpenTelemetry Collector
                   ├── Loki（ログ）
                   └── Tempo（トレース）
                            ▼
                         Grafana

tracer.startActiveSpan("userRepository.findById", async (span) => {
  // この時点では span がアクティブ
  logger.info("finding user");
  // Pino Instrumentation が span の Trace ID・Span ID を自動付与
});

npm create hono@latest hono-otel-logs -- --template nodejs --install --pm npm
cd hono-otel-logs

npm install \
  [email protected] \
  @opentelemetry/[email protected] \
  @opentelemetry/[email protected] \
  @opentelemetry/[email protected] \
  @opentelemetry/[email protected] \
  @opentelemetry/[email protected] \
  @opentelemetry/[email protected] \
  @opentelemetry/[email protected] \
  @opentelemetry/[email protected]

import { OTLPLogExporter } from "@opentelemetry/exporter-logs-otlp-proto";
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-proto";
import { HttpInstrumentation } from "@opentelemetry/instrumentation-http";
import { PinoInstrumentation } from "@opentelemetry/instrumentation-pino";
import { BatchLogRecordProcessor } from "@opentelemetry/sdk-logs";
import { NodeSDK } from "@opentelemetry/sdk-node";
 
// トレースとログを OTLP/HTTP で Collector へ送信する
const sdk = new NodeSDK({
  traceExporter: new OTLPTraceExporter(),
  logRecordProcessors: [
    new BatchLogRecordProcessor({
      exporter: new OTLPLogExporter(),
    }),
  ],
  // 必要なライブラリだけを個別に計装する
  instrumentations: [
    new HttpInstrumentation(),
    new PinoInstrumentation(),
  ],
});
 
sdk.start();
 
export const shutdownTelemetry = () => sdk.shutdown();

import pino from "pino";
 
export const logger = pino({
  // 環境変数がなければ info 以上のログを出力する
  level: process.env.LOG_LEVEL ?? "info",
});

logger.info({ "app.user.id": "1" }, "finding user");

import { SpanStatusCode, trace } from "@opentelemetry/api";
import { setTimeout } from "node:timers/promises";
import { logger } from "./logger.js";
 
type User = {
  id: string;
  name: string;
};
 
const users = new Map<string, User>([
  ["1", { id: "1", name: "Alice" }],
]);
const tracer = trace.getTracer("user-repository");
 
export const findUserById = (id: string) =>
  // 現在アクティブな HTTP スパンが親として使用される
  tracer.startActiveSpan("userRepository.findById", async (span) => {
    span.setAttribute("app.user.id", id);
 
    try {
      logger.info({ "app.user.id": id }, "finding user");
      // データベースアクセスにかかる時間を再現する
      await setTimeout(50);
 
      if (id === "error") {
        throw new Error("database is unavailable");
      }
 
      const user = users.get(id);
      if (!user) {
        logger.warn({ "app.user.id": id }, "user not found");
        return undefined;
      }
 
      logger.info({ "app.user.id": id }, "user found");
      return user;
    } catch (error) {
      const exception =
        error instanceof Error ? error : new Error(String(error));
 
      // 例外の内容とエラーステータスをスパンに記録する
      span.recordException(exception);
      span.setStatus({
        code: SpanStatusCode.ERROR,
        message: exception.message,
      });
      logger.error(
        { err: exception, "app.user.id": id },
        "failed to find user",
      );
      throw exception;
    } finally {
      span.end();
    }
  });

GET /users/:id              ← 親：HTTPスパン
└── userRepository.findById ← 子：アプリケーションスパン

import { serve } from "@hono/node-server";
import { trace } from "@opentelemetry/api";
import { Hono } from "hono";
import { routePath } from "hono/route";
import { shutdownTelemetry } from "./instrumentation.js";
import { logger } from "./logger.js";
import { findUserById } from "./userRepository.js";
 
const app = new Hono();
 
// "*" はすべてのリクエストにマッチするワイルドカード
// レスポンスの完了後にリクエストログを 1 件出力する
app.use("*", async (c, next) => {
  const startedAt = performance.now();
 
  await next();
 
  // 最後にマッチしたエンドポイントのルートを取得する
  const route = routePath(c, -1);
  const span = trace.getActiveSpan();
  span?.setAttribute("http.route", route);
  span?.updateName(`${c.req.method} ${route}`);
 
  const attributes = {
    "http.request.method": c.req.method,
    "http.route": route,
    "url.path": c.req.path,
    "http.response.status_code": c.res.status,
    "app.duration_ms": performance.now() - startedAt,
  };
 
  // HTTP ステータスコードに応じてログレベルを切り替える
  if (c.res.status >= 500) {
    logger.error(attributes, "request completed");
  } else if (c.res.status >= 400) {
    logger.warn(attributes, "request completed");
  } else {
    logger.info(attributes, "request completed");
  }
});
 
app.get("/users/:id", async (c) => {
  const user = await findUserById(c.req.param("id"));
 
  if (!user) {
    return c.json({ message: "User not found" }, 404);
  }
 
  return c.json(user);
});
 
app.onError((_error, c) => {
  return c.json({ message: "Internal Server Error" }, 500);
});
 
const server = serve(
  {
    fetch: app.fetch,
    port: 3001,
  },
  (info) => {
    logger.info({ port: info.port }, "server started");
  },
);
 
// graceful shutdown
const shutdown = (signal: NodeJS.Signals) => {
  logger.info({ signal }, "shutting down");
  server.close(async () => {
    // バッファに残っているログとトレースを送信して終了する
    await shutdownTelemetry();
    process.exit(0);
  });
};
 
process.once("SIGINT", shutdown);
process.once("SIGTERM", shutdown);

{
  "scripts": {
    "dev": "node --experimental-loader=@opentelemetry/instrumentation/hook.mjs --import tsx --import ./src/instrumentation.ts --watch src/index.ts",
    "build": "tsc",
    "start": "node --experimental-loader=@opentelemetry/instrumentation/hook.mjs --import ./dist/instrumentation.js dist/index.js"
  }
}

(node:12345) ExperimentalWarning: `--experimental-loader` may be removed in the future; instead use `register()`:
--import 'data:text/javascript,import { register } from "node:module"; import { pathToFileURL } from "node:url"; register("%40opentelemetry/instrumentation/hook.mjs", pathToFileURL("./"));'

docker run --rm \
  --name otel-lgtm \
  -p 3000:3000 \
  -p 4317:4317 \
  -p 4318:4318 \
  grafana/otel-lgtm:0.29.2

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: 0.0.0.0:4317
      http:
        endpoint: 0.0.0.0:4318
 
processors:
  # データをまとめてバックエンドへ送信する
  batch:
 
exporters:
  # トレースを Tempo へ送信する
  otlphttp/traces:
    endpoint: http://127.0.0.1:4418
    tls:
      insecure: true
 
  # ログを Loki へ送信する
  otlphttp/logs:
    endpoint: http://127.0.0.1:3100/otlp
    tls:
      insecure: true
 
service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [batch]
      exporters: [otlphttp/traces]
 
    logs:
      receivers: [otlp]
      processors: [batch]
      exporters: [otlphttp/logs]

OTEL_SERVICE_NAME=hono-api \
OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4318 \
OTEL_EXPORTER_OTLP_PROTOCOL=http/protobuf \
npm run dev

curl -i http://127.0.0.1:3001/users/1
curl -i http://127.0.0.1:3001/users/unknown
curl -i http://127.0.0.1:3001/users/error

{
  "level": 50,
  "time": 1785644315215,
  "pid": 86258,
  "hostname": "localhost",
  "trace_id": "631f628fcedda17b3ddfdb209c5dbade",
  "span_id": "17e6f76c36eaf37a",
  "trace_flags": "01",
  "err": {
    "type": "Error",
    "message": "database is unavailable",
    "stack": "Error: database is unavailable\n    at <anonymous> (/app/src/userRepository.ts:19:15)\n    ..."
  },
  "app.user.id": "error",
  "msg": "failed to find user"
}
{
  "level": 50,
  "time": 1785644315215,
  "pid": 86258,
  "hostname": "localhost",
  "trace_id": "631f628fcedda17b3ddfdb209c5dbade",
  "span_id": "34e27910106cc378",
  "trace_flags": "01",
  "http.request.method": "GET",
  "http.route": "/users/:id",
  "url.path": "/users/error",
  "http.response.status_code": 500,
  "app.duration_ms": 53.476,
  "msg": "request completed"
}

{service_name="hono-api"} | detected_level = "error"