Spring MVC, TeeOutputStream, grep4j and How it All Fits Together

Grep4j caters for an easy search in log files. Since it is really easy to use and simple enough  I could not resist the temptation to try it out. I came up with a simple scenario: Let’s use Spring MVC to conduct a small JSON-based web app, capture the exchanged requests and responses in a log file and use grep4j to do most of the verifications. I am writing to share experience I gained during my little exercise. As usual, source code is provided at the end of the post. 

In one of my previous posts I contemplated a primitive RSS news reader and gave it a nice web interface. Even though I was very happy with the quality and coverage of my automated functional tests, there was one bit missing. The incoming news, due to their unpredictable nature, were not being thoroughly checked.  My tests were driven by Selenium. Powerful tool as it is, detailed checks of unwieldy HTML did not sound really appetizing. I parked the advanced verifications as a non-issue until very recently, when I came across a brief post about grep4j. The simple idea of using log files as an integral part pointed me to the right direction.

To keep things clean and tidy I cloned the bare bones of the original example and started almost from scratch.

First of all, I isolated the core components and had them unit tested.

public class RssEntry {
  // custom fields and their mutators
}

public class RssEntryTest {
  @Test
  public void allFieldsShouldBePopulatedAsExpected() {..}

  @Test
  public void entriesShouldBeEqualIfTheirFieldsAreEqual() {..}
  ..
}

public class RssReader {
  // Fetches the news by category
  public List getFeeds(String category) {..}
}

public class RssReaderTest {
  @Test
  public void theExpectedNumberOfNewsShouldBeReturned() {..}

  @Test
  public void differentNewsShouldBeReadUnderDifferentCategories() {..}
  ..
}

Next, I limited the interaction between the server and the client to the JSON format. That way I had a solid base for reliable and easy verifications. Spring 3 provides an excellent support of JSON and configuration is almost a no-brainer.

@Controller
public class NewsController {

  @Autowired
  private RssReader reader;

  @RequestMapping("/get/news/{category}")
  public @ResponseBody List getNews(@PathVariable String category) {
    return reader.getFeeds(category);
  }
}

pom.xml:

..
<dependency>
<groupId>org.codehaus.jackson</groupId>
<artifactId>jackson-mapper-asl</artifactId>
<version>1.7.1</version>
</dependency>
..

news-servlet.xml:

..
<bean id="rssReader" class="org.zezutom.newsreader.model.RssReader">
<constructor-arg value="http://rss.news.yahoo.com/rss/" />
</bean>

<mvc:annotation-driven />
..

At this stage my only concern was capturing of the server-client interaction into a log file. Traditionally, HTTP responses do not let themselves very well to detailed logging. One has to write a custom wrapper and in some cases the implementation takes a significant number of rows. Luckily, HttpServletResponseWrapper and TeeOutputStream did most of the heavy-lifting and I was able to keep my code relatively short. 

import javax.servlet.http.HttpServletResponseWrapper;
..
public class ResponseWrapper extends HttpServletResponseWrapper {

  private HttpServletResponse response;

  private TeeServletOutputStream teeOut;

  private ByteArrayOutputStream baOut;

  public ResponseWrapper(HttpServletResponse response) {
    super(response);
    this.response = response;
  }

  @Override
  public ServletOutputStream getOutputStream() throws IOException {
    if (teeOut == null) {
      baOut = new ByteArrayOutputStream();
      teeOut = new TeeServletOutputStream(
                 response.getOutputStream(), baOut);
    }
    return teeOut;
  }

  // Captures the response body, the JSON string
  public String getContent() {
    return baOut.toString();
  }
}

..
import org.apache.commons.io.output.TeeOutputStream;

public class TeeServletOutputStream extends ServletOutputStream {

  private final TeeOutputStream target;

  public TeeServletOutputStream(OutputStream outOne,
                                OutputStream outTwo) {
    target = new TeeOutputStream(outOne, outTwo);
  }
  // custom implementation of flush, write, close

}

Now I had all the arrangements in place and was ready to start with integration testing.

mvn clean integration-test

As the output shows, jetty started up and the web application got deployed.

[INFO] web.xml file = news-reader-web/src/main/webapp/WEB-INF/web.xml
[INFO] Webapp directory = news-reader-web/src/main/webapp
[INFO] Starting jetty 6.1.26 ...
..
[INFO] Started Jetty Server

Next, the news request was triggered via the Spring’s REST template.

..
// JSON response as an array of key-value maps
return new RestTemplate()
    .getForObject("http://localhost:8080/get/news/{category}"
                  , Map[].class, "politics");
..

The server response was captured in a log file.

[http://localhost:8080/get/news/politics]:[{"description":"<p><a href="http://news.yahoo.com/momentum-vs-math-elections-final-full-week-182633826--election.html"><img src="http://l1.yimg.com/bt/api/res/1.2/C7k44nuckgV5svhR7M6cHQ--/YXBwaWQ9eW5ld3M7Zmk9ZmlsbDtoPTg2O3E9ODU7dz0xMzA-/http://media.zenfs.com/en_us/News/ap_webfeeds/13c613e74a63321e1f0f6a7067003e8a.jpg" width="130" height="86" alt="Republican presidential candidate..

Finally, grep4j performed elementary validations of the file content.

..
import org.grep4j.core.model.Profile;
import org.grep4j.core.model.ProfileBuilder;
import static org.grep4j.core.Grep4j.egrep;
..
public class NewsReaderIT {
..
private Profile profile = ProfileBuilder.newBuilder()
       .name("Local server log")
                            .filePath("newsreader.log")
                            .onLocalhost().build();
..
assertThat(
  executing(egrep("[0-9]+ms$",
            on(profile))).totalLines(), is(1));
..
}

It is fair to say that grep4j works on a line level. Using a static text (grep) or an advanced expression (egrep) one can verify the number of returned lines or print out the text present on the matching lines. In one of my tests however, I had to check specific text sequence on a particular line. I resorted to the standard Java regex handling.

..
import org.grep4j.core.result.GrepResult;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
..
  @Test
  public void newsShouldBePopulatedInLessThanTenSeconds() {
    GrepResult result = executing(egrep("[0-9]+ms$", on(profile)))
                        .getSingleResult();
    Pattern pattern = Pattern.compile("([0-9]+)ms$");
    Matcher matcher = pattern.matcher(result.getText());

    if (matcher.find()) {
      Long responseTime = new Long(matcher.group(1));
      assertThat(responseTime, greaterThan(0L));
      assertThat(responseTime, lessThan(10000L));
    } else {
      fail();
    }
  }
..

I reconstructed the incoming news from the response captured in the log file and utilized the JSON parser (Jackson) to recreate the response object. Then I merely compared its content against the original hash map populated at the very beginning. Not much of a test indeed but  the ability to restore potentially complex and varied traffic from a persistent store creates space for additional advanced validations.

Download Source Code or Explore It

Resources:

• Remove duplications and fix bad names
• Spring 3 MVC and JSON Example
• Servlet Filter to Log Request and Response Payload
• grep4j Homepage