Opentelemetry-js: Unable to rely on AsyncHooksScopeManager when wrapping async functions

[cohen990]

Please answer these questions before submitting a bug report.

What version of OpenTelemetry are you using?

0.3.3

What version of Node are you using?

13.6.0

What did you do?

I'm using the AsyncHooksScopeManager to keep track of my current scope. I'm expecting to be able to call tracer.withSpan(...) and from within call tracer.getCurrentSpan() and have it provide me with the span I am executing inside of. I've provided a failing unit test

import { AsyncHooksScopeManager } from '@opentelemetry/scope-async-hooks'
import { InMemorySpanExporter } from '@opentelemetry/tracing'
import {
  BasicTracerRegistry,
  SimpleSpanProcessor,
} from '@opentelemetry/tracing'

function makeTracer(exporter: InMemorySpanExporter) {
  const config = {
    scopeManager: new AsyncHooksScopeManager(),
  }
  const registry = new BasicTracerRegistry()
  registry.addSpanProcessor(new SimpleSpanProcessor(exporter))
  const tracer = registry.getTracer('tracer', undefined, config)
  return tracer
}

describe('async handling should fail', () => {
  const exporter = new InMemorySpanExporter()

  async function demo(ms): Promise<string> {
    const tracer = makeTracer(exporter)

    const span = tracer.startSpan('my span')

    return tracer.withSpan(span, async () => {
      await new Promise(resolve => setTimeout(resolve, ms))
      tracer.getCurrentSpan().addEvent('root-event', {})

      return 'ok'
    })
  }

  it('will not be able to retrieve the current span from within the `withSpan` block', async () => {
    const result = await demo(0)
    expect(result).toBe('ok')
    expect(exporter.getFinishedSpans().length).toBe(1)
    expect(exporter.getFinishedSpans()[0].events.length).toBe(1)
  })
})

What did you see instead?

Instead of giving me the current span, the ScopeManager has continued executing (because it doesn't await) and has deleted the scope for that span. So calling getCurrentSpan() is returning undefined

[vmarchaud]

I believe it's because the callback can't be async, could you try to something like this :

return tracer.withSpan(span, () => {
  return new Promise(resolve => setTimeout(resolve, ms))
    .then(res => {
        tracer.getCurrentSpan().addEvent('root-event', {})
     })
})

[cohen990]

@vmarchaud I do believe that would work but I'm writing a logging library and need to be able to give more flexibility than this offers. I need to be able to rely on the scope manager to manage the scope properly.

I found that by modifying the scope manager as so:

from:

    with(scope, fn) {
        const uid = asyncHooks.executionAsyncId();
        const oldScope = this._scopes[uid];
        this._scopes[uid] = scope;
        try {
            return fn();
        }
        catch (err) {
            throw err;
        }
        finally {
            if (oldScope === undefined) {
                this._destroy(uid);
            }
            else {
                this._scopes[uid] = oldScope;
            }
        }
    }

to

    async with(scope, fn) {
        const uid = asyncHooks.executionAsyncId();
        const oldScope = this._scopes[uid];
        this._scopes[uid] = scope;
        try {
            return await fn();
        }
        catch (err) {
            throw err;
        }
        finally {
            if (oldScope === undefined) {
                this._destroy(uid);
            }
            else {
                this._scopes[uid] = oldScope;
            }
        }
    }

[vmarchaud]

Indeed that would works but i believe it could have some performance impact, might need to dig a little bit more to make that change

[cohen990]

could be viable to create a second alongside the original? withAsync?

[vmarchaud]

@cohen990 Might be a solution indeed, don't know if we could detect if the original function is async or not.

[cohen990]

https://davidwalsh.name/javascript-detect-async-function

const isAsync = myFunction.constructor.name === "AsyncFunction";

This apparently works?

[vmarchaud]

Yep, that could do the trick. Do you have the time to make a PR for that ?

[cohen990]

I do indeed :)

[vmarchaud]

Feel free to ping me on gitter if you need any help :)

[OlivierAlbertini]

https://davidwalsh.name/javascript-detect-async-function

const isAsync = myFunction.constructor.name === "AsyncFunction";

This apparently works?

async function getPerson(id) { .. }

function getRecord(id) {
   return getPerson(id)
      .then(function(person){ return { data: person }; });
}

const isAsync = getRecord.constructor.name === "AsyncFunction"; // false

It won't work
Perhaps, you could always do Promise.resolve(...) but I'm not sure that is a solution.
Also I'm agree that async function should be supported.

[bobthemighty]

@cohen990 I'd be cautious about using the constructor trick to figure out whether the traced function is async. The problem is that functions can be async by virtue of returning a Promise. I think you might be setting yourself up for bugs later.

Is it worth testing the perf impact of always awaiting?

[cohen990]

@bobthemighty I believe the library has a suite of performance tests. I'll dig in

[vmarchaud]

@bobthemighty It is and we have benchmark there, one would need to add a case with NodeTracer (which use AsyncHooksScopeManager) and modify the code to await everytime.

[dyladan]

It seems like the performance impact would actually be pretty significant: multiple orders of magnitude.

I am in favor of adding a withAsync to be used with async functions.

const Benchmark = require('benchmark');
const pretty = require('beautify-benchmark');

new Benchmark.Suite()
    .on('cycle', event => pretty.add(event.target))
    .on('error', event => { throw event.target.error; })
    .on('complete', function () { pretty.log(); })
    .add('async', {
        defer: true,
        fn: async function (deferred) {
            await withAsync(foo);
            deferred.resolve();
        }
    })
    .add('sync', {
        defer: false,
        fn: function () {
            _with(foo);
        }
    })
    .run()

function foo() {
    return "bar";
}


function _with(fn) {
    try {
        return fn();
    }
    catch (err) {
        throw err;
    }
}

async function withAsync(fn) {
    try {
        return await fn();
    }
    catch (err) {
        throw err;
    }
}

➜  opentelemetry-js git:(master) ✗ node bench.js

  2 tests completed.

  async x   5,074,459 ops/sec ±0.91% (77 runs sampled)
  sync  x 926,202,036 ops/sec ±1.29% (90 runs sampled)

[vmarchaud]

Considering the impact i also think we should add a withAsync function.

[cohen990]

This would have to be propagated through to the Tracer level too. The tracers will need to offer a withSpanAsync function which uses the withAsync otherwise the change would be inaccessible at the application level

[obecny]

@cohen990 did you make the same test in web only with ZoneScopeManager without modifying the code yet ? Does it work ?

[obecny]

would something like this work ?

  async function demo(ms): Promise<string> {
    const tracer = makeTracer(exporter)
    const span = tracer.startSpan('my span')
    return tracer.withSpan(span, () => {
      return new Promise(async(resolve, reject) => {
        await new Promise(resolve => setTimeout(resolve, ms));
        tracer.getCurrentSpan().addEvent('root-event', {})
        resolve('ok');
      });
    })
  }

[Flarna]

I think there are two issues here:

• The sample initializes AsyncHooksScopeManager quite late - withing an async function where quite some (internal) promises have been created already. If there are no other users of async_hooks in the system these are not tracked as the PromiseHook get's installed in v8 on first use of async_hooks. As a result the executionAsyncId() at tracer.getCurrentSpan() is 0.
• AsyncHooksScopeManager removes entries in it's table in promiseResolve hook which is too early for cases like this

Even if adding an await seems to solved this here I'm not sure if adding this may cause unexpected side effects. In the end the return value returned by withSpan is a different Promise than that one returned by the original function. if the original Promise was e.g. from Bluebird the extra APIs provided by this one get lost.

[cohen990]

@obecny I think the ideal solution would be one that is flexible enough to allow the library to be used in whatever way seems natural. I might abandon this separate withAsync pathway and see if there's a cleaner resolution available

[Flarna]

What I miss also in above sample is a call to scopeManager.enable().
The NodeTracer takes care about this but here the BasicTracer is used which seems to leave this up to the user.

[cohen990]

Hi thanks for all your help. I've decided in the end to not use the AsyncHooksScopeManager and instead manage the scope within my own application. Best of luck

[yosiat]

Hi!

I want to try and use AsyncHooksScopeManager in my application, but the missing of supporting promise based function is problematic for me.

I can submit a PR for adding a new method, same as with but called withAsync that will support promise based function.

WDYT?

[dyladan]

Can you give an example of a situation where the current functionality fails? The original example had a few issues as pointed out by @Flarna and may very well have just been a misuse of the library.

[yosiat]

@dyladan maybe I am over-taking an existing non-relevant issue, sorry if this the case.

I want to use AsyncHooksScopeManager in my app and soon use open-telemetry for prometheus and jaeger.

For now, I have some async code which I want to wrap it in its own context (in order to save root span / request-id for example). using the with method will cause it to remove the context when the method is not finished yet. so I need it to wait for my method - just like this code - https://github.com/open-telemetry/opentelemetry-js/issues/752#issuecomment-580240420

But instead of changing the existing method and trying to detect whether the function is async, I am suggesting adding another method for handling async methods.

Hopefully, it makes more sense now

[dyladan]

are you awaiting the call to with?

[yosiat]

Take this example:

function onRequest(request) {
  const context = { request_id: request.headers.x_request_id, rootSpan: /* created span from request header*/ };
  scopeManager.with(context,() => processRequest(request));
}


async function processRequest(request) {
  // here I can call the DB and other services
  const user = await DB.fetchUser(request);
  // while doing so I want to get `request_id` from scope for logging
  // and get the rootSpan so I can pass when I interact with other services
}

If I will use with, it will clear the context while the async function is still running (https://github.com/open-telemetry/opentelemetry-js/blob/master/packages/opentelemetry-scope-async-hooks/src/AsyncHooksScopeManager.ts#L70)

BTW, you can look at cls-hooked which have a runPromise method.

[dyladan]

We will discuss this at the SIG meeting wednesday if you would like to join.

[yosiat]

hi @dyladan!
Wasn't next to a computer this week since I was sick.

Any updates on this?

[dyladan]

We are going to add withAsync and probably also bindAsync to the scope manager and tracer.

[yosiat]

@dyladan I can implement this, it looks fairly simple when I look at the scope manager for async hooks.

[dyladan]

@yosiat it is not as easy as you might think. I started work on this and couldn't get this assertion to pass https://github.com/dynatrace-oss-contrib/opentelemetry-js/blob/with-async/packages/opentelemetry-scope-async-hooks/test/AsyncHooksScopeManager.test.ts#L157

[yosiat]

sorry, didn't mean to offend.

Looks like you are already working on it! I can take a look at this test if you want.

[dyladan]

No I'm not offended at all :) please take a look and see if you can catch what i'm missing

[yosiat]

@dyladan the problem is that both scopes get the same executionAsyncId.
I had this issue while trying to implement opentracing for my application with cls-hooked, we hoped the context is hierarchal and we can store the inheritance of spans using context. So top-level context will have root span and children contexts will have their own children spans.

But, we found out, the hard way, that we can't have hierarchy here with contexts, we only store the root span in context, and every child (function) should create children spans and finish them.

Take this code for example with cls-hooked:

var { createNamespace } = require('cls-hooked');
var namespace = createNamespace('my session');


async function bottom() {
  namespace.set('value', 'bottom');
  process._rawDebug(`> bottom: value: ${namespace.get('value')}`)
}

async function top() {
  namespace.set('value', 'top');
  process._rawDebug(`> top: value: ${namespace.get('value')}`)


  await bottom();

  process._rawDebug(`> top: after bottom: value: ${namespace.get('value')}`)

}

namespace.runPromise(() => top())

/* output: (node v12.13.1)
> top: value: top
> bottom: value: bottom
> top: after bottom: value: bottom
*/

[vmarchaud]

@yosiat I found a fix that involves the way values are stored. Checkout my PR but i believe a similar fix would be possible in cls-hooked

[yosiat]

@vmarchaud this looks really cool!
can't wait for this to be released and replacing cls-hooked with this implementation.

and in the near future use node 14 experimental async local storage

[satazor]

Instead of adding a new method, couldn't we test the return value of the function, and see if it looks like a promise? If so, we would await it, otherwise we keep it like it is now.

The minor check should not impact performance that much for sync code.

[dyladan]

It's not as simple as just awaiting it unfortunately as new async contexts are created. @vmarchaud is looking into a solution with cls-hooked currently

[satazor]

@dyladan I see. Does it mean that https://github.com/open-telemetry/opentelemetry-js/commit/5ea299da7825927d8bd08db6436b43c1a7c0146b has issues?

[dyladan]

Yes unfortunately

[vmarchaud]

@satazor It has specific issue but depending on how you want to use it, it may have no impact. However the method is still not implemented on the tracer so its quite hard to use it for now

[Whoweez]

Hi everyone, great project. I am struggling with tracing beyond an await call:

tracer.getCurrentSpan().addEvent('starting await');
await function test(){
return true
}
tracer.getCurrentSpan().addEvent('finished first await');

Running without await works perfectly fine, but adding it results in an undefined span: "Cannot read property 'addEvent' of undefined"

Any assistance would be appreciated.
Cheers.

[obecny]

What if you run it inside the scope of the desired span ?

tracer.withAsync(tracer.getCurrentSpan(), async () => {
    tracer.getCurrentSpan().addEvent('finished first await');
    await function test(){
        return true;
    }
    tracer.getCurrentSpan().addEvent('finished first await');
});

[Whoweez]

Hey @obecny, thanks for replying!
I get "tracer.withAsync is not a function"

These are my versions:
"@google-cloud/opentelemetry-cloud-trace-exporter": "^0.3.0",
"@opentelemetry/api": "^0.8.0",
"@opentelemetry/node": "^0.8.0",
"@opentelemetry/plugin-express": "^0.7.0",
"@opentelemetry/plugin-http": "^0.8.0",
"@opentelemetry/plugin-mysql": "^0.7.0",
"@opentelemetry/tracing": "^0.8.0"

Do you perhaps know in which version withAsync was implemented?

Also, FYI this is how I create my tracer:

--> tracer.js
const opentelemetry = require("@opentelemetry/api");
const { NodeTracerProvider } = require("@opentelemetry/node");
const { SimpleSpanProcessor } = require("@opentelemetry/tracing");

// Create a provider for activating and tracking spans
const tracerProvider = new NodeTracerProvider({
plugins: {
http: {
enabled: true,
path: "@opentelemetry/plugin-http"
},
express: {
enabled: true,
path: "@opentelemetry/plugin-express"
}
}
});

// Create an exporter for sending spans data
const { TraceExporter } = require('@google-cloud/opentelemetry-cloud-trace-exporter');
// Initialize the exporter
const exporter = new TraceExporter({
projectId: 'xxxxx',
keyFilename: '...../json',
});

// Configure a span processor for the tracer
tracerProvider.addSpanProcessor(new SimpleSpanProcessor(exporter));

// Register the tracer
tracerProvider.register();

const tracer = opentelemetry.trace.getTracer();

module.exports = {
opentelemetry,
tracer
}

[vmarchaud]

We only landed the withAsync on the context manager, the PR for exposing it (via withSpanAsync) on the tracer is still WIP there: https://github.com/open-telemetry/opentelemetry-js/pull/1011

[obecny]

@vmarchaud thx, so @Whoweez this is not yet possible
as a workaround for now you can try tracer.with instead of tracer.withAsync and don't use async, but try with promise inside

[Whoweez]

hi @obecny, thanks! Although, "tracer.with" results in "tracer.with is not a function". Not too sure where this interface comes from in the above version I'm running. Is it perhaps in a another version? All the interface specifies is:
- getCurrentSpan(): Span | undefined;
- startSpan(name: string, options?: SpanOptions, context?: Context): Span;
- withSpan>(span: Span, fn: T):
- bind(target: T, context?: Span): T;

[obecny]

@Whoweez sry I meant withSpan

[Whoweez]

Thanks @obecny. With the above compiled tracer, I get the same error as I did when I ran it without the wrapper: "Cannot read property 'addEvent' of undefined" => on the second getCurrentSpan()

tracer.withSpan(tracer.getCurrentSpan(), async () => {
tracer.getCurrentSpan().addEvent('finished first await');
await function test(){
return true;
}
tracer.getCurrentSpan().addEvent('finished first await');
});

I've also tried adding the:
import { AsyncHooksScopeManager } from '@opentelemetry/scope-async-hooks'
and then registering the tracer with the config as @cohen990 did:
const tracer = registry.getTracer('tracer', undefined, config)

But this too delivers the same error.

On this issue, and the reason why I have jumped onto this thread: with express API running the above tracer:

• requesting the resource from and external client which has exactly the same tracer registered, the second getCurrentSpan() is available,

• requesting the resource from and external client which has no tracer registered, ie no tracer parent in header the second getCurrentSpan() is unavailable, and runs into this problem

The result is that with the first request all the traces are neatly compiled into a waterfall scene whereas with the second call each subsequent span definition, in all my methods, is split across separate traces.

This is just to give you all some context as to why I'm bugging you here, perhaps my setup could be fixed in another way...?

Let me know what you think.

Chio, Wzz

[vmarchaud]

@Whoweez there are no solution available now, thats why the issue is still open

[Whoweez]

@vmarchaud, thank you for the feedback. I'll wait for the implementation. Thanks again for the great repo! Take care :)