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

[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 5ea299d 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: #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<T extends (...args: unknown[]) => ReturnType>(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 :)