Showing posts with label Springframework. Show all posts
Showing posts with label Springframework. Show all posts

Friday, August 16, 2019

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


Wednesday, August 7, 2019

A Spring Boot based Log4j2 starter project


Spring Boot uses Logback as a default logging solution. In order to switch to Log4j2, there are some configurations that has to be made.

The following customized configurations provide the following features:

A Maven POM for a Spring Boot starter project
Logstash layout dependency for JSon log files to feed into ELK
Log4j configuration with MDC support
Log4j configuration produces multiple log files


<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
  <modelVersion>4.0.0</modelVersion>
  <parent>
    <groupId>com.urcorp</groupId>
    <artifactId>app-springboot-parent</artifactId>
    <version>0.0.1-SNAPSHOT</version>
  </parent>
  <artifactId>app-log4j2-starter</artifactId>
  <version>0.0.1-SNAPSHOT</version>
  <name>app-log4j2-starter</name>
  <description>Log4j2 starter</description>

  <properties>
    <log4j2-logstash-layout.version>0.19</log4j2-logstash-layout.version>
  </properties>

  <dependencies>
    <!-- logging -->
    <dependency>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-log4j2</artifactId>
    </dependency>

    <!-- logstash layout -->
    <dependency>
      <groupId>com.vlkan.log4j2</groupId>
      <artifactId>log4j2-logstash-layout</artifactId>
      <version>${log4j2-logstash-layout.version}</version>
    </dependency>
  </dependencies>

  <profiles>
    <profile>
      <id>local</id>
      <activation>
        <os>
          <family>windows</family>
        </os>
      </activation>
      <properties>
        <log.file.location>C:/app/logs</log.file.location>
      </properties>
    </profile>
    <profile>
      <id>server</id>
      <activation>
        <os>
          <family>!windows</family>
        </os>
      </activation>
      <properties>
        <log.file.location>/app/logs</log.file.location>
      </properties>
    </profile>
  </profiles>
</project>



log4j.xml


<?xml version="1.0" encoding="UTF-8"?>
<Configuration xmlns:xi="http://www.w3.org/2001/XInclude" status="DEBUG" name="log4j2-ur-app" monitorInterval="30">
  <Properties>
    <Property name="logPath">${log.file.location}</Property>
    <Property name="text.log.pattern">%d{yyyy-MM-HH:mm:ss.SSS} [%t - %X{HOSTNAME,APPLICATION,CORRELATION_ID,MESSAGE_ID}] %highlight{%level}{FATAL=bg_red, ERROR=red, WARN=yellow, INFO=green, DEBUG=blue} %c{3} - %m%n</Property>
  </Properties>

  <Appenders>
    <Console name="console" target="SYSTEM_OUT">
      <PatternLayout pattern="${text.log.pattern}" />
    </Console>

    <RollingFile name="serverJson" fileName="${logPath}/server.json"
      filePattern="${logPath}/server_%d{yyyy-MM-dd}.%i.json">
      <LogstashLayout dateTimeFormatPattern="yyyy-MM-dd'T'HH:mm:ss.SSSZZZ"
        templateUri="classpath:LogstashJsonEventLayoutV1.json" prettyPrintEnabled="false" stackTraceEnabled="true" />
      <xi:include href="log4j2-policies.xml" />
      <xi:include href="log4j2-rolloverStrategies.xml" />
    </RollingFile>

    <RollingFile name="serverText" fileName="${logPath}/server.log"
      filePattern="${logPath}/server_%d{yyyy-MM-dd}.log">
      <PatternLayout pattern="${text.log.pattern}" />
      <xi:include href="log4j2-policies.xml" />
      <xi:include href="log4j2-rolloverStrategies.xml" />
    </RollingFile>

    <RollingFile name="exceptionText" fileName="${logPath}/exception.log"
      filePattern="${logPath}/exception_%d{yyyy-MM-dd}.log">
      <Filters>
        <ThresholdFilter level="WARN" onMatch="ACCEPT" />
      </Filters>
      <PatternLayout pattern="${text.log.pattern}" />
      <xi:include href="log4j2-policies.xml" />
      <xi:include href="log4j2-rolloverStrategies.xml" />
    </RollingFile>

    <RollingFile name="eventText" fileName="${logPath}/event.log"
      filePattern="${logPath}/event_%d{yyyy-MM-dd}.log">
      <PatternLayout pattern="${text.log.pattern}" />
      <xi:include href="log4j2-policies.xml" />
      <xi:include href="log4j2-rolloverStrategies.xml" />
    </RollingFile>

    <RollingFile name="statsText" fileName="${logPath}/stats.log"
      filePattern="${logPath}/stats_%d{yyyy-MM-dd}.log">
      <PatternLayout pattern="${text.log.pattern}" />
      <xi:include href="log4j2-policies.xml" />
      <xi:include href="log4j2-rolloverStrategies.xml" />
    </RollingFile>

    <RollingFile name="perfText" fileName="${logPath}/perf.log"
      filePattern="${logPath}/perf_%d{yyyy-MM-dd}.log">
      <PatternLayout pattern="${text.log.pattern}" />
      <xi:include href="log4j2-policies.xml" />
      <xi:include href="log4j2-rolloverStrategies.xml" />
    </RollingFile>

    <RollingFile name="sqlText" fileName="${logPath}/sql.log"
      filePattern="${logPath}/sql_%d{yyyy-MM-dd}.log">
      <PatternLayout pattern="${text.log.pattern}" />
      <xi:include href="log4j2-policies.xml" />
      <xi:include href="log4j2-rolloverStrategies.xml" />
    </RollingFile>
  </Appenders>

  <Loggers>
    <Root level="info" additivity="false">
      <AppenderRef ref="console" />
      <AppenderRef ref="serverText" />
      <AppenderRef ref="serverJson" />
      <AppenderRef ref="exceptionText" />
    </Root>

    <logger name="EVENT" level="info" additivity="false">
      <AppenderRef ref="eventText" />
      <AppenderRef ref="console" />
    </logger>
    <logger name="STATISTICS" level="info" additivity="false">
      <AppenderRef ref="statsText" />
    </logger>
    <logger name="PERFORMANCE" level="info" additivity="false">
      <AppenderRef ref="perfText" />
    </logger>

    <logger name="SQL" level="info" additivity="false">
      <AppenderRef ref="sqlText" />
      <AppenderRef ref="console" />
    </logger>
    <logger name="com.zaxxer.hikari" level="debug" additivity="false">
      <AppenderRef ref="sqlText" />
    </logger>
    <logger name="java.sql" level="debug" additivity="false">
      <AppenderRef ref="sqlText" />
    </logger>
    <logger name="org.apache.ibatis" level="debug" additivity="false">
      <AppenderRef ref="sqlText" />
    </logger>
    <logger name="org.mybatis" level="debug" additivity="false">
      <AppenderRef ref="sqlText" />
    </logger>
    <logger name="com.urcorp.dao.generated.mapper" level="trace" additivity="false">
      <AppenderRef ref="sqlText" />
    </logger>
    <logger name="org.springframework.jdbc.core" level="trace" additivity="true">
      <AppenderRef ref="sqlText" />
    </logger>
  </Loggers>

</Configuration>


log4j2-policies.xml


<?xml version="1.0" encoding="UTF-8"?>
<Policies>
  <OnStartupTriggeringPolicy />
  <SizeBasedTriggeringPolicy size="300 MB" />
  <TimeBasedTriggeringPolicy interval="1"
    modulate="true" />
</Policies>


log4j2-rolloverStrategies.xml


<?xml version="1.0" encoding="UTF-8"?>
<DefaultRolloverStrategy>
  <Delete basePath="${logPath}" maxDepth="2">
    <IfFileName glob="*.(json|log)" />
    <IfLastModified age="7d" />
  </Delete>
</DefaultRolloverStrategy>




package com.urcorp.common.logging;

public enum LogFileTypes {
  EXCEPTION("EXCEPTION."),
  EVENT("EVENT."),
  PERFORMANCE("PERFORMANCE."),
  SERVER("SERVER."),
  SQL("SQL."),
  STATISTICS("STATISTICS.");

  private final String group;

  private LogFileTypes(final String group) {
    this.code = group;
  }

  public String group() {
    return group;
  }
}