Sunday, October 21, 2007

Working This Weekend at Home

I had to work from home about 6 hours this weekend. Our team is releasing the next major version of our product early November and we are to begin testing next week. This means that all changes need to be checked in by Monday which also means that I needed to finish things up over the weekend.

I enjoy working from home. I am physically more comfortable in the home office of my own design. I do not feel compelled to keep track of what I am doing, as close to 100% of my time goes to whatever task I intend to complete. I like my white boards, my wife, my 22" flat panel, my cigars, my cats, and my books all within reach. I generally feel more contemplative when I am in my home office which makes it easier to work through problems.

Often, when I leave work on a Friday knowing that something needs to be finished on Monday I feel tense and uneasy. These feelings are most extreme when there is some problem that has yet to be solved. This weekend, with Rebecca's help we were able to redesign a component that I have been struggling with all week in about 30 minutes; a feat only possible in the home office.

I would not give up my workweek to work at home full time, but I do enjoy the perks of the home office when the need arises.

Monday, October 15, 2007

How I Use log4j

Log4j is a 3rd party Java library that solves the huge (and under appreciated) problem that is application logging. I use log4j in all but the smallest applications as it is an invaluable tool to track down problems and recreate error conditions. As a general rule of thumb, I will use log4j in any program I write that somebody else is likely install and run. I absolutely love log4j and in my opinion it is the single most valuable tool for providing application visibility.

Even with simple console tools, it pays off to use log4j. Occasionally, I will get a question like "hey, tool X didn't work quite right a few days ago - what happened?". No problem, tool X was configured to send warnings and errors to the DailyRollingFileAppender. If I implemented logging correctly in tool X, I will have enough visibility to discover the problem and fix it.

Loading log4j properties

The first problem I run into is how configure log4j. I have the option to compile in configuration parameters, however by doing so I lose much log4j's vast flexibility. For most non-trivial applications I want to create a log4j properties file and load it when your application starts. For these reasons I prefer to pass the location of a log4j properties file into my program dynamically as a system property:

java -Dlog4jconfig=config/log4j.properties -cp "program.jar" Main arg1 ...

This solution is only acceptable for programs that are not executed by directly invoking the JVM. Things like setting the classpath and specifying system properties are a terrible burden on a user; therefore I recommend using a script or commons-launcher to handle the details of application startup. Further, by setting the log4j properties file name in a system property, I do not impact command line arguments specified by the user.

When it comes to the actual initialization of log4j, I generally have a block of code at the beginning of my program that looks like this:


String log4jConfig = System.getProperty("log4jconfig");

if (log4jConfig != null) {
PropertyConfigurator.configure(log4jConfig);
log.info("log4j initialized using properties file [" + log4jConfig + "]");
} else {
System.err.println("You must set system property log4jConfig");
System.exit(1);
}

When my program knows how to find the log4j properties file, I are now free to configure logging without having to recompile my application. My typical configuration looks like:

log4j.debug=false
log4j.rootLogger=debug, A1, A2

log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.Threshold=INFO
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%p %d [%t] %c - %m%n

log4j.appender.A2=org.apache.log4j.DailyRollingFileAppender
log4j.appender.A2.Threshold=INFO
log4j.appender.A2.DatePattern=.yyyy-MM-dd
log4j.appender.A2.layout=org.apache.log4j.PatternLayout
log4j.appender.A2.File=logs/application.log
log4j.appender.A2.layout.ConversionPattern=%p %d [%t] %c - %m%n

What to Log?

This is the real question. It is often difficult to decide what level of detail to send to your application logs. One of the most common logging statements in your program sends a caught exception to the logger. At this point I ask myself if the exception and stack trace will be enough to reproduce the error. If the answer is no, then I will log relevant inputs that caused the exception.

Assertions are another good place to add logging. Typically when my application is in the hands of users, assertions will be turned off. The only way to gain visibility into what happened is to log details of the assertion and what inputs caused the failure. Even if the assertion failure causes my program to terminate, a log can save me minuets to months when tracking down the problem.

Finally, I acknowledge there is always an else. Whenever I have an if without an else or a switch with an empty default condition, I consider the implications if my code hit the unhandled else/default. It often pays down the road to log "impossible" or "assumed" conditions such as these.

How?

Simply put, at the beginning of any class that supports logging, I will crate a static Logger object named log:

private static Logger log = Logger.getLogger(MyClassName.class);

One note of caution: I will undoubtedly copy/paste similar Logger initialization code throughout my program. I must make sure I change MyClassName to the actual name of my class. Forgetting to do so may not be caught by the compiler and may only show up months or years down the road when I actually need accurate information from the logs.

Lastly, when writing information to the log, I always enclose a concatenated string between braces. This makes empty strings more obvious and whitespace more readable:

log.error("Illegal condition [" + illegalCondition + "] occured");

Conclusion

I have barely scratched the surface of log4j's capabilities. For more information I highly recommend purchasing the log4j book for $19.67 USD. This text is an excellent reference and has proven to be quite useful to me. I am very interested in how others use log4j; I would appreciate a comment if you feel you have your own noteworthy log4j tips.