Logging Aspect with Spring AOP

Logging is a cross-cutting concern and therefore AOP comes on. With Spring Boot it is quite easy to make AOP work and configure different aspects. Here, I will concentrate on a logger  aspect that logs the entry and exit of a method call. Additionally, the execution time is logged as well.

First, we need to clarify some terminology that comes with AOP:

  • aspect: Class containing cross-cutting concern
  • adivice: Job of an aspect
  • join point: possible point in the application where an aspect can be applied
  • pointcut: defines where an aspect is applied
  • weaving: process of applying aspects to a target object

Spring AOP aspects are woven in during runtime, i.e. during the execution of the application. AspectJ allows to weave in aspects during compile time.

Runtime weaving with Spring AOP is based on proxy usage and thus has several limitations like that private or protected methods, constructors and attributes can not be used as pointcuts. However, I think in most cases this is not a big deal. If these things should be used anyway, consider using AspectJ’s compile time weaving.

In the following,  I will quickly demonstrate how to integrate AOP with Spring and implement the a logging aspect. First of all, the aspectjweaver dependency has to be included in the pom.xml as this will provide some annotations used for defining an aspect. Its version is managed by Spring Boot.


<dependency>
<groupId>org.aspectj</groupId>
<artifactId>aspectjweaver</artifactId>
</dependency>

view raw

pom.xml

hosted with ❤ by GitHub

There are two pointcuts defined in the logger aspect, the first for  @RequestMapping and the second for @Profiled annotations. The aspect is called for all methods annotated with one of these annotations. For the case there are multiple aspects defined and triggered simultaneously, the aspect class is annotated with @Order and set to lowest precedence where with the execution order of the aspect is controlled.


@Aspect
@Order(Ordered.LOWEST_PRECEDENCE)
@Component
public class LoggerAspect {
private Logger logger;
public LoggerAspect() {
logger = LoggerFactory.getLogger(getClass());
}
@Pointcut("@annotation(org.springframework.web.bind.annotation.RequestMapping)")
public void requestMapping() {
}
@Pointcut("@annotation(com.xovis.standalone_multisensor.aspects.Profiled)")
public void profiled() {
}
@Around("requestMapping() || profiled()")
public Object profile(ProceedingJoinPoint pjp) throws Throwable {
StopWatch sw = new StopWatch();
String className = pjp.getTarget().getClass().getSimpleName();
String methodName = pjp.getSignature().getName();
String name = className + "." + methodName;
logger.debug("call " + name);
try {
sw.start();
return pjp.proceed();
} finally {
sw.stop();
logger.debug("exit " + name + " [" + sw.getTotalTimeMillis() + "ms]");
}
}
}

@Profiled is a custom annotation and is implemented as follows:


@Retention(RetentionPolicy.RUNTIME)
public @interface Profiled {
}

view raw

Profiled.java

hosted with ❤ by GitHub

The output of an intercepted method will look like this
c.x.s.aspects.LoggerAspect: call StatusController.getStatus
c.x.s.aspects.LoggerAspect: exit StatusController.getStatus [15ms]

How to create a fat jar with maven

I have not generated a fat jar manually for a long time,  because in other projects there was everything already setup or I was used to use any frameworks that freed me of such „low-level“ tasks. Recently, however, I had to generate a fat jar for a project again, i.e. a final artifact for actual deployment or for manual distribution. I had to dig deeply until I could remember half-way how to do it.

There are different maven-plugin that allow to create an executable fat jar. Basically, there are three different ways:

maven-jar-plugin

The maven-jar is a very basic plugin that enables to generate a jar. However, mostly it is not the appropriate plugin that you are looking for to generate a fat jar. Unfortunately, it does not add the maven dependencies inside the final jar. All dependencies have to be included in the classpath in some way and normally that is not what you want.


<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-jar-plugin</artifactId>
<configuration>
<archive>
<manifest>
<mainClass>{your.package.main.class}</mainClass>
</manifest>
</archive>
</configuration>
</plugin>

maven-assembly-plugin

This plugin adds all maven dependencies inside the final fat jar and this is probably exactly what you are looking for. All dependencies are included as jars in the final jar. In the example below, the execution of the plugin is bound to the package phase. The final executable jar will be named with a postfix „jar-with-dependencies“ which I find quite annoying. I don’t want constantly renaming the final jar.


<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-assembly-plugin</artifactId>
<configuration>
<descriptorRefs>
<descriptorRef>jar-with-dependencies</descriptorRef>
</descriptorRefs>
<archive>
<manifest>
<mainClass>{your.package.main.class}</mainClass>
</manifest>
</archive>
</configuration>
<executions>
<execution>
<phase>package</phase>
<goals>
<goal>single</goal>
</goals>
</execution>
</executions>
</plugin>

maven-shade-plugin

The maven-shade-plugin provides probably the best way to create an executable fat jar. It adds all maven dependencies inside the final fat jar and additionally executes shading (i.e. renaming).  This plugin is bound in the example below to the package phase as well. The filters section is included to avoid any security issues not allowing to execute the jar. Avoid using jars generated in this way as maven dependency, as it is ruining the dependency resolution feature of maven. Create such jars only for the final artifact!


<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-shade-plugin</artifactId>
<configuration>
<transformers>
<transformer implementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer">
<mainClass>{your.package.main.class}</mainClass>
</transformer>
</transformers>
<filters>
<filter>
<artifact>*:*</artifact>
<excludes>
<exclude>META-INF/*.SF</exclude>
<exclude>META-INF/*.DSA</exclude>
<exclude>META-INF/*.RSA</exclude>
</excludes>
</filter>
</filters>
</configuration>
<executions>
<execution>
<phase>package</phase>
<goals>
<goal>shade</goal>
</goals>
</execution>
</executions>
</plugin>

Why you should never write your own logger

I never imagined that there are software projects these days that write their own logger. Recently,  I learned that this assumption was wrong… I see some problems when you write your own logger, which I would briefly describe here. Then I will say which logger I recommend today and how to configure it.

I see two reasons why people write their own logger: First, they do not know an official logger. Second, they believe they have requirements that can not be covered with an off-the-shelf logger. To point one, yes this is quite unfortunate. To point two, I believe that one should strongly question its requirements. Normally one should adjust its requirements so that a normal logger is sufficient and in most cases it is more than that.

Writing a separate logger is to reinvent the wheel. There are numerous loggers that have been developed over the years and are widely used and popular. In addition, time is invested in technical details rather than focusing on business logic. Furthermore, most developers know official loggers and find themselves right in a new project immediately. On the other hand, an own written logger has to be understood first. You think these are enough reasons why not writing an own logger? The best reason only come now: Own loggers are probably buggy and do not work as expected! Recently, I had an issue with an application wherefore an own logger was implemented. The application crashed regularly after a couple of hours. As the logger was implemented with System.out.println, I had absolutely no clue what was going on. There was no output at all that could indicate me what’s happening. This was quite a big blind flight. Only when I migrated the logger to slf4j, I was able to see what was going on. An OutOfMemory happened..And guess why? It was the own written logger! Oh my god…Something like the following was implemented:


private static StringBuilder dbgSb = null;
public static void DoLog(String s) {
if (dbgSb == null) {
dbgSb = new StringBuilder();
dbgSb.append("\n###********************\n");
}
dbgSb.append(s + "\n");
}
public static String getLogString() {
String s = dbgSb.toString();
dbgSb = null;
return s;
}

view raw

own_logger.java

hosted with ❤ by GitHub

It took me not a long time to see that this is generating an OutOfMemory if the getLogString() is never called. Ok, enough of this stuff… Let’s concentrate of how to do it properly.

Today,  I recommend to use logback. Logback is developed by the same developer as Log4j was and has a couple of adavantages over Log4j. Primarly it is faster. To put logback in place in your project, use these two dependencies:


<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>1.0.13</version>
</dependency>
<dependency>
<groupId>org.codehaus.janino</groupId>
<artifactId>janino</artifactId>
<version>2.7.8</version>
</dependency>

Actually, only the former dependency is used, but the janino dependency is included here to enable conditional features in the logback configuration file as we will see below. Next, you need to create a logback.xml and place it under src/main/resources


<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<property name="CONSOLE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:-%5p} — [%t] %-40.40logger{39} : %m%n}"/>
<property name="FILE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:-%5p} — [%t] %-40.40logger{39} : %m%n"/>
<property name="LOG_FILE" value="logs/mylog.log"/>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>utf8</charset>
</encoder>
</appender>
<appender name="FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<encoder>
<pattern>${FILE_LOG_PATTERN}</pattern>
</encoder>
<file>${LOG_FILE}</file>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<fileNamePattern>${LOG_FILE}.%i</fileNamePattern>
</rollingPolicy>
<triggeringPolicy
class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<MaxFileSize>10MB</MaxFileSize>
</triggeringPolicy>
</appender>
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
</root>
<if condition='property("profiles.active").contains("debug")'>
<then>
<logger name="com.company.tools" level="DEBUG" additivity="false">
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
</logger>
</then>
</if>
</configuration>

view raw

logback.xml

hosted with ❤ by GitHub

I do not go in further details here. It is how to configure a logger and can be read in numerous other documentations. The only thing I want to mention is the conditional setting of the logging level at the end of the file. Whenever the application is started with this application property , the logging level is set to debug.

java -Dprofiles.active=debug -jar app.jar

At last, loggers can be included is the source code as follows:

private static final Logger LOGGER = LoggerFactory.getLogger(MyClass.class);

Builder in practice

In this blog post I’m going to explain how to construct a builder for constructing objects. To be clear from the beginning, what I’m going to describe is not the official builder pattern, however, in practice this is often referred to as the builder pattern nevertheless.

A builder is used to construct complex objects with many constructor parameters where some of them are optional. An alternative to handle optional parameters is the telescoping constructor pattern. For each possibility an object can be constructed, a constructor is provided. This has the drawback that it blows up the code and it is quite hard to read. From time to time, this is seen in practice and can be eliminated by bringing a builder into action. A second alternative is the JavaBeans pattern, in which a parameter-less constructor is called whereafter the properties are set via setter methods. However, this pattern has the disadvantages that the object may be in inconsistent state through its construction and it precludes the possibility to make the class immutable. Builders are by far the best approach to deal with optional parameters. Furthermore, I also have often used builders in tests to construct test objects. Builders are quite popular as it allows one to construct a fluent API.

So let’s create a builder for a Airplane object. The object has one mandatory parameter seats. Mandatory parameters  usally set directly in the constructor. Furthermore, there are two optional parameters named engine and rescue and an optional List of instruments. The builder is implemented as a static nested inner class. The constructor of the Airplane is private. Note that most IDE can generate exactly this code for you!


public final class Airplane {
private final int seats;
private final int engine;
private final int rescue;
private final List<Instrument> instruments;
private Airplane(Builder builder){
this.seats = builder.seats;
this.engine = builder.engine;
this.rescue = builder.rescue;
this.instruments = builder.instruments;
}
public static class Builder {
private final int seats;
private int engine;
private int rescue;
private List<Instrument> instruments = new ArrayList<>();
public Builder(int seats){
this.seats = seats;
}
public Builder withEngine(int engine) {
this.engine = engine;
return this;
}
public Builder withRescue(int rescue) {
this.rescue = rescue;
return this;
}
public Builder withInstrumentList(List<Instrument> instruments) {
this.instruments = instruments;
return this;
}
public Airplane build(){
return new Airplane(this);
}
}
}

view raw

Airplane.java

hosted with ❤ by GitHub

An airplane object is then constructed as follows:


List<Instrument> instruments = new ArrayList<>();
instruments.add(new Instrument("Altimeter"));
instruments.add(new Instrument("Velocity"));
Airplane airplane = new Airplane.Builder(4).withEngine(375).withRescue(2).withInstrumentList(instruments).build();

So far so good. But it would be nice if we have not to construct a list before the builder is called. It would be much more elegant if we could create the instruments list by means of the builder. In the following section we are going to dive into this problem. The goal is to construct an airplane object, that encompasses a list of instruments, as follows:


Airplane airplane = new Airplane.Builder(4).withEngine(375).withRescue(2).addList().add().withName("Altimeter").toList().add().withName("Velocity").toList().done().build();

The concept behind this construct is to have parent and child builders. There is an Instrument builder that has a ListBuilder and the ListBuilder has again a Airplane builder.

The Airplane class has just slightly changed. There were only added two method called addList. The first method gets the child builder and hands over the parent builder. The second method is just a setter which is used in the child builder.


public final class Airplane {
private final int seats;
private final int engine;
private final int rescue;
private final List<Instrument> instruments;
private Airplane(Builder builder){
this.seats = builder.seats;
this.engine = builder.engine;
this.rescue = builder.rescue;
this.instruments = builder.instruments;
}
public static class Builder {
private final int seats;
private int engine;
private int rescue;
private List<Instrument> instruments;
public Builder(int seats){
this.seats = seats;
}
public Builder withEngine(int engine) {
this.engine = engine;
return this;
}
public Builder withRescue(int rescue) {
this.rescue = rescue;
return this;
}
// get child builder and hands over parent builder
public Instrument.ListBuilder addList(){
return new Instrument.ListBuilder().setAirplaneBuilder(this);
}
public void addList(List<Instrument> instruments){
this.instruments = instruments;
}
public Airplane build(){
return new Airplane(this);
}
}
}

view raw

Airplane.java

hosted with ❤ by GitHub

The Instrument class now comprises two nested static classes, namely the Builder and the ListBuilder. Both these classes are structurally built in the same way and in each of them there exists a parent builder.


public class Instrument {
private String name;
private Instrument(Builder builder) {
this.name = builder.name;
}
public static class Builder {
private String name;
private ListBuilder listBuilder; // parent builder
public Builder withName(String name) {
this.name = name;
return this;
}
public Instrument build() {
return new Instrument(this);
}
// setter for parent builder
public Builder setListBuilder(ListBuilder builder) {
this.listBuilder = builder;
return this;
}
// build it and get parent builder again
public ListBuilder toList(){
this.listBuilder.add(this.build());
return this.listBuilder;
}
}
public static class ListBuilder {
private List<Instrument> instruments = new ArrayList<>();
private Airplane.Builder airplaneBuilder; // parent builder
public ListBuilder add(Instrument instrument){
this.instruments.add(instrument);
return this;
}
public List<Instrument> build(){
return this.instruments;
}
// get child builder and hands over parent builder
public Instrument.Builder add() {
return new Instrument.Builder().setListBuilder(this);
}
// setter for parent builder
public ListBuilder setAirplaneBuilder(Airplane.Builder builder){
this.airplaneBuilder = builder;
return this;
}
// build it and get parent builder again
public Airplane.Builder done() {
this.airplaneBuilder.addList(this.build());
return airplaneBuilder;
}
}
}

view raw

Instrument.java

hosted with ❤ by GitHub

With the help of generics and reflections, these builders could be constructed more generically. Maybe I will explain this some when later.