From b0fce7981b7c94ba933aa493a655b8c4886df794 Mon Sep 17 00:00:00 2001 From: Johnny Lim Date: Sat, 8 Feb 2025 03:53:59 +0900 Subject: [PATCH] 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 --- .../io/micrometer/core/aop/CountedAspect.java | 27 +++++++------ .../io/micrometer/core/aop/TimedAspect.java | 6 +-- .../spring6/aop/CountedAspectTest.java | 21 ++++++++++ .../samples/spring6/aop/TimedAspectTest.java | 39 ++++++++++++++++++- 4 files changed, 77 insertions(+), 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 index fcddc4cc2b..a22b968939 100644 --- 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 DONT_SKIP_ANYTHING = pjp -> false; @@ -180,7 +180,7 @@ private Function> 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 index fc2138d839..016c88abb9 100644 --- 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 DONT_SKIP_ANYTHING = pjp -> false; @@ -176,7 +176,7 @@ private Function> 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/samples/micrometer-samples-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/CountedAspectTest.java b/samples/micrometer-samples-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/CountedAspectTest.java index 0f2e004837..3a9fa17dab 100644 --- a/samples/micrometer-samples-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/CountedAspectTest.java +++ b/samples/micrometer-samples-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 getAdvisedService(T countedService) { @@ -354,6 +370,11 @@ CompletableFuture successButNullWithoutMetrics() { return null; } + @Counted(value = "metric.broken", extraTags = { "key1" }) + CompletableFuture brokenExtraTags() { + return CompletableFuture.completedFuture("test"); + } + } static class GuardedResult { diff --git a/samples/micrometer-samples-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/TimedAspectTest.java b/samples/micrometer-samples-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/TimedAspectTest.java index 80b11cc955..70d36041ab 100644 --- a/samples/micrometer-samples-spring-framework6/src/test/java/io/micrometer/samples/spring6/aop/TimedAspectTest.java +++ b/samples/micrometer-samples-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 brokenExtraTags() { + return CompletableFuture.completedFuture("test"); + } + } static class GuardedResult {