Log4j? Logging 4 U!

The whole need for "logging" is not obvious when you have a good debugger. A good debugger is a godsend for our productivity as software developers. It’s the little things that you don’t even notice as you’re working with Visual Studio on a daily basis:

• You can set a breakpoint by clicking next to a line of code
• You can easily step in, out, and over functions while debugging
• You can hold your cursor over a variable name and see its value
• You can right-click on the name of a function to quickly jump to its definition
• You can see the entire call stack at a glance

Problem is, in our world of specialized and somewhat clunky simulation modeling languages, you may not be able to do some or any of these!

For example, one particular annoyance of AnyLogic 5.5 is the complete inability to use the debugger in your own custom Java code. If you have a model that’s written completely using the Enterprise Library without a single line of Java, then sure, no problem, you can debug as usual. (Let me know if you have a project like that, because I want on it.)

Thus, we turn to a time-honored tradition: logging. This highly technical term just refers to writing code that produces external files that provide diagnostic information or track system behavior Think of all the code you write in your models that produces lines in a text file -- that's logging.

"Simulation time 2.86\tCreating new order 17 for customer 276 containing 3 widgets."

Logging can be useful for remote troubleshooting. If your application or model is running on a server or a machine that is not directly under your watch, a log file can help you diagnose the system behavior in case of an error. It’s also really useful in simulation models to get a “narrative” for what’s going on in the process logic at a higher level than stepping through individual lines of code.

A Historical Perspective

You may be doing this in your projects already, but logging has been around a very long time. The oldest form of logging, invented by caveman programmers in the Paleolithic era, looked like this:

logfile.println(“This is a log message.”);

It was neat, clean, and functional, and just about the right complexity for their brains at the time.

In early Babylonian civilizations, pharaohs were tired of the continuous stream of log messages polluting their output scrolls. And so, it was declared that each module would contain a boolean flag that indicated whether or not we wanted to turn logging on for that particular module.
if (DEBUG_FLAG)
{
logfile.println(“This is an optional log message.”);
}

Then, in the Dark Ages, the Catholic Church decreed that some log messages were holier than others. A simple boolean flag was thus replaced by a hierarchy of “debug levels” that could be used to distinguish between log messages based on their holiness.

When debugging, you set up your application’s debug level to print lots and lots of supporting detail to understand and diagnose what was going on. When the application is released, you no longer want the super-detailed data in your log files (the file I/O can be expensive to your application), so you limit the logs to the very important stuff like critical error messages.

writeToDebugLog( 1, “This is a very important log message.”);
writeToDebugLog( 8, “These are just supporting details, not as important.”);

public void writeToDebugLog( int iDebugLevel, String sMsg )
{
if (iDebugLevel <= CURRENT_DEBUG_LEVEL)
{
logfile.println(sMsg);
}
}

We’ve used this custom-logging technique commonly in various Arena, AutoMod, AnyLogic, and VB projects over the years. But there are several annoyances about it. What if you want more information than just the error message? What was the function call stack? What if you want to always add certain data about the context in which the application was running, like the current simulation time? And one of the trickiest: how do we deal with safely opening and closing the global file variable logfile in all of the contexts that a model may originate and terminate?

The Java Logging API

Like nearly all non-trivial software issues, we’re not the first programmers in the world to run across this problem. Google "java logging jdk log4j" and you'll discover that the whole concept of logging in Java is extremely controversial! Man, we programmers have too much time on our hands.

I’ve used the Java logging APIs in a recent AnyLogic project, and it works great! One of the fundamental features is that one simple line like: logger.warning(sMsg); gives you so much extra information for free! The Java logging APIs do three important things that you would have to implement manually in a custom logger:

1. Wraps the log message in a LogRecord object with a ton of contextual information about the state of the application: call stack, log level, time of day, etc.
2. Filters this message depending on the debug level set for the application (by default, these log levels include SEVERE, WARNING, INFO, CONFIG, FINE, FINER, and FINEST)
3. Passes the LogRecord to one or more handlers and formatters that can process and output the logging information depending on what format you choose. (It’ll output XML by default.)

Not to mention that I don’t have to worry about details like managing file I/O. I just instantiate and configure the logger object for one or more classes in the application, and it just works.

For example, in my project, I’ve created a SimLogFormatter class that will automatically print out the current simulation time along with the log message and a couple of other fields. Instead of outputting it in XML format, I use a tab-delimited text file. Let me know if you'd like a copy and I can pass it along.

Additional Resources

Anyway, check out the links below for more detailed information about how you can use logging in your models.

“Java Logging API and how to use it”

Java Logging API technical docs from Sun

Of course, you can do this in .NET too.

An unbiased rundown on the controversial history of logging in Java