Trace HTTP request in with Micrometer

Why do we want to trace http request?

On an API application, that has numerous concurrent request calls. If get an exception of a bug and you want to find the root cause, it can be hard when you look in the simple logs.

We can use trace IDs to correlate our log messages. From that, you can figure out the logs belong to which request. Furthermore, we can include trace IDs in our error response and then use that IDs to trace back to the cause.

In this post, I will add trace IDS to logs in Spring Boot 3 by using Micrometer.

What is Micrometer?

Micrometer is a tool that helps developers keep track of how their application performing. It does this by collecting and displaying data about things like response times, errors, and how many requests are being made.

Setting up project

build.gradle

plugins {
    id 'java'
    id 'org.springframework.boot' version '3.1.2'
    id 'io.spring.dependency-management' version '1.1.2'
}

group 'com.example'
version '1.0-SNAPSHOT'

repositories {
    mavenCentral()
}

sourceCompatibility = '18'
targetCompatibility = '18'

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-web'
    compileOnly 'org.projectlombok:lombok:1.18.28'
    annotationProcessor 'org.projectlombok:lombok:1.18.28'

    implementation 'org.springframework.boot:spring-boot-starter-actuator:3.1.2'

    implementation platform('io.micrometer:micrometer-tracing-bom:latest.release')
    implementation 'io.micrometer:micrometer-observation:1.11.3'
    implementation 'io.micrometer:micrometer-tracing-bridge-brave:1.1.4'

    testImplementation 'org.springframework.boot:spring-boot-starter-test'
}

test {
    useJUnitPlatform()
}

micrometer-observation maven dependency is responsible for making Observations, which are a way of measuring and recording metrics in a Spring Boot application.
micrometer-tracing-bridge-brave dependency is used for tracing your Spring Boot application.

HelloController.java

@Slf4j
@RestController
public class HelloController {
    private final HelloService helloService;

    public HelloController(HelloService helloService) {
        this.helloService = helloService;
    }

    @GetMapping("/hello")
    public ResponseEntity<String> hello() {
        log.info("Hello from HelloController");
        helloService.hello();
        return ResponseEntity.ok("hello");
    }
}

OtherController.java

@Slf4j
@RestController
public class OtherController {
    @GetMapping("/other")
    public ResponseEntity<String> hello(HttpServletRequest request) {
        log.info("trace-parent: {}", request.getHeader("traceparent"));
        log.info("Hello from OtherController");
        return ResponseEntity.ok("other");
    }
}

HelloService.java

@Slf4j
@Service
public class HelloService {
    private final RestTemplate restTemplate;

    public HelloService(RestTemplate restTemplate) {
        this.restTemplate = restTemplate;
    }

    public void hello(){
        restTemplate.getForEntity("http://localhost:8080/other", String.class);
        log.info("Hello from HelloService");
    }
}

application.yml

spring:
  application:
    name: demo-app
logging:
  pattern:
    level: "%5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}]"

After launching the application and making a call to GET /hello, the logs will display:

2023-09-11T15:11:59.823+07:00  INFO [demo-app,64fecbcf6b2bdd2599bac406daa15be9,99bac406daa15be9] 11292 --- [nio-8080-exec-1] c.e.c.controllers.HelloController        : Hello from HelloController
2023-09-11T15:11:59.847+07:00  INFO [demo-app,64fecbcf6b2bdd2599bac406daa15be9,89152579a3e20cdd] 11292 --- [nio-8080-exec-2] c.e.c.controllers.OtherController        : trace-parent: 00-64fecbcf6b2bdd2599bac406daa15be9-bab034ee1ede1212-01
2023-09-11T15:11:59.848+07:00  INFO [demo-app,64fecbcf6b2bdd2599bac406daa15be9,89152579a3e20cdd] 11292 --- [nio-8080-exec-2] c.e.c.controllers.OtherController        : Hello from OtherController
2023-09-11T15:11:59.866+07:00  INFO [demo-app,64fecbcf6b2bdd2599bac406daa15be9,99bac406daa15be9] 11292 --- [nio-8080-exec-1] c.e.correlationid.services.HelloService  : Hello from HelloService

Look at the first log, we can see:

application name: demo-log
traceId: 64fecbcf6b2bdd2599bac406daa15be9
spanId: 99bac406daa15be9

traceId: This is the ID of the whole trace forest and is used to uniquely identify a distributed trace through a system.
spanId: This is the ID of this request.

For example, if you have an issue in OtherController, you can use the traceId to find the whole execution to diagnose and debug.

On the 2'nd log

trace-parent: 00-64fecbcf6b2bdd2599bac406daa15be9-bab034ee1ede1212-01

we can see that traceparent contains 4 values, delimited by -.

These values are:

version
trace-id
parent-id
trace-flags

You can read more about the traceparent header here.

Adding the traceId to Exception responses

HttpExceptionHandler.java

@RestControllerAdvice
@Slf4j
public class HttpExceptionHandler {

    private final TraceIDHandler traceIDHandler;

    public HttpExceptionHandler(TraceIDHandler traceIDHandler) {
        this.traceIDHandler = traceIDHandler;
    }

    @ExceptionHandler(IllegalArgumentException.class)
    @ResponseStatus(HttpStatus.BAD_REQUEST)
    public ResponseEntity<ExceptionResponse> handleIllegalArgumentException(IllegalArgumentException exception) {
        log.warn(exception.getMessage(), exception);
        var exceptionResponse = new ExceptionResponse(HttpStatus.BAD_REQUEST, exception, traceIDHandler.getTraceId());
        return new ResponseEntity<>(exceptionResponse, exceptionResponse.getStatus());
    }
}

TraceIDHandler.java

@Component
public class TraceIDHandler {
    private final Tracer tracer;

    public TraceIDHandler(Tracer tracer) {
        this.tracer = tracer;
    }

    public String getTraceId() {
        return Optional.of(tracer).map(Tracer::currentTraceContext).map(CurrentTraceContext::context).map(TraceContext::traceId).orElse("");
    }
}

ExceptionResponse.java

@Data
public class ExceptionResponse {
    private final String traceId;
    private final HttpStatus status;
    @JsonFormat(shape = JsonFormat.Shape.STRING, pattern = "yyyy-MM-dd HH:mm:ss")
    private final LocalDateTime datetime;
    private final String error;

    public ExceptionResponse(@NonNull HttpStatus status, @NonNull Exception ex, String traceId) {
        datetime = LocalDateTime.now();
        this.status = status;
        this.error = ex.getMessage();
        this.traceId = traceId;
    }
}

Make a call to GET /bad-call, the response:

{
  "traceId": "64fed4c8e85b2264d2978faa37107f47",
  "status": "BAD_REQUEST",
  "datetime": "2023-09-11 15:50:16",
  "error": "Bad call exception"
}

Logs message:

2023-09-11T15:50:16.544+07:00  INFO [demo-app,64fed4c8e85b2264d2978faa37107f47,d2978faa37107f47] 29716 --- [nio-8080-exec-1] c.e.c.controllers.HelloController        : Called /bad-call
2023-09-11T15:50:16.545+07:00  WARN [demo-app,64fed4c8e85b2264d2978faa37107f47,d2978faa37107f47] 29716 --- [nio-8080-exec-1] c.e.c.configs.HttpExceptionHandler       : Bad call exception

Conclusion

This post helped configure your Spring Boot 3 application with Micrometer to log the traceId, which is used in diagnosing and debugging issues when they arise.

Hope you like that.

Reference: