Logging: 2004 roundup

I seem to be having a “tools fortnight” at the moment :), because we’ve been trying out both log4j and java.util.logging in the grexengine core libs. Now that we have a branch of the core libs which replaces our proprietary/closed logging system with log4j, and another for java.util.logging, we could do a direct comparison.

Which means I temporarily have an overview of the topic with equal knowledge of all the main options, and thought it might be handy to summarise that whilst it’s fresh, and that it would be handy for people here…and, as with my UML roundup, I expect that some of the Titans ;D on this forum will have some valuable extra points to add.

Sadly, my conclusions are mostly not good :frowning: - however, we already HAVE a logging API that we’ve been using and extending for years; for people not using logging at the moment, I’d say it’s still a massive improvement to adopt one of the major ones despite their current inadequacies.

java.util.logging

Ohmygod. Sun, what happened with the documentation for Java 1.4? Was there an explosion in a magnet factory that sent magnets flying into all places where the data was backed up, and they were so hot that all the paper copies caught fire too? Or was there just one copy of the logging docs, kept in the same room as the NIO docs, and they both died in one tragic accident? You started so well in the 1990’s, with the JFC and it’s “trails” - did the authors and maintainers all leave for better paid jobs elsewhere? How come there’s no official Java Tutorial ™ trail on logging? Isn’t this important enough to be considered “fundamental” ?

Total time to understand enough of util.logging to do a “hello world” from scratch, without pasting code: about 20 minutes. Total time spent trying to load configuration from a file: 2 hours, and it still didn’t work.

We explored config files further, and found that Sun has almost no flexibility here. Their logging API is emasculated if you need flexibility or control over what file is loaded from where - and any error messages if it’s not found. Boom! Not good! The problem here is that with Sun, you MUST put your logging configuration file in ONE place: your JRE lib directory!

Think about that for a second. Sun wants you to have a single configuration file SHARED between EVERY SINGLE APP ON YOUR HARD DISK. Ahem. Can anyone see a teensy little problem? What happens the first time an app tries to install it’s own one, has a bug with not checking the existence first, and suddenly breaks logging in every other app you run? Wow. Brain-dead or what.

But that’s OK, you (eventually) realise - because Sun lets you choose which file to load. OK, so you have to load it via a System Property (no other choices - it HAS to be this way with Sun); and of course if you make a typo in the property you’ll get no warning or error message, which is one of the reasons why normal people don’t use properties for this kind of thing.

Except…Sun’s API is broken if you set the property in your source code. It simply doesn’t work properly, apparently because they do some stuff at startup (before your code to change the loaded filename gets executed) which we could never work out how to re-inoke. We couldn’t get around the following horror of Sun’s logging:

  • If you load a named configuration from disk, it doesn’t work until you “reset” it
  • Resetting a configuration trashes the loggers and does something nasty to the logging hierarchy so that lots of loggers cease to work from then on - we proved this by using a file that did nothing, and when commenting out the load line, it worked, and when you didn’t, it didn’t - although if you put anything in the file (like changing log levels) the changes were reflected in the few loggers that continued to work anyway.

The sad truth is that - apart from lethal bugs like this, and no documentation - the longer you dig in the Sun API the more you realise it wasn’t designed, it was hacked together (of course, the reason you are digging in it is because they didn’t write any docs, so you have to dig through the method names to try and find something - anything! - that might be related to your problems). I get the impression that some intern was given the job of making this, that they copied the design of log4j, and then because he/she was a beginner programmer, they produced a naive, buggy API that undermined several of it’s own design decisions (because they didn’t fully understand the purpose of some things they were cloning).

Where is the most basic functionality, like rotating logfiles? Log4j has this, but Sun’s doesn’t. Argh!

Eventually, we simply gave up entirely. Rating:

  • Robustness: 1/10. If a logging API can’t even be configured without unexplained bugs, and you have no workaround documentation, it’s useless.
  • Documentation: 3/10. Where is it? All you give is is javadocs. No good at all.
  • Performance: ?. Didn’t even bother.

Argh! YaBB wouldn’t let me post this because “your message is too long”…

log4j

I shall start off with the reasons why you probably would / would not choose log4j in the first place, the trivial ones - the things that most of us have on our mind when first looking at it.

Pro:

  • Prefer open-source software. Whether because of politics, or a genuine belief in higher quality, or even because you actually make use of the ability to patch bugs you find.
  • Mature. Unlike Sun’s logging, this has been around for many years; so, there’s a reasonable expectation that - irrespective of development methodology - it’s probably more stable.
  • Features can be added and bugs fixed on a daily basis; Sun can only release bugfixes 4 times a year (max) and new features only once every two years (max) due to their own rules on changes to core libraries distributed with their JVM.

Con:

  • It adds approx 350k download to your app or game. For a 10Mb game, or a local app, you don’t care. For a 1Mb game, this makes a big difference.
  • It’s open source. For whatever reasons (c.f. those in pro) you may sway the other way and be biased against it for this.
  • Stability. Because it gets updates much more frequently it gets tested much less extensively. Sun’s release strategy is done for good reasons, including the fact that it can greatly increase consistency and stability. It takes longer to fix things, but when they’re fixed they STAY fixed and don’t introduce new bugs (at least, in general, when compared to frequently-release software)

As it happens, I think most of those don’t really matter in the long run; the issues we’ve confronted in practice dwarf those listed above. I put them down here because those were ones that we came up with when we evaulated whether to switch to log4j a long time ago, when we didn’t have the time or spare resource to just try it out and see (takes a long time to convert 10 or more libraries!)

(again, too long to post!)

First problem with log4j is the documentation. It’s there, but … you have to pay for it! This, I am sure, fits in well with RMS’s view that all software should be free but you should also be allowed to make money out of it. In my opinion, software which is free (in all senses) but which makes it illegal to provide the documentation unless you write it all yourself from scratch (due to copyright laws) is NOT free and should cease and desist from claiming it is. The “manual” available from the official website is, in fact, a long sales pitch with a poorly organized overview of the main elements of the API. The actual explanations themselves are fair to good, but there’s not even basic indexing, and when you realise that the author is also the author of the $40 book containing the real docs, you start to quickly suspect that the lack of clear organization etc is deliberate - he doesn’t make money if this is easy to follow, but if it whets your appetite then he might make even more money.

I suspect that once you have that (paid-for) documentation that log4j is pretty easy to use - the author certainly is capable of explaining things acceptably well, although his style in this example is full of waffle, and I’ve certainly read much better technical prose (but I’ve also read much much worse!). Bearing in mind that he is probably aiming for a less experienced technical audience, I presume that I’m an exception and that it comes across more favourably to most readers.

On to the API itself. Log4j’s basic design (cloned by Sun’s one) is poor but easy to use. I’ve spoken out before on this forum on what I think of the naive one-dimensional basic logging. As Mark Thornton pointed out, you actually have arbitrarily-many dimensional logging, but the big screw-up here is that you have to implement it yourself - including any harnesses for it etc - since it provides next to no support for multi-dimensional logging other than the basic fact that it lets you do it. Since some people didn’t see a need for multi-d logging, here’s my previous explanation (not particularly good, but hopefully gives you the general idea):

With fundamental-yet-optional-and-often-unpopular API’s like logging you always have to strike some kind of balance between “powerful” and “easy enough to use that people actually use it”, so I’m happy to accept that the ease of use probably makes up for the loss of functionality for most people (although more on that later).

Now that we’ve used log4j a bit, here are my (personal) observations:

[] The way that it allows multi-d logging - i.e. by forcing you to have a separate Object for each dimension - is actually pretty good in practice. Although it feels like jumping through hoops I noticed that a lot of our logging statements seemed a bit clearer, I think because it forces you to think more carefully about what you’re doing and why - you cannot just go “log( message )”, you have to explicitly choose a particular log to put it in.
[
] It’s very easy to make it very slow - the only way to guarantee to avoid this is extremely messy - you have to surround every single log statement with: “if( thelogger.isDebugEnabled() ) { … }” (or isErrorEnabled() etc). This kind of non-compiler-enforced manual ugly code chunk is IME a dangerous problem. It’s not that programmers deliberately avoid using it (although no-one wants to do it all the time - so much so that there exists an Eclipse plugin that will automatically convert every one-line log statement into one of thes multi-line predicated log statements), but that tired programmers trying not to make the code impenetrably messy inadvertently often don’t think they need it in places where they do, and you don’t discover until the next stress test that hits that piece of code, which can often waste a lot of dev time.
[] Fundamentally, it’s slow. Our existing logging system uses static final boolean’s. This means that java can (and, as far as I know, does) compile out unused logging statements. Initially we would set these boolean’s at compile-time, which was especially useful for delivering small + fast class files to our licensees. However, it’s very easy to convert any or all of these to runtime-set booleans (and those places where licensees regularly need or want to change the logging used this approach), which Mark Thornton seems confident gets compiled out at runtime by the Sun server VM. This is fine for us, because our software is only ever run on the server VM, and works well with runtime recompiles anyway, since it’s a long-running (months, literally, without being restarted) server process.
[
] …but for all that, it’s still quite fast. I haven’t seen results from a stress test yet to see how it compares with compiled-out logging (our benchmark), and I await those results with interest. This will give us an actual figure for the relative speeds.
[] It uses write-back logging by default, whereas our existing log system uses write-through logging by default. This means that - by default - on the non-log4j any log message that doesn’t itself crash the server will be in the log when you recover from a crash, whereas log4j will tend to lose some of the last log messages when it crashes. Both API’s allow you to effortlessly switch back and forth, but I found it interesting how they differed: log4j by default likes to be faster but less safe, and the other one vice versa.
[
] Neither API is really fast enough for us when it comes to write-back entries written to disk. One of the things I need to evaulate ASAP once 1.5 goes gold is whether we can fix that by writing some custom clever “faster” write-through code using NIO. Given the current unstable state of disk NIO with 1.4 it seems not worth trying yet. I’m thinking of something along the lines of journalled FS’s. I’m not sure it’s even possible, but I am sufficiently disappointed by the speed of appended writes to large (e.g. 1 Gb) files in java 1.4 with each API that it’s an area I feel we need to improve on if possible.
[] Although log4j is touted as having “lots of add-on modules written by lots of people” they’re damn hard to find. This is a major issue for us, because there are only a handful of projects other than grexengine using our existing proprietary logging system. However, some very useful basic ones come with the API, e.g. they have a very nice easy-to-use formatter that uses a syntax very similar to Apache webserver’s log-file-format specifier strings - or, in other words, a system with the power of printf, but a lot more user friendly.
[
] Sadly, we’ve been unable to find ANY documentation on extending the API. This is a major bummer because we have lots of custom extensions that certainly don’t exist in log4j and are essential for big servers. e.g. much more intelligent and more advanced approaches to how you filter log messages. I think we can convert these fairly easily (almost effortlessly) to log4j just by extending classes … BUT the complete lack of support for multi-d logging leaves us with big concerns, like : “how are we going to locate the custom classes at runtime in order to interact with them?” because log4j has a VERY basic / weak / simplistic naming scheme which makes locating particular elements of the logging chain very difficult - e.g. it does NOT have any kind of “feature-based” search of the logging chain; you can only poll for particular names (reminds me of the windows registry tree, which has historically also had a very bad API/UI IMHO ;)). So, in the long-run, we’d need to implement an entire search system on top of their simplistic naming scheme - and that is not a pleasant thought.
[] Although the docs have major problems right now, it is a very well-known and widely-used API, so if we use it for the core of our product then a lot of our licensees will be pleased to control the logging without having to do any retraining. Then again, so far only one of our licensees already had any log4j expertise at all in-house, so it’s not yet reached a critical mass in our segment.
[
]…and the paucity of docs for it has me worried that those who are without log4j expertise won’t always appreciate having to learn it.
[*]…but the proprietary logging system we use at the moment has even less docs, and lacks the many hundreds of developers worldwide (on the log4j mailing lists) willing to help people who are trying to understand it. At the moment, we have to support that logging system ourselves; with log4j, we reduce our support effort.

On the whole, I’m personally quite tempted by log4j. We’ll have to see how the next round of stress tests go with the different branches, and I wait to see if anyone discovers any major problems…

Robustness: 8/10. Hasn’t broken in any way that we’ve discovered so far. There are certainly bugs (I’m told there are 180 oustanding in their bugzilla list), but we’ve either been lucky or most of those are cosmetic.

Documentation: 5/10. There IS a manual, but you aren’t allowed to read it unless you buy it. From reading web articles by the author, I suspect that the quality of the manual would probably lead to a 7 or 8 out of ten. But forcing people to buy it means I have to mark it down. Also, bear in mind that there are approx 6 easy to find tutorials on the web (although all bar 3 are crap) for log4j, whereas I struggled to find more than 2 (of which both were crap) for java.util.logging. I’m hoping someone will reply to this with “Idiot! There’s HUNDREDS of great tutorials, c.f. …” and provide a list of ones I missed :). The ones linked to from the apache site are either godawful or else just as basic as the main one. It’s a conspiracy, I tell you! The book author is paying people not to undermine his sales! ;D (tongue in cheek).

Performance: 7/10. For most people, it’s probably fast enough that you don’t care. For us, I’m not sure until we have some stress tests completed. Let’s see how it copes with piping output to multiple files in parallel, with automatic file rotation, whilst under heavy load…

I have chosen Log4j for my projects. It works great. I altered LogFactor5 which is the Swing GUI that comes along with Log4j to operate much more efficiently in a constant real time logging situation. LogFactor5 is integrated into my framework and can be popped up any time along with the ability to change the Log4J config files and reinitialize logging.

I am thinking about creating a facade interface at the framework level for logging in general, so that the underlying logging package can be changed if necessary without having to alter a ton of application level code. There are of course some things I haven’t fully looked at in regard to transparently supporting multiple logging implementations though I think I have them worked out in head space, etc.

This of course is another area I wouldn’t mind working with you Adam… As it is an open part of my framework (err once it’s released!)…

Apache Commons has a generic logging interface specifically designed to let you chop and change logging systems. It is often used for java-util to log4j and vice versa experimentation.

However, it is also know to have a vast amount of bugs - even between these similar API’s it appears difficult to create a “pluggable service provider” type API.

Anyway, if you have time to spend in this area, what could be a lot more interesting is to see if anything can be done to open up and improve the proprietary logging system we’re currently using. But that’s a topic for another day - when I have time to write a mammoth review of THAT logging system as a pre-cursor to deciding if it’s really worth trying to fix the major players, or if it’s better to try and improve and open up that one.

I use java.util.logging in my app simply because it is there. I’m not going to bother installing a third party package just for logs.

Re: loading a config file. What is this all about? I’ve never bothered with it.

Re: rotating log files. This is implemented in java.util.logging. By setting certain patterns for the log filename, I think.

I assume you found these doc’s: http://java.sun.com/j2se/1.4.2/docs/guide/util/logging/

“FileHandler: A handler that writes formatted log records either to a single file, or to a set of rotating log files.”

http://java.sun.com/j2se/1.4.2/docs/api/java/util/logging/FileHandler.html

Overall I think your review is unfairly critical of the java.util.logging stuff. I didn’t have any problems with the documentation when I went to use it for the first time. And you obviously didn’t read much if you missed the rotating logs.

The Sun Logging stuff isn’t that bad. I wrote an entire article on the subject, entitled Building the Ultimate Logging Solution. As for docs, I was able to sort through it fairly quickly, despite being a complete newb to logging. I do agree with the properties file problem. However, part of the point of naming the logger is that different programs have different configurations that don’t collide. If it’s still a big problem, just set your preferences programatically.

Log4J is really not that much different from Sun’s stuff. (Not surprising since Log4J predates the 1.4 logging.) My only beef with it, is that they’ve released several incompatible versions. This has the side effect of making many libraries incompatible with each other, and has even been known to cause breakage in J2EE servers due to an “older” version shipping with the server. (You hear me Macromedia?!)

Personally, I recommend sticking with java.util.logging. Read my article. It’s not that hard to use, and the results are quite pleasing.

Thanks, guys. I considered not saying anything about java.util.logging because obviously it had to work reasonably well for it to be included in the JVM, but then I decided:

  • people expect a minimum quality of JVM libs, and my experience suggests logging isn’t hitting that. It’s an unusual horror story, yes, but the fact that it happens is damn important to give people an idea of what’s actually been put in the JVM - for instance, it appears considerably less robust than the OSS alternative

  • if I said nothing, then the review would be entirely devoted to log4j, which isn’t much as a comparison

  • with the UML editors, if they broke and I couldn’t get them working in 10 minutes I gave up, which is what a lot of devs will do - we don’t have time to mess about. If it works perfectly but requires a day or more of debugging an under-documented API then that’s more than many people have the spare time (or energy) for.

  • …I guessed someone else would have a good resource to point to as an alternative :slight_smile:

If we get util.logging working, I’ll do a detailed review of it in-action alongside - unless it turns out to be no different from jbanes’

PS: I have found some documentation, at wiki.apache.org. It’s really good, but - oh, what a surprise! - most of it is missing, and you will quickly come to detest the words

…because they occur EVERY time it’s about to describe the thing you went looking for.

I am getting increasingly fed up with the conspiratorial “Let’s make Ceki some more money” approach to log4j. Personally, I think it’s outrageous that Apache has adopted a logging system which people aren’t able to use without paying for. I resent this underhand tactic >:(.

I’ve spent some more time on j.u.l (java.util.logging) and there is some good to say about it.

EDIT: e.g. … j.u.l actually makes some major changes to log4j which are big improvements, basic OOP stuff. For instance, LogRecord is a big step forwards.

However, the more I use it the more accurate my first impressions turn out to be - this is poor from a design POV, and it is clear that the JSR process utterly failed to work for this particular part of java, producing a haphazard half-arsed API designed mainly by people who don’t really use logging and certainly don’t understand it.

EDIT: if j.u.l were an open-source project I’d be saying it was pretty good. But it’s not: this is part of the standard official JVM distribution, and it is forced upon every developer and every user whether they like it or not. The minimum acceptable quality threshold is much, much higher. The insertion of half-arsed API’s into the core distribution only further drives people like Cas up the wall, forcing more crap onto them and artificially inflating the downloads for no net benefit.

After digging very deep, I’ve started to find some alternative API’s that have real promise, and they only serve to highlight how big a mistake was made in basing j.u.l on log4j. At the same time, we’ve been finding more and more problems with log4j as we try to use it in the field. I thought it ought to be mature, given it’s age. How wrong could I be? Log4j is hopelessly immature; the upcoming release (which has been upcoming for a year now!) will finally bring it into the 21st century in several areas, but even then it will still be a fairly mediocre logging API.

Something interesting I unearthed is the following criticism of j.u.l, which was actually submitted to them during the design phase, and yet allegedly was largely ignored. Whilst I do not endorse every criticism, there is a lot of meat in there that is all but impossible to argue with yet was not incorporated into the java 1.4 logging.

http://www.swzoo.org/documents/miscellaneous/jsr047/

…watch this space, more to come soon…

[quote]I am getting increasingly fed up with the conspiratorial “Let’s make Ceki some more money” approach to log4j. Personally, I think it’s outrageous that Apache has adopted a logging system which people aren’t able to use without paying for. I resent this underhand tactic >:(.
[/quote]
I’ve said it before, and I’ll say it again: You’re a little seething ball of hate, aren’t you? ;D

Here’s my opinion: Webapps, log4j. Other apps, java.util.logging.

In webapps I use log4j because I’ve used it for a long time and am comfortable with it. The extra bloat and any speed issues are totally irrelevant - there’s no benefit in a slim webapp, and when every hit on the server will probably require file IO and several DB hits, speed goes out the window.

In other apps I use java.util.logging because it’s there. I’ve not seen any speed problems, there’s no extra library to distribute, and it’s one less dependency to worry about. The syntax is close enough to every other logging API I’ve tried that using it is painless.

I suspect that the only people who have high demands of their logging API are those writing very high-performance APIs in a possibly hostile environment, where they need lots of run-time logging, and their revenue stream largely depends on problems being detected and squashed.

In short, that’s you Adam!

Did you (blah3) try the java.util.logging.LogManager.readConfiguration(InputStream in) method to override the default configuration. Obviously in this case you can get the InputStream from any file you like.
I’m not convinced that applications ought to replace the logging configuration in this way. Instead I think they should programatically add to whatever configuration they find. After all if i’m the machine admin do I want apps choosing to send logs somewhere other than my chosen destination?

On your more general points, I think it is important to distinguish between logging and tracing. Tracing will often need much higher performance and does not need localisation. There is some overlap in that modest tracing needs can be met by logging. Also any log information should also appear in trace output along with pure trace text.

I currently use my own trace system, which has zero cost when disabled, and can generate trace files > 500MB without excessive pain (disk space permitting). If anyone is interested I could perhaps discuss that in a separate thread.

I have had little difficulty using java.util.logging. The only problem I have found is that FileHandler doesn’t work if the file is specified using a UNC type path — the stupid code replaces the double slash at the beginning with a single slash.

Of course, I’m still not entirely sure what’s going on with j.u.l simply because we’ve not yet found any real docs, so I may be making stupid mistakes here. (but then I expect most people who’ve not used it before are in the same boat, which is where the value comes from in documenting our experiences).

[quote]Did you (blah3) try the java.util.logging.LogManager.readConfiguration(InputStream in) method to override the default configuration. Obviously in this case you can get the InputStream from any file you like.
[/quote]
I think that’s what we tried that simply didn’t work properly, although I’m not sure.

? The problem we had was just getting an initial configuration in the first place…the way that j.u.l. wants you to do it is to have a single global configuration file shared between all apps, but that’s stupid, especially given that Properties files are inherently non-hierarchical - it’s an admin nightmare waiting to happen.

All I ask of j.u.l. is that the app can tell it to configure the log from a file without having to bother the user with typing in a stupid system property on every single darned invocation - the concept of loading any kind of config from a default location unless overriden on the command line by the user has been standard for decades now.

Hmm. Personally, I’ve never thought of tracing as separate, unless perhaps when making the distinction between logging and “instrumentation” (performance logging stats etc). Probably I’m influenced by distributed transactions, where the standard terminology uses the word “log” for stuff that’s actually extremely fine-grained (e.g. the info logged on each transaction to guarantee atomicity even in the event of a pathologically badly timed system failure).

I find it interesting that log4j seems to have an ongoing battle between those that think they should add a new loglevel “TRACE” and those that don’t. I’ve not read the detailed arguments for / against, but it seems at least for them not to be a simple issue. Perhaps they are just being bitten by the fact that it’s next to impossible to find a good free standard tracing system - so people needing tracing latch onto the few free standard logging systems as their only option?

I’d certainly be interested, even if only academically :).

Preliminary stress tests suggest that log4j is not only noticeably slower than our previous logging system, but excessively so. This is only preliminary, but we’re seeing a huge differential on identical hardware (upgraded JVM and other things, so nothing is conclusive yet).

The bit that I think is due to log4j is that where server VM used to go about 30% faster than client VM after 10 minutes warmup, it now only goes about the same speed, +/- 3% - and the only code change I can think of that’s responsible would be the change from the previous logging (which, as Mark described previously, uses the runtime-settable static final booleans which can be compiled out by the server at runtime) to log4j (which keeps all logging statements in and executes them irrespective of whether they are used or not).

There’s a lot still left to test, and lots left to check (for instance, because the previous scheme was compiled in/out, it was safe to have expensive debug statements; now, with log4j, you have to manually check every line of code to make sure that anything expensive is split from one line into 3 or more and predicated on the logger status. This could easily cause significant performance loss).

[quote]I currently use my own trace system, which has zero cost when disabled, and can generate trace files > 500MB without excessive pain (disk space permitting). If anyone is interested I could perhaps discuss that in a separate thread.
[/quote]
I’m more interested than ever, now; I’m guessing that your trace system uses the same basic idea as our old logging system, and perhaps there’s a tolerably cheap way we could take the best ideas from the old proprietary logigng system we used to have, and from the more generic API’s like log4j, and make a good, fast, usable, sensible logging API. It would have to be open-source, I think, (under BSD, apache, or similar) because we don’t have the resource to own and update a logging system all on our own :(.

Unless the above performance issues turn out to be nothing to do with log4j, or j.u.l turns out significantly better, I think we’ll have to create a new logging system (yet another one!). There’s so much wrong with the design of those two API’s, and the fact that they ignore java’s ability to dynamically compile-out unused statements is depressing - java offers a way to make logging really fast (which we were using as you described in a previous thread, although I wasn’t sure it actually worked as expected until you described your use of the same approach) but neither API actually uses it >:(. Instead, they have this stupid “.isDebugEnabled()” stuff, that is fine for toy examples, but in a huge application (like ours) the only way to avoid missing some is to use code-lint tools and mandate that every logline has this predication.

If we’re going to do that then we might as well use the approach from our old logger - predication on static final booleans! - and get guaranteed better performance.