suboptimal behavior of @Traced when applied to methods that don't finish synchronously

[Ladicek]

There's a couple of "context propagation" issues in this issue tracker already, but I think this deserves its own :-)

Say I have a CDI bean with a @Traced method, which returns a CompletionStage. This can be for example:

• a method that is annotated with MP Fault Tolerance @Asynchronous and therefore is executed on an extra thread
• a method that uses MP Context Propagation's ManagedExecutor to defer execution of some part of the method

Such method can be called for example from a JAX-RS endpoint, where the method also returns CompletionStage (this is standard since JAX-RS 2.1).

In such case, whatever is done to the span asynchronously (after the @Traced method returns) may be lost, and that is even if I hack together OpenTracing context propagation (which we've done in SmallRye Fault Tolerance). This is because the @Traced interceptor closes the scope synchronously. That's of course a correct/specified behavior, but I think it's also rather suboptimal.

We should find a way how to make these scenarios work. Integrating with Context Propagation is necessary, but not enough.

[pavolloffay]

@Ladicek I am not sure if I fully understand you. Could you please provide a code snipped and mark where changes to span will be lost?

I think a new scope should be created when the execution is dispatched to the new thread.

I am not sure how exactly CompletionStage with servlet filters work. My concern is that servlet filter would close the span while the CompletionStage is still running, once span is finished it is reported.

[Ladicek]

I don't know about servlet, that's not part of MicroProfile :-) But with JAX-RS, if the resource method returns CompletionStage, then the response only finishes after that CompletionStage completes and the result is written to the response stream. And only at that time is the span closed.

For example:

@ApplicationScoped
public class HelloService {
    @Inject
    ManagedExecutor executor; // MP Context Propagation

    @Inject
    Tracer tracer;

    @Traced
    public CompletionStage<String> get(String name) {
        tracer.activeSpan().log("HelloService called");

        return executor.supplyAsync(() -> {
            tracer.activeSpan().log("HelloService async processing");
            return "Hello, " + name + "!";
        });
    }
}

@Path("/hello")
public class HelloResource {
    @Inject
    HelloService hello;

    @GET
    public CompletionStage<String> hello() {
        return hello.get("World");
    }
}

Here, the HelloService async processing log can be lost, because the span is closed when the HelloService.get method returns. However, if I remove the @Traced annotation, it's all fine, because the active span is the one for the JAX-RS resource method, which is only closed after the response is finished (which happens after the CompletionStage completes).

Again, I realize this is how it's supposed to work (as @Traced is an interceptor), but it's unfriendly. It actually took me quite a while to realize what's going on.

[pavolloffay]

I don't know about servlet, that's not part of MicroProfile :-)

It doesn't have to be servlet it can be any underlying technology that is running JAX-RS. E.g. SmallRye-OpenTracing uses servlet filter by to finish spans bc jax-rs response filter is not invoked in case of exceptions...

Thanks for the great explanation. The problem like this could be solved by using a reference counting on number of created OpenTracing Scopes. Then the span is closed only when all scopes are closed. Here is an implementation of such ScopeManager https://github.com/opentracing/opentracing-java/blob/master/opentracing-testbed/src/test/java/io/opentracing/testbed/AutoFinishScopeManager.java#L30. It also brings other problems...

The other solution might be to create a new span for the execution of the callback:

        return executor.supplyAsync(() -> {
            tracer.activeSpan().log("HelloService async processing");
            return "Hello, " + name + "!";
        });