Prevent metrics failures from adversely affecting web responses

Fixes gh-24151

Author: wilkinsona

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 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 @@
 @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 @@ private void onError(ServerWebExchange exchange, long start, Throwable cause) {
 	}
 
 	private void record(ServerWebExchange exchange, long start, Throwable cause) {
-		Iterable<Tag> tags = this.tagsProvider.httpRequestTags(exchange, cause);
-		this.autoTimer.builder(this.metricName).tags(tags).register(this.registry).record(System.nanoTime() - start,
-				TimeUnit.NANOSECONDS);
+		try {
+			Iterable<Tag> 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
+		}
 	}
 
 }

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.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 @@
  */
 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 @@ private void startAndAttachTimingContext(HttpServletRequest request, Object hand
 	private Collection<LongTaskTimer.Sample> getLongTaskTimerSamples(HttpServletRequest request, Object handler,
 			Set<Timed> annotations) {
 		List<LongTaskTimer.Sample> samples = new ArrayList<>();
-		annotations.stream().filter(Timed::longTask).forEach((annotation) -> {
-			Iterable<Tag> 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<Tag> 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;
 	}
 

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.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 @@
  */
 public class WebMvcMetricsFilter extends OncePerRequestFilter {
 
+	private static final Log logger = LogFactory.getLog(WebMvcMetricsFilter.class);
+
 	private final MeterRegistry registry;
 
 	private final WebMvcTagsProvider tagsProvider;
@@ -120,21 +124,27 @@ private TimingContext startAndAttachTimingContext(HttpServletRequest request) {
 
 	private void record(TimingContext timingContext, HttpServletRequest request, HttpServletResponse response,
 			Throwable exception) {
-		Object handler = getHandler(request);
-		Set<Timed> 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<Timed> 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
+		}
 	}
 
 	private Object getHandler(HttpServletRequest request) {

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.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 @@ void trailingSlashShouldNotRecordDuplicateMetrics() {
 		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 @@ private void assertMetricsContainsTag(String tagKey, String tagValue) {
 		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<Tag> 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);
+		}
+
+	}
+
 }

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<Tag> 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<Tag> 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);
+	}
+
+}

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 @@
 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 @@ void asyncCallableRequest() throws Exception {
 				.isEqualTo(0);
 	}
 
+	@Test
+	void whenMetricsRecordingFailsResponseIsUnaffected() throws Exception {
+		this.tagsProvider.failOnce();
+		AtomicReference<MvcResult> 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 @@ CyclicBarrier callableBarrier() {
 		}
 
 		@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));
 				}
 
 			};