Putting an End to System.out.println (or jUnit and Chainsaw)

We've all done it, trying to investigate some problem, we write some println()'s. I'm pretty sure we've all accidentally left them in some production code too. We hate them in our own code, we hate them in other people's code. At some point, many switch to logging. Hey, we can just change the log level to filter out things of lesser importance.

But, when I'm working on a problem, I don't want all the DEBUG messages, just the ones relevant to the task at hand.

Then there is test code. Whether little unit tests written by developers or big integration tests written by QA. I think we all hate excessively noisy tests. Logging either creates file or console pollution, println()'s are just plain unacceptable.

log4j Chainsaw

A little reality? Sometimes, you want to expose some information. Especially, when investigating an API or a library. The purists would say, use an assert. The pragmatist says, "I don't even know what to assert for....yet".

Once upon a time, I'd write little classes with main methods to query API's and spit output to the console. This helped me discover how to use them. Nowadays, I'll often just start with a test case, it's just quicker and easier. As information is discovered, info dumps to the console are replaced with asserts. But, sometimes, I'd like to know a little more (but, only when I want to). Leaving commented out println()'s is just plain old code pollution.

A Completely Random Idea

While working on another project, I pulled out a tool I haven't used in a few years, Chainsaw.

Two really cool features of Chainsaw:

This gave me an idea (maybe not the best... but, hey. Little changes still make things better). Why not make the log level high enough to keep the console clean and send lower lever messages to a socket?

So, I whipped up a new log4j.xml file to live in: src/test/resources (yea, I use Maven)

So, it's only used during testing. I configured it to only send ERROR or greater to the console, TRACE level can go over the network. Generally, builds run nice and clean; no new log files, no junk on the console.

If I want to see TRACE/DEBUG/INFO/whatever logging, I just fire up Chainsaw. The best part is, I can filter down to the specific test case I care about.

When dealing with large amounts of information, a good filter is a key to success. It's all about signal-to-noise ratios.

Sample log4j.xml

Here's the log4j.xml I'm currently using for some tests:


<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" [
  <!ENTITY minLevel "TRACE">
  <!ENTITY annoyLevel "ERROR">
]>
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

  <appender name="console" class="org.apache.log4j.ConsoleAppender">
    <param name="Target" value="System.out" />
    <param name="Threshold" value="&annoyLevel;" />
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern"
             value="%d{yy-MMM-dd HH:mm:ss,SSS} [%t] %c %x %-5p %m%n %C.%M()" />
    </layout>
  </appender>
 
  <appender name="socketHubAppender"
    class="org.apache.log4j.net.SocketHubAppender">
    <param name="Port" value="4445" />
    <param name="locationInfo" value="true" />
    <param name="Threshold" value="&minLevel;" />
  </appender>

  <root>
    <priority value="&minLevel;" />
    <appender-ref ref="console" />
    <appender-ref ref="socketHubAppender" />
  </root>

</log4j:configuration>

This is no panacea. It's pretty rare that'll be needed. But, it is a little better than dumping to the console or leaving around lots of commented out code.

Yea, those are entities for the log levels. Call it an old habit from being able to support quick changes in large config files.

Tips

When using Chainsaw, use the SocketHubReceiver. Change the "reconnectDelay" to 10 milliseconds. Focus/ignore till you are filtering for only what you want to see.

Author

by: Paul E Davis
Tech Tags:


Sponsors:

About willCode4Beer