Using Generic 'log' Methods in Java Logging

When developing Java applications, it is easy to get used to invoking logging on the provided logger via its log level-specific methods. For example, Log4j's Logger provides methods such as Logger.info(Object), Logger.warn(Object), Logger.error(Object), and Logger.fatal(Object) and java.util.logging's Logger provides methods such as Logger.info(String), Logger.warning(String), and Logger.severe(String). These methods have names that explicitly convey the level at which the message is logged and often work well. However, there are situations when the code can be cleaner and the logging more efficient when a more generic logging method is used. In this blog post, I look at Log4j's overloaded Logger.log methods and java.util.logging's overloaded Logger.log methods.

The next example is a little contrived, but should suffice. It demonstrates logging at a specific level (INFO in this case) using java.util.logging.

Code Listing One

/**
    * Divide the provided dividend by the provided divisor and return the quotient.
    *
    * @param dividend Number to be divided.
    * @param divisor Number by which dividend is to be divided.
    * @return Quotient of dividend divided by divisor.
    */
   private double divide(final double dividend, final double divisor)
   {
      final double quotient = dividend / divisor;
      LOGGER.info("Quotient of " + dividend + " divided by " + divisor + " is " + quotient + ".");
      return quotient;
   }

The logging statement in the above code will always log at INFO level if it logs at all (only logs if INFO-level logging is turned on). This might be satisfactory in most cases, but one might want it to be a higher level if the divisor is zero. Before getting to that, though, I want to take a side detour and look at NetBeans 6.9's hint that highlights the line of code above with the log statement. The next screen snapshot shows the above code again, but this time as it is rendered in the NetBeans editor window with the logging line highlighted with a hint.

This particular hint (Inefficient use of string concatenation in logger) is not one of the hints that I highlighted in my earlier post Seven Indispensable NetBeans Java Hints, but I'll follow its recommendation here. When I select the option to have NetBeans automatically address this hint ("Convert string concatenation to a message template"), it changes the code as shown in the next two screen captures and code listing.

The code has been changed by NetBeans 6.9 to that shown in the next code listing.

Code Listing Two

/**
    * Divide the provided dividend by the provided divisor and return the quotient.
    *
    * @param dividend Number to be divided.
    * @param divisor Number by which dividend is to be divided.
    * @return Quotient of dividend divided by divisor.
    */
   private double divide(final double dividend, final double divisor)
   {
      final double quotient = dividend / divisor;
      LOGGER.log(Level.INFO, "Quotient of {0} divided by {1} is {2}.", new Object[]{dividend, divisor, quotient});
      return quotient;
   }

Accepting the NetBeans hint's automatic fix changed the explicit call to Logger.info to instead call the more generic Logger.log method. In this case, a driving reason for the change seems to be the availability in the Logger.log method to support a message String with object parameters to the String. Although it is not surprising that NetBeans would change from the explicit and specific info method to the more generic log method to take advantage of the message String with object parameters, that is not the only reason one might prefer the more generic log method.

To illustrate another reason for using the more generic log method in some cases, I go back to the code as originally listed in Code Listing One with a twist. In Code Listing Three, I have modified that code to change its log level depending on runtime information.

Code Listing Three

/**
    * Divide the provided dividend by the provided divisor and return the quotient.
    *
    * @param dividend Number to be divided.
    * @param divisor Number by which dividend is to be divided.
    * @return Quotient of dividend divided by divisor.
    */
   private double divide(final double dividend, final double divisor)
   {
      final double quotient = dividend / divisor;
      if (Double.doubleToLongBits(divisor) == 0)
      {
         LOGGER.warning("Quotient of " + dividend + " divided by " + divisor + " is " + quotient + ".");
      }
      else
      {
         LOGGER.info("Quotient of " + dividend + " divided by " + divisor + " is " + quotient + ".");
      }
      return quotient;
   }

In the above code, the same statement is potentially logged at different levels depending on a runtime condition. Suppose that the application was run with logging only enabled for warning and more significant log levels. In such a hypothetical situation, only the case with a divisor of zero would be logged and the "normal" cases would not. This might be intentional because only the zero divisor situation might require typical logging. The code could be slightly improved by avoiding duplicate String literals. This is shown in Code Listing Four.

Code Listing Four

/**
    * Divide the provided dividend by the provided divisor and return the quotient.
    *
    * @param dividend Number to be divided.
    * @param divisor Number by which dividend is to be divided.
    * @return Quotient of dividend divided by divisor.
    */
   private double divide(final double dividend, final double divisor)
   {
      final double quotient = dividend / divisor;
      final String message = "Quotient of " + dividend + " divided by " + divisor + " is " + quotient + ".";
      if (Double.doubleToLongBits(divisor) == 0)
      {
         LOGGER.warning(message);
      }
      else
      {
         LOGGER.info(message);
      }
      return quotient;
   }

Code Listing Four makes it more obvious that the String is the same in both logging cases. Incidentally, it also is rendered without NetBeans hint because the string concatenation is not within the logging statement.

Changing the log call to use the generic Logger.log allows the developer to only need to specify the log statement once. This is demonstrated in Code Listing Five.

Code Listing Five

/**
    * Divide the provided dividend by the provided divisor and return the quotient.
    *
    * @param dividend Number to be divided.
    * @param divisor Number by which dividend is to be divided.
    * @return Quotient of dividend divided by divisor.
    */
   private double divide(final double dividend, final double divisor)
   {
      final double quotient = dividend / divisor;
      final String message = "Quotient of " + dividend + " divided by " + divisor + " is " + quotient + ".";
      final Level logLevel = 
           Double.doubleToLongBits(divisor) == 0
         ? Level.WARNING
         : Level.INFO;
      LOGGER.log(logLevel, message);
      return quotient;
   }

Code Listing Five demonstrates the ability to set the log level at runtime with a single conditional ternary operator and then only have one log statement that will log at the appropriate level given runtime differentiation.

So far, the discussion has centered around java.util.logging. However, Log4j provides similar support both for methods with name specific to a logging level and for more general logging methods based on a provided log level. Code Listing Six is shown next and provides the Log4j equivalent of Code Listing Five.

Code Listing Six

/**
    * Divide the provided dividend by the provided divisor and return the quotient.
    *
    * @param dividend Number to be divided.
    * @param divisor Number by which dividend is to be divided.
    * @return Quotient of dividend divided by divisor.
    */
   private double divide(final double dividend, final double divisor)
   {
      final double quotient = dividend / divisor;
      final String message = "Quotient of " + dividend + " divided by " + divisor + " is " + quotient + ".";
      final Level logLevel = 
           Double.doubleToLongBits(divisor) == 0
         ? Level.WARN
         : Level.INFO;
      LOGGER.log(logLevel, message);
      return quotient;
   }

The code for the Log4j example is almost identical to the java.util.logging example. One of the only differences is that java.util.logging's warning-level constant is Level.WARNING while Log4j's similar constant is Level.WARN. I obviously also had to import different Logger and Level classes in both cases.

Having a dynamic log level can also be useful when writing logging guards. There are numerous cases where it is most efficient to check if a given log level is applicable before trying to log to that level. This is especially the case when long-running logic is necessary to build up the String to be logged and can include explicitly or implicitly called toString() implementations.

I will be using the nonsensical SlowToString class (shown in Code Listing Seven) to illustrate the value of logging guards and how to use dynamic resolution of logging level in conjunction with such guards. Although the SlowToString class is nonsense, it simulates the potential inefficiencies of logging String representations of objects with complex toString() methods.

Code Listing Seven: SlowToString.java

/**
 * Class with intentionally slow toString() implementation.
 *
 * @author Dustin
 */
public class SlowToString
{
   @Override
   public String toString()
   {
      try
      {
         Thread.sleep(Integer.MAX_VALUE);
      }
      catch (InterruptedException threadEx)
      {
         // this is really bad; don't do this!!!
      }
      return "";
   }
}

In this extreme case, logging of any messages that invoke SlowToString's toString() method will be held up a painfully long time. Code Listing Eight shows a piece of code that would suffer from this with java.util.logging.

Code Listing Eight

/**
    * Demonstrate logging of object with slow toString() implementation.
    */
   private void demonstrateLoggingGuard()
   {
      final SlowToString slow = new SlowToString();
      LOGGER.finer(slow.toString());  // toString must be explicitly called
   }

Developers new to Java might think that the delay of SlowToString's toString() method will only be incurred if logging at FINER level is enabled. Unfortunately, that is not the case. The toString() above will always be invoked regardless of level. In fact, even code as shown in Code Listing Nine will have the same unsatisfactory delay.

Code Listing Nine

/**
    * Demonstrate logging of object with slow toString() implementation.
    */
   private void demonstrateLoggingGuard()
   {
      final SlowToString slow = new SlowToString();
      LOGGER.setLevel(Level.SEVERE);
      LOGGER.finer(slow.toString());   // toString must be explicitly called
   }

Even explicitly setting the logging level to be SEVERE is not sufficient to prevent the SlowToString.toString() method from being invoked. A logging guard is needed. This is demonstrated in Code Listing Ten for this java.util.logging-based example.

Code Listing Ten

/**
    * Demonstrate logging of object with slow toString() implementation.
    */
   private void demonstrateLoggingGuard()
   {
      final SlowToString slow = new SlowToString();
      if (LOGGER.isLoggable(Level.FINER))
      {
         LOGGER.finer(slow.toString());   // toString must be explicitly called
      }
   }

When Code Listing Ten is executed, it will only bother trying to build up the long-running toString() implementation if the logging level is set to at least FINER. There's a maintenance issue with this code, however. One could, especially if the code base was much larger, change one level (either the logging statement or the guard) without changing the other. If the guard was changed to a less severe log level (finest), the log statement would never get run despite it still using the "finer" method. That is likely to be less of a problem than the other possibility: if the guard is more restrictive (say INFO), then the performance cost would be incurred anyway despite the guard and even though nothing would actually get logged. The solution for this to be more maintainable is to set the log level once and then use that same set log level for the guard and for the logging statement itself. This is demonstrated in Code Listing Eleven.

Code Listing Eleven

/**
    * Demonstrate logging of object with slow toString() implementation.
    */
   private void demonstrateLoggingGuard()
   {
      final SlowToString slow = new SlowToString();
      final Level logLevel = Level.FINER;
      if (LOGGER.isLoggable(logLevel))
      {
         LOGGER.log(logLevel, slow.toString());   // toString must be explicitly called
      }
   }

Use of the more generic log method as demonstrated in Code Listing Eleven allows the guard and the logging statement itself to remain synchronized in terms of level. When the developer wishes to change the level of this particular logging, he or she can do so by changing only one line (where the logLevel variable is set). This is even potentially more powerful when one considers combining this with the ability to set this level dynamically as shown earlier in this post. The guards and the individual logging statements can potentially be controlled in a synchronized fashion based on dynamic runtime considerations. That's pretty powerful stuff!

All of the above discussions apply to Log4j as much as they apply to java.util.logging. Log4j has guard methods with specific levels in their names just as it does for the logging methods. For example, it has methods like Logger.isTraceEnabled(), Logger.isInfoEnabled(), and Logger.isDebugEnabled(). Fortunately, Log4j also provides a generic form of the guard method similar to that provided by java.util.logging. Log4j's Logger.isEnabledFor(Priority) method can be used as a generic logging guard.

Code Listing Twelve provides a rough Log4j equivalent to the java.util.logging example.

Code Listing Twelve

/**
    * Demonstrate logging of object with slow toString() implementation.
    */
   private void demonstrateLoggingGuard()
   {
      final SlowToString slow = new SlowToString();
      final Level logLevel = Level.DEBUG;
      if (LOGGER.isEnabledFor(logLevel))
      {
         LOGGER.log(logLevel, slow);  // Look Ma!  No toString() required!
      }
   }

Because Log4j's logging methods accept an Object rather than a String, the toString() method does not need to be explicitly called for Log4j. This means that the toString() might even be called without the developer realizing it. Using Log4j's Logger.isEnabledFor(Priority) method allows the developer to again synchronize the level of the guard with the level of the message or messages being logged.

Beyond Log4j and java.util.logging

I have focused on Log4j and java.util.logging in this post. Although these are dominant Java logging frameworks, many Java developers like to use higher level logging APIs such as Apache Commons Logging or Simple Logging Facade for Java (SLF4J). I typically use one of the frameworks (Log4j or java.util.logging) directly, so I'm not familiar with these other frameworks. That being stated, it appears that Apache Commons Logging's Log interface does not provide for generic logging methods or generic guard methods. As far as I can tell, SLF4J's Logger interface similarly does not support generic logging and guard methods either. If anyone knows differently than this, please let me know via feedback comment. Because SLF4J and Apache Commons Logging are largely "wrappers"/"facades" for Log4j and java.util.logging, it seems that the generic support for logging and guard checking provided by those underlying libraries could be "passed through."

Conclusion

In many situations, the developer knows what at which level logging needs to occur and, if the logged string is literal or quick to generate, use of the level-specific logging methods may be easiest, cleanest, and most readable. However, when the level of logging is more dependent on runtime conditions than development time conditions or when guards need to be synchronized with the log method(s) invoked within the guard, the ability to log generically to a runtime-provided level allows the code to be more efficient, more maintainable, and more consistent.

Additional Reading

I thought of writing this post based on recent publication of blogs related to effective logging practices. These included The Dark Art of Logging (discusses importance of logging at appropriate level and using logging guards) and Logging Do's and Dont's (tightly associated with use of SLF4J).