Tools

Observability

Introduction#

The framework reports what it does: every request, query, job, mail, notification, live hint, scheduled run, command, log entry, exception and event. It publishes these reports on channels of Node's node:diagnostics_channel, and the framework's tools listen in, among others the devtools and the Server-Timing header while you develop, and OpenTelemetry in production. Your own code can listen too:

import { Logger, type Application, type ServiceProvider } from '@marmeon/core';
import { channels } from '@marmeon/core/diagnostics';

export class SlowQueryServiceProvider implements ServiceProvider {
  #off: (() => void) | undefined;

  boot(app: Application): void {
    const log = app.container.make(Logger).child({ channel: 'db' });
    this.#off = channels.subscribe(app, 'db.query', {
      end: (query) => {
        if (query.durationMs >= 500) log.warn('Slow query', { sql: query.sql, ms: Math.round(query.durationMs) });
      },
    });
  }

  shutdown(): void {
    this.#off?.();
  }
}

List the provider in the module's providers, as the service providers page shows. When nothing listens to a channel, the framework builds no report for it at all, so the channels cost nothing in an app that does not use them.

The channels#

Every report names its app and carries the time it started and where it happened: the requestId, the jobId or the scheduled task. A report of an operation that ended also has durationMs, and error when it failed. The types name each report: ChannelMessage<'db.query'> is the report of a query, and a misspelt channel or field is a compile error.

Subscribing#

channels.subscribe(app, name, handlers) listens to one channel and returns a function that stops listening. A provider subscribes in boot() and stops in shutdown(). The handlers depend on the kind of channel:

• An operation such as http.request or db.query takes { start, end, error }. start runs before the operation, end after it, whether it succeeded or failed, and error when it failed. A query is reported once it ran, so its start comes after the statement too.
• A plain channel, log, exception or event, takes one function.

A subscription hears only the reports of its own app, so two apps in one process, such as parallel tests, never mix. A handler that throws is reported as a process warning, and the operation goes on. A subscriber of log must not write to the log itself.

Queries and secret columns#

secret is true when a statement touches a table with secret columns. Its parameters may hold a password hash or a token, so whatever records queries shows none of them. The devtools record such a statement without parameters, and OpenTelemetry never records parameters at all.

Connections of @marmeon/database has a plain listener for code that counts queries itself, such as a test: connections.onQuery(listener) hears every statement of every connection with its connection, sql, parameters, durationMs and error, and returns the function that stops it. It knows no secret flag and passes the parameters as they are, so keep it out of anything that records or ships them. The catalog queries a connection runs to learn its schema, its relations and secret columns, are not statements of the app: no listener, log or devtools panel sees them.

The log channel#

Every log entry goes to the log channel while something listens, at any level, before the logger's own level decides whether to write it. The devtools record the log this way, and the development error page shows the log entries of the failed request. In a test, the channel is the way to assert on log entries without parsing lines:

import { channels, type LogMessage } from '@marmeon/core/diagnostics';
import { createTestApp } from '@marmeon/testing';
import { expect, it } from 'vitest';
import application from '../../bootstrap/app.ts';

it('logs a request line', async () => {
  const app = await createTestApp(application);
  const entries: LogMessage[] = [];
  const off = channels.subscribe(app.application, 'log', (entry) => void entries.push(entry));
  await app.get('/nothing-here').assertNotFound();
  off();
  expect(entries).toContainEqual(expect.objectContaining({ level: 'info', message: 'GET /nothing-here 404' }));
});

Events#

The event channel reports every dispatch, before a test's event fake decides whether listeners run. It suits code that watches all events, such as an audit trail. For your own reactions to one event, write a listener.

Following a request#

Every response carries the request's id in x-request-id: the client's own when it sent a sane one, otherwise a new one. Every log entry written during the request carries it as requestId. A job dispatched in the request remembers it, so the job's log entries and reports point back to the request that caused them, also in a worker on another machine. The devtools show a request with everything it set off, and OpenTelemetry puts the job into the request's trace.

Server-Timing in development#

With NODE_ENV=development, every response says what its request spent, and the browser's network panel shows it:

Server-Timing: app;dur=18.4;desc="App", db;dur=3.1;desc="4 queries", ssr;dur=9.7;desc="SSR"

app is the request until its response, or until the page's frame for a streamed page. db is the time of its queries and how many there were. ssr is the server rendering until the frame, when the page rendered on the server. The header exists only with NODE_ENV=development: not with test, not on staging, never in production.

OpenTelemetry#

@marmeon/otel turns the channels into OpenTelemetry spans: requests, queries, jobs, scheduled runs, mails, notifications, live hints and server rendering, following OpenTelemetry's semantic conventions. It talks only to the OpenTelemetry API. The SDK and the exporter are your app's, so you choose what your tracing backend speaks. Nothing patches a module, and there is no auto-instrumentation.

Installation#

pnpm add @marmeon/otel @opentelemetry/api@^1.9.0
pnpm add @opentelemetry/sdk-trace @opentelemetry/context-async-hooks @opentelemetry/core @opentelemetry/resources @opentelemetry/exporter-trace-otlp-http

The API is a peer of @marmeon/otel, never a dependency of its own: your SDK registers its tracer provider on the API, and the framework must read that same copy. Install the SDK as dependencies, not dev dependencies: it runs in production, and a production install leaves dev dependencies out. Without the API the start fails, and its message starts with what to install:

@marmeon/otel needs the OpenTelemetry API, which is not installed in this app: pnpm add @opentelemetry/api@^1.9.0

Starting the SDK#

The SDK must be registered before the app boots. Write it as a file of its own:

import { context, propagation, trace } from '@opentelemetry/api';
import { AsyncLocalStorageContextManager } from '@opentelemetry/context-async-hooks';
import { W3CTraceContextPropagator } from '@opentelemetry/core';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import { defaultResource, detectResources, envDetector } from '@opentelemetry/resources';
import { BatchSpanProcessor, TracerProvider } from '@opentelemetry/sdk-trace';

const resource = defaultResource().merge(detectResources({ detectors: [envDetector] }));
context.setGlobalContextManager(new AsyncLocalStorageContextManager().enable());
propagation.setGlobalPropagator(new W3CTraceContextPropagator());
trace.setGlobalTracerProvider(new TracerProvider({ resource, spanProcessors: [new BatchSpanProcessor({ exporter: new OTLPTraceExporter() })] }));

Node loads it first with --import, in every process of the app:

OTEL_SERVICE_NAME=notes OTEL_EXPORTER_OTLP_ENDPOINT=http://collector:4318 NODE_OPTIONS='--import ./bootstrap/telemetry.ts' marmeon start

marmeon start, queue:work and schedule:work each run in one Node process, which reads NODE_OPTIONS. With the files of make:docker, put the three variables into .env.production, which every container reads. The deployment page covers that file.

• The context manager makes spans nest, so a query is the child of its request. Without it spans are recorded flat, and the start warns.
• The propagator reads a caller's traceparent header, which becomes a link, as below.
• No SIGTERM handler. marmeon stops the server gracefully, and the provider flushes the SDK's spans when the app shuts down, for at most two seconds. The spans of the last requests and jobs are exported.
• Without an SDK the provider subscribes to nothing: no span, no cost, no error.

@opentelemetry/sdk-node starts in one line with new NodeSDK({ traceExporter }).start(), which registers the context manager and the propagator too, but it installs every exporter there is.

What it records#

Each operation is one span, and its work runs inside the span. What happens there, such as its queries, the jobs it dispatches, its log entries and your own spans, becomes its child:

The attributes follow OpenTelemetry's semantic conventions, and the names under marmeon. are the framework's own. Build dashboards and alerts on these names:

Every span the framework records also carries deployment.environment.name: the app's APP_ENV, such as staging, or the name that goes with NODE_ENV, as the configuration page explains. The resource belongs to your SDK. To name the environment there too, set OTEL_RESOURCE_ATTRIBUTES=deployment.environment.name=staging beside OTEL_SERVICE_NAME: the envDetector above reads it.

A failed operation marks its span as failed, with error.type set to the error's class and an exception event whose message and stack are redacted. A request that ends in a 5xx without an exception gets the status code as its error.type. A job or a scheduled task that failed without throwing, such as a job that called job.fail(), gets the error status and _OTHER as its error.type, without an exception event.

An island or a layer's base that the server resolves for a page is an internal child of the page's request. A statement outside every span, such as one of a command or a health check, is no trace of its own. /up and /up/ready are never traced, since they answer before the request pipeline. Your own spans work as usual:

import { trace } from '@opentelemetry/api';

const tracer = trace.getTracer('notes');

export async function exportNotes(userId: number, write: () => Promise<void>): Promise<void> {
  await tracer.startActiveSpan('notes export', { attributes: { 'notes.user_id': userId } }, async (span) => {
    try {
      await write();
    } finally {
      span.end();
    }
  });
}

Called in a controller, the span is a child of the request's span.

Log entries written inside a span carry its trace_id, span_id and trace_flags, the request's own log line included. Logs and traces join on trace_id.

A caller's traceparent#

Anyone can send a traceparent header. Taken as the parent, it would put the request into a trace the caller picked, and its sampled flag would decide whether the request is recorded at all. So every request from outside starts a trace of its own, which your sampler decides on, and a valid incoming traceparent becomes a link of the request's span. The caller's context stays findable, and nothing of it is taken, its baggage neither.

OTEL_TRUST_TRACEPARENT=true continues the caller's trace instead: the incoming traceparent becomes the parent. The caller's baggage is taken too when your SDK registers a baggage propagator, such as W3CBaggagePropagator in a CompositePropagator. The telemetry.ts above registers none.

A job continues the trace of its dispatch in any case, since its traceparent comes from your own queue.

Redaction#

Every attribute and exception that may hold a secret passes the app's redactor, the same one the devtools use: url.query, user_agent.original, exception messages and stacks, the query text, and path segments of route parameters with a sensitive name, so /reset-password/:token becomes /reset-password/[redacted]. The redactor masks by name and by the shape of a text.

• The URL's query string is exported as url.query with its keys only: ?q=ada%40example.com&page=2 becomes q=&page=, so an e-mail address, a search term or a token under a harmless name stays in the process. A part without =, such as ?ada%40example.com, could be a value, so it is written as [redacted]. OTEL_RECORD_QUERY_VALUES=true exports the values too, with secret-looking ones masked, while every other value leaves the process as it is.
• The bound parameters of SQL statements are never recorded. db.query.text is the statement as it is sent: a value written into the SQL itself, with sql.raw() or sql.lit(), is part of the text and is exported.
• Request headers are recorded only when you name them, and then redacted by name:

OTEL_INSTRUMENTATION_HTTP_CAPTURE_HEADERS_SERVER_REQUEST=x-tenant,accept-language

This records http.request.header.x-tenant, while authorization, cookie and the session cookie would show [redacted].

Configuration#

Everything else belongs to the SDK: OTEL_SERVICE_NAME, OTEL_EXPORTER_OTLP_ENDPOINT, OTEL_TRACES_SAMPLER and the rest.

Testing#

Register an SDK with an exporter in memory before the test app boots. Vitest runs each test file in a worker of its own, so the registration stays in the file:

import { context, trace } from '@opentelemetry/api';
import { AsyncLocalStorageContextManager } from '@opentelemetry/context-async-hooks';
import { InMemorySpanExporter, SimpleSpanProcessor, TracerProvider } from '@opentelemetry/sdk-trace';
import { createTestApp } from '@marmeon/testing';
import { afterAll, beforeAll, expect, it } from 'vitest';
import application from '../../bootstrap/app.ts';

const exporter = new InMemorySpanExporter();
const provider = new TracerProvider({ spanProcessors: [new SimpleSpanProcessor({ exporter })] });
beforeAll(() => {
  context.setGlobalContextManager(new AsyncLocalStorageContextManager().enable());
  trace.setGlobalTracerProvider(provider);
});
afterAll(() => {
  trace.disable();
  context.disable();
});

it('traces a registration with its job', async () => {
  const app = await createTestApp(application, { database: 'refresh' });
  await app.post('/register', {
    form: { name: 'Katherine Johnson', email: 'kj@example.com', password: 'orbital mechanics', password_confirmation: 'orbital mechanics' },
  });
  await app.queue.work();
  await provider.forceFlush();
  const names = exporter.getFinishedSpans().map((span) => span.name);
  expect(names).toContain('POST /register');
  expect(names).toContain('process marmeon.listener');
});

The test needs the SDK's packages. An app that traces in production has them as dependencies already.