Spring Boot and Tracing Calls

By | January 12, 2020
Reading Time: 12 minutes

For quite some time now I have thought it would be very useful to have some type of id associated with the processing of a request logged in connection to the log messages generated when the request is processed. This in order to be able to query Elasticsearch or similar for all the logs generated in connection to a request. In this article I am going to show how to accomplish this in a Spring Boot application/service and also tell you a little about my winding path to this goal.

Spoiler:
In the end I chose Spring Cloud Sleuth, which is an adaption of Brave from OpenZipkin for Spring Cloud.

Prerequisites

In order to focus on the subject, I will use, or perhaps re-use, my rest-example Spring Boot application, the version in which Spring WebFlux is used. If you want to work along the example in this article then please clone the webflux+reactor branch of that GitHub repository.

Current State

In the current state the rest-example application/service is built using the following three-layered architecture:

Layered architecture used in the rest-example application.

If running the testUpdateEntity test in the CircleResourceTest, the log will look something like this:

2020-01-01 19:45:51.398 TRACE 1687 --- [nio-8080-exec-1] o.s.w.s.adapter.HttpWebHandlerAdapter    : [71667ceb] HTTP PUT "/circles/17", headers=[accept:"application/json", content-type:"application/json; charset=UTF-8", content-length:"99", host:"localhost:8080", connection:"Keep-Alive", user-agent:"Apache-HttpClient/4.5.10 (Java/12.0.2)", accept-encoding:"gzip,deflate"]
2020-01-01 19:45:51.399 DEBUG 1687 --- [nio-8080-exec-1] s.w.r.r.m.a.RequestMappingHandlerMapping : [71667ceb] Mapped to se.ivankrizsan.restexample.restadapter.CircleResource#updateEntity(LongIdEntity, Long)
2020-01-01 19:45:51.399 DEBUG 1687 --- [nio-8080-exec-1] .r.m.a.RequestBodyMethodArgumentResolver : [71667ceb] Content-Type:application/json;charset=UTF-8
2020-01-01 19:45:51.400 DEBUG 1687 --- [nio-8080-exec-1] .r.m.a.RequestBodyMethodArgumentResolver : [71667ceb] 0..1 [se.ivankrizsan.restexample.domain.Circle]
2020-01-01 19:45:51.401 DEBUG 1687 --- [nio-8080-exec-1] org.springframework.web.HttpLogging      : [71667ceb] Decoded [Circle{mRadius=750, mColour='Colour75', mPosition=java.awt.Point[x=1125,y=1500], mId=17}]
2020-01-01 19:45:51.401  INFO 1687 --- [nio-8080-exec-1] s.i.r.r.RestResourceBaseReactor          : Received request to update entity with id 17
2020-01-01 19:45:51.402 DEBUG 1687 --- [nio-8080-exec-1] o.s.w.r.r.m.a.ResponseBodyResultHandler  : Using 'application/json;charset=UTF-8' given [application/json] and supported [application/json;charset=UTF-8]
2020-01-01 19:45:51.402 DEBUG 1687 --- [nio-8080-exec-1] o.s.w.r.r.m.a.ResponseBodyResultHandler  : [71667ceb] 0..1 [se.ivankrizsan.restexample.domain.Circle]
2020-01-01 19:45:51.403  INFO 1687 --- [     parallel-6] s.i.r.s.AbstractServiceBaseReactor       : Updating entity: Circle{mRadius=750, mColour='Colour75', mPosition=java.awt.Point[x=1125,y=1500], mId=17}
2020-01-01 19:45:51.404  INFO 1687 --- [     parallel-6] .i.r.r.c.JpaRepositoryCustomisationsImpl : Persisting entity: Circle{mRadius=750, mColour='Colour75', mPosition=java.awt.Point[x=1125,y=1500], mId=17}
2020-01-01 19:45:51.404  INFO 1687 --- [     parallel-6] .i.r.r.c.JpaRepositoryCustomisationsImpl : Entity has id: '17'
2020-01-01 19:45:51.416  INFO 1687 --- [     parallel-6] .i.r.r.c.JpaRepositoryCustomisationsImpl : Entity has id and exists - merging.
2020-01-01 19:45:51.422 DEBUG 1687 --- [     parallel-6] org.springframework.web.HttpLogging      : [71667ceb] Encoding [Circle{mRadius=750, mColour='Colour75', mPosition=java.awt.Point[x=1125,y=1500], mId=17}]
2020-01-01 19:45:51.423 TRACE 1687 --- [     parallel-6] o.s.w.s.adapter.HttpWebHandlerAdapter    : [71667ceb] Completed 200 OK, headers=[Content-Type:"application/json;charset=UTF-8", Content-Length:"99", Date:"Wed, 01 Jan 2020 18:45:51 GMT"]
{
    "shapeType": ".Circle",
    "radius": 750,
    "position": {
        "x": 1125.0,
        "y": 1500.0
    },
    "colour": "Colour75",
    "id": 17
}

Lines 1-8 are logged from the green, REST resource adaptor, layer or from libraries invoked from the green layer.

Line 9 is logged from the yellow, service, layer.

Lines 10-12 are logged from the orange, persistence, layer.

Finally, lines 13 and 14 are logged from the blue, third party libraries, layer.

Admitted, I have switched on both DEBUG and TRACE logging for some packages, but nevertheless I think it can be agreed upon that if there would be log statements from 10 or 100 requests, it would become significantly more difficult to determine which request caused which log.

Do note how there are two different threads, nio-8080-exec-1 and parallel-6, involved in the processing of the above request.

Wishes

I have the following initial wishes, a.k.a. requirements, for a tracing solution:

  • It should not pollute business logic or other code.
    To me, tracing is a typical cross-cutting concern and as such the code implementing the tracing should kept separated from other code.
  • It should be simple, or even better trivial, to add to an application.
    The less configuration and/or work, the larger the chance that the result will be the same in each and every application/service.
  • The trace id should also be displayed in logs generated by all underlying libraries that are invoked as part of the request processing.
    Input to libraries and frameworks used by the application/service may be bad and cause failures in said libraries or frameworks. In such a case it is essential to be able to correlate any logs from those libraries or frameworks to a request.
  • It should be possible to use the tracing solution in a monolith application but also in an application that consists of multiple, loosely coupled, services (a.k.a. microservices).
  • Should work with multi-threaded Reactor code.
    Reactor with scheduling is what is used in my rest-example application.

The above are some initial requirements. I can imagine a few more, but I will settle for this initial list.

Naive Approach

It is of course trivial to add a few log statements in the application or service in question, similar to the highlighted rows in the code below, passing the trace id in a parameter as the processing propagates in the application/service.

    @PutMapping(
        path = "{id}",
        produces = "application/json;charset=UTF-8",
        consumes = "application/json")
    public Mono<E> updateEntity(@RequestBody final E inEntity,
        @PathVariable("id") @NotNull final Long inEntityId) {
        final String theTraceId = UUID.randomUUID().toString();
        LOGGER.info("Received request to update entity with id {}. Trace id: {}", inEntityId, theTraceId);

        inEntity.setId(inEntityId);
        return mService.update(inEntity, theTraceId);
    }

Regretfully, this approach does not meet many of the requirements.

MDC Approach

The approach uses what is called the mapped diagnostic context, MDC. Several logging frameworks, namely Log4J, Log4J2, SLF4J/Logback contain a MDC or similar. The MDC can be used to make information available to the logging framework out-of-band, without having to pass parameters around etc.

Inserting a trace id into the MDC and having it displayed in the logs consists of the following steps:

  • Inserting a trace id into the MDC:
    @PutMapping(
        path = "{id}",
        produces = "application/json;charset=UTF-8",
        consumes = "application/json")
    public Mono<E> updateEntity(@RequestBody final E inEntity,
        @PathVariable("id") @NotNull final Long inEntityId) {
        MDC.put("traceId", UUID.randomUUID().toString());
        LOGGER.info("Received request to update entity with id {}.", inEntityId);

        inEntity.setId(inEntityId);
        return mService.update(inEntity);
    }
  • Configuring the logging pattern to include the tracing id:
…
logging.pattern.console=%-4r [%t] %5p %c{1} - %m, trace id: %X{traceId}%n
…

Note how the key “traceId” used in the call to MDC.put matches the key in the logging pattern.

If we run the testUpdateEntity test in the CircleResourceTest again, the log will look something like this:

7292 [http-nio-8080-exec-1] TRACE o.s.w.s.a.HttpWebHandlerAdapter - [7aadac43] HTTP PUT "/circles/17", headers=[accept:"application/json", content-type:"application/json; charset=UTF-8", content-length:"97", host:"localhost:8080", connection:"Keep-Alive", user-agent:"Apache-HttpClient/4.5.10 (Java/12.0.2)", accept-encoding:"gzip,deflate"], trace id: 
7293 [http-nio-8080-exec-1] DEBUG o.s.w.r.r.m.a.RequestMappingHandlerMapping - [7aadac43] Mapped to se.ivankrizsan.restexample.restadapter.CircleResource#updateEntity(LongIdEntity, Long), trace id: 
7293 [http-nio-8080-exec-1] DEBUG o.s.w.r.r.m.a.RequestBodyMethodArgumentResolver - [7aadac43] Content-Type:application/json;charset=UTF-8, trace id: 
7293 [http-nio-8080-exec-1] DEBUG o.s.w.r.r.m.a.RequestBodyMethodArgumentResolver - [7aadac43] 0..1 [se.ivankrizsan.restexample.domain.Circle], trace id: 
7294 [http-nio-8080-exec-1] DEBUG o.s.w.HttpLogging - [7aadac43] Decoded [Circle{mRadius=430, mColour='Colour43', mPosition=java.awt.Point[x=645,y=860], mId=17}], trace id: 
7294 [http-nio-8080-exec-1]  INFO s.i.r.r.RestResourceBaseReactor - Received request to update entity with id 17., trace id: 41129802-2e8e-4ca1-83b5-1dfccaf7f925
7295 [http-nio-8080-exec-1] DEBUG o.s.w.r.r.m.a.ResponseBodyResultHandler - Using 'application/json;charset=UTF-8' given [application/json] and supported [application/json;charset=UTF-8], trace id: 41129802-2e8e-4ca1-83b5-1dfccaf7f925
7295 [http-nio-8080-exec-1] DEBUG o.s.w.r.r.m.a.ResponseBodyResultHandler - [7aadac43] 0..1 [se.ivankrizsan.restexample.domain.Circle], trace id: 41129802-2e8e-4ca1-83b5-1dfccaf7f925
7296 [parallel-6]  INFO s.i.r.s.AbstractServiceBaseReactor - Updating entity: Circle{mRadius=430, mColour='Colour43', mPosition=java.awt.Point[x=645,y=860], mId=17}, trace id: 
7298 [parallel-6]  INFO s.i.r.r.c.JpaRepositoryCustomisationsImpl - Persisting entity: Circle{mRadius=430, mColour='Colour43', mPosition=java.awt.Point[x=645,y=860], mId=17}, trace id: 
7298 [parallel-6]  INFO s.i.r.r.c.JpaRepositoryCustomisationsImpl - Entity has id: '17', trace id: 
7312 [parallel-6]  INFO s.i.r.r.c.JpaRepositoryCustomisationsImpl - Entity has id and exists - merging., trace id: 
7319 [parallel-6] DEBUG o.s.w.HttpLogging - [7aadac43] Encoding [Circle{mRadius=430, mColour='Colour43', mPosition=java.awt.Point[x=645,y=860], mId=17}], trace id: 
7320 [parallel-6] TRACE o.s.w.s.a.HttpWebHandlerAdapter - [7aadac43] Completed 200 OK, headers=[Content-Type:"application/json;charset=UTF-8", Content-Length:"97", Date:"Thu, 02 Jan 2020 19:13:43 GMT"], trace id: 
{
    "shapeType": ".Circle",
    "radius": 430,
    "position": {
        "x": 645.0,
        "y": 860.0
    },
    "colour": "Colour43",
    "id": 17
}

We can see that there is no trace id logged until in connection to the message “Received request to update entity with id 17” – this is the log that is output immediately after the traceId key having been inserted into the MDC.

MDC context is not shared between threads; two threads, each with its own MDC instance.

Note that when executing on a different thread, parallel-6 in the log above, then no trace id is written to the log. This is because the MDC is bound to a specific thread using a ThreadLocal and those log statements are written by a thread for which the MDC context does not contain the trace id.

This is clearly an improvement over the naive approach but there still are a few requirements that are not met.

Aspect-Oriented Programming

I would consider myself quite ignorant if I had forgotten to mention aspect-oriented programming after having talked about tracing being a cross-cutting concern. I did consider aspect-oriented programming but since I found a better solution, I never implemented anything.

Spring Cloud Sleuth

Spring Cloud Sleuth in its most simple use-case offers log correlation, which, after having read some of the documentation, sounds like what I am looking for.

Adding Basic Tracing

Adding tracing with Spring Cloud Sleuth to a Spring Boot application is as simple as adding the following dependency to the project’s pom.xml:

...
        <dependency>
            <groupId>org.springframework.cloud</groupId>
            <artifactId>spring-cloud-starter-sleuth</artifactId>
            <version>2.2.1.RELEASE</version>
        </dependency>
...

In order to have the name of the application written to the log in connection to the trace ids, the following property is also added to the application.properties file of the project:

...
# Set an application name so the service can be identified in the logs
# when the trace and span ids are logged.
spring.application.name=rest-example
...

Having added the above dependency and property to my rest-example application, the testUpdateEntity test in the CircleResourceTest will produce the following log when being run:

2020-01-04 21:35:13.171 TRACE [rest-example,,,] 1993 --- [nio-8080-exec-1] o.s.w.s.adapter.HttpWebHandlerAdapter    : [4091421e] HTTP PUT "/circles/17", headers=[accept:"application/json", content-type:"application/json; charset=UTF-8", content-length:"98", host:"localhost:8080", connection:"Keep-Alive", user-agent:"Apache-HttpClient/4.5.10 (Java/12.0.2)", accept-encoding:"gzip,deflate"]
2020-01-04 21:35:13.173 DEBUG [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [nio-8080-exec-1] s.w.r.r.m.a.RequestMappingHandlerMapping : [4091421e] Mapped to se.ivankrizsan.restexample.restadapter.CircleResource#updateEntity(LongIdEntity, Long)
2020-01-04 21:35:13.173 DEBUG [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [nio-8080-exec-1] .r.m.a.RequestBodyMethodArgumentResolver : [4091421e] Content-Type:application/json;charset=UTF-8
2020-01-04 21:35:13.173 DEBUG [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [nio-8080-exec-1] .r.m.a.RequestBodyMethodArgumentResolver : [4091421e] 0..1 [se.ivankrizsan.restexample.domain.Circle]
2020-01-04 21:35:13.175 DEBUG [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [nio-8080-exec-1] org.springframework.web.HttpLogging      : [4091421e] Decoded [Circle{mRadius=510, mColour='Colour51', mPosition=java.awt.Point[x=765,y=1020], mId=17}]
2020-01-04 21:35:13.175  INFO [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [nio-8080-exec-1] s.i.r.r.RestResourceBaseReactor          : Received request to update entity with id 17.
2020-01-04 21:35:13.176 DEBUG [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [nio-8080-exec-1] o.s.w.r.r.m.a.ResponseBodyResultHandler  : Using 'application/json;charset=UTF-8' given [application/json] and supported [application/json;charset=UTF-8]
2020-01-04 21:35:13.176 DEBUG [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [nio-8080-exec-1] o.s.w.r.r.m.a.ResponseBodyResultHandler  : [4091421e] 0..1 [se.ivankrizsan.restexample.domain.Circle]
2020-01-04 21:35:13.177  INFO [rest-example,eb930c946638a6dc,fd05218e6d683af9,false] 1993 --- [     parallel-6] s.i.r.s.AbstractServiceBaseReactor       : Updating entity: Circle{mRadius=510, mColour='Colour51', mPosition=java.awt.Point[x=765,y=1020], mId=17}
2020-01-04 21:35:13.178  INFO [rest-example,eb930c946638a6dc,fd05218e6d683af9,false] 1993 --- [     parallel-6] .i.r.r.c.JpaRepositoryCustomisationsImpl : Persisting entity: Circle{mRadius=510, mColour='Colour51', mPosition=java.awt.Point[x=765,y=1020], mId=17}
2020-01-04 21:35:13.178  INFO [rest-example,eb930c946638a6dc,fd05218e6d683af9,false] 1993 --- [     parallel-6] .i.r.r.c.JpaRepositoryCustomisationsImpl : Entity has id: '17'
2020-01-04 21:35:13.191  INFO [rest-example,eb930c946638a6dc,fd05218e6d683af9,false] 1993 --- [     parallel-6] .i.r.r.c.JpaRepositoryCustomisationsImpl : Entity has id and exists - merging.
2020-01-04 21:35:13.197 DEBUG [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [     parallel-6] org.springframework.web.HttpLogging      : [4091421e] Encoding [Circle{mRadius=510, mColour='Colour51', mPosition=java.awt.Point[x=765,y=1020], mId=17}]
2020-01-04 21:35:13.198 TRACE [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] 1993 --- [     parallel-6] o.s.w.s.adapter.HttpWebHandlerAdapter    : [4091421e] Completed 200 OK, headers=[Content-Type:"application/json;charset=UTF-8", Content-Length:"98", Date:"Sat, 04 Jan 2020 20:35:12 GMT"]
{
    "shapeType": ".Circle",
    "radius": 510,
    "position": {
        "x": 765.0,
        "y": 1020.0
    },
    "colour": "Colour51",
    "id": 17
}

Note that:

  • Spring Cloud Sleuth adds output of trace and span ids to the logging pattern.
    There are two versions of the part of log statements that contain trace and span ids.
    The first is logged when there are no trace or span id information (highlighted in red):
    [rest-example,,,]
    The second is logged when there is trace and span id information (highlighted in green):
    [rest-example,eb930c946638a6dc,eb930c946638a6dc,false]

  • In [rest-example,eb930c946638a6dc,eb930c946638a6dc,false] the trace id is the first eb930c946638a6dc and the span id is the second eb930c946638a6dc.

  • The span id changes to fd05218e6d683af9 when execution enters the service layer in the application.

  • There is only one log statement in which there are no trace or span id – the first log statement from HttpWebHandlerAdapter.

  • Spring Cloud Sleuth adds trace and span ids earlier than my MDC approach.

  • Trace and span ids are logged even from the other thread (parallel-6 in the log above) that is part of processing the request.

The above already satisfies all but one of my requirements and the one remaining requirement is just not examined, not unsatisfied. Very nice!

Note!

It cannot be seen in the log above, but if the Spring Boot project does not use SLF4J then the logging pattern will not be automatically configured by Spring Cloud Sleuth and you will not see trace or span ids in the log without having modified the logging pattern yourself.

Customizing Trace and Span Id Logging

In order to examine what Spring Cloud Sleuth places in the MDC context map, I added a line of logging to the updateEntity method in the RestResourceBaseReactor class:

    @PutMapping(
        path = "{id}",
        produces = "application/json;charset=UTF-8",
        consumes = "application/json")
    public Mono<E> updateEntity(@RequestBody final E inEntity,
        @PathVariable("id") @NotNull final Long inEntityId) {
        LOGGER.info("Received request to update entity with id {}.", inEntityId);
        LOGGER.info("MDC context map: {}", MDC.getCopyOfContextMap());

        inEntity.setId(inEntityId);
        return mService.update(inEntity);
    }

Running the test again, the following is logged:

2020-01-05 17:58:05.921  INFO [rest-example,c11ded46565a96ac,c11ded46565a96ac,false] 1181 --- [nio-8080-exec-1] s.i.r.r.RestResourceBaseReactor          : MDC context map: {traceId=c11ded46565a96ac, spanId=c11ded46565a96ac, spanExportable=false, X-Span-Export=false, X-B3-SpanId=c11ded46565a96ac, X-B3-TraceId=c11ded46565a96ac}

The result is:

  • The trace id is present in the MDC context map under the keys traceId and X-B3-TraceId.
  • The span id is present in the MDC context map under the keys spanId and X-B3-SpanId.
  • There are additional keys present in the MDC context map, namely spanExportable and X-Span-Export.

The default pattern set by Spring Cloud Sleuth is:

logging.pattern.level=%5p [${spring.zipkin.service.name:${spring.application.name:-}},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}]

Armed with this knowledge we can now customize the output of the trace and span ids.
For example, the following configuration will output application name and trace id only:

logging.pattern.level=%5p [${spring.zipkin.service.name:${spring.application.name:-}},%X{X-B3-TraceId:-}]

Example of output with the above configuration:

2020-01-05 20:34:18.880  INFO [rest-example,caafb2671465a3b6] 2286 --- [nio-8080-exec-1] s.i.r.r.RestResourceBaseReactor          : Received request to update entity with id 17.

Logging Additional Information

At times you may want to have other information propagated and logged in the same manner as the trace and span ids we have seen above. With Spring Cloud Sleuth this type of information can be passed as what is called baggage. Both trance id, span id and baggage is part of what is called the span context. Trace and span ids are required parts of this context while baggage is an optional part.

The following is an example showing how to store a key-value pair in the baggage:

ExtraFieldPropagation.set("testBaggage", "12345");

A value can later be retrieved from the baggage if we know the key:

LOGGER.info("Test baggage: {}", ExtraFieldPropagation.get("testBaggage"));

Baggage can be made available in the MDC by including the name of the baggage key in the following two properties:

spring.sleuth.baggage-keys=testBaggage
spring.sleuth.log.slf4j.whitelisted-mdc-keys=testBaggage

Then it should be possible to include the key when logging like in this example:

logging.pattern.level=%5p [${spring.zipkin.service.name:${spring.application.name:-}},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{testBaggage:-}]

I say should, because the key-value of the baggage will not be propagated to the MDC immediately when setting the baggage but, in the tests I made, when the MDC context was propagated from one thread to another.

Incoming Trace and Span Ids

Trace and span ids can be passed into the Spring Boot application that uses Spring Boot Sleuth by setting certain HTTP headers.

Modify the testUpdateEntity method in RestResourceTestBase to look like below. Highlighted rows are new.

    @Test(timeOut = TEST_TIMEOUT)
    public void testUpdateEntity() throws Exception {
        final Long theExistingEntityId = mExpectedEntity.getId();
        final E theExpectedEntity =
            mEntityFactory.createEntity(mCreateEntityIndex + 1);
        theExpectedEntity.setId(theExistingEntityId);
        final String theJsonRepresentation =
            JsonConverter.objectToJson(theExpectedEntity);
        final Response theResponse = RestAssured
            .given()
            .contentType("application/json")
            .header("x-b3-traceid", "0000000000000001")
            .header("x-b3-spanid", "0000000000000002")
            .accept("application/json")
            .body(theJsonRepresentation)
            .when()
            .put(mResourceUrlPath + "/" + mExpectedEntity.getId());
        final String theResponseJson = theResponse.prettyPrint();
        theResponse
            .then()
            .statusCode(200)
            .contentType(ContentType.JSON);

        final Object theUpdatedEntity = JsonConverter.jsonToObject(
            theResponseJson, mExpectedEntity.getClass());
        ReflectionAssert.assertLenientEquals(
            "Updated entity should have the correct property values",
            theExpectedEntity, theUpdatedEntity);
    }

If we now run, or re-run, the testUpdateEntity test in CircleResourceTest, the first log line containing trace and span ids will look similar to this:

2020-01-06 10:02:56.388 DEBUG [rest-example,0000000000000001,0000000000000002,] 1143 --- [nio-8080-exec-3] s.w.r.r.m.a.RequestMappingHandlerMapping : [37f1f2da] Mapped to se.ivankrizsan.restexample.restadapter.CircleResource#updateEntity(LongIdEntity, Long)

We can see that the values passed in the HTTP headers “x-b3-traceid” and “x-b3-spanid” are the values that are used for the trace and span ids respectively.

Outgoing Trance and Span Ids

To simulate a request to another application/service that also uses Spring Cloud Sleuth for call tracing, let’s make the following modifications:

  • In the RestExampleApplication class, add the following method:
    @Bean
    public WebClient webClient() {
        return WebClient.create();
    }
  • Modify the updateEntity method in the RestResourceBaseReactor class to look like this (added rows are highlighted):
    @PutMapping(
        path = "{id}",
        produces = "application/json;charset=UTF-8",
        consumes = "application/json")
    public Mono<E> updateEntity(@RequestBody final E inEntity,
        @PathVariable("id") @NotNull final Long inEntityId) {
        LOGGER.info("Received request to update entity with id {}.", inEntityId);

        final ClientResponse theResponse = mWebClient
            .get()
            .uri("http://localhost:8080" + RectangleResource.PATH)
            .accept(MediaType.APPLICATION_JSON)
            .exchange()
            .log()
            .block();

        inEntity.setId(inEntityId);
        return mService.update(inEntity);
    }

If again running the testUpdateEntity test in CircleResourceTest, the log will look similar to this:

2020-01-06 10:23:13.589 TRACE [rest-example,,,] 1190 --- [nio-8080-exec-1] o.s.w.s.adapter.HttpWebHandlerAdapter    : [3906b2de] HTTP PUT "/circles/17", headers=[x-b3-traceid:"0000000000000001", x-b3-spanid:"0000000000000002", accept:"application/json", content-type:"application/json; charset=UTF-8", content-length:"101", host:"localhost:8080", connection:"Keep-Alive", user-agent:"Apache-HttpClient/4.5.10 (Java/12.0.2)", accept-encoding:"gzip,deflate"]
2020-01-06 10:23:13.591 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] s.w.r.r.m.a.RequestMappingHandlerMapping : [3906b2de] Mapped to se.ivankrizsan.restexample.restadapter.CircleResource#updateEntity(LongIdEntity, Long)
2020-01-06 10:23:13.591 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] .r.m.a.RequestBodyMethodArgumentResolver : [3906b2de] Content-Type:application/json;charset=UTF-8
2020-01-06 10:23:13.592 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] .r.m.a.RequestBodyMethodArgumentResolver : [3906b2de] 0..1 [se.ivankrizsan.restexample.domain.Circle]
2020-01-06 10:23:13.593 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] org.springframework.web.HttpLogging      : [3906b2de] Decoded [Circle{mRadius=1000, mColour='Colour100', mPosition=java.awt.Point[x=1500,y=2000], mId=17}]
2020-01-06 10:23:13.593  INFO [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] s.i.r.r.RestResourceBaseReactor          : Received request to update entity with id 17.
2020-01-06 10:23:13.612  INFO [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] reactor.Mono.Lift.1                      : onContextUpdate(Context1{class brave.Span=NoopSpan(0000000000000001/0000000000000002)})
2020-01-06 10:23:13.615  INFO [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] reactor.Mono.Lift.1                      : onSubscribe([Fuseable] ScopePassingSpanSubscriber)
2020-01-06 10:23:13.616  INFO [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] reactor.Mono.Lift.1                      : request(unbounded)
2020-01-06 10:23:13.691 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] o.s.w.r.f.client.ExchangeFunctions       : [79019676] HTTP GET http://localhost:8080/rectangles
2020-01-06 10:23:13.828 TRACE [rest-example,,,] 1190 --- [nio-8080-exec-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [46f9fb53] HTTP GET "/rectangles", headers=[accept-encoding:"gzip", user-agent:"ReactorNetty/0.9.1.RELEASE", host:"localhost:8080", accept:"application/json", x-b3-traceid:"0000000000000001", x-b3-spanid:"a6c1c040deedfab4", x-b3-parentspanid:"0000000000000002", x-b3-sampled:"0"]
2020-01-06 10:23:13.830 DEBUG [rest-example,0000000000000001,a6c1c040deedfab4,] 1190 --- [nio-8080-exec-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [46f9fb53] Mapped to se.ivankrizsan.restexample.restadapter.RectangleResource#getAll()
2020-01-06 10:23:13.835 DEBUG [rest-example,0000000000000001,a6c1c040deedfab4,] 1190 --- [nio-8080-exec-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : Using 'application/json;charset=UTF-8' given [application/json] and supported [application/json;charset=UTF-8]
2020-01-06 10:23:13.835 DEBUG [rest-example,0000000000000001,a6c1c040deedfab4,] 1190 --- [nio-8080-exec-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : [46f9fb53] 0..N [se.ivankrizsan.restexample.domain.Rectangle]
2020-01-06 10:23:13.837  INFO [rest-example,0000000000000001,862c60c08145dd52,] 1190 --- [     parallel-6] s.i.r.s.AbstractServiceBaseReactor       : Retrieving all entities.
2020-01-06 10:23:13.841 DEBUG [rest-example,0000000000000001,a6c1c040deedfab4,] 1190 --- [     parallel-6] org.springframework.web.HttpLogging      : [46f9fb53] Encoding [[]]
2020-01-06 10:23:13.843 TRACE [rest-example,0000000000000001,a6c1c040deedfab4,] 1190 --- [     parallel-6] o.s.w.s.adapter.HttpWebHandlerAdapter    : [46f9fb53] Completed 200 OK, headers=[Content-Type:"application/json;charset=UTF-8", Transfer-Encoding:"chunked", Date:"Mon, 06 Jan 2020 09:23:13 GMT"]
2020-01-06 10:23:13.850 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [ctor-http-nio-1] o.s.w.r.f.client.ExchangeFunctions       : [79019676] Response 200 OK
2020-01-06 10:23:13.862  INFO [rest-example,0000000000000001,0000000000000002,] 1190 --- [ctor-http-nio-1] reactor.Mono.Lift.1                      : onNext(org.springframework.web.reactive.function.client.DefaultClientResponse@74d6e6dc)
2020-01-06 10:23:13.863  INFO [rest-example,0000000000000001,0000000000000002,] 1190 --- [ctor-http-nio-1] reactor.Mono.Lift.1                      : onComplete()
2020-01-06 10:23:13.864 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] o.s.w.r.r.m.a.ResponseBodyResultHandler  : Using 'application/json;charset=UTF-8' given [application/json] and supported [application/json;charset=UTF-8]
2020-01-06 10:23:13.864 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [nio-8080-exec-1] o.s.w.r.r.m.a.ResponseBodyResultHandler  : [3906b2de] 0..1 [se.ivankrizsan.restexample.domain.Circle]
2020-01-06 10:23:13.865  INFO [rest-example,0000000000000001,a004b6db37865016,] 1190 --- [     parallel-7] s.i.r.s.AbstractServiceBaseReactor       : Updating entity: Circle{mRadius=1000, mColour='Colour100', mPosition=java.awt.Point[x=1500,y=2000], mId=17}
2020-01-06 10:23:13.867  INFO [rest-example,0000000000000001,a004b6db37865016,] 1190 --- [     parallel-7] .i.r.r.c.JpaRepositoryCustomisationsImpl : Persisting entity: Circle{mRadius=1000, mColour='Colour100', mPosition=java.awt.Point[x=1500,y=2000], mId=17}
2020-01-06 10:23:13.867  INFO [rest-example,0000000000000001,a004b6db37865016,] 1190 --- [     parallel-7] .i.r.r.c.JpaRepositoryCustomisationsImpl : Entity has id: '17'
2020-01-06 10:23:13.882  INFO [rest-example,0000000000000001,a004b6db37865016,] 1190 --- [     parallel-7] .i.r.r.c.JpaRepositoryCustomisationsImpl : Entity has id and exists - merging.
2020-01-06 10:23:13.888 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [     parallel-7] org.springframework.web.HttpLogging      : [3906b2de] Encoding [Circle{mRadius=1000, mColour='Colour100', mPosition=java.awt.Point[x=1500,y=2000], mId=17}]
2020-01-06 10:23:13.889 TRACE [rest-example,0000000000000001,0000000000000002,] 1190 --- [     parallel-7] o.s.w.s.adapter.HttpWebHandlerAdapter    : [3906b2de] Completed 200 OK, headers=[Content-Type:"application/json;charset=UTF-8", Content-Length:"101", Date:"Mon, 06 Jan 2020 09:23:13 GMT"]
{
    "shapeType": ".Circle",
    "radius": 1000,
    "position": {
        "x": 1500.0,
        "y": 2000.0
    },
    "colour": "Colour100",
    "id": 17
}

Note that:

  • The logging generated by the request to list all rectangles starts with the following line of log:
2020-01-06 10:23:13.828 TRACE [rest-example,,,] 1190 --- [nio-8080-exec-2] o.s.w.s.adapter.HttpWebHandlerAdapter
  • The trace id from the request to the circle resource is preserved but a new span id is generated for the request to the rectangles resource.
    This can be seen in the following log:
2020-01-06 10:23:13.830 DEBUG [rest-example,0000000000000001,a6c1c040deedfab4,] 1190 --- [nio-8080-exec-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [46f9fb53] Mapped to se.ivankrizsan.restexample.restadapter.RectangleResource#getAll()
  • The first line of log written after the client has received the response from the request to the rectangles resource is this line:
2020-01-06 10:23:13.850 DEBUG [rest-example,0000000000000001,0000000000000002,] 1190 --- [ctor-http-nio-1] o.s.w.r.f.client.ExchangeFunctions       : [79019676] Response 200 OK
  • In the above log we can see that the trace and span ids are restored to the values they had immediately prior to the request to the rectangles resource.

Spring Cloud Sleuth thus automatically propagates trace and span ids when the WebClient is used to make requests to other applications or services.

This concludes my first encounter with Spring Cloud Sleuth. As there is much more to it, I am sure that I will find reasons for further explorations in a not too distant future!

Happy coding!

One thought on “Spring Boot and Tracing Calls

  1. Kumar

    As per blog did below steps but still not seeing custom baggage-Traceid in the logs. Anything missing here?
    – I used spring-cloud-starter-sleuth 2.2.1.release with springboot 2.2.0.
    – Both properties where set as –
    spring.sleuth.baggage-keys=baggage-TraceId
    spring.sleuth.log.slf4j.whitelisted-mdc-keys=baggage-TraceId.
    – logback-spring.xml is set with this TraceId.
    – in Filter, set the header value fetched from the service request.
    ExtraFieldPropagation.set(“baggage-TraceId”,
    (new ContentCachingRequestWrapper((HttpServletRequest) req).getHeader(“baggage-TraceId”)));

    Reply

Leave a Reply

Your email address will not be published. Required fields are marked *