Marc van Andel.nl

|

Logging Delegate

—

by

Marc van Andel
in ,

Logging is part of every application and we’re used to the lines of code which clutter our codebase with logger.info("something is happening here with {}" , var1); But is this great code? Or has this become the level of quality we’re familiar with? In the light of ”separation of concerns” (one and only one reason for change), ”same level of abstraction” (inspired by Clean Code of Uncle Bob) what would be the best practice to implement logging (without going to external solutions like AOP or alike)? Well, not really a question about the implementation of logging itself of course. SLF4J, LogBack, Log4j, Java Logging API and others are excellent implementations for logging info to a log file. The question here is about the best way to use a(ny) logger. Many developers will recognise the following lines (examples with org.slf4j.Logger):


private logger = LoggerFactory.getLogger(this.getClass());

or static final:


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

and using the declared logger:


public String doSomething(final String input) {
  logger.debug("doSomething START met input [{}]", input);
  String result = businessService.executeLogic(input);
  logger.info("doSomething FINISH input [{}], result [{}]", input, result);
  return result;
}

The first issue with this code snippet is the difference in level of abstraction. Using the logger with the full info being logged isn’t the same level as the executeLogic method call of a businessService. The following snippet has more equal abstraction levels:


public String doSomething(final String input) {
  logDoSomethingStart(input);
  String result = businessService.executeLogic(input);
  logDoSomethingFinish(input, result);
  return result;
}
 
public void logDoSomethingStart(final String input) {
  logger.debug("doSomething START met input [{}]", input);
}
 
public void logDoSomethingFinish(final String input, final String result) {
  logger.info("doSomething FINISH input [{}], result [{}]", input, result);
}

Although it is getting better there’s still an issue about the separation of concerns. There is reason to change this class for the actual logic being executed, calling a businessService, but also for the logging info. To separate these concerns the logging methods could be extracted into a loggingDelegate as a second class beside the current class. Taking into account it is a best practice to program against interfaces this would double the amount of interfaces and concrete classes. Each BusinessService interface would have a BusinessServiceLoggingDelegate interface as would the implementations BusinessServiceImpl and BusinessServiceLoggingDelegateImpl. This is not really an improvement of the whole code base, is it?

Solution

Well, what about a separate class without having a separate .java file: an ”inner class”. The not often used inner class might provide a solution here. This will not totally separate the concern outside the .java file but separates it on class level. An instance of the logging delegate could be named logger for the feel of it. The LoggingDelegate class could extend a general abstract implementation with common features.

The result:


/**
 * Example business service implementation only as example for application of the {@link LoggingDelegate} pattern.
 */
public class BusinessServiceImpl {

    private LoggingDelegate logger;

    public BusinessServiceImpl() {
        super();
        logger = new LoggingDelegate();
    }

    public String doSomething(final String input) {
        logger.logDoSomethingStart(input);
        String result = otherBusinessService.executeLogic(input);
        logger.logDoSomethingFinish(input, result);
        return result;
    }

    private static class LoggingDelegate extends Slf4jLoggingDelegate {

        public void logDoSomethingStart(final String input) {
            logger.debug("doSomething START with [{}]", input);
        }

        public void logDoSomethingFinish(final String input, final String result) {
            logger.info("doSomething FINISH with [{}], result: [{}]", input, result);
        }

    }

}

On Github is the working code example of above extract: https://github.com/marcvanandel/logging-delegate

A few final thoughts:

  • Applying this into a real world application my Sonar report does not improve with this pattern in place. On the contrary it decreases. So what is the problem?
  • One rule is not mentioned and forgotten: Is it testable? Maybe we should change the private accessor to default? And have some tests in the test companion object of the BusinessServiceImpl?

 

Top