Monday, May 5, 2008

Testing and Handling Logging in Java

Logging is a great way to communicate the systems past steps and state for debugging. Often, they are the last resort to get an idea about what is happening in a remote system.
But, not all is shiny. Usually, the log entries are printed onto the console and to a file. The later one is no problem, however, the first one can be a pain point.
How? Assuming you have an application with a good suit of unit tests. Say a couple of hundreds so that the output of running the tests does not fit on one screen any more. Now, when you run the tests, you get a few lines for each test and a bunch of logging informations. This is called noise. It gets even worse if the output is laced with exception stack traces. Sure, there are cases were you want to test error conditions and those will cause exceptions in return. However, consider yourself new to a team and you just setup a new sandbox, a good corporate citizen as you are, you run all the tests before you pick up your first user story to work on. But, what is this? The screen is scattered with exceptions in the test output. I would be scared and would assume that I did something wrong during setup. The noise drowns out the real state of the system -- a build system should communicate the health of the system in a unambiguous way. This is a risk which can be avoided easily.

Logging -- which was added to Java 1.4 -- allows you to add a filter. With that filter you can intercept and decide which logs to actually log.
Also, you have to make sure to use the same logger as the one you want to suppress. Just use the same string as identifier for both. I usually use the name of the class from the class object itself.
Logger LOG = Logger.getLogger(Example.class.getName());
once you have the logger instance, you add a filter which deals with the log record and suppresses its logging.
logger.setFilter(new Filter()
{
 public boolean isLoggable(LogRecord logRecord) {
   if (logRecord.getLevel().intValue() == Level.SEVERE.intValue()) {
        // deal with log record
   }
   return false; // suppress logging  }
});
Here the code for a small Example
public class Example {
  private static final Logger LOG = Logger.getLogger(Example.class.getName());
  public void foo() {
    LOG.info("entering");
    try {
      willFail();
    } catch (Exception e) {
      LOG.logp(Level.SEVERE, Example.class.getName(),
               "foo", "something bad happened", e);
    }
    LOG.info("exiting");
  } 
  private void willFail() throws Exception {
    throw new Exception("ERROR MSG");
  }
}
And here the matching test
public class ExamleTest extends TestCase {
  private Example example;
  private Logger logger;
  private List logRecords;

 protected void setUp() throws Exception {
   example = new Example();
   logger = Logger.getLogger(Example.class.getName());
   logRecords = new ArrayList();
 }

 public void testFooLogsSevereIfFailure() {
   logger.setFilter(new Filter()
   {
     public boolean isLoggable(LogRecord logRecord) {
       if (logRecord.getLevel().intValue() == Level.SEVERE.intValue()) {
         logRecords.add(logRecord);
       }
       return false;
   }});

   example.foo();

   assertEquals(1, logRecords.size());
   assertEquals("something bad happened", logRecords.get(0).getMessage());
   assertEquals("ERROR MSG", logRecords.get(0).getThrown().getMessage());
 }

 public void testFooLogsEntryAndExit() {
   logger.setFilter(new Filter()
   {
     public boolean isLoggable(LogRecord logRecord) {
       if (logRecord.getLevel().intValue() == Level.INFO.intValue()) {
         logRecords.add(logRecord);
       }
       return false;
   }});

   example.foo();

   assertEquals(2, logRecords.size());
   assertEquals("entering", logRecords.get(0).getMessage());
   assertEquals("exiting", logRecords.get(1).getMessage());
 }
}
With this you remove the noise from running your tests as this
ExamleTest,testFooLogsSevereIfFailure
May 5, 2008 9:50:18 PM Example foo
INFO: entering
May 5, 2008 9:50:18 PM Example foo
SEVERE: something bad happened
java.lang.Exception: ERROR MSG
 at Example.willFail(Example.java:20)
 at Example.foo(Example.java:11)
 at ExamleTest.testFooLogsSevereIfFailure(ExamleTest.java:33)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at junit.framework.TestCase.runTest(TestCase.java:164)
 at junit.framework.TestCase.runBare(TestCase.java:130)
 at junit.framework.TestResult$1.protect(TestResult.java:106)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.framework.TestResult.run(TestResult.java:109)
 at junit.framework.TestCase.run(TestCase.java:120)
 at junit.textui.TestRunner.doRun(TestRunner.java:121)
 at com.intellij.rt.execution.junit.IdeaTestRunner.doRun(IdeaTestRunner.java:65)
 at junit.textui.TestRunner.doRun(TestRunner.java:114)
 at com.intellij.rt.execution.junit.IdeaTestRunner.startRunnerWithArgs(IdeaTestRunner.java:24)
 at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:118)
 at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:40)
May 5, 2008 9:50:18 PM Example foo
INFO: exiting

Process finished with exit code 0
becomes that
Process finished with exit code 0
The second line shows you that the tests passed (exit code 0) with no errors. All you need to know. No noise!
Best of all, you now actually test a specific exception to be thrown if a certain condition occurs. So, if a fellow programmer removes the exception with or without intention you get at least a raised finger in form of a failing test. That should lead to a conversation which again makes sure that the situation is resolved accordingly. Agile is about communication!

Note: This applies only for the JDK logger. log4j does not feature a filter which can be modified at runtime. I haven't spent lots of time investigating, but as of now I did not discover a work around. Drop me a line if you figured that one out ;)

13 comments:

良哥 said...

Teenagers in a track adidas shoes can go through shoes rate adidas outlet teenage runner well knows that adidas sneakers to wear the right shoes air jordan 2010 any cross country among world jordan shoes especially important to the sportsman discount jordan shoes a young person growing up Pure GHD Not only do they want to bourke dooney handbags grow out of their shoes dooney bourke bags but shape of their feet changes which means every time we dooney bourke outlet the time comes to get dooney bourke totes a new pair of shoes eveyone NIKE SHOX a good choice to get NIKE SHOX SHOES it with a high material SHOX SHOES that breathes easily on random moncler They should be extended runs moncler jackets give enough support to athlets moncler coats especially around the ankles area moncler vest to avoid injury your ankles discount moncler outlet when you make your trip discount moncler t-shirt something in store possible fit cheap ugg boots his is also the way to discount ugg boots that don't fit properly only ugg boots it focuses on your convenience classic ugg boots but they are not returnable ugg classic tall boots

aiai said...

For a pair of sleek gloves that would look great with your suit, pick up the Ross Gloves Italian Sheepskin Gloves with Cashmere lining. These gloves are perfect for those who live in metropolitan areas
spyder skiwhere the temperatures drop in the winter because these gloves are lined with extra warm and soft cashmere for that added layer of spyderwarmth and insulation. The premium Italian lambskin will mold to your hands in a close fit and the slim lines of this glove are convenient enough to slip into your pockets when not neededspyder jacket.

For a great pair of gloves that will keep up with you on the slopes even spyder ski wearin the harshest of temperatures, pick up the Burton' Gore-Tex Under Gloves for $64.95. The Thermacore insulation on these ski jacketgloves will keep your fingers warm even when the freezing wind and slate beats down on you. spyderThe DryRide Ultrashell combined with the Gore-Tex Insert ensures that nothing will get your fingers wet. spyderThe hidden heater and vent pocket stashes extra warmth on the cold days and dumps spyder jacketsexcess heat in the spring. spyder ski wearIf you are worried about your goggles getting steamed up, these gloves help solve that problem with the soft chamois goggle wipe which will keep your vision clear.

建平 said...

Supra Shoes are well-known for their fashion, comfort, toughness and uncompromised skate boarding attributes. Supra Sneakers are designed to provide you that utmost sense of stability. The simplicity and clean design of Supra Footwear lead it the excellent skate shoe for hitting the streets or the park.

lee said...

Radii Shoes are a high top sneaker which gives a rounded toe design, a rounded toe, 3 adjustable straps on the upper, and a large adjustable ankle strap around the ankle for even more attitude. Radii Sneakers are available in a range of striking colorways and will catch attention as soon as you put them on. The Radii Footwear gives a futuristic feel, look and design to the daily hitop shoe!

贝贝 said...

The Tax Return Crack-Up<3>
Granted, there are usuallyMicrosoft Office 2010write-ups when presidential contenders make their tax returns available, but the coverage falls far short of the Office 2010
full court press (pardon the pun) that the Clintons have received. What's Microsoft Office 2007different now?Office 2007One possibility is that most upper middle class Democrats, and therefore most Microsoft OfficeOffice 2007 keyeditors and reporters of our nation's big papers as well as Office 2007 downloadtelevision producers, are Obama supporters who think that Hillary should hurry up Office 2007 Professionaland drop out of the race already.Microsoft outlook
Microsoft outlook 2010Whom elite liberals are pulling for really does shape political coverage in ways

Javin Paul said...

Excellent article , you have indeed covered topic in details with code examples and explanation. I have also blogged some of my experience as 10 tips on logging in Java

Thanks
Javin

teragoldonlinefsbest said...

I prefer headlines that create a little controversy, I always find myself clicking on titles that are imaginative out of curiosity. Many best players know some online game. Here useful link:cheap wow gold Runescape gold Tera Gold Tera account

Spineless said...

ibrahim saraçoğlu
seal
blogger indeks
saç ekimi
estetik
meme küçültme
liposuction
meme büyütme

AMY said...

In fact, Dryad has special abilities which can play a support role in the fight, such as Abolish Magic. As a Dryad, she is good at remote attack with Impale.

_______________________________
cheap rs gold
runescape money

Shelia Smithson said...

your Guild Wars 2 Gold Cheap had packed percussion mule and hang up with him over a discover the damaging swamp for the nearby village. Will you help them to in the process? I really believe therefore more information.Or any other instance - in the neighborhood in the town settles down bandits and fortifies their hq several cannons

somnus11258 said...

What a beautiful dragonfly and what wonderful post!!I am a china tour lover,You can learn more: China tour operator | China tour packages | China city travel

Learn Chinese language on hanbridgemandarin said...

Since our founding in 2002, Hanbridge Mandarin has provided thousands of learners with high-quality campus-based courses, online classes, and intensive cultural immersion programs. Utilizing easy, fun and rewarding methods, we work hard to ensure our students can understand, use and ultimately master Mandarin communication skills.




More Chinese learning tags : Mandarin Learning in Shenzhen | Chinese Online Learning | mandarin online lesson

Peterdell said...

Great Post !!!

java books