Tuesday, January 31, 2006

Tiny Howto: Getting log4j to make noise

I have to start off this note by saying that I pretty much despise logging. Not the generation of all log files, per se. Heck, a log like the apache access_log can be a awesome. But I'm talking about stuff like:

// some method, somewhere Logger.log(LOG_NOISE, "UserAgent was null"); ...

Why? Well, where do I begin...

  • Most of the time, a log message meant something to someone at some point. And after a bug has been fixed, or time has past, the message doesn't mean anything. It's produced, and after a time people don't read it or care about it. It becomes unnecessary code. And I don't like unnecessary code. I remove unnecessary code.
  • People don't check logs. The catalina log file of tomcat on most machines I come across are like 6 gigs (OK, I'm exagerating a bit for effect here). The bottom line is that nobody is going look back and review that stuff. So why produce it in the first place?
  • A good exception message can kick a logging message's butt any day. What good is telling me that something is null? If it's an error, don't just tell me about it, do something. Throw an exception and make my caller handle it (or, usually, just re-throw it). Logging messages make someone reading code scratch their head and wonder what they should do with the knowledge being passed on to them.
  • If you make use of exceptions, and assertions in your code, you'll have confidence that it's running right every time. Which means you don't need to produce a log file to give you a warm and fuzzy feeling. You know the code works because if any tiny thing went wrong, the system would do something about it.
  • Logging messages are lines of code which aren't needed. I'm a big fan of keeping my code as trim as possible. By all means, use System.out.println to debug an issue. But just remove it before checking it in.

  • I'm from the unix school of thought: programs should be like luxury cars -- running silent. When you run the command: tar cf - / | gzip -c | base64 | mail -s 'Wacky Backup' foo@bar.com, do you think that you get lots of warm and fuzzy error messages? No, the job gets done, or you get an error saying what failed. Again, it's a matter of trust.

And I'm sure there's more...

But, this post isn't about my general feeling toward logging. It's about dealing with code that makes use of everyone's favorite logging framework: log4j.

See, tomcat makes heavy use of log4j. Which means that when a servlet throws an exception, and it reaches the top level of the container, by default, it swallows it. It's even worse when a listener or servlet fails on startup. This of course seems insane to someone like myself. You'll gladly give me all sorts of noise about what valves and stuff are starting up, but the tiny little detail, such as why a listener failed and why you won't deploy my application, is completely not there. It just didn't make the cut.

Now, if it were up to me, the catalina log file would be empty of everything except for stack traces. As I said, I don't despise the generation of log files --it's the noise, the random junk being printed out along with the useful gems that get to me. I just want the gems!

OK, back to the subject at hand. How on earth do you get a log4j application to actually log?

Well, every time I need to figure this out I google 'log4j configuration' and come across this link. Which never makes much sense to me at all. Probably because my production server won't start up, and I have beads of sweat rolling down my forehead as I stare at some vague message from tomcat. However, over the last few weeks, thanks to those at work, I've kinda cracked the code. So here, it is, Ben's super short way to get log4j to spit out logging messages.

  1. Create a file named log4j.properties. Put the following content in that file:
    log4j.rootLogger=info, R
    log4j.appender.R=org.apache.log4j.ConsoleAppender
    log4j.appender.R.layout=org.apache.log4j.PatternLayout
    log4j.appender.R.layout.ConversionPattern=%-5p %-30.30c{1} %x - %m%n
    
  2. Store this file in your classpath. As my friend Christian Cantrell used to say, "90% of fixing Java related problems is getting the classpath right" (or something close to that). In the tomcat world, this means putting this file in a place like $CATALINA_HOME/webapps/yourapp/WEB-INF/classes.
  3. I think this part may be optional, but I'd do it to keep log4j happy. Add the following system property to your command line: -Dlog4j.configuration=log4j.properties. Note, that's not a path to a file (like I spent some large amount of time trying to get work), but the name of the file to search for in your classpath.

And that's all there is to it. Start up your application, and watch with joy as the messages poor out.

4 comments:

  1. Anonymous2:47 AM

    Hmmmm, lots of pretty good points worth arguing about, but most of all I have to disagree with your tar analogy.

    Given that you're talking about a "server" here, in this case a Java Servlet container, I think a more analagous candidate would be a "server" in the Unix world. So, when was the last time you tried to analyze/debug a mail server, dns server, httpd server, or Samba problem without cranking up the log verbosity?

    Regarding your points about extra code, etc. etc. -- this is exactly why Aspects are a beautiful thing. Not necessarily a one-for-all solution, but certainly helpful in lots of cases. Better yet, if you're using Spring, Spring AOP makes this piece of cake. In fact, you can add log advice without writing one line of code, well except for a few lines of XML.

    ReplyDelete
  2. Hey Mark -

    Good point about looking at things from a server vs. client perspective.

    When I look at a program like postfix, or sendmail -- I see the real value of logging is in /var/log/maillog. Which is analagous to the apache access_log I mentioned. The information being logged here is extremely useful to knowing what your server is doing, but it's not just some simple logging statements tossed into your code. It's explicitly built in, like any other feature postfix.

    I guess that's what I'm voting for is an accounting log of some kind, and useful error messages when things don't work (like it can't start up because of permissions problems).

    As for Aspects -- I agree 100% with the concept. Though, I'm not sure which would be better for debugging purposes, turning on method tracing for a single method, or just dropping in a println where I want one. Either way, as long as the checked in code base is clean, I'm cool with that.

    ReplyDelete
  3. Anonymous8:00 PM

    Wow this coding seems complex.
    Thanks

    ReplyDelete
  4. Anonymous8:00 PM

    I hear much about servers.
    Client access is important.
    Debugging would be very useful, too.

    ReplyDelete