startSpan path causes incorrect span ordering

[jpasquers]

Expected behaviour As I understand it from the docs, The following paths should be equivalent:

let span = tracer.startSpan("x", {
      childOf: tracer.scope().active() ?? undefined,
});
someFn();
span.finish();

And

tracer.trace('x', {}, () => someFn());

Actual behaviour In the former code block, the span is created and associated to the correct trace. However, it shows out of order to the other spans within the trace (which are using tracer.trace). Namely, it is at the bottom of the trace after all the other spans that should be underneath it. From what I can tell from other experimenting, the span is only being added to the trace around the finish() time.

Steps to reproduce Use the startSpan approach with a nested tracer.trace and see that the span produced by startSpan exists after it. E.g.:

let someTracedFn = () => {
    tracer.trace("y", {}, () => console.log("hello"));
}

let span = tracer.startSpan("x", {
      childOf: tracer.scope().active() ?? undefined,
});
someTracedFn();
span.finish();

In that scenario, "y" should be a child of "x", but it does not display that way

Environment

• Operation system:
• Node.js version:
• Tracer version:
• Agent version:
• Relevant library versions:

"dd-trace": "^4.11.1",
"opentracing": "^0.14.7",

[jpasquers]

It looks like this issue is potentially tied to:

https://github.com/DataDog/dd-trace-js/issues/1231

For some added context, this is intended to wrap ApolloServer, particularly the NestJS ApolloGatewayDriver. This driver exposes methods around the start and end of execution but no way to reference the actual execution.

We are also unable to use the graphql plugin because ApolloServer in tandem with ApolloGateway No longer uses graphql.execute

The real code looks as follows:

executionDidStart: async (executionRequestContext: GraphQLRequestContextExecutionDidStart<BaseContext>) => {
                const queryName = executionRequestContext.operation.name?.value;
                if (!queryName || queryName === INTROSPECTION_QUERY_NAME) return;
                const span: Span = tracer.startSpan('graphql.execute', {
                    tags: {
                        'service.name': `${config.DD_SERVICE_NAME}-graphql`,
                        'resource.name': queryName,
                    },
                    childOf: tracer.scope().active() ?? undefined,
                });
                return {
                    executionDidEnd: async (err) => {
                        if (err) {
                            bindSpanInfoFromError(err, span);
                        }
                        span.finish();
                    },
                };
            },

[jotadepicas]

@jpasquers hi, I'm dealing with the same issue here. Have you found any workarounds?

[ex-nerd]

@jpasquers hi, I'm dealing with the same issue here. Have you found any workarounds?

I've been using a variation on this and it seems to work fine with both sync and async functions:

tracer.trace(name, options, async () => {
    // do stuff here
})