The other day, I couldn't resist blurting out the following Facebook status:
Ben Simon is wondering if it's time to blog, yet again, about how much he dislikes logging in code? Yuck. Exactly how is a 42Meg log file going to help me solve anything?
As you may or may not know, I'm not a fan of logging. In past experiences, I've found it clutters the code, never seems to have quite the right info I need for debugging, is too loud on matters I don't care about and silent on matters I'm interested in. And then there's my favorite, when the log message is out of date and says one thing, but the code does another.
But enough about kvetching about logging - that's not the point of this post. The point of this post is that I've actually gotten some value from Log4j on a new project I'm working on. And I'd like to (a) celebrate (whoo!) and (b) document what I did so that perhaps future logging-cynics can get some value from this.
The Setup
In this particular case, I'm trying to debug a fairly large system (about 1000 Java files). The files have pretty extensive logging in them, though they suffer from the issues mentioned above.
If I turned on all the logging I ended up with a 42Meg log file that had so much chatter in it that meant nothing to me. If I turned off all the logging, I saw critical exceptions, but was left scratching my head wondering what the app was doing.
Finally, after I don't know how many years, I decided it was time to embrace Log4j and get a tiny bit fancy. I wrote up the following logging.properties:
# Setup the log handlers, which will be configured below
handlers=1con.java.util.logging.ConsoleHandler,2fh.java.util.logging.FileHandler
# Set the default logging level to SEVERE. In other words, by default,
# I only want to see the most urgent of messages.
.level=SEVERE
# Configure the logging to the screen. Set `level' to FINE to essentially
# catch all messages that are logged. But remember, above we set the
# level to .SEVERE, so there shouldn't be anything to log
1con.java.util.logging.ConsoleHandler.level=FINE
1con.java.util.logging.ConsoleHandler.formatter=org.x4juli.formatter.PatternFormatter
1con.org.x4juli.formatter.PatternFormatter.pattern=[%t] - %d{MM/dd/yyyy HH:mm:ss} [%c{1}] %p: %m%n%throwable
# Same as above, but with logging turned on
2fh.java.util.logging.FileHandler.level=FINE
2fh.java.util.logging.FileHandler.formatter=org.x4juli.formatter.PatternFormatter
2fh.org.x4juli.formatter.PatternFormatter.pattern=[%t] - %d{MM/dd/yyyy HH:mm:ss} [%c{1}] %p: %m%n%throwable
2fh.java.util.logging.FileHandler.pattern=output.log
2fh.java.util.logging.FileHandler.append=true
At this point, you've got a logging configuration which only generates the SEVERE messages. You also have log handlers ready to log any messages that are actually generated.
Now I got a little bit tricky. I'd find a class that I thought was central to the process I was studying and add the following to my logging.properties file:
com.foo.MailSender.level=INFO
Now when I run the system, I get a bunch of log messages - but they are ones that I actually have a chance of being interested in.
I also found that I can easily monitor a bunch of related objects, just by tweaking the logging at the package level. Consider this logging.properties change:
com.foo.mail.handlers.level=INFO
Thanks to the log messages in place and the structure of the code - the above tricks actually produce useful output. I do find myself using my programmer's scratchpad to write little scripts to parse the log file, but even without these scripts, the right level of logging makes all the difference.
Perhaps the real lesson I've learned about Log4j is that it works best when you use it in an iterative fashion. Turn on some logging, run the app, see what you can learn. As your needs change, tweak the logging configuration some more. It's not about finding the ultimate logging settings and never touching things again.
So there you have it, I'm actually thankful for Log4j. I'd keep an eye out for flying pigs, if I were you.
No comments:
Post a Comment