Multiple traces using same traceId with Express plugin

[mateodelnorte]

I'm using a fairly boiler plate implementation to trace my express.js application, but am seeing traceIds reused among unrelated traces. I'm also seeing zero tracing of middleware, which I would have expected.

Any tips on what I might be able to change to fix these two problems?

Here is the code I'm using to trace:

import {
  diag,
  DiagConsoleLogger,
  DiagLogLevel,
  SamplingDecision,
  SpanKind,
  trace,
} from "@opentelemetry/api";
import { AlwaysOnSampler, RandomIdGenerator } from "@opentelemetry/core";
import { JaegerExporter } from "@opentelemetry/exporter-jaeger";
import { registerInstrumentations } from "@opentelemetry/instrumentation";
import { ExpressInstrumentation } from "@opentelemetry/instrumentation-express";
import { HttpInstrumentation } from "@opentelemetry/instrumentation-http";
import { Resource } from "@opentelemetry/resources";
import {
  ConsoleSpanExporter,
  SimpleSpanProcessor,
} from "@opentelemetry/sdk-trace-base";
import { NodeTracerProvider } from "@opentelemetry/sdk-trace-node";
import {
  SemanticAttributes,
  SemanticResourceAttributes,
} from "@opentelemetry/semantic-conventions";

const Exporter = JaegerExporter;

diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.INFO);

export function registerTracing(serviceName) {
  const provider = new NodeTracerProvider({
    idGenerator: new RandomIdGenerator(),
    resource: new Resource({
      [SemanticResourceAttributes.SERVICE_NAME]: serviceName,
    }),
    sampler: filterSampler(ignoreHealthCheck, new AlwaysOnSampler()),
  });

  registerInstrumentations({
    instrumentations: [
      // Express instrumentation expects HTTP layer to be instrumented
      new HttpInstrumentation(),
      new ExpressInstrumentation(),
    ],
    tracerProvider: provider,
  });

  const exporter = new Exporter({
    serviceName,
  });

  provider.addSpanProcessor(new SimpleSpanProcessor(exporter));
  provider.addSpanProcessor(new SimpleSpanProcessor(new ConsoleSpanExporter()));

  // Initialize the OpenTelemetry APIs to use the NodeTracerProvider bindings
  provider.register();

  return trace.getTracer(serviceName);
}

const filterSampler = (filterFn, parent) => ({
  shouldSample(ctx, tid, spanName, spanKind, attr, links) {
    if (!filterFn(spanName, spanKind, attr)) {
      return { decision: SamplingDecision.NOT_RECORD };
    }

    return parent.shouldSample(ctx, tid, spanName, spanKind, attr, links);
  },
  toString: () => `FilterSampler(${parent.toString()})`,
});

const ignoreHealthCheck = (_spanName, spanKind, attributes) =>
  spanKind !== SpanKind.SERVER ||
  attributes[SemanticAttributes.HTTP_ROUTE] !== "/health";

I'm leveraging this as the top executed line in my server/index.js file:

... // other imports
import { registerTracing } from "./tracing";

const { appName } = argv;

registerTracing(appName);

Behavior in jaeger:

From the client's perspective, all of the above GET requests are separate, but tracing seems to thinking they all have the same traceId on the server.

Tags from the top level trace:

http.flavor | 1.1 |  
-- | -- | --
http.host | 0.0.0.0:8080 |  
http.method | GET |  
http.status_code | 204 |  
http.status_text | NO CONTENT |  
http.target | /omitted/authorizations/control/read |  
http.url | http://0.0.0.0:8080/omitted/authorizations/control/read |  
http.user_agent | Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.51 Safari/537.36 |  
internal.span.format | proto |  
net.host.ip | ::ffff:127.0.0.1 |  
net.host.name | 0.0.0.0 |  
net.host.port | 8080 |  
net.peer.ip | ::ffff:127.0.0.1 |  
net.peer.port | 61286 |  
net.transport | ip_tcp |  
otel.library.name | @opentelemetry/instrumentation-http |  
otel.library.version | 0.27.0 |  
otel.status_code | OK |  
service.name |(omitted) |  
span.kind | server |  
telemetry.sdk.language | nodejs |  
telemetry.sdk.name | opentelemetry |  
telemetry.sdk.version | 1.1.0

Is there something I'm doing incorrectly?

[dyladan]

Hard to tell from your example because the tracing file was pretty detailed but the file that required it was sort of glossed over but the most likely thing is that you're importing express before initializing tracing. It is very important that the tracing component is the first thing to load. I would recommend using the -r flag of node to start your application in order to ensure tracing is first rather than requiring the tracing file from your main app.js. node -r tracing.js app.js

[mateodelnorte]

That did the trick. Thank you. Though I still don't see all of my middleware instrumented.