feat: setup o11y (#18)

* feat: setup otel libraries and initialised with env specific exporters

* feat: added logging

* fix: introduced request metrics

* fix: added error logger

* fix: fixed issues

bunfig.toml

@@ -1,4 +1,4 @@
 [test]
-
 # always enable coverage
-coverage = true
+coverage = true
+

package.json

@@ -15,8 +15,20 @@
     "typescript": "^5.0.0"
   },
   "dependencies": {
+    "@opentelemetry/api": "^1.9.0",
+    "@opentelemetry/auto-instrumentations-node": "^0.47.0",
+    "@opentelemetry/exporter-logs-otlp-http": "^0.52.0",
+    "@opentelemetry/exporter-metrics-otlp-http": "^0.52.0",
+    "@opentelemetry/instrumentation-express": "^0.40.1",
+    "@opentelemetry/instrumentation-http": "^0.52.0",
+    "@opentelemetry/instrumentation-winston": "^0.38.0",
+    "@opentelemetry/sdk-metrics": "^1.25.0",
+    "@opentelemetry/sdk-node": "^0.52.0",
+    "@opentelemetry/sdk-trace-node": "^1.25.0",
+    "@opentelemetry/winston-transport": "^0.4.0",
     "env-var": "^7.5.0",
-    "express": "^4.19.2"
+    "express": "^4.19.2",
+    "winston": "^3.13.0"
   },
   "scripts": {
     "prepare": "if test \"$NODE_ENV\" != \"production\" ; then husky ; fi"

src/app.ts

@@ -1,19 +1,37 @@
-import express from "express";
+import express, { Router } from "express";
 import { config } from "./init/config";
+import { initOtel } from "./init/otel";
+import { getLogger } from "./init/logger";
+import { getOTELMiddleware, getRequestErrorHandler } from "./middleware";
+import { getReqMetrics } from "./init/metrics";
 
 export const app = express();
 
-app.get("/", (req, res) => {
-  res.send("Hello World!");
-});
+export function start() {
+  initOtel();
+  const logger = getLogger();
+  const reqMetrics = getReqMetrics();
 
-app.get("/metadata", (req, res) => {
-  res.json({
-    gitSHA: config.gitSHA,
+  const router = Router();
+  router.use(getOTELMiddleware(logger, reqMetrics));
+  router.get("/", (req, res) => {
+    res.send("Hello World!");
   });
-});
 
-export function start() {
+  router.get("/metadata/:id", (req, res) => {
+    res.status(200).json({
+      gitSHA: config.gitSHA,
+    });
+  });
+
+  router.get("/error", (req, res, next) => {
+    next(new Error("This is a test error"));
+  });
+
+  router.use(getRequestErrorHandler(logger));
+
+  app.use("/", router);
+
   app.listen(config.port, () => {
     console.log(`Server is running on port ${config.port}`);
   });

src/init/logger.ts

@@ -0,0 +1,8 @@
+import { createLogger } from "winston";
+import { OpenTelemetryTransportV3 } from "@opentelemetry/winston-transport";
+
+export function getLogger() {
+  return createLogger({
+    transports: [new OpenTelemetryTransportV3()],
+  });
+}

src/init/metrics.ts

@@ -0,0 +1,16 @@
+import { metrics, type Counter, type UpDownCounter } from "@opentelemetry/api";
+
+export interface RequestMetrics {
+  totalRequestsCounter: Counter;
+  totalErrorsCounter: Counter;
+  inProgressRequestsGauge: UpDownCounter;
+}
+
+export function getReqMetrics(): RequestMetrics {
+  const meter = metrics.getMeter("request");
+  return {
+    totalRequestsCounter: meter.createCounter("requests.total"),
+    totalErrorsCounter: meter.createCounter("requests.errors"),
+    inProgressRequestsGauge: meter.createUpDownCounter("requests.in_progress"),
+  };
+}

src/init/otel/index.ts

@@ -0,0 +1,47 @@
+import { Resource } from "@opentelemetry/resources";
+import os from "os";
+import {
+  SEMRESATTRS_SERVICE_NAME,
+  SEMRESATTRS_DEPLOYMENT_ENVIRONMENT,
+  SEMRESATTRS_HOST_NAME,
+  SEMRESATTRS_HOST_ARCH,
+  SEMRESATTRS_SERVICE_VERSION,
+  SEMRESATTRS_PROCESS_PID,
+  SEMRESATTRS_PROCESS_EXECUTABLE_NAME,
+  SEMRESATTRS_PROCESS_EXECUTABLE_PATH,
+  SEMRESATTRS_PROCESS_COMMAND_ARGS,
+  SEMRESATTRS_PROCESS_RUNTIME_VERSION,
+  SEMRESATTRS_PROCESS_RUNTIME_NAME,
+  SEMRESATTRS_PROCESS_RUNTIME_DESCRIPTION,
+  SEMRESATTRS_PROCESS_COMMAND,
+  SEMRESATTRS_PROCESS_OWNER,
+} from "@opentelemetry/semantic-conventions";
+import { initLogging } from "./logs";
+import { initMetrics } from "./metrics";
+import { initTracing } from "./traces";
+
+const resource = Resource.default().merge(
+  new Resource({
+    [SEMRESATTRS_SERVICE_NAME]: process.env.SERVICE_NAME,
+    [SEMRESATTRS_DEPLOYMENT_ENVIRONMENT]: process.env.DEPLOYMENT_ENVIRONMENT,
+    [SEMRESATTRS_HOST_NAME]: os.hostname(),
+    [SEMRESATTRS_HOST_ARCH]: os.arch(),
+    [SEMRESATTRS_SERVICE_VERSION]: process.env.GIT_SHA,
+    [SEMRESATTRS_PROCESS_PID]: process.pid,
+    [SEMRESATTRS_PROCESS_EXECUTABLE_NAME]: process.title,
+    [SEMRESATTRS_PROCESS_EXECUTABLE_PATH]: process.argv[0],
+    [SEMRESATTRS_PROCESS_COMMAND_ARGS]: process.argv.slice(1),
+    [SEMRESATTRS_PROCESS_RUNTIME_VERSION]: process.version,
+    [SEMRESATTRS_PROCESS_RUNTIME_NAME]: "bun",
+    [SEMRESATTRS_PROCESS_RUNTIME_DESCRIPTION]:
+      "Node.js compatible runtime for bun.",
+    [SEMRESATTRS_PROCESS_COMMAND]: process.argv.join(" "),
+    [SEMRESATTRS_PROCESS_OWNER]: os.userInfo().username,
+  }),
+);
+
+export function initOtel() {
+  initLogging(resource);
+  initMetrics(resource);
+  initTracing(resource);
+}

src/init/otel/logs.ts

@@ -0,0 +1,24 @@
+import * as logsAPI from "@opentelemetry/api-logs";
+import { Resource } from "@opentelemetry/resources";
+import {
+  LoggerProvider,
+  SimpleLogRecordProcessor,
+  BatchLogRecordProcessor,
+  ConsoleLogRecordExporter,
+} from "@opentelemetry/sdk-logs";
+import { OTLPLogExporter } from "@opentelemetry/exporter-logs-otlp-http";
+
+export function initLogging(resource: Resource) {
+  const isProduction = process.env.NODE_ENV === "production";
+  const loggerProvider = new LoggerProvider({ resource });
+  const exporter = isProduction
+    ? new OTLPLogExporter()
+    : new ConsoleLogRecordExporter();
+
+  const processor = isProduction
+    ? new BatchLogRecordProcessor(exporter)
+    : new SimpleLogRecordProcessor(exporter);
+
+  loggerProvider.addLogRecordProcessor(processor);
+  logsAPI.logs.setGlobalLoggerProvider(loggerProvider);
+}

src/init/otel/metrics.ts

@@ -0,0 +1,26 @@
+import opentelemetry from "@opentelemetry/api";
+import {
+  ConsoleMetricExporter,
+  MeterProvider,
+  PeriodicExportingMetricReader,
+} from "@opentelemetry/sdk-metrics";
+import { Resource } from "@opentelemetry/resources";
+import { OTLPMetricExporter } from "@opentelemetry/exporter-metrics-otlp-http";
+
+export function initMetrics(resource: Resource) {
+  const isProduction = process.env.NODE_ENV === "production";
+  const exporter = isProduction
+    ? new OTLPMetricExporter()
+    : new ConsoleMetricExporter();
+
+  const metricReader = new PeriodicExportingMetricReader({
+    exporter,
+  });
+
+  const meterProvider = new MeterProvider({
+    resource: resource,
+    readers: [metricReader],
+  });
+
+  opentelemetry.metrics.setGlobalMeterProvider(meterProvider);
+}

src/init/otel/traces.ts

@@ -0,0 +1,23 @@
+import { Resource } from "@opentelemetry/resources";
+import {
+  SimpleSpanProcessor,
+  ConsoleSpanExporter,
+  BatchSpanProcessor,
+} from "@opentelemetry/sdk-trace-base";
+import { NodeTracerProvider } from "@opentelemetry/sdk-trace-node";
+import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
+
+export function initTracing(resource: Resource) {
+  const traceProvider = new NodeTracerProvider({ resource });
+  const isProduction = process.env.NODE_ENV === "production";
+  const exporter = isProduction
+    ? new OTLPTraceExporter()
+    : new ConsoleSpanExporter();
+
+  const spanProcessor = isProduction
+    ? new BatchSpanProcessor(exporter)
+    : new SimpleSpanProcessor(exporter);
+
+  traceProvider.addSpanProcessor(spanProcessor);
+  traceProvider.register();
+}

src/middleware/errorLogger.ts

@@ -0,0 +1,15 @@
+import type { ErrorRequestHandler } from "express";
+import type { Logger } from "winston";
+
+export function getRequestErrorHandler(logger: Logger): ErrorRequestHandler {
+  return function (err: Error, req, res, next) {
+    logger.error("request error", {
+      method: req.method,
+      path: req.route?.path,
+      code: 500,
+      error: err.message,
+      stackTrace: err.stack,
+    });
+    res.status(500).send("Something broke!");
+  };
+}

src/middleware/index.ts

@@ -0,0 +1,2 @@
+export { getRequestErrorHandler } from "./errorLogger";
+export { getOTELMiddleware } from "./otel";

src/middleware/otel/getReqAttributes.ts

@@ -0,0 +1,16 @@
+import type { Request } from "express";
+import type { Attributes } from "@opentelemetry/api";
+
+export function getReqAttributes(req: Request): Attributes {
+  return {
+    "http.method": req.method,
+    "http.scheme": req.protocol,
+    "http.host": req.get("host"),
+    "http.target": req.originalUrl,
+    "http.user_agent": req.get("user-agent"),
+    "http.flavor": req.httpVersion,
+    "http.status_code": req.statusCode,
+    "http.status_text": req.statusMessage,
+    "express.matched_route": `${req.method} ${req.route?.path}`,
+  };
+}

src/middleware/otel/index.ts

@@ -0,0 +1,69 @@
+import type { Handler } from "express";
+import type { Span } from "@opentelemetry/api";
+import opentelemetry, { SpanStatusCode } from "@opentelemetry/api";
+import { Logger } from "winston";
+import { getReqAttributes } from "./getReqAttributes";
+import type { RequestMetrics } from "../../init/metrics";
+
+export const getOTELMiddleware = (
+  logger: Logger,
+  reqMetrics: RequestMetrics,
+): Handler => {
+  return function (req, res, next) {
+    const start = process.hrtime();
+    const {
+      totalRequestsCounter,
+      totalErrorsCounter,
+      inProgressRequestsGauge,
+    } = reqMetrics;
+    const tracer = opentelemetry.trace.getTracer("http-request");
+    inProgressRequestsGauge.add(1);
+
+    /**
+     * start an active span with an empty name. this is because the matched route path is not available on the
+     * the request object (req.route.path) until the request is fully executed by the route handler.
+     * we update the span name in the res.on("finish") event listener below.
+     */
+    tracer.startActiveSpan("", (span: Span) => {
+      /**
+       * TODO: check if bun runtime's issue with triggering req.on("end") has been resolved.
+       * this should ideally be req.on("end"). However, bun runtime  has issues with triggering the end event.
+       * the res.on("finish") is being used as a workaround.
+       */
+      res.on("finish", () => {
+        const [_, timeInNanoSeconds] = process.hrtime(start);
+
+        const method = req.method;
+        const path = req.route?.path;
+        const attributes = getReqAttributes(req);
+        const reqPath = `${method} ${path}`;
+        span.updateName(reqPath);
+        totalRequestsCounter.add(1, attributes);
+        const code = res.statusCode;
+        if (code >= 500) {
+          span.setStatus({ code: SpanStatusCode.ERROR });
+          totalErrorsCounter.add(1, attributes);
+          logger.error("request", {
+            method,
+            path: req.path,
+            code,
+          });
+        } else {
+          span.setStatus({ code: SpanStatusCode.OK });
+          logger.info("request", {
+            method,
+            path: req.path,
+            code,
+          });
+        }
+
+        span.setAttributes(attributes);
+        inProgressRequestsGauge.add(-1);
+        span.end();
+      });
+
+      // call the next middleware
+      next();
+    });
+  };
+};