Observability

Three tools tell you what a request cost, in production and in development. They are separate and cost nothing when unused: the code behind them is a chunk the handler loads only when one is configured (a tracer, the serverTiming option, the metrics option, or development mode), and a handler with none of them reads no clock and creates no span.

A bad serverTiming or metrics value does not stop the server: a TypeError goes to the error sink (phase instrumentation) right after the handler is created, and the app runs without observability. Everything else here fails the same way: a tracer, a meter or a hook that throws is reported and the request is answered.

The Server-Timing header#

serverTiming is true, false or { header, onTimings }. Left out, it is on in development and off in production: the numbers describe your server's internals, so a production site turns it on on purpose. The header looks like this (durations are milliseconds from performance.now()):

Server-Timing: total;dur=12.3, route;desc="/posts/:id";dur=0.4, loaders;dur=8.1, render;dur=2.2, db;desc="load post";dur=7.6

A response that already has its own Server-Timing header (set by a route, a middleware or a header rule) is left alone. For a streamed page the head is sent when the shell is ready, so total and render are the time to the shell; the time until the last chunk is in the dusk.page.stream span and in the onTimings hook below.

Record your own metrics with event.timing.measure(name, fn, description?), which returns what fn returns (a promise is measured until it settles), or event.timing.add(name, durationMs, description?). In code that has no event at hand, timing(name, fn) from @shadow-js/dusk/server does the same for the request that is running. A name is a token (letters, digits and !#$%&'*+-.^_`|~) of at most 64 characters, and not total, route, loaders or render; a request records at most 20 distinct names, and measuring a name again adds to its total. An invalid name throws a TypeError, so a name taken from user input cannot reach a header. A description is reduced to printable ASCII (a quote, a backslash, a comma, a semicolon or a line break becomes _) and cut at 100 characters. With serverTiming off, both methods only run your function.

onTimings(timings) is called once when the request is over: for a streamed page when the body ends, for a request the client abandoned when it does. It receives the request id, method, path, route pattern, status, the durations (totalMs, routeMs, loadersMs, renderMs, streamMs), aborted and your metrics. streamMs is the full render time of a streamed page. { header: false, onTimings } records without putting the numbers in responses, which is the way to feed a log or a dashboard from production.

Child spans#

When src/instrumentation.ts exports a tracer, the request span dusk.request gets child spans, all ended exactly once, also when the client disconnects or the request times out (a span the request outlived is ended with the status error and error.type set to aborted, timeout or abandoned):

A span whose work throws records the exception (recordException), sets error.type to the error's name and the status to error. A redirect, a not-found and an error below 500 are answers, not failures: they end their span without an exception. An error the framework reports for the request is also recorded on dusk.request. A tracer that throws is reported once and spans stop for the rest of the process; requests are not affected.

Metrics#

metrics takes the subset of the OpenTelemetry Metrics Meter that Dusk uses: createCounter(name, options).add(value, attributes) and createHistogram(name, options).record(value, attributes). Pass metrics.getMeter("my-app") from @opentelemetry/api, or any object with those two methods. Dusk creates two instruments when the handler starts:

Both carry http.request.method (_OTHER for a method outside GET, HEAD, POST, PUT, DELETE, PATCH and OPTIONS), http.response.status_class (2xx, 4xx, 5xx) and, when a route matched, http.route (the pattern, so the label has as many values as the app has routes). A streamed page is recorded when its body ends.

OpenTelemetry in src/instrumentation.ts#

This is a complete setup with the OpenTelemetry Node SDK. The @opentelemetry/* packages are yours to install (npm install @opentelemetry/api @opentelemetry/sdk-node @opentelemetry/sdk-metrics @opentelemetry/exporter-trace-otlp-http @opentelemetry/exporter-metrics-otlp-http); Dusk depends on none of them. register() starts the SDK once when the server starts. Dusk reads tracer from this module and records exceptions on the spans itself. The meter goes to the metrics option of the entry's options, in src/entry-server.ts: export default { serverTiming: { header: false }, metrics: meter } satisfies Omit<HandlerOptions, "manifest"> with meter imported from ./instrumentation (header: false keeps the numbers out of responses and still feeds onTimings, the spans and the meter).

import { metrics, trace } from "@opentelemetry/api";
import { OTLPMetricExporter } from "@opentelemetry/exporter-metrics-otlp-http";
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
import { PeriodicExportingMetricReader } from "@opentelemetry/sdk-metrics";
import { NodeSDK } from "@opentelemetry/sdk-node";

const sdk = new NodeSDK({
  serviceName: "my-app",
  traceExporter: new OTLPTraceExporter(),
  metricReader: new PeriodicExportingMetricReader({ exporter: new OTLPMetricExporter() }),
});

export function register(): void {
  sdk.start();
  process.once("SIGTERM", () => void sdk.shutdown());
}

// The API returns proxies that use the provider the SDK installs, so these exports can be created before `register()` runs.
export const tracer = trace.getTracer("my-app");
export const meter = metrics.getMeter("my-app");

Turn Server-Timing into a response header only where you want it: serverTiming: true in production lets anyone who can load a page read your server's timings, which is useful behind a trusted proxy and a leak otherwise.