Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

4.x Telemetry scopes are not closed properly when using baggage #8187

Closed
tjquinno opened this issue Jan 3, 2024 · 0 comments · Fixed by #8225
Closed

4.x Telemetry scopes are not closed properly when using baggage #8187

tjquinno opened this issue Jan 3, 2024 · 0 comments · Fixed by #8225
Assignees
Labels
3.x Issues for 3.x version branch 4.x Version 4.x bug Something isn't working P2 telemetry
Milestone

Comments

@tjquinno
Copy link
Member

tjquinno commented Jan 3, 2024

Environment Details

  • Helidon Version: 4.x
  • Helidon SE or Helidon MP
  • JDK version:
  • OS:
  • Docker version (if applicable):

Problem Description

In an app that uses OpenTelemetry tracing, adding baggage disrupts the handling of scopes.

Specifically, creating a span, activating it (which creates an autocloseable Scope), and then adding baggage to the span within the try block causes the try-with-resources close handling for the scope to act as a no-op.

Steps to reproduce

You do not need to start Jaeger to receive the tracing; just ignore the runtime errors about being unable to send the tracing information.

  1. Create a new SE app using helidon init and specify custom with tracing; take the other defaults.
  2. Replace the generated TracedService.TracedHandler#handle method with this:
         @Override
         public void handle(ServerRequest req, ServerResponse res) {
             Tracer tracer = req.context().get(Tracer.class)
                     .orElseGet(Tracer::global);
             Span span = tracer.spanBuilder("custom-span")
                     .start();
             Span.current().ifPresentOrElse(s -> System.err.println("Current span before try-with-resources: " + s.context().spanId()),
                                            () -> System.err.println("No current span before try-with-resources"));
    
             try (Scope scope = span.activate()) {
                 Span.current().ifPresentOrElse(s -> System.err.println("Current span in try-with-resources: " + s.context().spanId()),
                                                () -> System.err.println("No current span in try-with-resources"));
                 span.addEvent("my nice log");
    
                 res.send(message);
             } finally {
                 span.end();
             }
             Span.current().ifPresentOrElse(s -> System.err.println("Current span after try-with-resources: " + s.context().spanId()),
                                            () -> System.err.println("No current span after try-with-resources"));
         }
    
    The changes do two things:
    1. Explicitly activate the custom span in the try, creating an auto-closable Scope.
    2. Display the current span just before, just inside, and just after the try-with-resources block.
  3. Build and run the app and run curl http://localhost:8080/traced. You see the expected two different current spans at the expected times:
    Current span before try-with-resources: 268165d9440e2b8f
    Current span in try-with-resources: 1cfbe8a1c629213b
    Current span after try-with-resources: 268165d9440e2b8f
    
  4. Add the following lines after the span.addEvent line in TracedService.TracedHandler#handle:
    span.baggage("myInfo", "myValue");
    Span.current().ifPresentOrElse(s -> System.err.println("Current span after setting baggage: " + s.context().spanId()),
                                () -> System.err.println("No current span after setting baggage"));
    
  5. Stop, rebuild, and rerun the app and run curl http://localhost:8080/traced again.

The output reports the same span all three times:

Current span before try-with-resources: f3aa5b9b91198f31
Current span in try-with-resources: d93eaba9643f0c51
Current span after setting baggage: d93eaba9643f0c51
Current span after try-with-resources: d93eaba9643f0c51

The scope explicitly declared in the try that should be auto-closed is not.

This seems to occur because the Helidon OpenTelemetrySpan#baggage(String, String) method creates a new Baggage instance (as it should) and stores it in a new context and makes the new context current. This creates a new activeScope but the scope is not exposed to the caller nor closed.

Later, during the auto-close of the explicit scope in the modified example code, the Helidon scope delegates the close operation to the OpenTelemetry scope which checks to see if the scope being closed is the current scope. It is not in this scenario, so the OTel code ignores the attempt to close the scope.

That is why the span ID after the try-with-resources block is unchanged once the baggage is added.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
3.x Issues for 3.x version branch 4.x Version 4.x bug Something isn't working P2 telemetry
Projects
Archived in project
2 participants