Catch runtime exception thrown from pjp function in aspects (#5585)

Before, this would result in an exception bubbling up to user code (CountedAspect) or the metric recording not happening (TimedAspect). This changes the behavior to consistently record the metric without the tags from the pjp function if it throws. This aligns the behavior between the two and is safer (in the case of CountedAspect). An alternative that would also be safe and consistent would be to align to the existing behavior of TimedAspect - not recording any metric when an exception is thrown.

Author: shakuzen

micrometer-core/src/main/java/io/micrometer/core/aop/CountedAspect.java

@@ -17,6 +17,7 @@
 
 import io.micrometer.common.lang.NonNullApi;
 import io.micrometer.common.lang.Nullable;
+import io.micrometer.common.util.internal.logging.WarnThenDebugLogger;
 import io.micrometer.core.annotation.Counted;
 import io.micrometer.core.instrument.*;
 import org.aspectj.lang.ProceedingJoinPoint;
@@ -75,6 +76,8 @@
 @NonNullApi
 public class CountedAspect {
 
+    private static final WarnThenDebugLogger joinPointTagsFunctionLogger = new WarnThenDebugLogger(CountedAspect.class);
+
     private static final Predicate<ProceedingJoinPoint> DONT_SKIP_ANYTHING = pjp -> false;
 
     public final String DEFAULT_EXCEPTION_TAG_VALUE = "none";
@@ -161,10 +164,24 @@ public CountedAspect(MeterRegistry registry, Predicate<ProceedingJoinPoint> shou
     public CountedAspect(MeterRegistry registry, Function<ProceedingJoinPoint, Iterable<Tag>> tagsBasedOnJoinPoint,
             Predicate<ProceedingJoinPoint> shouldSkip) {
         this.registry = registry;
-        this.tagsBasedOnJoinPoint = tagsBasedOnJoinPoint;
+        this.tagsBasedOnJoinPoint = makeSafe(tagsBasedOnJoinPoint);
         this.shouldSkip = shouldSkip;
     }
 
+    private Function<ProceedingJoinPoint, Iterable<Tag>> makeSafe(
+            Function<ProceedingJoinPoint, Iterable<Tag>> function) {
+        return pjp -> {
+            try {
+                return function.apply(pjp);
+            }
+            catch (Throwable t) {
+                joinPointTagsFunctionLogger
+                    .log("Exception thrown from the tagsBasedOnJoinPoint function configured on CountedAspect.", t);
+                return Tags.empty();
+            }
+        };
+    }
+
     /**
      * Intercept methods annotated with the {@link Counted} annotation and expose a few
      * counters about their execution status. By default, this aspect records both failed

micrometer-core/src/main/java/io/micrometer/core/aop/TimedAspect.java

@@ -17,6 +17,7 @@
 
 import io.micrometer.common.lang.NonNullApi;
 import io.micrometer.common.lang.Nullable;
+import io.micrometer.common.util.internal.logging.WarnThenDebugLogger;
 import io.micrometer.core.annotation.Incubating;
 import io.micrometer.core.annotation.Timed;
 import io.micrometer.core.instrument.*;
@@ -83,6 +84,8 @@
 @Incubating(since = "1.0.0")
 public class TimedAspect {
 
+    private static final WarnThenDebugLogger joinPointTagsFunctionLogger = new WarnThenDebugLogger(TimedAspect.class);
+
     private static final Predicate<ProceedingJoinPoint> DONT_SKIP_ANYTHING = pjp -> false;
 
     public static final String DEFAULT_METRIC_NAME = "method.timed";
@@ -156,10 +159,24 @@ public TimedAspect(MeterRegistry registry, Predicate<ProceedingJoinPoint> should
     public TimedAspect(MeterRegistry registry, Function<ProceedingJoinPoint, Iterable<Tag>> tagsBasedOnJoinPoint,
             Predicate<ProceedingJoinPoint> shouldSkip) {
         this.registry = registry;
-        this.tagsBasedOnJoinPoint = tagsBasedOnJoinPoint;
+        this.tagsBasedOnJoinPoint = makeSafe(tagsBasedOnJoinPoint);
         this.shouldSkip = shouldSkip;
     }
 
+    private Function<ProceedingJoinPoint, Iterable<Tag>> makeSafe(
+            Function<ProceedingJoinPoint, Iterable<Tag>> function) {
+        return pjp -> {
+            try {
+                return function.apply(pjp);
+            }
+            catch (Throwable t) {
+                joinPointTagsFunctionLogger
+                    .log("Exception thrown from the tagsBasedOnJoinPoint function configured on TimedAspect.", t);
+                return Tags.empty();
+            }
+        };
+    }
+
     @Around("@within(io.micrometer.core.annotation.Timed)")
     @Nullable
     public Object timedClass(ProceedingJoinPoint pjp) throws Throwable {

micrometer-core/src/test/java/io/micrometer/core/aop/CountedAspectTest.java

@@ -15,16 +15,19 @@
  */
 package io.micrometer.core.aop;
 
+import io.micrometer.core.Issue;
 import io.micrometer.core.annotation.Counted;
 import io.micrometer.core.instrument.Counter;
 import io.micrometer.core.instrument.MeterRegistry;
+import io.micrometer.core.instrument.Tag;
 import io.micrometer.core.instrument.search.MeterNotFoundException;
 import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
 import org.aspectj.lang.ProceedingJoinPoint;
 import org.junit.jupiter.api.Test;
 import org.springframework.aop.aspectj.annotation.AspectJProxyFactory;
 
 import java.util.concurrent.CompletableFuture;
+import java.util.function.Function;
 import java.util.function.Predicate;
 
 import static java.util.concurrent.CompletableFuture.supplyAsync;
@@ -193,6 +196,21 @@ void countedWithEmptyMetricNamesWhenCompleted() {
         assertThat(meterRegistry.get("method.counted").tag("result", "failure").counter().count()).isOne();
     }
 
+    @Test
+    @Issue("#5584")
+    void pjpFunctionThrows() {
+        CountedService countedService = getAdvisedService(new CountedService(),
+                new CountedAspect(meterRegistry, (Function<ProceedingJoinPoint, Iterable<Tag>>) jp -> {
+                    throw new RuntimeException("test");
+                }));
+        countedService.succeedWithMetrics();
+
+        Counter counter = meterRegistry.get("metric.success").tag("extra", "tag").tag("result", "success").counter();
+
+        assertThat(counter.count()).isOne();
+        assertThat(counter.getId().getDescription()).isNull();
+    }
+
     static class CountedService {
 
         @Counted(value = "metric.none", recordFailuresOnly = true)

micrometer-core/src/test/java/io/micrometer/core/aop/TimedAspectTest.java

@@ -18,11 +18,10 @@
 import io.micrometer.common.annotation.ValueExpressionResolver;
 import io.micrometer.common.annotation.ValueResolver;
 import io.micrometer.common.lang.NonNull;
+import io.micrometer.core.Issue;
 import io.micrometer.core.annotation.Timed;
-import io.micrometer.core.instrument.LongTaskTimer;
+import io.micrometer.core.instrument.*;
 import io.micrometer.core.instrument.Meter.Id;
-import io.micrometer.core.instrument.MeterRegistry;
-import io.micrometer.core.instrument.Timer;
 import io.micrometer.core.instrument.distribution.DistributionStatisticConfig;
 import io.micrometer.core.instrument.distribution.pause.PauseDetector;
 import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
@@ -36,6 +35,7 @@
 import javax.annotation.Nonnull;
 import java.util.concurrent.CompletableFuture;
 import java.util.concurrent.CompletionException;
+import java.util.function.Function;
 import java.util.function.Predicate;
 
 import static java.util.concurrent.CompletableFuture.supplyAsync;
@@ -377,6 +377,23 @@ void timeClassFailure() {
         assertThat(failingRegistry.getMeters()).isEmpty();
     }
 
+    @Test
+    @Issue("#5584")
+    void pjpFunctionThrows() {
+        MeterRegistry registry = new SimpleMeterRegistry();
+
+        AspectJProxyFactory pf = new AspectJProxyFactory(new TimedService());
+        pf.addAspect(new TimedAspect(registry, (Function<ProceedingJoinPoint, Iterable<Tag>>) jp -> {
+            throw new RuntimeException("test");
+        }));
+
+        TimedService service = pf.getProxy();
+
+        service.call();
+
+        assertThat(registry.get("call").tag("extra", "tag").timer().count()).isEqualTo(1);
+    }
+
     @Nested
     class MeterTagsTests {