Introduction

AspectJDemo provides a simple, real-world example of how AspectJ can be used to separate two common cross cutting concerns: logging and instrumentation, in Java projects.

Background

During 2014 I released successive updates to my open source project Method Invocation Remoting to include first logging, and then instrumentation (logging of metrics) into the major classes of the project. The code example below shows the Send() method of the TcpRemoteSender class, from the C# side of the project (the TcpRemoteSender class is used to send a string to a corresponding TcpRemoteReceiver class via a TCP network)...

public void Send(string message) { metricsUtilities.Begin(new MessageSendTime()); CheckNotDisposed(); CheckConnected(); try { EncodeAndSend(message); } catch (Exception e) { HandleExceptionAndResend(e, message); } IncrementMessageSequenceNumber(); metricsUtilities.End(new MessageSendTime()); metricsUtilities.Increment(new MessageSent()); loggingUtilities.Log(this, LogLevel.Information, "Message sent and acknowledged."); }

Logging and instrumentation are implemented using the 'metricsUtilities' and 'loggingUtilities' objects. Methods on these objects use the C# 'Conditional' attribute, which means logging and instrumentation can be simply enabled or disabled by compiler options when building the code base (as in the following example)...

[Conditional("LOGGING_ON")] public void Log(object source, LogLevel level, string text) { logger.Log(source, level, text); }

Implementing in this way means that the logging and instrumentation code is kept to a minimum within the methods of the TcpRemoteSender class (i.e. only one line of code per logging or instrumentation operation is required).

In the equivalent TcpRemoteSender class in the Java side of the project however, the situation is different. Because Java doesn't have any built in preprocessor functionality, enabling or disabling of the logging and instrumentation functionality is done by using Ant build scripts, and appears in the code as commented method calls (which get uncommented depending on the Ant build settings). The equivalent Send() method in the Java TcpRemoteSender class looks like this...

public void Send(String message) throws Exception { /* //[BEGIN_METRICS] metricLogger.Begin(new MessageSendTime()); //[END_METRICS] */ if (socketChannel.isConnected() == false) { throw new Exception("Connection to TCP socket has not been established."); } try { EncodeAndSend(message); } catch (Exception e) { HandleExceptionAndResend(e, message); } IncrementMessageSequenceNumber(); /* //[BEGIN_METRICS] metricLogger.End(new MessageSendTime()); metricLogger.Increment(new MessageSent()); //[END_METRICS] */ /* //[BEGIN_LOGGING] logger.Log(this, LogLevel.Information, "Message sent and acknowledged."); //[END_LOGGING] */ }

Because of the extra comment lines required, of the 20 lines of code/comment in the method, 10 of them (50%) relate to logging and instrumentation rather than the primary function of the class (i.e. to send a string via TCP). I wanted to improve this, as it made the code somewhat messy, and also made it apparent that 'concerns' (or different functions of the code) were not properly separated inside the class... i.e. the code concerning sending the message was mixed in with the logging and instrumentation code.

At some point I came across the concept of aspect oriented programming, and came to understand that its primary goal was to allow separation of cross cutting concerns from the main code. I also discovered the AspectJ project, and learned that it was a mature, and widely used framework for implementing aspect oriented programming for Java projects.

Hence I decided to try implementing the logging and instrumentation functionality inside the Java TcpRemoteSender class using AspectJ. The result was this AspectJDemo project.

Downloading and Installing AspectJ

I used AspectJ 1.8.2 for this project. This and later versions are available for download here as .jar files. The AspectJ files can be unpacked from the .jar by executing the following command...

java -jar aspectj-1.8.2.jar

...or in Windows by simply double clicking the .jar file (which will show the following installation dialog)...

AspectJ Installer

The installation process will install the AspectJ files into a chosen path, including the AspectJ compiler (in the \bin folder under the installation path), and the .jar files that must be referenced when executing the compiler (in the \lib folder).

Basic AspectJ Concepts

The AspectJ Programming Guide gives comprehensive instructions in programming in AspectJ. However for the purpose of this tutorial, there are 3 key items to understand...

Aspects

An aspect is the basic functional 'unit' in AspectJ (analogous to a class being the basic functional unit in Java). Aspects have many similarities to Java classes... they have constructors, can implement interfaces and derive from other aspects, can contain public and private methods, and can contain inner classes. The purpose of the aspect is to define how cross cutting concerns for a class (or classes) are implemented. The implementation is described through pointcuts and advice (see below).

Pointcuts

Pointcuts are defined within an aspect, and identify an area within a class where some cross cutting code should act. Typically this area is before or after a call to a method within the class. At a high level the pointcut defines 'where' the cross cutting code should execute within a class.

Advice

Advice is also defined within an aspect, and can be thought of as defining 'what' cross cutting code should run at each of the defined pointcuts. An advice block is a routine very similar to a method inside a class, and contains standard Java code.

Converting Inline Code into Aspects

Instrumentation

In the Method Invocation Remoting version of the TcpRemoteSender class, the Send() method captures 2 separate instrumentation metrics... the time to send the message, and incrementing a 'MessageSent' counter. In the Send() method, these are captured using the private 'metricLogger' member...

public void Send(String message) throws Exception { /* //[BEGIN_METRICS] metricLogger.Begin(new MessageSendTime()); //[END_METRICS] */ if (socketChannel.isConnected() == false) { throw new Exception("Connection to TCP socket has not been established."); } try { EncodeAndSend(message); } catch (Exception e) { HandleExceptionAndResend(e, message); } IncrementMessageSequenceNumber(); /* //[BEGIN_METRICS] metricLogger.End(new MessageSendTime()); metricLogger.Increment(new MessageSent()); //[END_METRICS] */ /* //[BEGIN_LOGGING] logger.Log(this, LogLevel.Information, "Message sent and acknowledged."); //[END_LOGGING] */ }

The first step to moving this instrumentation code into an aspect, was to create the aspect. Aspects are defined in a similar way to classes, and can include imports, private members, and a constructor...

package net.alastairwyse.aspectjdemo; import java.lang.Thread.UncaughtExceptionHandler; import java.io.*; import javax.xml.parsers.*; import javax.xml.xpath.*; import org.w3c.dom.Document; import net.alastairwyse.applicationmetrics.*; import net.alastairwyse.methodinvocationremotingmetrics.*; /** * Aspect which provides an example of instrumentation/metric logging for class TcpRemoteSender * @author Alastair Wyse */ aspect Instrumentation { private final String configurationFileName = "ApectJDemoConfiguration.xml"; ConfigurationSettings configurationSettings; FileMetricLogger metricLogger; public Instrumentation() throws Exception { configurationSettings = readConfigurationSettings(); metricLogger = new FileMetricLogger('|', configurationSettings.MetricLogFilePath, configurationSettings.MetricEventWriteFrequency, true, new MetricLoggerExceptionHandler()); metricLogger.Start(); }

Aspects are allowed to only define a single, parameterless constructor (see here for more information). The constructor in the Instrumentation aspect initializes an instance of the applicationmetrics.FileMetricLogger class using parameters from an XML configuration document (more on this later), and then starts the FileMetricLogger.

To replicate the instrumentation metrics captured in the Send() method, the next step is to create a pointcut at the Send() method itself. This is defined in the Instrumentation aspect as follows...

/** * Defines a join point for when a message is sent. */ private pointcut SendMessage(): call (void TcpRemoteSender.Send(String));

...then, to define what instrumention code should be executed at that pointcut, 2 pieces of advice must be defined, one executing before the call to Send(), and one after...

/** * Implements metric logging before sending a message. */ before(): SendMessage() { metricLogger.Begin(new MessageSendTime()); } /** * Implements metric logging after sending a message. */ after() returning: SendMessage() { metricLogger.End(new MessageSendTime()); metricLogger.Increment(new MessageSent()); }

The Method Invocation Remoting version of the TcpRemoteSender class also logs a metric when a TCP reconnect occurs. This happens inside private method HandleExceptionAndResend()...

private void HandleExceptionAndResend(Exception sendException, String message) throws Exception { if (sendException instanceof IOException) { logger.Log(this, LogLevel.Error, sendException.getClass().getSimpleName() + " occurred whilst attempting to send message.", sendException); logger.Log(this, LogLevel.Warning, "Disconnected from TCP socket."); } else if ((sendException instanceof java.nio.channels.ClosedChannelException) || (sendException instanceof MessageAcknowledgementTimeoutException)) { logger.Log(this, LogLevel.Error, sendException.getClass().getSimpleName() + " occurred whilst attempting to send message.", sendException); } else { throw new Exception("Error sending message. Unhandled exception while sending message.", sendException); } logger.Log(this, LogLevel.Warning, "Attempting to reconnect to TCP socket."); socketChannel.close(); AttemptConnect(); /* //[BEGIN_METRICS] metricLogger.Increment(new TcpRemoteSenderReconnected()); //[END_METRICS] */ try { EncodeAndSend(message); } catch (Exception e) { throw new Exception("Error sending message. Failed to send message after reconnecting.", e); } }

To move this instrumentation code into the aspect, a pointcut should be defined around the call to the AttemptConnect() method (and advice defined to execute after that pointcut). The problem here is that AttemptConnect() is called not only when reconnecting, but also when connecting for the first time (in which case no disconnect has occurred, so no metric should be logged). Fortunately AspectJ allows you to define a pointcut at a method, where that method has been called from another method (using the 'withincode' declaration)...

/** * Defines a join point for when a TCP reconnect occurs. */ private pointcut Reconnect(): call (void TcpRemoteSender.AttemptConnect()) && withincode (void TcpRemoteSender.HandleExceptionAndResend(Exception, String));

This allows you to define a pointcut around the AttemptConnect() method, but only when it has been called from within the HandleExceptionAndResend() method. The advice which logs the reconnect metric using the above pointcut is then defined as follows...

/** * Implements metric logging after a reconnect occurs. */ after() returning: Reconnect() { metricLogger.Increment(new TcpRemoteSenderReconnected()); }

Closing Resources

An instance of the FileMetricLogger class is instantiated in the Instrumentation aspect constructor, and started with the Start() method. This creates a worker thread, and also uses an underlying FileWriter object, which have to be stopped and closed (respectively) when the FileMetricLogger client code (i.e. the Instrumentation aspect) is closed/destructed.

To capture the point when the target TcpRemoteSender object is closed (and hence when the aspect should be closed), a pointcut should be created around the TcpRemoteSender close() method...

/** * Defines a join point for when the close() method is called. */ private pointcut Close(): call (void TcpRemoteSender.close());

Then, a piece of advice can be defined to call the Stop() and close() methods on the FileMetricLogger class...

/** * Cleans up aspect resources after the target object is closed */ after() : Close() { try { metricLogger.Stop(); metricLogger.close(); } catch (Exception e){ e.printStackTrace(System.out); } }

Note that the 'after' keyword here is used in isolation (i.e. without a 'returning' keyword), to specify that the advice should execute regardless of whether the close() method exits successfully or from an exception being thrown.

One additional caveat here, is that whilst creating a pointcut at the close() method works fine in the context of this project, it may not work correctly in cases where multiple instances of the target class are created. See the 'Dislikes' section for a full discussion of this.

Logging

The Method Invocation Remoting TcpRemoteSender class implements logging in a similar way to instrumentation, using private member 'logger'. The logger is used to log both status events (e.g. connecting, disconnecting, sending a message) and also to log exceptions. I implemented only the status logging using AspectJ. I defined a separate aspect to perform the logging (named 'Logging'), and created an instance of the applicationlogging.ConsoleApplicationLogger class in its constructor...

privileged aspect Logging { ConsoleApplicationLogger logger; public Logging() { logger = new ConsoleApplicationLogger(LogLevel.Debug, '|', " "); }

Note that the aspect is marked as 'privileged'), which means it's able to access the private and protected members of the TcpRemoteSender class (or any other class it targets). The Send() method in TcpRemoteSender writes a simple log message after successfully sending a message...

/* //[BEGIN_LOGGING] logger.Log(this, LogLevel.Information, "Message sent and acknowledged."); //[END_LOGGING] */

...in converting this into an aspect, I wanted to also log the content of the message that was sent. To do this I needed to define a pointcut around the Send() method, but which also captured the content of the method's 'message' parameter. This can be achieved in AspectJ by using the 'args' declaration in the pointcut...

/** * Defines a join point for when a message is sent. */ private pointcut SendMessage(String message): call (void TcpRemoteSender.Send(String)) && args(message);

A piece of advice can then be defined which acts after the SendMessage() pointcut, and captures and uses the 'message' parameter...

/** * Implements logging after sending a message. */ after(String message) returning: SendMessage(message) { logger.Log(thisJoinPoint.getTarget(), LogLevel.Information, "Message sent and acknowledged."); logger.Log(thisJoinPoint.getTarget(), LogLevel.Debug, "Sent message '" + message.toString() + "'."); }

Note the use of the special variable 'thisJoinPoint' which allows you to access reflective information about the current pointcut/advice. In this case we are able to get a reference to the current object on which the advice is acting (using the getTarget() method). This is then passed to the Log() method, so the logger can record which object performed the logging.

Pointcuts and advice for logging disconnects and reconnects are created using similar declarations to those for instrumentation. However, for logging the initial connection, additionally the 'target' declaration is used. This allows a reference to the object acted on by the pointcut, to be available to any advice using that pointcut...

/** * Defines a join point for when the sender connects. */ private pointcut Connected(TcpRemoteSender sender): call (void TcpRemoteSender.AttemptConnect()) && target(sender);

In the corresponding advice, the 'sender' variable can then be used as a reference to the TcpRemoteSender that the pointcut and advice are acting on. As the aspect was declared 'privileged', private members 'ipAddress' and 'port' can be accessed and details of them can be written to the logger...

/** * Implements logging after the sender connects. */ after(TcpRemoteSender sender) returning: Connected(sender) { logger.Log(thisJoinPoint.getTarget(), LogLevel.Information, "Connected to " + sender.ipAddress.toString() + ":" + sender.port + "."); }

After moving the logging and instrumentation code into aspects, the Send() method in the aspectjdemo version of TcpRemoteSender only contains code relating to sending messages...

public void Send(String message) throws Exception { if (socketChannel.isConnected() == false) { throw new Exception("Connection to TCP socket has not been established."); } try { EncodeAndSend(message); } catch (Exception e) { HandleExceptionAndResend(e, message); } IncrementMessageSequenceNumber(); }

Additional Notes

Aspects can contain private methods, and execute them just as in regular Java code. The Instrumentation aspect contains a private method ReadConfigurationSettings(), which reads configuration settings from an XML file. The aspect's constructor calls this ReadConfigurationSettings() method and passes the returned settings to the constructor of the FileMetricLogger object.

Aspects can also contain inner classes, which is demonstrated by inner class MetricLoggerExceptionHandler inside the Instrumentation aspect. Finally, although not demonstrated in this project, aspects are able to implement Java interfaces.

Building / Compiling

The term 'weaving' is used to describe the process of combining aspects with the Java classes which are the targets of the aspects. Weaving can be performed at various stages during the build/run process... at compile time (i.e. using .java source files), after compiling (using .class and .jar files), and even at load time (i.e. at the point the class is loaded by the Java virtual machine). Compile-time weaving is the simplest approach, and hence is what I describe here.

Aspects and their target Java classes can be woven and compiled into standard Java .class files using the ajc compiler included with the AspectJ distrubution (in the /bin folder). Ajc has many parameters, but in this project, the ones required to get it to properly compile were the following...

Option Description
-source The official documentation states that this 'toggles assertions'. However I found I needed to set this parameter to match the Java version of the code being compiled.
-cp The class paths to include when compiling (same as for the Java compiler)
-outjar The .jar file to combine the resulting classes into
(default required parameter) A space-separated list of the aspects and Java files to compile

Hence the whole ajc command line I used was (split across separate lines to make for easier reading)...

ajc -source 1.7 -cp "[path containing the AspectJ installation]\lib\aspectjrt.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\operatingsystemabstraction.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationlogging.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationmetrics.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremoting.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremotingmetrics.jar" -outjar "[path to write the resulting .jar file to]\aspectjdemo.jar" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\ConfigurationSettings.java" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\TcpRemoteSender.java" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\Logging.java" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\Instrumentation.java" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\SenderProgram.java" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\ReceiverProgram.java"

This should run the ajc compiler, and produce an aspectjdemo.jar file in the directory specified by the -outjar parameter.

Update for ajc 1.8.5

I recently tried running this project using AspectJ version 1.8.5 on Windows Server 2008 (64 bit). Either because of the updated version of AspectJ, or the updated operating system, ajc would not build with the above command. It seems that the individual .jars to be included in the classpath should no longer be surrounded with individual sets of double quotes. Rather the whole -cp parameter should be surrounded in double quotes. I also wasn't able to get ajc to accept multiple source files in the command. Hence, as all source .java files are in the same path, I used the 'sourceroots' parameter set to the directory containing the AspectJDemo source files. The complete command line was...

ajc -source 1.8 -cp "[path containing the AspectJ installation]\lib\aspectjrt.jar; [path containing AspectJDemo]\AspectJDemo\lib\operatingsystemabstraction.jar; [path containing AspectJDemo]\AspectJDemo\lib\applicationlogging.jar; [path containing AspectJDemo]\AspectJDemo\lib\applicationmetrics.jar; [path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremoting.jar; [path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremotingmetrics.jar" -outjar "[path to write the resulting .jar file to]\aspectjdemo.jar" -sourceroots [path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\

Consider using the above command as an alternative if the first fails.

Running the Program

The SenderProgram class is designed to demonstrate all advice code in both the Logging and Instrumentation aspects. It performs the following steps...

  1. Connects to a TcpRemoteReceiver class
  2. Immediately disconnects from the receiver (to demonstrate the logging of disconnects)
  3. Connects again to the receiver (to demonstrate logging and instrumentation of reconnects)
  4. Sends 2 separate messages
  5. Disconnects

To run the program, both the SenderProgram and ReceiverProgram must be started as separate processes. The receiver can be started using the following command line (again split across separate lines to make for easier reading)...

java -cp "[path containing ajc compiled jar]\aspectjdemo.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\operatingsystemabstraction.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationlogging.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationmetrics.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremotingmetrics.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremoting.jar" net.alastairwyse.aspectjdemo.ReceiverProgram

...and the sender can be started using this...

java -cp "[path containing ajc compiled jar]\aspectjdemo.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\operatingsystemabstraction.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationlogging.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationmetrics.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremotingmetrics.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremoting.jar" "[path containing the AspectJ installation]\lib\aspectjrt.jar"; net.alastairwyse.aspectjdemo.SenderProgram

The following text will be displayed in the sender console...

2015-02-23 23:14:12.968 | Source = TcpRemoteSender | Connected to localhost/127.0.0.1:10000. 2015-02-23 23:14:43.312 | Source = TcpRemoteSender | WARNING | Attempting to reconnect to TCP socket. 2015-02-23 23:14:43.312 | Source = TcpRemoteSender | Connected to localhost/127.0.0.1:10000. 2015-02-23 23:14:51.125 | Source = TcpRemoteSender | Message sent and acknowledged. 2015-02-23 23:14:51.125 | Source = TcpRemoteSender | Sent message 'Neque porro quisquam est qui dolorem ipsum quia dolor sit amet, consectetur, adipisci velit... (message 1)'. 2015-02-23 23:14:51.250 | Source = TcpRemoteSender | Message sent and acknowledged. 2015-02-23 23:14:51.250 | Source = TcpRemoteSender | Sent message 'Lorem ipsum dolor sit amet, mel mazim viderer at, per quis saepe dissentias ad, case scaevola... (message 2)'. 2015-02-23 23:14:51.250 | Source = TcpRemoteSender | Disconnected. 2015-02-23 23:14:51.250 | Source = TcpRemoteSender | Disconnected.

All of the above logging is being performed by the Logging aspect. Note that 'Disconnected' is logged twice. The first one is due to the explicit execution of the Disconnect() method. The second comes from the implicit call to the close() method as part of the try with resources statement in the SenderProgram class (which in turn also calls Disconnect()).

The program will also create a metric log file in the location specified by the <MetricLogFilePath> in the XML configuration file. The contents of this file will be as follows (re-ordered by timestamp to make reading easier)...

2015-02-23 23:14:13.250 | MessageSendTime | 37875 2015-02-23 23:14:43.312 | TcpRemoteSenderReconnected 2015-02-23 23:14:51.125 | MessageSent 2015-02-23 23:14:51.125 | MessageSendTime | 125 2015-02-23 23:14:51.250 | MessageSent

A final note is to ensure that the XML configuration file 'ApectJDemoConfiguration.xml' exists in the same folder as the aspectjdemo.jar file created during compilation with ajc (if it's not there it will result in a FileNotFoundException).

Likes

Separation of Cross Cutting Code

The primary goal of AspectJ is to allow the separation and centralization of cross cutting code, and for the case of the AspectJDemo project, this was very well achieved. In this project, after moving the logging and instrumentation code into aspects, the TcpRemoteSender Send() method contains only code relating to sending messages over TCP (and the number of lines of code has been reduced by half).

Allows Access to Private Members

As demonstrated in the Logging aspect, AspectJ allows aspects to access the private members of classes they target. This provides enormous flexibility in the aspect code... in this project, it meant the Logging aspect could write detailed logging messages by including details of private members of the TcpRemoteSender class.

Composed (nested) Pointcuts

Allowing composed pointcuts provides greater flexibility in determining exactly where in the code of class that a piece of advice should act on. This feature was used in both the Logging and Instrumentation aspects to define pointcuts around the AttemptConnect() method, but only where it had been called from within the HandleExceptionAndResend() method. If composing of pointcuts wasn't available, it would be in some cases impossible to define precisely where advice code should act.

Availability of Standard Java Code Features

Aspects can contain standard features of regular Java code, such as private methods, inner classes, inheritance, and implementing interfaces. This means that aspects can utilize the same power and flexibility that these features provide in standard Java code.

Cross Cutting Code can be simply Switched Off

It's easy to turn off the AspectJ cross cutting code if it's not required (e.g. you may want to turn off granular logging in a high performance production environment)... simply build the Java code with the standard Java compiler. For example, in AspectJDemo the TcpRemoteSender class has no dependency on AspectJ aspects, and hence can be built completely independently of AspectJ.

The AspectJDemo project can be built with logging and instrumentation disabled by using the following command line...

javac -cp "[path containing AspectJDemo]\AspectJDemo\lib\operatingsystemabstraction.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationlogging.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationmetrics.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremoting.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremotingmetrics.jar" -d [path to write the resulting .class files to] "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\ConfigurationSettings.java" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\TcpRemoteSender.java" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\SenderProgram.java" "[path containing AspectJDemo]\AspectJDemo\src\net\alastairwyse\aspectjdemo\ReceiverProgram.java"

...and then run with this command line (to run the receiver, substitute the ReceiverProgram class in the last parameter)...

java -cp "[path containing AspectJDemo]\AspectJDemo\lib\operatingsystemabstraction.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationlogging.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\applicationmetrics.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremoting.jar"; "[path containing AspectJDemo]\AspectJDemo\lib\methodinvocationremotingmetrics.jar"; [path containing compiled .class files] net.alastairwyse.aspectjdemo.SenderProgram

Dislikes

Objects Created by Aspects Aren't Destructed

This point is touched on in the 'Closing Resources' section above. In the Instrumentation aspect constructor, an applicationmetrics.FileMetricLogger class is instantiated...

public Instrumentation() throws Exception { configurationSettings = readConfigurationSettings(); metricLogger = new FileMetricLogger('|', configurationSettings.MetricLogFilePath, configurationSettings.MetricEventWriteFrequency, true, new MetricLoggerExceptionHandler()); metricLogger.Start(); }

This class creates a worker thread, and also uses an underlying java.io.FileWriter object, and hence exposes a Stop() method, and also implements the AutoCloseable interface to allow these resources to be released when the instance of the class is no longer needed. In the Instrumentation aspect, a pointcut is created at the TcpRemoteSender.close() method, and the advice associated with that pointcut calls FileMetricLogger.Stop() and FileMetricLogger.close() when the TcpRemoteSender.close() method is called. This works fine in the context of this project, as only a single instance of the TcpRemoteSender class is instantiated. However if multiple TcpRemoteSender classes were created and one of them was closed, calls to the methods of the remaining instances would not perform any instrumentation logging (as the FileMetricLogger would have already been stopped). Potentially this could be overcome by using the 'pertarget' declaration, to create an individual instance of the aspect for each instance of the target class. However, that would also mean the behaviour would change... multiple worker threads would be created, and the instrumentation metrics would be logged to separate files (different log file paths would need to be configured for each instance of the FileMetricLogger class).

The basic problem here is that for singleton aspects, whilst underlying objects are implicitly instantiated in the aspect's constructor, there seems to be no way to correspondingly destruct or close these underlying objects. In a previous version of the project, I tried both making the Instrumentation aspect implement the AutoCloseable interface (and calling FileMetricLogger.Stop() and FileMetricLogger.close() in the aspect's close() method), and also overriding the Object.finalize() method, but in both cases the respective methods were not called. Additionally, in this previous version I did not have a pointcut defined on the TcpRemoteSender.close() method, and hence when running the SenderProgram the program would not end cleanly and had to be explicitly stopped with CTRL-break (the reason for this was that the worker thread created by the FileMetricLogger class was never stopped, and this prevented the main thread from also stopping).

It's not unusual that cross cutting code would require connections to external resources (files, databases, messages queues, etc...), and worker threads to manage these external resources. These external resources would likely be accessed through objects which need to be explicitly closed, stopped, or terminated to be released. I was surprised that AspectJ seems to have no way to release these external resources for singleton aspects.

Can be Difficult to Pinpoint Exact Code in Pointcuts

I mentioned that the original Method Invocation Remoting TcpRemoteSender class contained logging code for both status logging and for exception handling, and that in the Logging aspect I implemented only the status logging code. The reason for this was that it wasn't possible to write pointcuts which accurately reflected the location of exception handler logging code. Take the AttemptConnect() method as an example...

private void AttemptConnect() throws Exception { int connectAttempt = 0; while (connectAttempt <= connectRetryCount) { try { socketChannel.open(); socketChannel.connect(new InetSocketAddress(ipAddress, port)); break; } catch (IOException ioException) { logger.Log(this, LogLevel.Error, ioException.getClass().getSimpleName() + " occurred whilst trying to connect to " + ipAddress.toString() + ":" + port + ".", ioException); if (connectRetryInterval > 0) { Thread.sleep(connectRetryInterval); } } catch (Exception e) { throw new Exception("Error connecting to " + ipAddress.toString() + ":" + port + ".", e); } connectAttempt = connectAttempt + 1; } if (socketChannel.isConnected() == false) { throw new Exception("Failed to connect to " + ipAddress.toString() + ":" + port + " after " + connectAttempt + " attempts."); } }

In this method, if an IOException is caught when trying to connect, the exception is logged using the 'logger' member, and the connection retried. AspectJ advice can be written to intercept exceptions (using the 'after() throwing' declaration. However, pointcuts are fundamentally defined around method calls, not code within methods, so in the above case I couldn't see anyway to accurately replace the Log() method call with a pointcut. It would ofcourse be possible to put the call to Log() in a separate private method and define a pointcut around that method. However, applying this technique to all calls to Log() which manage exception handling would create many surplus, small private methods, and would make the code harder to understand and subsequently modify. It would also mean that the code of the class that the aspect targeted would have to be modified specifically to suit the aspect (which is arguably not good design... strictly speaking the class should know nothing about the existence of the corresponding aspect).

Unit Testing of Aspects is not Straightforward

The Method Invocation Remoting project includes unit tests which specifically test the logging and instrumentation functionality in the TcpRemoteSender class. This is facilitated by exposing a 'test' constructor which accepts instances of IApplicationLogger and IMetricLogger classes...

/** * Initialises a new instance of the TcpRemoteSender class. * <b>Note</b> this is an additional constructor to facilitate unit tests, and should not be used to instantiate the class under normal conditions. * @param ipAddress The remote IP address to connect to. * @param port The remote port to connect to. * @param connectRetryCount The number of times to retry when initially connecting, or attempting to reconnect to a TcpRemoteReceiver. * @param connectRetryInterval The interval between retries to connect or reconnect in milliseconds. * @param acknowledgementReceiveTimeout The maximum time to wait for an acknowledgement of a message in milliseconds. * @param acknowledgementReceiveRetryInterval The time between retries to check for an acknowledgement in milliseconds. * @param logger The logger to write log events to. * @param metricLogger The metric logger to write metric and instrumentation events to. * @param socketChannel A test (mock) socket channel. * @throws UnknownHostException If the specified IP address could not be resolved. */ public TcpRemoteSender(String ipAddress, int port, int connectRetryCount, int connectRetryInterval, int acknowledgementReceiveTimeout, int acknowledgementReceiveRetryInterval, IApplicationLogger logger, IMetricLogger metricLogger, ISocketChannel socketChannel) throws UnknownHostException { this(InetAddress.getByName(ipAddress), port, connectRetryCount, connectRetryInterval, acknowledgementReceiveTimeout, acknowledgementReceiveRetryInterval, logger, metricLogger); this.socketChannel = socketChannel; }

In unit test code, mocks of the IApplicationLogger and IMetricLogger interfaces are set on this constructor, and assertions made on these mocks to implement the tests. However, when the logging and instrumentation code is moved into aspects, unit testing is not so straightforward. Aspects only allow a single constructor with no parameters, so it's not possible to 'inject' mock loggers into the aspect for testing. The only way I can see that the instances of logger classes inside the aspect could be replaced with mocks, would be to use some type of singleton to provide the logger classes (e.g. use a factory-type pattern to provide instances of IApplicationLogger and IMetricLogger classes). In the normal use case, the factory could be configured to provide real instances of the logger classes, while in tests the factory could be configured to provide mocks. Having to use a singleton to instantiate aspects could however been seen as unfavourable, as it reduces the modularity of the code (as aspects then have a dependency on an external singleton or factory). Moreso a factory-type solution may not even be possible, if the standard singleton instantiation of aspects is used. Singleton aspects are instantiated when the aspect's classfile is loaded. This would occur before a factory object could be created in the program's main routine, and would likely result in a NullPointerException.

To me, this is a major and unfortunate deficiency in AspectJ. As more and more projects move towards a TDD paradigm, it's often a fundamental requirement that cross cutting code has unit tests written around it in critical systems (especially for concerns like instrumentation and particularly billing).

Corrections?

I am by no means an expert of AspectJ, and it's possible that it already includes functionality to overcome the problems I've listed above. Feel free to contact me if you think this is the case.

Further Questions

I didn't have any time to test or analyze the performance of AspectJ. I would be interesting to see whether AspectJ offered any performance benefit (or detrement) over implementing the cross cutting concerns in inline code.

Other Features

Inheritance

The Instrumentation aspect demonstrates how aspects can implement interfaces. Aspects can also be part of a complete inheritance hierarchy just as for regular Java objects (including defining abstract aspects, and extending other aspects). This is a really useful feature to reduce code repetition. Even in the basic example presented in AspectJDemo, the SendMessage() and Reconnect() pointcuts in the Logging and Instrumentation aspects are basically the same, and could be 'pulled up' into an abstract superclass ('superaspect'). The Logging and Instrumentation aspects could then extend this superclass.

Pattern Matching

The pointcuts demonstrated in AspectJDemo are defined around specific methods inside the TcpRemoteSender class. However AspectJ offers a lot of flexibility when defining pointcuts, including defining a pointcut across methods in all classes with certain arguments (using the 'args' keyword), using wildcards to specify a group of methods the pointcut should target, and defining pointcuts on subtypes of a specified type (See the pointcut language semantics and quick reference guide for more details).

Conclusions

AspectJ definitely achieves what it set out to do... that is clearly modularizing and separating cross cutting concerns from the main code. It's a mature framework, which is demonstrated by its rich feature set, and extensive set of options around defining pointcuts and advice. Based on the experience of building the AspectJDemo project, I would definitely consider using it to separate any instrumentation code... since the instrumentation code seems to always exist around method calls in a class, it lends itself well to being implemented using AspectJ (as pointcuts are also defined around method calls). I would be hesitant to use it for logging, as I believe logging requires a greater ability to pinpoint specific areas of code, than pointcut definitions allow (as described above when trying to log connect exceptions). My biggest concern though is with the ability to write unit tests around AspectJ code. As described, because aspects can't be explicitly instantiated, you're not able to inject mocks into aspects for the purpose of unit testing, and this could be a major issue for managing a code base around TDD and agile paradigms.

Download

The source code for AspectJDemo is available on GitHub.

Contact

Feel free to contact me via the details here with any questions or comments.