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 521532c3e9..357ca2f760 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 @@ -23,6 +23,8 @@ import java.util.concurrent.TimeUnit; import io.micrometer.core.annotation.Timed; 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; @@ -49,6 +51,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; @@ -98,13 +102,19 @@ public class MetricsWebFilter implements WebFilter { } private void record(ServerWebExchange exchange, Throwable cause, long start) { - cause = (cause != null) ? cause : exchange.getAttribute(ErrorAttributes.ERROR_ATTRIBUTE); - Object handler = exchange.getAttribute(HandlerMapping.BEST_MATCHING_HANDLER_ATTRIBUTE); - Set annotations = getTimedAnnotations(handler); - Iterable tags = this.tagsProvider.httpRequestTags(exchange, cause); - long duration = System.nanoTime() - start; - AutoTimer.apply(this.autoTimer, this.metricName, annotations, - (builder) -> builder.tags(tags).register(this.registry).record(duration, TimeUnit.NANOSECONDS)); + try { + cause = (cause != null) ? cause : exchange.getAttribute(ErrorAttributes.ERROR_ATTRIBUTE); + Object handler = exchange.getAttribute(HandlerMapping.BEST_MATCHING_HANDLER_ATTRIBUTE); + Set annotations = getTimedAnnotations(handler); + Iterable tags = this.tagsProvider.httpRequestTags(exchange, cause); + long duration = System.nanoTime() - start; + AutoTimer.apply(this.autoTimer, this.metricName, annotations, + (builder) -> builder.tags(tags).register(this.registry).record(duration, TimeUnit.NANOSECONDS)); + } + catch (Exception ex) { + logger.warn("Failed to record timer metrics", ex); + // Allow exchange to continue, unaffected by metrics problem + } } private Set getTimedAnnotations(Object handler) { 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 524a09b449..7f5be970bb 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 f633a652af..6a56195ac0 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 @@ -30,6 +30,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.boot.actuate.metrics.annotation.TimedAnnotations; @@ -52,6 +54,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; @@ -127,11 +131,17 @@ 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(); - AutoTimer.apply(this.autoTimer, this.metricName, annotations, - (builder) -> timerSample.stop(getTimer(builder, handler, request, response, exception))); + try { + Object handler = getHandler(request); + Set annotations = getTimedAnnotations(handler); + Timer.Sample timerSample = timingContext.getTimerSample(); + AutoTimer.apply(this.autoTimer, this.metricName, annotations, + (builder) -> 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 + } } private Object getHandler(HttpServletRequest request) { 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 1dc4819176..9ce605634b 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 @@ -18,9 +18,11 @@ package org.springframework.boot.actuate.metrics.web.reactive.server; import java.io.EOFException; import java.time.Duration; +import java.util.concurrent.atomic.AtomicBoolean; import io.micrometer.core.annotation.Timed; 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; @@ -35,6 +37,7 @@ import org.springframework.mock.web.server.MockServerWebExchange; import org.springframework.util.ReflectionUtils; import org.springframework.web.method.HandlerMethod; 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; @@ -51,6 +54,8 @@ class MetricsWebFilterTests { private static final String REQUEST_METRICS_NAME_PERCENTILE = REQUEST_METRICS_NAME + ".percentile"; + private final FaultyWebFluxTagsProvider tagsProvider = new FaultyWebFluxTagsProvider(); + private SimpleMeterRegistry registry; private MetricsWebFilter webFilter; @@ -59,7 +64,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); } @@ -208,6 +213,14 @@ class MetricsWebFilterTests { assertThat(this.registry.get(REQUEST_METRICS_NAME_PERCENTILE).tag("phi", "0.5").gauge().value()).isNotZero(); } + @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 createTimedHandlerMethodExchange(String methodName) { MockServerWebExchange exchange = createExchange("/projects/spring-boot", "/projects/{project}"); exchange.getAttributes().put(HandlerMapping.BEST_MATCHING_HANDLER_ATTRIBUTE, @@ -245,4 +258,26 @@ class MetricsWebFilterTests { } + 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 0000000000..111082fdf1 --- /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 1279f3131a..68420af8b9 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 419d913c3a..2fd6774145 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 @@ -122,6 +122,9 @@ class WebMvcMetricsFilterTests { @Qualifier("completableFutureBarrier") private CyclicBarrier completableFutureBarrier; + @Autowired + private FaultyWebMvcTagsProvider tagsProvider; + @BeforeEach void setupMockMvc() { this.mvc = MockMvcBuilders.webAppContextSetup(this.context) @@ -193,6 +196,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 { @@ -365,9 +374,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(); } }