Issue Description
Exception Details
2023-11-26T16:00:43.087Z WARN [order service,,] 1 --- [order service] [BatchSpanProcessor_WorkerThread-1] [] i.o.exporter.zipkin.ZipkinSpanExporter : Failed to export spans
org.springframework.web.client.HttpClientErrorException$BadRequest: 400 Bad Request: "valid annotation timestamp required<EOL>"
at org.springframework.web.client.HttpClientErrorException.create(HttpClientErrorException.java:103)
at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:183)
at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:137)
at org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)
at org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:932)
at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:881)
at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:781)
at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:663)
at org.springframework.boot.actuate.autoconfigure.tracing.zipkin.ZipkinRestTemplateSender$RestTemplateHttpPostCall.doExecute(ZipkinRestTemplateSender.java:68)
at org.springframework.boot.actuate.autoconfigure.tracing.zipkin.ZipkinRestTemplateSender$RestTemplateHttpPostCall.doEnqueue(ZipkinRestTemplateSender.java:75)
at zipkin2.Call$Base.enqueue(Call.java:406)
at io.opentelemetry.exporter.zipkin.ZipkinSpanExporter.export(ZipkinSpanExporter.java:82)
at io.micrometer.tracing.otel.bridge.CompositeSpanExporter.lambda$export$3(CompositeSpanExporter.java:88)
at java.base/java.lang.Iterable.forEach(Iterable.java:75)
at io.micrometer.tracing.otel.bridge.CompositeSpanExporter.export(CompositeSpanExporter.java:88)
at io.opentelemetry.sdk.trace.export.BatchSpanProcessor$Worker.exportCurrentBatch(BatchSpanProcessor.java:327)
at io.opentelemetry.sdk.trace.export.BatchSpanProcessor$Worker.run(BatchSpanProcessor.java:245)
at java.base/java.lang.Thread.run(Thread.java:833)
Environment Details
Spring Boot Version: 3.2.0
Issue Summary
When upgrading the observability stack from Spring Boot version 3.1.3 to 3.2.0, the following exception is encountered:
Dependencies
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.2.0</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependencies>
<dependency>
<groupId>io.micrometer</groupId>
<artifactId>micrometer-tracing-bridge-otel</artifactId>
</dependency>
<dependency>
<groupId>io.opentelemetry</groupId>
<artifactId>opentelemetry-exporter-zipkin</artifactId>
</dependency>
</dependencies>
Reproduction Steps
- Clone the repository: food-delivery-backend
- Checkout the branch/tag:
v3.2.0 - Check README.md on how to run
- Now check the
orderAPI logs in Grafana
Additional Information
- Working Sample (Spring Boot 3.1.3):
- v3.1.3/order - No issues observed
- Failing Sample (Spring Boot 3.2.0):
- v3.2.0/order - Exception occurs
Note
The issue seems to be specific to Spring Boot version 3.2.0. The provided code samples and branches should aid in reproducing and investigating the problem.
Comment From: wilkinsona
This appears to be a duplicate of https://stackoverflow.com/questions/77552544/exception-in-observability-stack-after-upgrading-spring-boot-to-version-3-2-0 where people are already trying to help you. To avoid wasting their time, I'm going to close this issue for now. We can re-open it if a bug in Spring Boot is identified. I will also ask someone from the Observability team to look at the question.
Comment From: mrjackbo
I observed the same problem, and I don't have a stackoverflow account, so I am posting here. I captured the packet causing tempo to return 400, and it seems the offending part is as follows:
{
"traceId": "XXXX",
"parentId": "XXXX",
"id": "XXXX",
"kind": "CLIENT",
"name": "connection",
"timestamp": 1702045951598046,
"duration": 6111,
"localEndpoint": {
"serviceName": "XXXX",
"ipv4": "XXXX""
},
"annotations": [
{
"timestamp": 0,
"value": "\"acquired\":{}"
},
{
"timestamp": 0,
"value": "\"commit\":{}"
}
],
"tags": {
"jdbc.datasource.driver": "org.postgresql.Driver",
"jdbc.datasource.pool": "HikariPool-1",
"otel.library.name": "org.springframework.boot",
"otel.library.version": "3.2.0",
"otel.scope.name": "org.springframework.boot",
"otel.scope.version": "3.2.0"
}
},
Once I remove all such hikari traces, I can send the payload to tempo and the traces are created as expected. The timestamps are obviously invalid, which fits with the error message 400 Bad Request: "valid annotation timestamp required
Comment From: philwebb
Thanks for that additional info @mrjackbo.
It looks like this is problem with the new io.micrometer.observation.Observation.Event.getWallTime() method which was added in Micrometer 1.12.0 (which we use in Spring Boot 3.2) and defaults to 0.
net.ttddyy.observation.tracing.JdbcObservationDocumentation.JdbcEvents is built against an older version of micrometer and doesn't override the method so we end up with 0 being used.
I think there's possibly two bugs here. JdbcObservationDocumentation could be updated and Micrometer could also fail with a better message.
Comment From: philwebb
https://github.com/micrometer-metrics/tracing/issues/488 https://github.com/jdbc-observations/datasource-micrometer/issues/29
Comment From: jonatan-ivanov
Thanks to the collaboration on this, a bug was identified in Micrometer Tracing, fixed then released (1.2.1). Please upgrade your Micrometer Tracing version (you can also wait till the next Boot release since it should pick up the fixed version).