Log metrics recording failures in CountedAspect and TimedAspect (#5841)

This commit also prevents metrics recording failures from interfering with application flow in CountedAspect. See gh-5820 Signed-off-by: Johnny Lim <[email protected]>
micrometer-metrics · Feb 7, 2025 · b0fce79 · b0fce79
1 parent c91fb51
commit b0fce79
Show file tree

Hide file tree

Showing 4 changed files with 77 additions and 16 deletions.
diff --git a/micrometer-core/src/main/java/io/micrometer/core/aop/CountedAspect.java b/micrometer-core/src/main/java/io/micrometer/core/aop/CountedAspect.java
@@ -79,7 +79,7 @@
 @NonNullApi
 public class CountedAspect {
 
-    private static final WarnThenDebugLogger joinPointTagsFunctionLogger = new WarnThenDebugLogger(CountedAspect.class);
+    private static final WarnThenDebugLogger WARN_THEN_DEBUG_LOGGER = new WarnThenDebugLogger(CountedAspect.class);
 
     private static final Predicate<ProceedingJoinPoint> DONT_SKIP_ANYTHING = pjp -> false;
 
@@ -180,7 +180,7 @@ private Function<ProceedingJoinPoint, Iterable<Tag>> makeSafe(
                 return function.apply(pjp);
             }
             catch (Throwable t) {
-                joinPointTagsFunctionLogger
+                WARN_THEN_DEBUG_LOGGER
                     .log("Exception thrown from the tagsBasedOnJoinPoint function configured on CountedAspect.", t);
                 return Tags.empty();
             }
@@ -283,16 +283,21 @@ else if (!counted.recordFailuresOnly()) {
     }
 
     private void record(ProceedingJoinPoint pjp, Counted counted, String exception, String result) {
-        Counter.Builder builder = Counter.builder(counted.value())
-            .description(counted.description().isEmpty() ? null : counted.description())
-            .tags(counted.extraTags())
-            .tag(EXCEPTION_TAG, exception)
-            .tag(RESULT_TAG, result)
-            .tags(tagsBasedOnJoinPoint.apply(pjp));
-        if (meterTagAnnotationHandler != null) {
-            meterTagAnnotationHandler.addAnnotatedParameters(builder, pjp);
+        try {
+            Counter.Builder builder = Counter.builder(counted.value())
+                .description(counted.description().isEmpty() ? null : counted.description())
+                .tags(counted.extraTags())
+                .tag(EXCEPTION_TAG, exception)
+                .tag(RESULT_TAG, result)
+                .tags(tagsBasedOnJoinPoint.apply(pjp));
+            if (meterTagAnnotationHandler != null) {
+                meterTagAnnotationHandler.addAnnotatedParameters(builder, pjp);
+            }
+            builder.register(registry).increment();
+        }
+        catch (Throwable ex) {
+            WARN_THEN_DEBUG_LOGGER.log("Failed to record.", ex);
         }
-        builder.register(registry).increment();
     }
 
     /**

diff --git a/micrometer-core/src/main/java/io/micrometer/core/aop/TimedAspect.java b/micrometer-core/src/main/java/io/micrometer/core/aop/TimedAspect.java
@@ -90,7 +90,7 @@
 @Incubating(since = "1.0.0")
 public class TimedAspect {
 
-    private static final WarnThenDebugLogger joinPointTagsFunctionLogger = new WarnThenDebugLogger(TimedAspect.class);
+    private static final WarnThenDebugLogger WARN_THEN_DEBUG_LOGGER = new WarnThenDebugLogger(TimedAspect.class);
 
     private static final Predicate<ProceedingJoinPoint> DONT_SKIP_ANYTHING = pjp -> false;
 
@@ -176,7 +176,7 @@ private Function<ProceedingJoinPoint, Iterable<Tag>> makeSafe(
                 return function.apply(pjp);
             }
             catch (Throwable t) {
-                joinPointTagsFunctionLogger
+                WARN_THEN_DEBUG_LOGGER
                     .log("Exception thrown from the tagsBasedOnJoinPoint function configured on TimedAspect.", t);
                 return Tags.empty();
             }
@@ -272,7 +272,7 @@ private void record(ProceedingJoinPoint pjp, Timed timed, String metricName, Tim
             sample.stop(recordBuilder(pjp, timed, metricName, exceptionClass).register(registry));
         }
         catch (Exception e) {
-            // ignoring on purpose
+            WARN_THEN_DEBUG_LOGGER.log("Failed to record.", e);
         }
     }
 

diff --git a/...-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/CountedAspectTest.java b/...-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/CountedAspectTest.java
@@ -279,6 +279,18 @@ void countedWithoutSuccessfulMetricsWhenReturnsCompletionStageNull() {
         assertThatThrownBy(() -> meterRegistry.get("metric.none").counter()).isInstanceOf(MeterNotFoundException.class);
     }
 
+    @Test
+    void brokenExtraTags() {
+        assertThatNoException().isThrownBy(() -> countedService.brokenExtraTags());
+        assertThat(meterRegistry.getMeters()).isEmpty();
+    }
+
+    @Test
+    void brokenExtraTagsWithCompletionStage() {
+        assertThatNoException().isThrownBy(() -> asyncCountedService.brokenExtraTags().get());
+        assertThat(meterRegistry.getMeters()).isEmpty();
+    }
+
     static class CountedService {
 
         @Counted(value = "metric.none", recordFailuresOnly = true)
@@ -306,6 +318,10 @@ void emptyMetricNameWithException() {
             throw new RuntimeException("This is it");
         }
 
+        @Counted(value = "metric.broken", extraTags = { "key1" })
+        void brokenExtraTags() {
+        }
+
     }
 
     private <T> T getAdvisedService(T countedService) {
@@ -354,6 +370,11 @@ CompletableFuture<?> successButNullWithoutMetrics() {
             return null;
         }
 
+        @Counted(value = "metric.broken", extraTags = { "key1" })
+        CompletableFuture<String> brokenExtraTags() {
+            return CompletableFuture.completedFuture("test");
+        }
+
     }
 
     static class GuardedResult {

diff --git a/...es-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/TimedAspectTest.java b/...es-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/TimedAspectTest.java
@@ -44,8 +44,8 @@
 import java.util.function.Predicate;
 
 import static java.util.concurrent.CompletableFuture.supplyAsync;
-import static org.assertj.core.api.Assertions.assertThat;
-import static org.assertj.core.api.Assertions.assertThatThrownBy;
+import static org.assertj.core.api.Assertions.*;
+import static org.assertj.core.api.Assertions.assertThatNoException;
 
 class TimedAspectTest {
 
@@ -515,6 +515,32 @@ void timeMethodWithJoinPoint() {
         assertThat(registry.get("call").tag("extra", "override").timer().count()).isEqualTo(1);
     }
 
+    @Test
+    void brokenExtraTags() {
+        MeterRegistry registry = new SimpleMeterRegistry();
+
+        AspectJProxyFactory pf = new AspectJProxyFactory(new TimedService());
+        pf.addAspect(new TimedAspect(registry));
+
+        TimedService service = pf.getProxy();
+
+        assertThatNoException().isThrownBy(() -> service.brokenExtraTags());
+        assertThat(registry.getMeters()).isEmpty();
+    }
+
+    @Test
+    void brokenExtraTagsWithCompletionStage() {
+        MeterRegistry registry = new SimpleMeterRegistry();
+
+        AspectJProxyFactory pf = new AspectJProxyFactory(new AsyncTimedService());
+        pf.addAspect(new TimedAspect(registry));
+
+        AsyncTimedService service = pf.getProxy();
+
+        assertThatNoException().isThrownBy(() -> service.brokenExtraTags().get());
+        assertThat(registry.getMeters()).isEmpty();
+    }
+
     @Nested
     class MeterTagsTests {
 
@@ -846,6 +872,10 @@ void longCallRaisingError() {
             throw new TestError();
         }
 
+        @Timed(value = "broken", extraTags = { "key1" })
+        void brokenExtraTags() {
+        }
+
     }
 
     static class AsyncTimedService {
@@ -870,6 +900,11 @@ CompletableFuture<?> longCallNull() {
             return null;
         }
 
+        @Timed(value = "broken", extraTags = { "key1" })
+        CompletableFuture<String> brokenExtraTags() {
+            return CompletableFuture.completedFuture("test");
+        }
+
     }
 
     static class GuardedResult {