Tracing

A trace follows one request across services; spans are its steps, and the traceparent header carries the link.

Syntaxtracer.startActiveSpan(name, (span) => { /* work */ span.end(); })

A trace is the record of one request as it moves through your system. Each step is a span: a name, a start and end time, some attributes, and the id of the span it happened inside. Every span belonging to one request shares a trace id, so a viewer can draw them as nested bars and show which step consumed the time. Metrics say the route is slow. A trace says the slowness is one query, called eleven times.

OpenTelemetry is the vendor-neutral standard for producing traces. In Node you load its SDK before your own code, so it can wrap the modules you are about to require: node --require ./instrumentation.js app.js for CommonJS, or node --import ./instrumentation.mjs app.js for ES modules. With auto-instrumentation, incoming requests, outgoing HTTP calls and database queries become spans without you writing any span code.

Propagation

Context crosses a network boundary as a header. The W3C traceparent header has the form 00-<32 hex trace id>-<16 hex span id>-<2 hex flags>. The HTTP instrumentation adds it to outbound requests for you. For a carrier it knows nothing about, a queue message for instance, call propagation.inject(context.active(), carrier) on the way out and propagation.extract(context.active(), carrier) on the way in.

Your own spans

tracer.startActiveSpan(name, fn) is the short form. The long form is const span = tracer.startSpan(name) followed by context.with(trace.setSpan(context.active(), span), fn). They are the same thing; the short form makes the span active for you.

Example

Try it yourself
Loading editor…
Press Run to execute the code.

When to use it

  • Find which of six downstream calls is responsible for a slow endpoint.
  • Spot an N+1 query as the same span repeating dozens of times in one request.
  • Follow a failing request from the public API through two internal services.
  • Link a background job's work back to the user action that queued it.

More examples

The setup file, loaded before your app

Order is the whole trick: the SDK has to patch http and your database driver before app.js requires them, which is why it goes in --require rather than at the top of app.js. This file plus one environment variable is usually all the tracing a service needs.

Example · javascript
// instrumentation.js
const { NodeSDK } = require('@opentelemetry/sdk-node');
const { OTLPTraceExporter } = require('@opentelemetry/exporter-trace-otlp-http');
const {
  getNodeAutoInstrumentations,
} = require('@opentelemetry/auto-instrumentations-node');

const sdk = new NodeSDK({
  traceExporter: new OTLPTraceExporter(), // endpoint from OTEL_EXPORTER_OTLP_ENDPOINT
  instrumentations: [getNodeAutoInstrumentations()],
});

sdk.start();

// Flush buffered spans before the process goes away.
process.on('SIGTERM', () => {
  sdk.shutdown().finally(() => process.exit(0));
});

// Run it:
//   OTEL_SERVICE_NAME=orders node --require ./instrumentation.js app.js

A span around a step worth naming

Auto-instrumentation gives you spans for I/O, not for meaning. Add one by hand where a business step is worth seeing by name in a waterfall, and keep the identifiers on it as attributes rather than in the span name, which must stay low-cardinality.

Example · javascript
const { trace, SpanStatusCode } = require('@opentelemetry/api');

const tracer = trace.getTracer('orders', '1.4.0');

async function chargeCard(order) {
  return tracer.startActiveSpan('charge-card', async (span) => {
    // Attributes are the searchable fields of a span.
    span.setAttribute('order.id', order.id);
    span.setAttribute('order.amount_cents', order.amountCents);
    try {
      const receipt = await payments.charge(order);
      span.setAttribute('payment.provider_id', receipt.id);
      return receipt;
    } catch (err) {
      span.recordException(err); // attaches type, message, stack
      span.setStatus({ code: SpanStatusCode.ERROR, message: err.message });
      throw err;
    } finally {
      span.end(); // runs on both paths
    }
  });
}

Carrying context onto a queue

A queue breaks the chain, because nothing automatically copies headers onto a message. Inject and extract reconnect the job's spans to the request that created it, which is the difference between a trace that stops at the enqueue and one that shows the email going out.

Example · javascript
const { propagation, context } = require('@opentelemetry/api');

// Producer: write the current context into the message itself.
async function enqueueEmail(job) {
  const carrier = {};
  propagation.inject(context.active(), carrier); // adds a traceparent key
  await queue.add('send-email', { ...job, _otel: carrier });
}

// Consumer: read it back and run the work inside it.
async function onMessage(message) {
  const parent = propagation.extract(context.active(), message.data._otel ?? {});
  await context.with(parent, async () => {
    await sendEmail(message.data);
  });
}

Related

node request idsnode loggingnode metricsnode queuesnode api errors

Discussion

  • Be the first to comment on this lesson.