Tracing gRPC calls with Micrometer

Why do we want to trace the gRPC call?

In the previous post, I introduced tracing HTTP requests in Spring Boot 3 with Micrometer.

And how do we in gRPC call? Let's get started.

On a microservice system implemented with gRPC, 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 those IDs to trace back to the cause.

In this post, I will add trace IDs to logs in Spring Boot 3 (implement gRPC call) by using Micrometer.

With the gRPC server project

build.gradle

plugins {
    id 'java'
    id 'com.google.protobuf' version '0.9.1'
    id 'org.springframework.boot' version '3.1.1'
    id 'io.spring.dependency-management' version '1.1.0'
}

group = 'org.example'
version = '1.0-SNAPSHOT'

repositories {
    mavenCentral()
    mavenLocal()
}

def springBootVersion = '3.1.+'
def grpcVersion = '1.56.1'
def protobufVersion = '3.22.3'
def protocVersion = protobufVersion

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-web'
    implementation platform("org.springframework.boot:spring-boot-dependencies:${springBootVersion}")
    implementation "io.grpc:grpc-protobuf:${grpcVersion}"
    implementation "io.grpc:grpc-stub:${grpcVersion}"
    implementation "io.grpc:grpc-netty:${grpcVersion}"

    compileOnly "org.apache.tomcat:annotations-api:6.0.53"
    compileOnly 'org.projectlombok:lombok:1.18.28'
    annotationProcessor 'org.projectlombok:lombok'

    implementation 'com.fasterxml.jackson.core:jackson-annotations:2.15.2'

    implementation group: 'com.googlecode.protobuf-java-format', name: 'protobuf-java-format', version: '1.4'

    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 platform('org.junit:junit-bom:5.9.1')
    testImplementation 'org.junit.jupiter:junit-jupiter'
}

protobuf {
    protoc { artifact = "com.google.protobuf:protoc:${protocVersion}" }
    plugins {
        grpc { artifact = "io.grpc:protoc-gen-grpc-java:${grpcVersion}" }
    }
    generateProtoTasks {
        all()*.plugins { grpc {} }
    }
}

sourceSets {
    main {
        java {
            srcDirs 'build/generated/source/proto/main/grpc'
            srcDirs 'build/generated/source/proto/main/java'
        }
    }
}

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.

HelloApplication.java

package com.example.grpcserver;


import com.benchmarking.grpc.GetRequest;
import com.benchmarking.grpc.GetResponse;
import com.benchmarking.grpc.SampleServiceGrpc;
import com.fasterxml.jackson.databind.DeserializationFeature;
import com.fasterxml.jackson.databind.ObjectMapper;
import io.grpc.Server;
import io.grpc.ServerBuilder;
import io.grpc.stub.StreamObserver;
import io.micrometer.core.instrument.binder.grpc.ObservationGrpcServerInterceptor;
import io.micrometer.observation.ObservationRegistry;
import io.micrometer.tracing.Tracer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.DisposableBean;
import org.springframework.beans.factory.InitializingBean;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.WebApplicationType;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.builder.SpringApplicationBuilder;
import org.springframework.context.annotation.Bean;
import org.springframework.http.converter.json.MappingJackson2HttpMessageConverter;
import org.springframework.http.converter.protobuf.ProtobufHttpMessageConverter;
import org.springframework.stereotype.Service;

@SpringBootApplication
public class HelloApplication {
    @Value("${server.port:9090}")
    int port;

    private static final Logger logger = LoggerFactory.getLogger(HelloApplication.class);

    public static void main(String... args) {
        new SpringApplicationBuilder(HelloApplication.class).web(WebApplicationType.NONE).run(args);
    }

    @Bean
    ProtobufHttpMessageConverter protobufHttpMessageConverter()
    {
        return new ProtobufHttpMessageConverter();
    }

    @Bean
    public MappingJackson2HttpMessageConverter mappingJackson2HttpMessageConverter() {
        MappingJackson2HttpMessageConverter jsonConverter = new MappingJackson2HttpMessageConverter();
        ObjectMapper objectMapper = new ObjectMapper();
        objectMapper.configure(DeserializationFeature.FAIL_ON_UNKNOWN_PROPERTIES, false);
        jsonConverter.setObjectMapper(objectMapper);
        return jsonConverter;
    }

    @Bean
    public ObservationGrpcServerInterceptor interceptor(ObservationRegistry observationRegistry) {
        return new ObservationGrpcServerInterceptor(observationRegistry);
    }

    @Bean
    Server server(SampleService sampleService, ObservationGrpcServerInterceptor interceptor) {
        return ServerBuilder.forPort(this.port).addService(sampleService).intercept(interceptor).build();
    }

    @Bean
    InitializingBean startServer(Server server) {
        return () -> {
            logger.info("Running server in port={}", this.port);
            server.start();
            new Thread(() -> {
                try {
                    server.awaitTermination();
                } catch (InterruptedException ex) {
                    Thread.currentThread().interrupt();
                }
            }).start();
        };
    }

    @Bean
    DisposableBean stopServer(Server server) {
        return server::shutdownNow;
    }

    @Service
    static class SampleService extends SampleServiceGrpc.SampleServiceImplBase {

        private static final Logger log = LoggerFactory.getLogger(SampleService.class);

        private final Tracer tracer;

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

        // echo the request message

        @Override
        public void get(GetRequest request, StreamObserver<GetResponse> responseObserver) {
            int message = request.getNumber();
            GetResponse response = GetResponse.newBuilder().setResult(message).build();
            responseObserver.onNext(response);
            // log it before onCompleted. The onCompleted triggers closing the span.
            log.info("<ACCEPTANCE_TEST> <TRACE:{}> Hello from grpc server", this.tracer.currentSpan().context().traceId());
            responseObserver.onCompleted();
        }
    }
}

In SampleService, there is an injection of Tracer. That props allow access to the traceId from the gRPC calls.

application.yml

spring:
  application:
    name: grpc-server

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

With the gRPC client project

build.gradle

plugins {
    id 'java'
    id 'com.google.protobuf' version '0.9.1'
    id 'org.springframework.boot' version '3.1.1'
    id 'io.spring.dependency-management' version '1.1.0'
}

group = 'org.example'
version = '1.0-SNAPSHOT'

repositories {
    mavenCentral()
    mavenLocal()
}

def springBootVersion = '3.1.+'
def grpcVersion = '1.56.1'
def protobufVersion = '3.22.3'
def protocVersion = protobufVersion

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-web'
    implementation platform("org.springframework.boot:spring-boot-dependencies:${springBootVersion}")
    implementation "io.grpc:grpc-protobuf:${grpcVersion}"
    implementation "io.grpc:grpc-stub:${grpcVersion}"
    implementation "io.grpc:grpc-netty:${grpcVersion}"

    compileOnly "org.apache.tomcat:annotations-api:6.0.53"

    compileOnly 'org.projectlombok:lombok:1.18.28'
    annotationProcessor 'org.projectlombok:lombok'

    implementation 'com.fasterxml.jackson.core:jackson-annotations:2.15.2'

    implementation group: 'com.googlecode.protobuf-java-format', name: 'protobuf-java-format', version: '1.4'

    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 platform('org.junit:junit-bom:5.9.1')
    testImplementation 'org.junit.jupiter:junit-jupiter'
}

protobuf {
    protoc { artifact = "com.google.protobuf:protoc:${protocVersion}" }
    plugins {
        grpc { artifact = "io.grpc:protoc-gen-grpc-java:${grpcVersion}" }
    }
    generateProtoTasks {
        all()*.plugins { grpc {} }
    }
}

// Inform IDEs like IntelliJ IDEA, Eclipse or NetBeans about the generated code.
sourceSets {
    main {
        java {
            srcDirs 'build/generated/source/proto/main/grpc'
            srcDirs 'build/generated/source/proto/main/java'
        }
    }
}

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.

HelloApplication.java

package com.example.grpcclient;

import com.benchmarking.grpc.GetRequest;
import com.benchmarking.grpc.GetResponse;
import com.benchmarking.grpc.SampleServiceGrpc;
import io.grpc.ManagedChannel;
import io.grpc.ManagedChannelBuilder;
import io.micrometer.core.instrument.binder.grpc.ObservationGrpcClientInterceptor;
import io.micrometer.observation.Observation;
import io.micrometer.observation.ObservationRegistry;
import io.micrometer.tracing.Tracer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.CommandLineRunner;
import org.springframework.boot.WebApplicationType;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.builder.SpringApplicationBuilder;
import org.springframework.context.annotation.Bean;

@SpringBootApplication
public class HelloApplication {
    @Value("${url:localhost:9090}")
    String url;

    private static final Logger log = LoggerFactory.getLogger(HelloApplication.class);

    public static void main(String[] args) {
        new SpringApplicationBuilder(HelloApplication.class).web(WebApplicationType.NONE).run(args);
    }

    @Bean
    public ObservationGrpcClientInterceptor interceptor(ObservationRegistry observationRegistry) {
        return new ObservationGrpcClientInterceptor(observationRegistry);
    }

    @Bean
    SampleServiceGrpc.SampleServiceBlockingStub client(ObservationGrpcClientInterceptor interceptor) {
        ManagedChannel channel = ManagedChannelBuilder.forTarget(url).usePlaintext().intercept(interceptor).build();
        return SampleServiceGrpc.newBlockingStub(channel);
    }

    @Bean
    CommandLineRunner runner(SampleServiceGrpc.SampleServiceBlockingStub blockingStub, ObservationRegistry observationRegistry,
                             Tracer tracer) {
        return (args) -> {
            GetRequest request = GetRequest.newBuilder().setNumber(0).build();
            Observation.createNotStarted("grpc.client", observationRegistry).observe(() -> {
                log.info("<ACCEPTANCE_TEST> <TRACE:{}> Hello from grpc client", tracer.currentSpan().context().traceId());
                GetResponse response = blockingStub.get(request);
                log.info("Greeting: " + response.getResult());
            });
        };
    }
}

In the @Bean runner, that inject a Tracer object with tracerId to the request observer.

application.yml

spring:
  application:
    name: grpc-client

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

Check the result

gRPC client log

2023-10-22T11:18:52.089+07:00  INFO [grpc-client,6534a2acefecbfb0d73d8ca7ac1484b1,d73d8ca7ac1484b1] 44538 --- [           main] c.example.grpcclient.HelloApplication    : <ACCEPTANCE_TEST> <TRACE:6534a2acefecbfb0d73d8ca7ac1484b1> Hello from grpc client
2023-10-22T11:18:52.291+07:00  INFO [grpc-client,6534a2acefecbfb0d73d8ca7ac1484b1,d73d8ca7ac1484b1] 44538 --- [           main] c.example.grpcclient.HelloApplication    : Greeting: 0

gRPC server log

2023-10-22T11:18:52.286+07:00  INFO [grpc-server,6534a2acefecbfb0d73d8ca7ac1484b1,93c32c584fca75e1] 44536 --- [ault-executor-0] c.e.g.HelloApplication$SampleService     : <ACCEPTANCE_TEST> <TRACE:6534a2acefecbfb0d73d8ca7ac1484b1> Hello from grpc server

Look at those logs, we can see the traceId value is 6534a2acefecbfb0d73d8ca7ac1484b1

Conclusion

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

Hope you like that.

Reference: