Thursday, October 21, 2021

Spring boot upgrade from 2.2.x to 2.5.x - Spring Cloud Sleuth Zipkin - log message format change . . .

I recently upgraded a Spring Boot micro-service application from Spring Boot 2.2.11 to 2.5.3 and Java OpenJDK 15 to Java Amazon Corretto 16.

Upgrading Java was smooth. Some major and breaking changes that I came across from Spring Boot side include:
  • Profile changes - documented well
  • Dependency changes - Obvious
  • Spring Cloud Sleuth Zipkin - Undocumented glitch
This post is on the Spring Cloud Sleuth Zipkin - undocumented removal of exportable property.

Environment: Java 16, Spring Boot 2.5.3 on macOS Catalina 10.15.7

We have application logs collected, ingested and indexed in Datadog by Logstash scrapping Mesos application's stdout. Soon after the upgrade, logs stopped showing up in Datadog. After some investigation, figured out that the pattern parser failed to parse log string as it was expecting log string format like: [service, trace, span, exportable]. But the format after the upgrade was: [service, trace, span]. Basically, the last exportable property with value true or false was missing. 

The trace, span, exportable are injected into log messages by Spring Cloud Sleuth and Zipkin for distributed tracing via log framework MD5. The documentation of Spring Cloud Sleuth seems not updated with this details. :(

In order to get away with this issue on the Datadog, switching to JSON log message format seemed like a better solution as the JSON is better than strict string pattern matchers. This required an explicit logback definition in resources/logback-spring.xml file (yes, XML is the only way) and a new dependency for JSON logging.

src/main/resources/logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?> <configuration> <include resource="org/springframework/boot/logging/logback/defaults.xml"/> <springProperty scope="context" name="serviceName" source="spring.zipkin.service.name"/> <appender name="console" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder"> <providers> <pattern> <pattern> { "timestamp": "%d{yyyy-MM-dd HH:mm:ss.SSS}", "severity": "%level", "service": "${serviceName:-}", "pid": "${PID:-}", "thread": "%thread", "class": "%logger{40}", "trace": "%X{traceId:-}", "span": "%X{spanId:-}", "parent": "%X{parentId:-}", "exportable": "%X{sampled:-}", "logmessage": "%message" } </pattern> </pattern> <!-- Additional support needed for logging stack trace in JSON message --> <!-- https://github.com/logfellow/logstash-logback-encoder --> <stackTrace> <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter"> <maxDepthPerThrowable>30</maxDepthPerThrowable> <maxLength>4096</maxLength> <shortenedClassNameLength>20</shortenedClassNameLength> <rootCauseFirst>true</rootCauseFirst> </throwableConverter> </stackTrace> </providers> </encoder> </appender> <root level="INFO"> <appender-ref ref="console" /> </root> </configuration>

Maven build file, new dependency for JSON log message: pom.xml
<dependency> <groupId>net.logstash.logback</groupId> <artifactId>logstash-logback-encoder</artifactId> <version>6.6</version> </dependency>

With this a sample JSON exception log messages looks like:

{ "timestamp": "2021-12-22 12:26:26.552", "severity": "ERROR", "service": "my-service-api", "pid": "65623", "thread": "http-nio-8080-exec-6", "class": "c.g.s.e.MyServceImpl", "trace": "529f2d2d7a65dde4", "span": "529f2d2d7a65dde4", "parent": "", "exportable": "", "logmessage": "My Exception log mesage.", "stack_trace": "c.g.s.e.MyException: my exception message\n\tat c.g.s.s.MyServiceImpl.serviceMethodOne(MyServiceImpl.java:210)\n\tat c.g.s.s.MyServiceImpl.serviceMethoTwo(MyServiceImpl.java:280)\n" }

References


No comments:

Post a Comment