Enforcing a common log format with AspectJ
Enforcing a common log format with AspectJ
Andy Wilson has recently blogged about the need for uniformly formatted log messages containing all the necessary information to make log parsing easier and mentioned an extensive refactoring he did on a project to achieve this. One of the readers mentioned that he could save the effort of manually modifying the log statements and use AOP to add the formatting automatically. Well, here is the solution.Before we dive into the code, I should mention that I do not include a user name in the log, because it is not clear how to obtain it. If it was e.g. stored in a ThreadLocal variable, it would be easy to access it and include it in the log statement. Another thing is that if we could limit ourselves to Log4j instead of commons-logging, we could achieve the same with less effort using a custom formatter and perhaps Log4j's Nested Diagnostic Context.
The code is basically quite simple - we have one AspectJ aspect using the annotation-style, which intercepts calls to commons-logging's info(Object) and info(Object, Throwable) and re-formatts the message before handing it over to the actual logger.
package net.jakubholy.example.aoplog.aspect;
import org.apache.commons.logging.*;
import org.aspectj.lang.*;
import org.aspectj.lang.annotation.*;
@Aspect
public class LogFormattingAspect {
private static final Log LOG = LogFactory.getLog(LogFormattingAspect.class);
@Around("call(public void org.apache.commons.logging.Log.info(Object)) && args(msg) && !within(LogFormattingAspect)")
public Object formatMessageLog(
final Object msg
, final ProceedingJoinPoint invocation
, final JoinPoint.EnclosingStaticPart callerContext) throws Throwable {
return formatLogAndProceed(msg, null, invocation, callerContext);
}
@Around("call(public void org.apache.commons.logging.Log.info(Object, Throwable)) && args(msg, exception) && !within(LogFormattingAspect)")
public Object formatMessageLog(
final Object msg
, final Throwable exception
, final ProceedingJoinPoint invocation
, final JoinPoint.EnclosingStaticPart callerContext) throws Throwable {
return formatLogAndProceed(msg, exception, invocation, callerContext);
}
private Object formatLogAndProceed(final Object msg, final Throwable exception
, final ProceedingJoinPoint invocation
, final JoinPoint.EnclosingStaticPart callerContext
) throws Throwable {
final String callingMethod = callerContext.getSignature().getName();
LOG.info("Log.info has been called from the method " + callingMethod +
" with message=" + msg + ", exception=" + exception);
final Object[] arguments = invocation.getArgs();
arguments[0] = formatMessage(callingMethod, msg);
return invocation.proceed(arguments);
}
private String formatMessage(final String callingMethod,
final Object originalMessage) {
return "APPMSG: " + callingMethod + ": " + originalMessage;
}
}
If you are new to AspectJ then you need to understand that
- the methods annotated with @Around are invoked whenever Log.info(..) is called
- AspectJ provides values for the interceptor method's arguments including runtime and static information about the intercepted call, as represented by the *JoinPoint* instances
- those methods extract some information about the actual call and its arguments from the invocation context provided by AspectJ
- finally, they invoke the original intercepted method by calling proceed()
To apply the aspect to you code you need to weave them into it. You can choose either Load-Time Weaving (LTW), which uses Java 5's -javaagent option and instruments classes as they're loaded by the JVM based on configuration in an aop.xml file and which provides rather nice debugging output (when enabled), or Bytecode Weaving (also called build- or compile-time weaving), which injects the aspects into .class files using the command-line compiler/weaver ajc or AspectJ's Ant tasks. During development I prefer LTW, which is more flexible, but for use in a production environment it's better to weave the bytecode because LTW consumes more memory (due to custom classloaders) and CPU.
Try it out
The easiest way to try this out is to use Maven 2:- Download the source code archive aop-log-formatter-0.0.1-sources.jar
- Unpack them somewhere
- In the directory with the sources (namely pom.xml), execute mvn -Pexecute-from-sources compile exec:exec
- This will download some maven/project dependencies (a lot, if you don't use maven often, sorry), compile the sources and execute the application while printing its log to the console
- Download the source code archive aop-log-formatter-0.0.1-sources.jar
- Download also the compiled binaries aop-log-formatter-0.0.1.jar
- Download the dependencies, as recorded in the project's pom.xml (commons-logging, AspectJ weaver)
- Execute it with Load-Time Weaving (java 5 or higher required; it's assumed that all dependencies are in the same folder):
java -cp aop-log-formatter-0.0.1.jar:commons-logging-1.1.1.jar -javaagent:aspectjweaver-1.6.8.jar net.jakubholy.example.aoplog.ExampleLoggingClass
[INFO] [INFO] LogFormattingAspect - Log.info has been called from the method main with message=A message w/o an exception., exception=null [INFO] [INFO] ExampleLoggingClass - APPMSG: main: A message w/o an exception. [INFO] [INFO] LogFormattingAspect - Log.info has been called from the method main with message=Another message accompanied by an exception., exception=java.lang.RuntimeException: I'm the exception! [INFO] [INFO] ExampleLoggingClass - APPMSG: main: Another message accompanied by an exception. java.lang.RuntimeException: I'm the exception!You can see that the ExampleLoggingClass log message has been decorated with the prefix APPMSG and the method name (main).