Search code examples
open-telemetry-java

Missing opentelemetry-java SERVER span with nested span


I'm seeing some odd behavior with opentelemetry-java (via SmallRye OpenTelemetry). For some context, this is running in the WildFly application server, which integrates smallrye-opentelemtry for its otel support. In SR Otel, there is a ContainerRequestFilter/ContainerResponseFilter that implicitly adds a span to all incoming Jakarta REST requests. You can see that code here: https://github.com/smallrye/smallrye-opentelemetry/blob/2.9.2/implementation/rest/src/main/java/io/smallrye/opentelemetry/implementation/rest/OpenTelemetryServerFilter.java

For a simple REST endpoint (e.g., something that just returns a String), we see the expected span created and exported. However, if the endpoint method creates a nested span, the span created by the filter is not exported. That method might look something like this:

    @GET
    @Produces(MediaType.TEXT_PLAIN)
    @Path("/test")
    public String testOpentelemetry(@QueryParam("question") String question) {
        Span span = tracer.spanBuilder("explicit span")
                .setAttribute("com.acme.string-key", "value")
                .startSpan();
        try { 
            String answer;
            try {
                span.setAttribute("com.acme.question", "question");
                span.addEvent(question);
                answer = question + " received";
                span.setStatus(StatusCode.OK);
            } catch (Exception e) {
                e.printStackTrace();
                span.recordException(e);
                span.setStatus(StatusCode.ERROR);
                answer = "My failure reason is:\n\n" + e.getMessage();
            }
            span.addEvent(answer);
            return answer;
        } finally {
            span.end();
        }
    }

(This is a simple test endpoint, so it's not supposed to make sense :)

If I debug the SdkSpan class, I can see endInternal(long endEpochNanos) called and the span being ending, but it's not ever exported. If I comment out the span-related code, the "implicit" span is again exported.

Is there something odd about explicit spans like this verses the SpanKind.SERVER created in the filter? What am I missing?


Solution

  • OK, so I have an answer, and it's stupid, but I'm going to leave the question and post an answer here in case it helps someone. In this case, the max queue size was set to 1, so the system was dropping the other span. That value is an erroneous and historical wart that I hadn't noticed until I'd put way too much work into debugging this.

    Long story short: if you're seeing this behavior, check your configuration for dumb values. :)