Fix an issue with logging retries inside WebClient

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

@@ -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()
                 }
             }
         }

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/TimeControllerRetryTest.java

@@ -0,0 +1,54 @@
+/*
+ * 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.controllers;
+
+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.boot.test.system.CapturedOutput;
+import org.springframework.boot.test.system.OutputCaptureExtension;
+import org.springframework.test.context.ActiveProfiles;
+import org.springframework.test.web.reactive.server.EntityExchangeResult;
+
+import java.time.LocalDateTime;
+import java.util.Locale;
+import javax.annotation.Nonnull;
+
+import static io.github.mfvanek.spring.boot2.test.filters.TraceIdInResponseServletFilter.TRACE_ID_HEADER_NAME;
+import static org.assertj.core.api.Assertions.assertThat;
+
+@ActiveProfiles("test-retry")
+@ExtendWith(OutputCaptureExtension.class)
+class TimeControllerRetryTest extends TestBase {
+
+    @Test
+    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)
+            .isEqualTo("38c19768104ab8ae64fabbeed65bbbdf");
+
+        assertThat(output.getAll())
+            .containsPattern(String.format(Locale.ROOT,
+                ".*INFO \\[spring-boot-2-demo-app,%s,[a-fA-F0-9]{16}] \\d+ --- \\[.*?] i\\.g\\.m\\.s\\.b\\.test\\.service\\.PublicApiService {2}: Retrying request to",
+                traceId))
+            .containsPattern(String.format(Locale.ROOT,
+                ".*ERROR \\[spring-boot-2-demo-app,%s,[a-fA-F0-9]{16}] \\d+ --- \\[.*?] i\\.g\\.m\\.s\\.b\\.test\\.service\\.PublicApiService {2}: Request to '/%s' failed after 2 attempts",
+                traceId, zoneName));
+    }
+}

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

@@ -129,39 +129,6 @@ void mdcValuesShouldBeReportedInLogs(@Nonnull final CapturedOutput output) throw
             .contains("\"tenant.name\":\"ru-a1-private\"");
     }
 
-    @Test
-    void spanAndMdcShouldBeReportedWhenRetry(@Nonnull final CapturedOutput output) throws Exception {
-        final String zoneNames = stubErrorResponse();
-
-        final EntityExchangeResult<LocalDateTime> result = webTestClient.get()
-            .uri(uriBuilder -> uriBuilder.path("current-time")
-                .build())
-            .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(output.getAll())
-            .contains(
-                "Received record: " + received.value() + " with traceId " + traceId,
-                "Retrying request to ",
-                "Retries exhausted",
-                "\"instance_timezone\":\"" + zoneNames + "\""
-            );
-    }
-
     private void assertThatTraceIdPresentInKafkaHeaders(@Nonnull final ConsumerRecord<UUID, String> received,
                                                         @Nonnull final String expectedTraceId) {
         assertThat(received.value()).startsWith("Current time = ");

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

@@ -1,65 +1,84 @@
-/*
- * 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 org.springframework.test.context.ActiveProfiles;
+
+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;
+
+@ActiveProfiles("test-retry")
+@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 ScopedSpan span = tracer.startScopedSpan("test");
+        try {
+            final String zoneName = stubErrorResponse();
+
+            final LocalDateTime result = publicApiService.getZonedTime();
+            verify(2, getRequestedFor(urlPathMatching("/" + zoneName)));
+
+            assertThat(result).isNull();
+
+            final String traceId = span.context().traceId();
+            assertThat(output.getAll())
+                .containsPattern(String.format(Locale.ROOT,
+                    ".*INFO \\[spring-boot-2-demo-app,%s,[a-fA-F0-9]{16}] \\d+ --- \\[.*?] i\\.g\\.m\\.s\\.b\\.test\\.service\\.PublicApiService {2}: Retrying request to",
+                    traceId))
+                .containsPattern(String.format(Locale.ROOT,
+                    ".*ERROR \\[spring-boot-2-demo-app,%s,[a-fA-F0-9]{16}] \\d+ --- \\[.*?] i\\.g\\.m\\.s\\.b\\.test\\.service\\.PublicApiService {2}: Request to '/%s' failed after 2 attempts",
+                    traceId, zoneName))
+                .doesNotContain("Failed to convert response ");
+        } finally {
+            span.end();
+        }
+    }
+}

spring-boot-2-demo-app/src/test/java/io/github/mfvanek/spring/boot2/test/support/TestBase.java

@@ -55,15 +55,15 @@ void resetExternalMocks() {
 
     @Nonnull
     protected String stubOkResponse(@Nonnull final ParsedDateTime parsedDateTime) {
-        final String zoneNames = TimeZone.getDefault().getID();
-        stubOkResponse(zoneNames, parsedDateTime);
-        return zoneNames;
+        final String zoneName = TimeZone.getDefault().getID();
+        stubOkResponse(zoneName, parsedDateTime);
+        return zoneName;
     }
 
     @SneakyThrows
-    private void stubOkResponse(@Nonnull final String zoneNames, @Nonnull final ParsedDateTime parsedDateTime) {
+    private void stubOkResponse(@Nonnull final String zoneName, @Nonnull final ParsedDateTime parsedDateTime) {
         final CurrentTime currentTime = new CurrentTime(parsedDateTime);
-        stubFor(get(urlPathMatching("/" + zoneNames))
+        stubFor(get(urlPathMatching("/" + zoneName))
             .willReturn(aResponse()
                 .withStatus(200)
                 .withBody(objectMapper.writeValueAsString(currentTime))
@@ -72,15 +72,15 @@ private void stubOkResponse(@Nonnull final String zoneNames, @Nonnull final Pars
 
     @Nonnull
     protected String stubErrorResponse() {
-        final String zoneNames = TimeZone.getDefault().getID();
+        final String zoneName = TimeZone.getDefault().getID();
         final RuntimeException exception = new RuntimeException("Retries exhausted");
-        stubErrorResponse(zoneNames, exception);
-        return zoneNames;
+        stubErrorResponse(zoneName, exception);
+        return zoneName;
     }
 
     @SneakyThrows
-    private void stubErrorResponse(@Nonnull final String zoneNames, @Nonnull final RuntimeException errorForResponse) {
-        stubFor(get(urlPathMatching("/" + zoneNames))
+    private void stubErrorResponse(@Nonnull final String zoneName, @Nonnull final RuntimeException errorForResponse) {
+        stubFor(get(urlPathMatching("/" + zoneName))
             .willReturn(aResponse()
                 .withStatus(500)
                 .withBody(objectMapper.writeValueAsString(errorForResponse))

spring-boot-2-demo-app/src/test/resources/application-test-retry.yml

@@ -0,0 +1,3 @@
+logging:
+    appender:
+        name: CONSOLE

spring-boot-2-demo-app/src/test/resources/application-test.yml

@@ -2,10 +2,6 @@ app:
     external-base-url: "http://localhost:${wiremock.server.port}/"
     retries: 1
 
-#to change default appender in tests use:
-#logging:
-#    appender.name: CONSOLE
-
 logging:
     level:
         org.testcontainers: INFO # In order to troubleshoot issues with Testcontainers, increase the logging level to DEBUG

spring-boot-3-demo-app/build.gradle.kts

@@ -10,7 +10,7 @@ dependencies {
     implementation(platform(project(":common-internal-bom")))
     implementation(platform("org.springdoc:springdoc-openapi:2.6.0"))
     implementation(platform(libs.spring.boot.v3.dependencies))
-    implementation(platform("org.springframework.cloud:spring-cloud-dependencies:2023.0.4"))
+    implementation(platform("org.springframework.cloud:spring-cloud-dependencies:2023.0.5"))
 
     implementation("org.springframework.boot:spring-boot-starter-web")
     implementation("org.springframework.boot:spring-boot-starter-webflux")