Missing parent spans

[fischerman]

I'm using OpenTelemetry to debug graphql requests (spanning a single process). My setup is pretty standard:

    const exporter = new ConsoleSpanExporter()
    const sdk = new NodeSDK({
        resource: new Resource({
            [SemanticResourceAttributes.SERVICE_NAME]: '...',
        }),
        traceExporter: exporter,
        instrumentations: [getNodeAutoInstrumentations({
            '@opentelemetry/instrumentation-graphql': {
                depth: 1000,
            },
            '@opentelemetry/instrumentation-dns': {
                enabled: false
            },
        })],
    });

The root span of each request should be an HTTP POST. This is the case for small requests. However, with larger requests (containing >1000 graphql.resolve) the HTTP POST is consistently missing (so is graphql.execute). Jaeger shows this as an invalid parent span.

The verify that this is not a problem with the exporter I tested with the console exporter. Same problem. I see a span like this one but no span with the the id 76ee549d4c80a6f0 is logged.

{
  traceId: 'afe223ec30203882140c7717edae9193',
  parentId: '76ee549d4c80a6f0',
  name: 'graphql.resolve',
  id: '5b427ac2d03ef18f',
....

Smaller request look fine

{
  traceId: '6eeb3ab0698ee8a9f9eabdfd33ef3947',
  parentId: undefined,
  name: 'HTTP POST',
  id: '6515706f53830573',
  kind: 1,
  timestamp: 1669304096916122,
  duration: 12920,
  attributes: {
    'http.url': 'http://localhost:4000/graphql?',
...

I also used a custom span processor to see whether the span is sampled. For all requests, I'm seeing a span sampled: HTTP POST.

        spanProcessor: { 
            forceFlush: async () => {},
            onStart: (_span: Span, _parentContext: Context) => {},
            onEnd: (span: ReadableSpan) => { 
                const sampled = !!(span.spanContext().traceFlags & TraceFlags.SAMPLED);
                if(!sampled) {
                    console.log(`span not sampled: ${span.name}`);
                } else {
                    console.log(`span sampled: ${span.name}`)
                }
            },
            shutdown: async () => {},
        },

What could explain those (consistently) missing spans?

[Flarna]

Best guess is that the HTTP span is never ended. As of now OTel only exports finished spans.

You could verify this by added some log output in the onStart() method of your custom span processor.

In case my guess is true next step would be find out why the HTTP instrumentation is not ending this span.

[fischerman]

I should mention that I ran this trace with @opentelemetry/instrumentation-graphql.depth = 2 so it's "flatter" than normal. But it doesn't change anything else.

[Flarna]

If you specify an traceExporter but no spanProcessor SDK uses BatchSpanProcessor on default.
BatchSpanProcessor sends spans as batches and likely with some delay. If you end our app to fast some spans may be not exported yet.

You could try to configure a SimpleSpanProcessor for testing as this exports spans immediately. Clearly this is nothing you want in production.

[fischerman]

Delay is not the problem. I just learned that the BatchSpanProcessor silently drops spans. Increasing the queue size fixes the problem.

spanProcessor: new BatchSpanProcessor(exporter, {
    maxQueueSize: 3000,
})

That is kind of counterintuitive. I wouldn't expect the default processor to drop half of a trace. And I think that could deserve an info-level log message.

[Flarna]

Nice finding. I agree that this seems to be wrong.
There is #3094 which is related as it would improve the throughput.

But even with the better throughput it's likely that someone can write an app which creates spans faster then one can export. At least an info log should be there.

[anavrotski]

If the problem is in queue size, it will be good to clarify the units of that queue - the number of spans or bytes or whatever.
As well as describe all other BatchSpanProcessor parameters.