diff --git a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/reactive/server/MetricsWebFilter.java b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/reactive/server/MetricsWebFilter.java index 09760ba24a7..c07b08c0cb4 100644 --- a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/reactive/server/MetricsWebFilter.java +++ b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/reactive/server/MetricsWebFilter.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2020 the original author or authors. + * Copyright 2012-2021 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -20,6 +20,8 @@ import java.util.concurrent.TimeUnit; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Tag; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.reactivestreams.Publisher; import reactor.core.publisher.Mono; @@ -41,6 +43,8 @@ import org.springframework.web.server.WebFilterChain; @Order(Ordered.HIGHEST_PRECEDENCE + 1) public class MetricsWebFilter implements WebFilter { + private static Log logger = LogFactory.getLog(MetricsWebFilter.class); + private final MeterRegistry registry; private final WebFluxTagsProvider tagsProvider; @@ -97,9 +101,15 @@ public class MetricsWebFilter implements WebFilter { } private void record(ServerWebExchange exchange, long start, Throwable cause) { - Iterable tags = this.tagsProvider.httpRequestTags(exchange, cause); - this.autoTimer.builder(this.metricName).tags(tags).register(this.registry).record(System.nanoTime() - start, - TimeUnit.NANOSECONDS); + try { + Iterable tags = this.tagsProvider.httpRequestTags(exchange, cause); + this.autoTimer.builder(this.metricName).tags(tags).register(this.registry).record(System.nanoTime() - start, + TimeUnit.NANOSECONDS); + } + catch (Exception ex) { + logger.warn("Failed to record timer metrics", ex); + // Allow exchange to continue, unaffected by metrics problem + } } } diff --git a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptor.java b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptor.java index 524a09b4491..7f5be970bb7 100644 --- a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptor.java +++ b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptor.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2019 the original author or authors. + * Copyright 2012-2021 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -30,6 +30,8 @@ import io.micrometer.core.annotation.Timed; import io.micrometer.core.instrument.LongTaskTimer; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Tag; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.springframework.core.annotation.MergedAnnotationCollectors; import org.springframework.core.annotation.MergedAnnotations; @@ -46,6 +48,8 @@ import org.springframework.web.servlet.HandlerInterceptor; */ public class LongTaskTimingHandlerInterceptor implements HandlerInterceptor { + private static final Log logger = LogFactory.getLog(LongTaskTimingHandlerInterceptor.class); + private final MeterRegistry registry; private final WebMvcTagsProvider tagsProvider; @@ -90,12 +94,18 @@ public class LongTaskTimingHandlerInterceptor implements HandlerInterceptor { private Collection getLongTaskTimerSamples(HttpServletRequest request, Object handler, Set annotations) { List samples = new ArrayList<>(); - annotations.stream().filter(Timed::longTask).forEach((annotation) -> { - Iterable tags = this.tagsProvider.getLongRequestTags(request, handler); - LongTaskTimer.Builder builder = LongTaskTimer.builder(annotation).tags(tags); - LongTaskTimer timer = builder.register(this.registry); - samples.add(timer.start()); - }); + try { + annotations.stream().filter(Timed::longTask).forEach((annotation) -> { + Iterable tags = this.tagsProvider.getLongRequestTags(request, handler); + LongTaskTimer.Builder builder = LongTaskTimer.builder(annotation).tags(tags); + LongTaskTimer timer = builder.register(this.registry); + samples.add(timer.start()); + }); + } + catch (Exception ex) { + logger.warn("Failed to start long task timers", ex); + // Allow request-response exchange to continue, unaffected by metrics problem + } return samples; } diff --git a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter.java b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter.java index 989b0f78718..b57baed75fd 100644 --- a/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter.java +++ b/spring-boot-project/spring-boot-actuator/src/main/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2020 the original author or authors. + * Copyright 2012-2021 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -31,6 +31,8 @@ import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Timer; import io.micrometer.core.instrument.Timer.Builder; import io.micrometer.core.instrument.Timer.Sample; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.springframework.boot.actuate.metrics.AutoTimer; import org.springframework.core.annotation.MergedAnnotationCollectors; @@ -53,6 +55,8 @@ import org.springframework.web.util.NestedServletException; */ public class WebMvcMetricsFilter extends OncePerRequestFilter { + private static final Log logger = LogFactory.getLog(WebMvcMetricsFilter.class); + private final MeterRegistry registry; private final WebMvcTagsProvider tagsProvider; @@ -120,20 +124,26 @@ public class WebMvcMetricsFilter extends OncePerRequestFilter { private void record(TimingContext timingContext, HttpServletRequest request, HttpServletResponse response, Throwable exception) { - Object handler = getHandler(request); - Set annotations = getTimedAnnotations(handler); - Timer.Sample timerSample = timingContext.getTimerSample(); - if (annotations.isEmpty()) { - if (this.autoTimer.isEnabled()) { - Builder builder = this.autoTimer.builder(this.metricName); - timerSample.stop(getTimer(builder, handler, request, response, exception)); + try { + Object handler = getHandler(request); + Set annotations = getTimedAnnotations(handler); + Timer.Sample timerSample = timingContext.getTimerSample(); + if (annotations.isEmpty()) { + if (this.autoTimer.isEnabled()) { + Builder builder = this.autoTimer.builder(this.metricName); + timerSample.stop(getTimer(builder, handler, request, response, exception)); + } + } + else { + for (Timed annotation : annotations) { + Builder builder = Timer.builder(annotation, this.metricName); + timerSample.stop(getTimer(builder, handler, request, response, exception)); + } } } - else { - for (Timed annotation : annotations) { - Builder builder = Timer.builder(annotation, this.metricName); - timerSample.stop(getTimer(builder, handler, request, response, exception)); - } + catch (Exception ex) { + logger.warn("Failed to record timer metrics", ex); + // Allow request-response exchange to continue, unaffected by metrics problem } } diff --git a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/reactive/server/MetricsWebFilterTests.java b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/reactive/server/MetricsWebFilterTests.java index 7f3008343de..c6c7a5195be 100644 --- a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/reactive/server/MetricsWebFilterTests.java +++ b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/reactive/server/MetricsWebFilterTests.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2020 the original author or authors. + * Copyright 2012-2021 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -17,8 +17,10 @@ package org.springframework.boot.actuate.metrics.web.reactive.server; import java.time.Duration; +import java.util.concurrent.atomic.AtomicBoolean; import io.micrometer.core.instrument.MockClock; +import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.simple.SimpleConfig; import io.micrometer.core.instrument.simple.SimpleMeterRegistry; import org.junit.jupiter.api.BeforeEach; @@ -29,6 +31,7 @@ import org.springframework.boot.actuate.metrics.AutoTimer; import org.springframework.mock.http.server.reactive.MockServerHttpRequest; import org.springframework.mock.web.server.MockServerWebExchange; import org.springframework.web.reactive.HandlerMapping; +import org.springframework.web.server.ServerWebExchange; import org.springframework.web.util.pattern.PathPatternParser; import static org.assertj.core.api.Assertions.assertThat; @@ -43,6 +46,8 @@ class MetricsWebFilterTests { private static final String REQUEST_METRICS_NAME = "http.server.requests"; + private final FaultyWebFluxTagsProvider tagsProvider = new FaultyWebFluxTagsProvider(); + private SimpleMeterRegistry registry; private MetricsWebFilter webFilter; @@ -51,7 +56,7 @@ class MetricsWebFilterTests { void setup() { MockClock clock = new MockClock(); this.registry = new SimpleMeterRegistry(SimpleConfig.DEFAULT, clock); - this.webFilter = new MetricsWebFilter(this.registry, new DefaultWebFluxTagsProvider(true), REQUEST_METRICS_NAME, + this.webFilter = new MetricsWebFilter(this.registry, this.tagsProvider, REQUEST_METRICS_NAME, AutoTimer.ENABLED); } @@ -116,6 +121,14 @@ class MetricsWebFilterTests { assertThat(this.registry.get(REQUEST_METRICS_NAME).tag("status", "200").timer().count()).isEqualTo(2); } + @Test + void whenMetricsRecordingFailsThenExchangeFilteringSucceeds() { + MockServerWebExchange exchange = createExchange("/projects/spring-boot", "/projects/{project}"); + this.tagsProvider.failOnce(); + this.webFilter.filter(exchange, (serverWebExchange) -> exchange.getResponse().setComplete()) + .block(Duration.ofSeconds(30)); + } + private MockServerWebExchange createExchange(String path, String pathPattern) { PathPatternParser parser = new PathPatternParser(); MockServerWebExchange exchange = MockServerWebExchange.from(MockServerHttpRequest.get(path).build()); @@ -127,4 +140,26 @@ class MetricsWebFilterTests { assertThat(this.registry.get(REQUEST_METRICS_NAME).tag(tagKey, tagValue).timer().count()).isEqualTo(1); } + class FaultyWebFluxTagsProvider extends DefaultWebFluxTagsProvider { + + private volatile AtomicBoolean fail = new AtomicBoolean(false); + + FaultyWebFluxTagsProvider() { + super(true); + } + + @Override + public Iterable httpRequestTags(ServerWebExchange exchange, Throwable exception) { + if (this.fail.compareAndSet(true, false)) { + throw new RuntimeException(); + } + return super.httpRequestTags(exchange, exception); + } + + void failOnce() { + this.fail.set(true); + } + + } + } diff --git a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/FaultyWebMvcTagsProvider.java b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/FaultyWebMvcTagsProvider.java new file mode 100644 index 00000000000..111082fdf10 --- /dev/null +++ b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/FaultyWebMvcTagsProvider.java @@ -0,0 +1,61 @@ +/* + * Copyright 2012-2021 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.springframework.boot.actuate.metrics.web.servlet; + +import java.util.concurrent.atomic.AtomicBoolean; + +import javax.servlet.http.HttpServletRequest; +import javax.servlet.http.HttpServletResponse; + +import io.micrometer.core.instrument.Tag; + +/** + * {@link WebMvcTagsProvider} used for testing that can be configured to fail when getting + * tags or long task tags. + * + * @author Andy Wilkinson + */ +class FaultyWebMvcTagsProvider extends DefaultWebMvcTagsProvider { + + private volatile AtomicBoolean fail = new AtomicBoolean(false); + + FaultyWebMvcTagsProvider() { + super(true); + } + + @Override + public Iterable getTags(HttpServletRequest request, HttpServletResponse response, Object handler, + Throwable exception) { + if (this.fail.compareAndSet(true, false)) { + throw new RuntimeException(); + } + return super.getTags(request, response, handler, exception); + } + + @Override + public Iterable getLongRequestTags(HttpServletRequest request, Object handler) { + if (this.fail.compareAndSet(true, false)) { + throw new RuntimeException(); + } + return super.getLongRequestTags(request, handler); + } + + void failOnce() { + this.fail.set(true); + } + +} diff --git a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptorTests.java b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptorTests.java index 1279f3131a8..68420af8b95 100644 --- a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptorTests.java +++ b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/LongTaskTimingHandlerInterceptorTests.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2019 the original author or authors. + * Copyright 2012-2021 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -19,6 +19,7 @@ package org.springframework.boot.actuate.metrics.web.servlet; import java.util.concurrent.Callable; import java.util.concurrent.CompletableFuture; import java.util.concurrent.CyclicBarrier; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicReference; import io.micrometer.core.annotation.Timed; @@ -76,6 +77,9 @@ class LongTaskTimingHandlerInterceptorTests { @Autowired private CyclicBarrier callableBarrier; + @Autowired + private FaultyWebMvcTagsProvider tagsProvider; + private MockMvc mvc; @BeforeEach @@ -117,6 +121,26 @@ class LongTaskTimingHandlerInterceptorTests { .isEqualTo(0); } + @Test + void whenMetricsRecordingFailsResponseIsUnaffected() throws Exception { + this.tagsProvider.failOnce(); + AtomicReference result = new AtomicReference<>(); + Thread backgroundRequest = new Thread(() -> { + try { + result.set( + this.mvc.perform(get("/api/c1/callable/10")).andExpect(request().asyncStarted()).andReturn()); + } + catch (Exception ex) { + fail("Failed to execute async request", ex); + } + }); + backgroundRequest.start(); + this.callableBarrier.await(10, TimeUnit.SECONDS); + this.callableBarrier.await(10, TimeUnit.SECONDS); + backgroundRequest.join(); + this.mvc.perform(asyncDispatch(result.get())).andExpect(status().isOk()); + } + @Configuration(proxyBeanMethods = false) @EnableWebMvc @Import(Controller1.class) @@ -138,13 +162,17 @@ class LongTaskTimingHandlerInterceptorTests { } @Bean - WebMvcConfigurer handlerInterceptorConfigurer(MeterRegistry meterRegistry) { + FaultyWebMvcTagsProvider webMvcTagsProvider() { + return new FaultyWebMvcTagsProvider(); + } + + @Bean + WebMvcConfigurer handlerInterceptorConfigurer(MeterRegistry meterRegistry, WebMvcTagsProvider tagsProvider) { return new WebMvcConfigurer() { @Override public void addInterceptors(InterceptorRegistry registry) { - registry.addInterceptor( - new LongTaskTimingHandlerInterceptor(meterRegistry, new DefaultWebMvcTagsProvider())); + registry.addInterceptor(new LongTaskTimingHandlerInterceptor(meterRegistry, tagsProvider)); } }; diff --git a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilterTests.java b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilterTests.java index 97288459d5e..db2af3bd3e9 100644 --- a/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilterTests.java +++ b/spring-boot-project/spring-boot-actuator/src/test/java/org/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilterTests.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2020 the original author or authors. + * Copyright 2012-2021 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -121,6 +121,9 @@ class WebMvcMetricsFilterTests { @Qualifier("completableFutureBarrier") private CyclicBarrier completableFutureBarrier; + @Autowired + private FaultyWebMvcTagsProvider tagsProvider; + @BeforeEach void setupMockMvc() { this.mvc = MockMvcBuilders.webAppContextSetup(this.context) @@ -192,6 +195,12 @@ class WebMvcMetricsFilterTests { .isEqualTo(1L); } + @Test + void whenMetricsRecordingFailsResponseIsUnaffected() throws Exception { + this.tagsProvider.failOnce(); + this.mvc.perform(get("/api/c1/10")).andExpect(status().isOk()); + } + @Test void anonymousError() { try { @@ -363,9 +372,14 @@ class WebMvcMetricsFilterTests { } @Bean - WebMvcMetricsFilter webMetricsFilter(MeterRegistry registry, WebApplicationContext ctx) { - return new WebMvcMetricsFilter(registry, new DefaultWebMvcTagsProvider(true), "http.server.requests", - AutoTimer.ENABLED); + WebMvcMetricsFilter webMetricsFilter(MeterRegistry registry, FaultyWebMvcTagsProvider tagsProvider, + WebApplicationContext ctx) { + return new WebMvcMetricsFilter(registry, tagsProvider, "http.server.requests", AutoTimer.ENABLED); + } + + @Bean + FaultyWebMvcTagsProvider faultyWebMvcTagsProvider() { + return new FaultyWebMvcTagsProvider(); } }