Skip to content

Commit 0c37c72

Browse files
mfvanekmfvanek
authored
Fix an issue with logging retries inside WebClient (#230)
* Logging retries in Spring Boot 2 * Logging retries in Spring Boot 3 * Logging retries in Spring Boot 2 * Logging retries in Spring Boot 3 * Logging retries in Spring Boot 3 * Logging retries in Spring Boot 2 * Split profiles * Fix tests * Ordering tests * Test retries * Fix test
1 parent 09bc24a commit 0c37c72

File tree

15 files changed

+249
-249
lines changed

15 files changed

+249
-249
lines changed

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

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -98,8 +98,8 @@ tasks {
9898
maxParallelForks = 1
9999

100100
retry {
101-
maxRetries.set(1)
102-
maxFailures.set(3)
101+
maxRetries.set(2)
102+
maxFailures.set(5)
103103
failOnPassedAfterRetry.set(false)
104104
}
105105
}
@@ -132,14 +132,14 @@ tasks {
132132
limit {
133133
counter = "INSTRUCTION"
134134
value = "COVEREDRATIO"
135-
minimum = "0.82".toBigDecimal()
135+
minimum = "0.90".toBigDecimal()
136136
}
137137
}
138138
rule {
139139
limit {
140140
counter = "BRANCH"
141141
value = "COVEREDRATIO"
142-
minimum = "0.50".toBigDecimal()
142+
minimum = "0.65".toBigDecimal()
143143
}
144144
}
145145
}

‎config/pmd/pmd.xml‎

Lines changed: 2 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -9,12 +9,7 @@
99
<exclude name="UnitTestContainsTooManyAsserts"/>
1010
<exclude name="UnitTestAssertionsShouldIncludeMessage"/>
1111
<exclude name="GuardLogStatement"/>
12-
</rule>
13-
14-
<rule ref="category/java/bestpractices.xml/AbstractClassWithoutAbstractMethod">
15-
<properties>
16-
<property name="violationSuppressXPath" value=".[@SimpleName = 'TestBase']"/>
17-
</properties>
12+
<exclude name="AbstractClassWithoutAbstractMethod"/>
1813
</rule>
1914

2015
<rule ref="category/java/bestpractices.xml/LooseCoupling">
@@ -78,12 +73,7 @@
7873
<exclude name="UseUtilityClass"/>
7974
<exclude name="ExcessiveImports"/>
8075
<exclude name="CouplingBetweenObjects"/>
81-
</rule>
82-
83-
<rule ref="category/java/design.xml/AbstractClassWithoutAnyMethod">
84-
<properties>
85-
<property name="violationSuppressXPath" value=".[@SimpleName = 'TestBase']"/>
86-
</properties>
76+
<exclude name="AbstractClassWithoutAnyMethod"/>
8777
</rule>
8878

8979
<rule ref="category/java/design.xml/TooManyFields">

‎settings.gradle.kts‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@ include("db-migrations")
77
dependencyResolutionManagement {
88
versionCatalogs {
99
create("libs") {
10-
val springBoot3Version = version("spring-boot-v3", "3.3.7")
10+
val springBoot3Version = version("spring-boot-v3", "3.3.9")
1111
plugin("spring-boot-v3", "org.springframework.boot")
1212
.versionRef(springBoot3Version)
1313
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‎

Lines changed: 17 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -52,26 +52,27 @@ public LocalDateTime getZonedTime() {
5252
}
5353

5454
private CurrentTime getZonedTimeFromWorldTimeApi() throws JsonProcessingException {
55-
final String zoneNames = TimeZone.getDefault().getID();
55+
final String zoneName = TimeZone.getDefault().getID();
5656
final Mono<String> response = webClient.get()
57-
.uri(String.join("/", zoneNames))
57+
.uri(zoneName)
5858
.accept(MediaType.APPLICATION_JSON)
5959
.retrieve()
6060
.bodyToMono(String.class)
61-
.retryWhen(Retry.fixedDelay(retries, Duration.ofSeconds(2))
62-
.doBeforeRetry(retrySignal -> {
63-
try (MDC.MDCCloseable ignored = MDC.putCloseable("instance_timezone", zoneNames)) {
64-
final WebClient.RequestHeadersSpec<?> uri = webClient.options().uri(String.join("", zoneNames));
65-
log.info("Retrying request to {}, attempt {}/{} due to error:",
66-
uri, retrySignal.totalRetries() + 1, retries, retrySignal.failure());
67-
}
68-
})
69-
.onRetryExhaustedThrow((retryBackoffSpec, retrySignal) -> {
70-
final WebClient.RequestHeadersSpec<?> uri = webClient.options().uri(String.join("", zoneNames));
71-
log.error("Request to {} failed after {} attempts.", uri, retrySignal.totalRetries() + 1);
72-
return new ExhaustedRetryException("Retries exhausted", retrySignal.failure());
73-
})
74-
);
61+
.retryWhen(prepareRetry(zoneName));
7562
return mapper.readValue(response.block(), CurrentTime.class);
7663
}
64+
65+
private Retry prepareRetry(final String zoneName) {
66+
return Retry.fixedDelay(retries, Duration.ofSeconds(2))
67+
.doBeforeRetry(retrySignal -> {
68+
try (MDC.MDCCloseable ignored = MDC.putCloseable("instance_timezone", zoneName)) {
69+
log.info("Retrying request to '/{}', attempt {}/{} due to error:",
70+
zoneName, retrySignal.totalRetries() + 1, retries, retrySignal.failure());
71+
}
72+
})
73+
.onRetryExhaustedThrow((retryBackoffSpec, retrySignal) -> {
74+
log.error("Request to '/{}' failed after {} attempts.", zoneName, retrySignal.totalRetries() + 1);
75+
return new ExhaustedRetryException("Retries exhausted", retrySignal.failure());
76+
});
77+
}
7778
}

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

Lines changed: 28 additions & 44 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@
1616
import org.junit.jupiter.api.AfterAll;
1717
import org.junit.jupiter.api.BeforeAll;
1818
import org.junit.jupiter.api.BeforeEach;
19+
import org.junit.jupiter.api.Order;
1920
import org.junit.jupiter.api.Test;
2021
import org.junit.jupiter.api.TestInstance;
2122
import org.junit.jupiter.api.extension.ExtendWith;
@@ -31,6 +32,7 @@
3132
import java.time.LocalDateTime;
3233
import java.util.Arrays;
3334
import java.util.List;
35+
import java.util.Locale;
3436
import java.util.Map;
3537
import java.util.Objects;
3638
import java.util.UUID;
@@ -70,6 +72,7 @@ void cleanUpDatabase() {
7072
jdbcTemplate.execute("truncate table otel_demo.storage");
7173
}
7274

75+
@Order(1)
7376
@Test
7477
void spanShouldBeReportedInLogs(@Nonnull final CapturedOutput output) throws Exception {
7578
stubOkResponse(ParsedDateTime.from(LocalDateTime.now(clock).minusDays(1)));
@@ -97,69 +100,50 @@ void spanShouldBeReportedInLogs(@Nonnull final CapturedOutput output) throws Exc
97100
awaitStoringIntoDatabase();
98101

99102
assertThat(output.getAll())
100-
.contains("Received record: " + received.value() + " with traceId " + traceId);
103+
.contains("Received record: " + received.value() + " with traceId " + traceId)
104+
.contains("\"tenant.name\":\"ru-a1-private\"");
101105
final String messageFromDb = namedParameterJdbcTemplate.queryForObject("select message from otel_demo.storage where trace_id = :traceId",
102106
Map.of("traceId", traceId), String.class);
103107
assertThat(messageFromDb)
104108
.isEqualTo(received.value());
105109
}
106110

107-
private long countRecordsInTable() {
108-
final Long queryResult = jdbcTemplate.queryForObject("select count(*) from otel_demo.storage", Long.class);
109-
return Objects.requireNonNullElse(queryResult, 0L);
110-
}
111-
111+
@Order(2)
112112
@Test
113-
void mdcValuesShouldBeReportedInLogs(@Nonnull final CapturedOutput output) throws Exception {
114-
stubOkResponse(ParsedDateTime.from(LocalDateTime.now(clock).minusDays(1)));
115-
116-
webTestClient.get()
117-
.uri(uriBuilder -> uriBuilder.path("current-time")
118-
.build())
119-
.exchange()
120-
.expectStatus().isOk()
121-
.expectHeader().exists(TRACE_ID_HEADER_NAME)
122-
.expectBody(LocalDateTime.class)
123-
.returnResult();
124-
125-
final ConsumerRecord<UUID, String> received = consumerRecords.poll(10, TimeUnit.SECONDS);
126-
assertThat(received).isNotNull();
127-
128-
assertThat(output.getAll())
129-
.contains("\"tenant.name\":\"ru-a1-private\"");
130-
}
131-
132-
@Test
133-
void spanAndMdcShouldBeReportedWhenRetry(@Nonnull final CapturedOutput output) throws Exception {
134-
final String zoneNames = stubErrorResponse();
113+
void spanAndMdcShouldBeReportedWhenRetry(@Nonnull final CapturedOutput output) {
114+
final String zoneName = stubErrorResponse();
135115

136116
final EntityExchangeResult<LocalDateTime> result = webTestClient.get()
137117
.uri(uriBuilder -> uriBuilder.path("current-time")
138118
.build())
119+
.header("traceparent", "00-38c19768104ab8ae64fabbeed65bbbdf-4cac1747d4e1ee10-01")
139120
.exchange()
140121
.expectStatus().isOk()
141122
.expectHeader().exists(TRACE_ID_HEADER_NAME)
142123
.expectBody(LocalDateTime.class)
143124
.returnResult();
144125
final String traceId = result.getResponseHeaders().getFirst(TRACE_ID_HEADER_NAME);
145-
assertThat(traceId).isNotBlank();
146-
assertThat(output.getAll())
147-
.contains("Called method getNow. TraceId = " + traceId)
148-
.contains("Awaiting acknowledgement from Kafka");
149-
150-
final ConsumerRecord<UUID, String> received = consumerRecords.poll(10, TimeUnit.SECONDS);
151-
assertThat(received).isNotNull();
152-
assertThatTraceIdPresentInKafkaHeaders(received, traceId);
153-
154-
awaitStoringIntoDatabase();
126+
assertThat(traceId)
127+
.isEqualTo("38c19768104ab8ae64fabbeed65bbbdf");
155128

156129
assertThat(output.getAll())
157-
.contains(
158-
"Received record: " + received.value() + " with traceId " + traceId,
159-
"Retrying request to ",
160-
"Retries exhausted",
161-
"\"instance_timezone\":\"" + zoneNames + "\""
162-
);
130+
.containsPattern(String.format(Locale.ROOT,
131+
".*\"message\":\"Retrying request to '/%1$s', attempt 1/1 due to error:\"," +
132+
"\"logger\":\"io\\.github\\.mfvanek\\.spring\\.boot2\\.test\\.service\\.PublicApiService\"," +
133+
"\"thread\":\"[^\"]+\",\"level\":\"INFO\",\"stack_trace\":\".+?\"," +
134+
"\"traceId\":\"38c19768104ab8ae64fabbeed65bbbdf\",\"spanId\":\"[a-f0-9]+\",\"instance_timezone\":\"%1$s\",\"applicationName\":\"spring-boot-2-demo-app\"}%n",
135+
zoneName))
136+
.containsPattern(String.format(Locale.ROOT,
137+
".*\"message\":\"Request to '/%s' failed after 2 attempts.\"," +
138+
"\"logger\":\"io\\.github\\.mfvanek\\.spring\\.boot2\\.test\\.service\\.PublicApiService\"," +
139+
"\"thread\":\"[^\"]+\",\"level\":\"ERROR\",\"traceId\":\"38c19768104ab8ae64fabbeed65bbbdf\",\"spanId\":\"[a-f0-9]+\",\"applicationName\":\"spring-boot-2-demo-app\"}%n",
140+
zoneName))
141+
.doesNotContain("Failed to convert response ");
142+
}
143+
144+
private long countRecordsInTable() {
145+
final Long queryResult = jdbcTemplate.queryForObject("select count(*) from otel_demo.storage", Long.class);
146+
return Objects.requireNonNullElse(queryResult, 0L);
163147
}
164148

165149
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‎

Lines changed: 86 additions & 65 deletions
Original file line numberDiff line numberDiff line change
@@ -1,65 +1,86 @@
1-
/*
2-
* Copyright (c) 2020-2025. Ivan Vakhrushev and others.
3-
* https://github.com/mfvanek/spring-boot-open-telemetry-demo
4-
*
5-
* Licensed under the Apache License 2.0
6-
*/
7-
8-
package io.github.mfvanek.spring.boot2.test.service;
9-
10-
import io.github.mfvanek.spring.boot2.test.service.dto.ParsedDateTime;
11-
import io.github.mfvanek.spring.boot2.test.support.TestBase;
12-
import org.junit.jupiter.api.Test;
13-
import org.junit.jupiter.api.extension.ExtendWith;
14-
import org.springframework.beans.factory.annotation.Autowired;
15-
import org.springframework.boot.test.system.CapturedOutput;
16-
import org.springframework.boot.test.system.OutputCaptureExtension;
17-
18-
import java.time.LocalDateTime;
19-
import java.time.temporal.ChronoUnit;
20-
import javax.annotation.Nonnull;
21-
22-
import static com.github.tomakehurst.wiremock.client.WireMock.getRequestedFor;
23-
import static com.github.tomakehurst.wiremock.client.WireMock.urlPathMatching;
24-
import static com.github.tomakehurst.wiremock.client.WireMock.verify;
25-
import static org.assertj.core.api.Assertions.assertThat;
26-
27-
@ExtendWith(OutputCaptureExtension.class)
28-
class PublicApiServiceTest extends TestBase {
29-
30-
@Autowired
31-
private PublicApiService publicApiService;
32-
33-
@Test
34-
void getZonedTimeSuccessfully(@Nonnull final CapturedOutput output) {
35-
final LocalDateTime localDateTimeNow = LocalDateTime.now(clock);
36-
final String zoneNames = stubOkResponse(ParsedDateTime.from(localDateTimeNow));
37-
38-
final LocalDateTime result = publicApiService.getZonedTime();
39-
verify(getRequestedFor(urlPathMatching("/" + zoneNames)));
40-
41-
assertThat(result).isNotNull();
42-
assertThat(result.truncatedTo(ChronoUnit.MINUTES))
43-
.isEqualTo(localDateTimeNow.truncatedTo(ChronoUnit.MINUTES));
44-
assertThat(output.getAll())
45-
.contains("Request received:")
46-
.doesNotContain(
47-
"Retrying request to ",
48-
"Retries exhausted",
49-
"Failed to convert response ",
50-
"timezone");
51-
}
52-
53-
@Test
54-
void retriesOnceToGetZonedTime(@Nonnull final CapturedOutput output) {
55-
final String zoneNames = stubErrorResponse();
56-
57-
final LocalDateTime result = publicApiService.getZonedTime();
58-
verify(2, getRequestedFor(urlPathMatching("/" + zoneNames)));
59-
60-
assertThat(result).isNull();
61-
assertThat(output.getAll())
62-
.contains("Retrying request to ", "Retries exhausted", "\"instance_timezone\":\"" + zoneNames + "\"")
63-
.doesNotContain("Failed to convert response ");
64-
}
65-
}
1+
/*
2+
* Copyright (c) 2020-2025. Ivan Vakhrushev and others.
3+
* https://github.com/mfvanek/spring-boot-open-telemetry-demo
4+
*
5+
* Licensed under the Apache License 2.0
6+
*/
7+
8+
package io.github.mfvanek.spring.boot2.test.service;
9+
10+
import io.github.mfvanek.spring.boot2.test.service.dto.ParsedDateTime;
11+
import io.github.mfvanek.spring.boot2.test.support.TestBase;
12+
import org.junit.jupiter.api.Test;
13+
import org.junit.jupiter.api.extension.ExtendWith;
14+
import org.springframework.beans.factory.annotation.Autowired;
15+
import org.springframework.boot.test.system.CapturedOutput;
16+
import org.springframework.boot.test.system.OutputCaptureExtension;
17+
import org.springframework.cloud.sleuth.ScopedSpan;
18+
import org.springframework.cloud.sleuth.Tracer;
19+
20+
import java.time.LocalDateTime;
21+
import java.time.temporal.ChronoUnit;
22+
import java.util.Locale;
23+
import javax.annotation.Nonnull;
24+
25+
import static com.github.tomakehurst.wiremock.client.WireMock.getRequestedFor;
26+
import static com.github.tomakehurst.wiremock.client.WireMock.urlPathMatching;
27+
import static com.github.tomakehurst.wiremock.client.WireMock.verify;
28+
import static org.assertj.core.api.Assertions.assertThat;
29+
30+
@ExtendWith(OutputCaptureExtension.class)
31+
class PublicApiServiceTest extends TestBase {
32+
33+
@Autowired
34+
private PublicApiService publicApiService;
35+
@Autowired
36+
private Tracer tracer;
37+
38+
@Test
39+
void getZonedTimeSuccessfully(@Nonnull final CapturedOutput output) {
40+
final LocalDateTime localDateTimeNow = LocalDateTime.now(clock);
41+
final String zoneName = stubOkResponse(ParsedDateTime.from(localDateTimeNow));
42+
43+
final LocalDateTime result = publicApiService.getZonedTime();
44+
verify(getRequestedFor(urlPathMatching("/" + zoneName)));
45+
46+
assertThat(result).isNotNull();
47+
assertThat(result.truncatedTo(ChronoUnit.MINUTES))
48+
.isEqualTo(localDateTimeNow.truncatedTo(ChronoUnit.MINUTES));
49+
assertThat(output.getAll())
50+
.contains("Request received:")
51+
.doesNotContain(
52+
"Retrying request to ",
53+
"Retries exhausted",
54+
"Failed to convert response ",
55+
"timezone");
56+
}
57+
58+
@Test
59+
void retriesOnceToGetZonedTime(@Nonnull final CapturedOutput output) {
60+
final String zoneName = stubErrorResponse();
61+
final ScopedSpan span = tracer.startScopedSpan("test");
62+
try {
63+
final LocalDateTime result = publicApiService.getZonedTime();
64+
assertThat(result).isNull();
65+
66+
final String traceId = span.context().traceId();
67+
assertThat(output.getAll())
68+
.containsPattern(String.format(Locale.ROOT,
69+
".*\"message\":\"Retrying request to '/%s', attempt 1/1 due to error:\"," +
70+
"\"logger\":\"io\\.github\\.mfvanek\\.spring\\.boot2\\.test\\.service\\.PublicApiService\"," +
71+
"\"thread\":\"[^\"]+\",\"level\":\"INFO\",\"stack_trace\":\".+?\"," +
72+
"\"traceId\":\"%s\",\"spanId\":\"[a-f0-9]+\",\"instance_timezone\":\"%s\",\"applicationName\":\"spring-boot-2-demo-app\"}%n",
73+
zoneName, traceId, zoneName))
74+
.containsPattern(String.format(Locale.ROOT,
75+
".*\"message\":\"Request to '/%s' failed after 2 attempts.\"," +
76+
"\"logger\":\"io\\.github\\.mfvanek\\.spring\\.boot2\\.test\\.service\\.PublicApiService\"," +
77+
"\"thread\":\"[^\"]+\",\"level\":\"ERROR\",\"traceId\":\"%s\",\"spanId\":\"[a-f0-9]+\",\"applicationName\":\"spring-boot-2-demo-app\"}%n",
78+
zoneName, traceId))
79+
.doesNotContain("Failed to convert response ");
80+
} finally {
81+
span.end();
82+
}
83+
84+
verify(2, getRequestedFor(urlPathMatching("/" + zoneName)));
85+
}
86+
}

0 commit comments

Comments
 (0)