Unexpected call to Scope::detach() in asynchronous environment.

[bartvanhoutte]

Describe your environment PHP 8.3, ext-ffi enabled, using Fibers with ReactPHP.

Steps to reproduce

$span = $tracer->spanBuilder('init')->startSpan();
$context = $span->activate();

Loop::addTimer(5, async(function () use ($span, $context) {
    $span->end();
    $context->detach();
}));

Obviously the real life example makes more sense but the code above demonstrates the problem rather well.

What is the expected behavior? I'm expecting the scope to be detached without notice. As per the documentation the context is being detached after the span is ended.

What is the actual behavior? The following notice is printed: Notice: Scope: unexpected call to Scope::detach() for scope #2654, scope successfully detached from different execution context in DebugScope.php on line 48

It looks like the BatchSpanProcessor is calling detach on the span before I have the chance to do it.

[brettmc]

I have not tried this before, but looking at the code for the initialize_fiber_handler.php file, it looks like you need to enable fiber support with OTEL_PHP_FIBERS_ENABLED - have you done this?

[bartvanhoutte]

Yes, OTEL_PHP_FIBERS_ENABLED is true and works in most obvious async/await scenarios. The out-of-the-box support for this blew my mind by the way. However, when calling $span->end() & $context->detach() in a timer callback, or RxPHP Observable onCompleted handler, the notice is thrown.

[Nevay]

Scopes must be detached in the execution context (Fiber/Coroutine) they were created in.

$span = $tracer->spanBuilder('init')->startSpan();
$scope = $span->activate();

Loop::addTimer(5, async(function () use ($span) {
    $span->end();
}));

$scope->detach();

Note that the context is not propagated to event loop callbacks by default ref.: open-telemetry/context. I am not aware of an implementation that handles this directly for ReactPHP, but you could try using https://github.com/Nevay/opentelemetry-revolt-adapter with https://github.com/revoltphp/event-loop-adapter-react.

[bartvanhoutte]

Thanks @Nevay. I will look into this further. I was under the impression this would work since otel keeps track of fibers and the async call creates a new fiber?

I'm unsure about how the code in your example would work since the $scope->detach(); will trigger immediately after $span->activate();?

[bartvanhoutte]

@Nevay Does this make more sense?

$span = $this->tracer->spanBuilder('init')->startSpan();
$scope = $span->activate();
$context = Context::getCurrent();

$span->addEvent('something happened');

Loop::addTimer(5, async(function () use ($span, $context) {
    $scope = $context->activate();
    $span->addEvent('event added from timer');
    $span->end();
    $scope->detach();
}));

$scope->detach();

[Nevay]

I was under the impression this would work since otel keeps track of fibers and the async call creates a new fiber?

It would work if async() would create the fiber immediately; the fiber is only created once the returned callable is invoked.

https://github.com/open-telemetry/opentelemetry-php/issues/1199#issuecomment-1870466627

This is the correct usage / what should be done by the event loop on callback registration to preserve the context without having to pass it around. Using the example function from open-telemetry/context; bindContext() would be implemented by an event loop wrapper and not explicitly called by the user:

$span = $tracer->spanBuilder('init')->startSpan();
$scope = $span->activate();

$span->addEvent('something happened');

// Loop::addTimer(5, async(function () use ($span) {
Loop::addTimer(5, bindContext(async(function () use ($span) {
    assert($span === Span::getCurrent());
    $span->addEvent('event added from timer');
    $span->end();
})));

$scope->detach();

function bindContext(Closure $closure): Closure {
    $context = Context::getCurrent();
    return static function (mixed ...$args) use ($closure, $context): mixed {
        $scope = $context->activate();
        try {
            return $closure(...$args);
        } finally {
            $scope->detach();
        }
    };
}

[brettmc]

I think we need some documentation and examples for context + async/fibers in https://opentelemetry.io/docs/instrumentation/php/

[bartvanhoutte]

Thanks for the example @Nevay, that clears things up. I'll create a decorator for the ReactPHP event loop and report back.

[bartvanhoutte]

@brettmc I'm guessing using the gRPC transport also blocks the event loop? If that's the case we'll have to document that as well.

[brettmc]

Somewhat related to this issue, I started writing some doco for Context in https://github.com/open-telemetry/opentelemetry.io/pull/3857 I touched on async context, but I think most of what is mentioned in this issue is too low-level for the average user.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.