Adding Versatility to Java Logging Aspect

Logging plays a key role in software development, helping troubleshoot live applications. Log messages, therefore, need special attention and be curated to be clearly made out. 

A large enterprise application usually hosts different types of logging strategies and may not log every single, relatively unimportant message in a production environment, unlike in a development environment. This helps save storage and boosts performance. Purging older logs follows organizational policy, and logging comes at the cost of performance, though we may not apparently feel the latency of milliseconds on lower environments catering to much less load than on the production. 

Like code and documentation, logging itself is often boilerplate and manual and thus prone to human errors. To avoid human errors, such as the omission of a log message, or to get rid of boilerplates, we often resort to using Aspects in Java applications. Logging on a method or methods of a class becomes dynamically woven. This article deep dives and illustrates how a logging aspect may be boosted to make the most of it. 

Brief About Using Aspect in Logging

Let us look at the code snippet in [Listing-1] showing a traditional good old approach of using SLF4J to log method execution time and metrics:

public void someMethod(String arg0, String arg1, int arg2) {
		long ts=System.currentTimeMillis();
		log.debug("someMethod invoked : arg0: {} arg1: {} arg2: {}",arg0,arg1,arg2);
		// business operations 
		// ...
		//.......
		log.debug("someMethod returns. Took {} millseconds",(System.currentTimeMillis()-ts));
	}

[Listing-1]

The above code snippet, however, uses generalized methods and parameter names. 

The log object may be obtained via any of the following without loss of generality:

1. Logger logger=Logger.getLogger("logger-1"); // For Java 8 or lower versions       // without third-party dependencies 
2. java.lang.System.Logger logger=System.getLogger("sysloger"); // Java 9 or  // higher with or without third-party dependencies 
3. Using SLF4j implementation such as Log4j/Log4j2 / Logback, etc., directly or indirectly, such as by using my favorite Lombok annotation that generates the code via APT. @Slf4j

The approach, regardless of how and what we create as a log object, remains the same. 

This approach has the following pitfalls: they are manual and hence prone to error and are, of course, boilerplates, which Aspects help mitigate. Aspects are instrumented triggers that may be used with or without the Spring framework, though Aspect Oriented Programming often infers usage of the latter. This article, however, uses Spring Aspect throughout and including the example we are going to revisit shortly on how a Logging Aspect might have been used in [Listing-1]. 

We create a custom annotation and an Aspect that triggers around the methods annotated with it. 

@Documented
@Retention(RUNTIME)
@Target(ElementType.METHOD)
public @interface LogExecutionTime {
}



@Component
@Aspect
@Slf4j
public class LoggingAspect {

	
@Around("@annotation(com.somecompany.pkg.annotation.LogExecutionTime)")
	public Object aroundMethodExecution(ProceedingJoinPoint joinPoint) throws Throwable {
		long start = System.currentTimeMillis();

		Object result = joinPoint.proceed();
		long executionTime = System.currentTimeMillis() - start;
		log.info("{} took {} milliseconds to execute",jointPoint.getSignature().getName(),executionTime);
		}
       	return result;
	}

[Listing-2]

The aspect logs the execution time of methods along with their names. Nothing new hitherto has been discussed, and the assumption has been that the audience is aware of the Spring framework, custom annotation, and aspects. Should one require a quick reference or revision, any study material, including official documentation of Spring and Java, may be referred to. The next section is dedicated to an approach we have used and benefited from and that we use across different projects as good as a library. 

Adding Sophisticated Features to the Logging Aspect

We added to add sophisticated features to our logging aspect as we were not content with just method execution time. We wanted to have log levels in the aspect. As we discussed earlier in the chapter, LEVEL plays a crucial role in logging. Having the ability to switch log level is, therefore, indispensable. Also, having provision to log method parameters and return value, if one, would have been fine-grained. 

While loggers come with their respective conversion patterns, such as log4j, which offers an XML-based approach to configure almost everything and not just the Conversion Pattern and Layout of Appenders, it’s worth noting that some projects are designed to follow a pre-defined message pattern regardless of the configuration. The reason for doing so may be to not blindly rely on a configuration and chance losing the usual search patterns. An organization may wish to have all the microservices it owns log a message like “className  ##   methodName ## logMessage.” We wanted the conversion pattern, too, to be customizable in the logging aspect.

The code snippet in [Listing-3] shows an enhanced version of the annotation LoggingAspect:

@Retention(RUNTIME)
@Target(ElementType.METHOD)
public @interface LogExecution {

	public Class<? extends LogFormatter> formatter() default LogFormatter.class;
	public String level() default "info";
	public boolean logResult() default false;
	public boolean logParams() default false;
	
}

// The LogFormatter class looks like this:

public class LogFormatter {
	public  String format(MethodSignature methodSignature ,Object result) {
		return String.valueOf(methodSignature.getDeclaringTypeName()+" :: "+methodSignature.getName()+"[] :: "+ result);
	}
}

[Lisiting-3]

Using the Logging Aspect

@LogExecution(logResult = true,level ="info",logParams = true,formatter = SimpleLogFormatter.class)
	
public Object someMethod(String x,int y) {
		try {
			TimeUnit.SECONDS.sleep(3); // Intentional, NoOp delay 
		} catch (InterruptedException e) {
		}
		return "x = "+x+" y= "+y+" Now it's "+LocalDateTime.now();
}


public class SimpleLogFormatter extends LogFormatter {

@Override
public String format(MethodSignature methodSignature, Object result){
		
		return methodSignature.getName()+"---->"+result;
}

}

[Listing-4]            

    So, we pass the following to it: 

1. Whether to log the method’s return value
2. Level of the log
3. Whether to log parameters passed to the method
4. And finally, a transformer Class, which subclasses the LogFormatter                 

This is a sample log of the above method:

024-01-10 01:09:27.971[0;39m [32m INFO[0;39m [35m12904[0;39m [2m---[0;39m [2m[nio-8080-exec-1][0;39m [36mio.spb.ordered.a.aspect.LoggingAspect   [0;39m [2m:[0;39m someMethod---->x = John y= Doe Now it’s 2024-01-10T01:09:27.961848100 

We can update the formatting by providing a relevant sub-class of LogFromatter and using it as the formatter. 

Finally, we can keep on adding features and make it more and more sophisticated. However, the full source code is provided here so that readers may jointly take it ahead.