Why We Need to Test with Logging Level FINEST

Does your team run a full test cycle with logging level FINEST? Probably not. From my experience in several projects, we are happy if all tests passed with default logging level. But there are good reasons why we need to include logging level FINEST in part of our testing:

• Expose application erros such as NullPointerException, ClassCastException, etc. They are buried deep in code blocks that are only executed with logging level FINE, FINER, or FINEST. In production environment, customers or field engineers turn on FINE logging level for userful info, not these nasty exceptions. Catch them early in testing. For example,
  

  if(logger.isLoggable(Level.FINE)) {
  logger.log(Level.FINE, user.toString());
  }

• Make sure sensitive data, such as password and account numbers are not logged anywhere at any levels.
  


• Expose any thread deadlocks caused by more frequent logging. Several commonly used classes are heavily synchronized, such as java.util.Logger, java.lang.ClassLoader, java.util.ResourceBundle, java.io.PrintStream, etc. In a multi-threaded application, it's easy to get into thread deadlocks, especially when java.util.Logger is invoked more frequently at FINEST level. For example,
  
  Thread A holds a lock on its context classloader to load a class, and also tries to acquire a lock on logger to log some FINE messages : Loading class with Class.forName(classname).
  
  Thread B holds a lock on the same logger to do some logging, which invokes ResourceBundle.loadBundle(), which in turn invokes ClassLoader.loadClass(), which requires a lock on the class loader. Therefore, thread A is holding a lock on context classloader and waiting on a lock on logger; thread B is holding a lock on logger and waiting on a lock on the context classloader, hence the deadlock.
  

To fix the above bug, don't call any logging-related methods inside synchronized methods of a classloader.

Tags: java, JDK, java testing, java.util.Logger, java logging, java deadlock, java thread