quarkus: Regression: Programmatic OpenTelemetry spans get ignored
Describe the bug
NOTE: This is a regression in Quarkus 2.13.0.CR1. In previous releases this has always worked as expected.
Background: In our application we store the OpenTelemetry context of incoming REST calls and then use it as the parent in calls which are triggered by a schedule. The schedule does this by programmatically creating a new span with the original span’s Context as parent and then activates the span. When now within this span a RestEasy Reactive Client call is used to call some API, the corresponding CLIENT span ignores the programmatically created span and in fact has no parent span. In previous releases the CLIENT span would reference the programmatically created span as its parent.
The programmatic logic to create a span looks something like this (see org.acme.MyScheduler#scheduled() in attached test for details):
Span span = tracer.spanBuilder("scheduler").setParent(context).startSpan();
try (Scope ignore = context.makeCurrent(); Scope ignore1 = span.makeCurrent()) {
response = client.hello(addressee);
span.end();
}
Expected behavior
Programmatic creation of spans should work as it did in previous Quarkus releases.
Actual behavior
See description.
Here are the spans (serialized JSON) created by the attached example project:
{
"resource": {
"attributes": [
{
"key": "service.name",
"value": {
"stringValue": "code-with-quarkus"
}
},
{
"key": "service.version",
"value": {
"stringValue": "1.0.0-SNAPSHOT"
}
},
{
"key": "telemetry.sdk.language",
"value": {
"stringValue": "java"
}
},
{
"key": "telemetry.sdk.name",
"value": {
"stringValue": "opentelemetry"
}
},
{
"key": "telemetry.sdk.version",
"value": {
"stringValue": "1.17.0"
}
},
{
"key": "webengine.name",
"value": {
"stringValue": "Quarkus"
}
},
{
"key": "webengine.version",
"value": {
"stringValue": "2.13.0.CR1"
}
}
]
},
"scopeSpans": [
{
"scope": {
"name": "io.quarkus.opentelemetry"
},
"spans": [
{
"traceId": "62ffe5f3278ee2dbefabc499f50037e2",
"spanId": "5f78270f084c18c7",
"parentSpanId": "a49e8f9f5b8e4d77",
"name": "/hello",
"kind": "SPAN_KIND_SERVER",
"startTimeUnixNano": "1663341640147360000",
"endTimeUnixNano": "1663341640191058401",
"attributes": [
{
"key": "http.response_content_length",
"value": {
"intValue": "28"
}
},
{
"key": "http.route",
"value": {
"stringValue": "/hello"
}
},
{
"key": "http.user_agent",
"value": {
"stringValue": "Apache-HttpClient/4.5.13 (Java/17.0.4)"
}
},
{
"key": "http.flavor",
"value": {
"stringValue": "1.1"
}
},
{
"key": "http.target",
"value": {
"stringValue": "/hello"
}
},
{
"key": "http.status_code",
"value": {
"intValue": "200"
}
},
{
"key": "http.client_ip",
"value": {
"stringValue": "127.0.0.1"
}
},
{
"key": "http.scheme",
"value": {
"stringValue": "http"
}
},
{
"key": "http.host",
"value": {
"stringValue": "localhost:8081"
}
},
{
"key": "http.method",
"value": {
"stringValue": "GET"
}
}
],
"events": [],
"links": [],
"status": {}
},
{
"traceId": "3042707be1f4a888f1f52c1fd49f5520",
"spanId": "56cbdfd8da10b8b3",
"parentSpanId": "f2d8926f2e017182",
"name": "/hello/internal",
"kind": "SPAN_KIND_SERVER",
"startTimeUnixNano": "1663341641109469200",
"endTimeUnixNano": "1663341641115058800",
"attributes": [
{
"key": "http.response_content_length",
"value": {
"intValue": "11"
}
},
{
"key": "http.route",
"value": {
"stringValue": "/hello/internal"
}
},
{
"key": "http.user_agent",
"value": {
"stringValue": "Resteasy Reactive Client"
}
},
{
"key": "http.flavor",
"value": {
"stringValue": "1.1"
}
},
{
"key": "http.target",
"value": {
"stringValue": "/hello/internal"
}
},
{
"key": "http.status_code",
"value": {
"intValue": "200"
}
},
{
"key": "http.client_ip",
"value": {
"stringValue": "127.0.0.1"
}
},
{
"key": "http.scheme",
"value": {
"stringValue": "http"
}
},
{
"key": "http.host",
"value": {
"stringValue": "localhost:8081"
}
},
{
"key": "http.method",
"value": {
"stringValue": "GET"
}
},
{
"key": "http.request_content_length",
"value": {
"intValue": "5"
}
}
],
"events": [],
"links": [],
"status": {}
},
{
"traceId": "3042707be1f4a888f1f52c1fd49f5520",
"spanId": "f2d8926f2e017182",
"name": "HTTP GET",
"kind": "SPAN_KIND_CLIENT",
"startTimeUnixNano": "1663341641105501300",
"endTimeUnixNano": "1663341641119615600",
"attributes": [
{
"key": "http.response_content_length",
"value": {
"intValue": "11"
}
},
{
"key": "http.user_agent",
"value": {
"stringValue": "Resteasy Reactive Client"
}
},
{
"key": "http.status_code",
"value": {
"intValue": "200"
}
},
{
"key": "http.method",
"value": {
"stringValue": "GET"
}
},
{
"key": "http.url",
"value": {
"stringValue": "http://localhost:8081/hello/internal"
}
}
],
"events": [],
"links": [],
"status": {}
},
{
"traceId": "62ffe5f3278ee2dbefabc499f50037e2",
"spanId": "10611f1988f86ede",
"parentSpanId": "5f78270f084c18c7",
"name": "scheduler",
"kind": "SPAN_KIND_INTERNAL",
"startTimeUnixNano": "1663341641000663901",
"endTimeUnixNano": "1663341641123223601",
"attributes": [],
"events": [],
"links": [],
"status": {}
}
]
}
]
}
How to Reproduce?
Run mvn verify in the attached test application: code-with-quarkus.zip
Output of uname -a or ver
No response
Output of java -version
No response
GraalVM version (if different from Java)
No response
Quarkus version or git rev
2.13.0.CR1
Build tool (ie. output of mvnw --version or gradlew --version)
No response
Additional information
No response
About this issue
- Original URL
- State: closed
- Created 2 years ago
- Comments: 17 (16 by maintainers)
In fact I think we have an on-success hook (forgot what it is called right now) with which we immediately attempt to execute the registered operation. While still using OpenTracing we created a FOLLOWS_FROM span (part of the same trace). This concept doesn’t exist in OpenTelemetry, but we should again look into linked spans.
Workarounds often have this characteristic 😃 But thanks a lot for investigating and this workaround. We will certainly be able to wait for a proper solution in a patch release.