Slf4j Custom Logger using customized toString

Introduction:

The object details such as its attribute values during course of program run is extremely valuable during troubleshooting. This amount of information usually turns out as too voluminous or as sparse. In order to be safe than sorry the developers usually put all attributes in the toString method. The aggravating problem thus is when the objects presented have deeply nested value object structures within; or, if they are in a collection; resulting in object details occupying pretty much the whole of real-estate in the debug log file leaving marginal space for the trace of program flow. Though the modern logging frameworks already do provide a certain level of coarsening with each emitted line bound to a log level such as DEBUG, INFO, the object data stays fairly high as toString method is not log-level sensitive.

Issues at a glance:

Recently i was in a situation; where the voluminous logging seemed seriously intimidating and the goal was To control the amount of information logged from an object in correspondence with logger level. I surmised that the following issues are blocking doing this objective.

1. The objects typically have the toString method statically available to print one-and-only one form of string representation of the object irrespective of levels of fine-grain-ness desired.
2. The loggers that we use (such as Slf4j with log4j for eg) always use this implicit toString method of an object in its core logging methods

Strategy:

The strategy to solve this issue is as follows

1. Define an enum LevelOfDetail to indicate different levels of details to be logged such as brief, medium, none and all for eg; which could be easily mapped to log levels.
2. Define an interface say for eg: LevelledToString having a method toString(LevelOfDetail) that can respond to desired levels of detail with appropriate amount of information on the object. 
3. Make value objects implement LevelledToString (Get this done either manually or take help of annotations and code-generators such has eclipse xtend)
4. Next build a flavour of Slf4j's Log4jLoggerAdapter such that the logger actually calls toString(LevelOfDetail)on LevelledToString instances (even in case of nested/collection) rather than the implicit toString method for logging value objects.
5. Glue this new logger adapter using standard mechanisms as defined/documented by Slf4j such that clients of  existing Slf4j logger are oblivious to the use of this new replaced logger.

Sample:

While the other below sections provide some insight into what has been done here is a quick sample. The level-log-sample is housed in slf4j-custom-logger repo. Please remember this is not a maven module under slf4j-custom-logger and hence the level-logger and level-tostring dependent modules need to be built first, installed locally and then used as follows in the instruction set.

1. Say you are at  c:\workspaces folder
2. git clone https://github.com/venkateshamurthy/slf4j-custom-logger.git
3. cd c:\workspaces\slf4j-custom-logger
4. mvn clean install { This installs level-logger, level-tostring to local-repository to say ${user.home}/.m2/repository
5. Next cd c:\workspaces\slf4j-custom-logger\level-log-sample
6. [this is an independent project (not part of the parent pom slf4j-custom-logger)]
7. [Assumption: level-logger, level-tostring to local-repository in ${user.home}/.m2/repository. will need to move the re-usable dependencies to OSSRH subsequently.]
8. mvn clean test exec:java -Dexec.mainClass="com.github.venkateshamurthy.util.logging.Sample" -Dexec.classpathScope="test"

Approach:

This section details a few interfaces and classes that are key to materialize the strategy mentioned before.

Reference : Please refer to the code at: https://github.com/venkateshamurthy/slf4j-custom-logger

Changes on the object:

1. Come up with an enum LevelOfDetail and an associated interface LevelledToString  to use the same in a toString overloaded method
2. Develop all value objects implementing LevelledToString - in case if you want to manually do.
3. Develop an annotation @ToLevelledStringAnnotation that can allow definiton of what attributes to print at what level say for eg:(brief={"attr1","attr2"})
4. Develop annotation processor that reads this annotation and regenerates the source code along with toString(LevelOfDetail) met/hod written

LevelOfDetail and LevelledToString:

The Level of Detail can be assumed to be an enum that may or may not implement an interface such as :

As an example to this interface (constructors/setters left out for brevity):

Changes on Logger:

1. Develop a new CustomFormattingLog4jLoggerAdapter (and may be an abstract class to hold common methods)
1. Abstract class to hold common methods
2. concrete class to deal with custom Message formatting
2. Wrap the existing 
1. SLf4j MessageFormatter into an adapter interface (IFormattingTupleFactory)
2. FormattingTuple into IFormattingTuple implementation  just so we could add additional derivatives . (For eg: when we need a customized to string format in the message formatting)
3. As documented by slf4j;
1.  define a customized logger adapter factory bound to ILoggerFactory and have this customized factory produce instances of CustomFormattingLog4jLoggerAdapter 
2. Add StaticLoggerBinder in org.slf4j.impl package and bind  customized logger adapter factory so that clients of SLF4J loggers are transparently handed the new logger

Summary:

In summary; the logging needs have grown beyond rudimentary level based logging such as debug, info. The current times demand for log-level sensitive printing of object attributes just at the tap of annotation declaration say such as @ToLevelledString(brief={"attr1","attr2"}) on an class containing several attributes including say attr1, attr2. 

In this experiment; i was able to develop a customized logger (along with other slf4j eco-system classes) and the interface for objects to implement dynamic toString. In the near future would experiment with some annotation libraries to get the automation of toString(LevelOfDetail) generation and update this post.

Details:

The New Log4jLoggerAdapter:

The new flavour of Log4jLoggerAdapter can take a form an abstract class implementing the very same MarkIgnoringBase class which even Log4jLoggerAdapter also extends to hold most mundane/ repeated/boiler-plate code leaving the interesting toString handling to a small concrete class.

The abstract class AbstractLog4jLoggerAdapter has one abstract method called doLog which consumes a Slf4jLevel (this again is a enum representation of different log levels of Slf4j as Slf4j doesnt natively provide an level enumeration.)

   /**

    * This method does Level enabled formatting and logging.
    *
    * @param slf4jLevel
    *           the {@link Slf4jLevel} passed
    * @param format
    *           message format in the standard slf4j marker format {}
    * @param args
    *           to be passed to the logging
    */
   protected abstract void doLog(final Slf4jLevel slf4jLevel, final String format,
         final Object... args);

Custom adapter (CustomFormattingLog4jLoggerAdapter):

The concrete class that extends above doLog method requires few supporting classes/interfaces to achieve the level based printing of object attributes. The Slf4j uses a helper class called MessageFormatter to read the message pattern and an argument array to create instances of FormattingTuple which further would be used to actually log. The logic to convert an object to an appropriate format/style is the responsibility of MessageFormatter.

However there is a slight catch that both MessageFormatter and FormattingTuple dont implement an interface say unlike Log4jLoggerFactory which is crucial to have extensibility and pluggability of different formatters for example. To circumvent this; we could take refuge to superpose an interface called IFormattingTupleFactory and IFormattingTuple and write a small adapter to wire the existing MessageFormatter and FormattingTuple as adaptees and use it as follows (Check the doLog method).

We could call this adapter ass CustomFormattingLog4jLoggerAdapter; just so to indicate  more specialization on customized string representation during logging.  

/**
 * The Class CustomFormattingLog4jAdapter allows a custom {@link IFormattingTupleFactory formatting
 * tuple factory} to be used to provide a customized string representation in Log statements.
 */

import org.apache.log4j.Level;
import org.apache.log4j.LogManager;
import org.slf4j.Logger;
import org.springframework.util.ObjectUtils;

public class CustomFormattingLog4jLoggerAdapter extends AbstractLog4jLoggerAdapter {

:

:

:
   @Override
   protected final void doLog(final Slf4jLevel slf4jLevel, final String format, final Object... args) {
      Level level = slf4jLevel.getLog4jLevel();
      if (logger.isEnabledFor(level)) {
         Level effectiveLevel = level == Level.TRACE ? effectiveTraceLevel() : level;
         IFormattingTuple ft;
         if (args != null && args.length == 1) {
            ft = args[0].getClass().isArray()

                 ? tupleFactory.arrayFormat(slf4jLevel, format, ObjectUtils.toObjectArray(args[0])) 

                 : tupleFactory.format(slf4jLevel, format, args[0]);
         } else if (args != null && args.length == 2) {
            ft = tupleFactory.format(slf4jLevel, format, args[0], args[1]);
         } else {
            ft = tupleFactory.arrayFormat(slf4jLevel, format, args);
         }
         logger.log(FQCN, effectiveLevel, ft.getMessage(), ft.getThrowable());
      }
   }
}

The CustomFormattingLog4jLoggerFactory

The CustomFormattingLog4jLoggerFactory is a simple implementation that just creates our logger.

The FormattingTuple and its factory 

The formatting tuple is adapted to an interface IFormattingTuple just so that any future variation in that can be dealt with differing implements of IFormattingTuple . Similarly the factory to produce the IFormattingTuple.

Glue class StaticLoggerBinder

Beyond these the glue class StaticLoggerBinder will need to be placed in org.slf4j.impl package to get the necessary glue working.