Spring Aspects - Logging debugging information of service methods

Method Tracing Aspects

Following aspects enable method tracing by using Spring AOP. The following information will be gathered and logged:

1. Types and values of input parameters
2. Type and value of return object
3. Types and details of exceptions

@Configuration @Aspect public class MethodTracingAspect {   private static Logger logger = LoggerFactory.getLogger(MethodTracingAspect.class);   @Autowired private LoggerCache loggerCache;   @PostConstruct   protected void init() {     logger.warn("###-AOP-### DebuggableAspect initialized...");   }   @Before(       "(com.yourcorp.common.aspect.CommonPointcut.servicePackageMethodDebugEnabled() "           + "|| com.yourcorp.common.aspect.CommonPointcut.implPackageMethodDebugEnabled()) && "           + "!com.yourcorp.common.aspect.CommonPointcut.nonTraceableAnnotationEnabled()")   public void logDebugInformationMethodBeforeEntering(JoinPoint joinPoint) {     final Logger mLogger = loggerCache.getLogger(joinPoint);     mLogger.debug(         "Entering class:{} - method : {} with input parameters {}",         joinPoint.getTarget().getClass().getSimpleName(),         joinPoint.getSignature().getName(),         joinPoint.getArgs());   }   @AfterReturning(     value =         "(com.yourcorp.common.aspect.CommonPointcut.servicePackageMethodDebugEnabled() "             + "|| com.yourcorp.common.aspect.CommonPointcut.implPackageMethodDebugEnabled()) && "             + "!com.yourcorp.common.aspect.CommonPointcut.nonTraceableAnnotationEnabled()",     returning = "result"   )   public void logDebugInformationMethodAfterReturning(JoinPoint joinPoint, Object result) {     final Logger mLogger = loggerCache.getLogger(joinPoint);     mLogger.debug(         "Returning from class:{} - method : {} with return type: {} - value {}",         joinPoint.getTarget().getClass().getSimpleName(),         joinPoint.getSignature().getName(),         ((MethodSignature) (joinPoint.getSignature())).getReturnType().getSimpleName(),         result);   } } @Configuration @Aspect public class ExceptionHandlingAspect {   @Autowired private LoggerCache loggerCache;   @AfterThrowing(     value = "com.yourcorp.common.aspect.CommonPointcut.servicePackageMethodDebugEnabled()",     throwing = "exception"   )   public void logRecoverableFailureException(       JoinPoint joinPoint, RecoverableFailureException exception) {     Logger logger = loggerCache.getLogger(joinPoint);     logger.warn("\t " + exception.getFullMessage(), exception);   }   @AfterThrowing(     value = "com.yourcorp.common.aspect.CommonPointcut.servicePackageMethodDebugEnabled()",     throwing = "exception"   )   public void logUnRecoverableFailureException(       JoinPoint joinPoint, UnRecoverableFailureException exception) {     Logger logger = loggerCache.getLogger(joinPoint);     logger.error("\t " + exception.getFullMessage(), exception);   } }

Common Pointcuts

import org.aspectj.lang.annotation.Pointcut; /**  * The pointcuts defined here are the service classes most likely logging, metrics and tracing  * concerns will be the applied.  */ @Aspect public class CommonPointcut {   // All method in service packages   @Pointcut("execution(* com.yourcorp.app..service.*.*(..))")   public void servicePackageMethodDebugEnabled() {     // no implementation.   }   // All method in impl packages   @Pointcut("execution(* com.yourcorp.app..impl..*.*(..))")   public void implPackageMethodDebugEnabled() {     // no implementation.   }   // Methods with @MethodDebuggingDisable   @Pointcut("@annotation(com.yourcorp.app.common.aspect.debug.MethodDebuggingDisable))")   public void nonTraceableAnnotationEnabled() {     // no implementation.   } }

Custom Annotation

/**  * If a method is very sensitive to  */ @Target({ElementType.METHOD}) @Retention(RetentionPolicy.RUNTIME) public @interface MethodTracingDisable {}

Logger Cache

/**  * Cache logger according to type, the logger search operation is expensive.  */ @Service public class LoggerCacheImpl implements LoggerCache {   private Map<Class<?>, Logger> loggerCache = new ConcurrentReferenceHashMap<>();   @Override   @MethodTracingDisable   public Logger getLogger(JoinPoint joinPoint) {     final Class<?> clazz = joinPoint.getTarget().getClass();     return loggerCache.computeIfAbsent(clazz, e -> LoggerFactory.getLogger(e));   } }

A Micrometer Aspect to collect count and timer of method execution

The Aspect could be used in a Spring Boot based application, any method that is labeled with Micrometer's @Timed annotation will be intercepted, the following metrics will be collected against the method:

1. Elapsed time of method execution
2. Total count of method execution
3. Success count of method execution
4. Failure count of method execution

The Micrometer meters are cached so that they could be re-used for the same method.

Aspect

package com.yourcorp.common.statistics; import com.yourcorp.common.common.aspect.util.StatisticsCache; import io.micrometer.core.instrument.Clock; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Timer; import java.util.concurrent.TimeUnit; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.context.annotation.Configuration; @Configuration @Aspect public class TimedAndCountedAspect {   private static final Logger LOGGER = LoggerFactory.getLogger(TimedAndCountedAspect.class);   private final MeterRegistry registry;   private final StatisticsCache staticticsCache;   private final TimeSampler timeSampler = new TimeSampler();   public TimedAndCountedAspect(MeterRegistry registry, StatisticsCache statisticsCache) {     this.registry = registry;     this.staticticsCache = statisticsCache;   }   @Around("execution (@io.micrometer.core.annotation.Timed * *.*(..))")   public Object timedMethod(ProceedingJoinPoint pjp) throws Throwable {     final Timer.Sample sample = Timer.start(registry);     timeSampler.setStart(Clock.SYSTEM.monotonicTime());     try {       final Object result = pjp.proceed();       staticticsCache.getExecutionCounter(pjp, "successCount", registry).increment();       return result;     } catch (Exception ex) {       staticticsCache.getExecutionCounter(pjp, "failCount", registry).increment();       throw ex;     } finally {       staticticsCache.getExecutionCounter(pjp, "totalCount", registry).increment();       try {         Timer timer = this.staticticsCache.getExecutionTimer(pjp, registry);         sample.stop(timer);       } catch (Exception e) {         // ignoring on purpose       }       timeSampler.setEnd(Clock.SYSTEM.monotonicTime());       if (LOGGER.isDebugEnabled()) {       LOGGER.debug(           "successCount:{}",           staticticsCache.getExecutionCounter(pjp, "successCount", registry).count());       LOGGER.debug(           "failCount:{}", staticticsCache.getExecutionCounter(pjp, "failCount", registry).count());       LOGGER.debug(           "totalCount:{}",           staticticsCache.getExecutionCounter(pjp, "totalCount", registry).count());       LOGGER.debug("timer Count:{}", this.staticticsCache.getExecutionTimer(pjp, registry).count());       LOGGER.debug(           "timer totalTime:{}",           this.staticticsCache.getExecutionTimer(pjp, registry).totalTime(TimeUnit.MILLISECONDS));       LOGGER.debug(           "timer max:{}",           this.staticticsCache.getExecutionTimer(pjp, registry).max(TimeUnit.MILLISECONDS));       LOGGER.debug(           "timer mean:{}",           this.staticticsCache.getExecutionTimer(pjp, registry).mean(TimeUnit.MILLISECONDS));       LOGGER.debug(           "gauge eclapsed time:{}",           this.staticticsCache.getElaspedTimeGauge(pjp, timeSampler, registry).value());       }     }   }   public static class TimeSampler {     private long start;     private long end;     public void setStart(long start) {       this.start = start;     }     public void setEnd(long end) {       this.end = end;     }     public double calculateEclapsedTime() {       return this.end - this.start;     }     @Override     public String toString() {       return "TimeSample [start=" + start + ", end=" + end + "]";     }   } }

MeterCache

Inside the class, the meters are built first then cached.

package com.yourcorp.common.aspect.util.impl; import com.yourcorp.common.aspect.util.StatisticsCache; import com.yourcorp.common.statistics.TimedAndCountedAspect.TimeSampler; import io.micrometer.core.annotation.Timed; import io.micrometer.core.instrument.Counter; import io.micrometer.core.instrument.Gauge; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.Tags; import io.micrometer.core.instrument.Timer; import java.lang.annotation.Annotation; import java.lang.reflect.Method; import java.time.Duration; import java.util.Map; import java.util.function.Function; import javax.validation.constraints.NotNull; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.reflect.MethodSignature; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Service; import org.springframework.util.ConcurrentReferenceHashMap; import org.springframework.validation.annotation.Validated; @Service @Validated public class StatisticsCacheImpl implements StatisticsCache {   private static final Logger LOGGER = LoggerFactory.getLogger(StatisticsCacheImpl.class);   private Map<String, Counter> counterCache = new ConcurrentReferenceHashMap<>();   private Map<String, Gauge> gaugeCache = new ConcurrentReferenceHashMap<>();   private Map<String, Timer> timerCache = new ConcurrentReferenceHashMap<>();   @Override   public Counter getExecutionCounter(       @NotNull ProceedingJoinPoint pjp,       @NotNull String counterType,       @NotNull MeterRegistry meterRegistry) {     final Timed timed = this.getTimed(pjp);     final Function<ProceedingJoinPoint, Iterable<Tag>> tagsBasedOnJoinPoint =         this.getTagsReteivingFunction();     return counterCache.computeIfAbsent(         getKey(pjp, counterType),         key ->             Counter.builder(key)                 .description(timed.description().isEmpty() ? null : timed.description())                 .tags(timed.extraTags())                 .tags(tagsBasedOnJoinPoint.apply(pjp))                 .register(meterRegistry));   }   @Override   public Timer getExecutionTimer(       @NotNull ProceedingJoinPoint pjp, @NotNull @NotNull MeterRegistry meterRegistry) {     final Timed timed = getTimed(pjp);     final Function<ProceedingJoinPoint, Iterable<Tag>> tagsBasedOnJoinPoint =         this.getTagsReteivingFunction();     return timerCache.computeIfAbsent(         getKey(pjp, "timer"),         key ->             Timer.builder(key)                 .description(timed.description().isEmpty() ? null : timed.description())                 .tags(timed.extraTags())                 .tags(tagsBasedOnJoinPoint.apply(pjp))                 .publishPercentileHistogram(timed.histogram())                 .publishPercentiles(timed.percentiles().length == 0 ? null : timed.percentiles())                 .distributionStatisticExpiry(Duration.ofHours(1))                 .register(meterRegistry));   }   private Timed getTimed(ProceedingJoinPoint pjp) {     Method method = ((MethodSignature) pjp.getSignature()).getMethod();     Timed timed = method.getAnnotation(Timed.class);     if (timed == null) {       try {         method = pjp.getTarget().getClass().getMethod(method.getName(), method.getParameterTypes());       } catch (NoSuchMethodException | SecurityException e) {         LOGGER.warn("failed to retrieve method information.", e);       }       timed = method.getAnnotation(Timed.class);       if (timed == null) {         timed =             new Timed() {               @Override               public Class<? extends Annotation> annotationType() {                 return Timed.class;               }               @Override               public String value() {                 return null;               }               @Override               public String[] extraTags() {                 return null;               }               @Override               public boolean longTask() {                 return false;               }               @Override               public double[] percentiles() {                 return null;               }               @Override               public boolean histogram() {                 return false;               }               @Override               public String description() {                 return null;               }             };       }     }     return timed;   }   private Function<ProceedingJoinPoint, Iterable<Tag>> getTagsReteivingFunction() {     return pjp ->         Tags.of(             "class",             pjp.getStaticPart().getSignature().getDeclaringTypeName(),             "method",             pjp.getStaticPart().getSignature().getName());   }   @Override   public Gauge getElaspedTimeGauge(       @NotNull ProceedingJoinPoint pjp,       @NotNull TimeSampler timeSampler,       @NotNull MeterRegistry meterRegistry) {     final Timed timed = getTimed(pjp);     final Function<ProceedingJoinPoint, Iterable<Tag>> tagsBasedOnJoinPoint =         this.getTagsReteivingFunction();     return gaugeCache.computeIfAbsent(         getKey(pjp, "gauge"),         key ->             Gauge.builder(key, timeSampler::calculateEclapsedTime)                 .description(timed.description().isEmpty() ? null : timed.description())                 .tags(timed.extraTags())                 .tags(tagsBasedOnJoinPoint.apply(pjp))                 .register(meterRegistry));   }   private String getKey(ProceedingJoinPoint pjp, String suffix) {     final String className = pjp.getStaticPart().getSignature().getDeclaringTypeName();     final String methodName = pjp.getStaticPart().getSignature().getName();     return className + "." + methodName + "." + suffix;   }   @Override   public void clear() {     this.counterCache.forEach((k, v) -> v.close());     this.counterCache.clear();     this.gaugeCache.forEach((k, v) -> v.close());     this.gaugeCache.clear();     this.timerCache.forEach((k, v) -> v.close());     this.timerCache.clear();   } }

Metrics Logging

Collected metrics could be logged into local log files by retrieving the Micrometer rate aggregations from MBean server. Spring Actuator module is required for automatic MBean server setup.

package com.yourcorp.common.statistics.jvm.impl; import java.lang.management.ManagementFactory; import java.util.Arrays; import java.util.List; import java.util.regex.Pattern; import javax.annotation.PostConstruct; import javax.management.AttributeNotFoundException; import javax.management.InstanceNotFoundException; import javax.management.MBeanException; import javax.management.MBeanServer; import javax.management.MalformedObjectNameException; import javax.management.ObjectName; import javax.management.ReflectionException; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.beans.factory.annotation.Value; import org.springframework.stereotype.Service; @Service public class MBeanAttributeLoggingManager {   private static final Logger LOGGER = LoggerFactory.getLogger(MBeanAttributeLoggingManager.class);   @Value("#{'${mbean.shortterm.attributes}'.split(',')}")   private List<String> mbeanShorttermAttributes;   @Value("#{'${mbean.midterm.attributes}'.split(',')}")   private List<String> mbeanMidtermAttributes;   @Value("#{'${mbean.longterm.attributes}'.split(',')}")   private List<String> mbeanLongtermAttributes;   @PostConstruct   private void init() {     LOGGER.debug("mbeanShorttermAttributes:{}", mbeanShorttermAttributes);   }   public void logShorttermAttributes() {     this.logMBeanInfo(mbeanShorttermAttributes);   }   public void logMidtermAttributes() {     this.logMBeanInfo(mbeanMidtermAttributes);   }   public void logLongtermAttributes() {     this.logMBeanInfo(mbeanLongtermAttributes);   }   private void logMBeanInfo(List<String> attributes) {     final MBeanServer mBeanServer = ManagementFactory.getPlatformMBeanServer();     for (String attribute : attributes) {       LOGGER.info("attribute:{}", attribute);       String[] nameTokens = attribute.split(Pattern.quote("|"));       LOGGER.info("nameTokens:{}", Arrays.asList(nameTokens));       ObjectName mxBeanName = null;       try {         mxBeanName = new ObjectName(nameTokens[0]);       } catch (MalformedObjectNameException e) {         LOGGER.warn("failed to create ObjectName:" + nameTokens[0], e);       }       try {         Object attributeValue = null;         attributeValue = mBeanServer.getAttribute(mxBeanName, nameTokens[1]);         LOGGER.info("*** *** *** mbean{}:{}", attribute, attributeValue);       } catch (InstanceNotFoundException           | AttributeNotFoundException           | ReflectionException           | MBeanException e) {         LOGGER.info("failed to retrieve MBean attribute:" + attribute, e);       }     }   } }

application.properties

object.name.common.prefix=com.yourcorp.metrics:name=DelayedServiceDoWithDelay object.name.common.tags=.region.phoenix.stack.dev object.name.DelayedServiceDoWithDelayFailCount=${object.name.common.prefix}FailCount${object.name.common.tags} object.name.DelayedServiceDoWithDelayGauge=${object.name.common.prefix}Gauge${object.name.common.tags} object.name.DelayedServiceDoWithDelaySuccessCount=${object.name.common.prefix}SuccessCount${object.name.common.tags} object.name.DelayedServiceDoWithDelayTimer=${object.name.common.prefix}Timer${object.name.common.tags} object.name.DelayedServiceDoWithDelayTotalCount=${object.name.common.prefix}TotalCount${object.name.common.tags} mbean.shortterm.attributes=${object.name.DelayedServiceDoWithDelayTimer}|Mean\   ,${object.name.DelayedServiceDoWithDelayTimer}|Max\   ,${object.name.DelayedServiceDoWithDelayTimer}|Min\   ,${object.name.DelayedServiceDoWithDelayTimer}|StdDev\   ,${object.name.DelayedServiceDoWithDelayTimer}|Max\   ,${object.name.DelayedServiceDoWithDelayTimer}|50thPercentile\   ,${object.name.DelayedServiceDoWithDelayTimer}|95thPercentile\   ,${object.name.DelayedServiceDoWithDelayTimer}|99thPercentile\   ,${object.name.DelayedServiceDoWithDelayGauge}|Value\   ,${object.name.DelayedServiceDoWithDelayTotalCount}|Count\   ,${object.name.DelayedServiceDoWithDelayTotalCount}|OneMinuteRate\   ,${object.name.DelayedServiceDoWithDelaySuccessCount}|Count\   ,${object.name.DelayedServiceDoWithDelaySuccessCount}|OneMinuteRate\   ,${object.name.DelayedServiceDoWithDelayFailCount}|Count\   ,${object.name.DelayedServiceDoWithDelayFailCount}|OneMinuteRate   mbean.midterm.attributes=${object.name.DelayedServiceDoWithDelayTimer}|FiveMinuteRate\   ,${object.name.DelayedServiceDoWithDelayTotalCount}|FiveMinuteRate\   ,${object.name.DelayedServiceDoWithDelaySuccessCount}|FiveMinuteRate\   ,${object.name.DelayedServiceDoWithDelayFailCount}|FiveMinuteRate mbean.longterm.attributes=${object.name.DelayedServiceDoWithDelayTimer}|FifteenMinuteRate\   ,${object.name.DelayedServiceDoWithDelayTotalCount}|FifteenMinuteRate\   ,${object.name.DelayedServiceDoWithDelaySuccessCount}|FifteenMinuteRate\   ,${object.name.DelayedServiceDoWithDelayFailCount}|FifteenMinuteRate