Part 11 · 3 chapters · ~18 min

Observability

Structured logging and the cost of console.log, OpenTelemetry in Node with auto-instrumentation internals and context propagation, RED and USE metrics plus the event loop metrics that matter, tracing across async boundaries, error tracking with source maps and an unhandled rejection policy, and continuous profiling.

Logging and metrics

code

// pino: structured JSON, cheap, with request context and redaction
import pino from 'pino';
export const log = pino({ level: process.env.LOG_LEVEL ?? 'info', redact: ['req.headers.authorization', '*.bvn', '*.password'] });
app.addHook('onRequest', async req => { req.log = log.child({ reqId: req.id, traceId: currentTraceId() }); });
req.log.info({ transferId, amountKobo }, 'transfer accepted');

console.log is synchronous when writing to files and TTYs and asynchronous for pipes; it formats with util.inspect and emits unstructured text. Under load, heavy logging becomes a measurable share of CPU. Use a structured logger, log at info sparingly, sample debug logs, and never log secrets or full request bodies.

metric	why
request rate, errors, duration histogram per route (RED)	the user-facing health of the service
event loop utilisation and delay p99	saturation of the one thread that matters
heap used, RSS, GC pause time	memory pressure and leaks
pool total / idle / waiting (DB, HTTP agents)	saturation of dependencies (USE)
queue depth and job age (BullMQ)	background work falling behind

OpenTelemetry and tracing across async boundaries

code

// otel.mjs: load with node --import ./otel.mjs dist/server.js
import { NodeSDK } from '@opentelemetry/sdk-node';
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-proto';
new NodeSDK({
  serviceName: 'transfers',
  traceExporter: new OTLPTraceExporter({ url: 'http://otel-collector:4318/v1/traces' }),
  instrumentations: [getNodeAutoInstrumentations({ '@opentelemetry/instrumentation-fs': { enabled: false } })],
}).start();

Context is lost when work escapes the async chain: callbacks registered on a long-lived emitter, connection pools that run callbacks in the context of whoever created the connection, or custom thenables. The fix is to bind (AsyncResource.bind) or to use libraries with proper instrumentation.

HOW OPENTELEMETRY HOOKS NODE

auto-instrumentation patches modules as they load, then context follows the request

swipe the figure sideways, or tap expand for full screen

1/5

load first

Instrumentation must load before the modules it patches: node --import ./otel.mjs app.js (or --require for CJS). Loaded later, http and pg are already cached unpatched.

instrumentation loads before app code--import / --require, never an import inside app.js

Errors, unhandled rejections and continuous profiling

code

// one policy for the unexpected
process.on('unhandledRejection', (reason) => { log.fatal({ err: reason }, 'unhandled rejection'); throw reason; });
process.on('uncaughtException', (err) => {
  log.fatal({ err }, 'uncaught exception');
  // state may be corrupt: stop taking traffic and exit; the orchestrator restarts a clean process
  shutdown().finally(() => process.exit(1));
});
// since Node 15 the default for unhandled rejections is 'throw' (crash); keep it that way

practice	detail
source maps	`--enable-source-maps` so stack traces point at TypeScript lines; upload maps to the error tracker
error tracking	Sentry or similar, tagged with release, route, tenant and trace id
continuous profiling	Pyroscope, Datadog or Google Cloud Profiler sample CPU and heap all the time at low overhead; compare profiles between releases to catch regressions