Exception in observability stack after upgrading Spring Boot to version 3.2.0

[kcsurapaneni]

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

1. Clone the repository: food-delivery-backend
2. Checkout the branch/tag: v3.2.0
3. Check README.md on how to run
4. Now check the order API 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.

[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.

[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

[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.

[philwebb]

micrometer-metrics/tracing#488
jdbc-observations/datasource-micrometer#29

[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).