Application Logging with Aspect-Oriented Programming: Part 1

Overview

Application logging is a common problem every software developer needs to deal with. Logs are valuable, providing various types of information about your application while it is running. This may include how many times a particular section of code is execute or how long is takes certain code to execute. However, sometimes it is difficult to know what logging you need before you build and deploy your application. This article is the first in a series about building a logging system using Aspect-Oriented Programming (AOP) allowing you to control what you log outside of your application. This article focuses on finding a solution for Scala and Java applications.

AOP Terminology:

AOP is a large subject, so let’s first review the terminology which applies to what we are trying to accomplish here.

pointcut – A pointcut is responsible for locating join points (points in code…methods in our case…that matches a given pattern). Pointcuts are also able to expose data from these join points (i.e. param values).

advice – Advice is where behavior is defined. In our case, this is where we will implement our logging logic. This behavior is executed for each join point (i.e. method) identified by the related Pointcut.

around – Around is a type of Advice (other Advice include before and after..which are less expensive than Around). This advice allows you to do pre-processing and post-processing. Where the other two types of Advice allow you to do one or the other.

Goal

Let’s first define what our first iteration of our Application Logger will look like. As mentioned earlier, what we want is a way to add/remove/change out logging without having to rebuild and deploy our application. What we will do to accomplish this is build a Scala java agent that we can include in any Java or Scala application. All we need will need to do is define what we want to log in a separate xml file, include our java agent in our application’s startup parameters and add our xml file to our application’s WEB-INF directory.

Building a Simple Logger Application

We will build our logging application with Scala. This application is actually pretty simple since we will use aspectj to do most of the real work. So let’s first define the core of our application, the monitor abstract class.

@Aspect
abstract class ScalaMonitor extends Logging {
    @Around(value = "methodPerformancePointcut()")
    def logMethodPerformance(jp: ProceedingJoinPoint) = {
        val startTime = currentTime
        jp.proceed()
        val endTime = currentTime
        // JMXClient.recordExecution(jp.getSignature().toString(), startTime, endTime)
        logger.info(s"type=perf elapsedTime: ${endTime-startTime}, ${jp.getSignature()}")
    }
}

The code snippet above adds logging logic to our application which measures how long it takes the targeted methods to execute. We’re using the @Around annotation which allows us to put our timing code `before` and `after` the calling method (aka JoinPoint). If we wanted to instead just add logging before or after the JoinPoint, then we’d use with the @Before or @After annotation.

The next step is to define which methods you want to add this logging to. This is done in the the aop.xml file which will be different for each application you are measuring. The xml below says we want to monitor two methods, ElevationService.process and TimezoneService.process. Here we are defining the concrete monitoring class and also defining the Pointcut. The Pointcut syntax can also include wildcards.

<aspects>
    <concrete-aspect name="com.christophergagne.scalaperformance.ScalaMonitorImpl" 
        extends="com.christophergagne.scalaperformance.ScalaMonitor">

        <pointcut name="methodPerformancePointcut" expression="execution(void com.christophergagne.sampleapp.ElevationService.process(..)) || 
            execution(void com.christophergagne.sampleapp.TimezoneService.process(..))"/>
    </concrete-aspect>
  </aspects>

Conclusion

This is all you need to start building your own logging application that you can use on any of your projects. However, I did intentionally leave out some of the details, so you can review a fully working sample application here: https://github.com/gagnechris/ScalaPerformanceMonitorDemo. Our next articles will go into more detail on the following:

• How to define your Pointcuts with aspectj
• How to extract method parameter values from your Joinpoint
• Building a JMX Client which we can log to allowing us to review our data in jconsole
• Other more advanced aspectj topics