Fix an issue with logging retries inside WebClient

buildSrc/src/main/kotlin/sb-ot-demo.java-conventions.gradle.kts

@@ -98,8 +98,8 @@ tasks {
         maxParallelForks = 1
 
         retry {
-            maxRetries.set(1)
-            maxFailures.set(3)
+            maxRetries.set(2)
+            maxFailures.set(5)
             failOnPassedAfterRetry.set(false)
         }
     }
@@ -132,14 +132,14 @@ tasks {
                 limit {
                     counter = "INSTRUCTION"
                     value = "COVEREDRATIO"
-                    minimum = "0.82".toBigDecimal()
+                    minimum = "0.90".toBigDecimal()
                 }
             }
             rule {
                 limit {
                     counter = "BRANCH"
                     value = "COVEREDRATIO"
-                    minimum = "0.50".toBigDecimal()
+                    minimum = "0.65".toBigDecimal()
                 }
             }
         }

config/pmd/pmd.xml

@@ -9,12 +9,7 @@
         <exclude name="UnitTestContainsTooManyAsserts"/>
         <exclude name="UnitTestAssertionsShouldIncludeMessage"/>
         <exclude name="GuardLogStatement"/>
-    </rule>
-
-    <rule ref="category/java/bestpractices.xml/AbstractClassWithoutAbstractMethod">
-        <properties>
-            <property name="violationSuppressXPath" value=".[@SimpleName = 'TestBase']"/>
-        </properties>
+        <exclude name="AbstractClassWithoutAbstractMethod"/>
     </rule>
 
     <rule ref="category/java/bestpractices.xml/LooseCoupling">
@@ -78,12 +73,7 @@
         <exclude name="UseUtilityClass"/>
         <exclude name="ExcessiveImports"/>
         <exclude name="CouplingBetweenObjects"/>
-    </rule>
-
-    <rule ref="category/java/design.xml/AbstractClassWithoutAnyMethod">
-        <properties>
-            <property name="violationSuppressXPath" value=".[@SimpleName = 'TestBase']"/>
-        </properties>
+        <exclude name="AbstractClassWithoutAnyMethod"/>
     </rule>
 
     <rule ref="category/java/design.xml/TooManyFields">

settings.gradle.kts

@@ -7,7 +7,7 @@ include("db-migrations")
 dependencyResolutionManagement {
     versionCatalogs {
         create("libs") {
-            val springBoot3Version = version("spring-boot-v3", "3.3.7")
+            val springBoot3Version = version("spring-boot-v3", "3.3.9")
             plugin("spring-boot-v3", "org.springframework.boot")
                 .versionRef(springBoot3Version)
             library("spring-boot-v3-dependencies", "org.springframework.boot", "spring-boot-dependencies")

spring-boot-2-demo-app/src/main/java/io/github/mfvanek/spring/boot2/test/service/PublicApiService.java

@@ -52,26 +52,27 @@ public LocalDateTime getZonedTime() {
     }
 
     private CurrentTime getZonedTimeFromWorldTimeApi() throws JsonProcessingException {
-        final String zoneNames = TimeZone.getDefault().getID();
+        final String zoneName = TimeZone.getDefault().getID();
         final Mono<String> response = webClient.get()
-            .uri(String.join("/", zoneNames))
+            .uri(zoneName)
             .accept(MediaType.APPLICATION_JSON)
             .retrieve()
             .bodyToMono(String.class)
-            .retryWhen(Retry.fixedDelay(retries, Duration.ofSeconds(2))
-                .doBeforeRetry(retrySignal -> {
-                    try (MDC.MDCCloseable ignored = MDC.putCloseable("instance_timezone", zoneNames)) {
-                        final WebClient.RequestHeadersSpec<?> uri = webClient.options().uri(String.join("", zoneNames));
-                        log.info("Retrying request to {}, attempt {}/{} due to error:",
-                            uri, retrySignal.totalRetries() + 1, retries, retrySignal.failure());
-                    }
-                })
-                .onRetryExhaustedThrow((retryBackoffSpec, retrySignal) -> {
-                    final WebClient.RequestHeadersSpec<?> uri = webClient.options().uri(String.join("", zoneNames));
-                    log.error("Request to {} failed after {} attempts.", uri, retrySignal.totalRetries() + 1);
-                    return new ExhaustedRetryException("Retries exhausted", retrySignal.failure());
-                })
-            );
+            .retryWhen(prepareRetry(zoneName));
         return mapper.readValue(response.block(), CurrentTime.class);
     }
+
+    private Retry prepareRetry(final String zoneName) {
+        return Retry.fixedDelay(retries, Duration.ofSeconds(2))
+            .doBeforeRetry(retrySignal -> {
+                try (MDC.MDCCloseable ignored = MDC.putCloseable("instance_timezone", zoneName)) {
+                    log.info("Retrying request to '/{}', attempt {}/{} due to error:",
+                        zoneName, retrySignal.totalRetries() + 1, retries, retrySignal.failure());
+                }
+            })
+            .onRetryExhaustedThrow((retryBackoffSpec, retrySignal) -> {
+                log.error("Request to '/{}' failed after {} attempts.", zoneName, retrySignal.totalRetries() + 1);
+                return new ExhaustedRetryException("Retries exhausted", retrySignal.failure());
+            });
+    }
 }

spring-boot-2-demo-app/src/test/java/io/github/mfvanek/spring/boot2/test/controllers/TimeControllerTest.java

@@ -16,6 +16,7 @@
 import org.junit.jupiter.api.AfterAll;
 import org.junit.jupiter.api.BeforeAll;
 import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Order;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.TestInstance;
 import org.junit.jupiter.api.extension.ExtendWith;
@@ -31,6 +32,7 @@
 import java.time.LocalDateTime;
 import java.util.Arrays;
 import java.util.List;
+import java.util.Locale;
 import java.util.Map;
 import java.util.Objects;
 import java.util.UUID;
@@ -70,6 +72,7 @@ void cleanUpDatabase() {
         jdbcTemplate.execute("truncate table otel_demo.storage");
     }
 
+    @Order(1)
     @Test
     void spanShouldBeReportedInLogs(@Nonnull final CapturedOutput output) throws Exception {
         stubOkResponse(ParsedDateTime.from(LocalDateTime.now(clock).minusDays(1)));
@@ -97,69 +100,50 @@ void spanShouldBeReportedInLogs(@Nonnull final CapturedOutput output) throws Exc
         awaitStoringIntoDatabase();
 
         assertThat(output.getAll())
-            .contains("Received record: " + received.value() + " with traceId " + traceId);
+            .contains("Received record: " + received.value() + " with traceId " + traceId)
+            .contains("\"tenant.name\":\"ru-a1-private\"");
         final String messageFromDb = namedParameterJdbcTemplate.queryForObject("select message from otel_demo.storage where trace_id = :traceId",
             Map.of("traceId", traceId), String.class);
         assertThat(messageFromDb)
             .isEqualTo(received.value());
     }
 
-    private long countRecordsInTable() {
-        final Long queryResult = jdbcTemplate.queryForObject("select count(*) from otel_demo.storage", Long.class);
-        return Objects.requireNonNullElse(queryResult, 0L);
-    }
-
+    @Order(2)
     @Test
-    void mdcValuesShouldBeReportedInLogs(@Nonnull final CapturedOutput output) throws Exception {
-        stubOkResponse(ParsedDateTime.from(LocalDateTime.now(clock).minusDays(1)));
-
-        webTestClient.get()
-            .uri(uriBuilder -> uriBuilder.path("current-time")
-                .build())
-            .exchange()
-            .expectStatus().isOk()
-            .expectHeader().exists(TRACE_ID_HEADER_NAME)
-            .expectBody(LocalDateTime.class)
-            .returnResult();
-
-        final ConsumerRecord<UUID, String> received = consumerRecords.poll(10, TimeUnit.SECONDS);
-        assertThat(received).isNotNull();
-
-        assertThat(output.getAll())
-            .contains("\"tenant.name\":\"ru-a1-private\"");
-    }
-
-    @Test
-    void spanAndMdcShouldBeReportedWhenRetry(@Nonnull final CapturedOutput output) throws Exception {
-        final String zoneNames = stubErrorResponse();
+    void spanAndMdcShouldBeReportedWhenRetry(@Nonnull final CapturedOutput output) {
+        final String zoneName = stubErrorResponse();
 
         final EntityExchangeResult<LocalDateTime> result = webTestClient.get()
             .uri(uriBuilder -> uriBuilder.path("current-time")
                 .build())
+            .header("traceparent", "00-38c19768104ab8ae64fabbeed65bbbdf-4cac1747d4e1ee10-01")
             .exchange()
             .expectStatus().isOk()
             .expectHeader().exists(TRACE_ID_HEADER_NAME)
             .expectBody(LocalDateTime.class)
             .returnResult();
         final String traceId = result.getResponseHeaders().getFirst(TRACE_ID_HEADER_NAME);
-        assertThat(traceId).isNotBlank();
-        assertThat(output.getAll())
-            .contains("Called method getNow. TraceId = " + traceId)
-            .contains("Awaiting acknowledgement from Kafka");
-
-        final ConsumerRecord<UUID, String> received = consumerRecords.poll(10, TimeUnit.SECONDS);
-        assertThat(received).isNotNull();
-        assertThatTraceIdPresentInKafkaHeaders(received, traceId);
-
-        awaitStoringIntoDatabase();
+        assertThat(traceId)
+            .isEqualTo("38c19768104ab8ae64fabbeed65bbbdf");
 
         assertThat(output.getAll())
-            .contains(
-                "Received record: " + received.value() + " with traceId " + traceId,
-                "Retrying request to ",
-                "Retries exhausted",
-                "\"instance_timezone\":\"" + zoneNames + "\""
-            );
+            .containsPattern(String.format(Locale.ROOT,
+                ".*\"message\":\"Retrying request to '/%1$s', attempt 1/1 due to error:\"," +
+                    "\"logger\":\"io\\.github\\.mfvanek\\.spring\\.boot2\\.test\\.service\\.PublicApiService\"," +
+                    "\"thread\":\"[^\"]+\",\"level\":\"INFO\",\"stack_trace\":\".+?\"," +
+                    "\"traceId\":\"38c19768104ab8ae64fabbeed65bbbdf\",\"spanId\":\"[a-f0-9]+\",\"instance_timezone\":\"%1$s\",\"applicationName\":\"spring-boot-2-demo-app\"}%n",
+                zoneName))
+            .containsPattern(String.format(Locale.ROOT,
+                ".*\"message\":\"Request to '/%s' failed after 2 attempts.\"," +
+                    "\"logger\":\"io\\.github\\.mfvanek\\.spring\\.boot2\\.test\\.service\\.PublicApiService\"," +
+                    "\"thread\":\"[^\"]+\",\"level\":\"ERROR\",\"traceId\":\"38c19768104ab8ae64fabbeed65bbbdf\",\"spanId\":\"[a-f0-9]+\",\"applicationName\":\"spring-boot-2-demo-app\"}%n",
+                zoneName))
+            .doesNotContain("Failed to convert response ");
+    }
+
+    private long countRecordsInTable() {
+        final Long queryResult = jdbcTemplate.queryForObject("select count(*) from otel_demo.storage", Long.class);
+        return Objects.requireNonNullElse(queryResult, 0L);
     }
 
     private void assertThatTraceIdPresentInKafkaHeaders(@Nonnull final ConsumerRecord<UUID, String> received,

spring-boot-2-demo-app/src/test/java/io/github/mfvanek/spring/boot2/test/service/PublicApiServiceTest.java

@@ -1,65 +1,86 @@
-/*
- * Copyright (c) 2020-2025. Ivan Vakhrushev and others.
- * https://github.com/mfvanek/spring-boot-open-telemetry-demo
- *
- * Licensed under the Apache License 2.0
- */
-
-package io.github.mfvanek.spring.boot2.test.service;
-
-import io.github.mfvanek.spring.boot2.test.service.dto.ParsedDateTime;
-import io.github.mfvanek.spring.boot2.test.support.TestBase;
-import org.junit.jupiter.api.Test;
-import org.junit.jupiter.api.extension.ExtendWith;
-import org.springframework.beans.factory.annotation.Autowired;
-import org.springframework.boot.test.system.CapturedOutput;
-import org.springframework.boot.test.system.OutputCaptureExtension;
-
-import java.time.LocalDateTime;
-import java.time.temporal.ChronoUnit;
-import javax.annotation.Nonnull;
-
-import static com.github.tomakehurst.wiremock.client.WireMock.getRequestedFor;
-import static com.github.tomakehurst.wiremock.client.WireMock.urlPathMatching;
-import static com.github.tomakehurst.wiremock.client.WireMock.verify;
-import static org.assertj.core.api.Assertions.assertThat;
-
-@ExtendWith(OutputCaptureExtension.class)
-class PublicApiServiceTest extends TestBase {
-
-    @Autowired
-    private PublicApiService publicApiService;
-
-    @Test
-    void getZonedTimeSuccessfully(@Nonnull final CapturedOutput output) {
-        final LocalDateTime localDateTimeNow = LocalDateTime.now(clock);
-        final String zoneNames = stubOkResponse(ParsedDateTime.from(localDateTimeNow));
-
-        final LocalDateTime result = publicApiService.getZonedTime();
-        verify(getRequestedFor(urlPathMatching("/" + zoneNames)));
-
-        assertThat(result).isNotNull();
-        assertThat(result.truncatedTo(ChronoUnit.MINUTES))
-            .isEqualTo(localDateTimeNow.truncatedTo(ChronoUnit.MINUTES));
-        assertThat(output.getAll())
-            .contains("Request received:")
-            .doesNotContain(
-                "Retrying request to ",
-                "Retries exhausted",
-                "Failed to convert response ",
-                "timezone");
-    }
-
-    @Test
-    void retriesOnceToGetZonedTime(@Nonnull final CapturedOutput output) {
-        final String zoneNames = stubErrorResponse();
-
-        final LocalDateTime result = publicApiService.getZonedTime();
-        verify(2, getRequestedFor(urlPathMatching("/" + zoneNames)));
-
-        assertThat(result).isNull();
-        assertThat(output.getAll())
-            .contains("Retrying request to ", "Retries exhausted", "\"instance_timezone\":\"" + zoneNames + "\"")
-            .doesNotContain("Failed to convert response ");
-    }
-}
+/*
+ * Copyright (c) 2020-2025. Ivan Vakhrushev and others.
+ * https://github.com/mfvanek/spring-boot-open-telemetry-demo
+ *
+ * Licensed under the Apache License 2.0
+ */
+
+package io.github.mfvanek.spring.boot2.test.service;
+
+import io.github.mfvanek.spring.boot2.test.service.dto.ParsedDateTime;
+import io.github.mfvanek.spring.boot2.test.support.TestBase;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.ExtendWith;
+import org.springframework.beans.factory.annotation.Autowired;
+import org.springframework.boot.test.system.CapturedOutput;
+import org.springframework.boot.test.system.OutputCaptureExtension;
+import org.springframework.cloud.sleuth.ScopedSpan;
+import org.springframework.cloud.sleuth.Tracer;
+
+import java.time.LocalDateTime;
+import java.time.temporal.ChronoUnit;
+import java.util.Locale;
+import javax.annotation.Nonnull;
+
+import static com.github.tomakehurst.wiremock.client.WireMock.getRequestedFor;
+import static com.github.tomakehurst.wiremock.client.WireMock.urlPathMatching;
+import static com.github.tomakehurst.wiremock.client.WireMock.verify;
+import static org.assertj.core.api.Assertions.assertThat;
+
+@ExtendWith(OutputCaptureExtension.class)
+class PublicApiServiceTest extends TestBase {
+
+    @Autowired
+    private PublicApiService publicApiService;
+    @Autowired
+    private Tracer tracer;
+
+    @Test
+    void getZonedTimeSuccessfully(@Nonnull final CapturedOutput output) {
+        final LocalDateTime localDateTimeNow = LocalDateTime.now(clock);
+        final String zoneName = stubOkResponse(ParsedDateTime.from(localDateTimeNow));
+
+        final LocalDateTime result = publicApiService.getZonedTime();
+        verify(getRequestedFor(urlPathMatching("/" + zoneName)));
+
+        assertThat(result).isNotNull();
+        assertThat(result.truncatedTo(ChronoUnit.MINUTES))
+            .isEqualTo(localDateTimeNow.truncatedTo(ChronoUnit.MINUTES));
+        assertThat(output.getAll())
+            .contains("Request received:")
+            .doesNotContain(
+                "Retrying request to ",
+                "Retries exhausted",
+                "Failed to convert response ",
+                "timezone");
+    }
+
+    @Test
+    void retriesOnceToGetZonedTime(@Nonnull final CapturedOutput output) {
+        final String zoneName = stubErrorResponse();
+        final ScopedSpan span = tracer.startScopedSpan("test");
+        try {
+            final LocalDateTime result = publicApiService.getZonedTime();
+            assertThat(result).isNull();
+
+            final String traceId = span.context().traceId();
+            assertThat(output.getAll())
+                .containsPattern(String.format(Locale.ROOT,
+                    ".*\"message\":\"Retrying request to '/%s', attempt 1/1 due to error:\"," +
+                        "\"logger\":\"io\\.github\\.mfvanek\\.spring\\.boot2\\.test\\.service\\.PublicApiService\"," +
+                        "\"thread\":\"[^\"]+\",\"level\":\"INFO\",\"stack_trace\":\".+?\"," +
+                        "\"traceId\":\"%s\",\"spanId\":\"[a-f0-9]+\",\"instance_timezone\":\"%s\",\"applicationName\":\"spring-boot-2-demo-app\"}%n",
+                    zoneName, traceId, zoneName))
+                .containsPattern(String.format(Locale.ROOT,
+                    ".*\"message\":\"Request to '/%s' failed after 2 attempts.\"," +
+                        "\"logger\":\"io\\.github\\.mfvanek\\.spring\\.boot2\\.test\\.service\\.PublicApiService\"," +
+                        "\"thread\":\"[^\"]+\",\"level\":\"ERROR\",\"traceId\":\"%s\",\"spanId\":\"[a-f0-9]+\",\"applicationName\":\"spring-boot-2-demo-app\"}%n",
+                    zoneName, traceId))
+                .doesNotContain("Failed to convert response ");
+        } finally {
+            span.end();
+        }
+
+        verify(2, getRequestedFor(urlPathMatching("/" + zoneName)));
+    }
+}