Blogbody Rotating Header Image

Tip: Compact Logging in Java

One of the little touches I added to Able, which came from code originally in BrowserMob, was a nice little JDK logging formatter. It is designed to work with modern IDEs (IntelliJ IDEA being my personal favorite) and their ability to understand shorthand notation for classes.

As I was building BrowserMob, I was getting irritated by long package and class names as well as the fact that my log messages weren’t lined up nicely. For example, I’d get:

INFO 12/29 19:26:28 org.directwebremoting.impl.StartupUtil - Starting: DwrGuiceServlet v3.0.0.109.dev
INFO 12/29 19:26:31 com.browsermob.stripes.WelcomeActionBean - Some log message
INFO 12/29 19:26:37 com.browsermob.stripes.WelcomeActionBean - Some log message

I tried a simple formatter that truncated the class name, but the result wasn’t very helpful, since the class name (usually the most important part) would get cut off when the package name was too long:

INFO 12/29 19:26:28 org.directwebremotin - Starting: DwrGuiceServlet v3.0.0.109.dev
INFO 12/29 19:26:31 com.browsermob.strip - Some log message
INFO 12/29 19:26:37 com.browsermob.strip - Some log message

That was when I realized that often the package name wasn’t that useful, especially since they were often very predictable and unique even in a compact state. For example, in the past developers I have worked with would often write “n.s.s.c.StripesFilter” as a short hand for “net.sourceforge.stripes.controller.StripesFilter”. So why not use this for logging too? The result was much easier on the eyes:

INFO 12/29 19:26:28 o.d.i.StartupUtil    - Starting: DwrGuiceServlet v3.0.0.109.dev
INFO 12/29 19:26:31 c.b.s.WelcomeAction~ - Some log message
INFO 12/29 19:26:37 c.b.s.WelcomeAction~ - Some log message

Basically, the packages would get cut down to the first letter of each sub-package. If the class name pushes the whole thing beyond 20 characters, then a tilde is added to indicate the name is longer than could fit.

The nice thing about this is that it works beautifully with modern IDEs. I can copy the text “c.b.s.WelcomeAction” and locate that string in IDEA and it’ll know what I mean:

200812291142.jpg

If you want to use this formatter, you can find the code here in the Able source repository. It could probably get some performance improvements, such as some simple memoization, so feel free to send any tweaks you make my way. Do you have any neat tricks you do with logging? If so, please share in the comments!

9 Comments on “Tip: Compact Logging in Java”

  1. #1 Stephane
    on Dec 30th, 2008 at 12:24 am

    Hey, do you mind if I take this code and I migrate it to the log4j formatter? I’ve been searching this for a while now!

  2. #2 dolphin
    on Dec 30th, 2008 at 2:08 am

    Very useful stuff! Thank you!

  3. #3 Ignacio Coloma
    on Dec 30th, 2008 at 3:10 am

    The proposed solution would not work with long class names like factory classes (in this example, WelcomeActionBeanFactory). On the other hand, removing the entire package name should not introduce ambiguity for logging purposes. Sure, you could have two different WelcomeActionBean, but that has never been an issue for me.

  4. #4 plightbo
    on Dec 30th, 2008 at 6:23 am

    Stephane – feel free to take it and do what you want with it. If you do use it or modify it, I’d love to hear about it though. Thanks!

    Ignacio – Yes, that’s my feeling as well. It doesn’t provide a 100% unique identification, but it’s usually “good enough”

  5. #5 Shams Mahmood
    on Jan 1st, 2009 at 8:56 am

    really liked the idea.

    abt long class names why consider splitting at word boundaries,
    i.e. why not consider c.b.s.WelActBeaFact~
    It will still work in idea and eclipse (not sure abt netbeans) due to the camel case :)

  6. #6 plightbo
    on Jan 1st, 2009 at 9:21 am

    Shams – Great idea! I’ll get around to it eventually, but if you beat me to it please share your modified code. Thanks!

  7. #7 jake
    on Jan 1st, 2009 at 11:59 pm

    good stuff, thanks for sharing. The problem at hand makes me think that instead of trying to compromise on what is logged (and potentially losing or having ambiguous data), that the pretty/compact view should be applied by some sort of log viewer program

  8. #8 Shams Mahmood
    on Jan 2nd, 2009 at 6:09 pm

    just implemented and sent a copy at your gmail acct hopefully :)

    Here are some results;
    Input Class Name Result
    —————- ——
    SimpleDateFormat SimpleDateFormat
    java.util.logging.LogRecord j.u.l.LogRecord
    java.net.InetSocketAddress j.n.InetSockeAddress
    able.util.SocketTestWaitCondition a.u.SockTestWaitCon~
    org.test.logging.AnotherClassToBeTested o.t.l.AnClToBeTested
    org.test.AnotherClassWithLotsOfWordsInName o.t.AnClWiLoOfWoInN~
    java.lang.Character$UnicodeBlock j.l.Char$UnicodBlock

  9. #9 Brian Fox
    on Jan 10th, 2009 at 3:01 pm

    Hi Patrick,
    Great idea, we might try to use this in Nexus (https://issues.sonatype.org/browse/NEXUS-1358)

Leave a Comment