Spring Boot 3.2 — Logging correlation
Introduction
Spring Boot reimagines Java development, prioritizing speed and simplicity. Gone are verbose configurations and complex setups. Embrace convention, leverage embedded servers, and build applications in a flash. Spring Boot delivers opinionated defaults and powerful starters, enabling developers to focus on core functionalities and unlock rapid application development. More than just ease of use, Spring Boot champions production-ready features, built-in monitoring, and seamless cloud deployments. This is Java development, streamlined.
Spring Boot 3.2 arrives amidst much anticipation, bringing with it a wave of performance enhancements and cutting-edge features. Virtual threads unlock unprecedented scalability, while JVM Checkpoint Restore slashes application restart times. And much more. This article focuses on one particular Spring Boot 3.2 feature: Logging correlation.
Logging correlation
With 3.2, Spring Boot starts logging a correlation ID for all the logs relating to one HTTP transaction as long as micrometer tracing is enabled. This behavior is ON by default.
Behavior till Spring Boot 3.1
To fully appreciate the advancements in Spring Boot 3.2, let’s first take a step back and examine QR code generation within the context of Spring Boot 3.1. To illustrate this process, consider the following QR generator application:
pom.xml
<?xml version="1.0" encoding="UTF-8"?>
<project
xmlns="http://maven.apache.org/POM/4.0.0"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.1.0</version>
<relativePath/>
</parent>
<groupId>com.example</groupId>
<artifactId>demo</artifactId>
<version>0.0.1-SNAPSHOT</version>
<name>demo</name>
<description>QR project for Spring Boot</description>
<properties>
<java.version>21</java.version>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-test</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependency>
<groupId>io.micrometer</groupId>
<artifactId>micrometer-observation</artifactId>
</dependency>
<dependency>
<groupId>io.micrometer</groupId>
<artifactId>micrometer-tracing-bridge-brave</artifactId>
</dependency>
<dependency>
<groupId>io.zipkin.reporter2</groupId>
<artifactId>zipkin-reporter-brave</artifactId>
</dependency>
<dependency>
<groupId>io.micrometer</groupId>
<artifactId>micrometer-registry-atlas</artifactId>
<version>1.11.0</version>
</dependency>
<dependency>
<groupId>com.google.zxing</groupId>
<artifactId>core</artifactId>
<version>3.4.0</version>
</dependency>
<dependency>
<groupId>com.google.zxing</groupId>
<artifactId>javase</artifactId>
<version>3.4.0</version>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
<configuration>
<mainClass>com.example.qr.QrApplication</mainClass>
<layout>JAR</layout>
</configuration>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-compiler-plugin</artifactId>
<version>3.10.1</version>
<configuration>
<release>21</release>
<enablePreview>true</enablePreview>
<compilerArgs>--enable-preview</compilerArgs>
</configuration>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-surefire-plugin</artifactId>
<version>3.1.2</version>
<configuration>
<argLine>--enable-preview</argLine>
</configuration>
</plugin>
</plugins>
</build>
</project>QrApplication.java
package com.example.qr;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.web.embedded.tomcat.TomcatProtocolHandlerCustomizer;
import org.springframework.context.annotation.Bean;
import java.util.concurrent.Executors;
@SpringBootApplication
public class QrApplication {
public static void main(String[] args) {
SpringApplication.run(QrApplication.class, args);
}
}
QrController.java
package com.example.qr;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.http.ResponseEntity;
import org.springframework.http.HttpStatus;
import org.springframework.http.HttpHeaders;
import org.springframework.web.bind.annotation.RestController;
import java.util.Optional;
import com.example.qr.QrRequest;
import com.example.qr.QrGenerator;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@RestController
public class QrController {
private static final Logger log = LoggerFactory.getLogger(QrController.class);
@PostMapping("/qr")
public ResponseEntity handleRequest(@RequestBody QrRequest qrRequest) {
log.info("Received client request");
if(qrRequest.getUrlToEmbed() == null) {
return new ResponseEntity<>(HttpStatus.BAD_REQUEST);
}
try {
HttpHeaders httpHeaders = new HttpHeaders();
httpHeaders.add(HttpHeaders.CONTENT_TYPE, "image/png");
String urlToEmbed = qrRequest.getUrlToEmbed();
log.info("Generating QR image for "+urlToEmbed);
return new ResponseEntity<byte[]>(
QrGenerator.generateQR(urlToEmbed, 512, 512),
httpHeaders,
HttpStatus.OK);
} catch (Exception e) {
return new ResponseEntity<>(HttpStatus.INTERNAL_SERVER_ERROR);
}
}
}
QrRequest.java
package com.example.qr;
public class QrRequest {
private String urlToEmbed;
public String getUrlToEmbed() {
return this.urlToEmbed;
}
public void setUrlToEmbed(String urlToEmbed) {
this.urlToEmbed = urlToEmbed;
}
}QrGenerator.java
package com.example.qr;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import com.google.zxing.BarcodeFormat;
import com.google.zxing.WriterException;
import com.google.zxing.client.j2se.MatrixToImageConfig;
import com.google.zxing.client.j2se.MatrixToImageWriter;
import com.google.zxing.common.BitMatrix;
import com.google.zxing.qrcode.QRCodeWriter;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class QrGenerator {
private static final Logger log = LoggerFactory.getLogger(QrGenerator.class);
public static byte[] generateQR(String text, int width, int height) throws WriterException, IOException {
QRCodeWriter qrCodeWriter = new QRCodeWriter();
BitMatrix bitMatrix = qrCodeWriter.encode(text, BarcodeFormat.QR_CODE, width, height);
ByteArrayOutputStream pngOutputStream = new ByteArrayOutputStream();
MatrixToImageConfig con = new MatrixToImageConfig() ;
MatrixToImageWriter.writeToStream(bitMatrix, "PNG", pngOutputStream, con);
byte[] pngData = pngOutputStream.toByteArray();
log.info("Generated QR image for "+text);
return pngData;
}
}Let’s run a couple of tests (one success and one failure) using curl:
> curl https://localhost:3000/qr -d '{}' -H 'content-type: application/json' -k -o /dev/null -s
> curl https://localhost:3000/qr -d '{"urlToEmbed": "http://abcd.com"}' -H 'content-type: application/json' -k -o /dev/null -sHere are the logs on the server side:
2023-12-25T21:30:48.714-08:00 INFO 63413 --- [nio-3000-exec-5] com.example.qr.QrController : Received client request
2023-12-25T21:30:48.714-08:00 INFO 63413 --- [nio-3000-exec-5] com.example.qr.QrController : Required parameter urlToEmbed missing
2023-12-25T21:30:56.810-08:00 INFO 63413 --- [io-3000-exec-10] com.example.qr.QrController : Received client request
2023-12-25T21:30:56.810-08:00 INFO 63413 --- [io-3000-exec-10] com.example.qr.QrController : Generating QR image for http://abcd.com
2023-12-25T21:30:56.874-08:00 INFO 63413 --- [io-3000-exec-10] com.example.qr.QrGenerator : Generated QR image for http://abcd.comWhile the log statements reveal two client requests handled by distinct threads, relying solely on thread IDs for identification may not be enough. Thread IDs are not a unique identifier and can get reused very quickly, increasing the likelihood of confusion and hindering accurate tracing in complex systems.
Spring Boot 3.2
With Spring Boot 3.2, we get a unique correlation ID (free!) in each log statement as long as micrometer tracing is used. This makes it very easy to trace the journey of the request without doing anything except for enabling the micrometer tracing.
Everything remains the same in the pom.xml except for the Spring Boot version:
pom.xml (abbreviated)
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.2.1</version>
<relativePath/>
</parent>Here are the server logs for Spring Boot 3.2 (using the same curl requests):
2023-12-25T21:39:28.882-08:00 INFO 64259 --- [omcat-handler-4] [658a67107efe094781f4b6e8e0ecedc6-81f4b6e8e0ecedc6] com.example.qr.QrController : Received client request
2023-12-25T21:39:28.882-08:00 INFO 64259 --- [omcat-handler-4] [658a67107efe094781f4b6e8e0ecedc6-81f4b6e8e0ecedc6] com.example.qr.QrController : Required parameter urlToEmbed missing
2023-12-25T21:39:34.242-08:00 INFO 64259 --- [omcat-handler-9] [658a67168c3f00236c4f5f3f04d50f07-6c4f5f3f04d50f07] com.example.qr.QrController : Received client request
2023-12-25T21:39:34.242-08:00 INFO 64259 --- [omcat-handler-9] [658a67168c3f00236c4f5f3f04d50f07-6c4f5f3f04d50f07] com.example.qr.QrController : Generating QR image for http://abcd.com
2023-12-25T21:39:34.295-08:00 INFO 64259 --- [omcat-handler-9] [658a67168c3f00236c4f5f3f04d50f07-6c4f5f3f04d50f07] com.example.qr.QrGenerator : Generated QR image for http://abcd.comTo facilitate comprehensive request tracking, Spring Boot 3.2 meticulously assigns a distinct ID to each client request, which is then consistently embedded within all log statements produced throughout its lifecycle.
Thanks for reading!
