JAW Speak

Jonathan Andrew Wolter

Archive for the ‘java’ tag

Test Driven log4j Logging Code Example

with 3 comments

Reading time: 3 – 4 minutes

Update: Added a snippet so that you can easily assert a message was contained in the logged messages.

Frequently logging is not viewed as “important” by engineers as, say, the logic for refunding a customer’s purchase. The customer’s won’t mind, after all, if we forget to log something right? Maybe so, until there are problems and the operational team supporting your application has very little ability to diagnose problems.

I propose logging should be viewed as another user interface, and thus needs its’ own set of acceptance and unit tests. This makes for more tedious and up front work for development teams — however I want to survive in production without a pager going off, and with fewer late night scrambles to ship patches.

Imagine a class that has logic associated with logging. Below you will see a unit test verifying logging statements are correct. Often logging uses statics, and as Misko has said, statics are a death to testabilty. With Guice you can easily inject loggers automatically for the class under construction. This method gets around most of the issues with static loggers, although I still despise statics everywhere.

This is a basic example, but the point is to understand how to hook into appenders and add/change one to use a test appender.

package com.jawspeak.common.testing;
 
import com.google.common.collect.Lists;
import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.spi.LoggingEvent;
 
import java.util.List;
 
/**
* Use me for spying on test logs and making asserts against them.
*
* Example how to use:
*        final SpyLoggerAppenderForTesting spyAppender = new SpyAppenderForTesting();
*        final Logger logger = Logger.getLogger(MyClass.class.getName());
*        try {
*            logger.addAppender(spyAppender);
*            // do something
*            assertEquals(Lists.newArrayList("Attempted to read such-and-such, but could not: oops"), spyAppender.getMessagesLogged());
*        } finally {
*            logger.removeAppender(spyAppender); // clean up global state
*        }
*/
public class SpyLoggingAppenderForTesting extends AppenderSkeleton {
  private List messages = Lists.newArrayList();
 
  protected void append(LoggingEvent loggingEvent) {
    messages.add(loggingEvent.getRenderedMessage());
  }
 
  public List getMessagesLogged() {
    return messages;
  }
 
  public boolean doMessagesContain(String snippet) {
      boolean isFound = false;
      for (String message : messages) {
          if (message.indexOf(snippet) >= 0) {
              isFound = true;
          }
      }
      return isFound;
  }
 
  public void close() { }
  public boolean requiresLayout() { return false; }
}

Here’s an example test where we make use of it. Note that we didn’t assert the lists are exactly the same, because in this project we were also using aspects to do logging, and depending on if you ran with or without the aspects enabled, a different number of logging messages would be created.

package com.jawspeak.common.utility;
 
import com.google.common.collect.Maps;
import com.jawspeak.common.testing.SpyLoggingAppenderForTesting;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.junit.After;
import static org.junit.Assert.*;
import org.junit.Before;
import org.junit.Test;
 
import java.util.LinkedHashMap;
import java.util.List;
 
public class SessionSizeLoggingTest {
private SpyLoggingAppenderForTesting spyAppender = new SpyLoggingAppenderForTesting();
private Logger logger = Logger.getLogger(SessionSizeLoggingTest.class.getName());
private Level oldLoggingLevel = logger.getLevel();
private SessionSizeLogging sessionSizeLogging = new SessionSizeLogging();
 
  @Before
  public void setUp() {
    logger.addAppender(spyAppender);
    logger.setLevel(Level.TRACE); // set the level in case a log4j.properties or log4j.xml disables this level of logging
  }
 
  @After
  public void tearDown() {
    logger.setLevel(oldLoggingLevel);
    logger.removeAppender(spyAppender);
  }
 
  @Test
  public void logBytesWhenUnprintable() throws Exception {
    LinkedHashMap map = Maps.newLinkedHashMap();
    map.put("key", new String(new byte[] { 1, 31, 127, -97}, "ISO-8859-1"));
    String sessionId = "abc123";
    sessionSizeLogging.logSessionSize(logger, sessionId, map);
    List messagesLogged = spyAppender.getMessagesLogged();
    assertTrue(spyAppender.doMessagesContain("Session Size for session id: " + sessionId + " (approx. total " + (7 + 3 + 1 + 4 + 1) + " bytes)"));
     // or use
    assertTrue(messagesLogged.contains("  key[   3 bytes]                            key  -->  value[   4 bytes] '\\u0001\\u0031\\u0127\\u0159'"));
  }
 
  // .. many more tests
}

This is a trick that I don’t see written about too much, but I recommend it often. And, I’d love to have some readers post enhancements, links, and take testability further with respect to logging.

Written by Jonathan

June 21st, 2009 at 8:17 pm

Posted in code, java, testability

Tagged with , ,

Using (These) Anonymous Inner Classes is Probably Too Clever for Your Own Good

with 3 comments

Reading time: 3 – 5 minutes

Sometimes it is tempting to have less verbose Java code and be clever. Say you have an object you need to build and set several properties on it, then use it. This way looks clever, but is a bad idea – especially in production code. Read on for why.

  	TripChoice myTrip = new TripChoice() {{
                        // look at these clever initialization blocks!
			setDestination("San Francisco");
			setAvailableRoutes(new HashSet() {{
				add("LAX-SFO");
				add("BUR-SFO");
				add("ONT-SFO");
			});
	   }};

This is a huge problem because it can cause a NotSerializableException or create a memory leak. How? Because with that clever anonymous class and initialization block, there is an implicit reference to the outer class’ instance. That outer class will not be garbage collected so long as there is one reference to the anonymous class. Worse, if we ever

Here’s the typical way to do it.

                // blah blah, this is typical, and a rather boring looking great big block of text.
		// (That's also probably scattered over several places in your code when you build these objects).
		TripChoice myTrip = new TripChoice();
		myTrip.setDestination("San Francisco");
		Set availableRoutes = new HashSet();
		availableRoutes.add("LAX-SFO");
		availableRoutes.add("BUR-SFO");
		availableRoutes.add("ONT-SFO");
		myTrip.setAvailableRoutes(availabileRoutes);

Here’s why this improved version is even not the best:

  • It uses setters. Setters allow your object to be constructed in an inconsistent state. There are some situations setters are fine (i.e. form backing objects) but often your code is more clear without setters. In this particular case the setters aren’t egregious, but I still consider them a smell and much more verbose way that constructor injection. Read more about the problem with setter injection here
  • It is verbose.
  • It is also mutable (often a negative), again a problem due to the use of setters.

So what’s the best way to do it? I have found constructor injection and in our particular example use of Google Collections. As for seeing an implementation of the best solution – just leave a comment.

Below is a full example you can run that illustrates the hard to catch serialization bug.

package com.jawspeak;
 
import com.google.common.collect.Lists;
import static org.junit.Assert.*;
import org.junit.Test;
 
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.NotSerializableException;
import java.io.ObjectOutputStream;
import java.util.ArrayList;
import java.util.List;
 
/**
 * Understands the danger of anonymous subclasses for lists.
 */
public class TooCleverForOurOwnGoodTest {
 
        @Test(expected = NotSerializableException.class)  // UPDATE: Thanks for the reminder from Dennis, below
	public void serializableDangerBugFromPatricksCleverness() throws IOException {
		// you think a List would be serializable, which it is. And so are Strings.
		final String myString = "3";
		List strings = new ArrayList() {
			add("one");
			add("two");
			// However, because there is an anonymous subclass of ArrayList created,
			// there is an implicit reference to the outer class, which is **not serializable**.
			// This is a nice feature, which lets us have closure-ish syntax in java, such as
			// the following reference to the outer myString.
			add(myString); // It will throw the exception even without this reference.
		}};
 
		// call your method that requires args to be serializable
		ByteArrayOutputStream baos = new ByteArrayOutputStream();
		ObjectOutputStream oos = new ObjectOutputStream(baos);
		oos.writeObject(strings);
		// The particular bug I had was even worse, because we were creating leaking a reference
		// through that List's implicit reference to the outer object.
	}
 
	@Test
	public void serializableDangerBugSafeButNotClever() throws IOException {
		// A List is serialiazable. And so are Strings.
		List strings = new ArrayList();
		strings.add("one");
		strings.add("two");
		// No longer is there a reference to the outer class.
 
		// call your method that requires args to be serializable
		ByteArrayOutputStream baos = new ByteArrayOutputStream();
		ObjectOutputStream oos = new ObjectOutputStream(baos);
		oos.writeObject(strings);
	}
 
	@Test
	public void serializableDangerBugSafeAndNiceLooking() throws IOException {
		// A List is serialiazable. And so are Strings.
		List strings = Lists.newArrayList("one", "two");
 
		// call your method that requires args to be serializable
		ByteArrayOutputStream baos = new ByteArrayOutputStream();
		ObjectOutputStream oos = new ObjectOutputStream(baos);
		oos.writeObject(strings);
	}
}

Written by Jonathan

March 10th, 2009 at 11:33 pm

Posted in Uncategorized, code, java, testability

Tagged with , ,