feat: try and fix logs to include trace information

Author: djMax

package.json

@@ -72,20 +72,21 @@
   "dependencies": {
     "@godaddy/terminus": "^4.12.1",
     "@opentelemetry/api": "^1.9.0",
-    "@opentelemetry/exporter-prometheus": "^0.53.0",
+    "@opentelemetry/auto-instrumentations-node": "^0.51.0",
+    "@opentelemetry/exporter-prometheus": "^0.54.0",
     "@opentelemetry/instrumentation-dns": "^0.39.0",
     "@opentelemetry/instrumentation-express": "^0.43.0",
     "@opentelemetry/instrumentation-generic-pool": "^0.39.0",
     "@opentelemetry/instrumentation-graphql": "^0.43.0",
-    "@opentelemetry/instrumentation-http": "^0.53.0",
+    "@opentelemetry/instrumentation-http": "^0.54.0",
     "@opentelemetry/instrumentation-ioredis": "^0.43.0",
     "@opentelemetry/instrumentation-net": "^0.39.0",
     "@opentelemetry/instrumentation-pg": "^0.46.0",
     "@opentelemetry/instrumentation-pino": "^0.42.0",
     "@opentelemetry/instrumentation-undici": "^0.6.0",
     "@opentelemetry/resource-detector-container": "^0.4.4",
     "@opentelemetry/resource-detector-gcp": "^0.29.12",
-    "@opentelemetry/sdk-node": "^0.53.0",
+    "@opentelemetry/sdk-node": "^0.54.0",
     "@opentelemetry/semantic-conventions": "^1.27.0",
     "@sesamecare-oss/confit": "^2.2.1",
     "@sesamecare-oss/opentelemetry-node-metrics": "^1.1.0",
@@ -96,6 +97,7 @@
     "express": "^5.0.1",
     "express-openapi-validator": "^5.3.7",
     "glob": "^11.0.0",
+    "import-in-the-middle": "^1.11.2",
     "minimist": "^1.2.8",
     "moderndash": "^3.12.0",
     "pino": "^9.5.0",
@@ -113,12 +115,12 @@
     "@types/cookie-parser": "^1.4.7",
     "@types/express": "^5.0.0",
     "@types/minimist": "^1.2.5",
-    "@types/node": "^22.7.7",
+    "@types/node": "^22.7.9",
     "@types/request-ip": "^0.0.41",
     "@types/supertest": "^6.0.2",
     "@typescript-eslint/eslint-plugin": "^7.18.0",
     "@typescript-eslint/parser": "^7.18.0",
-    "coconfig": "^1.6.0",
+    "coconfig": "^1.6.1",
     "eslint": "^8.57.1",
     "eslint-config-prettier": "^9.1.0",
     "eslint-import-resolver-typescript": "^3.6.3",

src/bin/start-service.ts

@@ -15,6 +15,10 @@ const argv = minimist(process.argv.slice(2), {
   boolean: ['built', 'repl', 'telemetry', 'nobind'],
 });
 
+if (argv.telemetry) {
+  await import('../telemetry/hook-modules.js');
+}
+
 const noTelemetry = (argv.repl || isDev()) && !argv.telemetry;
 bootstrap({
   ...argv,

src/express-app/app.ts

@@ -5,7 +5,7 @@ import path from 'path';
 
 import { pino } from 'pino';
 import cookieParser from 'cookie-parser';
-import { metrics } from '@opentelemetry/api';
+import { context, metrics, trace } from '@opentelemetry/api';
 import { setupNodeMetrics } from '@sesamecare-oss/opentelemetry-node-metrics';
 import { createTerminus } from '@godaddy/terminus';
 import type { RequestHandler, Response } from 'express';
@@ -52,6 +52,22 @@ export async function startApp<
     dest: process.env.LOG_TO_FILE || process.stdout.fd,
     minLength: process.env.LOG_BUFFER ? Number(process.env.LOG_BUFFER) : undefined,
   });
+
+  function poorMansOtlp(mergeObject: object) {
+    if (!('trace_id' in mergeObject)) {
+      const activeSpan = trace.getSpan(context.active());
+      if (activeSpan) {
+        const ctx = activeSpan.spanContext();
+        Object.assign(mergeObject, {
+          trace_id: ctx.traceId,
+          span_id: ctx.spanId,
+          trace_flags: ctx.traceFlags
+        });
+      }
+    }
+    return mergeObject;
+  }
+
   const logger = shouldPrettyPrint
     ? pino(
       {
@@ -61,6 +77,7 @@ export async function startApp<
             colorize: true,
           },
         },
+        mixin: poorMansOtlp,
       },
       destination,
     )
@@ -71,6 +88,7 @@ export async function startApp<
             return { level: label };
           },
         },
+        mixin: poorMansOtlp,
       },
       destination,
     );

src/telemetry/hook-modules.ts

@@ -0,0 +1,18 @@
+import module from 'node:module';
+
+module.register('import-in-the-middle/hook.mjs', import.meta.url, {
+  parentURL: import.meta.url,
+  data: {
+    include: [
+      'express',
+      'pino',
+      'http',
+      'dns',
+      'net',
+      'pg',
+      'ioredis',
+      'undici',
+      'generic-pool',
+    ],
+  },
+});

src/telemetry/index.ts

@@ -1,9 +1,14 @@
+import { OTLPLogExporter } from '@opentelemetry/exporter-logs-otlp-proto';
 import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-proto';
 import {
+  Detector,
+  DetectorSync,
   envDetectorSync,
   hostDetectorSync,
+  IResource,
   osDetectorSync,
   processDetectorSync,
+  ResourceDetectionConfig,
 } from '@opentelemetry/resources';
 import { containerDetector } from '@opentelemetry/resource-detector-container';
 import { gcpDetector } from '@opentelemetry/resource-detector-gcp';
@@ -23,7 +28,7 @@ import type { ConfigurationSchema } from '../config/schema.js';
 import { getAutoInstrumentations } from './instrumentations.js';
 import { DummySpanExporter } from './DummyExporter.js';
 
-function getExporter() {
+function getSpanExporter() {
   if (
     !process.env.DISABLE_OLTP_EXPORTER &&
     (['production', 'staging'].includes(process.env.APP_ENV || process.env.NODE_ENV || '') ||
@@ -39,9 +44,36 @@ function getExporter() {
   return new DummySpanExporter();
 }
 
+function getLogExporter() {
+  if (
+    !process.env.DISABLE_OLTP_EXPORTER &&
+    (['production', 'staging'].includes(process.env.APP_ENV || process.env.NODE_ENV || '') ||
+      process.env.OTLP_EXPORTER)
+  ) {
+    return new OTLPLogExporter({
+      url: process.env.OTLP_EXPORTER || 'http://otlp-exporter:4318/v1/logs',
+    });
+  }
+  if (process.env.ENABLE_CONSOLE_OLTP_EXPORTER) {
+    return new opentelemetry.logs.ConsoleLogRecordExporter();
+  }
+  return undefined;
+}
+
 let prometheusExporter: PrometheusExporter | undefined;
 let telemetrySdk: opentelemetry.NodeSDK | undefined;
 
+function awaitAttributes(detector: DetectorSync): Detector {
+  return {
+    async detect(config?: ResourceDetectionConfig): Promise<IResource> {
+      const resource = detector.detect(config)
+      await resource.waitForAsyncAttributes?.()
+
+      return resource
+    },
+  }
+}
+
 /**
  * OpenTelemetry is not friendly to the idea of stopping
  * and starting itself, it seems. So we can only keep a global
@@ -52,31 +84,31 @@ let telemetrySdk: opentelemetry.NodeSDK | undefined;
  */
 export async function startGlobalTelemetry(serviceName: string) {
   if (!prometheusExporter) {
-    // For troubleshooting, set the log level to DiagLogLevel.DEBUG
-    opentelemetry.api.diag.setLogger(new (opentelemetry.api.DiagConsoleLogger)(), opentelemetry.api.DiagLogLevel.INFO);
+    const { metrics, logs, NodeSDK } = opentelemetry;
 
     prometheusExporter = new PrometheusExporter({ preventServerStart: true });
     const instrumentations = getAutoInstrumentations();
-    telemetrySdk = new opentelemetry.NodeSDK({
+    const logExporter = getLogExporter();
+    telemetrySdk = new NodeSDK({
       serviceName,
       autoDetectResources: false,
-      traceExporter: getExporter(),
       resourceDetectors: [
-        envDetectorSync,
-        hostDetectorSync,
-        osDetectorSync,
-        processDetectorSync,
-        containerDetector,
-        gcpDetector,
+        awaitAttributes(envDetectorSync),
+        awaitAttributes(hostDetectorSync),
+        awaitAttributes(osDetectorSync),
+        awaitAttributes(processDetectorSync),
+        awaitAttributes(containerDetector),
+        awaitAttributes(gcpDetector),
       ],
+      traceExporter: getSpanExporter(),
       metricReader: prometheusExporter,
       instrumentations,
-      logRecordProcessors: [],
+      logRecordProcessors: logExporter ? [new logs.BatchLogRecordProcessor(logExporter)] : [],
       views: [
-        new opentelemetry.metrics.View({
+        new metrics.View({
           instrumentName: 'http_request_duration_seconds',
-          instrumentType: opentelemetry.metrics.InstrumentType.HISTOGRAM,
-          aggregation: new opentelemetry.metrics.ExplicitBucketHistogramAggregation(
+          instrumentType: metrics.InstrumentType.HISTOGRAM,
+          aggregation: new metrics.ExplicitBucketHistogramAggregation(
             [0.003, 0.03, 0.1, 0.3, 1.5, 10],
             true,
           ),