Use of Commons Logging

The apache commons logging (by default configured for log4j) should be used for all log and debug messages. The pricipal advantage of this practice is that the format and quantity of log information can be controlled at runtime, which makes it much easier for the admistrator to track problems.

Some notes on configuring log4j are on the forum here and here

Use of Logging Levels

Copied from Javadoc:

• FATAL: The FATAL level designates very severe error events that will presumably lead the application to abort.
• ERROR: The ERROR level designates error events that might still allow the application to continue running.
• WARN: The WARN level designates potentially harmful situations.
• INFO: The INFO level designates informational messages that highlight the progress of the application at coarse-grained level.
• DEBUG: The DEBUG Level designates fine-grained informational events that are most useful to debug an application.
• TRACE: The TRACE Level designates finer-grained informational events than the DEBUG

Best practice

1. Declare a logger

        private static org.apache.commons.logging.Log logger =
         org.apache.commons.logging.LogFactory.getLog(RegistryEntryBuilder.class);
        

2. log informational messages with

         logger.info("saved file to myspace"); 
        

   be reasonably sparing with these sort of messages so that the user looking at the logs can watch the normal progress of the application without being overwhelmed with information
3. log debug messages with

         logger.debug("querying registry at endpoint="+endpoint+" for key="+key);
        

   These messages can be considerably more verbose

Bad practice

Here are some examples of poor practice unbelivably taken from iteration 6 code, well after we had agreed on using commons logging.

Example 1

   private static boolean DEBUG_FLAG = true ;

        if (DEBUG_FLAG) System.out.println("") ;
        if (DEBUG_FLAG) System.out.println("----\"----") ;
        if (DEBUG_FLAG) System.out.println("FileStoreSoapDelegate()") ;
        if (DEBUG_FLAG) System.out.println("  URL : '" + endpoint + "'") ;

Errors

1. Not using commons logging - no run-time control!!
2. Using a static DEBUG_FLAG - no run-time control (the compile time saving of code size that this idiom is used for is just not worth it for logging) use the following idiom instead

              if(logger.isDebugEnabled() {
           logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
         }
        

   if you are worried about speed.
3. using multiple lines and separators is a bad idea because the commons logging allows the user to chose formatting options at runtime - any extra attempt at formatting such as the above just subverts this control. Just use a single logger statement per message. [Except for debug/trace level logs; some way of separating huge chunks of information can make the relevent bits much easier to locate - MCH]
4. you do not need to include any information about code location in the message as the log mechanism does that for you.
5. ...

   ########  #######   #######     ##     ## ##     ##  ######  ##     ## 
      ##    ##     ## ##     ##    ###   ### ##     ## ##    ## ##     ## 
      ##    ##     ## ##     ##    #### #### ##     ## ##       ##     ## 
      ##    ##     ## ##     ##    ## ### ## ##     ## ##       ######### 
      ##    ##     ## ##     ##    ##     ## ##     ## ##       ##     ## 
      ##    ##     ## ##     ##    ##     ## ##     ## ##    ## ##     ## 
      ##     #######   #######     ##     ##  #######   ######  ##     ## 
      ###     ######   ######  #### ####       ###    ########  ######## 
     ## ##   ##    ## ##    ##  ##   ##       ## ##   ##     ##    ##    
    ##   ##  ##       ##        ##   ##      ##   ##  ##     ##    ##    
   ##     ##  ######  ##        ##   ##     ##     ## ########     ##    
   #########       ## ##        ##   ##     ######### ##   ##      ##    
   ##     ## ##    ## ##    ##  ##   ##     ##     ## ##    ##     ##    
   ##     ##  ######   ######  #### ####    ##     ## ##     ##    ##    
   
   

   Which makes it difficult to filter the output with standard tools

Example 2

      log.debug("entered const(url) of RegistryService");
      if(DEBUG_FLAG) log.info("entered const(url) of RegistryService");

here there is an obvious misunderstanding of the hierarchy of possible levels that exist in the logger, that is DEBUG, INFO, WARN, ERROR and FATAL. If the output log level is set to a particular level then all messages at that level and above will be seen. So for instance if the level is set to INFO then no DEBUG messages will be seen, but all the WARN, ERROR and FATAL messages will be seen.

-- PaulHarrison - 05 Aug 2004

We should all help improving logging.

On a practical note, there's really handy plugin for Eclipse called Log4E that provides menu actions to add a commons logger to a class, instrument a method with log statements, and best of all, convert System.out.printlns to calls to the logger.

As code ownership is a bad thing anyway, I'd suggest that anyone encountering any logging code that is really dreadful just run Log4E over the whole damn lot. Fixing logging is a lot easier than some of our codes other faults.

While we're at it, I also recommend the CodeSugar eclipse plugin, which provides actions to auto-generate toString, equals and hashCode methods for a class. Much nicer than writing by hand - or not bothering with these methods at all.

One benefit of applying codeSugar to your classes is that you can then trivially dump whole object (trees) to the log, relying on the .toString() method to produce informative output.

-- NoelWinstanley - 05 Aug 2004

These automated tools are a good first step in making it easier to convert old code, but it is still essential for some thought to be applied in setting the correct level of detail and verbosity in info and debug messages

-- PaulHarrison - 06 Aug 2004

Tracing

At the Red Team meeting there was discussion over whether the if (DEBUG) idiom was still acceptable for trace logging. I'd like to re-iterate my objection to this practice, for all the same reasons as for other logging - lack of runtime controllability, inflexibility etc. If you're really concerned about performance, use a profiler. If that shows up a huge hit from your logging statements, switch them off using the if(logger.isDebugEnabled()... construct above. On a techie note, although commons-logging supports a trace method, log4j doesn't, so all trace calls just get mapped onto debug.

-- JohnTaylor - 06 Aug 2004