Java Logging Abandoned
Developer's Cave, Potential RPG November 6th. 2008, 3:19pmThis article provides a use case that chronicles my experience with the Java Logging API, as used for my MMORPG platform. Software developers can take this article as a cautionary tale against code reuse zealotry. It is often advantageous to follow your own software design goals rather than force your design around an existing system.
As an initial disclaimer, I am not entirely discrediting the Java Logging API. From a software engineering standpoint, java.util.logging provides a flexible, well-designed logging system, which is fully capable of providing logging services for a variety of applications. However, I have found it to be several times too complicated in the common case, and I disagree with some of its basic principles.
Although I argue against static design in almost all cases, logging is one situation in which you do not want to be passing an instance reference through all your methods. Languages with aspects, other cross-cutting features, or even multiple inheritance can allow logging to be mixed into classes. Since Java does not (natively) support these language features, a static logging API is the cleanest solution.
I do not fault the static design of the Java Logging API, but I take exception to calling Logger.getLogger(this.getClass().getName()) just to obtain a logging instance. The first design simplification I made was to write my own static logging API to encapsulate the ugly details of obtaining the Java Logger. My logging calls look something like Log.warn(this, "message"), which is somewhat cleaner.
All logging systems I’ve ever used have been based on logging levels, and I’ve never agreed with this concept. Logging messages are generated for different purposes, not at different levels. Severity levels make sense for informational/warning/error messages. Other message types do not fit into this model, such as debug, audit, start, stop, and configuration logging. Furthermore, levels named fine, finer, and finest (all lower than config messages) force programmers to arbitrarily decide how important a log message should be. Java arbitrarily includes exactly seven levels, placing further restrictions on extensibility.
I do not blame the Java Logging engineers for following a well-established design, even though it is faulty, in my opinion. Nonetheless, the second design decision I made was to isolate Java’s logging levels behind my own logging categories (fail, warn, info, init, stop, user, debug). My categories are mapped to Java’s logging levels, which are required to call the underlying Java Logging API. Custom formatters output my category names in place of the Java logging levels.
Registering custom formatters and handlers is another example of good engineering becoming somewhat overbearing in the common case. Based on any criteria, Java logging messages can be reformatted and redirected to different files (e.g., summary, detail, error) and sent over the network. While this is a potentially useful feature, the configuration is more complicated than desired for common use.
The third design simplification I made was to limit my logging to one flat file. If category or message source filtering is needed, grep is a perfectly adequate command-line tool. It is more reliable to post-process a complete log file, rather than rely on code changes to adjust logging output. This simplification alleviated any need for complicated Java handler and filter configuration. Since remote logging is useful, I added a few lines of code to (optionally) open a socket and send log messages to a remote server.
At this point, my logging API provided simple static integration from anywhere in my code, featuring source-named messages with meaningful categories. The complexities of configuring and calling the Java Logging API were all hidden behind my static Log class.
With all this effort heaped upon my code just to avoid reinventing yet-another logging system, two straws finally broke the proverbial camel’s back. For one, I had exhausted the seven available Java logging levels and could not add any additional categories. Even more severe, Java tended to stop logging before the application was finished. Log files lost the last lines of logging, because the logging API stopped outputting at the first signal of application shutdown. There does not appear to be any programmatic control over Java logging shutdown timing.
These issues prompted me to make my fourth, and definitive, simplification to using the Java Logging API; I abandoned it entirely. Since the rest of my code was integrated with my logging facade, I didn’t have to touch any code outside my static Log class. My application now initializes my logging system at startup, which involves opening a file, and stops it at shutdown, which involves closing the file. To preserve the best of the Java logging design, I have a simple formatter interface, which allows custom output. To prevent file output from blocking the application, I implemented a simple thread handoff queue, so all log calls return immediately. Flushing this queue is coordinated as part of application shutdown, so no messages are lost (even in the case of unhandled application exceptions).
In conclusion, I agree with the sentiment of not reinventing the wheel by using available software libraries. However, there is little added value when more time is spent dealing with the complexities, anomalies, and inadequacies of another library. There is a tradeoff, which can be both a strength and a weakness, between learning to integrate a software library versus developing it yourself. Although the Java Logging API is entirely capable, in this case, I would have made better use of time by implementing my own, simplified, logging API in the first place.






November 6th, 2008 at 5:35 pm
Good idea. I’m using tags daily in gmail and remember the milk, but I’ve never thought about tagging my logging in Java!
/Regards Pär
November 6th, 2008 at 6:03 pm
Pär, thanks for the comment. I see what you mean, but I must admit that I didn’t actually think of it as “tagging.” Nonetheless, by throwing away the notion of “levels,” my categories are essentially log tags. However, unlike blog articles and gmail, I never tag a log message with more than one category. For example, my log output looks something like this:
November 7th, 2008 at 9:10 am
Cool. Logging. So does that mean I can buy/create an axe and go cut down trees now? I’ll give it a go.
November 7th, 2008 at 10:19 am
Actually, it’s the other way around. First you acquire the resources to create an axe, then you craft it. Logging is fun.
November 7th, 2008 at 12:49 pm
I assume that the axe to be created would have a handle made of wood, correct? I think I see circular dependency!
November 7th, 2008 at 1:06 pm
Fortunately, the evil creatures of the land (inexplicably) harvest resources for you. You’ll just have to attack them with your bear hands to get the Wood, Metal, and Leather you need to craft your first weapon.
To stay on topic, my log files show when a resource reward is dropped. I think I’m logging too much, though. My log files tend to grow larger than the entire database of the world. Is that wrong?