To begin with, I'm a big fun of logging. In fact, I rarely use a debugger and only as a last resort. I've always believed that code is best debugged in your "head", as long as you know what you are doing. (It could be also that I'm just a louzy IDE user :)

 

For a long time, I admired the JBoss org.jboss.logging.Logger "wrapper" for a couple of reasons: the API is small, simple, and it only includes 5 + 1 levels of logging: ERROR, WARN, INFO, DEBUG & TRACE. (there is the FATAL level, but I doubt if it is ever used, it should be removed, really.)

 

Whenever you want to log something, it is almost a no-brainer to pick up the right logging level:

  • ERROR - A definite problem
  • WARN - Likely a problem, but can live with it
  • INFO - Common notifications, lifecycle stuff
  • DEBUG - Low volume debug
  • TRACE - High volume debug
(Compare this to java.util.logging.Logger ALL, CONFIG, FINE, FINER, FINEST, INFO, OFF, SEVER, WARNING, levels, or the entering() exiting() methods. It's almost hilarious!)

 

Then, there were those isInfoEnabled(), isDebugEnabled(), isTraceEnabled() performance enhancers that you could call in order to avoid preparing expensive logging output, that is never used. And as a sensible developer, I'd always use isDebugEnabled() whenever I would log.debug(..) any non-trivial stuff.

 

And all was well, until Adrian deprecated isDebugEnabled() (and isInfoEnabled()), and suddently the build bursted with ugly warnings, and eclipse started showing up those tiny yellow signs next to the slide bar. The code was not clean anymore...

 

Well, I could understand deprecating isInfoEnabled() (which is almost *always* enabled), but why isDebugEnabled()? Why now? Why me? That was cruel; we grew up with this method, we couldn't possibly live without it :)

 

Then as I started correcting warnings as I would come across them, by either removing the isDebugEnabled() statement all together, for logging messages that seemed of low-volume and of interest to the user, or turning this to a isTraceEnabled()/log.trace() combo for very detailed developer or high traffic logging messages, it all became clear: isLogDebug() was really not needed!

 

That was quite a revelation which brought to my mind pictures of Adrian with a "helo" hovering over his head (I've seen Richard Stallman doing this stunt wearing an "ancient" 1-foot hard disk as a helo, preaching his is Saint Ignucious, or something). Yes, Adrian, was telling the truth, and noboby listened (except Scott, of course :)

 

So now I'm a believer, too, and on top of that, I came to realise (or acknowledge?) that there is an ever better way to think about the log levels: INFO goes *always* to the console, DEBUG *always* to server.log, and TRACE *conditionally* to server.log. (ERROR and WARN are obvious.)

 

The usage of isDebugEnabled() gave the wrong impression that those debug messages may not be logged, which is rarely true. server.log is a tool primarily for the *users* of the server, to be able to troubleshoot problems and ask for help using informative log traces, from the forums (or the jboss support team of course :). In this regard, it is important that we don't log.debug() excessive information that is of no interest to the user; In other word, server.log size should always be kept relatively small or under control.

 

Another factor that isDebugEnabled() has been abused is due to the fact that in many cases we (developers) have used DEBUG for high traffic logging, that should really be TRACE. The reason being, we (developers) are usually lazy to enable the TRACE level in log4j.xml while developing, and we prefer to just use debug() instead, that we know it will work by default!

 

"If the user doesn't like this, she can turn if off", while the idea should really be, "I need to enable TRACE while I do development, and save server.log from being filled up with garbage, and the user from getting lost inside my verbose traces".

 

Happy Logging :)

 

dimitris@jboss