feat(otel): collect api response logs

Author: yoshinorin

__tests__/unit/otel/logger.test.ts

@@ -0,0 +1,27 @@
+import { SeverityNumber } from "@opentelemetry/api-logs";
+import { expect, test } from "vitest";
+import { isKnownLevel, toSeverityNumber } from "../../../src/otel/logger";
+
+test("toSeverityNumber maps known levels", () => {
+  expect(toSeverityNumber("debug")).toBe(SeverityNumber.DEBUG);
+  expect(toSeverityNumber("info")).toBe(SeverityNumber.INFO);
+  expect(toSeverityNumber("warn")).toBe(SeverityNumber.WARN);
+  expect(toSeverityNumber("error")).toBe(SeverityNumber.ERROR);
+});
+
+test("toSeverityNumber handles casing and trimming", () => {
+  expect(toSeverityNumber("  INFO ")).toBe(SeverityNumber.INFO);
+  expect(toSeverityNumber("Warn")).toBe(SeverityNumber.WARN);
+});
+
+test("toSeverityNumber returns UNSPECIFIED for unknown", () => {
+  expect(toSeverityNumber("unknown" as any)).toBe(SeverityNumber.UNSPECIFIED);
+  expect(toSeverityNumber("")).toBe(SeverityNumber.UNSPECIFIED);
+  expect(toSeverityNumber(undefined as any)).toBe(SeverityNumber.UNSPECIFIED);
+  expect(toSeverityNumber(null as any)).toBe(SeverityNumber.UNSPECIFIED);
+});
+
+test("isKnownLevel", () => {
+  expect(isKnownLevel("info")).toBe(true);
+  expect(isKnownLevel("foo")).toBe(false);
+});

src/api/request.ts

@@ -1,6 +1,7 @@
 import { RequestContext } from "../models/models";
+import { emit } from "../otel/logger";
 import { injectPropagation } from "../otel/propagation";
-import { logger } from "../utils/logger";
+import { makeInstance } from "../utils/logger";
 import { isMatch } from "../utils/match";
 
 export type RequestOptions = {
@@ -9,6 +10,8 @@ export type RequestOptions = {
   blockIgnoredPaths?: boolean;
 };
 
+const logger = makeInstance(emit);
+
 // TODO: write test code
 // TODO: more simply
 export async function fetchFromApi(
@@ -28,17 +31,18 @@ export async function fetchFromApi(
   const url = buildRequestUrl(endpoint, queryParams);
   const header = headers ? { header: headers } : {};
   const startTime = Date.now();
+  const method = "GET";
 
   const response = await fetch(url, {
-    method: "GET",
+    method: method,
     cache: "no-cache",
     headers: header as any
   });
 
   const duration = Date.now() - startTime;
   logger.httpResponse(
     "HTTP Response",
-    "GET",
+    method,
     url,
     response.status,
     duration,

src/instrumentation.ts

@@ -3,11 +3,6 @@ import { getOtelConfig } from "./otel/config";
 export async function register() {
   if (process.env.NEXT_RUNTIME === "nodejs") {
     const otelConfig = getOtelConfig();
-
-    // NOTE: Explicitly initialize the logger here.
-    const { logger } = await import("./utils/logger");
-    logger.info({ message: "logger initialized" });
-
     await import("./otel/lifecycle").then(({ initializeOtel }) =>
       initializeOtel(otelConfig)
     );

src/otel/logger.ts

@@ -0,0 +1,53 @@
+import { context, trace } from "@opentelemetry/api";
+import { logs, SeverityNumber } from "@opentelemetry/api-logs";
+import type { PostProcess } from "../utils/logger";
+
+const levelMap: Record<string, SeverityNumber> = {
+  debug: SeverityNumber.DEBUG,
+  info: SeverityNumber.INFO,
+  warn: SeverityNumber.WARN,
+  error: SeverityNumber.ERROR
+};
+
+export function toSeverityNumber(
+  level: string | undefined | null
+): SeverityNumber {
+  if (!level) {
+    return SeverityNumber.UNSPECIFIED;
+  }
+  const key = level.toLowerCase().trim();
+  return levelMap[key] ?? SeverityNumber.UNSPECIFIED;
+}
+
+export function isKnownLevel(level: string): boolean {
+  return levelMap[level.toLowerCase()] !== undefined;
+}
+
+export const emit: PostProcess = (
+  level: string,
+  message: string,
+  metadata: Record<string, any>
+) => {
+  try {
+    const severity = toSeverityNumber(level);
+    const span = trace.getSpan(context.active());
+    const attrs: Record<string, any> = { ...metadata };
+    if (span) {
+      const spanContext = span.spanContext();
+      attrs.trace_id = spanContext.traceId;
+      attrs.span_id = spanContext.spanId;
+    }
+    const logger = logs.getLogger("quintet-logger");
+    logger.emit({
+      body:
+        metadata && Object.keys(metadata).length > 0
+          ? { ...metadata, message }
+          : message,
+      severityNumber: severity,
+      severityText: SeverityNumber[severity],
+      attributes: attrs
+    });
+  } catch {
+    // Nothing todo
+  }
+};

src/utils/logger.ts

@@ -4,34 +4,49 @@ interface LogMetadata {
   [key: string]: any;
 }
 
-class PinoLogger {
+export type PostProcess = (
+  level: string,
+  message: string,
+  metadata: Record<string, any>
+) => void;
+const noop: PostProcess = () => {};
+
+export class PinoLogger {
   private pinoLogger: pino.Logger;
+  private postProcess: PostProcess;
 
-  constructor() {
+  constructor(postProcess: PostProcess = noop) {
     this.pinoLogger = pino({
       level: process.env.NODE_ENV === "production" ? "info" : "debug",
-      formatters: {
-        level: (label) => ({ level: label })
-      },
+      formatters: { level: (label) => ({ level: label }) },
       timestamp: pino.stdTimeFunctions.isoTime,
       messageKey: "message"
     });
+    this.postProcess = postProcess;
   }
 
   debug(metadata: LogMetadata) {
-    this.pinoLogger.debug(metadata || {});
+    const meta = metadata || {};
+    this.pinoLogger.debug(meta);
+    this.postProcess("debug", meta.message, meta);
   }
 
   info(metadata: LogMetadata) {
-    this.pinoLogger.info(metadata || {});
+    const meta = metadata || {};
+    this.pinoLogger.info(meta);
+    this.postProcess("info", meta.message, meta);
   }
 
   warn(metadata: LogMetadata) {
-    this.pinoLogger.warn(metadata || {});
+    const meta = metadata || {};
+    this.pinoLogger.warn(meta);
+    this.postProcess("warn", meta.message, meta);
   }
 
   error(metadata: LogMetadata) {
-    this.pinoLogger.error(metadata || {});
+    const meta = metadata || {};
+    this.pinoLogger.error(meta);
+    this.postProcess("error", meta.message, meta);
   }
 
   httpResponse(
@@ -61,5 +76,12 @@ class PinoLogger {
   }
 }
 
-// Singleton instance
-export const logger = new PinoLogger();
+let instance: PinoLogger | undefined;
+let initialized = false;
+export function makeInstance(postProcess?: PostProcess): PinoLogger {
+  if (!initialized || !instance) {
+    instance = new PinoLogger(postProcess || noop);
+    initialized = true;
+  }
+  return instance;
+}