Logging, Blessing and Curse

http://www.slf4j.org/

Logging can be blessing or curse...

No doubt that logging saves lives of developers and system administrators. But the truth is in inadequate hands it can turn to be a suicide.

Developers and system administrators not using it sensibly, can hit their application with a great performance penalty...!


I am a developer, so the main focus will be on the developers' view of how logging should be implemented.

Advises on what to use

First of all, given that we all use common libraries from all around the projects around the glob, as all projects use different logging implementations namely; commons-logging, jul, log4j, etc., I recommend using slf4j as the base of your logging facility. slf4j, by replacing the common logging classes with proxy versions, allows one to divert all logging - both from within application and the libraries used by the application - to a common real logger. And as for the real logger I advise going with log4j.


Base Project Set up a-la Maven

Here is a set up in maven to archive the structure advised above:

<project>
 <!-- ... -->

 <properties>
  <slf4j.version>1.6.4</slf4j.version>
 </properties>

 <!-- ... -->

 <dependencies>

  <!-- ... -->

  <!-- Logging -->
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-api</artifactId>
   <version>${slf4j.version}</version>
  </dependency>
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-log4j12</artifactId>
   <version>${slf4j.version}</version>
  </dependency>
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>jcl-over-slf4j</artifactId>
   <version>${slf4j.version}</version>
  </dependency>
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>jul-to-slf4j</artifactId>
   <version>${slf4j.version}</version>
  </dependency>

  <!-- ... -->
  
 </dependencies>
 
 <!-- ... -->
 
</project>

Best Practices on How to Code Logging

Now that we have the base set up done, we can move onto how to code the logging.

1. Always check if a particular log level is enabled. The reason for that is you only construct the full log string if it really can be logged.

//BAD
this.logger.debug("Creating customer: customer Id " + customer.getId() + " customer name: " + customer.getName());
  
//GOOD
if (this.logger.isDebugEnabled()) {
 this.logger.debug("Creating customer: customer Id " + customer.getId() + " customer name: " + customer.getName());
}







Better, use log statements constructed with parameters. This will help the maintainer of the code to add in appropriate new parameters to log statement easily.


//BAD
this.logger.debug("Creating customer: customer Id: " + customer.getId() + " customer name: " + customer.getName());

//GOOD
if (this.logger.isDebugEnabled()) {
 this.logger.debug(MessageFormat.format("Creating customer: customer Id: {0}, customer name: {1}", customer.getId(),  customer.getName()));
}


Separate out the log files in your application for modules. Again this will serve the same purpose as before. The one who is looking at your logs will start with a finer grained location.

On the flip side,  going with too much segmentation will make the log observer unable to synchronize the events scattered in different files.

So use your instincts on that one.
If you use log4j, turn on the great feature log4j has, configureAndWatch facility.

This will allow system administrators to alter logging configuration or put the gear on DEBUG from INFO as needed without having restarted the application. This is especially come handy in server applications in high SAL requirements.
During development, if you need to see the debug level information, change your log configuration, not the level of i.e. trace() to info() or error(). You may easily forget to change it back to original and you can cause a great deal of performance degradation to your application.
Last but not the least, carefully select the appropriate log level. Making a should-be DEBUG log statement INFO, level will confuse other developers and system administrators, and will cost them more time to find what they are looking for in the logs.

A Base Logger for Your Application 

Having suggested slf4j previously, I still see an improvement for slf4j. I have submitted a an enhancement to slf4j, which I think a better Logger implementation.

This is fully parameterized Logger implementation with automatic checks for level availability.

Until (or never) it makes it to the mainstream, you may download the attachment from the enhancement to use it as your Logger implementation.

For System Administrators

1. Never turn DEBUG log on on a production unless you are in hunt for a cause of a system error or malfunction. Better set it to WARN to avoid even INFO logging performance penalty if there is no logical reason to keep INFO level log.
2. If you are required / asked to switch to DEBUG log, then turn it back on previous level when the requirement or sample collection is over.
3. Keep an eye on size of your log files. A file system partition filed with logs may render your application down.
   
   You may automatize this with appropriate implementation of DailyRollingFileAppender.
4. For the sake of being on the safe side, keep logs in a separate log file system partition.

Summary

In my experience of +15 years of Enterprise software development, I have seen cases where inappropriate use of logging can easily (believe me very easily ) cause you application performance to drop 1 / 4 or even 1 / 10.

So use it sensible or not use it at all. And also train your developers and system administrators on it.