Opentelemetry-js: Thenable objects don't seem to get access to the current span in a node app

[MadRabbit]

Please answer these questions before submitting a bug report.

What version of OpenTelemetry are you using?

latest, as in 0.9.0

What version of Node are you using?

14.4

What did you do?

So I have this ORM library that i'm trying to instrument. it has a thenable Query unit, that looks somewhat like this:

class Query {
  all() {
    return makeTheActualDBQueryAndReturnAPromise();
  }

  // fake thenable interface
  then(resolve, reject) {
    return this.all().then(resolve, reject);
  }
}

then net result of this trickery is that you can await on a query directly without calling the #all(), for example

// you can get records like this
const adults = await users.where({ age: { $gt: 20 }});
// instead of
const adults = await users.where({ age: { $gt: 20 }}).all();

and i'm using this orm in a pretty much a vanilla express app.

i'm trying to make an opentelemetry plugin to get stack traces for the orm layer. basically cloning the mongo/mysql plugins

What did you expect to see?

when my opentelemetry plugin calls plugin._tracer.getCurrentSpan(), i should get the current span regardless whether i await on the native promise from #all(), or i await on the implicit #then method in the thenable query

What did you see instead?

It works fine when i await on a real (native) Promise from the #all() method
but when i await on the thenable query itself, then the tracer returns undefined for the current span

Additional context

Weirdly enough, this only happens in the context of an express app. when i make the same queries in tests for the plugin itself, everything works fine.

My sense there is something funny happening with the native promises patching or something like that.

[MadRabbit]

Here is a snippet to reproduce the issue:

// in the app initialisation layer
const provider = new NodeTracerProvider();

// in the library instrumentation
const tracer = provider.getTracer();

class Query {
  async result() {
    const parent = tracer.getCurrentSpan();
    const span = tracer.startSpan("doSomething", {
      attributes: {
        a: 1
      },
      kind: 2,
      name: 'foo',
      parent
    });
    console.log({ parent });

    await new Promise(r => setTimeout(r, 10));

    span.end();

    return 'result';
  }

  then(r1, r2) {
    return this.result().then(r1, r2);
  }
}

// in the express app
console.log(await new Query().result()) // explicit await on Promise
console.log(await new Query())             // implicit await on thenable object

the output of this looks like so

{
  parent: Span {
    attributes: {
      'http.url': 'http://127.0.0.1:3128/listings',
      'http.host': '127.0.0.1:3128',
      'net.host.name': '127.0.0.1',
      'http.method': 'GET',
      'http.route': '/listings',
      'http.target': '/listings',
      'http.user_agent': 'curl/7.58.0',
      'http.flavor': '1.1',
      'net.transport': 'IP.TCP',
      component: 'http'
    },
    links: [],
    events: [],
    status: { code: 0 },
    endTime: [ 0, 0 ],
    _ended: false,
    _duration: [ -1, -1 ],
    name: 'GET /listings',
    spanContext: {
      traceId: 'd00c3f70b1cb690b9bc80325eb4931aa',
      spanId: '960bf356569e89ab',
      traceFlags: 1,
      traceState: undefined
    },
    parentSpanId: undefined,
    kind: 1,
    startTime: [ 1592974136, 754595941 ],
    resource: Resource { labels: [Object] },
    _logger: ConsoleLogger {
      debug: [Function],
      info: [Function],
      warn: [Function],
      error: [Function]
    },
    _traceParams: {
      numberOfAttributesPerSpan: 32,
      numberOfLinksPerSpan: 32,
      numberOfEventsPerSpan: 128
    },
    _spanProcessor: MultiSpanProcessor { _spanProcessors: [Array] }
  }
}
{
  traceId: 'd00c3f70b1cb690b9bc80325eb4931aa',
  parentId: '960bf356569e89ab',
  name: 'doSomething',
  id: '58595da4a118377a',
  kind: 2,
  timestamp: 1592974136758901,
  duration: 11784,
  attributes: { a: 1 },
  status: { code: 0 },
  events: []
}
result
{ parent: undefined }
{
  traceId: '2d7d3797deac6656ad10c17feecede7f',
  parentId: undefined,
  name: 'doSomething',
  id: '25fe609a49d880a8',
  kind: 2,
  timestamp: 1592974136771632,
  duration: 10681,
  attributes: { a: 1 },
  status: { code: 0 },
  events: []
}
result

as you can see on the implicit call there is no parent span available

i hope this helps

[MadRabbit]

poked at this a bit more. both variants work fine if I use node provider without an express app, so that does not seem like a culprit.

disabling the express plugin, doesnt change anything, i still see the same problem.
disabling the http plugin makes both variants to have the parent span as undefined, which i guess is expected

[legendecas]

This is related to https://github.com/nodejs/node/pull/33778. There isn't any Node.js version released with this patch yet. So maybe we can wait for a new release to verify this issue again.

[MadRabbit]

ah, that's neat, thanks! maybe they will release that in a few days

[h3isenbug]

I use node 15.11 and I still face the same issue. my code:
const newSpan = tracer.startSpan( name, undefined, setSpan(context.active(), parentSpan) );
This works fine on non-async functions, but when i wanna trace async calls it results in only one of the childs having the correct parent and timing(probably first one).
any ideas?

[Flarna]

@h3isenbug Could you please post a complete sample? If it is not related to thenables a new issue may be better to avoid mixing it with this one.