RESTEasy Reactive: Opentracing has incorrect operation name & span is finished prior to aroundWriteTo

[bcluap]

Describe the bug
Opentracing behaves differently in 2 cases between standard RESTEasy and Reactive. In both cases standard RESTEasy seems to be correct:

1. When a sub resource is called, the operation name should be that of the sub resource as opposed to the root resource
2. The jax-rs span should remain open until all aroundWriteTo have been processed so that filters can add additional context into the span (e.g. in our case we add the response body if its a small response)

Expected behavior
As above

Actual behavior
As above

To Reproduce
git clone https://github.com/bcluap/quarkus-examples.git
cd quarkus-examples/resteasy-reactive
mvn clean test
With resteasy reactive one will see two errors in the logs where the values are not as they should be in the span. Run with standard resteasy and the errors are not there as the spans are as expected.

Configuration
Nothing abnormal

Screenshots
Run the reproducer

Environment (please complete the following information):
1.12.2.Final

[bcluap]

Something like this seems to solve issue (2):
It finishes the span in the aroundWriteTo.

@Provider
@Priority(Interceptor.Priority.PLATFORM_AFTER)
public class QuarkusSmallRyeTracingStandaloneContainerResponseFilter implements WriterInterceptor {

    @ServerResponseFilter(priority = Priorities.HEADER_DECORATOR - 1) // this needs to be executed after ServerTracingFilter
    public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext, Throwable t) {
        Object wrapperObj = requestContext.getProperty(SpanWrapper.PROPERTY_NAME);
        if (!(wrapperObj instanceof SpanWrapper)) {
            return;
        }
        SpanWrapper wrapper = (SpanWrapper) wrapperObj;
        Tags.HTTP_STATUS.set(wrapper.get(), responseContext.getStatus());
        if (t != null) {
            FilterUtil.addExceptionLogs(wrapper.get(), t);
        }
    }

    @Override
    public void aroundWriteTo(WriterInterceptorContext wic) throws IOException {
        try {
        wic.proceed();
        } finally {
        Object wrapperObj = wic.getProperty(SpanWrapper.PROPERTY_NAME);
        if (wrapperObj instanceof SpanWrapper) {
            SpanWrapper wrapper = (SpanWrapper) wrapperObj;
            wrapper.getScope().close();
            wrapper.finish();
        }
        }
    }
}

Issue is that I've had to add beans.xml so the provider is picked up. Not sure what the correct way would be to do this within Quarkus itself.

[geoand]

Thanks for reporting!

@Ladicek is this similar to what you were looking at?

[Ladicek]

I don't think it's similar, no.

But it let me connect some pieces together, so that's nice! Here are some of my thoughts that are [mostly] unrelated to this issue.

I didn't know about QuarkusSmallRyeTracingStandaloneContainerResponseFilter, which is an important piece of the puzzle, as it is this class that finishes the span when RESTEasy Reactive is used. (I thought we don't finish it anywhere, silly me!)

OpenTracing Contrib JAX-RS uses a servlet filter to finish the span, because a ContainerResponseFilter doesn't have to be invoked for unmapped exceptions. I don't know if RESTEasy Reactive always invokes ContainerResponseFilters / @ServerResponseFilters, even for unmapped exceptions, that would be good to know.

It would also be interesting to know what happens when RESTEasy Reactive runs on top of servlet (which I know it can). Who will finish the span? Is the QuarkusSmallRyeTracingStandaloneContainerResponseFilter somehow ignored in this scenario, and the OpenTracing Contrib JAX-RS's servlet filter is used? Looking at SmallRyeOpenTracingProcessor, it seems we're good in this regard.

• We always use QuarkusSmallRyeTracingDynamicFeature to start the span. It simply delegates to OpenTracing Contrib JAX-RS's ServerTracingDynamicFeature.
• To finish the span, we use:
  • OpenTracing Contrib JAX-RS's SpanFinishingFilter, if we're on servlet (both classic RESTEasy and RESTEasy Reactive);
  • QuarkusSmallRyeTracingStandaloneVertxDynamicFeature if we're on classic RESTEasy (it uses Vert.x's RoutingContext.addHeadersEndHandler to register a callback that "later" finishes the span);
  • QuarkusSmallRyeTracingStandaloneContainerResponseFilter if we're on RESTEasy Reactive.

When it comes to finishing the span in WriterInterceptor, I guess I don't really have an opinion. MicroProfile OpenTracing only says "The MicroProfile implementation must provide a mechanism to automatically start a Span for any incoming JAX-RS request, and finish the Span when the request completes", which leaves considerable freedom to implementers.

As I describe above, we already have a significant difference in when the span is finished, based on the underlying JAX-RS implementation. If WriterInterceptor is guaranteed to be always called, and is guaranteed to be always after all response filters, then I guess we could finish the span there. But I honestly don't know JAX-RS well enough to say if the conditions hold.

[geoand]

If WriterInterceptor is guaranteed to be always called, and is guaranteed to be always after all response filters, then I guess we could finish the span there. But I honestly don't know JAX-RS well enough to say if the conditions hold.

These assumptions do hold. See https://jakarta.ee/specifications/restful-ws/3.0/jakarta-restful-ws-spec-3.0.html#processing_pipeline

[Ladicek]

That's nice. We could collapse all 3 span-finishing options into 1 :-)

(Well, maybe we should keep using the servlet filter for JAX-RS on servlet. People may have additional servlet filters. But when running on Vert.x, it sounds like both classic RESTEasy and RESTEasy Reactive could use the writer interceptor.)

[geoand]

Yeah, that sounds reasonable

[bcluap]

Hi guys, any luck on this one?

[geoand]

I think this fell through the cracks.
I'll try and take a look next week

[bcluap]

@geoand I've submitted a PR which resolves the span finishing too soon

[bcluap]

Git had an all-fall-down so I needed to recreate the branch and PR. Should be good to go now. If merged, can it be included in 2.0?

[geoand]

Yeah, we can do that

[bcluap]

I've tried to find the cause of the operation name being wrong. Any clues where to look?

[geoand]

I don't know a whole about how OpenTracing has been integrated, so unfortunately I can't provide any pointers

[bcluap]

I investigated a bit and saw that by adding config:

mp.opentracing.server.operation-name-provider=http-path

Now the operation name uses the path which is actually better for me and is not impacted by whether its served by a sub resource or not

[geoand]

Is this still an issue?

[bcluap]

Nope, can be closed due to the other PR's that have resolved these 2 issues.

[geoand]

Thanks!